Re: [hylafax-users] Modem Command Errors

[Horst Simon <hsimon@xxxxxxxxxxxxxxx>]

On Aug 22, 2004 12:42 AM, Lee Howard <faxguy@xxxxxxxxxxxxxxxx> wrote:
> 
> If this is completely reproducible then something is wrong with the 
> Optima 288.  It may, however, be a very limited problem.
> 
> Lee.
Hi Lee,

I have replaced the Optima 288 with an Optima 336 and now both ends have
the same modem. The failure is now different and every time the same
errors.
The log of the Sender:
Aug 23 09:15:49.63: [20961]: SESSION BEGIN 000000021 61395531624
Aug 23 09:15:49.63: [20961]: HylaFAX (tm) Version 4.2.0
Aug 23 09:15:49.63: [20961]: SEND FAX: JOB 14 DEST 95531624 COMMID
000000021 DEVICE '/dev/ttyS0'
Aug 23 09:15:49.63: [20961]: <-- [12:AT+FCLASS=1\r]
Aug 23 09:15:49.77: [20961]: --> [2:OK]
Aug 23 09:15:49.77: [20961]: DIAL 95531624
Aug 23 09:15:49.77: [20961]: <-- [13:ATDT95531624\r]
Aug 23 09:16:23.17: [20961]: --> [7:CONNECT]
Aug 23 09:16:24.91: [20961]: --> [2:OK]
Aug 23 09:16:24.91: [20961]: REMOTE NSF "B5 00 AA 48 79 6C 61 46 41 58
20 28 74 6D 29 20 56 65 72 73 69 6F 6E 20 34 2E 32 2E 30"
Aug 23 09:16:24.91: [20961]: NSF remote fax equipment: HylaFAX 
Aug 23 09:16:24.91: [20961]: NSF remote station ID: "HylaFAX (tm)
Version 4.2.0"
Aug 23 09:16:24.91: [20961]: <-- [9:AT+FRH=3\r]
Aug 23 09:16:24.96: [20961]: --> [7:CONNECT]
Aug 23 09:16:25.60: [20961]: --> [2:OK]
Aug 23 09:16:25.60: [20961]: REMOTE CSI "HSC +61(0)3 95531624"
Aug 23 09:16:25.60: [20961]: <-- [9:AT+FRH=3\r]
Aug 23 09:16:25.64: [20961]: --> [7:CONNECT]
Aug 23 09:16:25.97: [20961]: --> [2:OK]
Aug 23 09:16:25.97: [20961]: REMOTE best rate 14400 bit/s
Aug 23 09:16:25.97: [20961]: REMOTE max A3 page width (303 mm)
Aug 23 09:16:25.97: [20961]: REMOTE max unlimited page length
Aug 23 09:16:25.97: [20961]: REMOTE best vres R16 x 15.4 line/mm
Aug 23 09:16:25.97: [20961]: REMOTE best format 2-D MMR
Aug 23 09:16:25.97: [20961]: REMOTE supports T.30 Annex A, 256-byte ECM
Aug 23 09:16:25.97: [20961]: REMOTE best 0 ms/scanline
Aug 23 09:16:25.97: [20961]: USE 14400 bit/s
Aug 23 09:16:25.97: [20961]: USE error correction mode
Aug 23 09:16:25.97: [20961]: USE 0 ms/scanline
Aug 23 09:16:25.97: [20961]: SEND file "docq/doc14.ps;c0"
Aug 23 09:16:25.97: [20961]: USE A4 page width (215 mm)
Aug 23 09:16:25.97: [20961]: USE unlimited page length
Aug 23 09:16:25.97: [20961]: USE 3.85 line/mm
Aug 23 09:16:25.97: [20961]: USE 2-D MMR
Aug 23 09:16:25.97: [20961]: SEND training at v.17 14400 bit/s
Aug 23 09:16:25.97: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:26.11: [20961]: --> [7:CONNECT]
Aug 23 09:16:26.11: [20961]: <-- data [23]
Aug 23 09:16:26.11: [20961]: <-- data [2]
Aug 23 09:16:27.10: [20961]: --> [7:CONNECT]
Aug 23 09:16:27.10: [20961]: <-- data [7]
Aug 23 09:16:27.10: [20961]: <-- data [2]
Aug 23 09:16:28.14: [20961]: --> [2:OK]
Aug 23 09:16:28.14: [20961]: <-- [9:AT+FTS=7\r]
Aug 23 09:16:28.25: [20961]: --> [2:OK]
Aug 23 09:16:28.25: [20961]: <-- [11:AT+FTM=145\r]
Aug 23 09:16:28.31: [20961]: --> [7:CONNECT]
Aug 23 09:16:28.31: [20961]: <-- data [1024]
Aug 23 09:16:29.92: [20961]: <-- data [1024]
Aug 23 09:16:30.31: [20961]: <-- data [652]
Aug 23 09:16:30.71: [20961]: <-- data [2]
Aug 23 09:16:31.23: [20961]: --> [2:  ]
Aug 23 09:16:31.23: [20961]: Problem sending TCF data
Aug 23 09:16:31.23: [20961]: <-- [9:AT+FRH=3\r]
Aug 23 09:16:31.23: [20961]: --> [2:OK]
Aug 23 09:16:31.23: [20961]: DELAY 1500 ms
Aug 23 09:16:32.73: [20961]: SEND training at v.17 12000 bit/s
Aug 23 09:16:32.73: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:32.73: [20961]: --> [7:CONNECT]
Aug 23 09:16:32.73: [20961]: <-- data [23]
Aug 23 09:16:32.73: [20961]: <-- data [2]
Aug 23 09:16:32.74: [20961]: --> [2:OK]
Aug 23 09:16:32.74: [20961]: Error sending T.30 prologue frames
Aug 23 09:16:32.74: [20961]: SEND training at v.17 9600 bit/s
Aug 23 09:16:32.74: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:35.29: [20961]: Error sending T.30 prologue frames
Aug 23 09:16:35.29: [20961]: SEND training at v.29 9600 bit/s
Aug 23 09:16:35.29: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:35.38: [20961]: --> [7:CONNECT]
Aug 23 09:16:35.38: [20961]: <-- data [23]
Aug 23 09:16:35.38: [20961]: <-- data [2]
Aug 23 09:16:36.37: [20961]: --> [7:CONNECT]
Aug 23 09:16:36.37: [20961]: <-- data [7]
Aug 23 09:16:36.37: [20961]: <-- data [2]
Aug 23 09:16:37.41: [20961]: --> [2:OK]
Aug 23 09:16:37.41: [20961]: <-- [9:AT+FTS=7\r]
Aug 23 09:16:37.52: [20961]: --> [2:OK]
Aug 23 09:16:37.52: [20961]: <-- [10:AT+FTM=96\r]
Aug 23 09:16:37.58: [20961]: --> [7:CONNECT]
Aug 23 09:16:37.58: [20961]: <-- data [1024]
Aug 23 09:16:37.97: [20961]: <-- data [776]
Aug 23 09:16:38.48: [20961]: <-- data [2]
Aug 23 09:16:39.37: [20961]: --> [2:  ]
Aug 23 09:16:39.37: [20961]: Problem sending TCF data
Aug 23 09:16:39.37: [20961]: <-- [9:AT+FRH=3\r]
Aug 23 09:16:39.37: [20961]: --> [2:OK]
Aug 23 09:16:39.37: [20961]: DELAY 1500 ms
Aug 23 09:16:40.87: [20961]: SEND training at v.29 7200 bit/s
Aug 23 09:16:40.87: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:40.87: [20961]: --> [7:CONNECT]
Aug 23 09:16:40.87: [20961]: <-- data [23]
Aug 23 09:16:40.87: [20961]: <-- data [2]
Aug 23 09:16:40.87: [20961]: --> [2:OK]
Aug 23 09:16:40.87: [20961]: Error sending T.30 prologue frames
Aug 23 09:16:40.87: [20961]: SEND training at v.27ter 4800 bit/s
Aug 23 09:16:40.87: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:43.42: [20961]: Error sending T.30 prologue frames
Aug 23 09:16:43.42: [20961]: SEND training at v.27ter fallback mode 2400
bit/s
Aug 23 09:16:43.42: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:43.51: [20961]: --> [7:CONNECT]
Aug 23 09:16:43.51: [20961]: <-- data [23]
Aug 23 09:16:43.51: [20961]: <-- data [2]
Aug 23 09:16:44.51: [20961]: --> [7:CONNECT]
Aug 23 09:16:44.51: [20961]: <-- data [7]
Aug 23 09:16:44.51: [20961]: <-- data [2]
Aug 23 09:16:45.54: [20961]: --> [2:OK]
Aug 23 09:16:45.54: [20961]: <-- [9:AT+FTS=7\r]
Aug 23 09:16:45.65: [20961]: --> [2:OK]
Aug 23 09:16:45.65: [20961]: <-- [10:AT+FTM=24\r]
Aug 23 09:16:45.76: [20961]: --> [7:CONNECT]
Aug 23 09:16:45.76: [20961]: <-- data [450]
Aug 23 09:16:45.76: [20961]: <-- data [2]
Aug 23 09:16:48.24: [20961]: --> [2:OK]
Aug 23 09:16:48.24: [20961]: <-- [9:AT+FRH=3\r]
Aug 23 09:16:51.34: [20961]: --> [0:]
Aug 23 09:16:51.34: [20961]: MODEM <Empty line>
Aug 23 09:16:51.34: [20961]: <-- data [1]
Aug 23 09:16:51.36: [20961]: --> [2:OK]
Aug 23 09:16:51.36: [20961]: DELAY 1500 ms
Aug 23 09:16:52.86: [20961]: TRAINING failed
Aug 23 09:16:52.86: [20961]: <-- [9:AT+FTH=3\r]
Aug 23 09:16:52.95: [20961]: --> [7:CONNECT]
Aug 23 09:16:52.95: [20961]: <-- data [3]
Aug 23 09:16:52.95: [20961]: <-- data [2]
Aug 23 09:16:54.17: [20961]: --> [2:OK]
Aug 23 09:16:54.17: [20961]: <-- [5:ATH0\r]
Aug 23 09:16:54.92: [20961]: --> [2:OK]
Aug 23 09:16:54.92: [20961]: SESSION END

