[cisco-voip] H323 Voip Call Connected for 5 sec and then drops

Fri Nov 11 10:46:07 EST 2011

Anthony,

  The Gatekeeper intervenes during the whole call.

  Take a look at this document. It is not directly related to your
issue, but it describes how a GK monitors and disconnects calls.

Ariel.

From: Anthony Kouloglou [mailto:akoul at dataways.gr] 
Sent: viernes, 11 de noviembre de 2011 12:40 p.m.
To: ROZA, Ariel
Cc: cisco-voip at puck-nether.net
Subject: Re: [cisco-voip] H323 Voip Call Connected for 5 sec and then
drops

Thanks Ariel,
i thought that gatekeeper was involved initially only, for the gateway
that makes the call, to get the appropriate h323 end point.
So, after it discovers it, then GK is not used any more.
Or maybe not?

On 11-Nov-11 17:36, ROZA, Ariel wrote: 

Anthony,

  From what you describe, i think you should debug the gatekeeper
involved in the call. For some reason the gatekeeper signals the
gateways to tear down the call. I have seen something similar between a
Cisco Gatekeeper and a Nortel BCM1000 that was not updating the call
status to the GK, so the GK ended the call after four attempts to get
that info.

Some debugs that should prove useful:

debug h225 asn1

debug ras

debug gatekeeper main 10

Hope this helps,

Ariel.

From: cisco-voip-bounces at puck.nether.net [
mailto:cisco-voip-bounces at puck.nether.net] On Behalf Of Anthony
Kouloglou
Sent: viernes, 11 de noviembre de 2011 12:15 p.m.
To: cisco-voip at puck-nether.net
Subject: [cisco-voip] H323 Voip Call Connected for 5 sec and then drops

Hi all,
i really need your help before i go crazy.
I have never seen a call connected and talk (both dirextions)  for 5
secs and then disconnect!!
I have seen calls not being able to initiate or one way audio or no
audio but not this!!

The call flow is: A calls a destination in B

A(PBX with E1/PRI)
--->2800-----------------voip------------>2900---->B(PBX with E1/Pri) B.

2800 discovers 2900 dial plan with ras command (gatekeeper controlled
both).
I would be searching for misconfigurations in translation rules and all
these but the call SUCCEEDS initially, so i guess it is OK.
I can see Transfer number is Null but i can't tell why.

Also, i have tried to set progress_ind setup enable 3 (in the pots
dial-peer from 2900 to PBX (B)) but no luck!
The same problem.

Keep in mind, that i have NO access to 2800: it is a TSP with the same
config for everyone else.

Here is the debug i got (ccapi voip and q931):

Nov 11 13:03:39.539:
//-1/9C287DE9AAC7/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   cisco-username=gw-2811 at XXX.gr
   ----- ccCallInfo IE subfields -----
   cisco-ani=2107275672
   cisco-anitype=0
   cisco-aniplan=1
   cisco-anipi=0
   cisco-anisi=0
   dest=2321049160
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   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

Nov 11 13:03:39.539:
//-1/9C287DE9AAC7/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x2AF60854, Call Info(
   Calling Number=2107275672,(Calling Name=)(TON=Unknown, NPI=ISDN,
Screening=Not Screened, Presentation=Allowed),
   Called Number=2321049160(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=Unknown,
FinalDestinationFlag=TRUE,
   Incoming Dial-peer=21, Progress Indication=ORIGINATING SIDE IS NON
ISDN(3), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID
Transparent=FALSE), Call Id=103
Nov 11 13:03:39.539: //-1/9C287DE9AAC7/CCAPI/ccCheckClipClir:
   In: Calling Number=2107275672(TON=Unknown, NPI=ISDN, Screening=Not
Screened, Presentation=Allowed)
Nov 11 13:03:39.539: //-1/9C287DE9AAC7/CCAPI/ccCheckClipClir:
   Out: Calling Number=2107275672(TON=Unknown, NPI=ISDN, Screening=Not
Screened, Presentation=Allowed)
Nov 11 13:03:39.539: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 11 13:03:39.539: :cc_get_feature_vsa malloc success
Nov 11 13:03:39.539: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 11 13:03:39.539:  cc_get_feature_vsa count is 1
Nov 11 13:03:39.539: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 11 13:03:39.539: :FEATURE_VSA attributes are:
feature_name:0,feature_time:836178384,feature_id:102
Nov 11 13:03:39.539:
//103/9C287DE9AAC7/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=2107275672(TON=Unknown, NPI=ISDN,
Screening=Not Screened, Presentation=Allowed),
   Called Number=2321049160(TON=Unknown, NPI=Unknown))
