HylaFAX The world's most advanced open source fax server
[Date Prev][Date Next][Thread Prev][Thread Next] [Date Index] [Thread Index]

Re: [hylafax-users] Problem with one US Robotics modem : keeping unconfirmed page, "No carrier", "FCS error"...

On 2004.10.13 02:53 Sylvain MACHEFERT wrote:

Oct 13 11:15:07.26: [ 1985]: SESSION BEGIN 000000062 330477818119
Oct 13 11:15:07.26: [ 1985]: HylaFAX (tm) Version 4.1.8
Oct 13 11:15:07.26: [ 1985]: <-- [13:AT+FCLASS=1A\r]
Oct 13 11:15:12.55: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:12.55: [ 1985]: ANSWER: FAX CONNECTION  DEVICE
'/dev/ttyS0'
Oct 13 11:15:12.55: [ 1985]: RECV FAX: begin
Oct 13 11:15:12.58: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:14.53: [ 1985]: --> [2:OK]
Oct 13 11:15:14.53: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:15:17.63: [ 1985]: --> [0:]
Oct 13 11:15:17.63: [ 1985]: MODEM <Empty line>
Oct 13 11:15:17.64: [ 1985]: --> [2:OK]

Seeing this at the outset of a receiving session is not all that uncommon. It generally means that the sender did not receive our prologue messages properly and is expecting us to resend them.

Oct 13 11:15:17.64: [ 1985]: DELAY 1500 ms
Oct 13 11:15:19.14: [ 1985]: <-- [9:AT+FTH=3\r]
Oct 13 11:15:19.18: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:19.21: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:21.26: [ 1985]: --> [2:OK]
Oct 13 11:15:21.26: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:15:21.89: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:23.15: [ 1985]: --> [5:ERROR]
Oct 13 11:15:23.15: [ 1985]: MODEM Command error
Oct 13 11:15:23.15: [ 1985]: FCS error

This means that the sender received our prologue messages and responded, but that we did not receive their response properly... so we do it over again...

Oct 13 11:15:23.15: [ 1985]: DELAY 1500 ms
Oct 13 11:15:24.65: [ 1985]: <-- [9:AT+FTH=3\r]
Oct 13 11:15:24.85: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:24.88: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:26.93: [ 1985]: --> [2:OK]
Oct 13 11:15:26.93: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:15:29.89: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:31.54: [ 1985]: --> [2:OK]
Oct 13 11:15:31.54: [ 1985]: REMOTE TSI "0477466252"
Oct 13 11:15:31.54: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:15:31.56: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:31.83: [ 1985]: --> [2:OK]
Oct 13 11:15:31.83: [ 1985]: REMOTE wants 14400 bit/s
Oct 13 11:15:31.83: [ 1985]: REMOTE wants page width 1728 pixels in
215 mm
Oct 13 11:15:31.83: [ 1985]: REMOTE wants A4 page length (297 mm)
Oct 13 11:15:31.83: [ 1985]: REMOTE wants 3.85 line/mm
Oct 13 11:15:31.83: [ 1985]: REMOTE wants 1-D MR
Oct 13 11:15:31.83: [ 1985]: RECV training at v.17 14400 bit/s

Okay, this time everything came through fine.

Oct 13 11:15:31.83: [ 1985]: <-- [11:AT+FRM=145\r]
Oct 13 11:15:33.57: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:34.73: [ 1985]: RECV: TCF 2093 bytes, 2% non-zero, 1260
zero-run
Oct 13 11:15:34.73: [ 1985]: RECV: reject TCF (zero run too short, min
1800)

So the sender sends us the TCF (training) signal, and of the 2093 bytes that were sent, 2% of them were erronious, and the errors were not clustered at one end of the signal, either. (Generally an indicator of a noisy line/channel.)

Oct 13 11:15:34.73: [ 1985]: --> [10:NO CARRIER]
Oct 13 11:15:34.73: [ 1985]: DELAY 75 ms
Oct 13 11:15:34.81: [ 1985]: <-- [9:AT+FTH=3\r]
Oct 13 11:15:35.01: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:36.19: [ 1985]: --> [2:OK]
Oct 13 11:15:36.19: [ 1985]: TRAINING failed

