[hylafax-users] HylaFAX (tm) Version 5.4.1 - Unspecified Transmit Phase C error {E149}

[Derek LAM]

hi,

we are using (HylaFAX (tm) Version 5.4.1 on Fedora release 11.

we consistently could not fax to certain destinations with log below
(the destination number is masked with xxxx). we get the same failure
with flow control xon/xoff and rtscts.

Apr 17 08:56:28.27: [16553]: SESSION BEGIN 002600120 150077797004656222xxxx
Apr 17 08:56:28.27: [16553]: HylaFAX (tm) Version 5.4.1
Apr 17 08:56:28.27: [16553]: SEND FAX: JOB 1804465 DEST
150077797004656222xxxx COMMID 002600120 DEVICE '/dev/ttyIAX10' FROM
'LAM_Derek <LAM_...@virtualbox01.zonetel.com>' USER 15007779
Apr 17 08:56:28.27: [16553]: STATE CHANGE: RUNNING -> SENDING
Apr 17 08:56:28.27: [16553]: <-- [12:AT+FCLASS=1\r]
Apr 17 08:56:28.27: [16553]: --> [2:OK]
4月 17 08:56:28.33: [16553]: DIAL 150077797004656222xxxx
4月 17 08:56:28.33: [16553]: <-- [27:ATDT150077797004656222xxxx\r]
4月 17 08:56:49.32: [16553]: --> [7:CONNECT]
4月 17 08:56:49.41: [16553]: --> [10:NO CARRIER]
4月 17 08:56:49.41: [16553]: MODEM No carrier
4月 17 08:56:49.41: [16553]: DELAY 70 ms
4月 17 08:56:49.48: [16553]: <-- [9:AT+FTH=3\r]
4月 17 08:56:49.49: [16553]: --> [7:CONNECT]
4月 17 08:56:49.49: [16553]: <-- HDLC<3:FF C8 D8>
4月 17 08:56:49.49: [16553]: <-- data [3]
4月 17 08:56:49.49: [16553]: <-- data [2]
4月 17 08:56:50.59: [16553]: --> [2:OK]
4月 17 08:56:50.59: [16553]: SEND send CRP (command repeat)
4月 17 08:56:50.59: [16553]: <-- [9:AT+FRH=3\r]
4月 17 08:56:56.61: [16553]: --> [7:CONNECT]
4月 17 08:56:58.36: [16553]: --> HDLC<25:FF C0 02 04 04 04 04 04 04 04
04 04 04 04 04 04 04 04 04 04 1E 86 62 51 CB>
4月 17 08:56:58.36: [16553]: --> [2:OK]
4月 17 08:56:58.36: [16553]: REMOTE CSI "Fax"
4月 17 08:56:58.36: [16553]: <-- [9:AT+FRH=3\r]
4月 17 08:56:58.74: [16553]: --> [7:CONNECT]
4月 17 08:56:58.74: [16553]: --> HDLC<9:FF C8 01 00 76 1E 00 F8 B7>
4月 17 08:56:58.76: [16553]: --> [2:OK]
4月 17 08:56:58.76: [16553]: REMOTE best rate 14400 bit/s
4月 17 08:56:58.76: [16553]: REMOTE max A4 page width (215 mm)
4月 17 08:56:58.76: [16553]: REMOTE max unlimited page length
4月 17 08:56:58.76: [16553]: REMOTE best vres 7.7 line/mm
4月 17 08:56:58.76: [16553]: REMOTE format support: MH
4月 17 08:56:58.76: [16553]: REMOTE best 0 ms/scanline
4月 17 08:56:58.76: [16553]: USE 9600 bit/s
4月 17 08:56:58.76: [16553]: SEND file "docq/doc1807692.tif;1c61"
4月 17 08:56:58.76: [16553]: USE A4 page width (215 mm)
4月 17 08:56:58.76: [16553]: USE unlimited page length
4月 17 08:56:58.76: [16553]: USE 7.7 line/mm
4月 17 08:56:58.76: [16553]: USE 1-D MH
4月 17 08:56:58.76: [16553]: USE 0 ms/scanline
4月 17 08:56:58.76: [16553]: SEND training at v.29 9600 bit/s
4月 17 08:56:58.76: [16553]: DELAY 70 ms
4月 17 08:56:58.83: [16553]: <-- [9:AT+FTH=3\r]
4月 17 08:56:58.84: [16553]: --> [7:CONNECT]
4月 17 08:56:58.84: [16553]: <-- HDLC<23:FF C0 C2 0C 8C 9C 4C CC 04 04
04 04 04 04 04 04 04 04 04 04 04 04 04>
4月 17 08:56:58.84: [16553]: <-- data [23]
4月 17 08:56:58.84: [16553]: <-- data [2]
4月 17 08:57:00.44: [16553]: --> [7:CONNECT]
4月 17 08:57:00.44: [16553]: <-- HDLC<6:FF C8 C1 00 62 1E>
4月 17 08:57:00.44: [16553]: <-- data [6]
4月 17 08:57:00.44: [16553]: <-- data [2]
4月 17 08:57:00.82: [16553]: --> [2:OK]
4月 17 08:57:00.82: [16553]: <-- [9:AT+FTS=7\r]
4月 17 08:57:00.92: [16553]: --> [2:OK]
4月 17 08:57:00.92: [16553]: <-- [10:AT+FTM=96\r]
4月 17 08:57:00.94: [16553]: --> [7:CONNECT]
4月 17 08:57:00.94: [16553]: DELAY 400 ms
4月 17 08:57:01.34: [16553]: <-- data [1024]
4月 17 08:57:01.34: [16553]: <-- data [776]
4月 17 08:57:01.34: [16553]: <-- data [2]
4月 17 08:57:02.96: [16553]: --> [2:OK]
4月 17 08:57:02.96: [16553]: <-- [9:AT+FRH=3\r]
4月 17 08:57:06.06: [16553]: --> [0:]
4月 17 08:57:06.06: [16553]: MODEM <Empty line>
4月 17 08:57:06.06: [16553]: MODEM TIMEOUT: waiting for v.21 carrier
4月 17 08:57:06.06: [16553]: <-- data [1]
4月 17 08:57:06.08: [16553]: --> [2:OK]
4月 17 08:57:06.08: [16553]: DELAY 70 ms
4月 17 08:57:06.15: [16553]: SEND training at v.29 7200 bit/s
4月 17 08:57:06.15: [16553]: <-- [9:AT+FTH=3\r]
4月 17 08:57:06.16: [16553]: --> [7:CONNECT]
4月 17 08:57:06.16: [16553]: <-- HDLC<23:FF C0 C2 0C 8C 9C 4C CC 04 04
04 04 04 04 04 04 04 04 04 04 04 04 04>
4月 17 08:57:06.16: [16553]: <-- data [23]
4月 17 08:57:06.16: [16553]: <-- data [2]
4月 17 08:57:07.76: [16553]: --> [7:CONNECT]
4月 17 08:57:07.76: [16553]: <-- HDLC<6:FF C8 C1 00 72 1E>
4月 17 08:57:07.76: [16553]: <-- data [6]
4月 17 08:57:07.76: [16553]: <-- data [2]
4月 17 08:57:08.13: [16553]: --> [2:OK]
4月 17 08:57:08.13: [16553]: <-- [9:AT+FTS=7\r]
4月 17 08:57:08.23: [16553]: --> [2:OK]
4月 17 08:57:08.23: [16553]: <-- [10:AT+FTM=72\r]
4月 17 08:57:08.25: [16553]: --> [7:CONNECT]
4月 17 08:57:08.25: [16553]: DELAY 400 ms
4月 17 08:57:08.66: [16553]: <-- data [1024]
4月 17 08:57:08.66: [16553]: <-- data [326]
4月 17 08:57:08.66: [16553]: <-- data [2]
4月 17 08:57:10.27: [16553]: --> [2:OK]
4月 17 08:57:10.27: [16553]: <-- [9:AT+FRH=3\r]
4月 17 08:57:11.78: [16553]: --> [7:CONNECT]
4月 17 08:57:12.96: [16553]: --> HDLC<5:FF C8 21 57 BE>
4月 17 08:57:13.00: [16553]: --> [2:OK]
4月 17 08:57:13.00: [16553]: TRAINING succeeded
4月 17 08:57:13.00: [16553]: DELAY 70 ms
4月 17 08:57:13.07: [16553]: <-- [10:AT+FTM=72\r]
4月 17 08:57:13.08: [16553]: --> [7:CONNECT]
4月 17 08:57:13.11: [16553]: DELAY 400 ms
4月 17 08:57:13.51: [16553]: SEND begin page
4月 17 08:57:13.51: [16553]: <-- data [1026]
4月 17 08:57:13.51: [16553]: <-- data [1026]
4月 17 08:57:13.51: [16553]: <-- data [1025]
4月 17 08:57:13.51: [16553]: <-- data [1030]
4月 17 08:57:13.52: [16553]: <-- data [1031]
4月 17 08:57:13.52: [16553]: <-- data [1032]
4月 17 08:57:13.52: [16553]: <-- data [1032]
4月 17 08:57:13.52: [16553]: <-- data [1031]
4月 17 08:57:18.23: [16553]: <-- data [1027]
4月 17 08:57:18.23: [16553]: <-- data [1025]
4月 17 08:57:18.23: [16553]: <-- data [1026]
4月 17 08:57:18.23: [16553]: <-- data [1024]
4月 17 08:57:22.94: [16553]: <-- data [1025]
4月 17 08:57:22.94: [16553]: <-- data [1029]
4月 17 08:57:22.94: [16553]: <-- data [1025]
4月 17 08:57:22.94: [16553]: <-- data [1028]
4月 17 08:57:27.63: [16553]: <-- data [1026]
4月 17 08:57:27.63: [16553]: <-- data [1027]
4月 17 08:57:27.63: [16553]: <-- data [1029]
4月 17 08:57:27.63: [16553]: <-- data [1025]
4月 17 08:57:32.32: [16553]: <-- data [1026]
4月 17 08:57:32.32: [16553]: <-- data [1025]
4月 17 08:57:32.32: [16553]: <-- data [1029]
4月 17 08:57:32.32: [16553]: <-- data [1026]
4月 17 08:57:37.01: [16553]: <-- data [1025]
4月 17 08:57:37.01: [16553]: <-- data [1024]
4月 17 08:57:37.01: [16553]: <-- data [1025]
4月 17 08:57:37.01: [16553]: <-- data [1029]
4月 17 08:57:41.68: [16553]: <-- data [1027]
4月 17 08:57:41.68: [16553]: <-- data [1026]
4月 17 08:57:41.68: [16553]: <-- data [1029]
4月 17 08:57:41.68: [16553]: <-- data [1026]
4月 17 08:57:46.35: [16553]: <-- data [1027]
4月 17 08:57:46.35: [16553]: <-- data [1027]
4月 17 08:57:46.35: [16553]: <-- data [1028]
4月 17 08:57:46.35: [16553]: <-- data [1030]
4月 17 08:57:46.49: [16553]: <-- data [1025]
4月 17 08:57:46.49: [16553]: <-- data [1027]
4月 17 08:57:46.49: [16553]: <-- data [1027]
4月 17 08:57:46.49: [16553]: <-- data [1026]
4月 17 08:57:46.49: [16553]: <-- data [1027]
4月 17 08:57:46.49: [16553]: <-- data [1029]
4月 17 08:57:46.49: [16553]: <-- data [1026]
4月 17 08:57:46.49: [16553]: <-- data [1027]
4月 17 08:57:46.49: [16553]: <-- data [1027]
4月 17 08:57:46.49: [16553]: <-- data [1024]
4月 17 08:57:46.49: [16553]: <-- data [1016]
4月 17 08:57:46.49: [16553]: SENT 48120 bytes of data
4月 17 08:57:46.49: [16553]: SEND 1D RTC
4月 17 08:57:46.49: [16553]: <-- data [29]
4月 17 08:57:46.49: [16553]: <-- data [2]
4月 17 08:57:46.49: [16553]: SEND end page
4月 17 08:57:46.49: [16553]: --> [58: ]
4月 17 08:57:46.49: [16553]: --> [10:NO CARRIER]
4月 17 08:57:46.49: [16553]: MODEM flush i/o
4月 17 08:57:46.49: [16553]: Unspecified Transmit Phase C error {E149}
4月 17 08:57:46.49: [16553]: DELAY 70 ms
4月 17 08:57:46.56: [16553]: <-- [9:AT+FTH=3\r]
4月 17 08:57:46.57: [16553]: --> [5:ERROR]
4月 17 08:57:46.57: [16553]: MODEM input buffering enabled
4月 17 08:57:46.57: [16553]: SEND FAILED: JOB 1804465 DEST
150077797004656222xxxx ERR Unspecified Transmit Phase C error {E149};
too many attempts to dial
4月 17 08:57:47.57: [16553]: <-- [5:ATH0\r]
4月 17 08:57:47.67: [16553]: --> [2:OK]
4月 17 08:57:47.67: [16553]: MODEM set DTR OFF
4月 17 08:57:47.67: [16553]: MODEM set baud rate: 0 baud (flow control
unchanged)
4月 17 08:57:47.67: [16553]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
4月 17 08:57:47.67: [16553]: SESSION END


your kind advice is much appreciated.

regards,
derek


____________________ HylaFAX(tm) Users Mailing List _______________________
To subscribe/unsubscribe, click http://lists.hylafax.org/cgi-bin/lsg2.cgi
On UNIX: mail -s unsubscribe hylafax-us...@hylafax.org < /dev/null
*To learn about commercial HylaFAX(tm) support, mail sa...@ifax.com.*

[Lee Howard]

On 04/16/2012 06:47 PM, Derek LAM wrote:
> 4月 17 08:56:58.36: [16553]: <-- [9:AT+FRH=3\r]
> 4月 17 08:56:58.74: [16553]: --> [7:CONNECT]
> 4月 17 08:56:58.74: [16553]: --> HDLC<9:FF C8 01 00 76 1E 00 F8 B7>
> 4月 17 08:56:58.76: [16553]: --> [2:OK]
> 4月 17 08:56:58.76: [16553]: REMOTE best rate 14400 bit/s
> 4月 17 08:56:58.76: [16553]: REMOTE max A4 page width (215 mm)
> 4月 17 08:56:58.76: [16553]: REMOTE max unlimited page length
> 4月 17 08:56:58.76: [16553]: REMOTE best vres 7.7 line/mm
> 4月 17 08:56:58.76: [16553]: REMOTE format support: MH
> 4月 17 08:56:58.76: [16553]: REMOTE best 0 ms/scanline
> 4月 17 08:56:58.76: [16553]: USE 9600 bit/s
> 4月 17 08:56:58.76: [16553]: SEND file "docq/doc1807692.tif;1c61"
> 4月 17 08:56:58.76: [16553]: USE A4 page width (215 mm)
> 4月 17 08:56:58.76: [16553]: USE unlimited page length
> 4月 17 08:56:58.76: [16553]: USE 7.7 line/mm
> 4月 17 08:56:58.76: [16553]: USE 1-D MH
> 4月 17 08:56:58.76: [16553]: USE 0 ms/scanline
> 4月 17 08:56:58.76: [16553]: SEND training at v.29 9600 bit/s

So the receiver supports V.17 and yet you're not attempting V.17 and
instead are preferring V.29. Are you using an old iaxmodem version from
before V.17 support was stable?

Something wasn't right with the V.29 9600 bps training. It's not clear
what, exactly, was the problem, though. It does subsequently train with
V.29 7200 bps.

> 4月 17 08:57:46.49: [16553]: <-- data [1027]
> 4月 17 08:57:46.49: [16553]: <-- data [1024]
> 4月 17 08:57:46.49: [16553]: <-- data [1016]
> 4月 17 08:57:46.49: [16553]: SENT 48120 bytes of data
> 4月 17 08:57:46.49: [16553]: SEND 1D RTC
> 4月 17 08:57:46.49: [16553]: <-- data [29]
> 4月 17 08:57:46.49: [16553]: <-- data [2]
> 4月 17 08:57:46.49: [16553]: SEND end page
> 4月 17 08:57:46.49: [16553]: --> [58: ]
>
> 4月 17 08:57:46.49: [16553]: --> [10:NO CARRIER]

So the call is disconnected sometime in the middle of Phase C. There's
no real explanation as to why from the sender's side. We'd really need
to know what the receiver thought... since it's probably the one that
initiated the disconnection.

Thanks,

Lee.