[hylafax-users] No answer (T.30 T1 timeout)

["Jeroen van Vierzen" <j.vanvierzen@xxxxxxxxx>]

Hello,

 

I’m currently running HylaFAX Version 4.3.3 on CentOS 5 2.6.18-53.1.19.el5 on several IAX modems.

The HylaFAX installation came with a popular PBX distribution called Elastix(1.3-2).

 

There have been no configuration changes nor have there been any updates executed.

Out of the blue I’m unable to send any faxes over Hylafax. It has worked fine for several months.

 

When sending any random fax it will promptly give me the errormessage “No Answer (T.30 T1 timeout)” on the senders end with the following tracelog:

 

Sending end>

Feb 02 08:51:01.50: [ 4922]: SESSION BEGIN 000000014 [removed phonenumber]

Feb 02 08:51:01.50: [ 4922]: HylaFAX (tm) Version 4.3.3

Feb 02 08:51:01.50: [ 4922]: SEND FAX: JOB 1 DEST [removed phonenumber] COMMID 000000014 DEVICE '/dev/ttyIAX1' FROM 'root <j.vanvierzen@xxxxxxxxx>' USER root

Feb 02 08:51:01.50: [ 4922]: STATE CHANGE: RUNNING -> SENDING

Feb 02 08:51:01.50: [ 4922]: <-- [12:AT+FCLASS=1\r]

Feb 02 08:51:01.50: [ 4922]: --> [2:OK]

Feb 02 08:51:01.50: [ 4922]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled

Feb 02 08:51:01.50: [ 4922]: DIAL [removed phonenumber]

Feb 02 08:51:01.50: [ 4922]: <-- [15:ATDT[removed phonenumber]\r]

Feb 02 08:51:06.18: [ 4922]: --> [7:CONNECT]

Feb 02 08:51:16.18: [ 4922]: MODEM TIMEOUT: receiving HDLC frame data

Feb 02 08:51:16.18: [ 4922]: <-- data [1]

Feb 02 08:51:16.20: [ 4922]: --> [2:OK]

Feb 02 08:51:16.20: [ 4922]: DELAY 200 ms

Feb 02 08:51:16.40: [ 4922]: <-- [9:AT+FRH=3\r]

Feb 02 08:51:23.40: [ 4922]: --> [0:]

Feb 02 08:51:23.40: [ 4922]: MODEM <Empty line>

Feb 02 08:51:23.40: [ 4922]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:51:23.40: [ 4922]: <-- data [1]

Feb 02 08:51:23.40: [ 4922]: --> [2:OK]

Feb 02 08:51:23.40: [ 4922]: DELAY 200 ms

Feb 02 08:51:23.60: [ 4922]: <-- [9:AT+FRH=3\r]

Feb 02 08:51:28.76: [ 4922]: ABORT: job abort requested

Feb 02 08:51:30.60: [ 4922]: --> [0:]

Feb 02 08:51:30.60: [ 4922]: MODEM <Empty line>

Feb 02 08:51:30.60: [ 4922]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:51:30.60: [ 4922]: <-- data [1]

Feb 02 08:51:30.60: [ 4922]: --> [2:OK]

Feb 02 08:51:30.60: [ 4922]: DELAY 200 ms

Feb 02 08:51:30.80: [ 4922]: <-- [9:AT+FRH=3\r]

Feb 02 08:51:37.81: [ 4922]: --> [0:]

Feb 02 08:51:37.81: [ 4922]: MODEM <Empty line>

Feb 02 08:51:37.81: [ 4922]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:51:37.81: [ 4922]: <-- data [1]

Feb 02 08:51:37.81: [ 4922]: --> [2:OK]

Feb 02 08:51:37.81: [ 4922]: DELAY 200 ms

Feb 02 08:51:38.01: [ 4922]: <-- [9:AT+FRH=3\r]

Feb 02 08:51:45.01: [ 4922]: --> [0:]

Feb 02 08:51:45.01: [ 4922]: MODEM <Empty line>

Feb 02 08:51:45.01: [ 4922]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:51:45.01: [ 4922]: <-- data [1]

Feb 02 08:51:45.01: [ 4922]: --> [2:OK]

Feb 02 08:51:45.01: [ 4922]: DELAY 200 ms

Feb 02 08:51:45.21: [ 4922]: <-- [9:AT+FRH=3\r]

Feb 02 08:51:52.21: [ 4922]: --> [0:]

Feb 02 08:51:52.21: [ 4922]: MODEM <Empty line>

Feb 02 08:51:52.21: [ 4922]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:51:52.21: [ 4922]: <-- data [1]

Feb 02 08:51:52.21: [ 4922]: --> [2:OK]

Feb 02 08:51:52.21: [ 4922]: DELAY 200 ms

Feb 02 08:51:52.41: [ 4922]: No answer (T.30 T1 timeout)