Nov 11 13:03:39.539: //103/9C287DE9AAC7/CCAPI/cc_process_call_setup_ind:
   Event=0x31809038
Nov 11 13:03:39.539: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Try with the demoted called number 2321049160
Nov 11 13:03:39.539: //103/9C287DE9AAC7/CCAPI/ccCallSetContext:
   Context=0x2A68E544
Nov 11 13:03:39.539: //103/9C287DE9AAC7/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 103 with tag 21 to app
"_ManagedAppProcess_Default"
Nov 11 13:03:39.539: //103/9C287DE9AAC7/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
Nov 11 13:03:39.543: //103/9C287DE9AAC7/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=TRUE, Mode=0,
   Outgoing Dial-peer=23210491, Params=0x2A69723C, Progress
Indication=ORIGINATING SIDE IS NON ISDN(3)
Nov 11 13:03:39.543: //103/9C287DE9AAC7/CCAPI/ccCheckClipClir:
   In: Calling Number=2107275672(TON=Unknown, NPI=ISDN, Screening=Not
Screened, Presentation=Allowed)
Nov 11 13:03:39.543: //103/9C287DE9AAC7/CCAPI/ccCheckClipClir:
   Out: Calling Number=2107275672(TON=Unknown, NPI=ISDN, Screening=Not
Screened, Presentation=Allowed)
Nov 11 13:03:39.543: //103/9C287DE9AAC7/CCAPI/ccCallSetupRequest:
   Destination Pattern=23210491.., Called Number=2321049160, Digit
Strip=TRUE
Nov 11 13:03:39.543: //103/9C287DE9AAC7/CCAPI/ccCallSetupRequest:
   Calling Number=2107275672(TON=Unknown, NPI=ISDN, Screening=Not
Screened, Presentation=Allowed),
   Called Number=2321049160(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=
   Account Number=gw-2811 at XXX.gr, Final Destination Flag=TRUE,
   Guid=9C287DE9-0B8B-11E1-AAC7-0013C3996140, Outgoing
Dial-peer=23210491
Nov 11 13:03:39.543:
//103/9C287DE9AAC7/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=gw-2811 at XXX.gr
   ----- ccCallInfo IE subfields -----
   cisco-ani=2107275672
   cisco-anitype=0
   cisco-aniplan=1
   cisco-anipi=0
   cisco-anisi=0
   dest=2321049160
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   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

Nov 11 13:03:39.543:
//103/9C287DE9AAC7/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x3183EBD8, Interface Type=6, Destination=, Mode=0x0,
   Call Params(Calling Number=2107275672,(Calling Name=)(TON=Unknown,
NPI=ISDN, Screening=Not Screened, Presentation=Allowed),
   Called Number=2321049160(TON=Unknown, NPI=Unknown), Calling
Translated=FALSE,
   Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE, Outgoing
Dial-peer=23210491, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=,
tg_label_flag=0, Application Call Id=)
Nov 11 13:03:39.543: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 11 13:03:39.543: :cc_get_feature_vsa malloc success
Nov 11 13:03:39.543: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 11 13:03:39.543:  cc_get_feature_vsa count is 2
Nov 11 13:03:39.543: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Nov 11 13:03:39.543: :FEATURE_VSA attributes are:
feature_name:0,feature_time:836178832,feature_id:103
Nov 11 13:03:39.543:
//104/9C287DE9AAC7/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
Nov 11 13:03:39.543: //104/9C287DE9AAC7/CCAPI/ccCallSetContext:
   Context=0x2A6971EC
Nov 11 13:03:39.543: //103/9C287DE9AAC7/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=23210491
Nov 11 13:03:39.547: ISDN Se0/0/0:15 Q931: Applying typeplan for sw-type
0x12 is 0x0 0x1, Calling num 2107275672
Nov 11 13:03:39.547: ISDN Se0/0/0:15 Q931: Sending SETUP  callref =
0x009D callID = 0x801E switch = primary-net5 interface = Network 
Nov 11 13:03:39.547: ISDN Se0/0/0:15 Q931: TX -> SETUP pd = 8  callref =
0x009D 
        Bearer Capability i = 0x9090A3 
                Standard = CCITT 
                Transfer Capability = 3.1kHz Audio 
                Transfer Mode = Circuit 
                Transfer Rate = 64 kbit/s 
        Channel ID i = 0xA98381 
                Exclusive, Channel 1 
        Progress Ind i = 0x8183 - Origination address is non-ISDN  
        Calling Party Number i = 0x0180, '2107275672' 
                Plan:ISDN, Type:Unknown 
        Called Party Number i = 0x80, '160' 
                Plan:Unknown, Type:Unknown
Nov 11 13:03:39.683: ISDN Se0/0/0:15 Q931: RX <- SETUP_ACK pd = 8
callref = 0x809D
Nov 11 13:03:39.859: ISDN Se0/0/0:15 Q931: RX <- CALL_PROC pd = 8
callref = 0x809D
Nov 11 13:03:39.859: //104/9C287DE9AAC7/CCAPI/cc_api_call_proceeding:
   Interface=0x3183EBD8, Progress Indication=NULL(0)
Nov 11 13:03:39.871: ISDN Se0/0/0:15 Q931: RX <- ALERTING pd = 8
callref = 0x809D
Nov 11 13:03:39.871: //104/9C287DE9AAC7/CCAPI/cc_api_call_alert:
   Interface=0x3183EBD8, Progress Indication=NULL(0), Signal
Indication=NOT PRESENT(255)
Nov 11 13:03:39.871: //104/9C287DE9AAC7/CCAPI/cc_api_call_alert:
   Call Entry(Retry Count=0, Responsed=TRUE)
Nov 11 13:03:39.871: //103/9C287DE9AAC7/CCAPI/ccCallAlert:
   Progress Indication=NULL(0), Signal Indication=NOT PRESENT(255)
Nov 11 13:03:39.871: //103/9C287DE9AAC7/CCAPI/ccCallAlert:
   Call Entry(Responsed=TRUE, Alert Sent=TRUE)
Nov 11 13:03:39.871:
//104/9C287DE9AAC7/CCAPI/cc_api_get_called_ccm_detected:
   CallInfo(ccm detected=0)
Nov 11 13:03:39.871: //103/9C287DE9AAC7/CCAPI/ccCallNotify:
   Data Bitmask=0x7, Call Id=103
Nov 11 13:03:39.871:
//104/9C287DE9AAC7/CCAPI/cc_api_get_called_ccm_detected:
   CallInfo(ccm detected=0)
Nov 11 13:03:39.871: //103/9C287DE9AAC7/CCAPI/cc_api_get_delay_xport:
   CallInfo(delay xport=FALSE)
Nov 11 13:03:46.043: ISDN Se0/0/0:15 Q931: RX <- CONNECT pd = 8  callref
= 0x809D 
        Progress Ind i = 0x8182 - Destination address is non-ISDN  
        Connected Number i = 0x0180, '49160'
Nov 11 13:03:46.043: %ISDN-6-CONNECT: Interface Serial0/0/0:0 is now
connected to 160 N/A
Nov 11 13:03:46.043: ISDN Se0/0/0:15 Q931: TX -> CONNECT_ACK pd = 8
callref = 0x009D
Nov 11 13:03:46.043: //104/9C287DE9AAC7/CCAPI/cc_api_call_connected:
   Interface=0x3183EBD8, Data Bitmask=0x1, Progress
Indication=DESTINATION IS NON ISDN(2),
   Connection Handle=0
Nov 11 13:03:46.043: //104/9C287DE9AAC7/CCAPI/cc_api_call_connected:
   Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/ccConferenceCreate:
   (confID=0x2A6C8EB4, callID1=0x67, gcid=0-0-0-0, tag=0x0)
Nov 11 13:03:46.047: //104/9C287DE9AAC7/CCAPI/ccConferenceCreate:
   (confID=0x2A6C8EB4, callID2=0x68, gcid=0-0-0-0, tag=0x0)
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/ccConferenceCreate:
   Conference Id=0x2A6C8EB4, Call Id1=103, Call Id2=104, Tag=0x0
Nov 11 13:03:46.047: //103/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

Nov 11 13:03:46.047: cc_api_get_xcode_stream : 4702
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/cc_api_bridge_done:
   Conference Id=0x19, Source Interface=0x2AF60854, Source Call Id=103,
   Destination Call Id=104, Disposition=0x0, Tag=0x0
Nov 11 13:03:46.047: //104/9C287DE9AAC7/CCAPI/cc_api_bridge_done:
   Conference Id=0x19, Source Interface=0x3183EBD8, Source Call Id=104,
   Destination Call Id=103, Disposition=0x0, Tag=0xFFFFFFFF
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/cc_generic_bridge_done:
   Conference Id=0x19, Source Interface=0x3183EBD8, Source Call Id=104,
   Destination Call Id=103, Disposition=0x0, Tag=0xFFFFFFFF
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x19, Destination Call Id=104)
Nov 11 13:03:46.047: //104/9C287DE9AAC7/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x19, Destination Call Id=103)
Nov 11 13:03:46.047: //104/9C287DE9AAC7/CCAPI/cc_api_caps_ind:
   Destination Interface=0x2AF60854, Destination Call Id=103, Source