... anyway, this training process continues until 7200 baud is selected ...

Oct 13 11:15:50.01: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:15:50.25: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:51.86: [ 1985]: --> [2:OK]
Oct 13 11:15:51.86: [ 1985]: REMOTE TSI "0477466252"
Oct 13 11:15:51.86: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:15:51.88: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:52.18: [ 1985]: --> [2:OK]
Oct 13 11:15:52.18: [ 1985]: REMOTE wants 2400 bit/s

The preceding line was an error, which I believe is fixed in 4.2.0, but it's non-consequential to this session.

Oct 13 11:15:52.18: [ 1985]: REMOTE wants page width 1728 pixels in
215 mm
Oct 13 11:15:52.18: [ 1985]: REMOTE wants A4 page length (297 mm)
Oct 13 11:15:52.18: [ 1985]: REMOTE wants 3.85 line/mm
Oct 13 11:15:52.18: [ 1985]: REMOTE wants 1-D MR
Oct 13 11:15:52.18: [ 1985]: RECV training at v.17 7200 bit/s
Oct 13 11:15:52.18: [ 1985]: <-- [10:AT+FRM=73\r]
Oct 13 11:15:53.89: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:55.45: [ 1985]: RECV: TCF 1406 bytes, 4% non-zero, 648
zero-run
Oct 13 11:15:55.46: [ 1985]: --> [10:NO CARRIER]
Oct 13 11:15:55.46: [ 1985]: DELAY 75 ms
Oct 13 11:15:55.54: [ 1985]: TRAINING succeeded
Oct 13 11:15:55.54: [ 1985]: <-- [9:AT+FTH=3\r]
Oct 13 11:15:55.74: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:56.92: [ 1985]: --> [2:OK]
Oct 13 11:15:56.92: [ 1985]: <-- [10:AT+FRM=74\r]
Oct 13 11:15:59.89: [ 1985]: --> [7:CONNECT]
Oct 13 11:15:59.89: [ 1985]: RECV: begin page
Oct 13 11:16:00.88: [ 1985]: RECV: 0 total lines, 0 bad lines, 0
consecutive
bad lines
Oct 13 11:16:00.88: [ 1985]: RECV: end page

You can almost guarantee that a 0-line page is an error, probably caused by mistakenly "hearing" a carrier drop.

Oct 13 11:16:00.88: [ 1985]: --> [10:NO CARRIER]
Oct 13 11:16:00.88: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:16:05.89: [ 1985]: --> [7:CONNECT]
Oct 13 11:16:07.39: [ 1985]: --> [2:OK]
Oct 13 11:16:07.39: [ 1985]: REMOTE TSI "0477466252"
Oct 13 11:16:07.39: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:16:07.41: [ 1985]: --> [7:CONNECT]
Oct 13 11:16:07.68: [ 1985]: --> [2:OK]
Oct 13 11:16:07.68: [ 1985]: REMOTE wants 2400 bit/s
Oct 13 11:16:07.68: [ 1985]: REMOTE wants page width 1728 pixels in
215 mm
Oct 13 11:16:07.68: [ 1985]: REMOTE wants A4 page length (297 mm)
Oct 13 11:16:07.68: [ 1985]: REMOTE wants 3.85 line/mm
Oct 13 11:16:07.68: [ 1985]: REMOTE wants 1-D MR
Oct 13 11:16:07.68: [ 1985]: RECV training at v.17 7200 bit/s
Oct 13 11:16:07.68: [ 1985]: <-- [10:AT+FRM=73\r]
Oct 13 11:16:09.40: [ 1985]: --> [7:CONNECT]
Oct 13 11:16:10.96: [ 1985]: RECV: TCF 1406 bytes, 4% non-zero, 629
zero-run
Oct 13 11:16:10.97: [ 1985]: --> [10:NO CARRIER]
Oct 13 11:16:10.97: [ 1985]: DELAY 75 ms
Oct 13 11:16:11.05: [ 1985]: TRAINING succeeded
Oct 13 11:16:11.05: [ 1985]: <-- [9:AT+FTH=3\r]
Oct 13 11:16:11.25: [ 1985]: --> [7:CONNECT]
Oct 13 11:16:12.43: [ 1985]: --> [2:OK]
Oct 13 11:16:12.43: [ 1985]: <-- [10:AT+FRM=74\r]
Oct 13 11:16:13.51: [ 1985]: --> [7:CONNECT]
Oct 13 11:16:13.51: [ 1985]: RECV: begin page
Oct 13 11:16:15.50: [ 1985]: RECV: 60 total lines, 2 bad lines, 1
consecutive bad lines
Oct 13 11:16:15.50: [ 1985]: RECV: end page

