Archive for the ‘H323’ Category

One of our customer reported an issue with ring back tone when calling their Contact center.

I made a test call and observed that as a caller when you call their main Contact center number all you hear is dead silence and then when agent picks up the phone you could hear them talk. There was no ring back tone and no automated messages before an agent picks up the call.

The call flow was something like this:

PSTN > ISDN30 > H323 Dial-peer > SIP Trunk > 3rd-party Contact Center Equipment

First I thought it could be the third-party equipment which was not sending back the ring back tone so I asked them to confirm this. They came back saying they are definitely sending ring back and there was no issue with their equipment.

Looking at Q931 debugs I could see ALERTING message with payload but wasn’t sure why there was no ring back.

The dial-peers were looking ok as well:

!

dial-peer voice 8500 voip
corlist outgoing CCM
description DC1CCM01
preference 1
destination-pattern 361[01].
progress_ind setup enable 3
progress_ind alert enable 8
session target ipv4:10.1.30.12
dtmf-relay h245-signal h245-alphanumeric
no vad

!

dial-peer voice 8501 voip
corlist outgoing CCM
description DC1CCM02 Cycos Ansage
preference 2
destination-pattern 361[01].
progress_ind setup enable 3
progress_ind alert enable 8
session target ipv4:10.1.30.13
dtmf-relay h245-signal h245-alphanumeric
no vad
!
I then decided to run some debugs to get a complete picture as to what is going wrong. These were the debugs I opened on the gateway:

debug voip ccapi inout
debug cch323 all
debug h225 asn1
debug h245 asn1
debug ip tcp trans
debug ccsip all

Collected debugs in the following manner:

Router(config)# service sequence
Router(config)# service timestamps debug datetime localtime msec
Router(config)# logging buffered 10000000 7
Router(config)# no logging con
Router(config)# no logging mon
Router(config)# voice iec syslog

Note: Please be very careful when you run the above debugs as these are processor intensive and make sure you are not logging monitor and console.

The debugs were massive but this is what I observed:

From Gateway traces I can see RINGBACK has definitely been sent to Gateway –

005302: *Aug 25 23:44:07.256: //-1/xxxxxxxxxxxx/H323/cch323_h225_receiver: Received msg of type ALERTIND_CHOSEN
005303: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/alert_ind: ====== PI = 0
005304: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/alert_ind: alert ind ie_bit_mask 0x1260, displayInfo
005305: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/alert_ind: delay H245 address in alert
005306: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/alert_ind: Call Manager detected
005307: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/cch323_h225_receiver: ALERTIND_CHOSEN: src address = 10.187.10.8; dest address = 10.1.30.12
005308: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/run_h225_sm: Received event H225_EV_ALERT_IND while at state H225_REQ_FS_CALLPROC
005309: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/cch323_get_embedded_obj_from_ccb: ccb=0x4715D7A0, tag=18, size=83
005310: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/cch323_get_embedded_obj_from_ccb: Extraction FAILED
005311: *Aug 25 23:44:07.256: //3610/D48C17148501/CCAPI/cc_api_set_called_ccm_detected:
CallInfo(called ccm detected=TRUE ccmVersion 3)
005312: *Aug 25 23:44:07.256: //3610/D48C17148501/CCAPI/cc_api_set_delay_xport:
CallInfo(delay xport=TRUE)
005313: *Aug 25 23:44:07.256: //3610/D48C17148501/CCAPI/cc_api_call_alert:
Interface=0x46B2BAA8, Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
005314: *Aug 25 23:44:07.256: //3610/D48C17148501/CCAPI/cc_api_call_alert:
Call Entry(Retry Count=0, Responsed=TRUE)
005315: *Aug 25 23:44:07.256: //3610/D48C17148501/H323/cch323_h225_set_new_state: Changing from H225_REQ_FS_CALLPROC state to H225_REQ_FS_ALERT state
005316: *Aug 25 23:44:07.260: //3609/D48C17148501/CCAPI/ccCallAlert:
Progress Indication=INBAND(8), Signal Indication=SIGNAL RINGBACK(1)

Then ALERTING Signal shown in ISDN Q931 debug:

005331: *Aug 25 23:44:07.264: ISDN Se0/0/0:15 Q931: TX -> ALERTING pd = 8 callref = 0x803A

But then Observed this:

005332: *Aug 25 23:44:07.264: //3610/D48C17148501/H323/h323_open_rtp_stream: Media In-active notification object not attached to ccb
005333: *Aug 25 23:44:07.264: //3610/D48C17148501/H323/cch323_set_dtmf_iw_enabled: negotiated dtmf relay: 0, dtmf_iw_enabled: 0, dtmf_sccp_enabled: 0
005334: *Aug 25 23:44:07.264: //3610/D48C17148501/H323/cch323_caps_ind: gw_id=1
005335: *Aug 25 23:44:07.264: //3610/D48C17148501/H323/cch323_peer_caps_ind_common: Load DSP with Preferred codec(16) g729r8, Bytes=20
005336: *Aug 25 23:44:07.264: //3610/D48C17148501/H323/cch323_peer_caps_ind_common: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE
005337: *Aug 25 23:44:07.396: TCP0: ACK timeout timer expired
005338: *Aug 25 23:44:07.448: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 2 Event 0x1
005339: *Aug 25 23:44:07.448: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x46DA9F30, len=53, msgPtr=0x475C62BC
005340: *Aug 25 23:44:07.448: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.225

I was a bit surprised as to why G729 codec was negotiated when the whole path is G711. Even the SIP trunk was in all-G711 region.

Looking closely at dial-peers I found what was missing!! The VOIP dial-peers were missing the “Voice class codec 1” command which had G711 as priority 1 codec. As the command was not there, the call was matching dial-peer 0 and hence negotiating G729 codec. I added the command and the problem was solved. I can now hear ring back tone as well as all automated messages.

This is how it looks after I made the changes:

005935: *Aug 26 00:15:26.432: //3620/349708E58506/H323/h323_open_rtp_stream: Media In-active notification object not attached to ccb
005936: *Aug 26 00:15:26.432: //3620/349708E58506/H323/cch323_set_dtmf_iw_enabled: negotiated dtmf relay: 0, dtmf_iw_enabled: 0, dtmf_sccp_enabled: 0
005937: *Aug 26 00:15:26.432: //3620/349708E58506/H323/cch323_caps_ind: gw_id=1
005938: *Aug 26 00:15:26.432: //3620/349708E58506/H323/cch323_peer_caps_ind_common: Load DSP with Preferred codec(5) g711ulaw, Bytes=160
005939: *Aug 26 00:15:26.432: //3620/349708E58506/H323/cch323_peer_caps_ind_common: Set DSP for dtmf-relay = CC_CAP_DTMF_RELAY_INBAND_VOICE
005940: *Aug 26 00:15:26.568: TCP0: ACK timeout timer expired
005941: *Aug 26 00:15:26.620: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 2 Event 0x1
005942: *Aug 26 00:15:26.620: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x46DAB900, len=53, msgPtr=0x475C5200
005943: *Aug 26 00:15:26.620: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.225
005944: *Aug 26 00:15:26.620: H225.0 INCOMING ENCODE BUFFER::= 28501900060008914A0005003497A50DEE3911E19D37B87571A7872310800100
005945: *Aug 26 00:15:26.620:
005946: *Aug 26 00:15:26.620: H225.0 INCOMING PDU ::=

Most of the time problems like these are Codec or MRG related so it’s always a good idea to start checking your codecs first.

There are times when you would like to forward a call coming into your gateway out to PSTN before it goes to Call manager. Reason could be WAN outage to Call managers or Call manager down situation.

This is how you can route out an incoming call out of the gateway.

Let suppose the mainline number coming into the gateway is ‘881456’. The following setup will route the call out of the gateway to PSTN.

voice translation-rule 10
rule 1 /881456/ /901139886666/
!
voice translation-profile RedirectPSTN
translate called 10
!
dial-peer voice 10 pots
description Incoming Dial Peer
translation-profile incoming RedirectPSTN
incoming called-number 881456
direct-inward-dial
port 0/0/0:15
!
dial-peer voice 20 pots
description Outbound Dial Peer
destination-pattern 9T
port 0/0/0:15
!

Call comes in and match incoming-called number dialpeer 10 and then it will match the incoming translation profile. The translation profile will translate the number to another PSTN number with prefix ‘9’. This will match dialpeer 20 and will send the call out to PSTN.

One of our customer has multiple sites across the globe including sites in UK and US.

Their initial design was to send all UK calls from US over a SIP trunk to break out from a UK gateway for LCR (least cost routing). For some reason they stopped using that trunk and configured local dial peers on US gateways for international calls. All sites were working fine as they were going through one route pattern (for international calls), one route list (Local Route Group) except one site. This site was getting an ‘unallocated/unassigned number’ when calling an international number (UK inour case). This was a bit suprising as all sites were using same settings on Route Pattern, Route List , Route Group etc.

