CME 11 - Incomming call drop after 7 seconds

[s4siddiqui]

Hello all...can some one please advice what is the cause of the call getting dropped right at 7 seconds mark...outgoing is no issue....I am struggling with this system and need help. sh run attached.

[Ratheesh Kumar]

Hi there

Can you get the disconnect cause of the call from debug voice ccapi all, Pls share the debuts.

Hope this helps

Cheers

Rath!

***Please rate helpful posts***

[s4siddiqui]

thanks for the reply...please see attached debug you requested...no idea what anomaly to look for.

in this 7 seconds call the audio appears to be fine both ways but get disconnect right at 7 seconds....bizarre behavior..

please advice. 

[Maren Mahoney]

The cause code 102 at 14:10:26.323, which is the first message at the point of disconnect generally indicates an expired timer of some kind. But what kind is unclear. And I can't tell the directionality of the message either.

I would have asked for a debug ccsip messages, or if you can isolate a single call (because of the volume of output) a debug ccsip all for one of these calls.

I'm guessing that ongoing OK messages are not being acknowledged, but I can't be sure until I see more information.

Question: I see that you have globally bound SIP to your internal gi0/0 interface. Did your service provider work with you on that? With ITSP SIP trunks I usually see SIP bound to the external-facing interface directly on the dial-peer pointing to the service provider. The problem you are experiencing might be caused by this, but if it is by design per the service provider then hopefully not.

[R0g22]

There is a conference create for call legs - 161 and 162 -

May 27 14:10:18.819: //161/7AF32B6D0733/CCAPI
KEMVG1#/ccConferenceCreate:
Call Entry(Conference Id=0x4, Destination Call Id=162)
May 27 14:10:18.819: //162/7AF32B6D0733/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x4, Destination Call Id=161)
May 27 14:10:18.819: //161/7AF32B6D0733/CCAPI/ccConferenceCreate:

After about 8 seconds, your ITSP drops the call (Leg 161) -

May 27 14:10:26.323: //161/7AF32B6D0733/CCAPI/cc_api_call_disconnected:
Cause Value=102, Interface=0x22312B40, Call Id=161
May 27 14:10:26.323: //161/7AF32B6D0733/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=TRUE, Cause
KEMVG1# Value=102, Retry Count=0)

Now coming to your config, your global SIP binds would be necessary since you have a SIP CME working.

Add the following commands to all your dial-peers -

voice-class sip bind media source-interface gig0/0
voice-class sip bind control source-interface gig0/0

Post the change, test your calls.

[Maren Mahoney]

How can you tell that the message:

"May 27 14:10:26.323: //161/7AF32B6D0733/CCAPI/cc_api_call_disconnected:
Cause Value=102, Interface=0x22312B40, Call Id=161"

Is coming from the service provider? I don't see directionality on that message and I'm curious to know how you see that.

[R0g22]

Sure @Maren Mahoney

There is no direction to CCAPI logs.

If you would check the logs again, incoming dial-peer gets selected and CCAPI assigns leg = 161 to it (this is a random arbitrary number) -

Incoming Dial-peer=1, Progress Indication=NULL(0), Calling IE Present=TRUE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=161

Next, the outbound virtual dial-peer is selected and CCAPI will assign another call leg which will be incoming+1 i.e. 162 -

Account Number=4168778426, Final Destination Flag=TRUE,
Guid=7AF32B6D-C403-4365-0733-8C99B653BD6C, Outgoing Dial-peer=40001

May 27 14:10:14.791: //162/7AF32B6D0733/CCAPI/cc_insert_guid_pod_entry:
Incoming=FALSE, Call Id=162

Finally when the IP Phones answers, both the legs need to be joined to create a call which is the "ccConferenceCreate" event. You see both 162 and 161 mentioned in there.

KEMVG1#/ccConferenceCreate:
Call Entry(Conference Id=0x4, Destination Call Id=162)
May 27 14:10:18.819: //162/7AF32B6D0733/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x4, Destination Call Id=161)

KEMVG1#819: //161/7AF32B6D0733/CCAPI/cc_process_notify_bridge_done:
Conference Id=0x4, Call Id1=161, Call Id2=162

Now for the disconnect, the CV=102 when first hits the CCAPI stack on IOS references ID=161 which was initially assigned for the incoming/ITSP facing leg. This happened due to some disconnect being triggered at the SIP/Application stack from the ITSP which was relayed down to the CCAPI stack.

May 27 14:10:26.323: //161/7AF32B6D0733/CCAPI/cc_api_call_disconnected:
Cause Value=102, Interface=0x22312B40, Call Id=161
May 27 14:10:26.323: //161/7AF32B6D0733/CCAPI/cc_api_call_disconnected:

This is then further relayed down to the second/IP Phone leg up the SIP stack post which there would have been a SIP message to tear down the session -

