×

Warning message

  • Cisco Support Forums is in Read Only mode while the site is being migrated.
  • Cisco Support Forums is in Read Only mode while the site is being migrated.

Call drops - CUCM v9

Unanswered Question
May 11th, 2014
User Badges:

Hi All,

We are facing a critical issue with Call drops during conference bridges on ATT Teleconferencing service on cloud.

* Even though callers join the bridge from PSTN and all our Global Voice clusters, only the callers from our India Voice cluster face the call drop issue.

* No specific timings for drop. But mostly between 15 to 20 minutes.

* CUCM v9 and Voice Gateway C3945 with IOS 12.5

* PRI vendor sees no issue on the link and no other calls on this PRI faces have any issues.

* ATT confirms with their logs that the disconnection is coming from our side.

* Disconnection cause code : Cause No. 38 - network out of order [Q.850]  -> Destination Cause Value

Can someone please help me by looking into the attached log or the dropped part of the call log given below and tell me where exactly is the problem.

Dropped call reference

Start Time : May 9, 2014 10:57:30

Call Drop Time : May 9, 2014 11:21:54

Calling Number : 1476

 

Dropped part of the log

---------------------------------

    Line 3921: 16972928.000 |11:21:54.481 |SdlSig   |AuDisconnectRequest                    |wait                           |ConnectionManager(2,100,207,1)   |MatrixControl(2,100,135,572653)  |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=T IF2Created=T party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3922: 16972929.000 |11:21:54.481 |SdlSig   |AuDisconnectRequest                    |wait                           |MediaCoordinator(2,100,134,1)    |ConnectionManager(2,100,207,1)   |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=T IF2Created=T party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3923: 16972930.000 |11:21:54.481 |SdlSig   |AuDisconnectRequest                    |waitDisconnect                 |MediaManager(2,100,133,546869)   |MediaCoordinator(2,100,134,1)    |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=T IF2Created=T party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3925: 16972931.000 |11:21:54.481 |SdlSig   |AuDisconnectRequest                    |interfacesEstablished          |MediaExchange(2,100,138,544586)  |MediaManager(2,100,133,546869)   |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=T IF2Created=T party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3928: 16972934.000 |11:21:54.481 |SdlSig   |MXAgenaCloseLogicalChannel             |restart0                       |StationD(2,100,58,2031896)       |AgenaInterface(2,100,234,651129)                                                             |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:5,L:0,V:0,Z:0,D:0]  ConferenceID= 0 PartyId= 34244826 streamFlag=F ClearType= 0 PortHandling=0 ci=42536958 lcn=0 PT=F PTId=16777216 switchingToFax=F ConnType=3
    Line 3931: 16972937.000 |11:21:54.481 |SdlSig   |MXStopTalking                          |restart0                       |StationD(2,100,58,2031896)       |AgenaInterface(2,100,234,651129)                                                             |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:4,L:0,V:0,Z:0,D:0] ClearType= 0 mConferenceID= 0 ci=42536958 mPartyId=0x20a88da PortHandling=0 ConnType=3
    Line 3935: 16972941.000 |11:21:54.481 |SdlSig   |MXAgenaCloseLogicalChannel             |active10                       |StationCdpc(2,100,59,902624)     |StationD(2,100,58,2031896)       |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:4,L:0,V:0,Z:0,D:0]  ConferenceID= 0 PartyId= 34244826 streamFlag=F ClearType= 0 PortHandling=0 ci=42536958 lcn=0 PT=F PTId=16777216 switchingToFax=F ConnType=3
    Line 3936: 16972942.000 |11:21:54.481 |SdlSig   |MXStopTalking                          |active10                       |StationCdpc(2,100,59,902624)     |StationD(2,100,58,2031896)       |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:4,L:0,V:0,Z:0,D:0] ClearType= 0 mConferenceID= 0 ci=42536958 mPartyId=0x20a88da PortHandling=0 ConnType=3
    Line 3941: 16972946.000 |11:21:54.481 |SdlSig   |StationOutputCloseReceiveChannel       |restart0                       |StationD(2,100,58,2031896)       |StationCdpc(2,100,59,902624)     |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:4,L:0,V:0,Z:0,D:0]  ConfId=42536958 CI=42536958 PartyId=0x20a88da portHandling=0
    Line 3941: 16972946.000 |11:21:54.481 |SdlSig   |StationOutputCloseReceiveChannel       |restart0                       |StationD(2,100,58,2031896)       |StationCdpc(2,100,59,902624)     |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:4,L:0,V:0,Z:0,D:0]  ConfId=42536958 CI=42536958 PartyId=0x20a88da portHandling=0
    Line 3942: 16972947.000 |11:21:54.481 |SdlSig   |StationOutputStopMediaTransmission     |restart0                       |StationD(2,100,58,2031896)       |StationCdpc(2,100,59,902624)     |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:3,L:0,V:0,Z:0,D:0] ConfId=42536958 CI=42536958 PartyId=0x20a88da portHandling=0
    Line 3942: 16972947.000 |11:21:54.481 |SdlSig   |StationOutputStopMediaTransmission     |restart0                       |StationD(2,100,58,2031896)       |StationCdpc(2,100,59,902624)     |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:3,L:0,V:0,Z:0,D:0] ConfId=42536958 CI=42536958 PartyId=0x20a88da portHandling=0
    Line 3980: 16972970.000 |11:21:54.483 |SdlSig   |AuDisconnectReply                      |waitCleanup                    |MediaManager(2,100,133,546869)   |MediaExchange(2,100,138,544586)  |2,100,13,2497608.8^*^*                   |[R:N-H:0,N:0,L:1,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=T IF2Created=T party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3982: 16972971.000 |11:21:54.483 |SdlSig   |AuDisconnectReply                      |wait                           |MediaCoordinator(2,100,134,1)    |MediaManager(2,100,133,546869)   |2,100,13,2497608.8^*^*                   |[R:N-H:0,N:0,L:1,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=F IF2Created=F party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3983: 16972972.000 |11:21:54.483 |SdlSig   |AuDisconnectReply                      |wait                           |ConnectionManager(2,100,207,1)   |MediaCoordinator(2,100,134,1)    |2,100,13,2497608.8^*^*                   |[R:N-H:0,N:0,L:1,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=F IF2Created=F party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3984: 16972973.000 |11:21:54.483 |SdlSig   |AuDisconnectReply                      |dissolving                     |MatrixControl(2,100,135,572653)  |ConnectionManager(2,100,207,1)   |2,100,13,2497608.8^*^*                   |[R:N-H:0,N:0,L:1,V:0,Z:0,D:0] CI1=42536958 CI2=42536959 sc=0 disconnType=1 ssReason=0 clearType=0 IF1Created=F IF2Created=F party1.mMediaCoordinatorNodeId=0 party2.mMediaCoordinatorNodeId=0 party1.dtmCall=0 party2.dtmCall=0 reconnectPending=F forceStop=F
    Line 3988: 16972975.000 |11:21:54.483 |SdlSig   |CcDisconnReq                           |restart0                       |LineControl(2,100,167,78541)     |Cdcc(2,100,212,660508)           |2,100,13,2497608.8^*^*                   |[R:N-H:0,N:0,L:1,V:0,Z:0,D:0] CI=42536958 CI.branch=0  clearType=0 c.l=2 c.cid=8 c.cs=0 c.lc=2 c.r=0 cv=38 FDataType=0opId=0ssType=0 SsKey=0invokeId=0resultExp=Fbpda=F OnBehalf=Device rfr=0 localPatternUsage=2 connectedPatternUsage=5 rdDestPart= rdDestPatt= rdDestCdpn=pi=0si1 lrnCepn= redDestName=locale: 1 Name:  UnicodeName:  pi: 0 annId=0 lHPMemCEPN= cHPMemCEPN= dtmCall=F dtmDisconn=F dtmMcNodeId=0 forcedClear=F TransparentData=null CanSupportSIPTandN=false TransId=0 AllowBitMask=0x0 UserAgentOrServer= OrigDDName=locale: 1 Name:  UnicodeName:  pi: 0 mCallerId= mCallerName= mediaCause=0
    Line 3989: 16972976.000 |11:21:54.483 |SdlSig   |CcDisconnReq                           |call_active10                  |LineCdpc(2,100,168,906157)       |LineControl(2,100,167,78541)     |2,100,13,2497608.8^*^*                   |[R:N-H:0,N:0,L:1,V:0,Z:0,D:0] CI=42536958 CI.branch=0  clearType=0 c.l=2 c.cid=8 c.cs=0 c.lc=2 c.r=0 cv=38 FDataType=0opId=0ssType=0 SsKey=0invokeId=0resultExp=Fbpda=F OnBehalf=Device rfr=0 localPatternUsage=2 connectedPatternUsage=5 rdDestPart= rdDestPatt= rdDestCdpn=pi=0si1 lrnCepn= redDestName=locale: 1 Name:  UnicodeName:  pi: 0 annId=0 lHPMemCEPN= cHPMemCEPN= dtmCall=F dtmDisconn=F dtmMcNodeId=0 forcedClear=F TransparentData=null CanSupportSIPTandN=false TransId=0 AllowBitMask=0x0 UserAgentOrServer= OrigDDName=locale: 1 Name:  UnicodeName:  pi: 0 mCallerId= mCallerName= mediaCause=0

 

 

 

Attachment: 
  • 1
  • 2
  • 3
  • 4
  • 5
Overall Rating: 0 (0 ratings)
Loading.
Jason Treloar Sun, 05/11/2014 - 16:54
User Badges:

Well there are a number of questions here but let me start with this:

Have you configured RSVP req? this looks like it could be failing due to lack of RSVP e2e, please turn it off for this trunk if it is configured.

abraham23482 Sun, 05/11/2014 - 21:46
User Badges:

Thanks for your reply Jason.

We have not enabled RSVP on this trunk on CUCM or Voice Gateway

 

Jason Treloar Mon, 05/12/2014 - 00:28
User Badges:

Sorry, does this break after connection?

ie, the conference bridge establishes, but then the Indian call legs fall out?

abraham23482 Mon, 05/12/2014 - 03:55
User Badges:

Correct. The bridge establishes and then may be after 15 to 20 minutes all Indian call legs starts to drop out.

abraham23482 Mon, 05/12/2014 - 03:56
User Badges:

From the SDI/SDL logs, can you give me some clues where to look at. I am not able to understand this new format of logs in v9.

Nishant Savalia Tue, 05/13/2014 - 00:40
User Badges:
  • Silver, 250 points or more

Hi Abraham,

Can you please share how the network topology is? I mean how CUCM and voice gateways are connected?

The call coming form India site is connected to voice gateway in which manner?

What protocol voice gateway is running? How is the connectivity with Teleconferencing?

 

abraham23482 Tue, 05/13/2014 - 04:36
User Badges:

Hi Nishant,

Thank you for you response.

Voice Gateways are connected via H323 to the CUCM and it is in the same  LAN. Teleconferencing calls are to the PSTN. We dial a specific pattern that goes out via one of the PRIs and reaches ATT cloud for teleconf service.

I have checked with the PRI vendors and they say no issues. No other calls through this PRIs are affected. But ATT confirms with their logs that they see our side end point disconnecting and trying back again.

Please let me know if you need more info. Thank you

 

 

 

Nishant Savalia Tue, 05/13/2014 - 05:02
User Badges:
  • Silver, 250 points or more

Hi Abraham,

Thank you for providing info.

Can you please share below logs for end to end call:-

1). debug h225 asn1

2). debug h245 asn1

3). debug isdn q931

