T1 CAS MGCP inbound call fast busy PSTN troubleshooting

[artem.matsyplyuk77]

Upgraded CUCM 11.5 SU4 to 11.5 SU10 and started having issues with T1 CAS setup, here is some debugs if someone can point me in the right direction, i see its getting to inbound dial peer successfully. 

*Jul 12 19:28:48.908: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346454 *@Router_voice MGCP 0.1
X: 0
O:
<---

*Jul 12 19:28:48.919: MGCP Packet received from 10.10.10.111:2427--->
200 897346454
<---

*Jul 12 19:29:03.909: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346455 *@Router_voice MGCP 0.1
X: 0
O:
<---

*Jul 12 19:29:03.918: MGCP Packet received from 10.10.10.111:2427--->
200 897346455
<---

*Jul 12 19:29:18.909: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346456 *@Router_voice MGCP 0.1
X: 0
O:
<---

*Jul 12 19:29:18.920: MGCP Packet received from 10.10.10.111:2427--->
200 897346456
<---

*Jul 12 19:29:24.170: //-1/xxxxxxxxxxxx/VTSP:(0/1/0:1):-1:-1:-1/vtsp_allocate_cdb:
CDB=0x7F020DF3E478
*Jul 12 19:29:24.170: //-1/xxxxxxxxxxxx/VTSP:(0/1/0:1):-1:-1:-1/vtsp_do_call_setup_ind:
Event=E_TSP_SETUP_IND
Progress Indication=3, CarrierIDCode=, Info Trans Capability=144, Source Carrier ID=, tg_label_flag=0
*Jul 12 19:29:24.170: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_timer:
Timer Start Time=565285400, Timer Value=180000(ms)
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
XCC State Machine (XCCSM) Added
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_insert_cdb:
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_opened_cb:
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_setup_ind_pend_success:
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_realloc_cdb:
CDB=0x7F020DF3E478
*Jul 12 19:29:24.171: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_indicate_call:
*Jul 12 19:29:24.171: //-1/4C793235AC58/CCAPI/cc_api_display_ie_subfields:
cc_api_call_setup_ind_common:
cisco-username=
----- ccCallInfo IE subfields -----
cisco-ani=
cisco-anitype=0
cisco-aniplan=0
cisco-anipi=0
cisco-anisi=0
dest=
cisco-desttype=0
cisco-destplan=0
cisco-rdie=FFFFFFFFFFFFFFFF
cisco-rdn=
cisco-rdntype=0
cisco-rdnplan=0
cisco-rdnpi=0
cisco-rdnsi=0
cisco-redirectreason=0 fwd_final_type =0
final_redirectNumber =
hunt_group_timeout =0

*Jul 12 19:29:24.171: //-1/4C793235AC58/CCAPI/cc_api_call_setup_ind_common:
Interface=0x7F0203A5A310, Call Info(
Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=(TON=Unknown, NPI=Unknown),
Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=FALSE,
Incoming Dial-peer=999000991, Progress Indication=ORIGINATING SIDE IS NON ISDN(3), Calling IE Present=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
*Jul 12 19:29:24.171: //-1/4C793235AC58/CCAPI/ccCheckClipClir:
In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Jul 12 19:29:24.171: //-1/4C793235AC58/CCAPI/ccCheckClipClir:
Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Jul 12 19:29:24.172: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Jul 12 19:29:24.172: :cc_get_feature_vsa malloc success
*Jul 12 19:29:24.172: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Jul 12 19:29:24.172: cc_get_feature_vsa count is 1
*Jul 12 19:29:24.172: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Jul 12 19:29:24.172: :FEATURE_VSA attributes are: feature_name:0,feature_time:139646507349964,feature_id:4643
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/cc_api_call_setup_ind_common:
Set Up Event Sent;
Call Info(Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=(TON=Unknown, NPI=Unknown))
*Jul 12 19:29:24.172: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_insert_cdb:
*Jul 12 19:29:24.172: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer:
Timer Start Time=565285400, Timer Value=180000(ms)
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/cc_process_call_setup_ind:
Event=0x7F01FC788EC8
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/cc_process_call_setup_ind:
>>>>CCAPI handed cid 4643 with tag 999000991 to app "MGCPAPP"
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/ccCallSetContext:
Context=0x7F01F4B64A30
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/ccCallSetupAck:
Call Id=4643
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/cc_api_set_transfer_info:
Transfer Number=, Transfer Reason=0x0
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
(callID=0x1223, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=4643
*Jul 12 19:29:24.172: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x7F0203A5A310, callID=0x1223, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:24.172: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:24.173: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))
*Jul 12 19:29:24.173: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
Digit Reporting=TRUE
*Jul 12 19:29:24.173: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346457 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
N: ca@10.10.10.111:2427
X: b
O: DT/sup
<---

*Jul 12 19:29:24.173: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_SETUP_INDICATED, event:E_CC_SETUP_ACK]
*Jul 12 19:29:24.173: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_setup_ind_ack:
Fax Relay=TRUE, Dial Tone=FALSE, Digit Collect=TRUE, Overlap=FALSE, DID=FALSE
*Jul 12 19:29:24.173: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=565285400
*Jul 12 19:29:24.173: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_setup_ind_ack:
Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms), Playout Max=1000(ms), Fax Nom=300(ms)
*Jul 12 19:29:24.182: MGCP Packet received from 10.10.10.111:2427--->
200 897346457
<---

*Jul 12 19:29:24.184: MGCP Packet received from 10.10.10.111:2427--->
CRCX 33379 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
C: A000000002adb481000000F5
X: b
L: p:20, a:PCMU, s:off, t:b8
M: recvonly
R: DT/rel
Q: process,loop
<---

*Jul 12 19:29:24.185: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
(callID=0x1223, digit_event=0x0, enable=FALSE, consume=FALSE)
*Jul 12 19:29:24.185: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=4643
*Jul 12 19:29:24.185: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
*Jul 12 19:29:24.185: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x7F0203A5A310, callID=0x1223, disp=0, digit_event=0x0, enable=FALSE, consume=FALSE)
*Jul 12 19:29:24.185: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:24.185: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=15000(ms), Inter Digit Timeout=10000(ms))
*Jul 12 19:29:24.185: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
Digit Reporting=FALSE
*Jul 12 19:29:24.185: //4643/4C793235AC58/CCAPI/ccCallModify:
Nominator=0x1, Params=0x7F020425AFCC, Call Id=4643
*Jul 12 19:29:24.185: //-1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
Interface=0x7F01FB3AFF10, Interface Type=9, Destination=0.0.0.0, Mode=0x9,
Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
Called Number=(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
Subscriber Type Str=, FinalDestinationFlag=FALSE, Outgoing Dial-peer=0, Call Count On=FALSE,
Source Trkgrp Route Label=, Target Trkgrp Route Label=, tg_label_flag=0, Application Call Id=)
*Jul 12 19:29:24.185: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Jul 12 19:29:24.185: :cc_get_feature_vsa malloc success
*Jul 12 19:29:24.185: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Jul 12 19:29:24.185: cc_get_feature_vsa count is 2
*Jul 12 19:29:24.185: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Jul 12 19:29:24.185: :FEATURE_VSA attributes are: feature_name:0,feature_time:139646507349740,feature_id:4644
*Jul 12 19:29:24.185: //4644/4C793235AC58/CCAPI/ccIFCallSetupRequestPrivate:
SPI Call Setup Request Is Success; Interface Type=9, FlowMode=1
*Jul 12 19:29:24.185: //4644/4C793235AC58/CCAPI/ccCallSetContext:
Context=0x7F01F4B64968
*Jul 12 19:29:24.186: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Jul 12 19:29:24.186: //4643/4C793235AC58/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:24.186: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:24.186: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Call Entry=NULL, Call Id=-1
*Jul 12 19:29:24.186: //4644/4C793235AC58/CCAPI/cc_api_call_connected:
Interface=0x7F01FB3AFF10, Data Bitmask=0x0, Progress Indication=NULL(0),
Connection Handle=0
*Jul 12 19:29:24.186: //4644/4C793235AC58/CCAPI/cc_api_call_connected:
Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
*Jul 12 19:29:24.186: //4644/4C793235AC58/CCAPI/ccConferenceCreate:
(confID=0xFFFFFFFFFFFFFFFF, callID1=0x1224, gcid=0-0-0-0, tag=0x0)
*Jul 12 19:29:24.186: //4643/4C793235AC58/CCAPI/ccConferenceCreate:
(confID=0xFFFFFFFFFFFFFFFF, callID2=0x1223, gcid=4C793235-E27E11EB-AC589144-37ED22A3, tag=0x0)
*Jul 12 19:29:24.186: //4644/4C793235AC58/CCAPI/ccConferenceCreate:
Conference Id=0xFFFFFFFFFFFFFFFF, Call Id1=4644, Call Id2=4643, Tag=0x0
*Jul 12 19:29:24.186: //4644/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Jul 12 19:29:24.186: cc_api_get_xcode_stream : 4983
*Jul 12 19:29:24.186: //4644/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

*Jul 12 19:29:24.187: call_info mainst_callID:0x1224, peer_callID:0x1223, confID:0x8EE, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

*Jul 12 19:29:24.187: //4644/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

*Jul 12 19:29:24.187: stream[0]: callid:0x1224, media_passthrough:0
*Jul 12 19:29:24.187: //4644/4C793235AC58/CCAPI/cc_api_bridge_done:
Conference Id=0x8EE, Source Interface=0x7F01FB3AFF10, Source Call Id=4644,
Destination Call Id=4643, Disposition=0x0, Tag=0x0
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_bridge_check_cb:
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_bridge_check_cb:exit@1496
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_bridge_status_cb:
*Jul 12 19:29:24.187: //4643/4C793235AC58/CCAPI/cc_api_bridge_done:
Conference Id=0x8EE, Source Interface=0x7F0203A5A310, Source Call Id=4643,
Destination Call Id=4644, Disposition=0x0, Tag=0xFFFFFFFFFFFFFFFF
*Jul 12 19:29:24.187: //4644/4C793235AC58/CCAPI/cc_generic_bridge_done:
Conference Id=0x8EE, Source Interface=0x7F0203A5A310, Source Call Id=4643,
Destination Call Id=4644, Disposition=0x0, Tag=0xFFFFFFFFFFFFFFFF
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=DISABLED - MGCP Application
Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=IGNORE_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=MGCP Call Type
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param:
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_tty_config:
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_tty_config:
Save TTY configuration
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_set_tty_feat_param:
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_set_tty_feat_param:
Set TTY feat parameters
*Jul 12 19:29:24.187: //4644/4C793235AC58/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x8EE, Destination Call Id=4643)
*Jul 12 19:29:24.187: //4643/4C793235AC58/CCAPI/ccConferenceCreate:
Call Entry(Conference Id=0x8EE, Destination Call Id=4644)
*Jul 12 19:29:24.187: //4644/4C793235AC58/CCAPI/ccConferenceCreate:

*Jul 12 19:29:24.187: confID:0x8EE; callEntry1 callID1:0x1224, type:9; callEntry2 callID2:0x1223, type:6

*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_DIGIT_COLLECT, event:E_CC_DO_CAPS_IND]
*Jul 12 19:29:24.187: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_peer_event_cb:
Event=E_DSM_CC_CAPS_IND
*Jul 12 19:29:24.187: //4643/4C793235AC58/CCAPI/cc_api_caps_ind:
Destination Interface=0x7F01FB3AFF10, Destination Call Id=4644, Source Call Id=4643,
Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,
Modem=0x2, Codec Bytes=20, Signal Type=3)
*Jul 12 19:29:24.188: //4643/4C793235AC58/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))
*Jul 12 19:29:24.188: //4644/4C793235AC58/CCAPI/cc_api_caps_ind:
Destination Interface=0x7F0203A5A310, Destination Call Id=4643, Source Call Id=4644,
Caps(Codec=0x1, Fax Rate=0x2, Fax Version:=0, Vad=0x1,
Modem=0x2, Codec Bytes=160, Signal Type=2)
*Jul 12 19:29:24.188: //4644/4C793235AC58/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))
*Jul 12 19:29:24.188: //4644/4C793235AC58/CCAPI/cc_api_caps_ack:
Destination Interface=0x7F0203A5A310, Destination Call Id=4643, Source Call Id=4644,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Fax Version:=0, Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=5632)
*Jul 12 19:29:24.188: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_DIGIT_COLLECT, event:E_CC_CAPS_IND]
*Jul 12 19:29:24.188: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_peer_event_cb:
Event=E_DSM_CC_CAPS_ACK
*Jul 12 19:29:24.188: //4643/4C793235AC58/CCAPI/cc_api_caps_ack:
Destination Interface=0x7F01FB3AFF10, Destination Call Id=4644, Source Call Id=4643,
Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_VOICE(0x2), Fax Version:=0, Vad=OFF(0x1),
Modem=ON(0x2), Codec Bytes=160, Signal Type=2, Seq Num Start=5632)
*Jul 12 19:29:24.188: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_feature_notify_cb:
Feature ID=0, Feature Status=1
*Jul 12 19:29:24.188: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_reactivate_ringback:
*Jul 12 19:29:24.188: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_reactivate_ringback:exit@1287
*Jul 12 19:29:24.188: //4643/4C793235AC58/CCAPI/cc_api_voice_mode_event:
Call Id=4643
*Jul 12 19:29:24.188: //4643/4C793235AC58/CCAPI/cc_api_voice_mode_event:
Call Entry(Context=0x7F01F4B64A30)
*Jul 12 19:29:24.189: //4644/4C793235AC58/CCAPI/cc_process_notify_bridge_done:
Conference Id=0x8EE, Call Id1=4644, Call Id2=4643
*Jul 12 19:29:24.189: MGCP Packet sent to 10.10.10.111:2427--->
200 33379 OK
I: 8DA

v=0
c=IN IP4 10.119.37.40
m=audio 12570 RTP/AVP 0 100
a=rtpmap:100 X-NSE/8000
a=fmtp:100 192-194
<---

*Jul 12 19:29:24.190: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:
Event=E_DSMP_FPI_ENABLE_TDM_RTCP
*Jul 12 19:29:24.200: MGCP Packet received from 10.10.10.111:2427--->
MDCX 33380 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
C: A000000002adb481000000F5
I: 8DA
X: b
L: p:20, a:PCMU, s:off, t:b8
M: sendrecv
R: D/[0-9ABCD*#], DT/rel, L/hf
S:
Q: process,loop

v=0
o=- 2266 0 IN EPN S0/SU1/DS1-0/12@Router_voice
s=Cisco SDP 0
t=0 0
m=audio 26018 RTP/AVP 0
c=IN IP4 10.119.8.20
<---

*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/ccSetDigitTimeouts:
Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms)
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/ccSetDigitTimeouts:
Call Entry(Inter Digit Timeout=4000(ms), Initial Digit Timeout=4000(ms))
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/ccRestartDigitTimeoutMsec:
Digit Timeout=0, Call Id=4643
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
(callID=0x1223, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=4643
*Jul 12 19:29:24.200: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x7F0203A5A310, callID=0x1223, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms))
*Jul 12 19:29:24.200: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
Digit Reporting=TRUE
*Jul 12 19:29:24.200: //4643/4C793235AC58/CCAPI/ccCallModifyExtended:
Nominator=0x7F020425A058, Params=0x7F020425AFD0, Call Id=4643
*Jul 12 19:29:24.200: //4644/4C793235AC58/CCAPI/ccCallModify:
Nominator=0x18E30, Params=0x7F020425A998, Call Id=4644
*Jul 12 19:29:24.201: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Jul 12 19:29:24.201: //4643/4C793235AC58/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:24.201: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:24.201: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:24.201: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=ENABLED
Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=NONE_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=MGCP Call Type
*Jul 12 19:29:24.201: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param:
*Jul 12 19:29:24.201: //4644/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Jul 12 19:29:24.201: cc_api_get_xcode_stream : 4983
*Jul 12 19:29:24.201: //4644/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Jul 12 19:29:24.201: cc_api_get_xcode_stream : 4983
*Jul 12 19:29:24.201: //4644/4C793235AC58/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x7F01FB3AFF10, Call Id=4644
*Jul 12 19:29:24.201: //4644/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

*Jul 12 19:29:24.201: call_info mainst_callID:0x1224, peer_callID:0x1223, confID:0x8EE, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

*Jul 12 19:29:24.201: //4644/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

*Jul 12 19:29:24.201: stream[0]: callid:0x1224, media_passthrough:0
*Jul 12 19:29:24.202: MGCP Packet sent to 10.10.10.111:2427--->
200 33380 OK
<---

*Jul 12 19:29:24.204: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:
Event=E_DSMP_FPI_ENABLE_TDM_RTCP
*Jul 12 19:29:24.702: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
*Jul 12 19:29:24.702: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Begin Digit=7
*Jul 12 19:29:24.702: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:24.702: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=7, DigitBeginFlags=0x1,
Rtp Timestamp=0x3A2A1BEB, Rtp Expiration=0x0
*Jul 12 19:29:24.702: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Consume mask is not set. Relaying Digit 7 to dstCallId 0x1224
*Jul 12 19:29:24.702: //4643/4C793235AC58/CCAPI/cc_relay_digit_begin_for_3way_conference:
Check DTMF relay digit begin for 3way conf
*Jul 12 19:29:24.763: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
*Jul 12 19:29:24.763: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=565285459
*Jul 12 19:29:24.763: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
End Digit=7
*Jul 12 19:29:24.763: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:24.764: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=7, Duration=92,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Jul 12 19:29:24.764: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
*Jul 12 19:29:24.764: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Consume mask is not set. Relaying Digit 7 to dstCallId 0x1224
*Jul 12 19:29:24.764: //4643/4C793235AC58/CCAPI/cc_relay_digit_end_for_3way_conference:
Check DTMF relay digit end for 3way conf
*Jul 12 19:29:24.764: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346458 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
N: ca@10.10.10.111:2427
X: b
O: D/7
<---

*Jul 12 19:29:24.774: MGCP Packet received from 10.10.10.111:2427--->
200 897346458
<---

*Jul 12 19:29:24.843: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
*Jul 12 19:29:24.843: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Begin Digit=6
*Jul 12 19:29:24.843: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:24.843: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=6, DigitBeginFlags=0x1,
Rtp Timestamp=0x3A2A2048, Rtp Expiration=0x0
*Jul 12 19:29:24.843: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Consume mask is not set. Relaying Digit 6 to dstCallId 0x1224
*Jul 12 19:29:24.843: //4643/4C793235AC58/CCAPI/cc_relay_digit_begin_for_3way_conference:
Check DTMF relay digit begin for 3way conf
*Jul 12 19:29:24.904: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
*Jul 12 19:29:24.904: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=565285474
*Jul 12 19:29:24.904: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
End Digit=6
*Jul 12 19:29:24.904: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:24.904: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=6, Duration=95,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Jul 12 19:29:24.904: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
*Jul 12 19:29:24.904: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Consume mask is not set. Relaying Digit 6 to dstCallId 0x1224
*Jul 12 19:29:24.904: //4643/4C793235AC58/CCAPI/cc_relay_digit_end_for_3way_conference:
Check DTMF relay digit end for 3way conf
*Jul 12 19:29:24.905: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346459 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
N: ca@10.10.10.111:2427
X: b
O: D/6
<---

*Jul 12 19:29:24.914: MGCP Packet received from 10.10.10.111:2427--->
200 897346459
<---

*Jul 12 19:29:24.985: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
*Jul 12 19:29:24.985: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Begin Digit=0
*Jul 12 19:29:24.986: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:24.986: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=0, DigitBeginFlags=0x1,
Rtp Timestamp=0x3A2A24A8, Rtp Expiration=0x0
*Jul 12 19:29:24.986: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Consume mask is not set. Relaying Digit 0 to dstCallId 0x1224
*Jul 12 19:29:24.986: //4643/4C793235AC58/CCAPI/cc_relay_digit_begin_for_3way_conference:
Check DTMF relay digit begin for 3way conf
*Jul 12 19:29:25.045: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
*Jul 12 19:29:25.045: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=565285488
*Jul 12 19:29:25.045: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
End Digit=0
*Jul 12 19:29:25.045: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:25.045: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=0, Duration=95,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Jul 12 19:29:25.045: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
*Jul 12 19:29:25.045: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Consume mask is not set. Relaying Digit 0 to dstCallId 0x1224
*Jul 12 19:29:25.045: //4643/4C793235AC58/CCAPI/cc_relay_digit_end_for_3way_conference:
Check DTMF relay digit end for 3way conf
*Jul 12 19:29:25.046: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346460 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
N: ca@10.10.10.111:2427
X: b
O: D/0
<---

*Jul 12 19:29:25.056: MGCP Packet received from 10.10.10.111:2427--->
200 897346460
<---

*Jul 12 19:29:25.126: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
*Jul 12 19:29:25.126: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Begin Digit=0
*Jul 12 19:29:25.127: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_begin_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:25.127: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=0, DigitBeginFlags=0x1,
Rtp Timestamp=0x3A2A2906, Rtp Expiration=0x0
*Jul 12 19:29:25.127: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:
Consume mask is not set. Relaying Digit 0 to dstCallId 0x1224
*Jul 12 19:29:25.127: //4643/4C793235AC58/CCAPI/cc_relay_digit_begin_for_3way_conference:
Check DTMF relay digit begin for 3way conf
*Jul 12 19:29:25.186: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
*Jul 12 19:29:25.186: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=565285502
*Jul 12 19:29:25.186: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
End Digit=0
*Jul 12 19:29:25.186: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_digit_end_cb:
Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=TRUE
*Jul 12 19:29:25.186: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Destination Interface=0x7F01FB3AFF10, Destination Mask=0x3, Destination Call Id=4644,
Source Call Id=4643, Digit=0, Duration=97,
Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Jul 12 19:29:25.187: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Call Entry(Handoff Depth=0)
*Jul 12 19:29:25.187: //4643/4C793235AC58/CCAPI/cc_api_call_digit_end:
Consume mask is not set. Relaying Digit 0 to dstCallId 0x1224
*Jul 12 19:29:25.187: //4643/4C793235AC58/CCAPI/cc_relay_digit_end_for_3way_conference:
Check DTMF relay digit end for 3way conf
*Jul 12 19:29:25.187: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346461 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
N: ca@10.10.10.111:2427
X: b
O: D/0
<---

*Jul 12 19:29:25.196: MGCP Packet received from 10.10.10.111:2427--->
200 897346461
<---