I thought to first find out if our dialled number is hitting the gateway as it is without any change. Did a CCAPI INOUT to find out as follows: (The X mark in Calling/Called number can be any digit)
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/cc_api_supported_data: data_mode=0x10082
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructTDUsrContainer: usrContainer[0x6408896C], magic[FACE0FFF]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: container=0x6408896C, tagID=6, dataSize=16, instID=-1,modifier=2
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x65C89E68], nxtElem[0x0], magic[0xFACE0FFF] tagID[6], dataLen[16], modif[2]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x65C89E68] instID[-1] into container[0x6408896C]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: container=0x6408896C, tagID=22, dataSize=12, instID=-1,modifier=4
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x638DCC78], nxtElem[0x0], magic[0xFACE0FFF] tagID[22], dataLen[12], modif[4]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x638DCC78] instID[-1] into container[0x6408896C]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/cc_api_display_ie_subfields:

02:05:19: cc_api_call_setup_ind:

02:05:19:  cisco-username=Sharon Sidd
02:05:19: —– ccCallInfo IE subfields —–

02:05:19:  cisco-ani=585XXX50X0
02:05:19:  cisco-anitype=1
02:05:19:  cisco-aniplan=1
02:05:19:  cisco-anipi=0
02:05:19:  cisco-anisi=1

02:05:19:  dest=90114411898X1XXX    <<<< As you can see Call manager handed over the same number which was dialled

02:05:19:  cisco-desttype=0
02:05:19:  cisco-destplan=0
02:05:19:  cisco-rdn=

02:05:19:  cisco-rdntype=-1
02:05:19:  cisco-rdnplan=-1
02:05:19:  cisco-rdnpi=-1
02:05:19:  cisco-rdnsi=-1
02:05:19:  cisco-redirectreason=-1

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind: (vdbPtr=0x6428E260, callInfo={called=90114411898X1XXX,called_oct3=0x80,calling=585XXX50X0,calling_oct3=0x11,calling_oct3a=0x81,calling_xlated=false,subscriber_type_str=Unknown,fdest=1,peer_tag=50, prog_ind=0,callingIE_present 1, src_route_label=, tgt_route_label= clid_transparent=0},callID=0x6408BD24)
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind:
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind: type 0 , prot 1
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
02:05:19: ccCheckClipClir: calling number is: “585XXX50X0”, calling oct3a is: 0x81
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
02:05:19: Calling Party number is User Provided
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
02:05:19: Leaving ccCheckClipClir
calling number is: “585XXX50X0”
calling oct3 is:  0x11
calling oct3a is: 0x81

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind: (vdbPtr=0x6428E260, callInfo={called=90114411898X1XXX, calling=585XXX50X0, fdest=1 peer_tag=50}, callID=0x6408BD24)
02:05:19: //207/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: Increment call volume: 0
02:05:19: //207/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: current call volume: 1
02:05:19: //207/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: entry’s incoming TRUE.

02:05:19: //207/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: is_incoming is FALSE

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructHashProfileTab: profileTable[0x653738A0], numBuckets[11], numEntries[0]

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccTDPvtProfileTableBuildManager: Invoking necessary profileTable updaters…

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: Updating profileTable[0x653738A0] with objects in container[0x6408896C]

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[5] for the tag[6]

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x653738A0], tdObject[0x65C89E68]

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[0] for the tag[22]

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x653738A0], tdObject[0x638DCC78]

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccTDPvtProfileTableBuildManager:

02:05:19: ccTDUtilDumpAllElemInProfileTab: profileTable[0x653738A0], numBuckets[11], numEntries[2]

02:05:19: Bucket { 0 } ——>0x638DCC78[0x0,t-22,l-12,d-0x638DCC98,m-4,u-7519,g-FACE0FFF]

02:05:19:

02:05:19: Bucket { 5 } ——>0x65C89E68[0x0,t-6,l-16,d-0x65C89E88,m-2,u-7519,g-FACE0FFF]

02:05:19:

.
.
.
.
.

02:05:19: //207/xxxxxxxxxxxx/SSAPP:50:-1/ssaCallSetupInd: cid(207), st(SSA_CS_MAPPING),oldst(0), ev(24)ev->e.evCallSetupInd.nCallInfo.finalDestFlag = 1
02:05:19: //207/xxxxxxxxxxxx/SSAPP:50:-1/ssaCallSetupInd: src route label=, tgt route label= tg_label_flag 0x0
02:05:19: //207/xxxxxxxxxxxx/SSAPP:50:-1/ssaCallSetupInd: finalDest cllng(585XXX50X0), clled(90114411898X1XXX) tgt_route_label()tg_label_flag 0x0
02:05:19: //207/xxxxxxxxxxxx/SSAPP:50:-1/ssaCallSetupInd: cid(207), st(SSA_CS_CALL_SETTING),oldst(0), ev(24)dpMatchPeersMoreArg result= 0
02:05:19: //207/xxxxxxxxxxxx/SSAPP:50:-1/ssaDebugPeers: ssaSetupPeer cid(207) peer list: tag(1) called number (90114411898X1XXX) tag(104) called number (90114411898X1XXX) tag(105) called number (90114411898X1XXX)
02:05:19: //207/xxxxxxxxxxxx/SSAPP:50:-1/ssaSetupPeer: dialpeer tags in rotary= 1  104  105
02:05:19: //207/xxxxxxxxxxxx/SSAPP:50:-1/ssaSetupPeer: cid(207), destPat(90114411898X1XXX), matched(1), prefix(), peer(64A70EFC), peer->encapType (1)
02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccCallProceeding: (callID=0xCF, prog_ind=0x0)
02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccCallSetupRequest: (Inbound call = 0xCF, outbound peer =1, dest=,
params=0x64392138 mode=0, *callID=0x64392708, prog_ind = 0callingIE_present 1)
02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccCallSetupRequest:

02:05:19: ccCallSetupRequest numbering_type 0x80
02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccCallSetupRequest:
02:05:19: ccCallSetupRequest: calling number is:585XXX50X0

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccCallSetupRequest: calling oct3a is:0x81

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate: (vdbPtr=0x64852F88, dest=, callParams={called=90114411898X1XXX,called_oct3=0x80, calling=585XXX50X0,calling_oct3=0x11, calling_oct3a= 0x81, calling_xlated=false,  subscriber_type_str=Unknown, fdest=1, voice_peer_tag=1},mode=0x0, appl_call_id=, callingIE_present=1)

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
02:05:19: ccIFCallSetupRequestPrivate: src route label  tgt route label tg_label_flag 0x0

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:  vdbPtr type = 6

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate: (vdbPtr=0x64852F88, dest=, callParams={called=90114411898X1XXX, called_oct3 0x80,  calling=585XXX50X0,calling_oct3 0x11, calling_oct3a 0x81, calling_xlated=false,  fdest=1, voice_peer_tag=1}, mode=0x0, xltrc=-5)
02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
02:05:19: //208/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: not incoming entry
02:05:19: //208/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: entry’s incoming FALSE.
02:05:19: //208/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: is_incoming is FALSE
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/cc_set_voice_port_value:
02:05:19: CC_IF_TELEPHONY: echo =0, playout = 0

02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccSaveDialpeerTag: (callID=0xCF, dialpeer_tag=1)
02:05:19: //208/xxxxxxxxxxxx/CCAPI/ccCallSetContext: (callID=0xD0, context=0x638F184C)
02:05:19: //207/xxxxxxxxxxxx/CCAPI/ccCallReportDigits: (callID=0xCF, enable=0x0)
02:05:19: //-1/xxxxxxxxxxxx/CCA

VG-FRNA-MON-3725#PI/ccTDConstructTDUsrContainer: usrContainer[0x64082410], magic[FACE0FFF]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: container=0x64082410, tagID=19, dataSize=4, instID=0,modifier=1
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x638FB624], nxtElem[0x0], magic[0xFACE0FFF] tagID[19], dataLen[4], modif[1]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x638FB624] instID[0] into container[0x64082410]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructMultiInstHolderObject: multiHolder[0x653B1B44], nxtElem[0x0], magic[0xFACE0FFF], tagID[19], dataLen[0], modif[-1], numInst[0]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtPushInstToMultiInstHolder: Successful in pushing instance object[0x638FB624] into holder[0x653B1B44]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructHashProfileTab: profileTable[0x6566213C], numBuckets[11], numEntries[0]
02:05:19: //208/xxxxxxxxxxxx/CCAPI/ccTDPvtProfileTableBuildManager: Invoking necessary profileTable updaters…
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: Updating profileTable[0x6566213C] with objects in container[0x64082410]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[6] for the tag[19]
02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x6566213C], tdObject[0x653B1B44]
02:05:19: //208/xxxxxxxxxxxx/CCAPI/ccTDPvtProfileTableBuildManager:
02:05:19: ccTDUtilDumpAllElemInProfileTab: profileTable[0x6566213C], numBuckets[11], numEntries[1]
02:05:19: Bucket { 6 } ——>0x653B1B44[0x0,t-19,m-1,g-FACE0FFF 0x638FB624,i-0<t-19,l-4,d-0x638FB644,m-1,u-7519,g-FACE0FFF> ]
02:05:19:

02:05:19: //-1/xxxxxxxxxxxx/CCAPI/ccTDDestructTDUsrContainer: Container[0x64082410]

