send faxes, but they arrive as garbage

[kanaan@if.ufrgs.br (Antonio Kanaan)]

Hello folks,

I have hylafax 4.0.pl1 on a Linux system (2.0.23 kernel).  

This is what my modem claims to be when I query it with 'AT I4':

Telepath 2 14,400/FAX/Voice RS Rev. 2.0

This is a class 1 fax/modem.

I've been trying to send and receive fax for a while now without
success.  I am now able to get my modem to call other phone numbers.
Once the call is completed two things may happen:

1) it does call, the other (FAX) machine answers and I get this:

(In short: it does get to the other machine and it tries to do the
training and never succeeds)

Apr 19 04:38:27.30: [ 1664]: SESSION BEGIN 00000055 55512264940
Apr 19 04:38:27.30: [ 1664]: SEND FAX: JOB 27 DEST 2264940 COMMID 00000055
Apr 19 04:38:27.30: [ 1664]: MODEM set DTR OFF
Apr 19 04:38:27.30: [ 1664]: DELAY 2600 ms
Apr 19 04:38:29.91: [ 1664]: MODEM set DTR ON
Apr 19 04:38:29.91: [ 1664]: MODEM set baud rate: 9600 baud, input flow XON/XOFF, output flow XON/XOFF
Apr 19 04:38:29.91: [ 1664]: MODEM flush i/o
Apr 19 04:38:29.92: [ 1664]: <-- [15:ATE0V1Q0S0=0H0\r]
Apr 19 04:38:30.07: [ 1664]: --> [2:OK]
Apr 19 04:38:30.07: [ 1664]: <-- [21:ATS8=2S7=60&K3&D2&C1\r]
Apr 19 04:38:30.22: [ 1664]: --> [2:OK]
Apr 19 04:38:30.22: [ 1664]: <-- [12:AT+FCLASS=1\r]
Apr 19 04:38:30.37: [ 1664]: --> [2:OK]
Apr 19 04:38:30.37: [ 1664]: <-- [7:ATL1M1\r]
Apr 19 04:38:30.51: [ 1664]: --> [2:OK]
Apr 19 04:38:30.51: [ 1664]: STATE CHANGE: RUNNING -> SENDING
Apr 19 04:38:30.51: [ 1664]: MODEM input buffering enabled
Apr 19 04:38:30.51: [ 1664]: Apply DialString rules to "2264940"
Apr 19 04:38:30.52: [ 1664]: --> return result "2264940"
Apr 19 04:38:30.52: [ 1664]: <-- [12:AT+FCLASS=1\r]
Apr 19 04:38:30.76: [ 1664]: --> [2:OK]
Apr 19 04:38:30.76: [ 1664]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled
Apr 19 04:38:30.77: [ 1664]: DIAL 2264940
Apr 19 04:38:30.77: [ 1664]: <-- [13:ATDT2264940@\r]
Apr 19 04:38:50.58: [ 1664]: --> [7:CONNECT]
Apr 19 04:38:50.58: [ 1664]: MODEM input buffering disabled
Apr 19 04:38:50.58: [ 1664]: --> HDLC<45:FF C0 04 00 00 9E 00 00 00 41 F0 90 48 00 08 A0 40 A1 13 11 01 01 80 80 92 40 62 A2 4A 72 82 72 22 F2 04 5A 82 E2 F2 04 04 04 C0 72 BA>
Apr 19 04:38:50.58: [ 1664]: --> [2:OK]
Apr 19 04:38:50.59: [ 1664]: <-- [9:AT+FRH=3\r]
Apr 19 04:38:50.61: [ 1664]: --> [7:CONNECT]
Apr 19 04:38:51.16: [ 1664]: --> HDLC<25:FF C0 02 0C 2C 9C 2C 04 6C 4C 4C 04 04 04 04 04 04 04 04 04 04 04 04 B7 55>
Apr 19 04:38:51.17: [ 1664]: --> [2:OK]
Apr 19 04:38:51.17: [ 1664]: REMOTE CSI "226 4940"
Apr 19 04:38:51.17: [ 1664]: <-- [9:AT+FRH=3\r]
Apr 19 04:38:51.20: [ 1664]: --> [7:CONNECT]
Apr 19 04:38:51.43: [ 1664]: --> HDLC<9:FF C8 01 00 72 1D 00 71 24>
Apr 19 04:38:51.44: [ 1664]: --> [2:OK]
Apr 19 04:38:51.44: [ 1664]: REMOTE best rate 9600 bit/s
Apr 19 04:38:51.44: [ 1664]: REMOTE max page width 1728 pixels in 215 mm
Apr 19 04:38:51.44: [ 1664]: REMOTE max unlimited page length 
Apr 19 04:38:51.44: [ 1664]: REMOTE best vres 7.7 line/mm
Apr 19 04:38:51.44: [ 1664]: REMOTE best format 1-D MR
Apr 19 04:38:51.45: [ 1664]: REMOTE best 20 ms, 10 ms/scanline
Apr 19 04:38:51.45: [ 1664]: USE 9600 bit/s
Apr 19 04:38:51.45: [ 1664]: USE 20 ms, 10 ms/scanline
Apr 19 04:38:51.45: [ 1664]: SEND file "docq/doc39.ps;30"
Apr 19 04:38:51.45: [ 1664]: USE page width 1728 pixels in 215 mm
Apr 19 04:38:51.45: [ 1664]: USE unlimited page length 
Apr 19 04:38:51.45: [ 1664]: USE 3.85 line/mm
Apr 19 04:38:51.45: [ 1664]: USE 1-D MR
Apr 19 04:38:51.45: [ 1664]: SEND training at v.29 9600 bit/s
Apr 19 04:38:51.45: [ 1664]: <-- [9:AT+FTH=3\r]
Apr 19 04:38:54.00: [ 1664]: MODEM TIMEOUT: reading line from modem
Apr 19 04:38:54.00: [ 1664]: Error sending T.30 prologue frames
... (lots of training trials)
Apr 19 04:39:09.30: [ 1664]: Error sending T.30 prologue frames
Apr 19 04:39:09.30: [ 1664]: SEND training at v.27ter fallback mode 2400 bit/s
Apr 19 04:39:09.30: [ 1664]: <-- [9:AT+FTH=3\r]
Apr 19 04:39:11.85: [ 1664]: MODEM TIMEOUT: reading line from modem
Apr 19 04:39:11.85: [ 1664]: Error sending T.30 prologue frames
Apr 19 04:39:11.85: [ 1664]: TRAINING failed
Apr 19 04:39:11.85: [ 1664]: <-- [9:AT+FTH=3\r]
Apr 19 04:39:14.40: [ 1664]: --> [0:]
Apr 19 04:39:14.40: [ 1664]: MODEM TIMEOUT: sending HDLC frame
Apr 19 04:39:14.40: [ 1664]: MODEM input buffering enabled
Apr 19 04:39:14.40: [ 1664]: <-- [5:ATH0\r]
Apr 19 04:39:19.40: [ 1664]: MODEM TIMEOUT: reading line from modem
Apr 19 04:39:19.40: [ 1664]: MODEM <Timeout>
Apr 19 04:39:19.40: [ 1664]: MODEM set DTR OFF
Apr 19 04:39:19.40: [ 1664]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
Apr 19 04:39:19.41: [ 1664]: SESSION END

