cancel
Showing results for 
Search instead for 
Did you mean: 
cancel

Understanding CUCM Traces: End to End

28535
Views
205
Helpful
29
Comments

 

1.1 Introduction

In this document, I will attempt to share one or two things about understanding how to read and interpret CUCM traces. CUCM is a very complex call control system and sometimes it is hard to troubleshoot issues without looking at logs. These logs can be daunting if you don’t know what to look for or how to interpret what you are looking for. In this document I will be sharing a few tips that have really helped me to understand this product a little better.

This document is not protocol specific although we will be looking at a sip centric call flow. There are several protocol specific documentations that have been written and you should refer to them. I will post links to some of these excellent documents later on

My aim here is to look at a call end to end and dealing with each protocol that are involved in the call flow

2.1 Collecting CUCM logs

The first place to start is obviously collecting CUCM logs, hence we need to know how to collect them. As simple as it sounds, knowing how to collect CUCM logs and which servers in your cluster to collect the logs from could save you lots of time in troubleshooting.

So how do we collect these logs. CUCM logs can be collected either via RTMT or the OS CLI. RTMT is the easiest and most efficient so I thats the one we will focus on.

2.1.1 RTMT

RTMT is the tool we use in downloading logs from CUCM. There are certain settings that may be needed on the CUCM itself before you can collect meaningful traces. Please refer to the link below to see what you need to ensure your CUCM servers are correctly configured. Collecting CUCM logs is mostly the same in most CUCM version however there are some variations depending on which CUCM version you are using.

  • CUCM 8.6.2

https://supportforums.cisco.com/document/126666/collecting-CUCM-traces-CUCM-862-tac-sr

  • CUCM 9.1 and Above:

The link above does apply but there is an additional useful feature here. The little icon by the save button (set to default) will automatically configure your trace settings for you and in most cases these settings will be sufficient. The image below shows the set default icon

Figure 1.1

 

  • CUCM 10.5 and above:

There is an additional step to configuring your traces in this version. You will need to tick the tickbox (Trace ON) as shown in the image below

Figure 1.2

 

2.2 CUCM Nodes To Download Logs From

Knowing which server is your cluster to collect the logs from is usually the most challenging part of this whole task. In a cluster with multiple CUCM servers, it is imperative to know which CUCM servers were involved in the particular call you are interested in. Depending on how your CUCM is configured and the type of call you are troubleshooting, there may be several servers involved in a single call

  • Local Device Node:

The best place to start collecting your logs is the server your phone/device you are troubleshooting is registered to.

The CUCM server that a device is registered to, will always have at least some of the logs involved in the call. You must always start here. It is possible that a SDL signal is sent to another CUCM server in the cluster for further call processing, but you will always see that from the server the device is registered to. We shall be demonstrating this in detail further down in this document.

Let us look at an example of a call flow and use this to know which node we need for logs

In this example, I am troubleshooting a call between two phones registered to two different CUCM clusters. In this scenario, there are different CUCM involved in this call and we will need to collect CUCM logs from each and every one of them

  • So we will start from the CUCM the phone is registered to. Once we do this, we will be able to see which CUCM node on the remote cluster has been selected as the destination for the sip traffic.
  • We then need to collect CUCM logs from that server too.
  • It is possible that the node where the phone is registered to is not the node that processed the sip traffic, hence we will need to collect logs from the node the phone is registered to

The call flow above assumed that we are using run on all active CUCM node feature on the originating CUCM cluster hence the CUCM node the originating ip phone is registered to is also the node that processed the sip traffic. However in scenarios where this is not the case, it is possible that a different CUCM node will processed the sip traffic and send out the sip invite to the destination node.
At this point I want to quickly touch on the feature "Run on all active cucm node" and the role it plays in collecting CUCM logs.

 

2.2.1 Run on all active CM node


One of the many benefits of using this feature is that it aids in troubleshooting. This is because when this feature is in use, the calling local feature is triggered hence the node the originating ip phone is registered to is the node that will process the sip traffic. This therefore eliminates the need for SDL signalling across the CUCM cluster, thereby reducing the number of nodes involved in a call, hence reducing the places where we need to collect CUCM logs. The call flow illustrates what happens when this feature is not enabled

Figure 1.3

From this call flow, we do not have run on all active CUCM node on both the sip trunk and Route list. The node the IP hone is registered is also different from the node that the RL is regsitered to, hence the node that will process the sip traffic will be different from the node the calling ip phone is registered to. Therefore there is going to be SDL signal to the CUCM node the RL (for the sip trunk) is registered to. The implication of this is that we will need to collect CUCM logs from all CUCM involved here increasing the complexity of the task we face.

If you are interested in knowing more about this feature, I wrote a separate document on this. Please refer to it here.

https://supportforums.cisco.com/blog/12088366/sip-trunks-and-run-all-active-cm-nodes

As you can see, it’s no small task troubleshooting CUCM related issues. Before we even begin to look into the trace we need to know the CUCM nodes involved in the call, which in itself is an art (one that I love very much)

3.1 Analysing Logs

Now that we have our logs, the next crucial set of tasks involves dissecting these logs. Yes it doesn’t get any easier I am afraid. :)

Tools

The first question I ask myself when analysing logs is, what tool do I use to review this?

Two of my favourite’s tools are listed above. The question is “when do I use which”. The answer to this is it all depends on what I am looking at.

TranslatorX is very efficient when I have a large trace files I need to look at. It’s such a powerful tool and I can look at multiple trace files in a single view. It also comes into play when I want to see the sip ladder for a call flow when considering a sip trace. It gives you an overview of how that call is routed and can be very useful when you want to quickly identify where something is gone wrong.

Notepad++ is your go to guy, when you need to dissect in detail, when I need to look at each line of a trace, when I need to look a little closer and a little intimately :)

Most often, I use both tools together. You must get your hands on both and catapult yourself into another realm of knowledge, passion and ecstasy with CUCM traces :)

3.1.1 The Anatomy Of A Trace File

Now that we have our logs and are armed to go to war with the best of tools, it’s time to dissect and to perform an anatomy of our trace file

To analyse CUCM logs there are basic things and elements/parameters we need to know. I will start from the simplest to the more complex.

Call Details.

  • Calling number
  • Called number
  • Time of Call

The most important piece of information you need is identifying that you have the right logs and this is done by ensuring the call details are present in those logs. I have a practice of verifying any log I send to TAC is the right log by looking in to ensure my call details are present. There is nothing so painful as taking your time, gathering logs and then you get a response back (after 2hrs, 3 hrs, 4hrs), however long it takes the TAC engineer or the person reviewing the log saying that they can’t find the call in the log. So the first rule of thumb is ensure your call details are present in the logs

Call Identifier (CI)

In a CUCM log there could be thousands of calls and hence lots of trace files. Therefore we need to find a way to identify each call. CUCM does this by assigning a unique CI (call identifier) to each leg of a call. CUCM allocates a unique CI for every instance/process that it invokes. Eg when a transcoder is needed, CUCM will allocate a CI for that. When an ANN is needed, CUCM allocates a CI for that. With the CI you can then trace the transaction for that process.
Within your CUCM logs, you also have each protocol such as SIP, H323, SCCP using their unique call-ids. Listed below are some of the unique identifiers that some of the processes on CUCM uses

  • CUCM “CI”
  • SIP: Call-ID
  • H225: “GUID”
  • H245: "TtPid"
  • Device Registration: "TCP Handle" (Unique identifier for device registered to CUCM)

Digit Analysis (DA)

