Hylafax will not answer incoming calls

[Shuvam Misra <shuvam@spacenetindia.com>]

Hi everyone,

I have been using Hylafax for a couple of years now, and have set it up
on various machines, all of them Linux boxes and ZyXEL modems. The latest
install I did yesterday gave me an error I've never seen before.

My hardware is Intel 486DX4 with 16MB, running Linux 2.0.27 from
Slackware 3.1.0. I'm using Hylafax 4.0pl0 binary distribution which I
got from ftp.sgi.com. My modem is ZyXEL O288S (the Omni) with firmware
1.18. I'm running faxgetty from inittab, since I want to handle incoming
and outgoing faxes.

I've tested the modem with kermit. I've made outgoing calls, and also
done an "ATZ" followed by "ATE0Q1S0=2" and received an incoming data
call. The caller dialled in, the modem answered at 28.8kbps after two
rings, and we chatted for half an hour. No flakiness anywhere.

I tried sending out faxes using "sendfax". They went out perfectly. (My
favourite test images are golfer.ps and tiger.ps from the GS
distribution.) Even details like the time and the LocalID string on top
of the page were perfect.

But when I dial into the modem, Hylafax doesn't answer. I switched on
SessionTracing and ServerTracing to level 33037, and this fragment is
what I got in the log:

       			[... init complete ...]

       17:01:45 rose FaxQueuer[128]: MODEM faxmodem: READY, capabilities P3fd7e
7ff:ff
       17:01:45 rose FaxGetty[1857]: STATE CHANGE: LISTENING -> RUNNING
       17:01:45 rose FaxGetty[1857]: MODEM input buffering disabled
       17:01:46 rose FaxGetty[1857]: STATE CHANGE: RUNNING -> LISTENING
       17:01:46 rose FaxGetty[1857]: MODEM input buffering enabled
       17:01:46 rose FaxQueuer[128]: MODEM faxmodem: BUSY
       17:01:51 rose FaxGetty[1857]: MODEM TIMEOUT: reading line from modem
       17:01:51 rose FaxGetty[1857]: <-- [5:ATH0\r]
       17:01:51 rose FaxGetty[1857]: --> [2:OK]
       17:01:51 rose FaxGetty[1857]: MODEM set DTR OFF
       17:01:51 rose FaxGetty[1857]: MODEM set DTR OFF
       17:01:54 rose FaxGetty[1857]: MODEM set DTR ON

       			[... init cycle restarted ...]

I had set the modem to answer after 2 rings. Each time, it would wait
for two rings, then give this message changing state from RUNNING to
LISTENING, then it would report MODEM TIMEOUT, then give the ATH0
command, and go into the reinitialisation cycle. If kept the calling
line on, this cycle would continue:

	1.	pause for two rings
	2.	report MODEM TIMEOUT
	3.	reinitialise the modem
	4.	pause for two more rings...

	ad nauseum.

Funnily, I use Linux 1.2.13 with an O288S firmware 1.13 at home. And
Hylafax 4.0pl0 works just fine. Is there something which changed when
Linux moved from 1.xx to 2.xx? Or is there something which broke when
the modem moved from 1.13 to 1.18 firmware?

I remember reading something somewhere that with Linux 2.0, the kernel
now implements some I/O system calls differently, to make them conform
more closely with new standards. And apparently, the note said, one of
the apps which need modifications is Hylafax. I'd assumed that the new
Hylafax binaries would take care of these changes. Will anyone please
tell me whether my problem is due to these changes? Has anyone faced
these problems at all?

Is this an FAQ? I'm still searching through the list of questions, but
nothing seems to match.

Shuvam
== log fragment, showing cycling of initialisations and errors =========

