Call drops after 25-30 seconds exactly - Need some help CCIE guys!

[Cesar Ortega]

Hello guys,

I've call dropping problems when dialing an external number from my VoIP network. Called number is a 0800 and it's answer by an IVR, with other called numbers everything works (hold, for example).

My issue is just with 0800 numbers!

ccCallDisconnect:

Cause Value=41, Call Entry(Disconnect Cause=0)

DEBUG VOIP CCAPI ALL gives:

SAE-CCS-DEFENSE-RTC-EXPE#
Aug 20 16:59:29.626: //-1/xxxxxxxxxxxx/CCAPI/cc_api_supported_data:
   data_mode=0x10082
Aug 20 16:59:29.630: //857/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found
Aug 20 16:59:29.634: //857/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found
Aug 20 16:59:29.634: //-1/002128B70800/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   cisco-username=22.255.31.27
   ----- ccCallInfo IE subfields -----
   cisco-ani=155238470
   cisco-anitype=0
   cisco-aniplan=1
   cisco-anipi=1
   cisco-anisi=1
   dest=0820346020
   cisco-desttype=0
   cisco-destplan=0
   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 20 16:59:29.638: //-1/002128B70800/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x49F63A88, Call Info(
   Calling Number=155238470,(Calling Name=)(TON=Unknown, NPI=ISDN, Screening=User, Passed, Presentation=Restricted),
   Called Number=0820346020(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE,
   Incoming Dial-peer=0, Progress Indication=NULL(0), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=857
Aug 20 16:59:29.638: //-1/002128B70800/CCAPI/cc_api_call_setup_ind_common:
   Interface Type=0, Protocol=1
Aug 20 16:59:29.638: //-1/002128B70800/CCAPI/cc_api_call_setup_ind_common:
   After Number Translation Checking:
   Calling Number=155238470(TON=Unknown, NPI=ISDN, Screening=User, Passed, Presentation=Restricted),
   Called Number=0820346020(TON=Unknown, NPI=Unknown)
Aug 20 16:59:29.638: //857/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=0, Call Entry(Call Count On=FALSE, Incoming Call=TRUE)
Aug 20 16:59:29.638: //857/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=1
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 20 16:59:29.638: :cc_get_feature_vsa malloc success
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 20 16:59:29.638:  cc_get_feature_vsa count is 1
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 20 16:59:29.638: :FEATURE_VSA attributes are: feature_name:0,feature_time:1206488552,feature_id:635
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_init_call_entry:

Aug 20 16:59:29.638:  call_init_entry calle is 47DCA560,callid is 857
Aug 20 16:59:29.638: //857/002128B70800/CCAPI/cc_insert_guid_pod_entry:
   Incoming=TRUE, Call Id=857
Aug 20 16:59:29.638: //857/002128B70800/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=155238470(TON=Unknown, NPI=ISDN, Screening=User, Passed, Presentation=Restricted),
   Called Number=0820346020(TON=Unknown, NPI=Unknown))
Aug 20 16:59:29.638: //857/002128B70800/CCAPI/cc_incr_if_call_volume:
   Remote IP Address=22.255.31.27, Hwidb=GigabitEthernet0/0
Aug 20 16:59:29.638: //857/002128B70800/CCAPI/cc_incr_if_call_volume:
   Total Call Count=1, Voip Call Count=1, MMoip Call Count=0
Aug 20 16:59:29.638: //857/002128B70800/CCAPI/cc_process_call_setup_ind:
   Event=0x50ACEFE8
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_registration_lookup:
   Matching Parameters; Called Number=0820346020, Call Transfer Consult Id=
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Searching Node;
   Called Number=0820346020, Call Transfer Consult Id=
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_compare:

Aug 20 16:59:29.638: Comparing SSOpCode; 0x50 and 0x0
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_compare:

Aug 20 16:59:29.638: Comparing SSOpCode; 0x12 and 0x0
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Try with the demoted called number 0820346020
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_compare:

Aug 20 16:59:29.638: Comparing SSOpCode; 0x50 and 0x0
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_compare:

Aug 20 16:59:29.638: Comparing SSOpCode; 0x12 and 0x0
Aug 20 16:59:29.638: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_registration_lookup:
   No Matching Node
Aug 20 16:59:29.642: //-1/xxxxxxxxxxxx/CCAPI/ccAppInitializePID:
   Application Process Name=_ManagedAppProcess_Default, Application Process Id=149, Application Handle=0x47DD1360
Aug 20 16:59:29.642: //857/002128B70800/CCAPI/ccCallSetContext:
   Context=0x47DE74A0
