Received-SPF: pass (google.com: domain of linux-kernel+bounces-134881-linux.lists.archive=gmail.com@vger.kernel.org designates 147.75.80.249 as permitted sender) client-ip=147.75.80.249;
Message-ID: <1f64af9a-0618-a7da-4acc-f043b6580308@linux.intel.com>
Date: Mon, 8 Apr 2024 10:17:15 +0300
Precedence: bulk
MIME-Version: 1.0
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:102.0) Gecko/20100101
 Firefox/102.0 Thunderbird/102.13.0
Content-Language: en-US
To: =?UTF-8?Q?Micha=c5=82_Pecio?= <michal.pecio@gmail.com>,
 Paul Menzel <pmenzel@molgen.mpg.de>
Cc: Mathias Nyman <mathias.nyman@intel.com>,
 LKML <linux-kernel@vger.kernel.org>, linux-usb@vger.kernel.org
References: <58bca6f2-797a-4e20-a476-2294309afdd5@molgen.mpg.de>
 <20240405113247.743e34b2@foxbook>
 <7090d3af-18ce-40e1-8ac2-bf18152e5c4a@molgen.mpg.de>
 <20240406183659.3daf4fa0@foxbook>
 <c57f2116-8c42-44fb-9c32-6115ad88f914@molgen.mpg.de>
 <20240407142542.036fb02f@foxbook>
From: Mathias Nyman <mathias.nyman@linux.intel.com>
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
In-Reply-To: <20240407142542.036fb02f@foxbook>
Content-Type: text/plain; charset=UTF-8; format=flowed
Content-Transfer-Encoding: 8bit

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.

Thanks
Mathias