Re: [hylafax-users] Modem stop responding

["Jean-Christophe Etienne" <jean-christophe.etienne@xxxxxxx>]

Hi,

Waiting the next stop, here is more information :

- Apparently all Hylafax processes are still running after modem stop responding

- Informations about modem are in the logs

- Faxmaster didn't receive anything

Here below are the logs :

Apparently modem stop after this call (from /var/spool/hylafax/log/xferfaxlog) :

09/07/10 14:24 RECV 000000048 ttyS0 "" fax "+ 33 1 47 23 49 20" "." 2121768 2 1:28 1:28 "No sender protocol (T.30 T1 timeout)" "" "" "" "" "00 45 1E"

09/07/10 14:24 CALL 000000048 ttyS0 "" fax "+ 33 1 47 23 49 20" "" 0 0 1:36 1:36 "No sender protocol (T.30 T1 timeout)" "" "" "" 

Modem communication for this call  (from /var/spool/hylafax/log/c000000048) :

sep 07 14:24:04.02: [31519]: SESSION BEGIN 000000048 33147234920

sep 07 14:24:04.02: [31519]: HylaFAX (tm) Version 4.4.4

sep 07 14:24:04.02: [31519]: DynamicConfig: bin/dynconf.php "/dev/ttyS0"

sep 07 14:24:04.16: [31519]: <-- [4:ATA\r]

sep 07 14:24:10.92: [31519]: --> [7:CONNECT]

sep 07 14:24:10.92: [31519]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyS0'

sep 07 14:24:10.92: [31519]: RECV FAX: begin

sep 07 14:24:10.92: [31519]: <-- data [32]

sep 07 14:24:10.92: [31519]: <-- data [2]

sep 07 14:24:10.95: [31519]: --> [7:CONNECT]

sep 07 14:24:10.95: [31519]: <-- data [23]

sep 07 14:24:10.95: [31519]: <-- data [2]

sep 07 14:24:10.97: [31519]: --> [7:CONNECT]

sep 07 14:24:10.98: [31519]: <-- data [13]

sep 07 14:24:10.98: [31519]: <-- data [2]

sep 07 14:24:13.18: [31519]: --> [2:OK]

sep 07 14:24:13.18: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:24:13.49: [31519]: --> [7:CONNECT]

sep 07 14:24:15.18: [31519]: --> [2:OK]

sep 07 14:24:15.18: [31519]: REMOTE TSI "."

sep 07 14:24:15.18: [31519]: RECV recv TSI (sender id)

sep 07 14:24:15.18: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:24:15.20: [31519]: --> [7:CONNECT]

sep 07 14:24:15.44: [31519]: --> [2:OK]

sep 07 14:24:15.44: [31519]: REMOTE wants 14400 bit/s

sep 07 14:24:15.44: [31519]: REMOTE wants A4 page width (215 mm)

sep 07 14:24:15.44: [31519]: REMOTE wants unlimited page length

sep 07 14:24:15.44: [31519]: REMOTE wants 3.85 line/mm

sep 07 14:24:15.44: [31519]: REMOTE wants 2-D MR

sep 07 14:24:15.44: [31519]: RECV recv DCS (command signal)

sep 07 14:24:15.44: [31519]: RECV training at v.17 14400 bit/s

sep 07 14:24:15.44: [31519]: <-- [11:AT+FRM=145\r]

sep 07 14:24:15.51: [31519]: --> [8:+FCERROR]

sep 07 14:24:15.51: [31519]: <-- [11:AT+FRM=145\r]

sep 07 14:24:17.21: [31519]: --> [7:CONNECT]

sep 07 14:24:18.75: [31519]: RECV: TCF 2768 bytes, 0% non-zero, 2755 zero-run

sep 07 14:24:18.75: [31519]: --> [10:NO CARRIER]

sep 07 14:24:18.76: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:24:18.84: [31519]: --> [2:OK]

sep 07 14:24:18.84: [31519]: TRAINING succeeded

sep 07 14:24:18.84: [31519]: <-- [9:AT+FTH=3\r]

sep 07 14:24:19.71: [31519]: --> [7:CONNECT]

sep 07 14:24:19.71: [31519]: <-- data [3]

sep 07 14:24:19.71: [31519]: <-- data [2]