The Log of the Receiver:
recvq/fax000000020.tif (ftp://neptune:4559/recvq/fax000000020.tif): 
 Could not open recvq/fax000000020.tif; either not TIFF or corrupted. 
 ReceivedOn: ttyS1 
 
 The full document was not received because: 
 
 COMREC invalid response received (expected PPS) 
 
 ---- Transcript of session follows ---- 
 
 Aug 23 09:16:15.63: [ 2080]: SESSION BEGIN 000000024 61395531624 
 Aug 23 09:16:15.63: [ 2080]: HylaFAX (tm) Version 4.2.0 
 Aug 23 09:16:15.63: [ 2080]: <-- [4:ATA\r] 
 Aug 23 09:16:23.01: [ 2080]: --> [7:CONNECT] 
Aug 23 09:16:23.01: [ 2080]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyS1'
 Aug 23 09:16:23.01: [ 2080]: RECV FAX: begin 
 Aug 23 09:16:23.91: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:23.94: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:25.97: [ 2080]: --> [2:OK] 
 Aug 23 09:16:25.97: [ 2080]: <-- [9:AT+FRH=3\r] 
 Aug 23 09:16:26.27: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:27.89: [ 2080]: --> [2:OK] 
 Aug 23 09:16:27.89: [ 2080]: REMOTE TSI "Horstpc1 9621-2535" 
 Aug 23 09:16:27.89: [ 2080]: <-- [9:AT+FRH=3\r] 
 Aug 23 09:16:27.93: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:28.17: [ 2080]: --> [2:OK] 
 Aug 23 09:16:28.17: [ 2080]: REMOTE wants 14400 bit/s 
 Aug 23 09:16:28.17: [ 2080]: REMOTE wants A4 page width (215 mm) 
 Aug 23 09:16:28.17: [ 2080]: REMOTE wants unlimited page length 
 Aug 23 09:16:28.17: [ 2080]: REMOTE wants 3.85 line/mm 
 Aug 23 09:16:28.17: [ 2080]: REMOTE wants 2-D MMR 
 Aug 23 09:16:28.17: [ 2080]: REMOTE wants T.30 Annex A, 256-byte ECM 
 Aug 23 09:16:28.17: [ 2080]: RECV training at v.17 14400 bit/s 
 Aug 23 09:16:28.17: [ 2080]: <-- [11:AT+FRM=145\r] 
 Aug 23 09:16:29.73: [ 2080]: --> [7:CONNECT] 
Aug 23 09:16:31.47: [ 2080]: RECV: TCF 2798 bytes, 14% non-zero, 289
 zero-run
Aug 23 09:16:31.47: [ 2080]: RECV: reject TCF (too many non-zero, max
 10%)
Aug 23 09:16:31.47: [ 2080]: RECV: reject TCF (zero run too short, min
 1800)
 Aug 23 09:16:31.68: [ 2080]: --> [10:NO CARRIER] 
 Aug 23 09:16:31.68: [ 2080]: DELAY 75 ms 
 Aug 23 09:16:31.76: [ 2080]: <-- [9:AT+FTH=3\r] 
 Aug 23 09:16:31.84: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:33.07: [ 2080]: --> [2:OK] 
 Aug 23 09:16:33.07: [ 2080]: TRAINING failed 
 Aug 23 09:16:33.07: [ 2080]: <-- [9:AT+FRH=3\r] 
 Aug 23 09:16:35.54: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:37.15: [ 2080]: --> [2:OK] 
 Aug 23 09:16:37.15: [ 2080]: REMOTE TSI "Horstpc1 9621-2535" 
 Aug 23 09:16:37.15: [ 2080]: <-- [9:AT+FRH=3\r] 
 Aug 23 09:16:37.19: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:37.43: [ 2080]: --> [2:OK] 
 Aug 23 09:16:37.43: [ 2080]: REMOTE wants 9600 bit/s 
 Aug 23 09:16:37.43: [ 2080]: REMOTE wants A4 page width (215 mm) 
 Aug 23 09:16:37.43: [ 2080]: REMOTE wants unlimited page length 
 Aug 23 09:16:37.43: [ 2080]: REMOTE wants 3.85 line/mm 
 Aug 23 09:16:37.43: [ 2080]: REMOTE wants 2-D MMR 
 Aug 23 09:16:37.43: [ 2080]: REMOTE wants T.30 Annex A, 256-byte ECM 
 Aug 23 09:16:37.43: [ 2080]: RECV training at v.29 9600 bit/s 
 Aug 23 09:16:37.43: [ 2080]: <-- [10:AT+FRM=96\r] 
 Aug 23 09:16:37.86: [ 2080]: --> [7:CONNECT] 
Aug 23 09:16:39.63: [ 2080]: RECV: TCF 1892 bytes, 4% non-zero, 1322
 zero-run
 Aug 23 09:16:39.63: [ 2080]: --> [10:NO CARRIER] 
 Aug 23 09:16:39.63: [ 2080]: DELAY 75 ms 
 Aug 23 09:16:39.71: [ 2080]: TRAINING succeeded 
 Aug 23 09:16:39.71: [ 2080]: <-- [9:AT+FTH=3\r] 
 Aug 23 09:16:39.79: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:41.02: [ 2080]: --> [2:OK] 
 Aug 23 09:16:41.02: [ 2080]: <-- [10:AT+FRM=96\r] 
 Aug 23 09:16:45.02: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:45.03: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.03: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.14: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.25: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.47: [ 2080]: HDLC frame with bad address field 0xe3 
 Aug 23 09:16:45.47: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.57: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.58: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.58: [ 2080]: Bad HDLC terminating flag received. 
 Aug 23 09:16:45.91: [ 2080]: RECV assumed RCP frame with block end 
 Aug 23 09:16:45.92: [ 2080]: --> [10:NO CARRIER] 
 Aug 23 09:16:45.92: [ 2080]: <-- [9:AT+FRH=3\r] 
 Aug 23 09:16:46.13: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:48.34: [ 2080]: --> [5:ERROR] 
 Aug 23 09:16:48.34: [ 2080]: MODEM Command error 
 Aug 23 09:16:48.34: [ 2080]: FCS error 
 Aug 23 09:16:48.34: [ 2080]: <-- [9:AT+FRH=3\r] 
 Aug 23 09:16:53.10: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:54.17: [ 2080]: --> [2:OK] 
 Aug 23 09:16:54.17: [ 2080]: RECV recv DCN (disconnect) 
Aug 23 09:16:54.17: [ 2080]: RECV FAX (000000024): from Horstpc1
 9621-2535, page 1 in 0:15, INF, 3.85 line/mm, 2-D MMR, 9600 bit/s
Aug 23 09:16:54.17: [ 2080]: RECV FAX (000000024):
 recvq/fax000000020.tif from Horstpc1 9621-2535, route to <unspecified>,
 1 pages in 0:31
Aug 23 09:16:54.18: [ 2080]: RECV FAX: COMREC invalid response received
 (expected PPS)
 Aug 23 09:16:54.18: [ 2080]: <-- [9:AT+FTH=3\r] 
 Aug 23 09:16:54.30: [ 2080]: --> [7:CONNECT] 
 Aug 23 09:16:55.53: [ 2080]: --> [2:OK] 
Aug 23 09:16:55.53: [ 2080]: RECV FAX (000000024): session with Horstpc1
 9621-2535 terminated abnormally: COMREC invalid response received
 (expected PPS)
Aug 23 09:16:55.53: [ 2080]: RECV FAX: bin/faxrcvd
 "recvq/fax000000020.tif" "ttyS1" "000000024" "COMREC invalid response
 received (expected PPS)" "" ""
 Aug 23 09:16:55.56: [ 2080]: RECV FAX: end 

Regards,
Horst
 Aug 23 09:16:55.56: [ 2080]: SESSION END 


____________________ 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*