Digit analysis is a powerful process on CUCM that has several connotations. Here are some based on my experience. There may be more

  • It happens only on the node that processes the call
  • It is used by CUCM to match the calling and called entity
  • It tell us the pattern type (Enterprise pattern or Translation pattern)
  • It is used by CUCM to know where to route the call

It is a practice of mine to look for digit analysis once I have identified my call. This would help me to know if I am on the right server that processed the call and where the call was sent to.
I don’t like talking too much as you must have observed. :) So let all the fun begin. Let’s get cracking. Let’s put all this together by analysing a trace file..
For this analysis, here is the call flow that we will be using.

false

It is a very complex call flow. This will help us to see all the aspects I have mentioned in this document. We will only consider CUCM logs and not the expressway logs.

IP details

These are the Ip details int he trace file.

expwcA 192.105.10.5
JabberA 192.168.0.7 (Registered with CUCMUK—192.105.10.11)
CUCMUK 192.105.10.11
CUCMUS1 192.105.12.13
CUCMUS2 192.105.12.174
expwcB 192.105.12.135
JabberB Registered to CUCM 192.105.12.174)           

 

Call details:
Calling number: 72403225
called number: 87555650
Time of call: 12:24-GMT (7:24 EST—where called endpoint is registered to)

Now let’s download the logs:

  • The first place to start will be the 192.105.10.11 node. This is where our Jabber client is registered to.
  • Sip trunk destination node

Next question is which node the call will be sent to on the remote cluster, because we need to collect the logs from that node as well. The answer to this is that, since this is a sip call, we can look at the outbound INVITE (translatorX can quickly tell us this). Once we identify the node the INVITE request was sent to, we can then go to that node and download the logs.
In this call, the INVITE was sent to multiple nodes (there were about eight servers) configured on the destination sip trunk. But because run on all active cucm node wasn’t checked on the sip trunk only the node on the cucm group of the trunk accepted the call. That node is 192.105.12.13

  • Called party node (192.105.12.174)


Here are the three log files.

SDL004_100_000315.txt
SDL010_100_000915.txt
SDL022_100_000756.txt

A quick word about the actual CUCM trace files. It is good to know what the file naming actually means.
From CUCM 9.1 and above, both SDI files and SDL files are combined in a single trace file now referred to as SDL_CUCMNODECTIID_PROCESSNAME_FILESEQUECENUMBER

So this file “SDL004_100_000315.txt “ is broken down as follows:
004= CTI ID  of 4 (CUCM node ID)
100= CUCM process ID
000315 = file number on that CUCM server
With this you can quickly  match Node IDs to server names by looking at the SDL trace files
To know that your CTI ID or node ID is you can simply go to system>Cisco Unified CM

Figure 1.4

3.1.2 References

I mentioned earlier that this document is not looking in detail at protocols such as SIP, H323, MGCP or SCCP. However we will be using the knowledge of these protocols in analysing these traces. It is imperative that you familiar yourself with them and here are some of the excellent links to understanding CUCM traces from the perspective of some of these protocols

1.    Understanding SIP traces
a.    https://supportforums.cisco.com/document/113271/understanding-sip-traces

2.    Tracking H.323 Calls in CUCM SDI Traces
a.    https://supportforums.cisco.com/document/44911/tracking-h323-calls-cucm-sdi-traces#Locate_the_problem_call

3.    How to read CUCM traces - A Basic Call Signalling Protocol Reference Guide
a.    https://supportforums.cisco.com/document/12387851/how-read-cucm-traces-basic-call-signalling-protocol-reference-guide

3.1.3 Dive In

Now then, we will attempt to look at these traces task by task. This is to help you to formulate a practical approach to troubleshooting. So here goes.

3.1.4 Task 1: Open Up All The Traces In TranslatorX

You can use built in filters in translatorX to filter through the call based on your call details.

The sip ladder below shows the call flow for this particular call. One of the many benefits on translatorX is the quick overview it gives. As you can see we can quickly identify certain issues even without drilling into the trace files.

Figure 1.5

3.1.5 Task 2: Open Up The Traces In notepad++

Now that we have an overview, its time to open up the traces and see what’s going on in detail

3.1.5.1 Inbound Invite

+++ This node (192.105.10.11) received INVITE from 192.168.10.5 (expwcA) +++

71463168.003 |12:24:11.967 |AppInfo  |SIPTcp - wait_SdlReadRsp: Incoming SIP TCP message from 192.105.10.5 on port 25057 index
[3209965,NET]
INVITE sip:87555650@192.105.10.11;user=phone SIP/2.0
Via: SIP/2.0/TCP 192.105.10.5:5060;egress-zone=CEtcp101054011;branch=z9hG4bK0eaf0237eaaffecea193409900fe09a162780;proxy-call-id=dc7814d2-4204-4d4b-b738-3819d23a213f;rport
Via: SIP/2.0/TLS 192.105.10.5:5073;branch=z9hG4bKe121c1f328d1abaa38fafd2c9374daa84183;x-cisco-local-service=nettle;received=192.105.10.5;rport=34815;ingress-zone=DefaultZone
Via: SIP/2.0/TLS 192.105.10.5:5061;egress-zone=DefaultZone;branch=z9hG4bK62be10dc342a46137249a40f67264bbf62779.c7f78fcb7f0f7be0456ab31b3c665219;proxy-call-id=b1f2edca-168b-4636-a479-3c61a15636c4;received=192.105.10.5;rport=25015
Via: SIP/2.0/TLS 10.106.3.84:7001;egress-zone=ExpweTraversal;branch=z9hG4bK5e974241584e1cd038ddd27724b21cf094883.ee2c868e6dc530b149461a661a30df3e;proxy-call-id=a8ffb6ac-d968-4253-b007-ccc10ddd9191;received=10.106.3.84;rport=7001;ingress-zone=ExpwcTraversal
Via: SIP/2.0/TLS 192.168.0.7:38056;branch=z9hG4bK6b59edc9;received=86.29.4.226;rport=38056;ingress-zone=CollaborationEdgeZone
Call-ID: 73f64906-ee92000c-0954f6c3-4fcae256@192.168.0.7

 

+++ Next CUCM sends a 100 trying +++

