Re: [hylafax-users] Failure to transmit clean ECM image data.;

["Michiel Kersjes" <michielkersjes@xxxxxxxxxxx>]

Dear Lee,


I have had some "No response to MPS repeated 3 tries" error after I added 
"ModemFlowControl:  rtscts" to the modem config file.
Is there for this error also an config file option I have to change?



The log of the failed fax:

Jan 23 16:03:22.28: [14543]: SESSION BEGIN 000000787 XXXXXXXXXX
Jan 23 16:03:22.28: [14543]: HylaFAX (tm) Version 5.0.3
Jan 23 16:03:22.28: [14543]: SEND FAX: JOB 503 DEST XXXXXXXXXX COMMID 
000000787 DEVICE '/dev/ttyS0' FROM 'user' USER user
Jan 23 16:03:22.28: [14543]: <-- [12:AT+FCLASS=1\r]
Jan 23 16:03:22.39: [14543]: --> [2:OK]
Jan 23 16:03:22.39: [14543]: DIAL XXXXXXXXXX
Jan 23 16:03:22.39: [14543]: <-- [15:ATDTXXXXXXXXXX\r]
Jan 23 16:03:40.06: [14543]: --> [7:CONNECT]
Jan 23 16:03:41.59: [14543]: --> [2:OK]
Jan 23 16:03:41.59: [14543]: REMOTE NSF "00 00 79 00 00 00 02 0F 09 03 00 10 
05 02 95 88 08"
Jan 23 16:03:41.59: [14543]: NSF remote fax equipment: Panasonic
Jan 23 16:03:41.59: [14543]: <-- [9:AT+FRH=3\r]
Jan 23 16:03:41.60: [14543]: --> [7:CONNECT]
Jan 23 16:03:42.34: [14543]: --> [2:OK]
Jan 23 16:03:42.34: [14543]: REMOTE CSI "XXXXXXXXXX"
Jan 23 16:03:42.34: [14543]: <-- [9:AT+FRH=3\r]
Jan 23 16:03:42.35: [14543]: --> [7:CONNECT]
Jan 23 16:03:42.74: [14543]: --> [2:OK]
Jan 23 16:03:42.74: [14543]: REMOTE best rate 9600 bit/s
Jan 23 16:03:42.74: [14543]: REMOTE max A4 page width (215 mm)
Jan 23 16:03:42.74: [14543]: REMOTE max A4 page length (297 mm)
Jan 23 16:03:42.74: [14543]: REMOTE best vres 7.7 line/mm
Jan 23 16:03:42.74: [14543]: REMOTE format support: MH, MR
Jan 23 16:03:42.74: [14543]: REMOTE best 20 ms, 10 ms/scanline
Jan 23 16:03:42.74: [14543]: USE 9600 bit/s
Jan 23 16:03:42.74: [14543]: SEND file "docq/doc498.ps;00"
Jan 23 16:03:42.74: [14543]: USE A4 page width (215 mm)
Jan 23 16:03:42.74: [14543]: USE A4 page length (297 mm)
Jan 23 16:03:42.74: [14543]: USE 3.85 line/mm
Jan 23 16:03:42.74: [14543]: USE 2-D MR
Jan 23 16:03:42.74: [14543]: USE 20 ms/scanline
Jan 23 16:03:42.74: [14543]: SEND training at v.29 9600 bit/s
Jan 23 16:03:42.74: [14543]: DELAY 70 ms
Jan 23 16:03:42.81: [14543]: <-- [9:AT+FTH=3\r]
Jan 23 16:03:42.86: [14543]: --> [7:CONNECT]
Jan 23 16:03:42.86: [14543]: <-- data [23]
Jan 23 16:03:42.86: [14543]: <-- data [2]
Jan 23 16:03:42.88: [14543]: --> [7:CONNECT]
Jan 23 16:03:42.88: [14543]: <-- data [6]
Jan 23 16:03:42.88: [14543]: <-- data [2]
Jan 23 16:03:45.06: [14543]: --> [2:OK]
Jan 23 16:03:45.06: [14543]: DELAY 70 ms
Jan 23 16:03:45.13: [14543]: <-- [10:AT+FTM=96\r]
Jan 23 16:03:45.64: [14543]: --> [7:CONNECT]
Jan 23 16:03:45.64: [14543]: <-- data [1024]
Jan 23 16:03:45.64: [14543]: <-- data [776]
Jan 23 16:03:45.64: [14543]: <-- data [2]
Jan 23 16:03:47.19: [14543]: --> [2:OK]
Jan 23 16:03:47.19: [14543]: <-- [9:AT+FRH=3\r]
Jan 23 16:03:47.87: [14543]: --> [7:CONNECT]
Jan 23 16:03:49.14: [14543]: --> [2:OK]
Jan 23 16:03:49.14: [14543]: TRAINING succeeded
Jan 23 16:03:49.14: [14543]: DELAY 70 ms
Jan 23 16:03:49.21: [14543]: <-- [10:AT+FTM=96\r]
Jan 23 16:03:49.79: [14543]: --> [7:CONNECT]
Jan 23 16:03:49.79: [14543]: SEND begin page
Jan 23 16:03:49.79: [14543]: Reading MH-compressed image file
Jan 23 16:03:49.82: [14543]: <-- data [1034]
Jan 23 16:03:49.82: [14543]: <-- data [1037]
Jan 23 16:03:49.82: [14543]: <-- data [1048]
Jan 23 16:03:49.82: [14543]: <-- data [1033]
Jan 23 16:03:51.13: [14543]: <-- data [1041]
Jan 23 16:03:51.13: [14543]: <-- data [1034]
Jan 23 16:03:51.73: [14543]: <-- data [1027]
Jan 23 16:03:52.32: [14543]: <-- data [1030]
Jan 23 16:03:52.90: [14543]: <-- data [1030]
Jan 23 16:03:54.08: [14543]: <-- data [1026]
Jan 23 16:03:54.65: [14543]: <-- data [1029]
Jan 23 16:03:55.79: [14543]: <-- data [1025]
Jan 23 16:03:56.37: [14543]: <-- data [1026]
Jan 23 16:03:57.53: [14543]: <-- data [1027]
Jan 23 16:03:58.10: [14543]: <-- data [1031]
Jan 23 16:03:59.26: [14543]: <-- data [1030]
Jan 23 16:03:59.83: [14543]: <-- data [1027]
Jan 23 16:04:00.99: [14543]: <-- data [1032]
Jan 23 16:04:01.56: [14543]: <-- data [1024]
Jan 23 16:04:02.71: [14543]: <-- data [1024]
Jan 23 16:04:03.29: [14543]: <-- data [1024]
Jan 23 16:04:04.45: [14543]: <-- data [1024]
Jan 23 16:04:05.02: [14543]: <-- data [1024]
Jan 23 16:04:06.17: [14543]: <-- data [1024]
Jan 23 16:04:06.74: [14543]: <-- data [1024]
Jan 23 16:04:07.31: [14543]: <-- data [1024]
Jan 23 16:04:08.46: [14543]: <-- data [941]
Jan 23 16:04:09.03: [14543]: SENT 27562 bytes of data
Jan 23 16:04:09.03: [14543]: <-- data [1030]
Jan 23 16:04:10.18: [14543]: <-- data [1033]
Jan 23 16:04:10.75: [14543]: <-- data [1033]
Jan 23 16:04:11.90: [14543]: <-- data [1029]
Jan 23 16:04:12.48: [14543]: <-- data [1031]
Jan 23 16:04:13.62: [14543]: <-- data [1026]
Jan 23 16:04:14.22: [14543]: <-- data [1029]
Jan 23 16:04:15.38: [14543]: <-- data [356]
Jan 23 16:04:15.38: [14543]: SENT 7524 bytes of data
Jan 23 16:04:15.38: [14543]: SEND 2D RTC
Jan 23 16:04:15.38: [14543]: <-- data [30]
Jan 23 16:04:15.38: [14543]: <-- data [2]
Jan 23 16:04:15.38: [14543]: SEND end page
Jan 23 16:04:19.37: [14543]: --> [2:OK]
Jan 23 16:04:19.37: [14543]: DELAY 70 ms
Jan 23 16:04:19.44: [14543]: SEND send MPS (more pages, same document)
Jan 23 16:04:19.44: [14543]: <-- [9:AT+FTH=3\r]
Jan 23 16:04:19.49: [14543]: --> [7:CONNECT]
Jan 23 16:04:19.49: [14543]: <-- data [3]
Jan 23 16:04:19.49: [14543]: <-- data [2]
Jan 23 16:04:20.80: [14543]: --> [2:OK]
Jan 23 16:04:20.80: [14543]: <-- [9:AT+FRH=3\r]
Jan 23 16:04:23.91: [14543]: --> [0:]
Jan 23 16:04:23.91: [14543]: MODEM <Empty line>
Jan 23 16:04:23.91: [14543]: <-- data [1]
Jan 23 16:04:24.11: [14543]: MODEM <Timeout>
Jan 23 16:04:24.11: [14543]: SEND send MPS (more pages, same document)
Jan 23 16:04:24.11: [14543]: <-- [9:AT+FTH=3\r]
Jan 23 16:04:24.16: [14543]: --> [7:CONNECT]
Jan 23 16:04:24.16: [14543]: <-- data [3]
Jan 23 16:04:24.16: [14543]: <-- data [2]
Jan 23 16:04:25.47: [14543]: --> [2:OK]
Jan 23 16:04:25.47: [14543]: <-- [9:AT+FRH=3\r]
Jan 23 16:04:28.58: [14543]: --> [0:]
Jan 23 16:04:28.58: [14543]: MODEM <Empty line>
Jan 23 16:04:28.58: [14543]: <-- data [1]
Jan 23 16:04:28.78: [14543]: MODEM <Timeout>
Jan 23 16:04:28.78: [14543]: SEND send MPS (more pages, same document)
Jan 23 16:04:28.78: [14543]: <-- [9:AT+FTH=3\r]
Jan 23 16:04:28.83: [14543]: --> [7:CONNECT]
Jan 23 16:04:28.83: [14543]: <-- data [3]
Jan 23 16:04:28.83: [14543]: <-- data [2]
Jan 23 16:04:30.15: [14543]: --> [2:OK]
Jan 23 16:04:30.15: [14543]: <-- [9:AT+FRH=3\r]
Jan 23 16:04:33.25: [14543]: --> [0:]
Jan 23 16:04:33.25: [14543]: MODEM <Empty line>
Jan 23 16:04:33.25: [14543]: <-- data [1]
Jan 23 16:04:33.45: [14543]: MODEM <Timeout>
Jan 23 16:04:33.45: [14543]: No response to MPS repeated 3 tries
Jan 23 16:04:33.45: [14543]: SEND: No response to MPS repeated 3 tries; 
Giving up after 3 attempts to send same page "docq/doc498.ps;00", dirnum 0
Jan 23 16:04:33.46: [14543]: DELAY 70 ms
Jan 23 16:04:33.53: [14543]: <-- [9:AT+FTH=3\r]
Jan 23 16:04:33.58: [14543]: --> [7:CONNECT]
Jan 23 16:04:33.58: [14543]: <-- data [3]
Jan 23 16:04:33.58: [14543]: <-- data [2]
Jan 23 16:04:34.89: [14543]: --> [2:OK]
Jan 23 16:04:34.89: [14543]: <-- [5:ATH0\r]
Jan 23 16:04:35.32: [14543]: --> [10:NO CARRIER]
Jan 23 16:04:35.32: [14543]: MODEM No carrier
Jan 23 16:04:35.32: [14543]: SESSION END


