cancel
Showing results for 
Search instead for 
Did you mean: 
cancel
5603
Views
55
Helpful
18
Replies

SIP Basic Trace Analysis

Abdul Jaseem
Level 1
Level 1

Hi Experts,

Please help me to analyse the attached SIP Trace and identify the following.

1. Firmware of the phone
2. Phone model :
3. Called Number
4. CI1
5. SIP Call ID 1
6. CI2
7. SIP call ID 2
8. which message indicates that the phone went off hook?
9. Type of DTMF method supported by the phone?

Thanks,

1 Accepted Solution

Accepted Solutions

Adarsh Chauhan
Level 3
Level 3

Hi,

Analysis of call made at 22:58:28.018 from 5006 to 5010.
Strictly on the basis of SIP signalling in CUCM traces and not diving into CUCM architecture.

1. Firmware of the phone(calling):
Line:19329
User-Agent: Cisco-CP7861/10.3.1


2. Phone model(calling):
Line:19329
User-Agent: Cisco-CP7861/10.3.1


3. Called Number
Line:20561
Remote-Party-ID: <sip:5010


4. CI1
Line:20552
CI:21384627 (last part of to value)
To: <sip:5@10.173.98.10>;tag=4990~8d4ebf65-f2dd-4e5a-96d8-9741c8d14440-21384627


5. SIP Call ID 1
line:19325
Call-ID: 885a92d9-acf80020-6877c6ce-38005827@10.173.247.125


6. CI2
Line:20320
CI:21384628 (last part of tag value)
From: <sip:5006@10.173.98.10>;tag=4992~8d4ebf65-f2dd-4e5a-96d8-9741c8d14440-21384628


7. SIP call ID 2
Line:20323
Call-ID: d3e1e600-7d3184e5-236-a62ad0a@10.173.98.10


8. which message indicates that the phone went off hook?
Line:20653
SIP/2.0 200 OK
A 200okay from SIPCallID2 means that the other phone went offhook.


9. Type of DTMF method supported by the phone (calling)?
Line (rfc2833):19354
a=rtpmap:101 telephone-event/8000

Line (kpml):19336
Allow-Events: kpml,dialog

Also you should refer to reading SIP TRACES

Please rate and mark correct if helpful

Regards,

Adarsh Chauhan


Please rate and mark correct if helpful
Regards,
Adarsh Chauhan

View solution in original post

18 Replies 18

Adarsh Chauhan
Level 3
Level 3

Hi,

Analysis of call made at 22:58:28.018 from 5006 to 5010.
Strictly on the basis of SIP signalling in CUCM traces and not diving into CUCM architecture.

1. Firmware of the phone(calling):
Line:19329
User-Agent: Cisco-CP7861/10.3.1


2. Phone model(calling):
Line:19329
User-Agent: Cisco-CP7861/10.3.1


3. Called Number
Line:20561
Remote-Party-ID: <sip:5010


4. CI1
Line:20552
CI:21384627 (last part of to value)
To: <sip:5@10.173.98.10>;tag=4990~8d4ebf65-f2dd-4e5a-96d8-9741c8d14440-21384627


5. SIP Call ID 1
line:19325
Call-ID: 885a92d9-acf80020-6877c6ce-38005827@10.173.247.125


6. CI2
Line:20320
CI:21384628 (last part of tag value)
From: <sip:5006@10.173.98.10>;tag=4992~8d4ebf65-f2dd-4e5a-96d8-9741c8d14440-21384628


7. SIP call ID 2
Line:20323
Call-ID: d3e1e600-7d3184e5-236-a62ad0a@10.173.98.10


8. which message indicates that the phone went off hook?
Line:20653
SIP/2.0 200 OK
A 200okay from SIPCallID2 means that the other phone went offhook.


9. Type of DTMF method supported by the phone (calling)?
Line (rfc2833):19354
a=rtpmap:101 telephone-event/8000

Line (kpml):19336
Allow-Events: kpml,dialog