02:05:19: ISDN Se2/0:23 Q931: TX -> SETUP pd = 8  callref = 0x00B0

Bearer Capability i = 0x8090A2
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA98397
Exclusive, Channel 23
Calling Party Number i = 0x1181, ‘585XXX50X0’
Plan:ISDN, Type:International
Called Party Number i = 0x80, ‘4411898X1XXX’    <<< Number got changed at the gateway
Plan:Unknown, Type:Unknown
Cause i = 0x8281 – Unallocated/unassigned number   <<< The error is coming from provider side

 

It appears though that call manager is sending the correct number ‘901144….’ but for some reason the Q931 debugs were showing number going out as ’44……’ without the prefix ‘011’. I checked the dialpeers and there was no stripping or forward-digits restriction on it. To remove any doubt concerning dial peers, I  created an explicit 9011 dial peer with prefix 011 and assign it preference 1. Even that didn’t work and my call was going out without 011 and failing.

Looking closely at Q931 debugs I found something interesting:

Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA98397
Exclusive, Channel 23
Calling Party Number i = 0x1181, ‘585XXX50X0’
Plan:ISDN, Type:International
Called Party Number i = 0x80, ‘4411898X1XXX’
Plan:Unknown, Type:Unknown
Cause i = 0x8281 – Unallocated/unassigned number

The outgoing called number had plan and type ‘Unknown’. Though the same settings were working fine for other sites I thought to explicitly assign proper type and plan and see if that makes any difference.

I created a seperate translation rule and Voice translation profile and included it in POTS dial peer.

!
voice translation-rule 5
rule 1 // // type any international plan any isdn
!

voice translation-profile PRI-INTL
translate calling 3
translate called 5
!

!
dial-peer voice 9011 pots
translation-profile outgoing PRI-INTL
preference 1
destination-pattern 9011T
progress_ind alert enable 8
progress_ind progress enable 8
progress_ind connect enable 8
port 2/0:23
prefix 011
!

Now when I dialled the number, it worked like a charm:

19:21:26: ISDN Se2/0:23 Q931: TX -> SETUP pd = 8  callref = 0x0147
Bearer Capability i = 0x8090A2
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA98397
Exclusive, Channel 23
Calling Party Number i = 0x1181, ‘585XXX50X0’
Plan:ISDN, Type:International
Called Party Number i = 0x91, ‘4411898X1XXX’
     Plan:ISDN, Type:International

19:21:26: ISDN Se2/0:23 Q931: RX <- CALL_PROC pd = 8  callref = 0x8147
Channel ID i = 0xA98397
Exclusive, Channel 23
19:21:28: ISDN Se2/0:23 Q931: RX <- ALERTING pd = 8  callref = 0x8147
Progress Ind i = 0x8488 – In-band info or appropriate now available
19:21:33: ISDN Se2/0:23 Q931: TX -> DISCONNECT pd = 8  callref = 0x0147
Cause i = 0x8090 – Normal call clearing
19:21:33: ISDN Se2/0:23 Q931: RX <- RELEASE pd = 8  callref = 0x8147
19:21:33: ISDN Se2/0:23 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x0147

Provider was expecting proper type and plan and even though the call was still going without prefix ‘011’ but it was working.

I had an interesting case where SIP calls over a SIP trunk were dropping after like 75 minutes. The duration was not confirmed as sometimes it use to drop even before 75 minutes.

I looked into few CCSIP debugs (debug ccsip messages) and found that the ‘BYE’ message was actually coming from our end (Call manager/Gateway).

Platform information:

CCM: System version: 7.1.3.32900-4

CUBE-10#sh ver

Cisco IOS Software, 3800 Software (C3825-ADVIPSERVICESK9-M), Version 12.4(24)T4, RELEASE SOFTWARE (fc2)

Technical Support: http://www.cisco.com/techsupport
Copyright (c) 1986-2010 by Cisco Systems, Inc.
Compiled Fri 03-Sep-10 09:15 by prod_rel_team

ROM: System Bootstrap, Version 12.4(13r)T, RELEASE SOFTWARE (fc1)

CUBE-10 uptime is 27 weeks, 3 days, 44 minutes

voice-card 0
!
!
voice call send-alert
voice rtp send-recv
!
voice service voip
allow-connections sip to sip
fax protocol cisco
sip
options-ping 180
!
!
voice class codec 1
codec preference 1 g729r8
codec preference 2 g711alaw

!

voice class sip-profiles 1
request INVITE sip-header Allow-Header modify “, UPDATE” “”

!

dial-peer voice 10 voip
description *** Outbound to GXXX – SIP Provider ***
translation-profile outgoing OUTBOUND
huntstop
destination-pattern 9T
voice-class codec 1
voice-class sip early-offer forced
voice-class sip profiles 1
session protocol sipv2
session target ipv4:10.0.222.69
dtmf-relay rtp-nte
fax-relay sg3-to-g3
no vad

!
!

gateway
timer receive-rtp 1200

!
sip-ua
retry invite 1
retry response 2
retry bye 2
retry cancel 1
retry options 1
timers trying 200
!

!

!

Debug Output:

Jul 11 12:17:54.579 BST: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Sent:

BYE sip:079XXXXXXX@10.0.222.69:5060 SIP/2.0

Via: SIP/2.0/UDP 10.0.222.65:5060;branch=z9hG4bK100B17D
From: “anonymous” <sip:anonymous@10.0.222.65>;tag=B891B2E8-282
To: <sip:079XXXXXXX@10.0.222.69>;tag=3519367399-656588
Date: Mon, 11 Jul 2011 11:15:27 GMT
Call-ID: D687F817-AADB11E0-A725957A-CA524E0B@10.0.222.65
User-Agent: Cisco-SIPGateway/IOS-12.x
Max-Forwards: 70
Timestamp: 1310383074
CSeq: 128 BYE
Reason: Q.850;cause=16
Content-Length: 0

Jul 11 12:17:54.591 BST: //-1/xxxxxxxxxxxx/SIP/Msg/ccsipDisplayMsg:

Received:
SIP/2.0 200 OK

Via: SIP/2.0/UDP 10.0.222.65:5060;branch=z9hG4bK100B17D
To: <sip:079XXXXXXX@10.0.222.69>;tag=3519367399-656588
From: “anonymous” <sip:anonymous@10.0.222.65>;tag=B891B2E8-282
Call-ID: D687F817-AADB11E0-A725957A-CA524E0B@10.0.222.65
CSeq: 128 BYE

Allow: INVITE, BYE, OPTIONS, CANCEL, ACK, REGISTER, NOTIFY, INFO, REFER, SUBSCRIBE, PRACK, UPDATE, MESSAGE, PUBLISH

Contact: <sip:079XXXXXXX@10.0.222.69:5060>

Content-Leng

= = = =

This is what I have done to fix the problem:

I added these commands under sip-profile:

voice class sip-profiles 1
request INVITE sip-header Allow-Header modify “UPDATE,” “”      < < <  This was already there
request REINVITE sip-header Allow-Header modify ” UPDATE,” “”
response 200 sip-header Allow-Header modify “UPDATE,” “”
response 180 sip-header Allow-Header modify “UPDATE,” “”

The next step was to increase the Service Parameter “SIP Session Expire Timer” which you can find under Service Parameters > Call manager:

That was it, it fixed the issue and customer confirmed having a call for more than 3 hours.

I had an interesting case last week where calls over ICT trunk would connect but then either party will not hear each other for 8-10 seconds.

The issue was first reported from US users trying to reach UK users over an Inter-cluster trunk (Non-GK). Both clusters had two call managers version 8.0.3. The whole issue started after US call managers were re-located and their IP addresses were changed. The ping response between two clusters was about 145ms which wasn’t too bad. I did a test call to a UK phone by connecting my IP communicator to US (due to time difference it was very difficult to get someone in US to make test calls). I did a CFA on UK phone to Voicemail and could see on my communicator that the call has connected but I didn’t hear the first 10 seconds of the voicemail.

I made a similar test by calling a UK phone but this time asked someone to answer it. The call was connected fine but we couldn’t hear each other for like 10 seconds. After 10 s it was all ok.

The issue was bit different when someone from UK to US would call. In that case call will connect 70% of the time with no issues but 30% of the time it will connect and drop.

I had to run through different CCM traces on both clusters to find below:

### Digit analysis for the call
04:42:47.464 |Digit analysis: match(pi=”2″, fqcn=”XXXXXX1409″, cn=”1409″,plv=”5″, pss=”PT_FRNA_INTERNAL:PT_FRNA_ROUTE”, TodFilteredPss=”PT_FRNA_INTERNAL:PT_FRNA_ROUTE”, dd=”303165″,dac=”0″)|2,100,49,1.20123926^10.128.68.1^SEP002318D1DF43
04:42:47.464 |Digit analysis: analysis results|2,100,49,1.20123926^10.128.68.1^SEP002318D1DF43
04:42:47.464 ||PretransformCallingPartyNumber=1409
|CallingPartyNumber=201409
|DialingPartition=PT_FRNA_INTERNAL
|DialingPattern=21XXXX
|FullyQualifiedCalledPartyNumber=303165

