search

gonicus / gofaxip

GOfax.IP - T.38 / Fax Over IP backend for HylaFAX using FreeSWITCH
GNU General Public License v2.0
123 stars 43 forks source link

Fax incorrectly reported as completed by hylafax #34

Closed alexcrow closed 6 years ago

alexcrow commented 6 years ago

Hi,

I've experienced some intermittent issues where we have had a fax fail with no pages sent, yet Hylfax has returned an email to the sender indicating the fax is complete (Subject: Notification of facsimile job Trade (6809) to 90035316130401: done) - here's the content of the email:

 ------- job status -------
  Destination: 90035316130401
        JobID: 6809
      GroupID: 6809
       Sender: jds
     Mailaddr: pooled@integrafin.co.uk
       CommID: 00009069
        Modem: any

Submitted From: 172.17.40.163 Page Width: 210 (mm) Page Length: 297 (mm) Resolution: 196 (lpi) Status: The HDLC carrier did not stop in a timely manner Dialogs: 1 Dials: 0 Calls: 1 Pages: 0 TotPages: 1 Attempts: 0 Dirnum:

Here's the relevant line in xferfaxlog: 09/11/17 14:41 SEND 00009069 freeswitch0 6809 Trade pooled@integrafin.co.uk "90035316130401" "+11 111 111111" 65576 0 00:00:40 00:00:40 The HDLC carrier did not stop in a timely manner jds ""

And the last part of the logs from freeswitch:

8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 T4-flagged expired in phase B_RX, state D_POST_TCF. An HDLC frame lasted too long. 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Status changing to The HDLC carrier did not stop in a timely manner 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:496 ============================================================================== 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:508 Fax processing not successful - result (5) The HDLC carrier did not stop in a timely manner. 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:513 Remote station id: +11 111 111111 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:514 Local station id: 020 7063 8601 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:515 Pages transferred: 0 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:517 Total fax pages: 1 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:518 Image resolution: 8040x7700 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:519 Transfer Rate: 14400 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:521 ECM status on 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:522 remote country: 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:523 remote vendor: 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:524 remote model: 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:526 ============================================================================== 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D_POST_TCF to CALL_FINISHED 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to CALL_FINISHED 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 9 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 9 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T FAX exchange complete 8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Call completed

I've not seen this on another fax server we use that uses T38Modem - however I much prefer gofax as it's an awful lot easier to build and maintain!

I've had a look at the go code and I've not been able to see where there might be an issue or quite where I would insert an extra check to make sure Hylafax definitively fails such a job.

Any ideas?

Best regards Alex

denzs commented 6 years ago

As gofaxip relies on the feedback from mod_spandsp i would expect spandsp to return the wrong code after sending the fax....

gofaxip is waiting for an event spandsp::txfaxresult on the event socket and parses the fax-success line.

The easiest way to verify this would be something like this: tcpdump -AA -i any port 8021 |grep -i fax-success

If it looks like this in your error case, you propably found a bug in freeswitch/mod_spandsp

root@fax-test:~# tcpdump -AA -i any port 8021 |grep -i fax-success
tcpdump: verbose output suppressed, use -v or -vv for full protocol decode
listening on any, link-type LINUX_SLL (Linux cooked), capture size 262144 bytes
fax-success: 1

If fax-success is anything else than 1 you found a bug in gofaxip which would need further investigation...

alexcrow commented 6 years ago

Hi Sebastian,

I have a recent one, and here's the spandsp debug from freeswitch.log:

root@fishtail:/var/log/freeswitch# grep 9819b2d0-68b5-4dba-b308-ffe041e94926 freeswitch.log.2018-01-24-14-25-29.1 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.870763 [NOTICE] switch_channel.c:1104 New Channel sofia/fax/90035224609500 [9819b2d0-68b5-4dba-b308-ffe041e94926] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.870763 [DEBUG] mod_sofia.c:4753 (sofia/fax/90035224609500) State Change CS_NEW -> CS_INIT 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.870763 [DEBUG] switch_core_session.c:613 sofia/fax/90035224609500 set UUID=9819b2d0-68b5-4dba-b308-ffe041e94926 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.870763 [DEBUG] switch_core_state_machine.c:584 (sofia/fax/90035224609500) Running State Change CS_INIT 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:627 (sofia/fax/90035224609500) State INIT 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] mod_sofia.c:90 sofia/fax/90035224609500 SOFIA INIT 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] sofia_glue.c:1253 sip:172.16.24.111 Setting proxy route to sofia/fax/90035224609500 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] sofia_glue.c:1282 sofia/fax/90035224609500 sending invite version: 1.6.12 -20-b91a0a6 64bit 9819b2d0-68b5-4dba-b308-ffe041e94926 Local SDP: 9819b2d0-68b5-4dba-b308-ffe041e94926 v=0 9819b2d0-68b5-4dba-b308-ffe041e94926 o=FreeSWITCH 1516613109 1516613110 IN IP4 172.17.10.170 9819b2d0-68b5-4dba-b308-ffe041e94926 s=FreeSWITCH 9819b2d0-68b5-4dba-b308-ffe041e94926 c=IN IP4 172.17.10.170 9819b2d0-68b5-4dba-b308-ffe041e94926 t=0 0 9819b2d0-68b5-4dba-b308-ffe041e94926 m=audio 19674 RTP/AVP 8 0 101 13 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:8 PCMA/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:0 PCMU/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:101 telephone-event/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=fmtp:101 0-16 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:13 CN/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=ptime:20 9819b2d0-68b5-4dba-b308-ffe041e94926 a=sendrecv 9819b2d0-68b5-4dba-b308-ffe041e94926 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:40 sofia/fax/90035224609500 Standard INIT 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:48 (sofia/fax/90035224609500) State Change CS_INIT -> CS_ROUTING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:627 (sofia/fax/90035224609500) State INIT going to sleep 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:584 (sofia/fax/90035224609500) Running State Change CS_ROUTING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:643 (sofia/fax/90035224609500) State ROUTING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] mod_sofia.c:143 sofia/fax/90035224609500 SOFIA ROUTING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_ivr_originate.c:67 (sofia/fax/90035224609500) State Change CS_ROUTING -> CS_CONSUME_MEDIA 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:643 (sofia/fax/90035224609500) State ROUTING going to sleep 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:584 (sofia/fax/90035224609500) Running State Change CS_CONSUME_MEDIA 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] sofia.c:6965 Channel sofia/fax/90035224609500 entering state [calling][0] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:662 (sofia/fax/90035224609500) State CONSUME_MEDIA 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:03.890771 [DEBUG] switch_core_state_machine.c:662 (sofia/fax/90035224609500) State CONSUME_MEDIA going to sleep 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] sofia.c:6965 Channel sofia/fax/90035224609500 entering state [proceeding][183] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] sofia.c:6975 Remote SDP: 9819b2d0-68b5-4dba-b308-ffe041e94926 v=0 9819b2d0-68b5-4dba-b308-ffe041e94926 o=FreeSWITCH 1516611214 1516611215 IN IP4 172.16.24.111 9819b2d0-68b5-4dba-b308-ffe041e94926 s=FreeSWITCH 9819b2d0-68b5-4dba-b308-ffe041e94926 c=IN IP4 172.16.24.111 9819b2d0-68b5-4dba-b308-ffe041e94926 t=0 0 9819b2d0-68b5-4dba-b308-ffe041e94926 m=audio 21570 RTP/AVP 8 101 13 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:8 PCMA/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:101 telephone-event/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=fmtp:101 0-16 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:13 CN/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=ptime:20 9819b2d0-68b5-4dba-b308-ffe041e94926 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:4366 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:4311 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:4227 Set telephone-event payload to 101@8000 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:3021 Set Codec sofia/fax/90035224609500 PCMA/8000 20 ms 160 samples 64000 bits 1 channels 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_codec.c:111 sofia/fax/90035224609500 Original read codec set to PCMA:8 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:4572 Set telephone-event payload to 101@8000 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:4631 sofia/fax/90035224609500 Set 2833 dtmf send payload to 101 recv payload to 101 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:6588 AUDIO RTP [sofia/fax/90035224609500] 172.17.10.170 port 19674 -> 172.16.24.111 port 21570 codec: 8 ms: 20 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_rtp.c:3875 Starting timer [soft] 160 bytes per 20ms 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:6887 sofia/fax/90035224609500 Set 2833 dtmf send payload to 101 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:6894 sofia/fax/90035224609500 Set 2833 dtmf receive payload to 101 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:6917 sofia/fax/90035224609500 Set rtp dtmf delay to 40 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_core_media.c:6923 Set comfort noise payload to 13 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [NOTICE] sofia_media.c:92 Pre-Answer sofia/fax/90035224609500! 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:04.931050 [DEBUG] switch_channel.c:3471 (sofia/fax/90035224609500) Callstate Change DOWN -> EARLY 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] sofia.c:6965 Channel sofia/fax/90035224609500 entering state [completing][200] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] sofia.c:6972 Duplicate SDP 9819b2d0-68b5-4dba-b308-ffe041e94926 v=0 9819b2d0-68b5-4dba-b308-ffe041e94926 o=FreeSWITCH 1516611214 1516611215 IN IP4 172.16.24.111 9819b2d0-68b5-4dba-b308-ffe041e94926 s=FreeSWITCH 9819b2d0-68b5-4dba-b308-ffe041e94926 c=IN IP4 172.16.24.111 9819b2d0-68b5-4dba-b308-ffe041e94926 t=0 0 9819b2d0-68b5-4dba-b308-ffe041e94926 m=audio 21570 RTP/AVP 8 101 13 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:8 PCMA/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:101 telephone-event/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=fmtp:101 0-16 9819b2d0-68b5-4dba-b308-ffe041e94926 a=rtpmap:13 CN/8000 9819b2d0-68b5-4dba-b308-ffe041e94926 a=ptime:20 9819b2d0-68b5-4dba-b308-ffe041e94926 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] sofia.c:6965 Channel sofia/fax/90035224609500 entering state [ready][200] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [NOTICE] sofia.c:7964 Channel [sofia/fax/90035224609500] has been answered 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] switch_channel.c:3770 (sofia/fax/90035224609500) Callstate Change EARLY -> ACTIVE 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [INFO] switch_channel.c:3127 sofia/fax/90035224609500 Flipping CID from "rgw"

<2076084900> to "Outbound Call" <0035224609500> 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] mod_commands.c:4788 (sofia/fax/90035224609500) State Change CS_CONSUME_MEDIA -> CS_EXECUTE 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] switch_core_state_machine.c:584 (sofia/fax/90035224609500) Running State Change CS_EXECUTE 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] switch_core_state_machine.c:650 (sofia/fax/90035224609500) State EXECUTE 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] mod_sofia.c:198 sofia/fax/90035224609500 SOFIA EXECUTE 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] switch_core_state_machine.c:328 sofia/fax/90035224609500 Standard EXECUTE 9819b2d0-68b5-4dba-b308-ffe041e94926 EXECUTE sofia/fax/90035224609500 txfax(/tmp/gofaxsend_9819b2d0-68b5-4dba-b308-ffe041e94926.tif) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] mod_spandsp_fax.c:1440 Raw read codec activation Success L16 20000 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] switch_core_codec.c:223 sofia/fax/90035224609500 Push codec L16:100 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.811052 [DEBUG] mod_spandsp_fax.c:1458 Raw write codec activation Success L16 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:06.850950 [DEBUG] switch_rtp.c:6963 Correct audio ip/port confirmed. 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:08.711052 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:08.891056 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:08.951087 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:11.971056 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:12.031055 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:12.271022 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:12.271022 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase A_CNG to B_RX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:12.271022 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set rx type 4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:12.271022 [DEBUG] mod_spandsp_fax.c:276 FLOW FAX Set tx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:12.271022 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:12.831051 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.070993 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.210972 [DEBUG] sofia.c:6965 Channel sofia/fax/90035224609500 entering state [received][100] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.210972 [DEBUG] sofia.c:6975 Remote SDP: 9819b2d0-68b5-4dba-b308-ffe041e94926 v=0 9819b2d0-68b5-4dba-b308-ffe041e94926 o=FreeSWITCH 1516611214 1516611216 IN IP4 172.16.24.111 9819b2d0-68b5-4dba-b308-ffe041e94926 s=FreeSWITCH 9819b2d0-68b5-4dba-b308-ffe041e94926 c=IN IP4 172.16.24.111 9819b2d0-68b5-4dba-b308-ffe041e94926 t=0 0 9819b2d0-68b5-4dba-b308-ffe041e94926 m=image 21570 udptl t38 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxVersion:0 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38MaxBitRate:14400 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxRateManagement:transferredTCF 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxMaxBuffer:300 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxMaxDatagram:176 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxUdpEC:t38UDPRedundancy 9819b2d0-68b5-4dba-b308-ffe041e94926 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1037 T38 SDP Origin = FreeSWITCH 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1038 T38FaxVersion = 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1039 T38MaxBitRate = 14400 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1040 T38FaxFillBitRemoval = 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1041 T38FaxTranscodingMMR = 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1042 T38FaxTranscodingJBIG = 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1043 T38FaxRateManagement = transferredTCF 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1044 T38FaxMaxBuffer = 300 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1045 T38FaxMaxDatagram = 176 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1046 T38FaxUdpEC = t38UDPRedundancy 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1047 T38VendorInfo = 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1048 ip = 172.16.24.111 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] mod_spandsp_fax.c:1050 port = 21570 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] switch_core_media.c:9435 Remote address:port [172.16.24.111:21570] has not changed. 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] switch_core_media.c:9074 sofia/fax/90035224609500 image media sdp: 9819b2d0-68b5-4dba-b308-ffe041e94926 v=0 9819b2d0-68b5-4dba-b308-ffe041e94926 o=FreeSWITCH 1516613109 1516613111 IN IP4 172.17.10.170 9819b2d0-68b5-4dba-b308-ffe041e94926 s=FreeSWITCH 9819b2d0-68b5-4dba-b308-ffe041e94926 c=IN IP4 172.17.10.170 9819b2d0-68b5-4dba-b308-ffe041e94926 t=0 0 9819b2d0-68b5-4dba-b308-ffe041e94926 m=image 19674 udptl t38 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxVersion:0 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38MaxBitRate:14400 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxRateManagement:transferredTCF 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxMaxBuffer:300 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxMaxDatagram:400 9819b2d0-68b5-4dba-b308-ffe041e94926 a=T38FaxUdpEC:t38UDPRedundancy 9819b2d0-68b5-4dba-b308-ffe041e94926 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] switch_core_media.c:9435 Remote address:port [172.16.24.111:21570] has not changed. 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.230985 [DEBUG] sofia.c:6965 Channel sofia/fax/90035224609500 entering state [completed][200] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.250992 [DEBUG] sofia.c:6965 Channel sofia/fax/90035224609500 entering state [ready][200] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.850998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 A signal is present 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.850998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.850998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.850998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase A_CNG to B_RX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.850998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:13.850998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.711052 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type CSI - CRC OK (clean) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.711052 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.711052 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  CSI without final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.711052 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 03 40 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 20 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.711052 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Remote gave CSI as: "" 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type DIS - CRC OK (clean) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop none (0 remaining) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  DIS with final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 13 80 00 6e b8 00 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state T 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase B_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DIS: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= 3G mobile network: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..0. ....= V.8 capabilities: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= Preferred octets: 256 octets 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Ready to transmit a fax document (polling): Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..1.= Can receive fax: Set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= 2-D coding: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..00= Recording width: 215mm +- 1% 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 10..= Recording length: Unlimited 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .011 ....= Receiver's minimum scan line time: 20ms at 3.85 l/mm; T7.7 = 1/2 T3.85 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   1... ....= Extension indicator: Set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..0.= Compressed/uncompressed mode: Compressed 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Error correction mode (ECM): Non-ECM 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .0.. ....= T.6 coding: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= Extension indicator: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:317 === Negotiation Result ======================================================= 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:318 Remote station id: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:319 Local station id: 020 7063 8601 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:320 Transfer Rate: 14400 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:322 ECM status off 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:323 remote country: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:324 remote vendor: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:325 remote model: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:327 ============================================================================== 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Trying to send file /tmp/gofaxsend_9819b2d0-68b5-4dba-b308-ffe041e94926.tif 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start sending document 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Choose image type bi-level (0), compression T.4 1-D (2) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Minimum bits per row will be 144 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting page 1 of transfer 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Image width is A4 at 8040dpm x 7700dpm 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Put document with modem (7) V.17 at 14400bps 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state T to D 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Sending ident 020 7063 8601 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  TSI without final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:14.990992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 03 43 31 30 36 38 20 33 36 30 37 20 30 32 30 20 20 20 20 20 20 20 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:15.030972 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Receive complete in phase B_RX, state D 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:15.030972 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state D 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:15.030972 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to B_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:15.030972 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:15.030972 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:15.030972 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state D 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 DCS: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ...0= Store and forward Internet fax (T.37): Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... .0..= Real-time Internet fax (T.38): Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 0...= 3G mobile network: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..1.= Receive fax: Set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   ..10 00..= Selected data signalling rate: V.17 14400bps 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= 2-D coding: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... ..00= Recording width: 215mm +- 1% 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .... 10..= Recording length: Unlimited 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   .010 ....= Minimum scan line time: 10ms 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30   0... ....= Extension indicator: Not set 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  DCS with final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:16.730996 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 83 00 62 28 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:17.010998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state D 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:17.010998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase B_TX, state D 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:17.010998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D to D_TCF 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:17.010998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_TX to C_NON_ECM_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:17.010998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:17.010998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:17.010998 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 7 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:20.370987 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase C_NON_ECM_TX, state D_TCF 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:20.370987 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_TX to B_RX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:20.370987 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:20.370987 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:20.370987 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:20.370987 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D_TCF to D_POST_TCF 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:22.591045 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 A signal is present 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:22.591045 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state D_POST_TCF 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:22.591045 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state D_POST_TCF 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:22.591045 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4-flagged 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type CFR - CRC OK (clean) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T4-flagged (12000 remaining) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  CFR with final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 13 84 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state D_POST_TCF 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Trainability test succeeded 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state D_POST_TCF to I 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.090949 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase C_NON_ECM_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.150994 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Receive complete in phase B_RX, state I 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.150994 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state I 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.150994 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase B_RX to C_NON_ECM_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.150994 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.150994 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.150994 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 7 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:53:24.150994 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase C_NON_ECM_TX, state I 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase C_NON_ECM_TX to D_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state I to II_Q 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No more pages to send 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  EOP with final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:03.531007 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 2f 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:04.870992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state II_Q 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:04.870992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state II_Q 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:04.870992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to D_RX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:04.870992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:04.870992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:04.870992 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:07.451011 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 A signal is present 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:07.451011 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier up (-2) in state II_Q 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:07.451011 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Framing OK (-6) in state II_Q 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:07.451011 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Start T4-flagged 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Type RTN - CRC OK (clean) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Stop T4-flagged (12000 remaining) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  RTN with final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx:  ff 13 4c 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Rx final frame in state II_Q 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:428 ==== Page Sent =============================================================== 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:429 Page no = 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:430 Image type = bi-level (bi-level in the file) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:431 Image size = 1728 x 2292 pixels (1728 x 2292 pixels in the file) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:432 Image resolution = 8040/m x 7700/m (8228/m x 7716/m in the file) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:433 Compression = T.4 1-D (2) 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:434 Compressed image size = 70306 bytes 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:435 Bad rows = 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:436 Longest bad row run = 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:437 ============================================================================== 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Queuing phase D_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state II_Q to C 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  DCN with final frame tag 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:08.951009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Tx:  ff 13 fb 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:09.010974 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Receive complete in phase D_RX, state C 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:09.010974 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 HDLC signal status is Carrier down (-1) in state C 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:09.010974 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_RX to D_TX 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:09.010974 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:09.010974 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 4 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:09.010974 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 No signal is present 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:10.171009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:10.171009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase D_TX, state C 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:10.171009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Starting final pause before disconnecting 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:10.171009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase D_TX to E 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:10.171009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:10.171009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 1 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:10.171009 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state C to B 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Send complete in phase E, state B 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:496 ============================================================================== 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:500 Fax successfully sent. 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:513 Remote station id: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:514 Local station id: 020 7063 8601 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:515 Pages transferred: 0 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:517 Total fax pages: 1 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:518 Image resolution: 8040x7700 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:519 Transfer Rate: 14400 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:521 ECM status off 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:522 remote country: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:523 remote vendor: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:524 remote model: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:526 ============================================================================== 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from state B to CALL_FINISHED 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Changing from phase E to CALL_FINISHED 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set rx type 9 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T Set tx type 9 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:276 FLOW T.38T FAX exchange complete 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:276 FLOW T.30 Call completed 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_codec.c:248 sofia/fax/90035224609500 Restore previous codec PCMA:8. 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [NOTICE] sofia.c:1011 Hangup sofia/fax/90035224609500 [CS_EXECUTE] [NORMAL_CLEARING] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:650 (sofia/fax/90035224609500) State EXECUTE going to sleep 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:584 (sofia/fax/90035224609500) Running State Change CS_HANGUP 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:850 (sofia/fax/90035224609500) Callstate Change ACTIVE -> HANGUP 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:852 (sofia/fax/90035224609500) State HANGUP 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] mod_sofia.c:438 Channel sofia/fax/90035224609500 hanging up, cause: NORMAL_CLEARING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:60 sofia/fax/90035224609500 Standard HANGUP, cause: NORMAL_CLEARING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:852 (sofia/fax/90035224609500) State HANGUP going to sleep 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:619 (sofia/fax/90035224609500) State Change CS_HANGUP -> CS_REPORTING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:584 (sofia/fax/90035224609500) Running State Change CS_REPORTING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:938 (sofia/fax/90035224609500) State REPORTING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:174 sofia/fax/90035224609500 Standard REPORTING, cause: NORMAL_CLEARING 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:938 (sofia/fax/90035224609500) State REPORTING going to sleep 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:610 (sofia/fax/90035224609500) State Change CS_REPORTING -> CS_DESTROY 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_session.c:1647 Session 10627 (sofia/fax/90035224609500) Locked, Waiting on external entities 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [NOTICE] switch_core_session.c:1665 Session 10627 (sofia/fax/90035224609500) Ended 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [NOTICE] switch_core_session.c:1669 Close Channel sofia/fax/90035224609500 [CS_DESTROY] 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:741 (sofia/fax/90035224609500) Running State Change CS_DESTROY 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:751 (sofia/fax/90035224609500) State DESTROY 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] mod_sofia.c:343 sofia/fax/90035224609500 SOFIA DESTROY 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:181 sofia/fax/90035224609500 Standard DESTROY 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:12.330802 [DEBUG] switch_core_state_machine.c:751 (sofia/fax/90035224609500) State DESTROY going to sleep This does seem to suggest that spandsp is reporting success in the case of 0 pages being sent, which seems counter-intuitive, espcially as it reports that image data was sent. The recipient says they didn't receive anything at all. This happens so rarely that I'd have to run the trace continuously for a few months to catch one! I hope this is of some help to you. Best regards Alex On 04/12/17 16:06, Sebastian Denz wrote: > > As gofaxip relies on the feedback from mod_spandsp i would expect > spandsp to return the wrong code after sending the fax.... > > gofaxip is waiting for an event |spandsp::txfaxresult| on the event > socket and parses the fax-success line. > > The easiest way to verify this would be something like this: > |tcpdump -AA -i any port 8021 |grep -i fax-success| > > If it looks like this in your error case, you propably found a bug in > freeswitch/mod_spandsp > > |root@fax-test:~# tcpdump -AA -i any port 8021 |grep -i fax-success > tcpdump: verbose output suppressed, use -v or -vv for full protocol > decode listening on any, link-type LINUX_SLL (Linux cooked), capture > size 262144 bytes fax-success: 1 | > > If fax-success is anything else than 1 you found a bug in gofaxip > which would need further investigation... > > — > You are receiving this because you authored the thread. > Reply to this email directly, view it on GitHub > , > or mute the thread > . > -- This message is intended only for the addressee and may contain confidential information. Unless you are that person, you may not disclose its contents or use it in any way and are requested to delete the message along with any attachments and notify us immediately. This email is not intended to, nor should it be taken to, constitute advice. The information provided is correct to our knowledge & belief and must not be used as a substitute for obtaining tax, regulatory, investment, legal or any other appropriate advice. "Transact" is operated by Integrated Financial Arrangements Ltd. 29 Clement's Lane, London EC4N 7AE. Tel: (020) 7608 4900 Fax: (020) 7608 5300. (Registered office: as above; Registered in England and Wales under number: 3727592). Authorised and regulated by the Financial Conduct Authority (entered on the Financial Services Register; no. 190856).
denzs commented 6 years ago

As you already mentioned, FreeSwitch seems to report success: 9819b2d0-68b5-4dba-b308-ffe041e94926 2018-01-22 14:54:11.490783 [DEBUG] mod_spandsp_fax.c:500 Fax successfully sent.

So please open an issue in the FreeSwitch bugtracker, as this should be fixed in mod_spandsp itself. Your trace should be very helpful to locate the reason :)

alexcrow commented 6 years ago

Yes, I think the second report is a spandsp bug, I didn't notice the difference from the other case. The first one, however, has:

8753919e-9db6-4cac-b133-9e2108c201c4 2017-09-11 14:42:05.290999 [DEBUG] mod_spandsp_fax.c:508 Fax processing not successful - result (5) The HDLC carrier did not stop in a timely manner.

But yet Hylafax sends a "done" message to the client. As I understand it gofaxip writes the xferfaxlog, which shows a "0" in the "Success" field.