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] Recieve Errors

On 2004.08.18 16:40 Stephen Carville wrote:

Aug 18 14:55:20.44: [ 9190]: SESSION BEGIN 000001500 18003854994
Aug 18 14:55:20.44: [ 9190]: HylaFAX (tm) Version 4.2.0rc2
Aug 18 14:55:20.44: [ 9190]: <-- [4:ATA\r]
Aug 18 14:55:32.27: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:32.27: [ 9190]: ANSWER: FAX CONNECTION  DEVICE
'/dev/ttyM1a'
Aug 18 14:55:32.27: [ 9190]: RECV FAX: begin
Aug 18 14:55:32.34: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:32.40: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:34.63: [ 9190]: --> [2:OK]
Aug 18 14:55:34.63: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:55:34.75: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:36.52: [ 9190]: --> [2:OK]
Aug 18 14:55:36.52: [ 9190]: REMOTE TSI "8003473941"
Aug 18 14:55:36.52: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:55:36.60: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:36.84: [ 9190]: --> [2:OK]
Aug 18 14:55:36.84: [ 9190]: REMOTE wants 14400 bit/s
Aug 18 14:55:36.84: [ 9190]: REMOTE wants A4 page width (215 mm)
Aug 18 14:55:36.84: [ 9190]: REMOTE wants unlimited page length
Aug 18 14:55:36.84: [ 9190]: REMOTE wants 3.85 line/mm
Aug 18 14:55:36.84: [ 9190]: REMOTE wants 2-D MMR
Aug 18 14:55:36.84: [ 9190]: REMOTE wants T.30 Annex A, 256-byte ECM
Aug 18 14:55:36.84: [ 9190]: RECV training at v.17 14400 bit/s
Aug 18 14:55:36.84: [ 9190]: <-- [11:AT+FRM=145\r]
Aug 18 14:55:38.63: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:40.18: [ 9190]: RECV: TCF 2704 bytes, 1% non-zero, 1098
zero-run
Aug 18 14:55:40.18: [ 9190]: RECV: reject TCF (zero run too short, min
1800)

Uh oh, looks like a noisy connection. So, we're going to try again...

Aug 18 14:55:40.21: [ 9190]: --> [10:NO CARRIER]
Aug 18 14:55:40.21: [ 9190]: DELAY 75 ms
Aug 18 14:55:40.29: [ 9190]: <-- [9:AT+FTH=3\r]
Aug 18 14:55:41.32: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:41.74: [ 9190]: --> [2:OK]
Aug 18 14:55:41.74: [ 9190]: TRAINING failed
Aug 18 14:55:41.74: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:55:41.88: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:43.65: [ 9190]: --> [2:OK]
Aug 18 14:55:43.65: [ 9190]: REMOTE TSI "8003473941"
Aug 18 14:55:43.65: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:55:43.73: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:43.97: [ 9190]: --> [2:OK]
Aug 18 14:55:43.97: [ 9190]: REMOTE wants 14400 bit/s
Aug 18 14:55:43.97: [ 9190]: REMOTE wants A4 page width (215 mm)
Aug 18 14:55:43.97: [ 9190]: REMOTE wants unlimited page length
Aug 18 14:55:43.97: [ 9190]: REMOTE wants 3.85 line/mm
Aug 18 14:55:43.97: [ 9190]: REMOTE wants 2-D MMR
Aug 18 14:55:43.97: [ 9190]: REMOTE wants T.30 Annex A, 256-byte ECM
Aug 18 14:55:43.97: [ 9190]: RECV training at v.17 14400 bit/s
Aug 18 14:55:43.97: [ 9190]: <-- [11:AT+FRM=145\r]
Aug 18 14:55:45.76: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:47.31: [ 9190]: RECV: TCF 2704 bytes, 0% non-zero, 2158
zero-run

This time it was good (nearly perfect). 2158 bytes * 14400 baud = 1.2 sec. That's close enough to 1.5 sec to count.

