[hylafax-users] Failure to train remote modem at 2400 bps or minimum speed.

[Songtao Yu <yustao_2002@xxxxxxxxxxx>]

Hi All,

I used Asterisk + IAXModem+(Hylafax+)+Avantfax to send the fax to others. I have successfully set up one machine to send and receive faxes. But when I tried to run the same on the second machine, I always got the error as the title.

But when I used the same phone line to connect the first machine, I can send fax successfully. So the issue should NOT be related to the audio quality between the sender and receiver.

Apart from that, I used Asterisk 1.6 and Asterisk 1.8, Hylafax+5.5.0, Hylafax+ 5.4.2. Unfortunately, I got the same error. Below is the log:
==============================================================
Dec 30 20:57:56.04: [ 5725]: SESSION BEGIN 000000017 82593977
Dec 30 20:57:56.04: [ 5725]: HylaFAX (tm) Version 5.4.2
Dec 30 20:57:56.04: [ 5725]: SEND FAX: JOB 13 DEST 82593977 COMMID 000000017 DEVICE '/dev/ ttyIAX0' FROM 'root <root@xxxxxxxxx>' USER admin
Dec 30 20:57:56.04: [ 5725]: STATE CHANGE: RUNNING -> SENDING
Dec 30 20:57:56.04: [ 5725]: <-- [12:AT+FCLASS=1\r]
Dec 30 20:57:56.06: [ 5725]: --> [2:OK]
Dec 30 20:57:56.06: [ 5725]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled
Dec 30 20:57:56.07: [ 5725]: DIAL 82593977
Dec 30 20:57:56.07: [ 5725]: <-- [13:ATDT82593977\r]
Dec 30 20:58:12.53: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:12.65: [ 5725]: --> [10:NO CARRIER]
Dec 30 20:58:12.65: [ 5725]: MODEM No carrier
Dec 30 20:58:12.65: [ 5725]: <-- [10:AT+FRS=21\r]
Dec 30 20:58:15.33: [ 5725]: --> [2:OK]
Dec 30 20:58:15.33: [ 5725]: <-- [9:AT+FTH=3\r]
Dec 30 20:58:15.35: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:15.35: [ 5725]: <-- HDLC<3:FF C8 D8>
Dec 30 20:58:15.35: [ 5725]: <-- data [3]
Dec 30 20:58:15.35: [ 5725]: <-- data [2]
Dec 30 20:58:16.44: [ 5725]: --> [2:OK]
Dec 30 20:58:16.44: [ 5725]: SEND send CRP (command repeat)
Dec 30 20:58:16.44: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:17.29: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:18.67: [ 5725]: --> HDLC<16:FF C0 04 61 00 8D 00 00 64 13 02 0F C0 00 BB FE>
Dec 30 20:58:18.67: [ 5725]: --> [2:OK]
Dec 30 20:58:18.67: [ 5725]: REMOTE NSF "86 00 B1 00 00 26 C8 40 F0 03 00"
Dec 30 20:58:18.67: [ 5725]: NSF remote fax equipment: unknown
Dec 30 20:58:18.67: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:19.41: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:19.41: [ 5725]: --> HDLC<25:FF C0 02 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 A4 F3>
Dec 30 20:58:19.41: [ 5725]: --> [2:OK]
Dec 30 20:58:19.41: [ 5725]: REMOTE CSI ""
Dec 30 20:58:19.41: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:19.81: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:19.81: [ 5725]: --> HDLC<11:FF C8 01 00 77 15 01 01 C8 47 AF>
Dec 30 20: 58:19.90: [ 5725]: --> [2:OK]
Dec 30 20:58:19.90: [ 5725]: REMOTE best rate 14400 bit/s
Dec 30 20:58:19.90: [ 5725]: REMOTE max A4 page width (215 mm)
Dec 30 20:58:19.90: [ 5725]: REMOTE max unlimited page length
Dec 30 20:58:19.90: [ 5725]: REMOTE best vres 300 x 300 dpi
Dec 30 20:58:19.90: [ 5725]: REMOTE format support: MH, MR
Dec 30 20:58:19.90: [ 5725]: REMOTE best 10 ms/scanline
Dec 30 20:58:19.90: [ 5725]: USE 14400 bit/s
Dec 30 20:58:19.90: [ 5725]: SEND file "docq/doc13.pdf;1ce0"
Dec 30 20:58:19.90: [ 5725]: USE A4 page width (215 mm)
Dec 30 20:58:19.90: [ 5725]: USE unlimited page length
Dec 30 20:58:19.90: [ 5725]: USE 3.85 line/mm
Dec 30 20:58:19.90: [ 5725]: USE 2-D MR
Dec 30 20:58:19.90: [ 5725]: USE 10 ms/scanline
Dec 30 20:58:19.90: [ 5725]: SEND training at v.17 14400 bit/s
Dec 30 20:58:19.90: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:19.96: [ 5725]: --> [2:OK]
Dec 30 20:58:19.96: [ 5725]: <-- [9: AT+FTH=3\r]
Dec 30 20:58:19.98: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:19.98: [ 5725]: <-- HDLC<23:FF C0 C2 76 96 86 EA A6 76 96 16 CA 04 04 04 04 04 04 04 04 04 04 04>
Dec 30 20:58:19.98: [ 5725]: <-- data [23]
Dec 30 20:58:19.98: [ 5725]: <-- data [2]
Dec 30 20:58:21.53: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:21.53: [ 5725]: <-- HDLC<6:FF C8 C1 00 45 14>
Dec 30 20:58:21.53: [ 5725]: <-- data [6]
Dec 30 20:58:21.53: [ 5725]: <-- data [2]
Dec 30 20:58:21.89: [ 5725]: --> [2:OK]
Dec 30 20:58:21.89: [ 5725]: <-- [9:AT+FTS=7\r]
Dec 30 20:58:21.99: [ 5725]: --> [2:OK]
Dec 30 20:58:21.99: [ 5725]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Dec 30 20:58:21.99: [ 5725]: <-- [11:AT+FTM=145\r]
Dec 30 20:58:22.01: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:22.01: [ 5725]: DELAY 400 ms
Dec 30 20:58:22.41: [ 5725]: <-- data [1024]
Dec 30 20:58:22.41: [ 5725]: <-- data [ 1024]
Dec 30 20:58:22.41: [ 5725]: <-- data [652]
Dec 30 20:58:22.41: [ 5725]: <-- data [2]
Dec 30 20:58:25.00: [ 5725]: --> [2:OK]
Dec 30 20:58:25.00: [ 5725]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Dec 30 20:58:25.00: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:25.79: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:26.92: [ 5725]: --> HDLC<5:FF C8 22 67 DD>
Dec 30 20:58:26.96: [ 5725]: --> [2:OK]
Dec 30 20:58:26.96: [ 5725]: SEND training at v.17 12000 bit/s
Dec 30 20:58:26.96: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:27.04: [ 5725]: --> [2:OK]
Dec 30 20:58:27.04: [ 5725]: <-- [9:AT+FTH=3\r]
Dec 30 20:58:27.06: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:27.06: [ 5725]: <-- HDLC<23:FF C0 C2 76 96 86 EA A6 76 96 16 CA 04 04 04 04 04 04 04 04 04 04 04>
Dec 30 20:58:27.06: [ 5725]: <-- data [23]
Dec 30 20:58:27.06: [ 5725]: <-- data [2]
Dec 30 20:58:28.61: [ 5725]: --> [ 7:CONNECT]
Dec 30 20:58:28.61: [ 5725]: <-- HDLC<6:FF C8 C1 00 55 14>
Dec 30 20:58:28.61: [ 5725]: <-- data [6]
Dec 30 20:58:28.61: [ 5725]: <-- data [2]
Dec 30 20:58:28.97: [ 5725]: --> [2:OK]
Dec 30 20:58:28.97: [ 5725]: <-- [9:AT+FTS=7\r]
Dec 30 20:58:29.07: [ 5725]: --> [2:OK]
Dec 30 20:58:29.07: [ 5725]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Dec 30 20:58:29.07: [ 5725]: <-- [11:AT+FTM=121\r]
Dec 30 20:58:29.09: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:29.09: [ 5725]: DELAY 400 ms
Dec 30 20:58:29.49: [ 5725]: <-- data [1024]
Dec 30 20:58:29.49: [ 5725]: <-- data [1024]
Dec 30 20:58:29.49: [ 5725]: <-- data [202]
Dec 30 20:58:29.49: [ 5725]: <-- data [2]
Dec 30 20:58:32.08: [ 5725]: --> [2:OK]
Dec 30 20:58:32.08: [ 5725]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Dec 30 20:58:32.08: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:32.90: [ 5725] : --> [7:CONNECT]
Dec 30 20:58:33.99: [ 5725]: --> HDLC<5:FF C8 22 67 DD>
Dec 30 20:58:34.05: [ 5725]: --> [2:OK]
Dec 30 20:58:34.05: [ 5725]: SEND training at v.29 9600 bit/s
Dec 30 20:58:34.05: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:34.11: [ 5725]: --> [2:OK]
Dec 30 20:58:34.11: [ 5725]: <-- [9:AT+FTH=3\r]
Dec 30 20:58:34.13: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:34.13: [ 5725]: <-- HDLC<23:FF C0 C2 76 96 86 EA A6 76 96 16 CA 04 04 04 04 04 04 04 04 04 04 04>
Dec 30 20:58:34.13: [ 5725]: <-- data [23]
Dec 30 20:58:34.13: [ 5725]: <-- data [2]
Dec 30 20:58:35.68: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:35.68: [ 5725]: <-- HDLC<6:FF C8 C1 00 61 14>
Dec 30 20:58:35.68: [ 5725]: <-- data [6]
Dec 30 20:58:35.68: [ 5725]: <-- data [2]
Dec 30 20:58:36.04: [ 5725]: --> [2:OK]
Dec 30 20:58:36.04: [ 5725]: <-- [9:AT+FTS=7\r]
Dec 30 20:58:36.14: [ 5725]: --> [2:OK]< br>Dec 30 20:58:36.14: [ 5725]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Dec 30 20:58:36.14: [ 5725]: <-- [10:AT+FTM=96\r]
Dec 30 20:58:36.16: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:36.16: [ 5725]: DELAY 400 ms
Dec 30 20:58:36.56: [ 5725]: <-- data [1024]
Dec 30 20:58:36.56: [ 5725]: <-- data [776]
Dec 30 20:58:36.56: [ 5725]: <-- data [2]
Dec 30 20:58:38.14: [ 5725]: --> [2:OK]
Dec 30 20:58:38.14: [ 5725]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Dec 30 20:58:38.14: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:38.96: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:40.07: [ 5725]: --> HDLC<5:FF C8 22 67 DD>
Dec 30 20:58:40.13: [ 5725]: --> [2:OK]
Dec 30 20:58:38.14: [ 5725]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Dec 30 20:58:38.14: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:38.96: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:40.07: [ 5725]: --> HDLC< 5:FF C8 22 67 DD>
Dec 30 20:58:40.13: [ 5725]: --> [2:OK]
Dec 30 20:58:40.13: [ 5725]: SEND training at v.29 7200 bit/s
Dec 30 20:58:40.13: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:40.21: [ 5725]: --> [2:OK]
Dec 30 20:58:40.21: [ 5725]: <-- [9:AT+FTH=3\r]
Dec 30 20:58:40.23: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:40.23: [ 5725]: <-- HDLC<23:FF C0 C2 76 96 86 EA A6 76 96 16 CA 04 04 04 04 04 04 04 04 04 04 04>
Dec 30 20:58:40.23: [ 5725]: <-- data [23]
Dec 30 20:58:40.23: [ 5725]: <-- data [2]
Dec 30 20:58:41.78: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:41.78: [ 5725]: <-- HDLC<6:FF C8 C1 00 71 14>
Dec 30 20:58:41.78: [ 5725]: <-- data [6]
Dec 30 20:58:41.78: [ 5725]: <-- data [2]
Dec 30 20:58:42.14: [ 5725]: --> [2:OK]
Dec 30 20:58:42.14: [ 5725]: <-- [9:AT+FTS=7\r]
Dec 30 20:58:42.24: [ 5725]: --> [2:OK]
Dec 30 20:58:42.24: [ 5725]: MODEM set XON/XOFF/FLUSH: input inte rpreted, output disabled
Dec 30 20:58:42.24: [ 5725]: <-- [10:AT+FTM=72\r]
Dec 30 20:58:42.26: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:42.26: [ 5725]: DELAY 400 ms
Dec 30 20:58:42.66: [ 5725]: <-- data [1024]
Dec 30 20:58:42.66: [ 5725]: <-- data [326]
Dec 30 20:58:42.66: [ 5725]: <-- data [2]
Dec 30 20:58:44.22: [ 5725]: --> [2:OK]
Dec 30 20:58:44.22: [ 5725]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Dec 30 20:58:44.22: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:45.08: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:46.15: [ 5725]: --> HDLC<5:FF C8 22 67 DD>
Dec 30 20:58:46.23: [ 5725]: --> [2:OK]
Dec 30 20:58:46.23: [ 5725]: SEND training at v.27ter 4800 bit/s
Dec 30 20:58:46.23: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:46.29: [ 5725]: --> [2:OK]
Dec 30 20:58:46.29: [ 5725]: <-- [9:AT+FTH=3\r]
Dec 30 20:58:46.31: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:46.31: [ 5725]: < -- HDLC<23:FF C0 C2 76 96 86 EA A6 76 96 16 CA 04 04 04 04 04 04 04 04 04 04 04>
Dec 30 20:58:46.31: [ 5725]: <-- data [23]
Dec 30 20:58:46.31: [ 5725]: <-- data [2]
Dec 30 20:58:47.86: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:47.86: [ 5725]: <-- HDLC<6:FF C8 C1 00 51 14>
Dec 30 20:58:47.86: [ 5725]: <-- data [6]
Dec 30 20:58:47.86: [ 5725]: <-- data [2]
Dec 30 20:58:48.22: [ 5725]: --> [2:OK]
Dec 30 20:58:48.22: [ 5725]: <-- [9:AT+FTS=7\r]
Dec 30 20:58:48.32: [ 5725]: --> [2:OK]
Dec 30 20:58:48.32: [ 5725]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Dec 30 20:58:48.32: [ 5725]: <-- [10:AT+FTM=48\r]
Dec 30 20:58:48.34: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:48.34: [ 5725]: DELAY 400 ms
Dec 30 20:58:48.74: [ 5725]: <-- data [900]
Dec 30 20:58:48.74: [ 5725]: <-- data [2]
Dec 30 20:58:50.63: [ 5725]: --> [2:OK]
Dec 30 20:58:50.63: [ 5725]: MODEM set XON/XOFF/D RAIN: input ignored, output disabled
Dec 30 20:58:50.63: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:51.44: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:52.56: [ 5725]: --> HDLC<5:FF C8 22 67 DD>
Dec 30 20:58:52.61: [ 5725]: --> [2:OK]
Dec 30 20:58:52.61: [ 5725]: SEND training at v.27ter fallback mode 2400 bit/s
Dec 30 20:58:52.61: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:52.69: [ 5725]: --> [2:OK]
Dec 30 20:58:52.69: [ 5725]: <-- [9:AT+FTH=3\r]
Dec 30 20:58:52.71: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:52.71: [ 5725]: <-- HDLC<23:FF C0 C2 76 96 86 EA A6 76 96 16 CA 04 04 04 04 04 04 04 04 04 04 04>
Dec 30 20:58:52.71: [ 5725]: <-- data [23]
Dec 30 20:58:52.71: [ 5725]: <-- data [2]
Dec 30 20:58:54.25: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:54.25: [ 5725]: <-- HDLC<6:FF C8 C1 00 41 14>
Dec 30 20:58:54.25: [ 5725]: <-- data [6]
Dec 30 20:58:54.25: [ 5725]: <-- data [2]
Dec 3 0 20:58:54.62: [ 5725]: --> [2:OK]
Dec 30 20:58:54.62: [ 5725]: <-- [9:AT+FTS=7\r]
Dec 30 20:58:54.72: [ 5725]: --> [2:OK]
Dec 30 20:58:54.72: [ 5725]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Dec 30 20:58:54.72: [ 5725]: <-- [10:AT+FTM=24\r]
Dec 30 20:58:54.74: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:54.74: [ 5725]: DELAY 400 ms
Dec 30 20:58:55.14: [ 5725]: <-- data [450]
Dec 30 20:58:55.14: [ 5725]: <-- data [2]
Dec 30 20:58:57.27: [ 5725]: --> [2:OK]
Dec 30 20:58:57.27: [ 5725]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Dec 30 20:58:57.27: [ 5725]: <-- [9:AT+FRH=3\r]
Dec 30 20:58:58.10: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:59.20: [ 5725]: --> HDLC<5:FF C8 22 67 DD>
Dec 30 20:58:59.26: [ 5725]: --> [2:OK]
Dec 30 20:58:59.26: [ 5725]: TRAINING failed
Dec 30 20:58:59.26: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:59.32: [ 5725]: --> [2:OK]
Dec 30 20:58:59.26: [ 5725]: TRAINING failed
Dec 30 20:58:59.26: [ 5725]: <-- [9:AT+FRS=7\r]
Dec 30 20:58:59.32: [ 5725]: --> [2:OK]
Dec 30 20:58:59.32: [ 5725]: <-- [9:AT+FTH=3\r]
Dec 30 20:58:59.34: [ 5725]: --> [7:CONNECT]
Dec 30 20:58:59.34: [ 5725]: <-- HDLC<3:FF C8 DF>
Dec 30 20:58:59.34: [ 5725]: <-- data [3]
Dec 30 20:58:59.34: [ 5725]: <-- data [2]
Dec 30 20:59:00.43: [ 5725]: --> [2:OK]
Dec 30 20:59:00.43: [ 5725]: MODEM input buffering enabled
Dec 30 20:59:01.43: [ 5725]: <-- [5:ATH0\r]
Dec 30 20:59:01.55: [ 5725]: --> [2:OK]
Dec 30 20:59:01.55: [ 5725]: MODEM set DTR OFF
Dec 30 20:59:01.55: [ 5725]: MODEM set baud rate: 0 baud (flow control unchanged)
Dec 30 20:59:01.55: [ 5725]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
Dec 30 20:59:01.55: [ 5725]: SESSION END
=============================================================================

Thanks in advance for your nice help,
Yu