Receive Fax but not sending mail

Hi,
I have been having an ongoing problem with the Faxing module on FreePBX. I am running the FreePBX 2.11.0, Asterisk 11.7.0 on a VM Server originally installed from a Distro.
I have configured faxes using Incoming routes, detecting faxes on SIP and setting a destination of a Fax recipient. The fax call is coming in via SIP from a Cisco CUBE over G711. All faxes are working fine except for a handful of faxes that come in for our German colleagues. Looking at the logs we receive the fax as a TIF file, but at the point where Asterisk should be running the PHP script to create the email it fails with FAX FAILED. No reason why.
Are there any other logs I can look at to see why these faxes are failing? Other forum discussions appear to give a reason but mine just says failed. On a couple of occasions I have managed to get the TIF file off the box and send the mail manually but I can’t do this for every failed fax.

Below is the required log entries showing a failed fax.

[2017-01-24 15:51:42] VERBOSE[1311][C-00000365] pbx.c: – Goto (ext-fax,s,3)
[2017-01-24 15:51:42] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:3] StopPlayTones(“SIP/10.0.5.3-00000369”, “”) in new stack
[2017-01-24 15:51:42] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:4] ReceiveFAX(“SIP/10.0.5.3-00000369”, “/var/spool/asterisk/fax/1485273102.937.tif,f”) in new stack
[2017-01-24 15:51:42] VERBOSE[1311][C-00000365] res_fax.c: – Channel ‘SIP/10.0.5.3-00000369’ receiving FAX ‘/var/spool/asterisk/fax/1485273102.937.tif’
[2017-01-24 15:51:45] VERBOSE[1311][C-00000365] netsock2.c: == Using UDPTL TOS bits 184
[2017-01-24 15:51:45] VERBOSE[1311][C-00000365] netsock2.c: == Using UDPTL CoS mark 5
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: == Spawn extension (ext-fax, s, 4) exited non-zero on ‘SIP/10.0.5.3-00000369’
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/10.0.5.3-00000369”, “1?failed”) in new stack
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Goto (ext-fax,h,103)
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:103] NoOp(“SIP/10.0.5.3-00000369”, “FAX FAILED for: [email protected] , From: “062018750813” <062018750813>”) in new stack
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:104] Macro(“SIP/10.0.5.3-00000369”, “hangupcall,”) in new stack
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/10.0.5.3-00000369”, “1?theend”) in new stack
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Goto (macro-hangupcall,s,3)
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:3] ExecIf(“SIP/10.0.5.3-00000369”, “0?Set(CDR(recordingfile)=)”) in new stack
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:4] Hangup(“SIP/10.0.5.3-00000369”, “”) in new stack
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/10.0.5.3-00000369’ in macro ‘hangupcall’
[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: == Spawn extension (ext-fax, h, 104) exited non-zero on ‘SIP/10.0.5.3-00000369’

This is an example of a working fax.

[2017-01-24 18:26:18] VERBOSE[1538][C-00000368] pbx.c: – Goto (ext-fax,s,3)
[2017-01-24 18:26:18] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:3] StopPlayTones(“SIP/10.0.5.3-0000036c”, “”) in new stack
[2017-01-24 18:26:18] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:4] ReceiveFAX(“SIP/10.0.5.3-0000036c”, “/var/spool/asterisk/fax/1485282374.940.tif,f”) in new stack
[2017-01-24 18:26:18] VERBOSE[1538][C-00000368] res_fax.c: – Channel ‘SIP/10.0.5.3-0000036c’ receiving FAX ‘/var/spool/asterisk/fax/1485282374.940.tif’
[2017-01-24 18:26:21] VERBOSE[1538][C-00000368] netsock2.c: == Using UDPTL TOS bits 184
[2017-01-24 18:26:21] VERBOSE[1538][C-00000368] netsock2.c: == Using UDPTL CoS mark 5
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: == Spawn extension (ext-fax, s, 4) exited non-zero on ‘SIP/10.0.5.3-0000036c’
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/10.0.5.3-0000036c”, “0?failed”) in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:2] GotoIf(“SIP/10.0.5.3-0000036c”, “0?noemail”) in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:3] Set(“SIP/10.0.5.3-0000036c”, “DELETE_AFTER_SEND=true”) in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:4] System(“SIP/10.0.5.3-0000036c”, “/var/lib/asterisk/bin/fax2mail.php --to "[email protected]” --dest “442828871516” --callerid '“anonymous” ’ --file /var/spool/asterisk/fax/1485282374.940.tif --exten “Larne Main Fax (14)” --delete “true” --attachformat “pdf”") in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:5] Macro(“SIP/10.0.5.3-0000036c”, “hangupcall,”) in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:1] GotoIf(“SIP/10.0.5.3-0000036c”, “1?theend”) in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Goto (macro-hangupcall,s,3)
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:3] ExecIf(“SIP/10.0.5.3-0000036c”, “0?Set(CDR(recordingfile)=)”) in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: – Executing [[email protected]:4] Hangup(“SIP/10.0.5.3-0000036c”, “”) in new stack
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] app_macro.c: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘SIP/10.0.5.3-0000036c’ in macro ‘hangupcall’
[2017-01-24 18:27:11] VERBOSE[1538][C-00000368] pbx.c: == Spawn extension (ext-fax, h, 5) exited non-zero on ‘SIP/10.0.5.3-0000036c’

I can see in the failed fax the line,

GotoIf(“SIP/10.0.5.3-00000369”, “1?failed”) in new stack

compared to the working fax the 1 becomes a 0,

GotoIf(“SIP/10.0.5.3-0000036c”, “0?failed”) in new stack

The 1 presumably meaning that the fax failed. This is quickly followed by the line,

[2017-01-24 15:51:50] VERBOSE[1311][C-00000365] pbx.c: – Executing [[email protected]:103] NoOp(“SIP/10.0.5.3-00000369”, “FAX FAILED for: [email protected] , From: “062018750813” <062018750813>”) in new stack

I would point out that this is not the case for all faxes to this number. However a lot of faxes do fail with these same sets of errors.

One other thing I have noticed is that in the CDR Records a failed fax shows this,

ReceiveFAX 496218044333 ANSWERED 00:14

Whereas a successful fax shows this,

ReceiveFAX s [ext-fax] ANSWERED 00:57

I’m not sure why the Destination changes to “s [ext-fax]” on a working fax when it shows the destination DID on a failed fax. May be completely unrelated, but just thought it was worth a mention.

I have tried deleting and recreating the Extension and Incoming Route. I have tried detecting faxes, not detecting faxes and have the route send to a Fax Recipient.

The dial-peer on the CUBE is exactly the same as all of the other fax numbers which work fine. I presume this isn’t the issue though as the fax itself is received.

I have upgraded all of the modules to the latest available version.

Has anyone come across this before? Any help is greatly appreciated.

bump!