Aug 18 14:55:47.34: [ 9190]: --> [10:NO CARRIER]
Aug 18 14:55:47.34: [ 9190]: DELAY 75 ms
Aug 18 14:55:47.42: [ 9190]: TRAINING succeeded
Aug 18 14:55:47.42: [ 9190]: <-- [9:AT+FTH=3\r]
Aug 18 14:55:48.45: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:48.87: [ 9190]: --> [2:OK]
Aug 18 14:55:48.87: [ 9190]: <-- [11:AT+FRM=146\r]
Aug 18 14:55:49.83: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:49.83: [ 9190]: Bad HDLC terminating flag received.
Aug 18 14:55:50.11: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0xf8
Aug 18 14:55:50.39: [ 9190]: Bad HDLC terminating flag received.
Aug 18 14:55:50.57: [ 9190]: RECV received frame number 3
Aug 18 14:55:50.76: [ 9190]: RECV received frame number 4
Aug 18 14:55:50.94: [ 9190]: RECV received frame number 5
Aug 18 14:55:51.03: [ 9190]: RECV received frame number 6
Aug 18 14:55:51.22: [ 9190]: RECV received frame number 7
Aug 18 14:55:51.31: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0xc0
Aug 18 14:55:51.68: [ 9190]: RECV received frame number 10
Aug 18 14:55:51.77: [ 9190]: RECV received frame number 11
Aug 18 14:55:51.77: [ 9190]: RECV frame FCS check failed
Aug 18 14:55:51.96: [ 9190]: RECV received frame number 12
Aug 18 14:55:52.05: [ 9190]: RECV received frame number 13
Aug 18 14:55:52.24: [ 9190]: RECV received frame number 14
Aug 18 14:55:52.24: [ 9190]: RECV frame FCS check failed
Aug 18 14:55:52.42: [ 9190]: RECV received frame number 15
Aug 18 14:55:52.51: [ 9190]: RECV received frame number 16
Aug 18 14:55:52.51: [ 9190]: RECV frame FCS check failed
Aug 18 14:55:52.70: [ 9190]: RECV received frame number 17
Aug 18 14:55:52.79: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0xfc
Aug 18 14:55:53.16: [ 9190]: RECV received frame number 20
Aug 18 14:55:53.16: [ 9190]: Bad HDLC terminating flag received.
Aug 18 14:55:53.25: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0
Aug 18 14:55:53.78: [ 9190]: RECV received frame number 23
Aug 18 14:55:53.78: [ 9190]: RECV received RCP frame

Alas, it still looks like a noisy connection. Notice all of the errors in the data stream. Luckily, the ECM function is going to recover these for us...

Aug 18 14:55:53.78: [ 9190]: --> [10:NO CARRIER]
Aug 18 14:55:53.78: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:55:53.90: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:55.02: [ 9190]: --> [2:OK]
Aug 18 14:55:55.02: [ 9190]: RECV recv PPS (partial page signal)
Aug 18 14:55:55.02: [ 9190]: RECV recv MPS (more pages, same document)
Aug 18 14:55:55.02: [ 9190]: RECV received 24 frames of block 1 of
page 1
Aug 18 14:55:55.02: [ 9190]: <-- [9:AT+FRS=7\r]
Aug 18 14:55:55.14: [ 9190]: --> [2:OK]
Aug 18 14:55:55.14: [ 9190]: <-- [9:AT+FTH=3\r]
Aug 18 14:55:56.15: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:57.59: [ 9190]: --> [2:OK]
Aug 18 14:55:57.59: [ 9190]: RECV send PPR (partial page request)

PPR means, "Hey, we didn't get all of those image data frames correctly. Please resend these." And the specific frame numbers are mentioned in the signal.

