Re: [hylafax-users] MT modem hangs OH and TR stays on forever

[GianLuca Sarto <glsarto@xxxxxxxxxx>]

Lee Howard wrote:

GianLuca Sarto wrote:

Lee Howard wrote:

It's clear from the session log that the modem itself is getting hung (not the software)... OR that the serial communication between the modem and HylaFAX has failed.

So does everything return to normal if you power-cycle the modem and also restart faxgetty?  (The faxgetty restart may be required to re-initialize the modem, but quite possibly you don't need to do that.)

Power-cycling the modem does not unlock the serial port (TR stays on): faxstat will report "waiting for modem to come ready" forever.
I have to shutdown the server and pull the plug out, to down the TR.

If restarting faxgetty and power-cycling the modem does not bring things back to normal then I think that the next suspect would be the serial port hardware or driver themselves.

we got 289 faxes without errors, and then the dreaded "T.30 T2 timeout, expected signal not received" came up again.
I was almost incline to blame the modem itself, 'cause we didn't receive errors for over 250 faxes, and here we are again:

Errors were received:
Feb 06 19:05:11.13: [11858]: SESSION BEGIN 000001398 390248953807
Feb 06 19:05:11.13: [11858]: HylaFAX (tm) Version 4.4.0
Feb 06 19:05:11.13: [11858]: <-- [4:ATA\r]
Feb 06 19:05:20.38: [11858]: --> [7:CONNECT]
Feb 06 19:05:20.38: [11858]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyS0'
Feb 06 19:05:20.38: [11858]: RECV FAX: begin
Feb 06 19:05:20.38: [11858]: <-- data [32]
Feb 06 19:05:20.38: [11858]: <-- data [2]
Feb 06 19:05:20.42: [11858]: --> [7:CONNECT]
Feb 06 19:05:20.42: [11858]: <-- data [23]
Feb 06 19:05:20.42: [11858]: <-- data [2]
Feb 06 19:05:20.45: [11858]: --> [7:CONNECT]
Feb 06 19:05:20.45: [11858]: <-- data [13]
Feb 06 19:05:20.45: [11858]: <-- data [2]
Feb 06 19:05:22.71: [11858]: --> [2:OK]
Feb 06 19:05:22.71: [11858]: <-- [9:AT+FRH=3\r]
Feb 06 19:05:23.11: [11858]: --> [7:CONNECT]
Feb 06 19:05:24.77: [11858]: --> [2:OK]
Feb 06 19:05:24.77: [11858]: REMOTE TSI "+39 051 2099456"
Feb 06 19:05:24.77: [11858]: RECV recv TSI (sender id)
Feb 06 19:05:24.77: [11858]: <-- [9:AT+FRH=3\r]
Feb 06 19:05:24.79: [11858]: --> [7:CONNECT]
Feb 06 19:05:25.04: [11858]: --> [2:OK]
Feb 06 19:05:25.04: [11858]: REMOTE wants 14400 bit/s
Feb 06 19:05:25.04: [11858]: REMOTE wants A4 page width (215 mm)
Feb 06 19:05:25.04: [11858]: REMOTE wants unlimited page length
Feb 06 19:05:25.04: [11858]: REMOTE wants 3.85 line/mm
Feb 06 19:05:25.04: [11858]: REMOTE wants 2-D MMR
Feb 06 19:05:25.04: [11858]: REMOTE wants T.30 Annex A, 256-byte ECM
Feb 06 19:05:25.04: [11858]: RECV recv DCS (command signal)
Feb 06 19:05:25.04: [11858]: RECV training at v.17 14400 bit/s
Feb 06 19:05:25.04: [11858]: <-- [11:AT+FRM=145\r]
Feb 06 19:05:26.79: [11858]: --> [7:CONNECT]
Feb 06 19:05:28.30: [11858]: RECV: TCF 2704 bytes, 0% non-zero, 2704 zero-run
Feb 06 19:05:28.30: [11858]: --> [10:NO CARRIER]
Feb 06 19:05:28.30: [11858]: DELAY 70 ms
Feb 06 19:05:28.37: [11858]: TRAINING succeeded
Feb 06 19:05:28.37: [11858]: <-- [9:AT+FTH=3\r]
Feb 06 19:05:29.34: [11858]: --> [7:CONNECT]
Feb 06 19:05:29.34: [11858]: <-- data [3]
Feb 06 19:05:29.34: [11858]: <-- data [2]
Feb 06 19:05:29.74: [11858]: --> [2:OK]
Feb 06 19:05:29.74: [11858]: <-- [11:AT+FRM=146\r]
Feb 06 19:05:30.60: [11858]: --> [7:CONNECT]
Feb 06 19:05:30.97: [11858]: RECV received frame number 0
Feb 06 19:05:31.12: [11858]: RECV received frame number 1
Feb 06 19:05:31.27: [11858]: RECV received frame number 2
Feb 06 19:05:31.41: [11858]: RECV received frame number 3
Feb 06 19:05:31.62: [11858]: RECV received frame number 4
Feb 06 19:05:31.76: [11858]: RECV received frame number 5
Feb 06 19:05:31.90: [11858]: RECV received frame number 6
Feb 06 19:05:32.05: [11858]: RECV received frame number 7
Feb 06 19:05:32.19: [11858]: RECV received frame number 8
Feb 06 19:05:32.34: [11858]: RECV received frame number 9
Feb 06 19:05:32.48: [11858]: RECV received frame number 10
Feb 06 19:05:32.62: [11858]: RECV received frame number 11
Feb 06 19:05:32.78: [11858]: RECV received frame number 12
Feb 06 19:05:32.93: [11858]: RECV received frame number 13
Feb 06 19:05:33.07: [11858]: RECV received frame number 14
Feb 06 19:05:33.22: [11858]: RECV received frame number 15
Feb 06 19:05:33.36: [11858]: RECV received frame number 16
Feb 06 19:05:33.50: [11858]: RECV received frame number 17
Feb 06 19:05:33.65: [11858]: RECV received frame number 18
Feb 06 19:05:33.80: [11858]: RECV received frame number 19
Feb 06 19:05:34.02: [11858]: Bad HDLC terminating flag received.
Feb 06 19:06:04.03: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:06:04.03: [11858]: Bad HDLC terminating flag received.
Feb 06 19:06:34.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:06:34.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:07:04.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:07:04.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:07:34.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:07:34.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:08:04.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:08:04.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:08:34.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:08:34.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:09:04.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:09:04.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:09:34.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:09:34.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:10:04.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:10:04.00: [11858]: Bad HDLC terminating flag received.
Feb 06 19:10:34.00: [11858]: Timeout awaiting synchronization sequence
Feb 06 19:11:06.02: [11858]: MODEM <Empty line>
Feb 06 19:11:08.03: [11858]: MODEM <Empty line>
Feb 06 19:11:10.04: [11858]: MODEM <Empty line>
Feb 06 19:11:10.04: [11858]: <-- [9:AT+FRH=3\r]
Feb 06 19:11:55.56: [11858]: --> [0:]
Feb 06 19:11:55.56: [11858]: MODEM <Empty line>
Feb 06 19:11:55.56: [11858]: <-- data [1]
Feb 06 19:11:55.77: [11858]: MODEM <Timeout>
Feb 06 19:11:55.80: [11858]: RECV: 5120 bytes of data, 197 total lines
Feb 06 19:11:55.80: [11858]: RECV keeping unconfirmed page
Feb 06 19:11:55.80: [11858]: RECV FAX (000001398): from +39 051 2099456, page 1 in 6:35, INF, 3.85 line/mm, 2-D MMR, 14400 bit/s
Feb 06 19:11:55.81: [11858]: RECV FAX (000001398): recvq/fax000009289.tif from +39 051 2099456, route to <unspecified>, 1 pages in 6:35
Feb 06 19:11:55.81: [11858]: RECV FAX: T.30 T2 timeout, expected signal not received
Feb 06 19:11:55.81: [11858]: <-- [9:AT+FTH=3\r]
Feb 06 19:12:03.37: [11858]: --> [0:]
Feb 06 19:12:03.37: [11858]: RECV FAX (000001398): session with +39 051 2099456 terminated abnormally: T.30 T2 timeout, expected signal not received
Feb 06 19:12:03.37: [11858]: RECV FAX: bin/faxrcvd "recvq/fax000009289.tif" "ttyS0" "000001398" "T.30 T2 timeout, expected signal not received"
Feb 06 19:12:03.37: [11858]: RECV FAX: end
Feb 06 19:12:03.37: [11858]: T.30 T2 timeout, expected signal not received
Feb 06 19:12:03.37: [11858]: SESSION END

Why can't the modem handle this error without locking up the server?!

The modems are connected to analog ports of an isdn pabx.

Any advice very welcome.

-GianLuca Sarto