Calls get stuck in T1

Answered Question
Aug 20th, 2010

Hi All,

I found one weird issue in our T1. We have one call center which has one number the customers can call in. I found out two calls which already ended several minutes ago. But they are still shown under the "show isdn active". They occupied the T1 slots. I called those two callers and they said they already hang up several minutes ago. At that time, the calls still show in active status.

We have a call queue setup in UCCX server. Is there any possiblity that the call ends actually but the queue still hold it for some time?

Thanks for your help!!!

Lou

I have this problem too.
0 votes
Correct Answer by Steven Holl about 6 years 2 months ago

Oh so the call isn't eternally stuck?

The problem is upstream of the gaetway, then.  The disconnect doesn't come from the H323 peer (CM I presume?) until 10:20:

7381844: Sep 10 10:20:20.712 CDT: H225.0 INCOMING PDU ::=

value H323_UserInformation ::=
    {
      h323-uu-pdu
      {
        h323-message-body releaseComplete :
        {
          protocolIdentifier { 0 0 8 2250 0 5 }
          callIdentifier
          {
            guid 'B54316E1BC2311DF901EFD8A79705EB9'H
          }
        }
        h245Tunneling FALSE
      }
    }

7381845: Sep 10 10:20:20.712 CDT: //1652696/B5427AB9991B/CCAPI/cc_api_call_disconnected:
   Cause Value=16, Interface=0x68589F00, Call Id=1652696

And then the call is torn down on ISDN right after that:

7381858: Sep 10 10:20:20.732 CDT: H225.0 OUTGOING PDU ::=

value H323_UserInformation ::=
    {
      h323-uu-pdu
      {
        h323-message-body releaseComplete :
        {
          protocolIdentifier { 0 0 8 2250 0 4 }
          callIdentifier
          {
            guid 'B54316E1BC2311DF901EFD8A79705EB9'H
          }
        }
        h245Tunneling FALSE
      }
    }

7381859: Sep 10 10:20:20.732 CDT: H225.0 OUTGOING ENCODE BUFFER::= 2580060008914A000411001100B54316E1BC2311DF901EFD8A79705EB910800100
7381860: Sep 10 10:20:20.732 CDT:
7381861: Sep 10 10:20:20.732 CDT: //1652696/B5427AB9991B/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x68589F00, Tag=0x0, Call Id=1652696,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
7381862: Sep 10 10:20:20.732 CDT: //1652696/B5427AB9991B/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
7381863: Sep 10 10:20:20.732 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
7381864: Sep 10 10:20:20.732 CDT: :cc_free_feature_vsa freeing 6CA41DC0
7381865: Sep 10 10:20:20.732 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
7381866: Sep 10 10:20:20.732 CDT:  vsacount in free is 37
7381867: Sep 10 10:20:20.736 CDT: %ISDN-6-DISCONNECT: Interface Serial0/0/0:6  disconnected from 3147502946 , call lasted 880 seconds
7381868: Sep 10 10:20:20.736 CDT: ISDN Se0/0/0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x82FE
    Cause i = 0x8090 - Normal call clearing
7381869: Sep 10 10:20:20.768 CDT: ISDN Se0/0/0:23 Q931: RX <- RELEASE pd = 8  callref = 0x02FE
7381870: Sep 10 10:20:20.768 CDT: ISDN Se0/0/0:23 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x82FE

You need to investigate why the release complete transmission from the node across from dial-peer 100 is delays by 12 minutes.  Detailed CM traces are the way to go.

Correct Answer by Steven Holl about 6 years 3 months ago

(C3845-SPSERVICESK9-M), Version 12.4(22)T. Actually the calls will not hang there forever. I noticed that they usually only hang there for less than one minute.

That sounds like the media inactivity timer may be popping.  Do you have that configured under the 'gateway' sub-configuration?  Ideally, the call should have a disconnect coming in from one of the sides.

If you can get some debugs during one of these scenarios, we can take a look.  If this is h323, you can also get 'sh h323 gateway cause' and see which value increments when the call drops.

debug voip ccapi inout