04:42:47.464 |DeviceManager::star_DmPidReq – RequestedName=dec100fa-40c7-ac1a-9dcb-50a73af41700 LookupName=dec100fa-40c7-ac1a-9dcb-50a73af41700|2,100,49,1.20123926^10.128.68.1^SEP002318D1DF43
04:42:47.464 |Digit analysis: wait_DmPidRes- Partition=[8a2bfaaa-13f0-4631-9c26-02a08a573cf7] Pattern=[21XXXX] Where=[],cmDeviceType=[AccessDevice], OutsideDialtone =[0], DeviceOverride=[0], PID=RouteListControl(2,100,73,10)|2,100,49,1.20123926^10.128.68.1^SEP002318D1DF43

### H225 set-up sent via ICT:
04:42:47.616 |Out Message — H225SetupMsg — Protocol= H225Protocol|*^*^*
04:42:47.616 |Ie – H225BearerCapabilityIe IEData= 04 03 80 90 A2 |*^*^*
04:42:47.616 |Ie – Q931DisplayIe IEData= 28 0B 43 68 61 64 20 48 61 69 6E 65 73 |*^*^*
04:42:47.616 |Ie – H225CallingPartyIe IEData= 6C 08 00 81 32 30 31 34 30 39 |*^*^*
04:42:47.616 |Ie – Q931CalledPartyIe IEData= 70 05 80 33 30 36 33 |*^*^*

### Connect received (call answered)
04:42:49.461 |In  Message — H225ConnectMsg — Protocol= H225Protocol|*^*^*
04:42:49.461 |Ie – H225BearerCapabilityIe — IEData= 04 03 80 90 A2 |*^*^*
04:42:49.461 |Ie – Q931DisplayIe — IEData= 28 0C 53 74 65 76 65 20 47 61 72 6E 65 72 |*^*^*
04:42:49.461 |Ie – Q931ConnectedNumIe — IEData= 4C 06 00 81 33 30 36 33 |*^*^*

### outgoing TCS sent after about 8 seconds:
04:42:57.260 |TranslateAndTransport(21728)::waitForSdlRsp_H245TcpConnectionInfo – received H245TcpConnectionInfo from H245Handler|0,0,0,0.0^*^*
04:42:57.264 |
H245ASN – TtPid=(21728) -Outgoing #195026  -value MultimediaSystemControlMessage ::= request : terminalCapabilitySet :

¬Also, the SDL logs indicate a significant delay in the TCS being sent out:
Line 135: 027643128| 2011/07/06 04:42:49.465| 002| SdlSig    | H245ConnectReq                        | wait                          | H245Handler(2,100,24,1)         | TranslateAndTransport(2,100,16,21728)| (2,100,23,21728).1-(*:*)                | [NP – PQ: 0]
Line 331: 027643324| 2011/07/06 04:42:57.259| 002| SdlSig    | H245TcpConnectionInfo                 | waitForSdlRsp                 | TranslateAndTransport(2,100,16,21728)| H245Handler(2,100,24,1)         | (0,0,0,0).0-(*:*)                       | [R:NP – HP: 0, NP: 0, LP: 0, VLP: 0, LZP: 0 DBP: 0]
Line 332: 027643325| 2011/07/06 04:42:57.259| 002| SdlSig    | TtControlChannelEstablished           | waitForTransportEstablishment | H245SessionManager(2,100,23,21728)| TranslateAndTransport(2,100,16,21728)| (0,0,0,0).0-(*:*)                       | [R:NP – HP: 0, NP: 0, LP: 0, VLP: 0, LZP: 0 DBP: 0]
Lin

This shows the H225 part of H323 is fine but H245 was taking time. I did reset of trunks, changed Call manager priorities etc but that didn’t help.

I then enabled ‘Outbound FastStart’ for all outbound calls from US to UK and enabled the same for inbound calls on UK trunk. This fixed the issue.

I had to provide a MTP resource under MRGL at US trunk as FastStart needs MTP.

US Cluster:

UK Cluster:

A little about how ‘Outbound FastStart’ works from Cisco:

Outbound Calls :

Enable Outbound FastStart   

Check this check box to enable the H.323 FastStart feature on outgoing calls.
By default, the check box remains unchecked for the H.323 gateway or trunk.
When you check the Enable Outbound FastStart check box, you must set the Media Termination Point Required, Media Resource Group Lists, and Codec for Outbound FastStart.

Inbound Calls:

Enable Outbound FastStart   

Check this check box to enable the H.323 FastStart call connections on incoming calls.
By default, the check box remains unchecked for the H.323 gateway.
For intercluster calls, you must check the Enable Inbound FastStart check box on Cisco CallManager servers in other clusters for the outbound FastStart feature to work.
If you updated Cisco CallManager 3.3(2) servers in other clusters with support patch B, do not enable inbound FastStart because 3.3(2)spB does not support the inbound FastStart feature over intercluster trunks

QoS is very important for Voice traffic which is delay sensitive. I won’t go into details of QoS over here and will just explain the configuration we normally use on a Voice gateway for QoS.

class-map match-any Voice-RTP
match ip precedence 5
match ip dscp ef
match ip rtp 16384 16383
class-map match-any Voice-Cntl
match ip precedence 3
match ip dscp af31
match access-group name voice-signal
!
ip access-list extended voice-signal
permit tcp any any range 2000 2002
permit udp any any eq 2427
permit tcp any any eq 2428
permit tcp any any eq 1720
permit tcp any any range 11000 11999
!
!
policy-map QoS-LAN-Policy
class Voice-RTP
set dscp ef
priority 500
class Voice-Cntl
set dscp af31
bandwidth 30
class class-default
fair-queue
!

Apply it on Voice VLAN interface or towards the WAN interface if you are configuring it between sites:

!
interface FastEthernet0/1
ip address 10.0.1.1 255.255.255.0
ip rip advertise 2
ip virtual-reassembly
ip tcp adjust-mss 1360
duplex full
speed 100
service-policy output QoS-LAN-Policy
!

OR

!
interface GigabitEthernet0/0.105
description *** Voice VLAN ***
encapsulation dot1Q 105
ip address 10.60.x.x 255.255.255.0
h323-gateway voip bind srcaddr 10.60.x.x
service-policy output QoS-LAN-Policy

====

Confirmation that the voice packets are hitting the service policy:

GW#sh policy-map int fa0/1
FastEthernet0/1

Service-policy output: QoS-LAN-Policy

Class-map: Voice-RTP (match-any)
55890 packets, 11178000 bytes
5 minute offered rate 0 bps, drop rate 0 bps
Match: ip precedence 5
55890 packets, 11178000 bytes
5 minute rate 0 bps
Match: ip dscp ef (46)
0 packets, 0 bytes
5 minute rate 0 bps
Match: ip rtp 16384 16383
0 packets, 0 bytes
5 minute rate 0 bps
QoS Set
dscp ef
Packets marked 55890
Queueing
Strict Priority
Output Queue: Conversation 264
Bandwidth 500 (kbps) Burst 12500 (Bytes)
(pkts matched/bytes matched) 55890/11960460
(total drops/bytes drops) 0/0

Class-map: Voice-Cntl (match-any)
605 packets, 80661 bytes
5 minute offered rate 0 bps, drop rate 0 bps
Match: ip precedence 3
605 packets, 80661 bytes
5 minute rate 0 bps
Match: ip dscp af31 (26)
0 packets, 0 bytes
5 minute rate 0 bps
Match: access-group name voice-signal
0 packets, 0 bytes
5 minute rate 0 bps
QoS Set
dscp af31
Packets marked 605
Queueing
Output Queue: Conversation 265
Bandwidth 30 (kbps)Max Threshold 64 (packets)
(pkts matched/bytes matched) 605/76019
(depth/total drops/no-buffer drops) 0/0/0

Class-map: class-default (match-any)
1103573 packets, 80456575 bytes
5 minute offered rate 151000 bps, drop rate 0 bps
Match: any
Queueing
Flow Based Fair Queueing
Maximum Number of Hashed Queues 256
(total queued/total drops/no-buffer drops) 0/0/0

I came across this issue with one of  our customer last week where a call was coming in to receptionist at Site ‘A’ but she was not able to transfer the call to someone at Site ‘B’. They had Centralized deployment and all phones on branch sites were registered to Central site. The call was dropping as soon as she would press ‘hold’ to transfer the call. This is what I was getting on Site ‘A’ gateway:

2621-VG01#
.Feb  7 09:25:14.805: ISDN Se1/0:15 Q931: RX <- SETUP pd = 8  callref = 0x0002
Sending Complete
Bearer Capability i = 0x8090A3
Standard = CCITT
Transer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA98382
Exclusive, Channel 2
Called Party Number i = 0x81, ‘700481’
Plan:ISDN, Type:Unknown
.Feb  7 09:25:14.837: ISDN Se1/0:15 Q931: TX -> CALL_PROC pd = 8  callref = 0x8002
Channel ID i = 0xA98382
Exclusive, Channel 2
.Feb  7 09:25:14.961: ISDN Se1/0:15 Q931: TX -> ALERTING pd = 8  callref = 0x8002
Progress Ind i = 0x8188 – In-band info or appropriate now available
.Feb  7 09:25:22.877: ISDN Se1/0:15 Q931: TX -> CONNECT pd = 8  callref = 0x8002
.Feb  7 09:25:22.945: ISDN Se1/0:15 Q931: RX <- CONNECT_ACK pd = 8  callref = 0x0002

