how to troubleshoot dropped calls

[cashqoo]

hi, i am experiencing drop calls between remote sites

Backgound: the network between a HQ and 2 remote sites are connected in a hub-and-spoke. the HQ is using CCM5.1, while the remote sites are using CME. Remote sites are connected by trunks to the HQ ccm.

Problem: calls between remote sites are dropped. when the called party answer the call using softkey, the call didnt established. however, the phone received another ringing tone almost immediately. when the called party answer the phone again, the call is dropped permanently with the calling party hearing the hangup tone.

there are no problems with calls between HQ and either remote site.

appreciate any advice.

cash

[Md. Mijanur Rahman]

Hi,

Can you test with 'debug voice ccapi all' and get the disconnect cause? This will help to find out the issue.

HTH.

Thanks,

Mijanur Rahman

[cashqoo]

i noticed disconnect code=65, meaning its codec problem?

the calling party CME's debug voip ccapi all log is attached.

[Md. Mijanur Rahman]

Well, it might be the codec issue, can you post your both CME configs? It would be easy to troubleshoot then.

Thanks,

Mijanur Rahman

[cashqoo]

i have removed some of the unnecessary and sensitive lines.

the dialled number is matched to dial plan 100, 101.

[Cedric Van Labeke]

Hi Cash,

Let me go through this info as I normally would do:

I looked at your configs for both, but without any calling/called party info and an overview of what is which IP address, I couldn't figure out really how everything fitted together. Always a good idea to post show ver, show deb, show run and then show log (which had captured the debugs).

So I looked at your "debug voip ccapi ino" output and below you can find my analysis. I'm writing it in a clarifying way so that you and other readers of this post can hopefully use it to troubleshoot other issues later.

Here your call is being setup, and apparently your outbound call leg is already selected. I know this because you already see the call ID's.

You might see other cases where the ID is showing -1. This means there's no ID assigned yet.

Continuing:

ccCallSetupRequest:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=3076
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=7387552
   cisco-desttype=0

..

Oct 19 09:12:36.975: //23053/D869713AAC46/CCAPI/ccIFCallSetupRequestPrivate:

   Interface=0x705B9E9C, Interface Type=1, Destination=, Mode=0x0,

   Call Params(Calling Number=3076

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

   Called Number=7387552

(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,

   Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE, Outgoing Dial-peer=100

, Call Count On=FALSE,

   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)

Oct 19 09:12:36.975: //23054/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:

   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)

23053 is your incoming call leg (IP Phone to CCAPI)

23054 is your outbound call leg (CCAPI to voip side - SPI)

Looking at that dial-peer, we're planning to contact host 2.2.2.2

Then we see this:

Oct 19 09:12:36.975: //23054/D869713AAC46/CCAPI/cc_incr_if_call_volume:
   Remote IP Address=10.220.0.10, Hwidb=GigabitEthernet1/0

In the show run you gave us, dial-peer 101 has 10.220.0.11 as session target, and dial-peer 100 has 2.2.2.2. I can only assume that you were testing something and that the config changed after you collected the ccapi debugs. I shall assume that 10.220.0.10 is another node in your CM5 cluster.

Then here's something you need to know:

If you see cc_api_blabla_blablabla (anything with underscores), it's the call leg talking to CCAPI.

If you see ccApiBlablaBlablabla (anything without underscores), it's CCAPI talking to the call leg.

So here we have:

Oct 19 09:12:38.615: //23054/D869713AAC46/CCAPI/cc_api_call_alert:
   Interface=0x705B9E9C, Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)

=> The voip leg (CUCM in this case - call leg 23054!!) is telling CCAPI there's alerting.

Oct 19 09:12:38.615: //23053/D869713AAC46/CCAPI/ccCallAlert:
   Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)

=> CCAPI is passing this info to the calling call leg 23053!

So far, signaling is fine, as you already know. Just proven now with traces.

Then we see this:

Oct 19 09:12:44.743: //23054/D869713AAC46/CCAPI/cc_api_call_disconnected:
   Cause Value=65, Interface=0x705B9E9C, Call Id=23054

As you can see by looking at this message: the call leg 23054 is signaling to CCAPI that the call disconnected due to reason 65 being bearer cap not implemented if I remember correctly.

Then we try again:

Oct 19 09:12:44.747: //23053/D869713AAC46/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=3076
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=7387552

Incoming call leg is still the same ofcourse, but the outgoing call leg will be changed. This time we'll also use preference 2, dial-peer 101.

