[Urgent] Please help me verify the debug output on E&M interface.

[Thotsaphon Lueangwattanaphong]

Hello,

    I've got a problem when trying to make a call from the E&M interface on the router to PABX(Panasonic). I've got any dail-tone back. Please help me verify the logging output. It seemed to already send the digits.

###########################debug vpm signal####################

.Sep 20 06:43:43.911: htsp_process_event: [0/0/0, EM_ONHOOK, E_DSP_SIG_1100]em_onhook_offhook htsp_setup_ind
.Sep 20 06:43:43.911: [0/0/0] get_local_station_id calling num= calling name= calling time=09/20 13:43  orig called=
.Sep 20 06:43:43.915: htsp_timer - 3000 msec
.Sep 20 06:43:43.923: htsp_process_event: [0/0/0, EM_WAIT_SETUP_ACK, E_HTSP_SETUP_ACK]em_wait_setup_ack_get_ack
.Sep 20 06:43:43.923: htsp_timer_stop interdigit timer cfgd to 3000
.Sep 20 06:43:44.183: htsp_digit_ready: digit = 38
.Sep 20 06:43:44.183: htsp_process_event: [0/0/0, EM_OFFHOOK, E_VTSP_DIGIT]em_offhook_digit_collect
.Sep 20 06:43:44.443: htsp_digit_ready: digit = 39
.Sep 20 06:43:44.443: htsp_process_event: [0/0/0, EM_OFFHOOK, E_VTSP_DIGIT]em_offhook_digit_collect
.Sep 20 06:43:44.724: htsp_digit_ready: digit = 30
.Sep 20 06:43:44.724: htsp_process_event: [0/0/0, EM_OFFHOOK, E_VTSP_DIGIT]em_offhook_digit_collect
.Sep 20 06:43:44.996: htsp_digit_ready: digit = 38
.Sep 20 06:43:44.996: htsp_process_event: [0/0/0, EM_OFFHOOK, E_VTSP_DIGIT]em_offhook_digit_collect
.Sep 20 06:43:45.004: htsp_process_event: [0/0/0, EM_OFFHOOK, E_HTSP_PROCEEDING]
.Sep 20 06:43:46.224: htsp_call_bridged invokedhtsp_progress_notify
.Sep 20 06:43:46.228: htsp_process_event: [0/0/0, EM_OFFHOOK, E_HTSP_VOICE_CUT_THROUGH]em_offhook_voice_cut
.Sep 20 06:43:51.184: htsp_process_event: [0/0/0, EM_OFFHOOK, E_DSP_SIG_0000]em_offhook_onhook, HF duration=480
.Sep 20 06:43:51.184: mlpp_detection_enabled MLPP is not supported on this interface
.Sep 20 06:43:51.184: em_start_timer: 480 ms
.Sep 20 06:43:51.184: htsp_timer - 480 msec
.Sep 20 06:43:51.664: htsp_process_event: [0/0/0, EM_OFFHOOK, E_HTSP_EVENT_TIMER]em_offhook_wait_release_req
.Sep 20 06:43:51.664: htsp_timer_stop
.Sep 20 06:43:51.664: htsp_timer_stop2
.Sep 20 06:43:51.676: htsp_process_event: [0/0/0, EM_RLS_WAIT_RLS_REQ, E_HTSP_RELEASE_REQ]em_wait_rls_release em_onhook (0)
.Sep 20 06:43:51.676: [0/0/0] set signal state = 0x0 timestamp = 0
.Sep 20 06:43:51.676: em_start_timer: 400 ms
.Sep 20 06:43:51.676: htsp_timer - 400 msec
.Sep 20 06:43:52.076: htsp_process_event: [0/0/0, EM_WAIT_CLR_DONE, E_HTSP_EVENT_TIMER]em_clr_done
.Sep 20 06:43:52.076: htsp_process_event: [0/0/0, EM_ONHOOK, E_DSP_SIG_0000]em_onhook_onhook

##########################debug vpip vtsp all####################

.Sep 20 07:02:51.640: //44/D16BA46380FC/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=23417277
.Sep 20 07:02:51.640: //-1/D16BA46380FC/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x47575388
.Sep 20 07:02:55.416: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_allocate_cdb:
   CDB=0x47574E08
