Takes ages until external caller gets Announciator message for "unallocated number" / H323-GW/ISDN

[Andreas Wittemann]

Hi VoIP artists ;)

i have a somehow strange issue at a customer, if anyone calls an internally unallocated number it takes ages until he gets the message from annouciator that the number doesn´t exist.
On the debugs i saw the infamous around 15s again, so i was quite sure how to fix it, tuning timers and so on.
But, as i could see, the timers should be OK, as well on the H323 gateways and also the callmanagers, according to the service parameters.

Environment is as follows:
2x CISCO2921 / c2900-universalk9-mz.SPA.154-2.T1.bin / 4 BRI-ports / German "Anlagenanschluss" / H323-Config
CUCM 10.5.1.11901 Cluster with two servers

Here the debug of my call to the not allocated internal number:

1643111: Sep 8 10:22:45.602: ISDN BR0/1/0 Q931: RX <- SETUP pd = 8 callref = 0x01
Sending Complete
Bearer Capability i = 0x8090A3
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0x8A
Exclusive, B2
Calling Party Number i = 0x2183, '<MY EXTERNAL PHONE NUMBER>'
Plan:ISDN, Type:National
Called Party Number i = 0xC1, '843<DN WHICH IS NOT ACTIVE>'
Plan:ISDN, Type:Subscriber(local)
High Layer Compat i = 0x9181
1643112: Sep 8 10:22:45.610: ISDN BR0/1/0 Q931: TX -> CALL_PROC pd = 8 callref = 0x81
Channel ID i = 0x8A
Exclusive, B2
1643113: Sep 8 10:22:45.626: ISDN BR0/1/0 Q931: TX -> ALERTING pd = 8 callref = 0x81
Progress Ind i = 0x8188 - In-band info or appropriate now available

### Ringing now ###

1643114: Sep 8 10:22:50.542: ISDN BR0/1/0 Q931: RX <- FACILITY pd = 8 callref = 0xC7
Facility i = 0x91A113020260FD020122300AA1053003020103820100
Protocol Profile = Remote Operations Protocol
0xA113020260FD020122300AA1053003020103820100
Component = Invoke component
Invoke Id = 24829
Operation = AOCDChargingUnit

1643115: Sep 8 10:22:59.674: ISDN BR0/1/0 Q931: TX -> PROGRESS pd = 8 callref = 0x81
Cause i = 0x8181 - Unallocated/unassigned number
Progress Ind i = 0x8188 - In-band info or appropriate now available

### Announciator playing its message now ###

1643116: Sep 8 10:23:13.690: ISDN BR0/1/0 Q931: TX -> DISCONNECT pd = 8 callref = 0x81
Cause i = 0x8081 - Unallocated/unassigned number
1643117: Sep 8 10:23:13.818: ISDN BR0/1/0 Q931: RX <- RELEASE pd = 8 callref = 0x01
1643118: Sep 8 10:23:13.818: ISDN BR0/1/0 Q931: TX -> RELEASE_COMP pd = 8 callref = 0x81
### Call is hanged up finally ###

Relevant config snippets on dialpeers/ports/etcpp:

voice service voip
voice call send-alert
voice call disc-pi-off
voice call convert-discpi-to-prog
voice call carrier capacity active
voice rtp send-recv
!
voice service voip
allow-connections sip to sip
fax protocol pass-through g711ulaw
h323
h225 timeout t302 2
h225 signal overlap
modem passthrough nse codec g711ulaw
sip
bind control source-interface GigabitEthernet0/0
registrar server expires max 1200 min 300
!
voice class codec 1
codec preference 1 g711alaw
codec preference 2 g711ulaw
codec preference 3 g729r8
codec preference 4 g729br8
!
voice class h323 1
h225 timeout tcp establish 3
call start slow
call preserve
!
...
interface BRI0/x/x (CFGS ON ALL PORTS THE SAME!)
no ip address
isdn switch-type basic-net3
isdn overlap-receiving T302 3000
isdn point-to-point-setup
isdn incoming-voice voice
isdn send-alerting
isdn static-tei 0
...
voice-port 0/x/x (CFGS ON ALL PORTS THE SAME!)
no vad
compand-type a-law
no comfort-noise
cptone DE
bearer-cap 3100Hz
...
dial-peer voice 8430000 pots (CFGS ON ALL OUTGOING DPS THE SAME!)
tone ringback alert-no-PI
translation-profile outgoing OUTGOING-POTS
preference 1
destination-pattern 0.T
progress_ind alert enable 8
progress_ind progress enable 8
progress_ind connect enable 8
port 0/x/x
forward-digits all
...
dial-peer voice 100 voip (CFGS ON ALL DPS TOWARDS CUCMS THE SAME!)
translation-profile outgoing OUTGOING-VOIP
preference 1
destination-pattern 843.T
progress_ind setup enable 3
modem passthrough nse codec g711ulaw
session target ipv4:<IP PUBLISHER/SUBSCRIBER>
incoming called-number .
voice-class codec 1
voice-class h323 1
dtmf-relay h245-alphanumeric
fax-relay ecm disable
fax rate disable
fax protocol pass-through g711ulaw
no vad
no supplementary-service h225-notify cid-update
...
dial-peer voice 843 pots
tone ringback alert-no-PI
incoming called-number .
direct-inward-dial