sep 07 14:24:20.03: [31519]: --> [2:OK]

sep 07 14:24:20.03: [31519]: <-- [11:AT+FRM=146\r]

sep 07 14:24:20.68: [31519]: --> [7:CONNECT]

sep 07 14:24:20.68: [31519]: RECV: begin page

sep 07 14:24:30.49: [31519]: RECV: 1173 total lines, 0 bad lines, 0 consecutive bad lines

sep 07 14:24:30.49: [31519]: RECV: end page

sep 07 14:24:30.49: [31519]: --> [10:NO CARRIER]

sep 07 14:24:30.49: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:24:30.62: [31519]: --> [7:CONNECT]

sep 07 14:24:31.74: [31519]: --> [2:OK]

sep 07 14:24:31.74: [31519]: RECV recv MPS (more pages, same document)

sep 07 14:24:31.74: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:24:31.93: [31519]: --> [2:OK]

sep 07 14:24:31.93: [31519]: <-- [9:AT+FTH=3\r]

sep 07 14:24:32.89: [31519]: --> [7:CONNECT]

sep 07 14:24:32.90: [31519]: RECV send MCF (message confirmation)

sep 07 14:24:32.90: [31519]: RECV FAX (000000048): from ., page 1 in 0:20, INF, 3.85 line/mm, 2-D MR, 14400 bit/s

sep 07 14:24:32.90: [31519]: <-- data [3]

sep 07 14:24:32.90: [31519]: <-- data [2]

sep 07 14:24:33.32: [31519]: --> [2:OK]

sep 07 14:24:33.32: [31519]: <-- [11:AT+FRM=146\r]

sep 07 14:24:33.94: [31519]: --> [7:CONNECT]

sep 07 14:24:33.94: [31519]: RECV: begin page

sep 07 14:24:48.48: [31519]: RECV: 632 total lines, 24 bad lines, 7 consecutive bad lines

sep 07 14:24:48.48: [31519]: RECV: REJECT page quality, 7-line run (max 5)

sep 07 14:24:48.48: [31519]: RECV: end page

sep 07 14:24:48.48: [31519]: --> [10:NO CARRIER]

sep 07 14:24:48.48: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:24:48.61: [31519]: --> [7:CONNECT]

sep 07 14:24:53.98: [31519]: --> [2:OK]

sep 07 14:24:53.98: [31519]: RECV recv EOP (no more pages or documents)

sep 07 14:24:53.98: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:24:54.16: [31519]: --> [2:OK]

sep 07 14:24:54.16: [31519]: <-- [9:AT+FTH=3\r]

sep 07 14:24:55.13: [31519]: --> [7:CONNECT]

sep 07 14:24:55.13: [31519]: RECV send RTN (retrain negative)

sep 07 14:24:55.13: [31519]: RECV FAX (000000048): from ., page 2 in 0:18, INF, 3.85 line/mm, 2-D MR, 14400 bit/s

sep 07 14:24:55.13: [31519]: <-- data [3]

sep 07 14:24:55.13: [31519]: <-- data [2]

sep 07 14:24:55.55: [31519]: --> [2:OK]

sep 07 14:24:55.56: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:25:02.56: [31519]: --> [0:]

sep 07 14:25:02.56: [31519]: MODEM <Empty line>

sep 07 14:25:02.56: [31519]: <-- data [1]

sep 07 14:25:02.66: [31519]: --> [2:]

sep 07 14:25:02.66: [31519]: --> [2:OK]

sep 07 14:25:02.66: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:25:02.85: [31519]: --> [2:OK]

sep 07 14:25:02.85: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:25:05.04: [31519]: --> [7:CONNECT]

sep 07 14:25:06.29: [31519]: --> [2:OK]

sep 07 14:25:06.29: [31519]: RECV recv EOP (no more pages or documents)

sep 07 14:25:06.29: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:25:07.77: [31519]: --> [2:OK]

sep 07 14:25:07.77: [31519]: <-- [9:AT+FTH=3\r]

sep 07 14:25:08.74: [31519]: --> [7:CONNECT]

sep 07 14:25:08.74: [31519]: <-- data [3]

sep 07 14:25:08.74: [31519]: <-- data [2]

sep 07 14:25:09.16: [31519]: --> [2:OK]

sep 07 14:25:09.16: [31519]: RECV send RTN (retrain negative)

sep 07 14:25:09.16: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:25:09.35: [31519]: --> [2:OK]

sep 07 14:25:09.35: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:25:16.35: [31519]: --> [0:]

sep 07 14:25:16.35: [31519]: MODEM <Empty line>

sep 07 14:25:16.35: [31519]: <-- data [1]

sep 07 14:25:16.46: [31519]: --> [2:]

sep 07 14:25:16.46: [31519]: --> [2:OK]

sep 07 14:25:16.46: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:25:16.64: [31519]: --> [2:OK]

sep 07 14:25:16.64: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:25:23.64: [31519]: --> [0:]

sep 07 14:25:23.64: [31519]: MODEM <Empty line>

sep 07 14:25:23.64: [31519]: <-- data [1]

sep 07 14:25:23.75: [31519]: --> [2:]

sep 07 14:25:23.75: [31519]: --> [2:OK]

sep 07 14:25:23.75: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:25:23.93: [31519]: --> [2:OK]

sep 07 14:25:23.93: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:25:30.94: [31519]: --> [0:]

sep 07 14:25:30.94: [31519]: MODEM <Empty line>

sep 07 14:25:30.94: [31519]: <-- data [1]

sep 07 14:25:31.04: [31519]: --> [2:]

sep 07 14:25:31.04: [31519]: --> [2:OK]

sep 07 14:25:31.04: [31519]: <-- [9:AT+FRS=7\r]

sep 07 14:25:31.52: [31519]: --> [2:OK]

sep 07 14:25:31.52: [31519]: <-- [9:AT+FRH=3\r]

sep 07 14:25:38.52: [31519]: --> [0:]

sep 07 14:25:38.52: [31519]: MODEM <Empty line>

sep 07 14:25:38.52: [31519]: <-- data [1]

sep 07 14:25:38.63: [31519]: --> [2:]

sep 07 14:25:38.63: [31519]: --> [2:OK]

sep 07 14:25:38.63: [31519]: RECV FAX (000000048): recvq/fax000000047.tif from ., route to <unspecified>, 2 pages in 1:28

sep 07 14:25:38.63: [31519]: RECV FAX: No sender protocol (T.30 T1 timeout)

sep 07 14:25:38.63: [31519]: <-- [9:AT+FTH=3\r]

sep 07 14:25:39.60: [31519]: --> [7:CONNECT]

sep 07 14:25:39.60: [31519]: <-- data [3]

sep 07 14:25:39.60: [31519]: <-- data [2]

sep 07 14:25:40.03: [31519]: --> [2:OK]

sep 07 14:25:40.03: [31519]: RECV FAX (000000048): session with . terminated abnormally: No sender protocol (T.30 T1 timeout)

sep 07 14:25:40.03: [31519]: RECV FAX: bin/faxrcvd.php "recvq/fax000000047.tif" "ttyS0" "000000048" "No sender protocol (T.30 T1 timeout)"

sep 07 14:25:40.04: [31519]: RECV FAX: end

sep 07 14:25:40.04: [31519]: No sender protocol (T.30 T1 timeout)

sep 07 14:25:40.04: [31519]: SESSION END

Server tracing (from /var/log/syslog) :

Sep  7 14:23:58 lcnpp01 FaxQueuer[31500]: MODEM ttyS0: BUSY
Sep  7 14:24:04 lcnpp01 FaxQueuer[31500]: MODEM ttyS0: COMID 000000048
Sep  7 14:24:04 lcnpp01 FaxGetty[31519]: DynamicConfig: bin/dynconf.php "/dev/ttyS0"
Sep  7 14:24:10 lcnpp01 FaxGetty[31519]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyS0'
Sep  7 14:24:32 lcnpp01 FaxGetty[32025]: RECV FAX (000000048): from ., page 1 in 0:20, INF, 3.85 line/mm, 2-D MR, 14400 bit/s
Sep  7 14:24:48 lcnpp01 FaxGetty[31519]: RECV: REJECT page quality, 7-line run (max 5)
Sep  7 14:24:55 lcnpp01 FaxGetty[32027]: RECV FAX (000000048): from ., page 2 in 0:18, INF, 3.85 line/mm, 2-D MR, 14400 bit/s
Sep  7 14:25:38 lcnpp01 FaxGetty[32029]: RECV FAX (000000048): recvq/fax000000047.tif from ., route to <unspecified>, 2 pages in 1:28
Sep  7 14:25:40 lcnpp01 FaxGetty[31519]: RECV FAX (000000048): session with . terminated abnormally: No sender protocol (T.30 T1 timeout)
Sep  7 14:25:40 lcnpp01 FaxGetty[31519]: RECV FAX: bin/faxrcvd.php "recvq/fax000000047.tif" "ttyS0" "000000048" "No sender protocol (T.30 T1 timeout)"
Sep  7 14:25:40 lcnpp01 FaxQueuer[31500]: MODEM ttyS0: COMID 
Sep  7 14:25:55 lcnpp01 FaxGetty[31519]: MODEM VENUS V.90 KFAV173 SERIAL S101598V KORTEX 56000 V1.00 110 920/
Sep  7 14:25:56 lcnpp01 FaxQueuer[31500]: MODEM ttyS0: READY, capabilities Pcaf9c77f:ff

Thanks

Kind regards

Jean-Christophe


-----Message d'origine-----
De : Stefan Wagner [mailto:stefan-usenet@xxxxxxxxxxxxxxxxxx] 
Envoyé : jeudi 9 septembre 2010 10:46
À : Jean-Christophe Etienne
Cc : hylafax-users@xxxxxxxxxxx
Objet : RE: [hylafax-users] Modem stop responding

> Hylafax server 4.4.4 on Debian 5.0.5

This is running here rock stable with an Eicon Diva Server ISDN board.

> external modem Kortex 56000 Internet Fax Everything runs fine for 
> hours (or days) then the modem stop responding.

If faxgetty is still running in this state, it looks like a modem problem.
Can you still communicate with the modem using cu or minicom, when this occurs?
If not: What happens, if you power cycle the modem?

And: Do you have more information on this modem type, e.g. the chip set used? I could not find any information on the manufacturer's web site nor elsewhere.

In any way I would recommend to enable logging of the modem communication (see hylafax-config (5) for the values of ServerTracing and  SessionTracing) and then look for the situation and command with missing response.

What happens durint the initialization phase? Are there any errors?

> If I try to restart Hylafax, I get the message :
> "Not starting HylaFAX daemons since they are already running"

That looks quite ok, hfaxd is usually not affected by a wedged modem.

Ok, let's see and good luck.

Kind regards

Stefan
 

-----Message d'origine-----
De : Stefan Wagner [mailto:stefan-usenet@xxxxxxxxxxxxxxxxxx] 
Envoyé : jeudi 9 septembre 2010 10:46
À : Jean-Christophe Etienne
Cc : hylafax-users@xxxxxxxxxxx
Objet : RE: [hylafax-users] Modem stop responding

> Hylafax server 4.4.4 on Debian 5.0.5

This is running here rock stable with an Eicon Diva Server ISDN board.

> external modem Kortex 56000 Internet Fax Everything runs fine for 
> hours (or days) then the modem stop responding.

If faxgetty is still running in this state, it looks like a modem problem.
Can you still communicate with the modem using cu or minicom, when this occurs?
If not: What happens, if you power cycle the modem?

And: Do you have more information on this modem type, e.g. the chip set used? I could not find any information on the manufacturer's web site nor elsewhere.

In any way I would recommend to enable logging of the modem communication (see hylafax-config (5) for the values of ServerTracing and  SessionTracing) and then look for the situation and command with missing response.

What happens durint the initialization phase? Are there any errors?

> If I try to restart Hylafax, I get the message :
> "Not starting HylaFAX daemons since they are already running"

That looks quite ok, hfaxd is usually not affected by a wedged modem.

Ok, let's see and good luck.

Kind regards

Stefan



____________________ HylaFAX(tm) Users Mailing List _______________________
  To subscribe/unsubscribe, click http://lists.hylafax.org/cgi-bin/lsg2.cgi
 On UNIX: mail -s unsubscribe hylafax-users-request@xxxxxxxxxxx < /dev/null
  *To learn about commercial HylaFAX(tm) support, mail sales@xxxxxxxxx*