Please help me verify the debug output on E&M interface

Unanswered Question
Sep 20th, 2010
User Badges:
  • Gold, 750 points or more

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 not 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 voip 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:[email protected]
.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:[email protected]
.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:[email protected]
.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

  • 1
  • 2
  • 3
  • 4
  • 5
Overall Rating: 0 (0 ratings)
Loading.
Steven Holl Mon, 09/20/2010 - 07:47
User Badges:
  • Cisco Employee,

What the other side of the call?


Can you post a config, and get these debugs all in parallel for a call?


debug voip ccapi inout

debug vpm sig

debug ccsip mess (if the other side is SIP)

debug h225 asn1 (if the other side is H323)

debug mgcp pack (if the other side is MGCP)

debug isdn q931 (if the other side is a PRI)

Actions

This Discussion