Client shows wrong state during fax transmission about gofaxip HOT 6 CLOSED

I am aware of at least one user who is using yahfc in combination with GOfax.IP and standard hylafax (not hylafax+) and he did not complain about this behaviour...

So please provide some more information like

• output of 'faxstat -s' during sending and
• corresponding gofaxip and hylafax logs

Then we'll see what we can do...

from gofaxip.

faxstat -s (during transmission)

HylaFAX scheduler on efax.<mydomain.com>.novalocal: Running
Modem freeswitch2 (): Running and idle
Modem freeswitch0 (): Running and idle
Modem freeswitch4 (): Sending facsimile
Modem freeswitch3 (): Running and idle
Modem freeswitch1 (): Running and idle

JID Pri S Owner Number Pages Dials TTS Status
39 127 R hge-ri 030123456 0:1 1:12 Sending 14400/ECM

syslog

Dec 18 16:33:42 efax2 HylaFAX[1424]: -> Got a: 127.0.0.1[13] Dec 18 16:33:42 efax2 HylaFAX[1424]: -> Got a: 59512[19]
Dec 18 16:33:42 efax2 HylaFAX[1424]: -> Got a: 127.0.0.1[13] Dec 18 16:33:42 efax2 HylaFAX[1424]: -> Got a: 53980[19]
Dec 18 16:33:48 efax2 FaxQueuer[1210]: SUBMIT JOB 39
Dec 18 16:33:49 efax2 /usr/bin/gofaxd[1139]: device.go:101: /var/spool/hylafax/FIFO.freeswitch4 received message: L
Dec 18 16:33:49 efax2 /usr/bin/gofaxd[1139]: device.go:208: Changing state of modem freeswitch4 to LOCKED
Dec 18 16:33:49 efax2 FaxQueuer[1425]: req.items[1].item = "docq/doc33.ps;c1" ()
Dec 18 16:33:49 efax2 /usr/bin/gofaxd[1139]: device.go:101: /var/spool/hylafax/FIFO.freeswitch4 received message: SB
Dec 18 16:33:49 efax2 /usr/bin/gofaxd[1139]: device.go:183: Changing state of modem freeswitch4 to BUSY
Dec 18 16:33:49 efax2 /usr/bin/gofaxd[1139]: faxq.go:73: Sending message to /var/spool/hylafax/FIFO: +freeswitch4:U
Dec 18 16:33:49 efax2 gofaxsend[1432]: sendqfile.go:140: Logging events for commid 00000062 to log/c00000062
Dec 18 16:33:49 efax2 gofaxsend[1432]: sessionlog.go:70: Processing HylaFAX Job 39 as 16c087dd-302b-4bbf-ac7a-7cb2e3ad0d09
Dec 18 16:33:49 efax2 gofaxsend[1432]: sessionlog.go:70: Originating channel to 030123456 using gateway default
Dec 18 16:33:51 efax2 gofaxsend[1432]: sessionlog.go:70: Originate successful
Dec 18 16:33:51 efax2 gofaxsend[1432]: sessionlog.go:70: Call state change: ACTIVE
Dec 18 16:33:57 efax2 HylaFAX[1442]: -> Got a: 127.0.0.1[13] Dec 18 16:33:57 efax2 HylaFAX[1442]: -> Got a: 60930[19]
Dec 18 16:33:57 efax2 HylaFAX[1442]: -> Got a: 127.0.0.1[13] Dec 18 16:33:57 efax2 HylaFAX[1442]: -> Got a: 37569[19]
Dec 18 16:34:03 efax2 gofaxsend[1432]: sessionlog.go:70: Remote ID: "Company Inc", Transfer Rate: 14400, ECM=true
Dec 18 16:34:10 efax2 HylaFAX[1444]: -> Got a: 127.0.0.1[13] Dec 18 16:34:10 efax2 HylaFAX[1444]: -> Got a: 48078[19]
Dec 18 16:34:10 efax2 HylaFAX[1444]: -> Got a: 127.0.0.1[13] Dec 18 16:34:10 efax2 HylaFAX[1444]: -> Got a: 36294[19]
Dec 18 16:34:13 efax2 gofaxsend[1432]: sessionlog.go:70: Page 1 sent: Image Size: 1728x2324, Compression: T.6, Comp Size: 1080 bytes, Bad Rows: 0
Dec 18 16:34:16 efax2 gofaxsend[1432]: sessionlog.go:70: Call state change: HANGUP
Dec 18 16:34:16 efax2 gofaxsend[1432]: sessionlog.go:70: Success: true, Hangup Cause: NORMAL_CLEARING, Result: OK
Dec 18 16:34:16 efax2 gofaxsend[1432]: main.go:93: Exiting with status 2
Dec 18 16:34:16 efax2 FaxQueuer[1210]: NOTIFY: bin/notify "doneq/q39" "done" "0:00:27"
Dec 18 16:34:16 efax2 /usr/bin/gofaxd[1139]: device.go:101: /var/spool/hylafax/FIFO.freeswitch4 received message: SR
Dec 18 16:34:16 efax2 /usr/bin/gofaxd[1139]: device.go:174: Changing state of modem freeswitch4 to READY
Dec 18 16:34:16 efax2 /usr/bin/gofaxd[1139]: faxq.go:73: Sending message to /var/spool/hylafax/FIFO: +freeswitch4:N
Dec 18 16:34:16 efax2 /usr/bin/gofaxd[1139]: faxq.go:73: Sending message to /var/spool/hylafax/FIFO: +freeswitch4:Rpcbffff01
Dec 18 16:34:16 efax2 FaxQueuer[1210]: NOTIFY exit status: 0 (1445)