Aug 18 14:55:57.59: [ 9190]: <-- [11:AT+FRM=146\r]
Aug 18 14:55:58.54: [ 9190]: --> [7:CONNECT]
Aug 18 14:55:58.81: [ 9190]: RECV received frame number 0
Aug 18 14:55:59.00: [ 9190]: RECV received frame number 1
Aug 18 14:55:59.00: [ 9190]: RECV frame FCS check failed
Aug 18 14:55:59.18: [ 9190]: RECV received frame number 2
Aug 18 14:55:59.27: [ 9190]: RECV received frame number 8
Aug 18 14:55:59.46: [ 9190]: RECV received frame number 9
Aug 18 14:55:59.64: [ 9190]: RECV received frame number 11
Aug 18 14:55:59.73: [ 9190]: RECV received frame number 14
Aug 18 14:55:59.92: [ 9190]: RECV received frame number 16
Aug 18 14:56:00.01: [ 9190]: RECV received frame number 18
Aug 18 14:56:00.20: [ 9190]: RECV received frame number 19
Aug 18 14:56:00.38: [ 9190]: RECV received frame number 21
Aug 18 14:56:00.47: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0xfc
Aug 18 14:56:00.47: [ 9190]: RECV received RCP frame

So we got a lot of them recovered, but still there are some bad ones that we'll request to be resent via the PPR signal.

Aug 18 14:56:00.72: [ 9190]: --> [10:NO CARRIER]
Aug 18 14:56:00.72: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:56:00.88: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:01.93: [ 9190]: --> [2:OK]
Aug 18 14:56:01.93: [ 9190]: RECV recv PPS (partial page signal)
Aug 18 14:56:01.93: [ 9190]: RECV recv MPS (more pages, same document)
Aug 18 14:56:01.93: [ 9190]: RECV received 12 frames of block 1 of
page 1
Aug 18 14:56:01.93: [ 9190]: <-- [9:AT+FRS=7\r]
Aug 18 14:56:02.05: [ 9190]: --> [2:OK]
Aug 18 14:56:02.05: [ 9190]: <-- [9:AT+FTH=3\r]
Aug 18 14:56:03.08: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:04.53: [ 9190]: --> [2:OK]
Aug 18 14:56:04.53: [ 9190]: RECV send PPR (partial page request)

This is the 2nd PPR signal.

Aug 18 14:56:04.53: [ 9190]: <-- [11:AT+FRM=146\r]
Aug 18 14:56:05.48: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:05.75: [ 9190]: RECV received frame number 1
Aug 18 14:56:05.94: [ 9190]: RECV received frame number 22
Aug 18 14:56:05.94: [ 9190]: RECV received RCP frame
Aug 18 14:56:06.10: [ 9190]: --> [10:NO CARRIER]
Aug 18 14:56:06.10: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:56:06.25: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:07.38: [ 9190]: --> [2:OK]
Aug 18 14:56:07.38: [ 9190]: RECV recv PPS (partial page signal)
Aug 18 14:56:07.38: [ 9190]: RECV recv MPS (more pages, same document)
Aug 18 14:56:07.38: [ 9190]: RECV received 2 frames of block 1 of page
1
Aug 18 14:56:07.38: [ 9190]: <-- [9:AT+FRS=7\r]
Aug 18 14:56:07.50: [ 9190]: --> [2:OK]
Aug 18 14:56:07.51: [ 9190]: RECV: 5919 bytes of data, 1065 total
lines
Aug 18 14:56:07.51: [ 9190]: <-- [9:AT+FTH=3\r]
Aug 18 14:56:08.52: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:08.52: [ 9190]: RECV send MCF (message confirmation)

Great, we got them all correctly now. So now, finally, we can move on to the next page...