71463172.001 |12:24:11.968 |AppInfo |SIPTcp - wait_SdlSPISignal: Outgoing SIP TCP message to 192.105.10.5 on port 25057 index 2145
[3209966,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.105.10.5:5060;egress-zone=CEtcp101054011;branch=z9hG4bK0eaf0237eaaffecea193409900fe09a162780;proxy-call-id=dc7814d2-4204-4d4b-b738-3819d23a213f;rport,SIP/2.0/TLS 192.105.10.5:5073;branch=z9hG4bKe121c1f328d1abaa38fafd2c9374daa84183;x-cisco-local-service=nettle;received=192.105.10.5;rport=34815;ingress-zone=DefaultZone,SIP/2.0/TLS 192.105.10.5:5061;egress-zone=DefaultZone;branch=z9hG4bK62be10dc342a46137249a40f67264bbf62779.c7f78fcb7f0f7be0456ab31b3c665219;proxy-call-id=b1f2edca-168b-4636-a479-3c61a15636c4;received=192.105.10.5;rport=25015,SIP/2.0/TLS 10.106.3.84:7001;egress-zone=ExpweTraversal;branch=z9hG4bK5e974241584e1cd038ddd27724b21cf094883.ee2c868e6dc530b149461a661a30df3e;proxy-call-id=a8ffb6ac-d968-4253-b007-ccc10ddd9191;received=10.106.3.84;rport=7001;ingress-zone=ExpwcTraversal,SIP/2.0/TLS 192.168.0.7:38056;branch=z9hG4bK6b59edc9;received=86.29.4.226;rport=38056;ingress-zone=CollaborationEdgeZone
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=73f64906ee9200341e7558b1-346a1ebf
To: <sip:87555650@192.105.10.11>
Date: Fri, 20 Nov 2015 12:24:11 GMT
Call-ID: 73f64906-ee92000c-0954f6c3-4fcae256@192.168.0.7
CSeq: 101 INVITE
Allow-Events: presence
Content-Length: 0

 

3.1.5.2 Digit Analysis

+++ Next CUCM does a Digit Analysis. This process begins with a DaReq (DA request) +++

71463201.000 |12:24:11.972 |SdlSig |DaReq |wait |Da(22,100,204,1)
|Cdcc(22,100,212,233043) |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI=383048635
Fqdn=ti=1nd=02070043225pi=0si1 Cgpn=tn=0npi=0ti=1nd=72403225pi=1si0 DialedNum=tn=0npi=1ti=1nd=87555650User=87555650Host=192.105.10.11Port=5060PassWord=Madder=Transport=4m
DisplayName=RawUrl=sip:87555650@192.105.10.11;user=phonepi=0si1 requestID=0 DigitAnalysisComplexity=0
CallingUser= IgnoreIntercept=0
71463201.001 |12:24:11.972 |AppInfo |Digit Analysis: star_DaReq:
daReq.partitionSearchSpace(2728b956-43d7-d756-fa63-e8601b9d2245:ca002184-f2d1-e36d-c5d2-dcfa8292eb37),
filteredPartitionSearchSpaceString(PT_UKNP_PREMIUM_BLOCKED:Internal_PT:ABUK556_TX_PT:SYS_OnNet_PT:
SYS_Video_PT:SYS_E164_XLAT_GEO_PT:SYS_G711_PSTN_PT), partitionSearchSpaceString (PT_UKNP_PREMIUM_BLOCKED:
Internal_PT:ABUK556_TX_PT:SYS_OnNet_PT:SYS_Video_PT:SYS_E164_XLAT_GEO_PT:SYS_G711_PSTN_PT)
71463201.002 |12:24:11.972 |AppInfo |Digit Analysis: Host Address=192.105.10.11 MATCHES this node's IPv4 address.
71463201.003 |12:24:11.972 |AppInfo |Digit Analysis: star_DaReq: Matching SIP URL, Numeric User, user=87555650

 

 

 +++ Next we get a DA results +++


71463201.010 |12:24:11.972 |AppInfo  |DbMobility: getMatchedRemDest can't find remdest 87555650 in map
71463201.011 |12:24:11.972 |AppInfo  |Digit analysis: match(pi="2", fqcn="02070043225", cn="72403225",plv="5", pss="PT_UKNP_PREMIUM_BLOCKED:Internal_PT:ABUK556_TX_PT:SYS_OnNet_PT:SYS_Video_PT

:SYS_E164_XLAT_GEO_PT:SYS_G711_PSTN_PT", TodFilteredPss="PT_UKNP_PREMIUM_BLOCKED:Internal_PT:ABUK556_TX_PT:SYS_OnNet_PT:SYS_Video_PT:
SYS_E164_XLAT_GEO_PT:SYS_G711_PSTN_PT", dd="87555650",dac="0")
71463201.012 |12:24:11.973 |AppInfo  |Digit analysis: analysis results
71463201.013 |12:24:11.973 |AppInfo  ||PretransformCallingPartyNumber=72403225
|CallingPartyNumber=72403225
|DialingPartition=SYS_Video_PT
|DialingPattern=87555650
|FullyQualifiedCalledPartyNumber=87555650
|DialingPatternRegularExpression=(87555650)
--
--

|CallableEndPointName=[efb8b5fc-adb1-e22c-cec8-cd53215d60f6]

--
71463202.000 |12:24:11.973 |SdlSig   |DmPidReq                               |initialized                    |DeviceManager(22,100,199,1)     
 |Da(22,100,204,1)                 |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]  
Cepn=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 Id=2650870944
71463202.001 |12:24:11.973 |AppInfo  |SMDMSharedData::findAliasRegInfo - AliasName = efb8b5fc-adb1-e22c-cec8-cd53215d60f6 not in AliasInfo hashmap
71463202.002 |12:24:11.973 |AppInfo  |DeviceManager::star_DmPidReq - RequestedName=efb8b5fc-adb1-e22c-cec8-cd53215d60f6
LookupName=efb8b5fc-adb1-e22c-cec8-cd53215d60f6
71463202.003 |12:24:11.973 |AppInfo  |SMDMSharedData::findLocalDevice - Name=SYS_US1_Cluster_RL
Key=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 isActvie=1 Pid=(22,82,58) found
71463203.000 |12:24:11.973 |SdlSig   |DmPidRes                               |wait                           |Da(22,100,204,1)                 
|DeviceManager(22,100,199,1)      |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0]  
Cepn=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 Id=2650870944 ccmType=3 Pid=22,100,82,58,
71463203.001 |12:24:11.973 |AppInfo  |Digit analysis: wait_DmPidRes- Partition=[f183a6a8-0588-ac9e-544a-51eaf097eb94]
Pattern=[87555650] Where=[],cmDeviceType=[AccessDevice], OutsideDialtone =[0], DeviceOverride=[0], PID=RouteListControl(22,100,82,58),
CI=[383048635],Sender=Cdcc(22,100,212,233043)
71463204.000 |12:24:11.973 |SdlSig   |DaRes                                  |setup_da                       |Cdcc(22,100,212,233043)          
|Da(22,100,204,1)                 |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI=383048635

 There are three important things I also look for in the DA results

  • Called Endpoint (This we can find in the "CallableEndPointName"): The value here is in reference to the database so that the device manager will find the match. The device manager will use the process ID responsible for the device to find it.
  •  Local device/Remote Device that the call is sent to: This could be a RL/ICT Trunk/Phone. This we find under the process  "DmPidReq"
  • The CI for this leg of the call: We did discuss the CI earlier. So here I find mine. There are multiple ways to find the CI for each call. Under DA results we find our CI from "DmPidRes"
    Typically CUCM uses a process called CCCiReq and a CCCiRes to allocate the CI for a call. So in the DA result CUCM just allocates the CI that has already being created for the call to the DA results. For me I find it easier to locate my CI using the DA results.
    For this call here is the CCCiReq and CCCiRes ( in here you will see the CI allocated)

 +++ CCCiReq +++

71463079.000 |12:24:11.748 |SdlSig   |CcCiReq                                |wait                           |Cc(22,100,213,1)                 |LineControl(22,100,167,45507)    |22,100,13,149006883.778^192.105.10.5^BOTMHANNAN |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0]  handle=0 handle2=0pi=0si1


+++ CCCiRes +++

71463080.000 |12:24:11.748 |SdlSig   |CcCiRes                                |restart0                       |LineControl(22,100,167,45507)    |Cc(22,100,213,1)                 |22,100,13,149006883.778^192.105.10.5^BOTMHANNAN |[R:H-H:0,N:0,L:0,V:0,Z:0,D:0] CI=383048635 CI.branch=0  ci=383048635 callIns=0 handle=0 handle2=0


+++ So in our DA results trace here is the line that showed which device this call was extended to +++

71463202.003 |12:24:11.973 |AppInfo  |SMDMSharedData::findLocalDevice - Name=SYS_US1_Cluster_RL Key=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 isActvie=1 Pid=(22,82,58) found


+++ And here we see our CI +++