Same thing, but this time we got some lines. 60 lines is still very, very few. At 3.85 line/mm you're looking at a 1.5 cm long page, so it's pretty clear that the carrier drop was mistakenly heard again.

Oct 13 11:16:15.50: [ 1985]: --> [10:NO CARRIER]
Oct 13 11:16:15.50: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:16:19.16: [ 1985]: --> [7:CONNECT]
Oct 13 11:16:21.90: [ 1985]: --> [5:ERROR]
Oct 13 11:16:21.90: [ 1985]: MODEM Command error
Oct 13 11:16:21.90: [ 1985]: FCS error

Noise can cause this again...

Oct 13 11:16:21.90: [ 1985]: <-- [9:AT+FRH=3\r]
Oct 13 11:16:21.92: [ 1985]: --> [7:CONNECT]
Oct 13 11:16:26.93: [ 1985]: --> [2:OK]

Not sure what this message was, but it was probably DCN.

Oct 13 11:16:26.93: [ 1985]: RECV keeping unconfirmed page
Oct 13 11:16:26.93: [ 1985]: RECV FAX (000000062): from 0477466252,
page 1
in 0:31, A4, 3.85 line/mm, 1-D MR, 2400 bit/s
Oct 13 11:16:26.93: [ 1985]: RECV FAX (000000062):
recvq/fax000000048.tif
from 0477466252, route to <unspecified>, 1 pages in 1:14
Oct 13 11:16:26.93: [ 1985]: RECV FAX: T.30 T2 timeout, expected page
not
received

Anyway, on that one the main problem looks to be noise on the connection. I can't tell you where it's coming from, though.

Oct 12 20:09:08.24: [ 1984]: SESSION BEGIN 000000052 330477818119

This session was plagued by pretty much the same problems. So I'm going to skip it.

Oct 13 10:57:55.06: [ 1986]: SESSION BEGIN 000000049 330477963096
... snip ... 
Oct 13 10:59:22.02: [ 1986]: <-- [9:AT+FRH=3\r]
Oct 13 10:59:22.37: [ 1986]: --> [7:CONNECT]
Oct 13 10:59:22.81: [ 1986]: --> [2:OK]
Oct 13 10:59:22.81: [ 1986]: RECV recv MPS (more pages, same document)
Oct 13 10:59:22.81: [ 1986]: <-- [9:AT+FRS=7\r]
Oct 13 10:59:22.92: [ 1986]: --> [2:OK]
Oct 13 10:59:22.92: [ 1986]: <-- [9:AT+FTH=3\r]
Oct 13 10:59:52.92: [ 1986]: MODEM <Timeout>
Oct 13 10:59:52.92: [ 1986]: RECV send MCF (message confirmation)
Oct 13 10:59:52.92: [ 1986]: RECV FAX (000000049): from 0478377320,
page 3
in 0:47, INF, 3.85 line/mm, 2-D MR, 9600 bit/s
Oct 13 10:59:55.47: [ 1986]: --> [5:ÿ?]

This is a common firmware problem with USR modems. Some people have reported success in working around this firmware problem by disabling the usage of AT+FRS/AT+FTS in their modem config file. Please see the Topic config template (config/topic) on how to do that.

Lee.

____________________ 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