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

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"
[off-list ref] wrote:

quoted

On Wed, Jan 21, 2015 at 03:00:15PM +0000, Andri Yngvason wrote:

quoted

Quoting Ahmed S. Darwish (2015-01-21 14:43:23)

quoted

Hi!

...

quoted

quoted

<-- 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:

quoted

quoted

quoted

 ERRORFRAME
        bus-error
        error-counter-tx-rx{{16}{0}}

[...]

quoted

        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.

quoted

        bus-error
        error-counter-tx-rx{{96}{0}}

Nice.

quoted

quoted

 (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.

quoted

        bus-error
        error-counter-tx-rx{{128}{0}}

Also nice :-)

quoted

quoted

 (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?

quoted

Hmmm...

[ ... ]

quoted

Reverse state transitions are missing from the logs. See comments

above.

quoted

quoted

When the device is on the _receiving_ end, and I unplug the CAN cable

after

quoted

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

quoted

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.

quoted

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