Call Id=104,
   Caps(Codec=0x1, Fax Rate=0x1, Vad=0x1,
   Modem=0x2, Codec Bytes=20, Signal Type=3)
Nov 11 13:03:46.047: //104/9C287DE9AAC7/CCAPI/cc_api_caps_ind:
   Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
   Playout Max=1000(ms), Fax Nom=300(ms))
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/ccCallConnect:
   Progress Indication=DESTINATION IS NON ISDN(2), Data Bitmask=0x1
Nov 11 13:03:46.047:
//104/9C287DE9AAC7/CCAPI/cc_api_get_called_ccm_detected:
   CallInfo(ccm detected=0)
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/ccCallConnect:
   Call Entry(Connected=TRUE, Responsed=TRUE)
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/ccCallNotify:
   Data Bitmask=0x7, Call Id=103
Nov 11 13:03:46.047:
//104/9C287DE9AAC7/CCAPI/cc_api_get_called_ccm_detected:
   CallInfo(ccm detected=0)
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/cc_api_caps_ind:
   Destination Interface=0x3183EBD8, Destination Call Id=104, Source
Call Id=103,
   Caps(Codec=0x4, Fax Rate=0x1, Vad=0x1,
   Modem=0x2, Codec Bytes=20, Signal Type=2)
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/cc_api_caps_ind:
   Caps(Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms),
   Playout Max=1000(ms), Fax Nom=300(ms))
Nov 11 13:03:46.047: //103/9C287DE9AAC7/CCAPI/cc_api_caps_ack:
   Destination Interface=0x3183EBD8, Destination Call Id=104, Source
Call Id=103,
   Caps(Codec=g729r8(0x4), Fax Rate=FAX_RATE_NONE(0x1), Vad=OFF(0x1),
   Modem=ON(0x2), Codec Bytes=20, Signal Type=2, Seq Num Start=6330)
