Re: USB bug

Re: USB bug

[Alan Stern]

On Sat, 22 Jun 2019, Harutyun Khachatryan wrote:

> Dear Alan Stern,
> 
> I thought that I should wait Mathias's response. I am terribly sorry for 
> that. I am sending dmesg log and trace content as you asked. I tried the 
> procedure on kernel 5.1.12-050112-generic since it's most recent now and 
> the bug still exists in it. If you need for 5.0 write me back. Thank you 
> in advance.

The linux-usb mailing list does not accept email messages in HTML 
format.  Please resend your message using plain text only.

Also, I'm not the xHCI maintainer -- Mathias is.  You should send your 
messages to him along with (or instead of) me.

Finally, posting the logs isn't very useful if you don't say what you 
were doing at the time.  When you resend your message, include a 
detailed description of exactly what you did while the logs were being 
collected.

Alan Stern

Re: USB bug

[Harutyun Khachatryan]

Dear Mathias Nyman,

the commands has actually helped. But it is strange that the system 
behavior has changed, without that command no more usb devices can be 
connected to the machine. Even Seagate HDD after disconnecting was not 
able to be connected again. So only with that commands you had written 
all usb devices was able to work.

Regards, Harutyun Khachatryan

On 6/25/19 3:01 PM, Mathias Nyman wrote:
> On 24.6.2019 21.11, Alan Stern wrote:
>> On Sun, 23 Jun 2019, Harutyun Khachatryan wrote:
>>
>>> Dear Alan Stern,
>>>
>>> I thought that I should wait Mathias's response. I am terribly sorry 
>>> for
>>> that. I am sending dmesg log and trace content as you asked. I tried 
>>> the
>>> procedure on kernel 5.1.12-050112-generic since it's most recent now 
>>> and
>>> the bug still exists in it. If you need for 5.0 write me back. Thank 
>>> you
>>> in advance.
>>>
>>> Regards, Harutyun Khachatryan
>>
>> Mathias, can you please look through the log and trace output that
>> Harutyun sent?  His message doesn't appear to have gotten onto the
>> mailing list, so I have attached copies of his files here.
>>
>> I guess he tried to follow the procedure given in
>>
>>     https://marc.info/?l=linux-usb&m=155293069118478&w=2
>>
>> Namely:
>>
>> Boot with the Seagate HDD attached
>> 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
>> <Plug in other USB device>
>> <Wait 10 seconds>
>> <Unplug other USB device>
>> <Unplug the Seagate HDD>
>> <Plug in other USB device>
>> Send output of dmesg
>> Send content of /sys/kernel/debug/tracing/trace
>>
>> The problem is that the other USB device is not detected. Harutyun
>> didn't say at what points in the log the other device was plugged in,
>> or which port it was plugged into.  It looks like the Seagate HDD was
>> plugged into 4-1.
>>
>
> There are no other port events than the disconnect of the 4-1 Seagate HDD
> in the traces: (port link goes to Inactive first, then Disabled)
>
> 153.590150: xhci_handle_port_status: port-0: Powered Not-connected 
> Disabled Link:Inactive PortSpeed:0 Change: CSC PLC Wake
> 153.590130: xhci_handle_event: EVENT: TRB 0000000005000000 status 
> 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C
> 153.590157: xhci_hub_status_data: port-0: Powered Not-connected 
> Disabled Link:Inactive PortSpeed:0 Change: CSC PLC Wake:
> 153.590158: xhci_hub_status_data: port-1: Powered Connected Enabled 
> Link:U2 PortSpeed:4 Change: Wake:
> 153.590160: xhci_hub_status_data: port-2: Powered Not-connected 
> Disabled Link:RxDetect PortSpeed:0 Change: Wake:
> 153.590163: xhci_hub_status_data: port-3: Powered Not-connected 
> Disabled Link:RxDetect PortSpeed:0 Change: Wake:
> ...
> 153.689459: xhci_handle_event: EVENT: TRB 0000000005000000 status 
> 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C
> 153.689477: xhci_handle_port_status: port-0: Powered Not-connected 
> Disabled Link:RxDetect PortSpeed:0 Change: WRC PRC Wake:
> < disabling slot, freeing ring etc here>
>
> After a while the SS bus is suspended, xhci traces show wake flags are
> set for SS roothub ports. Then there's nothing for 12 seconds, after 
> which
> we see a Interrupt URB being handled a few times every a second, probably
> the external hub. Nothing else, no other port activity or traffic is 
> seen.
>
> 154.839474: xhci_hub_status_data: port-0: Powered Not-connected 
> Disabled Link:RxDetect PortSpeed:0 Change: Wake: WCE WOE
> 154.839476: xhci_hub_status_data: port-1: Powered Connected Enabled 
> Link:U2 PortSpeed:4 Change: Wake: WDE WOE
> 154.839478: xhci_hub_status_data: port-2: Powered Not-connected 
> Disabled Link:RxDetect PortSpeed:0 Change: Wake: WCE WOE
> 154.839479: xhci_hub_status_data: port-3: Powered Not-connected 
> Disabled Link:RxDetect PortSpeed:0 Change: Wake: WCE WOE
> 166.604073: xhci_handle_event: EVENT: TRB 000000044dd539c0 status 
> 'Success' len 0 slot 4 ep 3 type 'Transfer Event' flags e:C
> 166.604080: xhci_handle_transfer: INTR: Buffer 000000044dd57000 length 
> 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
> 166.604083: xhci_inc_deq: INTR ..
> 166.604086: xhci_urb_giveback: ep1in-intr: urb 0000000046808855 pipe 
> 1077969792 slot 4 length 8/8 sgs 0/0 stream 0 flags 00000204
>
> I can't spot any activity on the HS/FS side of xhci at all, and the SS 
> bus
> (usb4) is suspended here with a device (external hub?) in U2 link state.
> Best guess so far is that it is related to runtime or link power 
> management
> withand the external hub.
>
> Could be related to the SS device with LPM resume issue fixed here:
> https://marc.info/?l=linux-usb&m=156101728630448&w=2
>
> Harutyun Khachatryan, how about disabling runtime power management
> for hubs before disconnecting the Seagate drive, can you check if
> that helps. (as sudo or root, do)
>
> echo on > /sys/bus/usb/devices/usb3/power/control
> echo on > /sys/bus/usb/devices/usb4/power/control
> echo on > /sys/bus/usb/devices/usb3/3-2/power/control
> echo on > /sys/bus/usb/devices/usb4/4-2/power/control
>
> Does it help?
>
> -Mathias