Also you should refer to reading SIP TRACES

Please rate and mark correct if helpful

Regards,

Adarsh Chauhan


Please rate and mark correct if helpful
Regards,
Adarsh Chauhan

Ayodeji Okanlawon
VIP Alumni
VIP Alumni

Abdul

In addition to the excellent answers provided by Adarsh (+5)

Here are more details (NB that my log references a different time stamp from Adarsh's)

Please refer to understanding CUCM traces for ore explanation.

https://supportforums.cisco.com/document/12724111/understanding-cucm-traces-end-end


## The phone going off hook process is indicated by CUCM SUBSCRIBE request to the phone
Phone goes off hook and cucm tells phone to subscribe to KPML to dial digits ##


00331001.006 |22:51:22.161 |AppInfo |//SIP/Stack/Info/0x0/ccsip_spi_process_app_subscribe_event: Event [SIPSPI_EV_CC_SUBSCRIBE] received in State [SUBSCRIBE_STATE_IDLE]
--
00331001.029 |22:51:22.162 |AppInfo |//SIP/Stack/Info/0x0/act_idle_continue_subscribe_event: Changing from State: SUBSCRIBE_STATE_IDLE to state SUBSCRIBE_STATE_DIALOG_PENDING
--
00331002.001 |22:51:22.162 |AppInfo |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 10.173.247.125:[5060]:
[11654,NET]
SUBSCRIBE sip:0994af0a-ce7e-b885-b943-30c6f518bab6@10.173.247.125:5060;transport=udp SIP/2.0
Via: SIP/2.0/UDP 10.173.98.10:5060;branch=z9hG4bK301d84de38
From: <sip:5@10.173.98.10>;tag=1220406462
To: <sip:5006@10.173.247.125>
Call-ID: d55ede80-7d31833a-22d-a62ad0a@10.173.98.10

## phone responds with 200 OK to subscribe request ##


00331003.001 |22:51:22.178 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 452 from 10.173.247.125:[5060]:
[11655,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 10.173.98.10:5060;branch=z9hG4bK301d84de38
From: <sip:5@10.173.98.10>;tag=1220406462
To: <sip:5006@10.173.247.125>;tag=885a92d9acf8007847113ced-7f682005
Call-ID: d55ede80-7d31833a-22d-a62ad0a@10.173.98.10
Date: Sat, 10 Sep 2016 03:51:21 GMT
CSeq: 101 SUBSCRIBE
Server: Cisco-CP7861/10.3.1

### dialled number can be seen after DA ###
dd="5010"
00331053.007 |22:51:23.066 |AppInfo |Digit analysis: match(pi="2", fqcn="5006", cn="5006",plv="5", pss="Global Learned E164 Numbers:Global Learned E164 Patterns:Internal", TodFilteredPss="Global Learned E164 Numbers:Global Learned E164 Patterns:Internal", dd="5010",dac="0")

##CI 1 ##
you can find CIs in the CcCiReq and CciRes ###
21384619

## CI 2 (21384620 ##
You can find your CI 2 in either of the following places..

##1 LBMIF process that associates the first call leg (CI1 to the 2nd call leg, CI 2)

00331062.001 |22:51:23.069 |AppInfo |LBMIF: CI: 21384619 ASSOC 21384620

or you can find it in the From header of the outbound INVITE to called phone

INVITE sip:52f81139-c8eb-3de2-3d4c-af5b05043fc1@10.173.247.116:5060;transport=udp SIP/2.0

From: <sip:5006@10.173.98.10>;tag=4949~8d4ebf65-f2dd-4e5a-96d8-9741c8d14440-21384620

## DTMF Support ###
The answer here depends on which phone we are looking at. The called or the calling phone?
From the logs one phone wants to do both rfc 2833 and sip kpml but the other phone only wants to do rfc2833

00331236.002 |22:51:25.619 |AppInfo |SIP DTMF Info: mLocalDtmfCaps...UNSOL=0, KPML=0, Inband=1(101) mEndppointsDtmfCaps...UNSOL=0, KPML=1, Inband=1(101)

## we can also see this in both the offer and the answer from both phones ##

phone 1
SIP/2.0 200 OK
Allow-Events: kpml,dialog
--
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

phone 2
ACK sip:52f81139-c8eb-3de2-3d4c-af5b05043fc1@10.173.247.116:5060;transport=udp SIP/2.0
--
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15

Please rate all useful posts

Hi Ayodeji,

You are simply amazing, I have seen your 'Expert VIP Live Webcast- Troubleshooting SIP in Cisco Unified Communications Deployments' video and started with SIP trace analysis.

Thanks for your explanation in the above question, I got pretty good understanding of Basic SIP trace.

-Abdul

Hi Abdul , Can you post the link of Ayodeji's 'Expert VIP Live Webcast- Troubleshooting SIP in Cisco Unified Communications Deployments' video. 

I'm at the beginning stage of trace reading. So please provide assistance by sharing the video link.

Thanks in Advance.

Hi,

You can watch the video here..

https://www.youtube.com/watch?v=b588HWfXaWQ

Please rate all useful posts

Hi Ayodeji ,

 

Thanks for the quick reply.

Your way of explanation was so deep and precise.

Have you created any more video series regarding CUCM TRACE READING ??

If so please share the link. It would be of great use for Engineers like me.

 

Thanks Again. 

Hi Arkham,

Here is a link to a detailed deep dive into understanding CUCM traces I wrote a while back.

 

https://supportforums.cisco.com/t5/collaboration-voice-and-video/understanding-cucm-traces-end-to-end/ta-p/3161800

Please rate all useful posts

Hi Ayodeji,

One simple question, in the INVITE message I see below line, why it is only '5' ?

To: <sip:5@10.173.98.10>

Helps are much appreciated.

Abdul,

Here is the process that a SIP phone uses to send digits to CUCM using KPML

1. The phone sends an initial INVITE with the first digit dialed

Incoming SIP UDP message size 1418 from 10.173.247.125:[5060]:
[11624,NET]
INVITE sip:5@10.173.98.10;user=phone SIP/2.0

2. CUCM tells the phone to subscribe to KPML

3. The phone then uses NOTIFY to send the remaining digits to CUCM. The remaining digits apart from the first dialed digit (5 here) are encoded in a xml document as shown below

## Here we see digit 5 as the initial dialed digit ##


00331008.001 |22:51:22.179 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 580 from 10.173.247.125:[5060]:
[11656,NET]
NOTIFY sip:5@10.173.98.10:5060 SIP/2.0
-
Call-ID: d55ede80-7d31833a-22d-a62ad0a@10.173.98.10

### the subsequent digits are encoded in xml by KPML ###
## Next we see digit 0 ##

00331015.001 |22:51:22.425 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 880 from 10.173.247.125:[5060]:
[11658,NET]
NOTIFY sip:5@10.173.98.10:5060 SIP/2.0
-
-
Call-ID: d55ede80-7d31833a-22d-a62ad0a@10.173.98.10
--
Content-Type: application/kpml-response+xml


<?xml version="1.0" encoding="UTF-8"?>
<kpml-response xmlns="urn:ietf:params:xml:ns:kpml-response" version="1.0" code="200" text="OK" suppressed="false" forced_flush="false" digits="0" tag="Backspace OK"/>

## digit 1 ##

00331029.001 |22:51:22.745 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 880 from 10.173.247.125:[5060]:
[11660,NET]
NOTIFY sip:5@10.173.98.10:5060 SIP/2.0
--
<?xml version="1.0" encoding="UTF-8"?>
<kpml-response xmlns="urn:ietf:params:xml:ns:kpml-response" version="1.0" code="200" text="OK" suppressed="false" forced_flush="false" digits="1" tag="Backspace OK"/>

## digit 0 ##

00331043.001 |22:51:23.065 |AppInfo |//SIP/SIPUdp/wait_SdlDataInd: Incoming SIP UDP message size 880 from 10.173.247.125:[5060]:
[11662,NET]
NOTIFY sip:5@10.173.98.10:5060 SIP/2.0
-
Call-ID: d55ede80-7d31833a-22d-a62ad0a@10.173.98.10
-
<?xml version="1.0" encoding="UTF-8"?>
<kpml-response xmlns="urn:ietf:params:xml:ns:kpml-response" version="1.0" code="200" text="OK" suppressed="false" forced_flush="false" digits="0" tag="Backspace OK"/>

--

Next CUCM performs digit analysis to find the called number


00331053.000 |22:51:23.066 |SdlSig |DaReq
00331053.008 |22:51:23.067 |AppInfo |Digit analysis: analysis results
00331053.009 |22:51:23.067 |AppInfo ||PretransformCallingPartyNumber=5006
|CallingPartyNumber=5006
|DialingPartition=Internal
|DialingPattern=5010

So you will always see the first digit dialed from the phone in the INVITE sent to CUCM.

Please rate all useful posts

Abdul Jaseem
Level 1
Level 1

Hi Adarsh,

Thanks a lot for your prompt response. Now I'm able to track the call in Translator X with the Call ID provided by you.

One quick question, How do we know the direction of a SIP message? For example,

INVITE sip:5@10.173.98.10;user=phone SIP/2.0
Via: SIP/2.0/UDP 10.173.247.125:5060;branch=z9hG4bK058a103e
From: "5006" <sip:5006@10.173.98.10>;tag=885a92d9acf800835d527fe2-3f06a479
To: <sip:5@10.173.98.10>
Call-ID: 885a92d9-acf80020-6877c6ce-38005827@10.173.247.125
Max-Forwards: 70
Date: Sat, 10 Sep 2016 03:58:27 GMT
CSeq: 101 INVITE
User-Agent: Cisco-CP7861/10.3.1
Contact: <sip:0994af0a-ce7e-b885-b943-30c6f518bab6@10.173.247.125:5060;transport=udp>
Expires: 180
Accept: application/sdp

In the above message, the direction is from Phone (10.173.247.125) to the Call Manager (10.173.98.10).

Hi Abdul,

There are a couple of things which we can look at and determine the direction.

1) in a SIP Requests the via field can be used to determine from where the message is coming.

which in our case is 10.173.247.125 i.e the phone.

2) User-Agent Field can also tell us the initiator of the Request which in our case is the 7861 phone.

