All,
I have a situation whereby faxes are failing to a fax attached to an FXS port on a Cisco 2901. (H.323 with CUCM)
The gateway is setup as follows:
fax protocol t38 nse version 0 ls-redundancy 0 hs-redundancy 0 fallback pass-through g711alaw
Fax is connected to the gateway as follows and is setup in CUCM as an analog endpoint.
voice-port 0/1/0
cptone AT
timeouts ringing infinity
description 12345
station-id number 67890
caller-id enable
Here is the full output of a 'debug voip vtsp all'
I am struggling with this debug as I don't have a lot of experience with them, so would appreciate any help or pointers.
(I do also have ccapi inout/ccsip messages if required)
002320: May 2 13:22:36.334: //-1/xxxxxxxxxxxx/VTSP:(0/1/0):-1:-1:-1/vtsp_allocate_cdb:
CDB=0x21084900
002321: May 2 13:22:36.334: //-1/xxxxxxxxxxxx/VTSP:(0/1/0):-1:-1:-1/vtsp_insert_cdb:
002322: May 2 13:22:36.334: //-1/xxxxxxxxxxxx/VTSP:(0/1/0):-1:-1:-1/vtsp_process_event:
[state:INVALID STATE MACHINE, event:E_CC_SETUP_REQ]
002323: May 2 13:22:36.334: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:-1:-1/vtsp_do_call_setup_req:
002324: May 2 13:22:36.334: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_opened_cb:
002325: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQ_PEND, event:E_VTSP_DSM_OPEN_SUCCESS]
002326: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_req_pend_succ:
002327: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_request_call:
Mode=0, Peer=0
002328: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_create_call_active_on_setup_req:
Target Carrier ID=
002329: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_create_call_active_on_setup_req:
Source Carrier ID=
002330: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_request_call:
Progress Indication=0, Info Trans Capability=0
Calling Number=12345, TON=Unknown, NPI=Unknown, Screening=Not Screened, Presentation=Allowed
Called Number=67890, TON=Unknown, NPI=Unknown
002331: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQUEST, event:E_TSP_PROCEEDING]
002332: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_pend_proceeding:
002333: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_timer:
Timer Start Time=104484834, Timer Value=25000(ms)
002334: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_pend_proceeding:
Peer=0, Progress Indication=0, Return Code=2
002335: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_NULL, event:E_TSP_PROGRESS]
002336: May 2 13:22:36.338: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_req_pend_defer:
Event=12
002337: May 2 13:22:36.342: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_opened_cb:
002338: May 2 13:22:36.342: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_NULL, event:E_VTSP_DSM_OPEN_SUCCESS]
002339: May 2 13:22:36.342: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_req_wait_pend_success:
Event=76
002340: May 2 13:22:36.342: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_timer_stop:
Timer Stop Time=104484834
002341: May 2 13:22:36.342: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_pend_progress:
Progress Indication=8, Signal Indication=2, cdb->answer_supervision=0
002342: May 2 13:22:36.346: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQ_PROC, event:E_TSP_ALERT]
002343: May 2 13:22:36.346: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_pend_alert:
Progress Indication=8, Signal Indication=1
002344: May 2 13:22:36.346: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_pend_alert:
Ringback Indication=TRUE, Ring Timeout=-1(s)
002345: May 2 13:22:38.926: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_feature_notify_cb:
Feature ID=6, Feature Status=2
002346: May 2 13:22:44.742: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_SETUP_REQ_PROC, event:E_TSP_CONNECT]
002347: May 2 13:22:44.742: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/act_setup_pend_connect:
Progress Indication=2
002348: May 2 13:22:44.742: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_ring_noan_timer_stop:
Timer Stop Time=104485674
002349: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_CONNECT, event:E_CC_CONNECT]
002350: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
Unexpected EVENT [E_CC_CONNECT] Received For STATE [S_CONNECT];
Previous STATE [0.11 ]
002351: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_bridge_check_cb:
002352: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_bridge_check_cb:exit@1496
002353: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_bridge_status_cb:
002354: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_save_fax_config:
002355: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=ENABLED
Primary Fax Protocol=T38_FAX_RELAY, Fallback Fax Protocol=CISCO_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=SCCP Call Type
002356: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_save_fax_config:
Fax Version:=0, LS Red=0, HS Red=0
002357: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_set_fax_feat_param:
002358: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_save_tty_config:
002359: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_save_tty_config:
Save TTY configuration
002360: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_set_tty_feat_param:
002361: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_set_tty_feat_param:
Set TTY feat parameters
002362: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_CONNECT, event:E_CC_DO_CAPS_IND]
002363: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_peer_event_cb:
Event=E_DSM_CC_CAPS_IND
002364: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_process_event:
[state:S_CONNECT, event:E_CC_CAPS_IND]
002365: May 2 13:22:44.802: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_peer_event_cb:
Event=E_DSM_CC_CAPS_ACK
002366: May 2 13:22:44.806: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_feature_notify_cb:
Feature ID=0, Feature Status=1
002367: May 2 13:22:44.806: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_reactivate_ringback:
002368: May 2 13:22:44.806: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_reactivate_ringback:exit@1287
002369: May 2 13:22:44.846: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_report_digit_control:
002370: May 2 13:22:44.846: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_report_digit_control:
Digit Reporting=TRUE
002371: May 2 13:22:44.846: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_call_mod_done_cb:
002372: May 2 13:22:44.846: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_save_fax_config:
002373: May 2 13:22:44.846: //123101/xxxxxxxxxxxx/VTSP:(0/1/0):-1:1:1/vtsp_dsm_save_fax_config:
Fax Relay=ENABLED
Primary Fax Protocol=T38_FAX_RELAY, Fallback Fax Protocol=CISCO_FAX_RELAY
Fax Relay CM Suppression :=ENABLED, Fax Relay ANS Suppression :=DISABLED
Fax Parameters Set By=SCCP Call Type
