Re: [hylafax-users] Junk in logfile since upgrading to 4.3.3

[Aidan Van Dyk <aidan@xxxxxxxx>]

* Ulf Zimmermann <ulf@xxxxxxxxxxxxxx> [070516 17:47]:
> I recently upgraded one of our servers to 4.3.3 (yeah! Finally!) and once in a while getting things like this below:

And you never got this with earlier versions?  And is it always the same
sender, or seemingly random senders?

The log looks really bad, but the error is simple, the modem is still
sending image data when faxgetty is expecing a response to a command.

Here is the same log, just "<SNIPPING>" the binary data out, where you
can see the problem clearly:

> > May 16 14:41:20.32: [ 5278]: SESSION BEGIN 000005257 16023241958
> > May 16 14:41:20.32: [ 5278]: HylaFAX (tm) Version 4.3.3
> > May 16 14:41:20.32: [ 5278]: CallID: "XXXXXXXXXXX" "XXXXXXXXXXX"
> > May 16 14:41:20.32: [ 5278]: <-- [11:ATS0=255;A\r]
> > May 16 14:41:20.32: [ 5278]: --> [4:RING]
> > May 16 14:41:32.37: [ 5278]: --> [5:+FCON]
> > May 16 14:41:32.37: [ 5278]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyds01'
> > May 16 14:41:32.37: [ 5278]: RECV FAX: begin
> > May 16 14:41:32.37: [ 5278]: --> [26:+FTSI:        731 925 1881]
> > May 16 14:41:32.37: [ 5278]: REMOTE TSI "XXXXXX"
> > May 16 14:41:32.37: [ 5278]: --> [22:+FDCS: 1,B,0,2,0,2,0,0]
> > May 16 14:41:32.37: [ 5278]: REMOTE wants 28800 bit/s
> > May 16 14:41:32.37: [ 5278]: REMOTE wants A4 page width (215 mm)
> > May 16 14:41:32.37: [ 5278]: REMOTE wants unlimited page length
> > May 16 14:41:32.37: [ 5278]: REMOTE wants 7.7 line/mm
> > May 16 14:41:32.37: [ 5278]: REMOTE wants 1-D MH
> > May 16 14:41:32.37: [ 5278]: REMOTE wants T.30 Annex C, half duplex ECM
> > May 16 14:41:32.37: [ 5278]: --> [2:OK]
> > May 16 14:41:32.37: [ 5278]: <-- [7:AT+FDR\r]
> > May 16 14:41:32.37: [ 5278]: --> [5:+FCFR]
> > May 16 14:41:32.37: [ 5278]: --> [22:+FDCS: 1,B,0,2,0,2,0,0]
> > May 16 14:41:32.37: [ 5278]: REMOTE wants 28800 bit/s
> > May 16 14:41:32.37: [ 5278]: REMOTE wants A4 page width (215 mm)
> > May 16 14:41:32.37: [ 5278]: REMOTE wants unlimited page length
> > May 16 14:41:32.37: [ 5278]: REMOTE wants 7.7 line/mm
> > May 16 14:41:32.37: [ 5278]: REMOTE wants 1-D MH
> > May 16 14:41:32.37: [ 5278]: REMOTE wants T.30 Annex C, half duplex ECM
> > May 16 14:41:32.37: [ 5278]: --> [7:CONNECT]
> > May 16 14:41:32.37: [ 5278]: RECV: begin page
> > May 16 14:41:32.37: [ 5278]: RECV: send trigger 021
> > May 16 14:41:32.37: [ 5278]: Copy quality checking performed by host
> > May 16 14:41:39.67: [ 5278]: RECV: 32728 bytes of data, 1103 total lines
> > May 16 14:41:45.80: [ 5278]: RECV: 32766 bytes of data, 1831 total lines
> > May 16 14:42:47.07: [ 5278]: RECV: Missing EOL after 5 seconds

faxgetty believed it had an EOF raised as it was receiving the Phase C
data.  This made it hangup/giveup.   But meanwhile, the modem (Eicon
DIVA I'm assuming) was continuing to send us more image data.

> > May 16 14:42:47.07: [ 5278]: REMOTE HANGUP: Missing EOL after 5 seconds (section 3.2/T.4) (code 91)
> > May 16 14:42:47.07: [ 5278]: RECV FAX (000005257): recvq/fax000002589.tif from XXXXXXXXXXXX, route to <unspecified>, 0 pages in 1:15
> > May 16 14:42:47.07: [ 5278]: RECV FAX: Missing EOL after 5 seconds (section 3.2/T.4)
> > May 16 14:42:47.07: [ 5278]: <-- [6:AT+FK\r]
> > May 16 14:42:54.47: [ 5278]: --> [130:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [49:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [619:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [819:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [72:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [204:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [90:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [181:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [80:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [348:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [54:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [1:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [151:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [67:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [309:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [12:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [914:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [675:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [28:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [477:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [78:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [62:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [131:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [42:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [23:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [54:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [117:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [53:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [35:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [92:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [166:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [52:<SNIP BINARY DATA>]
> > May 16 14:42:54.47: [ 5278]: --> [97:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [130:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [50:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [33:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [50:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [152:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [31:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [53:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [73:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [262:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [144:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [25:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [252:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [364:<SNIP BINARY DATA>]
> > May 16 14:42:55.56: [ 5278]: --> [13:+FPTS: 1,2152]
> > May 16 14:42:55.56: [ 5278]: --> [7:+FET: 2]
> > May 16 14:42:55.56: [ 5278]: --> [2:OK]

And here, the modem has stopped sending the tiff data...

> > May 16 14:42:55.56: [ 5278]: RECV FAX (000005257): session with 731 925 1881 terminated abnormally: Missing EOL after 5 seconds (section 3.2/T.4)
> > May 16 14:42:55.56: [ 5278]: RECV FAX: bin/faxrcvd.autc "recvq/fax000002589.tif" "ttyds01" "000005257" "Missing EOL after 5 seconds (section 3.2/T.4)" "XXXXXXXXX" "XXXXXXXXXX"
> > May 16 14:42:55.56: [ 5278]: RECV FAX: end
> > May 16 14:42:55.56: [ 5278]: SESSION END
> 
> Anyone else seen this?



-- 
Aidan Van Dyk                                             aidan@xxxxxxxx
Senior Software Developer                          +1 215 825-8700 x8103
iFAX Solutions, Inc.                                http://www.ifax.com/

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