May 27 14:10:26.323: //161/7AF32B6D0733/CCAPI/ccCallDisconnect:
Cause Value=102, Call Entry(Disconnect Cause=102)
May 27 14:10:26.323: //161/7AF32B6D0733/CCAPI/ccCallDisconnect:
Call Entry(Disconnect Cause=102)

Hope that makes sense :)

[Maren Mahoney]

It does, and I learned something so thank you very much!

However, the call leg 161 is the leg that initiated the disconnect but I still don't see how we can know that the disconnect was caused by signaling from the ITSP on call leg 161 or if it was caused by signaling from the router on call leg 161. I suppose we can infer that the absence of other ccapi messages on the router would indicate that the router did not initiate it. But can we be sure?

[R0g22]

Your welcome.

And yes as well as No to your question. It is also dependant upon CV. 102 is really some sort of a timer and we can infer that a SIP signaling caused that to happen and also the fact that the call got connected initially. So some sort of a signaling did not complete which caused the call drop. That some sort of happened on 161 call leg.
Other than that, it's just out of experience that I was quite sure. Once you go over these logs over time and along with application stack logs, some things will just become second nature.

So we still need SIP debugs to see what happened on the SIP stack and whether the signaling was not completed by us or by the ITSP.

[s4siddiqui]

thansk you call for your input,

• yes the bind interface is my gig 0/1 which is an external interface and is connected to my Firewall where the NATing is happening.
• I have added bind int gig 0/1 to all my dial peers (still same issue)
• this is definietely appears to be a timer issue.
• I have managed to get pcap of this and it looks like the message BYE is coming from the CME interface 192.168.70.254 which is my gig 0/1 (see attached)

also debug ccsip is attached calling from 4168778426- outside number to 6042833262 - CME number

[R0g22]

The debugs don't have the inbound call. It only has calls from 6042833262 and not to. PCAP is also just a snippet.

Enable the following only -

debug ccsip message
debug ccsip error
debug voice ccapi inout

Take the logs in a buffer only and not terminal.

[s4siddiqui]

thanks raghav...please see attached updated debug I just created (all three commands)

*not letting me attach pcap file though.

[R0g22]

Yeah, I suspected it correct. Your ITSP never responds back with an ACK. CME keeps sending "200 OK" but never receives a ACK and then times out, drops the call and sends a BYE.

May 28 09:02:02.025: //75/9493C2ED7463/SIP/Msg/ccsipDisplay
KEMVG1#Msg:
Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 208.43.27.75;branch=z9hG4bKa7d6.5cefbec978d2bf2f6752f3d158310875.0,SIP/2.0/UDP 208.43.27.75:5065;branch=z9hG4bKa569130a09e0199dae6ba92c83e2cf9a;rport=5065
From: 4168778426 <sip:4168778426@208.43.27.75>;tag=8ae45b6df21ca968c71cafdac59d60ba
To: <sip:16042833263@64.114.20.54>;tag=222758-D57
Date: Mon, 28 May 2018 16:01:55 GMT
Call-ID: 83FC8446@208.72.120.66-b2b_1
CSeq: 200 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRI
KEMVG1#BE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Contact: <sip:16042833263@192.168.70.254:5060>
Supported: replaces
Supported: sdp-anat
Server: Cisco-SIPGateway/IOS-15.6.2.T2
Session-ID: 5eaee15300105000a000285261c06097;remote=452c73ac4c40581c870af8be32b37c24
Supported: timer
Content-Type: application/sdp
Content-Disposition: session;handling=required
Content-Length: 253

v=0
o=CiscoSystemsSIP-GW-UserAgent 3385 1918 IN IP4 192.168.70.254
s=SIP Call
c=IN IP4 192.168.70.
KEMVG1#254
t=0 0
m=audio 16406 RTP/AVP 0 101
c=IN IP4 192.168.70.254
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20

A couple of things -
1. Did you do this test after the adding the dial-peer sip binds that I highlighted ?
2. Who is doing NAT in your network ? Can you take a pcap from it's egress interface ?

[Ayodeji Okanlawon]

Hi Based on these new sets of logs, I can say that it is not the ITSP that is disconnecting the call. Here are the anaysis

++INVITE received +++

May 28 09:01:55.985: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:
Received:
INVITE sip:16042833263@64.114.20.54:5060 SIP/2.0
Via: SIP/2.0/UDP 208.43.27.75;branch=z9hG4bKa7d6.5cefbec978d2bf2f6752f3d158310875.0
Via: SIP/2.0/UDP 208.43.27.75:5065;branch=z9hG4bKa569130a09e0199dae6ba92c83e2cf9a;rport=5065
Max-Forwards: 69
From: 4168778426 <sip:4168778426@208.43.27.75>;tag=8ae45b6df21ca968c71cafdac59d60ba
To: <sip:16042833263@64.114.20.54>
Call-ID: 83FC8446@208.72.120.66-b2b_1

+++ Here is the 200 OK you send to your ITSP. Your ITSP didnt respond to it. +++

