Re: Following CUCM 9.1.2 to 11.5.1SU3a we get intermittent no audio on calls via PSTN

seb_at_work · ‎10-23-2017

Hi foilks,

Has anyone experienced issues with no audio on calls via PSTN (ISDN in our case) following a CUCM 9 to 11 upgrade?

We are seeing these very intermittently (maybe 1 in 20 calls) following the upgrade over the weekend.

So call will connect succesfully but no audio flows either way.

I've tested internal calls and calls between other cucm clusters using intercluster trunks and they don't seem to be affected.

Handsets:

Seems to affect all handsets: 7841 SIP with a couple of 7945 SCCP and also IP communicator (SCCP) - so can't pin this down to a particular handset unfortunately.

I'm mainly testing on the 7841 which isn't great for stats but when I tested this on the IP communicator and pressed the ? button I could see the tx/rx counters increment even without audio.

CUCM upgrade: note we uninstalled our country dial plan (GBNP) prior to the upgrade and then reinstalled afterwards as saw the multiple posts related to CUCM upgrade issues with non-NANP plan in place. Not sure whether that could be related? Also note we've reinstalled the GB user & combined network locale and set all handsets user/network locale to UK following the upgrade.

Voice gateway:

I'm therefore thinking this could be voice gateway related (ISR 2900 configured as H323 gateway in CUCM with ISDN interface to our POTS provider). Prior to the CUCM upgrade we had upgraded the firmware on the VG to 15.6.3M1 as that was on the Cucm compatibility matrix and last night upgraded to the latest release in that train 15.6.3M3a - but that didn't help.

Note the pair of ethernet interfaces on the VG are linked in a BVI for failover.

I did do some ISDN debugging on the voice gateway to see if they showed differences on a working / none working call and can't see any differences in the output:

Bad call:

=====

Oct 22 16:14:28.472: ISDN Se0/0/0:15 EVENT: process_pri_call: call id 0x8028, number 01234567890, Guid 80CFD2123700, speed 0, call type VOICE, redial No, CSM call No, pdata Yes
Oct 22 16:14:28.472: ISDN Se0/0/0:15 Q931: Applying typeplan for sw-type 0x12 is 0x0 0x0, Calling num 5973
Oct 22 16:14:28.472: ISDN Se0/0/0:15 Q931: Sending SETUP callref = 0x00A7 callID = 0x8028 switch = primary-net5 interface = User
Oct 22 16:14:28.476: ISDN Se0/0/0:15 Q931: TX -> SETUP pd = 8 callref = 0x00A7
Bearer Capability i = 0x8090A3
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA18381
Preferred, Channel 1
Calling Party Number i = 0x0081, '5973'
Plan:Unknown, Type:Unknown
Called Party Number i = 0x80, '01234567890'
Plan:Unknown, Type:Unknown
Oct 22 16:14:28.644: ISDN Se0/0/0:15 Q931: RX <- CALL_PROC pd = 8 callref = 0x80A7
Channel ID i = 0xA98381
Exclusive, Channel 1
Oct 22 16:14:28.644: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x8028 calltype 2 CALL_PROCEEDING
Oct 22 16:14:35.008: ISDN Se0/0/0:15 Q931: RX <- ALERTING pd = 8 callref = 0x80A7
Progress Ind i = 0x8488 - In-band info or appropriate now available
Oct 22 16:14:35.008: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x8028 calltype 2 CALL_PROGRESS
Oct 22 16:14:35.012: voip_rtp_allocate_port:Possible port leak? callID(113), port(16494) socket(0x0)
Oct 22 16:14:37.908: ISDN Se0/0/0:15 Q931: RX <- CONNECT pd = 8 callref = 0x80A7
Oct 22 16:14:37.908: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x8028 calltype 2 CALL_CONNECT
Oct 22 16:14:37.908: ISDN Se0/0/0:15 EVENT: isdn_neighbor_update: NLCB->State 10
Oct 22 16:14:37.908: ISDN Se0/0/0:15 EVENT: isdn_neighbor_update: NLCB->State 10
Oct 22 16:14:37.908: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x8028 calltype 2 CALL_PROGRESS
Oct 22 16:14:37.908: ISDN Se0/0/0:15 Q931: TX -> CONNECT_ACK pd = 8 callref = 0x00A7
Oct 22 16:14:41.180: ISDN Se0/0/0:15 Q931: TX -> DISCONNECT pd = 8 callref = 0x00A7
Cause i = 0x8090 - Normal call clearing
Oct 22 16:14:41.356: ISDN Se0/0/0:15 Q931: RX <- RELEASE pd = 8 callref = 0x80A7
Oct 22 16:14:41.360: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x8028 calltype 2 CALL_CLEARED
Oct 22 16:14:41.360: ISDN Se0/0/0:15 Q931: TX -> RELEASE_COMP pd = 8 callref = 0x00A7

=====

Good call:

=====

