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] T.30 T2 timeout

Nicolas Douville wrote:
Hi,
We have an issue with a remote fax. When it sends us some faxes, it never works... Here are the traces. We suspect that it comes from the remote fax, but is there anyone who can translate me the logs and give me any idea about the cause?
Thank you

The full document was not received because:

T.30 T2 timeout, expected page not received

---- Transcript of session follows ----

Mar 19 11:55:16.44: [18399]: SESSION BEGIN 000020394 3350563433030
Mar 19 11:55:16.44: [18399]: HylaFAX (tm) Version 4.2.2

This line is an indicator that you should upgrade to HylaFAX+ 5.2.9 (http://hylafax.sourceforge.net) ;-)

Mar 19 11:55:16.44: [18399]: <-- [4:ATA\r]
Mar 19 11:55:22.44: [18399]: --> [7:CONNECT]
Mar 19 11:55:22.44: [18399]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyS0'
Mar 19 11:55:22.44: [18399]: RECV FAX: begin
Mar 19 11:55:24.47: [18399]: --> [7:CONNECT]
Mar 19 11:55:25.30: [18399]: --> [7:CONNECT]
Mar 19 11:55:25.87: [18399]: --> [2:OK]
Mar 19 11:55:25.87: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:55:32.87: [18399]: --> [0:]
Mar 19 11:55:32.87: [18399]: MODEM <Empty line>
Mar 19 11:55:32.92: [18399]: --> [2:OK]

NSF, CSI, and DIS signals were sent, but no response was detected from the sender.

Mar 19 11:55:32.92: [18399]: DELAY 1500 ms

A silly delay that could be causing some problem. It's better with HylaFAX+ 5.2.9.

Mar 19 11:55:34.42: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:55:34.46: [18399]: --> [7:CONNECT]
Mar 19 11:55:36.49: [18399]: --> [7:CONNECT]
Mar 19 11:55:37.32: [18399]: --> [7:CONNECT]
Mar 19 11:55:37.88: [18399]: --> [2:OK]
Mar 19 11:55:37.88: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:55:44.89: [18399]: --> [0:]
Mar 19 11:55:44.89: [18399]: MODEM <Empty line>
Mar 19 11:55:44.94: [18399]: --> [2:OK]

Same as before.

Mar 19 11:55:44.94: [18399]: DELAY 1500 ms

Likewise.

Mar 19 11:55:46.44: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:55:46.49: [18399]: --> [7:CONNECT]
Mar 19 11:55:48.51: [18399]: --> [7:CONNECT]
Mar 19 11:55:49.34: [18399]: --> [7:CONNECT]
Mar 19 11:55:49.91: [18399]: --> [2:OK]
Mar 19 11:55:49.91: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:55:56.91: [18399]: --> [0:]
Mar 19 11:55:56.91: [18399]: MODEM <Empty line>
Mar 19 11:55:56.96: [18399]: --> [2:OK]
Mar 19 11:55:56.96: [18399]: DELAY 1500 ms

Repeat.

Mar 19 11:55:58.46: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:55:58.51: [18399]: --> [7:CONNECT]
Mar 19 11:56:00.53: [18399]: --> [7:CONNECT]
Mar 19 11:56:01.36: [18399]: --> [7:CONNECT]
Mar 19 11:56:01.93: [18399]: --> [2:OK]
Mar 19 11:56:01.93: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:56:07.30: [18399]: --> [7:CONNECT]
Mar 19 11:56:08.75: [18399]: --> [2:OK]
Mar 19 11:56:08.75: [18399]: REMOTE TSI "05XXXXXXX"

Perhaps by luck this time TSI is received.

Mar 19 11:56:08.75: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:56:08.76: [18399]: --> [7:CONNECT]
Mar 19 11:56:09.07: [18399]: --> [2:OK]
Mar 19 11:56:09.07: [18399]: REMOTE wants 9600 bit/s
Mar 19 11:56:09.07: [18399]: REMOTE wants A4 page width (215 mm)
Mar 19 11:56:09.07: [18399]: REMOTE wants unlimited page length
Mar 19 11:56:09.07: [18399]: REMOTE wants 3.85 line/mm
Mar 19 11:56:09.07: [18399]: REMOTE wants 2-D MR
Mar 19 11:56:09.07: [18399]: RECV training at v.29 9600 bit/s

DCS is received.

Mar 19 11:56:09.07: [18399]: <-- [10:AT+FRM=96\r]
Mar 19 11:56:09.45: [18399]: --> [7:CONNECT]
Mar 19 11:56:11.05: [18399]: RECV: TCF 1888 bytes, 3% non-zero, 1104 zero-run
Mar 19 11:56:11.05: [18399]: RECV: reject TCF (zero run too short, min 1200)
Mar 19 11:56:11.05: [18399]: --> [10:NO CARRIER]

But the TCF signal (training) is bad.

Mar 19 11:56:11.05: [18399]: DELAY 75 ms

Another software delay that is silly that shouldn't be there in 5.2.9.

Mar 19 11:56:11.12: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:56:11.17: [18399]: --> [7:CONNECT]
Mar 19 11:56:12.49: [18399]: --> [2:OK]
Mar 19 11:56:12.49: [18399]: TRAINING failed

FTT is signaled.

Mar 19 11:56:12.49: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:56:13.73: [18399]: --> [7:CONNECT]
Mar 19 11:56:15.18: [18399]: --> [2:OK]
Mar 19 11:56:15.18: [18399]: REMOTE TSI "05XXXXXXX"

TSI is received again as expected.

Mar 19 11:56:15.18: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:56:15.19: [18399]: --> [7:CONNECT]
Mar 19 11:56:15.50: [18399]: --> [2:OK]
Mar 19 11:56:15.50: [18399]: REMOTE wants 7200 bit/s
Mar 19 11:56:15.50: [18399]: REMOTE wants A4 page width (215 mm)
Mar 19 11:56:15.50: [18399]: REMOTE wants unlimited page length
Mar 19 11:56:15.50: [18399]: REMOTE wants 3.85 line/mm
Mar 19 11:56:15.50: [18399]: REMOTE wants 2-D MR
Mar 19 11:56:15.50: [18399]: RECV training at v.29 7200 bit/s

DCS again (as expected).

Mar 19 11:56:15.50: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:56:15.88: [18399]: --> [7:CONNECT]
Mar 19 11:56:17.48: [18399]: RECV: TCF 1419 bytes, 2% non-zero, 1356 zero-run
Mar 19 11:56:17.48: [18399]: --> [10:NO CARRIER]

This time it's a good train.

Mar 19 11:56:17.48: [18399]: DELAY 75 ms

And another senseless software pause.

Mar 19 11:56:17.55: [18399]: TRAINING succeeded
Mar 19 11:56:17.56: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:56:17.60: [18399]: --> [7:CONNECT]
Mar 19 11:56:18.92: [18399]: --> [2:OK]
Mar 19 11:56:18.92: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:56:20.42: [18399]: --> [7:CONNECT]
Mar 19 11:56:20.42: [18399]: RECV: begin page
Mar 19 11:56:41.45: [18399]: RECV: 1156 total lines, 1 bad lines, 1 consecutive bad lines
Mar 19 11:56:41.45: [18399]: RECV: end page
Mar 19 11:56:41.45: [18399]: --> [10:NO CARRIER]

Good page.

Mar 19 11:56:41.45: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:56:41.94: [18399]: --> [7:CONNECT]
Mar 19 11:56:42.72: [18399]: --> [2:OK]
Mar 19 11:56:42.72: [18399]: RECV recv MPS (more pages, same document)

The log says enough.

Mar 19 11:56:42.72: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:56:42.94: [18399]: --> [2:OK]
Mar 19 11:56:42.94: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:56:43.09: [18399]: --> [7:CONNECT]
Mar 19 11:56:43.09: [18399]: RECV send MCF (message confirmation)

Page confirmed as received.

Mar 19 11:56:43.09: [18399]: RECV FAX (000020394): from 05XXXXXXX, page 1 in 1:19, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:56:44.41: [18399]: --> [2:OK]
Mar 19 11:56:44.41: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:56:45.96: [18399]: --> [7:CONNECT]
Mar 19 11:56:45.96: [18399]: RECV: begin page
Mar 19 11:57:01.12: [18399]: RECV: 1113 total lines, 9 bad lines, 3 consecutive bad lines
Mar 19 11:57:01.12: [18399]: RECV: end page
Mar 19 11:57:01.12: [18399]: --> [10:NO CARRIER]

Another page received, not bad.

Mar 19 11:57:01.12: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:57:01.57: [18399]: --> [7:CONNECT]
Mar 19 11:57:02.41: [18399]: --> [2:OK]
Mar 19 11:57:02.41: [18399]: RECV recv MPS (more pages, same document)
Mar 19 11:57:02.41: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:57:02.63: [18399]: --> [2:OK]
Mar 19 11:57:02.63: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:57:02.78: [18399]: --> [7:CONNECT]
Mar 19 11:57:02.78: [18399]: RECV send MCF (message confirmation)
Mar 19 11:57:02.78: [18399]: RECV FAX (000020394): from 05XXXXXXX, page 2 in 0:20, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:57:04.09: [18399]: --> [2:OK]
Mar 19 11:57:04.09: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:57:05.84: [18399]: --> [7:CONNECT]
Mar 19 11:57:05.84: [18399]: RECV: begin page
Mar 19 11:57:15.85: [18399]: RECV: 853 total lines, 2 bad lines, 1 consecutive bad lines
Mar 19 11:57:15.85: [18399]: RECV: end page
Mar 19 11:57:15.85: [18399]: --> [10:NO CARRIER]

And another page.

Mar 19 11:57:15.85: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:57:16.34: [18399]: --> [7:CONNECT]
Mar 19 11:57:17.12: [18399]: --> [2:OK]
Mar 19 11:57:17.12: [18399]: RECV recv MPS (more pages, same document)
Mar 19 11:57:17.12: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:57:17.34: [18399]: --> [2:OK]
Mar 19 11:57:17.34: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:57:17.49: [18399]: --> [7:CONNECT]
Mar 19 11:57:17.49: [18399]: RECV send MCF (message confirmation)
Mar 19 11:57:17.49: [18399]: RECV FAX (000020394): from 05XXXXXXXX, page 3 in 0:14, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:57:18.80: [18399]: --> [2:OK]
Mar 19 11:57:18.80: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:57:20.32: [18399]: --> [7:CONNECT]
Mar 19 11:57:20.32: [18399]: RECV: begin page
Mar 19 11:57:39.24: [18399]: RECV: 1126 total lines, 7 bad lines, 4 consecutive bad lines
Mar 19 11:57:39.24: [18399]: RECV: end page
Mar 19 11:57:39.24: [18399]: --> [10:NO CARRIER]

Yawn. Another page.

Mar 19 11:57:39.24: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:57:39.73: [18399]: --> [7:CONNECT]
Mar 19 11:57:40.62: [18399]: --> [2:OK]
Mar 19 11:57:40.62: [18399]: RECV recv MPS (more pages, same document)
Mar 19 11:57:40.62: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:57:40.84: [18399]: --> [2:OK]
Mar 19 11:57:40.84: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:57:40.99: [18399]: --> [7:CONNECT]
Mar 19 11:57:40.99: [18399]: RECV send MCF (message confirmation)
Mar 19 11:57:40.99: [18399]: RECV FAX (000020394): from 05XXXXXXX, page 4 in 0:24, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:57:42.31: [18399]: --> [2:OK]
Mar 19 11:57:42.31: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:57:43.92: [18399]: --> [7:CONNECT]
Mar 19 11:57:43.92: [18399]: RECV: begin page
Mar 19 11:57:56.01: [18399]: RECV: 1128 total lines, 5 bad lines, 4 consecutive bad lines
Mar 19 11:57:56.01: [18399]: RECV: end page
Mar 19 11:57:56.01: [18399]: --> [10:NO CARRIER]

...

Mar 19 11:57:56.01: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:57:56.49: [18399]: --> [7:CONNECT]
Mar 19 11:57:57.30: [18399]: --> [2:OK]
Mar 19 11:57:57.30: [18399]: RECV recv MPS (more pages, same document)
Mar 19 11:57:57.30: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:57:57.52: [18399]: --> [2:OK]
Mar 19 11:57:57.52: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:57:57.67: [18399]: --> [7:CONNECT]
Mar 19 11:57:57.67: [18399]: RECV send MCF (message confirmation)
Mar 19 11:57:57.67: [18399]: RECV FAX (000020394): from 05XXXXXX, page 5 in 0:17, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:57:58.99: [18399]: --> [2:OK]
Mar 19 11:57:58.99: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:58:00.48: [18399]: --> [7:CONNECT]
Mar 19 11:58:00.48: [18399]: RECV: begin page
Mar 19 11:58:23.46: [18399]: RECV: 1123 total lines, 6 bad lines, 2 consecutive bad lines
Mar 19 11:58:23.46: [18399]: RECV: end page
Mar 19 11:58:23.46: [18399]: --> [10:NO CARRIER]

:-)