Jul 18 17:01:45 rose FaxQueuer[128]: MODEM faxmodem: READY, capabilities P3fd7e
7ff:ff
Jul 18 17:01:45 rose FaxGetty[1857]: STATE CHANGE: LISTENING -> RUNNING
Jul 18 17:01:45 rose FaxGetty[1857]: MODEM input buffering disabled
Jul 18 17:01:46 rose FaxGetty[1857]: STATE CHANGE: RUNNING -> LISTENING
Jul 18 17:01:46 rose FaxGetty[1857]: MODEM input buffering enabled
Jul 18 17:01:46 rose FaxQueuer[128]: MODEM faxmodem: BUSY
Jul 18 17:01:51 rose FaxGetty[1857]: MODEM TIMEOUT: reading line from modem
Jul 18 17:01:51 rose FaxGetty[1857]: <-- [5:ATH0\r]
Jul 18 17:01:51 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:51 rose FaxGetty[1857]: MODEM set DTR OFF
Jul 18 17:01:51 rose FaxGetty[1857]: MODEM set DTR OFF
Jul 18 17:01:54 rose FaxGetty[1857]: MODEM set DTR ON
Jul 18 17:01:54 rose FaxGetty[1857]: MODEM set baud rate: 38400 baud, input flo
w RTS/CTS, output flow RTS/CTS
Jul 18 17:01:54 rose FaxGetty[1857]: MODEM flush i/o
Jul 18 17:01:54 rose FaxGetty[1857]: <-- [39:AT&B1&N0&S0*F0S18=4S38.3=1E0V1Q0S0
=0H0\r]
Jul 18 17:01:54 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:54 rose FaxGetty[1857]: <-- [21:ATS8=2S7=60&H3&D2&C1\r]
Jul 18 17:01:54 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:54 rose FaxGetty[1857]: <-- [12:AT+FCLASS=?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [15:0,1,2,2.0,6,8,Z]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [14:AT+FCLASS=2.0\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [8:AT+FMI?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [5:ZyXEL]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [8:AT+FMM?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [18:O288S  V 1.18     ]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [8:AT+FMR?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [18:O288S  V 1.18     ]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [9:AT+FCC=?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [43:(0,1),(0-5),(0-2),(0-2),(0,1),(0),
(0),(0-7)]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [9:AT+FCQ=?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [11:(0-2),(0-2)]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [9:AT+FAP=?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [5:ERROR]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [9:AT+FSP=?\r]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [3:0,1]
Jul 18 17:01:55 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:55 rose FaxGetty[1857]: <-- [14:AT+FCLASS=2.0\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [9:AT+FLO=2\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [9:AT+FPP=0\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [9:AT+FBO=0\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [10:AT+FCT=30\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [15:AT+FNR=1,1,1,1\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [9:AT+FIE=0\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [23:AT+FCC=1,5,2,2,1,0,0,0\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: MODEM ZYXEL O288S/V 1.18
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [5:ATM0\r]
Jul 18 17:01:56 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:56 rose FaxGetty[1857]: <-- [9:AT+FCR=1\r]
Jul 18 17:01:57 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:57 rose FaxGetty[1857]: <-- [24:AT+FLI="Ramon and Demm"\r]
Jul 18 17:01:57 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:57 rose FaxGetty[1857]: <-- [9:AT+FAA=1\r]
Jul 18 17:01:57 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:01:57 rose FaxQueuer[128]: MODEM faxmodem: READY, capabilities P3fd7e
7ff:ff
Jul 18 17:01:57 rose FaxGetty[1857]: STATE CHANGE: LISTENING -> RUNNING
Jul 18 17:01:57 rose FaxGetty[1857]: MODEM input buffering disabled
Jul 18 17:01:58 rose FaxGetty[1857]: STATE CHANGE: RUNNING -> LISTENING
Jul 18 17:01:58 rose FaxGetty[1857]: MODEM input buffering enabled
Jul 18 17:01:58 rose FaxQueuer[128]: MODEM faxmodem: BUSY
Jul 18 17:02:03 rose FaxGetty[1857]: MODEM TIMEOUT: reading line from modem
Jul 18 17:02:03 rose FaxGetty[1857]: <-- [5:ATH0\r]
Jul 18 17:02:04 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:04 rose FaxGetty[1857]: MODEM set DTR OFF
Jul 18 17:02:04 rose FaxGetty[1857]: MODEM set DTR OFF
Jul 18 17:02:06 rose FaxGetty[1857]: MODEM set DTR ON
Jul 18 17:02:06 rose FaxGetty[1857]: MODEM set baud rate: 38400 baud, input flo
w RTS/CTS, output flow RTS/CTS
Jul 18 17:02:06 rose FaxGetty[1857]: MODEM flush i/o
Jul 18 17:02:06 rose FaxGetty[1857]: <-- [39:AT&B1&N0&S0*F0S18=4S38.3=1E0V1Q0S0
=0H0\r]
Jul 18 17:02:06 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:06 rose FaxGetty[1857]: <-- [21:ATS8=2S7=60&H3&D2&C1\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [12:AT+FCLASS=?\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [15:0,1,2,2.0,6,8,Z]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [14:AT+FCLASS=2.0\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [8:AT+FMI?\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [5:ZyXEL]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [8:AT+FMM?\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [18:O288S  V 1.18     ]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [8:AT+FMR?\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [18:O288S  V 1.18     ]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [9:AT+FCC=?\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [43:(0,1),(0-5),(0-2),(0-2),(0,1),(0),
(0),(0-7)]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [9:AT+FCQ=?\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [11:(0-2),(0-2)]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [9:AT+FAP=?\r]
Jul 18 17:02:07 rose FaxGetty[1857]: --> [5:ERROR]
Jul 18 17:02:07 rose FaxGetty[1857]: <-- [9:AT+FSP=?\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [3:0,1]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [14:AT+FCLASS=2.0\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [9:AT+FLO=2\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [9:AT+FPP=0\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [9:AT+FBO=0\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [10:AT+FCT=30\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [15:AT+FNR=1,1,1,1\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [9:AT+FIE=0\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [23:AT+FCC=1,5,2,2,1,0,0,0\r]
Jul 18 17:02:08 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:08 rose FaxGetty[1857]: MODEM ZYXEL O288S/V 1.18
Jul 18 17:02:08 rose FaxGetty[1857]: <-- [5:ATM0\r]
Jul 18 17:02:09 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:09 rose FaxGetty[1857]: <-- [9:AT+FCR=1\r]
Jul 18 17:02:09 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:09 rose FaxGetty[1857]: <-- [24:AT+FLI="Ramon and Demm"\r]
Jul 18 17:02:09 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:09 rose FaxGetty[1857]: <-- [9:AT+FAA=1\r]
Jul 18 17:02:09 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:09 rose FaxQueuer[128]: MODEM faxmodem: READY, capabilities P3fd7e
7ff:ff
Jul 18 17:02:09 rose FaxGetty[1857]: STATE CHANGE: LISTENING -> RUNNING
Jul 18 17:02:09 rose FaxGetty[1857]: MODEM input buffering disabled
Jul 18 17:02:10 rose FaxGetty[1857]: STATE CHANGE: RUNNING -> LISTENING
Jul 18 17:02:10 rose FaxGetty[1857]: MODEM input buffering enabled
Jul 18 17:02:10 rose FaxQueuer[128]: MODEM faxmodem: BUSY
Jul 18 17:02:15 rose FaxGetty[1857]: MODEM TIMEOUT: reading line from modem
Jul 18 17:02:15 rose FaxGetty[1857]: <-- [5:ATH0\r]
Jul 18 17:02:16 rose FaxGetty[1857]: --> [2:OK]
Jul 18 17:02:16 rose FaxGetty[1857]: MODEM set DTR OFF
Jul 18 17:02:16 rose FaxGetty[1857]: MODEM set DTR OFF
Jul 18 17:02:18 rose FaxGetty[1857]: MODEM set DTR ON


------- End of Forwarded Message