3) the contact field tells the UAS (user agent server) where the response should be sent.

which in our case is @10.173.247.125 i.e. phone. (can be different at times.)

4) the SIP-REQ-URI itself  (INVITE sip:5@10.173.98.10) tells us that we are looking for 5 at 10.173.98.10 which is our destination i.e. call manager.

With all this you can make a conclusion that the user agent which is a phone is requesting the server.

Please rate and mark correct if helpful

Regards,

Adarsh Chauhan


Please rate and mark correct if helpful
Regards,
Adarsh Chauhan

Hi Adarsh,

Great.. :) Much appreciated!

 

Hi Adarsh,

Thanks a lot for sharing.

I have 1 more question to clarify.

How do we understand the second call leg. 

For example if I get the Call ID, I can see the Phone A to CUCM Call leg.

How to relate this call ID to the second call, that is CUCM to Phone B

-Thanks

Hi Abdul,

It would be a bit tricky as we are working on call legs from CUCM perspective.

Without diving into CUCM architecture it be very difficult to relate two call legs.

You can search with port number shared in the sdp.

this wont work 100% of the time as the port would not be common if media resource is invoked on call manager but you can give it a shot.

Please rate and mark if helpful

Regards,

Adarsh Chauhan


Please rate and mark correct if helpful
Regards,
Adarsh Chauhan
Getting Started

Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community: