[hylafax-users] MODEM TIMEOUT: waiting for v.21 carrier

To: hylafax-users@xxxxxxxxxxx
Subject: [hylafax-users] MODEM TIMEOUT: waiting for v.21 carrier
From: Daniele Gallarato <daniele.gallarato@xxxxxxxx>
Date: Thu, 04 Sep 2008 10:55:29 +0200

Hi all. I've this problem with some destination faxes.
Hylafax try to send fax but fail with this final error:

Failure to train remote modem at 2400 bps or minimum speed


I've investigated looking log files, and I've found these errors:

Sep 04 10:48:57.87: [14325]: MODEM <Empty line>
Sep 04 10:48:57.87: [14325]: MODEM TIMEOUT: waiting for v.21 carrier


Searching in mailing-list archive I've tried these changes to configuration:

Class1ECMSupport:       no
Class1TMConnectDelay:   400
Class1RMQueryCmd:       "!24,48,72,96" # V.17 fast-train recv doesn't work well
RTNHandlingMethod:      giveup	#or ignore


But problem remains.

My version is (on a debian system):

hylafax-server                    4.3.1-7

I've attach complete call log.

Thanks for any help.

Daniele

Sep 04 10:48:06.05: [14325]: SESSION BEGIN 000000246 0116704725
Sep 04 10:48:06.05: [14325]: HylaFAX (tm) Version 4.3.1
Sep 04 10:48:06.05: [14325]: SEND FAX: JOB 133 DEST 0116704725 COMMID 000000246 DEVICE '/dev/ttyp0' FROM 'daniele.gallarato <daniele.gallarato@xxxxxxxxx>' USER root
Sep 04 10:48:06.05: [14325]: STATE CHANGE: RUNNING -> SENDING
Sep 04 10:48:06.05: [14325]: <-- [12:AT+FCLASS=1\r]
Sep 04 10:48:06.05: [14325]: --> [2:OK]
Sep 04 10:48:06.05: [14325]: DIAL 0116704725
Sep 04 10:48:06.05: [14325]: <-- [15:ATDT0116704725\r]
Sep 04 10:48:17.62: [14325]: --> [7:CONNECT]
Sep 04 10:48:18.78: [14325]: --> HDLC<16:FF C0 04 B5 00 8A 5A 00 00 00 00 00 00 00 FD 74>
Sep 04 10:48:18.78: [14325]: --> [2:OK]
Sep 04 10:48:18.78: [14325]: REMOTE NSF "AD 00 51 5A 00 00 00 00 00 00 00"
Sep 04 10:48:18.78: [14325]: NSF remote fax equipment: Telogy Networks 
Sep 04 10:48:18.78: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:18.79: [14325]: --> [7:CONNECT]
Sep 04 10:48:19.47: [14325]: --> HDLC<25:FF C0 02 AC 4C EC 2C 0C EC 6C 04 8C 8C 04 9C CC D4 04 04 04 04 04 04 D4 D0>
Sep 04 10:48:19.47: [14325]: --> [2:OK]
Sep 04 10:48:19.47: [14325]: REMOTE CSI "+39 11 6704725"
Sep 04 10:48:19.47: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:19.47: [14325]: --> [7:CONNECT]
Sep 04 10:48:19.80: [14325]: --> HDLC<11:FF C8 01 00 73 15 01 01 88 86 6D>
Sep 04 10:48:19.80: [14325]: --> [2:OK]
Sep 04 10:48:19.80: [14325]: REMOTE best rate 9600 bit/s
Sep 04 10:48:19.80: [14325]: REMOTE max A4 page width (215 mm)
Sep 04 10:48:19.80: [14325]: REMOTE max unlimited page length
Sep 04 10:48:19.80: [14325]: REMOTE best vres 15.4 line/mm
Sep 04 10:48:19.80: [14325]: REMOTE format support: MH, MR
Sep 04 10:48:19.80: [14325]: REMOTE best 10 ms/scanline
Sep 04 10:48:19.80: [14325]: USE 9600 bit/s
Sep 04 10:48:19.80: [14325]: SEND file "docq/doc139.pdf;71"
Sep 04 10:48:19.80: [14325]: USE A4 page width (215 mm)
Sep 04 10:48:19.80: [14325]: USE unlimited page length
Sep 04 10:48:19.80: [14325]: USE 7.7 line/mm
Sep 04 10:48:19.80: [14325]: USE 2-D MR
Sep 04 10:48:19.80: [14325]: USE 10 ms/scanline
Sep 04 10:48:19.80: [14325]: SEND training at v.29 9600 bit/s
Sep 04 10:48:19.80: [14325]: <-- [9:AT+FRS=7\r]
Sep 04 10:48:19.87: [14325]: --> [2:OK]
Sep 04 10:48:19.87: [14325]: <-- [9:AT+FTH=3\r]
Sep 04 10:48:19.87: [14325]: --> [7:CONNECT]
Sep 04 10:48:19.87: [14325]: <-- HDLC<23:FF C0 C2 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Sep 04 10:48:19.87: [14325]: <-- data [23]
Sep 04 10:48:19.87: [14325]: <-- data [2]
Sep 04 10:48:21.46: [14325]: --> [7:CONNECT]
Sep 04 10:48:21.46: [14325]: <-- HDLC<6:FF C8 C1 00 63 14>
Sep 04 10:48:21.46: [14325]: <-- data [6]
Sep 04 10:48:21.46: [14325]: <-- data [2]
Sep 04 10:48:21.76: [14325]: --> [2:OK]
Sep 04 10:48:21.76: [14325]: <-- [9:AT+FTS=7\r]
Sep 04 10:48:21.91: [14325]: --> [2:OK]
Sep 04 10:48:21.91: [14325]: <-- [10:AT+FTM=96\r]
Sep 04 10:48:21.91: [14325]: --> [7:CONNECT]
Sep 04 10:48:21.91: [14325]: DELAY 400 ms
Sep 04 10:48:22.31: [14325]: <-- data [1024]
Sep 04 10:48:22.31: [14325]: <-- data [776]
Sep 04 10:48:22.31: [14325]: <-- data [2]
Sep 04 10:48:23.86: [14325]: --> [2:OK]
Sep 04 10:48:23.86: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:24.41: [14325]: --> [7:CONNECT]
Sep 04 10:48:29.14: [14325]: --> [5:ERROR]
Sep 04 10:48:29.14: [14325]: MODEM Command error
Sep 04 10:48:29.14: [14325]: FCS error
Sep 04 10:48:29.14: [14325]: <-- [9:AT+FRS=7\r]
Sep 04 10:48:29.22: [14325]: --> [2:OK]
Sep 04 10:48:29.22: [14325]: <-- [9:AT+FTH=3\r]
Sep 04 10:48:29.22: [14325]: --> [7:CONNECT]
Sep 04 10:48:29.22: [14325]: <-- HDLC<3:FF C8 D8>
Sep 04 10:48:29.22: [14325]: <-- data [3]
Sep 04 10:48:29.22: [14325]: <-- data [2]
Sep 04 10:48:31.30: [14325]: --> [2:OK]
Sep 04 10:48:31.30: [14325]: SEND send CRP (command repeat)
Sep 04 10:48:31.30: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:34.41: [14325]: --> [0:]
Sep 04 10:48:34.41: [14325]: MODEM <Empty line>
Sep 04 10:48:34.41: [14325]: MODEM TIMEOUT: waiting for v.21 carrier
Sep 04 10:48:34.41: [14325]: <-- data [1]
Sep 04 10:48:34.41: [14325]: --> [2:OK]
Sep 04 10:48:34.41: [14325]: DELAY 1500 ms
Sep 04 10:48:35.91: [14325]: SEND training at v.29 7200 bit/s
Sep 04 10:48:35.91: [14325]: <-- [9:AT+FRS=7\r]
Sep 04 10:48:35.98: [14325]: --> [2:OK]
Sep 04 10:48:35.98: [14325]: <-- [9:AT+FTH=3\r]
Sep 04 10:48:35.98: [14325]: --> [7:CONNECT]
Sep 04 10:48:35.98: [14325]: <-- HDLC<23:FF C0 C2 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Sep 04 10:48:35.98: [14325]: <-- data [23]
Sep 04 10:48:35.98: [14325]: <-- data [2]
Sep 04 10:48:37.54: [14325]: --> [7:CONNECT]
Sep 04 10:48:37.54: [14325]: <-- HDLC<6:FF C8 C1 00 73 14>
Sep 04 10:48:37.54: [14325]: <-- data [6]
Sep 04 10:48:37.54: [14325]: <-- data [2]
Sep 04 10:48:37.84: [14325]: --> [2:OK]
Sep 04 10:48:37.84: [14325]: <-- [9:AT+FTS=7\r]
Sep 04 10:48:37.99: [14325]: --> [2:OK]
Sep 04 10:48:37.99: [14325]: <-- [10:AT+FTM=72\r]
Sep 04 10:48:37.99: [14325]: --> [7:CONNECT]
Sep 04 10:48:37.99: [14325]: DELAY 400 ms
Sep 04 10:48:38.39: [14325]: <-- data [1024]
Sep 04 10:48:38.39: [14325]: <-- data [326]
Sep 04 10:48:38.39: [14325]: <-- data [2]
Sep 04 10:48:40.52: [14325]: --> [2:OK]
Sep 04 10:48:40.52: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:41.88: [14325]: --> [7:CONNECT]
Sep 04 10:48:43.19: [14325]: --> HDLC<16:FF C0 04 B5 00 8A 5A 00 00 00 00 00 00 00 FD 74>
Sep 04 10:48:43.19: [14325]: --> [2:OK]
Sep 04 10:48:43.19: [14325]: REMOTE NSF "AD 00 51 5A 00 00 00 00 00 00 00"
Sep 04 10:48:43.19: [14325]: NSF remote fax equipment: Telogy Networks 
Sep 04 10:48:43.19: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:43.19: [14325]: --> [7:CONNECT]
Sep 04 10:48:43.88: [14325]: --> HDLC<25:FF C0 02 AC 4C EC 2C 0C EC 6C 04 8C 8C 04 9C CC D4 04 04 04 04 04 04 D4 D0>
Sep 04 10:48:43.88: [14325]: --> [2:OK]
Sep 04 10:48:43.88: [14325]: REMOTE CSI "+39 11 6704725"
Sep 04 10:48:43.88: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:43.88: [14325]: --> [7:CONNECT]
Sep 04 10:48:44.20: [14325]: --> HDLC<11:FF C8 01 00 73 15 01 01 88 86 6D>
Sep 04 10:48:44.20: [14325]: --> [2:OK]
Sep 04 10:48:44.20: [14325]: SEND training at v.29 7200 bit/s
Sep 04 10:48:44.20: [14325]: <-- [9:AT+FRS=7\r]
Sep 04 10:48:44.28: [14325]: --> [2:OK]
Sep 04 10:48:44.28: [14325]: <-- [9:AT+FTH=3\r]
Sep 04 10:48:44.28: [14325]: --> [7:CONNECT]
Sep 04 10:48:44.28: [14325]: <-- HDLC<23:FF C0 C2 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Sep 04 10:48:44.28: [14325]: <-- data [23]
Sep 04 10:48:44.28: [14325]: <-- data [2]
Sep 04 10:48:45.87: [14325]: --> [7:CONNECT]
Sep 04 10:48:45.87: [14325]: <-- HDLC<6:FF C8 C1 00 73 14>
Sep 04 10:48:45.87: [14325]: <-- data [6]
Sep 04 10:48:45.87: [14325]: <-- data [2]
Sep 04 10:48:46.18: [14325]: --> [2:OK]
Sep 04 10:48:46.18: [14325]: <-- [9:AT+FTS=7\r]
Sep 04 10:48:46.32: [14325]: --> [2:OK]
Sep 04 10:48:46.32: [14325]: <-- [10:AT+FTM=72\r]
Sep 04 10:48:46.32: [14325]: --> [7:CONNECT]
Sep 04 10:48:46.32: [14325]: DELAY 400 ms
Sep 04 10:48:46.72: [14325]: <-- data [1024]
Sep 04 10:48:46.72: [14325]: <-- data [326]
Sep 04 10:48:46.72: [14325]: <-- data [2]
Sep 04 10:48:48.27: [14325]: --> [2:OK]
Sep 04 10:48:48.27: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:49.15: [14325]: --> [7:CONNECT]
Sep 04 10:48:50.16: [14325]: --> HDLC<5:FF C8 22 67 DD>
Sep 04 10:48:50.16: [14325]: --> [2:OK]
Sep 04 10:48:50.16: [14325]: SEND training at v.27ter 4800 bit/s
Sep 04 10:48:50.16: [14325]: <-- [9:AT+FRS=7\r]
Sep 04 10:48:50.24: [14325]: --> [2:OK]
Sep 04 10:48:50.24: [14325]: <-- [9:AT+FTH=3\r]
Sep 04 10:48:50.24: [14325]: --> [7:CONNECT]
Sep 04 10:48:50.24: [14325]: <-- HDLC<23:FF C0 C2 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Sep 04 10:48:50.24: [14325]: <-- data [23]
Sep 04 10:48:50.24: [14325]: <-- data [2]
Sep 04 10:48:51.83: [14325]: --> [7:CONNECT]
Sep 04 10:48:51.83: [14325]: <-- HDLC<6:FF C8 C1 00 53 14>
Sep 04 10:48:51.83: [14325]: <-- data [6]
Sep 04 10:48:51.83: [14325]: <-- data [2]
Sep 04 10:48:52.13: [14325]: --> [2:OK]
Sep 04 10:48:52.13: [14325]: <-- [9:AT+FTS=7\r]
Sep 04 10:48:52.28: [14325]: --> [2:OK]
Sep 04 10:48:52.28: [14325]: <-- [10:AT+FTM=48\r]
Sep 04 10:48:52.28: [14325]: --> [7:CONNECT]
Sep 04 10:48:52.28: [14325]: DELAY 400 ms
Sep 04 10:48:52.68: [14325]: <-- data [900]
Sep 04 10:48:52.68: [14325]: <-- data [2]
Sep 04 10:48:54.76: [14325]: --> [2:OK]
Sep 04 10:48:54.76: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:48:57.87: [14325]: --> [0:]
Sep 04 10:48:57.87: [14325]: MODEM <Empty line>
Sep 04 10:48:57.87: [14325]: MODEM TIMEOUT: waiting for v.21 carrier
Sep 04 10:48:57.87: [14325]: <-- data [1]
Sep 04 10:48:57.87: [14325]: --> [2:OK]
Sep 04 10:48:57.87: [14325]: DELAY 1500 ms
Sep 04 10:48:59.37: [14325]: SEND training at v.27ter fallback mode 2400 bit/s
Sep 04 10:48:59.37: [14325]: <-- [9:AT+FRS=7\r]
Sep 04 10:48:59.45: [14325]: --> [2:OK]
Sep 04 10:48:59.45: [14325]: <-- [9:AT+FTH=3\r]
Sep 04 10:48:59.45: [14325]: --> [7:CONNECT]
Sep 04 10:48:59.45: [14325]: <-- HDLC<23:FF C0 C2 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04 04>
Sep 04 10:48:59.45: [14325]: <-- data [23]
Sep 04 10:48:59.45: [14325]: <-- data [2]
Sep 04 10:49:01.00: [14325]: --> [7:CONNECT]
Sep 04 10:49:01.00: [14325]: <-- HDLC<6:FF C8 C1 00 43 14>
Sep 04 10:49:01.00: [14325]: <-- data [6]
Sep 04 10:49:01.00: [14325]: <-- data [2]
Sep 04 10:49:01.30: [14325]: --> [2:OK]
Sep 04 10:49:01.30: [14325]: <-- [9:AT+FTS=7\r]
Sep 04 10:49:01.45: [14325]: --> [2:OK]
Sep 04 10:49:01.45: [14325]: <-- [10:AT+FTM=24\r]
Sep 04 10:49:01.45: [14325]: --> [7:CONNECT]
Sep 04 10:49:01.45: [14325]: DELAY 400 ms
Sep 04 10:49:01.85: [14325]: <-- data [450]
Sep 04 10:49:01.85: [14325]: <-- data [2]
Sep 04 10:49:04.14: [14325]: --> [2:OK]
Sep 04 10:49:04.14: [14325]: <-- [9:AT+FRH=3\r]
Sep 04 10:49:05.21: [14325]: --> [7:CONNECT]
Sep 04 10:49:06.23: [14325]: --> HDLC<5:FF C8 22 67 DD>
Sep 04 10:49:06.23: [14325]: --> [2:OK]
Sep 04 10:49:06.23: [14325]: TRAINING failed
Sep 04 10:49:06.23: [14325]: <-- [9:AT+FTH=3\r]
Sep 04 10:49:06.23: [14325]: --> [7:CONNECT]
Sep 04 10:49:06.23: [14325]: <-- HDLC<3:FF C8 DF>
Sep 04 10:49:06.23: [14325]: <-- data [3]
Sep 04 10:49:06.23: [14325]: <-- data [2]
Sep 04 10:49:07.36: [14325]: --> [2:OK]
Sep 04 10:49:07.36: [14325]: MODEM input buffering enabled
Sep 04 10:49:07.36: [14325]: <-- [5:ATH0\r]
Sep 04 10:49:07.46: [14325]: --> [2:OK]
Sep 04 10:49:07.46: [14325]: MODEM set DTR OFF
Sep 04 10:49:07.46: [14325]: MODEM set baud rate: 0 baud (flow control unchanged)
Sep 04 10:49:07.46: [14325]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
Sep 04 10:49:07.46: [14325]: SESSION END

Follow-Ups:
- Re: [hylafax-users] MODEM TIMEOUT: waiting for v.21 carrier
  - From: Lee Howard

Prev by Date: Re: [hylafax-users] hylafax future plans?
Next by Date: Re: [hylafax-users] DateStamp PDF Attachment Received by from FaxDispatch
Previous by thread: Re: [hylafax-users] hylafax future plans?
Next by thread: Re: [hylafax-users] MODEM TIMEOUT: waiting for v.21 carrier
Index(es):
- Main
- Thread

Project hosted by iFAX Solutions