*Jul 12 19:29:29.186: //4643/4C793235AC58/CCAPI/cc_handle_inter_digit_timer:
Generate inter-digit timeout CC_EV_CALL_DIGIT_END event
*Jul 12 19:29:29.186: //4643/4C793235AC58/CCAPI/cc_handle_inter_digit_timer:
Generate inter-digit timeout CC_EV_CALL_DIGIT_END event
*Jul 12 19:29:33.503: MGCP Packet received from 10.10.10.111:2427--->
MDCX 33390 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
C: A000000002adb481000000F5
I: 8DA
X: b
M: recvonly
R: D/[0-9ABCD*#], DT/rel, L/hf
S:
Q: process,loop
<---

*Jul 12 19:29:33.503: //4643/4C793235AC58/CCAPI/ccCallModifyExtended:
Nominator=0x7F020425A058, Params=0x7F020425AFD0, Call Id=4643
*Jul 12 19:29:33.503: //4644/4C793235AC58/CCAPI/ccCallModify:
Nominator=0x800, Params=0x7F020425A998, Call Id=4644
*Jul 12 19:29:33.503: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Jul 12 19:29:33.503: //4643/4C793235AC58/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:33.503: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:33.503: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:33.504: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=ENABLED
Primary Fax Protocol=IGNORE_FAX_RELAY, Fallback Fax Protocol=NONE_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=MGCP Call Type
*Jul 12 19:29:33.504: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_set_fax_feat_param:
*Jul 12 19:29:33.504: //4644/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Jul 12 19:29:33.504: cc_api_get_xcode_stream : 4983
*Jul 12 19:29:33.504: //4644/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Jul 12 19:29:33.504: cc_api_get_xcode_stream : 4983
*Jul 12 19:29:33.504: //4644/4C793235AC58/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x7F01FB3AFF10, Call Id=4644
*Jul 12 19:29:33.504: //4644/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

*Jul 12 19:29:33.504: call_info mainst_callID:0x1224, peer_callID:0x1223, confID:0x8EE, spi_type:6, media_flo_thru:1,num_streams:1, swmtpmsp_present:0

*Jul 12 19:29:33.504: //4644/xxxxxxxxxxxx/CCAPI/cc_api_ha_call_active_notify:

*Jul 12 19:29:33.504: stream[0]: callid:0x1224, media_passthrough:0
*Jul 12 19:29:33.504: MGCP Packet sent to 10.10.10.111:2427--->
200 33390 OK
<---

*Jul 12 19:29:33.507: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:
Event=E_DSMP_FPI_ENABLE_TDM_RTCP
*Jul 12 19:29:33.516: MGCP Packet received from 10.10.10.111:2427--->
RQNT 33391 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
X: b
R: DT/rel
S: T/ro
Q: process,loop
<---

*Jul 12 19:29:33.516: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
(callID=0x1223, digit_event=0x0, enable=FALSE, consume=FALSE)
*Jul 12 19:29:33.516: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=4643
*Jul 12 19:29:33.516: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
*Jul 12 19:29:33.516: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x7F0203A5A310, callID=0x1223, disp=0, digit_event=0x0, enable=FALSE, consume=FALSE)
*Jul 12 19:29:33.516: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:33.516: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms))
*Jul 12 19:29:33.516: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
Digit Reporting=FALSE
*Jul 12 19:29:33.516: //4643/4C793235AC58/CCAPI/ccGenerateToneInfo:
Stop Tone On Digit=FALSE, Tone=Fast Busy,
Tone Direction=Network, Params=0x0, Call Id=4643
*Jul 12 19:29:33.516: MGCP Packet sent to 10.10.10.111:2427--->
200 33391 OK
<---

*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_DIGIT_COLLECT, event:E_TSP_DISCONNECT_IND]
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_generate_disc:
Cause Value=16
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=565286907
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=565286907
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_set_release_source:
Release Direction=PSTN, Release Source=Calling Party-PSTN
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_cc_call_disconnected:
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_cc_call_disconnected:
Cause Value=16
*Jul 12 19:29:39.235: //4643/4C793235AC58/CCAPI/cc_api_call_disconnected:
Cause Value=16, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:39.235: //4643/4C793235AC58/CCAPI/cc_api_call_disconnected:
Call Entry(Responsed=FALSE, Cause Value=16, Retry Count=0)
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer:
Timer Start Time=565286907, Timer Value=15000(ms)
*Jul 12 19:29:39.235: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_generate_disc:
Return Code=0
*Jul 12 19:29:39.236: //4643/4C793235AC58/CCAPI/ccGenerateToneInfo:
Stop Tone On Digit=FALSE, Tone=Null,
Tone Direction=Network, Params=0x0, Call Id=4643
*Jul 12 19:29:39.236: MGCP Packet sent to 10.10.10.111:2427--->
NTFY 897346462 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
N: ca@10.10.10.111:2427
X: b
O: DT/rel(0)
<---

*Jul 12 19:29:39.245: MGCP Packet received from 10.10.10.111:2427--->
200 897346462
<---

*Jul 12 19:29:39.246: MGCP Packet received from 10.10.10.111:2427--->
DLCX 33396 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
C: A000000002adb481000000F5
I: 8DA
X: b
<---

*Jul 12 19:29:39.246: //4644/4C793235AC58/CCAPI/ccGetCallStatistics:
Call Stats=0x7F01F4B7C9D8, Call Id=4644
*Jul 12 19:29:39.246: //4644/4C793235AC58/CCAPI/ccConferenceDestroy:
Conference Id=0x8EE, Tag=0x0
*Jul 12 19:29:39.246: //4644/4C793235AC58/CCAPI/ccConferenceDestroy:

*Jul 12 19:29:39.246: confID:0x8EE; callEntry1 callID1:0x1224, type:9; callEntry2 callID2:0x1223, type:6

*Jul 12 19:29:39.246: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_fpi_event_cb:
Event=E_DSMP_FPI_DISABLE_TDM_RTCP
*Jul 12 19:29:39.246: //4644/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Jul 12 19:29:39.246: cc_api_get_xcode_stream : 4983
*Jul 12 19:29:39.246: //4644/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Jul 12 19:29:39.246: cc_api_get_xcode_stream : 4983
*Jul 12 19:29:39.246: //4644/4C793235AC58/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x8EE, Source Interface=0x7F01FB3AFF10, Source Call Id=4644,
Destination Call Id=4643, Disposition=0x0, Tag=0x0
*Jul 12 19:29:39.246: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_bridge_status_cb:
*Jul 12 19:29:39.246: //4643/4C793235AC58/CCAPI/cc_api_bridge_drop_done:
Conference Id=0x8EE, Source Interface=0x7F0203A5A310, Source Call Id=4643,
Destination Call Id=4644, Disposition=0x0, Tag=0x0
*Jul 12 19:29:39.246: //4644/4C793235AC58/CCAPI/cc_generic_bridge_done:
Conference Id=0x8EE, Source Interface=0x7F0203A5A310, Source Call Id=4643,
Destination Call Id=4644, Disposition=0x0, Tag=0x0
*Jul 12 19:29:39.248: //4644/4C793235AC58/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Jul 12 19:29:39.248: //4644/4C793235AC58/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Jul 12 19:29:39.248: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
(callID=0x1223, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:39.248: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=4643
*Jul 12 19:29:39.248: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
*Jul 12 19:29:39.248: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x7F0203A5A310, callID=0x1223, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:39.248: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:39.248: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms))
*Jul 12 19:29:39.248: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
Digit Reporting=TRUE
*Jul 12 19:29:39.249: //4644/4C793235AC58/CCAPI/cc_api_nw_stats:
Call Stats=0x7F020255A3F8, Call Id=4644
*Jul 12 19:29:39.249: //4644/4C793235AC58/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x7F01FB3AFF10, Tag=0x0, Call Id=4644,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Jul 12 19:29:39.249: //4644/4C793235AC58/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
*Jul 12 19:29:39.249: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Jul 12 19:29:39.249: :cc_free_feature_vsa freeing 7F01FC76F6E0
*Jul 12 19:29:39.249: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Jul 12 19:29:39.249: vsacount in free is 1
*Jul 12 19:29:39.250: MGCP Packet sent to 10.10.10.111:2427--->
250 33396 OK
P: PS=725, OS=144523, PR=466, OR=93200, PL=0, JI=0, LA=0
<---

