Router#debug VPM signal
Voice Port Module signaling debugging is enabled
Router#term
Router#terminal moni
Router#terminal monitor
Router#
*Aug 29 15:57:30.245: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=34067 systime=200865044
*Aug 29 15:57:30.245: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:57:30.245: htsp_timer - 125 msec
*Aug 29 15:57:30.265: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=34088 systime=200865046
*Aug 29 15:57:30.265: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:57:30.265: htsp_timer - 125 msec
*Aug 29 15:57:30.373: htsp_process_event: [0/0/0, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
*Aug 29 15:57:30.373: htsp_timer - 10000 msec
*Aug 29 15:57:30.393: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_timer
*Aug 29 15:57:30.393: htsp_timer - 10000 msec
*Aug 29 15:57:31.341: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=35159 systime=200865153
*Aug 29 15:57:31.341: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=35159 systime=200865153
*Aug 29 15:57:31.341: htsp_process_event: [0/0/0, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:31.341: fxols_ringing_not
*Aug 29 15:57:31.341: htsp_timer_stop
*Aug 29 15:57:31.341: htsp_timer_stop3
*Aug 29 15:57:31.341: [0/0/0] htsp_stop_caller_id_rx. message length 0htsp_setup_ind
*Aug 29 15:57:31.341: [0/0/0] get_fxo_caller_id:Caller ID receive failed.  parseCallerIDString:no data.
*Aug 29 15:57:31.341: [0/0/0] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig called=
*Aug 29 15:57:31.341: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x241462B8
*Aug 29 15:57:31.341: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_do_call_setup_ind:
   Event=E_TSP_SETUP_IND
   Progress Indication=3, CarrierIDCode=, Info Trans Capability=144, Source Carrier ID=Mobile, tg_label_flag=1
*Aug 29 15:57:31.341: //-1/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:31.341: //-1/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_timer:
   Timer Start Time=200865153, Timer Value=180000(ms)
*Aug 29 15:57:31.341: //-1/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:31.341: //-1/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:31.341: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:31.341: fxols_ringing_not
*Aug 29 15:57:31.341: htsp_timer_stop
*Aug 29 15:57:31.341: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:57:31.341: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig cal
led=
*Aug 29 15:57:31.341: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x24146878
*Aug 29 15:57:31.341: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:57:31.341: //-1/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:31.341: //-1/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200865153, Timer Value=180000(ms)
*Aug 29 15:57:31.341: //-1/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:31.341: //-1/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:31.345: //-1/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_opened_cb:
*Aug 29 15:57:31.345: //-1/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:31.345: //-1/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_setup_ind_pend_success:
*Aug 29 15:57:31.345: //-1/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_realloc_cdb:
   CDB=0x241462B8
*Aug 29 15:57:31.345: //-1/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_indicate_call:
*Aug 29 15:57:31.349: //-1/121F854FA9CD/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=100
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   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

*Aug 29 15:57:31.349: //-1/121F854FA9CD/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x22DE3FA0, Call Info(
   Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=100(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE,
   Incoming Dial-peer=0, Progress Indication=ORIGINATING SIDE IS NON ISDN(3), Calling IE Present=FALSE,
   Source Trkgrp Route Label=Mobile, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
*Aug 29 15:57:31.349: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.349: :cc_get_feature_vsa malloc success
*Aug 29 15:57:31.349: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.349:  cc_get_feature_vsa count is 1
*Aug 29 15:57:31.349: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.349: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:601
*Aug 29 15:57:31.349: //9074/121F854FA9CD/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=100(TON=Unknown, NPI=Unknown))
*Aug 29 15:57:31.349: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_insert_cdb:
*Aug 29 15:57:31.349: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_indicate_call:
   Source Trkgrp Route Label=Mobile
*Aug 29 15:57:31.349: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer:
   Timer Start Time=200865154, Timer Value=180000(ms)
*Aug 29 15:57:31.349: //-1/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:57:31.353: [0/0/0] htsp_dsm_close_done
*Aug 29 15:57:31.353: //-1/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:31.353: //-1/121F854FA9CF/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:57:31.353: //-1/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x24146878
*Aug 29 15:57:31.353: //-1/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:57:31.353: //-1/121F854FA9CF/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:57:31.353: //-1/121F854FA9CF/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=FFFFFFFF
   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

*Aug 29 15:57:31.353: //-1/121F854FA9CF/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:57:31.353: //-1/121F854FA9CF/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:31.353: //-1/121F854FA9CF/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:31.353: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.353: :cc_get_feature_vsa malloc success
*Aug 29 15:57:31.353: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.353:  cc_get_feature_vsa count is 2
*Aug 29 15:57:31.353: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.353: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080256,feature_id:602
*Aug 29 15:57:31.353: //9075/121F854FA9CF/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))
*Aug 29 15:57:31.353: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:57:31.353: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200865154, Timer Value=180000(ms)
*Aug 29 15:57:31.353: htsp_process_event: [0/0/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:31.353: fxols_wait_setup_ack:
*Aug 29 15:57:31.353: htsp_timer - 6000 msec
*Aug 29 15:57:31.353: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:31.353: fxols_wait_setup_ack:
*Aug 29 15:57:31.353: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:57:31.353: //9074/121F854FA9CD/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:57:31.353: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Try with the demoted called number 100
*Aug 29 15:57:31.353: //9074/121F854FA9CD/CCAPI/ccCallSetContext:
   Context=0x249B9F00
*Aug 29 15:57:31.353: //9074/121F854FA9CD/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 9074 with tag 0 to app "_ManagedAppProcess_Default"
*Aug 29 15:57:31.353: //9075/121F854FA9CF/CCAPI/cc_process_call_setup_ind:
   Event=0x3E759F00
*Aug 29 15:57:31.353: %CALL_CONTROL-6-APP_NOT_FOUND: Application stcapp in dial-peer 21 not found.  Handing call
id 9075 to the alternate app .

*Aug 29 15:57:31.353: //9075/121F854FA9CF/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:57:31.353: //9075/121F854FA9CF/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:57:31.353: //9075/121F854FA9CF/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:57:31.353: //9075/121F854FA9CF/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:57:31.353: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:57:31.353: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:57:31.353: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200865154
*Aug 29 15:57:31.353: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200865155
*Aug 29 15:57:31.357: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:57:31.357: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200865155, Timer Value=30000(ms)
*Aug 29 15:57:31.357: htsp_pre_connect_disconnect, cdb = 24146878 cause = 3F

*Aug 29 15:57:31.357: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:57:31.357: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=FALSE, Mode=0,
   Outgoing Dial-peer=40005, Params=0x249C4C90, Progress Indication=ORIGINATING SIDE IS NON ISDN(3)
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccCallSetupRequest:
   Destination Pattern=100$, Called Number=100, Digit Strip=FALSE
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccCallSetupRequest:
   Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=100(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=
   Account Number=, Final Destination Flag=TRUE,
   Guid=121F854F-AADB-11E8-A9CD-984CA2021AB0, Outgoing Dial-peer=40005
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=100
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   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

*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x225C2060, Interface Type=3, Destination=, Mode=0x0,
   Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Al
lowed),
   Called Number=100(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE, Outgoing Dial-peer=40005, Call Count On=FALSE,
   Source Trkgrp Route Label=Mobile, Target Trkgrp Route Label=, tg_label_flag=1, Application Call Id=)
*Aug 29 15:57:31.357: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.357: :cc_get_feature_vsa malloc success
*Aug 29 15:57:31.357: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.357:  cc_get_feature_vsa count is 3
*Aug 29 15:57:31.357: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:31.357: :FEATURE_VSA attributes are: feature_name:0,feature_time:554079808,feature_id:603
*Aug 29 15:57:31.357: //9076/121F854FA9CD/SIP/Error/sipSPIGetCallServerGroupTargets:
 No server group configured
*Aug 29 15:57:31.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_spi_event_handler:
   Event Category=1, Event=189
*Aug 29 15:57:31.357: //9076/121F854FA9CD/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=3, FlowMode=1
*Aug 29 15:57:31.357: //9076/121F854FA9CD/CCAPI/ccCallSetContext:
   Context=0x249C4C40
*Aug 29 15:57:31.357: //9074/121F854FA9CD/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=40005
*Aug 29 15:57:31.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_PROCEEDING]
*Aug 29 15:57:31.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_proceeding:
   Progress Indication=0
*Aug 29 15:57:31.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865155
*Aug 29 15:57:31.361: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
SIP: (9076) Group (a= group line) attribute, level 65535 instance 1 not found.
SIP: (9076) Group (a= group line) attribute, level 65535 instance 1 not found.
*Aug 29 15:57:31.361: //9076/121F854FA9CD/CCAPI/cc_api_call_proceeding:
   Interface=0x225C2060, Progress Indication=NULL(0)
*Aug 29 15:57:31.481: //9076/121F854FA9CD/CCAPI/cc_api_call_alert:
   Interface=0x225C2060, Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
*Aug 29 15:57:31.481: //9076/121F854FA9CD/CCAPI/cc_api_call_alert:
   Call Entry(Retry Count=0, Responsed=TRUE)
*Aug 29 15:57:31.481: //9074/121F854FA9CD/CCAPI/ccCallAlert:
   Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
*Aug 29 15:57:31.481: //9074/121F854FA9CD/CCAPI/ccCallAlert:
   Call Entry(Responsed=TRUE, Alert Sent=TRUE)
*Aug 29 15:57:31.481: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_PROCEEDING, event:E_CC_ALERT]
*Aug 29 15:57:31.481: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_alert:
   Progress Indication=0, Signal Indication=1, Setup Progress Indication=3
*Aug 29 15:57:31.481: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865167
*Aug 29 15:57:31.481: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_alert:
   [Ring Back]-Tone Played In Direction [Network]htsp_alert_notify
*Aug 29 15:57:31.481: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_open_packet_path:
   Progress Indication=0
*Aug 29 15:57:31.481: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_alert:
   Progress Indication=0, Tone=Ring Back
*Aug 29 15:57:31.485: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert
*Aug 29 15:57:31.605: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=35428 systime=200865180
*Aug 29 15:57:31.605: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:57:31.605: htsp_timer2 - 350 msec
*Aug 29 15:57:31.997: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:57:31.997: htsp_timer_stop
*Aug 29 15:57:31.997: htsp_timer_stop2
*Aug 29 15:57:31.997: htsp_timer_stop3
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:57:31.997: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:57:31.997: htsp_timer_stop
*Aug 29 15:57:31.997: htsp_timer_stop2
*Aug 29 15:57:31.997: htsp_timer_stop3
*Aug 29 15:57:31.997: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:57:31.997: htsp_timer - 2000 msec
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200865219
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200865219
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x24146878
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:57:31.997: //9075/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200865219
*Aug 29 15:57:31.997: //9075/121F854FA9CF/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9075,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:57:31.997: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:31.997: :cc_free_feature_vsa freeing 210697F8
*Aug 29 15:57:31.997: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:31.997:  vsacount in free is 2
*Aug 29 15:57:31.997: //-1/121F854FA9CF/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x24146878
*Aug 29 15:57:32.173: htsp_dsp_message: SEND_SIG_STATUS: state=0x6 timestamp=35996 systime=200865236
*Aug 29 15:57:32.173: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0110]fxols_rvs_battery
*Aug 29 15:57:32.173: htsp_timer_stop2
*Aug 29 15:57:32.673: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:32.673: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=0
*Aug 29 15:57:32.673: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:32.721: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:32.721: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865291
*Aug 29 15:57:32.721: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=0
*Aug 29 15:57:32.721: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:32.881: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:32.881: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=1
*Aug 29 15:57:32.881: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:32.921: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:32.921: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865311
*Aug 29 15:57:32.921: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=1
*Aug 29 15:57:32.921: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.093: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:33.093: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=0
*Aug 29 15:57:33.093: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.133: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:33.133: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865332
*Aug 29 15:57:33.133: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=0
*Aug 29 15:57:33.133: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.301: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:33.301: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=9
*Aug 29 15:57:33.301: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.341: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:33.341: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865353
*Aug 29 15:57:33.341: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=9
*Aug 29 15:57:33.341: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.701: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:33.701: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=9
*Aug 29 15:57:33.701: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.753: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:33.753: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865394
*Aug 29 15:57:33.753: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=9
*Aug 29 15:57:33.753: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.909: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:33.909: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=0
*Aug 29 15:57:33.909: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.953: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:33.953: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865414
*Aug 29 15:57:33.953: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=0
*Aug 29 15:57:33.953: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:33.997: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:57:33.997: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200865419
*Aug 29 15:57:33.997: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:57:34.141: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:34.141: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=1
*Aug 29 15:57:34.141: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:34.165: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:34.165: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865436
*Aug 29 15:57:34.165: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=1
*Aug 29 15:57:34.165: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:34.321: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:34.321: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=9
*Aug 29 15:57:34.321: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:34.369: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:34.369: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865456
*Aug 29 15:57:34.369: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=9
*Aug 29 15:57:34.369: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:34.529: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:34.529: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=0
*Aug 29 15:57:34.529: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:34.581: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:34.581: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865477
*Aug 29 15:57:34.581: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=0
*Aug 29 15:57:34.581: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:34.745: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:57:34.745: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=9
*Aug 29 15:57:34.745: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:34.789: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:57:34.789: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865498
*Aug 29 15:57:34.789: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=9
*Aug 29 15:57:34.789: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:57:37.357: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_EVENT_TIMER]fxols_disc_confirm
*Aug 29 15:57:37.357: htsp_timer_stop
*Aug 29 15:57:37.357: htsp_timer_stop2
*Aug 29 15:57:37.357: htsp_timer_stop3
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_ALERTING, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_generate_disc:
   Cause Value=16
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865755
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200865755
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_set_release_source:
   Release Direction=PSTN, Release Source=Calling Party-PSTN
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_cc_call_disconnected:
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_cc_call_disconnected:
   Cause Value=16
*Aug 29 15:57:37.357: //9074/121F854FA9CD/CCAPI/cc_api_call_disconnected:
   Cause Value=16, Interface=0x22DE3FA0, Call Id=9074
*Aug 29 15:57:37.357: //9074/121F854FA9CD/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer:
   Timer Start Time=200865755, Timer Value=15000(ms)
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_generate_disc:
   Return Code=0
*Aug 29 15:57:37.357: //9074/121F854FA9CD/CCAPI/ccGenerateToneInfo:
   Stop Tone On Digit=FALSE, Tone=Null,
   Tone Direction=Network, Params=0x0, Call Id=9074
*Aug 29 15:57:37.357: //9076/121F854FA9CD/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:57:37.357: //9076/121F854FA9CD/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Aug 29 15:57:37.357: //9074/121F854FA9CD/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
*Aug 29 15:57:37.357: //9074/121F854FA9CD/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Aug 29 15:57:37.357: //9074/121F854FA9CD/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_HOST_DISC, event:E_CC_DISCONNECT]
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_host_disc_cleanup:
   dsm_indicate_error=0, short_cleardown_timeout=1, Mode=0
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_fax_config:
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_host_disc_cleanup:
   Exit State=16
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_dsm_dsp_stats_complete:
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer:
   Timer Start Time=200865755, Timer Value=60000(ms)
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
*Aug 29 15:57:37.357: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
*Aug 29 15:57:37.357: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:57:37.357: htsp_timer_stop
*Aug 29 15:57:37.357: htsp_timer_stop2
*Aug 29 15:57:37.361: htsp_timer_stop3
*Aug 29 15:57:37.361: [0/0/0] set signal state = 0x4 timestamp = 0
*Aug 29 15:57:37.361: htsp_timer - 1000 msec
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/act_wrelease_release:
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_play_busy_timer_stop:
   Timer Stop Time=200865755
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865755
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_do_call_history:
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:1:1/vtsp_is_valid_dsm_handle:
   DMGR=0x297B036C, VTSP CDB=0x241462B8
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/act_terminate:
*Aug 29 15:57:37.361: //9074/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200865755
*Aug 29 15:57:37.361: //9074/121F854FA9CD/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x22DE3FA0, Tag=0x0, Call Id=9074,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:57:37.361: //9074/121F854FA9CD/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Aug 29 15:57:37.361: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:37.361: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:57:37.361: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:37.361:  vsacount in free is 1
*Aug 29 15:57:37.361: //-1/121F854FA9CD/VTSP:(0/0/0):-1:-1:-1/vtsp_free_cdb:
   CDB=0x241462B8
*Aug 29 15:57:37.889: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIRemoveBranchName:
 invalid ccb, bName or branch list for sipSPIRemoveBranchName
*Aug 29 15:57:37.889: //9076/121F854FA9CD/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x225C2060, Tag=0x0, Call Id=9076,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:57:37.889: //9076/121F854FA9CD/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Aug 29 15:57:37.889: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:37.889: :cc_free_feature_vsa freeing 21069638
*Aug 29 15:57:37.889: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:37.889:  vsacount in free is 0
*Aug 29 15:57:37.889: htsp_process_event: [0/0/0, FXOLS_GUARD_OUT, E_DSP_SIG_0000]fxols_guard_out_ringing
*Aug 29 15:57:37.889: htsp_timer_stop fxols_onhook_ringing
*Aug 29 15:57:37.889: htsp_timer - 125 msec
*Aug 29 15:57:37.889: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:57:37.889: htsp_timer - 125 msec
*Aug 29 15:57:38.017: htsp_process_event: [0/0/0, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:57:38.017: htsp_timer - 10000 msec
*Aug 29 15:57:38.017: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:57:38.017: htsp_timer - 10000 msec
*Aug 29 15:57:39.441: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=42483 systime=200865886
*Aug 29 15:57:39.441: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=42483 systime=200865963
*Aug 29 15:57:39.441: htsp_process_event: [0/0/0, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:39.441: fxols_ringing_not
*Aug 29 15:57:39.441: htsp_timer_stop
*Aug 29 15:57:39.441: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:57:39.441: [0/0/0] get_fxo_caller_id:Caller ID receive failed.  parseCallerIDString:no data.
*Aug 29 15:57:39.441: [0/0/0] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig cal
led=
*Aug 29 15:57:39.441: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x24146598
*Aug 29 15:57:39.441: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_do_call_setup_ind:
   Event=E_TSP_SETUP_IND
   Progress Indication=3, CarrierIDCode=, Info Trans Capability=144, Source Carrier ID=Mobile, tg_label_flag=1
*Aug 29 15:57:39.441: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:39.441: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_timer:
   Timer Start Time=200865963, Timer Value=180000(ms)
*Aug 29 15:57:39.441: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:39.445: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:39.445: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:39.445: fxols_ringing_not
*Aug 29 15:57:39.445: htsp_timer_stop
*Aug 29 15:57:39.445: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:57:39.445: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig cal
led=
*Aug 29 15:57:39.445: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x24146878
*Aug 29 15:57:39.445: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:57:39.445: //-1/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:39.445: //-1/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200865964, Timer Value=180000(ms)
*Aug 29 15:57:39.445: //-1/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:39.445: //-1/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:39.453: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_dsm_opened_cb:
*Aug 29 15:57:39.457: //-1/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:57:39.457: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:39.457: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_setup_ind_pend_success:
*Aug 29 15:57:39.457: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_realloc_cdb:
   CDB=0x24146598
*Aug 29 15:57:39.457: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_indicate_call:
*Aug 29 15:57:39.457: //-1/16F37B00A9D7/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=100
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   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

*Aug 29 15:57:39.457: //-1/16F37B00A9D7/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x22DE3FA0, Call Info(
   Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=100(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE,
   Incoming Dial-peer=0, Progress Indication=ORIGINATING SIDE IS NON ISDN(3), Calling IE Present=FALSE,
   Source Trkgrp Route Label=Mobile, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=-1
*Aug 29 15:57:39.457: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.457: :cc_get_feature_vsa malloc success
*Aug 29 15:57:39.457: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.457:  cc_get_feature_vsa count is 1
*Aug 29 15:57:39.457: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.457: :FEATURE_VSA attributes are: feature_name:0,feature_time:554079808,feature_id:604
*Aug 29 15:57:39.457: //9077/16F37B00A9D7/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=100(TON=Unknown, NPI=Unknown))
*Aug 29 15:57:39.457: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_insert_cdb:
*Aug 29 15:57:39.457: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_indicate_call:
   Source Trkgrp Route Label=Mobile
*Aug 29 15:57:39.457: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_timer:
   Timer Start Time=200865965, Timer Value=180000(ms)
*Aug 29 15:57:39.457: //-1/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:39.461: //-1/16F41728A9D9/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:57:39.461: //-1/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x24146878
*Aug 29 15:57:39.461: //-1/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:57:39.461: //-1/16F41728A9D9/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:57:39.461: //-1/16F41728A9D9/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=FFFFFFFF
   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

*Aug 29 15:57:39.461: //-1/16F41728A9D9/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:57:39.461: //-1/16F41728A9D9/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:39.461: //-1/16F41728A9D9/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:39.461: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.461: :cc_get_feature_vsa malloc success
*Aug 29 15:57:39.461: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.461:  cc_get_feature_vsa count is 2
*Aug 29 15:57:39.461: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.461: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:605
*Aug 29 15:57:39.461: //9078/16F41728A9D9/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))
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200865965, Timer Value=180000(ms)
*Aug 29 15:57:39.461: htsp_process_event: [0/0/0, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:39.461: fxols_wait_setup_ack:
*Aug 29 15:57:39.461: htsp_timer - 6000 msec
*Aug 29 15:57:39.461: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:39.461: fxols_wait_setup_ack:
*Aug 29 15:57:39.461: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:57:39.461: //9077/16F37B00A9D7/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:57:39.461: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Try with the demoted called number 100
*Aug 29 15:57:39.461: //9077/16F37B00A9D7/CCAPI/ccCallSetContext:
   Context=0x249B8958
*Aug 29 15:57:39.461: //9077/16F37B00A9D7/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 9077 with tag 0 to app "_ManagedAppProcess_Default"
*Aug 29 15:57:39.461: //9078/16F41728A9D9/CCAPI/cc_process_call_setup_ind:
   Event=0x3E759F00
*Aug 29 15:57:39.461: %CALL_CONTROL-6-APP_NOT_FOUND: Application stcapp in dial-peer 21 not found.  Handing call
id 9078 to the alternate app .

*Aug 29 15:57:39.461: //9078/16F41728A9D9/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:57:39.461: //9078/16F41728A9D9/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:57:39.461: //9078/16F41728A9D9/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:57:39.461: //9078/16F41728A9D9/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200865965
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200865965
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200865965, Timer Value=30000(ms)
*Aug 29 15:57:39.461: htsp_pre_connect_disconnect, cdb = 24146878 cause = 3F

*Aug 29 15:57:39.461: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:57:39.461: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:57:39.461: //9077/16F37B00A9D7/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=FALSE, Mode=0,
   Outgoing Dial-peer=40005, Params=0x249B48B0, Progress Indication=ORIGINATING SIDE IS NON ISDN(3)
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/ccCallSetupRequest:
   Destination Pattern=100$, Called Number=100, Digit Strip=FALSE
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/ccCallSetupRequest:
   Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed),
   Called Number=100(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=
   Account Number=, Final Destination Flag=TRUE,
   Guid=16F37B00-AADB-11E8-A9D7-984CA2021AB0, Outgoing Dial-peer=40005
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=
   ----- ccCallInfo IE subfields -----
   cisco-ani=
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=0
   dest=100
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   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

*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x225C2060, Interface Type=3, Destination=, Mode=0x0,
   Call Params(Calling Number=,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Al
lowed),
   Called Number=100(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=RegularLine, FinalDestinationFlag=TRUE, Outgoing Dial-peer=40005, Call Count On=FALSE,
   Source Trkgrp Route Label=Mobile, Target Trkgrp Route Label=, tg_label_flag=1, Application Call Id=)
*Aug 29 15:57:39.465: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.465: :cc_get_feature_vsa malloc success
*Aug 29 15:57:39.465: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.465:  cc_get_feature_vsa count is 3
*Aug 29 15:57:39.465: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:39.465: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080256,feature_id:606
*Aug 29 15:57:39.465: //9079/16F37B00A9D7/SIP/Error/sipSPIGetCallServerGroupTargets:
 No server group configured
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_spi_event_handler:
   Event Category=1, Event=189
*Aug 29 15:57:39.465: //9079/16F37B00A9D7/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=3, FlowMode=1
*Aug 29 15:57:39.465: //9079/16F37B00A9D7/CCAPI/ccCallSetContext:
   Context=0x249B4860
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=40005
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_PROCEEDING]
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_proceeding:
   Progress Indication=0
*Aug 29 15:57:39.465: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865966
*Aug 29 15:57:39.465: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_PROCEEDING]fxols_offhook_proc
SIP: (9079) Group (a= group line) attribute, level 65535 instance 1 not found.
SIP: (9079) Group (a= group line) attribute, level 65535 instance 1 not found.
*Aug 29 15:57:39.469: //9079/16F37B00A9D7/CCAPI/cc_api_call_proceeding:
   Interface=0x225C2060, Progress Indication=NULL(0)
*Aug 29 15:57:39.793: //9079/16F37B00A9D7/CCAPI/cc_api_call_alert:
   Interface=0x225C2060, Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
*Aug 29 15:57:39.793: //9079/16F37B00A9D7/CCAPI/cc_api_call_alert:
   Call Entry(Retry Count=0, Responsed=TRUE)
*Aug 29 15:57:39.793: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:57:39.793: htsp_timer2 - 350 msec
*Aug 29 15:57:39.793: //9077/16F37B00A9D7/CCAPI/ccCallAlert:
   Progress Indication=NULL(0), Signal Indication=SIGNAL RINGBACK(1)
*Aug 29 15:57:39.793: //9077/16F37B00A9D7/CCAPI/ccCallAlert:
   Call Entry(Responsed=TRUE, Alert Sent=TRUE)
*Aug 29 15:57:39.793: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_PROCEEDING, event:E_CC_ALERT]
*Aug 29 15:57:39.793: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_alert:
   Progress Indication=0, Signal Indication=1, Setup Progress Indication=3
*Aug 29 15:57:39.793: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200865998
*Aug 29 15:57:39.793: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_alert:
   [Ring Back]-Tone Played In Direction [Network]htsp_alert_notify
*Aug 29 15:57:39.797: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_open_packet_path:
   Progress Indication=0
*Aug 29 15:57:39.797: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_alert:
   Progress Indication=0, Tone=Ring Back
*Aug 29 15:57:39.797: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_ALERT]fxols_offhook_alert
*Aug 29 15:57:40.941: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:57:40.941: htsp_timer_stop
*Aug 29 15:57:40.941: htsp_timer_stop2
*Aug 29 15:57:40.941: htsp_timer_stop3
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:57:40.941: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:57:40.941: htsp_timer_stop
*Aug 29 15:57:40.941: htsp_timer_stop2
*Aug 29 15:57:40.941: htsp_timer_stop3
*Aug 29 15:57:40.941: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:57:40.941: htsp_timer - 2000 msec
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200866113
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200866113
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:57:40.941: //9078/16F41728A9D9/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x24146878
*Aug 29 15:57:40.961: //9078/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:57:40.961: //9078/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:57:40.961: //9078/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:57:40.961: //9078/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200866116
*Aug 29 15:57:40.965: //9078/16F41728A9D9/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9078,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:57:40.965: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:40.965: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:57:40.965: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:40.965:  vsacount in free is 2
*Aug 29 15:57:40.965: //-1/16F41728A9D9/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x24146878
*Aug 29 15:57:42.601: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=46420 systime=200866279
*Aug 29 15:57:42.601: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
*Aug 29 15:57:42.601: htsp_timer_stop
*Aug 29 15:57:42.601: htsp_timer_stop2
*Aug 29 15:57:42.621: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=46440 systime=200866281
*Aug 29 15:57:42.621: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_DSP_SIG_0000]fxols_guard_out_ringing
*Aug 29 15:57:42.621: htsp_timer_stop fxols_onhook_ringing
*Aug 29 15:57:42.621: htsp_timer - 125 msec
*Aug 29 15:57:42.749: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:57:42.749: htsp_timer - 10000 msec
*Aug 29 15:57:43.701: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=47520 systime=200866389
*Aug 29 15:57:43.701: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=47521 systime=200866389
*Aug 29 15:57:43.701: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
*Aug 29 15:57:43.701: htsp_timer_stop2
*Aug 29 15:57:43.701: htsp_timer - 6000 msec
*Aug 29 15:57:43.701: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:43.701: fxols_ringing_not
*Aug 29 15:57:43.701: htsp_timer_stop
*Aug 29 15:57:43.701: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:57:43.701: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig cal
led=
*Aug 29 15:57:43.701: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x241462B8
*Aug 29 15:57:43.701: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:57:43.701: //-1/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:43.701: //-1/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200866389, Timer Value=180000(ms)
*Aug 29 15:57:43.701: //-1/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:43.701: //-1/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:43.705: //-1/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:57:43.705: //-1/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:43.705: //-1/197D8082A9E1/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:57:43.705: //-1/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x241462B8
*Aug 29 15:57:43.705: //-1/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:57:43.705: //-1/197D8082A9E1/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:57:43.705: //-1/197D8082A9E1/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=FFFFFFFF
   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

*Aug 29 15:57:43.705: //-1/197D8082A9E1/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:57:43.705: //-1/197D8082A9E1/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:43.705: //-1/197D8082A9E1/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:43.705: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:43.705: :cc_get_feature_vsa malloc success
*Aug 29 15:57:43.705: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:43.705:  cc_get_feature_vsa count is 3
*Aug 29 15:57:43.705: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:43.705: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:607
*Aug 29 15:57:43.705: //9080/197D8082A9E1/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))
*Aug 29 15:57:43.705: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:57:43.705: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200866390, Timer Value=180000(ms)
*Aug 29 15:57:43.705: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:43.705: fxols_wait_setup_ack:
*Aug 29 15:57:43.705: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:57:43.705: //9080/197D8082A9E1/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:57:43.705: //9080/197D8082A9E1/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:57:43.705: //9080/197D8082A9E1/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:57:43.705: //9080/197D8082A9E1/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:57:43.709: //9080/197D8082A9E1/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:57:43.709: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:57:43.709: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:57:43.709: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200866390
*Aug 29 15:57:43.709: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200866390
*Aug 29 15:57:43.709: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:57:43.709: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200866390, Timer Value=30000(ms)
*Aug 29 15:57:43.709: htsp_pre_connect_disconnect, cdb = 241462B8 cause = 3F

