Cisco Trace - CUCM call logs...

Lazarus_telecomTech · ‎03-23-2016

Hello! I have been looking at some of the trace logs of some calls I have made, and I'm not sure how to interpret some of the results. Here is my CUCM call logs trace:

1) 2016/03/23 20:57:19.338|CC|SETUP|130020296|130020297|7050|XXXXXXX7000|XXXXXXX70002) 2016/03/23 20:57:19.345|CC|OFFERED|130020296|130020297|7050|XXXXXXX7000|XXXXXXX7000|SEP74867A6D24DD|S0/SU0/DS1-0@SLG-VGW013) 2016/03/23 20:57:30.165|CC|SETUP|130020298|130020301|XXXXXXX7000|7000|42014) 2016/03/23 20:57:30.177|CC|OFFERED|130020298|130020301|XXXXXXX7000|7000|4201|S0/SU0/DS1-0@SLG-VGW01|SEP7C95F33EFE215) 2016/03/23 20:59:30.245|CC|SETUP|130020298|130020304|XXXXXXX7000|7000|42026) 2016/03/23 20:59:30.256|CC|OFFERED|130020298|130020304|XXXXXXX7000|7000|4202|S0/SU0/DS1-0@SLG-VGW01|SEP7C95F33EFE217) 2016/03/23 21:00:30.368|CC|RELEASE|130020298|130020304|1028) 2016/03/23 21:00:42.932|CC|RELEASE|130020296|130020297|16

My question is: What is the reason for the release of the call at line 7? There is a code at the end that says 102. How can I find out what that means??

Below you can see a step by step explanation of the trace:

The line numbers at the beginning of each line were added by me.

Line 1 indicates a call from 7050 to an internal number via the PSTN. So the call is going out the the PSTN and returning. The use of the voice gateway can be seen on line 2

Line 3 shows the incoming portion of the call (CLID indicates 7000 as the caller because no internal numbers are "advertised" all calls to the PSTN show XXXXXXXX7000 as the caller). This then gets forwarded to 4201 which is a hunt pilot.

Line 5 shows the call being forwarded again to another hunt pilot 4202. Then, without warning, Line 7 disconnects the call exactly 3 minutes (+11 seconds for the initial welcome message). To understand the reason for the disconnection, what does the 102 indicate?

Any help would be much appreciated!

Dennis Mink · ‎03-23-2016

those look like MGCP traces, which is only part of the picture, the undelying application might result in MGCP releasing the call for some reason.

RTMT> voice/Video>real time data use the appropriate time frame and called/calling number and trace the call that way,

this will give you all the info re. the call including the SDL traces.

interesting to see BTW from your log, is that the call releases after exactly 60 seconds.

Please remember to rate useful posts, by clicking on the stars below.

Lazarus_telecomTech · ‎03-25-2016

Dennis thanks for the reply!

I have taken an SDL trace for the specific time of the disconnection of the call (2016/03/23 21:00:30.368) and I have attached it here. I am not as familiar with the syntax of the SDL traces so if you have any input concerning this, it is welcome.

Thanks!

Marcelo Morais · ‎03-23-2016

Hi,

it looks like a Call Setup Timeout ... check the following command:

#show voice cause-code category-q850
Error Configured Default Description
Category Q850 Q850

 128 3 3 Destination address resolution failure 
 129 102 102 Call setup timeout 
 178 41 41 Internal Communication Error 
 179 41 41 External communication Error 
 180 47 47 Software Error 
 181 47 47 Software Resources Unavailable 
 182 47 47 Hardware Resources Unavailable 
 183 41 41 Capability Exchange Failure 
 184 49 49 QoS Error 
 185 41 41 RTP/RTCP receive timer expired or bearer layer failure 
 186 38 38 Signaling socket failure 
 187 38 38 Gateway or signalling interface taken out of service 
 228 50 50 User is denied access to this service 
 278 65 65 Media Negotiation Failure due to non-existing Codec

Hope this helps.

Lazarus_telecomTech · ‎03-25-2016

Hello Marcelo. Actually, this helps immensely!!

What I didn't mention in my first post (to save space and time) is that this disconnect occurs on unanswered calls that get ringback tone for exactly three minutes. Once the 3 minutes are up, the call is dropped. This coincides perfectly with the Call setup timeout.

The problem is that my client wants this timeout to increase to 12 minutes.

Note this timeout occurs ONLY for calls through the MGCP gateway. For internal calls, I get ringback without being disconnected for over the required 12 minutes.

My next questions are:

1) Where is this call setup timeout configured? On the MGCP gateway? On the PRI from the telco? How can I determine this?

2) How can I increase this timeout?

Your help would be invaluable...

Thanks again!

Lazaros Agapides

Lazarus_telecomTech · ‎03-25-2016

After doing some research I found this command from the Cisco IOS voice command reference:

timeout tone ringback ringback-tone-value

The default value is 180 seconds which is EXACTLY the amount of time before the call drops.

This is set up in the profile of the MGCP gateway. It can go up to 600 seconds (which is what I will do.) I will test it tonight or tomorrow and I'll get back to you and let you know the results.

Thanks for your help!

Marcelo Morais · ‎03-25-2016

Hi Lazaros,

excellent news ... keep us posted!!!

Best regards.

Lazarus_telecomTech · ‎03-26-2016

Hello again. I haven't solved it yet but here's what I've done so far. The MGCP profile has several timers which are set at 180 seconds by default. These include the following:

Ringback tone timeout is 600 sec

Ringback tone on connection timeout is 600 sec
Network congestion tone timeout is 600 sec,

Ringing tone timeout is 600 sec, Distinctive ringing tone timeout is 600 sec

As can be seen from the above output, I have changed all of these to 600 seconds. This however, has not changed the behaviour of the calls. I have done a debug isdn q931 detail and made a call and I get the following:

Mar 26 19:21:04.482: ISDN Se0/0/0:15 Q931d: data =
Mar 26 19:21:04.482: 13DD85A400000003024004BF00010000
Mar 26 19:21:04.482: 08028EC1021803A98381
Mar 26 19:21:04.482: ISDN Se0/0/0:15 Q931: TX -> CALL_PROC pd = 8 callref = 0x8EC1
Channel ID i = 0xA98381
Exclusive, Channel 1
Mar 26 19:21:04.490: ISDN Se0/0/0:15 Q931d: srl_send_l3_pak:
source_id = CCM MANAGER 0x0003, dest_id = Q.921 0x0000, prim = DL_DATA_REQ 0x0240
priv_len = 4 int_id = 0x13DD85A4 datasize = 25
Mar 26 19:21:04.490: ISDN Se0/0/0:15 Q931d: data =
Mar 26 19:21:04.490: 13DD85A400000003024004D500010000
Mar 26 19:21:04.490: 08028EC1031E028188
Mar 26 19:21:04.490: ISDN Se0/0/0:15 Q931: TX -> PROGRESS pd = 8 callref = 0x8EC1
Progress Ind i = 0x8188 - In-band info or appropriate now available
Mar 26 19:21:04.566: ISDN Se0/0/0:15 Q931: RX <- PROGRESS pd = 8 callref = 0x8003
Progress Ind i = 0x8088 - In-band info or appropriate now available
Mar 26 19:21:14.790: ISDN Se0/0/0:15 Q931d: srl_send_l3_pak:
source_id = CCM MANAGER 0x0003, dest_id = Q.921 0x0000, prim = DL_DATA_REQ 0x0240
priv_len = 4 int_id = 0x13DD85A4 datasize = 25
Mar 26 19:21:14.790: ISDN Se0/0/0:15 Q931d: data =
Mar 26 19:21:14.790: 13DD85A400000003024004EA00010000
Mar 26 19:21:14.790: 08028EC1011E028088
Mar 26 19:21:14.790: ISDN Se0/0/0:15 Q931: TX -> ALERTING pd = 8 callref = 0x8EC1
Progress Ind i = 0x8088 - In-band info or appropriate now available
Mar 26 19:21:14.866: ISDN Se0/0/0:15 Q931: RX <- ALERTING pd = 8 callref = 0x8003
Progress Ind i = 0x8088 - In-band info or appropriate now available
Mar 26 19:24:14.865: ISDN Se0/0/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x0EC1
Cause i = 0x80E6 - Recovery on timer expiry
Mar 26 19:24:14.869: ISDN Se0/0/0:15 Q931: RX <- PROGRESS pd = 8 callref = 0x8003
Progress Ind i = 0x8088 - In-band info or appropriate now available
Mar 26 19:24:14.901: ISDN Se0/0/0:15 Q931d: srl_send_l3_pak:
source_id = CCM MANAGER 0x0003, dest_id = Q.921 0x0000, prim = DL_DATA_REQ 0x0240
priv_len = 4 int_id = 0x13DD85A4 datasize = 21
Mar 26 19:24:14.901: ISDN Se0/0/0:15 Q931d: data =
Mar 26 19:24:14.901: 13DD85A400000003024004FF00010000
Mar 26 19:24:14.901: 08028EC14D
Mar 26 19:24:14.901: ISDN Se0/0/0:15 Q931: TX -> RELEASE pd = 8 callref = 0x8EC1
Mar 26 19:24:14.965: ISDN Se0/0/0:15 Q931: RX <- RELEASE_COMP pd = 8 callref = 0x0EC1
Mar 26 19:24:45.117: ISDN Se0/0/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x8003
Cause i = 0x80FF - Interworking error; unspecified
Mar 26 19:24:45.141: ISDN Se0/0/0:15 Q931d: srl_send_l3_pak:
source_id = CCM MANAGER 0x0003, dest_id = Q.921 0x0000, prim = DL_DATA_REQ 0x0240
priv_len = 4 int_id = 0x13DD85A4 datasize = 21
Mar 26 19:24:45.141: ISDN Se0/0/0:15 Q931d: data =
Mar 26 19:24:45.141: 13DD85A4000000030240041000010000
Mar 26 19:24:45.141: 080200034D
Mar 26 19:24:45.141: ISDN Se0/0/0:15 Q931: TX -> RELEASE pd = 8 callref = 0x0003
Mar 26 19:24:45.217: ISDN Se0/0/0:15 Q931: RX <- RELEASE_COMP pd = 8 callref = 0x8003

Notice that the call begins at Mar 26 19:21:14.790 and we get the following message exactly 3 minutes later:

Mar 26 19:24:14.865: ISDN Se0/0/0:15 Q931: RX <- DISCONNECT pd = 8 callref = 0x0EC1
Cause i = 0x80E6 - Recovery on timer expiry

The cause code 80E6 states that the code origination is the router (80) and that the error (E6) indicates the following:

Your call does not go through, probably because an error occurs. For example, a state synchronization error. Wait and try again later. If the problem persists, contact your ISDN service provider.

This information is based on this link.

Is there any configuration on the Call Manager setup of the MGCP gateway that will cause a 3 minute timeout that overrides the settings on the gateway? According to Cisco documentation, all of these settings use these timeout values "when the call agent does not provide a timeout value associated with the request to generate a ringback/ringing/etc tone signal." I haven't been able to find any such setting. Could the issue be with the telco?

Any insights you can give would be helpful...