Fax Pro - Failed inbound faxes from only a few senders

Commercial Modules
1

I have recently installed Fax Pro it works to send faxes but has been failing to receive faxes from several services we need to get faxes from…here is a log of a failure…The log does not seem tell why it failed only that it failed after permitted retries. I had retires set to 1 then changed it to 3 both settings still fails… Hopefully someone can make a recommendation on what to try to get this working.

[2017-08-31 11:55:57] VERBOSE[32234][C-00000a23] pbx.c: Executing [h@ext-fax:105] Macro("SIP/voipms_ny6-0000093e", "hangupcall,") in new stack
[2017-08-31 11:55:57] VERBOSE[32234][C-00000a23] pbx.c: Spawn extension (ext-fax, h, 105) exited non-zero on 'SIP/voipms_ny6-0000093e'
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [5084737699@from-trunk:20] Goto("SIP/voipms_ny6-0000093f", "ext-fax,7,1") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx_builtins.c: Goto (ext-fax,7,1)
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [7@ext-fax:1] Set("SIP/voipms_ny6-0000093f", "FAX_FOR=FAX (7)") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [7@ext-fax:2] NoOp("SIP/voipms_ny6-0000093f", "Receiving Fax for: FAX (7), From: "9493724369" <9493724369>") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [7@ext-fax:3] Set("SIP/voipms_ny6-0000093f", "FAX_RX_USER=7") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [7@ext-fax:4] Set("SIP/voipms_ny6-0000093f", "FAX_RX_EMAIL_LEN=23") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [7@ext-fax:5] ExecIf("SIP/voipms_ny6-0000093f", "1?Set(ARIUSER=7)") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [7@ext-fax:6] ExecIf("SIP/voipms_ny6-0000093f", "1?AGI(fax.agi)") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/fax.agi
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] res_agi.c: <SIP/voipms_ny6-0000093f>AGI Script fax.agi completed, returning 0
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [7@ext-fax:7] Goto("SIP/voipms_ny6-0000093f", "s,receivefax") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx_builtins.c: Goto (ext-fax,s,3)
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [s@ext-fax:3] StopPlayTones("SIP/voipms_ny6-0000093f", "") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] pbx.c: Executing [s@ext-fax:4] ReceiveFAX("SIP/voipms_ny6-0000093f", "/var/spool/asterisk/fax/1504194974.5318.tif,f") in new stack
[2017-08-31 11:56:17] VERBOSE[32469][C-00000a24] res_fax.c: Channel 'SIP/voipms_ny6-0000093f' receiving FAX '/var/spool/asterisk/fax/1504194974.5318.tif'
[2017-08-31 11:56:39] VERBOSE[32469][C-00000a24] pbx.c: Executing [s@ext-fax:5] ExecIf("SIP/voipms_ny6-0000093f", "1?Set(FAXSTATUS="FAILED: error: Disconnected after permitted retries statusstr: Disconnected after permitted retries")") in new stack

Retries set to 3:

[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:1] Set("SIP/voipms_ny6-00000949", "__DIRECTION=INBOUND") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:2] Gosub("SIP/voipms_ny6-00000949", "sub-record-check,s,1(in,5084737699,dontcare)") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:1] GotoIf("SIP/voipms_ny6-00000949", "0?initialized") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:2] Set("SIP/voipms_ny6-00000949", "__REC_STATUS=INITIALIZED") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:3] Set("SIP/voipms_ny6-00000949", "NOW=1504197080") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:4] Set("SIP/voipms_ny6-00000949", "__DAY=31") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:5] Set("SIP/voipms_ny6-00000949", "__MONTH=08") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:6] Set("SIP/voipms_ny6-00000949", "__YEAR=2017") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:7] Set("SIP/voipms_ny6-00000949", "__TIMESTR=20170831-123120") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:8] Set("SIP/voipms_ny6-00000949", "__FROMEXTEN=unknown") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:9] Set("SIP/voipms_ny6-00000949", "__MON_FMT=wav") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:10] NoOp("SIP/voipms_ny6-00000949", "Recordings initialized") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:11] ExecIf("SIP/voipms_ny6-00000949", "0?Set(ARG3=dontcare)") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:12] Set("SIP/voipms_ny6-00000949", "REC_POLICY_MODE_SAVE=") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:13] ExecIf("SIP/voipms_ny6-00000949", "0?Set(REC_STATUS=NO)") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:14] GotoIf("SIP/voipms_ny6-00000949", "2?checkaction") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx_builtins.c: Goto (sub-record-check,s,17)
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@sub-record-check:17] GotoIf("SIP/voipms_ny6-00000949", "1?sub-record-check,in,1") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx_builtins.c: Goto (sub-record-check,in,1)
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [in@sub-record-check:1] NoOp("SIP/voipms_ny6-00000949", "Inbound Recording Check to 5084737699") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [in@sub-record-check:2] Set("SIP/voipms_ny6-00000949", "FROMEXTEN=unknown") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [in@sub-record-check:3] ExecIf("SIP/voipms_ny6-00000949", "10?Set(FROMEXTEN=4029703226)") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [in@sub-record-check:4] Gosub("SIP/voipms_ny6-00000949", "recordcheck,1(dontcare,in,5084737699)") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [recordcheck@sub-record-check:1] NoOp("SIP/voipms_ny6-00000949", "Starting recording check against dontcare") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [recordcheck@sub-record-check:2] Goto("SIP/voipms_ny6-00000949", "dontcare") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx_builtins.c: Goto (sub-record-check,recordcheck,3)
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [recordcheck@sub-record-check:3] Return("SIP/voipms_ny6-00000949", "") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [in@sub-record-check:5] Return("SIP/voipms_ny6-00000949", "") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:3] Gosub("SIP/voipms_ny6-00000949", "app-blacklist-check,s,1()") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@app-blacklist-check:1] GotoIf("SIP/voipms_ny6-00000949", "0?blacklisted") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@app-blacklist-check:2] Set("SIP/voipms_ny6-00000949", "CALLED_BLACKLIST=1") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@app-blacklist-check:3] Return("SIP/voipms_ny6-00000949", "") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:4] Set("SIP/voipms_ny6-00000949", "__FROM_DID=5084737699") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:5] Set("SIP/voipms_ny6-00000949", "CDR(did)=5084737699") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:6] ExecIf("SIP/voipms_ny6-00000949", "0 ?Set(CALLERID(name)=4029703226)") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:7] Set("SIP/voipms_ny6-00000949", "__MOHCLASS=") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:8] Ringing("SIP/voipms_ny6-00000949", "") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:9] Set("SIP/voipms_ny6-00000949", "__RINGINGSENT=TRUE") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:10] Set("SIP/voipms_ny6-00000949", "__REVERSAL_REJECT=FALSE") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:11] GotoIf("SIP/voipms_ny6-00000949", "1?post-reverse-charge") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx_builtins.c: Goto (from-trunk,5084737699,13)
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:13] NoOp("SIP/voipms_ny6-00000949", "") in new stack
[2017-08-31 12:31:20] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:14] Wait("SIP/voipms_ny6-00000949", "3") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:15] Set("SIP/voipms_ny6-00000949", "__CALLINGNAMEPRES_SV=allowed_not_screened") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:16] Set("SIP/voipms_ny6-00000949", "__CALLINGNUMPRES_SV=allowed_not_screened") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:17] Set("SIP/voipms_ny6-00000949", "CALLERID(name-pres)=allowed_not_screened") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:18] Set("SIP/voipms_ny6-00000949", "CALLERID(num-pres)=allowed_not_screened") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:19] NoOp("SIP/voipms_ny6-00000949", "CallerID Entry Point") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [5084737699@from-trunk:20] Goto("SIP/voipms_ny6-00000949", "ext-fax,7,1") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx_builtins.c: Goto (ext-fax,7,1)
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [7@ext-fax:1] Set("SIP/voipms_ny6-00000949", "FAX_FOR=FAX (7)") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [7@ext-fax:2] NoOp("SIP/voipms_ny6-00000949", "Receiving Fax for: FAX (7), From: "4029703226" <4029703226>") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [7@ext-fax:3] Set("SIP/voipms_ny6-00000949", "FAX_RX_USER=7") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [7@ext-fax:4] Set("SIP/voipms_ny6-00000949", "FAX_RX_EMAIL_LEN=23") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [7@ext-fax:5] ExecIf("SIP/voipms_ny6-00000949", "1?Set(ARIUSER=7)") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [7@ext-fax:6] ExecIf("SIP/voipms_ny6-00000949", "1?AGI(fax.agi)") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] res_agi.c: Launched AGI Script /var/lib/asterisk/agi-bin/fax.agi
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] res_agi.c: <SIP/voipms_ny6-00000949>AGI Script fax.agi completed, returning 0
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [7@ext-fax:7] Goto("SIP/voipms_ny6-00000949", "s,receivefax") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx_builtins.c: Goto (ext-fax,s,3)
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@ext-fax:3] StopPlayTones("SIP/voipms_ny6-00000949", "") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@ext-fax:4] ReceiveFAX("SIP/voipms_ny6-00000949", "/var/spool/asterisk/fax/1504197080.5334.tif,f") in new stack
[2017-08-31 12:31:23] VERBOSE[47147][C-00000a2e] res_fax.c: Channel 'SIP/voipms_ny6-00000949' receiving FAX '/var/spool/asterisk/fax/1504197080.5334.tif'
[2017-08-31 12:31:44] VERBOSE[47147][C-00000a2e] pbx.c: Executing [s@ext-fax:5] ExecIf("SIP/voipms_ny6-00000949", "1?Set(FAXSTATUS="FAILED: error: Disconnected after permitted retries statusstr: Disconnected after permitted retries")") in new stack
2
3

Thanks for the link. I am using thee Fax Pro with Fax Detection set = No and a dedicated extension already. The fax works to send and receives from some Fax Senders but not others. I am not sure why the connection to some fax machines is not working. I am hoping someone knows how to get the Fax Pro to work and connect with all Fax machines.

4

Just so you are aware the inbound functionality is free and is part of faxing, not fax pro.

5

Thanks so much for your input, I did know the inbound fax was free; however I do need to send faxes so I have installed Fax Pro. By any chance do you have any input on how to configure the inbound faxes so that all fax machines can communicate with them?

6

It looks like the issue is with T.38 negotiation. As in the far end is not negotiating with you correctly. Sorry I don’t have much help to help you with