CME - Calls Dropping after 15m

Davidwagman1 · ‎01-21-2014

Hi All,

I've got a 2851 running CME. Outbound calls are dropping after 15 minutes, consistently. I've attached a santized version of the sh run and debug ccsip. I did some google-ing for Reason: Q.850;cause=21, but I can't find anything relevant so I've come to the experts. Any help would be greatly appreciated.

Thanks,

David

Jay Schulze · ‎01-21-2014

Hello,

I can't really tell since some of the info was removed from the debugs as to which was the initial call. But if I picked the right one. Looks like you are getting a re-invite. This is almost always a problem with the session expires timer and it not being refreshed properly. Have a look at this thread with a similar issue.

https://supportforums.cisco.com/thread/2244188

Davidwagman1 · ‎01-22-2014

Thanks for the reply Jay. I took a look at that thread, and I have the solution in that thread ("dtmf-relay rtp-nte") included in the appropriate dial peer here. I've also reached out to my provider, but any other help would be appreciated. It looks like this is probably the relevant bit of the logs:

Jan 21 23:34:02.266: //67781/4EBA98189131/SIP/Info/sipSPISendInviteResponse: Associated container=0x4C3E5B38 to Invite Response 403

Jan 21 23:34:02.266: //67781/4EBA98189131/SIP/Transport/sipSPITransportSendMessage: msg=0x4B491DF4, addr=172.246.162.170, port=5085, sentBy_port=5085, local_addr=, is_req=0, transport=1, switch=0, callBack=0x0

Jan 21 23:34:02.266: //67781/4EBA98189131/SIP/Transport/sipSPITransportSendMessage: Proceedable for sending msg immediately

Jan 21 23:34:02.266: //67781/4EBA98189131/SIP/Transport/sipTransportLogicSendMsg: switch transport is 0

Jan 21 23:34:02.266: //67781/4EBA98189131/SIP/Transport/sipTransportLogicSendMsg: Trying to send resp=0x4B491DF4 to default port=5085

Jan 21 23:34:02.266: //-1/xxxxxxxxxxxx/SIP/Transport/sipConnectionManagerGetConnection: connection required for raddr:172.246.162.170, rport:5085 with laddr:

Jan 21 23:34:02.266: //67781/4EBA98189131/SIP/Transport/sipTransportLogicSendMsg: Connection obtained...sending msg=0x4B491DF4

Jan 21 23:34:02.266: //-1/xxxxxxxxxxxx/SIP/Transport/sipTransportPostSendMessage: Posting send for msg=0x4B491DF4, addr=172.246.162.170, port=5085, local_addr=, connId=5 for UDP

Jan 21 23:34:02.266: //67781/4EBA98189131/SIP/Msg/ccsipDisplayMsg:

Sent:

SIP/2.0 403 Forbidden

Via: SIP/2.0/UDP 172.246.162.170:5085;branch=z9hG4bK-c9c98cc5d75a5919538e9ea26972924e;rport

From: 1213<1213>;tag=b319c76b

To: 1011972598546259<1011972598546259>;tag=1EED94F0-21C4

Date: Tue, 21 Jan 2014 23:33:46 GMT

Call-ID: c9c98cc5d75a5919538e9ea26972924e

CSeq: 1 INVITE

Allow-Events: telephone-event

Server: Cisco-SIPGateway/IOS-12.x

Reason: Q.850;cause=21

Content-Length: 0

Suresh Subramanian · ‎01-22-2014

what is the IOS version? if it is 15.1 have you added these IP addresses 172.246.162.170 & 98.X.X.X

under trust list?

if it not 15.1 ios, have you configured these IP address in your dial-peers?

Please rate all the useful posts

//Suresh Please rate all the useful posts.

Davidwagman1 · ‎01-22-2014

Thanks for the reply sureshsub2. The 98.XXX IP is my CME's external IP. I have my provider's IP in the trusted list. I'm not sure where the 172.248.162.170 IP is coming from. The below code happened mid call. After checking with my provider, they don't believe its one of theirs, and the To/Fron below confuses me a bit:

Thanks,

David

Received:

INVITE sip:1011972598546259@98.XXX.XXX.XXX SIP/2.0

To: 1011972598546259<1011972598546259>

From: 1213<1213>;tag=b319c76b

Via: SIP/2.0/UDP 172.246.162.170:5085;branch=z9hG4bK-c9c98cc5d75a5919538e9ea26972924e;rport

Call-ID: c9c98cc5d75a5919538e9ith key=[37670] to table

Jan 21 23:33:46.730: //-1/000000000000/SIP/Info/ccsip_offer_ans_init:

Jan 21 23:33:46.730: //-1/000000000000/SIP/Info/ccsip_iwf_init: ea26972924e

CSeq: 1 INVITE

Contact: <1213>

Max-Forwards: 70

Allow: INVITE, ACK, CANCEL, BYE

User-Agent: sipcli/v1.8

Content-Type: application/sdp

Content-Length: 286

v=0

o=sipcli-Session 129339380 1856427634 IN IP4 172.246.162.170

s=sipcli

c=IN IP4 172.246.162.170

t=0 0

m=audio 5089 RTP/AVP 18 0 8 101

a=fmtp:101 0-15

a=rtpmap:18 G729/8000

a=rtpmap:0 PCMU/8000

a=rtpmap:8 PCMA/8000

a=rtpmap:101 telephone-event/8000

a=ptime:20

a=sendrecv

luirami2 · ‎01-22-2014

David,

I don't actually see the call connecting for it to be droped after 15 min.

Also as soon as the call comes into the router the router rejects it with cause 21 (call rejected) which I would say it is due to the toll fraud application (ip address trusted list) not including the IP address coming from ITSP.

You can try adding that IP into the trusted list if that is your issue.

If the call is actually connecgting and dropping, could you explain that more in detail and also the exact call flow and capturfe the following debugs.

debug ccsip messages

debug voip ccapi inout

~ Luis Ramirez,

MOHIT SINGH · ‎01-22-2014

Hi David,

Call is getting disconnected because your ITSP is not refreshing the SIP session. Below is my expanation

1. In 100 Trying or 200 OK ITSP update that the session will expire in 1800 sec (30 min) and session can be only refreshed (using ReInvite or Update) by ITSP (uas=>called party). Go through rfc4028 to understand in detail about session-expire timer

Jan 21 23:18:54.002: //67776/387461CF9115/SIP/Msg/ccsipDisplayMsg:

Received:

SIP/2.0 100 Trying

Call-ID: 3A9A522A-822911E3-911AF15E-B6B24127@98.XXX.XXX.XXX <---- use this call id to track call

Session-Expires: 1800;refresher=uas

2. As per RFC4028 recommends uac (calling side) to wait for around 1/3rd of session-expire timer before sending BYE to disconnect the call. Below is snipet from RFC regarding disconnecting the call

"

   Similarly, if the side not performing refreshes does not receive a
   session refresh request before the session expiration, it SHOULD send
   a BYE to terminate the session, slightly before the session
   expiration.  The minimum of 32 seconds and one third of the session
   interval is RECOMMENDED"

2. Generally Cisco router will not wait for 30 minut for a refresh (Re Invite) to disconnect the call. It waits for around half the time of "session-expire" time. So before 15 minute of active call if your ITSP does not send a ReInvite to gateway to refresh the session then gateway will disconnect the call. We can see in log as soon as half the timer expires gateway disconnects the call

Jan 21 23:34:46.663: //-1/xxxxxxxxxxxx/SIP/Event/sipSPIEventInfo: Queued event from SIP SPI : SIPSPI_EV_CC_CALL_DISCONNECT

Jan 21 23:34:46.667: //67776/387461CF9115/SIP/Info/ccsip_indicate_rt_packet_stats: Processing stats for callid=67776, proc_id=1

Jan 21 23:34:46.667: //-1/xxxxxxxxxxxx/SIP/Info/ccsip_process_sipspi_queue_event: ccsip_spi_get_msg_type returned: 3 for event 8

Jan 21 23:34:46.667: //67776/387461CF9115/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer

Jan 21 23:34:46.667: //67776/387461CF9115/SIP/Info/sipSPIStopHoldTimer: Stopping hold timer

Jan 21 23:34:46.667: //67776/387461CF9115/SIP/Info/sipSPISendBye: Associated container=0x4C3E63D0 to Bye

Jan 21 23:34:46.667: //67776/387461CF9115/SIP/Transport/sipSPISendBye: Sending BYE to the transport layer

Jan 21 23:34:46.679: //67776/387461CF9115/SIP/Msg/ccsipDisplayMsg:

Sent:

BYE sip:[CALLED #]@74.63.41.218:5060 SIP/2.0

Via: SIP/2.0/UDP 98.XXX.XXX.XXX:5060;branch=z9hG4bK2701BF5

From: "[NAME]" <>;tag=1EDFF594-1681

So I will suggest you to ask your provider to either remove session-expire header from SIP message so that session can stay active without refresh mechanism if not then they should send a session refresh (Invite or Update) before 15 minute so that gateway will not disconnect the call. I don't think there is any configuration in gateway to bypass session expire timeout check.

Regards,

Mohit Singh

Davidwagman1 · ‎01-22-2014

Thanks for the replies.

Mohit - I submitted another ticket with my provider to see what they say about the session-expire header.

Luis - I've pasted a santized copy of debug ccsip messages & debug voip ccapi inout below. I'm not sure it will be too helpful as there isn't much from the disconnect. I've been testing by calling my cell from the IP phone, and what happens is voice will cut out for a few seconds and then my cell will disconnect and hang up and the voip line will remain open. This also happens with other outbound #s where it just cuts to silence on both ends (though the call doesn't actually off-hook on the IP phone until you hit end call or hang up the receiver).

Thanks

David

=~=~=~=~=~=~=~=~=~=~=~= PuTTY log 2014.01.22 18:28:25 =~=~=~=~=~=~=~=~=~=~=~=

CME#debug ccsip messages

SIP Call messages tracing is enabled

CME#debug voip ccapi inout

voip ccapi inout debugging is on

CME#

Jan 22 23:28:47.094: //-1/C68AE3F395C5/CCAPI/cc_api_display_ie_subfields:

cc_api_call_setup_ind_common:

cisco-username=

----- ccCallInfo IE subfields -----

cisco-ani=109

cisco-anitype=0

cisco-aniplan=0

cisco-anipi=0

cisco-anisi=0

dest=

cisco-desttype=0

cisco-destplan=0

cisco-rdie=FFFFFFFF

cisco-rdn=

cisco-rdntype=0

cisco-rdnplan=0

cisco-rdnpi=0

cisco-rdnsi=0

cisco-redirectreason=0 fwd_final_type =0

final_redirectNumber =

hunt_group_timeout =0

Jan 22 23:28:47.094: //-1/C68AE3F395C5/CCAPI/cc_api_call_setup_ind_common:

Interface=0x4CA3AAC8, Call Info(

Calling Number=109,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),

Called Number=(TON=Unknown, NPI=Unknown),

Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE,

Incoming Dial-peer=20013, Progress Indication=ORIGINATING SIDE IS NON ISDN(3), Calling IE Present=TRUE,

Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1

Jan 22 23:28:47.094: //-1/C68AE3F395C5/CCAPI/ccCheckClipClir:

In: Calling Number=109(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)

Jan 22 23:28:47.094: //-1/C68AE3F395C5/CCAPI/ccCheckClipClir:

Out: Calling Number=109(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)

Jan 22 23:28:47.094: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Jan 22 23:28:47.094: :cc_get_feature_vsa malloc success

Jan 22 23:28:47.094: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Jan 22 23:28:47.094: cc_get_feature_vsa count is 1

Jan 22 23:28:47.094: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Jan 22 23:28:47.094: :FEATURE_VSA attributes are: feature_name:0,feature_time:1320780192,feature_id:4401

Jan 22 23:28:47.098: //68014/C68AE3F395C5/CCAPI/cc_api_call_setup_ind_common:

Set Up Event Sent;

Call Info(Calling Number=109(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),

Called Number=(TON=Unknown, NPI=Unknown))

Jan 22 23:28:47.098: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:

Jan 22 23:28:47.098: :Inside cc_build_feature_vsa

Jan 22 23:28:47.098: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:

Jan 22 23:28:47.098: feature call basic

Jan 22 23:28:47.098: //-1/xxxxxxxxxxxx/CCAPI/cc_build_feature_vsa:

Jan 22 23:28:47.098: cc_build_feature_vsa attr is fn:TWC,ft:01/22/2014 18:28:47.094,cgn:109,cdn:,frs:0,fid:4401,fcid:C68AE3F382F311E395C5F15EB6B24127,legID:109AE

Jan 22 23:28:47.102: //68014/C68AE3F395C5/CCAPI/cc_process_call_setup_ind:

Event=0x4BBD6ED8

Jan 22 23:28:47.102: //68014/C68AE3F395C5/CCAPI/ccCallSetContext:

Context=0x4EBBE3F8

Jan 22 23:28:47.102: //68014/C68AE3F395C5/CCAPI/cc_process_call_setup_ind:

>>>>CCAPI handed cid 68014 with tag 20013 to app "_ManagedAppProcess_Default"

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/ccCallSetupAck:

Call Id=68014

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/cc_api_set_transfer_info:

Transfer Number=, Transfer Reason=0x0

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/ccGenerateToneInfo:

Stop Tone On Digit=TRUE, Tone=Dial Tone,

Tone Direction=Network, Params=0x0, Call Id=68014

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/ccSetDigitTimeouts:

Initial Digit Timeout=-1000(ms), Inter Digit Timeout=-1000(ms)

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/ccSetDigitTimeouts:

Call Entry(Inter Digit Timeout=10000(ms), Initial Digit Timeout=10000(ms))

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/ccCallReportDigits:

(callID=0x109AE, digit_event=0x1, enable=TRUE, consume=FALSE)

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/ccCallReportDigits:

Enabled=TRUE, Call Id=68014

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/cc_api_call_report_digits_done:

(vdbPtr=0x4CA3AAC8, callID=0x109AE, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/cc_api_call_report_digits_done:

Enabled=TRUE, Disposition=0x0, Interface=0x4CA3AAC8, Call Id=68014

Jan 22 23:28:47.106: //68014/C68AE3F395C5/CCAPI/cc_api_call_report_digits_done:

Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))

Jan 22 23:28:48.130: //68014/C68AE3F395C5/CCAPI/cc_api_call_digit_begin: