Re: [PATCH v5 2/5] can: kvaser_usb: Consolidate and unify state change handling

Ahmed S. Darwish
2015-01-23T06:07:41Z

On Wed, Jan 21, 2015 at 05:13:45PM +0100, Wolfgang Grandegger wrote:
> On Wed, 21 Jan 2015 10:36:47 -0500, "Ahmed S. Darwish"
> <darwish.07@gmail.com> wrote:
> > On Wed, Jan 21, 2015 at 03:00:15PM +0000, Andri Yngvason wrote:
> >> Quoting Ahmed S. Darwish (2015-01-21 14:43:23)
> >> > Hi!
> >
> > ...
> >
> >> > <-- Unplug the cable -->
> >> >
> >> > (000.009106) can0 20000080 [8] 00 00 00 00 00 00 08 00
> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{8}{0}}
> >> > (000.001872) can0 20000080 [8] 00 00 00 00 00 00 10 00
>
> For a bus-errors I would also expcect some more information in the
> data[2..3] fields. But these are always zero.
>

M16C error factors made it possible to report things like
CAN_ERR_PROT_FORM/STUFF/BIT0/BIT1/TX in data[2], and
CAN_ERR_PROT_LOC_ACK/CRC_DEL in data[3].

Unfortunately such error factors are only reported in Leaf, but
not in USBCan-II due to the wire format change in the error event:

struct leaf_msg_error_event {
u8 tid;
u8 flags;
__le16 time[3];
u8 channel;
u8 padding;
u8 tx_errors_count;
u8 rx_errors_count;
u8 status;
u8 error_factor;
} __packed;

struct usbcan_msg_error_event {
u8 tid;
u8 padding;
u8 tx_errors_count_ch0;
u8 rx_errors_count_ch0;
u8 tx_errors_count_ch1;
u8 rx_errors_count_ch1;
u8 status_ch0;
u8 status_ch1;
__le16 time;
} __packed;

I speculate that the wire format was changed due to controller
bugs in the USBCan-II, which was slightly mentioned in their
data sheets here:

http://www.kvaser.com/canlib-webhelp/page_hardware_specific_can_controllers.html

So it seems there's really no way for filling such bus error
info given the very limited amount of data exported :-(

The issue of incomplete data does not even stop here, kindly
check below notes regarding reverse state transitions:

> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{16}{0}}
> >> [...]
> >> > error-counter-tx-rx{{80}{0}}
> >> > (000.001910) can0 20000080 [8] 00 00 00 00 00 00 58 00
> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{88}{0}}
> >> > (000.001753) can0 20000084 [8] 00 08 00 00 00 00 60 00
> >> > ERRORFRAME
> >> > controller-problem{tx-error-warning}
> >> Good.
> >> > bus-error
> >> > error-counter-tx-rx{{96}{0}}
> >
> > Nice.
> >
> >> > (000.001720) can0 20000080 [8] 00 00 00 00 00 00 68 00
> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{104}{0}}
> >> > (000.001876) can0 20000080 [8] 00 00 00 00 00 00 70 00
> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{112}{0}}
> >> > (000.001749) can0 20000080 [8] 00 00 00 00 00 00 78 00
> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{120}{0}}
> >> > (000.001771) can0 20000084 [8] 00 20 00 00 00 00 80 00
> >> > ERRORFRAME
> >> > controller-problem{tx-error-passive}
> >> Also good.
> >> > bus-error
> >> > error-counter-tx-rx{{128}{0}}
> >
> > Also nice :-)
> >
> >> > (000.001868) can0 20000080 [8] 00 00 00 00 00 00 80 00
> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{128}{0}}
> >> > (000.001982) can0 20000080 [8] 00 00 00 00 00 00 80 00
> >> > ERRORFRAME
> >> > bus-error
> >> > error-counter-tx-rx{{128}{0}}
> >> >
> >> > (( Then a continous flood, exactly similar to the above packet,
> >> > appears.
> >> > Unfortunately this flooding is a firmware problem. ))
> >> >
> >> > <-- Replug the cable, after a good amount of time -->
> >> >
> >> Where are the reverse state transitions?
> >> >
> >
> > Hmmm...
> >
> > [ ... ]
> >>
> >> Reverse state transitions are missing from the logs. See comments
> above.
> >>
> >
> > When the device is on the _receiving_ end, and I unplug the CAN cable
> after
> > introducing some noise to the level of reaching WARNING or PASSIVE, I
> > receive a BUS_ERROR event with the rxerr count reset back to 0 or 1. In
> > that case, the driver correctly transitions back the state to
> ERROR_ACTIVE
> > and candump produces something similar to:
> >
> > (000.000362) can0 2000008C [8] 00 40 40 00 00 00 00 01
> > ERRORFRAME
> > controller-problem{}
> > protocol-violation{{back-to-error-active}{}}
> > bus-error
> > error-counter-tx-rx{{0}{1}}
> >
> > which is, AFAIK, the correct behaviour from the driver side.
> >
> > Meanwhile, when the device is on the _sending_ end and I re-plug the CAN
> > cable again. Sometimes I receive events with txerr reset to 0 or 1, and
> > the driver correctly reverts back to ERROR_ACTIVE in that case. But on
> > another times like the quoted case above, I don't receive any events
> > resetting txerr back -- only data packets on the bus.
>
> Well, the firmware seems to report *only* bus-errors via
> CMD_CAN_ERROR_EVENT messages, also carrying the new state, but no
> CMD_CHIP_STATE_EVENT just for the state changes.
>

I've dumped _every_ message I receive from the firmware while
disconnecting the CAN bus, waiting a while, and connecting it again.
I really received _nothing_ from the firmware when the CAN bus was
reconnected and the data packets were flowing again. Not even a
single CHIP_STATE_EVENT, even after waiting for a long time.

So it's basically:
...
ERR EVENT, txerr=128, rxerr=0
ERR EVENT, txerr=128, rxerr=0
ERR EVENT, txerr=128, rxerr=0
...

then complete silence, except the data frames. I've even tried with
different versions of the firmware, but the same behaviour persisted.

> > So, What can the driver do given the above?
>
> Little if the notification does not come.
>

We can poll the state by sending CMD_GET_CHIP_STATE to the firmware,
and it will hopefully reply with a CHIP_STATE_EVENT response
containing the new txerr and rxerr values that we can use for
reverse state transitions.

But do we _really_ want to go through the path? I feel that it will
open some cans of worms w.r.t. concurrent access to both the netdev
and USB stacks from a single driver.

A possible solution can be setting up a kernel thread that queries
for a CHIP_STATE_EVENT every second?

Your inputs on this is appreciated.

> Wolfgang.
>

Regards,
Darwish