Aug 20 16:59:29.642: //857/002128B70800/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 857 with tag 0 to app "_ManagedAppProcess_Default"
Aug 20 16:59:29.642: //-1/xxxxxxxxxxxx/CCAPI/ccAppInitialize:
   Application Name=_ManagedAppProcess_Default, Application Process Id=149, Application Handle=0x4A934A28
Aug 20 16:59:29.642: //857/002128B70800/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=TRUE, Mode=0,
   Outgoing Dial-peer=1, Params=0x47DE9B00, Progress Indication=NULL(0)
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCallSetupRequest:
   Outgoing Dial-peer(Tag=1, Trunk Group List=0x50945710)
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/cc_fill_tg_params:
   Not a cic call
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCallSetupRequest:
   Params(Target Trkgrp Route Label=PSTN-IN, tg_label_flag=TRUE)
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCallSetupRequest:
   Trunk Group Select Interface Success;
   Interface=0x50B13190, Selected Interface=1, Selected DSL=0
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCheckClipClir:
   In: Calling Number=155238470(TON=Unknown, NPI=ISDN, Screening=User, Passed, Presentation=Restricted)
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCheckClipClir:
   Calling Party Number Is User Provided
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCheckClipClir:
   Out: Calling Number=155238470(TON=Unknown, NPI=ISDN, Screening=User, Passed, Presentation=Restricted)
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCallSetupRequest:
   Destination Pattern=0T, Called Number=0820346020, Digit Strip=TRUE
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/ccCallSetupRequest:
   Calling Number=155238470(TON=Unknown, NPI=ISDN, Screening=User, Passed, Presentation=Restricted),
   Called Number=0820346020(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=
   Account Number=22.255.31.27, Final Destination Flag=TRUE,
   Guid=002128B7-F350-2103-0800-6002160A0B89, Outgoing Dial-peer=1
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=22.255.31.27
   ----- ccCallInfo IE subfields -----
   cisco-ani=155238470
   cisco-anitype=0
   cisco-aniplan=1
   cisco-anipi=1
   cisco-anisi=1
   dest=0820346020
   cisco-desttype=0
   cisco-destplan=0
   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 20 16:59:29.646: //857/002128B70800/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x50B13190, Interface Type=6, Destination=, Mode=0x0,
   Call Params(Calling Number=155238470,(Calling Name=)(TON=Unknown, NPI=ISDN, Screening=User, Passed, Presentation=Restricted),
   Called Number=0820346020(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=Unknown, FinalDestinationFlag=TRUE, Outgoing Dial-peer=1, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=PSTN-IN, tg_label_flag=2, Application Call Id=)
Aug 20 16:59:29.646: //858/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry:
   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)
Aug 20 16:59:29.646: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 20 16:59:29.646: :cc_get_feature_vsa malloc success
Aug 20 16:59:29.646: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 20 16:59:29.646:  cc_get_feature_vsa count is 2
Aug 20 16:59:29.646: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

Aug 20 16:59:29.646: :FEATURE_VSA attributes are: feature_name:0,feature_time:1206488328,feature_id:636
Aug 20 16:59:29.646: //-1/xxxxxxxxxxxx/CCAPI/cc_init_call_entry:

Aug 20 16:59:29.646:  call_init_entry calle is 47DCBD10,callid is 858
Aug 20 16:59:29.646: //857/002128B70800/CCAPI/cc_peer_bind:
   Bind=TRUE, Binder Call Id=857, Bindee Call Id=858
Aug 20 16:59:29.646: //858/002128B70800/CCAPI/cc_insert_guid_pod_entry:
   Incoming=FALSE, Call Id=858
Aug 20 16:59:29.646: //858/002128B70800/CCAPI/cc_set_voice_port_value:
   CC_IF_TELEPHONY: Echo=0, Playout=0
Aug 20 16:59:29.650: //858/002128B70800/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
Aug 20 16:59:29.650: //857/002128B70800/CCAPI/ccCallSetupRequest:
   Trunk Group Call Setting;
   Call Entry(Retry Count=0, Voice Class Cause Code=0)
Aug 20 16:59:29.650: //857/002128B70800/CCAPI/ccCallSetupRequest:exit@2521
Aug 20 16:59:29.650: //858/002128B70800/CCAPI/ccCallSetContext:
   Context=0x47DE9AB0
Aug 20 16:59:29.650: //857/002128B70800/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=1
Aug 20 16:59:29.650: //857/002128B70800/CCAPI/cc_api_modify_tgt_cid_call_active_record:
   Target Trkgrp Route Label=PSTN-IN, tg_label_flag=TRUE, Call Id=0x359
Aug 20 16:59:30.090: //858/002128B70800/CCAPI/cc_api_call_proceeding:
   Interface=0x50B13190, Progress Indication=NULL(0)
Aug 20 16:59:30.090: //858/002128B70800/CCAPI/cc_api_call_proceeding:exit@7008
Aug 20 16:59:30.854: //858/002128B70800/CCAPI/cc_api_call_cut_progress:
   Interface=0x50B13190, Progress Indication=DESTINATION IS NON ISDN(2), Signal Indication=INTERCEPT(2),
   Cause Value=0
Aug 20 16:59:30.854: //858/002128B70800/CCAPI/cc_api_call_cut_progress:
   Call Entry(Responsed=TRUE)
Aug 20 16:59:30.854: //857/002128B70800/CCAPI/ccCallCutProgress:
   Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2), Cause Value=0
   Voice Call Send Alert=FALSE, Call Entry(Alert Sent=FALSE)