Feb 02 08:51:52.41: [ 4922]: SEND FAILED: JOB 1 DEST [removed phonenumber] ERR No answer (T.30 T1 timeout)

Feb 02 08:51:52.41: [ 4922]: <-- [9:AT+FTH=3\r]

Feb 02 08:51:52.43: [ 4922]: --> [7:CONNECT]

Feb 02 08:51:52.43: [ 4922]: <-- HDLC<3:FF C8 DF>

Feb 02 08:51:52.43: [ 4922]: <-- data [2]

Feb 02 08:51:52.43: [ 4922]: MODEM input buffering enabled

Feb 02 08:51:52.43: [ 4922]: SEND FAILED: JOB 1 DEST [removed phonenumber] ERR Call aborted by user

Feb 02 08:51:52.43: [ 4922]: <-- [5:ATH0\r]

Feb 02 08:51:53.62: [ 4922]: --> [10:NO CARRIER]

Feb 02 08:51:53.62: [ 4922]: MODEM No carrier

Feb 02 08:51:53.62: [ 4922]: MODEM set DTR OFF

Feb 02 08:51:53.62: [ 4922]: MODEM set baud rate: 0 baud (flow control unchanged)

Feb 02 08:51:53.62: [ 4922]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)

Feb 02 08:51:53.62: [ 4922]: SESSION END

 

On the receiving end I noticed a similar problem, it appears to me that one end isn’t getting any audio signals through to the opposing end.

 

Log receiving end>

Feb 02 08:49:50.41: [30973]: SESSION BEGIN 000001696 [removed phonenumber]

Feb 02 08:49:50.41: [30973]: HylaFAX (tm) Version 4.3.3

Feb 02 08:49:50.41: [30973]: CallID: "[removed phonenumber]" "[removed phonenumber]" "<NONE>" "s"

Feb 02 08:49:50.41: [30973]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled

Feb 02 08:49:50.41: [30973]: <-- [4:ATA\r]

Feb 02 08:49:54.22: [30973]: --> [7:CONNECT]

Feb 02 08:49:54.22: [30973]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyIAX1'

Feb 02 08:49:54.22: [30973]: STATE CHANGE: ANSWERING -> RECEIVING

Feb 02 08:49:54.22: [30973]: RECV FAX: begin

Feb 02 08:49:54.22: [30973]: <-- 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 2C 74 CC 74 CC>

Feb 02 08:49:54.22: [30973]: <-- data [32]

Feb 02 08:49:54.22: [30973]: <-- data [2]

Feb 02 08:49:55.27: [30973]: --> [7:CONNECT]

Feb 02 08:49:55.28: [30973]: <-- HDLC<23:FF C0 02 CE 76 F6 96 2E AE 36 F6 CA 04 CE AE A6 86 CE 92 04 04 04 04>

Feb 02 08:49:55.28: [30973]: <-- data [23]

Feb 02 08:49:55.28: [30973]: <-- data [2]

Feb 02 08:49:56.11: [30973]: --> [7:CONNECT]

Feb 02 08:49:56.11: [30973]: <-- HDLC<13:FF C8 01 00 73 5F 23 01 FB C1 01 01 18>

Feb 02 08:49:56.11: [30973]: <-- data [13]

Feb 02 08:49:56.11: [30973]: <-- data [2]

Feb 02 08:49:56.71: [30973]: --> [2:OK]

Feb 02 08:49:56.71: [30973]: <-- [9:AT+FRH=3\r]

Feb 02 08:50:03.72: [30973]: --> [0:]

Feb 02 08:50:03.72: [30973]: MODEM <Empty line>

Feb 02 08:50:03.72: [30973]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:50:03.72: [30973]: <-- data [1]

Feb 02 08:50:03.73: [30973]: --> [2:OK]

Feb 02 08:50:03.73: [30973]: DELAY 1500 ms

Feb 02 08:50:05.23: [30973]: <-- [9:AT+FTH=3\r]

Feb 02 08:50:05.24: [30973]: --> [7:CONNECT]

Feb 02 08:50:05.24: [30973]: <-- 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 2C 74 CC 74 CC>

Feb 02 08:50:05.24: [30973]: <-- data [32]

Feb 02 08:50:05.24: [30973]: <-- data [2]

Feb 02 08:50:07.19: [30973]: --> [7:CONNECT]

Feb 02 08:50:07.19: [30973]: <-- HDLC<23:FF C0 02 CE 76 F6 96 2E AE 36 F6 CA 04 CE AE A6 86 CE 92 04 04 04 04>

Feb 02 08:50:07.19: [30973]: <-- data [23]

Feb 02 08:50:07.19: [30973]: <-- data [2]

Feb 02 08:50:08.05: [30973]: --> [7:CONNECT]

Feb 02 08:50:08.05: [30973]: <-- HDLC<13:FF C8 01 00 73 5F 23 01 FB C1 01 01 18>

Feb 02 08:50:08.05: [30973]: <-- data [13]

Feb 02 08:50:08.05: [30973]: <-- data [2]

Feb 02 08:50:08.63: [30973]: --> [2:OK]

Feb 02 08:50:08.63: [30973]: <-- [9:AT+FRH=3\r]

Feb 02 08:50:15.64: [30973]: --> [0:]

Feb 02 08:50:15.64: [30973]: MODEM <Empty line>

Feb 02 08:50:15.64: [30973]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:50:15.64: [30973]: <-- data [1]

Feb 02 08:50:15.64: [30973]: --> [2:OK]

Feb 02 08:50:15.64: [30973]: DELAY 1500 ms

Feb 02 08:50:17.14: [30973]: <-- [9:AT+FTH=3\r]

Feb 02 08:50:17.14: [30973]: --> [7:CONNECT]

Feb 02 08:50:17.14: [30973]: <-- 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 2C 74 CC 74 CC>

Feb 02 08:50:17.14: [30973]: <-- data [32]

Feb 02 08:50:17.14: [30973]: <-- data [2]

Feb 02 08:50:19.09: [30973]: --> [7:CONNECT]

Feb 02 08:50:19.09: [30973]: <-- HDLC<23:FF C0 02 CE 76 F6 96 2E AE 36 F6 CA 04 CE AE A6 86 CE 92 04 04 04 04>

Feb 02 08:50:19.09: [30973]: <-- data [23]

Feb 02 08:50:19.09: [30973]: <-- data [2]

Feb 02 08:50:19.95: [30973]: --> [7:CONNECT]

Feb 02 08:50:19.95: [30973]: <-- HDLC<13:FF C8 01 00 73 5F 23 01 FB C1 01 01 18>

Feb 02 08:50:19.95: [30973]: <-- data [13]

Feb 02 08:50:19.95: [30973]: <-- data [2]

Feb 02 08:50:20.55: [30973]: --> [2:OK]

Feb 02 08:50:20.55: [30973]: <-- [9:AT+FRH=3\r]

Feb 02 08:50:27.56: [30973]: --> [0:]

Feb 02 08:50:27.56: [30973]: MODEM <Empty line>

Feb 02 08:50:27.56: [30973]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:50:27.56: [30973]: <-- data [1]

Feb 02 08:50:27.57: [30973]: --> [2:OK]

Feb 02 08:50:27.57: [30973]: DELAY 1500 ms

Feb 02 08:50:29.07: [30973]: <-- [9:AT+FTH=3\r]

Feb 02 08:50:29.08: [30973]: --> [7:CONNECT]

Feb 02 08:50:29.08: [30973]: <-- 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 2C 74 CC 74 CC>

Feb 02 08:50:29.08: [30973]: <-- data [32]

Feb 02 08:50:29.08: [30973]: <-- data [2]

Feb 02 08:50:31.03: [30973]: --> [7:CONNECT]

Feb 02 08:50:31.03: [30973]: <-- HDLC<23:FF C0 02 CE 76 F6 96 2E AE 36 F6 CA 04 CE AE A6 86 CE 92 04 04 04 04>

Feb 02 08:50:31.03: [30973]: <-- data [23]

Feb 02 08:50:31.03: [30973]: <-- data [2]

Feb 02 08:50:31.86: [30973]: --> [7:CONNECT]

Feb 02 08:50:31.86: [30973]: <-- HDLC<13:FF C8 01 00 73 5F 23 01 FB C1 01 01 18>

Feb 02 08:50:31.86: [30973]: <-- data [13]

Feb 02 08:50:31.86: [30973]: <-- data [2]

Feb 02 08:50:32.45: [30973]: --> [2:OK]

Feb 02 08:50:32.45: [30973]: <-- [9:AT+FRH=3\r]

Feb 02 08:50:39.46: [30973]: --> [0:]

Feb 02 08:50:39.46: [30973]: MODEM <Empty line>

Feb 02 08:50:39.46: [30973]: MODEM TIMEOUT: waiting for v.21 carrier

Feb 02 08:50:39.46: [30973]: <-- data [1]

Feb 02 08:50:39.46: [30973]: --> [2:OK]

Feb 02 08:50:39.46: [30973]: RECV FAX: No answer (T.30 T1 timeout)

Feb 02 08:50:39.46: [30973]: RECV FAX: end

Feb 02 08:50:39.46: [30973]: SESSION END

 

I can’t see why this fails, the obvious seems to be that audio isn’t getting through.. why this happends so randomly is beyond me, let alone how to fix this.

The codec used by the IAX modem setup by Elastix is set to ulaw, which should be fine.

 

Any suggestions would be greatly appreciated!

 

Regards,

J. van Vierzen