I additionally added the screenshots of the CUCMs service parameters regarding H323...maybe someone can point out easily whats wrong, and i just missed a detail. Currently i am a bit lost, assume everything should be OK..but isn´t obviously. We can replicate that issue easily.

Many thanks in advance for any hint,

Andreas

[Andreas Wittemann]

OK, i cannot upload the two images, tried several times

[Elliot Dierksen]

what does "show call history voice brief" look like after a failed call? What does DNA in CM say when you give it the digit string your gateways sends to it? I suspect you have something that is wrapping back to the gateway when it is not found. If you can find a slow time, use "debug voip ccapi inout" to see what is getting sent where. I feel pretty sure you have some sort of dial plan loop where the gateway sends the call to CM, the gateway sends it, etc. until it all times out at around 15 seconds.

[Andreas Wittemann]

Hi Elliot,

many thanks for your input. I checked in DNA, it clearly says (as expected) "Unallocated number" with NO alternative matches, when i put in the unmatched and by GW modified number.

In general it does what it should, but i somehow have to adjust that timeout...

Regarding to my gateways information/debugs it matches only to my dial-peers 100 (and then 200, same like 100, just pointing to subscriber...buuut, the Message already plays after the first not matched dialpeer on GW, the 100).

It rings six times, until the message of the not known number finally plays.

So, in general i wouldn´t say its a typical back-and-forth-and-back dialplan loop. Do you have any idea which timer it is to adjust that behaviour?

See the debug again:

1646357: Sep 9 10:35:25.528: ISDN BR0/0/1 Q931: RX <- SETUP pd = 8 callref = 0x01
Sending Complete
Bearer Capability i = 0x8090A3
Standard = CCITT
Transfer Capability = Speech
Transfer Mode = Circuit
Transfer Rate = 64 kbit/s
Channel ID i = 0x89
Exclusive, B1
Calling Party Number i = 0x2183, '<MY EXTERNAL PHONE NUMBER>'
Plan:ISDN, Type:National
Called Party Number i = 0xC1, '843<DN WHICH IS NOT ACTIVE>'
Plan:ISDN, Type:Subscriber(local)
High Layer Compat i = 0x9181
1646358: Sep 9 10:35:25.536: ISDN BR0/0/1 Q931: TX -> CALL_PROC pd = 8 callref = 0x81
Channel ID i = 0x89
Exclusive, B1
1646359: Sep 9 10:35:25.552: ISDN BR0/0/1 Q931: TX -> ALERTING pd = 8 callref = 0x81
Progress Ind i = 0x8188 - In-band info or appropriate now available
1646360: Sep 9 10:35:39.584: ISDN BR0/0/1 Q931: TX -> PROGRESS pd = 8 callref = 0x81
Cause i = 0x8181 - Unallocated/unassigned number
Progress Ind i = 0x8188 - In-band info or appropriate now available
1646361: Sep 9 10:35:53.644: ISDN BR0/0/1 Q931: TX -> DISCONNECT pd = 8 callref = 0x81
Cause i = 0x8081 - Unallocated/unassigned number
1646362: Sep 9 10:35:53.788: ISDN BR0/0/1 Q931: RX <- RELEASE pd = 8 callref = 0x01
1646363: Sep 9 10:35:53.788: ISDN BR0/0/1 Q931: TX -> RELEASE_COMP pd = 8 callref = 0x81

