Cause i = 0x82E6 - Recovery on timer expiry

jfrackiewicz · ‎08-20-2014

Hello,

we are experiencing a problem with external incoming calls. When our customer is in active call and somebody wants to call him from a mobile phone (like Vodafone etc.) it takes a long time until we get a error on the H323 gateway.

Aug 20 13:01:38.696 GMT: ISDN Se0/1/0:15 Q931: RX <- SETUP pd = 8  callref = 0x447C
        Bearer Capability i = 0x8090A3
                Standard = CCITT
                Transfer Capability = Speech  
                Transfer Mode = Circuit
                Transfer Rate = 64 kbit/s
        Channel ID i = 0xA98386
                Exclusive, Channel 6
        Calling Party Number i = 0x2183, '170792xxx'
                Plan:ISDN, Type:National
        Called Party Number i = 0xC1, '85794xxxx'
                Plan:ISDN, Type:Subscriber(local)
        High Layer Compat i = 0x9181
Aug 20 13:01:38.696 GMT: ISDN Se0/1/0:15 Q931: Received SETUP  callref = 0xC47C callID = 0x0225 switch = primary-net5 interface = User
Aug 20 13:01:38.700 GMT: ISDN Se0/1/0:15 Q931: TX -> SETUP_ACK pd = 8  callref = 0xC47C
        Channel ID i = 0xA98386
                Exclusive, Channel 6
Aug 20 13:01:39.700 GMT: ISDN Se0/1/0:15 Q931: TX -> CALL_PROC pd = 8  callref = 0xC47C
Aug 20 13:02:09.703 GMT: ISDN Se0/1/0:15 Q931: TX -> DISCONNECT pd = 8  callref = 0xC47C
        Cause i = 0x8090 - Normal call clearing
Aug 20 13:02:09.715 GMT: ISDN Se0/1/0:15 Q931: RX <- DISCONNECT pd = 8  callref = 0x447C
        Cause i = 0x82E6 - Recovery on timer expiry
Aug 20 13:02:09.715 GMT: ISDN Se0/1/0:15 Q931: TX -> RELEASE pd = 8  callref = 0xC47C
Aug 20 13:02:09.719 GMT: ISDN Se0/1/0:15 Q931: RX <- RELEASE pd = 8  callref = 0x447C

If the call comes from a "fix" external phone (like Telekom etc.) not a mobile phone we get a busy response.

Aug 20 13:05:01.347 GMT: ISDN Se0/0/0:15 Q931: RX <- SETUP pd = 8  callref = 0x3871
        Sending Complete
        Bearer Capability i = 0x8090A3
                Standard = CCITT
                Transfer Capability = Speech  
                Transfer Mode = Circuit
                Transfer Rate = 64 kbit/s
        Channel ID i = 0xA9838D
                Exclusive, Channel 13
        Calling Party Number i = 0x2180, '699xxxxx'
                Plan:ISDN, Type:National
        Calling Party Number i = 0x2183, '699xxx'
                Plan:ISDN, Type:National
        Called Party Number i = 0xC1, '857xxxxxx'
                Plan:ISDN, Type:Subscriber(local)
Aug 20 13:05:01.347 GMT: ISDN Se0/0/0:15 Q931: Received SETUP  callref = 0xB871 callID = 0x022C switch = primary-net5 interface = User
Aug 20 13:05:01.351 GMT: ISDN Se0/0/0:15 Q931: TX -> CALL_PROC pd = 8  callref = 0xB871
        Channel ID i = 0xA9838D
                Exclusive, Channel 13
Aug 20 13:05:01.363 GMT: ISDN Se0/0/0:15 Q931: TX -> DISCONNECT pd = 8  callref = 0xB871
        Cause i = 0x8091 - User busy
Aug 20 13:05:01.431 GMT: ISDN Se0/0/0:15 Q931: RX <- RELEASE pd = 8  callref = 0x3871
Aug 20 13:05:01.431 GMT: ISDN Se0/0/0:15 Q931: TX -> RELEASE_COMP pd = 8  callref = 0xB871


interface Serial0/0/0:15
 no ip address
 encapsulation hdlc
 isdn switch-type primary-net5
 isdn overlap-receiving T302 2500
 isdn incoming-voice voice
 isdn send-alerting
 isdn sending-complete
 no cdp enable


interface Serial0/1/0:15
 no ip address
 encapsulation hdlc
 isdn switch-type primary-net5
 isdn overlap-receiving T302 2500
 isdn incoming-voice voice
 isdn send-alerting
 isdn sending-complete
 no cdp enable

It think this is a telco problem. Since the problem persist since the last week and there was a telco migration.

Brian Meade · ‎08-20-2014

Are you using CUCM or CME? If CUCM, what does your dial-peer config look like?

jfrackiewicz · ‎08-20-2014

We are using CUCM 8.6.2.

!
dial-peer voice 100 voip
 preference 2
 destination-pattern 498985794T
 no modem passthrough
 session target ipv4:172.xx
 voice-class codec 10  
 voice-class h323 10
 dtmf-relay h245-alphanumeric
 playout-delay fax 40
 no fax-relay sg3-to-g3
 fax rate 9600
 fax nsf 000000
 fax protocol t38 version 0 ls-redundancy 1 hs-redundancy 1 fallback none
 ip qos dscp cs3 signaling
 no vad
!
dial-peer voice 110 voip
 preference 4
 destination-pattern 498985794T
 no modem passthrough
 session target ipv4:172.xx
 voice-class codec 10  
 voice-class h323 10
 dtmf-relay h245-alphanumeric
 playout-delay fax 40
 no fax-relay sg3-to-g3
 fax rate 9600
 fax nsf 000000
 fax protocol t38 version 0 ls-redundancy 1 hs-redundancy 1 fallback none
 ip qos dscp cs3 signaling
 no vad

