Incoming fax from analog lines fail. Dialplan problem? FaxOpt to blame... resolution required

I am encountering a problem when receiving a fax sent from an analog line. I tested a fax from fax zero to destination DID/sip extension and it came in just fine. Is it possible that my generated ext-fax dial plan is the problem? For receiving faxes from an analog line what should I be looking for? Attached are error(s) and success(s).

Fax from Fax Zero to DID

[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:1] Set("SIP/SOME-TRNK-0000075a", "__FROM_DID=5552221313") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:2] Gosub("SIP/SOME-TRNK-0000075a", "app-blacklist-check,s,1") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/SOME-TRNK-0000075a", "0?blacklisted") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/SOME-TRNK-0000075a", "CALLED_BLACKLIST=1") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/SOME-TRNK-0000075a", "") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:3] ExecIf("SIP/SOME-TRNK-0000075a", "0 ?Set(CALLERID(name)=8009806858)") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:4] Set("SIP/SOME-TRNK-0000075a", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:5] Set("SIP/SOME-TRNK-0000075a", "CALLERPRES()=allowed_not_screened") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:6] Set("SIP/SOME-TRNK-0000075a", "FAX_DEST=ext-fax^4001^1") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:7] Answer("SIP/SOME-TRNK-0000075a", "") in new stack
[2011-08-04 15:38:43] VERBOSE[19180] pbx.c: -- Executing [5552221313@from-trunk:8] Wait("SIP/SOME-TRNK-0000075a", "4") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] chan_sip.c: == Redirecting 'SIP/SOME-TRNK-0000075a' to fax extension due to CNG detection
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: == Spawn extension (from-trunk, fax, 1) exited non-zero on 'SIP/SOME-TRNK-0000075a'
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [fax@from-trunk:1] Goto("SIP/SOME-TRNK-0000075a", "ext-fax,4001,1") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Goto (ext-fax,4001,1)
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [4001@ext-fax:1] NoOp("SIP/SOME-TRNK-0000075a", "Receiving Fax for: SPC4001 (4001), From: "8009806858" <8009806858>") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [4001@ext-fax:2] Set("SIP/SOME-TRNK-0000075a", "[email protected]") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [4001@ext-fax:3] Goto("SIP/SOME-TRNK-0000075a", "s,receivefax") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Goto (ext-fax,s,3)
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [s@ext-fax:3] StopPlayTones("SIP/SOME-TRNK-0000075a", "") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [s@ext-fax:4] ReceiveFAX("SIP/SOME-TRNK-0000075a", "/var/spool/asterisk/fax/1312497522.2395.tif,f") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] res_fax.c: -- Channel 'SIP/SOME-TRNK-0000075a' receiving FAX '/var/spool/asterisk/fax/1312497522.2395.tif'
[2011-08-04 15:38:55] WARNING[19180] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2011-08-04 15:38:56] WARNING[19180] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2011-08-04 15:38:56] WARNING[19180] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2011-08-04 15:39:19] VERBOSE[19180] pbx.c: == Spawn extension (ext-fax, s, 4) exited non-zero on 'SIP/SOME-TRNK-0000075a'
[2011-08-04 15:39:19] VERBOSE[19180] pbx.c: -- Executing [h@ext-fax:1] GotoIf("SIP/SOME-TRNK-0000075a", "0?failed") in new stack
[2011-08-04 15:39:19] VERBOSE[19180] pbx.c: -- Executing [h@ext-fax:2] GotoIf("SIP/SOME-TRNK-0000075a", "0?end") in new stack
[2011-08-04 15:39:19] VERBOSE[19180] pbx.c: -- Executing [h@ext-fax:3] System("SIP/SOME-TRNK-0000075a", "/var/lib/asterisk/bin/fax-process.pl --to "[email protected]" --from "" --dest "5552221313" --subject "New fax from 8009806858 %3C8009806858%3E" --attachment fax_8009806858.pdf --type application/pdf --file /var/spool/asterisk/fax/1312497522.2395.tif") in new stack
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Executing [h@ext-fax:4] Macro("SIP/SOME-TRNK-0000075a", "hangupcall,") in new stack
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/SOME-TRNK-0000075a", "1?skiprg") in new stack
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Goto (macro-hangupcall,s,4)
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/SOME-TRNK-0000075a", "1?skipblkvm") in new stack
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Goto (macro-hangupcall,s,7)
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/SOME-TRNK-0000075a", "1?theend") in new stack
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Goto (macro-hangupcall,s,9)
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/SOME-TRNK-0000075a", "") in new stack
[2011-08-04 15:39:20] VERBOSE[19180] app_macro.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/SOME-TRNK-0000075a' in macro 'hangupcall'
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: == Spawn extension (ext-fax, h, 4) exited non-zero on 'SIP/SOME-TRNK-0000075a'

Above was successful and came through to email just fine as .pdf. Now what happens when sent from an analog line to system.

[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:1] Set("SIP/SOME-TRNK-00000760", "__FROM_DID=5552221313") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:2] Gosub("SIP/SOME-TRNK-00000760", "app-blacklist-check,s,1") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/SOME-TRNK-00000760", "0?blacklisted") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/SOME-TRNK-00000760", "CALLED_BLACKLIST=1") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:3] ExecIf("SIP/SOME-TRNK-00000760", "0 ?Set(CALLERID(name)=3235555567)") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:4] Set("SIP/SOME-TRNK-00000760", "__CALLINGPRES_SV=allowed_not_screened") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:5] Set("SIP/SOME-TRNK-00000760", "CALLERPRES()=allowed_not_screened") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:6] Set("SIP/SOME-TRNK-00000760", "FAX_DEST=ext-fax^4001^1") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:7] Answer("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [5552221313@from-trunk:8] Wait("SIP/SOME-TRNK-00000760", "4") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] chan_sip.c: == Redirecting 'SIP/SOME-TRNK-00000760' to fax extension due to CNG detection
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: == Spawn extension (from-trunk, fax, 1) exited non-zero on 'SIP/SOME-TRNK-00000760'
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [fax@from-trunk:1] Goto("SIP/SOME-TRNK-00000760", "ext-fax,4001,1") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Goto (ext-fax,4001,1)
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [4001@ext-fax:1] NoOp("SIP/SOME-TRNK-00000760", "Receiving Fax for: SPC4001 (4001), From: "3235555567" <3235555567>") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [4001@ext-fax:2] Set("SIP/SOME-TRNK-00000760", "[email protected]") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [4001@ext-fax:3] Goto("SIP/SOME-TRNK-00000760", "s,receivefax") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Goto (ext-fax,s,3)
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:3] StopPlayTones("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:4] ReceiveFAX("SIP/SOME-TRNK-00000760", "/var/spool/asterisk/fax/1312498031.2401.tif,f") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] res_fax.c: -- Channel 'SIP/SOME-TRNK-00000760' receiving FAX '/var/spool/asterisk/fax/1312498031.2401.tif'
[2011-08-04 15:47:27] WARNING[19251] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2011-08-04 15:47:28] WARNING[19251] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2011-08-04 15:47:28] WARNING[19251] res_fax_spandsp.c: WARNING T.30 ECM carrier not found
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:5] ExecIf("SIP/SOME-TRNK-00000760", "1?Set(FAXSTATUS=FAILED LICENSE EXCEEDED)") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:6] ExecIf("SIP/SOME-TRNK-00000760", "0?Set(FAXSTATUS="FAILED FAXOPT: error: status: SUCCESS statusstr: OK")") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:7] Hangup("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: == Spawn extension (ext-fax, s, 7) exited non-zero on 'SIP/SOME-TRNK-00000760'
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [h@ext-fax:1] GotoIf("SIP/SOME-TRNK-00000760", "1?failed") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Goto (ext-fax,h,103)
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [h@ext-fax:103] NoOp("SIP/SOME-TRNK-00000760", "FAX FAILED LICENSE EXCEEDED for: [email protected] , From: "3235555567" <32355555567>") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [h@ext-fax:104] Macro("SIP/SOME-TRNK-00000760", "hangupcall,") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@macro-hangupcall:1] GotoIf("SIP/SOME-TRNK-00000760", "1?skiprg") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Goto (macro-hangupcall,s,4)
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@macro-hangupcall:4] GotoIf("SIP/SOME-TRNK-00000760", "1?skipblkvm") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Goto (macro-hangupcall,s,7)
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@macro-hangupcall:7] GotoIf("SIP/SOME-TRNK-00000760", "1?theend") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Goto (macro-hangupcall,s,9)
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@macro-hangupcall:9] Hangup("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] app_macro.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/SOME-TRNK-00000760' in macro 'hangupcall'
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: == Spawn extension (ext-fax, h, 104) exited non-zero on 'SIP/SOME-TRNK-00000760'

Here it fails. Dial plan being utilized below.

[ext-fax]
exten => in_fax,1,StopPlaytones ; you must do this or it will play ring sounds over your fax
exten => in_fax,2,GotoIf($[${FAX_RX} = system]?3:analog_fax,1)
exten => in_fax,3,Macro(faxreceive)
exten => in_fax,4,Hangup
exten => analog_fax,1,GotoIf($[${FAX_RX} = disabled]?3:2) ;if fax is disabled, just hang up
exten => analog_fax,2,DBGet(DIAL=DEVICE/${FAX_RX}/dial);
exten => analog_fax,3,Dial(${DIAL},20,d)
exten => analog_fax,4,Hangup
exten => out_fax,1,txfax(${TXFAX_NAME},caller)
exten => out_fax,2,Hangup
exten => h,1,system(/var/lib/asterisk/bin/fax-process.pl --to ${EMAILADDR} --from ${FAX_RX_FROM} --subject "Fax from ${URIENCODE(${CALLERID(number)})} ${URIENCODE(${CALLERID(name)})}" --attachment fax_${URIENCODE(${CALLERID(number)})}.pdf --type application/pdf --file ${FAXFILE});
exten => h,2,system(rm ${FAXFILE})
exten => h,3,Hangup()

If relevant asterisk cli information for FAX license etc.

'fax show license'

Fax Licensing Information
==============================
Free fax licenses: 1
Total licensed ports: 1

Licenses Found:
File: FFA-......

'core show applications like fax'

    -= Matching Asterisk Applications =-
            ReceiveFAX: Receive a Fax 
               SendFAX: Send a Fax 
    -= 2 Applications Matching =-

'fax show settings'

FAX For Asterisk Settings:
	ECM: Enabled
	Status Events: Off
	Minimum Bit Rate: 14400
	Maximum Bit Rate: 14400
	Modem Modulations Allowed: V17,V27,V29


FAX Technology Modules:

Spandsp (Spandsp FAX Driver) Settings:
DIGIUM (Digium FAX Driver) Settings:
	Maximum T.38 Packet Delay: 800
	T.38 Session Packet Capture: Off
	G.711 Session Audio Capture: Off

I hope this helps with the debugging of the problem. Also is there another forum I should be replicating this information to saturate and receive a better response and fix? Thank you for any help/support/advice in advance.

Have you noted this:

[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:5] ExecIf("SIP/SOME-TRNK-00000760", "1?Set(FAXSTATUS=FAILED LICENSE EXCEEDED)") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [h@ext-fax:103] NoOp("SIP/SOME-TRNK-00000760", "FAX FAILED LICENSE EXCEEDED for: [email protected] , From: "3239315667" <3239315667>") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [h@ext-fax:104] Macro("SIP/SOME-TRNK-00000760", "hangupcall,") in new stack

Which part? The mail was replaced it goes to a real account just pulled for the sake of privacy. Or an I looking at something else entirely? What exactly are you referring to?

FAX FAILED LICENSE EXCEEDED

Asterisk FFA is reporting that you have exceeded the license.

Using a single license, only receiving faxes on that line not others. The license exceeded error only comes up when an analog line sends a fax through. When I sent the fax over faxzero.com the fax came in just fine. Where can I look at *FFA to see more than just verbosity from the CLI?

I have read through the link below but new to the system. Not sure what needs to be changed to avoid that false positive.

http://www.freepbx.org/v2/ticket/4045

Mentions a fax license exceed error as a bug. Am I encountering a similar problem?

Just a question, where did you get the ext-fax dialplan from?
Because that dialplan is not what it is used in the log files.

Dialplan is coming from /etc/asterisk/extensions_custom.conf
I noticed the same but can’t seem to find any other plan.

The plan from the location mentioned above does not include any of the lines below. Notable is the 5/6/7 calls. So I am at a complete loss. went through some motions including removing fax configuration module then reinstalling it. Dialplan from /etc/asterisk/extensions_custom.conf did not change. Should I be looking for a dialplan elsewhere?


[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:5] ExecIf("SIP/SOME-TRNK-00000760", "1?Set(FAXSTATUS=FAILED LICENSE EXCEEDED)") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:6] ExecIf("SIP/SOME-TRNK-00000760", "0?Set(FAXSTATUS="FAILED FAXOPT: error: status: SUCCESS statusstr: OK")") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [s@ext-fax:7] Hangup("SIP/SOME-TRNK-00000760", "") in new stack

Thank you for your attention to this matter. Appreciate the help.

The ext-fax dialplan is in the extensions_additional.conf file.
Check that you don’t have a hung channel by typing core show channels in an Asterisk CLI.

No hung channels. Popping in with the correct config.

[ext-fax]
include => ext-fax-custom
exten => 400,1,Noop(Receiving Fax for: SPC (400), From: ${CALLERID(all)})
exten => 400,n,Set([email protected])
exten => 400,n(receivefax),Goto(s,receivefax)
exten => s,1,Macro(user-callerid,)
exten => s,n,Noop(Receiving Fax for: ${FAX_RX_EMAIL} , From: ${CALLERID(all)})
exten => s,n(receivefax),StopPlaytones
exten => s,n,ReceiveFAX(${ASTSPOOLDIR}/fax/${UNIQUEID}.tif,f)
exten => s,n,ExecIf($["${FAXOPT(error)}"=""]?Set(FAXSTATUS=FAILED LICENSE EXCEEDED))
exten => s,n,ExecIf($["${FAXOPT(error)}"!="" && "${FAXOPT(error)}"!="NO_ERROR"]?Set(FAXSTATUS="FAILED FAXOPT: error: ${FAXOPT(error)} status: ${FAXOPT(status)} statusstr: ${FAXOPT(statusstr)}"))
exten => s,n,Hangup
exten => h,1,GotoIf($["${FAXSTATUS:0:6}" = "FAILED"]?failed)
exten => h,n(process),GotoIf($[${LEN(${FAX_RX_EMAIL})} = 0]?end)
exten => h,n,System(${ASTVARLIBDIR}/bin/fax-process.pl --to "${FAX_RX_EMAIL}" --from "" --dest "${FROM_DID}" --subject "New fax from ${URIENCODE(${CALLERID(name)})} ${URIENCODE(<${CALLERID(number)}>)}" --attachment fax_${URIENCODE(${CALLERID(number)})}.pdf --type application/pdf --file ${ASTSPOOLDIR}/fax/${UNIQUEID}.tif)
exten => h,n(end),Macro(hangupcall,)
exten => h,process+101(failed),Noop(FAX ${FAXSTATUS} for: ${FAX_RX_EMAIL} , From: ${CALLERID(all)})
exten => h,n,Macro(hangupcall,)

; end of [ext-fax]

FreePBX version and version of Fax module please.

Mikael,

Per your request. Again thank you.


REQUESTED ITEMS

FreePBX 2.8.1.4

'fax show version’
FAX For Asterisk Components:
Applications: 1.8.4.1
Spandsp FAX Driver: 20100830 183516
Digium FAX Driver: 1.8.4_1.3.0 (optimized for i686_32)

Asterisk 1.8.4.1

Upgrade FreePBX to 2.9, there were a lot of changes in both FreePBX and fax. You can use Version Upgrade module to upgrade.

Are there any extra precautions to take when upgrading to 2.9? Besides the basic backup? More so the system is really stable sans fax should I be worried about any instability when moving to 2.9?

2.9 update did a number on the dial plan. Faxes are now going through and arriving at the appropriate email(s). Thank you was out of town just had the time to take a look at this and went through the rounds.
Now that I updated system is extremely insecure. Passwords are all default. Locked it out for the moment. Need to spend some time closing it back up (passwords, etc.).
Any recommendations on using ATA to POTS lines with this utility?
Once again you have my thanks for your ongoing support.