Re: USB bug

[Mathias Nyman]

On 24.6.2019 21.11, Alan Stern wrote:
> On Sun, 23 Jun 2019, Harutyun Khachatryan wrote:
> 
>> Dear Alan Stern,
>>
>> I thought that I should wait Mathias's response. I am terribly sorry for
>> that. I am sending dmesg log and trace content as you asked. I tried the
>> procedure on kernel 5.1.12-050112-generic since it's most recent now and
>> the bug still exists in it. If you need for 5.0 write me back. Thank you
>> in advance.
>>
>> Regards, Harutyun Khachatryan
> 
> Mathias, can you please look through the log and trace output that
> Harutyun sent?  His message doesn't appear to have gotten onto the
> mailing list, so I have attached copies of his files here.
> 
> I guess he tried to follow the procedure given in
> 
> 	https://marc.info/?l=linux-usb&m=155293069118478&w=2
> 
> Namely:
> 
> Boot with the Seagate HDD attached
> 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
> <Plug in other USB device>
> <Wait 10 seconds>
> <Unplug other USB device>
> <Unplug the Seagate HDD>
> <Plug in other USB device>
> Send output of dmesg
> Send content of /sys/kernel/debug/tracing/trace
> 
> The problem is that the other USB device is not detected.  Harutyun
> didn't say at what points in the log the other device was plugged in,
> or which port it was plugged into.  It looks like the Seagate HDD was
> plugged into 4-1.
> 

There are no other port events than the disconnect of the 4-1 Seagate HDD
in the traces: (port link goes to Inactive first, then Disabled)

153.590150: xhci_handle_port_status: port-0: Powered Not-connected Disabled Link:Inactive PortSpeed:0 Change: CSC PLC Wake
153.590130: xhci_handle_event: EVENT: TRB 0000000005000000 status 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C
153.590157: xhci_hub_status_data: port-0: Powered Not-connected Disabled Link:Inactive PortSpeed:0 Change: CSC PLC Wake:
153.590158: xhci_hub_status_data: port-1: Powered Connected Enabled Link:U2 PortSpeed:4 Change: Wake:
153.590160: xhci_hub_status_data: port-2: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake:
153.590163: xhci_hub_status_data: port-3: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake:
...
153.689459: xhci_handle_event: EVENT: TRB 0000000005000000 status 'Success' len 0 slot 0 ep 0 type 'Port Status Change Event' flags e:C
153.689477: xhci_handle_port_status: port-0: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: WRC PRC Wake:
< disabling slot, freeing ring etc here>

After a while the SS bus is suspended, xhci traces show wake flags are
set for SS roothub ports. Then there's nothing for 12 seconds, after which
we see a Interrupt URB being handled a few times every a second, probably
the external hub. Nothing else, no other port activity or traffic is seen.

154.839474: xhci_hub_status_data: port-0: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake: WCE WOE
154.839476: xhci_hub_status_data: port-1: Powered Connected Enabled Link:U2 PortSpeed:4 Change: Wake: WDE WOE
154.839478: xhci_hub_status_data: port-2: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake: WCE WOE
154.839479: xhci_hub_status_data: port-3: Powered Not-connected Disabled Link:RxDetect PortSpeed:0 Change: Wake: WCE WOE
166.604073: xhci_handle_event: EVENT: TRB 000000044dd539c0 status 'Success' len 0 slot 4 ep 3 type 'Transfer Event' flags e:C
166.604080: xhci_handle_transfer: INTR: Buffer 000000044dd57000 length 8 TD size 0 intr 0 type 'Normal' flags b:i:I:c:s:I:e:C
166.604083: xhci_inc_deq: INTR ..
166.604086: xhci_urb_giveback: ep1in-intr: urb 0000000046808855 pipe 1077969792 slot 4 length 8/8 sgs 0/0 stream 0 flags 00000204

I can't spot any activity on the HS/FS side of xhci at all, and the SS bus
(usb4) is suspended here with a device (external hub?) in U2 link state.
Best guess so far is that it is related to runtime or link power management
withand the external hub.

Could be related to the SS device with LPM resume issue fixed here:
https://marc.info/?l=linux-usb&m=156101728630448&w=2

Harutyun Khachatryan, how about disabling runtime power management
for hubs before disconnecting the Seagate drive, can you check if
that helps. (as sudo or root, do)

echo on > /sys/bus/usb/devices/usb3/power/control
echo on > /sys/bus/usb/devices/usb4/power/control
echo on > /sys/bus/usb/devices/usb3/3-2/power/control
echo on > /sys/bus/usb/devices/usb4/4-2/power/control

Does it help?

-Mathias