Categories

CUC (6) CUCM (28) Jabber (6) Python (2) Routing (3) Solarwinds Orion NPM (4) switching (1) Video (6) voice (3)

Monday, 27 April 2015

Verifying Codecs, using trace files and CLI, an example


Cooking is easy, anyone can cook, just get a recipe and stick to it.   With Analysing Call Manager trace file, there is no such thing, its all about trial and error and experience.  Sadly there is no official documentation on interpreting trace files and the Cisco certification seriously lacks in this direction as well. 

What i want to do in this post if give some hints and tips on how I use tracefiles to analyse calls, and as always; correct me if I am wrong.  So lets assume you want to find out what codecs are being used for a particular call path.

In this example, I have an external caller calling into a MGCP gateway to be connected to a webex conference. First thing I always do is check the call leg on the relevant voice gateway, see below.

voipgw#sh call active voice compact 
 <callID>  A/O FAX T<sec> Codec       type        Peer Address       IP R<ip>:<udp>
Total call-legs: 6
    252281 ORG     T125   g729r8      VOIP        P       10.6.2.82:24632
    252280 ORG     T125   g729r8      TELE        P


This call connects to a peer IP address of the CUCM (10.6.2.82) and uses G729 as the codec.

Sometimes it is as simple as that, in this particular case, it is only the first leg of the call, between Voice gateway and call manager, the second leg connects between CUCM and webEX, via a SIP trunk. This means that the trace file will need to be analysed to get more information about this particular call.

Tracefiles can be big, so if you are going to analyse anything like a specific call, you must need to obtain an exact as possible time stamp of the time the call took place.  (I always start the call as soon as my OS clock has just ticked into the next minute, this makes it just a little bit easier).

After you noted the time stamp down, download your traces using RTMT. I use absolute time ranges and download no more than 2 minutes of traces.

CUCM service Trace files contain 2 directories; Call Logs and SDL file. Open the call logs first and establish the exact system time stamp of your test call, something like 13:29:34.290  

Now go back to your SDL directory and open the file that covers the time stamp you just obtained from the previous step.  Use notepad++  as it is superior over notepad or any other text editor. Tracefiles will contain all SIP signalling if you set your trace details to the correct level in CUCM.

So below is an INVITE with an SDP, and as you can see, the preferred codec is PCMU (G711u-law)

To: <sip:+61393312345@10.6.2.89>;tag=59ee875a4905fb3e+10.61.2.89
From: <sip:43832345@10.1.2.82>;tag=105895144~1b5af941-cea2-4a00-a0bd-15a532224d7d-33705330
Via: SIP/2.0/TCP 10.6.2.82:5060;branch=z9hG4bKd85c7f5fe1c367
Call-ID: 3f98b580-5391a660-6e04e9-52023d0a@10.6.2.82
CSeq: 102 INVITE
Contact: <sip:1800122222@10.6.2.89:5062;transport=tcp>;isfocus
Max-Forwards: 70
Session-Expires: 1200
Allow: INVITE, OPTIONS, INFO, BYE, CANCEL, ACK, SUBSCRIBE, NOTIFY
Content-Type: application/sdp
Supported: timer
Content-Length: 308
Remote-Party-ID: "Australia"<sip:18001222222@10.6.2.89>;screen=yes;privacy=off

v=0
o=CMS 645378 666823 IN IP4 10.6.2.89
s=ciscowebex_cms_session
c=IN IP4 10.6.2.89
t=0 0
m=audio 19796 RTP/AVP 0 8 18 9 101
a=rtpmap:0 PCMU/8000     <----prefers G711 u law
a=rtpmap:8 PCMA/8000
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20



After the SIP message, containing the SDP has been received (Early Offer), call manager invokes its internal processes and does a capabilities check.