.Sep 20 07:02:55.416: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_insert_cdb:
.Sep 20 07:02:55.416: //-1/xxxxxxxxxxxx/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:INVALID STATE MACHINE, event:E_CC_SETUP_REQ]
.Sep 20 07:02:55.416: htsp_timer_stop3
.Sep 20 07:02:55.416: //48/E9FE7CA28104/VTSP:(0/0/1):-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
.Sep 20 07:02:55.416: //48/E9FE7CA28104/VTSP:(0/0/1):-1:-1:-1/vtsp_do_call_setup_req:
.Sep 20 07:02:55.420: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_opened_cb:
.Sep 20 07:02:55.420: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_SETUP_REQ_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
.Sep 20 07:02:55.420: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_setup_req_pend_succ:
.Sep 20 07:02:55.420: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_request_call:
   Mode=0, Peer=2
.Sep 20 07:02:55.420: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_create_call_active_on_setup_req:
   Target Carrier ID=
.Sep 20 07:02:55.420: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_create_call_active_on_setup_req:
   Source Carrier ID=htsp_setup_req
.Sep 20 07:02:55.420: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_request_call:
   Progress Indication=3, Info Trans Capability=16
   Calling Number=, TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed
   Called Number=7744, TON=Unknown, NPI=ISDN
.Sep 20 07:02:55.420: htsp_process_event: [0/0/1, EM_ONHOOK, E_HTSP_SETUP_REQ]em_onhook_setup
.Sep 20 07:02:55.424: em_offhook (0)
.Sep 20 07:02:55.424: [0/0/1] set signal state = 0x8 timestamp = 0
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_SETUP_REQUEST, event:E_TSP_PROCEEDING]
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_setup_pend_proceeding:
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_timer:
   Timer Start Time=23417655, Timer Value=10000(ms)
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_setup_pend_proceeding:
   Peer=2, Progress Indication=0, Return Code=2
.Sep 20 07:02:55.424: htsp_process_event: [0/0/1, EM_BRANCH, EM_EVENT_IMMEDIATE]em_branch_immediate
.Sep 20 07:02:55.424: htsp_timer - 300 msec
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_opened_cb:
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_NULL, event:E_VTSP_DSM_OPEN_SUCCESS]
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_setup_req_wait_pend_success:
   Event=72
.Sep 20 07:02:55.424: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_timer_stop:
   Timer Stop Time=23417655
.Sep 20 07:02:55.724: htsp_process_event: [0/0/1, EM_WAIT_DIALOUT_DELAY, E_HTSP_EVENT_TIMER]em_imm_send_digits  em_send_digits  htsp_dial
.Sep 20 07:02:55.724: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_TSP_DIAL]
.Sep 20 07:02:55.724: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_setup_pend_dial:
   Digits=7744, Tone Mode=0
.Sep 20 07:02:55.724: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dial:
.Sep 20 07:02:55.724: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/ds_do_dial:
   Digits To Dial=7744
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_dial_done_cb:
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_DS_DIALING, event:E_VTSP_DSM_DIALING_COMPLETE]
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/ds_dialing:
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/ds_do_dial:
   Digits To Dial=
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_setup_pend_dial_comp:
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/ds_do_dial:exit@556
.Sep 20 07:02:56.568: htsp_process_event: [0/0/1, EM_WAIT_DIAL_DONE, E_DSP_DIALING_DONE]em_offhook_digit_done
.Sep 20 07:02:56.568: htsp_timer_stop2 htsp_progress
.Sep 20 07:02:56.568: htsp_timer2 - 850 msec
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_TSP_PROGRESS]
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_setup_pend_progress:
   Progress Indication=8, Signal Indication=2, cdb->answer_supervision=0
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_ring_noan_timer_start:
   Timer Start Time=23417770, No Answer Timer Value=180000(ms)
.Sep 20 07:02:56.568: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_bridge_check_cb:
.Sep 20 07:02:56.572: htsp_call_bridged invoked
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_bridge_check_cb:exit@1187
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_bridge_status_cb:
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_save_fax_config:
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_save_fax_config:
   Fax Relay=ENABLED
   Primary Fax Protocol=CISCO_FAX_RELAY, Fallback Fax Protocol=NONE_FAX_RELAY
   Fax Relay CM Suppression :=ENABLED, Fax Parameters Set By=Global Settings
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_set_fax_feat_param:
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_save_tty_config:
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_save_tty_config:
   Save TTY configuration
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_set_tty_feat_param:
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_set_tty_feat_param:
   Set TTY feat parameters
.Sep 20 07:02:56.572: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_CC_DO_CAPS_IND]
.Sep 20 07:02:56.576: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_peer_event_cb:
   Event=E_DSM_CC_CAPS_ACK
