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

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

Daer Lee,

Thank you very much for your reply.
I have added "ModemFlowControl: rtscts" to my config file.
After that we have sent over 100 faxes with no error so I think this problem is solved.

I have another question.
On an other server we have installed Asterisk with iaxmodem and hylafax for receiving faxes.
Sometimes i get the next error "COMREC received DCN" when receiving a fax.
On that server we have installed:
hylafax 4.3.0
iaxmodem-0.2.0
Asterisk 1.2.7.1

I have a log from a failed fax:

Jan 22 14:02:28.01: [25489]: SESSION BEGIN 000030694 XXXXXXXXXX
Jan 22 14:02:28.01: [25489]: HylaFAX (tm) Version 4.3.0
Jan 22 14:02:28.01: [25489]: CallID: "XXXXXXXXXX" "<NONE>" "<NONE>" "XXXXXXXXXX"
Jan 22 14:02:28.01: [25489]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled
Jan 22 14:02:28.01: [25489]: <-- [4:ATA\r]
Jan 22 14:02:31.73: [25489]: --> [7:CONNECT]
Jan 22 14:02:31.73: [25489]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyIAX1'
Jan 22 14:02:31.73: [25489]: STATE CHANGE: ANSWERING -> RECEIVING
Jan 22 14:02:31.73: [25489]: RECV FAX: begin
Jan 22 14:02:31.73: [25489]: <-- HDLC<32:FF C0 04 B5 00 AA 12 9E 36 86 62 82 1A 04 14 2E B6 94 04 6A A6 4E CE 96 F6 76 04 2C 74 CC 74 0C>
Jan 22 14:02:32.65: [25489]: --> [7:CONNECT]
Jan 22 14:02:32.65: [25489]: <-- HDLC<23:FF C0 02 8C B6 A6 26 F6 B6 1A 82 92 04 04 04 04 04 04 04 04 04 04 04>
Jan 22 14:02:33.41: [25489]: --> [7:CONNECT]
Jan 22 14:02:33.41: [25489]: <-- HDLC<13:FF C8 01 00 73 5F 23 01 FB C1 01 01 18>
Jan 22 14:02:33.99: [25489]: --> [2:OK]
Jan 22 14:02:33.99: [25489]: <-- [9:AT+FRH=3\r]
Jan 22 14:02:34.38: [25489]: --> [7:CONNECT]
Jan 22 14:02:35.98: [25489]: --> HDLC<25:FF C0 C2 8C AC 0C 0C CC 0C 6C 0C CC 0C 04 04 04 04 04 04 04 04 04 04 60 06>
Jan 22 14:02:35.98: [25489]: --> [2:OK]
Jan 22 14:02:35.98: [25489]: REMOTE TSI "XXXXXXXXXX"
Jan 22 14:02:35.98: [25489]: <-- [9:AT+FRH=3\r]
Jan 22 14:02:36.28: [25489]: --> [7:CONNECT]
Jan 22 14:02:36.28: [25489]: --> HDLC<10:FF C8 C1 00 61 15 01 00 F0 62>
Jan 22 14:02:36.34: [25489]: --> [2:OK]
Jan 22 14:02:36.34: [25489]: REMOTE wants 9600 bit/s
Jan 22 14:02:36.34: [25489]: REMOTE wants A4 page width (215 mm)
Jan 22 14:02:36.34: [25489]: REMOTE wants unlimited page length
Jan 22 14:02:36.34: [25489]: REMOTE wants 3.85 line/mm
Jan 22 14:02:36.34: [25489]: REMOTE wants 2-D MR
Jan 22 14:02:36.34: [25489]: RECV training at v.29 9600 bit/s
Jan 22 14:02:36.34: [25489]: MODEM set XON/XOFF/DRAIN: input ignored, output generated
Jan 22 14:02:36.34: [25489]: <-- [10:AT+FRM=96\r]
Jan 22 14:02:36.66: [25489]: --> [7:CONNECT]
Jan 22 14:02:38.24: [25489]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Jan 22 14:02:38.24: [25489]: RECV: TCF 1892 bytes, 1% non-zero, 1872 zero-run
Jan 22 14:02:38.24: [25489]: --> [10:NO CARRIER]
Jan 22 14:02:38.24: [25489]: <-- [9:AT+FRS=7\r]
Jan 22 14:02:38.30: [25489]: --> [2:OK]
Jan 22 14:02:38.30: [25489]: TRAINING succeeded
Jan 22 14:02:38.30: [25489]: <-- [9:AT+FTH=3\r]
Jan 22 14:02:38.31: [25489]: --> [7:CONNECT]
Jan 22 14:02:38.31: [25489]: <-- HDLC<3:FF C8 21>
Jan 22 14:02:39.39: [25489]: --> [2:OK]
Jan 22 14:02:39.39: [25489]: <-- [10:AT+FRM=96\r]
Jan 22 14:02:39.94: [25489]: --> [7:CONNECT]
Jan 22 14:02:39.94: [25489]: MODEM input buffering enabled
Jan 22 14:02:39.94: [25489]: MODEM set XON/XOFF/FLUSH: input ignored, output generated
Jan 22 14:02:39.94: [25489]: RECV: begin page
Jan 22 14:03:54.72: [25489]: RECV/CQ: Bad 1D pixel count, row 2298, got 0, expected 1728
Jan 22 14:03:54.72: [25489]: RECV/CQ: Bad 1D pixel count, row 2299, got 0, expected 1728
Jan 22 14:03:54.72: [25489]: RECV/CQ: Bad 1D pixel count, row 2300, got 0, expected 1728
Jan 22 14:03:54.72: [25489]: RECV/CQ: Bad 1D pixel count, row 2301, got 0, expected 1728
Jan 22 14:03:54.72: [25489]: RECV/CQ: Adjusting for RTC found at row 2298
Jan 22 14:03:54.72: [25489]: RECV: 2298 total lines, 0 bad lines, 0 consecutive bad lines
Jan 22 14:03:54.72: [25489]: RECV: end page
Jan 22 14:03:54.72: [25489]: --> [10:NO CARRIER]
Jan 22 14:03:54.72: [25489]: <-- [9:AT+FRH=3\r]
Jan 22 14:03:55.04: [25489]: --> [7:CONNECT]
Jan 22 14:03:56.16: [25489]: --> HDLC<5:FF C8 F2 AC A0>
Jan 22 14:03:56.16: [25489]: --> [2:OK]
Jan 22 14:03:56.16: [25489]: RECV recv MPS (more pages, same document)
Jan 22 14:03:56.16: [25489]: <-- [9:AT+FRS=7\r]
Jan 22 14:03:56.26: [25489]: --> [2:OK]
Jan 22 14:03:56.26: [25489]: <-- [9:AT+FTH=3\r]
Jan 22 14:03:56.37: [25489]: --> [7:CONNECT]
Jan 22 14:03:56.37: [25489]: RECV send MCF (message confirmation)
Jan 22 14:03:56.38: [25489]: RECV FAX (000030694): from XXXXXXXXXX, page 1 in 1:23, INF, 3.85 line/mm, 2-D MR, 9600 bit/s
Jan 22 14:03:56.38: [25489]: <-- HDLC<3:FF C8 31>
Jan 22 14:03:57.46: [25489]: --> [2:OK]
Jan 22 14:03:57.46: [25489]: <-- [10:AT+FRM=96\r]
Jan 22 14:04:00.68: [25489]: --> [6:+FRH:3]
Jan 22 14:04:00.68: [25489]: --> [7:CONNECT]
Jan 22 14:04:01.80: [25489]: --> HDLC<5:FF C8 DF 59 6F>
Jan 22 14:04:01.80: [25489]: --> [2:OK]
Jan 22 14:04:01.80: [25489]: RECV recv DCN (disconnect)
Jan 22 14:04:01.80: [25489]: MODEM set XON/XOFF/DRAIN: input ignored, output disabled
Jan 22 14:04:01.80: [25489]: MODEM input buffering disabled
Jan 22 14:04:01.80: [25489]: RECV recv DCN
Jan 22 14:04:01.80: [25489]: RECV FAX (000030694): recvq/fax000006480.tif from XXXXXXXXXX, route to <unspecified>, 1 pages in 1:30
Jan 22 14:04:01.80: [25489]: RECV FAX: COMREC received DCN
Jan 22 14:04:01.80: [25489]: MODEM input buffering enabled
Jan 22 14:04:01.80: [25489]: RECV FAX (000030694): session with XXXXXXXXXX terminated abnormally: COMREC received DCN
Jan 22 14:04:01.80: [25489]: RECV FAX: bin/faxrcvd "recvq/fax000006480.tif" "ttyIAX1" "000030694" "COMREC received DCN" "XXXXXXXXXX" "<NONE>" "<NONE>" "XXXXXXXXXX"
Jan 22 14:04:01.81: [25489]: RECV FAX: end
Jan 22 14:04:01.81: [25489]: SESSION END

Do you think that this is solved when I upgrade hylafax to hylafax+ 5 or shoul I change something else?

Regards,

Michiel


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

Project hosted by iFAX Solutions