[hylafax-users] Various errors to one number (T.30 T1 timeout, MPS, unknown frame)

["Walter Stanish" <walter@xxxxxxxxxxxxxxxxxxx>]

Hi there,

Our hylafax install is going well but we hit upon a number we
can't send to today.

Attached are logs, we variously receive messages like:
 - T.30 T1 Timeout
 - No response to MPS repeated 3 tries
 - Fax protocol error (unknown frame received)
 - Remote fax disconnected prematurely

The first contact we had with this number was a failed receive.

That trace is here:
================================================
Dec 12 11:42:10.07: [25684]: SESSION BEGIN 000001568 +868718052088
Dec 12 11:42:10.07: [25684]: HylaFAX (tm) Version 5.2.2
Dec 12 11:42:10.07: [25684]: CallID: '075582323458' '' '<NONE>' 'fax'
Dec 12 11:42:10.07: [25684]: MODEM set XON/XOFF/FLUSH: input ignored,
output disabled
Dec 12 11:42:10.07: [25684]: <-- [4:ATA\r]
Dec 12 11:42:13.80: [25684]: --> [7:CONNECT]
Dec 12 11:42:13.80: [25684]: ANSWER: FAX CONNECTION  DEVICE '/dev/iaxmodem1'
Dec 12 11:42:13.80: [25684]: STATE CHANGE: ANSWERING -> RECEIVING
Dec 12 11:42:13.80: [25684]: RECV FAX: begin
Dec 12 11:42:13.80: [25684]: <-- HDLC<32:FF C0 04 B5 00 AA 12 9E 36 86
62 82 1A 04 14 2E B6 94 04 6A A6 4E CE 96 F6 76 04 AC 74 4C 74 4C>
Dec 12 11:42:13.80: [25684]: <-- data [32]
Dec 12 11:42:13.80: [25684]: <-- data [2]
Dec 12 11:42:14.76: [25684]: --> [7:CONNECT]
Dec 12 11:42:14.76: [25684]: <-- HDLC<23:FF C0 02 CE B6 A6 2E CE 9E CA
04 2E 76 A6 26 96 C6 C6 F2 04 04 04 04>
Dec 12 11:42:14.76: [25684]: <-- data [23]
Dec 12 11:42:14.76: [25684]: <-- data [2]
Dec 12 11:42:15.50: [25684]: --> [7:CONNECT]
Dec 12 11:42:15.50: [25684]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
Dec 12 11:42:15.50: [25684]: <-- data [13]
Dec 12 11:42:15.50: [25684]: <-- data [2]
Dec 12 11:42:16.08: [25684]: --> [2:OK]
Dec 12 11:42:16.08: [25684]: <-- [9:AT+FRH=3\r]
Dec 12 11:42:16.70: [25684]: --> [7:CONNECT]
Dec 12 11:42:18.28: [25684]: --> HDLC<25:FF C0 C2 04 04 04 04 04 04 04
04 04 04 04 04 04 04 04 04 04 65 37 0D E4 DD>
Dec 12 11:42:18.28: [25684]: --> [2:OK]
Dec 12 11:42:18.28: [25684]: RECV recv TSI (sender id)
Dec 12 11:42:18.28: [25684]: REMOTE TSI ""
Dec 12 11:42:18.28: [25684]: <-- [9:AT+FRH=3\r]
Dec 12 11:42:18.60: [25684]: --> [7:CONNECT]
Dec 12 11:42:18.60: [25684]: --> HDLC<9:FF C8 C1 00 46 1F 00 3D 9B>
Dec 12 11:42:18.72: [25684]: --> [2:OK]
Dec 12 11:42:18.72: [25684]: RECV recv DCS (command signal)
Dec 12 11:42:18.72: [25684]: REMOTE wants 14400 bit/s
Dec 12 11:42:18.72: [25684]: REMOTE wants A4 page width (215 mm)
Dec 12 11:42:18.72: [25684]: REMOTE wants unlimited page length
Dec 12 11:42:18.72: [25684]: REMOTE wants 7.7 line/mm
Dec 12 11:42:18.72: [25684]: REMOTE wants 1-D MH
Dec 12 11:42:18.72: [25684]: RECV training at v.17 14400 bit/s
Dec 12 11:42:18.72: [25684]: MODEM set XON/XOFF/DRAIN: input ignored,
output generated
Dec 12 11:42:18.72: [25684]: <-- [11:AT+FRM=145\r]
Dec 12 11:42:20.62: [25684]: --> [7:CONNECT]
Dec 12 11:42:22.20: [25684]: MODEM set XON/XOFF/DRAIN: input ignored,
output disabled
Dec 12 11:42:22.20: [25684]: RECV: TCF 2826 bytes, 1% non-zero, 2779 zero-run
Dec 12 11:42:22.20: [25684]: --> [10:NO CARRIER]
Dec 12 11:42:22.20: [25684]: <-- [9:AT+FRS=7\r]
Dec 12 11:42:22.26: [25684]: --> [2:OK]
Dec 12 11:42:22.26: [25684]: TRAINING succeeded
Dec 12 11:42:22.26: [25684]: <-- [9:AT+FTH=3\r]
Dec 12 11:42:22.28: [25684]: --> [7:CONNECT]
Dec 12 11:42:22.28: [25684]: <-- HDLC<3:FF C8 21>
Dec 12 11:42:22.28: [25684]: <-- data [3]
Dec 12 11:42:22.28: [25684]: <-- data [2]
Dec 12 11:42:23.36: [25684]: --> [2:OK]
Dec 12 11:42:23.36: [25684]: <-- [11:AT+FRM=146\r]
Dec 12 11:42:23.98: [25684]: --> [7:CONNECT]
Dec 12 11:42:23.98: [25684]: MODEM input buffering enabled
Dec 12 11:42:23.98: [25684]: MODEM set XON/XOFF/FLUSH: input ignored,
output generated
Dec 12 11:42:23.98: [25684]: RECV: begin page
Dec 12 11:42:53.10: [25684]: RECV/CQ: Bad 1D pixel count, row 2291,
got 0, expected 1728
Dec 12 11:42:53.10: [25684]: RECV/CQ: Bad 1D pixel count, row 2292,
got 0, expected 1728
Dec 12 11:42:53.10: [25684]: RECV/CQ: Bad 1D pixel count, row 2293,
got 0, expected 1728
Dec 12 11:42:53.10: [25684]: RECV/CQ: Bad 1D pixel count, row 2294,
got 0, expected 1728
Dec 12 11:42:53.26: [25684]: RECV/CQ: Adjusting for RTC found at row 2291
Dec 12 11:42:53.26: [25684]: RECV: 2291 total lines, 0 bad lines, 0
consecutive bad lines
Dec 12 11:42:53.26: [25684]: RECV: end page
Dec 12 11:42:53.26: [25684]: --> [10:NO CARRIER]
Dec 12 11:42:53.26: [25684]: <-- [9:AT+FRH=3\r]
Dec 12 11:42:53.56: [25684]: --> [7:CONNECT]
Dec 12 11:42:54.62: [25684]: --> HDLC<5:FF C8 F2 AC A0>
Dec 12 11:42:54.72: [25684]: --> [2:OK]
Dec 12 11:42:54.72: [25684]: RECV recv MPS (more pages, same document)
Dec 12 11:42:54.72: [25684]: <-- [9:AT+FRS=7\r]
Dec 12 11:42:54.82: [25684]: --> [2:OK]
Dec 12 11:42:54.82: [25684]: RECV send MCF (message confirmation)
Dec 12 11:42:54.82: [25684]: <-- [9:AT+FTH=3\r]
Dec 12 11:42:54.92: [25684]: --> [7:CONNECT]
Dec 12 11:42:54.92: [25684]: RECV FAX (000001568): from , page 1 in
0:00:40, INF, 7.7 line/mm, 1-D MH, 14400 bit/s
Dec 12 11:42:54.92: [25684]: <-- HDLC<3:FF C8 31>
Dec 12 11:42:54.92: [25684]: <-- data [3]
Dec 12 11:42:54.92: [25684]: <-- data [2]
Dec 12 11:42:56.00: [25684]: --> [2:OK]
Dec 12 11:42:56.00: [25684]: <-- [11:AT+FRM=146\r]
Dec 12 11:42:56.58: [25684]: --> [7:CONNECT]
Dec 12 11:42:56.58: [25684]: MODEM set XON/XOFF/FLUSH: input ignored,
output generated
Dec 12 11:42:56.58: [25684]: RECV: begin page
Dec 12 11:43:25.54: [25684]: RECV/CQ: Bad 1D pixel count, row 2291,
got 0, expected 1728
Dec 12 11:43:25.54: [25684]: RECV/CQ: Bad 1D pixel count, row 2292,
got 0, expected 1728
Dec 12 11:43:25.54: [25684]: RECV/CQ: Bad 1D pixel count, row 2293,
got 0, expected 1728
Dec 12 11:43:25.54: [25684]: RECV/CQ: Bad 1D pixel count, row 2294,
got 0, expected 1728
Dec 12 11:43:25.54: [25684]: RECV/CQ: Adjusting for RTC found at row 2291
Dec 12 11:43:25.54: [25684]: RECV: 2291 total lines, 0 bad lines, 0
consecutive bad lines
Dec 12 11:43:25.54: [25684]: RECV: end page
Dec 12 11:43:25.64: [25684]: --> [10:NO CARRIER]
Dec 12 11:43:25.64: [25684]: <-- [9:AT+FRH=3\r]
Dec 12 11:43:25.94: [25684]: --> [7:CONNECT]
Dec 12 11:43:26.98: [25684]: --> HDLC<5:FF C8 F4 CC 66>
Dec 12 11:43:27.10: [25684]: --> [2:OK]
Dec 12 11:43:27.10: [25684]: RECV recv EOP (no more pages or documents)
Dec 12 11:43:27.10: [25684]: <-- [9:AT+FRS=7\r]
Dec 12 11:43:27.20: [25684]: --> [2:OK]
Dec 12 11:43:27.20: [25684]: RECV send MCF (message confirmation)
Dec 12 11:43:27.20: [25684]: <-- [9:AT+FTH=3\r]
Dec 12 11:43:27.30: [25684]: --> [7:CONNECT]
Dec 12 11:43:27.30: [25684]: <-- HDLC<3:FF C8 31>
Dec 12 11:43:27.30: [25684]: <-- data [3]
Dec 12 11:43:27.30: [25684]: <-- data [2]
Dec 12 11:43:28.38: [25684]: --> [2:OK]
Dec 12 11:43:28.38: [25684]: <-- [9:AT+FRH=3\r]
Dec 12 11:43:29.02: [25684]: --> [7:CONNECT]
Dec 12 11:43:30.08: [25684]: --> HDLC<5:FF C8 DF 59 6F>
Dec 12 11:43:30.18: [25684]: --> [2:OK]
Dec 12 11:43:30.18: [25684]: RECV recv DCN (disconnect)
Dec 12 11:43:30.18: [25684]: RECV FAX (000001568): from , page 2 in
0:00:32, INF, 7.7 line/mm, 1-D MH, 14400 bit/s
Dec 12 11:43:31.19: [25684]: RECV FAX (000001568):
recvq/fax000000284.tif from , subaddress <unspecified>, 2 pages in
0:01:17
Dec 12 11:43:31.19: [25684]: RECV FAX: bin/faxrcvd
'recvq/fax000000284.tif' 'iaxmodem1' '000001568' '' '075582323458' ''
'<NONE>' 'fax'
Dec 12 11:43:31.20: [25684]: RECV FAX: end
Dec 12 11:43:31.20: [25684]: SESSION END
================================================

Attached are the traces for the failed, outgoing faxes.  Part-way through
I replaced the automatically generated info file for that number with a
stored, reduced-capabilities configuration, which is as follows.
This usually resolves issues, but in this case apparently made no
difference.
================================================
supportsVRes:1
supports2DEncoding:no
supportsMMR:no
hasV34Trouble:yes
hasV17Trouble:yes
senderHasV17Trouble:yes
senderSkipsV29:yes
supportsPostScript:no
supportsBatching:yes
calledBefore:yes
maxPageWidth:1728
maxPageLength:65535
maxSignallingRate:"14400"
minScanlineTime:"0ms"
remoteCSI:""
remoteNSF:""
remoteDIS:"00 76 1E"
sendFailures:0
lastSendFailure:"No response to MPS repeated 3 tries {E150}"
dialFailures:0
pagingProtocol:"ixo"
================================================

We are using hylafax-5.2.2 with iaxmodem-0.1.10 and
asterisk-1.4.22, via a AFT-A102c PCI T1/E1 card and
driver set wanpipe-3.3.14.6

Regards,
Walter Stanish
Owner / Director
Occident Systems
(+86 15808 700 801)

Attachment: fax-traces.tar.gz
Description: GNU Zip compressed data