HylaFAX The world's most advanced open source fax server

[Date Prev][Date Next][Thread Prev][Thread Next] [Date Index] [Thread Index]

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




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*




Project hosted by iFAX Solutions