Increase reliability of outgoing faxing

Community-based Support for users of Free Fax For Asterisk

Increase reliability of outgoing faxing

Postby brettlehrer » Tue Oct 02, 2012 5:24 pm

I apologize if this is too broad of a question/topic, or if I'm neglecting to include any information.

We're using Asterisk 1.8.11.1, and have several paid fax licenses registered with the res_fax_digium module running. I have a heavily modified web interface that allows people to upload a PDF to fax to any given number (which converts it to a TIFF, generates a call file, and places it in the spool). Our trunking service is through nexVortex, and the PBX is connected to the Internet via a DSL line. Unfortunately, about a quarter of the faxes sent out fail for a handful of common reasons (TIMEOUT/T1_TIMEOUT, 3RD_FRM_CHECK_ERROR, HANGUP, OUT_OF_RATES). Are there any general tips or tricks to make outgoing T.38 faxes more robust and reliable?

Could the DSL line be part of the problem? It is solely used by the PBX, our data Internet connection is an entirely different service provider. It's on a 6 Mbps down/768 Kbps up plan.

I also removed the V17 modem and toned down the max baud rate to match (it won't allow 14400 without V17). I'm not sure if that's good or bad anymore, it was just another option to try. TIMEOUTs/T1_TIMEOUTs seem to pop up almost instantly into the call, finishing the dialplan context long before the call itself actually terminates. ECM seems to always wind up disabled on both failed and successful faxes.



Here's some info for a fax that failed to go out, giving the 3RD_FRM_CHECK_ERROR:


sip.conf:
t38pt_udptl=yes,fec,maxdatagram=400



dialplan context:
[outboundfax]

; exten => s,1,NoOp(send a fax)
exten => s,1,Set(FAXOPT(filename)=${FAXFILE})
exten => s,n,Set(FAXOPT(ecm)=yes)
exten => s,n,Set(FAXOPT(headerinfo)=${FAXHEADER})
exten => s,n,Set(FAXOPT(localstationid)=${LOCALID})
exten => s,n,NoOp(Sender : ${EMAIL})
exten => s,n,NoOp(Recipient : ${DESTINATION})
exten => s,n,Set(FAXOPT(modem)=V27,V29)
exten => s,n,Set(FAXOPT(maxrate)=9600)
exten => s,n,Set(FAXOPT(minrate)=2400)
exten => s,n,SendFAX(${FAXFILE},dfz)
exten => h,1,NoOp(FAXOPT(ecm) : ${FAXOPT(ecm)})
exten => h,n,NoOp(FaxStatus : ${FAXSTATUS})
exten => h,n,NoOp(FaxStatusString : ${FAXSTATUSSTRING})
exten => h,n,NoOp(FaxError : ${FAXERROR})
exten => h,n,NoOp(RemoteStationID : ${REMOTESTATIONID})
exten => h,n,NoOp(FaxPages : ${FAXPAGES})
exten => h,n,NoOp(FaxBitRate : ${FAXBITRATE})
exten => h,n,NoOp(FaxResolution : ${FAXRESOLUTION})
exten => h,n,System(/etc/asterisk/includes/scripts/fax_email_error.sh "${FAXOPT(error)}" "${EMAIL}" "${DESTINATION}" "${TIMESTAMP}")
exten => h,n,System(rm ${FAXFILE})
; end of outboundfax context



Sample callfile of a failed fax:
Channel: SIP/631xxxxxxx@voip-out
MaxRetries: 3
RetryTime: 60
WaitTime: 180
Archive: yes
Context: outboundfax
Extension: s
Priority: 1
Set: FAXHEADER=xyz
Set: TIMESTAMP=10/02/12 : 16:58:27
Set: DESTINATION=631xxxxxxx
Set: LOCALID=414yyyyyyy
Set: EMAIL=<email of user for failure notification>



Log:
-- Attempting call on SIP/631xxxxxxx@voip-out for s@outboundfax:1 (Retry 1)
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
> Channel SIP/voip-out-00012f11 was answered.
-- Executing [s@outboundfax:1] Set("SIP/voip-out-00012f11", "FAXOPT(filename)=/faxouttmp/phpgCujSc") in new stack
[Oct 2 16:58:47] WARNING[22386]: res_fax.c:2835 acf_faxopt_write: channel 'SIP/voip-out-00012f11' set FAXOPT(filename) to '/faxouttmp/phpgCujSc' is unhandled!
-- Executing [s@outboundfax:2] Set("SIP/voip-out-00012f11", "FAXOPT(ecm)=yes") in new stack
-- Executing [s@outboundfax:3] Set("SIP/voip-out-00012f11", "FAXOPT(headerinfo)=xyz") in new stack
-- Executing [s@outboundfax:4] Set("SIP/voip-out-00012f11", "FAXOPT(localstationid)=414xxxxxxx") in new stack
-- Executing [s@outboundfax:5] NoOp("SIP/voip-out-00012f11", "Sender : xyz") in new stack
-- Executing [s@outboundfax:6] NoOp("SIP/voip-out-00012f11", "Recipient : 631xxxxxxx") in new stack
-- Executing [s@outboundfax:7] Set("SIP/voip-out-00012f11", "FAXOPT(modem)=V27,V29") in new stack
-- Executing [s@outboundfax:8] Set("SIP/voip-out-00012f11", "FAXOPT(maxrate)=9600") in new stack
-- Executing [s@outboundfax:9] Set("SIP/voip-out-00012f11", "FAXOPT(minrate)=2400") in new stack
-- Executing [s@outboundfax:10] SendFAX("SIP/voip-out-00012f11", "/faxouttmp/phpgCujSc,dfz") in new stack
-- Channel 'SIP/voip-out-00012f11' sending FAX:
-- /faxouttmp/phpgCujSc
== Using UDPTL TOS bits 184
== Using UDPTL CoS mark 5
-- Channel 'SIP/voip-out-00012f11' FAX session '1610' started
-- FAX handle 1: [ 000.000179 ], STAT_EVT_STRT_TX st: IDLE rt: IDLENSTX
-- FAX handle 1: [ 000.000304 ], STAT_EVT_TX_HW_RDY st: WT_TX_HW_RDY rt: TRDYNHTY
-- FAX handle 1: [ 000.000358 ], P30EVN_SEND_STARTED
-- FAX handle 1: [ 008.732706 ], STAT_INFO_NSF
-- FAX handle 1: [ 009.442775 ], STAT_INFO_CSI
-- FAX handle 1: [ 009.762821 ], STAT_INFO_DIS
-- FAX handle 1: [ 009.762901 ], STAT_EVT_DIS st: WT_DIS rt: XXXXNDIS
-- FAX handle 1: [ 009.762936 ], STAT_EVT_REMOTE_RX st: WT_DIS rt: WDISNRRX
-- FAX handle 1: [ 009.762972 ], STAT_NEG_V29_9600
-- FAX handle 1: [ 009.762994 ], STAT_NEG_MR
-- FAX handle 1: [ 009.763015 ], STAT_NEG_RES_204x196
-- FAX handle 1: [ 009.763036 ], STAT_NEG_A4
-- FAX handle 1: [ 009.763062 ], STAT_INFO_TSI
-- FAX handle 1: [ 009.763130 ], STAT_INFO_DCS
-- FAX handle 1: [ 011.792213 ], STAT_EVT_TX_V21_DONE st: WT_DIS rt: WDISNT21
-- FAX handle 1: [ 013.651853 ], STAT_EVT_TX_TRN_END st: WT_TRN_RESP rt: XXXXNT21
-- FAX handle 1: [ 016.862550 ], STAT_FRM_FTT
-- FAX handle 1: [ 016.862624 ], STAT_EVT_FTT st: WT_TRN_RESP rt: WTTNNFTT
-- FAX handle 1: [ 016.862656 ], STAT_NEG_LOWER_RATE
-- FAX handle 1: [ 016.862684 ], STAT_INFO_TSI
-- FAX handle 1: [ 016.862751 ], STAT_INFO_DCS
-- FAX handle 1: [ 018.892049 ], STAT_EVT_TX_V21_DONE st: WT_DIS rt: WDISNT21
-- FAX handle 1: [ 020.751458 ], STAT_EVT_TX_TRN_END st: WT_TRN_RESP rt: XXXXNT21
-- FAX handle 1: [ 023.962794 ], STAT_FRM_FTT
-- FAX handle 1: [ 023.962871 ], STAT_EVT_FTT st: WT_TRN_RESP rt: WTTNNFTT
-- FAX handle 1: [ 023.962913 ], STAT_NEG_LOWER_RATE
-- FAX handle 1: [ 023.962950 ], STAT_INFO_TSI
-- FAX handle 1: [ 023.963066 ], STAT_INFO_DCS
-- FAX handle 1: [ 025.992154 ], STAT_EVT_TX_V21_DONE st: WT_DIS rt: WDISNT21
-- FAX handle 1: [ 028.580871 ], STAT_EVT_TX_TRN_END st: WT_TRN_RESP rt: XXXXNT21
-- FAX handle 1: [ 030.492875 ], STAT_FRM_CFR
-- FAX handle 1: [ 030.492951 ], STAT_EVT_CFR st: WT_TRN_RESP rt: WTTNNCFR
-- FAX handle 1: [ 030.493009 ], P30EVN_PHASE_C
-- FAX handle 1: [ 030.493050 ], P30EVN_DOC_START
-- FAX handle 1: [ 030.493088 ], P30EVN_PAGE_START
-- FAX handle 1: [ 030.781830 ], STAT_EVT_TX_IMG_STRT st: SEND_IMAGE rt: XXXXNTIB
-- FAX handle 1: [ 100.727757 ], STAT_EVT_TX_IMG_END st: SEND_IMAGE rt: XIMGNETI
-- FAX handle 1: [ 100.727839 ], P30EVN_PAGE_END
-- FAX handle 1: [ 100.727880 ], P30EVN_DOC_END
-- FAX handle 1: [ 100.727909 ], STAT_EVT_LAST_DOC st: SEND_IMAGE rt: XIMGNLST
-- FAX handle 1: [ 100.727938 ], STAT_FRM_EOP
-- FAX handle 1: [ 101.917804 ], STAT_EVT_TX_V21_DONE st: WT_EOP_RSP rt: XXXXNT21
-- FAX handle 1: [ 102.552624 ], STAT_FRM_EOP
-- FAX handle 1: [ 102.552700 ], STAT_EVT_EOP st: WT_EOP_RSP rt: XXXXNFSC
-- FAX handle 1: [ 102.552746 ], STAT_FRM_EOP
-- FAX handle 1: [ 103.744232 ], STAT_EVT_TX_V21_DONE st: WT_EOP_RSP rt: XXXXNT21
-- FAX handle 1: [ 104.372639 ], STAT_FRM_EOP
-- FAX handle 1: [ 104.372716 ], STAT_EVT_EOP st: WT_EOP_RSP rt: XXXXNFSC
-- FAX handle 1: [ 104.372762 ], STAT_FRM_EOP
-- FAX handle 1: [ 105.563529 ], STAT_EVT_TX_V21_DONE st: WT_EOP_RSP rt: XXXXNT21
-- FAX handle 1: [ 106.192922 ], STAT_FRM_EOP
-- FAX handle 1: [ 106.193001 ], STAT_EVT_EOP st: WT_EOP_RSP rt: XXXXNFSC
-- FAX handle 1: [ 106.193046 ], STAT_EVT_GO_TO_C st: WT_EOP_RSP rt: XXXXNGOC
-- FAX handle 1: [ 106.193091 ], P30EVN_PHASE_E
-- FAX handle 1: [ 106.193124 ], entering CLOSING state
-- FAX handle 1: [ 106.193148 ], STAT_FRM_DCN
-- FAX handle 1: [ 107.387153 ], STAT_EVT_TX_V21_DONE st: SEND_DCN rt: XDCNNT21
-- FAX handle 1: [ 109.887785 ], STAT_EVT_HW_CLOSE st: WT_HW_CLS rt: WCLSNCLS
-- FAX handle 1: [ 109.888024 ], STAT_SES_COMPLETE
-- FAX handle 1: [ 109.888091 ], P30EVN_COMPLETE
-- Channel 'SIP/voip-out-00012f11' FAX session '1610' is complete, result: 'FAILED' (FAX_FAILURE_PARTIAL), error: '3RD_FRM_CHECK_ERROR', pages: 1, resolution: '204x196', transfer rate: '4800', remoteSID: '631xxxxxxx'
[Oct 2 17:00:59] WARNING[22386]: pbx.c:5185 __ast_pbx_run: Timeout, but no rule 't' or 'e' in context 'outboundfax'
-- Executing [h@outboundfax:1] NoOp("SIP/voip-out-00012f11", "FAXOPT(ecm) : no") in new stack
-- Executing [h@outboundfax:2] NoOp("SIP/voip-out-00012f11", "FaxStatus : FAILED") in new stack
-- Executing [h@outboundfax:3] NoOp("SIP/voip-out-00012f11", "FaxStatusString : FAX_FAILURE_PARTIAL") in new stack
-- Executing [h@outboundfax:4] NoOp("SIP/voip-out-00012f11", "FaxError : 3RD_FRM_CHECK_ERROR") in new stack
-- Executing [h@outboundfax:5] NoOp("SIP/voip-out-00012f11", "RemoteStationID : 631xxxxxxx") in new stack
-- Executing [h@outboundfax:6] NoOp("SIP/voip-out-00012f11", "FaxPages : 1") in new stack
-- Executing [h@outboundfax:7] NoOp("SIP/voip-out-00012f11", "FaxBitRate : 4800") in new stack
-- Executing [h@outboundfax:8] NoOp("SIP/voip-out-00012f11", "FaxResolution : 204x196") in new stack
-- Executing [h@outboundfax:9] System("SIP/voip-out-00012f11", "/etc/asterisk/includes/scripts/fax_email_error.sh "3RD_FRM_CHECK_ERROR" "xyz@notification email" "631xxxxxxx" "10/02/12 : 16:58:27"") in new stack
-- Executing [h@outboundfax:10] System("SIP/voip-out-00012f11", "rm /faxouttmp/phpgCujSc") in new stack
[Oct 2 17:00:59] NOTICE[22386]: pbx_spool.c:366 attempt_thread: Call completed to SIP/631xxxxxxx@voip-out
Last edited by brettlehrer on Tue Oct 02, 2012 5:34 pm, edited 1 time in total.
brettlehrer
Newsterisk
 
Posts: 2
Joined: Tue Jul 17, 2012 8:38 am

Re: Increase reliability of outgoing faxing

Postby brettlehrer » Tue Oct 02, 2012 5:33 pm

Here's the log on a TIMEOUT/T1_TIMEOUT failure. I say that because the failure comes up long before the T1 window expires (35 sec +/- 5 sec, aka a max of 40 seconds), but the fax eventually DOES fail and the call ends.



-- Attempting call on SIP/516xxxxxxx@voip-out for s@outboundfax:1 (Retry 1)
== Using SIP RTP TOS bits 184
== Using SIP RTP CoS mark 5
> Channel SIP/voip-out-00012eda was answered.
-- Executing [s@outboundfax:1] Set("SIP/voip-out-00012eda", "FAXOPT(filename)=/faxouttmp/phphygQZv") in new stack
[Oct 2 16:18:15] WARNING[22118]: res_fax.c:2835 acf_faxopt_write: channel 'SIP/voip-out-00012eda' set FAXOPT(filename) to '/faxouttmp/phphygQZv' is unhandled!
-- Executing [s@outboundfax:2] Set("SIP/voip-out-00012eda", "FAXOPT(ecm)=yes") in new stack
-- Executing [s@outboundfax:3] Set("SIP/voip-out-00012eda", "FAXOPT(headerinfo)=xyz") in new stack
-- Executing [s@outboundfax:4] Set("SIP/voip-out-00012eda", "FAXOPT(localstationid)=414xxxxxxx") in new stack
-- Executing [s@outboundfax:5] NoOp("SIP/voip-out-00012eda", "Sender : xyz") in new stack
-- Executing [s@outboundfax:6] NoOp("SIP/voip-out-00012eda", "Recipient : 516xxxxxxx") in new stack
-- Executing [s@outboundfax:7] Set("SIP/voip-out-00012eda", "FAXOPT(modem)=V27,V29") in new stack
-- Executing [s@outboundfax:8] Set("SIP/voip-out-00012eda", "FAXOPT(maxrate)=9600") in new stack
-- Executing [s@outboundfax:9] Set("SIP/voip-out-00012eda", "FAXOPT(minrate)=2400") in new stack
-- Executing [s@outboundfax:10] SendFAX("SIP/voip-out-00012eda", "/faxouttmp/phphygQZv,dfz") in new stack
-- Channel 'SIP/voip-out-00012eda' sending FAX:
-- /faxouttmp/phphygQZv
== Using UDPTL TOS bits 184
== Using UDPTL CoS mark 5
-- Channel 'SIP/voip-out-00012eda' FAX session '1604' started
-- FAX handle 0: [ 000.000214 ], STAT_EVT_STRT_TX st: IDLE rt: IDLENSTX
-- FAX handle 0: [ 000.000337 ], STAT_EVT_TX_HW_RDY st: WT_TX_HW_RDY rt: TRDYNHTY
-- FAX handle 0: [ 000.000430 ], P30EVN_SEND_STARTED
[Oct 2 16:18:40] ERROR[22118]: res_fax.c:1365 generic_fax_exec: channel 'SIP/voip-out-00012eda' FAX session '1604' failure, reason: 'fax session timed-out' (TIMEOUT)
[Oct 2 16:18:51] WARNING[22118]: pbx.c:5185 __ast_pbx_run: Timeout, but no rule 't' or 'e' in context 'outboundfax'
-- Executing [h@outboundfax:1] NoOp("SIP/voip-out-00012eda", "FAXOPT(ecm) : yes") in new stack
-- Executing [h@outboundfax:2] NoOp("SIP/voip-out-00012eda", "FaxStatus : FAILED") in new stack
-- Executing [h@outboundfax:3] NoOp("SIP/voip-out-00012eda", "FaxStatusString : fax session timed-out") in new stack
-- Executing [h@outboundfax:4] NoOp("SIP/voip-out-00012eda", "FaxError : TIMEOUT") in new stack
-- Executing [h@outboundfax:5] NoOp("SIP/voip-out-00012eda", "RemoteStationID : ") in new stack
-- Executing [h@outboundfax:6] NoOp("SIP/voip-out-00012eda", "FaxPages : 0") in new stack
-- Executing [h@outboundfax:7] NoOp("SIP/voip-out-00012eda", "FaxBitRate : ") in new stack
-- Executing [h@outboundfax:8] NoOp("SIP/voip-out-00012eda", "FaxResolution : ") in new stack
-- Executing [h@outboundfax:9] System("SIP/voip-out-00012eda", "/etc/asterisk/includes/scripts/fax_email_error.sh "TIMEOUT" "xyz@notification email" "516xxxxxxx" "10/02/12 : 16:17:56"") in new stack
-- Executing [h@outboundfax:10] System("SIP/voip-out-00012eda", "rm /faxouttmp/phphygQZv") in new stack
[Oct 2 16:18:51] NOTICE[22118]: pbx_spool.c:366 attempt_thread: Call completed to SIP/516xxxxxxx@voip-out
-- FAX handle 0: [ 040.000975 ], STAT_EVT_T1_EXP st: WT_DIS rt: WDISNT1X
-- FAX handle 0: [ 042.500568 ], STAT_EVT_HW_CLOSE st: WT_HW_CLS rt: WCLSNCLS
-- FAX handle 0: [ 042.500879 ], STAT_SES_COMPLETE
-- FAX handle 0: [ 042.500934 ], P30EVN_COMPLETE
-- Channel 'SIP/voip-out-00012eda' FAX session '1604' is complete, result: 'FAILED' (FAX_NO_FAX), error: 'T1_TIMEOUT', pages: 0, resolution: 'unknown', transfer rate: '2400', remoteSID: ''
brettlehrer
Newsterisk
 
Posts: 2
Joined: Tue Jul 17, 2012 8:38 am


Return to Fax For Asterisk

Who is online

Users browsing this forum: No registered users and 1 guest