Hylafax log for that job

2017/12/18 16:33:49.424322 Processing HylaFAX Job 39 as 16c087dd-302b-4bbf-ac7a-7cb2e3ad0d09
2017/12/18 16:33:49.433040 Originating channel to 030123456 using gateway default
2017/12/18 16:33:51.490771 Originate successful
2017/12/18 16:33:51.492364 Call state change: ACTIVE
2017/12/18 16:34:03.246537 Remote ID: "Company Inc", Transfer Rate: 14400, ECM=true
2017/12/18 16:34:13.825719 Page 1 sent: Image Size: 1728x2324, Compression: T.6, Comp Size: 1080 bytes, Bad Rows: 0
2017/12/18 16:34:16.079831 Call state change: HANGUP
2017/12/18 16:34:16.080017 Success: true, Hangup Cause: NORMAL_CLEARING, Result: OK

I removed some personal data like phone number and company name. If you need more/other information, please let me know

from gofaxip.

If i understand the yahfc sources correctly, the qfile is parsed and the value of the state attribute is what you see in the GUI...

Regarding to a quick n dirty test i did, the behaviour of GOfax.IP seems correct to me?!

root@fax-test:/var/spool/hylafax# while true ; do grep state sendq/q116 ; sleep 1 ; done
grep: sendq/q116: No such file or directory
grep: sendq/q116: No such file or directory
grep: sendq/q116: No such file or directory
grep: sendq/q116: No such file or directory
state:5
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
state:6
grep: sendq/q116: No such file or directory
grep: sendq/q116: No such file or directory

from man doneq:

5 (ready, ready to be processed except for available resources),
6 (active, actively being  processed  by HylaFAX),

Please try to start yahfc with -d to see if we can get some more information from yahfc.

from gofaxip.

I wasn't able to see something interesting when starting yahfc with -d. But I observed something else:

I used your command

while true ; do grep state sendq/q116 ; sleep 1 ; done

but with sleep 0.1 instead of sleep 1 to get more output. I see that a fax transmission on my GOfax.IP installation always starts with output like

state:1
state:1
state:5
state:5
state:5
state:5
state:5
state:5
state:5
state:5
state:5
state:5
state:6
state:6
state:6

There is state 1 in the beginning, than it is switching to state 5 and than state 6.

I did the same on my Hylafax+ installation and most of the time I see output like this:

state:1
state:1
state:1
state:1
state:6
state:6
state:6

State switches from 1 to 6. There is no state 5. I sent about 20 faxes. One one transmission I saw state 5 between 1 and 6 and this time yahfc showed "Suspended" during the transmission.

At this point I really believe there is a bug in yahfc. I will try to contact the creator of yahfc and point him to this discussion.

I close the issue now and might reopen if necessary. Thanks for your help so far!

from gofaxip.

I created an issue on the repo of YajHFC:

https://bitbucket.org/jonaswolz/yajhfc/issues/57/yajhfc-shows-suspended-during-fax

from gofaxip.

Using Server ServerTracing: 2048 in /etc/hylafax/config, it seems hylafax is actually considering the state suspended for the job:

Dez 18 20:56:38 jessie2 FaxQueuer[26632]: JOB 767 (suspended dest  pri 127 tts 0:00:00 killtime 3:00:00): CREATE
Dez 18 20:56:38 jessie2 FaxQueuer[26632]: JOB 767 (ready dest 100 pri 127 tts 0:00:00 killtime 3:00:00): READY
Dez 18 20:56:39 jessie2 FaxQueuer[26632]: JOB 767 (ready dest 100 pri 127 tts 0:00:00 killtime 2:59:59): PROCESS
Dez 18 20:56:39 jessie2 FaxQueuer[26632]: JOB 767 (ready dest 100 pri 127 tts 0:00:00 killtime 2:59:59): BATCH
Dez 18 20:56:39 jessie2 FaxQueuer[26632]: JOB 767 (active dest 100 pri 127 tts 0:00:00 killtime 2:59:59): ACTIVE
Dez 18 20:56:39 jessie2 FaxQueuer[26632]: JOB 767 (active dest 100 pri 127 tts 0:00:00 killtime 2:59:59): SEND IN BATCH to 100

#
# gofaxsend output
#

Dez 18 20:59:12 jessie2 FaxQueuer[26632]: JOB 768 (done dest 100 pri 127 tts 0:00:00 killtime 2:59:32): DEAD
Dez 18 20:59:12 jessie2 FaxQueuer[26632]: JOB 768 (done dest 100 pri 127 tts 0:00:00 killtime 2:59:32): DELETE

yahfc:

$ java -jar yajhfc-0_6_1.jar -d|grep -B 1 'Raw data is'

--
Dec 18, 2017 8:58:46 PM yajhfc.model.servconn.defimpl.AbstractFaxJob reloadData
FINEST: Raw data is: [testuser, 100, , 0, 768, W, 2017/12/18 20.58.44, W]
--
Dec 18, 2017 8:58:50 PM yajhfc.model.servconn.defimpl.AbstractFaxJob reloadData
FINEST: Raw data is: [testuser, 100, Dialing, 0, 768, R, 2017/12/18 20.58.44, R, 00000892]
--
Dec 18, 2017 8:59:10 PM yajhfc.model.servconn.defimpl.AbstractFaxJob reloadData
FINEST: Raw data is: [testuser, 100, Sending 14400/ECM, 1, 768, R, 2017/12/18 20.58.44, R, 00000892]

#
# raw data of other (done) jobs
#

--
Dec 18, 2017 8:59:30 PM yajhfc.model.servconn.defimpl.AbstractFaxJob reloadData
FINEST: Raw data is: [testuser, 100, OK, 1, 768, D, 2017/12/18 20.59.12, 13, D, 00000892]

W in the first FaxJob Response seems to be Waiting, that is what i see in the gui and after 4 seconds it changes to Running.

But there is a notable delay between Hylafax (20:59:12), marking the transmission as done, and yahfc taking notice of it (20:59:30)

But you are right, this should be discussed in the yahfc issue tracker.

from gofaxip.