Re: kernel: xhci_hcd 0000:00:14.0: ERROR unknown event type 37 - Kernel 4.19.13

[Mathias Nyman]

On 10.01.2019 00:11, Nathan Royce wrote:
> Wow, my system got wrecked (exaggeration) during this latest stretch...
> Pulseaudio was stretched to the limit and beyond and was forced to
> restart. Anything that was producing audio had to be restarted to get
> it back.
> This time was much like the first time and went from timestamp
> 573100.060927 (line 1) to 572506.604155 (line 11069), where 100%
> (literally) of it was that event 37 in the journal, no other kernel
> log entries except for the systemd-hostnamed audit before it all went
> down.
> And as usual, it was my USB TV tuner (tvheadend really) giving the
> Poll Timeout log entries.
> Those same uploaded trace files will be updated with the latest bugout.

Hi.

Finally had a chance to look at this. Sorry about the delay.

Logs show event ring is full:

573047.104801: xhci_handle_event: EVENT: TRB 0000000000000000 status 'Event Ring Full Error' len 0 slot 0 ep 0 type 'Host Controller Event' flags e:C

It's filled with 0 length short transfer events due to a the following loop:

1. Class driver asks for 58658 bytes from device (queues BULK IN URB)
2. short transfer event, xhci interrupts, saying we got less than 58658 bytes.
   We actually got 0 bytes.
3. return URB with zero bytes to class driver
4. Class driver immediately queues a new URB, asking for 58658 bytes (see step 1)

Last 6ms before event ring is full this looped 255 times.

one cycle of the loop in log:

573047.104748: xhci_handle_event: EVENT: TRB 000000020b267770 status 'Short Packet' len 58658 slot 4 ep 7 type 'Transfer Event' flags e:C
573047.104749: xhci_handle_transfer: BULK: Buffer 000000001de20000 length 58658 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:c
573047.104749: xhci_inc_deq: BULK 0000000002f14758: enq 0x000000020b267860(0x000000020b267000) deq 0x000000020b267780(0x000000020b267000) segs 2 stream 0 free_trbs 495 bounce 512 cycle 0
573047.104752: xhci_urb_giveback: ep3in-bulk: urb 000000000bdcbe77 pipe 3225519232 slot 4 length 0/58658 sgs 0/0 stream 0 flags 00010200
573047.104758: xhci_urb_enqueue: ep3in-bulk: urb 000000000bdcbe77 pipe 3225519232 slot 4 length 0/58658 sgs 0/0 stream 0 flags 00010200
573047.104758: xhci_queue_trb: BULK: Buffer 000000001de20000 length 58658 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
573047.104759: xhci_inc_enq: BULK 0000000002f14758: enq 0x000000020b267870(0x000000020b267000) deq 0x000000020b267780(0x000000020b267000) segs 2 stream 0 free_trbs 494 bounce 512 cycle 0
573047.104759: xhci_inc_deq: EVENT 0000000022f906c2: enq 0x000000020b317000(0x000000020b317000) deq 0x000000020b3178d0(0x000000020b317000) segs 1 stream 0 free_trbs 254 bounce 0 cycle 1

I'll continue digging into this

-Mathias