Aug 20 16:59:30.854: //857/002128B70800/CCAPI/ccCallCutProgress:
   Call Entry(Responsed=TRUE)
Aug 20 16:59:30.854: //858/002128B70800/CCAPI/cc_api_get_called_ccm_detected:
   CallInfo(ccm detected=0)
Aug 20 16:59:30.854: //857/xxxxxxxxxxxx/CCAPI/ccConferenceCreate:
   (confID=0x51EAE788, callID1=0x359, callID2=0x35A, tag=0x0)
Aug 20 16:59:30.854: //857/xxxxxxxxxxxx/CCAPI/ccConferenceCreate:
   (confID=0x51EAE788, callID1=0x359, gcid=0-0-0-0, tag=0x0)
Aug 20 16:59:30.854: //858/xxxxxxxxxxxx/CCAPI/ccConferenceCreate:
   (confID=0x51EAE788, callID2=0x35A, gcid=0-0-0-0, tag=0x0)
Aug 20 16:59:30.854: //857/002128B70800/CCAPI/ccConferenceCreate:
   Conference Id=0x51EAE788, Call Id1=857, Call Id2=858, Tag=0x0
Aug 20 16:59:30.854: //857/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

Aug 20 16:59:30.854: cc_api_get_xcode_stream : 4534
Aug 20 16:59:30.854: //857/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:
   Conference Id=0x106, Source Interface=0x49F63A88, Source Call Id=857,
   Destination Call Id=858, Disposition=0x0, Tag=0x0
Aug 20 16:59:30.854: //858/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done:
   Conference Id=0x106, Source Interface=0x50B13190, Source Call Id=858,
   Destination Call Id=857, Disposition=0x0, Tag=0xFFFFFFFF
Aug 20 16:59:30.854: //857/002128B70800/CCAPI/cc_generic_bridge_done:
   Conference Id=0x106, Source Interface=0x50B13190, Source Call Id=858,
   Destination Call Id=857, Disposition=0x0, Tag=0xFFFFFFFF
Aug 20 16:59:30.854: //857/002128B70800/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x106, Destination Call Id=858)
Aug 20 16:59:30.854: //858/002128B70800/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0x106, Destination Call Id=857)
Aug 20 16:59:30.854: //858/002128B70800/CCAPI/cc_api_caps_ind:
   Destination Interface=0x49F63A88, Destination Call Id=857, Source Call Id=858,
   Caps(Codec=0x1, Fax Rate=0x1, Vad=0x1,
   Modem=0x2, Codec Bytes=20, Signal Type=3)
Aug 20 16:59:30.854: //858/002128B70800/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))
Aug 20 16:59:30.858: //857/002128B70800/CCAPI/cc_process_notify_bridge_done:
   Conference Id=0x106, Call Id1=857, Call Id2=858
Aug 20 16:59:32.902: //857/002128B70800/CCAPI/cc_api_caps_ind:
   Destination Interface=0x50B13190, Destination Call Id=858, Source Call Id=857,
   Caps(Codec=0x1, Fax Rate=0x2, Vad=0x1,
   Modem=0x0, Codec Bytes=160, Signal Type=2)
Aug 20 16:59:32.902: //857/002128B70800/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))
Aug 20 16:59:32.902: //857/002128B70800/CCAPI/cc_api_caps_ack:
   Destination Interface=0x50B13190, Destination Call Id=858, Source Call Id=857,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=1173)
Aug 20 16:59:32.902: //857/002128B70800/CCAPI/cc_api_caps_ind:
   Destination Interface=0x50B13190, Destination Call Id=858, Source Call Id=857,
   Caps(Codec=0x1, Fax Rate=0x2, Vad=0x1,
   Modem=0x0, Codec Bytes=160, Signal Type=2)
Aug 20 16:59:32.902: //857/002128B70800/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))
Aug 20 16:59:32.902: //857/002128B70800/CCAPI/cc_api_caps_ack:
   Destination Interface=0x50B13190, Destination Call Id=858, Source Call Id=857,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=1173)