Mar 19 11:58:23.46: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:58:23.95: [18399]: --> [7:CONNECT]
Mar 19 11:58:24.74: [18399]: --> [2:OK]
Mar 19 11:58:24.74: [18399]: RECV recv MPS (more pages, same document)
Mar 19 11:58:24.74: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:58:24.96: [18399]: --> [2:OK]
Mar 19 11:58:24.96: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:58:25.11: [18399]: --> [7:CONNECT]
Mar 19 11:58:25.11: [18399]: RECV send MCF (message confirmation)
Mar 19 11:58:25.11: [18399]: RECV FAX (000020394): from 05XXXXXX, page 6 in 0:27, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:58:26.43: [18399]: --> [2:OK]
Mar 19 11:58:26.43: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:58:27.90: [18399]: --> [7:CONNECT]
Mar 19 11:58:27.90: [18399]: RECV: begin page
Mar 19 11:58:46.86: [18399]: RECV: 1120 total lines, 12 bad lines, 3 consecutive bad lines
Mar 19 11:58:46.86: [18399]: RECV: end page
Mar 19 11:58:46.86: [18399]: --> [10:NO CARRIER]

8-)

Mar 19 11:58:46.86: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:58:47.35: [18399]: --> [7:CONNECT]
Mar 19 11:58:48.14: [18399]: --> [2:OK]
Mar 19 11:58:48.14: [18399]: RECV recv MPS (more pages, same document)
Mar 19 11:58:48.14: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:58:48.36: [18399]: --> [2:OK]
Mar 19 11:58:48.36: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:58:48.51: [18399]: --> [7:CONNECT]
Mar 19 11:58:48.51: [18399]: RECV send MCF (message confirmation)
Mar 19 11:58:48.51: [18399]: RECV FAX (000020394): from 05XXXXXX, page 7 in 0:23, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:58:49.82: [18399]: --> [2:OK]
Mar 19 11:58:49.82: [18399]: <-- [10:AT+FRM=72\r]
Mar 19 11:58:51.29: [18399]: --> [7:CONNECT]
Mar 19 11:58:51.29: [18399]: RECV: begin page
Mar 19 11:59:10.99: [18399]: RECV: 1112 total lines, 12 bad lines, 7 consecutive bad lines
Mar 19 11:59:10.99: [18399]: RECV: REJECT page quality, 7-line run (max 5)
Mar 19 11:59:10.99: [18399]: RECV: end page
Mar 19 11:59:11.09: [18399]: --> [10:NO CARRIER]

This page had errors that exceeded the quality thresholds (specifically the max-bad-consecutive-lines). So the page quality will be rejected with RTN, forcing the sender to retrain. Don't read anything else into this signal. It does not confirm the page. But it also does not deny confirmation. It does not require retransmission. But it also does not prevent retransmission. What the sender does with the RTN signal (a signal that merely says "the page quality is unacceptable") is completely up to it. See "BadPageHandlingMethod" in 5.2.9 in the hylafax-config man page.

Mar 19 11:59:11.09: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:59:11.57: [18399]: --> [7:CONNECT]
Mar 19 11:59:12.38: [18399]: --> [2:OK]
Mar 19 11:59:12.38: [18399]: RECV recv MPS (more pages, same document)
Mar 19 11:59:12.38: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:59:12.60: [18399]: --> [2:OK]
Mar 19 11:59:12.60: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:59:12.75: [18399]: --> [7:CONNECT]
Mar 19 11:59:14.06: [18399]: --> [2:OK]
Mar 19 11:59:14.06: [18399]: RECV send RTN (retrain negative)

There we send RTN.

Mar 19 11:59:14.06: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:59:15.30: [18399]: --> [7:CONNECT]
Mar 19 11:59:16.35: [18399]: --> [5:ERROR]
Mar 19 11:59:16.35: [18399]: MODEM Command error
Mar 19 11:59:16.35: [18399]: FCS error