dial-peer voice 999 voip
 session target ipv4:172.xx
 incoming called-number .
 voice-class codec 10  
 dtmf-relay h245-signal h245-alphanumeric rtp-nte
 no vad
!
dial-peer voice 998 voip
 session target ipv4:172.xx
 incoming called-number .
 voice-class codec 10  
 dtmf-relay h245-signal h245-alphanumeric rtp-nte
 no vad
!

Regards

Brian Meade · ‎08-21-2014

Can you collect CallManager traces set to Detailed and attach them for both call examples?

j.huizinga · ‎08-21-2014

Hi,

Recovery on timer expiry

Normally is layer 2 issue.

Can you debug isdn q921?

Jan

Sreekanth Narayanan · ‎08-22-2014

I think we need to see the behavior of the gateway on the other leg, h323. Maybe there's a difference in the way the call is being handled in the 2 cases. Let's take debugs on the other side too.

debug voip ccapi inout

debug h225 asn1

debug h245 asn1

debug cch323 h225

debug cch323 h245

jfrackiewicz · ‎08-22-2014

We found something -> Can someone tell me where the FinalDestinationFlag is set/generated? On Voicegateway side or provider side?

Brian Meade · ‎08-22-2014

I believe FinalDestinationFlag is set to True when there's only one matching outbound dial-peer. Can you post a full "debug voice ccapi inout" output so we can see if it tries another outgoing dial-peer in the failed scenario? I'm guessing the issue is going to be related to the failed call hunting to another dial-peer when getting the user-busy. Please also get the above debugs as requested by Sreekanth so we can see if the other side is actually sending user busy in both cases.

jfrackiewicz · ‎08-22-2014

Attached I have the

Debug h225 asn1

Debug h245 asn1

Debug voice ccapi inout

Currently I am not on site to do the other debugs.

Brian Meade · ‎08-22-2014

Please also add "debug isdn q931" and "debug cch323 all" and collect again with all.

Also turn on "service sequence-numbers", disable console and monitor logging, and set up a logging buffer.

conf t

service sequence-numbers

no logging console

no logging mon

logging buffer 5000000 debug

then do clear log and collect the log by running "show log". This method will ensure no messages are missed and also make sure you don't crash the router with intensive debugs.

Daniel Reibestein · ‎08-25-2014

Hi Guys,

I'm a colleague of the initiator(jfrackiewicz), please find attached "debug isdn q931" and "debug cch323 all" as requested

Calling Party Number i = 0x2183, '1707923821'
Plan:ISDN, Type:National
Called Party Number i = 0xC1, '8579453047'

We are fairly sure that is it no call manager issue, due to the fact, that we have a h323 gateway that sends a "setup_ack" 4 milliseconds after receiving the "setup" from the provider, we assume that everything "interesting" happens on the voice gateway.

Some time ago he had a look on the call manager traces and couldn't find anything that could help.

Also we are a bit confused what causes the issue, because it is just happening since the provider change and the busy tone fails provider based: for example Vodafone works not, Deutsche Telekom does. So primarily we try to find out whats the difference at incoming calls.

Thanks to all for the feedback

Kind Regards

Daniel

Brian Meade · ‎08-25-2014

Please collect all the requested debugs for working and non-working. These timestamps don't match the other debugs.

Daniel Reibestein · ‎08-25-2014

Hi Brian,

Sorry for the delay. I attached the requested debugs in "failed" and "success". Thank you

failed(Vodafone):

Calling 170792067

Called 49898579453047

success(O2):

Calling 15140036928

Called 49898579453047

SDESTOVGW01#sh debugging

H.225:
H.225 ASN1 Messages debugging is on
H.245:
H.245 ASN1 Messages debugging is on
CCH323 SPI: H225 State Machine tracing is enabled (filter is OFF)
CCH323 SPI: H245 State Machine tracing is enabled (filter is OFF)
CCAPI:
debug voip ccapi inout is ON (filter is OFF)

Brian Meade · ‎08-25-2014

Please also include "debug isdn q931".

For the failed scenario, it looks like direct-inward-dial isn't working.

It seems to generate dialtone to the caller:

204796: Aug 25 17:28:02.275 GMT: //30842/3C81266C8E85/CCAPI/ccGenerateToneInfo:
Stop Tone On Digit=TRUE, Tone=Dial Tone,
Tone Direction=Network, Params=0x0, Call Id=30842

It then waits until it receives a digit from the user:

204843: Aug 25 17:28:04.775 GMT: //30842/3C81266C8E85/CCAPI/cc_api_call_info:
Info Digits=, Info Complete=TRUE,
Interface=0x14A4DA8C, Data Bitmask=0x0, Call Id=30842
204844: Aug 25 17:28:04.775 GMT: //30842/3C81266C8E85/CCAPI/ccCallReportDigits:
(callID=0x787A, digit_event=0x0, enable=FALSE, consume=FALSE)

Why don't you have an incoming dial-peer configured? These calls are hitting dial-peer 0 incoming which is never good. You need to set up an incoming POTS dial-peer with direct-inward-dial enabled.

Daniel Reibestein · ‎08-25-2014

Thats exactly the point, we found out that the incoming dial-peer didnt work properly.

We have configured a new one with "incoming called-number" instead of a "destination-pattern"(+DID) and it seem to work fine. Thanks for the explanation and confirmation.

But we still don't know why the different Calling Parties from external are treated in a different way when the signaling from the provider looks exactly the same.