71463203.001 |12:24:11.973 |AppInfo  |Digit analysis: wait_DmPidRes- Partition=[f183a6a8-0588-ac9e-544a-51eaf097eb94] Pattern=[87555650] Where=[],cmDeviceType=[AccessDevice], OutsideDialtone =[0], DeviceOverride=[0], PID=RouteListControl(22,100,82,58),CI=[383048635],Sender=Cdcc(22,100,212,233043)

 

3.1.5.3 Outbound Leg


Next we need to begin to look at the outbound leg of the call. CUCM has identified the RL in this case to send the call to. One of the most important thing to identify here is the CI for the outbounbd leg of the call. Again there are many ways to find the outbound CI, but I usually use the process called “LBMIF” This is seen in the line below. Note that this process associates the inbound CI to the new

+++ Outbound leg CI +++

71463209.001 |12:24:11.973 |AppInfo |LBMIF: CI: 383048635 ASSOC   383048636

 

3.1.5.4 Route List Control Process

 +++ Next CUCM sends a setup request to the RouteListContorl Process +++

71463214.000 |12:24:11.973 |SdlSig   |CcSetupReq                            |idle                           |RouteListControl(22,100,82,58)   |Cdcc(22,100,212,233043)         |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] CI=383048636

71463214.001 |12:24:11.973 |AppInfo |RouteListControl::idle_CcSetupReq - RouteList(SYS_US1_Cluster_RL), numberSetup=0 numberMember=1 vmEnabled=0

 

+++ Here we see the RL name that CUCM is extending the call to and the CUCM nodes in the RL CUCM group. +++

71463215.003 |12:24:11.974 |AppInfo  |RouteList - RouteListName=''SYS_US1_Cluster_RL'' CallableEndPointName=''efb8b5fc-adb1-e22c-cec8-cd53215d60f6'' routeListEnabled=''1''
71463215.004 |12:24:11.974 |AppInfo  |TDCLdb.hpp - CallManagerGroup - serverCount = 2
71463215.005 |12:24:11.974 |AppInfo  |TDCLdb.hpp - CallManagerGroup - nodeId = 32
71463215.006 |12:24:11.974 |AppInfo  |TDCLdb.hpp - CallManagerGroup - nodeId = 28
71463215.007 |12:24:11.974 |AppInfo  |RouteList - RouteGroup count=''1''

 

 +++ Next CUCM sends a setup request to the gateway in the Route List—Observe that the CI is that of our outbound leg +++

71463218.000 |12:24:11.974 |SdlSig |CcSetupReq |null0 |RouteListCdrc(22,100,83,95826) |RouteListControl(22,100,82,58) |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN
71463218.001 |12:24:11.974 |AppInfo |RouteListCdrc::null0_CcSetupReq check vipr call mViprReroute=0 mViprAlreadyAttempt=0 CI=383048636 BRANCH=0

 

3.1.5.5 Gateway Selection

 +++ Next CUCM does a DmPidReq to locate the device to extend the call to in the Route List +++

71463219.000 |12:24:11.974 |SdlSig   |DmPidReq                               |initialized                    |DeviceManager(22,100,199,1)      |RouteListCdrc(22,100,83,95826)   |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]  Cepn=2576684a-c903-cb8c-aa46-4218b05d684a Id=0
71463219.001 |12:24:11.974 |AppInfo  |SMDMSharedData::findAliasRegInfo - AliasName = 2576684a-c903-cb8c-aa46-4218b05d684a not in AliasInfo hashmap
71463219.002 |12:24:11.974 |AppInfo  |DeviceManager::star_DmPidReq - RequestedName=2576684a-c903-cb8c-aa46-4218b05d684a LookupName=2576684a-c903-cb8c-aa46-4218b05d684a
71463219.003 |12:24:11.974 |AppInfo  |SMDMSharedData::findLocalDevice - Name=SYS_US_Cluster1 Key=2576684a-c903-cb8c-aa46-4218b05d684a isActvie=1 Pid=(22,74,97) found

 

+++ Next we get a DmPidRes and we see that the call is successfully extended to the device SYS_US_Cluster1 +++

71463220.000 |12:24:11.974 |SdlSig   |DmPidRes                               |select_facility                |RouteListCdrc(22,100,83,95826)   |DeviceManager(22,100,199,1)      |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN
--
71463220.004 |12:24:11.974 |AppInfo  |RouteListCdrc::distributeCall ccSetupReq CI=383048636 BRANCH=0
71463220.005 |12:24:11.974 |AppInfo  |RouteListCdrc::executeRouteAction: EXTEND_CALL_TO_CURRENT_MEMBER – Success

--

71463221.009 |12:24:11.975 |AppInfo |CcmCcmdbSIPNormalizeHelper::getSipDeviceScriptPkidGivenDeviceName: This is a regular SIPTrunk. deviceName - (SYS_US_Cluster1)

 

+++ Next CUCM sends a setup request to the SIP trunk. In my cluster we have multiple CUCM nodes in the sip trunk and we can see all the possible nodes here +++

71463239.000 |12:24:11.976 |SdlSig   |SIPSetupReq                           |wait                           |SIPHandler(22,100,72,1)         |SIPCdpc(22,100,75,50881)         |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0] SignalInfo= SIPInviteNoSdp CcbId=1243347 --TransType=2 --TransSecurity=0 PeerAddr=192.105.12.12:5060 addrList: |ipAddrType=0 (0)192.105.12.12:5060 (1)192.105.12.173:5060 (2)192.105.12.171:5060 (3)192.105.12.11:5060 (4)192.105.12.14:5060 (5)192.105.12.174:5060 (6)192.105.12.172:5060 (7)192.105.12.13:5060| rtp IP:Port=0 isDtmCall=0 rel1xxConfig=0

 

+++ Next cucm randomly chooses a node to extend the INVITE to +++

71463239.017 |12:24:11.977 |AppInfo  |//SIP/Stack/Info/0x9e9e1d08/act_idle_continue_call_setup:
71463239.018 |12:24:11.977 |AppInfo  |//SIP/Stack/Info/0x0/sipSPIProcessTargetInfoDestList: Processing target destination list
71463239.019 |12:24:11.977 |AppInfo  |//SIP/Stack/Info/0x0/sipSPITargetInfoChooseInitialDestinatio: numDests=8; Randomly chosen dest is 4, 192.105.12.14

 

3.1.5.6 Outbound Invite

 +++ Next CUCM sends INVITE out to the chosen node , CUCM appends the outbound CI to the end of the From header+++

71463256.001 |12:24:11.977 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 192.105.12.14:[5060]:
[3209967,NET]
INVITE sip:87555650@192.105.12.14:5060 SIP/2.0
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b5154976ba4
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.14>
Date: Fri, 20 Nov 2015 12:24:11 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11
Supported: timer,resource-priority,replaces
Min-SE:  1800
User-Agent: Cisco-CUCM9.1

 

+++ Next we get a trying +++