*Aug 29 15:57:43.709: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:57:43.709: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:57:44.437: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=47781 systime=200866415
*Aug 29 15:57:44.441: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:57:44.441: htsp_timer2 - 350 msec
*Aug 29 15:57:44.961: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:57:44.961: htsp_timer_stop
*Aug 29 15:57:44.961: htsp_timer_stop2
*Aug 29 15:57:44.961: htsp_timer_stop3
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:57:44.961: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:57:44.961: htsp_timer_stop
*Aug 29 15:57:44.961: htsp_timer_stop2
*Aug 29 15:57:44.961: htsp_timer_stop3
*Aug 29 15:57:44.961: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:57:44.961: htsp_timer - 2000 msec
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200866515
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200866515
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:57:44.961: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:57:44.965: //9080/197D8082A9E1/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x241462B8
*Aug 29 15:57:44.993: //9080/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:57:44.993: //9080/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:57:44.993: //9080/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:57:44.993: //9080/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200866518
*Aug 29 15:57:44.993: //9080/197D8082A9E1/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9080,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:57:44.993: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:44.993: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:57:44.993: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:44.993:  vsacount in free is 2
*Aug 29 15:57:44.993: //-1/197D8082A9E1/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x241462B8
*Aug 29 15:57:46.961: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:57:46.961: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200866715
*Aug 29 15:57:46.961: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:57:47.637: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=51458 systime=200866783
*Aug 29 15:57:47.637: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
*Aug 29 15:57:47.637: htsp_timer_stop
*Aug 29 15:57:47.637: htsp_timer_stop2
*Aug 29 15:57:47.657: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=51478 systime=200866785
*Aug 29 15:57:47.657: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:57:47.657: htsp_timer - 125 msec
*Aug 29 15:57:47.785: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:57:47.785: htsp_timer - 10000 msec
*Aug 29 15:57:48.737: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=52559 systime=200866893
*Aug 29 15:57:48.737: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=52560 systime=200866893
*Aug 29 15:57:48.737: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
*Aug 29 15:57:48.737: htsp_timer_stop2
*Aug 29 15:57:48.737: htsp_timer - 6000 msec
*Aug 29 15:57:48.737: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:48.737: fxols_ringing_not
*Aug 29 15:57:48.737: htsp_timer_stop
*Aug 29 15:57:48.737: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:57:48.737: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig cal
led=
*Aug 29 15:57:48.737: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x24146878
*Aug 29 15:57:48.737: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:57:48.737: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200866893, Timer Value=180000(ms)
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x24146878
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/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=FFFFFFFF
   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

*Aug 29 15:57:48.741: //-1/1C7DEF9BA9E5/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:57:48.745: //-1/1C7DEF9BA9E5/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:48.745: //-1/1C7DEF9BA9E5/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:48.745: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:48.745: :cc_get_feature_vsa malloc success
*Aug 29 15:57:48.745: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:48.745:  cc_get_feature_vsa count is 3
*Aug 29 15:57:48.745: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:48.745: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:608
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/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))
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200866894, Timer Value=180000(ms)
*Aug 29 15:57:48.745: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:48.745: fxols_wait_setup_ack:
*Aug 29 15:57:48.745: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:57:48.745: %CALL_CONTROL-6-APP_NOT_FOUND: Application stcapp in dial-peer 21 not found.  Handing call
id 9081 to the alternate app .

*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200866894
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200866894
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200866894, Timer Value=30000(ms)
*Aug 29 15:57:48.745: htsp_pre_connect_disconnect, cdb = 24146878 cause = 3F

*Aug 29 15:57:48.745: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:57:48.745: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:57:49.217: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=52819 systime=200866919
*Aug 29 15:57:49.217: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:57:49.217: htsp_timer2 - 350 msec
*Aug 29 15:57:49.569: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:57:49.569: htsp_timer_stop
*Aug 29 15:57:49.569: htsp_timer_stop2
*Aug 29 15:57:49.569: htsp_timer_stop3
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:57:49.569: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:57:49.569: htsp_timer_stop
*Aug 29 15:57:49.569: htsp_timer_stop2
*Aug 29 15:57:49.569: htsp_timer_stop3
*Aug 29 15:57:49.569: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:57:49.569: htsp_timer - 2000 msec
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200866976
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200866976
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x24146878
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200866976
*Aug 29 15:57:49.569: //9081/1C7DEF9BA9E5/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9081,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:57:49.569: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:49.569: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:57:49.569: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:49.569:  vsacount in free is 2
*Aug 29 15:57:49.569: //-1/1C7DEF9BA9E5/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x24146878
*Aug 29 15:57:51.569: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:57:51.569: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200867176
*Aug 29 15:57:51.569: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:57:52.677: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=56497 systime=200867287
*Aug 29 15:57:52.677: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
*Aug 29 15:57:52.677: htsp_timer_stop
*Aug 29 15:57:52.677: htsp_timer_stop2
*Aug 29 15:57:52.697: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=56518 systime=200867289
*Aug 29 15:57:52.697: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:57:52.697: htsp_timer - 125 msec
*Aug 29 15:57:52.825: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:57:52.825: htsp_timer - 10000 msec
*Aug 29 15:57:53.833: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=57593 systime=200867396
*Aug 29 15:57:53.833: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=57593 systime=200867402
*Aug 29 15:57:53.853: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
*Aug 29 15:57:53.853: htsp_timer_stop2
*Aug 29 15:57:53.853: htsp_timer - 6000 msec
*Aug 29 15:57:54.677: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:54.677: fxols_ringing_not
*Aug 29 15:57:54.677: htsp_timer_stop
*Aug 29 15:57:54.677: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:57:54.677: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig cal
led=
*Aug 29 15:57:54.677: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x241462B8
*Aug 29 15:57:54.677: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:57:54.677: //-1/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:54.677: //-1/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200867487, Timer Value=180000(ms)
*Aug 29 15:57:54.677: //-1/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:54.677: //-1/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:54.685: //-1/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:57:54.685: //-1/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:54.685: //-1/20084F12A9E9/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:57:54.685: //-1/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x241462B8
*Aug 29 15:57:54.685: //-1/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:57:54.685: //-1/20084F12A9E9/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:57:54.685: //-1/20084F12A9E9/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=FFFFFFFF
   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

*Aug 29 15:57:54.685: //-1/20084F12A9E9/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:57:54.685: //-1/20084F12A9E9/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:54.685: //-1/20084F12A9E9/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:54.685: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:54.685: :cc_get_feature_vsa malloc success
*Aug 29 15:57:54.685: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:54.685:  cc_get_feature_vsa count is 3
*Aug 29 15:57:54.685: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:54.685: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:609
*Aug 29 15:57:54.685: //9082/20084F12A9E9/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))
*Aug 29 15:57:54.685: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:57:54.685: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200867488, Timer Value=180000(ms)
*Aug 29 15:57:54.689: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:54.689: fxols_wait_setup_ack:
*Aug 29 15:57:54.689: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:57:54.689: //9082/20084F12A9E9/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:57:54.689: %CALL_CONTROL-6-APP_NOT_FOUND: Application stcapp in dial-peer 21 not found.  Handing call
id 9082 to the alternate app .

*Aug 29 15:57:54.689: //9082/20084F12A9E9/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:57:54.689: //9082/20084F12A9E9/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:57:54.689: //9082/20084F12A9E9/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:57:54.689: //9082/20084F12A9E9/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:57:54.689: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:57:54.689: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:57:54.689: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200867488
*Aug 29 15:57:54.689: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200867488
*Aug 29 15:57:54.689: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:57:54.689: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200867488, Timer Value=30000(ms)
*Aug 29 15:57:54.689: htsp_pre_connect_disconnect, cdb = 241462B8 cause = 3F

*Aug 29 15:57:54.689: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:57:54.689: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:57:55.245: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=58762 systime=200867513
*Aug 29 15:57:55.245: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:57:55.245: htsp_timer2 - 350 msec
*Aug 29 15:57:55.597: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:57:55.597: htsp_timer_stop
*Aug 29 15:57:55.597: htsp_timer_stop2
*Aug 29 15:57:55.597: htsp_timer_stop3
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:57:55.597: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:57:55.597: htsp_timer_stop
*Aug 29 15:57:55.597: htsp_timer_stop2
*Aug 29 15:57:55.597: htsp_timer_stop3
*Aug 29 15:57:55.597: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:57:55.597: htsp_timer - 2000 msec
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200867579
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200867579
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x241462B8
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:57:55.597: //9082/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200867579
*Aug 29 15:57:55.597: //9082/20084F12A9E9/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9082,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:57:55.597: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:55.597: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:57:55.597: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:57:55.597:  vsacount in free is 2
*Aug 29 15:57:55.597: //-1/20084F12A9E9/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x241462B8
*Aug 29 15:57:57.597: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:57:57.597: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200867779
*Aug 29 15:57:57.597: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:57:57.709: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=61529 systime=200867790
*Aug 29 15:57:57.709: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
*Aug 29 15:57:57.709: htsp_timer_stop
*Aug 29 15:57:57.709: htsp_timer_stop2
*Aug 29 15:57:57.729: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=61550 systime=200867792
*Aug 29 15:57:57.729: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:57:57.729: htsp_timer - 125 msec
*Aug 29 15:57:57.857: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:57:57.857: htsp_timer - 10000 msec
*Aug 29 15:57:58.809: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=62628 systime=200867900
*Aug 29 15:57:58.809: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=62629 systime=200867900
*Aug 29 15:57:58.809: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
*Aug 29 15:57:58.809: htsp_timer_stop2
*Aug 29 15:57:58.809: htsp_timer - 6000 msec
*Aug 29 15:57:58.809: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:57:58.809: fxols_ringing_not
*Aug 29 15:57:58.809: htsp_timer_stop
*Aug 29 15:57:58.809: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:57:58.809: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:57  orig cal
led=
*Aug 29 15:57:58.809: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x24146878
*Aug 29 15:57:58.809: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:57:58.809: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:57:58.809: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200867900, Timer Value=180000(ms)
*Aug 29 15:57:58.809: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:57:58.809: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x24146878
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/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=FFFFFFFF
   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

*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:58.813: //-1/227ECC9BA9ED/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:57:58.813: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:58.813: :cc_get_feature_vsa malloc success
*Aug 29 15:57:58.813: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:58.813:  cc_get_feature_vsa count is 3
*Aug 29 15:57:58.813: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:57:58.813: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:610
*Aug 29 15:57:58.813: //9083/227ECC9BA9ED/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))
*Aug 29 15:57:58.813: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:57:58.813: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200867900, Timer Value=180000(ms)
*Aug 29 15:57:58.813: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:57:58.813: fxols_wait_setup_ack:
*Aug 29 15:57:58.813: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200867901
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200867901
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200867901, Timer Value=30000(ms)
*Aug 29 15:57:58.817: htsp_pre_connect_disconnect, cdb = 24146878 cause = 3F

*Aug 29 15:57:58.817: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:57:58.817: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:57:59.753: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=62890 systime=200867926
*Aug 29 15:57:59.753: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:57:59.753: htsp_timer2 - 350 msec
*Aug 29 15:58:00.305: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:58:00.305: htsp_timer_stop
*Aug 29 15:58:00.305: htsp_timer_stop2
*Aug 29 15:58:00.305: htsp_timer_stop3
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:58:00.305: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:58:00.305: htsp_timer_stop
*Aug 29 15:58:00.305: htsp_timer_stop2
*Aug 29 15:58:00.305: htsp_timer_stop3
*Aug 29 15:58:00.305: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:58:00.305: htsp_timer - 2000 msec
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200868050
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200868050
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:58:00.305: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x24146878
*Aug 29 15:58:00.309: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:58:00.309: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:58:00.309: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:58:00.309: //9083/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200868050
*Aug 29 15:58:00.309: //9083/227ECC9BA9ED/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9083,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:58:00.309: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:00.309: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:58:00.309: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:00.309:  vsacount in free is 2
*Aug 29 15:58:00.309: //-1/227ECC9BA9ED/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x24146878
*Aug 29 15:58:02.305: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:58:02.305: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200868250
*Aug 29 15:58:02.305: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:58:02.745: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=1029 systime=200868294
*Aug 29 15:58:02.745: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
*Aug 29 15:58:02.745: htsp_timer_stop
*Aug 29 15:58:02.745: htsp_timer_stop2
*Aug 29 15:58:02.765: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=1050 systime=200868296
*Aug 29 15:58:02.765: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:58:02.765: htsp_timer - 125 msec
*Aug 29 15:58:02.893: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:58:02.893: htsp_timer - 10000 msec
*Aug 29 15:58:04.369: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=2126 systime=200868403
*Aug 29 15:58:04.369: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=2127 systime=200868456
*Aug 29 15:58:04.369: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
*Aug 29 15:58:04.369: htsp_timer_stop2
*Aug 29 15:58:04.369: htsp_timer - 6000 msec
*Aug 29 15:58:04.369: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:58:04.369: fxols_ringing_not
*Aug 29 15:58:04.369: htsp_timer_stop
*Aug 29 15:58:04.369: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:58:04.369: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:58  orig cal
led=
*Aug 29 15:58:04.369: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x241462B8
*Aug 29 15:58:04.369: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:58:04.369: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:58:04.369: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200868456, Timer Value=180000(ms)
*Aug 29 15:58:04.369: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:58:04.373: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:58:04.377: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:58:04.377: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:58:04.377: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:58:04.377: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x241462B8
*Aug 29 15:58:04.377: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:58:04.377: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:58:04.377: //-1/25CF30E7A9F1/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=FFFFFFFF
   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

*Aug 29 15:58:04.381: //-1/25CF30E7A9F1/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:58:04.381: //-1/25CF30E7A9F1/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:58:04.381: //-1/25CF30E7A9F1/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:58:04.381: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:04.381: :cc_get_feature_vsa malloc success
*Aug 29 15:58:04.381: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:04.381:  cc_get_feature_vsa count is 3
*Aug 29 15:58:04.381: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:04.381: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:611
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/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))
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200868457, Timer Value=180000(ms)
*Aug 29 15:58:04.381: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:58:04.381: fxols_wait_setup_ack:
*Aug 29 15:58:04.381: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:58:04.381: %CALL_CONTROL-6-APP_NOT_FOUND: Application stcapp in dial-peer 21 not found.  Handing call
id 9084 to the alternate app .

*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200868457
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200868457
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200868457, Timer Value=30000(ms)
*Aug 29 15:58:04.381: htsp_pre_connect_disconnect, cdb = 241462B8 cause = 3F

*Aug 29 15:58:04.381: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:58:04.381: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:58:04.781: htsp_dsp_message: SEND_SIG_STATUS: state=0xC timestamp=2919 systime=200868482
*Aug 29 15:58:04.781: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:58:04.781: htsp_timer2 - 350 msec
*Aug 29 15:58:05.133: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:58:05.133: htsp_timer_stop
*Aug 29 15:58:05.133: htsp_timer_stop2
*Aug 29 15:58:05.133: htsp_timer_stop3
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:58:05.133: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:58:05.133: htsp_timer_stop
*Aug 29 15:58:05.133: htsp_timer_stop2
*Aug 29 15:58:05.133: htsp_timer_stop3
*Aug 29 15:58:05.133: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:58:05.133: htsp_timer - 2000 msec
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200868532
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200868532
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:58:05.133: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x241462B8
*Aug 29 15:58:05.881: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:58:05.881: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:58:05.881: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:58:05.881: //9084/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200868607
*Aug 29 15:58:05.881: //9084/25CF30E7A9F1/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9084,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:58:05.881: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:05.881: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:58:05.881: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:05.881:  vsacount in free is 2
*Aug 29 15:58:05.881: //-1/25CF30E7A9F1/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x241462B8
*Aug 29 15:58:07.133: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:58:07.133: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200868732
*Aug 29 15:58:07.133: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:58:07.777: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=6062 systime=200868797
*Aug 29 15:58:07.777: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0000]fxols_proceed_ring
*Aug 29 15:58:07.777: htsp_timer_stop
*Aug 29 15:58:07.777: htsp_timer_stop2
*Aug 29 15:58:07.801: htsp_dsp_message: SEND_SIG_STATUS: state=0x0 timestamp=6083 systime=200868799
*Aug 29 15:58:07.801: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0000]fxols_onhook_ringing
*Aug 29 15:58:07.801: htsp_timer - 125 msec
*Aug 29 15:58:07.929: htsp_process_event: [0/0/1, FXOLS_WAIT_RING_MIN, E_HTSP_EVENT_TIMER]fxols_wait_ring_min_ti
mer
*Aug 29 15:58:07.929: htsp_timer - 10000 msec
*Aug 29 15:58:09.281: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=7166 systime=200868907
*Aug 29 15:58:09.281: htsp_dsp_message: SEND_SIG_STATUS: state=0x4 timestamp=7167 systime=200868947
*Aug 29 15:58:09.281: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_DSP_SIG_0100]fxols_proceed_clear
*Aug 29 15:58:09.281: htsp_timer_stop2
*Aug 29 15:58:09.281: htsp_timer - 6000 msec
*Aug 29 15:58:09.285: htsp_process_event: [0/0/1, FXOLS_RINGING, E_DSP_SIG_0100]
*Aug 29 15:58:09.285: fxols_ringing_not
*Aug 29 15:58:09.285: htsp_timer_stop
*Aug 29 15:58:09.285: htsp_timer_stop3 htsp_setup_ind
*Aug 29 15:58:09.285: [0/0/1] get_local_station_id calling num= calling name= calling time=08/29 17:58  orig cal
led=
*Aug 29 15:58:09.285: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x24146878
*Aug 29 15:58:09.285: //-1/xxxxxxxxxxxx/VTSP:(0/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
*Aug 29 15:58:09.285: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Aug 29 15:58:09.285: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_timer:
   Timer Start Time=200868948, Timer Value=180000(ms)
*Aug 29 15:58:09.285: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   IC State Machine (ICSM) Added
*Aug 29 15:58:09.285: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:58:09.293: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_dsm_opened_cb:
*Aug 29 15:58:09.293: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:58:09.293: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/act_setup_ind_pend_success:
*Aug 29 15:58:09.293: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_realloc_cdb:
   CDB=0x24146878
*Aug 29 15:58:09.293: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_indicate_call:
*Aug 29 15:58:09.293: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/is_secondary_dialtone_disabled:
   DID=TRUE
*Aug 29 15:58:09.293: //-1/28BD5056A9F5/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=FFFFFFFF
   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

*Aug 29 15:58:09.297: //-1/28BD5056A9F5/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x3E7C57A4, 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=TRUE,
   Incoming Dial-peer=21, 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
*Aug 29 15:58:09.297: //-1/28BD5056A9F5/CCAPI/ccCheckClipClir:
   In: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:58:09.297: //-1/28BD5056A9F5/CCAPI/ccCheckClipClir:
   Out: Calling Number=(TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed)
*Aug 29 15:58:09.297: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:09.297: :cc_get_feature_vsa malloc success
*Aug 29 15:58:09.297: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:09.297:  cc_get_feature_vsa count is 3
*Aug 29 15:58:09.297: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:09.297: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080032,feature_id:612
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/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))
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_insert_cdb:
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200868949, Timer Value=180000(ms)
*Aug 29 15:58:09.297: htsp_process_event: [0/0/1, FXOLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]
*Aug 29 15:58:09.297: fxols_wait_setup_ack:
*Aug 29 15:58:09.297: [0/0/1] set signal state = 0xC timestamp = 0fxols_check_auto_call
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/CCAPI/cc_set_release_source:
   Release Source=Internal Release-Call Control App
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/CCAPI/ccCallDisconnect:
   Cause Value=63, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/CCAPI/ccCallDisconnect:
   Cause Value=63, Call Entry(Responsed=TRUE, Cause Value=63)
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_DISCONNECT]
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Cause Value=63, Hairpin=FALSE
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200868949
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200868949
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   [Fast Busy]-Tone Played In Direction [Network]
*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_timer:
   Timer Start Time=200868949, Timer Value=30000(ms)
*Aug 29 15:58:09.297: htsp_pre_connect_disconnect, cdb = 24146878 cause = 3F

*Aug 29 15:58:09.297: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/act_pre_con_disconnect:
   Tone=Fast Busy, Tone Timeout=30(s), Progress Indication Sent=0
*Aug 29 15:58:09.297: htsp_process_event: [0/0/1, FXOLS_PROCEEDING, E_HTSP_PRE_CONN_DISC]
*Aug 29 15:58:09.301: //-1/xxxxxxxxxxxx/SIP/Error/httpish_msg_free:
 Freeing NULL pointer!
SIP: (9086) Attribute mid, level 1 instance 1 not found.
SIP: (9086) setup attribute, level 1 instance 1 not found.
SIP: (9086) connection attribute, level 1 instance 1 not found.
SIP: (9086) Attribute label, level 1 instance 1 not found.
SIP: (9086) a=framerate attribute, level 1 instance 1 not found.
SIP: (9086) Attribute ptime, level 1 instance 1 not found.
SIP: (9086) Attribute ptime, level 1 instance 1 not found.
*Aug 29 15:58:09.305: //-1/28BFC18EA9F9/CCAPI/cc_api_display_ie_subfields:
   cc_api_call_setup_ind_common:
   cisco-username=112
   ----- ccCallInfo IE subfields -----
   cisco-ani=112
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=1
   dest=9
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

*Aug 29 15:58:09.305: //-1/28BFC18EA9F9/CCAPI/cc_api_call_setup_ind_common:
   Interface=0x225C2060, Call Info(
   Calling Number=112,(Calling Name=)(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),
   Called Number=9(TON=Unknown, NPI=Unknown),
   Calling Translated=FALSE, Subscriber Type Str=Unknown, FinalDestinationFlag=FALSE,
   Incoming Dial-peer=40013, Progress Indication=NULL(0), Calling IE Present=TRUE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=, CLID Transparent=FALSE), Call Id=9086
*Aug 29 15:58:09.305: //-1/28BFC18EA9F9/CCAPI/ccCheckClipClir:
   In: Calling Number=112(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
*Aug 29 15:58:09.305: //-1/28BFC18EA9F9/CCAPI/ccCheckClipClir:
   Out: Calling Number=112(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
*Aug 29 15:58:09.305: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:09.305: :cc_get_feature_vsa malloc success
*Aug 29 15:58:09.305: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:09.305:  cc_get_feature_vsa count is 4
*Aug 29 15:58:09.305: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:09.305: :FEATURE_VSA attributes are: feature_name:0,feature_time:554079584,feature_id:613
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/cc_api_call_setup_ind_common:
   Set Up Event Sent;
   Call Info(Calling Number=112(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),
   Called Number=9(TON=Unknown, NPI=Unknown))
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/cc_process_call_setup_ind:
   Event=0x3E75C018
*Aug 29 15:58:09.305: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search:
   Try with the demoted called number 9
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/ccCallSetContext:
   Context=0x249B32B8
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/cc_process_call_setup_ind:
   >>>>CCAPI handed cid 9086 with tag 40013 to app "_ManagedAppProcess_Default"
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/ccCallSetupAck:
   Call Id=9086
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/cc_api_set_transfer_info:
   Transfer Number=, Transfer Reason=0x0
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/ccSetDigitTimeouts:
   Initial Digit Timeout=10000(ms), Inter Digit Timeout=10000(ms)
*Aug 29 15:58:09.305: //9086/28BFC18EA9F9/CCAPI/ccSetDigitTimeouts:
   Call Entry(Inter Digit Timeout=10000(ms), Initial Digit Timeout=10000(ms))
*Aug 29 15:58:09.309: //9086/28BFC18EA9F9/CCAPI/ccCallReportDigits:
   (callID=0x237E, digit_event=0x1, enable=TRUE, consume=FALSE)
*Aug 29 15:58:09.309: //9086/28BFC18EA9F9/CCAPI/ccCallReportDigits:
   Enabled=TRUE, Call Id=9086
*Aug 29 15:58:09.309: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIGetDialogParamStr:
 Invalid parameters
*Aug 29 15:58:09.477: //9086/28BFC18EA9F9/CCAPI/cc_api_call_report_digits_done:
   (vdbPtr=0x225C2060, callID=0x237E, disp=0, digit_event=0x1, enable=TRUE, consume=FALSE)
*Aug 29 15:58:09.477: //9086/28BFC18EA9F9/CCAPI/cc_api_call_report_digits_done:
   Enabled=TRUE, Disposition=0x0, Interface=0x225C2060, Call Id=9086
*Aug 29 15:58:09.477: //9086/28BFC18EA9F9/CCAPI/cc_api_call_report_digits_done:
   Call Entry(Initial Digit Timeout=10000(ms), Inter Digit Timeout=10000(ms))
*Aug 29 15:58:09.477: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:10.301: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:10.301: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=0, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:10.301: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=0, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:10.301: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:10.301: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_DSP_SIG_1100]fxols_offhook_disc
*Aug 29 15:58:10.301: htsp_timer2 - 350 msec
*Aug 29 15:58:10.889: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:10.889: htsp_process_event: [0/0/1, FXOLS_OFFHOOK, E_HTSP_EVENT_TIMER2]fxols_disc_confirm
*Aug 29 15:58:10.889: htsp_timer_stop
*Aug 29 15:58:10.889: htsp_timer_stop2
*Aug 29 15:58:10.889: htsp_timer_stop3
*Aug 29 15:58:10.889: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_NC, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:58:10.889: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
*Aug 29 15:58:10.889: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/act_pre_con_disc_rel:
   Cause Value=63
*Aug 29 15:58:10.889: htsp_process_event: [0/0/1, FXOLS_REMOTE_RELEASE, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:58:10.889: htsp_timer_stop
*Aug 29 15:58:10.889: htsp_timer_stop2
*Aug 29 15:58:10.889: htsp_timer_stop3
*Aug 29 15:58:10.889: [0/0/1] set signal state = 0x4 timestamp = 0
*Aug 29 15:58:10.893: htsp_timer - 2000 msec
*Aug 29 15:58:10.893: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_process_event:
   [state:S_WAIT_RELEASE_RESP, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:58:10.893: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/act_wrelease_release:
*Aug 29 15:58:10.893: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_play_busy_timer_stop:
   Timer Stop Time=200869108
*Aug 29 15:58:10.893: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_timer_stop:
   Timer Stop Time=200869108
*Aug 29 15:58:10.893: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
*Aug 29 15:58:10.893: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:58:10.893: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:1:3/vtsp_is_valid_dsm_handle:
   DMGR=0x3FA4F410, VTSP CDB=0x24146878
*Aug 29 15:58:10.909: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:58:10.909: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:58:10.909: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/act_terminate:
*Aug 29 15:58:10.909: //9085/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200869110
*Aug 29 15:58:10.909: //9085/28BD5056A9F5/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x3E7C57A4, Tag=0x0, Call Id=9085,
   Call Entry(Disconnect Cause=63, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:58:10.909: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:10.909: :cc_free_feature_vsa freeing 21069718
*Aug 29 15:58:10.909: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:10.909:  vsacount in free is 3
*Aug 29 15:58:10.909: //-1/28BD5056A9F5/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x24146878
*Aug 29 15:58:10.909: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=1, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:10.909: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=1, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:10.909: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:12.029: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:12.029: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=2, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:12.029: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=2, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:12.029: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:12.341: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:12.345: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=2, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:12.345: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=2, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:12.345: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:13.701: htsp_process_event: [0/0/1, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:58:13.705: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200869390
*Aug 29 15:58:13.705: htsp_process_event: [0/0/1, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:58:13.709: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:13.713: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=3, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:13.713: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=3, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:13.713: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:13.925: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:13.925: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=1, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:13.925: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=1, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:13.925: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:14.741: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:14.741: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=5, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:14.741: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=5, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:14.741: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:15.217: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:15.221: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=2, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:15.221: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=2, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:15.221: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:16.037: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:16.041: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_EVENT_TIMER]fxols_disc_confirm
*Aug 29 15:58:16.041: htsp_timer_stop
*Aug 29 15:58:16.041: htsp_timer_stop2
*Aug 29 15:58:16.041: htsp_timer_stop3
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_ALERTING, event:E_TSP_DISCONNECT_IND]
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_generate_disc:
   Cause Value=16
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200869623
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200869623
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_set_release_source:
   Release Direction=PSTN, Release Source=Calling Party-PSTN
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_cc_call_disconnected:
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_cc_call_disconnected:
   Cause Value=16
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/CCAPI/cc_api_call_disconnected:
   Cause Value=16, Interface=0x22DE3FA0, Call Id=9077
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/CCAPI/cc_api_call_disconnected:
   Call Entry(Responsed=TRUE, Cause Value=16, Retry Count=0)
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_timer:
   Timer Start Time=200869623, Timer Value=15000(ms)
*Aug 29 15:58:16.041: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_generate_disc:
   Return Code=0
*Aug 29 15:58:16.045: //9077/16F37B00A9D7/CCAPI/ccGenerateToneInfo:
   Stop Tone On Digit=FALSE, Tone=Null,
   Tone Direction=Network, Params=0x0, Call Id=9077
*Aug 29 15:58:16.045: //9079/16F37B00A9D7/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=0)
*Aug 29 15:58:16.045: //9079/16F37B00A9D7/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Aug 29 15:58:16.045: //9077/16F37B00A9D7/CCAPI/ccCallDisconnect:
   Cause Value=16, Tag=0x0, Call Entry(Previous Disconnect Cause=0, Disconnect Cause=16)
*Aug 29 15:58:16.045: //9077/16F37B00A9D7/CCAPI/ccCallDisconnect:
   Cause Value=16, Call Entry(Responsed=TRUE, Cause Value=16)
*Aug 29 15:58:16.045: //9077/16F37B00A9D7/CCAPI/cc_api_get_transfer_info:
   Transfer Number=NULL
*Aug 29 15:58:16.045: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_HOST_DISC, event:E_CC_DISCONNECT]
*Aug 29 15:58:16.045: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_host_disc_cleanup:
   dsm_indicate_error=0, short_cleardown_timeout=1, Mode=0
*Aug 29 15:58:16.045: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_fax_config:
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_host_disc_cleanup:
   Exit State=16
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_dsm_dsp_stats_complete:
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_timer:
   Timer Start Time=200869624, Timer Value=60000(ms)
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
*Aug 29 15:58:16.049: htsp_process_event: [0/0/0, FXOLS_PROCEEDING, E_HTSP_RELEASE_REQ]fxols_offhook_release
*Aug 29 15:58:16.049: htsp_timer_stop
*Aug 29 15:58:16.049: htsp_timer_stop2
*Aug 29 15:58:16.049: htsp_timer_stop3
*Aug 29 15:58:16.049: [0/0/0] set signal state = 0x4 timestamp = 0
*Aug 29 15:58:16.049: htsp_timer - 1000 msec
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/act_wrelease_release:
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_play_busy_timer_stop:
   Timer Stop Time=200869624
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200869624
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_do_call_history:
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_do_call_history:
   Coder Rate=-1
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:1:1/vtsp_is_valid_dsm_handle:
   DMGR=0x297B036C, VTSP CDB=0x24146598
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_dsm_closed_cb:
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/act_terminate:
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=200869624
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x22DE3FA0, Tag=0x0, Call Id=9077,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:58:16.049: //9077/16F37B00A9D7/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Aug 29 15:58:16.049: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:16.049: :cc_free_feature_vsa freeing 21069638
*Aug 29 15:58:16.053: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:16.053:  vsacount in free is 2
*Aug 29 15:58:16.053: //-1/16F37B00A9D7/VTSP:(0/0/0):-1:-1:-1/vtsp_free_cdb:
   CDB=0x24146598
*Aug 29 15:58:16.053: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=0, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:16.053: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=0, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:16.053: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:16.673: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIRemoveBranchName:
 invalid ccb, bName or branch list for sipSPIRemoveBranchName
*Aug 29 15:58:16.673: //9079/16F37B00A9D7/CCAPI/cc_api_call_disconnect_done:
   Disposition=0, Interface=0x225C2060, Tag=0x0, Call Id=9079,
   Call Entry(Disconnect Cause=16, Voice Class Cause Code=0, Retry Count=0)
*Aug 29 15:58:16.673: //9079/16F37B00A9D7/CCAPI/cc_api_call_disconnect_done:
   Call Disconnect Event Sent
*Aug 29 15:58:16.673: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:16.673: :cc_free_feature_vsa freeing 210697F8
*Aug 29 15:58:16.673: //-1/xxxxxxxxxxxx/CCAPI/cc_free_feature_vsa:

*Aug 29 15:58:16.673:  vsacount in free is 1
*Aug 29 15:58:16.677: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:16.681: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=9, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:16.681: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=9, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:16.681: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:17.517: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:17.517: htsp_process_event: [0/0/0, FXOLS_GUARD_OUT, E_HTSP_EVENT_TIMER]fxols_guard_out_timeout
*Aug 29 15:58:17.517: fxols_dsp_prealloc_clid_wait. Line reversal alerting DSP preallocation done
*Aug 29 15:58:17.517: [0/0/0] htsp_start_caller_id_rx:Mode BELLCORE. Alerting 0x1
*Aug 29 15:58:17.517: htsp_start_caller_id_rx create dsp_stream_manager
*Aug 29 15:58:17.521: htsp_dsp_message: RESP_SIG_STATUS: state=0x4 timestamp=0 systime=200869771
*Aug 29 15:58:17.533: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_DSP_SIG_0100]
*Aug 29 15:58:17.537: [0/0/0] htsp_dsm_create_success  returns 1
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_begin:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=0, DigitBeginFlags=0x0,
   Rtp Timestamp=0x0, Rtp Expiration=0x0
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Destination Interface=0x0, Destination Mask=0x1, Destination Call Id=-1,
   Source Call Id=9086, Digit=0, Duration=250,
   Xrule Calling Tag=0, Xrule Called Tag=0, Digit Tone Mode=DTMF
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/cc_api_call_digit_end:
   Call Entry(Handoff Depth=0)
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/ccCallReportDigits:
   (callID=0x237E, digit_event=0x0, enable=FALSE, consume=FALSE)
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/ccCallReportDigits:
   Enabled=TRUE, Call Id=9086
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/cc_api_call_report_digits_done:
   (vdbPtr=0x225C2060, callID=0x237E, disp=0, digit_event=0x0, enable=FALSE, consume=FALSE)
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/cc_api_call_report_digits_done:
   Enabled=TRUE, Disposition=0x0, Interface=0x225C2060, Call Id=9086
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/cc_api_call_report_digits_done:
   Call Entry(Initial Digit Timeout=10000(ms), Inter Digit Timeout=10000(ms))
*Aug 29 15:58:17.541: //-1/xxxxxxxxxxxx/SIP/Error/sipSPIGetDialogParamStr:
 Invalid parameters
*Aug 29 15:58:17.541: //9086/28BFC18EA9F9/CCAPI/ccCallProceeding:
   Progress Indication=NULL(0)
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccCallSetupRequest:
   Destination=, Calling IE Present=TRUE, Mode=0,
   Outgoing Dial-peer=4, Params=0x249B7400, Progress Indication=NULL(0)
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/cc_fill_tg_params:
   Not a cic call
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccCallSetupRequest:
   Trunk Group Select Interface Success;
   Interface=0x22DE3FA0, Selected Interface=1, Selected DSL=-1
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccCheckClipClir:
   In: Calling Number=112(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccCheckClipClir:
   Out: Calling Number=112(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed)
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccCallSetupRequest:
   Destination Pattern=901[012]........, Called Number=901223152090, Digit Strip=TRUE
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccCallSetupRequest:
   Calling Number=112(TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed),
   Called Number=901223152090(TON=Unknown, NPI=Unknown),
   Redirect Number=, Display Info=Omar Mohamed
   Account Number=112, Final Destination Flag=FALSE,
   Guid=28BFC18E-AADB-11E8-A9F9-984CA2021AB0, Outgoing Dial-peer=4
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/cc_api_display_ie_subfields:
   ccCallSetupRequest:
   cisco-username=112
   ----- ccCallInfo IE subfields -----
   cisco-ani=112
   cisco-anitype=0
   cisco-aniplan=0
   cisco-anipi=0
   cisco-anisi=1
   dest=901223152090
   cisco-desttype=0
   cisco-destplan=0
   cisco-rdie=FFFFFFFF
   cisco-rdn=
   cisco-rdntype=0
   cisco-rdnplan=0
   cisco-rdnpi=-1
   cisco-rdnsi=-1
   cisco-redirectreason=-1   fwd_final_type =0
   final_redirectNumber =
   hunt_group_timeout =0

*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccIFCallSetupRequestPrivate:
   Interface=0x22DE3FA0, Interface Type=6, Destination=, Mode=0x0,
   Call Params(Calling Number=112,(Calling Name=Omar Mohamed)(TON=Unknown, NPI=Unknown, Screening=User, Passed,
Presentation=Allowed),
   Called Number=901223152090(TON=Unknown, NPI=Unknown), Calling Translated=FALSE,
   Subscriber Type Str=Unknown, FinalDestinationFlag=FALSE, Outgoing Dial-peer=4, Call Count On=FALSE,
   Source Trkgrp Route Label=, Target Trkgrp Route Label=Mobile, tg_label_flag=2, Application Call Id=)
*Aug 29 15:58:17.545: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:17.545: :cc_get_feature_vsa malloc success
*Aug 29 15:58:17.545: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:17.545:  cc_get_feature_vsa count is 2
*Aug 29 15:58:17.545: //-1/xxxxxxxxxxxx/CCAPI/cc_get_feature_vsa:

*Aug 29 15:58:17.545: :FEATURE_VSA attributes are: feature_name:0,feature_time:554080256,feature_id:614
*Aug 29 15:58:17.545: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x241462B8
*Aug 29 15:58:17.545: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_insert_cdb:
*Aug 29 15:58:17.545: //9087/28BFC18EA9F9/CCAPI/ccIFCallSetupRequestPrivate:
   SPI Call Setup Request Is Success; Interface Type=6, FlowMode=1
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccCallSetupRequest:
   Trunk Group Call Setting;
   Call Entry(Retry Count=0, Voice Class Cause Code=0)
*Aug 29 15:58:17.545: //9087/28BFC18EA9F9/CCAPI/ccCallSetContext:
   Context=0x249B73B0
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/ccSaveDialpeerTag:
   Outgoing Dial-peer=4
*Aug 29 15:58:17.545: //-1/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_process_event:
   [state:INVALID STATE MACHINE, event:E_CC_SETUP_REQ]
*Aug 29 15:58:17.545: //9087/xxxxxxxxxxxx/VTSP:(0/0/0):-1:-1:-1/vtsp_og_call_req:
   Target Trkgrp Route Label=Mobile
*Aug 29 15:58:17.545: //9086/28BFC18EA9F9/CCAPI/cc_api_modify_tgt_cid_call_active_record:
   Target Trkgrp Route Label=Mobile, tg_label_flag=TRUE, Call Id=0x237E
*Aug 29 15:58:17.545: htsp_timer_stop3
*Aug 29 15:58:17.545: [0/0/0] htsp_stop_caller_id_rx. message length 0
*Aug 29 15:58:17.545: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:-1:-1/vtsp_og_call_req:
   Echo Cancel=TRUE, Gain Control=0
   Auto Gain Control=FALSE, Dual Tone Detect Mask=0x0, Seq Tone Detect=FALSE
*Aug 29 15:58:17.545: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:-1:-1/vtsp_do_call_setup_req:
*Aug 29 15:58:17.549: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_opened_cb:
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_REQ_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_req_pend_succ:
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_request_call:
   Mode=0, Peer=4
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_create_call_active_on_setup_req:
   Target Trkgrp Route Label=Mobile
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_create_call_active_on_setup_req:
   Source Trkgrp Route Label=htsp_setup_req
*Aug 29 15:58:17.553:  Orig called num:901223152090
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_request_call:
   Progress Indication=0, Info Trans Capability=0
   Calling Number=112, TON=Unknown, NPI=Unknown, Screening=User, Passed, Presentation=Allowed
   Called Number=901223152090, TON=Unknown, NPI=Unknown
*Aug 29 15:58:17.553: [0/0/0] htsp_dsm_close_done
*Aug 29 15:58:17.553: htsp_process_event: [0/0/0, FXOLS_ONHOOK, E_HTSP_SETUP_REQ]fxols_onhook_setup
*Aug 29 15:58:17.553: [0/0/0] set signal state = 0xC timestamp = 0
*Aug 29 15:58:17.553: htsp_timer - 1300 msec
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_REQUEST, event:E_TSP_PROCEEDING]
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_pend_proceeding:
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer:
   Timer Start Time=200869774, Timer Value=25000(ms)
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/CCAPI/cc_api_call_proceeding:
   Interface=0x22DE3FA0, Progress Indication=NULL(0)
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_pend_proceeding:
   Peer=4, Progress Indication=0, Return Code=2
*Aug 29 15:58:17.553: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_opened_cb:
*Aug 29 15:58:17.557: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_NULL, event:E_VTSP_DSM_OPEN_SUCCESS]
*Aug 29 15:58:17.557: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_req_wait_pend_success:
   Event=76
*Aug 29 15:58:17.557: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200869775
*Aug 29 15:58:18.257: //-1/xxxxxxxxxxxx/SIP/Error/is_sip_pass_through_configured_for_sn_event:

 Invalid values
*Aug 29 15:58:19.313: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_TONE, E_HTSP_EVENT_TIMER]fxols_wait_dial_timer
  htsp_dial
