[hylafax-users] happily sending/receiving for 2 months, then stopped receiving.....

To: "hylafax-user's list" <hylafax-users@xxxxxxxxxxx>
Subject: [hylafax-users] happily sending/receiving for 2 months, then stopped receiving.....
From: paul trader <fliptop@xxxxxxxxxxxx>
Date: Tue, 2 May 2006 13:08:46 -0400 (EDT)

hello list - i set up a fax server in march. for 2 months, there were no problems, the server was sending and receiving faxes just fine.

i'm using an internal usr 5610 that's configured as class 1. i had previously configured it as class 2.0, but some fax machines we were receiving from couldn't talk to it. switching to class 1 fixed that problem.

suddenly, in the middle of the day last week, it stopped receiving faxes altogether. sending still works fine. the last received fax log is below:

Apr 27 10:24:43.63: [ 2593]: SESSION BEGIN 000000582 1xxxxxxxxxx Apr 27 10:24:43.63: [ 2593]: HylaFAX (tm) Version 4.2.5 Apr 27 10:24:43.63: [ 2593]: <-- [13:AT+FCLASS=1A\r] Apr 27 10:24:49.07: [ 2593]: --> [7:CONNECT] Apr 27 10:24:49.07: [ 2593]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyS4' Apr 27 10:24:49.07: [ 2593]: RECV FAX: begin Apr 27 10:24:49.07: [ 2593]: <-- data [32] Apr 27 10:24:49.07: [ 2593]: <-- data [2] Apr 27 10:24:49.24: [ 2593]: --> [7:CONNECT] Apr 27 10:24:49.24: [ 2593]: <-- data [23] Apr 27 10:24:49.24: [ 2593]: <-- data [2] Apr 27 10:24:49.96: [ 2593]: --> [7:CONNECT] Apr 27 10:24:49.96: [ 2593]: <-- data [13] Apr 27 10:24:49.96: [ 2593]: <-- data [2] Apr 27 10:24:52.22: [ 2593]: --> [2:OK] Apr 27 10:24:52.22: [ 2593]: <-- [9:AT+FRH=3\r] Apr 27 10:24:52.54: [ 2593]: --> [7:CONNECT] Apr 27 10:24:53.73: [ 2593]: --> [2:OK] Apr 27 10:24:53.73: [ 2593]: <-- [9:AT+FRH=3\r] Apr 27 10:24:53.74: [ 2593]: --> [7:CONNECT] Apr 27 10:24:54.47: [ 2593]: --> [2:OK] Apr 27 10:24:54.47: [ 2593]: <-- [9:AT+FRH=3\r] Apr 27 10:24:54.48: [ 2593]: --> [7:CONNECT] Apr 27 10:24:54.85: [ 2593]: --> [2:OK] Apr 27 10:24:54.85: [ 2593]: DELAY 1500 ms Apr 27 10:24:56.35: [ 2593]: <-- [9:AT+FTH=3\r] Apr 27 10:24:56.54: [ 2593]: --> [7:CONNECT] Apr 27 10:24:56.54: [ 2593]: <-- data [32] Apr 27 10:24:56.54: [ 2593]: <-- data [2] Apr 27 10:24:56.70: [ 2593]: --> [7:CONNECT] Apr 27 10:24:56.70: [ 2593]: <-- data [23] Apr 27 10:24:56.70: [ 2593]: <-- data [2] Apr 27 10:24:57.42: [ 2593]: --> [7:CONNECT] Apr 27 10:24:57.42: [ 2593]: <-- data [13] Apr 27 10:24:57.42: [ 2593]: <-- data [2] Apr 27 10:24:59.69: [ 2593]: --> [2:OK] Apr 27 10:24:59.69: [ 2593]: <-- [9:AT+FRH=3\r] Apr 27 10:25:00.54: [ 2593]: --> [7:CONNECT] Apr 27 10:25:01.88: [ 2593]: --> [5:ERROR] Apr 27 10:25:01.88: [ 2593]: MODEM Command error Apr 27 10:25:01.88: [ 2593]: FCS error Apr 27 10:25:01.88: [ 2593]: DELAY 70 ms Apr 27 10:25:01.95: [ 2593]: <-- [9:AT+FTH=3\r] Apr 27 10:25:02.14: [ 2593]: --> [7:CONNECT] Apr 27 10:25:02.14: [ 2593]: <-- data [3] Apr 27 10:25:02.14: [ 2593]: <-- data [2] Apr 27 10:25:03.32: [ 2593]: --> [2:OK] Apr 27 10:25:03.32: [ 2593]: RECV send CRP (command repeat) Apr 27 10:25:03.32: [ 2593]: <-- [9:AT+FRH=3\r] Apr 27 10:25:04.95: [ 2593]: --> [7:CONNECT] Apr 27 10:25:08.72: [ 2593]: --> [5:ERROR] Apr 27 10:25:08.72: [ 2593]: MODEM Command error Apr 27 10:25:08.72: [ 2593]: FCS error Apr 27 10:25:08.72: [ 2593]: DELAY 70 ms Apr 27 10:25:08.79: [ 2593]: <-- [9:AT+FTH=3\r] Apr 27 10:25:08.98: [ 2593]: --> [7:CONNECT] Apr 27 10:25:08.98: [ 2593]: <-- data [3] Apr 27 10:25:08.98: [ 2593]: <-- data [2] Apr 27 10:25:10.15: [ 2593]: --> [2:OK] Apr 27 10:25:10.15: [ 2593]: RECV send CRP (command repeat) Apr 27 10:25:10.15: [ 2593]: <-- [9:AT+FRH=3\r] Apr 27 10:25:10.49: [ 2593]: --> [7:CONNECT] Apr 27 10:25:10.78: [ 2593]: --> [2:OK] Apr 27 10:25:10.78: [ 2593]: REMOTE wants 14400 bit/s Apr 27 10:25:10.78: [ 2593]: REMOTE wants A4 page width (215 mm) Apr 27 10:25:10.78: [ 2593]: REMOTE wants unlimited page length Apr 27 10:25:10.78: [ 2593]: REMOTE wants 3.85 line/mm Apr 27 10:25:10.78: [ 2593]: REMOTE wants 2-D MMR Apr 27 10:25:10.78: [ 2593]: REMOTE wants T.30 Annex A, 256-byte ECM Apr 27 10:25:10.78: [ 2593]: RECV training at v.17 14400 bit/s Apr 27 10:25:10.78: [ 2593]: <-- [11:AT+FRM=145\r] Apr 27 10:25:12.53: [ 2593]: --> [7:CONNECT] Apr 27 10:25:14.09: [ 2593]: RECV: TCF 2812 bytes, 2% non-zero, 2729 zero-run Apr 27 10:25:14.10: [ 2593]: --> [10:NO CARRIER] Apr 27 10:25:14.10: [ 2593]: DELAY 70 ms Apr 27 10:25:14.17: [ 2593]: TRAINING succeeded Apr 27 10:25:14.17: [ 2593]: <-- [9:AT+FTH=3\r] Apr 27 10:25:14.36: [ 2593]: --> [7:CONNECT] Apr 27 10:25:14.36: [ 2593]: <-- data [3] Apr 27 10:25:14.36: [ 2593]: <-- data [2] Apr 27 10:25:15.54: [ 2593]: --> [2:OK] Apr 27 10:25:15.54: [ 2593]: <-- [11:AT+FRM=146\r] Apr 27 10:25:16.54: [ 2593]: --> [7:CONNECT] Apr 27 10:25:16.96: [ 2593]: RECV received frame number 0 Apr 27 10:25:17.10: [ 2593]: RECV received frame number 1 Apr 27 10:25:17.24: [ 2593]: RECV received frame number 2 ...more of the same here... Apr 27 10:25:30.14: [ 2593]: RECV received frame number 88 Apr 27 10:25:30.36: [ 2593]: RECV received frame number 89 Apr 27 10:25:30.36: [ 2593]: RECV received RCP frame Apr 27 10:25:30.41: [ 2593]: --> [10:NO CARRIER] Apr 27 10:25:30.41: [ 2593]: <-- [9:AT+FRH=3\r] Apr 27 10:25:30.94: [ 2593]: --> [7:CONNECT] Apr 27 10:25:31.78: [ 2593]: --> [2:OK] Apr 27 10:25:31.78: [ 2593]: RECV recv PPS (partial page signal) Apr 27 10:25:31.78: [ 2593]: RECV recv EOP (no more pages or documents) Apr 27 10:25:31.78: [ 2593]: RECV received 90 frames of block 1 of page 1 Apr 27 10:25:31.87: [ 2593]: RECV: 23023 bytes of data, 1094 total lines Apr 27 10:25:31.87: [ 2593]: DELAY 70 ms Apr 27 10:25:31.94: [ 2593]: <-- [9:AT+FTH=3\r] Apr 27 10:25:32.13: [ 2593]: --> [7:CONNECT] Apr 27 10:25:32.13: [ 2593]: <-- data [3] Apr 27 10:25:32.13: [ 2593]: <-- data [2] Apr 27 10:25:33.31: [ 2593]: --> [2:OK] Apr 27 10:25:33.31: [ 2593]: RECV send MCF (message confirmation) Apr 27 10:25:33.31: [ 2593]: RECV FAX (000000582): from <UNSPECIFIED>, page 1 in 0:42, INF, 3.85 line/mm, 2-D MMR, 14400 bit/s Apr 27 10:25:33.31: [ 2593]: RECV FAX (000000582): recvq/fax000000320.tif from <UNSPECIFIED>, route to <unspecified>, 1 pages in 0:44 Apr 27 10:25:33.69: [ 2593]: --> [7:CONNECT] Apr 27 10:25:34.82: [ 2593]: --> [2:OK] Apr 27 10:25:34.82: [ 2593]: RECV recv DCN (disconnect) Apr 27 10:25:34.82: [ 2593]: RECV FAX: bin/faxrcvd "recvq/fax000000320.tif" "ttyS4" "000000582" "" Apr 27 10:25:34.82: [ 2593]: RECV FAX: end Apr 27 10:25:34.82: [ 2593]: SESSION END

here's what was in the messages log for this fax:

Apr 27 10:25:33 fax FaxGetty[12290]: RECV FAX (000000582): from <UNSPECIFIED>, page 1 in 0:42, INF, 3.85 line/mm, 2-D MMR, 14400 bit/s Apr 27 10:25:33 fax FaxGetty[12291]: RECV FAX (000000582): recvq/fax000000320.tif from <UNSPECIFIED>, route to <unspecified>, 1 pages in 0:44 Apr 27 10:25:34 fax FaxGetty[2593]: RECV FAX: bin/faxrcvd "recvq/fax000000320.tif" "ttyS4" "000000582" "" Apr 27 10:25:45 fax FaxGetty[2593]: MODEM USR U.S. Robotics 56K FAX INT V5.22.70/Configuration Profile... Product type US/Canada Internal Product ID: 00561002 Options V32bis,V.80,V.34+,V.90,V.92 Fax Options Class 1/Class 2.0 Line Options Caller ID, Distinctive Ring Clock Freq 92.0Mhz EPROM 256k RAM 32k FLASH date 9/22/2003 FLASH rev 5.22.70 DSP date 9/22/2003 DSP rev 5.22.70

looks normal, just like every other fax received for the last 2 months.

however, the very next fax, and every one after that one, look similar to this:

Apr 27 10:54:07.72: [ 2593]: SESSION BEGIN 000000583 1xxxxxxxxxx
Apr 27 10:54:07.72: [ 2593]: HylaFAX (tm) Version 4.2.5
Apr 27 10:54:07.72: [ 2593]: <-- [13:AT+FCLASS=1A\r]
Apr 27 10:54:13.16: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:13.16: [ 2593]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyS4'
Apr 27 10:54:13.16: [ 2593]: RECV FAX: begin
Apr 27 10:54:13.16: [ 2593]: <-- data [32]
Apr 27 10:54:13.16: [ 2593]: <-- data [2]
Apr 27 10:54:13.32: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:13.32: [ 2593]: <-- data [23]
Apr 27 10:54:13.32: [ 2593]: <-- data [2]
Apr 27 10:54:14.04: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:14.04: [ 2593]: <-- data [13]
Apr 27 10:54:14.04: [ 2593]: <-- data [2]
Apr 27 10:54:16.31: [ 2593]: --> [2:OK]
Apr 27 10:54:16.31: [ 2593]: <-- [9:AT+FRH=3\r]
Apr 27 10:54:23.31: [ 2593]: --> [0:]
Apr 27 10:54:23.31: [ 2593]: MODEM <Empty line>
Apr 27 10:54:23.31: [ 2593]: <-- data [1]
Apr 27 10:54:23.31: [ 2593]: --> [2:OK]
Apr 27 10:54:23.31: [ 2593]: DELAY 1500 ms
Apr 27 10:54:24.81: [ 2593]: <-- [9:AT+FTH=3\r]
Apr 27 10:54:24.84: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:24.84: [ 2593]: <-- data [32]
Apr 27 10:54:24.84: [ 2593]: <-- data [2]
Apr 27 10:54:25.01: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:25.01: [ 2593]: <-- data [23]
Apr 27 10:54:25.01: [ 2593]: <-- data [2]
Apr 27 10:54:25.73: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:25.73: [ 2593]: <-- data [13]
Apr 27 10:54:25.73: [ 2593]: <-- data [2]
Apr 27 10:54:27.99: [ 2593]: --> [2:OK]
Apr 27 10:54:27.99: [ 2593]: <-- [9:AT+FRH=3\r]
Apr 27 10:54:30.52: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:31.84: [ 2593]: --> [2:OK]
Apr 27 10:54:31.84: [ 2593]: <-- [9:AT+FRH=3\r]
Apr 27 10:54:31.86: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:32.62: [ 2593]: --> [2:OK]
Apr 27 10:54:32.62: [ 2593]: <-- [9:AT+FRH=3\r]
Apr 27 10:54:32.63: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:32.99: [ 2593]: --> [2:OK]
Apr 27 10:54:32.99: [ 2593]: DELAY 1500 ms
Apr 27 10:54:34.49: [ 2593]: <-- [9:AT+FTH=3\r]
Apr 27 10:54:34.68: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:34.68: [ 2593]: <-- data [32]
Apr 27 10:54:34.68: [ 2593]: <-- data [2]
Apr 27 10:54:34.85: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:34.85: [ 2593]: <-- data [23]
Apr 27 10:54:34.85: [ 2593]: <-- data [2]
Apr 27 10:54:35.57: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:35.57: [ 2593]: <-- data [13]
Apr 27 10:54:35.57: [ 2593]: <-- data [2]
Apr 27 10:54:37.83: [ 2593]: --> [2:OK]
Apr 27 10:54:37.83: [ 2593]: <-- [9:AT+FRH=3\r]
Apr 27 10:54:38.52: [ 2593]: --> [7:CONNECT]
Apr 27 10:54:39.49: [ 2593]: --> [2:OK]
Apr 27 10:54:39.49: [ 2593]: RECV FAX: RSPREC error/got DCN
Apr 27 10:54:39.49: [ 2593]: RECV FAX: end
Apr 27 10:54:39.49: [ 2593]: SESSION END