Aug 18 14:56:08.52: [ 9190]: RECV FAX (000001500): from 8003473941,
page 1 in 0:21, INF, 3.85 line/mm, 2-D MMR, 14400 bit/s
Aug 18 14:56:08.96: [ 9190]: --> [2:OK]
Aug 18 14:56:08.96: [ 9190]: <-- [11:AT+FRM=146\r]
Aug 18 14:56:09.90: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:10.18: [ 9190]: RECV received frame number 0
Aug 18 14:56:10.36: [ 9190]: RECV received frame number 1
Aug 18 14:56:10.54: [ 9190]: RECV received frame number 2
Aug 18 14:56:10.63: [ 9190]: RECV received frame number 3
Aug 18 14:56:10.82: [ 9190]: RECV received frame number 4
Aug 18 14:56:11.00: [ 9190]: RECV received frame number 5
Aug 18 14:56:11.09: [ 9190]: RECV received frame number 6
Aug 18 14:56:11.28: [ 9190]: RECV received frame number 7
Aug 18 14:56:11.37: [ 9190]: RECV received frame number 8
Aug 18 14:56:11.56: [ 9190]: RECV received frame number 9
Aug 18 14:56:11.74: [ 9190]: RECV received frame number 10
Aug 18 14:56:11.83: [ 9190]: RECV received frame number 11
Aug 18 14:56:12.02: [ 9190]: RECV received frame number 12
Aug 18 14:56:12.11: [ 9190]: RECV received frame number 13
Aug 18 14:56:12.29: [ 9190]: RECV received frame number 14
Aug 18 14:56:12.48: [ 9190]: RECV received frame number 15
Aug 18 14:56:12.57: [ 9190]: RECV received frame number 16
Aug 18 14:56:12.76: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0
Aug 18 14:56:13.03: [ 9190]: RECV received frame number 19
Aug 18 14:56:13.22: [ 9190]: RECV received frame number 20
Aug 18 14:56:13.31: [ 9190]: RECV received frame number 21
Aug 18 14:56:13.49: [ 9190]: RECV received frame number 22
Aug 18 14:56:13.68: [ 9190]: RECV received frame number 23
Aug 18 14:56:13.77: [ 9190]: RECV received frame number 24
Aug 18 14:56:13.87: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0
Aug 18 14:56:14.05: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0
Aug 18 14:56:14.42: [ 9190]: RECV received frame number 28
Aug 18 14:56:14.51: [ 9190]: RECV received frame number 29
Aug 18 14:56:14.51: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0xfc
Aug 18 14:56:14.79: [ 9190]: RECV received frame number 31
Aug 18 14:56:14.97: [ 9190]: RECV received frame number 32
Aug 18 14:56:15.16: [ 9190]: RECV received frame number 33
Aug 18 14:56:15.25: [ 9190]: RECV received frame number 34
Aug 18 14:56:15.43: [ 9190]: RECV received frame number 35
Aug 18 14:56:15.53: [ 9190]: RECV received frame number 36
Aug 18 14:56:15.71: [ 9190]: RECV received frame number 37
Aug 18 14:56:15.90: [ 9190]: RECV received frame number 38
Aug 18 14:56:15.99: [ 9190]: RECV received frame number 39
Aug 18 14:56:16.17: [ 9190]: RECV received frame number 40
Aug 18 14:56:16.27: [ 9190]: HDLC frame not byte-oriented.  Trailing
byte: 0
Aug 18 14:56:16.36: [ 9190]: Bad HDLC terminating flag received.
Aug 18 14:56:16.64: [ 9190]: RECV received frame number 43
Aug 18 14:56:16.73: [ 9190]: RECV received frame number 44
Aug 18 14:56:16.73: [ 9190]: RECV received RCP frame

Still a noisy connection, but apparently ECM will help us out again...

Aug 18 14:56:16.89: [ 9190]: --> [10:NO CARRIER]
Aug 18 14:56:16.89: [ 9190]: <-- [9:AT+FRH=3\r]
Aug 18 14:56:17.02: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:18.20: [ 9190]: --> [2:OK]
Aug 18 14:56:18.20: [ 9190]: RECV recv PPS (partial page signal)
Aug 18 14:56:18.20: [ 9190]: RECV recv MPS (more pages, same document)
Aug 18 14:56:18.20: [ 9190]: RECV received 45 frames of block 1 of
page 2
Aug 18 14:56:18.20: [ 9190]: <-- [9:AT+FRS=7\r]
Aug 18 14:56:18.32: [ 9190]: --> [2:OK]
Aug 18 14:56:18.32: [ 9190]: <-- [9:AT+FTH=3\r]
Aug 18 14:56:19.33: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:20.76: [ 9190]: --> [2:OK]
Aug 18 14:56:20.76: [ 9190]: RECV send PPR (partial page request)

