[hylafax-users] Hylafax comportation with high latency...

[Diego Ercolani <Diego.Ercolani@xxxxxxxxx>]

Hallo,
I would like to use hylafax with fastweb.
Fastweb is a Telco Company that gives mainly internet data connection over 
fiberglass, but as a classic telco company permits to have a classic phone 
line FXO mapped on their apparates so you can connect a standard phone that 
is then converted in VOIP stream (they said that codec is u-law so lossless).
The very annoying problem is that you can have a call with about 1 second of 
latency. This (I think) would really decrease Hylafax reliability.
What I have is that from the old installation of Hylafax where we had a 
classic copper phone pair, and hylafax did its work very well, now we are 
experiency the situation where transmit and receive faxes with hylafax is 
very difficult, many tryies and many requeues.
Prartial transmits and partial receives.
Reports from hylafax say only:
Communication failure during Phase B/C
But having a look to a session log runtime, it's possible to see that at some 
point transmission end while in a page and then after a timeout of 1min:20 
seconds, hylafax resumes its state.
But stop transmission.
The only difference was the line: before we have a copper line, after a 
fiberglass and VOIP.
Could it be a problem of high latency?
I've tryied with a standard fax machine (hp multifunction printer) and all 
work well......
How can hylafax help me?
For convenience I've included a sample log. Note that at about 17:49:38 modem 
stop writing data:
Sep 16 17:49:38.89: [ 4976]: <-- data [1026]
and then hylafax resumes with error:
Sep 16 17:50:58.88: [ 4976]: MODEM TIMEOUT: writing to modem
Sep 16 17:50:58.88: [ 4976]: MODEM WRITE SHORT: sent 1026, wrote 817
Sep 16 17:50:58.88: [ 4976]: SENT 22472 bytes of data
Sep 16 17:50:58.88: [ 4976]: SEND abort data transfer