Aug 20 16:59:32.902: //858/002128B70800/CCAPI/cc_api_caps_ack:
   Destination Interface=0x49F63A88, Destination Call Id=857, Source Call Id=858,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=1173)
Aug 20 16:59:32.902: //858/002128B70800/CCAPI/cc_api_caps_ack:
   Destination Interface=0x49F63A88, Destination Call Id=857, Source Call Id=858,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=1173)
Aug 20 16:59:32.902: //858/002128B70800/CCAPI/cc_api_voice_mode_event:
   Call Id=858
Aug 20 16:59:32.906: //858/002128B70800/CCAPI/cc_api_voice_mode_event:
   Call Entry(Context=0x47DE9AB0)
Aug 20 16:59:32.906: //858/002128B70800/CCAPI/cc_api_voice_mode_event:
   Call Id=858
Aug 20 16:59:32.906: //858/002128B70800/CCAPI/cc_api_voice_mode_event:
   Call Entry(Context=0x47DE9AB0)
Aug 20 16:59:32.906: //857/002128B70800/CCAPI/cc_api_caps_ind:
   Destination Interface=0x50B13190, Destination Call Id=858, Source Call Id=857,
   Caps(Codec=0x1, Fax Rate=0x2, Vad=0x1,
   Modem=0x0, Codec Bytes=160, Signal Type=2)
Aug 20 16:59:32.906: //857/002128B70800/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))
Aug 20 16:59:32.906: //857/002128B70800/CCAPI/cc_api_caps_ack:
   Destination Interface=0x50B13190, Destination Call Id=858, Source Call Id=857,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=1173)
Aug 20 16:59:32.906: //858/002128B70800/CCAPI/cc_api_caps_ack:
   Destination Interface=0x49F63A88, Destination Call Id=857, Source Call Id=858,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Vad=OFF(0x1),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=1173)
Aug 20 16:59:32.910: //858/002128B70800/CCAPI/cc_api_voice_mode_event:
   Call Id=858
Aug 20 16:59:32.910: //858/002128B70800/CCAPI/cc_api_voice_mode_event:
   Call Entry(Context=0x47DE9AB0)
Aug 20 16:59:46.726: //858/002128B70800/CCAPI/cc_api_call_connected:
   Interface=0x50B13190, Data Bitmask=0x1, Progress Indication=NULL(0),
   Connection Handle=0
Aug 20 16:59:46.726: //858/002128B70800/CCAPI/cc_api_call_connected:
   Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
Aug 20 16:59:46.726: //858/002128B70800/CCAPI/cc_api_call_connected:exit@5772
Aug 20 16:59:46.730: //857/002128B70800/CCAPI/ccCallConnect:
   Progress Indication=INBAND(8), Data Bitmask=0x1
Aug 20 16:59:46.730: //858/002128B70800/CCAPI/cc_api_get_called_ccm_detected:
   CallInfo(ccm detected=0)
Aug 20 16:59:46.730: //857/002128B70800/CCAPI/ccCallConnect:
   Call Entry(Connected=TRUE, Responsed=TRUE)
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/cc_api_call_disconnected:
   Cause Value=41, Interface=0x49F63A88, Call Id=857
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=41, Retry Count=0)
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/ccConferenceDestroy:
   Conference Id=0x106, Tag=0x0
Aug 20 16:59:58.731: //-1/xxxxxxxxxxxx/CCAPI/ccConferenceDestroy:
   CALL_ERROR_INFORMATIONAL; mute call detection failed with confID=0x106
Aug 20 16:59:58.731: //857/xxxxxxxxxxxx/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x106, Source Interface=0x49F63A88, Source Call Id=857,
   Destination Call Id=858, Disposition=0x0, Tag=0x0
Aug 20 16:59:58.731: //858/xxxxxxxxxxxx/CCAPI/cc_api_bridge_drop_done:
   Conference Id=0x106, Source Interface=0x50B13190, Source Call Id=858,
   Destination Call Id=857, Disposition=0x0, Tag=0x0
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/cc_generic_bridge_done:
   Conference Id=0x106, Source Interface=0x50B13190, Source Call Id=858,
   Destination Call Id=857, Disposition=0x0, Tag=0x0
Aug 20 16:59:58.731: //-1/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   CALL_ERROR_INFORMATIONAL; Call Id Is Invalid=-1
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/ccCallDisconnect:
   Cause Value=41, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=41)
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/ccCallDisconnect:
   Start Calling Accounting;
   Call Entry(Incoming=TRUE)
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/ccCallDisconnect:
   Cause Value=41, Call Entry(Disconnect Cause=41)
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/ccCallDisconnect:
   Call Entry(Disconnect Cause=41)
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/ccCallDisconnect:
   Cause Value=41, Call Entry(Responsed=TRUE, Cause Value=41)
