On 30.01.2019 14:38, Jan-Marek Glogowski wrote:
On plug-in of my USB-C device, its USB_SS_PORT_LS_SS_INACTIVE
link state bit is set. Greping all the kernel for this bit shows
that the port status requests a warm-reset this way.
This just happens, if its the only device on that hub and the
hub resumes, so we don't call port_event, which would otherwise
warm-reset ports. The device works ok without this patch, if
there is already any other device connected to the hub.
Signed-off-by: Jan-Marek Glogowski <glogow@xxxxxxxxxx>
---
The original thread is "USB-C storage device not detected on USB 3.1 Gen 2
host when plugged in after boot". A different patch, suggested by Mathias
Nyman, didn't work for me. This patch was just rebased on usb-next, but not
re-tested. Original tests are based on 5.0-rc.
I started to look into this in more detail, disregard the code I sent earlier, it's
not relevant.
I think your patch could be a solution, but it worries me that your logs show hub_event
evt (hub->event_bits) are zero even if port status 0x4002c0 should set a bit there.
From you earlier log:
[ 116.032422] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: Port Status Change Event for port 19
[ 116.032432] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: resume root hub
[ 116.032447] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
[ 116.032510] usbcore:usb_remote_wakeup: usb usb3: usb wakeup-resume
[ 116.032518] usbcore:hcd_bus_resume: usb usb3: usb auto-resume
[ 116.032538] usbcore:hub_resume: hub 3-0:1.0: hub_resume
[ 116.032567] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 0 status = 0x2a0
[ 116.032571] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 116.032602] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 1 status = 0x2a0
[ 116.032606] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 116.032624] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status = 0x4002c0
[ 116.032633] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x4002c0
[ 116.032654] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 3 status = 0x2a0
[ 116.032658] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 116.032675] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 4 status = 0x2a0
[ 116.032679] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 116.032697] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 5 status = 0x2a0
[ 116.032701] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 116.032766] usbcore:hub_event: hub 3-0:1.0: state 7 ports 6 chg 0000 evt 0000
[ 116.032784] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 0 status = 0xe0002a0
[ 116.032807] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 1 status = 0xe0002a0
[ 116.032829] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 2 status = 0xe4002c0
[ 116.032846] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 3 status = 0xe0002a0
[ 116.032870] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 4 status = 0xe0002a0
[ 116.032892] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 5 status = 0xe0002a0
[ 116.032906] usbcore:hub_suspend: hub 3-0:1.0: hub_suspend
[ 116.032925] usbcore:hcd_bus_suspend: usb usb3: bus auto-suspend, wakeup 1
[ 116.032946] usbcore:hcd_bus_suspend: usb usb3: suspend raced with wakeup event
[ 116.032950] usbcore:hcd_bus_resume: usb usb3: usb auto-resume
The hub->event bits are set when roothub polling timer function gets data from
hub_status_data(), writes the data to a status urb, and returns the urb.
Normal operation:
usb_hcd_poll_rh_status() // roothub polling timer function
hcd->driver->hub_status_data(hcd, buffer) -> xhci_hub_status_data()
xhci_hub_status_data() //returns buffer with bits set if a port needs attention
if (buffer && urb)
memcpy(urb->transfer_buffer, buffer) // copy buffer bits to urb
usb_hcd_giveback_urb(urb) -> hub_irq // calls urb complete callback function
hub_irq()
hub->event_bits = urb->transfer_buffer //
mod_timer(usb_hcd_poll_rh_status, future) // reschedule roothub polling timer
I'm guessing usb_hcd_poll_rh_status() never properly completes a URB in your case.
This could be possible if roothub is polled before properly resumed, then the URB wouldn't
be available yet, and no hub->event_bits are set.
Because no bits are set the hub starts suspending again after resume, probably before roothub
timer polls roothub again.
suspend fails when it manually checks hcd->driver->hub_status_data() for activity, and
it start resuming again, and continues this in a loop.
Either roothub polling is stopped at the suspend attempt, or maybe continuously rescheduled
into the future because as a part of suspend attempt/resume loop.
Could you add one more line of debugging and capture new logs:
diff --git a/drivers/usb/core/hcd.c b/drivers/usb/core/hcd.c
index 015b126..6d400f9 100644
--- a/drivers/usb/core/hcd.c
+++ b/drivers/usb/core/hcd.c
@@ -759,6 +759,10 @@ void usb_hcd_poll_rh_status(struct usb_hcd *hcd)
return;
length = hcd->driver->hub_status_data(hcd, buffer);
+
+ dev_err(&hcd->self.root_hub->dev, "%s, length %d, hcd->flags 0x%lx, status_urb %s\n",
+ __func__, length, hcd->flags, hcd->status_urb ? "Exists" : "NULL" );
+
if (length > 0) {
/* try to complete the status urb */
Thanks
-Mathias