the messages log for this one says:

Apr 27 10:54:13 fax FaxGetty[2593]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyS4' Apr 27 10:54:48 fax FaxGetty[2593]: MODEM USR U.S. Robotics 56K FAX INT V5.22.70/Configuration Profile... Product type US/Canada Internal Product ID: 00561002 Options V32bis,V.80,V.34+,V.90,V.92 Fax Options Class 1/Class 2.0 Line Options Caller ID, Distinctive Ring Clock Freq 92.0Mhz EPROM 256k RAM 32k FLASH date 9/22/2003 FLASH rev 5.22.70 DSP date 9/22/2003 DSP rev 5.22.70

it's showing it's answering (which i confirm by listening), but something sounds wrong with the handshake - the tone doesn't sound the same as it did. we're using a backup fax machine now, and it is happily receiving faxes with no problems.

from what i've read, it seems as though problems like this are troubleshot by trying another faxmodem and checking for line noise. i plan on swapping out the modem, but am wondering if it'll help since the server still sends faxes just fine.

if i'm missing something obvious, could someone let me know?

regards, paul


____________________ 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*

Follow-Ups:
- Re: [hylafax-users] happily sending/receiving for 2 months, then stopped receiving.....
  - From: Lee Howard

Prev by Date: Re: [hylafax-users] Seeking Recommendations: Multiport serial Cards
Next by Date: Re: [hylafax-users] happily sending/receiving for 2 months, then stopped receiving.....
Previous by thread: Re: [hylafax-users] Communication failure during Phase B/C
Next by thread: Re: [hylafax-users] happily sending/receiving for 2 months, then stopped receiving.....
Index(es):
- Main
- Thread

Report any problems to webmaster@hylafax.org

HylaFAX is a trademark of Silicon Graphics Corporation.
Internet connectivity for hylafax.org is provided by:
VirtuALL Private Host Services