- 1.1 Introduction
- 2.1 Collecting CUCM logs
- 2.2 CUCM Nodes To Download Logs From
- 3.1 Analysing Logs
- 3.1.1 The Anatomy Of A Trace File
- 3.1.2 References
- 3.1.3 Dive In
- 3.1.5 Task 2: Open Up The Traces In notepad++
- 4.1 Summary
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?
- Translator X (http://translatorx.org/)
- Notepad++
- Wingrep
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 |
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 +++
|
: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: |CallableEndPointName=[efb8b5fc-adb1-e22c-cec8-cd53215d60f6] -- |
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 -- 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]: |
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 -- |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!