----Original Message Follows----
From: Lee Howard <faxguy@xxxxxxxxxxxxxxxx>
To: Michiel Kersjes <michielkersjes@xxxxxxxxxxx>
CC: hylafax-users@xxxxxxxxxxx
Subject: Re: [hylafax-users] Failure to transmit clean ECM image data.;
Date: Thu, 18 Jan 2007 09:41:38 -0800

Michiel Kersjes wrote:

> Jan 17 13:33:22.75: [ 8233]: SEND send frame number 0

.....

> Jan 17 13:33:22.77: [ 8233]: SEND send frame number 58


> Jan 17 13:33:40.94: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:33:41.01: [ 8233]: SEND send frame number 5

.....

> Jan 17 13:33:41.03: [ 8233]: SEND send frame number 51


This log is interesting.  Notice that we send frames 0 through 58.  And 
notice also that the receiver got 0 - 4 and also 52 - 58.  Now notice in the 
retransmissions that it's getting only the first few frames hereafter.

> Jan 17 13:33:55.13: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:33:55.20: [ 8233]: SEND send frame number 10

.....

> Jan 17 13:33:55.21: [ 8233]: SEND send frame number 51


See?  Here it got frames 5 through 9.

> Jan 17 13:34:08.19: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:34:08.26: [ 8233]: SEND send frame number 15