.Feb  7 09:25:41.934: ISDN Se1/0:15 Q931: TX -> DISCONNECT pd = 8  callref = 0x8002
Cause i = 0x80FF – Interworking error; unspecified
.Feb  7 09:25:42.118: ISDN Se1/0:15 Q931: RX <- RELEASE pd = 8  callref = 0x0002
.Feb  7 09:25:42.122: ISDN Se1/0:15 Q931: TX -> RELEASE_COMP pd = 8  callref = 0x8002

Now this error had no explanation whatsoever and it was quite hard to troubleshoot.

I knew that for a transfer function to work properly across WAN (G729-G729) you need a MTP. The MRGL had a group with MTP as well as transcoder. I noticed MTP was added as part of one group where announciator, CFB etc were added with it as well. Transcoder was added seperately. I think I read somewhere that Call manager sometimes take Transcoder as MTP if MTP is not added in a seperate group. As transcoder can’t do G729-G729, it will fail to provide supplemantary services to the gateway and eventually the call will drop. As a good design approach, always place MTP in a seperate group and at the top of MRGL.

I removed MTP from that group, placed it in a seperate group and prioritized it at MRGL.

Made test calls and they all worked fine.

Came across a complex situation where customer was using this SIP trunk as an alternative to ISDN-30 (if all channels are used or if ISDN goes down). The ISDN-30 link was working fine but they had issues on SIP trunk (how many times I have heard this?) …. their outbound calls over SIP were using a prefix ‘8’ to route calls on SIP trunk to SIP Provider. The Outbound calls were working fine. The inbound calls drop after 8 secs and none of the calling/called party could hear each other. Complete silence..

Call flow was something like this:

PSTN (81763)  —– > 2311111  >>>> Hit Gateway >>> Translates to 2905 >>> dialpeer to reach CUCM >> Picks up the phone x2905 >>> Both Calling and Called party hear silence >>> Call drops in 8 secs

Some information off the gateway was something like this:

voice service voip
allow-connections h323 to sip
allow-connections sip to h323
allow-connections sip to sip
supplementary-service h450.12
fax protocol t38 ls-redundancy 2 hs-redundancy 2 fallback none
h323
emptycapability
h225 id-passthru
h225 connect-passthru
session transport udp
h245 passthru tcsnonstd-passthru
sip
bind control source-interface FastEthernet0/1
bind media source-interface FastEthernet0/1

!

voice class codec 1
codec preference 1 g711alaw
codec preference 2 g711ulaw
codec preference 3 g729r8
!
!
!

interface FastEthernet0/0
ip address 192.168.212.4 255.255.255.240
ip access-group H323-Security-In in
duplex auto
speed auto
h323-gateway voip bind srcaddr 192.168.212.4
service-policy output QoS-LAN-Policy
!
interface FastEthernet0/1
ip address 94.x.x.194 255.255.255.248
ip access-group SIP-Security-In in
ip access-group SIP-Security-Out out
duplex auto
speed auto
auto qos voip trust
no cdp enable
service-policy output AutoQoS-Policy-Trust

!

dial-peer voice 50 voip
description **Incoming Call from SIP Trunk to CUCM**
translation-profile incoming SIP-CALLS-IN
preference 1
redirect ip2ip
voice-class codec 1
voice-class sip dtmf-relay force rtp-nte
session protocol sipv2
session target ipv4:146.x.x.200
incoming called-number .%
dtmf-relay rtp-nte
no vad
!

dial-peer voice 60 voip
description **Outgoing Call to SIP Trunk**
translation-profile outgoing SIP-CALLS-OUT
huntstop
preference 5
destination-pattern 8.T
voice-class codec 1
voice-class sip dtmf-relay force rtp-nte
session protocol sipv2
session target ipv4:146.x.x.200
dtmf-relay rtp-nte
no vad
!
dial-peer voice 31 voip
description *** Outbound calls from CUCM system ***
huntstop
redirect ip2ip
voice-class codec 1
incoming called-number 8T
no vad
!

I ran some traces but the issue was not clear as I was getting cause code = 16 normal call clearing. I followed the following steps to resolve the issue:

Step#1:

At Call manager their MTP and Transcoder were in same group which is not a good design approach. MTP and Transcoder should always be in different MRGs so that Call manager doesn’t use a Transcoder where an MTP is required as a Transcoder cannot do g729-g729. I made these changes:

MRG-GW-MTP >> This contains SW MTP at Gateway only
MRG-CUCM-MTP >> This contains CUCM SW MTP
MRG-Gateway >> GW-CON & GW-Xcode (both hardware)
MRG-HQ >> ANN_2, CFB_2, MOH_2

At Gateway:
MRGL-GW  >> MRG-GW-MTP , MRG-CUCM-MTP ,  MRG-Gateway, MRG-HQ

HQ:

MRGL-HQ >> MRG-GW-MTP , MRG-CUCM-MTP, MRG-HQ

Step#2:

Removed the SIP bind commands. I tried pinging fa0/1 to CUCM which failed so I removed the binding and left it on IOS to pick closest LAN interface to CUCM and WAN interface for going outside

Step#3:

Under voice services voip – – added allow-connections h323 to h323 and removed redirect ip2ip. We should not need this command will redirect SIP phone calls to SIP phone calls.

Step#4:

Ran the following debugs:

debug voip ccapi inout
debug cch323 all
debug h225 asn1
debug h245 asn1
debug ip tcp trans
debug ccsip all

Collected debugs in the following manner:

Router(config)# service sequence
Router(config)# service timestamps debug datetime localtime msec
Router(config)# logging buffered 10000000 7
Router(config)# no logging con
Router(config)# no logging mon
Router(config)# voice iec syslog

Router(config)#service timestamps log datetime localtime msec

Router# term len 0
<Enable session capture to txt file in terminal program.>
Router# sh logg

Step#5:

The debugs were huge but I could see
045897: *Sep  3 20:46:57.975: TCP0: ACK timeout timer expired
045898: *Sep  3 20:47:05.679: //-1/xxxxxxxxxxxx/H323/cch323_process_carrier_update: Registered = 0, Event = 1, Reason = 2
045899: *Sep  3 20:47:05.907: //-1/xxxxxxxxxxxx/H323/cch323_ct_main: SOCK 3 Event 0x1
045900: *Sep  3 20:47:05.907: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: owner_data=0x4AE82D10, len=2, msgPtr=0x4A8F8D78
045901: *Sep  3 20:47:05.907: //-1/xxxxxxxxxxxx/H323/cch323_gw_process_read_socket: Received msg for H.245
045902: *Sep  3 20:47:05.907: h245_decode_one_pdu: more_pdus = 0, bytesLeftToDecode = 2
045903: *Sep  3 20:47:05.907: H245 MSC INCOMING ENCODE BUFFER::= 4A40
045904: *Sep  3 20:47:05.911:
045905: *Sep  3 20:47:05.911: H245 MSC INCOMING PDU ::

value MultimediaSystemControlMessage ::= command : endSessionCommand : disconnect : NULL

Observed no capability exchange when the call connects,  the endSession is being sent by the far h323 side because h245 negotiation isn’t occurring.

Further down the lines found  this:

163432: *Sep  5 17:36:35.240: //-1/xxxxxxxxxxxx/H323/cch323_h225_receiver: Received msg of type RELEASEIND_CHOSEN
163433: *Sep  5 17:36:35.240: //9761/F1DB1EE38000/H323/release_ind: Disconnect cause 16 location code 0
163434: *Sep  5 17:36:35.240: //-1/xxxxxxxxxxxx/H323/h323_set_release_source_for_peer: ownCallId[9761], src[4]
163435: *Sep  5 17:36:35.240: //9761/F1DB1EE38000/H323/cch323_h225_receiver: RELEASEIND_CHOSEN: src address = 192.168.212.4; dest address = 192.168.212.1
163436: *Sep  5 17:36:35.240: //9761/F1DB1EE38000/H323/run_h225_sm: Received event H225_EV_RELEASE_IND while at state H225_WAIT_FOR_H245

Noticed SIP provider is doing early-offer (note the SDP in the INVITE).  When this happens, CUBE needs to do fast-start on the outbound h323 leg to CM.  CM is not negotiating FS here.  I Checked the ‘Enable Inbound Fast Start’ box on CM under the CUBE’s H323 gateway config.

Also, observed that capabilities aren’t exchanged when the H245 TCP channel is opened up. Unchecked ‘Wait for far end h.245 capability exchange’ at the gateway config under CUCM. Reset the gateway.

This fixed the issue.