4). debug h225 q931 (see if this debug is supported or  not).

5). Detailed trace of CUCM from RTMT. (check all nodes are selected).

From the above trace log i don't see sdi logs. so please check and do provide sdi logs as well (in CUCM 9 sdl and sdi will be in single file i think so)

Please mention Calling number, called number and start time and end time of the call.

 

Regards,

Nishant Savalia

abraham23482 Tue, 05/13/2014 - 05:51
User Badges:

HI Nishant,

Unfortunately i cannot reproduce the issue at will. I have a previous failed call record and attached are the SDI and SDL logs.

Calling number : 1476

Called number : 9000117

 

Attachment: 
Brian Meade Tue, 05/13/2014 - 07:46
User Badges:
  • Silver, 250 points or more

You must have all the traces unchecked under Cisco CallManager.  There's hardly any AppInfo lines at all.  We really only have SDL information in here.

 

The call is disconnected due to an incoming H.225 release complete from the H.323 gateway:

16972912.000 |11:21:54.481 |SdlSig   |H225RelComplete                        |restart0                       |H225D(2,100,188,17)              |H225Handler(2,100,187,1)         |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:0,L:0,V:0,Z:0,D:0] CES=0 SAPI=0 DSL=0 IEP=0 PID=(2,100,13,2497607)

 

 

