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

sandovalg · August 5, 2011, 12:58am

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 [[email protected]:1] Set("SIP/SOME-TRNK-0000075a", "__FROM_DID=5552221313") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]:1] GotoIf("SIP/SOME-TRNK-0000075a", "0?blacklisted") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [[email protected]:2] Set("SIP/SOME-TRNK-0000075a", "CALLED_BLACKLIST=1") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [[email protected]:3] Return("SIP/SOME-TRNK-0000075a", "") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]:5] Set("SIP/SOME-TRNK-0000075a", "CALLERPRES()=allowed_not_screened") in new stack
[2011-08-04 15:38:42] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]:7] Answer("SIP/SOME-TRNK-0000075a", "") in new stack
[2011-08-04 15:38:43] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:2] Set("SIP/SOME-TRNK-0000075a", "[email protected]") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]:3] StopPlayTones("SIP/SOME-TRNK-0000075a", "") in new stack
[2011-08-04 15:38:44] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]:1] GotoIf("SIP/SOME-TRNK-0000075a", "0?failed") in new stack
[2011-08-04 15:39:19] VERBOSE[19180] pbx.c: -- Executing [[email protected]:2] GotoIf("SIP/SOME-TRNK-0000075a", "0?end") in new stack
[2011-08-04 15:39:19] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]:4] Macro("SIP/SOME-TRNK-0000075a", "hangupcall,") in new stack
[2011-08-04 15:39:20] VERBOSE[19180] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:1] Set("SIP/SOME-TRNK-00000760", "__FROM_DID=5552221313") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]:1] GotoIf("SIP/SOME-TRNK-00000760", "0?blacklisted") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [[email protected]:2] Set("SIP/SOME-TRNK-00000760", "CALLED_BLACKLIST=1") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [[email protected]:3] Return("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]:5] Set("SIP/SOME-TRNK-00000760", "CALLERPRES()=allowed_not_screened") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]:7] Answer("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:11] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:2] Set("SIP/SOME-TRNK-00000760", "[email protected]") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]:3] StopPlayTones("SIP/SOME-TRNK-00000760", "") in new stack
[2011-08-04 15:47:16] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]:104] Macro("SIP/SOME-TRNK-00000760", "hangupcall,") in new stack
[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]: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 [[email protected]: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.

mickecarlsson · August 5, 2011, 4:58am

Have you noted this:

[2011-08-04 15:47:42] VERBOSE[19251] pbx.c: -- Executing [[email protected]: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 [[email protected]: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 [[email protected]:104] Macro("SIP/SOME-TRNK-00000760", "hangupcall,") in new stack

sandovalg · August 5, 2011, 5:42am

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?

mickecarlsson · August 5, 2011, 6:48am

FAX FAILED LICENSE EXCEEDED

Asterisk FFA is reporting that you have exceeded the license.

sandovalg · August 5, 2011, 7:24pm

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?

mickecarlsson · August 5, 2011, 8:21pm

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.

sandovalg · August 5, 2011, 8:30pm

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 [[email protected]: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 [[email protected]: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 [[email protected]:7] Hangup("SIP/SOME-TRNK-00000760", "") in new stack

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

mickecarlsson · August 5, 2011, 9:05pm

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.

sandovalg · August 5, 2011, 9:26pm

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]

mickecarlsson · August 5, 2011, 9:59pm

FreePBX version and version of Fax module please.

sandovalg · August 5, 2011, 10:16pm

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

mickecarlsson · August 6, 2011, 7:24am

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

sandovalg · August 6, 2011, 4:46pm

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?

sandovalg · August 19, 2011, 10:42pm

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.

system · June 4, 2014, 7:19pm