The Cisco High-Density Packet Voice Digital Signal Processor (DSP) Module (PVDM2) enables Cisco Integrated Services Routers to provide high-density voice connectivity, conferencing, and transcoding capabilities in Cisco IP Communications solutions. PVDM stands for packet voice DSP module; it is the Cisco product name for the module that provides digital signal processing resources to a system. DSP stands for Digital Signal Processor; it is a generic Industry terminology. A PVDM module could be staffed with one or multiple DSPs.

PVDM2-8 = 8ch (G), 4ch (H), 4ch (M)

PVDM2-16 = 16ch (G), 6ch (H), 8ch (M)

PVDM2-32 = 32ch (G), 12ch (H), 16ch (M)

PVDM2-48 = 48ch (G), 18ch (H), 24ch (M)

PVDM2-64 = 64ch (G), 24ch (H), 32ch (M)

G=g711     H=G723.1,G728, G729, Gt29b, iLBC      M= G711, G729a, G729ab, G726, G722, Fax Relay

PVDM2-16 is one DSP chip (32=2, 48=3, 64=4)
PVDM2-8 is one DSP chip but less processing capacity than the DSP on the 16.
PVDM2-8 contains one TNETV2505GGW DSP; other PVDM2 modules contain 1 to 4 TNETV2510GGW DSPs (referred to C5510 in command outputs)

Codec Complexity and Flex Mode:

You can configure each DSP separately as either medium complexity, high complexity, or flex mode (C5510 only).Configure with voice-card x.  Then codec complexity (flex | high | medium). The DSP treats all calls according to its configured complexity, regardless of the actual complexity of the codec of the call. A resource with configured complexity equal or higher than the actual complexity of the incoming call must be available, or the call will fail.

3725 with NM-HDV in slot 0
!
Gateway#conf t
Gateway(config)#voice-card 0
Gateway(config-voicecard)#codec complexity ?
high    Set codec complexity high. High complexity, lower call density.
medium  Set codec complexity medium. Mid range complexity and call  density.
<cr>
Gateway(config-voicecard)#end

2811 with PVDM2-16 installed on main board.
!
GW_2811#config terminal
Enter configuration commands, one per line. End with CNTL/Z.
GW_2811(config)#voice-card 0
GW_2811(config-voicecard)#codec complexity ?
flex    Set codec complexity Flex. Flex complexity, higher call density.
high    Set codec complexity high. High complexity, lower call density.
medium  Set codec complexity medium. Mid range complexity and call density.

GW_2811(config-voicecard)#end
GW_2811#

For example, if a call requires a high-complexity codec but the DSP resource is configured for medium complexity mode, the call will fail. However, if a medium-complexity call is attempted on a DSP configured for high complexity mode, then the call will succeed and Cisco IOS will allocate a high-complexity mode resource.

Voice cards that do not have C5510 DSPs can be configured only for medium or high complexity. Voice cards that are equipped with C5510 DSPs have an additional complexity option called flex complexity. Setting the codec complexity to medium or high sets the number of voice terminations per DSP to a static number. Flex mode has an advantage when calls of multiple codecs must be supported on the same hardware because flex mode can support more calls than when the DSPs are configured as medium or high complexity. However, flex mode does allow oversubscription of the resources, which introduces the risk of call failure if all resources are used. With flex mode it is possible to have fewer DSP resources than with physical TDM interfaces.

DSP Sharing & Farming:

DSP sharing and DSP farming has been used interchangeably. Cisco IOS dspfarm command is used for both DSP sharing and DSP farming. The DSP farming term was originally used to describe using DSPs as media resources for CallManager. DSP sharing allows C5510 DSPs to terminate a voice call from a voice port that is located in another hardware slot. This can reduce the possibility of oversubscription when using flex complexity. It can also make it easier to add DSPs to an existing gateway. It is physically much easier to add PVDM2s to an NM-HDV2 than it is to add them to the main board of an ISR.

  • A local DSP is on the same voice card as the voice port.
  • A remote DSP is on a different voice card than the voice port.
  • The DSPs on the main board of an ISR are local to the High-Performance WAN Interface Card (HWIC) and Extension Voice Module (EVM) slots and are remote to the NM slots.
  • DSP sharing supports only voice termination not transcoding.
  • DSP sharing is supported on T1/E1 interfaces only.
  • DSP sharing is supported on PVDM2s that are installed on the main board of 2800 and 3800 ISRs.
  • DSP sharing is supported on NM-HDV2s that are installed in a 2800, 3700, or 3800 router.
  • All voice cards that share DSPs must have synchronized clocks.

You should configure all voice cards that share DSPs for the same complexity.
GW_2811(config)#voice-card 0
GW_2811(config-voicecard)#dspfarm
GW_2811(config-voicecard)#end

Please refer to configuration for IOS Transcoding and Hardware Conferencing.

Transcoding & MTP Resources:

Transcoding can be configured on following devices:

  • WS-X6608-T1/E1
  • WS-SVC-CMM-ACT
  • PVDM installed in NM-HDV
  • PVDM2s installed in NM-HDV2
  • PVDM2s installed in ISRs
  • NM-HD-1V/2V/2VE (C5510)
  • 1751/1760

Maximum number of transcoding sessions per device:

Device {Max Sessions}

WS-6608-T1/E1 {24 per port, 192 per module}
WS-SVC-CMM-ACT {64}
C549 {4}
C549 in 1751/1760  {2}
C5510 medium complexity {8}
C5510 high complexity {6}
c5510 flex complexity {16*}

* It is only possible to support 16 transcoding sessions when you are transcoding between two low- complexity codecs. Because this situation is rare, the practical maximum number of transcoding sessions per DSP is 8.

Note: Software-based MTPs can support two voice streams with the same packetization rates. If the voice streams use different packetization rates, a DSP is required. The number of software-based MTP sessions is CPU bound and varies per router platform. You can configure only the C5510 DSP to provide hardware-based MTP services. Each DSP can support 16 MTP sessions. If a call requires MTP services and no MTP is configured, a transcoder is used if available.

Conferencing:

You need to consider only one factor when calculating conference bridge DSP requirements: the number of conferences required.For example, the C5510 supports two mixed-mode conferences with up to eight participants each. Therefore, it is technically accurate to say that the C5510 supports 16 conference participants. But this does not mean we can have 4 conferences of 4 participants each. Number of DSPs required depends on number of Conferences. Particpants per conference are irrelevant.

Device {Max Conference – Max participant}

C549                               {1 – 6}
C5510 (G.711 only)           {8 – 8}
C5510 (G.729a/G.729)     {2 – 8}

E1 Card & PVDM:

How many DSPs/PVDM are required as per E1?

As a rule of thumb always consider One PVDM2-64 for 2 E1s. Each E1 takes up 30 channels (2×30 = 60 > 64). If you are using 1 x E1 then you may use one PVDM2-32.

A PVDM-12 or PVDM2 (32 or higher) can provide voice termination, transcoding, and conferencing simultaneously. The restriction on conferencing is per DSP, not per PVDM. The gateway does track the number of voice ports that are allocated to prevent oversubscription of DSPs. Even though the DSPs are not assigned to a specific voice port, the number of DSPs available for other purposes has been reduced.

You can also use Cisco DSP Calculator to find out DSP resources needed as per requirement.

Useful Commands:

sh voice dsp voice

show voice dsp group all

show dspfarm all

Show dspfarm dsp active

Gateway Outputs:

This is from a gateway which is using on-board PVDM-12 chips.

Show diag#

Slot 2:
High Density Voice Port adapter
Port adapter is analyzed
Port adapter insertion time unknown
EEPROM contents at hardware discovery:
Hardware Revision        : 1.1
Top Assy. Part Number    : 800-03567-01
Board Revision           : E0
Deviation Number         : 0-0
Fab Version              : 02
PCB Serial Number        : JAB04390KNG
RMA Test History         : 00
RMA Number               : 0-0-0-0
RMA History              : 00
Product (FRU) Number     : NM-HDV=
EEPROM format version 4
EEPROM contents (hex):
0x00: 04 FF 40 00 CC 41 01 01 C0 46 03 20 00 0D EF 01
0x10: 42 45 30 80 00 00 00 00 02 02 C1 8B 4A 41 42 30
0x20: 34 33 39 30 4B 4E 47 03 00 81 00 00 00 00 04 00
0x30: FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
0x40: FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
0x50: FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
0x60: FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF
0x70: FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF FF

HDV SIMMs: Product (FRU) Number: PVDM-12
SIMM slot 0: Empty.
SIMM slot 1: Empty.
SIMM slot 2: PVDM-12 SIMM present.
SIMM slot 3: PVDM-12 SIMM present.
SIMM slot 4: PVDM-12 SIMM present.
.

GWY01#sh voice dsp

