Faxes sending twice

Interloper · July 29, 2020, 8:36am

Hi folks, long time lurker, first time poster.

I’ve been sending faxes with moderate success for a while and have hit upon a puzzling problem after changing VoIP providers. I’m using a web fax portal created by CSRDU (web page now non-existent). It generates a call file that is put in /var/spool/asterisk/outgoing to initiate the fax call. That call file remains in the spool until the call completes. The problem I’m experiencing is that asterisk is executing the call file again while the fax is in progress. I’d seen this happening before but it wasn’t a big deal because the line was busy. But since changing providers I’m discovering that two calls are now being allowed to go out simultaneously. And a lot of the businesses I fax seem to have capability for multiple incoming faxes on the same number. So end result is I keep spamming my recipients with two of the same fax. Is there something I can do in my dial plan to prevent more than one call at a time on that line? Or some way to stop asterisk executing the call file a second time?

jcolp · July 29, 2020, 11:20am

You’d need to provide the actual console output and contents of the call file. The behavior is that a call file won’t do another call at the same time, so it’s likely something else occurring as a result.

Interloper · July 30, 2020, 6:29am

Thanks. I’ll try to collate these next time I send a fax. Should I turn on any extra fax/sip debugging for the console output or just use what it shows when I use the -rvvv flags?

jcolp · July 30, 2020, 9:13am

SIP level isn’t really needed, as that is not what would be controlling multiple calls.

Interloper · August 7, 2020, 6:56am

Okay, I’ve finally managed to grab the console output and call file while sending a fax.
Call file:

Channel: SIP/fax_line/07YYYYYYYY
MaxRetries: 1
RetryTime: 60
WaitTime: 60
Archive: yes
Context: outboundfax
Extension: s
Priority: 1
Set: FAXFILE=/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif
Set: FAXHEADER=MY_BUSINESS_NAME
Set: TIMESTAMP=07/08/20 : 16:18:44
Set: DESTINATION=07YYYYYYYY
Set: LOCALID=07XXXXXXXX
Set: EMAIL=Dr SENDER NAME

And then we have the following console output:

Executing [s@outboundfax:1] Set("SIP/fax_line-000001aa", "FAXOPT(filename)=/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif") in new stack
[Aug  7 16:18:46] WARNING[18404][C-000000e8]: res_fax.c:4670 acf_faxopt_write: channel 'SIP/fax_line-000001aa' set FAXOPT(filename) to '/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif' is unhandled!
    -- Executing [s@outboundfax:2] Set("SIP/fax_line-000001aa", "CALLERID(num-pres)=allowed") in new stack
    -- Executing [s@outboundfax:3] Set("SIP/fax_line-000001aa", "FAXOPT(ecm)=yes") in new stack
    -- Executing [s@outboundfax:4] Set("SIP/fax_line-000001aa", "FAXOPT(headerinfo)=MY_BUSINESS_NAME") in new stack
    -- Executing [s@outboundfax:5] Set("SIP/fax_line-000001aa", "FAXOPT(localstationid)=07XXXXXXXX") in new stack
    -- Executing [s@outboundfax:6] Set("SIP/fax_line-000001aa", "FAXOPT(maxrate)=9600") in new stack
    -- Executing [s@outboundfax:7] Set("SIP/fax_line-000001aa", "FAXOPT(minrate)=2400") in new stack
    -- Executing [s@outboundfax:8] System("SIP/fax_line-000001aa", "/usr/local/bin/faxnotify ANSWERED "Dr SENDER NAME" "07YYYYYYYY" "07/08/20 : 16:18:44" "IN_PROGRESS" "NO_PAGES" "/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif"") in new stack
    -- Executing [s@outboundfax:9] SendFAX("SIP/fax_line-000001aa", "/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif,d") in new stack
    -- Channel 'SIP/fax_line-000001aa' sending FAX:
    --    /<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif
  == Using UDPTL CoS mark 5
[Aug  7 16:19:44] WARNING[18284]: pbx_spool.c:350 safe_append: Unable to set utime on /var/spool/asterisk/outgoing/24470531.call: Operation not permitted
    -- Attempting call on SIP/fax_line/07YYYYYYYY for s@outboundfax:1 (Retry 1)
  == Using SIP RTP CoS mark 5
    -- Called fax_line/07YYYYYYYY
    -- SIP/fax_line-000001ab answered
    -- Executing [s@outboundfax:1] Set("SIP/fax_line-000001ab", "FAXOPT(filename)=/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif") in new stack
[Aug  7 16:19:46] WARNING[18410][C-000000e9]: res_fax.c:4670 acf_faxopt_write: channel 'SIP/fax_line-000001ab' set FAXOPT(filename) to '/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif' is unhandled!
    -- Executing [s@outboundfax:2] Set("SIP/fax_line-000001ab", "CALLERID(num-pres)=allowed") in new stack
    -- Executing [s@outboundfax:3] Set("SIP/fax_line-000001ab", "FAXOPT(ecm)=yes") in new stack
    -- Executing [s@outboundfax:4] Set("SIP/fax_line-000001ab", "FAXOPT(headerinfo)=MY_BUSINESS_NAME") in new stack
    -- Executing [s@outboundfax:5] Set("SIP/fax_line-000001ab", "FAXOPT(localstationid)=07XXXXXXXX") in new stack
    -- Executing [s@outboundfax:6] Set("SIP/fax_line-000001ab", "FAXOPT(maxrate)=9600") in new stack
    -- Executing [s@outboundfax:7] Set("SIP/fax_line-000001ab", "FAXOPT(minrate)=2400") in new stack
    -- Executing [s@outboundfax:8] System("SIP/fax_line-000001ab", "/usr/local/bin/faxnotify ANSWERED "Dr SENDER NAME" "07YYYYYYYY" "07/08/20 : 16:18:44" "IN_PROGRESS" "NO_PAGES" "/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif"") in new stack
    -- Executing [s@outboundfax:9] SendFAX("SIP/fax_line-000001ab", "/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif,d") in new stack
    -- Channel 'SIP/fax_line-000001ab' sending FAX:
    --    /<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif
  == Using UDPTL CoS mark 5
   -- Auto fallthrough, channel 'SIP/fax_line-000001ab' status is 'UNKNOWN'
    -- Executing [h@outboundfax:1] NoOp("SIP/fax_line-000001ab", "FAXOPT(ecm) : yes") in new stack
    -- Executing [h@outboundfax:2] NoOp("SIP/fax_line-000001ab", "FaxStatus : FAILED") in new stack
    -- Executing [h@outboundfax:3] NoOp("SIP/fax_line-000001ab", "FaxStatusString : Received no response to DCS or TCF") in new stack
    -- Executing [h@outboundfax:4] NoOp("SIP/fax_line-000001ab", "FaxError : Received no response to DCS or TCF") in new stack
    -- Executing [h@outboundfax:5] NoOp("SIP/fax_line-000001ab", "RemoteStationID : ") in new stack
    -- Executing [h@outboundfax:6] NoOp("SIP/fax_line-000001ab", "FaxPages : 0") in new stack
    -- Executing [h@outboundfax:7] NoOp("SIP/fax_line-000001ab", "FaxBitRate : 14400") in new stack
    -- Executing [h@outboundfax:8] NoOp("SIP/fax_line-000001ab", "FaxResolution : 8031x7700") in new stack
    -- Executing [h@outboundfax:9] System("SIP/fax_line-000001ab", "/usr/local/bin/faxnotify ONHOOK "Dr SENDER NAME" "07YYYYYYYY" "07/08/20 : 16:18:44" "FAILED" "0" "/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif"") in new stack
