HylaFAX The world's most advanced open source fax server
[Date Prev][Date Next][Thread Prev][Thread Next] [Date Index] [Thread Index]

[hylafax-users] Problem: Timeouts with MultiTech MultiModemDID

Today I started having problems receiving faxes on our MultiTech
MultiModemDID.  Connections would be accepted, then time out:

Feb  9 12:58:23 dialtone FaxGetty[29351]: STATE CHANGE: RUNNING -> LISTENING
Feb  9 12:58:23 dialtone FaxGetty[29351]: MODEM input buffering enabled
Feb  9 12:58:23 dialtone FaxQueuer[29332]: MODEM ttyS0: BUSY
Feb  9 12:58:23 dialtone FaxGetty[29351]: --> [5:DTMF4]
Feb  9 12:58:23 dialtone FaxGetty[29351]: --> [5:DTMF7]
Feb  9 12:58:23 dialtone FaxGetty[29351]: --> [5:DTMF6]
Feb  9 12:58:23 dialtone FaxGetty[29351]: --> [5:DTMF8]
Feb  9 12:58:23 dialtone FaxGetty[29351]: ANSWER: CID NUMBER "4768" NAME ""
Feb  9 12:58:23 dialtone FaxGetty[29351]: STATE CHANGE: LISTENING ->
ANSWERING
Feb  9 12:58:23 dialtone FaxGetty[29351]: MODEM input buffering enabled
Feb  9 12:58:23 dialtone FaxQueuer[29332]: MODEM ttyS0: COMID 000000061
Feb  9 12:58:37 dialtone FaxGetty[29351]: ANSWER: FAX CONNECTION  DEVICE
'/dev/t
tyS0'
Feb  9 12:59:21 dialtone FaxQueuer[29332]: MODEM ttyS0: COMID 
Feb  9 12:59:21 dialtone FaxGetty[29351]: <-- [5:ATH0\r]
Feb  9 12:59:26 dialtone FaxGetty[29351]: MODEM TIMEOUT: reading line from
modem
Feb  9 12:59:26 dialtone FaxGetty[29351]: MODEM <Timeout>

I killed faxgetty, turned the modem off, then on again, and restarted
faxgetty, and it started working again.  I'd like to figure out what the
problem is, though, so I don't have to babysit the modem all the time.  Has
anyone seen this behavior before?  Here's the full model number string from
the modem:

MODEM LT V.92 1.0 MT5634ZBA-DID SERIAL DATA/FAX/DID MODEM VERSION 1.32F LT
V.92 1.0 MT5634ZBA-DID Serial Data/Fax/DID Modem Version 1.32f

I'm running it in class 1.

Here is a log from the modem I tried to send with, in case it helps.  To my
untrained eye it looks like training failed, for some reason:

Feb 09 14:11:36.95: [  936]: SESSION BEGIN 00000900 17349754756
Feb 09 14:11:36.95: [  936]: HylaFAX (tm) Version 4.1.1
Feb 09 14:11:36.95: [  936]: SEND FAX: JOB 550 DEST 9754756 COMMID 00000900
DEVICE '/dev/ttyS1'
Feb 09 14:11:36.95: [  936]: MODEM set DTR OFF
Feb 09 14:11:36.95: [  936]: DELAY 75 ms
Feb 09 14:11:37.02: [  936]: MODEM set DTR ON
Feb 09 14:11:37.02: [  936]: DELAY 2600 ms
Feb 09 14:11:39.62: [  936]: MODEM set baud rate: 38400 baud, input flow
XON/XOFF, output flow XON/XOFF
Feb 09 14:11:39.62: [  936]: MODEM flush i/o
Feb 09 14:11:39.62: [  936]: <-- [4:ATZ\r]
Feb 09 14:11:39.75: [  936]: --> [3:ATZ]
Feb 09 14:11:39.75: [  936]: --> [2:OK]
Feb 09 14:11:39.75: [  936]: DELAY 3000 ms
Feb 09 14:11:42.75: [  936]: <-- [5:ATE0\r]
Feb 09 14:11:42.88: [  936]: --> [4:ATE0]
Feb 09 14:11:42.88: [  936]: --> [2:OK]
Feb 09 14:11:42.88: [  936]: <-- [5:ATV1\r]
Feb 09 14:11:43.01: [  936]: --> [2:OK]
Feb 09 14:11:43.01: [  936]: <-- [7:ATQ0X4\r]
Feb 09 14:11:43.14: [  936]: --> [2:OK]
Feb 09 14:11:43.14: [  936]: <-- [7:ATS0=0\r]
Feb 09 14:11:43.27: [  936]: --> [2:OK]
Feb 09 14:11:43.27: [  936]: <-- [7:ATS8=2\r]
Feb 09 14:11:43.40: [  936]: --> [2:OK]
Feb 09 14:11:43.40: [  936]: <-- [8:ATS7=60\r]
Feb 09 14:11:43.53: [  936]: --> [2:OK]
Feb 09 14:11:43.53: [  936]: <-- [12:AT&H2&I2&R1\r]
Feb 09 14:11:43.67: [  936]: --> [2:OK]
Feb 09 14:11:43.67: [  936]: <-- [11:ATS13=1&D2\r]
Feb 09 14:11:43.81: [  936]: --> [2:OK]
Feb 09 14:11:43.81: [  936]: <-- [6:AT&C1\r]
Feb 09 14:11:43.94: [  936]: --> [2:OK]
Feb 09 14:11:43.94: [  936]: <-- [12:AT+FCLASS=1\r]
Feb 09 14:11:44.08: [  936]: --> [2:OK]
Feb 09 14:11:44.08: [  936]: <-- [12:AT+FCLASS=0\r]
Feb 09 14:11:44.22: [  936]: --> [2:OK]
Feb 09 14:11:44.22: [  936]: <-- [5:ATM0\r]
Feb 09 14:11:44.35: [  936]: --> [2:OK]
Feb 09 14:11:44.35: [  936]: MODEM input buffering enabled
Feb 09 14:11:44.35: [  936]: <-- [12:AT+FCLASS=1\r]
Feb 09 14:11:44.59: [  936]: --> [2:OK]
Feb 09 14:11:44.59: [  936]: MODEM set XON/XOFF/FLUSH: input ignored, output
disabled
Feb 09 14:11:44.59: [  936]: DIAL 9754756
Feb 09 14:11:44.59: [  936]: <-- [12:ATDT9754756\r]
Feb 09 14:12:00.14: [  936]: --> [7:CONNECT]
Feb 09 14:12:00.14: [  936]: MODEM input buffering disabled
Feb 09 14:12:01.73: [  936]: --> HDLC<34:FF C0 04 AD 00 55 12 9E 36 86 62 82
1A 04 14 2E B6 94 04 6A A6 4E CE 96 F6 76 04 2C 74 4C 74 8C B1 17>
Feb 09 14:12:01.73: [  936]: --> [2:OK]
Feb 09 14:12:01.73: [  936]: 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 31 8D"
Feb 09 14:12:01.73: [  936]: NSF remote fax equipment: unknown 
Feb 09 14:12:01.73: [  936]: NSF possible remote station ID: "HylaFAX (tm)
Version 4.2.1"
Feb 09 14:12:01.73: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:01.74: [  936]: --> [7:CONNECT]
Feb 09 14:12:02.45: [  936]: --> HDLC<25:FF C0 02 2A 72 A2 B2 0A 92 AA 8A A2
04 72 82 A2 32 C2 4A A2 2A 72 92 27 5F>
Feb 09 14:12:02.45: [  936]: --> [2:OK]
Feb 09 14:12:02.45: [  936]: REMOTE CSI "INTERCLEAN EQUIPMENT"
Feb 09 14:12:02.45: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:02.46: [  936]: --> [7:CONNECT]
Feb 09 14:12:02.80: [  936]: --> HDLC<12:FF C8 01 04 76 5F 23 01 FB C0 09
20>
Feb 09 14:12:02.80: [  936]: --> [2:OK]
Feb 09 14:12:02.80: [  936]: REMOTE best rate 14400 bit/s
Feb 09 14:12:02.80: [  936]: REMOTE max page width 2432 pixels in 303 mm
Feb 09 14:12:02.80: [  936]: REMOTE max unlimited page length 
Feb 09 14:12:02.80: [  936]: REMOTE best vres 7.7 line/mm
Feb 09 14:12:02.80: [  936]: REMOTE best format 2-D MMR
Feb 09 14:12:02.80: [  936]: REMOTE supports T.30 Annex A, ECM
Feb 09 14:12:02.80: [  936]: REMOTE best 0 ms/scanline
Feb 09 14:12:02.80: [  936]: USE 14400 bit/s
Feb 09 14:12:02.80: [  936]: USE 0 ms/scanline
Feb 09 14:12:02.80: [  936]: SEND file "docq/doc1049.ps;31"
Feb 09 14:12:02.80: [  936]: USE page width 1728 pixels in 215 mm
Feb 09 14:12:02.80: [  936]: USE unlimited page length 
Feb 09 14:12:02.80: [  936]: USE 7.7 line/mm
Feb 09 14:12:02.80: [  936]: USE 1-D MR
Feb 09 14:12:02.80: [  936]: SEND training at v.17 14400 bit/s
Feb 09 14:12:02.80: [  936]: <-- [9:AT+FTH=3\r]
Feb 09 14:12:02.99: [  936]: --> [7:CONNECT]
Feb 09 14:12:02.99: [  936]: <-- HDLC<23:FF C0 C2 2E 76 A6 B6 0E 96 AE 8E A2
04 76 86 A6 36 C2 4E A6 2E 76 92>
Feb 09 14:12:03.01: [  936]: --> [7:CONNECT]
Feb 09 14:12:03.01: [  936]: <-- HDLC<6:FF C8 C1 00 46 1E>
Feb 09 14:12:04.97: [  936]: --> [2:OK]
Feb 09 14:12:04.97: [  936]: <-- [9:AT+FTS=7\r]
Feb 09 14:12:05.05: [  936]: --> [2:OK]
Feb 09 14:12:05.05: [  936]: MODEM set XON/XOFF/FLUSH: input interpreted,
output disabled
Feb 09 14:12:05.05: [  936]: <-- [11:AT+FTM=145\r]
Feb 09 14:12:06.53: [  936]: --> [7:CONNECT]
Feb 09 14:12:08.06: [  936]: --> [2:OK]
Feb 09 14:12:08.06: [  936]: MODEM set XON/XOFF/DRAIN: input ignored, output
disabled
Feb 09 14:12:08.06: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:09.48: [  936]: --> [7:CONNECT]
Feb 09 14:12:09.67: [  936]: --> [9:9E 78 38 D0 B9 19 F8 10 03]
Feb 09 14:12:09.67: [  936]: --> [5:ERROR]
Feb 09 14:12:09.67: [  936]: MODEM Command error
Feb 09 14:12:09.67: [  936]: FCS error
Feb 09 14:12:09.67: [  936]: DELAY 1500 ms
Feb 09 14:12:11.17: [  936]: SEND training at v.17 12000 bit/s
Feb 09 14:12:11.17: [  936]: <-- [9:AT+FTH=3\r]
Feb 09 14:12:11.36: [  936]: --> [7:CONNECT]
Feb 09 14:12:11.36: [  936]: <-- HDLC<23:FF C0 C2 2E 76 A6 B6 0E 96 AE 8E A2
04 76 86 A6 36 C2 4E A6 2E 76 92>
Feb 09 14:12:11.38: [  936]: --> [7:CONNECT]
Feb 09 14:12:11.38: [  936]: <-- HDLC<6:FF C8 C1 00 56 1E>
Feb 09 14:12:13.34: [  936]: --> [2:OK]
Feb 09 14:12:13.34: [  936]: <-- [9:AT+FTS=7\r]
Feb 09 14:12:13.42: [  936]: --> [2:OK]
Feb 09 14:12:13.42: [  936]: MODEM set XON/XOFF/FLUSH: input interpreted,
output disabled
Feb 09 14:12:13.42: [  936]: <-- [11:AT+FTM=121\r]
Feb 09 14:12:14.90: [  936]: --> [7:CONNECT]
Feb 09 14:12:16.43: [  936]: --> [2:OK]
Feb 09 14:12:16.43: [  936]: MODEM set XON/XOFF/DRAIN: input ignored, output
disabled
Feb 09 14:12:16.43: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:16.84: [  936]: --> [10:NO CARRIER]
Feb 09 14:12:16.84: [  936]: MODEM No carrier
Feb 09 14:12:16.84: [  936]: DELAY 1500 ms
Feb 09 14:12:18.34: [  936]: SEND training at v.17 9600 bit/s
Feb 09 14:12:18.34: [  936]: <-- [9:AT+FTH=3\r]
Feb 09 14:12:18.53: [  936]: --> [7:CONNECT]
Feb 09 14:12:18.53: [  936]: <-- HDLC<23:FF C0 C2 2E 76 A6 B6 0E 96 AE 8E A2
04 76 86 A6 36 C2 4E A6 2E 76 92>
Feb 09 14:12:18.55: [  936]: --> [7:CONNECT]
Feb 09 14:12:18.55: [  936]: <-- HDLC<6:FF C8 C1 00 66 1E>
Feb 09 14:12:20.51: [  936]: --> [2:OK]
Feb 09 14:12:20.51: [  936]: <-- [9:AT+FTS=7\r]
Feb 09 14:12:20.59: [  936]: --> [2:OK]
Feb 09 14:12:20.59: [  936]: MODEM set XON/XOFF/FLUSH: input interpreted,
output disabled
Feb 09 14:12:20.59: [  936]: <-- [10:AT+FTM=97\r]
Feb 09 14:12:22.07: [  936]: --> [7:CONNECT]
Feb 09 14:12:23.60: [  936]: --> [2:OK]
Feb 09 14:12:23.60: [  936]: MODEM set XON/XOFF/DRAIN: input ignored, output
disabled
Feb 09 14:12:23.60: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:24.69: [  936]: --> [7:CONNECT]
Feb 09 14:12:25.23: [  936]: --> [20:E4 5C 82 20 8A A1 18 5C 91 90 C0 6D 6F
85 02 31 18 8A D6 1F]
Feb 09 14:12:25.23: [  936]: --> [3:F0 10 03]
Feb 09 14:12:25.23: [  936]: --> [5:ERROR]
Feb 09 14:12:25.23: [  936]: MODEM Command error
Feb 09 14:12:25.23: [  936]: FCS error
Feb 09 14:12:25.23: [  936]: DELAY 1500 ms
Feb 09 14:12:26.73: [  936]: SEND training at v.17 7200 bit/s
Feb 09 14:12:26.73: [  936]: <-- [9:AT+FTH=3\r]
Feb 09 14:12:26.92: [  936]: --> [7:CONNECT]
Feb 09 14:12:26.92: [  936]: <-- HDLC<23:FF C0 C2 2E 76 A6 B6 0E 96 AE 8E A2
04 76 86 A6 36 C2 4E A6 2E 76 92>
Feb 09 14:12:26.94: [  936]: --> [7:CONNECT]
Feb 09 14:12:26.94: [  936]: <-- HDLC<6:FF C8 C1 00 76 1E>
Feb 09 14:12:28.90: [  936]: --> [2:OK]
Feb 09 14:12:28.90: [  936]: <-- [9:AT+FTS=7\r]
Feb 09 14:12:28.98: [  936]: --> [2:OK]
Feb 09 14:12:28.98: [  936]: MODEM set XON/XOFF/FLUSH: input interpreted,
output disabled
Feb 09 14:12:28.98: [  936]: <-- [10:AT+FTM=73\r]
Feb 09 14:12:30.46: [  936]: --> [7:CONNECT]
Feb 09 14:12:32.00: [  936]: --> [2:OK]
Feb 09 14:12:32.00: [  936]: MODEM set XON/XOFF/DRAIN: input ignored, output
disabled
Feb 09 14:12:32.00: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:32.27: [  936]: --> [7:CONNECT]
Feb 09 14:12:32.72: [  936]: --> [18:D7 25 0E 04 E0 6D 9D 00 9E 98 8E 22 C7
40 D8 00 10 03]
Feb 09 14:12:32.72: [  936]: --> [5:ERROR]
Feb 09 14:12:32.72: [  936]: MODEM Command error
Feb 09 14:12:32.72: [  936]: FCS error
Feb 09 14:12:32.72: [  936]: DELAY 1500 ms
Feb 09 14:12:34.22: [  936]: SEND training at v.27ter 4800 bit/s
Feb 09 14:12:34.22: [  936]: <-- [9:AT+FTH=3\r]
Feb 09 14:12:34.41: [  936]: --> [7:CONNECT]
Feb 09 14:12:34.41: [  936]: <-- HDLC<23:FF C0 C2 2E 76 A6 B6 0E 96 AE 8E A2
04 76 86 A6 36 C2 4E A6 2E 76 92>
Feb 09 14:12:34.43: [  936]: --> [7:CONNECT]
Feb 09 14:12:34.43: [  936]: <-- HDLC<6:FF C8 C1 00 52 1E>
Feb 09 14:12:36.39: [  936]: --> [2:OK]
Feb 09 14:12:36.39: [  936]: <-- [9:AT+FTS=7\r]
Feb 09 14:12:36.47: [  936]: --> [2:OK]
Feb 09 14:12:36.47: [  936]: MODEM set XON/XOFF/FLUSH: input interpreted,
output disabled
Feb 09 14:12:36.47: [  936]: <-- [10:AT+FTM=48\r]
Feb 09 14:12:37.48: [  936]: --> [7:CONNECT]
Feb 09 14:12:39.03: [  936]: --> [2:OK]
Feb 09 14:12:39.03: [  936]: MODEM set XON/XOFF/DRAIN: input ignored, output
disabled
Feb 09 14:12:39.03: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:42.13: [  936]: --> [0:]
Feb 09 14:12:42.13: [  936]: MODEM <Empty line>
Feb 09 14:12:42.13: [  936]: MODEM TIMEOUT: waiting for v.21 carrier
Feb 09 14:12:42.14: [  936]: --> [2:OK]
Feb 09 14:12:42.14: [  936]: DELAY 1500 ms
Feb 09 14:12:43.64: [  936]: SEND training at v.27ter fallback mode 2400
bit/s
Feb 09 14:12:43.64: [  936]: <-- [9:AT+FTH=3\r]
Feb 09 14:12:43.67: [  936]: --> [7:CONNECT]
Feb 09 14:12:43.67: [  936]: <-- HDLC<23:FF C0 C2 2E 76 A6 B6 0E 96 AE 8E A2
04 76 86 A6 36 C2 4E A6 2E 76 92>
Feb 09 14:12:43.69: [  936]: --> [7:CONNECT]
Feb 09 14:12:43.69: [  936]: <-- HDLC<6:FF C8 C1 00 42 1E>
Feb 09 14:12:45.65: [  936]: --> [2:OK]
Feb 09 14:12:45.65: [  936]: <-- [9:AT+FTS=7\r]
Feb 09 14:12:45.73: [  936]: --> [2:OK]
Feb 09 14:12:45.73: [  936]: MODEM set XON/XOFF/FLUSH: input interpreted,
output disabled
Feb 09 14:12:45.73: [  936]: <-- [10:AT+FTM=24\r]
Feb 09 14:12:46.97: [  936]: --> [7:CONNECT]
Feb 09 14:12:48.55: [  936]: --> [2:OK]
Feb 09 14:12:48.55: [  936]: MODEM set XON/XOFF/DRAIN: input ignored, output
disabled
Feb 09 14:12:48.55: [  936]: <-- [9:AT+FRH=3\r]
Feb 09 14:12:51.65: [  936]: --> [0:]
Feb 09 14:12:51.65: [  936]: MODEM <Empty line>
Feb 09 14:12:51.65: [  936]: MODEM TIMEOUT: waiting for v.21 carrier
Feb 09 14:12:51.66: [  936]: --> [2:OK]
Feb 09 14:12:51.66: [  936]: DELAY 1500 ms
Feb 09 14:12:53.16: [  936]: TRAINING failed
Feb 09 14:12:53.16: [  936]: <-- [9:AT+FTH=3\r]
Feb 09 14:12:53.19: [  936]: --> [7:CONNECT]
Feb 09 14:12:53.19: [  936]: <-- HDLC<3:FF C8 DF>
Feb 09 14:12:54.37: [  936]: --> [2:OK]
Feb 09 14:12:54.37: [  936]: MODEM input buffering enabled
Feb 09 14:12:54.37: [  936]: <-- [5:ATH0\r]
Feb 09 14:12:54.60: [  936]: --> [2:OK]
Feb 09 14:12:54.60: [  936]: MODEM set DTR OFF
Feb 09 14:12:54.60: [  936]: 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*

Project hosted by iFAX Solutions