Hello,
I am running FreePBX v13.0.197.14 (firmware 10.13.66-22) and Asterisk v13.23.1. Up until now, inbound fax-to-email has been working, but my client has reported to me that they have had a couple of their clients try to fax documents and either the entire fax does not come through (only some pages), or it fails.
My client does seem to mostly get faxes OK, but they are only a few pages. The issues seem to occur wih faxes that consist ofseveralpages.
I have been able to reproduce the problem with both a physical fax and a email-to-fax gateway that another client of mine uses. In my testing, I have tried two different multi-page documents: one consisting of 16 pages and the other 9 pages.
Regardless of which document or fax method I try, the whole fax does not go through. The fax is indicated as failed, but a couple of pages of my fax do still make it through, but it is random: sometime it will be the first two or three, but in one case, only page 3 made it through.
I have included a log of my last fax attempt below, which is from a physcial fax machine (IP addresss of my client’s PBX changed). I don’t see anything overtly wrong, but I am not an expert at this either.
Not sure if this points ot a problem with FreePBX, or perhaps the SIP trunk provider. I have opened a ticket with them too, but am just trying to cover all the bases I can.
The only real possible issue I see in the call trace is “WARNING T.30 ECM carrier not found”.
Here is the call trace:
[2019-12-10 16:33:48] VERBOSE[14303][C-00016876] netsock2.c: Using SIP RTP TOS bits 184
[2019-12-10 16:33:48] VERBOSE[14303][C-00016876] netsock2.c: Using SIP RTP CoS mark 5
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk-sip-ThinkTel-SIP-YEG1:1] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “GROUP()=OUT_2”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk-sip-ThinkTel-SIP-YEG1:2] Goto(“SIP/ThinkTel-SIP-YEG1-0001d781”, “from-trunk,6046838032,1”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (from-trunk,6046838032,1)
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:1] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__DIRECTION=INBOUND”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:2] Gosub(“SIP/ThinkTel-SIP-YEG1-0001d781”, “sub-record-check,s,1(in,6046838032,dontcare)”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:1] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “0?initialized”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:2] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__REC_STATUS=INITIALIZED”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:3] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “NOW=1576024428”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:4] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__DAY=10”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:5] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__MONTH=12”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:6] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__YEAR=2019”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:7] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__TIMESTR=20191210-163348”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:8] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__FROMEXTEN=unknown”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:9] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__MON_FMT=wav”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:10] NoOp(“SIP/ThinkTel-SIP-YEG1-0001d781”, “Recordings initialized”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:11] ExecIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “0?Set(ARG3=dontcare)”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:12] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “REC_POLICY_MODE_SAVE=”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:13] ExecIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “0?Set(REC_STATUS=NO)”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:14] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “2?checkaction”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (sub-record-check,s,17)
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@sub-record-check:17] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “1?sub-record-check,in,1”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (sub-record-check,in,1)
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [in@sub-record-check:1] NoOp(“SIP/ThinkTel-SIP-YEG1-0001d781”, “Inbound Recording Check to 6046838032”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [in@sub-record-check:2] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “FROMEXTEN=unknown”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [in@sub-record-check:3] ExecIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “10?Set(FROMEXTEN=7783401109)”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [in@sub-record-check:4] Gosub(“SIP/ThinkTel-SIP-YEG1-0001d781”, “recordcheck,1(dontcare,in,6046838032)”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp(“SIP/ThinkTel-SIP-YEG1-0001d781”, “Starting recording check against dontcare”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [recordcheck@sub-record-check:2] Goto(“SIP/ThinkTel-SIP-YEG1-0001d781”, “dontcare”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [recordcheck@sub-record-check:3] Return(“SIP/ThinkTel-SIP-YEG1-0001d781”, “”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [in@sub-record-check:5] Return(“SIP/ThinkTel-SIP-YEG1-0001d781”, “”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:3] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__FROM_DID=6046838032”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:4] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “returnhere=1”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:5] Gosub(“SIP/ThinkTel-SIP-YEG1-0001d781”, “app-blacklist-check,s,1()”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@app-blacklist-check:1] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “0?blacklisted”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@app-blacklist-check:2] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “CALLED_BLACKLIST=1”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [s@app-blacklist-check:3] Return(“SIP/ThinkTel-SIP-YEG1-0001d781”, “”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:6] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “CDR(did)=6046838032”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:7] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “0?”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:8] ExecIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “0 ?Set(CALLERID(name)=7783401109)”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:9] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__MOHCLASS=”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:10] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__REVERSAL_REJECT=FALSE”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:11] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “1?post-reverse-charge”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (from-trunk,6046838032,13)
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:13] NoOp(“SIP/ThinkTel-SIP-YEG1-0001d781”, “”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:14] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__CALLINGNAMEPRES_SV=allowed_not_screened”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:15] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__CALLINGNUMPRES_SV=allowed_not_screened”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:16] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “CALLERID(name-pres)=allowed_not_screened”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:17] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “CALLERID(num-pres)=allowed_not_screened”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:18] NoOp(“SIP/ThinkTel-SIP-YEG1-0001d781”, “CallerID Entry Point”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:19] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “FAX_DEST=ext-fax^222^1”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:20] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “FAXOPT(faxdetect)=yes”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:21] Answer(“SIP/ThinkTel-SIP-YEG1-0001d781”, “”) in new stack
[2019-12-10 16:33:48] VERBOSE[8996][C-00016876] pbx.c: Executing [6046838032@from-trunk:22] Wait(“SIP/ThinkTel-SIP-YEG1-0001d781”, “7”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] res_fax.c: Redirecting ‘SIP/ThinkTel-SIP-YEG1-0001d781’ to fax extension due to CNG detection
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Spawn extension (from-trunk, fax, 1) exited non-zero on ‘SIP/ThinkTel-SIP-YEG1-0001d781’
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [fax@from-trunk:1] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “__DIRECTION=INBOUND”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [fax@from-trunk:2] Goto(“SIP/ThinkTel-SIP-YEG1-0001d781”, “ext-fax,222,1”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (ext-fax,222,1)
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [222@ext-fax:1] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “FAX_FOR=FAX Metrix (222)”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [222@ext-fax:2] NoOp(“SIP/ThinkTel-SIP-YEG1-0001d781”, “Receiving Fax for: FAX Metrix (222), From: “PSD INC” <7783401109>”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [222@ext-fax:3] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “FAX_RX_USER=222”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [222@ext-fax:4] Set(“SIP/ThinkTel-SIP-YEG1-0001d781”, “FAX_RX_EMAIL_LEN=14”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [222@ext-fax:5] Goto(“SIP/ThinkTel-SIP-YEG1-0001d781”, “s,receivefax”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (ext-fax,s,3)
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [s@ext-fax:3] StopPlayTones(“SIP/ThinkTel-SIP-YEG1-0001d781”, “”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] pbx.c: Executing [s@ext-fax:4] ReceiveFAX(“SIP/ThinkTel-SIP-YEG1-0001d781”, “/var/spool/asterisk/fax/1576024428.125964.tif,f”) in new stack
[2019-12-10 16:33:50] VERBOSE[8996][C-00016876] res_fax.c: Channel ‘SIP/ThinkTel-SIP-YEG1-0001d781’ receiving FAX ‘/var/spool/asterisk/fax/1576024428.125964.tif’
[2019-12-10 16:34:05] WARNING[14303][C-00016876] chan_sip.c: Failed to initialize UDPTL, declining image stream
[2019-12-10 16:34:05] WARNING[14303][C-00016876] chan_sip.c: Failing due to no acceptable offer found
[2019-12-10 16:34:11] WARNING[8996][C-00016876] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2019-12-10 16:34:12] WARNING[8996][C-00016876] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2019-12-10 16:34:12] WARNING[8996][C-00016876] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Spawn extension (ext-fax, s, 4) exited non-zero on ‘SIP/ThinkTel-SIP-YEG1-0001d781’
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Executing [h@ext-fax:1] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “1?failed”) in new stack
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (ext-fax,h,104)
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Executing [h@ext-fax:104] NoOp(“SIP/ThinkTel-SIP-YEG1-0001d781”, “FAX FAILED for: FAX Metrix (222) , From: “PSD INC” <7783401109>”) in new stack
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Executing [h@ext-fax:105] Macro(“SIP/ThinkTel-SIP-YEG1-0001d781”, “hangupcall,”) in new stack
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Executing [s@macro-hangupcall:1] GotoIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “1?theend”) in new stack
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx_builtins.c: Goto (macro-hangupcall,s,3)
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Executing [s@macro-hangupcall:3] ExecIf(“SIP/ThinkTel-SIP-YEG1-0001d781”, “0?Set(CDR(recordingfile)=)”) in new stack
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Executing [s@macro-hangupcall:4] Hangup(“SIP/ThinkTel-SIP-YEG1-0001d781”, “”) in new stack
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] app_macro.c: Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/ThinkTel-SIP-YEG1-0001d781’ in macro ‘hangupcall’
[2019-12-10 16:35:07] VERBOSE[8996][C-00016876] pbx.c: Spawn extension (ext-fax, h, 105) exited non-zero on ‘SIP/ThinkTel-SIP-YEG1-0001d781’