Aug 20 16:59:58.731: //857/002128B70800/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
Aug 20 16:59:58.731: //-1/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   CALL_ERROR_INFORMATIONAL; Call Id Is Invalid=-1
Aug 20 16:59:58.731: //858/002128B70800/CCAPI/ccCallDisconnect:
   Cause Value=41, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
Aug 20 16:59:58.731: //858/002128B70800/CCAPI/ccCallDisconnect:
   Start Calling Accounting;
   Call Entry(Incoming=FALSE)
Aug 20 16:59:58.731: //858/002128B70800/CCAPI/ccCallDisconnect:
   Cause Value=41, Call Entry(Disconnect Cause=0)
Aug 20 16:59:58.731: //858/002128B70800/CCAPI/ccCallDisconnect:
   Cause Value=41, Call Entry(Responsed=TRUE, Cause Value=41)
Aug 20 16:59:58.731: //858/002128B70800/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
Aug 20 16:59:58.739: //857/002128B70800/CCAPI/cc_api_get_transfer_info:
   Transfer Number Is Null
Aug 20 16:59:58.739: //-1/xxxxxxxxxxxx/CCAPI/cc_api_icpif:
   ExpectFactor=0xA
Aug 20 16:59:58.739: //857/002128B70800/CCAPI/cc_decr_if_call_volume:
   Remote IP Address=22.255.31.27, Hwidb=GigabitEthernet0/0
Aug 20 16:59:58.739: //857/002128B70800/CCAPI/cc_decr_if_call_volume:
   Total Call Count=0, Voip Call Count=0, MMoip Call Count=0
Aug 20 16:59:58.743: //857/002128B70800/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x49F63A88, Tag=0x0, Call Id=857,
   Call Entry(Disconnect Cause=41, Voice Class Cause Code=0, Retry Count=0)
Aug 20 16:59:58.743: //857/002128B70800/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
Aug 20 16:59:58.743: //857/002128B70800/CCAPI/cc_delete_guid_pod_entry:
   Incoming=TRUE
Aug 20 16:59:58.743: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Aug 20 16:59:58.743: :cc_free_feature_vsa freeing 47E98DE0
Aug 20 16:59:58.743: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Aug 20 16:59:58.743:  vsacount in free is 1
Aug 20 16:59:58.743: //857/002128B70800/CCAPI/cc_delete_call_entry:
   Total Call Count=1, Call Entry(Call Count On=FALSE, Incoming Call=TRUE)
Aug 20 16:59:58.743: //857/002128B70800/CCAPI/cc_delete_call_entry:
   Total Call Count=0
Aug 20 16:59:58.743: //857/002128B70800/CCAPI/cc_delete_call_entry:
   Deleting profileTable[0x51B703CC]
Aug 20 16:59:58.747: //0/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found
Aug 20 16:59:58.747: //0/xxxxxxxxxxxx/CCAPI/cc_api_call_preempt_done:
   CALL_ERROR_INFORMATIONAL; Call Entry Is Not Found
Aug 20 16:59:59.327: //858/002128B70800/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x50B13190, Tag=0x0, Call Id=858,
   Call Entry(Disconnect Cause=41, Voice Class Cause Code=0, Retry Count=0)
Aug 20 16:59:59.327: //858/002128B70800/CCAPI/cc_api_call_disconnect_done:
   tg for this call is PSTN-IN success/fail is 0
Aug 20 16:59:59.327: //858/002128B70800/CCAPI/cc_api_call_disconnect_done:
   Prefix Is Not Defined From Peer; Peer=1, Called Number=0820346020
Aug 20 16:59:59.327: //858/002128B70800/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
Aug 20 16:59:59.327: //858/002128B70800/CCAPI/cc_delete_guid_pod_entry:
   Incoming=FALSE
Aug 20 16:59:59.327: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Aug 20 16:59:59.327: :cc_free_feature_vsa freeing 47E98D00
Aug 20 16:59:59.331: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

Aug 20 16:59:59.331:  vsacount in free is 0
Aug 20 16:59:59.331: //858/002128B70800/CCAPI/cc_delete_call_entry:
   Total Call Count=0, Call Entry(Call Count On=FALSE, Incoming Call=FALSE)
Aug 20 16:59:59.331: //858/002128B70800/CCAPI/cc_delete_call_entry:
   Deleting profileTable[0x51B702DC]
Aug 20 16:59:59.331: //0/xxxxxxxxxxxx/CCAPI/cc_get_call_entry:
   Call Entry Is Not Found
Aug 20 16:59:59.331: //0/xxxxxxxxxxxx/CCAPI/cc_api_call_preempt_done:
   CALL_ERROR_INFORMATIONAL; Call Entry Is Not Found
