[asterisk-users] rxfax, spandsp and lack of ecm

[Steve Davies]

Hi Steve,

On 9/14/06, Steve Davies <davies147 at gmail.com> wrote:
> On 9/14/06, Steve Underwood <steveu at coppice.org> wrote:
> > Steve Davies wrote:
> [snip]
> > >
> > > This looks pretty good I have to say - The ECM seems as if it may be a
> > > little intolerant... On a fax machine where I got 100% success in the
> > > past with 0.0.2, I am now getting "result (60) Disconnected after
> > > permitted retries." on about every 4th page.
> > >
> > > Is the ECM tolerance level tuneable in spandsp, or is this
> > > hard-defined in the standard? Is it just a matter of changing:
> > >  #define MAX_MESSAGE_TRIES   3
> >
> > Your problem probably has nothing to do with tolerance. If an exchange
> > doesn't succeed after 3 tries, it is unlikely to ever succeed. You are
> > probably hitting a bug. It is new code. :-)  Can you enable debug with
> > "|debug" on the command line to rxfax/txfax, and send me the log?
> >

I've been following the snapshot changes, and trying to dig into my
RxFax problem a little more - I think I have finally found a case
which breaks things, and perhaps some useful logs...

I added loads of extra debug statements to track the number of ECM
retries that were occuring, and to log the retries value whenever it
was set or changed. It turns out that the problem I see occurs both
with ECM and with Non-ECM capable machines!

s->retries is occasionally increased due to t4 timeouts, and I presume
that the retries never succeed, as I have yet to see a fax send
recover from this state (Perhaps the fax machines do not like the drop
back from phase C to phase B?)

The trace during the t4 timeout retries is:

Sep 25 13:36:03 DEBUG[6532]: Tx:  DIS with final frame tag
Sep 25 13:36:03 DEBUG[6532]: Tx:  ff 13 80 00 ce f8 c4 80 89 80 80 80
98 80 80 80 80 80 00
Sep 25 13:36:05 DEBUG[6532]: Send complete in phase T30_PHASE_B_TX, state 15
Sep 25 13:36:05 DEBUG[6532]: Send complete in phase T30_PHASE_B_TX, state 15
Sep 25 13:36:05 DEBUG[6532]: Changing from phase T30_PHASE_B_TX to
T30_PHASE_B_RX
Sep 25 13:36:05 DEBUG[6532]: FLOW FAX Set rx type 4
Sep 25 13:36:05 DEBUG[6532]: FLOW FAX Set tx type 0
Sep 25 13:36:05 DEBUG[6532]: HDLC carrier up in state 15
Sep 25 13:36:08 DEBUG[6532]: T4 timeout in phase T30_PHASE_B_RX, state 15
Sep 25 13:36:08 DEBUG[6532]: timer_t4_expired bumped retries count to 2
Sep 25 13:36:08 DEBUG[6532]: Changing from phase T30_PHASE_B_RX to
T30_PHASE_B_TX
Sep 25 13:36:08 DEBUG[6532]: FLOW FAX Set rx type 0
Sep 25 13:36:08 DEBUG[6532]: FLOW FAX Set tx type 4
Sep 25 13:36:08 DEBUG[6532]: DIS:

This happens 4 times, and then the exchange is cancelled. It looks as
thought this state is initiated when the following occurs at the start
of a page:

Non-ECM trace...

Sep 25 12:59:32 DEBUG[4533]: Send complete in phase T30_PHASE_D_TX, state 20
Sep 25 12:59:32 DEBUG[4533]: Changing from state 20 to 10
Sep 25 12:59:32 DEBUG[4533]: Changing from phase T30_PHASE_D_TX to
T30_PHASE_C_NON_ECM_RX
Sep 25 12:59:32 DEBUG[4533]: FLOW FAX Set rx type 8
Sep 25 12:59:32 DEBUG[4533]: FLOW FAX Set tx type 0
Sep 25 12:59:32 DEBUG[4533]: Non-ECM carrier up in state 10
Sep 25 12:59:32 DEBUG[4533]: HDLC carrier up in state 10
Sep 25 12:59:33 DEBUG[4533]: Non-ECM carrier training failed in state 10
Sep 25 12:59:39 DEBUG[4533]: T2 timeout in phase
T30_PHASE_C_NON_ECM_RX, state 10
Sep 25 12:59:39 DEBUG[4533]: Changing from phase
T30_PHASE_C_NON_ECM_RX to T30_PHASE_B_TX
Sep 25 12:59:39 DEBUG[4533]: FLOW FAX Set rx type 0
Sep 25 12:59:39 DEBUG[4533]: FLOW FAX Set tx type 4
Sep 25 12:59:39 DEBUG[4533]: Start receiving document
Sep 25 12:59:39 DEBUG[4533]: Changing from state 10 to 15
Sep 25 12:59:39 DEBUG[4533]: DIS:
Sep 25 12:59:39 DEBUG[4533]:   .... ...0= Store and forward Internet
fax (T.37): Not set
Sep 25 12:59:39 DEBUG[4533]:   .... .0..= Real-time Internet fax (T.38): Not set


And a similar ECM enabled trace...

Sep 25 14:25:11 DEBUG[6532]: Send complete in phase T30_PHASE_D_TX, state 13
Sep 25 14:25:11 DEBUG[6532]: Changing from state 13 to 10
Sep 25 14:25:11 DEBUG[6532]: Changing from phase T30_PHASE_D_TX to
T30_PHASE_C_ECM_RX
Sep 25 14:25:11 DEBUG[6532]: FLOW FAX Set rx type 8
Sep 25 14:25:11 DEBUG[6532]: FLOW FAX Set tx type 0
Sep 25 14:25:11 DEBUG[6532]: HDLC carrier up in state 10
Sep 25 14:25:11 DEBUG[6532]: HDLC carrier up in state 10
Sep 25 14:25:12 DEBUG[6532]: HDLC carrier training failed in state 10
Sep 25 14:25:18 DEBUG[6532]: T2 timeout in phase T30_PHASE_C_ECM_RX, state 10
Sep 25 14:25:18 DEBUG[6532]: Changing from phase T30_PHASE_C_ECM_RX to
T30_PHASE_B_TX
Sep 25 14:25:18 DEBUG[6532]: FLOW FAX Set rx type 0
Sep 25 14:25:18 DEBUG[6532]: FLOW FAX Set tx type 4
Sep 25 14:25:18 DEBUG[6532]: Start receiving document
Sep 25 14:25:18 DEBUG[6532]: Changing from state 10 to 15
Sep 25 14:25:18 DEBUG[6532]: DIS:
Sep 25 14:25:18 DEBUG[6532]:   .... ...0= Store and forward Internet
fax (T.37): Not set
Sep 25 14:25:18 DEBUG[6532]:   .... .0..= Real-time Internet fax (T.38): Not set


Sometimes I can get 5 or 6 pages through before this occurs. this is
on fax machines which appeared to behave 100% perfectly on old
spandsp-0.0.2 versions.

If it helps I can send a full-size log of a complete conversation.

Cheers,
Steve