71463269.001 |12:24:12.056 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 382 from 192.105.12.14:[5060]:
[3209968,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b5154976ba4
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.14>
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11
CSeq: 101 INVITE
Allow-Events: presence
Content-Length: 0

 

+++ Next we get a 503 service unavailable +++

71463273.001 |12:24:12.057 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 533 from 192.105.12.14:[5060]:
[3209969,NET]
SIP/2.0 503 Service Unavailable
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b5154976ba4
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.14>;tag=931256970
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11
CSeq: 101 INVITE
Allow-Events: presence
Warning: 399 GDN1US-BILRC-1CMS04 "Unable to find a device handler for the request received on port 5060 from 192.105.10.11"
Content-Length: 0


Here see that the node this call was extended to is not configured in the CUCM group assigned to the device pool of the sip trunk and since the run on all active cm node wasn’t checked on the trunk, that node rejected the call

+++ CUCM then proceeds to send INVITE to another node in the remote cluster +++

71463304.019 |12:24:12.247 |AppInfo  |//SIP/Stack/Info/0x9e9e1d08/sipSPISendInvite: Associated container=0x9e92d738 to Invite
71463304.020 |12:24:12.247 |AppInfo  |//SIP/Stack/Transport/0x9e9e1d08/sipSPISendInvite: Sending Invite to the transport layer
71463304.021 |12:24:12.247 |AppInfo  |//SIP/Stack/Transport/0x9e9e1d08/sipSPITransportSendMessage: msg=0x107f2a10, addr=192.105.12.13, port=5060, sentBy_port=0, is_req=1, transp

71463307.001 |12:24:12.247 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 192.105.12.13:[5060]:
[3209979,NET]
INVITE sip:87555650@192.105.12.13:5060 SIP/2.0
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b54480f60aa
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.13>
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11


+++ Next we get a 100 trying +++

71463317.001 |12:24:12.326 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 382 from 192.105.12.13:[5060]:
[3209980,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b54480f60aa
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.13>
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11
CSeq: 104 INVITE
Allow-Events: presence
Content-Length: 0

 

3.1.5.7 Inbound Invite On Remote Cluster


Now we need to go to the remote node that the call has been extended to see what’s happening there. A quick way to find the call in log file on that node is to use the SIP call-ID from the originating node (Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11)

+++ Inbound INVITE +++

80988202.001 |07:24:12.286 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 1116 from 192.105.10.11:[5060]:
[8404018,NET]
INVITE sip:87555650@192.105.12.13:5060 SIP/2.0
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b54480f60aa
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.13>
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11


+++ Next this CUCM node sends a trying and we can correlate this to the trying we received earlier +++

80988206.001 |07:24:12.287 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 192.105.10.11:[5060]:
[8404019,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b54480f60aa
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.13>
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11
CSeq: 104 INVITE
Allow-Events: presence
Content-Length: 0


+++ Next this CUCM node does a DA and allocates a CI for this leg of the call +++


80988231.000 |07:24:12.289 |SdlSig   |DaReq                                  |wait                           |Da(4,100,204,1)                  
|Cdcc(4,100,212,455461)           |4,100,238,1.371806^192.105.10.11^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0]  
CI=74628313 Fqdn=pi=0si1 Cgpn=tn=0npi=0ti=1nd=72403225pi=1si3 DialedNum=tn=0npi=1ti=1nd=87555650User=87555650Host=192.105.12.13Port=5060PassWord=Madder=Transport=4
mDisplayName=RawUrl=sip:87555650@192.105.12.13:5060pi=0si1 requestID=0 DigitAnalysisComplexity=0 CallingUser= IgnoreIntercept=0
80988231.001 |07:24:12.289 |AppInfo  |Digit Analysis: star_DaReq: daReq.partitionSearchSpace(1bc496d8-8ee2-018a-517e-fa9d941724b5),
--
--
80988231.002 |07:24:12.289 |AppInfo  |Digit Analysis: Host Address=192.105.12.13 MATCHES this node's IPv4 address.
80988231.003 |07:24:12.289 |AppInfo  |Digit Analysis: star_DaReq: Matching SIP URL, Numeric User, user=87555650
--
80988231.005 |07:24:12.290 |AppInfo  |Digit Analysis: getDaRes - Remote Destination [] isURI[1]
80988231.006 |07:24:12.290 |AppInfo  |Digit analysis: match(pi="2", fqcn="", cn="72403225",plv="5",
pss="Internal_PT:SYS_E164_OnNet_PT:SYS_LoopBL_INB_CLD_PT:SYS_GK_INB_CLD_PT:SYS_E164_XLAT_GEO_PT", TodFilteredPss="Internal_PT:SYS_E164_OnNet_PT:SYS_LoopBL_INB_CLD_PT:SYS_GK_INB_CLD_PT:SYS_E164_XLAT_GEO_PT", dd="87555650",dac="0")

 

+++ Next we get DA results +++

80988231.007 |07:24:12.290 |AppInfo  |Digit analysis: analysis results
80988231.008 |07:24:12.290 |AppInfo  ||PretransformCallingPartyNumber=72403225
|CallingPartyNumber=72403225
|DialingPartition=Internal_PT
|DialingPattern=87555650
|FullyQualifiedCalledPartyNumber=16317555650
|DialingPatternRegularExpression=(87555650)
|DialingWhere=
|PatternType=Enterprise

--

|CallableEndPointName=[5b4fa37c-2bd1-8712-a000-412f20426ab0]



+++ Next CUCM does a DmPidReq to locate the device to send the call to +++

80988232.000 |07:24:12.290 |SdlSig   |DmPidReq                               |initialized                    |DeviceManager(4,100,199,1)       |Da(4,100,204,1)                  |4,100,238,1.371806^192.105.10.11^*        |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]  Cepn=5b4fa37c-2bd1-8712-a000-412f20426ab0 Id=2806496856
----
80988232.002 |07:24:12.290 |AppInfo  |DeviceManager::star_DmPidReq - RequestedName=5b4fa37c-2bd1-8712-a000-412f20426ab0 LookupName=5b4fa37c-2bd1-8712-a000-412f20426ab0
80988232.003 |07:24:12.290 |AppInfo  |SMDMSharedData::findRemoteDeviceAny - Key=5b4fa37c-2bd1-8712-a000-412f20426ab0 found in RemoteDeviceInfo hashmap - PID(s)=1 Name=87555650:958454d4-0190-b885-adc6-dcebcaef3d7a isActive=1 isDualMode=0 Protocol=LINE Pid=(10,167,52412)


+++ Next we get a DmPidRes and we can also see the CI for this leg of the call here +++

80988233.000 |07:24:12.290 |SdlSig   |DmPidRes                               |wait                           |Da(4,100,204,1)                  |DeviceManager(4,100,199,1)       |4,100,238,1.371806^192.105.10.11^*
80988233.001 |07:24:12.290 |AppInfo  |Digit analysis: wait_DmPidRes- Partition=[958454d4-0190-b885-adc6-dcebcaef3d7a] Pattern=[87555650] Where=[],cmDeviceType=[UserDevice], OutsideDialtone =[0], DeviceOverride=[0], PID=LineControl(10,100,167,52412),CI=[74628313],Sender=Cdcc(4,100,212,455461)
80988234.000 |07:24:12.290 |SdlSig   |DaRes                                  |setup_da                       |Cdcc(4,100,212,455461)           |Da(4,100,204,1)                  |4,100,238,1.371806^192.105.10.11^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI=74628313

 

3.1.5.8 DA Local Device And Remote Device


In DA, CUCM determines if the device its extending the call to is a local device or a remote device. If the device is registered with the CUCM node that is processing the call, then the device is deemed a local device .If the device is remote to the CUCM node that is processing the call, then the device is deemed as a remote device.

So in the previous trace file we saw for the node 192.105.10.11 we have these entries in our DmPidReq:

+++ AppInfo  |SMDMSharedData::findLocalDevice +++

71463202.002 |12:24:11.973 |AppInfo  |DeviceManager::star_DmPidReq - RequestedName=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 LookupName=efb8b5fc-adb1-e22c-cec8-cd53215d60f6
71463202.003 |12:24:11.973 |AppInfo  |SMDMSharedData::findLocalDevice - Name=SYS_US1_Cluster_RL Key=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 isActvie=1 Pid=(22,82,58) found


We can see the line “findLocalDevice” this tells us that this RL is registered to this node

In this trace below file we see the “findRemoteDeviceAny” this tells us that the device is not registered to this node

+++ AppInfo  |SMDMSharedData::findRemoteDeviceAny +++

80988232.002 |07:24:12.290 |AppInfo  |DeviceManager::star_DmPidReq - RequestedName=5b4fa37c-2bd1-8712-a000-412f20426ab0 LookupName=5b4fa37c-2bd1-8712-a000-412f20426ab0
80988232.003 |07:24:12.290 |AppInfo  |SMDMSharedData::findRemoteDeviceAny - Key=5b4fa37c-2bd1-8712-a000-412f20426ab0 found in RemoteDeviceInfo hashmap - PID(s)=1 Name=87555650:958454d4-0190-b885-adc6-dcebcaef3d7a isActive=1 isDualMode=0 Protocol=LINE Pid=(10,167,52412)


From the trace above there are key things to know:

  • Pid=Process ID responsible for this device. The format of the PID= Process name (Node_id, Process Type, process instance)
  • Pid=(10,167,52412):
    • 10= Node_Id where the device isregistered to
    • 167=Process type which in this case is LineControl
  • Once we see this we know that this node will need to send a SDL signal to CUCM node 10 (192.105.12.174)
  • Protocol=LINE: The protocol identifies what this device is. Here it is a DN.
  • PID(s)=1 Name=87555650:958454d4-0190-b885-adc6-dcebcaef3d7a: This tells us the DN and the pkid for the partition of the DN.We can use the following SQL query to find the partition.
run sql select name from routepartition where pkid = ”958454d4-0190-b885-adc6-dcebcaef3d7a”

3.1.5.9 SDL Signal To CUCM Node Where Jabber Is registered

Next CUCM needs to allocate a CI for the outbound leg of the call and extend the call to the node where the device is registered

+++ Here we see CUCM associate the inboud CI to the outbound CI +++

80988255.000 |07:24:12.291 |SdlSig   |CACAssociateReq                        |connecting                     |LBMInterface(4,100,169,1)        |ReservationMgr(4,100,103,1)      |4,100,238,1.371806^192.105.10.11^*        |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI= 74628313  aCI=74628313 bCI=74628314 isASerCI=F isBSerCI=F sendResp=F mcNodeId=0
80988256.000 |07:24:12.291 |SdlSig   |PolicyAndCACAssociateRes               |wait                           |Cc(4,100,213,1)                  |ReservationMgr(4,100,103,1)      |4,100,238,1.371806^192.105.10.11^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI= 74628313  aCI=74628313 bCI=74628314 isASerCI=F isBSerCI=F sendResp=F mcNodeId=0
80988255.001 |07:24:12.291 |AppInfo  |LBMIF: CI: 74628313 ASSOC    74628314
80988255.002 |07:24:12.291 |AppInfo  |LBMIF: CI: 74628314 ASSOC'   74628313



+++ Next CUCM sends an outbound SDL setup request to the node +++

80988259.000 |07:24:12.291 |SdlSig-O |CcSetupReq                             |NA RemoteSignal                |LineControl(10,100,167,52412)    |Cdcc(4,100,212,455461)           |4,100,238,1.371806^192.105.10.11^*        |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] CI=74628314