debug isdn q931 (assuming this is a PRI.  Use 'debug vpm sig' if it isn't a PRI)

debug h225 asn1 (if this is h323)

debug ccsip mess (if this is SIP)

Collect debugs as follows.

Router(config)# service sequence
Router(config)# service timestamps debug datetime msec
Router(config)# logging buffered 10000000 7
Router(config)# no logging con
Router(config)# no logging mon
Router(config)# voice iec syslog

Router# term len 0

Router# sh logg

Note ANI/DNIS of a call with the issue.

  • 1
  • 2
  • 3
  • 4
  • 5
Overall Rating: 5 (3 ratings)
Loading.
philip.e.denton Fri, 08/20/2010 - 10:23

I wouldn't think so...

Any way you could catch these hanging calls with a debug isdn q931?

philip.e.denton Fri, 08/20/2010 - 10:41

Ok.  And can you provide any identifying information about the offending calls?  Any patterns from ANI/DNIS evident?  Can you recreate the issue at will?

hxmengmetro Fri, 08/20/2010 - 10:44

I can't recreat issue at will. I must wait and compare the T1 active calls to cisco supervisor desktop to find out which calls are stuck in T1 which actullay already end. Really hard to troubleshoot.

troy.laclair Mon, 08/23/2010 - 09:41

Are you using a survivability.tcl file on any of these inbound calls? What version of IOS are you running on your inbound gateway?

hxmengmetro Mon, 08/23/2010 - 15:02

No. I'm not running any script in the gateway. version is:

(C3845-SPSERVICESK9-M), Version 12.4(22)T

Thanks!

Paolo Bevilacqua Mon, 08/23/2010 - 10:30

Common IOS bug. Shut / no shut controller T1 to clear calls.

Update IOS to avoid future occourings.

philip.e.denton Mon, 08/23/2010 - 12:20

Remember that shut/no shut will remove ALL calls, not just the ones that are hung!!!

hxmengmetro Mon, 08/23/2010 - 15:01

(C3845-SPSERVICESK9-M), Version 12.4(22)T. Actually the calls will not hang there forever. I noticed that they usually only hang there for less than one minute. I just shut and no shut the the controller where there is no call active.

Paolo Bevilacqua Mon, 08/23/2010 - 15:42

IOS used is not of the most stable, however it could be a telco problem where they fail to send disconnect in some cases.

You can only troubleshoot loggin debug isdn q931 to buffer or server.

Correct Answer
Steven Holl Tue, 08/24/2010 - 07:03

(C3845-SPSERVICESK9-M), Version 12.4(22)T. Actually the calls will not hang there forever. I noticed that they usually only hang there for less than one minute.

That sounds like the media inactivity timer may be popping.  Do you have that configured under the 'gateway' sub-configuration?  Ideally, the call should have a disconnect coming in from one of the sides.

If you can get some debugs during one of these scenarios, we can take a look.  If this is h323, you can also get 'sh h323 gateway cause' and see which value increments when the call drops.

debug voip ccapi inout

debug isdn q931 (assuming this is a PRI.  Use 'debug vpm sig' if it isn't a PRI)

debug h225 asn1 (if this is h323)

debug ccsip mess (if this is SIP)

Collect debugs as follows.

Router(config)# service sequence
Router(config)# service timestamps debug datetime msec
Router(config)# logging buffered 10000000 7
Router(config)# no logging con
Router(config)# no logging mon
Router(config)# voice iec syslog

Router# term len 0

Router# sh logg

Note ANI/DNIS of a call with the issue.

hxmengmetro Tue, 08/24/2010 - 08:27

Thanks a lot for the detailed step. I will try them today and let you guys know.

Thanks.

Lou

hxmengmetro Fri, 09/10/2010 - 08:54

Finally I get some time to do more troubleshooting today. I enabled the debug as you suggested.

debug isdn error is             ON.
debug isdn q931 is              ON.   (filter is OFF)
H.225:
   H.225 ASN1 Messages debugging is on
CCAPI:
   debug voip ccapi inout is ON (filter is OFF)

Keep showing log constantly every 3 seconds. I captured the output. The log repeat a lot in the capture since I show log every 3 seconds. The stuck call number is 3147502946. From the cisco CDR Analysis and Reporting. This call started at Sep 10, 2010 10:05:39 AM and ended at Sep 10, 2010 10:07:22 AM lasting 107 seconds. I checked the log in gateway. The connected time is 10:05:40 AM but disconnected time is 10:20:20 AM lasting 880 seconds.

I check the h323 cause code and didn't see non-normal call clearing number increased. All increased number is normal call clearing. No other suspicious message between connect and disconnect message. The attachement is the capture.

This is really weired. It seems Call Manager already disconnect the call but gateway still connected. Not sure it's AT&T problem or not.

Please help. Thanks a lot!

Lou

hxmengmetro Fri, 09/10/2010 - 12:51

I took a look at the debug output again. The call process was happening like below:

1. 10:05:39 AM, call get into the T1. call setup. Call get into the queue waiting.

2. 10:07:22 AM. the agent is available. the call was out of queue.

3. 10:08:29 AM. the call ended according to CM CDR and cisco supervisor desktop. See the cc_api_set_called_ccm_detected, cc_api_voice_mode_event, ccCallNotify. cc_api_get_ccm_detected, cc_api_get_ssCTreRoutingNotSupported. no DISCONNECT related message popped up at this time.
4. 10:20:20 AM. The call really disconnected from T1. T1 slot got released.

Correct Answer
Steven Holl Fri, 09/10/2010 - 13:23

Oh so the call isn't eternally stuck?

The problem is upstream of the gaetway, then.  The disconnect doesn't come from the H323 peer (CM I presume?) until 10:20:

7381844: Sep 10 10:20:20.712 CDT: H225.0 INCOMING PDU ::=

value H323_UserInformation ::=
    {
      h323-uu-pdu
      {
        h323-message-body releaseComplete :
        {
          protocolIdentifier { 0 0 8 2250 0 5 }
          callIdentifier
          {
            guid 'B54316E1BC2311DF901EFD8A79705EB9'H
          }
        }
        h245Tunneling FALSE
      }
    }

7381845: Sep 10 10:20:20.712 CDT: //1652696/B5427AB9991B/CCAPI/cc_api_call_disconnected:
   Cause Value=16, Interface=0x68589F00, Call Id=1652696

And then the call is torn down on ISDN right after that:

7381858: Sep 10 10:20:20.732 CDT: H225.0 OUTGOING PDU ::=

value H323_UserInformation ::=
    {
      h323-uu-pdu
      {
        h323-message-body releaseComplete :
        {
          protocolIdentifier { 0 0 8 2250 0 4 }
          callIdentifier
          {
            guid 'B54316E1BC2311DF901EFD8A79705EB9'H
          }
        }
        h245Tunneling FALSE
      }
    }

7381859: Sep 10 10:20:20.732 CDT: H225.0 OUTGOING ENCODE BUFFER::= 2580060008914A000411001100B54316E1BC2311DF901EFD8A79705EB910800100
7381860: Sep 10 10:20:20.732 CDT:
7381861: Sep 10 10:20:20.732 CDT: //1652696/B5427AB9991B/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x68589F00, Tag=0x0, Call Id=1652696,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
7381862: Sep 10 10:20:20.732 CDT: //1652696/B5427AB9991B/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
7381863: Sep 10 10:20:20.732 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
7381864: Sep 10 10:20:20.732 CDT: :cc_free_feature_vsa freeing 6CA41DC0
7381865: Sep 10 10:20:20.732 CDT: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
7381866: Sep 10 10:20:20.732 CDT:  vsacount in free is 37
7381867: Sep 10 10:20:20.736 CDT: %ISDN-6-DISCONNECT: Interface Serial0/0/0:6  disconnected from 3147502946 , call lasted 880 seconds
7381868: Sep 10 10:20:20.736 CDT: ISDN Se0/0/0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x82FE
    Cause i = 0x8090 - Normal call clearing
7381869: Sep 10 10:20:20.768 CDT: ISDN Se0/0/0:23 Q931: RX <- RELEASE pd = 8  callref = 0x02FE
7381870: Sep 10 10:20:20.768 CDT: ISDN Se0/0/0:23 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x82FE

You need to investigate why the release complete transmission from the node across from dial-peer 100 is delays by 12 minutes.  Detailed CM traces are the way to go.

hxmengmetro Fri, 09/10/2010 - 13:34

Thanks a lot Steven. Right, the call would be released after some random delay. The dial peer 100 is to our cisco call manager. So you mean the call manager didn't send the disconnect message at correct time (10:08:29 AM)? It appears call manager itself knows this call is disconnected and sent out the disconnect message, but the message never reached the gateway. That's why CDR shows correct disconnected time but the gateway just hung there waiting for the disconnect message.

What kind of CM trace I should enable it to debug this issue? Thanks a lot Steven.

Lou

Steven Holl Fri, 09/10/2010 - 13:20

That call disconnect from the H323 side, and the disconnect on the ISDN side looks normal.  CCAPI appears to clean itself up properly, as well.

If the call entry is getting hung in some show commands, it looks like a bug.  You can try running recent IOS and see if behavior still exists.  Perhaps the latest rebuild of 15.0(1)M?  If so, open a TAC SR and we'll work with development to diagnose towards root cause and get it fixed.

Since the ISDN channel frees up, though, it is really mostly a cosmetic bug, other than it potentially affecting CDR records.

-Steve

Steven Holl Fri, 09/10/2010 - 13:36

Get detailed CM traces.

There isn't anything proxying the h225 connection between CM and the gateway (TCP/1720), is there?  Like a firewall?

The router clock does match the clock on CM which is used for CDR, right?

hxmengmetro Fri, 09/10/2010 - 13:40

There is no firewall or ACL setup between CM and gateway. All the ports are open. The gateway clock is pretty synchronized with CDR. I compared them when I looked at the debug output.

hxmengmetro Tue, 09/14/2010 - 10:04

So I caught another stuck call. This time I collected debug from gateway and Call Manager. Here is the detail about this phone call:

Calling number: 3146527946

11:41:05  Call get into the greetings. CM trace: 119

11:41:49  Finished the greetings, the agent picked up the call. CM trace:122

11:42:04  The call ended but still stuck in T1. CM trace: 123

11:46:57  The call finally released in T1. CM trace: 144

I attached the zip file for CM trace and another text file for gateway trace. I'm trying to compare this to the normal call.

Thanks for the help.

hxmengmetro Tue, 09/14/2010 - 11:16

No. IPCC is 10.101.1.13. 10.101.1.100 is another gateway. The gateway having stuck calls is 10.104.6.253

Steven Holl Tue, 09/14/2010 - 11:20

Well the call doesn't disconnect until 11:46:57 on the CM side, so the issue isn't with the gateway for sure.  The issue is at or upstream of CM.

The GUID for the issue is B3B1EAF1BF5511DF92C3FD8A79705EB9.

I don't have time to go through the entire trace and follow the other side of the CM leg.  The origin of the disconnect of the call needs to be traced in the CM traces, which may be occurring on another CM node.

hxmengmetro Tue, 09/14/2010 - 12:20

Thanks Steven. Yes, the call got disconnected until 11:46:57 by CM. The origin you are talking is the end who hang up the call first?

Lou

hxmengmetro Tue, 09/14/2010 - 15:06

I have looked at CDR and traces in CM. I found after the actual disconnection time, there is one call going from the gateway to another gateway. That's why the gateway in question holds the T1 slot. I'm trying to figure out why it works like this way.

hxmengmetro Thu, 09/16/2010 - 10:12

Ok. Here is the deal. The agent made the transfer to another call center in the site and they dial the DID not the internal extension. That's why the calls to out through another gateway. So that "stuck" call actually is a transferred call. The agent should not do this way, we already suggest them just dial the internal number without wasting the T1 slots.

Thanks Steve and the other helper. At least, I figured out how to troubleshoot this kind of issue. This is really helpful!!!

Lou

hxmengmetro Thu, 09/16/2010 - 11:29

Thanks! :-) This issue is really a non-technical issue. Human issue again. Hehe. :-) But we need take technical way to find out human errors.

Cheers!

Lou

Actions

This Discussion