94341469.000 |12:11:44.775 |SdlSig-O |MediaExchangeAgenaUpdateCapabilities   |NA RemoteSignal                |AgenaInterface(3,100,244,45105)  |MohDControl(2,100,130,2)         |3,100,14,1.636699^*^*                    |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] AudioCapCount=1(4,80) CryptoAudioCapCount0 VideoCapCount=0 CryptoVidCount0 AudioCapDir=0 VideoCapDir=0 DataCapDir=0 ipAddrType=0 ipv4=10.6.2.81 Supp.Payload RFC[0 0 0 0 0 ] CustomPictureFormatCount=0 devCap= [0x20 PORT_CAP] PortInfoList [ confID=0 callRefID=0] v150MER=F T38MER=F
94341470.000 |12:11:44.775 |SdlSig   |CACInfoRes                             |wait                           |ReservationMgr(2,100,110,1)      |RSVPSession(2,100,107,1277348)   |2,100,14,115691.5^10.1.2.89^*           |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI= 33705329  aCI=33705329 bCI=33705330 pol=0 rsvpStatus=1 aVideoTrafficClass=0 bVideoTrafficClass=0 sessJoined=F staIdx_no_agent=0 locationstatus=( NoBWReserved) eoSent=F aAgent:  confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0 bAgent:  confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0 aPort:  NumPort =0 bPort:  NumPort =0 otherAgentPort:  NumPort =0
94341471.000 |12:11:44.775 |SdlSig   |CACInfoRes                             |waitCACInfoRes                 |MediaManager(2,100,140,990393)   |ReservationMgr(2,100,110,1)      |2,100,14,115691.5^10.6.2.89^*           |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI= 0  aCI=33705329 bCI=33705330 pol=0 rsvpStatus=1 aVideoTrafficClass=0 bVideoTrafficClass=0 sessJoined=F staIdx_no_agent=0 locationstatus=( AudioBWReserved) eoSent=F aAgent:  confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0 bAgent:  confID =0 ci =0 capCt =0 reg= mtpType =2 agentCt =0 mmCapSet=0 agentAllo =0 RemoAgent=F DevCap=0 ipAddrMode=0 aPort:  NumPort =0 bPort:  NumPort =0 otherAgentPort:  NumPort =0
94341471.001 |12:11:44.775 |AppInfo  |DET-MediaManager-(990393) - waitCACInfoRes_CACInfoRes- qosType=0  videoEsc=0  mNoVideoResvAttempted=1  VideoCall=0
94341471.002 |12:11:44.775 |AppInfo  |DET-MediaManager-(990393)::waitCACInfoRes_CACInfoRes, rsvp(0,0), E2E RegionBwKbps[ A=64 V = 4000 I = 2147483647 ]  ,deviceAcaps(0) deviceBCaps(0),noVideoResv(1), mmAllowedCallType(0x00000000)
94341471.003 |12:11:44.775 |AppInfo  |DET-MediaManager-(990393)::mapCapabilitiesToMMCallType - Call is set to Audio Only - vidCall = 0)


After this the Regions are checked to see what codec is to be used:

4341471.007 |12:11:44.775 |AppInfo  |DET-MediaManager-(990393)::preCheckCapabilities, region1=AU_VIC_Melbourne_REG, region2=AU_VIC_melbourne_TP_REG, Pty1 capCount=10 (Cap,ptime)= (4,20) (2,20) (11,220) (12,220) (15,220) (84,110) (10,110) (83,70) (82,50) (107,0), Pty2 capCount=5 (Cap,ptime)= (4,20) (2,20) (11,20) (12,20) (6,20)
94341471.008 |12:11:44.775 |AppInfo  |DET-RegionsServer::matchCapabilities-- savedOption=0, PREF_NONE, regionA=(null) regionB=(null) latentCaps(A=0, B=0) kbps=64, capACount=10, capBCount=5

94341471.009 |12:11:44.775 |AppInfo  |DET-MediaManager-(990393)::prepareInitialConnectionList, Party1CapCount=10 Party2CapCount=5 XcoderRequired=0 xcodingSide=0 allowMTP=0





Location Bandwidth Manager (LBM)

Bandwidth calculation (80Kbps for G711, plus overhead)

94341632.002 |12:11:44.801 |AppInfo  |DET-MediaManager-(990393)::updateCallBwForAudio: callBW result = 80, incallBW = 80, hopBW = 80, selected BW= Lowest

send to MGCP gateway:

MDCX 2712580 S0/SU0/DS1-0/30@voipgw.au.com MGCP 0.1
C: D000000002024d71000000F580002119
I: 1C858
X: 1e
L: p:20, a:PCMU, s:off, t:b8, fxr/fx:t38
M: sendrecv
R: D/[0-9ABCD*#], FXR/t38
S: 
Q: process,loop

v=0
o=- 116824 0 IN EPN S0/SU0/DS1-0/30@voipgw.au.com
s=Cisco SDP 0
t=0 0
m=audio 24762 RTP/AVP 0
c=IN IP4 10.6.2.82
a=X-sqn:0

a=X-cap:1 image udptl t38


and sent to webex (SIP):

CK sip:1800120778@10.6.2.89:5062;transport=tcp SIP/2.0
Via: SIP/2.0/TCP 10.1.2.82:5060;branch=z9hG4bKd85c83d2dd5d
From: <sip:438305444@10.6.2.82>;tag=105895144~1b5af941-cea2-4a00-a0bd-15a532224d7d-33705330
To: <sip:+613933012345@10.6.2.89>;tag=59ee875a4905fb3e+10.6.2.89
Date: Fri, 24 Apr 2015 02:11:44 GMT
Call-ID: 3f98b580-5391a660-6e04e9-52023d0a@10.61.2.82
User-Agent: Cisco-CUCM10.0
Max-Forwards: 70
CSeq: 102 ACK
Allow-Events: presence, kpml
Content-Type: application/sdp
Content-Length: 245

v=0
o=CiscoSystemsCCM-SIP 105895144 1 IN IP4 10.6.2.82
s=SIP Call
c=IN IP4 10.61.2.82
b=TIAS:64000
b=CT:64
b=AS:64
t=0 0
m=audio 24760 RTP/AVP 0 101
a=ptime:20
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000

a=fmtp:101 0-15



So really, when it comes to analysing trace files, it is all about following the bouncing ball, open the tracefiles in Notepad ++ and search for terms like "error" or "failed", when analyzing SIP signalling, use the unique Call-ID. And above all, use an exact time stamp.





No comments:

Post a Comment