Unfortunately, you can't say things like "well, I know the codec is G711 because the phone told me so (double "?")" nor can you use explanations such as: "based on the annunciator message, I conclude that the call is failing because it is Unallocated/Unassigned". You actually need to show definitive proof to back up your conclusion. So, you need to dissect traces or debugs and demonstrate that you understand them fluently.
I have been collecting notes on trace dissection as I study and I figured that I should try to integrate studying with my blog a little more than I have to date. So, this may be ugly but I am going to start with a basic MGCP call and using "debug mgcp packet" to identify the key phases of call setup, media initiation, and call termination.
We want to capture an egress call from an IP phone to a PSTN station whereby the call traverses one of our MGCP gateways. We are only interested in identifying the key phases of the call setup, media initiation, and call termination. The call we are dissecting is "healthy". Meaning, there isn't an issue to troubleshoot. You can't really troubleshoot anything if you don't know what a "normal" call should look like, right?
The players:
The players:
- Cisco IP Phone (I am using a 7965 running SCCP, but it doesn't matter what you use)
- Cisco 2800 ISR running MGCP
- A PSTN station ("911 Operator")
- CUCM (7.0)
- Cisco IP phone goes off hook and dials: 911
- CUCM uses MGCP to initiate call setup to Cisco 2800
- Cisco 2800 relays ISDN messages to PSTN
- PSTN station answers the call
- The call is terminated
The Walkthrough
We are using the following commands on our Cisco 2800 ISR:
- debug mgcp packet
- debug isdn q931
When you do this live, the output of these debug options will be mingled together. I am going to clean that up a bit. Just keep in mind that if you have to use multiple debug commands (or trace flags in CCM trace) then you will want to hone your "detangling" skills.
Call Setup
The IP phone has gone off hook and has dialed "911". The first message we see is a MGCP CRCX (create connection) message from CUCM (10.3.120.11).
Let's do some dissection:
The MGCP gateway responds to CUCM (10.3.120.11) with a "200" OK message.
Some of the more interesting values in this response message:
The PSTN responds with a "call proceeding" message and relays the call alerting state.
Once the call is in alerting state, the CUCM will send a MDCX (modify connection) message to the MGCP gateway. You can see in the following example that the local call ID ("I: A") and the CUCM call ID ("X: 8") is used so the MGCP call is clearly identifiable. The codec information ("L: ") and digit map information is basically the same. What is notably different is the "M:" line, which now says: "sendrecv".
CUCM is instructing the gateway to transition from receive only to send/receive mode. We also see that the target endpoint for the media stream from the MGCP device is 10.3.200.128 on UDP port 27664.
The MGCP gateway responds with a 200 OK:Sep 5 13:41:24.089: MGCP Packet received from 10.3.120.11:2427---> CRCX 55 S0/SU0/DS1-0/8@HQ-RTR MGCP 0.1 C: D0000000021ab858000000F500000003 X: 8 L: p:20, a:PCMU, s:off, t:b8, fxr/fx:t38 M: recvonly R: D/[0-9ABCD*#] Q: process,loop <---
Let's do some dissection:
- We can clearly see that the MGCP packet is being sent from 10.3.120.11 and the endpoint on HQ-RTR is identified
- The "C:" is a globally unique conference ID for this connection
- "X:" identifies an ID that CUCM will use when it communicates information about this call. So, a follow up RQNT message about this call would have "X: 8"
- The "L:" value line is pretty handy, it tells us about the codec we are using:
- (p:20) sampling rate is 20ms
- (a:PCMU) the codec is G.711 u-law
- (s:off) VAD is BAD (therefore, we have turned it off)
- (t:b8) type of service
- "M: recvonly" instructs the MGCP device to set up its side of the connection, the call isn't bi-directional yet because we haven't answered on the other end
- "R:" instructs the MGCP device to load the "digit map" package and the valid digits are identified (0-9ABCD*#)
The MGCP gateway responds to CUCM (10.3.120.11) with a "200" OK message.
Sep 5 13:41:24.097: MGCP Packet sent to 10.3.120.11:2427---> 200 55 OK I: A v=0 c=IN IP4 10.3.110.1 m=audio 19128 RTP/AVP 0 100 a=rtpmap:100 X-NSE/8000 a=fmtp:100 192-194,200-202 a=X-sqn:0 a=X-cap: 1 audio RTP/AVP 100 a=X-cpar: a=rtpmap:100 X-NSE/8000 a=X-cpar: a=fmtp:100 192-194,200-202 a=X-cap: 2 image udptl t38 <---
Some of the more interesting values in this response message:
- The gateway instructs the CUCM to use the local call ID of "I=A" when the CUCM needs to reference this call.
- The gateway identifies the source IP address (10.3.110.1) that should be used for media streams from the IP phone.
- The "m=" line identifies the UDP port that should be used for RTP media (19128).
- The jumble of "a=" lines is part of capabilities exchange, "a=X-sqn:0" says that the endpoint supports G.711 u-law
The PSTN responds with a "call proceeding" message and relays the call alerting state.
Sep 5 13:41:24.101: ISDN Se0/0/0:23 Q931: TX -> SETUP pd = 8 callref = 0x0003 Bearer Capability i = 0x8090A2 Standard = CCITT Transfer Capability = Speech Transfer Mode = Circuit Transfer Rate = 64 kbit/s Channel ID i = 0xA98388 Exclusive, Channel 8 Calling Party Number i = 0x0081, '5552001' Plan:Unknown, Type:Unknown Called Party Number i = 0x80, '911' Plan:Unknown, Type:Unknown Sep 5 13:41:24.133: ISDN Se0/0/0:23 Q931: RX <- CALL_PROC pd = 8 callref = 0x8003 Channel ID i = 0xA98388 Exclusive, Channel 8 Sep 5 13:41:24.145: ISDN Se0/0/0:23 Q931: RX <- ALERTING pd = 8 callref = 0x8003 Progress Ind i = 0x8188 - In-band info or appropriate now available
Media Path Established
CUCM is instructing the gateway to transition from receive only to send/receive mode. We also see that the target endpoint for the media stream from the MGCP device is 10.3.200.128 on UDP port 27664.
Sep 5 13:41:24.177: MGCP Packet received from 10.3.120.11:2427---> MDCX 56 S0/SU0/DS1-0/8@HQ-RTR MGCP 0.1 C: D0000000021ab858000000F500000003 I: A X: 8 L: p:20, a:PCMU, s:off, t:b8, fxr/fx:t38 M: sendrecv R: D/[0-9ABCD*#], FXR/t38 S: Q: process,loop v=0 o=- 10 0 IN EPN S0/SU0/DS1-0/8@HQ-RTR s=Cisco SDP 0 t=0 0 m=audio 27664 RTP/AVP 0 c=IN IP4 10.3.200.128 a=X-sqn:0 a=X-cap:1 image udptl t38 <---
Sep 5 13:41:24.181: MGCP Packet sent to 10.3.120.11:2427---> 200 56 OK <---
The above sequence of events is establishing the media path information. Which is to say that the MGCP now has the information it needs to send the audio stream to the remote party when the call is connected. Shortly after the media information exchange, the ISDN party answers the call (ISDN Q.931 debug output):
Sep 5 13:41:26.721: ISDN Se0/0/0:23 Q931: RX <- CONNECT pd = 8 callref = 0x8003 Sep 5 13:41:26.725: ISDN Se0/0/0:23 Q931: TX -> CONNECT_ACK pd = 8 callref = 0x0003
The MGCP gateway receives notification that the call is connected and immediately sends a connection acknowledgement. At this point, the local IP phone and the remote PSTN party ("911 operator") have a full-duplex talk path.
Call Termination
Sep 5 13:41:36.577: MGCP Packet received from 10.3.120.11:2427---> MDCX 57 S0/SU0/DS1-0/8@HQ-RTR MGCP 0.1 C: D0000000021ab858000000F500000003 I: A X: 8 M: recvonly R: D/[0-9ABCD*#] Q: process,loop <---The MGCP device should respond with a "200 OK" message and then we will see ISDN call clearing messages sent to the PSTN.
Sep 5 13:41:36.585: ISDN Se0/0/0:23 Q931: TX -> DISCONNECT pd = 8 callref = 0x0003 Cause i = 0x8290 - Normal call clearing Sep 5 13:41:36.593: ISDN Se0/0/0:23 Q931: RX <- RELEASE pd = 8 callref = 0x8003
We are almost done here. The CUCM must send a DLCX (delete connection) message to the MGCP device to complete the call termination process. The MGCP device will respond with a 250 OK message. In the 250 OK message there is a "P:" line which provides call statistic information:
- Packets Sent (PS)
- Octets Sent (OS)
- Packets Received (PR)
- Octets Received (OR)
- Packet Loss (PL)
- Jitter (JI)
- Latency (LA)
Sep 5 13:41:36.593: MGCP Packet received from 10.3.120.11:2427---> DLCX 58 S0/SU0/DS1-0/8@HQ-RTR MGCP 0.1 C: D0000000021ab858000000F500000003 I: A X: 8 S: <--- Sep 5 13:41:36.617: MGCP Packet sent to 10.3.120.11:2427---> 250 58 OK P: PS=620, OS=99200, PR=620, OR=99200, PL=0, JI=0, LA=0 <---The last message we see here is the MGCP gateway sending a "Release Complete" to the PSTN. Since the CUCM deleted the connection, it is "released".
Sep 5 13:41:36.621: ISDN Se0/0/0:23 Q931: TX -> RELEASE_COMP pd = 8 callref = 0x0003
Using this Information
The first step to being able to clearly and concisely answer any troubleshooting questions is to understand what a normal call looks like. You have to understand the key fields in the various MGCP and ISDN messages. This way, when a call fails to establish for whatever reason, you can identify both where things are "healthy" (or normal) and where something fails. Not only that, you need to use the cryptic fields to support you assertion as to "why" a call failed.
Thanks for reading. If you have time, post a comment!
Hello Bill
ReplyDeleteThanks for this posts,
Some people like me have the problem that the voice lab is with ISDN signaling and we never used this signaling because the standard signaling in our country is CAS R2.
Thanks again.
AA Mendoza
P.S. when is your ccie lab day?
Awesome article !
ReplyDeleteBut where is Q.931 setup message ? & it doesn't give details on the capabilites negotiation part with the isdn (psnt no.)