*Aug 29 15:58:19.313: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_TSP_DIAL]
*Aug 29 15:58:19.313: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_pend_dial:
   Digits=01223152090, Tone Mode=0
*Aug 29 15:58:19.313: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dial:
*Aug 29 15:58:19.313: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/ds_do_dial:
   Digits To Dial=01223152090
*Aug 29 15:58:19.389: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:19.389: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=0
*Aug 29 15:58:19.389: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870043
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=0
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=1
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870043
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=1
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=2
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870043
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=2
*Aug 29 15:58:20.237: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=2
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870044
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=2
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=3
*Aug 29 15:58:20.245: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.453: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:20.453: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870064
*Aug 29 15:58:20.453: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=3
*Aug 29 15:58:20.453: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:20.453: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:20.453: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=1
*Aug 29 15:58:20.453: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870152
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=1
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=5
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870152
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=5
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=2
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870152
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=2
*Aug 29 15:58:21.325: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=0
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870153
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=0
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=9
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870153
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=9
*Aug 29 15:58:21.337: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=0
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=200870210
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=0
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_dial_done_cb:
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_DS_DIALING, event:E_VTSP_DSM_DIALING_COMPLETE]
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/ds_dialing:
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/ds_do_dial:
   Digits To Dial=
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_digit_pop:
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_pend_dial_comp:
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/ds_do_dial:exit@571
*Aug 29 15:58:21.909: htsp_process_event: [0/0/0, FXOLS_WAIT_DIAL_DONE, E_DSP_DIALING_DONE]fxols_wait_dial_done
htsp_progress
*Aug 29 15:58:21.909: htsp_timer - 350 msec
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_TSP_PROGRESS]
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_pend_progress:
   Progress Indication=8, Signal Indication=2, cdb->answer_supervision=0
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/CCAPI/cc_api_call_cut_progress:
   Interface=0x22DE3FA0, Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2),
   Cause Value=0
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/CCAPI/cc_api_call_cut_progress:
   Call Entry(Responsed=TRUE)
*Aug 29 15:58:21.909: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_ring_noan_timer_start:
   Timer Start Time=200870210, No Answer Timer Value=180000(ms)
*Aug 29 15:58:21.913: //9086/28BFC18EA9F9/CCAPI/ccCallCutProgress:
   Progress Indication=INBAND(8), Signal Indication=INTERCEPT(2), Cause Value=0
   Voice Call Send Alert=FALSE, Call Entry(Alert Sent=FALSE)
*Aug 29 15:58:21.913: //9086/28BFC18EA9F9/CCAPI/ccCallCutProgress:
   Call Entry(Responsed=TRUE)
*Aug 29 15:58:21.913: //9086/28BFC18EA9F9/CCAPI/ccConferenceCreate:
   (confID=0xFFFFFFFF, callID1=0x237E, gcid=28BFC18E-AADB11E8-A9FC984C-A2021AB0, tag=0x0)
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/CCAPI/ccConferenceCreate:
   (confID=0xFFFFFFFF, callID2=0x237F, gcid=28BFC18E-AADB11E8-A9FC984C-A2021AB0, tag=0x0)
*Aug 29 15:58:21.913: //9086/28BFC18EA9F9/CCAPI/ccConferenceCreate:
   Conference Id=0xFFFFFFFF, Call Id1=9086, Call Id2=9087, Tag=0x0
*Aug 29 15:58:21.913: //9086/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Aug 29 15:58:21.913: cc_api_get_xcode_stream : 4982
*Aug 29 15:58:21.913: //9086/xxxxxxxxxxxx/CCAPI/cc_api_get_xcode_stream:

*Aug 29 15:58:21.913: cc_api_get_xcode_stream : 4982
*Aug 29 15:58:21.913: //9086/28BFC18EA9F9/CCAPI/cc_api_bridge_done:
   Conference Id=0xB7, Source Interface=0x225C2060, Source Call Id=9086,
   Destination Call Id=9087, Disposition=0x0, Tag=0x0
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_bridge_check_cb:
*Aug 29 15:58:21.913: htsp_call_bridged invoked
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_bridge_check_cb:exit@1505
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_bridge_status_cb:
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/CCAPI/cc_api_bridge_done:
   Conference Id=0xB7, Source Interface=0x22DE3FA0, Source Call Id=9087,
   Destination Call Id=9086, Disposition=0x0, Tag=0xFFFFFFFF
*Aug 29 15:58:21.913: //9086/28BFC18EA9F9/CCAPI/cc_generic_bridge_done:
   Conference Id=0xB7, Source Interface=0x22DE3FA0, Source Call Id=9087,
   Destination Call Id=9086, Disposition=0x0, Tag=0xFFFFFFFF
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_fax_config:
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_fax_config:
   Fax Relay=DISABLED - 'fax protocol pass-through' set (global)
   Primary Fax Protocol=FAXPASSTHROUGH_FAX, Fallback Fax Protocol=IGNORE_FAX_RELAY
   Fax Relay CM Suppression :=DISABLED, Fax Relay ANS Suppression :=DISABLED
   Fax Parameters Set By=Dialpeer, Peer=40013
*Aug 29 15:58:21.913: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_fax_config:
   Passthrough Codec=g711ulaw
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_set_fax_feat_param:
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_tty_config:
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_save_tty_config:
   Save TTY configuration
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_set_tty_feat_param:
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_set_tty_feat_param:
   Set TTY feat parameters
*Aug 29 15:58:21.917: //9086/28BFC18EA9F9/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0xB7, Destination Call Id=9087)
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/CCAPI/ccConferenceCreate:
   Call Entry(Conference Id=0xB7, Destination Call Id=9086)
*Aug 29 15:58:21.917: //9086/28BFC18EA9F9/CCAPI/ccConferenceCreate:

*Aug 29 15:58:21.917: confID:0xB7; callEntry1 callID1:0x237E, type:3; callEntry2 callID2:0x237F, type:6

*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_CC_DO_CAPS_IND]
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_peer_event_cb:
   Event=E_DSM_CC_CAPS_IND
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/CCAPI/cc_api_caps_ind:
   Destination Interface=0x225C2060, Destination Call Id=9086, Source Call Id=9087,
   Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x1,
   Modem=0x2, Codec Bytes=20, Signal Type=3)
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/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 29 15:58:21.917: //9086/28BFC18EA9F9/CCAPI/cc_api_caps_ind:
   Destination Interface=0x22DE3FA0, Destination Call Id=9087, Source Call Id=9086,
   Caps(Codec=0x1, Fax Rate=0x1, Fax Version:=0, Vad=0x2,
   Modem=0x0, Codec Bytes=160, Signal Type=2)
*Aug 29 15:58:21.917: //9086/28BFC18EA9F9/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 29 15:58:21.917: //9086/28BFC18EA9F9/CCAPI/cc_api_caps_ack:
   Destination Interface=0x22DE3FA0, Destination Call Id=9087, Source Call Id=9086,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Fax Version:=0, Vad=ON(0x2),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=7281)
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_CC_CAPS_IND]
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_peer_event_cb:
   Event=E_DSM_CC_CAPS_ACK
*Aug 29 15:58:21.917: //9087/28BFC18EA9F9/CCAPI/cc_api_caps_ack:
   Destination Interface=0x225C2060, Destination Call Id=9086, Source Call Id=9087,
   Caps(Codec=g711ulaw(0x1), Fax Rate=FAX_RATE_NONE(0x1), Fax Version:=0, Vad=ON(0x2),
   Modem=OFF(0x0), Codec Bytes=160, Signal Type=2, Seq Num Start=7281)
*Aug 29 15:58:21.917: //9086/28BFC18EA9F9/CCAPI/ccCallNotify:
   Data Bitmask=0x7, Call Id=9086
*Aug 29 15:58:21.917: //9086/28BFC18EA9F9/CCAPI/ccCallNotify:
   Data Bitmask=0x7, Call Id=9086
*Aug 29 15:58:21.917: //9086/28BFC18EA9F9/SIP/Error/sipSPI_ipip_set_history_info_header:
 Not SIP2SIP mode
*Aug 29 15:58:21.917: //9086/28BFC18EA9F9/CCAPI/cc_process_notify_bridge_done:
   Conference Id=0xB7, Call Id1=9086, Call Id2=9087
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_feature_notify_cb:
   Feature ID=0, Feature Status=1
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_reactivate_ringback:
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_dsm_reactivate_ringback:exit@1296
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/CCAPI/cc_api_voice_mode_event:
   Call Id=9087
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/CCAPI/cc_api_voice_mode_event:
   Call Entry(Context=0x249B73B0)
*Aug 29 15:58:21.921: htsp_process_event: [0/0/0, FXOLS_WAIT_CUT_THRU, E_HTSP_VOICE_CUT_THROUGH]fxols_handle_cut
_thru
*Aug 29 15:58:21.921: htsp_timer_stop
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_TSP_CONNECT]
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/act_setup_pend_connect:
   Progress Indication=2
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/VTSP:(0/0/0):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=200870211
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/CCAPI/cc_api_call_connected:
   Interface=0x22DE3FA0, Data Bitmask=0x1, Progress Indication=DESTINATION IS NON ISDN(2),
   Connection Handle=0
*Aug 29 15:58:21.921: //9087/28BFC18EA9F9/CCAPI/cc_api_call_connected:
   Call Entry(Connected=TRUE, Responsed=TRUE, Retry Count=0)
*Aug 29 15:58:21.921: //9086/28BFC18EA9F9/CCAPI/ccCallConnect:
   Progress Indication=DESTINATION IS NON ISDN(2), Data Bitmask=0x1
*Aug 29 15:58:21.921: //9086/28BFC18EA9F9/CCAPI/ccCallConnect:
   Call Entry(Connected=TRUE, Responsed=TRUE)
*Aug 29 15:58:21.921: //9086/28BFC18EA9F9/CCAPI/ccCallNotify:
   Data Bitmask=0x7, Call Id=9086
*Aug 29 15:58:21.921: //9086/28BFC18EA9F9/SIP/Error/sipSPI_ipip_set_history_info_header:
 Not SIP2SIP mode