Sep 16 17:48:20.30: [ 4976]: SESSION BEGIN 00000242 390510240915002
Sep 16 17:48:20.30: [ 4976]: HylaFAX (tm) Version 4.1.8
Sep 16 17:48:20.30: [ 4976]: SEND FAX: JOB 44 DEST 0240915002 COMMID 00000242 DEVICE '/dev/modem-conexant'
Sep 16 17:48:20.30: [ 4976]: MODEM set DTR OFF
Sep 16 17:48:20.30: [ 4976]: DELAY 75 ms
Sep 16 17:48:20.38: [ 4976]: MODEM set DTR ON
Sep 16 17:48:20.38: [ 4976]: DELAY 2600 ms
Sep 16 17:48:23.98: [ 4976]: MODEM set baud rate: 19200 baud, input flow RTS/CTS, output flow RTS/CTS
Sep 16 17:48:23.98: [ 4976]: DELAY 10 ms
Sep 16 17:48:23.99: [ 4976]: MODEM flush i/o
Sep 16 17:48:23.99: [ 4976]: <-- [4:ATZ\r]
Sep 16 17:48:24.11: [ 4976]: --> [2:OK]
Sep 16 17:48:24.11: [ 4976]: DELAY 3000 ms
Sep 16 17:48:27.11: [ 4976]: <-- [5:ATE0\r]
Sep 16 17:48:27.12: [ 4976]: --> [4:ATE0]
Sep 16 17:48:27.12: [ 4976]: --> [2:OK]
Sep 16 17:48:27.12: [ 4976]: <-- [5:ATV1\r]
Sep 16 17:48:27.13: [ 4976]: --> [2:OK]
Sep 16 17:48:27.13: [ 4976]: <-- [5:ATQ0\r]
Sep 16 17:48:27.14: [ 4976]: --> [2:OK]
Sep 16 17:48:27.14: [ 4976]: <-- [7:ATS0=0\r]
Sep 16 17:48:27.15: [ 4976]: --> [2:OK]
Sep 16 17:48:27.15: [ 4976]: <-- [7:ATS8=2\r]
Sep 16 17:48:27.16: [ 4976]: --> [2:OK]
Sep 16 17:48:27.16: [ 4976]: <-- [8:ATS7=60\r]
Sep 16 17:48:27.17: [ 4976]: --> [2:OK]
Sep 16 17:48:27.17: [ 4976]: <-- [6:AT&K3\r]
Sep 16 17:48:27.18: [ 4976]: --> [2:OK]
Sep 16 17:48:27.18: [ 4976]: <-- [6:AT&D3\r]
Sep 16 17:48:27.19: [ 4976]: --> [2:OK]
Sep 16 17:48:27.19: [ 4976]: <-- [6:AT&C1\r]
Sep 16 17:48:27.20: [ 4976]: --> [2:OK]
Sep 16 17:48:27.20: [ 4976]: <-- [9:at#CLS=2\r]
Sep 16 17:48:27.81: [ 4976]: --> [2:OK]
Sep 16 17:48:27.81: [ 4976]: <-- [10:AT+FTBC=0\r]
Sep 16 17:48:27.83: [ 4976]: --> [2:OK]
Sep 16 17:48:27.83: [ 4976]: <-- [10:AT+FBOR=0\r]
Sep 16 17:48:27.84: [ 4976]: --> [2:OK]
Sep 16 17:48:27.84: [ 4976]: <-- [13:AT+FPHCTO=30\r]
Sep 16 17:48:27.85: [ 4976]: --> [2:OK]
Sep 16 17:48:27.85: [ 4976]: <-- [24:AT+FDCC=1,5,2,2,0,0,0,0\r]
Sep 16 17:48:27.87: [ 4976]: --> [2:OK]
Sep 16 17:48:27.87: [ 4976]: <-- [7:ATL2M1\r]
Sep 16 17:48:27.88: [ 4976]: --> [2:OK]
Sep 16 17:48:27.88: [ 4976]: MODEM input buffering enabled
Sep 16 17:48:27.88: [ 4976]: <-- [9:at#CLS=2\r]
Sep 16 17:48:27.99: [ 4976]: --> [2:OK]
Sep 16 17:48:27.99: [ 4976]: <-- [10:AT+FTBC=0\r]
Sep 16 17:48:28.11: [ 4976]: --> [2:OK]
Sep 16 17:48:28.11: [ 4976]: <-- [10:AT+FBOR=0\r]
Sep 16 17:48:28.22: [ 4976]: --> [2:OK]
Sep 16 17:48:28.22: [ 4976]: <-- [13:AT+FPHCTO=30\r]
Sep 16 17:48:28.33: [ 4976]: --> [2:OK]
Sep 16 17:48:28.33: [ 4976]: <-- [24:AT+FDCC=1,5,2,2,0,0,0,0\r]
Sep 16 17:48:28.45: [ 4976]: --> [2:OK]
Sep 16 17:48:28.45: [ 4976]: <-- [20:AT+FLID="Yacme srl"\r]
Sep 16 17:48:28.57: [ 4976]: --> [2:OK]
Sep 16 17:48:28.57: [ 4976]: DIAL 0240915002
Sep 16 17:48:28.57: [ 4976]: <-- [15:ATDT02123456\r]
Sep 16 17:48:53.41: [ 4976]: --> [5:+FCON]
Sep 16 17:48:55.50: [ 4976]: --> [29:+FCSI: "         02123456"]
Sep 16 17:48:55.50: [ 4976]: REMOTE CSI "02123456"
Sep 16 17:48:55.82: [ 4976]: --> [22:+FDIS: 1,5,0,2,1,0,0,3]
Sep 16 17:48:55.93: [ 4976]: --> [2:OK]
Sep 16 17:48:55.93: [ 4976]: REMOTE best rate 14400 bit/s
Sep 16 17:48:55.93: [ 4976]: REMOTE max page width 1728 pixels in 215 mm
Sep 16 17:48:55.93: [ 4976]: REMOTE max unlimited page length
Sep 16 17:48:55.93: [ 4976]: REMOTE best vres 7.7 line/mm
Sep 16 17:48:55.93: [ 4976]: REMOTE best format 2-D MR
Sep 16 17:48:55.93: [ 4976]: REMOTE best 10 ms/scanline
Sep 16 17:48:55.93: [ 4976]: USE 9600 bit/s
Sep 16 17:48:55.93: [ 4976]: USE 10 ms/scanline
Sep 16 17:48:55.93: [ 4976]: SEND file "docq/doc52.ps;30"
Sep 16 17:48:55.93: [ 4976]: USE page width 1728 pixels in 215 mm
Sep 16 17:48:55.93: [ 4976]: USE unlimited page length
Sep 16 17:48:55.93: [ 4976]: USE 3.85 line/mm
Sep 16 17:48:55.93: [ 4976]: USE 1-D MR
Sep 16 17:48:55.93: [ 4976]: <-- [24:AT+FDIS=0,3,0,2,0,0,0,3\r]
Sep 16 17:48:56.05: [ 4976]: --> [2:OK]
Sep 16 17:48:56.05: [ 4976]: <-- [7:AT+FDT\r]
Sep 16 17:49:03.00: [ 4976]: --> [22:+FDCS: 0,3,0,2,0,0,0,3]
Sep 16 17:49:03.00: [ 4976]: --> [7:CONNECT]
Sep 16 17:49:03.00: [ 4976]: SEND wait for XON
Sep 16 17:49:03.00: [ 4976]: --> [1:]
Sep 16 17:49:03.00: [ 4976]: SEND begin page
Sep 16 17:49:03.00: [ 4976]: <-- data [1027]
Sep 16 17:49:03.40: [ 4976]: <-- data [1026]
Sep 16 17:49:03.80: [ 4976]: <-- data [1027]
Sep 16 17:49:05.40: [ 4976]: <-- data [1029]
Sep 16 17:49:05.80: [ 4976]: <-- data [1027]
Sep 16 17:49:06.68: [ 4976]: <-- data [1025]
Sep 16 17:49:07.48: [ 4976]: <-- data [1026]
Sep 16 17:49:07.88: [ 4976]: <-- data [1024]
Sep 16 17:49:08.28: [ 4976]: <-- data [1028]
Sep 16 17:49:09.08: [ 4976]: <-- data [1028]
Sep 16 17:49:09.48: [ 4976]: <-- data [1026]
Sep 16 17:49:09.88: [ 4976]: <-- data [1027]
Sep 16 17:49:10.68: [ 4976]: <-- data [1025]
Sep 16 17:49:11.08: [ 4976]: <-- data [1029]
Sep 16 17:49:11.48: [ 4976]: <-- data [912]
Sep 16 17:49:12.28: [ 4976]: SENT 15248 bytes of data
Sep 16 17:49:12.28: [ 4976]: <-- data [2]
Sep 16 17:49:12.28: [ 4976]: SEND end page
Sep 16 17:49:23.98: [ 4976]: --> [2:OK]
Sep 16 17:49:23.98: [ 4976]: SEND send MPS (more pages, same document)
Sep 16 17:49:23.98: [ 4976]: <-- [9:AT+FET=0\r]
Sep 16 17:49:27.04: [ 4976]: --> [8:+FPTS: 1]
Sep 16 17:49:27.15: [ 4976]: --> [2:OK]
Sep 16 17:49:27.15: [ 4976]: SEND recv MCF (message confirmation)
Sep 16 17:49:27.15: [ 4976]: SEND FAX (00000242): FROM diego.ercolani@xxxxxxxxx TO 02123456 (page 1 of 9 sent in 0:32)
Sep 16 17:49:27.15: [ 4976]: USE page width 1728 pixels in 215 mm
Sep 16 17:49:27.15: [ 4976]: USE unlimited page length
Sep 16 17:49:27.15: [ 4976]: USE 3.85 line/mm
Sep 16 17:49:27.15: [ 4976]: USE 1-D MR
Sep 16 17:49:27.15: [ 4976]: <-- [7:AT+FDT\r]
Sep 16 17:49:28.09: [ 4976]: --> [7:CONNECT]
Sep 16 17:49:28.09: [ 4976]: SEND wait for XON
Sep 16 17:49:28.09: [ 4976]: --> [1:]
Sep 16 17:49:28.09: [ 4976]: SEND begin page
Sep 16 17:49:28.09: [ 4976]: <-- data [1028]
Sep 16 17:49:28.48: [ 4976]: <-- data [1033]
Sep 16 17:49:28.88: [ 4976]: <-- data [1025]
Sep 16 17:49:30.37: [ 4976]: <-- data [1027]
Sep 16 17:49:31.63: [ 4976]: <-- data [1028]
Sep 16 17:49:32.79: [ 4976]: <-- data [1025]
Sep 16 17:49:33.47: [ 4976]: <-- data [1025]
Sep 16 17:49:34.59: [ 4976]: <-- data [1025]
Sep 16 17:49:36.15: [ 4976]: <-- data [1026]
Sep 16 17:49:36.55: [ 4976]: <-- data [1028]
Sep 16 17:49:37.80: [ 4976]: <-- data [1024]
Sep 16 17:49:38.89: [ 4976]: <-- data [1026]
Sep 16 17:50:58.88: [ 4976]: MODEM TIMEOUT: writing to modem
Sep 16 17:50:58.88: [ 4976]: MODEM WRITE SHORT: sent 1026, wrote 817
Sep 16 17:50:58.88: [ 4976]: SENT 22472 bytes of data
Sep 16 17:50:58.88: [ 4976]: SEND abort data transfer
Sep 16 17:50:58.88: [ 4976]: <-- data [1]
Sep 16 17:50:58.88: [ 4976]: SEND end page
Sep 16 17:50:58.88: [ 4976]: <-- [6:AT+FK\r]
Sep 16 17:50:58.98: [ 4976]: --> [9:+FHNG: 43]
Sep 16 17:50:58.98: [ 4976]: REMOTE HANGUP: DTE to DCE data underflow (code 43)
Sep 16 17:50:58.98: [ 4976]: --> [2:OK]
Sep 16 17:50:58.98: [ 4976]: <-- [5:ATH0\r]
Sep 16 17:51:03.98: [ 4976]: MODEM TIMEOUT: reading line from modem
Sep 16 17:51:03.98: [ 4976]: MODEM <Timeout>
Sep 16 17:51:03.98: [ 4976]: MODEM set DTR OFF
Sep 16 17:51:33.97: [ 4976]: SESSION END