DSP  DSP             DSPWARE CURR  BOOT                         PAK     TX/RX
TYPE NUM CH CODEC    VERSION STATE STATE   RST AI VOICEPORT TS ABORT  PACK COUNT
==== === == ======== ======= ===== ======= === == ========= == ===== ============
C549 007 01 {medium}  4.1.45 IDLE  idle      0  0 2/0:15    01     0 95382631/933
51746
02 {medium}  4.1.45 IDLE  idle         0 2/0:15    02     0 47552148/467
89172
03 {medium}  4.1.45 IDLE  idle         0 2/0:15    03     0 20910677/206
87231
04 {medium}  4.1.45 IDLE  idle         0 2/0:15    04     0 8394645/8321
251
C549 008 01 {medium}  4.1.45 IDLE  idle      0  0 2/0:15    05     0 3004228/3000
106
02 {medium}  4.1.45 IDLE  idle         0 2/0:15    06     0 983950/97893
8
03 {medium}  4.1.45 IDLE  idle         0 2/0:15    07     0 538659/54259
5
04 {medium}  4.1.45 IDLE  idle         0 2/0:15    08     0 2102367/2139
512
C549 009 01 {medium}  4.1.45 IDLE  idle      0  0 2/0:15    09     0 8154416/8309
524
02 {medium}  4.1.45 IDLE  idle         0 2/0:15    10     0 23548128/239
63817
03 {medium}  4.1.45 IDLE  idle         0 2/0:15    11     0 56429286/574
41003
04 {medium}  4.1.45 IDLE  idle         0 2/0:15    12     0 106057197/10
7984725

This is from another gateway using PVDM2-32 & PVDM2-16:

GW_WCH_01#sh voice dsp group all

DSP groups on slot 0:
dsp 1:
State: UP, firmware: 4.4.24
Max signal/voice channel: 16/16
Max credits: 240
Group: FLEX_GROUP_VOICE, complexity: FLEX
Shared credits: 150, reserved credits: 0
Signaling channels allocated: 16
Voice channels allocated: 6
Credits used: 90
Voice channels:
Ch01: voice port: 0/0/0:15.29, codec: g711ulaw, credits allocated: 15
Ch02: voice port: 0/0/0:15.3, codec: g711alaw, credits allocated: 15
Ch03: voice port: 0/0/0:15.1, codec: g711alaw, credits allocated: 15
Ch04: voice port: 0/0/0:15.2, codec: g711alaw, credits allocated: 15
Ch05: voice port: 0/0/0:15.4, codec: g711alaw, credits allocated: 15
Ch06: voice port: 0/0/0:15.31, codec: g711alaw, credits allocated: 15

dsp 2:
State: UP, firmware: 4.4.24
Max signal/voice channel: 16/16
Max credits: 240
Group: FLEX_GROUP_VOICE, complexity: FLEX
Shared credits: 225, reserved credits: 0
Signaling channels allocated: 16
Voice channels allocated: 1
Credits used: 15
Voice channels:
Ch01: voice port: 0/0/0:15.5, codec: g711alaw, credits allocated: 15

dsp 5:
State: UP, firmware: 4.4.24
Max signal/voice channel: 16/16
Max credits: 240
Group: FLEX_GROUP_VOICE, complexity: FLEX
Shared credits: 240, reserved credits: 0
Signaling channels allocated: 2
Voice channels allocated: 0
Credits used: 0

DSP groups on slot 1:
This command is not applicable to slot 1

DSP groups on slot 2:
This command is not applicable to slot 2

0 DSP resource allocation failure

GW_WCH_01#sh voice dsp

DSP  DSP                DSPWARE CURR  BOOT                         PAK     TX/RX
TYPE NUM CH CODEC       VERSION STATE STATE   RST AI VOICEPORT TS ABORT  PACK COUNT
==== === == ======== ========== ===== ======= === == ========= == ===== ============

—————————-FLEX VOICE CARD 0 ——————————
*DSP VOICE CHANNELS*
DSP   DSP                DSPWARE CURR  BOOT                         PAK   TX/RX
TYPE  NUM CH CODEC       VERSION STATE STATE   RST AI VOICEPORT TS ABRT PACK COUNT
===== === == ======== ========== ===== ======= === == ========= == ==== ============
C5510 001 01 g711alaw     4.4.24 busy  idle      0  0 0/0/0:15  01    0    3128/3041
C5510 001 02 g711alaw     4.4.24 busy  idle      0  0 0/0/0:15  02    0  10125/10293
C5510 001 03 g711alaw     4.4.24 busy  idle      0  0 0/0/0:15  03    0    1432/1215
*DSP SIGNALING CHANNELS*
DSP   DSP                DSPWARE CURR  BOOT                         PAK   TX/RX
TYPE  NUM CH CODEC       VERSION STATE STATE   RST AI VOICEPORT TS ABRT PACK COUNT
===== === == ======== ========== ===== ======= === == ========= == ==== ============
C5510 001 01 {flex}       4.4.24 alloc idle      0  0 0/1/1     06    0         18/0
C5510 001 02 {flex}       4.4.24 alloc idle      0  0 0/1/0     06    0        442/0
C5510 001 03 {flex}       4.4.24 alloc idle      0  0 0/1/3     02    0         18/0
C5510 001 04 {flex}       4.4.24 alloc idle      0  0 0/1/2     02    0        110/0
————————END OF FLEX VOICE CARD 0 —————————-

GW_WCH_01#sh voice dsp active

DSP  DSP                DSPWARE CURR  BOOT                         PAK     TX/RX
TYPE NUM CH CODEC       VERSION STATE STATE   RST AI VOICEPORT TS ABORT  PACK COUNT
==== === == ======== ========== ===== ======= === == ========= == ===== ============

—————————-FLEX VOICE CARD 0 ——————————
*DSP ACTIVE VOICE CHANNELS*
DSP      DSPWARE           VOX DSP               SIG DSP            PAK   TX/RX
TYPE     VERSION CODEC    NUM CH TS VOICEPORT SLT NUM CH TS RST AI ABRT PACK COUNT
===== ========== ======== === == == ========= === === == == === == ==== ============
C5510 4.4.24 g711alaw 001 01 01 0/0/0:15  000 001 05 01   0  0    0  15825/15801
C5510 4.4.24 g711alaw 001 02 02 0/0/0:15  000 001 06 02   0  0    0  22822/23053
C5510 4.4.24 g711alaw 001 03 03 0/0/0:15  000 001 07 03   0  0    0  14129/14030
C5510 4.4.24 g711alaw 001 04 04 0/0/0:15  000 001 08 04   0  0    0    6865/5661
C5510 4.4.24 g711alaw 001 05 05 0/0/0:15  000 001 09 05   0  0    0    4636/4588
C5510 4.4.24 g711alaw 002 01 06 0/0/0:15  000 001 10 06   0  0    0    3141/3180
————————END OF FLEX VOICE CARD 0 —————————-

Transcoding SessionsWS-6608-T1/E1 {24 per port, 192 per module}

WS-SVC-CMM-ACT {64}

C549 {4}

C549 in 1751/1760  {2}

C5510 medium complexity {8}

C5510 high complexity {6}

c5510 flex complexity {16*}

* It is only possible to support 16 transcoding sessions when you are transcoding between two low- complexity codecs. Because this situation is rare, the practical maximum number of transcoding sessions per DSP is 8.

This was an interesting scenario where incoming calls were getting ‘user busy’ message at the gateway and an engage tone was heard at calling party side.

*Aug 18 08:36:53.581: ISDN Se0/0/0:15 Q931: RX <-CALL_PROC pd = 8  callref = 0x8D7E
Channel ID i = 0xA9839E
Exclusive, Channel 30

*Aug 18 08:36:54.997: ISDN Se0/0/0:15 Q931: RX <- DISCONNECT pd = 8  callref = 0x8D7E
Cause i = 0x8091 -User busy

It was not just one extension but several extensions which were having the same issue. They were all running fine till yesterday!

Something must have happened…

I did debug voip ccapi inout for a working extension and a non-working one, this is what I found:

Successful call to 7536 and un-successful call to 7534:

Call to 7536:

Aug 19 08:41:00.697: //757/541618588180/CCAPI/cc_api_display_ie_subfields:

ccCallSetupRequest:
cisco-username=
—– ccCallInfo IE subfields —–

cisco-ani=9XXXXXXX395
cisco-anitype=2
cisco-aniplan=1
cisco-anipi=0
cisco-anisi=1
dest=7536
cisco-desttype=0
cisco-destplan=1
cisco-rdie=FFFFFFFF
cisco-rdn=
cisco-lastrdn=
cisco-rdntype=-1
cisco-rdnplan=-1
cisco-rdnpi=-1
cisco-rdnsi=-1
cisco-redirectreason=-1   fwd_final_type =0
final_redirectNumber =
hunt_group_timeout =0