*Jul 12 19:29:39.260: MGCP Packet received from 10.10.10.111:2427--->
RQNT 33397 S0/SU1/DS1-0/12@Router_voice MGCP 0.1
X: b
R: DT/sup, D/[0-9ABCD*#]
S: DT/rlc
Q: process,loop
<---

*Jul 12 19:29:39.260: //4643/4C793235AC58/CCAPI/ccSetDigitTimeouts:
Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms)
*Jul 12 19:29:39.260: //4643/4C793235AC58/CCAPI/ccSetDigitTimeouts:
Call Entry(Inter Digit Timeout=4000(ms), Initial Digit Timeout=4000(ms))
*Jul 12 19:29:39.260: //4643/4C793235AC58/CCAPI/ccRestartDigitTimeoutMsec:
Digit Timeout=0, Call Id=4643
*Jul 12 19:29:39.260: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
(callID=0x1223, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:39.261: //4643/4C793235AC58/CCAPI/ccCallReportDigits:
Enabled=TRUE, Call Id=4643
*Jul 12 19:29:39.261: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
*Jul 12 19:29:39.261: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
(vdbPtr=0x7F0203A5A310, callID=0x1223, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
*Jul 12 19:29:39.261: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Enabled=TRUE, Disposition=0x0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:39.261: //4643/4C793235AC58/CCAPI/cc_api_call_report_digits_done:
Call Entry(Initial Digit Timeout=4000(ms), Inter Digit Timeout=4000(ms))
*Jul 12 19:29:39.261: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_report_digit_control:
Digit Reporting=TRUE
*Jul 12 19:29:39.261: //4643/4C793235AC58/CCAPI/ccCallModify:
Nominator=0x1000, Params=0x7F020425B168, Call Id=4643
*Jul 12 19:29:39.271: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Jul 12 19:29:39.271: //4643/4C793235AC58/CCAPI/cc_api_call_modify_done:
Result=0, Interface=0x7F0203A5A310, Call Id=4643
*Jul 12 19:29:39.271: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:39.271: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Call Entry=NULL, Call Id=4644
*Jul 12 19:29:39.271: //4643/4C793235AC58/CCAPI/ccCallDisconnect:
Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
*Jul 12 19:29:39.271: //4643/4C793235AC58/CCAPI/ccCallDisconnect:
Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Jul 12 19:29:39.271: //4643/4C793235AC58/CCAPI/cc_api_get_transfer_info:
Transfer Number=NULL
*Jul 12 19:29:39.272: MGCP Packet sent to 10.10.10.111:2427--->
200 33397 OK
<---

*Jul 12 19:29:39.272: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_WAIT_HOST_DISC, event:E_CC_DISCONNECT]
*Jul 12 19:29:39.272: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_host_disc_cleanup:
dsm_indicate_error=0, short_cleardown_timeout=1, Mode=0
*Jul 12 19:29:39.272: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
*Jul 12 19:29:39.272: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_save_fax_config:
Call Entry=NULL, Call Id=4644
*Jul 12 19:29:39.272: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_host_disc_cleanup:
Exit State=16
*Jul 12 19:29:39.294: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Jul 12 19:29:39.312: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Jul 12 19:29:39.312: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_dsm_dsp_stats_complete:
*Jul 12 19:29:39.312: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer:
Timer Start Time=565286914, Timer Value=60000(ms)
*Jul 12 19:29:39.715: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_process_event:
[state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Jul 12 19:29:39.715: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/act_wrelease_release:
*Jul 12 19:29:39.715: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_play_busy_timer_stop:
Timer Stop Time=565286955
*Jul 12 19:29:39.715: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_timer_stop:
Timer Stop Time=565286955
*Jul 12 19:29:39.715: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_do_call_history:
*Jul 12 19:29:39.715: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_do_call_history:
Coder Rate=5
*Jul 12 19:29:39.715: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:1:1/vtsp_is_valid_dsm_handle:
DMGR=0x7F01F4CF4948, VTSP CDB=0x7F020DF3E478
*Jul 12 19:29:39.720: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_dsm_closed_cb:
*Jul 12 19:29:39.720: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_process_event:
[state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Jul 12 19:29:39.720: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/act_terminate:
*Jul 12 19:29:39.720: //4643/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_timer_stop:
Timer Stop Time=565286955
*Jul 12 19:29:39.720: //4643/4C793235AC58/CCAPI/cc_api_call_disconnect_done:
Disposition=0, Interface=0x7F0203A5A310, Tag=0x0, Call Id=4643,
Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Jul 12 19:29:39.720: //4643/4C793235AC58/CCAPI/cc_api_call_disconnect_done:
Call Disconnect Event Sent
*Jul 12 19:29:39.720: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Jul 12 19:29:39.720: :cc_free_feature_vsa freeing 7F01FC76F7C0
*Jul 12 19:29:39.720: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Jul 12 19:29:39.720: vsacount in free is 0
*Jul 12 19:29:39.720: //-1/4C793235AC58/VTSP:(0/1/0:1):-1:-1:-1/vtsp_free_cdb:
CDB=0x7F020DF3E478

[Sadav Ansari]

Hi,

As per log 

>>DTFM issue  check your configuration or need to raise case with telco

*Jul 12 19:29:24.702: //4643/4C793235AC58/CCAPI/cc_api_call_digit_begin:

Consume mask is not set. Relaying Digit 7 to dstCallId 0x1224

*Jul 12 19:29:24.702: //4643/4C793235AC58/CCAPI/cc_relay_digit_begin_for_3way_conference:

Check DTMF relay digit begin for 3way conf

*Jul 12 19:29:24.763:

>>Call disconnect cause =16 indicate that normal call clearing.

*Jul 12 19:29:39.249: //4644/4C793235AC58/CCAPI/cc_api_call_disconnect_done:

Disposition=0, Interface=0x7F01FB3AFF10, Tag=0x0, Call Id=4644,

Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)

*Jul 12 19:29:39.249: //4644/4C793235AC58/CCAPI/cc_api_call_disconnect_done:

Call Disconnect Event Sent

Kindly share the debug isdn q931 output and your voice gateway configuration for more clarification.

++ Put No MGCP and MGCP command on gateway hope it will work.

Pls rate if its “Helpful”. If this answered your question pls click “Accept as Solution”.

[Nithin Eluvathingal]

What I understood , Busy tiger for inbound calls from PSTN. means your outbound calls are working fine.? is that correct. 

Have you made any Changes on inbound CSS, does gateway inbound CSS  have proper privilege to reach your extensions. 

Share    bedbug isdn q931 output.