.....

> Jan 17 13:34:08.27: [ 8233]: SEND send frame number 51


And here it got frames 10 - 15.

> Jan 17 13:34:20.14: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:34:21.63: [ 8233]: SEND send CTC (continue to correct)
> Jan 17 13:34:22.99: [ 8233]: SEND recv CTR (confirm continue to correct)
> Jan 17 13:34:23.00: [ 8233]: SEND send frame number 20

.....

> Jan 17 13:34:23.00: [ 8233]: SEND send frame number 51


The CTC/CTR exchange represents a slow-down occurring.  (Again, notice that 
the receiver got another 5 frames on the attempt prior to the CTC/CTR 
exchange.)

> Jan 17 13:34:35.77: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:34:35.84: [ 8233]: SEND send frame number 22

.....

> Jan 17 13:34:35.85: [ 8233]: SEND send frame number 51


And now it gets only 2 frames.

> Jan 17 13:34:47.95: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:34:48.02: [ 8233]: SEND send frame number 24

.....

> Jan 17 13:34:48.03: [ 8233]: SEND send frame number 51


And another 2 frames.

> Jan 17 13:34:59.55: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:34:59.62: [ 8233]: SEND send frame number 26

.....

> Jan 17 13:34:59.63: [ 8233]: SEND send frame number 51


