[Regression] xhci: some hard drives cannot be seen using a JMicron JMS56x enclosure

[Mathias Nyman <mathias.nyman@linux.intel.com>]

On 19.02.2018 01:38, Cyril Roelandt wrote:
> Hello,
> 
> I'm inlining my answers to your questions.
> 
> On 02/15/18 17:30, Mathias Nyman wrote:
>> On 15.02.2018 03:05, Cyril Roelandt wrote:
>>> Hi,
>>>
>>> I use two hard drives in an enclosure connected to my PC using UAS. The
>>> enclosure is a JMicron JMS56x (152d:0562); the drives are a Fujitsu MHZ2160BH
>>> G2 (2"5, 160GB) and a Western Digital EFRX-68N32N0 (3"5, 4TB).
>>>
>>> Using a USB2 port, I can see both drives as expected. I used to be able to use
>>> both drives using a USB3 port (and UAS) in Linux 4.11 and 4.12, but I am
>>> experiencing a bug starting with Linux 4.13.
>>>
>>
>> Did you see the:
>> "usb 4-2: device firmware changed"
>> message with 4.12 or older kernels?
> 
> No, I cannot see this message on a 4.11 kernel.
...
> 
>> could you send full logs, both dynamic debug and xhci traces to me:
>>
>> echo 'module xhci_hcd =p' > /sys/kernel/debug/dynamic_debug/control
>> echo 'module usbcore =p' >/sys/kernel/debug/dynamic_debug/control
>>
>> and
>>
>> echo 81920 > /sys/kernel/debug/tracing/buffer_size_kb
>> echo 1 > /sys/kernel/debug/tracing/events/xhci-hcd/enable
>>
>> both the /sys/kernel/debug/tracing/trace and dmesg
> 
> Here is the output of dmesg:
> 

Thanks, been staring at the logs for some time now.

I can see one issue on xhci side.

endpoint 3(IN) for xhci slot 2 uses two streams.

uas driver wants to cancel two URBS on this endpoint:
   URB1 (ffff9e50d43afa80) located in stream ring 1 at 0x1a3704130
   URB2 (ffff9e50d43af0c0) located in stream ring 2 at 0x1a3707080

xhci stops the endpoint to cancel the URBs, this causes both streams to stop.

For URB1 we notice xHC hw was currently working on the URB we want to cancel,
i.e. stream 1 stopped at the same location as URB1 (at 0x1a3704130).
xhci driver ask hardware to move past this position, and xhci driver gives back
URB1 as "cancelled". Stream 1 continue to work after this

For the second URB we don't notice that xHC hw is working on the same URB we
want to cancel, so we bluntly write over URB2  with zeroes, and driver gives
back URB2 as "cancelled".
Stream 2 does not recover, and the URB that is queued after this on stream 2 is
never handled. Stream 2 is stuck at the position of URB2 (0x1a3707080).

As the next URB on stream 2 is never given back it blocks usb_disconnect which
is waiting for all pending urbs to be given back.

could you change one flag in the xhci driver and take the same
set of logs? It will add more details about the URB and xHC hw position check.



Another thing not related to xhci is that the serial number seems to be changing
for this device after reset.
First log:
[Tue Feb  6 22:17:49 2018] usb 4-2: SerialNumber: RANDOM__8A4D7F833EEF
Second log:
[Sun Feb 18 22:46:01 2018] usb 2-2: SerialNumber: RANDOM__4157B7E21ACD

This causes the "usb 4-2: device firmware changed" messages, and usb core will
try to logically disconnect the device.

Can you also plug in and out the device a few times without changing the
drives in the enclosure, and check if the serial number really is changing.

Thanks
Mathias
---
To unsubscribe from this list: send the line "unsubscribe linux-usb" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

diff --git a/drivers/usb/host/xhci-ring.c b/drivers/usb/host/xhci-ring.c
index cc368ad..f1b73e6 100644
--- a/drivers/usb/host/xhci-ring.c
+++ b/drivers/usb/host/xhci-ring.c
@@ -772,7 +772,7 @@ static void xhci_handle_cmd_stop_ep(struct xhci_hcd *xhci, int slot_id,
                 hw_deq &= ~0xf;
  
                 if (trb_in_td(xhci, cur_td->start_seg, cur_td->first_trb,
-                             cur_td->last_trb, hw_deq, false)) {
+                             cur_td->last_trb, hw_deq, true)) {
                         xhci_find_new_dequeue_state(xhci, slot_id, ep_index,
                                                     cur_td->urb->stream_id,
                                                     cur_td, &deq_state);