Sent:
SIP/2.0 200 OK
Via: SIP/2.0/UDP 208.43.27.75;branch=z9hG4bKa7d6.5cefbec978d2bf2f6752f3d158310875.0,SIP/2.0/UDP 208.43.27.75:5065;branch=z9hG4bKa569130a09e0199dae6ba92c83e2cf9a;rport=5065
From: 4168778426 <sip:4168778426@208.43.27.75>;tag=8ae45b6df21ca968c71cafdac59d60ba
To: <sip:16042833263@64.114.20.54>;tag=222758-D57
Date: Mon, 28 May 2018 16:01:55 GMT
Call-ID: 83FC8446@208.72.120.66-b2b_1
CSeq: 200 INVITE
Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRI
KEMVG1#BE, NOTIFY, INFO, REGISTER
Allow-Events: telephone-event
Contact: <sip:16042833263@192.168.70.254:5060>

The reason is because of your contact header. ACK is called a future request and is sent to the IP address in the ocntact header. As you can see the host portion of your contact header has a private IP: 192.168.70.254

It appears that your NAT is not setup correctly..

[Ayodeji Okanlawon]

( NB I have edited my original post as that was inaccurate )

+ 5 to Nipun for an excellent explanation to your question Maren. ( I must sau however that it is not the ITSP that is disconnecting the call, it is the gateway)

There is another trick with CCAPI logs.

Here is the rule of thumb..

Anything with an _ (underscore) implies that CCAPI stack on gateway received the message

Anything without the _ means that CCAPI originated the message

So if you apply this logic, we can easily know who sends what during the life of the packets

++ In this example here ++

The cc_api_call_disconnected: Means that CCAPI recieved the disconnect message. The question is from where?  SIP application layer, ITSP or IP Phone. Since the ITSP doesnt talk to CCAPI layer on this call, we can say it is not from the ITSP. So we need to look deeper.

+++ INVITE from ITSP +++

Gateway receives INVITE request from ITSP 

Received:
INVITE sip:16042833263@64.114.20.54:5060 SIP/2.0
Via: SIP/2.0/UDP 208.43.27.75;branch=z9hG4bKa7d6.5cefbec978d2bf2f6752f3d158310875.0
---

++ Next thing we see is that SIP layer sends request to CCAPI ++

++ cc_api_call_setup_ind_common means that CCAPI received this request ++

ay 28 09:01:55.989: //-1/9493C2ED7463/CCAPI/cc_api_call_setup_ind_common:

++ CCAPI matches an inbound dial-peer and allocates a CI ++

Incoming Dial-peer=1, Progress Indication=NULL(0), Calling IE Present=TRUE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=75

++=CCAPI matches an outbound dial-peer and later allocates an outbound CI  (76)++

KEMVG1# Guid=9493C2ED-C682-B219-7463-5044FD781CFD, Outgoing Dial-peer=40001

--

May 28 09:01:55.997: //76/9493C2ED7463/CCAPI/ccIFCallSetupRequestPrivate:

+++ Now gateway sends an outbound request to IP Phone +++

Sent:
INVITE sip:3263@192.168.70.53:5060 SIP/2.0
Via: SIP/2.0/UDP 192.168.70.254:5060;branch=z9hG4bK772335

++ We get 180 ringing from IP Phone ++

May 28 09:01:56.125: //76/9493C2ED7463/SIP/Msg/ccsipDisplayMsg:
Received:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 192.168.70.254:5060;branch=z9hG4bK772335

+++ Now CCAPI receives alert on call-id 76 ( outbound leg to IP phone)

May 28 09:01:56.125: //76/9493C2ED7463/CCAPI/cc_api_call_alert:

++ Next CCAPI sends alert to Call -id 75 ( inbound leg ) ( from SIP layer not ITSP)
Call Entry(Retry Count=0, Responsed=TRUE)
May 28 09:01:56.125: //75/9493C2ED7463/CCAPI/ccCallAlert:

++ SIP layer sends ringing to ITSP ++

Sent:
SIP/2.0 180 Ringing
Via: SIP/2.0/UDP 208.43.27.75;branch=z9hG4bKa7d6.5cefbec978d2bf2f6752f3d158310875.0,SIP/2.0/UDP 208.43.27.75
KEMVG1#:5065;branch=z9hG4bKa569130a09e0199dae6ba92c83e2cf9a;rport=5065

++ Next CCAPI says I am out of retries ++

May 28 09:02:09.525: //75/9493C2ED7463/SIP/Error/act_sentsucc_wait_ack:
Out of retries

++ Next CCAPI receives a disconnect from the SIP layer ( remember the Call-ID 75 is for SIP layer to CCAPI +++

May 28 09:02:09.525: //75/9493C2ED7463
KEMVG1#/CCAPI/cc_api_call_disconnected:
Cause Value=102, Interface=0x22196900, Call Id=75