key things to note in this trace file

  • SdlSig-O: This indicate the SDL operation. Indicates if the Signal Is Local to the Server (SdlSig),Inbound from Another Node in the Cluster (SdlSig-I), or Out to Another Node in the Cluster (SdlSig-O). In our case we see that is is outbound to another node
  • CcSetupReq: This indicates the SDL signal name that is being sent from the source process to the destination process
  • RemoteSignal                |LineControl(10,100,167,52412): This indicates a remote signal sent to the CUCM process on node 10. (10,100,167,52412)

(10=node10, 100=CUCM process, 167=LineControl (process type))

  • Cdcc(4,100,212,455461): This shows where the SDL request originates from. Its from node 4 (this node) and it is Cdcc process of the cucm sending it.

 

3.1.5.10 Inbound SDL Signal To The CUCM NODE10

Now we need to go to the node 10 and see what happens to this request
The quickest way to find this call on node10 is to use the CI=74628314

+++ CUCM node10 receives the inbound SDL setup request +++

50128650.000 |07:24:12.301 |SdlSig-I |CcSetupReq                             |restart0                       |LineControl(10,100,167,52412)    |Cdcc(4,100,212,455461)           |4,100,238,1.371806^192.105.10.11^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI=74628314


+++ Next CUCM node10 processes the requests. The trace file below shows the relevant information needed to process this. The sip RepUri, Aor etc +++

50128666.008 |07:24:12.324 |AppInfo  |SIPCdpc(1863930) - getDefSetup: ReqURI is present: sip:5b4fa37c-2bd1-8712-a000-412f20426ab0@192.105.12.135:5060;transport=tcp;orig-hostport=62.191.28.104:50183
--
|07:24:12.324 |AppInfo  |SIPCdpc(1863930) - checkAorInToHeader: Using To header AoR sip:87555650@192.105.12.174
50128666.013 |07:24:12.324 |AppInfo  |SIPCdpc(1863930) - CcPtyNumIdEq: Comparing @, dn: 87555650, ti: DN with @, dn: 87555650, ti: DN, result: true
50128666.014 |07:24:12.324 |AppInfo  |SIPCdpc(1863930) - CcPtyNumIdEq: Comparing @, dn: 87555650, ti: DN with @, dn: 87555650, ti: DN, result: true



+++ Next CUCM sends a setup request to the SIPHandler process on this node +++

50128668.000 |07:24:12.324 |SdlSig   |SIPSetupReq                            |wait                           |SIPHandler(10,100,72,1)          |SIPCdpc(10,100,75,1863930)       |4,100,238,1.371806^192.105.10.11^*        |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]  SignalInfo= SIPInviteNoSdp CcbId=5745657 --TransType=1 --TransSecurity=0 PeerAddr=192.105.12.135:5060 addrList: || rtp IP:Port=0 isDtmCall=0 rel1xxConfig=0


+++ Next we get a SIPProceedInd (call proceeding) which indicates that the SIPHandler process has accepted the request and processing it +++

0128668.022 |07:24:12.324 |AppInfo  |//SIP/Stack/Transport/0x0/sipSPIUpdateResponseInfo: Dialog Transaction Address 192.105.12.135,Port 5060, Transport 2, SentBy Port 5060
50128671.000 |07:24:12.324 |SdlSig   |SIPProceedInd                          |wait                           |SIPStationD(10,100,66,854)       |SIPHandler(10,100,72,1)          |4,100,238,1.371806^192.105.10.11^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0]  CcbId= 5745657 --TransType=1 --TransSecurity=0 PeerAddr = 192.105.12.135:5060


+++ Next CUCM sends a callproceeding via SDL to the requesting node (node 4) +++

50128676.000 |07:24:12.324 |SdlSig-O |CcProceedInd                           |NA RemoteSignal                |Cc(4,100,213,1)                  |LineCdpc(10,100,168,332054)      |4,100,238,1.371806^192.105.10.11^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI=74628314

 

3.1.5.11 CUCM Node10 Call Progress

+++ Next CUCM proceeds to send the outbound INVITE to expressway-C +++

