Re: [hylafax-users] Help debugging modem session log

[Lee Howard <faxguy@xxxxxxxxxxxxxxxx>]

George H wrote:
> Nov 15 16:14:49.36: [27171]: <-- [10:AT+FRM=96\r]
> Nov 15 16:14:49.86: [27171]: --> [7:CONNECT]
>
> The AT+FRH=3 command  is successful twice (though in the T.31 doc they
> mention it occuring 3 times instead of 2 before AT+FRM=96
>   

I'm not looking at T.31 right now, but the sender can send other frames 
besides TSI and DCS.  However, usually a sender only sends those two.

> Nov 15 16:14:52.09: [27171]: MODEM set XON/XOFF/DRAIN: input ignored,
> output disabled
> Nov 15 16:14:52.09: [27171]: RECV: TCF 1781 bytes, 1% non-zero, 1756 zero-run
> Nov 15 16:14:52.09: [27171]: --> [10:NO CARRIER]
> Nov 15 16:14:52.09: [27171]: DELAY 70 ms
> Nov 15 16:14:52.16: [27171]: TRAINING succeeded
>
> I don't know if this is a problem with my modem config or not but the
> T.31 docs say it should delay 75ms not 70ms. But then again you guys
> are the experts so I don't know if this is ok.
>   

It's 75 ms +/- 15 ms.  So 70 ms is completely within bounds.  It would 
be exactly 75 ms, but the <delay:n> escape that you're using in your 
modem config file does not give us any more precision than 10 ms increments.

> Nov 15 16:14:52.17: [27171]: <-- [9:AT+FTH=3\r]
> Nov 15 16:14:59.72: [27171]: --> [0:]
> Nov 15 16:14:59.72: [27171]: MODEM TIMEOUT: sending HDLC frame
>
> I don't understand this part. The result code for AT+FTH=3  is empty.
>   

The modem crashed.  It is, after all, a USR modem.

Honestly, this should never happen.  It should respond with CONNECT or 
ERROR very quickly.

So something is happening on the DSP-side of the modem (the part that 
takes-in the audio and demodulates it) before this point that is causing 
it to crash... possibly something in the sender's TCF signalling.  Look 
for firmware updates... the only test at a workaround would be to 
disable V.29... at least for this caller... but then they'd be sending 
you faxes at 4800 bps at best.

> The T.31 doc (8.3.5) says it should return another frame if the DTE
> sends more data, or return OK if a null frame is sent and then the
> transmit carrier is turned off, or ERROR returned if 5 seconds elapses
> after a CONNECT is reported.
>   

Well, HylaFAX now is going to enter recovery procedures... which in this 
case will be to wait for TCF again... which truthfully... HylaFAX should 
probably fall back to waiting for TSI+DCS first.  Anything at this point 
is doomed anyway, though... the modem is crashed.

> Nov 15 16:14:59.72: [27171]: <-- [10:AT+FRM=96\r]
>
> To me looks like it's trying to retrain
>
> Nov 15 16:15:06.73: [27171]: MODEM TIMEOUT: reading line from modem
> Nov 15 16:15:06.73: [27171]: <-- data [1]
> Nov 15 16:15:06.93: [27171]: MODEM TIMEOUT: reading line from modem
> Nov 15 16:15:06.93: [27171]: MODEM <Timeout>
>
> Got no clue what's going on here.
>   

Both here and above with the AT+FTH=3 command... the modem is not 
responding to commands... even aborts.

> Nov 15 16:15:06.93: [27171]: <-- [9:AT+FRH=3\r]
> Nov 15 16:15:10.35: [27171]: --> [10:NO CARRIER]
> Nov 15 16:15:10.35: [27171]: MODEM No carrier
>
> Detects loss of carrier, but I Don't know what "MODEM No carrier"
> should indicate.
>   

I'm not sure what it is supposed to mean, either.  It's out-of-spec.  So 
one would have to get an answer from USR on this.  Good luck!  :-)

> Nov 15 16:15:10.35: [27171]: RECV FAX (000014681):
> recvq/fax000014638.tif from 961 x xxxxxx, subaddress <unspecified>, 0
> pages in 0:27
> Nov 15 16:15:10.36: [27171]: RECV FAX: T.30 T2 timeout, expected page
> not received {E111}
> Nov 15 16:15:10.36: [27171]: DELAY 70 ms
> Nov 15 16:15:10.43: [27171]: <-- [9:AT+FTH=3\r]
> Nov 15 16:15:10.48: [27171]: --> [5:ERROR]
>
> Here's the ERROR result code that I mentioned above. The last CONNECT
> was at 16:14:49.86, and ERROR was returned at 16:15:10.48 .. that's
> about a minute. Was this error due to that because in between no
> additional data was transmitted?
>   

The ERROR here means that now the modem is on-hook.  So the modem was 
dying for maybe 20 seconds... and now it's reset itself and is back 
on-hook in command mode.

> Nov 15 16:15:10.48: [27171]: MODEM input buffering enabled
> Nov 15 16:15:10.48: [27171]: RECV FAX (000014681): session with 961 x
> xxxxxx terminated abnormally: T.30 T2 timeout, expected page not
> received {E111}
> Nov 15 16:15:10.48: [27171]: RECV FAX: bin/faxrcvd
> 'recvq/fax000014638.tif' 'ttyS5' '000014681' 'T.30 T2 timeout,
> expected page not received {E111}'
> Nov 15 16:15:10.48: [27171]: RECV FAX: end
> Nov 15 16:15:10.48: [27171]: SESSION END
>
> End of the session log. This one sender trying to send me a fax has 6
> different session logs just like this one. What kind of conclusions
> could I draw from this?

That the USR modem is buggy.  Something is probably unique about this 
sender's V.29 signalling, and it apparently is crashing the modem.

Thanks,

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*