So we requested the problematic ones to be resent.

Aug 18 14:56:20.76: [ 9190]: <-- [11:AT+FRM=146\r]
Aug 18 14:56:21.05: [ 9190]: --> [8:+FCERROR]

And, what's this? +FCERROR means that the modem is detecting a carrier on the line, but it's not the V.17 14400 baud one. What carrier signal is it, then? Well, it's probably the V.21 300 baud message carrier. Maybe the sender didn't hear our PPR signal; maybe the sender chose to hang up and is trying to transmit DCN; who knows what the sender is doing? In any case, it's not doing what it should, so the session has to be aborted. But, being the robust and resiliant little program that it is, HylaFAX chooses to keep on trying to detect the V.17 14400 baud carrier for a while...

Aug 18 14:56:21.05: [ 9190]: <-- [11:AT+FRM=146\r]
Aug 18 14:56:21.32: [ 9190]: --> [8:+FCERROR]
.... 
Aug 18 14:56:34.99: [ 9190]: <-- [11:AT+FRM=146\r]
Aug 18 14:56:35.34: [ 9190]: --> [8:+FCERROR]
Aug 18 14:56:35.34: [ 9190]: RECV keeping unconfirmed page

Sometimes this actually helps. Sometimes the sender is just a bit slow to raise its transmission carrier and in those cases we may see a few +FCERROR at the outset. But in this case it didn't work out that way.

HylaFAX keeps the data and stores it in a page, but because there was an error in frame number 17 and because MMR image data cannot be readily decoded past a point of error, the line count will be stopped at the point of error (279 lines, a short page, 2.5 inches), and that's likely all the image length that you'll see on that page.

Aug 18 14:56:35.36: [ 9190]: RECV: 11520 bytes of data, 279 total
lines
Aug 18 14:56:35.36: [ 9190]: RECV FAX (000001500): from 8003473941,
page 2 in 0:27, INF, 3.85 line/mm, 2-D MMR, 14400 bit/s
Aug 18 14:56:35.36: [ 9190]: RECV FAX (000001500):
recvq/fax000005078.tif from 8003473941, route to <unspecified>, 2
pages in 1:03
Aug 18 14:56:35.36: [ 9190]: RECV FAX: Failed to properly detect
high-speed data carrier.

That's exactly the error: we were unable to detect a high-speed data carrier in order to receive more image data.

Aug 18 14:56:35.36: [ 9190]: <-- [9:AT+FTH=3\r]
Aug 18 14:56:36.37: [ 9190]: --> [7:CONNECT]
Aug 18 14:56:36.81: [ 9190]: --> [2:OK]
Aug 18 14:56:36.81: [ 9190]: RECV FAX (000001500): session with
8003473941 terminated abnormally: Failed to properly detect high-speed
data carrier.
Aug 18 14:56:36.81: [ 9190]: RECV FAX: bin/faxrcvd
"recvq/fax000005078.tif" "ttyM1a" "000001500" "Failed to properly
detect high-speed data carrier." "" ""
Aug 18 14:56:36.83: [ 9190]: RECV FAX: end
Aug 18 14:56:36.83: [ 9190]: SESSION END

The facsimile was automatically dispatched to:
inbound-385-4994@xxxxxxxxxxxxxxx

Is this realated to Class1TCFRecvHack?  I can't see how but I'm still
feeling my way thru this faxing stuff.

No, it's probably not related to Class1TCFRecvHack.

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