[hylafax-users] RSPREC error/got EOT
Jonathan Smithe
We have a customer that cannot receive faxes from a "Philips HFC 141"
machine. The error we get is "RSPREC error/got EOT" most of the
times,. but I can also see a "RSPREC error/got DCN". The error on the
Philips machine is "Report Error"
We're using Hylafax+ 4.3.0.3, with t38modem. The rest of the faxes go
in/out without any problem, we don't have any packetloss to the CISCO
machine we connect to (it's plugged in the same switch with the
Hylafax machine).
Any hint is appreciated.
Thanks
P.S: I have attached here the last transmission log.
Jun 26 08:24:42.78: [23815]: ANSWER: FAX CONNECTION DEVICE '/dev/ttyxe'
Jun 26 08:24:42.78: [23815]: STATE CHANGE: ANSWERING -> RECEIVING
Jun 26 08:24:42.78: [23815]: RECV FAX: begin
Jun 26 08:24:42.78: [23815]: <-- HDLC<19:FF C0 04 B5 00 AA A6 B4 66 86
1E 04 14 2E B6 94 04 6A CC>
Jun 26 08:24:42.78: [23815]: <-- data [19]
Jun 26 08:24:42.78: [23815]: <-- data [2]
Jun 26 08:24:44.29: [23815]: --> [7:CONNECT]
Jun 26 08:24:44.29: [23815]: <-- HDLC<23:FF C0 02 04 04 04 04 04 04 04
04 04 04 04 04 04 04 04 04 04 04 04 04>
Jun 26 08:24:44.29: [23815]: <-- data [23]
Jun 26 08:24:44.29: [23815]: <-- data [2]
Jun 26 08:24:45.01: [23815]: --> [7:CONNECT]
Jun 26 08:24:45.01: [23815]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
Jun 26 08:24:45.01: [23815]: <-- data [13]
Jun 26 08:24:45.01: [23815]: <-- data [2]
Jun 26 08:24:45.49: [23815]: --> [2:OK]
Jun 26 08:24:45.49: [23815]: <-- [9:AT+FRH=3\r]
Jun 26 08:24:46.68: [23815]: --> [7:CONNECT]
Jun 26 08:24:48.17: [23815]: --> HDLC<25:FF C0 C2 9C 2C EC CC 4C 4C 4C
8C 0C 2C D4 04 04 04 04 04 04 04 04 04 2D FB>
Jun 26 08:24:48.17: [23815]: --> [2:OK]
Jun 26 08:24:48.17: [23815]: REMOTE TSI "FAX"
Jun 26 08:24:48.17: [23815]: <-- [9:AT+FRH=3\r]
Jun 26 08:24:48.17: [23815]: --> [7:CONNECT]
Jun 26 08:24:48.52: [23815]: --> HDLC<12:FF C8 C1 00 60 15 01 01 01 00 FC 74>
Jun 26 08:24:48.52: [23815]: --> [2:OK]
Jun 26 08:24:48.52: [23815]: REMOTE wants 9600 bit/s
Jun 26 08:24:48.52: [23815]: REMOTE wants A4 page width (215 mm)
Jun 26 08:24:48.52: [23815]: REMOTE wants unlimited page length
Jun 26 08:24:48.52: [23815]: REMOTE wants 3.85 line/mm
Jun 26 08:24:48.52: [23815]: REMOTE wants 1-D MH
Jun 26 08:24:48.52: [23815]: RECV training at v.29 9600 bit/s
Jun 26 08:24:48.52: [23815]: <-- [10:AT+FRM=96\r]
Jun 26 08:24:50.55: [23815]: --> [10:NO CARRIER]
Jun 26 08:24:50.55: [23815]: MODEM No carrier
Jun 26 08:24:50.55: [23815]: <-- [9:AT+FRS=7\r]
Jun 26 08:24:50.63: [23815]: --> [2:OK]
Jun 26 08:24:50.63: [23815]: <-- [9:AT+FTH=3\r]
Jun 26 08:24:50.63: [23815]: --> [7:CONNECT]
Jun 26 08:24:50.63: [23815]: <-- HDLC<3:FF C8 22>
Jun 26 08:24:50.63: [23815]: <-- data [3]
Jun 26 08:24:50.63: [23815]: <-- data [2]
Jun 26 08:24:51.67: [23815]: --> [2:OK]
Jun 26 08:24:51.67: [23815]: TRAINING failed
Jun 26 08:24:51.67: [23815]: <-- [9:AT+FRH=3\r]
Jun 26 08:24:52.70: [23815]: --> [7:CONNECT]
Jun 26 08:24:54.19: [23815]: --> HDLC<25:FF C0 C2 9C 2C EC CC 4C 4C 4C
8C 0C 2C D4 04 04 04 04 04 04 04 04 04 2D FB>
Jun 26 08:24:54.19: [23815]: --> [2:OK]
Jun 26 08:24:54.19: [23815]: REMOTE TSI "FAX"
Jun 26 08:24:54.19: [23815]: <-- [9:AT+FRH=3\r]
Jun 26 08:24:54.19: [23815]: --> [7:CONNECT]
Jun 26 08:24:54.53: [23815]: --> HDLC<12:FF C8 C1 00 70 15 01 01 01 00 E6 F0>
Jun 26 08:24:54.53: [23815]: --> [2:OK]
Jun 26 08:24:54.53: [23815]: REMOTE wants 7200 bit/s
Jun 26 08:24:54.53: [23815]: REMOTE wants A4 page width (215 mm)
Jun 26 08:24:54.53: [23815]: REMOTE wants unlimited page length
Jun 26 08:24:54.53: [23815]: REMOTE wants 3.85 line/mm
Jun 26 08:24:54.53: [23815]: REMOTE wants 1-D MH
Jun 26 08:24:54.53: [23815]: RECV training at v.29 7200 bit/s
Jun 26 08:24:54.53: [23815]: <-- [10:AT+FRM=72\r]
Jun 26 08:24:59.04: [23815]: --> [0:]
Jun 26 08:24:59.04: [23815]: MODEM <Empty line>
Jun 26 08:24:59.04: [23815]: MODEM TIMEOUT: receiving TCF
Jun 26 08:24:59.04: [23815]: <-- data [1]
Jun 26 08:24:59.04: [23815]: --> [2:OK]
Jun 26 08:24:59.04: [23815]: <-- [9:AT+FRS=7\r]
Jun 26 08:24:59.11: [23815]: --> [2:OK]
Jun 26 08:24:59.11: [23815]: <-- [9:AT+FTH=3\r]
Jun 26 08:24:59.11: [23815]: --> [7:CONNECT]
Jun 26 08:24:59.11: [23815]: <-- HDLC<3:FF C8 22>
Jun 26 08:24:59.11: [23815]: <-- data [3]
Jun 26 08:24:59.11: [23815]: <-- data [2]
Jun 26 08:25:01.18: [23815]: --> [2:OK]
Jun 26 08:25:01.18: [23815]: TRAINING failed
Jun 26 08:25:01.18: [23815]: <-- [9:AT+FRH=3\r]
Jun 26 08:25:01.73: [23815]: --> [8:+FCERROR]
Jun 26 08:25:01.73: [23815]: DELAY 1500 ms
Jun 26 08:25:03.23: [23815]: <-- [9:AT+FTH=3\r]
Jun 26 08:25:03.23: [23815]: --> [7:CONNECT]
Jun 26 08:25:03.23: [23815]: <-- HDLC<19:FF C0 04 B5 00 AA A6 B4 66 86
1E 04 14 2E B6 94 04 6A CC>
Jun 26 08:25:03.23: [23815]: <-- data [19]
Jun 26 08:25:03.23: [23815]: <-- data [2]
Jun 26 08:25:05.69: [23815]: --> [7:CONNECT]
Jun 26 08:25:05.69: [23815]: <-- HDLC<23:FF C0 02 04 04 04 04 04 04 04
04 04 04 04 04 04 04 04 04 04 04 04 04>
Jun 26 08:25:05.69: [23815]: <-- data [23]
Jun 26 08:25:05.69: [23815]: <-- data [2]
Jun 26 08:25:06.41: [23815]: --> [7:CONNECT]
Jun 26 08:25:06.41: [23815]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
Jun 26 08:25:06.41: [23815]: <-- data [13]
Jun 26 08:25:06.41: [23815]: <-- data [2]
Jun 26 08:25:06.90: [23815]: --> [2:OK]
Jun 26 08:25:06.90: [23815]: <-- [9:AT+FRH=3\r]
Jun 26 08:25:09.91: [23815]: --> [8:+FCERROR]
Jun 26 08:25:09.91: [23815]: DELAY 1500 ms
Jun 26 08:25:11.41: [23815]: <-- [9:AT+FTH=3\r]
Jun 26 08:25:11.41: [23815]: --> [7:CONNECT]
Jun 26 08:25:11.41: [23815]: <-- HDLC<19:FF C0 04 B5 00 AA A6 B4 66 86
1E 04 14 2E B6 94 04 6A CC>
Jun 26 08:25:11.41: [23815]: <-- data [19]
Jun 26 08:25:11.41: [23815]: <-- data [2]
Jun 26 08:25:13.88: [23815]: --> [7:CONNECT]
Jun 26 08:25:13.88: [23815]: <-- HDLC<23:FF C0 02 04 04 04 04 04 04 04
04 04 04 04 04 04 04 04 04 04 04 04 04>
Jun 26 08:25:13.88: [23815]: <-- data [23]
Jun 26 08:25:13.88: [23815]: <-- data [2]
Jun 26 08:25:14.60: [23815]: --> [7:CONNECT]
Jun 26 08:25:14.60: [23815]: <-- HDLC<13:FF C8 01 00 77 5F 23 01 FB C1 01 01 18>
Jun 26 08:25:14.60: [23815]: <-- data [13]
Jun 26 08:25:14.60: [23815]: <-- data [2]
Jun 26 08:25:15.08: [23815]: --> [2:OK]
Jun 26 08:25:15.08: [23815]: <-- [9:AT+FRH=3\r]
Jun 26 08:25:17.78: [23815]: --> [10:NO CARRIER]
Jun 26 08:25:17.78: [23815]: MODEM No carrier
Jun 26 08:25:17.78: [23815]: DELAY 1500 ms
Jun 26 08:25:19.28: [23815]: <-- [9:AT+FTH=3\r]
Jun 26 08:25:19.38: [23815]: --> [5:ERROR]
Jun 26 08:25:19.38: [23815]: RECV FAX: RSPREC error/got EOT
Jun 26 08:25:19.38: [23815]: RECV FAX: end
Jun 26 08:25:19.38: [23815]: SESSION END
____________________ HylaFAX(tm) Users Mailing List _______________________
To subscribe/unsubscribe, click http://lists.hylafax.org/cgi-bin/lsg2.cgi
On UNIX: mail -s unsubscribe hylafax-us...@hylafax.org < /dev/null
*To learn about commercial HylaFAX(tm) support, mail sa...@ifax.com.*
Lee Howard
> We're using Hylafax+ 4.3.0.3, with t38modem.
> Jun 26 08:24:48.52: [23815]: RECV training at v.29 9600 bit/s
> Jun 26 08:24:48.52: [23815]: <-- [10:AT+FRM=96\r]
> Jun 26 08:24:50.55: [23815]: --> [10:NO CARRIER]
I'm a bit intrigued by the timing of this NO CARRIER response. T.31
provides for a NO CARRIER response only in the case where there is
actual carrier loss (in which case we *should* see a CONNECT before
it). In fact, the timing of the NO CARRIER response (2 seconds after
+FRM) would almost seem to indicate that t38modem erred and did not
report the CONNECT response as it should have.
It is expected that a NO CARRIER or ERROR result also occur on a
possible timeout situation. But I would think that we're not talking
about a timeout situation at a mere 2 seconds.
> Jun 26 08:24:54.53: [23815]: RECV training at v.29 7200 bit/s
> Jun 26 08:24:54.53: [23815]: <-- [10:AT+FRM=72\r]
> Jun 26 08:24:59.04: [23815]: --> [0:]
> Jun 26 08:24:59.04: [23815]: MODEM <Empty line>
> Jun 26 08:24:59.04: [23815]: MODEM TIMEOUT: receiving TCF
> Jun 26 08:24:59.04: [23815]: <-- data [1]
> Jun 26 08:24:59.04: [23815]: --> [2:OK]
In this instance I find the results a bit incredible. It's extremely
unlikely that the sender delivered TSI and DCS only to then omit TCF.
Most likely the modem was not capable of detecting (or failed to detect)
the V.29 7200 bps carrier as transmitted by the sender.
> Jun 26 08:25:01.18: [23815]: <-- [9:AT+FRH=3\r]
> Jun 26 08:25:01.73: [23815]: --> [8:+FCERROR]
> Jun 26 08:25:06.90: [23815]: <-- [9:AT+FRH=3\r]
> Jun 26 08:25:09.91: [23815]: --> [8:+FCERROR]
And these +FCERROR responses are something that, I believe, that
t38modem is doing incorrectly in response to +FRH=3.
T.31 does make provision for +FCERROR after +FRH=3. However, the modem
should only respond such when the expected modulation is V.27ter, V.29,
or V.17, like +FRH=146, and not V.21. (Yes, this may be contrary to a
strict adherance to the spec.) This is how other (hardware) modems
behave, and I believe that it is with sound reason, too. In more simple
terms, +FCERROR should only ever indicate that V.21 signalling was heard
when expecting some other modulation. It should never be used to
indicate that a high-speed modulation carrier was detected.
The reasons for this are multiple:
1) If used to indicate carrier presense other than V.21 it is quite
impossible for the DTE to know to what carrier the +FCERROR result is
referring. The +FCERROR result is ambiguous when used to indicate
carrier presense other than V.21.
2) Intermittent V.21 "handshakes" serve as a kind of synchronization
mechanism for fax. If ever the endpoints become disjointed or
out-of-sync they need only stop and wait for the next set of V.21 HDLC
signals and act accordingly in order to resync. By allowing the +FRH=3
command to sit and wait, without a response or result (even for a period
up to 30 or 45 or 60 seconds) ignoring any high-speed modulations
present until V.21 is detected allows the +FRH=3 command to serve in
this capacity as a "synchronization command".
3) If the DTE gets +FCERROR in response to +FRH=3 its options are very
limited. Fax carriers other than V.21 cannot be entered mid-stream
without first receiving the training phase of the carrier cycle. The
DTE must, essentially, continue repeating +FRH=3 until the +FCERROR
result stops. (It may use +FRS in order to limit the iterations of
+FRH=3/+FCERROR.) Thus the end-result of the +FCERROR result for
detected carriers other than V.21 is only an increased difficulty for
the DTE.
I can write some code to HylaFAX that will try to cope with +FCERROR
results to +FRH=3 as best as possible. (I may do this anyway.) But I
think that the best course of action here is for you to forward this
message to Vyacheslav (if he's not reading this list anyway still) and
let's see if we can all get together to resolve these issues. From my
perspective your trouble with this sender is due to problems in t38modem
itself.
Lee.
Jonathan Smithe
> I can write some code to HylaFAX that will try to cope with +FCERROR
> results to +FRH=3 as best as possible. (I may do this anyway.) But I
> think that the best course of action here is for you to forward this
> message to Vyacheslav (if he's not reading this list anyway still) and
> let's see if we can all get together to resolve these issues. From my
> perspective your trouble with this sender is due to problems in t38modem
> itself.
I have also FWD the e-mail to Vyacheslav.
Thanks for your time and I will keep you posted on any updates I might receive.
gigelusster
Jonathan Smithe
On 6/26/06, Lee Howard <fax...@howardsilvan.com> wrote:
> Jonathan Smithe wrote:
>
> > We're using Hylafax+ 4.3.0.3, with t38modem.
>
>
> I can write some code to HylaFAX that will try to cope with +FCERROR
> results to +FRH=3 as best as possible. (I may do this anyway.) But I
> think that the best course of action here is for you to forward this
> message to Vyacheslav (if he's not reading this list anyway still) and
> let's see if we can all get together to resolve these issues. From my
> perspective your trouble with this sender is due to problems in t38modem
> itself.
This e-mail is only FYI, in the case anyone else has problems with
Hylafax+t38modem+"RSPREC error/got EOT" errors
Tested Hylafax+ 4.3.0.5.
Besides generating +2MB logfiles for some of the received faxes, the
problem dissapeared and the pages are being received without any
problem.
The logfiles that are this big are full of:
-snip-
Jun 29 21:10:00.38: [ 4051]: <-- [9:AT+FRH=3\r]
Jun 29 21:10:00.38: [ 4051]: --> [8:+FCERROR]
Jun 29 21:10:00.38: [ 4051]: <-- [9:AT+FRH=3\r]
Jun 29 21:10:00.38: [ 4051]: --> [8:+FCERROR]
Jun 29 21:10:00.38: [ 4051]: <-- [9:AT+FRH=3\r]
Jun 29 21:10:00.38: [ 4051]: --> [8:+FCERROR]
Jun 29 21:10:00.38: [ 4051]: <-- [9:AT+FRH=3\r]
Jun 29 21:10:00.38: [ 4051]: --> [8:+FCERROR]
Jun 29 21:10:00.38: [ 4051]: <-- [9:AT+FRH=3\r]
Jun 29 21:10:00.38: [ 4051]: --> [8:+FCERROR]
-snip-
Bottom line, Hylafax+ 4.3.0.5 and t38modem doesn't generate the RSPREC error.
Regards,
gigelusster
Lee Howard
Yeah. You see, t38modem apparently gives +FCERROR after AT+FRH=3 when
it finds a V.17, V.29, or V.27ter carrier. This behavior *is * correct
according to rigid adherence to the T.31 specification, but it is not a
wise behavior (as discussed before) and does not follow what other
modems do. If the modem finds one of those carriers present after
AT+FRH=3 it really must just sit there and wait for the V.21 carrier to
become present.
In order to "approximate" the desired AT+FRH=3 behavior I merely looped
it in the case of +FCERROR until a timeout occurs. The log file that I
saw last time showed a delay between AT+FRH=3 and the +FCERROR response
and so I was hoping that the loop would not be fast due to that delay.
But it appears that the delay goes away after the first iteration or
so. Consequently I'll add a small pause in the loop to slow it down and
not generate so much logging. You'll see that in 4.3.0.6 or whatever
the next HylaFAX+ release is.
Thanks,
Lee.