2) With other machines (the same thing always happen to a given machine)
the training process works fine, the logs seem to indicate a succesful
transmission, but people on the other side of the line get garbage.
This is the log of one of these sessions (I don't see anything here
that may indicate problems):

Apr 21 12:48:33.19: [ 1520]: SESSION BEGIN 00000059 55513343306
Apr 21 12:48:33.19: [ 1520]: SEND FAX: JOB 32 DEST 3343306 COMMID 00000059
Apr 21 12:48:33.19: [ 1520]: MODEM set DTR OFF
Apr 21 12:48:33.19: [ 1520]: DELAY 2600 ms
Apr 21 12:48:35.80: [ 1520]: MODEM set DTR ON
Apr 21 12:48:35.81: [ 1520]: MODEM set baud rate: 9600 baud, input flow XON/XOFF, output flow XON/XOFF
Apr 21 12:48:35.81: [ 1520]: MODEM flush i/o
Apr 21 12:48:35.81: [ 1520]: <-- [15:ATE0V1Q0S0=0H0\r]
Apr 21 12:48:35.96: [ 1520]: --> [2:OK]
Apr 21 12:48:35.96: [ 1520]: <-- [21:ATS8=2S7=60&K3&D2&C1\r]
Apr 21 12:48:36.11: [ 1520]: --> [2:OK]
Apr 21 12:48:36.11: [ 1520]: <-- [12:AT+FCLASS=1\r]
Apr 21 12:48:36.26: [ 1520]: --> [2:OK]
Apr 21 12:48:36.26: [ 1520]: <-- [7:ATL1M1\r]
Apr 21 12:48:36.40: [ 1520]: --> [2:OK]
Apr 21 12:48:36.40: [ 1520]: STATE CHANGE: RUNNING -> SENDING
Apr 21 12:48:36.40: [ 1520]: MODEM input buffering enabled
Apr 21 12:48:36.40: [ 1520]: Apply DialString rules to "3343306"
Apr 21 12:48:36.40: [ 1520]: --> return result "3343306"
Apr 21 12:48:36.40: [ 1520]: <-- [12:AT+FCLASS=1\r]
Apr 21 12:48:36.65: [ 1520]: --> [2:OK]
Apr 21 12:48:36.86: [ 1520]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled
Apr 21 12:48:36.96: [ 1520]: DIAL 3343306
Apr 21 12:48:36.96: [ 1520]: <-- [13:ATDT3343306@\r]
Apr 21 12:49:24.22: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:24.22: [ 1520]: MODEM input buffering disabled
Apr 21 12:49:24.22: [ 1520]: --> HDLC<39:FF C0 04 00 00 8C 00 72 1D 00 21 B0 BB 00 00 BB BB 00 00 BB BB BB BB BB E9 20 84 40 C8 82 C0 B7 44 09 00 00 08 30 21>
Apr 21 12:49:24.22: [ 1520]: --> [2:OK]
Apr 21 12:49:24.22: [ 1520]: <-- [9:AT+FRH=3\r]
Apr 21 12:49:24.25: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:24.83: [ 1520]: --> HDLC<25:FF C0 02 04 6C 0C CC CC 2C CC CC D4 8C AC D4 AC AC 04 04 04 04 04 04 B6 9E>
Apr 21 12:49:24.84: [ 1520]: --> [2:OK]
Apr 21 12:49:24.84: [ 1520]: REMOTE CSI "55+51+3343306"
Apr 21 12:49:24.84: [ 1520]: <-- [9:AT+FRH=3\r]
Apr 21 12:49:24.87: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:25.10: [ 1520]: --> HDLC<9:FF C8 01 00 72 1D 00 71 24>
Apr 21 12:49:25.11: [ 1520]: --> [2:OK]
Apr 21 12:49:25.60: [ 1520]: REMOTE best rate 9600 bit/s
Apr 21 12:49:25.60: [ 1520]: REMOTE max page width 1728 pixels in 215 mm
Apr 21 12:49:25.60: [ 1520]: REMOTE max unlimited page length 
Apr 21 12:49:25.60: [ 1520]: REMOTE best vres 7.7 line/mm
Apr 21 12:49:25.60: [ 1520]: REMOTE best format 1-D MR
Apr 21 12:49:25.60: [ 1520]: REMOTE best 20 ms, 10 ms/scanline
Apr 21 12:49:25.60: [ 1520]: USE 9600 bit/s
Apr 21 12:49:25.60: [ 1520]: USE 20 ms, 10 ms/scanline
Apr 21 12:49:25.60: [ 1520]: SEND file "docq/doc44.ps;30"
Apr 21 12:49:25.68: [ 1520]: USE page width 1728 pixels in 215 mm
Apr 21 12:49:25.68: [ 1520]: USE unlimited page length 
Apr 21 12:49:25.68: [ 1520]: USE 3.85 line/mm
Apr 21 12:49:25.68: [ 1520]: USE 1-D MR
Apr 21 12:49:25.68: [ 1520]: SEND training at v.29 9600 bit/s
Apr 21 12:49:25.70: [ 1520]: <-- [9:AT+FTH=3\r]
Apr 21 12:49:25.75: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:25.75: [ 1520]: <-- HDLC<23:FF C0 C2 CC 04 96 4E 46 86 E2 F4 96 CE 96 32 F4 F6 96 76 F6 2E 76 82>
Apr 21 12:49:25.75: [ 1520]: <-- data [23]
Apr 21 12:49:25.75: [ 1520]: <-- data [2]
Apr 21 12:49:27.19: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:27.19: [ 1520]: <-- HDLC<6:FF C8 C1 00 60 10>
Apr 21 12:49:27.19: [ 1520]: <-- data [6]
Apr 21 12:49:27.19: [ 1520]: <-- data [2]
Apr 21 12:49:27.75: [ 1520]: --> [2:OK]
Apr 21 12:49:27.75: [ 1520]: DELAY 75 ms
Apr 21 12:49:27.84: [ 1520]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Apr 21 12:49:27.84: [ 1520]: <-- [10:AT+FTM=96\r]
Apr 21 12:49:28.18: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:28.18: [ 1520]: <-- data [1024]
Apr 21 12:49:28.18: [ 1520]: <-- data [776]
Apr 21 12:49:28.18: [ 1520]: <-- data [2]
Apr 21 12:49:30.17: [ 1520]: --> [2:OK]
Apr 21 12:49:30.17: [ 1520]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Apr 21 12:49:30.17: [ 1520]: <-- [9:AT+FRH=3\r]
Apr 21 12:49:31.27: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:31.39: [ 1520]: --> HDLC<5:FF C8 21 57 BE>
Apr 21 12:49:31.40: [ 1520]: --> [2:OK]
Apr 21 12:49:31.40: [ 1520]: TRAINING succeeded
Apr 21 12:49:31.40: [ 1520]: <-- [10:AT+FTM=96\r]
Apr 21 12:49:31.74: [ 1520]: --> [7:CONNECT]
Apr 21 12:49:31.74: [ 1520]: SEND begin page
Apr 21 12:49:31.74: [ 1520]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Apr 21 12:49:31.77: [ 1520]: <-- data [1028]
... (lots of lines saying the same)
Apr 21 12:49:55.85: [ 1520]: <-- data [1024]
Apr 21 12:49:55.86: [ 1520]: <-- data [874]
Apr 21 12:49:59.85: [ 1520]: SENT 27498 bytes of data
Apr 21 12:49:59.85: [ 1520]: <-- data [768]
Apr 21 12:49:59.85: [ 1520]: SENT 768 bytes of data
Apr 21 12:49:59.86: [ 1520]: SEND 1D RTC
Apr 21 12:49:59.86: [ 1520]: <-- data [29]
Apr 21 12:49:59.86: [ 1520]: <-- data [2]
Apr 21 12:49:59.86: [ 1520]: SEND end page
Apr 21 12:50:01.38: [ 1520]: --> [2:OK]
Apr 21 12:50:01.38: [ 1520]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Apr 21 12:50:01.38: [ 1520]: DELAY 75 ms
Apr 21 12:50:01.47: [ 1520]: SEND send MPS (more pages, same document)
Apr 21 12:50:01.47: [ 1520]: <-- [9:AT+FTH=3\r]
Apr 21 12:50:01.52: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:01.52: [ 1520]: <-- HDLC<3:FF C8 F2>
Apr 21 12:50:01.52: [ 1520]: <-- data [3]
Apr 21 12:50:01.52: [ 1520]: <-- data [2]
Apr 21 12:50:02.72: [ 1520]: --> [2:OK]
Apr 21 12:50:02.72: [ 1520]: <-- [9:AT+FRH=3\r]
Apr 21 12:50:04.66: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:04.78: [ 1520]: --> HDLC<5:FF C8 32 75 EC>
Apr 21 12:50:04.79: [ 1520]: --> [2:OK]
Apr 21 12:50:04.79: [ 1520]: SEND recv RTN (retrain negative)
Apr 21 12:50:04.79: [ 1520]: SEND training at v.29 9600 bit/s
Apr 21 12:50:04.79: [ 1520]: <-- [9:AT+FTH=3\r]
Apr 21 12:50:04.84: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:04.84: [ 1520]: <-- HDLC<23:FF C0 C2 CC 04 96 4E 46 86 E2 F4 96 CE 96 32 F4 F6 96 76 F6 2E 76 82>
Apr 21 12:50:04.84: [ 1520]: <-- data [23]
Apr 21 12:50:04.84: [ 1520]: <-- data [2]
Apr 21 12:50:06.26: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:06.26: [ 1520]: <-- HDLC<6:FF C8 C1 00 60 10>
Apr 21 12:50:06.26: [ 1520]: <-- data [6]
Apr 21 12:50:06.26: [ 1520]: <-- data [2]
Apr 21 12:50:06.84: [ 1520]: --> [2:OK]
Apr 21 12:50:06.84: [ 1520]: DELAY 75 ms
Apr 21 12:50:06.93: [ 1520]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Apr 21 12:50:06.93: [ 1520]: <-- [10:AT+FTM=96\r]
Apr 21 12:50:07.27: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:07.27: [ 1520]: <-- data [1024]
Apr 21 12:50:07.27: [ 1520]: <-- data [776]
Apr 21 12:50:07.27: [ 1520]: <-- data [2]
Apr 21 12:50:09.26: [ 1520]: --> [2:OK]
Apr 21 12:50:09.26: [ 1520]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Apr 21 12:50:09.26: [ 1520]: <-- [9:AT+FRH=3\r]
Apr 21 12:50:10.36: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:10.48: [ 1520]: --> HDLC<5:FF C8 21 57 BE>
Apr 21 12:50:10.49: [ 1520]: --> [2:OK]
Apr 21 12:50:10.49: [ 1520]: TRAINING succeeded
Apr 21 12:50:10.49: [ 1520]: <-- [10:AT+FTM=96\r]
Apr 21 12:50:10.83: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:10.83: [ 1520]: SEND begin page
Apr 21 12:50:10.83: [ 1520]: MODEM set XON/XOFF/FLUSH: input interpreted, output disabled
Apr 21 12:50:10.84: [ 1520]: <-- data [1028]
Apr 21 12:50:10.84: [ 1520]: <-- data [1024]
Apr 21 12:50:10.84: [ 1520]: <-- data [1024]
Apr 21 12:50:10.84: [ 1520]: <-- data [1027]
Apr 21 12:50:10.84: [ 1520]: <-- data [1031]
Apr 21 12:50:14.84: [ 1520]: <-- data [1025]
Apr 21 12:50:14.84: [ 1520]: <-- data [1025]
Apr 21 12:50:14.84: [ 1520]: <-- data [1024]
...
Apr 21 12:50:34.84: [ 1520]: <-- data [1024]
Apr 21 12:50:34.84: [ 1520]: <-- data [1024]
Apr 21 12:50:34.84: [ 1520]: <-- data [874]
Apr 21 12:50:38.84: [ 1520]: SENT 27498 bytes of data
Apr 21 12:50:38.84: [ 1520]: <-- data [768]
Apr 21 12:50:38.84: [ 1520]: SENT 768 bytes of data
Apr 21 12:50:38.84: [ 1520]: SEND 1D RTC
Apr 21 12:50:38.84: [ 1520]: <-- data [29]
Apr 21 12:50:38.85: [ 1520]: <-- data [2]
Apr 21 12:50:38.85: [ 1520]: SEND end page
Apr 21 12:50:40.45: [ 1520]: --> [2:OK]
Apr 21 12:50:40.47: [ 1520]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Apr 21 12:50:40.47: [ 1520]: DELAY 75 ms
Apr 21 12:50:40.56: [ 1520]: SEND send MPS (more pages, same document)
Apr 21 12:50:40.56: [ 1520]: <-- [9:AT+FTH=3\r]
Apr 21 12:50:40.61: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:40.61: [ 1520]: <-- HDLC<3:FF C8 F2>
Apr 21 12:50:40.61: [ 1520]: <-- data [3]
Apr 21 12:50:40.61: [ 1520]: <-- data [2]
Apr 21 12:50:41.81: [ 1520]: --> [2:OK]
Apr 21 12:50:41.81: [ 1520]: <-- [9:AT+FRH=3\r]
Apr 21 12:50:43.81: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:43.96: [ 1520]: --> HDLC<5:FF C8 5F C8 E7>
Apr 21 12:50:43.97: [ 1520]: --> [2:OK]
Apr 21 12:50:43.97: [ 1520]: SEND recv DCN (disconnect)
Apr 21 12:50:43.97: [ 1520]: <-- [9:AT+FTH=3\r]
Apr 21 12:50:44.02: [ 1520]: --> [7:CONNECT]
Apr 21 12:50:44.02: [ 1520]: <-- HDLC<3:FF C8 DF>
Apr 21 12:50:44.02: [ 1520]: <-- data [3]
Apr 21 12:50:44.02: [ 1520]: <-- data [2]
Apr 21 12:50:45.22: [ 1520]: --> [2:OK]
Apr 21 12:50:45.22: [ 1520]: MODEM input buffering enabled
Apr 21 12:50:45.22: [ 1520]: <-- [5:ATH0\r]
Apr 21 12:50:45.46: [ 1520]: --> [2:OK]
Apr 21 12:50:45.46: [ 1520]: MODEM set DTR OFF
Apr 21 12:50:45.46: [ 1520]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
Apr 21 12:50:45.46: [ 1520]: SESSION END


Sorry for the long message.  As I don't know where the problem is I
thought it would be better to send a log as complete as possible.  I
only erased lines that were clearly repetitive and indicated that with
...


I am sending a PS file.  I also checked the ps2fax scrpt, creating a tiff
file, and checked that file, it looks fine.  Therefore, I believe the
problem is in the transmission process, not in the file conversion.
Thanks,

Antonio

-- 
Antonio Kanaan
Astronomy Postdoc
Instituto de Fisica - Universidade Federal do Rio Grande do Sul
kanaan@if.ufrgs.br
phone = 55.51.3166432
fax   = 55.51.3191762
http://www.if.ufrgs.br/~kanaan