It looks like a cause value of 38 is being reported:

16972914.000 |11:21:54.481 |SdlSig   |CcRelInd                               |idle                           |RouteListControl(2,100,82,44)    |H225Cdpc(2,100,189,141016)       |2,100,13,2497607.8^10.205.250.9^*        |[R:N-H:0,N:2,L:0,V:0,Z:0,D:0] CI=42536959 CI.branch=0  c.l=2 c.cid=8 c.cs=0 c.lc=2 c.r=0 CV=38 isDeskPickup=F dtmDisconn=F FDataType=0opId=0ssType=0 SsKey=0invokeId=0resultExp=Fbpda=FTransparentData=null CanSupportSIPTandN=false TransId=0 AllowBitMask=0x0 UserAgentOrServer= OrigDDName=locale: 1 Name:  UnicodeName:  pi: 0 mCallerId= mCallerName=

 

We're probably going to need the gateway debugs and the trace details turned back to default in CUCM.  You can set up a syslog server to collect the gateway debugs over a long time since you say it is difficult to reproduce the issue.

 

abraham23482 Tue, 05/13/2014 - 19:36
User Badges:

Thanks Brian and Nishant.

I will try to enable the debugs to a syslog and come back with the results

Attached is the VG configuration. Since you pointed H225 release, should I look into any of the H225 timers on the VG ?

 

Thanks

Abraham

Attachment: 
Brian Meade Mon, 05/12/2014 - 13:00
User Badges:
  • Silver, 250 points or more

Those aren't logs from CUCM version 9.  There's no AppInfo lines with SDI information.  Make sure to set the CallManager service trace level to Detailed on all nodes.

abraham23482 Mon, 05/12/2014 - 19:32
User Badges:

Not sure what v9 you are referring to but this is the log from CUCM v9 and SDI trace is set to detailed. This is not the complete file i have extracted only the failed call part with the call reference ID.

Actions

This Discussion