SAE-CCS-DEFENSE-RTC-EXPE#undebu
SAE-CCS-DEFENSE-RTC-EXPE#undebug all
All possible debugging has been turned off
SAE-CCS-DEFENSE-RTC-EXPE#

"Media Termination Point Required" and "Wait for Far End H.245 Terminal Capability Set" are checked in the Call Manager (if unchecked, problem still the same).

ADDITIONAL INFORMATION:

SAE-CCS-DEFENSE-RTC-EXPE#sh h323 gateway cause-codes

CAUSE CODE STATISTICS AT 8w6d

     DISC CAUSE CODE        FROM OTHER PEER    FROM H323 PEER
   1 unassigned number (1)                3                 6
   3 no route to destinatio               5                 0
  16 normal call clearing (              66               194
  19 no user answer (19)                  0                 1
  27 destination out of ord               0                 9
  38 network out of order (               0                 2
  41 temporary failure (41)              79                 1
102 recovery on timer expi               2                 0

In my opinion my issues is related with mute and one time-out interval (maybe)...

Thanks in advance.

Alejandro

[brmeade]

Try putting "no vad" on your dial-peers.  You may have an issue with no RTP stream during mute causing the disconnect.  By turning off Voice Activity Detection, you will still send an RTP stream during a muted call.

[Cesar Ortega]

Hello Brian,

"no vad" was already configured in the dial-peers.

In the other hand, I solved my problem as follows:

Router(config)# ip rtcp report interval 5000

Router(config)# gateway

Router(config-gateway)# timer media-inactive 10

Router(config-gateway)# exit

The following example uses the ip rtcp report interval command to set the reporting interval to 5000 milliseconds, and then the timer media-inactive command to set the multiplication factor to 10. The result is that calls detected as inactive for 50 seconds (5,000 milliseconds times 10) will be disconnected.

EXPLANATION

When the timer media-inactive command is used, the gateway uses the inactivity timer as a combination of thetimer media-inactive command and the ip rtcp report interval command. The timer media-inactive command uses DSP statistics. This capability is based on the configuration of callfeature parameters using application command-line interface (CLI) to enable control.

The media are considered inactive only if there is no transfer of RTP packets in the send direction and no RTP packets in the receive direction. If RTP is present in either the send or receive direction, it is considered active. In this mode, DSP filters out any comfort noise packets, and the presence of any comfort noise packet is considered inactivity in either direction.

The multiple argument (or multiplication factor) is multiplied by the interval that is set using the ip rtcp report interval command. This command configures the average interval between successive RTCP report transmissions for a given voice session. For example, if the value argument is set to 25,000 milliseconds, an RTCP report is sent every 25 seconds, on average. If no RTP packets are received during the calculated interval, the call is disconnected. The gateway signals the disconnect to the VoIP network and the time-division multiplexing (TDM) network so that upstream and downstream devices can clear their resources.

Before doing that verify also in the Call Manager:

Devices > Gateway > MTP (has to be check)

source: http://www.cisco.com/en/US/docs/ios/voice/command/reference/vr_t2.html#wp1644723

[Ayodeji Okanlawon]

May I ask Cesar why do you have this command in the first place. Whta need does it address for you. If you dont need it then I suggest you remove it completely.

Please rate all useful posts

"'Nature is too thin a screen, the glory of the omnipresent God bursts through it everywhere"-Ralph Waldo Emerson

[Cesar Ortega]

Hello aokanlawon,

Sorry but I could not get you... what do you mean?

The explanation was posted. By default a voice gateway uses a 25 seconds timeout to disconnect a phone call when no RTP packets are transmitted.

"If no RTP packets are received during the calculated interval, the call is disconnected"

Interval is 25 seconds by default and I had this problem when calling 08XX numbers which are answers by IVR machines with messages longer than 25 seconds.

[Ayodeji Okanlawon]

The reason why I asked is that I have never come across such issue before and looking at the documentation, the default is that this is not enabled.. You can see the text "To reset to default, use the no form of this command" That suggests the default is that this is diabled and hence call should not be disconnected. I am just wondering if you had this command configured yourself as it is not enabled by default.

timer media-inactive

To enable the timer for media inactivity detection using the digital signal processor (DSP) (based on RTP as the only criterion) and to configure a multiplication factor based on the real-time control protocol (RTCP) timer interval, use the timer media-inactive command in gateway configuration mode. To reset to the default, use the no form of this command.

timer media-inactive multiple

no timer media-inactive multiple

Syntax Description

multiple

Multiples of the RTCP report transmission interval. Range is 4 to 1000. The default is 5, and the recommended value is 5.

Command Default

A call is considered inactive if no RTP packet activity is detected for a period of time calculated as five times the interval set by the ip rtcp report interval command.

Command Modes

Gateway configuration

Command History

Release	Modification
12.4(4)T	This command was introduced.

Usage Guidelines

When the timer media-inactive command is used, the gateway uses the inactivity timer as a combination of the timer media-inactive command and the ip rtcp report interval command. The timer media-inactive command uses DSP statistics. This capability is based on the configuration of callfeature parameters using application command-line interface (CLI) to enable control.

The media are considered inactive only if there is no transfer of RTP packets in the send direction and no RTP packets in the receive direction. If RTP is present in either the send or receive direction, it is considered active. In this mode, DSP filters out any comfort noise packets, and the presence of any comfort noise packet is considered inactivity in either direction.

The multiple argument (or multiplication factor) is multiplied by the interval that is set using the ip rtcp report interval command. This command configures the average interval between successive RTCP report transmissions for a given voice session. For example, if the value argument is set to 25,000 milliseconds, an RTCP report is sent every 25 seconds, on average. If no RTP packets are received during the calculated interval, the call is disconnected. The gateway signals the disconnect to the VoIP network and the time-division multiplexing (TDM) network so that upstream and downstream devices can clear their resources.

Please rate all useful posts

"'Nature is too thin a screen, the glory of the omnipresent God bursts through it everywhere"-Ralph Waldo Emerson

[Cesar Ortega]

Hello aokanlawon,

By default these timeout are operative and configured as follows:

ip rtcp report interval = 5000 ms

timer media-inactive = 5

http://www.cisco.com/en/US/docs/ios/12_3t/voice/command/reference/vrht_i1_ps5207_TSD_Products_Command_Reference_Chapter.html#wp1096253

In the end:

5000 ms x 5 = 25 seconds

which perfectly match with the time of call is dropped.

Then I change "timer media-inactive" to 10 so now it is:

5000 ms x 10 = 50 seconds

IVR (called number) can play messages during more than 25 seconds without call drops which solved my issue!

[brmeade]

Cesar,

Thanks for the update!  I've never seen this problem before as usually at least one side of the call is sending an RTP stream during an active call.  Glad to see you were able to resolve the issue!

Brian

[Cesar Ortega]

Yes, thank you.

Please keep in mind I had this problem only when called number was answered by a machine (IVR) (example, 0800 numbers) with long introduction messages.

Other normal cases works fine with default Cisco parameters.

Cesar

[brmeade]

You should still be receiving audio in that case though which would correspond to an RTP stream.  You may have an issue with your gateway not keeping track of that RTP stream.  Is this a SIP trunk or PRI/Analog?

[Cesar Ortega]

Belive me: I checked everything with no solutions, I'm totaly agree with you, though.

It's an H323 trunk between CM 7.5 and voice gateway. Between telco and voice gateway trunnk is ISDN.

[brmeade]

What version of IOS are you using?  You may be running into a bug.  You can try "debug voip rtp" or "debug cch323 rtp" and see if you are getting X(transmit) and R(received) packets for these calls.  You could also try a packet capture.  I'm guessing there is something unlinking a call flow from the RTP stream.  I know you have this workaround in place, but you will still run into issues for longer prompts.

[Cesar Ortega]

Hi Brian,

After applying "debug voip rtp" I got this (some part of the output was omitted):

Aug 24 10:04:15.114: voip_rtp_create_session idb tableid is 0,session table id is 0

Aug 24 10:04:15.114: voip_rtp_create_session: callID=102, dstCallID=103 laddr=22.10.11.249, lport=17858,raddr=0.0.0.0, rport=0, type=1, sig_tos=3, ip_tos=5

Aug 24 10:04:15.114: voip_rtp_update_local_ssrc srtp: 0 CallID: 102 dstCallID: 103 new ssrc: 0x17E30BF9

Aug 24 10:04:15.114: voip_rtcp_get_cname: cname=0.0.0@22.10.11.249

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info, dstvdbptr: 4A703ECC, dstCallID 103, gccb: 4BB10120, xmitFunc 41CFC4D8,context 0

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info Context is NULL, exit

Aug 24 10:04:15.114: voip_rtp_set_non_rtp_call: Non-RTP call end

Aug 24 10:04:15.114: voip_rtp_update_callinfo: first_pak=TRUE, new_ssrc=0, type=1

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info, dstvdbptr: 4A703ECC, dstCallID 103, gccb: 4BB10120, xmitFunc 41CFC4D8,context 0

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info Context is NULL, exit

Aug 24 10:04:15.114: voip_rtp_exchange_context_info

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info, dstvdbptr: 4A703ECC, dstCallID 103, gccb: 4BB10120, xmitFunc 41CFC4D8,context 4BA09E60

Aug 24 10:04:15.114:  voip_rtp_update_xmit_info Xmit Info node current values xmit_info->dstvdbptr: 4A703ECC, xmit_info->dstCallID 103, xmit_info->xmitFunc 41CFC4D8, xmit_info->context 4BA09E60

Aug 24 10:04:15.114:  voip xmit info count: 1

Aug 24 10:04:15.114: voip_rtcp_start_session:

Aug 24 10:04:15.114: voip_rtcp_start_session: start session

Aug 24 10:04:15.158: voip_rtp_exchange_context_info

Aug 24 10:04:15.158:  voip_rtp_update_xmit_info

Aug 24 10:04:15.158:  voip_rtp_update_xmit_info, dstvdbptr: 4A703ECC, dstCallID 103, gccb: 4BB10120, xmitFunc 41CFC4D8,context 4BA09E60

Aug 24 10:04:15.158:  voip_rtp_update_xmit_info Xmit Info node current values xmit_info->dstvdbptr: 4A703ECC, xmit_info->dstCallID 103, xmit_info->xmitFunc 41CFC4D8, xmit_info->context 4BA09E60

Aug 24 10:04:15.158:  voip xmit info count: 1

Aug 24 10:04:15.158: voip_rtp_update_callinfo: invalid RTP address/port changes 16FF1F1B:0

Aug 24 10:04:15.158: voip_rtp_update_callinfo: first_pak=TRUE, new_ssrc=0, type=1

Aug 24 10:04:15.158:  voip_rtp_update_xmit_info

Aug 24 10:04:15.158:  voip_rtp_update_xmit_info, dstvdbptr: 4A703ECC, dstCallID 103, gccb: 4BB10120, xmitFunc 41CFC4D8,context 4BA09E60

Aug 24 10:04:15.158:  voip_rtp_update_xmit_info Xmit Info node current values xmit_info->dstvdbptr: 4A703ECC, xmit_info->dstCallID 103, xmit_info->xmitFunc 41CFC4D8, xmit_info->context 4BA09E60

Aug 24 10:04:15.158:  voip xmit info count: 1

Aug 24 10:04:15.162: voip_rtp_set_non_rtp_call: Non-RTP call end

Aug 24 10:04:15.162: voip_rtp_update_callinfo: RTP address/port changes 0:0->16FDFF19:6230

Aug 24 10:04:15.162: voip_rtp_update_callinfo: first_pak=TRUE, new_ssrc=0, type=1

Aug 24 10:04:15.162:  voip_rtp_update_xmit_info

Aug 24 10:04:15.162:  voip_rtp_update_xmit_info, dstvdbptr: 4A703ECC, dstCallID 103, gccb: 4BB10120, xmitFunc 41CFC4D8,context 4BA09E60

Aug 24 10:04:15.162:  voip_rtp_update_xmit_info Xmit Info node current values xmit_info->dstvdbptr: 4A703ECC, xmit_info->dstCallID 103, xmit_info->xmitFunc 41CFC4D8, xmit_info->context 4BA09E60

Aug 24 10:04:15.162:  voip xmit info count: 1voip_rtp_start_disc_timer: Timer not started 0, 0

Aug 24 10:04:15.190: RTP(8520): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF385CD, ssrc=17E30BF9, marker=1

Aug 24 10:04:15.210: RTP(8521): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF3866D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.234: RTP(8522): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF3870D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.250: RTP(8523): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF387AD, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.270: RTP(8524): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF3884D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.294: RTP(8525): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF388ED, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.310: RTP(8526): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF3898D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.330: RTP(8527): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38A2D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.354: RTP(8528): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38ACD, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.370: RTP(8529): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38B6D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.390: RTP(8530): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38C0D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.414: RTP(8531): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38CAD, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.430: RTP(8532): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38D4D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.450: RTP(8533): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38DED, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.474: RTP(8534): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38E8D, ssrc=17E30BF9, marker=0

Aug 24 10:04:15.490: RTP(8535): fs tx s=22.10.11.249(17858), d=22.253.255.25(25136), pt=0, ts=2EF38F2D, ssrc=17E30BF9, marker=0

:

:

:

I don't see anything weird. Do you?

Cesar

[brmeade]

What do 22.10.11.249 and 22.253.255.25 correspond to?

I can only see one RTP stream unless I'm reading this wrong.  During your call drop scenario, does the calling phone have their handset muted?

Also, which IOS version are you running?  I can see if I can find a related bug.

[Cesar Ortega]

Hi Brian,

22.10.11.249   Voice Gateway 2851 with 12.4(24)T6 (ADVENTERPRIK9_IVS-M)

22.253.255.25 Call Manager Subscriber

And no, the handset was not in mute during the call.