ct 22 16:19:50.797: ISDN Se0/0/0:15 EVENT: process_pri_call: call id 0x802A, number 01234567890, Guid 801CC0D23900, speed 0, call type VOICE, redial No, CSM call No, pdata Yes
Oct 22 16:19:50.797: ISDN Se0/0/0:15 Q931: Applying typeplan for sw-type 0x12 is 0x0 0x0, Calling num 5818
Oct 22 16:19:50.797: ISDN Se0/0/0:15 Q931: Sending SETUP callref = 0x00A9 callID = 0x802A switch = primary-net5 interface = User
Oct 22 16:19:50.797: ISDN Se0/0/0:15 Q931: TX -> SETUP pd = 8 callref = 0x00A9
Bearer Capability i = 0x8090A3
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0xA18381
Preferred, Channel 1
Calling Party Number i = 0x0081, '5818'
Plan:Unknown, Type:Unknown
Called Party Number i = 0x80, '01234567890'
Plan:Unknown, Type:Unknown
Oct 22 16:19:50.985: ISDN Se0/0/0:15 Q931: RX <- CALL_PROC pd = 8 callref = 0x80A9
Channel ID i = 0xA98381
Exclusive, Channel 1
Oct 22 16:19:50.985: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x802A calltype 2 CALL_PROCEEDING
Oct 22 16:19:55.893: ISDN Se0/0/0:15 Q931: RX <- ALERTING pd = 8 callref = 0x80A9
Progress Ind i = 0x8488 - In-band info or appropriate now available
Oct 22 16:19:55.893: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x802A calltype 2 CALL_PROGRESS
Oct 22 16:19:55.893: voip_rtp_allocate_port:Possible port leak? callID(119), port(16500) socket(0x0)
Oct 22 16:19:58.049: ISDN Se0/0/0:15 Q931: RX <- CONNECT pd = 8 callref = 0x80A9
Oct 22 16:19:58.049: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x802A calltype 2 CALL_CONNECT
Oct 22 16:19:58.049: ISDN Se0/0/0:15 EVENT: isdn_neighbor_update: NLCB->State 10
Oct 22 16:19:58.049: ISDN Se0/0/0:15 EVENT: isdn_neighbor_update: NLCB->State 10
Oct 22 16:19:58.049: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x802A calltype 2 CALL_PROGRESS
Oct 22 16:19:58.049: ISDN Se0/0/0:15 Q931: TX -> CONNECT_ACK pd = 8 callref = 0x00A9
Oct 22 16:20:06.465: ISDN Se0/0/0:15 Q931: TX -> DISCONNECT pd = 8 callref = 0x00A9
Cause i = 0x8090 - Normal call clearing
Oct 22 16:20:06.637: ISDN Se0/0/0:15 Q931: RX <- RELEASE pd = 8 callref = 0x80A9
Oct 22 16:20:06.637: ISDN Se0/0/0:15 EVENT: process_rxstate: ces/callid 1/0x802A calltype 2 CALL_CLEARED
Oct 22 16:20:06.641: ISDN Se0/0/0:15 Q931: TX -> RELEASE_COMP pd = 8 callref = 0x00A9

=====

When we upgraded the VG some months back we also spotted the "voip_rtp_allocate_port:Possible port leak" warning then so that doesn't seem linked to the CUCM upgrade.

Networking:

Can ping the voice gateway constantly from another vlan without issue (when we experience the problem calls). I don't think networking is the issue (that hasn't changed over the weekend, only CUCM).

I'm wondering whether we need to change our Gateway config from H323 to SIP - but afaik H323 is still supported by CUCM 11.

Any other ideas?

I may need to contact TAC :)

Thanks in advance. Seb

seb_at_work · ‎10-25-2017

Hi,

Just to follow this was up, I think this was unrelated to the cucm upgrade itself but an underlying problem with an existing misconfiguration on the voice gateway (the effect of this only becoming apparent during testing post cucm upgrade).

So we found clock slip errors on the E1 controller on voice gateway:

show controller e1 0/0/0

<snip>

Total Data (last 24 hours)
0 Line Code Violations, 0 Path Code Violations,
6754 Slip Secs, 0 Fr Loss Secs, 0 Line Err Secs, 0 Degraded Mins,
6754 Errored Secs, 0 Bursty Err Secs, 0 Severely Err Secs, 0 Unavail Secs

In our voice gateway config relating to clocks we only had the following line

network-clock-participate wic 0

and were missing

network-clock-select 1 E1 0/0/0

so added that line as per https://supportforums.cisco.com/t5/collaboration-voice-and-video/clock-slips-continue-after-configuration-of-clocking-on-a-2600/ta-p/3132100

I can't now reproduce the problem after extensive testing - fingers crossed that has fixed it :)

Seb

kenyangibbs · ‎05-25-2018

Did you find the solution for this, we are just upgraded our CUCM last weekend from 10.5 to 11.5. Some calls made from our desk phones (7941) to local numbers are getting no audio but it connects. When i call from ip communicator which has the same DN as my deskphone it rings out and i get audio. showing the following error from my voice gateway.

001947: May 25 10:59:45.759: voip_rtp_allocate_port:Possible port leak? callID(4294967295), port(17930) socket(0x0)
001948: May 25 10:59:48.999: voip_rtp_allocate_port:Possible port leak? callID(1644), port(17920) socket(0x0)
001949: May 25 11:00:10.839: voip_rtp_allocate_port:Possible port leak? callID(1646), port(17972) socket(0x0)
001950: May 25 11:00:20.915: voip_rtp_allocate_port:Possible port leak? callID(1648), port(17946) socket(0x0)
001951: May 25 11:00:26.063: voip_rtp_allocate_port:Possible port leak? callID(1650), port(17952) socket(0x0)
001952: May 25 11:00:28.567: voip_rtp_allocate_port:Possible port leak? callID(1652), port(17918) socket(0x0)
001953: May 25 11:00:32.131: voip_rtp_allocate_port:Possible port leak? callID(4294967295), port(17812) socket(0x0)

seb_at_work · ‎06-05-2018

Hi,
As mentioned in my reply to my original post, the errors we were getting were not due to the cucm upgrade itself but an underlying misconfiguration on our voice gateways. So it was just our post upgrade testing that revealed the problem. Our solution was to fix the clock slip errors (thats ISDN specific - don't think too many people are using ISDN anymore!).
Hope that helps.
Cheers, Seb