[Elliot Dierksen]

I would still troubleshoot this by doing a 'debug voip ccapi inout' during a time when not much else is going on since that command generates a lot of output. I still suspect it is a dialplan overlap, but I don't have enough information to say for sure. You can also do a 'show dialplan num 12345' (where 12345 is the incoming called number you get from the PSTN. That command won't match things with a '%T" that it would match in real life, but it might help. It might be that it is matching another POTS dial peer. You really need more detail to see where it is hanging up. You could also consider putting 'huntstop' on the second voip dial peer, to keep it from searching for other destinations. You could even try that on that most preferred dial peer just to see if that is the issue.

[Andreas Wittemann]

Hi Elliot, i did this already before i replied this morning, all i could see is that it matches the dialpeer100, after it starts playing the announcement. No other dialpeers were matched.

The 200 gets hit as well, but the answer about the unallocated number already hit the GW.

I also put in the huntstop on the 200 as you suggested, and vice versa on the 100, didn´t change anything.

The dialplan checking doesn´t work as well, because of the T, which we have to use here in germany, otherwise not really funny with the customers ;)

[Elliot Dierksen]

Is any of this affected by removing the progress_ind or tone ringback commands from the voip dial peers? I assume you are getting 843 plus a consistent number of digits on inbound from the PSTN. Given that, I would also try changing the incoming called number on the pots peer and the destination pattern on the voip dial peers to ^843....$ (assuming 4 digits). Perhaps that will help. Are you getting all the digits at one time, or is the PSTN sending you the digits one at a time following by a 'sending complete' IE? I have seen that in some lab scenarios with German PRI's. If it is a digit at a time, you might need to add the overlap receiving command on the D serial interface.

[Andreas Wittemann]

About the fixed number of digits which r sent, thats true, we have three digits followed afterwards for the DN.

Problem is, sometimes we get directly the complete number, and sometimes, mainly from old fax-machines and analog-phones, we will receive the last three digits one by one. Usually this causes problems here in germany, thats for why we "wait" until setup is done. But as you maybe can see from the output above, in most cases its sent completely, like the not allocated 843xxx, which experiences these problems.

[Andreas Wittemann]

OK, tried the following:

1. changed destination pattern on the voip DPs to 843... / 843...$

-> no change

2. changed incoming called number on the pots DP to 843... / 843...$

-> no change

3. removed the progress_ind from the dialpeers

-> no change

BTW as i could see, its around 14s seconds, not 15s, until the message about the unallocated number appears:

1648160: Sep 9 17:33:26.254: ISDN BR0/1/0 Q931: TX -> CALL_PROC pd = 8 callref = 0x81
Channel ID i = 0x89
Exclusive, B1

1648162: Sep 9 17:33:40.294: ISDN BR0/1/0 Q931: TX -> PROGRESS pd = 8 callref = 0x81

Cause i = 0x8181 - Unallocated/unassigned number

And see my config above, we have BRIs, which have the overlap receiving added...we definitely need it here, like i mentioned above

Weird thing is i didn´t have this behaviour on any other UC installation before...meanwhile i´m thinking about convincing the customer if we can reboot the whole thing during next week nighttime...usually not my approach to such problems.

Just to mention, many thanks for ur input, some of the things i already checked for, but its always good to have some hints u may hove forgotten whilst searching in a completely wrong direction :)

[Andreas Wittemann]

Hey Elliot,

problem solved:

not with dialplan modification or correction, or adjusting of any timers or service parameters...

just by removing the announciators from the gateways associated MRG.

had a webex with a tac engineer who quickly figured out the root cause.

cheerz, and thanks for ur assistance,

andreas

[Andreas Wittemann]

Forgot to show you the "sh call his voice bri" output:

2D62 : 331492 -417722896ms.331481 (10:16:31.720 METDST Fri Sep 9 2016) +-1 +28260 pid:8430011 Answer <MY EXTERNAL PHONE NUMBER>
dur 00:00:00 tx:1396/234528 rx:1397/223520 1 (unassigned number (1)) dscp:0 media:0 audio tos:0x0 video tos:0x0
Telephony 0/1/1 (331492) [0/1/1.1] tx:13980/13980/0ms g711ulaw noise:-84dBm acom:51dBm
long duration call detected:n long dur callduration :n/a timestamp:n/a

As expected i´d say, right?