Introduction
Reading traces can be complicated at first and seem like going through something in the matrix, but once you get to familiarize yourself with more and more different traces, you start seeing that all of them have a lot in common and we can use the same pattern to read all of them. There are basically 4 different Call Signalling Protocols (the messages or language that CUCM (and other PBX systems) uses to establish and tear down calls between endpoints) we need to learn to be able to understand almost any call trace: SCCP, SIP, H323, MGCP(and Q.931).
Generally you'll see endpoints like phones use SCCP or SIP, and devices like Gateways will use H.323 or MGCP. These are the most common but you'll also see Gateways that use SIP (CUBEs) and SCCP (VG224) as well. You might even see a phone use H.323.
Whatever the case may be, the call signalling is the same within corresponding protocols. This means you'll be able to follow any call on any endpoint by just learning how to read these 4 protocols. However, altough the call signalling remains the same, it can get more in more complex when there are multiple call legs, different calling features (Hold, Conference) are invoked, or if different Call Applications (UCCX, UCCE) are being used. Because of this, this guide will center on a basic call; Call is established from an endpoint and sent to the CUCM for routing. Later on, I might add a guide to Advanced Call Signaling Traces.
For now, we'll view these basic calls being established with each of the protocols. I won't go through every possible scenario but hopefully I can give you enough of a general understanding to be able to look at a trace and use common sense to understand what you are seeing, even if you see a message that isn't in this guide.
SCCP (Skinny Call Control Protocol)
As mentioned earlier, you'll usually see SCCP being used with a SCCP phone, but it can also be used to communicate with other devices (Unity Voicemail, VG224). We'll look at how a SCCP phone starts a call. Here's a great way of finding the start of a SCCP call:
17:07:31.342 |StationInit: (0000002) SoftKeyEvent softKeyEvent=2( NewCall) lineInstance=0 callReference=0.|1,100,49,1.1464^10.1.200.53^SEP001B2A89C420)
We'll analyze the important parts.
But first, there's one thing we need to know: SCCP phones are really dumb. They can't really do anything without CUCM holding their hand. This means that you'll be able to see every single message that they send to each other. For example: SCCP phone tells CUCM "Hey, someone just took my receiver 'Offhook'" or "Hey, someone just pressed the 'New Call' Softkey". CUCM will respond with "OK, well why don't you turn on your "InsideDialTone' and display 'Enter Number' on your screen?"
These conversations are a great way to track every single step of the call. You'll notice in the above example we clearly read: SoftKeyEvent softKeyEvent=2( NewCall), we obviously understand that this means that the "New Call" softkey as been pressed.
Ok, that's easy to understand, but how do we know if this message is coming to CUCM or going to the phone? Notice the first part of the message: StationInit. This is important. StationInitmeans that this message is coming from the phone to CUCM (this might have been obvious here because a softkey will usually be pressed on a phone, but knowing the direction of a message is extremely useful and necessary to know for other parts of the call). When CUCM sends a message to the phone, instead of StationInit we'll see a StationD:
17:07:31.756 |StationD: (0000002) DisplayPromptStatus timeOut=0 Status='€ ' content='Enter Number'
Here we see CUCM is sending back the message "Display 'Enter Number'" on the phone. Knowing how phone's work, this makes sense.
Lastly, we need to know how to follow these messages. Many calls may be happening at the same time on a single page of traces so we can easily get lost. Notice what stayed the same with those above two messages? (0000002). This is called the TCP handle and will stay the same for the entire call so we can use it to track it. However, this number is actually associated with which SCCP device in use since its start up; the traces will show all messages to and from that device since that time. This means that yes we'll be able to use it to track a single call, but we'll need to know exactly when the call started and when it will end.
And that's how you follow a SCCP call. Now all that's left is to be familiar with what you are going to see for the rest of the call being established and connected:
Here you'll find all the expected messages you'll see in SCCP call trace.
SIP Session Initiation Protocol
SIP messages can come from a SIP Gateway (CUBE), a SIP trunk, or a SIP phone. The messages and call setup is the same on all devices. We'll take a look a call starting on a SIP phones here, but remember, you can expect to see the same messages on other SIP devices. SIP phones are a lot smarter than SCCP phones, they don't need CUCM to tell them what they have to do, they just need CUCM to help them establish the call.
The first message starting the call will be the SIP INVITE, which will look like this:
* Note: We won't look at SDP here.
There is a lot of information here, altough all of it can be useful for various reasons, we are only going to need to look at a few things to follow the call.
First off, to make sure we have the right invite for the right call, we can look at the time stamp, and the Calling and Called Numbers. Here we see INVITE sip:1012@10.10.210.254, which means the SIP message is directed to this Called Number (This could be right after these digits were dialed, or if the INVITE is forwarded from another device other than its source).
The Calling Number can be determined from the "From:" field: From: "Alex" <sip:1010@10.10.210.6> (*Note: The "From:" field is only reliable when seen on the initial INVITE, afterwards the "Via:" field will give us a more accurate source).
Once we've determined that this is in fact the first message of our call. We'll need to follow the call.
Just like the SCCP call, the direction of the messages being sent are important. On SIP calls this is extremely easy to tell, we can see it in the line above the INVITE: Incoming SIP TCP message from 10.10.210.6.
Remember that we are looking at the traces from the CUCM's perspective, it is receiving the first INVITE from the phone, so the message is Incoming.
Let's look at the next message:
14:34:04.529 |//SIP/SIPTcp/wait_SdlSPISignal: Outgoing SIP TCP message to 10.10.250.254 on port 5060 index 21325
[3389738,NET]
SIP/2.0 100 Trying Via: SIP/2.0/TCP 10.10.210.6:5060;branch=z9hG4bKc75d626a683ff
From: "Alex" <sip:1010@10.10.210.6>;tag=1266361~acaf1725-ef0a-44a5-89dd-e7a619b1c328-38813420
To: <sip:918002869247@10.10.250.254>
Date: Tue, 14 Oct 2014 18:05:25 GMT
Call-ID: dfb6b780-43d16cf4-a5cf3-6d20a0a@10.10.210.6
CSeq: 101 INVITE
Allow-Events: telephone-event
Content-Length: 0
So first thing we notice in the next message - which is a TRYING, is the message is now Outgoing. It's going from the CUCM back to the phone. And we also see that the Call-ID: dfb6b780-43d16cf4-a5cf3-6d20a0a@10.10.210.6 is identical to the one in the INVITE message. This is what is used to track that entire leg of the call. The call-ID will show all messages between the CUCM and the SIP phone until the end of the call.
And one last piece of useful information is this: CSeq: 101 INVITE. This is the sequence message, with this we can see what this SIP message is replying to. This 100 Trying was sent in response to the 101 Invite
And that's it, you'll follow the rest of the messages the same way using the Call-ID field. Here's what the rest of the SIP message exchange will look like:
Simple. Just imagine "Bob" is in fact a "CUCM" server.
H.323
As mentioned in the introduction, some phones do send H.323 messages but we won't be working with them often, it will usually be a H.323 gateway or H.323 Trunk. That being said, there's really no difference in reading H.323 traces for these devices. In this example we will see a call being initiated on the CUCM side which needs to go to the PSTN using a H.323 gateway. This will be the first message sent to the Gateway.
*Along with the H.225 message body there is also a compact printout of the H.225 message:
11:45:32.193 CCM|Out Message -- H225SetupMsg -- Protocol= H225Protocol
11:45:32.193 CCM|Ie - H225BearerCapabilityIe IEData= 04 03 80 90 A2
11:45:32.193 CCM|Ie - H225CallingPartyIe IEData= 6C 09 00 81 37 30 32 31 30 30 34
11:45:32.193 CCM|Ie - Q931CalledPartyIe IEData= 70 08 80 38 30 31 31 30 30 30
11:45:32.194 CCM|IsdnMsgData2= 08 02 00 03 05 04 03 80 90 A2 6C 09 00 81 37 30 32
It looks a little different and harder to read than the other traces, but you'll see it's just as simple. The first thing we'll check is which direction the message is going. This can be seen in the H.225 output message: Out Message --H225SetupMsg. This tells us that the message is leaving CUCM and it's a "Setup" message which indicates the beggining of the call.
Next we can find the Called Number and Calling Number in the H.225 output as well. "H225CallingPartyIe IEData= 6C 09 00 81 37 30 32 31 30 30 34" and "Q931CalledPartyIe IEData= 70 08 80 38 30 31 31 30 30 30" show these. The string of numbers that have 3's in front of them will be our digit information, remove the 3s and you'll have the accurate phone numbers. In this example, the Calling Number is 7021004 and the Called Number is 8011000 .
And lastly, to follow the messages there are actually two call identifiers. One is highlighted in the "guid" field: 807B41849C7D31C2030003010E302CCF'H. The other is again in the compact H.225 message in the ISDNMsgData2 field: 08 02 00 03 05 04 03 80 90 A2 6C 09 00 81 37 30 32. The 6th, 7th and 8th digits will be the same throughout all H.323 messages of the same call. These are the rest of the messages.
Feel free to ignore the Russian.
MGCP (and Q.931)
MGCP (Media Gateway Control Protocol) is a master/slave protocol that allows a call control device (CUCM) to take control of a specific port on a gateway. MGCP is also often used with CUCM as a PRI Backhaul. This occurs when CUCM takes control of the Q.931 signaling data used on an ISDN PRI. That's why we'll usually see MGCP messages with Q.931 messages following them closely. Here's the first message we'll see:
06/20/2014 16:00:32.354 CCM|MGCPHandler send msg SUCCESSFULLY to: 10.10.33.1
CRCX 101444 S0/SU0/DS1-0/23@GDF-VG2811 MGCP 0.1
C: D0000000020df28f000000F500000cc8
X: 17
L: p:20, a:PCMU, s:off, t:b8
M: recvonly
R: D/[0-9ABCD*#]
Q: process,loop
Here's the Q.931 information that follows:
06/20/2014 16:00:32.371 CCM|Out Message -- PriSetupMsg -- Protocol= PriNi2Protocol|<CLID::StandAloneCluster><NID::10.10.33.11><LVL::Significant><MASK::0040>
06/20/2014 16:00:32.371 CCM|Ie - Ni2BearerCapabilityIe IEData= 04 03 80 90 A2 |<CLID::StandAloneCluster><NID::10.10.33.11><LVL::State Transition><MASK::0040>
06/20/2014 16:00:32.371 CCM|Ie - Q931ChannelIdIe IEData= 18 03 A9 83 97 |<CLID::StandAloneCluster><NID::10.10.33.11><LVL::State Transition><MASK::0040>
06/20/2014 16:00:32.371 CCM|Ie - Q931DisplayIe IEData= 28 0C 41 64 6D 69 6E 2C 20 4C 69 6E 6B 73
06/20/2014 16:00:32.371 CCM|IsdnMsgData2= 08 02 00 06 05 04 03 80 20 A2 6C 09 00 81 37 30 54
The first message that will establish a call will be the MGCP "CRCX" (Create Connection) message and the ISDN "PriSetupMsg" message.
To track the call, we can use some values found in the MGCP message and Q.931 message (because of how descriptive the Q.931 messages are, it will be easier to follow the call using them). For MGCP we have C: D0000000020df28f000000F500000cc8, this will be the same throughout the call. In the ISDN message we use the same value as we did in H.323: the 6th, 7th and 8th value in the "IsdnMsgData2= 08 02 00 06 05 04 03 80 20 A2 6C 09 00 81 37 30 54" message. Also like H.323, we can see the direction of the message with "Out Message".
And that's all you need to track a MGCP call. Altough the rest of values in the MGCP message looks like nonsensical code, with a little research you'll find that the information there can be very valuable and help with troubleshooting an issue.
Here is the rest of the MGCP call signaling conversation:
When the call ends, you'll see a DLCX (Delete Connection) MGCP message and a ReleaseComplete Q.931 message.
Now you are ready
Hopefully, this guide gave you the tools you need to read any trace, understand where you are in the call and see where something might be wrong. Now, we've looked at each of the Call protocols individually, but calls usually have two legs (or more). You have one endpoint sending the call to CUCM and then CUCM establishing that call with the receiving endpoint. Each of these call legs can use a different Call Signaling Protocol. So how you can you follow both?
You've probably noticed that I added diagrams for the call flow for each of the protocols. Establishing phone calls isn't much different between them; they follow the same process. There's a message that starts to SETUP the call (Setup, Invite, CRCX), next the call will ring (Alerting, 190 Ringing), the call will then try to CONNECT (200 OK/ACK, MDCX) and lastly, the call will end (ReleaseComplete, DLCX, BYE). That's it.That's what you will see over and over again no matter what the call signalling protocol. Here's an example of how a call flow looks like with different call protocols on each side:
Notice how you can match up the messages between them or at the very least, see in which order they happen.
And that's all you need to know about traces...
well...not exactly.
However, you do now have a solid foundation for understanding any of them. It may seem like a lot of information to process now, but the key detail to keep in mind is: Remember the pattern. The more traces you'll see, the more familiar they'll get.
*Note: There are multiple ways to track a single call, one way would be looking for the CI=191015415 (Call Identifier) (this is present with any call, no matter the protocol) which will be found within the SDL trace lines. To learn more ways of tracking a call and more about SDL trace lines, you'll need to dive deeper into SDL Process Signals.
Other References
What traces to look up for different scenarios: https://supportforums.cisco.com/document/126941/cucm-trace-lookup-different-scenarios
How to read h.323 traces: https://supportforums.cisco.com/document/44911/tracking-h323-calls-cucm-sdi-traces
And another guide on the process: http://www.techphilosophy.com/2008/09/understanding-cisco-callmanager-traces.html