This means that the modem detected a signal from the sender but that it was corrupted (bad audio maybe).

Mar 19 11:59:16.35: [18399]: <-- [9:AT+FRS=7\r]
Mar 19 11:59:16.57: [18399]: --> [2:OK]
Mar 19 11:59:16.57: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:59:16.72: [18399]: --> [7:CONNECT]
Mar 19 11:59:18.03: [18399]: --> [2:OK]
Mar 19 11:59:18.03: [18399]: RECV send CRP (command repeat)

We send CRP to try to get the sender to repeat itself. (Which is probably going to be ineffective, and which is not likely done in this case with 5.2.9.)

Mar 19 11:59:18.03: [18399]: <-- [9:AT+FRH=3\r]
Mar 19 11:59:18.51: [18399]: --> [7:CONNECT]
Mar 19 11:59:24.26: [18399]: --> [2:OK]

Although it's not stated, DCN (disconnect) was probably received here. It would seem that the sender either did not like our CRP or it is giving up.

Mar 19 11:59:24.26: [18399]: RECV keeping unconfirmed page
Mar 19 11:59:24.26: [18399]: RECV FAX (000020394): from 05XXXXXXXX, page 8 in 0:24, INF, 3.85 line/mm, 2-D MR, 7200 bit/s
Mar 19 11:59:24.26: [18399]: RECV FAX (000020394): recvq/fax000013966.tif from 05XXXXXX, route to <unspecified>, 8 pages in 4:02
Mar 19 11:59:24.27: [18399]: RECV FAX: T.30 T2 timeout, expected page not received
Mar 19 11:59:24.27: [18399]: <-- [9:AT+FTH=3\r]
Mar 19 11:59:24.41: [18399]: --> [7:CONNECT]
Mar 19 11:59:25.73: [18399]: --> [2:OK]

This is us sending DCN... which is silly, and which is not likely done with 5.2.9.

Mar 19 11:59:25.73: [18399]: RECV FAX (000020394): session with 05XXXXXX terminated abnormally: T.30 T2 timeout, expected page not received
Mar 19 11:59:25.73: [18399]: RECV FAX: bin/faxrcvd "recvq/fax000013966.tif" "ttyS0" "000020394" "T.30 T2 timeout, expected page not received"
Mar 19 11:59:25.74: [18399]: RECV FAX: end
Mar 19 11:59:25.74: [18399]: SESSION END

The end.

Thanks,

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