.Sep 20 07:02:56.576: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_CC_CAPS_IND]
.Sep 20 07:02:56.576: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_peer_event_cb:
   Event=E_DSM_CC_CALL_MODIFY
.Sep 20 07:02:56.580: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_feature_notify_cb:
   Feature ID=0, Feature Status=1
.Sep 20 07:02:56.580: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_reactivate_ringback:
.Sep 20 07:02:56.580: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_reactivate_ringback:exit@996
.Sep 20 07:02:56.580: htsp_process_event: [0/0/1, EM_WAIT_FOR_ANSWER, E_HTSP_VOICE_CUT_THROUGH]
.Sep 20 07:02:56.580: htsp_timer_stop2
.Sep 20 07:03:13.913: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_dsm_bridge_status_cb:
.Sep 20 07:03:13.913: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_SETUP_REQ_PROC, event:E_CC_DISCONNECT]
.Sep 20 07:03:13.913: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_disconnect:
   Cause Value=16
.Sep 20 07:03:13.913: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_ring_noan_timer_stop:
   Timer Stop Time=23419504
.Sep 20 07:03:13.913: htsp_timer_stop3
.Sep 20 07:03:13.925: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_WAIT_STATS, event:E_VTSP_DSM_STATS_COMPLETE]
.Sep 20 07:03:13.925: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_dsm_dsp_stats_complete:
.Sep 20 07:03:13.925: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_timer:
   Timer Start Time=23419505, Timer Value=60000(ms)
.Sep 20 07:03:13.929: htsp_process_event: [0/0/1, EM_WAIT_FOR_ANSWER, E_HTSP_RELEASE_REQ]em_wait_answer_release
.Sep 20 07:03:13.929: em_stop_timers
.Sep 20 07:03:13.929: htsp_timer_stop
.Sep 20 07:03:13.929: htsp_timer_stop2 em_onhook (0)
.Sep 20 07:03:13.929: [0/0/1] set signal state = 0x0 timestamp = 0
.Sep 20 07:03:13.929: em_start_timer: 400 ms
.Sep 20 07:03:13.929: htsp_timer - 400 msec
.Sep 20 07:03:14.329: htsp_process_event: [0/0/1, EM_GUARD_ALL, E_HTSP_EVENT_TIMER]em_guard_all_timer
.Sep 20 07:03:14.329: em_stop_timers
.Sep 20 07:03:14.329: htsp_timer_stop
.Sep 20 07:03:14.329: em_start_timer: 3000 ms
.Sep 20 07:03:14.329: htsp_timer - 3000 msec
.Sep 20 07:03:14.329: htsp_process_event: [0/0/1, EM_PARK, E_DSP_SIG_0000]em_park_onhook
.Sep 20 07:03:14.329: htsp_timer_stop
.Sep 20 07:03:14.329: htsp_timer_stop2 htsp_report_onhook_sig
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_CALL_FEATURE_IND]
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_call_feature_ind:
   Feature Type=6
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_process_event:
   [state:S_WAIT_RELEASE, event:E_TSP_DISCONNECT_CONF]
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/act_wrelease_release:
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_play_busy_timer_stop:
   Timer Stop Time=23419546
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_timer_stop:
   Timer Stop Time=23419546
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_do_call_history:
.Sep 20 07:03:14.329: //48/E9FE7CA28104/VTSP:(0/0/1):-1:1:2/vtsp_do_call_history:
   Coder Rate=16
.Sep 20 07:03:14.333: //48/E9FE7CA28104/VTSP:(0/0/1):-1:-1:-1/vtsp_dsm_closed_cb:
.Sep 20 07:03:14.333: //48/E9FE7CA28104/VTSP:(0/0/1):-1:-1:-1/vtsp_process_event:
   [state:S_CLOSE_DSPRM, event:E_VTSP_DSM_CLOSE_COMPLETE]
.Sep 20 07:03:14.333: //48/E9FE7CA28104/VTSP:(0/0/1):-1:-1:-1/act_terminate:
.Sep 20 07:03:14.333: //48/E9FE7CA28104/VTSP:(0/0/1):-1:-1:-1/vtsp_timer_stop:
   Timer Stop Time=23419546
.Sep 20 07:03:14.333: //-1/E9FE7CA28104/VTSP:(0/0/1):-1:-1:-1/vtsp_free_cdb:
   CDB=0x47574E08

###################################################################################

Thanks in advance.

Toshi

[Thotsaphon Lueangwattanaphong]

EDIT:

            I've not got any dial-tone back from PABX.

Thanks in advance

Toshi