50128668.027 |07:24:12.324 |AppInfo  |//SIP/Stack/Transport/0xa4b3b598/sipSPISendInvite: Sending Invite to the transport layer
50128668.028 |07:24:12.324 |AppInfo  |//SIP/Stack/Transport/0xa4b3b598/sipSPITransportSendMessage: msg=0xa496da60, addr=192.105.12.135, port=5060, sentBy_port=0, is_req=1, transp
--
--
50128677.001 |07:24:12.324 |AppInfo  |SIPTcp - wait_SdlSPISignal: Outgoing SIP TCP message to 192.105.12.135 on port 5060 index 12281
[29778977,NET]
INVITE sip:5b4fa37c-2bd1-8712-a000-412f20426ab0@192.105.12.135:5060;transport=tcp;orig-hostport=62.191.28.104:50183 SIP/2.0
Via: SIP/2.0/TCP 192.105.12.174:5060;branch=z9hG4bK5eb17b335aa8e7
From: "Mike Hannan" <sip:72403225@192.105.12.174>;tag=5745657~52c1d180-11c8-49c2-8c0b-dea47e22e0b7-74628314
To: <sip:87555650@192.105.12.174>
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99dc0380-64f110ec-28a88e-ae2a690a@192.105.12.174
Supported: timer,resource-priority,replaces
Min-SE:  1800
User-Agent: Cisco-CUCM9.1



+++ Next we get a 100 trying from EXPRESSWAY-C +++

50128680.002 |07:24:12.330 |AppInfo  |SIPTcp - wait_SdlReadRsp: Incoming SIP TCP message from 192.105.12.135 on port 5060 index 12281 with 407 bytes:
[29778978,NET]
SIP/2.0 100 Trying
Via: SIP/2.0/TCP 192.105.12.174:5060;branch=z9hG4bK5eb17b335aa8e7;received=192.105.12.174;ingress-zone=CEtcp1010542174
Call-ID: 99dc0380-64f110ec-28a88e-ae2a690a@192.105.12.174


+++ Next we get a 180 ringing +++

50128694.002 |07:24:12.539 |AppInfo  |SIPTcp - wait_SdlReadRsp: Incoming SIP TCP message from 192.105.12.135 on port 5060 index 12281 with 822 bytes:
[29778982,NET]
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 192.105.12.174:5060;branch=z9hG4bK5eb17b335aa8e7;received=192.105.12.174;ingress-zone=CEtcp1010542174
Call-ID: 99dc0380-64f110ec-28a88e-ae2a690a@192.105.12.174
CSeq: 101 INVITE


+++ Next CUCM sends the alert to node4 via SDL +++

50128709.000 |07:24:12.540 |SdlSig-O |CcAlertInd                             |NA RemoteSignal                |Cc(4,100,213,1)                  |LineCdpc(10,100,168,332054)      |10,100,13,73940.14^192.105.12.135^*       |[R:N-H:0,N:1,L:0,V:0,Z:0,D:0] CI=74628314

 

3.1.5.12 CUCM Node4 Call Progress

+++ On CUCM node 4 we receive the inboud SDL alert +++

80988280.000 |07:24:12.550 |SdlSig-I |CcAlertInd                             |wait                           |Cc(4,100,213,1)                  |LineCdpc(10,100,168,332054)      |10,100,13,73940.14^192.105.12.135^*       |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI=74628314


+++Next CUCM node4 sends a 180 ringing to the remote cluster +++

80988289.001 |07:24:12.551 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 192.105.10.11:[5060]:
[8404020,NET]
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b54480f60aa
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.13>;tag=3227903~52c1d180-11c8-49c2-8c0b-dea47e22e0b7-74628313
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11

 

3.1.5.13 CUCMUK Node22 Call Progress

+++ Back on the remote UK cluster we see the call progress message arriving +++

71463385.001 |12:24:12.591 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 913 from 192.105.12.13:[5060]:
[3209981,NET]
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b54480f60aa
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.13>;tag=3227903~52c1d180-11c8-49c2-8c0b-dea47e22e0b7-74628313
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11


+++ Next CUCM node22 sends the ringing out to UK-expressway-C +++

71463410.001 |12:24:12.593 |AppInfo  |SIPTcp - wait_SdlSPISignal: Outgoing SIP TCP message to 192.105.10.5 on port 25057 index 2145
[3209982,NET]
SIP/2.0 180 Ringing
Via: SIP/2.0/TCP 192.105.10.5:5060;egress-zone=CEtcp101054011;branch=z9hG4bK0eaf0237eaaffecea193409900fe09a162780;proxy-call-id=dc7814d2-4204-4d4b-b738-3819d23a213f;rport,SIP/2.0/TLS 192.105.10.5:5073;branch=z9hG4bKe121c1f328d1abaa38fafd2c9374daa84183;x-cisco-local-service=nettle;received=192.105.10.5;rport=34815;ingress-zone=DefaultZone,SIP/2.0/TLS 192.105.10.5:5061;egress-zone=DefaultZone;branch=z9hG4bK62be10dc342a46137249a40f67264bbf62779.c7f78fcb7f0f7be0456ab31b3c665219;proxy-call-id=b1f2edca-168b-4636-a479-3c61a15636c4;received=192.105.10.5;rport=25015,SIP/2.0/TLS 10.106.3.84:7001;egress-zone=ExpweTraversal;branch=z9hG4bK5e974241584e1cd038ddd27724b21cf094883.ee2c868e6dc530b149461a661a30df3e;proxy-call-id=a8ffb6ac-d968-4253-b007-ccc10ddd9191;received=10.106.3.84;rport=7001;ingress-zone=ExpwcTraversal,SIP/2.0/TLS 192.168.0.7:38056;branch=z9hG4bK6b59edc9;received=86.29.4.226;rport=38056;ingress-zone=CollaborationEdgeZone
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=73f64906ee9200341e7558b1-346a1ebf
To: <sip:87555650@192.105.10.11>;tag=1243346~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048635
Date: Fri, 20 Nov 2015 12:24:11 GMT
Call-ID: 73f64906-ee92000c-0954f6c3-4fcae256@192.168.0.7

 

3.1.5.14 CUCM Node10 Call Progress

+++ CUCM node10 receives a 200 Ok from expressway-C > NB I have omitted the SDP +++

50128752.002 |07:24:15.516 |AppInfo  |SIPTcp - wait_SdlReadRsp: Incoming SIP TCP message from 192.105.12.135 on port 5060 index 12281 with 2685 bytes:
[29778988,NET]
SIP/2.0 200 OK
Via: SIP/2.0/TCP 192.105.12.174:5060;branch=z9hG4bK5eb17b335aa8e7;received=192.105.12.174;ingress-zone=CEtcp1010542174
Call-ID: 99dc0380-64f110ec-28a88e-ae2a690a@192.105.12.174
CSeq: 101 INVITE


+++ next CUCM computes SDP and sends SDP offer via SDL to node4 +++

50128773.000 |07:24:15.582 |SdlSig-O |SDPOfferInd                            |NA RemoteSignal                |SIPInterface(4,100,69,85035)     |SIPCdpc(10,100,75,1863930)       |10,100,13,73940.15^192.105.12.135^*       |[R:N-H:0,N:3,L:0,V:0,Z:0,D:0]  nAudio=1 stackIdx=1 audioCapCount=7 Caps[6(20),40(0),41(0),4(20),2(20),11(20),12(20)] port=54890 IP= ipAddrType=0 ipv4=192.105.12.135 SDPMode=0 mediaAttr=0x0 SP=F RTP=T SRTP=F idle=F QoS=FenabledMask=0rtcbFbCount=0LatentCaps=null ~nVideo=2 stackIdx=2 videoCapCount=2, [103 pt=96 h235=0],[103 pt=97 h235=0] port=54892 ipAddrType=0 ipv4=192.105.12.135

 

3.1.5.15 CUCM Node4 Call Progress

+++ Back on CUCM node 4 we receive the SDP offer via SDL +++

