VG 224 getting a fast busy tone whenever dialing the digits

Mohammed Saifuddin · ‎05-17-2015

HI All,

Facing a strange issue for Vg 224 gateway connected the analog polycom phone

whenever we are trying to make a call we are getting a fast busy tone and not able to make any outgoing calls internally and externally.

As per the call flow:

Polycom phone to analog port [MGCP]>> CUCM>> PRI

as per the internal calls the css and partition are perfect as we are able to make calls via Ip phones and able to receive calls.

Getting a dial tone when  onhook

Below is the debug for Vtsp all



-===========================

*Dec 30 08:51:19.427: [2/18] c2400_report_sig_state: ABCD = 0xC
*Dec 30 08:51:19.427: port 18 changed state new state = 12
*Dec 30 08:51:19.427: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_1100]fxsls_onhook_offhook htsp_setup_ind
*Dec 30 08:51:19.427: [2/18] get_local_station_id calling num= calling name= calling time=00/00 00:00  orig called=
*Dec 30 08:51:19.431: //-1/xxxxxxxxxxxx/VTSP:(2/18):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x65D151B0
*Dec 30 08:51:19.431: //-1/xxxxxxxxxxxx/VTSP:(2/18):-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
*Dec 30 08:51:19.431: //-1/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Dec 30 08:51:19.431: //-1/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_timer:
   Timer Start Time=-1665219172, Timer Value=180000(ms)
*Dec 30 08:51:19.431: //-1/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   XCC State Machine (XCCSM) Added
*Dec 30 08:51:19.431: //-1/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_insert_cdb:
*Dec 30 08:51:19.435: //-1/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_opened_cb:
*Dec 30 08:51:19.435: //-1/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Dec 30 08:51:19.435: //-1/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_setup_ind_pend_success:
*Dec 30 08:51:19.435: //-1/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_realloc_cdb:
   CDB=0x65D151B0
*Dec 30 08:51:19.435: //-1/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_indicate_call:
*Dec 30 08:51:19.435: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_insert_cdb:
*Dec 30 08:51:19.435: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665219172, Timer Value=180000(ms)
*Dec 30 08:51:19.439: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_SETUP_ACK]
*Dec 30 08:51:19.439: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Fax Relay=TRUE, Dial Tone=FALSE, Digit Collect=FALSE, Overlap=FALSE, DID=FALSE
*Dec 30 08:51:19.439: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665219171
*Dec 30 08:51:19.439: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms), Playout Max=1000(ms), Fax Nom=300(ms)
*Dec 30 08:51:19.443: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_DIGIT_COLLECT, event:E_CC_CONNECT]
*Dec 30 08:51:19.443: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act2/20

  Progress Indication=0
*Dec 30 08:51:19.443: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665219171
*Dec 30 08:51:19.443: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665219171
*Dec 30 08:51:19.443: htsp_process_event: [2/18, FXSLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]fxsls_check_auto_call
*Dec 30 08:51:19.443: htsp_process_event: [2/18, FXSLS_OFFHOOK, E_HTSP_CONNECT]fxsls_offhook_connect
*Dec 30 08:51:19.443: [2/18] c2400_set_sig_state_intercept: ABCD=6, timestamp=0, sys_time=-1665219171
*Dec 30 08:51:19.443: [2/18] c2400_set_sig_state: ABCD=6, timestamp=0, sys_time=-1665219171
*Dec 30 08:51:19.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:51:19.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=TRUE
*Dec 30 08:51:19.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DIGIT]
*Dec 30 08:51:19.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_digit:
*Dec 30 08:51:19.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:51:19.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:19.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config: sh voice por summary
   Call Entry=NULL, Call Id=-1
 *Dec 30 08:51:26.803: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:51:26.807: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:51:26.807: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:26.955: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:51:26.955: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665218420
*Dec 30 08:51:26.955: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:51:26.955: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:26.955: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:51:27.011: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:51:27.011: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:27.011: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:51:29.655: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:51:29.655: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:51:29.655: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:29.775: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:51:29.775: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665218138
*Dec 30 08:51:29.775: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:51:29.775: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:29.775: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:51:29.835: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:51:29.835: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=FALSE
*Dec 30 08:51:31.483: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:51:31.483: port 18 changed state new state = 4
*Dec 30 08:51:31.483: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
*Dec 30 08:51:31.483: htsp_timer - 1000 msec
*Dec 30 08:51:32.483: htsp_process_event: [2/18, FXSLS_CONNECT, E_HTSP_EVENT_TIMER]fxsls_connect_wait_release_req
*Dec 30 08:51:32.483: htsp_timer_stop
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_TSP_DISCONNECT_IND]
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_generate_disc:
   Cause Value=16
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665217867
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665217867
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_set_release_source:
   Release Direction=PSTN, Release Source=Calling Party-PSTN
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
   Cause Value=16
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665217867, Timer Value=15000(ms)
*Dec 30 08:51:32.483: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_generate_disc:
   Return Code=0
*Dec 30 08:51:32.487: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DISCONNECT]
*Dec 30 08:51:32.487: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_disconnect:
   Cause Value=16, Previous Cause Value=16
*Dec 30 08:51:32.487: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665217866
*Dec 30 08:51:32.487: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:32.487: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:51:32.487: htsp_timer_stop3
*Dec 30 08:51:32.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Dec 30 08:51:32.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:51:32.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_dsm_dsp_stats_complete:
*Dec 30 08:51:32.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665217866, Timer Value=60000(ms)
*Dec 30 08:51:32.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:51:32.491: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
*Dec 30 08:51:32.491: htsp_process_event: [2/18, FXSLS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]fxsls_waitrls_req_rls
*Dec 30 08:51:32.491: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665217866
*Dec 30 08:51:32.495: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665217866
*Dec 30 08:51:32.495: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665217866
*Dec 30 08:51:32.495: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665217866
*Dec 30 08:51:32.495: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:51:32.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Dec 30 08:51:32.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/act_wrelease_release:
*Dec 30 08:51:32.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_play_busy_timer_stop:
   Timer Stop Time=-1665217866
*Dec 30 08:51:32.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665217866
*Dec 30 08:51:32.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
*Dec 30 08:51:32.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
   Coder Rate=-1
*Dec 30 08:51:32.495: //3164/1EFFB8FEA067/VTSP:(2/18):-1:1:1/vtsp_is_valid_dsm_handle:
   DMGR=0x63DF1FA8, VTSP CDB=0x65D151B0
*Dec 30 08:51:32.499: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_0100]fxsls_onhook_onhook
*Dec 30 08:51:32.499: //3164/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_dsm_closed_cb:
*Dec 30 08:51:32.499: //3164/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Dec 30 08:51:32.499: //3164/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/act_terminate:
*Dec 30 08:51:32.499: //3164/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=-1665217865
*Dec 30 08:51:32.503: //-1/1EFFB8FEA067/VTSP:(2/18):-1:-1:-1/vtsp_free_cdb:
   CDB=0x65D151B0
*Dec 30 08:51:32.811: [2/18] c2400_report_sig_state: ABCD = 0xC
*Dec 30 08:51:32.811: port 18 changed state new state = 12
*Dec 30 08:51:32.811: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_1100]fxsls_onhook_offhook htsp_setup_ind
*Dec 30 08:51:32.811: [2/18] get_local_station_id calling num= calling name= calling time=00/00 00:00  orig called=
*Dec 30 08:51:32.815: //-1/xxxxxxxxxxxx/VTSP:(2/18):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x65D15A38
*Dec 30 08:51:32.815: //-1/xxxxxxxxxxxx/VTSP:(2/18):-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
*Dec 30 08:51:32.815: //-1/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Dec 30 08:51:32.815: //-1/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_timer:
   Timer Start Time=-1665217834, Timer Value=180000(ms)
*Dec 30 08:51:32.815: //-1/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   XCC State Machine (XCCSM) Added
*Dec 30 08:51:32.815: //-1/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_insert_cdb:
*Dec 30 08:51:32.819: //-1/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_opened_cb:
*Dec 30 08:51:32.819: //-1/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Dec 30 08:51:32.819: //-1/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_setup_ind_pend_success:
*Dec 30 08:51:32.819: //-1/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_realloc_cdb:
   CDB=0x65D15A38
*Dec 30 08:51:32.819: //-1/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_indicate_call:
*Dec 30 08:51:32.819: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_insert_cdb:
*Dec 30 08:51:32.819: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665217833, Timer Value=180000(ms)
*Dec 30 08:51:32.823: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_SETUP_ACK]
*Dec 30 08:51:32.823: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Fax Relay=TRUE, Dial Tone=FALSE, Digit Collect=FALSE, Overlap=FALSE, DID=FALSE
*Dec 30 08:51:32.823: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665217833
*Dec 30 08:51:32.823: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms), Playout Max=1000(ms), Fax Nom=300(ms)
*Dec 30 08:51:32.827: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_DIGIT_COLLECT, event:E_CC_CONNECT]
*Dec 30 08:51:32.827: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_connect:
   Progress Indication=0
*Dec 30 08:51:32.827: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665217832
*Dec 30 08:51:32.827: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665217832
*Dec 30 08:51:32.827: htsp_process_event: [2/18, FXSLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]fxsls_check_auto_call
*Dec 30 08:51:32.827: htsp_process_event: [2/18, FXSLS_OFFHOOK, E_HTSP_CONNECT]fxsls_offhook_connect
*Dec 30 08:51:32.831: [2/18] c2400_set_sig_state_intercept: ABCD=6, timestamp=0, sys_time=-1665217832
*Dec 30 08:51:32.831: [2/18] c2400_set_sig_state: ABCD=6, timestamp=0, sys_time=-1665217832
*Dec 30 08:51:32.875: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:51:32.875: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=TRUE
*Dec 30 08:51:32.879: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DIGIT]
*Dec 30 08:51:32.879: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_digit:
*Dec 30 08:51:32.879: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:51:32.879: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:32.879: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:51:39.579: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:51:39.579: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:51:39.579: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:39.667: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:51:39.667: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665217148
*Dec 30 08:51:39.667: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:51:39.667: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:39.671: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:51:39.723: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:51:39.723: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:39.723: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:51:41.459: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:51:41.459: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:51:41.459: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:41.547: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:51:41.547: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665216960
*Dec 30 08:51:41.547: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:51:41.547: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:41.551: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:51:41.603: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:51:41.603: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=FALSE
*Dec 30 08:51:42.643: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:51:42.643: port 18 changed state new state = 4
*Dec 30 08:51:42.643: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
*Dec 30 08:51:42.643: htsp_timer - 1000 msec
*Dec 30 08:51:43.643: htsp_process_event: [2/18, FXSLS_CONNECT, E_HTSP_EVENT_TIMER]fxsls_connect_wait_release_req
*Dec 30 08:51:43.643: htsp_timer_stop
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_TSP_DISCONNECT_IND]
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_generate_disc:
   Cause Value=16
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665216751
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665216751
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_set_release_source:
   Release Direction=PSTN, Release Source=Calling Party-PSTN
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
   Cause Value=16
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665216751, Timer Value=15000(ms)
*Dec 30 08:51:43.643: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_generate_disc:
   Return Code=0
*Dec 30 08:51:43.647: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DISCONNECT]
*Dec 30 08:51:43.647: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_disconnect:
   Cause Value=16, Previous Cause Value=16
*Dec 30 08:51:43.647: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665216750
*Dec 30 08:51:43.647: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:43.647: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:51:43.647: htsp_timer_stop3
*Dec 30 08:51:43.651: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Dec 30 08:51:43.651: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:51:43.651: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_dsm_dsp_stats_complete:
*Dec 30 08:51:43.651: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665216750, Timer Value=60000(ms)
*Dec 30 08:51:43.651: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:51:43.651: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
*Dec 30 08:51:43.651: htsp_process_event: [2/18, FXSLS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]fxsls_waitrls_req_rls
*Dec 30 08:51:43.651: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665216750
*Dec 30 08:51:43.651: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665216750
*Dec 30 08:51:43.655: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665216750
*Dec 30 08:51:43.655: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665216750
*Dec 30 08:51:43.655: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:51:43.655: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Dec 30 08:51:43.655: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/act_wrelease_release:
*Dec 30 08:51:43.655: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_play_busy_timer_stop:
   Timer Stop Time=-1665216750
*Dec 30 08:51:43.655: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665216750
*Dec 30 08:51:43.655: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
*Dec 30 08:51:43.655: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
   Coder Rate=-1
*Dec 30 08:51:43.655: //3165/26F9F4D2A06B/VTSP:(2/18):-1:1:1/vtsp_is_valid_dsm_handle:
   DMGR=0x63DF1FA8, VTSP CDB=0x65D15A38
*Dec 30 08:51:43.659: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_0100]fxsls_onhook_onhook
*Dec 30 08:51:43.659: //3165/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_dsm_closed_cb:
*Dec 30 08:51:43.659: //3165/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Dec 30 08:51:43.659: //3165/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/act_terminate:
*Dec 30 08:51:43.659: //3165/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=-1665216749
*Dec 30 08:51:43.663: //-1/26F9F4D2A06B/VTSP:(2/18):-1:-1:-1/vtsp_free_cdb:
   CDB=0x65D15A38
*Dec 30 08:51:44.267: [2/18] c2400_report_sig_state: ABCD = 0xC
*Dec 30 08:51:44.267: port 18 changed state new state = 12
*Dec 30 08:51:44.267: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_1100]fxsls_onhook_offhook htsp_setup_ind
*Dec 30 08:51:44.267: [2/18] get_local_station_id calling num= calling name= calling time=00/00 00:00  orig called=
*Dec 30 08:51:44.271: //-1/xxxxxxxxxxxx/VTSP:(2/18):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x65D15488
*Dec 30 08:51:44.271: //-1/xxxxxxxxxxxx/VTSP:(2/18):-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
*Dec 30 08:51:44.271: //-1/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Dec 30 08:51:44.271: //-1/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_timer:
   Timer Start Time=-1665216688, Timer Value=180000(ms)
*Dec 30 08:51:44.271: //-1/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   XCC State Machine (XCCSM) Added
*Dec 30 08:51:44.271: //-1/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_insert_cdb:
*Dec 30 08:51:44.275: //-1/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_opened_cb:
*Dec 30 08:51:44.275: //-1/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Dec 30 08:51:44.275: //-1/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_setup_ind_pend_success:
*Dec 30 08:51:44.275: //-1/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_realloc_cdb:
   CDB=0x65D15488
*Dec 30 08:51:44.275: //-1/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_indicate_call:
*Dec 30 08:51:44.275: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_insert_cdb:
*Dec 30 08:51:44.275: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665216688, Timer Value=180000(ms)
*Dec 30 08:51:44.279: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_SETUP_ACK]
*Dec 30 08:51:44.279: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Fax Relay=TRUE, Dial Tone=FALSE, Digit Collect=FALSE, Overlap=FALSE, DID=FALSE
*Dec 30 08:51:44.279: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665216687
*Dec 30 08:51:44.279: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms), Playout Max=1000(ms), Fax Nom=300(ms)
*Dec 30 08:51:44.283: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_DIGIT_COLLECT, event:E_CC_CONNECT]
*Dec 30 08:51:44.283: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_connect:
   Progress Indication=0
*Dec 30 08:51:44.283: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665216687
*Dec 30 08:51:44.283: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665216687
*Dec 30 08:51:44.283: htsp_process_event: [2/18, FXSLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]fxsls_check_auto_call
*Dec 30 08:51:44.283: htsp_process_event: [2/18, FXSLS_OFFHOOK, E_HTSP_CONNECT]fxsls_offhook_connect
*Dec 30 08:51:44.287: [2/18] c2400_set_sig_state_intercept: ABCD=6, timestamp=0, sys_time=-1665216686
*Dec 30 08:51:44.287: [2/18] c2400_set_sig_state: ABCD=6, timestamp=0, sys_time=-1665216686
*Dec 30 08:51:44.331: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:51:44.331: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=TRUE
*Dec 30 08:51:44.331: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DIGIT]
*Dec 30 08:51:44.335: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_digit:
*Dec 30 08:51:44.335: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:51:44.335: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:44.335: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, 2/20            --  fxs-ls      up    dorm on-hook  idle     y
*Dec 30 08:51:50.463: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:51:50.467: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:51:50.467: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:50.515: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:51:50.515: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665216064
*Dec 30 08:51:50.515: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:51:50.515: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:50.515: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:51:50.571: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:51:50.575: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:50.575: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:51:50.983: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:51:50.987: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:51:50.987: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:51.115: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:51:51.115: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665216004
*Dec 30 08:51:51.115: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:51:51.115: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:51.115: htsp_digit_ready(2/18):         7

*Dec 30 08:51:51.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:51:51.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=FALSE
*Dec 30 08:51:51.703: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:51:51.707: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:51:51.707: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:51.775: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:51:51.775: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665215938
*Dec 30 08:51:51.775: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:51:51.775: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=FALSE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:51:51.775: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:51:52.171: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:51:52.171: port 18 changed state new state = 4
*Dec 30 08:51:52.171: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
*Dec 30 08:51:52.171: htsp_timer - 1000 msec
*Dec 30 08:51:53.171: htsp_process_event: [2/18, FXSLS_CONNECT, E_HTSP_EVENT_TIMER]fxsls_connect_wait_release_req
*Dec 30 08:51:53.171: htsp_timer_stop
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_TSP_DISCONNECT_IND]
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_generate_disc:
   Cause Value=16
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665215798
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665215798
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_set_release_source:
   Release Direction=PSTN, Release Source=Calling Party-PSTN
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
   Cause Value=16
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665215798, Timer Value=15000(ms)
*Dec 30 08:51:53.171: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_generate_disc:
   Return Code=0
*Dec 30 08:51:53.175: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DISCONNECT]
*Dec 30 08:51:53.175: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_disconnect:
   Cause Value=16, Previous Cause Value=16
*Dec 30 08:51:53.175: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665215798
*Dec 30 08:51:53.175: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:51:53.175: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:51:53.175: htsp_timer_stop3
*Dec 30 08:51:53.179: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Dec 30 08:51:53.179: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:51:53.179: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_dsm_dsp_stats_complete:
*Dec 30 08:51:53.179: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665215797, Timer Value=60000(ms)
*Dec 30 08:51:53.179: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:51:53.179: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
*Dec 30 08:51:53.179: htsp_process_event: [2/18, FXSLS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]fxsls_waitrls_req_rls
*Dec 30 08:51:53.179: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665215797
*Dec 30 08:51:53.179: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665215797
*Dec 30 08:51:53.183: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665215797
*Dec 30 08:51:53.183: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665215797
*Dec 30 08:51:53.183: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:51:53.183: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Dec 30 08:51:53.183: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/act_wrelease_release:
*Dec 30 08:51:53.183: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_play_busy_timer_stop:
   Timer Stop Time=-1665215797
*Dec 30 08:51:53.183: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665215797
*Dec 30 08:51:53.183: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
*Dec 30 08:51:53.183: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
   Coder Rate=-1
*Dec 30 08:51:53.183: //3166/2DCE01ACA06F/VTSP:(2/18):-1:1:1/vtsp_is_valid_dsm_handle:
   DMGR=0x63DF1FA8, VTSP CDB=0x65D15488
*Dec 30 08:51:53.187: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_0100]fxsls_onhook_onhook
*Dec 30 08:51:53.187: //3166/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_dsm_closed_cb:
*Dec 30 08:51:53.187: //3166/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Dec 30 08:51:53.187: //3166/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/act_terminate:
*Dec 30 08:51:53.187: //3166/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=-1665215796
*Dec 30 08:51:53.191: //-1/2DCE01ACA06F/VTSP:(2/18):-1:-1:-1/vtsp_free_cdb:
   CDB=0x65D15488
*Dec 30 08:52:12.531: [2/18] c2400_report_sig_state: ABCD = 0xC
*Dec 30 08:52:12.531: port 18 changed state new state = 12
*Dec 30 08:52:12.531: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_1100]fxsls_onhook_offhook htsp_setup_ind
*Dec 30 08:52:12.531: [2/18] get_local_station_id calling num= calling name= calling time=00/00 00:00  orig called=
*Dec 30 08:52:12.535: //-1/xxxxxxxxxxxx/VTSP:(2/18):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x65D15760
*Dec 30 08:52:12.535: //-1/xxxxxxxxxxxx/VTSP:(2/18):-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
*Dec 30 08:52:12.535: //-1/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Dec 30 08:52:12.535: //-1/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_timer:
   Timer Start Time=-1665213862, Timer Value=180000(ms)
*Dec 30 08:52:12.535: //-1/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   XCC State Machine (XCCSM) Added
*Dec 30 08:52:12.535: //-1/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_insert_cdb:
*Dec 30 08:52:12.539: //-1/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_opened_cb:
*Dec 30 08:52:12.539: //-1/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Dec 30 08:52:12.539: //-1/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_setup_ind_pend_success:
*Dec 30 08:52:12.539: //-1/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_realloc_cdb:
   CDB=0x65D15760
*Dec 30 08:52:12.539: //-1/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_indicate_call:
*Dec 30 08:52:12.539: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_insert_cdb:
*Dec 30 08:52:12.539: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665213861, Timer Value=180000(ms)
*Dec 30 08:52:12.543: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_SETUP_ACK]
*Dec 30 08:52:12.543: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Fax Relay=TRUE, Dial Tone=FALSE, Digit Collect=FALSE, Overlap=FALSE, DID=FALSE
*Dec 30 08:52:12.543: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665213861
*Dec 30 08:52:12.543: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms), Playout Max=1000(ms), Fax Nom=300(ms)
*Dec 30 08:52:12.547: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_DIGIT_COLLECT, event:E_CC_CONNECT]
*Dec 30 08:52:12.547: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_connect:
   Progress Indication=0
*Dec 30 08:52:12.547: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665213860
*Dec 30 08:52:12.547: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665213860
*Dec 30 08:52:12.547: htsp_process_event: [2/18, FXSLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]fxsls_check_auto_call
*Dec 30 08:52:12.551: htsp_process_event: [2/18, FXSLS_OFFHOOK, E_HTSP_CONNECT]fxsls_offhook_connect
*Dec 30 08:52:12.551: [2/18] c2400_set_sig_state_intercept: ABCD=6, timestamp=0, sys_time=-1665213860
*Dec 30 08:52:12.551: [2/18] c2400_set_sig_state: ABCD=6, timestamp=0, sys_time=-1665213860
*Dec 30 08:52:12.599: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:52:12.599: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=TRUE
*Dec 30 08:52:12.599: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DIGIT]
*Dec 30 08:52:12.599: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_digit:
*Dec 30 08:52:12.603: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:52:12.603: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:52:12.603: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:52:17.799: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:52:17.799: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:52:17.799: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:17.967: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:52:17.971: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665213318
*Dec 30 08:52:17.971: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:52:17.971: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:17.971: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:52:18.023: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:52:18.023: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:52:18.023: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:52:18.419: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:52:18.419: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:52:18.419: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:18.547: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:52:18.551: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665213260
*Dec 30 08:52:18.551: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:52:18.551: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:18.551: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:52:18.603: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:52:18.603: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=FALSE
*Dec 30 08:52:19.571: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:52:19.571: port 18 changed state new state = 4
*Dec 30 08:52:19.571: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
*Dec 30 08:52:19.571: htsp_timer - 1000 msec
*Dec 30 08:52:20.467: [2/18] c2400_report_sig_state: ABCD = 0xC
*Dec 30 08:52:20.467: port 18 changed state new state = 12
*Dec 30 08:52:20.467: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_1100]fxsls_offhook_offhookhtsp_hook_flash_ind
*Dec 30 08:52:20.467: htsp_timer_stop
*Dec 30 08:52:20.467: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_TSP_CALL_FEATURE_IND]
*Dec 30 08:52:20.471: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_call_feature_ind:
   Feature Type=5
*Dec 30 08:52:21.851: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:52:21.851: port 18 changed state new state = 4
*Dec 30 08:52:21.851: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
*Dec 30 08:52:21.851: htsp_timer - 1000 msec
*Dec 30 08:52:22.851: htsp_process_event: [2/18, FXSLS_CONNECT, E_HTSP_EVENT_TIMER]fxsls_connect_wait_release_req
*Dec 30 08:52:22.851: htsp_timer_stop
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_TSP_DISCONNECT_IND]
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_generate_disc:
   Cause Value=16
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665212830
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665212830
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_set_release_source:
   Release Direction=PSTN, Release Source=Calling Party-PSTN
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
   Cause Value=16
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665212830, Timer Value=15000(ms)
*Dec 30 08:52:22.851: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_generate_disc:
   Return Code=0
*Dec 30 08:52:22.855: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DISCONNECT]
*Dec 30 08:52:22.855: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_disconnect:
   Cause Value=16, Previous Cause Value=16
*Dec 30 08:52:22.855: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665212830
*Dec 30 08:52:22.855: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:52:22.855: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:52:22.855: htsp_timer_stop3
*Dec 30 08:52:22.859: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Dec 30 08:52:22.859: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:52:22.859: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_dsm_dsp_stats_complete:
*Dec 30 08:52:22.859: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665212829, Timer Value=60000(ms)
*Dec 30 08:52:22.859: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:52:22.859: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
*Dec 30 08:52:22.859: htsp_process_event: [2/18, FXSLS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]fxsls_waitrls_req_rls
*Dec 30 08:52:22.859: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665212829
*Dec 30 08:52:22.859: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665212829
*Dec 30 08:52:22.859: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665212829
*Dec 30 08:52:22.863: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665212829
*Dec 30 08:52:22.863: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:52:22.863: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Dec 30 08:52:22.863: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/act_wrelease_release:
*Dec 30 08:52:22.863: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_play_busy_timer_stop:
   Timer Stop Time=-1665212829
*Dec 30 08:52:22.863: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665212829
*Dec 30 08:52:22.863: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
*Dec 30 08:52:22.863: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
   Coder Rate=-1
*Dec 30 08:52:22.863: //3167/3EA6BFEFA073/VTSP:(2/18):-1:1:1/vtsp_is_valid_dsm_handle:
   DMGR=0x63DF1FA8, VTSP CDB=0x65D15760
*Dec 30 08:52:22.863: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_0100]fxsls_onhook_onhook
*Dec 30 08:52:22.867: //3167/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_dsm_closed_cb:
*Dec 30 08:52:22.867: //3167/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Dec 30 08:52:22.867: //3167/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/act_terminate:
*Dec 30 08:52:22.867: //3167/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=-1665212828
*Dec 30 08:52:22.871: //-1/3EA6BFEFA073/VTSP:(2/18):-1:-1:-1/vtsp_free_cdb:
   CDB=0x65D15760
*Dec 30 08:52:23.331: [2/18] c2400_report_sig_state: ABCD = 0xC
*Dec 30 08:52:23.331: port 18 changed state new state = 12
*Dec 30 08:52:23.331: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_1100]fxsls_onhook_offhook htsp_setup_ind
*Dec 30 08:52:23.331: [2/18] get_local_station_id calling num= calling name= calling time=00/00 00:00  orig called=
*Dec 30 08:52:23.335: //-1/xxxxxxxxxxxx/VTSP:(2/18):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x65D151B0
*Dec 30 08:52:23.335: //-1/xxxxxxxxxxxx/VTSP:(2/18):-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
*Dec 30 08:52:23.335: //-1/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
*Dec 30 08:52:23.335: //-1/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_timer:
   Timer Start Time=-1665212782, Timer Value=180000(ms)
*Dec 30 08:52:23.335: //-1/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_do_normal_call_setup_ind:
   XCC State Machine (XCCSM) Added
*Dec 30 08:52:23.335: //-1/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_insert_cdb:
*Dec 30 08:52:23.339: //-1/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_opened_cb:
*Dec 30 08:52:23.339: //-1/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_IND_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
*Dec 30 08:52:23.339: //-1/4516B2DDA077/VTSP:(2/18):-1:1:1/act_setup_ind_pend_success:
*Dec 30 08:52:23.339: //-1/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_realloc_cdb:
   CDB=0x65D151B0
*Dec 30 08:52:23.339: //-1/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_indicate_call:
*Dec 30 08:52:23.339: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_insert_cdb:
*Dec 30 08:52:23.339: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665212781, Timer Value=180000(ms)
*Dec 30 08:52:23.343: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_SETUP_INDICATED, event:E_CC_SETUP_ACK]
*Dec 30 08:52:23.343: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Fax Relay=TRUE, Dial Tone=FALSE, Digit Collect=FALSE, Overlap=FALSE, DID=FALSE
*Dec 30 08:52:23.343: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665212781
*Dec 30 08:52:23.343: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_setup_ind_ack:
   Playout Mode=1, Playout Initial=60(ms), Playout Min=40(ms), Playout Max=1000(ms), Fax Nom=300(ms)
*Dec 30 08:52:23.347: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_DIGIT_COLLECT, event:E_CC_CONNECT]
*Dec 30 08:52:23.347: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_connect:
   Progress Indication=0
*Dec 30 08:52:23.347: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665212780
*Dec 30 08:52:23.347: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665212780
*Dec 30 08:52:23.347: htsp_process_event: [2/18, FXSLS_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]fxsls_check_auto_call
*Dec 30 08:52:23.351: htsp_process_event: [2/18, FXSLS_OFFHOOK, E_HTSP_CONNECT]fxsls_offhook_connect
*Dec 30 08:52:23.351: [2/18] c2400_set_sig_state_intercept: ABCD=6, timestamp=0, sys_time=-1665212780
*Dec 30 08:52:23.351: [2/18] c2400_set_sig_state: ABCD=6, timestamp=0, sys_time=-1665212780
*Dec 30 08:52:23.395: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:52:23.395: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=TRUE
*Dec 30 08:52:23.399: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DIGIT]
*Dec 30 08:52:23.399: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_digit:
*Dec 30 08:52:23.399: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:52:23.399: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:52:23.399: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:52:28.587: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:52:28.587: port 18 changed state new state = 4
*Dec 30 08:52:28.587: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
*Dec 30 08:52:28.587: htsp_timer - 1000 msec
*Dec 30 08:52:29.387: [2/18] c2400_report_sig_state: ABCD = 0xC
*Dec 30 08:52:29.387: port 18 changed state new state = 12
*Dec 30 08:52:29.387: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_1100]fxsls_offhook_offhookhtsp_hook_flash_ind
*Dec 30 08:52:29.387: htsp_timer_stop
*Dec 30 08:52:29.387: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_TSP_CALL_FEATURE_IND]
*Dec 30 08:52:29.391: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_call_feature_ind:
   Feature Type=5
*Dec 30 08:52:33.407: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:52:33.411: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:52:33.411: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:33.467: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:52:33.471: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665211768
*Dec 30 08:52:33.471: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:52:33.471: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:33.471: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:52:33.523: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_call_mod_done_cb:
*Dec 30 08:52:33.523: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:52:33.523: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:52:34.799: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
*Dec 30 08:52:34.799: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Begin Digit=7
*Dec 30 08:52:34.799: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_begin_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:34.847: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
*Dec 30 08:52:34.851: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665211630
*Dec 30 08:52:34.851: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   End Digit=7
*Dec 30 08:52:34.851: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_digit_end_cb:
   Digit Reporting=TRUE, Digit Consume=FALSE, Digit Relay=FALSE
*Dec 30 08:52:34.851: htsp_digit_ready(2/18): digit = 7
*Dec 30 08:52:34.903: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
*Dec 30 08:52:34.907: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_report_digit_control:
   Digit Reporting=FALSE
*Dec 30 08:52:35.827: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:52:35.827: port 18 changed state new state = 4
*Dec 30 08:52:35.827: htsp_process_event: [2/18, FXSLS_CONNECT, E_DSP_SIG_0100]fxsls_offhook_onhook, HF duration Max=1000, HF duration Min=150
*Dec 30 08:52:35.827: htsp_timer - 1000 msec
*Dec 30 08:52:36.827: htsp_process_event: [2/18, FXSLS_CONNECT, E_HTSP_EVENT_TIMER]fxsls_connect_wait_release_req
*Dec 30 08:52:36.827: htsp_timer_stop
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_TSP_DISCONNECT_IND]
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_generate_disc:
   Cause Value=16
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665211432
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665211432
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_set_release_source:
   Release Direction=PSTN, Release Source=Calling Party-PSTN
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_cc_call_disconnected:
   Cause Value=16
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665211432, Timer Value=15000(ms)
*Dec 30 08:52:36.827: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_generate_disc:
   Return Code=0
*Dec 30 08:52:36.831: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_CONNECT, event:E_CC_DISCONNECT]
*Dec 30 08:52:36.831: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_disconnect:
   Cause Value=16, Previous Cause Value=16
*Dec 30 08:52:36.831: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_ring_noan_timer_stop:
   Timer Stop Time=-1665211432
*Dec 30 08:52:36.831: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
*Dec 30 08:52:36.831: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_save_fax_config:
   Call Entry=NULL, Call Id=-1
*Dec 30 08:52:36.831: htsp_timer_stop3
*Dec 30 08:52:36.835: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_dsm_get_levels_done_cb:
*Dec 30 08:52:36.835: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:52:36.835: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_dsm_dsp_stats_complete:
*Dec 30 08:52:36.835: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer:
   Timer Start Time=-1665211432, Timer Value=60000(ms)
*Dec 30 08:52:36.835: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_VTSP_DSM_STATS_COMPLETE]
*Dec 30 08:52:36.835: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   Unexpected EVENT [E_VTSP_DSM_STATS_COMPLETE] Received For STATE [S_WAIT_RELEASE];
   Previous STATE [0.16 ]
*Dec 30 08:52:36.835: htsp_process_event: [2/18, FXSLS_WAIT_RELEASE_REQ, E_HTSP_RELEASE_REQ]fxsls_waitrls_req_rls
*Dec 30 08:52:36.835: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665211432
*Dec 30 08:52:36.835: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665211432
*Dec 30 08:52:36.839: [2/18] c2400_set_sig_state_intercept: ABCD=4, timestamp=0, sys_time=-1665211431
*Dec 30 08:52:36.839: [2/18] c2400_set_sig_state: ABCD=4, timestamp=0, sys_time=-1665211431
*Dec 30 08:52:36.839: [2/18] c2400_report_sig_state: ABCD = 0x4
*Dec 30 08:52:36.839: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
*Dec 30 08:52:36.839: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/act_wrelease_release:
*Dec 30 08:52:36.839: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_play_busy_timer_stop:
   Timer Stop Time=-1665211431
*Dec 30 08:52:36.839: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_timer_stop:
   Timer Stop Time=-1665211431
*Dec 30 08:52:36.839: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
*Dec 30 08:52:36.839: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_do_call_history:
   Coder Rate=-1
*Dec 30 08:52:36.839: //3168/4516B2DDA077/VTSP:(2/18):-1:1:1/vtsp_is_valid_dsm_handle:
   DMGR=0x63DF1FA8, VTSP CDB=0x65D151B0
*Dec 30 08:52:36.843: htsp_process_event: [2/18, FXSLS_ONHOOK, E_DSP_SIG_0100]fxsls_onhook_onhook
*Dec 30 08:52:36.843: //3168/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_dsm_closed_cb:
*Dec 30 08:52:36.843: //3168/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
*Dec 30 08:52:36.843: //3168/4516B2DDA077/VTSP:(2/18):-1:-1:-1/act_terminate:
*Dec 30 08:52:36.843: //3168/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=-1665211431
*Dec 30 08:52:36.847: //-1/4516B2DDA077/VTSP:(2/18):-1:-1:-1/vtsp_free_cdb:
   CDB=0x65D151B0

=-=-=-=-=-=-=-=-=-=-=-

And for show mgcp connection I remember the mode M=0 and codec=0 and was not able to save the logs for that one and the logs which I captured from CUCM was the digit recognised were only 7,7 and call disconnect reason code was 16
The logs which I captured in cucm were three days before and was not able to reproduce the issue again as the device is at remote location.
Kindly suggest what could be the issue to get the fast busy tone as the same configuration is working correctly for device at different location.
Please help me to understand Progress Indication=0 and 3 with Return Code=0
System image file is "slot0:vg224-i6k9s-mz.151-4.M7.bin"

Thanks and Regards,
Saif

gregorygout1 · ‎05-20-2016

Hi Saif,

did you resolve this issue please- I have a similar issue .

Best Regards,

Gregory

Chris Deren · ‎05-21-2016

Is the endpoint registered in CUCM?

gregorygout1 · ‎05-23-2016

Hi Mohammed, Chris,

I have found a workaround for my issue.

I migrated vg 224s used by modems from CUCM 7 (was working fine with MGCP) to CUCM 10.5. All my ports were registered in the new CUCM but none had any dial tones and ports were getting busy off-hook after 10-15s. Because we were prefixing 9 directly on the CUCM gui port setting...somehow our ports were not getting any dial tones...after removing the 9 and resetting the ports, they all got a dial tone...We had to find a workaround for prefixing 9 another way using new css, partition and translation pattern. The strange thing is that it was working fine with the same 9 prefix in CUCM 7.

Bottom line is I wonder if I have an issue somewhere with a service parameter setting in cucm 10.5-of if there is a bug in 10.5 when you prefix dn 9 on cucm gui port setting...for now my issue is resolved via a workaround. thanks

Mohammed Saifuddin · ‎05-23-2016

Hi Gregory,

Sorry for the late reply!

I didn't get any update from the user after words, Could you please confirm from your VG 224 to enable debug as "debug vpm signal" and see the digits are collecting by VG224.