IP Flex Inbound Calls Disconnected from Unity Mailboxes in 15-30 seconds

[Mike Shoop]

Out of several thousand end users with Unity voice mailboxes on a single, very widely extended CUCM system we have a small set of approximately 20 Unity voice mailboxes where inbound calls that route to voice mail are disconnected in approximately 20 or so seconds. 

Same is true for all mailboxes in this set of 20 mailboxes - and this occurs only in this set of 20 mailboxes..

These 20 mailboxes are newly installed, and are the only mailboxes in our system where the inbound calls come in via IP Flex trunks.

Note that the message length setting for these mailboxes and for the template they are based on is 300 seconds (5 minutes).

Based on a few thousand other Unity mailboxes that do not have this problem I do not believe the issue is the Unity system.

Also, 'answered calls' within the same population of stations, that come in on the IP Flex trunks do not get disconnected during conversation, no matter how long they talk.

But once a call forwards on an unanswered or busy condition to Unity, and is answered by a mailbox greeting, it is disconnected in approximately 20 or so seconds.

The one thing all of these mailboxes have in common is that their calls originate on IP Flex trunks.

So - I suspect there's a signaling issue between the IP Flex trunks and the Unity interface, on the IP Flex side, maybe the Flex trunks???

I'd really appreciate any input as to where to look, what to check or adjust, etc.

thanks as always,

[Jonathan Schulenberg]

The first question to answer is who tears down the call: the AT&T SIP Proxy, CUBE, CUCM, or CUC? Who sends the first BYE message?

I typically start at CUBE to see whether it's customer or carrier. If it was the customer side I typically grab CUCM traces next to see whether it was CUCM or CUC. If it was CUC then you'd want to grab conversation manager and SIP integration traces.

After you know who tore the call down you can focus on why. Perhaps they weren't receiving RTP media, there was a volume level problem that caused CUC to think there was silence, or CUBE felt something was missing (e.g. RTCP reports).

[Mike Shoop]

Jonathan,

I'm very grateful for your clear and methodical response and will proceed accordingly as soon as I get to that office in approx. 2 hours.  Looking forward to replying immediately after.  Thanks again! 

[Mike Shoop]

Jonathan, I am displaying below what I think is the disconnect event - it happens about 30 or so seconds into leaving a message, beginning after the end of the greeting. I am attaching the whole capture as a notepad .txt.

"*Jun 17 15:04:03.913: cc_api_get_xcode_stream : 4982
*Jun 17 15:04:03.913: //646813/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:
  
*Jun 17 15:04:03.913: cc_api_get_xcode_stream : 4982
*Jun 17 15:04:03.913: //646813/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:
  
*Jun 17 15:04:03.913: cc_api_get_xcode_stream : 4982
*Jun 17 15:04:03.913: //646813/69CA8996BB25/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x1A015, Source Interface=0x1588E210, Source Call Id=646813,
   Destination Call Id=646812, Disposition=0x0, Tag=0x0
*Jun 17 15:04:03.913: //646812/69CA8996BB25/CCAPI/cc_generic_bridge_done:
   Conference Id=0x1A015, Source Interface=0x1588E210, Source Call Id=646813,
   Destination Call Id=646812, Disposition=0x0, Tag=0x0
*Jun 17 15:04:03.913: //646812/69CA8996BB25/CCAPI/ccCallDisconnect:
   Cause Value=102, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Jun 17 15:04:03.913: //646812/69CA8996BB25/CCAPI/ccCallDisconnect:
   Cause Value=102, Call Entry(Responsed=TRUE, Cause Value=102)
*Jun 17 15:04:03.913: //646813/69CA8996BB25/CCAPI/ccCallDisconnect:
   Cause Value=102, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=102)
*Jun 17 15:04:03.913: //646813/69CA8996BB25/CCAPI/ccCallDisconnect:
   Cause Value=102, Call Entry(Responsed=TRUE, Cause Value=102)
*Jun 17 15:04:03.921: //646813/69CA8996BB25/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x1588E210, Tag=0x0, Call Id=646813,
   Call Entry(Disconnect Cause=102, Voice Class Cause Code=0, Retry Count=0)
*Jun 17 15:04:03.921: //646813/69CA8996BB25/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Jun 17 15:04:03.921: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
  
*Jun 17 15:04:03.921: :cc_free_feature_vsa freeing 16036940
*Jun 17 15:04:03.921: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
   

[Jonathan Schulenberg · Accepted solution]

Hi Mike-

I should have said this before: use debug ccsip messages when the router is quiet (i.e. very verbose debug). It'll print the messages out in human-readable form.

[Mike Shoop]

Jonathan, I am attaching a file 'ccsipDOH' (notepad) where I think I 've caught it in the act of disconnecting, but I'm not clear what it's saying.

I'm hoping you can take a look and maybe see the reason for the disconnect -

Here's roughly the last part of the last page.  the rest of the output is contained in  the file.

User-Agent: Cisco-SIPGateway/IOS-15.4.1.T1

Max-Forwards: 70

P-Asserted-Identity: "ST THOMAS RUTHE" <sip:6154943095@10.82.70.62>

Timestamp: 1466441714

CSeq: 102 BYE

Reason: Q.850;cause=102