80988381.000 |07:24:15.592 |SdlSig-I |SDPOfferInd                            |waitSDPResponse                |SIPInterface(4,100,69,85035)     |SIPCdpc(10,100,75,1863930)       |10,100,13,73940.15^192.105.12.135^*       |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0]  nAudio=1 stackIdx=1 audioCapCount=7 Caps[6(20),40(0),41(0),4(20),2(20),11(20),12(20)] port=54890 IP= ipAddrType=0 ipv4=192.105.12.135


+++ Next CUCM node4 computes its SDP offer and sends a 200 OK to CUCM node 22 (remote node) +++

80988412.001 |07:24:15.593 |AppInfo  |//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP message to 192.105.10.11:[5060]:
[8404021,NET]
SIP/2.0 200 OK
Via: SIP/2.0/UDP 192.105.10.11:5060;branch=z9hG4bK114b54480f60aa
From: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
To: <sip:87555650@192.105.12.13>;tag=3227903~52c1d180-11c8-49c2-8c0b-dea47e22e0b7-74628313
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11

 

3.1.5.16 CUCMUK Node22 Call Progress

Now we should receive the 200 OK sent by CUCM node4, but we never did
The next event we see on this node is a BYE sent from node4

 

71471172.001 |12:24:35.206 |AppInfo  |//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP message size 506 from 192.105.12.13:[5060]:
[3209999,NET]
BYE sip:72403225@192.105.10.11:5060 SIP/2.0
Via: SIP/2.0/UDP 192.105.12.13:5060;branch=z9hG4bK193885132d5402
From: <sip:87555650@192.105.12.13>;tag=3227903~52c1d180-11c8-49c2-8c0b-dea47e22e0b7-74628313
To: "Mike Hannan" <sip:72403225@192.105.10.11>;tag=1243347~ffa80926-5fac-4dd6-b405-2dbbc56ae9a2-383048636
Date: Fri, 20 Nov 2015 12:24:12 GMT
Call-ID: 99436d00-64f110eb-1018c6-b28690a@192.105.10.11
User-Agent: Cisco-CUCM9.1
Max-Forwards: 70
CSeq: 101 BYE
Reason: Q.850;cause=86
Content-Length: 0


For this particular issue there was a network related problem causing 200 OK sent via UDP to be dropped.

4.1 Summary

Congratulations if you stayed with me till the end of this and endure all of my rantings. This was a monster of a trace. But it did help us to analyse in detail many of the moving parts within a CUCM process.
It’s no easy task troubleshooting complex issues within a CUCM . Having the right tools, knowing where to look and what to look for will go a long way in separating the men from the boys and ccie(s) from CCIE(S) :)

I do hope this has been useful. Please feel free to ask questions and dont forget to rate if you absolutely love it!

Comments

Hi, I have hard time understanding the difference between 3 tuple and 4 tuple ID's formed at different point of time.  Are they different ?

As you mentioned PID is 3 tuple, when are 4 tuple process created, please clarify.

Thanks.

Beginner

Thanks for the great trace troubleshooting primer.  

I'm troubleshooting intermittent one-way audio issues.    Trying to uncover what's happening.  

Can you provide insight into were codec negoation is located.  

Community Member

awesome Ayodeji

VIP Mentor

Thanks Cariap

Dont forget to rate the document

Beginner

Hi, Ayodeji! Please, help me! I have some problems with my Cisco RTMT. I can not download logs. I download logs with wrong times. I attached the screen from my RTMT.

VIP Mentor

This usually happens when the timezone of your computer is different from the timezone on your cucm cluster.  You can either allow RTMT to automatically set the timezone for you or you can manually adjust the time on RTMT to the timezone of your cucm cluster. When you login to RTMT it will prompt you if the time zone on your pc is different from the time zone on your cucm cluster

Beginner

Thank you.

VIP Mentor

Please open a new thread in the IP telephony section of the forum. Describe the issue and attach the logs there.

Community Member

Hi Jitender,

Thanks for more details.

Also, could you please explain(in Red), how RouteListControl and Cdcc are interacting> I know the meaning of each term in () but what's happening with all the codes mentioned, I don't understand,

71463214.000 |12:24:11.973 |SdlSig   |CcSetupReq                            |idle                           |RouteListControl(22,100,82,58)   |Cdcc(22,100,212,233043)         |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] CI=383048636

There are other similar lines too,

71463219.000 |12:24:11.974 |SdlSig   |DmPidReq                               |initialized                    |DeviceManager(22,100,199,1)      |RouteListCdrc(22,100,83,95826)   |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]  Cepn=2576684a-c903-cb8c-aa46-4218b05d684a Id=0

Few more terms I want to know about,

Cdpc, Cdcc

Thanks,

Rakhi Saxena

VIP Mentor

Rakhi,

71463214.000 |12:24:11.973 |SdlSig   |CcSetupReq                            |idle                          |RouteListControl(22,100,82,58)   |Cdcc(22,100,212,233043)         |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] CI=383048636

The Cdcc (child process of the call control process) in this instance is sending a call setup request to the RouteListContorl process. Why is this the case? This is because after DA, CUCM determines that this call needs to be routed to this process and hence since the Cdcc is responsible for call control, it then sends the request to the destination process (which in this case is the route list control process)

71463219.000 |12:24:11.974 |SdlSig   |DmPidReq                               |initialized                   |DeviceManager(22,100,199,1)      |RouteListCdrc(22,100,83,95826)   |22,100,13,149006883.780^192.105.10.5^BOTMHANNAN |[T:N-H:0,N:0,L:0,V:0,Z:0,D:0]  Cepn=2576684a-c903-cb8c-aa46-4218b05d684a Id=0

Now that the RouteListControl has received the request it then needs to extend the call to members of the particular route list that was called. However these members are devices that are managed by the DeviceManager. So the RouteList Control process sends a request to the DeviceManager.

The DeviceManager-maps CEPN to the PID of its controlling process. We can see this in the trace here as well.

The device manager locates the PID of the called device ( here it was a sip trunk)

71463202.002 |12:24:11.973 |AppInfo  |DeviceManager::star_DmPidReq - RequestedName=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 LookupName=efb8b5fc-adb1-e22c-cec8-cd53215d60f6
71463202.003 |12:24:11.973 |AppInfo  |SMDMSharedData::findLocalDevice - Name=SYS_US1_Cluster_RL Key=efb8b5fc-adb1-e22c-cec8-cd53215d60f6 isActvie=1 Pid=(22,82,58) found

In summary CallManager interaction takes a very structured and layered approach. When a call comes in we pass the call to the CC ( call control layer), This is then passed on to the Cdcc( child process of CC which is unique for each call), then if we need to talk to a Route List, we pass the call to the RouteListControl Process, if that process needs to talk to a device, we pass the request to the DeviceManager, if that device is a sip trunk we send the request to a SIPCdpc which then sends it to a SIPHandler process and on and on.

There is a process responsible for each request/response. If we need to connect two call legs for media we call on the Media Layer which has several processes such as ConnectionManager,MediaManager, MediaControl etc.

Excellent Document...!!!

Beginner

Hi Deji!

 

What an inspiration you are!  You never cease to amaze me with your attention to detail.  You are a blessing to many!

 

Amir

Beginner

Hi Ayodeji,

 

Always thank you for sharing valuable information.
I would like to know what is capcount (11,1) and xfermode in sdl traces of CUCM, what Value of capcount defines which codec and xfermode defines what?

Could you help me with a document which share that information?

Thank you

Cisco Employee
I made a video about how to setup jEdit for reading logs so that others can see it is a great tool after you optimize it for reading logs. https://www.youtube.com/watch?v=AXslHfpJ5HM Let me know what you think.
CreatePlease to create content
Content for Community-Ad
August's Community Spotlight Awards
This widget could not be displayed.