Re: [3.16.1 BISECTED REGRESSION]: Simtec Entropy Key (cdc-acm) broken in 3.16

[Nix <nix@esperi.org.uk>]

Sorry for the delay: illness and work-related release time flurries.

On 24 Oct 2014, Johan Hovold told this:

> [ +CC: linux-usb ]
>
> On Wed, Oct 22, 2014 at 04:36:59PM +0100, Nix wrote:
>> On 22 Oct 2014, Johan Hovold outgrape:
>> 
>> > On Wed, Oct 22, 2014 at 10:31:17AM +0100, Nix wrote:
>> >> On 14 Oct 2014, Johan Hovold verbalised:
>> >> 
>> >> > On Sun, Oct 12, 2014 at 10:36:30PM +0100, Nix wrote:
>> >> >> I have checked: this code is being executed against a symlink that
>> >> >> points to /dev/ttyACM0, and the tcsetattr() succeeds. (At least, it's
>> >> >> succeeding on the kernel I'm running now, but of course that's 3.16.5
>> >> >> with this commit reverted...)
>> >> >
>> >> > You could verify that by enabling debugging in the cdc-acm driver and
>> >> > making sure that the corresponding control messages are indeed sent on
>> >> > close.
>> >> 
>> >> I have a debugging dump at
>> >> <http://www.esperi.org.uk/~nix/temporary/cdc-acm.log>; it's fairly
>> >
>> > What kernel were you using here? The log seems to suggest that it was
>> > generated with the commit in question reverted.
>> 
>> Look now :) (the previous log is still there in cdc-acm-reverted.log.)
>
> Unfortunately, it seems the logs are incomplete. There are lots of
> entries missing (e.g. "acm_tty_install" when opening, but also some
> "acm_submit_read_urb"), some of which were there in your first log.

OK. What we have now in
<http://www.esperi.org.uk/~nix/temporary/cdc-acm.log> is a log from the
pristine upstream 3.16.6 kernel with cdc-acm debugging turned on and the
acm_tty_write - count stuff in acm_tty_write() disabled: I've increased
the dmesg buffer size so the top isn't being cut off any more. It took a
lot of boots for it to fail this time: about a dozen. The log contains
the boot that failed and the one before.

(To my uneducated eye, the initial traffic to/from the key looks *very*
different in the second boot. Something is clearly wrong by this point,
but that's not much of a surprise!)

>> This contains two boots -- one on which the USB key worked, and the next
>> (with an identical kernel) with which the key was broken. (I'm not sure
>> whether this problem happens at startup or shutdown time, so it seemed
>> best to provide both.)
>
> That's a good idea.
>
> Is it only after reboot you've seen the device fail?

So far.

>                                                      What if you
> physically disconnect and reconnect the device instead, or simply

That fixes it, in fact it's the only way to fix it once it's broken by
this bug.

> repeatedly open and close it?

Hm. Good idea.

... no, that doesn't help. Additional log from that shows a lot of what
looks like error returns:

Oct 31 16:38:03 fold kern debug: : [  168.135213] cdc_acm 2-1:1.0: acm_tty_close
Oct 31 16:38:08 fold kern debug: : [  173.130531] cdc_acm 2-1:1.0: acm_ctrl_msg - rq 0x22, val 0x0, len 0x0, result -110
Oct 31 16:38:08 fold kern debug: : [  173.130557] cdc_acm 2-1:1.0: acm_port_shutdown
Oct 31 16:38:08 fold kern debug: : [  173.131475] cdc_acm 2-1:1.0: acm_ctrl_irq - urb shutting down with status: -2
Oct 31 16:38:08 fold kern debug: : [  173.132474] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.132519] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.133473] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.133510] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.134471] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.134507] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.135471] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.135509] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.136472] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.136507] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.137471] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.137517] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.138471] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.138520] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.139469] cdc_acm 2-1:1.1: acm_write_bulk - len 0/1, status -2
Oct 31 16:38:08 fold kern debug: : [  173.139515] cdc_acm 2-1:1.1: acm_softint
Oct 31 16:38:08 fold kern debug: : [  173.140470] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 0, len 0
Oct 31 16:38:08 fold kern debug: : [  173.140491] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.141469] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 1, len 0
Oct 31 16:38:08 fold kern debug: : [  173.141489] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.142469] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 2, len 0
Oct 31 16:38:08 fold kern debug: : [  173.142490] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.143468] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 3, len 0
Oct 31 16:38:08 fold kern debug: : [  173.143488] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.144468] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 4, len 0
Oct 31 16:38:08 fold kern debug: : [  173.144488] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.145467] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 5, len 0
Oct 31 16:38:08 fold kern debug: : [  173.145488] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.146467] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 6, len 0
Oct 31 16:38:08 fold kern debug: : [  173.146487] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.147477] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 7, len 0
Oct 31 16:38:08 fold kern debug: : [  173.147498] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.153496] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 8, len 0
Oct 31 16:38:08 fold kern debug: : [  173.153524] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.154468] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 9, len 0
Oct 31 16:38:08 fold kern debug: : [  173.154489] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.155466] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 10, len 0
Oct 31 16:38:08 fold kern debug: : [  173.155487] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.156466] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 11, len 0
Oct 31 16:38:08 fold kern debug: : [  173.156487] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.157466] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 12, len 0
Oct 31 16:38:08 fold kern debug: : [  173.157487] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.158466] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 13, len 0
Oct 31 16:38:08 fold kern debug: : [  173.158486] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.159465] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 14, len 0
Oct 31 16:38:08 fold kern debug: : [  173.159486] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.160475] cdc_acm 2-1:1.1: acm_read_bulk_callback - urb 15, len 0
Oct 31 16:38:08 fold kern debug: : [  173.160496] cdc_acm 2-1:1.1: acm_read_bulk_callback - non-zero urb status: -2
Oct 31 16:38:08 fold kern debug: : [  173.160567] tty ttyACM0: acm_tty_open
Oct 31 16:38:08 fold kern debug: : [  173.160588] cdc_acm 2-1:1.0: acm_port_activate
Oct 31 16:38:08 fold kern debug: : [  173.160626] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 0
Oct 31 16:38:08 fold kern debug: : [  173.160651] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 1
Oct 31 16:38:08 fold kern debug: : [  173.160674] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 2
Oct 31 16:38:08 fold kern debug: : [  173.160796] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 3
Oct 31 16:38:08 fold kern debug: : [  173.160820] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 4
Oct 31 16:38:08 fold kern debug: : [  173.160842] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 5
Oct 31 16:38:08 fold kern debug: : [  173.160863] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 6
Oct 31 16:38:08 fold kern debug: : [  173.160884] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 7
Oct 31 16:38:08 fold kern debug: : [  173.160906] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 8
Oct 31 16:38:08 fold kern debug: : [  173.160927] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 9
Oct 31 16:38:08 fold kern debug: : [  173.160948] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 10
Oct 31 16:38:08 fold kern debug: : [  173.160969] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 11
Oct 31 16:38:08 fold kern debug: : [  173.160991] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 12
Oct 31 16:38:08 fold kern debug: : [  173.161012] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 13
Oct 31 16:38:08 fold kern debug: : [  173.161033] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 14
Oct 31 16:38:08 fold kern debug: : [  173.161054] cdc_acm 2-1:1.1: acm_submit_read_urb - urb 15
Oct 31 16:38:08 fold kern debug: : [  173.161489] cdc_acm 2-1:1.0: acm_ctrl_msg - rq 0x22, val 0x3, len 0x0, result -62