|
Hylafax Mailing List Archives
|
[Date Prev][Date Next][Thread Prev][Thread Next]
[Date Index]
[Thread Index]
Re: [hylafax-users] Modem gets stuck on some incoming faxes
On 2003.10.20 11:19 Michael Evans wrote:
I've got HylaFAX installed on a SuSE 7.2 system with a Zoom 2920
internal faxmodem. The HylaFAX version is 4.6 from cvs, patched to
enable ECM. Sending faxes (via WHFC) works, although sometimes slowly
due to the ECM. Some faxes are received properly, as well. However,
some incoming faxes cause the modem to get "stuck" - it holds the
phone line infinitely, so that any new callers hear a busy signal.
Meanwhile, every 3 seconds or so a "Timeout awaiting synchronization
sequence" message gets written to the log file, resulting in some
enormous logs. Getting the modem to hang up the phone requires
stopping faxgetty, stopping hylafax, then restarting faxgetty and
hylafax.
Not that you're ever *supposed* to need to do it, but restarting
faxgetty probably would be sufficient.
Whenever this happens, some very weird stuff is written to the log
file, namely:
Oct 20 09:04:29.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:04:29.00: [ 3583]: Bad HDLC terminating flag received.
Oct 20 09:04:32.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:04:32.00: [ 3583]: Bad HDLC terminating flag received.
Oct 20 09:04:35.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:04:35.00: [ 3583]: Bad HDLC terminating flag received.
Oct 20 09:04:38.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:04:38.00: [ 3583]: Bad HDLC terminating flag received.
Oct 20 09:04:41.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:05:16.52: [ 3583]: --> [10:NO CARRIER]
Something's interfering with the communication. Since we're all the
way down to 2400 bps, this isn't surprising.
Oct 20 09:05:16.52: [ 3583]: <-- [9:AT+FRH=3\r]
Oct 20 09:05:16.61: [ 3583]: --> [7:CONNECT]
Oct 20 09:05:17.80: [ 3583]: --> [2:OK]
Oct 20 09:05:17.80: [ 3583]: RECV recv PPS (partial page signal)
Oct 20 09:05:17.80: [ 3583]: RECV recv EOP (no more pages or
documents)
Oct 20 09:05:17.80: [ 3583]: RECV received 105 frames of block 1 of
page 3
Oct 20 09:05:17.80: [ 3583]: <-- [9:AT+FRS=7\r]
Oct 20 09:05:17.88: [ 3583]: --> [2:OK]
Oct 20 09:05:17.88: [ 3583]: <-- [9:AT+FTH=3\r]
Oct 20 09:05:18.74: [ 3583]: --> [7:CONNECT]
Oct 20 09:05:18.74: [ 3583]: <-- data [35]
Oct 20 09:05:18.74: [ 3583]: <-- data [2]
Oct 20 09:05:20.06: [ 3583]: --> [2:OK]
Oct 20 09:05:20.06: [ 3583]: RECV send PPR (partial page request)
Oct 20 09:05:20.06: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:05:21.90: [ 3583]: --> [7:CONNECT]
Oct 20 09:05:24.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:05:24.00: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:05:24.11: [ 3583]: -->
[750:ÿÿÿûùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùù
This here is actual output from the modem itself in response to the
AT+FRM=24 command. It indicates some kind of error occurred with the
modem (hardware problem/firmware bug).
ùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùù
ùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùù
ùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùù
ùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùù
ùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùùù
ùùùùùùùùùùùùùùùù}`°P4"Þ¬ÀhPàì
At this point I am not certain whether this is still coming from the
modem or elsewhere, but I suspect it's garbage coming from the modem as
it resets itself due to the error above. We see this with other modems
when they reset while the tty is reading from it.
°}oçí"ñÎ;Ø8lÎnéu·tIK{&
Þt4rÇ Å Ã s ãô\!.îêrÆ7÷êXGÊ:x0ÔHgLH ¹v5Õ¦ëK{&Þ
;fb%Bb
8""·¦èLä
ú¾/À:}À4Ü8GÁç0ïfCBË
-RE\æ¦ëK{&Þtb""""rSÆÄÀT0
<¬GºG
At this point the garbage from the modem seems to have triggered a
memory dump via the HylaFAX session logger from the system somehow...
and that's why we get this...
--More--
Most commands optionally preceded by integer argument k. Defaults in
brackets.
Star (*) indicates argument becomes new default.
-------------------------------------------------------------------------------
<space> Display next k lines of text [current screen
size]
z Display next k lines of text [current screen
size]*
<return> Display next k lines of text [1]*
d or ctrl-D Scroll k lines [current scroll size,
initially 11]*
q or Q or <interrupt> Exit from more
s Skip forward k lines of text [1]
f Skip forward k screenfuls of text [1]
b or ctrl-B Skip backwards k screenfuls of text [1]
' Go to place where previous search started
= Display current line number
/<regular expression> Search for kth occurrence of regular
expression [1]
n Search for kth occurrence of last r.e [1]
!<cmd> or :!<cmd> Execute <cmd> in a subshell
v Start up /usr/bin/vi at current line
ctrl-L Redraw screen
:n Go to kth next file [1]
:p Go to kth previous file [1]
:f Display current file name and line number
. Repeat previous command
-------------------------------------------------------------------------------
Ú6ÈG{&ÞtÄ
ôÈ
Ô]
The reception attempt should ideally end here, since it's irrecoverable
from this point on.
Oct 20 09:05:24.11: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:05:24.11: [ 3583]: --> [2:OK]
The command above resulted in "OK", meaning it wasn't interpreted but
was merely a call to return to command-mode. The OK means we're back
in command mode.
Oct 20 09:05:24.11: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:05:24.22: [ 3583]: --> [7:CONNECT]
This would indicate that the remote is still on-line... somehow...
Oct 20 09:05:27.00: [ 3583]: Timeout awaiting synchronization sequence
...
Once these "Timeouts" start, they go on indefinitely, until I
intervene by stopping faxgetty and hylafax:
Oct 20 09:31:30.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:31:30.00: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:31:30.00: [ 3583]: --> [2:]
Oct 20 09:31:30.00: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:31:30.00: [ 3583]: --> [10:NO CARRIER]
After 25 minutes the remote is certainly gone, so these are not
surprising...
Oct 20 09:31:30.00: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:31:30.11: [ 3583]: --> [7:CONNECT]
But this one is surprising. Seems to be another firmware bug,
responding CONNECT when no carrier is present.
Oct 20 09:31:33.00: [ 3583]: Timeout awaiting synchronization sequence
Oct 20 09:31:33.00: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:31:33.00: [ 3583]: --> [2:]
Oct 20 09:31:33.00: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:31:33.00: [ 3583]: --> [10:NO CARRIER]
Oct 20 09:31:33.00: [ 3583]: <-- [10:AT+FRM=24\r]
Oct 20 09:31:33.11: [ 3583]: --> [7:CONNECT]
Oct 20 09:31:36.00: [ 3583]: Timeout awaiting synchronization sequence
The attached patch is an error-handling fix and should fix all of the
poor handling of the problematic responses above. Please test and lets
see how it goes. Seems to not inhibit normal behavior here.
I don't know how what appears to be help instructions for vi get
written to a hylafax log, but there they are.
The good news is that I configured HylaFAX to convert incoming faxes
to PDF files and send them as e-mail attachments to our receptionist,
and when it's able to receive a fax properly (about 50% of the time),
this part works perfectly.
50% is a very bad success ratio.
Any ideas, though, what the problem could be that prevents successful
fax reception the other 50% of the time?
Do 50% of the faxes result in logs like this one (with faxgetty
hanging)? Or can you show us a log of the usual problem type?
Thanks.
Lee.
diff -Nru hylafax.orig/faxd/Class1Recv.c++ hylafax/faxd/Class1Recv.c++
--- hylafax.orig/faxd/Class1Recv.c++ Thu Oct 16 23:09:34 2003
+++ hylafax/faxd/Class1Recv.c++ Mon Oct 20 12:48:11 2003
@@ -445,8 +445,9 @@
* high speed carrier traffic other than the TCF).
*/
fxStr rmCmd(curcap[HasShortTraining(curcap)].value, rmCmdFmt);
+ u_short attempts = 0;
ATResponse rmResponse = AT_NOTHING;
- while (rmResponse != AT_CONNECT && rmResponse != AT_TIMEOUT && rmResponse != AT_ERROR) {
+ while ((rmResponse == AT_NOTHING || rmResponse == AT_FCERROR) && attempts++ < 20) {
(void) atCmd(rmCmd, AT_NOTHING);
rmResponse = atResponse(rbuf, conf.t2Timer);
}
@@ -726,6 +727,7 @@
u_short rcpcnt = 0;
u_short pprcnt = 0;
u_int fcount = 0;
+ u_short syncattempts = 0;
bool blockgood = false;
do {
sentERR = false;
@@ -910,18 +912,25 @@
free(block);
return (false);
}
+ } else {
+ if (syncattempts++ > 20) {
+ emsg = "Cannot synchronize ECM frame reception.";
+ free(block);
+ return(false);
+ }
}
if (! blockgood) { // back to high-speed carrier
setInputBuffering(true);
if (flowControl == FLOW_XONXOFF)
(void) setXONXOFF(FLOW_NONE, FLOW_XONXOFF, ACT_FLUSH);
fxStr rmCmd(curcap[HasShortTraining(curcap)].value, rmCmdFmt);
+ u_short attempts = 0;
ATResponse response = AT_NOTHING;
- while (response != AT_CONNECT && response != AT_TIMEOUT && response != AT_ERROR) {
+ while ((response == AT_NOTHING || response == AT_FCERROR) && attempts++ < 20) {
(void) atCmd(rmCmd, AT_NOTHING);
response = atResponse(rbuf, conf.t2Timer);
}
- if (response == AT_TIMEOUT || response == AT_ERROR) {
+ if (response != AT_CONNECT) {
free(block);
return (false);
}
@@ -948,12 +957,13 @@
if (flowControl == FLOW_XONXOFF)
(void) setXONXOFF(FLOW_NONE, FLOW_XONXOFF, ACT_FLUSH);
fxStr rmCmd(curcap[HasShortTraining(curcap)].value, rmCmdFmt);
+ u_short attempts = 0;
ATResponse response = AT_NOTHING;
- while (response != AT_CONNECT && response != AT_TIMEOUT && response != AT_ERROR) {
+ while ((response == AT_NOTHING || response == AT_FCERROR) && attempts++ < 20) {
(void) atCmd(rmCmd, AT_NOTHING);
response = atResponse(rbuf, conf.t2Timer);
}
- if (response == AT_TIMEOUT || response == AT_ERROR) {
+ if (response != AT_CONNECT) {
free(block);
return (false);
}