P-RTP-Stat: PS=1662,OS=398880,PR=667,OR=104812,PL=0,JI=0,LA=0,DU=50

Content-Length: 0

*Jun 20 16:55:14.719: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x4246881C
*Jun 20 16:55:14.723: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x4246881C with refCount = 1
*Jun 20 16:55:14.723: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_create: created msg=0x101FE80 with refCount = 1
*Jun 20 16:55:14.723: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/HandleUdpIPv4SocketReads: Msg enqueued for SPI with IP addr: [10.82.70.30]:5060, local_address:[ - ]
*Jun 20 16:55:14.723: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x4246881C
*Jun 20 16:55:14.723: //-1/xxxxxxxxxxxx/SIP/Info/info/4096/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 2 for event 1
*Jun 20 16:55:14.727: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportProcessNWNewConnMsg: context=0x0
*Jun 20 16:55:14.727: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/ccsip_new_msg_preprocessor: Checking Invite Dialog
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sipSPIMatchRespToReqTran:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sippmh_match_resp_header_from:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sippmh_match_resp_header_to:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sipSPICopyToTagToCCB:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sipSPICopyToTagToCCB:exit@1948:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Info/info/1024/sipSPIMatchRespToReqTran: removing unneeded z9hG4bK82EC71AA4 from via branch list
*Jun 20 16:55:14.727: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_lock: Increment msg (0x101FE80) counter, current msg->refCount = 2
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sipSPIPushInboundContainerIntoCCB:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/ccsipDisplayMsg:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 200 OK

Via: SIP/2.0/UDP 10.82.70.62:5060;branch=z9hG4bK82EC71AA4

From: "ST THOMAS RUTHE" <sip:6154943095@10.82.70.62>;tag=18CD18B8-1610

To: <sip:6298885168@10.82.70.30>;tag=24187350~e0ad34d2-6b1f-4c52-ae41-36666e3464bc-173972103

Date: Mon, 20 Jun 2016 17:09:19 GMT

Call-ID: 71266573-363E11E6-82F3D669-12345CE1@10.82.70.62

Server: Cisco-CUCM10.5

CSeq: 102 BYE

Content-Length: 0

*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/act_disconnecting_new_message:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sact_disconnecting_new_message_response:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sipSPICheckResponseExt:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Info/verbose/1024/sipSPICheckResponseExt: non-INVITE response with no RSEQ - do not disable IS_REL1XX
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Info/sact_disconnecting_new_message_response: [sact_disconnecting_new_message_response] Received Response Class [2] Method Code [103]

*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sipSPIStopTimer:
*Jun 20 16:55:14.727: //647420/71252D2382ED/SIP/Function/sipSPICallClose:
*Jun 20 16:55:14.791: //647419/71252D2382ED/SIP/Function/sipSPIBwCacReleaseAccountedBw:exit@23294:
*Jun 20 16:55:14.791: //647419/71252D2382ED/SIP/Function/ccsip_clear_rtp_session_pending_q:
*Jun 20 16:55:14.791: //647419/71252D2382ED/SIP/Info/verbose/4096/sipSPIUfreeOneCCB: Freeing ccb 0x15DC7608
*Jun 20 16:55:14.791: //-1/xxxxxxxxxxxx/SIP/Info/verbose/4096/sipSPIGetContextFromTable: NO context for key[647391]
*Jun 20 16:55:14.791: //-1/xxxxxxxxxxxx/SIP/Info/info/1024/httpish_msg_free: Freed msg=0x1606AB1C
STM-VOICE-02#
STM-VOICE-02#
STM-VOICE-02#
STM-VOICE-02#
STM-VOICE-02#term no mon
STM-VOICE-02#undeg v bug all
All possible debugging has been turned off
STM-VOICE-02#

[Mike Shoop]

forgot to attach the file(s) attaching ccsip verbose, and ccsip messages

Below is the last page or so of the debug ccsip messages command output.

[Mike Shoop]

gateway
 media-inactivity-criteria all
 timer receive-rtcp 5
 timer receive-rtp 86400
!
sip-ua
 no remote-party-id
 retry invite 2
 timers expires 1800000
 connection-reuse
!

[Jonathan Schulenberg]

That won't work as Unity Connection doesn't send RTCP reports. You'll need to either disable media inactivity detection outright; or, rely on DSP-based methods to get it done. The problem with the later is that CUBE doesn't typically have DSPs installed/invoked, though it is possible using Local Transcoding Interface. You can use the DSP Calculator to figure out the DSP density required. There are other benefits such as Acoustic Shock Protection and Noise Reduction that can help with cost justification but be careful that the dial-peers those features are attached to never process a fax or modem call.

! Disable it
gateway
  no media-inactivity-criteria all
  no timer receive-rtcp 5
  no receive-rte 86400
!
! Relying on DSPs instead:
!
gateway
  media-inactivity-criteria rtplib
  timer receive-rtp 1200

[Deepak Mehta]

Very helpful info ...thanks

[Jonathan Schulenberg · Accepted solution]

Ok, that's progress. Does CUBE send that BYE packet (the first few lines where that is shown in the debug got stripped off)?

If yes, then my first guess is media inactivity detection based on that cause code. What's the configuration look like, especially the section called gateway?

[Mike Shoop]

Your first 'guess' was absolutely correct. Very grateful for the help.!!