And another 2 frames.

> Jan 17 13:35:10.54: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:35:12.03: [ 8233]: SEND send CTC (continue to correct)
> Jan 17 13:35:13.39: [ 8233]: SEND recv CTR (confirm continue to correct)
> Jan 17 13:35:13.39: [ 8233]: SEND send frame number 28

.....

> Jan 17 13:35:13.40: [ 8233]: SEND send frame number 51


And another 2 frames.  And now we slow down again with another CTC/CTR 
exchange.

> Jan 17 13:35:26.94: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:35:27.01: [ 8233]: SEND send frame number 29

.....

> Jan 17 13:35:27.01: [ 8233]: SEND send frame number 51


Now only 1 frame is getting through at a time.

> Jan 17 13:35:40.05: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:35:40.12: [ 8233]: SEND send frame number 30

.....

> Jan 17 13:35:40.12: [ 8233]: SEND send frame number 51


See?  Another single frame gets through.

> Jan 17 13:35:52.71: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:35:52.78: [ 8233]: SEND send frame number 37

.....

> Jan 17 13:35:52.79: [ 8233]: SEND send frame number 51


Again, only one frame gets through.

> Jan 17 13:36:04.93: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:36:06.42: [ 8233]: SEND send CTC (continue to correct)
> Jan 17 13:36:07.77: [ 8233]: SEND recv CTR (confirm continue to correct)
> Jan 17 13:36:07.77: [ 8233]: SEND send frame number 38

.....

> Jan 17 13:36:07.78: [ 8233]: SEND send frame number 51


And now we slow down again.

> Jan 17 13:36:26.06: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:36:26.13: [ 8233]: SEND send frame number 38

.....

> Jan 17 13:36:26.14: [ 8233]: SEND send frame number 51


And this comes as no surprise that no no frames are getting through at all.

> Jan 17 13:36:44.35: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:36:44.42: [ 8233]: SEND send frame number 38

.....

> Jan 17 13:36:44.43: [ 8233]: SEND send frame number 51


No frames get through.

> Jan 17 13:37:02.63: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:37:02.70: [ 8233]: SEND send frame number 38

.....

> Jan 17 13:37:02.71: [ 8233]: SEND send frame number 51


Nada, zilch, zip, nine, niet.

> Jan 17 13:37:20.91: [ 8233]: SEND recv PPR (partial page request)
> Jan 17 13:37:20.98: [ 8233]: Failure to transmit clean ECM image data.


And because slowing down ultimately made the situation worse so that no 
frames could ever get through this happens... we give up because we can't 
get the image through for some reason.

Maybe here HylaFAX could have been smarter - enough to realize that slowing 
down was only making the situation worse.  But it doesn't.  And maybe that's 
for the best so that it will prompt you to fix the real problem... flow 
control.

It *really* looks like the problem is flow control.  The first block 
transmission/reception is very telling in that some at the first gets 
through and then some at the end, but nothing in the middle.  That's what 
happens when your ModemRate well outpaces the transmission rate being used 
and the modem does not employ flow control properly.  The first data parts 
will fill the buffer and then it will start transmitting that data, but the 
data buffer does not become available for a while yet HylaFAX keeps throwing 
data at the modem.  When the modem finally becomes available again we've 
essentially skipped a bunch of data.

This happens when the modem does not instruct us properly to stop sending 
data to it.

So, take a look at the ModemFlowControl setting.  Yours appears to be left 
as default (XONXOFF).  So please change it to RTSCTS and see where you get.

 ModemFlowControl:  rtscts

If that doesn't help you probably need to consider a different modem.  That 
said, I am willing to make HylaFAX a bit more intelligent in it's CTC/CTR 
slowdowns... possibly so that it could speed up in the kind of situation 
where this happens.

Lee.


____________________ 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*



____________________ 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*