Aug 19 08:41:00.697: //757/541618588180/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x480CDF30, Interface Type=1, Destination=, Mode=0x0,
Call Params(Calling Number=9XXXXXXX395,(Calling Name=)(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),
Called Number=7536(TON=Unknown, NPI=ISDN), Calling Translated=FALSE,
Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE, Outgoing Dial-peer=10, Call Count On=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
Aug 19 08:41:00.701: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
Aug 19 08:41:00.701: :cc_get_feature_vsa malloc success
Aug 19 08:41:00.701: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:
Aug 19 08:41:00.701:  cc_get_feature_vsa count is 8
Aug 19 08:41:00.701: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 19 08:41:00.701: :FEATURE_VSA attributes are: feature_name:0,feature_time:1187854080,feature_id:785
Aug 19 08:41:00.701: //758/541618588180/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=1, FlowMode=1
Aug 19 08:41:00.701: //758/541618588180/CCAPI/ccCallSetContext:
Context=0x46B3748C
Aug 19 08:41:00.701: //757/541618588180/CCAPI/ccSaveDialpeerTag:

Outgoing Dial-peer=10

Aug 19 08:41:00.901: //758/541618588180/CCAPI/cc_api_set_called_ccm_detected:
CallInfo(called ccm detected=TRUE ccmVersion 1)
Aug 19 08:41:00.901: //758/541618588180/CCAPI/cc_api_call_proceeding:
Interface=0x480CDF30, Progress Indication=NULL(0)
Aug 19 08:41:00.905: //758/541618588180/CCAPI/cc_api_set_called_ccm_detected:
CallInfo(called ccm detected=TRUE ccmVersion 1)
Aug 19 08:41:00.905: //758/541618588180/CCAPI/cc_api_set_delay_xport:
CallInfo(delay xport=TRUE)
Aug 19 08:41:00.905: //758/541618588180/CCAPI/cc_api_call_alert:
Interface=0x480CDF30, Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
Aug 19 08:41:00.909: //758/541618588180/CCAPI/cc_api_call_alert:
Call Entry(Retry Count=0, Responsed=TRUE)
Aug 19 08:41:00.909: //758/541618588180/CCAPI/cc_api_set_called_ccm_detected:

CallInfo(called ccm detected=TRUE ccmVersion 1)

Aug 19 08:41:00.909: //758/541618588180/CCAPI/cc_api_call_notify:
Data Bitmask=0x5, Interface=0x480CDF30, Call Id=758
Aug 19 08:41:00.909: //757/541618588180/CCAPI/ccCallAlert:
Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
Aug 19 08:41:00.909: //757/541618588180/CCAPI/ccCallAlert:
Call Entry(Responsed=TRUE, Alert Sent=TRUE)
Aug 19 08:41:00.913: //757/541618588180/CCAPI/ccGenerateToneInfo:

Stop Tone On Digit=FALSE, Tone=Ring Back,

Tone Direction=Network, Params=0x0, Call Id=757
Aug 19 08:41:00.921: //758/541618588180/CCAPI/cc_api_get_ssCTreRoutingNotSupported:
CallInfo(ssCTreRoutingNotSupported=FALSE)
Aug 19 08:41:00.921: //758/541618588180/CCAPI/cc_api_get_ccm_detected:
CallInfo(ccm detected=TRUE)
Aug 19 08:41:00.921: //757/541618588180/

CCAPI/ccCallNotify:
Data Bitmask=0x5, Call Id=757

Call to 7534:

—– ccCallInfo IE subfields —–

cisco-ani=9XXXXXXX395
cisco-anitype=2
cisco-aniplan=1
cisco-anipi=0
cisco-anisi=1
dest=7534
cisco-desttype=0
cisco-destplan=1
cisco-rdie=FFFFFFFF
cisco-rdn=
cisco-lastrdn=
cisco-rdntype=-1
cisco-rdnplan=-1
cisco-rdnpi=-1
cisco-rdnsi=-1
cisco-redirectreason=-1   fwd_final_type =0
final_redirectNumber =
hunt_group_timeout =0

Aug 19 08:36:26.159: //-1/B07908F8816D/CCAPI/cc_api_call_setup_ind_common:
Interface=0x49470D5C, Call Info(Calling Number=9XXXXXXX395,(Calling Name=)(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),Called Number=7534(TON=Unknown, NPI=ISDN),

Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE,
Incoming Dial-peer=2, Progress Indication=NULL(0), Calling IE Present=TRUE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
Aug 19 08:36:26.159: //-1/B07908F8816D/CCAPI/ccCheckClipClir:
In: Calling Number=9XXXXXXX395(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed)
Aug 19 08:36:26.159: //-1/B07908F8816D/CCAPI/ccCheckClipClir:
Out: Calling Number=9XXXXXXX395(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed)
Aug 19 08:36:26.159: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 19 08:36:26.163: :cc_get_feature_vsa malloc success
Aug 19 08:36:26.163: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 19 08:36:26.163:  cc_get_feature_vsa count is 11
Aug 19 08:36:26.163: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 19 08:36:26.163: :FEATURE_VSA attributes are: feature_name:0,feature_time:1187856544,feature_id:752
Aug 19 08:36:26.163: //725/B07908F8816D/CCAPI/cc_api_call_setup_ind_common:

Set Up Event Sent;
Call Info(Calling Number=9XXXXXXX395(TON=National, NPI=ISDN, Screening=User, Passed, Presentation=Allowed),
Called Number=7534(TON=Unknown, NPI=ISDN))
Aug 19 08:36:26.167: //725/B07908F8816D/CCAPI/cc_process_call_setup_ind:

Event=0x48577A78
Aug 19 08:36:26.167: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:

Try with the demoted called number 7534

Aug 19 08:36:26.167: //725/B07908F8816D/CCAPI/ccCallSetContext:
Context=0x46B3C0AC
Aug 19 08:36:26.167: //725/B07908F8816D/CCAPI/cc_process_call_setup_ind:
>>>>CCAPI handed cid 725 with tag 2 to app “_ManagedAppProcess_Default”
Aug 19 08:36:26.179: //725/B07908F8816D/CCAPI/ccCallProceeding:
Progress Indication=NULL(0)

Aug 19 08:36:26.183: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
Try with the demoted called number 7534
Aug 19 08:36:26.183: //-1/xxxxxxxxxxxx/CCAPI/cc_update_feature_vsa:
Aug 19 08:36:26.183: : updating existing feature vsa
Aug 19 08:36:26.183: //-1/xxxxxxxxxxxx/CCAPI/cc_update_feature_vsa:

Aug 19 08:36:26.183:  feature call basic
Aug 19 08:36:26.203: //725/B07908F8816D/CCAPI/ccCallDisconnect:
Cause(Value=17, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
Aug 19 08:36:26.203: //725/B07908F8816D/CCAPI/ccCallDisconnect:

Cause Value=17, Call Entry(Responsed=TRUE, Cause Value=17)

Aug 19 08:36:26.203: //725/B07908F8816D/CCAPI/cc_api_get_transfer_info:
Transfer Number Is Null
Aug 19 08:36:26.371: //725/B07908F8816D/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x49470D5C, Tag=0x0, Call Id=725,
Call Entry(Disconnect Cause=17, Voice Class Cause Code=0, Retry Count=0)
Aug 19 08:36:26.375: //725/B07908F8816D/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
Aug 19 08:36:26.375: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:
Aug 19 08:36:26.375: :cc_free_feature_vsa freeing 46CD4098
Aug 19 08:36:26.375: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

The above results show that a successful call did hit the outbound VoIP dialpeer which was pointing to CCM but the failed call was just hitting the Inbound POTS dialpeer and was not routing to the VoIP dialpeer. Why in the world one DDI of same range is routing to CCM while other is returning user busy (the cause code 17 is user busy). The phone at x7534 was registered to call manager and there were all ISDN channels available (Show isdn service). I checked the gateway configuration and found telephony-service configured on it with auto-provision none.

telephony-service
srst mode auto-provision none
srst ephone template 1
srst ephone description srst fallback auto-provision phone
srst dn template 1
srst dn line-mode dual

.

.

But I could also see all ephones and ephone-dn’s in the configuration. I found out that this failed extension x7534 was sitting there under one of the ephone-dn. I confirmed that a third party engineer configured SRST on the router previous evening and he checked everything working fine ….. what he did….he configured srst auto provision all to learn the dn’s so that he can configure the hunt groups and then locked it down using srst auto provision none. This, however, produced abnormal results as the phones which were learned by the gateway were preferred over VoIP dialpeer and a call to these numbers was not getting routed to Call manager. This is what I did to solve this issue:

Router(config)# dial-peer hunt 3
•0—Specifies longest match in phone number, explicit preference, random selection (default)
•1—Specifies longest match in phone number, explicit preference, least recent use.
•2—Specifies explicit preference, longest match in phone number, random selection.
•3—Specifies explicit preference, longest match in phone number, least recent use.
•4—Specifies least recent use, longest match in phone number, explicit preference.
•5—Specifies least recent use, explicit preference, longest match in phone number.
•6—Specifies random selection.
•7—Specifies least recent use.

ephone-dn  1  dual-line
preference 8
!
!
ephone-dn  2  dual-line
preference 8
!
!
ephone-dn  3  dual-line
preference 8
!
!
ephone-dn  4  dual-line
preference 8
!
!
ephone-dn  5  dual-line
preference 8
!
!
ephone-dn  6  dual-line
preference 8
!

to ephone-dn 45

– same –

Tested the call all working fine.

What was happening – the call was coming in and because the phone was learned as ephone it was preferred over VoIP dialpeer.

To avoid incorrect routing when you prebuild ephone-dns for Cisco Unified Communications Manager phones in Cisco Unified CME, use the preference command in ephone-dn and voip-dial-peer configuration mode to create a higher preference (0 being the highest) for the voip dial peer than the preference for the prebuilt directory number.