Oct 19 09:12:44.747: //23053/D869713AAC46/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x705B9E9C, Interface Type=1, Destination=, Mode=0x0,
   Call Params(Calling Number=3076,(Calling Name=HQ )(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=7387552(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE, Outgoing Dial-peer=101, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
Oct 19 09:12:44.747: //23055/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)

Then skipping to the interesting parts:

Oct 19 09:12:51.415: //23055/D869713AAC46/CCAPI/cc_api_call_disconnected:
   Cause Value=65, Interface=0x705B9E9C, Call Id=23055

=> Voip leg again disconnects the call with the same cause value.

So now there isn't much more that we know other than it being a media issue.

You're using H.323 here where H.225 is the signaling part, and H.245 is the media negotiation part.

Please enable H.245 debugs on both CME's and take a look at those. See what you can find :-)

What is also information which is good to know is how you expect media to be flowing once media is setup correctly. Via CM5 using software MTP's? Via another device using hardware media resources? Or just IP phone to IP Phone? If the last one, is your network security allowing RTP across the remote sites or only between remote and HQ?

[Cedric Van Labeke]

FYI disconnect cause overview:

http://www.cisco.com/en/US/docs/ios/12_3/vvf_c/voice_troubleshooting/old/vts_appa.html#wp1007443

Standard Category	Standard Category Description	Q.850 Cause Code	Q.850 Release Cause Description

Media negotiation failure

Typical scenarios include: •No codec match occurred. •H.323 or H.245 problem leading to failure in media negotiation

65

CC_CAUSE_BEARER_CAPABILITY_ NOT_IMPLEMENTED Indicates that the equipment sending this cause does not support the bearer capability requested.

[cashqoo]

that was pretty useful for me trying to understand the debug logs.

i dont think that the problem is located in the network, as the call actually works for at least a day (self-resolve). afterwhich it fails again.

i been advised that it was most probably 1 of the call leg was not configured properly.

the debug h245 logs are attached.

[Cedric Van Labeke]

Hi Cash,

Glad you liked it! Hope it can help you in the future!

For the latest ones: can you sync your gateway clocks with an NTP server or something alike and collect a full set please?

A good way of collecting them would be like this:

#term no mon
#conf t
service timestamps debug datetime msec
service timestamps log datetime msec
service sequence-numbers
no logging console
no logging monitor
logging buffered 10000000 7
end

clear logging    => PLEASE clear buffer before the each test call.

deb voip ccapi ino

deb h225 q931

deb h225 asn1

deb h225 events

deb h245 asn1

deb h245 events

deb h245 srtp

deb cch323 h225

deb cch323 h245

deb cch323 session

Then after you make the call and simulate the issue, stop the debugging:
#undebug all
 
And collect the output in a new text file as below (include the show
ver/run in each file):
term len 0

show deb
show ver
show run
show log

If you use above template when working with TAC, they will already give you good points :-)

The reason I'm asking time sync and still ccapi and h225 is to be able to link the h245 events with the calls themselves. Right now, on calling gateway there's events around 1:19 while on called they appear around 1:15. Also on the called gateway I see fast start outgoing events which would make me think that in fact the called gw was the one making the calls.

show deb/ver/run are particularly useful as then we see which debugs exactly are in the log file with which exact IOS version, and the running config used while we took the debug (no chance for error there then!). It also makes collaboration with other teams/Development easier as one file contains all information needed (most of the time).

Also, please provide an overview of IP addresses and device associated if you can. Speeds up as it removes deducting them from logfiles and traces and it can help understanding complex and strange call flows.

Thanks!

Cedric

[Rakesh K]

Hi Cedric,,

Thanks for explaining, that was really helpful, I was just going through Mr.cashqoo attachment in that i was bit confused, could please help me out with it.

I couldn't understand why was the output showing Called Number=3076 which was suppose to be calling number and at the end it shows Called Number=7387552 which is proper.

Oct 19 09:12:38.615: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=3076, Peer Info Type=DIALPEER_INFO_SPEECH
Oct 19 09:12:38.615: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=3076
Oct 19 09:12:38.615: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Result=Success(0) after DP_MATCH_DEST
Oct 19 09:12:38.615: //-1/xxxxxxxxxxxx/DPM/dpMatchPeers:
   Result=SUCCESS(0)
   List of Matched Outgoing Dial-peer(s):
     1: Dial-peer Tag=20004
     2: Dial-peer Tag=20072
Oct 19 09:12:38.615: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Calling Number=, Called Number=7387552, Peer Info Type=DIALPEER_INFO_SPEECH
Oct 19 09:12:38.619: //-1/xxxxxxxxxxxx/DPM/dpMatchPeersCore:
   Match Rule=DP_MATCH_DEST; Called Number=7387552