linux-kernel - Re: xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 1 comp

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <bd4bdabc-2d83-4022-87f4-8c599009d9f5@molgen.mpg.de>
Date: Mon, 8 Apr 2024 18:37:22 +0200
From: Paul Menzel <pmenzel@...gen.mpg.de>
To: Mathias Nyman <mathias.nyman@...ux.intel.com>,
 Michał Pecio <michal.pecio@...il.com>
Cc: Mathias Nyman <mathias.nyman@...el.com>, linux-usb@...r.kernel.org,
 LKML <linux-kernel@...r.kernel.org>
Subject: Re: xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part
 of current TD ep_index 1 comp_code 1

Dear Mathias, dear Michał,


Thank you very much for your assistance.


Am 08.04.24 um 09:17 schrieb Mathias Nyman:
> On 7.4.2024 15.25, Michał Pecio wrote:
>> This (and the absence of any earlier errors on the endpoint) looks
>> like the hardware may be confirming a "successful" transfer twice or
>> the driver may be processing one such confirmation twice.
> 
> It's also possible this TD/TRB was cancelled due to the disconnect.
> Could be that even if driver removes the TD from the list and cleans out 
> the TRB from the ring buffer (turns TRB to no-op) hardware may have read
> ahead and cached the TRB, and process it anyway.
> 
>> [   94.088594] usb 1-2: USB disconnect, device number 8
>> [   94.089370] xhci_hcd 0000:00:14.0: ERROR Transfer event TRB DMA ptr not part of current TD ep_index 1 comp_code 1
>> [   94.089403] xhci_hcd 0000:00:14.0: Looking for event-dma 00000001250310f0 trb-start 0000000125031100 trb-end 0000000125031100 seg-start 0000000125031000 seg-end 0000000125031ff0
>> [   94.089427] xhci_hcd 0000:00:14.0: last xhci_td_cleanup: first_dma 1250310f0 last_dma 1250310f0 status -115 from finish_td
>>
>> (I say "successful" but it really isn't - the device is no longer
>> listening. But there is no delivery confirmation on isochronous OUT
>> endpoints so the xHC doesn't suspect anything.)
>>
>> Could you try again with this updated debug patch to get more info?
> 
> Would also be helpful to add xhci dynamic debug and xhci tracing (two 
> separate logs). These will show in detail everything that is going on.
> 
> Steps:
> 
> mount -t debugfs none /sys/kernel/debug
> echo 'module xhci_hcd =p' >/sys/kernel/debug/dynamic_debug/control
> echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
> echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
> echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
> echo 1 > /sys/kernel/debug/tracing/tracing_on
> < Reproduce issue >
> Send output of dmesg
> Send content of /sys/kernel/debug/tracing/trace
> 
> please copy the /sys/kernel/debug/tracing/trace file somewhere as soon
> as possible after reproducing the issue. It grows fast.

For posterity I created Linux Kernel Bugzilla issue #218695 [1], and 
attached the files there. Hopefully everything was captured, that you 
need. The discussion could continue on this list, but do as it suits you 
best.


Kind regards,

Paul


[1]: https://bugzilla.kernel.org/show_bug.cgi?id=218695