[Aug  7 16:20:31] NOTICE[18410][C-000000e9]: pbx_spool.c:460 attempt_thread: Call completed to SIP/fax_line/07YYYYYYYY
  == Spawn extension (outboundfax, s, 9) exited non-zero on 'SIP/fax_line-000001aa'
    -- Executing [h@outboundfax:1] NoOp("SIP/fax_line-000001aa", "FAXOPT(ecm) : yes") in new stack
    -- Executing [h@outboundfax:2] NoOp("SIP/fax_line-000001aa", "FaxStatus : FAILED") in new stack
    -- Executing [h@outboundfax:3] NoOp("SIP/fax_line-000001aa", "FaxStatusString : The call dropped prematurely") in new stack
    -- Executing [h@outboundfax:4] NoOp("SIP/fax_line-000001aa", "FaxError : The call dropped prematurely") in new stack
    -- Executing [h@outboundfax:5] NoOp("SIP/fax_line-000001aa", "RemoteStationID : ") in new stack
    -- Executing [h@outboundfax:6] NoOp("SIP/fax_line-000001aa", "FaxPages : 0") in new stack
    -- Executing [h@outboundfax:7] NoOp("SIP/fax_line-000001aa", "FaxBitRate : 9600") in new stack
    -- Executing [h@outboundfax:8] NoOp("SIP/fax_line-000001aa", "FaxResolution : 8031x7700") in new stack
    -- Executing [h@outboundfax:9] System("SIP/fax_line-000001aa", "/usr/local/bin/faxnotify ONHOOK "Dr SENDER NAME" "07YYYYYYYY" "07/08/20 : 16:18:44" "FAILED" "0" "/<<DIRECTORY_XXXXX>>/Faxes/SentXXXX_XXXXXX_Xlg_20200807_review.tif"") in new stack
[Aug  7 16:20:45] NOTICE[18404][C-000000e8]: pbx_spool.c:460 attempt_thread: Call completed to SIP/fax_line/07YYYYYYYY

I’m wondering if the message about safe_append is a clue - is something touching the call file and causing asterisk to see it as a new file again? The PHP script I’m using creates the call file in /var/spool/asterisk/tmp before moving it to /var/spool/asterisk/outgoing.

jcolp · August 7, 2020, 9:07am

If I recall, the modified time is how pbx_spool knows whether it should try a call or not. If it can’t update it, then I think it would see it as needing to be called again. What filesystem is in use? Is there a permissions issue?

Interloper · August 8, 2020, 2:58am

core show version gives me:

Asterisk 13.18.3~dfsg-1ubuntu4 built by nobody @ buildd.debian.org on a unknown running Linux

I’m on Ubuntu Server 18.04 and installed Asterisk using the standard ubuntu packages. The file system is ext4. I’ve googled around for the “unable to set utime” error and it looks like maybe I need to fix up the ownership or permissions of the call file - I guess because it’s being created by apache it’s not allowing asterisk to alter it (edit: although asterisk can delete the file once it completes).

Interloper · August 8, 2020, 3:33am

So I updated my PHP script to change the file permissions. I still get the error about permissions updating utime, but the fax seems to be only attempting to send once now, so we’ll see how it goes. Thanks for the help.

david551 · August 8, 2020, 11:07am

Do you have SELinux enabled? SELinux is likely to treat anything obtained through a web browser as untrustworthy, so will give it security tags that may result in its being rejected.

Interloper · August 9, 2020, 1:53am

No, but ubuntu uses apparmor by default instead, which might well be the culprit.

system · September 8, 2020, 1:53am

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.

Topic		Replies	Views
Dial plan called twice Asterisk Support	3	1037	August 2, 2023
Call files making two calls Asterisk Support	3	286	December 30, 2005
Autodial out and deliver message Asterisk Support	4	675	August 20, 2009
[SENDFAX] The call dropped prematurely Asterisk Support	2	1549	November 7, 2010
Does this look like an extension is being called twice? Asterisk Support	7	686	December 2, 2012

Faxes sending twice

Related topics