"Transfer event TRB DMA ptr not part of current TD" spam after USB disconnection

["Michał Pecio" <michal.pecio@gmail.com>]

Hi,


This is a long standing issue seen in many kernel versions up to 6.7.

Disconnecting a high- or super-speed UVC camera from USB 3.0 port during
recording prints a lot of these errors (usually much more than here).


This appears to come from handle_tx_event() and it is my understanding
that the function tries to look up a transfer request previously issued
by the driver which is pointed to by a completion event received from
the hardware, and the pointer is found to be out of expected bounds.

It is a consistent pattern that problematic event-dma pointers are
within segment bounds, but they start one slot past trb-end and grow.

Comments in the code suggest that "the HC is hosed", but I suspect the
real problem might be the driver failing to retire the _previous_ TD
after it completed with similar errors and continuing to wait for its
completion events forever, or something else with similar outcome.


Or, at any rate, I *hope* that it's a harmless bug and not some memory
corruption... I only have very basic understanding of XHCI.


Any thoughts or suggestions how to fix or debug this further?


Thanks,
Michal


# camera connected
[ 2968.873423] usb 8-1: new high-speed USB device number 54 using xhci_hcd
[ 2969.155383] usb 8-1: New USB device found, idVendor=0bda, idProduct=58b0, bcdDevice= 7.01
[ 2969.155393] usb 8-1: New USB device strings: Mfr=3, Product=1, SerialNumber=2
[ 2969.155396] usb 8-1: Product: FULL HD 1080P Webcam
[ 2969.155398] usb 8-1: Manufacturer: Generic
[ 2969.155400] usb 8-1: SerialNumber: 200901010001
[ 2969.162076] usb 8-1: Found UVC 1.00 device FULL HD 1080P Webcam (0bda:58b0)
# recording started
[ 2978.289442] usb 8-1: Device requested 3072 B/frame bandwidth
[ 2978.289461] usb 8-1: Selecting alternate setting 7 (3072 B/frame bandwidth)
[ 2978.291230] usb 8-1: Allocated 5 URB buffers of 32x3072 bytes each
[ 2978.910333] usb 8-1: Device requested 3072 B/frame bandwidth
[ 2978.910352] usb 8-1: Selecting alternate setting 7 (3072 B/frame bandwidth)
[ 2978.913549] usb 8-1: Allocated 5 URB buffers of 32x3072 bytes each
# camera disconnected
[ 2988.728338] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.728348] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d313890 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.728449] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.728452] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d3138a0 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.728527] usb 8-1: USB disconnect, device number 54
[ 2988.728573] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.728576] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d3138b0 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.728698] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.728701] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d3138c0 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.728841] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.728844] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d3138d0 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.728948] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.728951] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d3138e0 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.729073] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.729075] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d3138f0 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.729197] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.729199] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d313900 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.729322] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.729324] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d313910 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.729447] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.729450] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d313920 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.729572] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.729575] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d313930 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0
[ 2988.729697] xhci_hcd 0000:02:00.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 2 comp_code 4
[ 2988.729700] xhci_hcd 0000:02:00.0: Looking for event-dma 000000012d313940 trb-start 000000012d313870 trb-end 000000012d313880 seg-start 000000012d313000 seg-end 000000012d313ff0