Re: [hylafax-users] Modem wedged / "initializing server" problem

[jcleary@xxxxxxxxxxxxxx]

>  I'll look
> back through the log files and see if I can find anything.  If I do, I'll
> share what I find.

Okay, I looked at /var/log/messages.1, and here is what I found.  It looks
like the problem began right after the last successful fax received.

Here is /var/log/messages.1 starting from just before the last received fax:

Nov  5 07:01:05 localhost FaxGetty[14233]: MODEM LT V.92 1.0 MT5634SMI-V92
DATA/FAX MODEM VERSION 1.32D LT V.92 1.0 MT5634SMI-V92 Data/Fax Modem
Version 1.32d/
Nov  5 07:13:16 localhost FaxGetty[14233]: ANSWER: Call ID 1 "XXXXXXXXXX"
Nov  5 07:13:16 localhost FaxGetty[14233]: ANSWER: Call ID 2 ""
Nov  5 07:13:32 localhost FaxGetty[14233]: ANSWER: FAX CONNECTION  DEVICE
'/dev/ttyMU1a'
Nov  5 07:13:36 localhost FaxGetty[23520]: RECV FAX (000001643): from
<UNSPECIFIED>, page 1 in 0:04, INF, 3.85 line/mm, 2-D MMR, 26400 bit/s
Nov  5 07:14:11 localhost FaxGetty[23557]: RECV FAX (000001643): from
<UNSPECIFIED>, page 2 in 0:35, INF, 3.85 line/mm, 2-D MMR, 26400 bit/s
Nov  5 07:14:21 localhost FaxGetty[23572]: RECV FAX (000001643): from
<UNSPECIFIED>, page 3 in 0:10, INF, 3.85 line/mm, 2-D MMR, 26400 bit/s
Nov  5 07:14:21 localhost FaxGetty[23573]: RECV FAX (000001643):
recvq/fax000001637.tif from <UNSPECIFIED>, route to <unspecified>, 3 pages
in 0:49
Nov  5 07:14:21 localhost FaxGetty[14233]: RECV FAX (000001643): session
with <UNSPECIFIED> terminated abnormally: Received premature V.34
termination.
Nov  5 07:14:21 localhost FaxGetty[14233]: RECV FAX: bin/faxrcvd
"recvq/fax000001637.tif" "ttyMU1a" "000001643" "Received premature V.34
termination." "XXXXXXXXXX" ""
Nov  5 07:17:01 localhost FaxGetty[14233]: /dev/ttyMU1a: Can not
initialize modem.
Nov  5 07:22:34 localhost FaxGetty[14233]: Unable to setup modem on
/dev/ttyMU1a; giving up after 2 attempts
Nov  5 07:22:34 localhost FaxGetty[14233]: MODEM /dev/ttyMU1a appears to
be wedged
Nov  5 07:22:34 localhost FaxGetty[14233]: CLOSE /dev/ttyMU1a
Nov  5 07:22:34 localhost FaxGetty[24201]: OPEN /dev/ttyMU1a  HylaFAX (tm)
Version 4.2.2
Nov  5 07:25:06 localhost FaxGetty[24201]: /dev/ttyMU1a: Can not
initialize modem.
Nov  5 07:28:23 localhost FaxGetty[24201]: Unable to setup modem on
/dev/ttyMU1a; giving up after 2 attempts
Nov  5 07:28:23 localhost FaxGetty[24201]: MODEM /dev/ttyMU1a appears to
be wedged

And the wedged and initialization errors repeat from that point on.

Here's the fax recieve log from that same last received fax, with most of
the frame RECV lines removed for brevity:

Nov 05 07:13:16.46: [14233]: SESSION BEGIN 000001643 1XXXXXXXXXX
Nov 05 07:13:16.46: [14233]: HylaFAX (tm) Version 4.2.2
Nov 05 07:13:16.46: [14233]: <-- [4:ATA\r]
Nov 05 07:13:32.54: [14233]: --> [9:+F34:11,1]
Nov 05 07:13:32.54: [14233]: V.8 handshaking succeeded, V.34-Fax (SuperG3)
capability enabled.
Nov 05 07:13:32.54: [14233]: Primary channel rate: 26400 bit/s, Control
channel rate: 1200 bit/s.
Nov 05 07:13:32.54: [14233]: --> [7:CONNECT]
Nov 05 07:13:32.54: [14233]: ANSWER: FAX CONNECTION  DEVICE '/dev/ttyMU1a'
Nov 05 07:13:32.54: [14233]: RECV FAX: begin
Nov 05 07:13:32.54: [14233]: Control channel selected
Nov 05 07:13:32.54: [14233]: <-- data [32]
Nov 05 07:13:32.54: [14233]: <-- data [2]
Nov 05 07:13:32.54: [14233]: <-- data [23]
Nov 05 07:13:32.54: [14233]: <-- data [2]
Nov 05 07:13:32.54: [14233]: <-- data [10]
Nov 05 07:13:32.54: [14233]: <-- data [2]
Nov 05 07:13:33.89: [14233]: REMOTE wants 26400 bit/s
Nov 05 07:13:33.89: [14233]: REMOTE wants A4 page width (215 mm)
Nov 05 07:13:33.89: [14233]: REMOTE wants unlimited page length
Nov 05 07:13:33.89: [14233]: REMOTE wants 3.85 line/mm
Nov 05 07:13:33.89: [14233]: REMOTE wants 2-D MMR
Nov 05 07:13:33.89: [14233]: REMOTE wants T.30 Annex A, 256-byte ECM
Nov 05 07:13:33.89: [14233]: <-- data [3]
Nov 05 07:13:33.89: [14233]: <-- data [2]
Nov 05 07:13:34.73: [14233]: Primary channel selected
Nov 05 07:13:35.11: [14233]: RECV received frame number 0
[snip]
Nov 05 07:13:35.65: [14233]: RECV received frame number 7
Nov 05 07:13:36.10: [14233]: Control channel selected
Nov 05 07:13:36.43: [14233]: RECV recv PPS (partial page signal)
Nov 05 07:13:36.43: [14233]: RECV recv MPS (more pages, same document)
Nov 05 07:13:36.43: [14233]: RECV received 8 frames of block 1 of page 1
Nov 05 07:13:36.44: [14233]: RECV: 2048 bytes of data, 1073 total lines
Nov 05 07:13:36.45: [14233]: RECV send MCF (message confirmation)
Nov 05 07:13:36.45: [14233]: RECV FAX (000001643): from <UNSPECIFIED>,
page 1 in 0:04, INF, 3.85 line/mm, 2-D MMR, 26400 bit/s
Nov 05 07:13:36.45: [14233]: <-- data [3]
Nov 05 07:13:36.45: [14233]: <-- data [2]
Nov 05 07:13:37.29: [14233]: Primary channel selected
Nov 05 07:13:37.68: [14233]: RECV received frame number 0
[snip]
Nov 05 07:13:58.54: [14233]: RECV received frame number 255
Nov 05 07:13:58.98: [14233]: Control channel selected
Nov 05 07:13:59.31: [14233]: RECV recv PPS (partial page signal)
Nov 05 07:13:59.31: [14233]: RECV recv NULL (more blocks, same page)
Nov 05 07:13:59.31: [14233]: RECV received 256 frames of block 1 of page 2
Nov 05 07:13:59.59: [14233]: RECV: 65536 bytes of data, 0 total lines
Nov 05 07:13:59.60: [14233]: <-- data [3]
Nov 05 07:13:59.60: [14233]: <-- data [2]
Nov 05 07:13:59.60: [14233]: RECV send MCF (message confirmation)
Nov 05 07:14:00.43: [14233]: Primary channel selected
Nov 05 07:14:00.82: [14233]: RECV received frame number 0
[snip]
Nov 05 07:14:10.11: [14233]: RECV received frame number 114
Nov 05 07:14:10.57: [14233]: Control channel selected
Nov 05 07:14:10.90: [14233]: RECV recv PPS (partial page signal)
Nov 05 07:14:10.90: [14233]: RECV recv MPS (more pages, same document)
Nov 05 07:14:10.90: [14233]: RECV received 115 frames of block 2 of page 2
Nov 05 07:14:11.03: [14233]: RECV: 29440 bytes of data, 1074 total lines
Nov 05 07:14:11.03: [14233]: RECV send MCF (message confirmation)
Nov 05 07:14:11.03: [14233]: RECV FAX (000001643): from <UNSPECIFIED>,
page 2 in 0:35, INF, 3.85 line/mm, 2-D MMR, 26400 bit/s
Nov 05 07:14:11.03: [14233]: <-- data [3]
Nov 05 07:14:11.03: [14233]: <-- data [2]
Nov 05 07:14:11.88: [14233]: Primary channel selected
Nov 05 07:14:12.27: [14233]: RECV received frame number 0
[snip]
Nov 05 07:14:20.98: [14233]: RECV received frame number 107
Nov 05 07:14:21.25: [14233]: HDLC frame with bad control field 0xff
Nov 05 07:14:21.25: [14233]: HDLC frame with bad address field 0xba
Nov 05 07:14:21.25: [14233]: got <DLE><3C>
Nov 05 07:14:21.25: [14233]: got <DLE><A2>
Nov 05 07:14:21.25: [14233]: got <DLE><A2>
Nov 05 07:14:21.27: [14233]: got <DLE><A2>
Nov 05 07:14:21.27: [14233]: got <DLE><A2>
Nov 05 07:14:21.27: [14233]: got <DLE><3C>
Nov 05 07:14:21.27: [14233]: got <DLE><A2>
Nov 05 07:14:21.27: [14233]: got <DLE><21>
Nov 05 07:14:21.30: [14233]: got <DLE><3C>
Nov 05 07:14:21.32: [14233]: got <DLE><FF>
Nov 05 07:14:21.34: [14233]: got <DLE><22>
Nov 05 07:14:21.36: [14233]: got <DLE><BD>
Nov 05 07:14:21.36: [14233]: got <DLE><24>
Nov 05 07:14:21.39: [14233]: got <DLE><AE>
Nov 05 07:14:21.39: [14233]: got <DLE><24>
Nov 05 07:14:21.41: [14233]: got <DLE><8>
Nov 05 07:14:21.43: [14233]: got <DLE><FF>
Nov 05 07:14:21.45: [14233]: got <DLE><A4>
Nov 05 07:14:21.45: [14233]: got <DLE><A4>
Nov 05 07:14:21.47: [14233]: got <DLE><14>
Nov 05 07:14:21.50: [14233]: got <DLE><8>
Nov 05 07:14:21.50: [14233]: got <DLE><1>
Nov 05 07:14:21.50: [14233]: got <DLE><8>
Nov 05 07:14:21.50: [14233]: got <DLE><0>
Nov 05 07:14:21.50: [14233]: got <DLE><8>
Nov 05 07:14:21.52: [14233]: got <DLE><0>
Nov 05 07:14:21.54: [14233]: got <DLE><22>
Nov 05 07:14:21.54: [14233]: got <DLE><2>
Nov 05 07:14:21.54: [14233]: HDLC frame with bad address field 0x3a
Nov 05 07:14:21.54: [14233]: got <DLE><30>
Nov 05 07:14:21.54: [14233]: got <DLE><2>
Nov 05 07:14:21.56: [14233]: got <DLE><0>
Nov 05 07:14:21.56: [14233]: got <DLE><1E>
Nov 05 07:14:21.56: [14233]: got <DLE><5>
Nov 05 07:14:21.59: [14233]: got <DLE><0>
Nov 05 07:14:21.61: [14233]: got <DLE><6>
Nov 05 07:14:21.61: [14233]: got <DLE><40>
Nov 05 07:14:21.61: [14233]: got <DLE><6>
Nov 05 07:14:21.67: [14233]: got <DLE><1F>
Nov 05 07:14:21.67: [14233]: got <DLE><50>
Nov 05 07:14:21.70: [14233]: EOT received (end of transmission)
Nov 05 07:14:21.70: [14233]: Received premature V.34 termination.
Nov 05 07:14:21.70: [14233]: RECV keeping unconfirmed page
Nov 05 07:14:21.82: [14233]: RECV: 27648 bytes of data, 722 total lines
Nov 05 07:14:21.82: [14233]: RECV FAX (000001643): from <UNSPECIFIED>,
page 3 in 0:10, INF, 3.85 line/mm, 2-D MMR, 26400 bit/s
Nov 05 07:14:21.82: [14233]: RECV FAX (000001643): recvq/fax000001637.tif
from <UNSPECIFIED>, route to <unspecified>, 3 pages in 0:49
Nov 05 07:14:21.82: [14233]: RECV FAX: Received premature V.34 termination.
Nov 05 07:14:21.82: [14233]: RECV FAX (000001643): session with
<UNSPECIFIED> terminated abnormally: Received premature V.34 termination.
Nov 05 07:14:21.82: [14233]: RECV FAX: bin/faxrcvd
"recvq/fax000001637.tif" "ttyMU1a" "000001643" "Received premature V.34
termination." "XXXXXXXXXX" ""
Nov 05 07:14:21.82: [14233]: RECV FAX: end
Nov 05 07:14:21.82: [14233]: SESSION END

Do those "DLE" codes refer to voice actions?  Is it possible that a
handset was picked up mid-call and that could have screwed things up?

Looking through my logs, I count a total of 5 instances in the last month
of a session containint a "Received premature V.34 termination" error, so
this is not the first time that has happened.  This is, however, the first
time that the modem has found itself in this "wedged" state.

_Jeff Cleary



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