Nov 11 13:03:46.051: //104/9C287DE9AAC7/CCAPI/cc_api_caps_ack:
   Destination Interface=0x2AF60854, Destination Call Id=103, Source
Call Id=104,
   Caps(Codec=g729r8(0x4), Fax Rate=FAX_RATE_NONE(0x1), Vad=OFF(0x1),
   Modem=ON(0x2), Codec Bytes=20, Signal Type=2, Seq Num Start=6330)
Nov 11 13:03:46.051:
//103/9C287DE9AAC7/CCAPI/cc_process_notify_bridge_done:
   Conference Id=0x19, Call Id1=103, Call Id2=104
Nov 11 13:03:46.051: //104/9C287DE9AAC7/CCAPI/cc_api_voice_mode_event:
   Call Id=104
Nov 11 13:03:46.051: //104/9C287DE9AAC7/CCAPI/cc_api_voice_mode_event:
   Call Entry(Context=0x2A6971EC)

 Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/cc_api_call_disconnected:
   Cause Value=41, Interface=0x2AF60854, Call Id=103
Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=41, Retry Count=0)
Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/ccConferenceDestroy:
   Conference Id=0x19, Tag=0x0
Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x19, Source Interface=0x2AF60854, Source Call Id=103,
   Destination Call Id=104, Disposition=0x0, Tag=0x0
Nov 11 13:03:51.075: //104/9C287DE9AAC7/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x19, Source Interface=0x3183EBD8, Source Call Id=104,
   Destination Call Id=103, Disposition=0x0, Tag=0x0
Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/cc_generic_bridge_done:
   Conference Id=0x19, Source Interface=0x3183EBD8, Source Call Id=104,
   Destination Call Id=103, Disposition=0x0, Tag=0x0
Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/ccCallDisconnect:
   Cause Value=41, Tag=0x0, Call Entry(Previous Disconnect Cause=0,
Disconnect Cause=41)
Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/ccCallDisconnect:
   Cause Value=41, Call Entry(Responsed=TRUE, Cause Value=41)
Nov 11 13:03:51.075: //103/9C287DE9AAC7/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
Nov 11 13:03:51.075: //104/9C287DE9AAC7/CCAPI/ccCallDisconnect:
   Cause Value=41, Tag=0x0, Call Entry(Previous Disconnect Cause=0,
Disconnect Cause=0)
Nov 11 13:03:51.075: //104/9C287DE9AAC7/CCAPI/ccCallDisconnect:
   Cause Value=41, Call Entry(Responsed=TRUE, Cause Value=41)
Nov 11 13:03:51.075: //104/9C287DE9AAC7/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
Nov 11 13:03:51.087: //103/9C287DE9AAC7/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
Nov 11 13:03:51.087:
//103/9C287DE9AAC7/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x2AF60854, Tag=0x0, Call Id=103,
   Call Entry(Disconnect Cause=41, Voice Class Cause Code=0, Retry
Count=0)
Nov 11 13:03:51.087:
//103/9C287DE9AAC7/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
Nov 11 13:03:51.087: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Nov 11 13:03:51.087: :cc_free_feature_vsa freeing 31D711C8
Nov 11 13:03:51.087: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Nov 11 13:03:51.087:  vsacount in free is 1
Nov 11 13:03:51.099: %ISDN-6-DISCONNECT: Interface Serial0/0/0:0
disconnected from 160 , call lasted 5 seconds
Nov 11 13:03:51.099: ISDN Se0/0/0:15 Q931: TX -> DISCONNECT pd = 8
callref = 0x009D 
        Cause i = 0x82A9 - Temporary failure

BR
Anthony 

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20111111/d077f8b2/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Understanding and Troubleshooting Gatekeeper TTL and Aging out Process (gk_time2live).pdf
Type: application/octet-stream
Size: 15801 bytes
Desc: Understanding and Troubleshooting Gatekeeper TTL and Aging out Process (gk_time2live).pdf
URL: <https://puck.nether.net/pipermail/cisco-voip/attachments/20111111/d077f8b2/attachment.obj>