[v3] usb: warm-reset ports on hub resume, if requested

[Jan-Marek Glogowski <glogow@fbihome.de>]

Am 30.01.19 um 17:56 schrieb Jan-Marek Glogowski:
> Am 30.01.19 um 15:58 schrieb Mathias Nyman:
>> On 30.01.2019 14:38, Jan-Marek Glogowski wrote:
>>
>> 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.

So as you expected the status_urb is always NULL.

I tried to understand more of the code by adding some more debug message.

I looked at usb_hcd_resume_root_hub, which is called when we see the "resume root hub" dmesg.
This just queues the hcd->wakeup_work, so indeed, if usb_hcd_poll_rh_status is later called,
the hub might not have resumed yet and polling starts. So my simple approach was to add a
function to call flush_work(&hcd->wakeup_work) before usb_hcd_poll_rh_status. All variants I
tested killed the kernel. I also tried to add a udelay to no avail.

So I just added the usb_hcd_poll_rh_status to the hcd->wakeup_work, if we resume the hub,
which works for me, and results in the following patch:


I don't understand why we auto-suspend directly after a successful auto-resume.

The hunk is from a huge patch:

commit 9bbdf1e0afe771ca7650f9f476769310bee9d8f3
Author: Alan Stern <stern@rowland.harvard.edu>
Date:   Fri Jan 8 12:57:28 2010 -0500

    USB: convert to the runtime PM framework

But probably there is a better way to wait for the status_urb.
I definitely need some comments on this.

Jan-Marek

diff --git a/core/hcd.c b/core/hcd.c
index 015b126..06a3bf6 100644
--- a/core/hcd.c
+++ b/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 */
@@ -2347,6 +2351,7 @@ static void hcd_resume_work(struct work_struct *work)
 	struct usb_device *udev = hcd->self.root_hub;

 	usb_remote_wakeup(udev);
+	usb_hcd_poll_rh_status(hcd);
 }

 /**
diff --git a/core/hub.c b/core/hub.c
index 1d1e61e..cb41cc9 100644
--- a/core/hub.c
+++ b/core/hub.c
@@ -3563,7 +3563,7 @@ int usb_remote_wakeup(struct usb_device *udev)
 	if (udev->state == USB_STATE_SUSPENDED) {
 		dev_dbg(&udev->dev, "usb %sresume\n", "wakeup-");
 		status = usb_autoresume_device(udev);
-		if (status == 0) {
+		if (status != 0) {
 			/* Let the drivers do their thing, then... */
 			usb_autosuspend_device(udev);
 		}
diff --git a/xhci-ring.c b/xhci-ring.c
index 40fa25c..1f8b8c3 100644
--- a/xhci-ring.c
+++ b/xhci-ring.c
@@ -1562,6 +1562,7 @@ static void handle_port_status(struct xhci_hcd *xhci,
 	struct xhci_bus_state *bus_state;
 	bool bogus_port_status = false;
 	struct xhci_port *port;
+	bool needs_root_hub_resume;

 	/* Port status change events always have a successful completion code */
 	if (GET_COMP_CODE(le32_to_cpu(event->generic.field[2])) != COMP_SUCCESS)
@@ -1599,7 +1600,8 @@ static void handle_port_status(struct xhci_hcd *xhci,

 	trace_xhci_handle_port_status(hcd_portnum, portsc);

-	if (hcd->state == HC_STATE_SUSPENDED) {
+	needs_root_hub_resume = hcd->state == HC_STATE_SUSPENDED;
+	if (needs_root_hub_resume) {
 		xhci_dbg(xhci, "resume root hub\n");
 		usb_hcd_resume_root_hub(hcd);
 	}
@@ -1712,7 +1714,8 @@ cleanup:
 	set_bit(HCD_FLAG_POLL_RH, &hcd->flags);
 	spin_unlock(&xhci->lock);
 	/* Pass this up to the core */
-	usb_hcd_poll_rh_status(hcd);
+	if (!needs_root_hub_resume)
+		usb_hcd_poll_rh_status(hcd);
 	spin_lock(&xhci->lock);
 }

Which gets me the following dmesg output after the plug:

[ 2565.543348] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: Port Status Change Event for port 19
[ 2565.543358] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: resume root hub
[ 2565.543375] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
[ 2565.543432] usbcore:usb_remote_wakeup: usb usb2: usb wakeup-resume
[ 2565.543440] usbcore:hcd_bus_resume: usb usb2: usb auto-resume
[ 2565.543461] usbcore:hub_resume: hub 2-0:1.0: hub_resume
[ 2565.543478] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 0 status  = 0x2a0
[ 2565.543488] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 2565.543526] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 1 status  = 0x2a0
[ 2565.543530] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 2565.543546] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x4002c0
[ 2565.543550] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x4002c0
[ 2565.543566] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 3 status  = 0x2a0
[ 2565.543573] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 2565.543591] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 4 status  = 0x2a0
[ 2565.543595] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 2565.543610] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 5 status  = 0x2a0
[ 2565.543614] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 2565.543653] usb usb2: usb_hcd_poll_rh_status, length 1, hcd->flags 0x1a5, status_urb Exists
[ 2565.543663] usbcore:hub_event: hub 2-0:1.0: state 7 ports 6 chg 0000 evt 0000
[ 2565.543680] usbcore:hub_event: hub 2-0:1.0: state 7 ports 6 chg 0000 evt 0008
[ 2565.543696] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x4002c0
[ 2565.543705] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x4002c0
[ 2565.543718] usbcore:port_event: usb usb2-port3: link state change
[ 2565.543732] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port link state change, actual port 2 status  = 0x2c0
[ 2565.543744] usbcore:port_event: usb usb2-port3: do warm reset
[ 2565.602302] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x2b0
[ 2565.602308] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2b0
[ 2565.602338] usbcore:hub_port_wait_reset: usb usb2-port3: not warm reset yet, waiting 50ms
[ 2565.649226] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: Port Status Change Event for port 19
[ 2565.649236] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
[ 2565.649251] usb usb2: usb_hcd_poll_rh_status, length 1, hcd->flags 0x1a5, status_urb Exists
[ 2565.658200] usb usb2: usb_hcd_poll_rh_status, length 1, hcd->flags 0x1a5, status_urb Exists
[ 2565.662258] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x2a1203
[ 2565.662264] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x310203
[ 2565.662305] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port reset change, actual port 2 status  = 0xa1203
[ 2565.662323] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port warm(BH) reset change, actual port 2 status  = 0x21203
[ 2565.662340] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port link state change, actual port 2 status  = 0x21203
[ 2565.662354] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x21203
[ 2565.662358] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x10203
[ 2565.722034] usbcore:hub_event: hub 2-0:1.0: state 7 ports 6 chg 0000 evt 0008
[ 2565.722049] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x21203
[ 2565.722054] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x10203
[ 2565.722080] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port connect change, actual port 2 status  = 0x1203
[ 2565.722092] usbcore:hub_port_connect_change: usb usb2-port3: status 0203, change 0001, 10.0 Gb/s
[ 2565.722099] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x1203
[ 2565.722103] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x203
[ 2565.758232] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x1203
[ 2565.758237] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x203
[ 2565.794301] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x1203
[ 2565.794307] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x203
[ 2565.830243] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x1203
[ 2565.830249] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x203
[ 2565.866217] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x1203
[ 2565.866223] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x203
[ 2565.866249] usbcore:hub_port_debounce: usb usb2-port3: debounce total 100ms stable 100ms status 0x203
[ 2565.866260] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2565.866321] xhci_hcd:xhci_alloc_virt_device: xhci_hcd 0000:00:14.0: Slot 1 output ctx = 0x44f6d4000 (dma)
[ 2565.866328] xhci_hcd:xhci_alloc_virt_device: xhci_hcd 0000:00:14.0: Slot 1 input ctx = 0x454bed000 (dma)
[ 2565.866340] xhci_hcd:xhci_alloc_virt_device: xhci_hcd 0000:00:14.0: Set slot id 1 dcbaa entry 00000000bb5769a7 to 0x44f6d4000
[ 2565.866385] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x1203
[ 2565.866390] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x203
[ 2565.866409] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port reset, actual port 2 status  = 0x1311
[ 2565.866417] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: Port Status Change Event for port 19
[ 2565.866423] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
[ 2565.866435] usb usb2: usb_hcd_poll_rh_status, length 0, hcd->flags 0x1a5, status_urb Exists
[ 2565.906199] usb usb2: usb_hcd_poll_rh_status, length 0, hcd->flags 0x1a5, status_urb Exists
[ 2565.934213] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x201203
[ 2565.934219] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x100203
[ 2565.934251] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port reset change, actual port 2 status  = 0x1203
[ 2565.934268] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port warm(BH) reset change, actual port 2 status  = 0x1203
[ 2565.934286] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port link state change, actual port 2 status  = 0x1203
[ 2565.934300] xhci_hcd:xhci_clear_port_change_bit: xhci_hcd 0000:00:14.0: clear port connect change, actual port 2 status  = 0x1203
[ 2565.934314] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status  = 0x1203
[ 2565.934318] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x203
[ 2565.994227] xhci_hcd:xhci_setup_addressable_virt_dev: xhci_hcd 0000:00:14.0: Set root hub portnum to 19
[ 2565.994233] xhci_hcd:xhci_setup_addressable_virt_dev: xhci_hcd 0000:00:14.0: Set fake root hub portnum to 3
[ 2565.994238] xhci_hcd:xhci_setup_addressable_virt_dev: xhci_hcd 0000:00:14.0: udev->tt =           (null)
[ 2565.994243] xhci_hcd:xhci_setup_addressable_virt_dev: xhci_hcd 0000:00:14.0: udev->ttport = 0x0
[ 2565.994250] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2565.994360] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful setup address command
[ 2565.994370] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Op regs DCBAA ptr = 0x000004582b7000
[ 2565.994378] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Slot ID 1 dcbaa entry @00000000bb5769a7 = 0x0000044f6d4000
[ 2565.994383] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Output Context DMA address = 0x44f6d4000
[ 2565.994388] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Internal device address = 0
[ 2565.994398] usb 2-3: new SuperSpeed Gen 1 USB device number 2 using xhci_hcd
[ 2566.014881] usbcore:usb_parse_endpoint: usb 2-3: skipped 1 descriptor after endpoint
[ 2566.014887] usbcore:usb_parse_endpoint: usb 2-3: skipped 1 descriptor after endpoint
[ 2566.014918] xhci_hcd:process_ctrl_td: xhci_hcd 0000:00:14.0: Waiting for status stage event
[ 2566.014964] usbcore:usb_get_langid: usb 2-3: default language 0x0409
[ 2566.014996] xhci_hcd:process_ctrl_td: xhci_hcd 0000:00:14.0: Waiting for status stage event
[ 2566.015075] xhci_hcd:process_ctrl_td: xhci_hcd 0000:00:14.0: Waiting for status stage event
[ 2566.015155] xhci_hcd:process_ctrl_td: xhci_hcd 0000:00:14.0: Waiting for status stage event
[ 2566.015204] usbcore:usb_new_device: usb 2-3: udev 2, busnum 2, minor = 129
[ 2566.015210] usb 2-3: New USB device found, idVendor=0781, idProduct=5596, bcdDevice= 1.00
[ 2566.015214] usb 2-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[ 2566.015217] usb 2-3: Product: Ultra T C
[ 2566.015221] usb 2-3: Manufacturer: SanDisk
[ 2566.015224] usb 2-3: SerialNumber: 4C530001090830111403
[ 2566.015452] usbcore:usb_probe_device: usb 2-3: usb_probe_device
[ 2566.015458] usbcore:usb_choose_configuration: usb 2-3: configuration #1 chosen from 1 choice
[ 2566.015492] xhci_hcd:xhci_add_endpoint: xhci_hcd 0000:00:14.0: add ep 0x81, slot id 1, new drop flags = 0x0, new add flags = 0x8
[ 2566.015513] xhci_hcd:xhci_add_endpoint: xhci_hcd 0000:00:14.0: add ep 0x2, slot id 1, new drop flags = 0x0, new add flags = 0x18
[ 2566.015519] xhci_hcd:xhci_check_bandwidth: xhci_hcd 0000:00:14.0: xhci_check_bandwidth called for udev 000000008c40d767
[ 2566.015526] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2566.015667] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Endpoint Configure command
[ 2566.015677] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2566.015698] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stopped on No-op or Link TRB for slot 1 ep 2
[ 2566.015708] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2566.015848] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2566.015871] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stopped on No-op or Link TRB for slot 1 ep 3
[ 2566.015881] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2566.016154] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set up evaluate context for LPM MEL change.
[ 2566.016159] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2566.016186] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful evaluate context command
[ 2566.016292] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set up evaluate context for LPM MEL change.
[ 2566.016297] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2566.016331] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful evaluate context command
[ 2566.016389] usbcore:usb_set_configuration: usb 2-3: adding 2-3:1.0 (config #1, interface 0)
[ 2566.046707] usbcore:usb_probe_interface: usb-storage 2-3:1.0: usb_probe_interface
[ 2566.046718] usbcore:usb_probe_interface: usb-storage 2-3:1.0: usb_probe_interface - got id
[ 2566.046723] usb-storage 2-3:1.0: USB Mass Storage device detected
[ 2566.047790] scsi host6: usb-storage 2-3:1.0
[ 2566.047974] usbcore: registered new interface driver usb-storage
[ 2566.051272] usbcore: registered new interface driver uas
[ 2566.154204] xhci_hcd:xhci_hub_status_data: xhci_hcd 0000:00:14.0: xhci_hub_status_data: stopping port polling.
[ 2566.154213] usb usb2: usb_hcd_poll_rh_status, length 0, hcd->flags 0x1a1, status_urb Exists
[ 2567.063435] scsi 6:0:0:0: Direct-Access     SanDisk  Ultra T C        1.00 PQ: 0 ANSI: 6
[ 2567.064071] sd 6:0:0:0: Attached scsi generic sg1 type 0
[ 2567.064276] sd 6:0:0:0: [sdb] 60063744 512-byte logical blocks: (30.8 GB/28.6 GiB)
[ 2567.064701] xhci_hcd:process_bulk_intr_td: xhci_hcd 0000:00:14.0: ep 0x81 - asked for 192 bytes, 124 bytes untransferred
[ 2567.064710] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000005b7fd236, len = 68, expected = 192, status = 0
[ 2567.064941] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stalled endpoint for slot 1 ep 2
[ 2567.064949] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cleaning up stalled endpoint ring
[ 2567.064954] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Finding endpoint context
[ 2567.064959] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cycle state = 0x1
[ 2567.064965] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue segment = 000000006c31f892 (virtual)
[ 2567.064970] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue pointer = 0x4587f2070 (DMA)
[ 2567.064974] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Queueing new dequeue state
[ 2567.064982] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set TR Deq Ptr cmd, new deq seg = 000000006c31f892 (0x4587f2000 dma), new deq ptr = 0000000092dfa1c2 (0x4587f2070 dma), new cycle = 1
[ 2567.064986] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2567.064995] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000007c755c16, len = 0, expected = 13, status = -32
[ 2567.065006] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Ignoring reset ep completion code of 1
[ 2567.065013] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @4587f2070
[ 2567.065184] sd 6:0:0:0: [sdb] Write Protect is off
[ 2567.065189] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00
[ 2567.065297] xhci_hcd:process_bulk_intr_td: xhci_hcd 0000:00:14.0: ep 0x81 - asked for 192 bytes, 124 bytes untransferred
[ 2567.065304] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 00000000b751a34e, len = 68, expected = 192, status = 0
[ 2567.065334] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stalled endpoint for slot 1 ep 2
[ 2567.065341] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cleaning up stalled endpoint ring
[ 2567.065346] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Finding endpoint context
[ 2567.065350] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cycle state = 0x1
[ 2567.065355] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue segment = 000000006c31f892 (virtual)
[ 2567.065360] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue pointer = 0x4587f20a0 (DMA)
[ 2567.065364] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Queueing new dequeue state
[ 2567.065371] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set TR Deq Ptr cmd, new deq seg = 000000006c31f892 (0x4587f2000 dma), new deq ptr = 00000000752c9e76 (0x4587f20a0 dma), new cycle = 1
[ 2567.065376] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2567.065384] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000007c755c16, len = 0, expected = 13, status = -32
[ 2567.065391] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Ignoring reset ep completion code of 1
[ 2567.065397] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @4587f20a0
[ 2567.065504] sd 6:0:0:0: [sdb] Write cache: disabled, read cache: enabled, doesn't support DPO or FUA
[ 2567.066508] xhci_hcd:process_bulk_intr_td: xhci_hcd 0000:00:14.0: ep 0x81 - asked for 96 bytes, 68 bytes untransferred
[ 2567.066515] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000006b0219e8, len = 28, expected = 96, status = 0
[ 2567.066558] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stalled endpoint for slot 1 ep 2
[ 2567.066564] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cleaning up stalled endpoint ring
[ 2567.066569] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Finding endpoint context
[ 2567.066573] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cycle state = 0x1
[ 2567.066578] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue segment = 000000006c31f892 (virtual)
[ 2567.066583] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue pointer = 0x4587f20f0 (DMA)
[ 2567.066587] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Queueing new dequeue state
[ 2567.066594] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set TR Deq Ptr cmd, new deq seg = 000000006c31f892 (0x4587f2000 dma), new deq ptr = 00000000f42a488e (0x4587f20f0 dma), new cycle = 1
[ 2567.066598] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2567.066606] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000007c755c16, len = 0, expected = 13, status = -32
[ 2567.066615] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Ignoring reset ep completion code of 1
[ 2567.066621] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @4587f20f0
[ 2567.068530] xhci_hcd:process_bulk_intr_td: xhci_hcd 0000:00:14.0: ep 0x81 - asked for 192 bytes, 124 bytes untransferred
[ 2567.068538] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 00000000af01d088, len = 68, expected = 192, status = 0
[ 2567.068609] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stalled endpoint for slot 1 ep 2
[ 2567.068617] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cleaning up stalled endpoint ring
[ 2567.068621] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Finding endpoint context
[ 2567.068627] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cycle state = 0x1
[ 2567.068632] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue segment = 000000006c31f892 (virtual)
[ 2567.068637] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue pointer = 0x4587f2150 (DMA)
[ 2567.068653] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Queueing new dequeue state
[ 2567.068654] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set TR Deq Ptr cmd, new deq seg = 000000006c31f892 (0x4587f2000 dma), new deq ptr = 00000000419053a2 (0x4587f2150 dma), new cycle = 1
[ 2567.068655] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2567.068659] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000007c755c16, len = 0, expected = 13, status = -32
[ 2567.068661] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Ignoring reset ep completion code of 1
[ 2567.068666] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @4587f2150
[ 2567.068982] xhci_hcd:process_bulk_intr_td: xhci_hcd 0000:00:14.0: ep 0x81 - asked for 192 bytes, 124 bytes untransferred
[ 2567.068984] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 00000000851894f8, len = 68, expected = 192, status = 0
[ 2567.069032] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stalled endpoint for slot 1 ep 2
[ 2567.069034] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cleaning up stalled endpoint ring
[ 2567.069035] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Finding endpoint context
[ 2567.069036] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cycle state = 0x1
[ 2567.069037] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue segment = 000000006c31f892 (virtual)
[ 2567.069039] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue pointer = 0x4587f2180 (DMA)
[ 2567.069039] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Queueing new dequeue state
[ 2567.069041] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set TR Deq Ptr cmd, new deq seg = 000000006c31f892 (0x4587f2000 dma), new deq ptr = 00000000bcfc19be (0x4587f2180 dma), new cycle = 1
[ 2567.069042] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2567.069047] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000007c755c16, len = 0, expected = 13, status = -32
[ 2567.069049] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Ignoring reset ep completion code of 1
[ 2567.069074] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @4587f2180
[ 2567.081299]  sdb: sdb1
[ 2567.082144] xhci_hcd:process_bulk_intr_td: xhci_hcd 0000:00:14.0: ep 0x81 - asked for 192 bytes, 124 bytes untransferred
[ 2567.082147] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 0000000073ddcc93, len = 68, expected = 192, status = 0
[ 2567.082377] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stalled endpoint for slot 1 ep 2
[ 2567.082380] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cleaning up stalled endpoint ring
[ 2567.082381] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Finding endpoint context
[ 2567.082383] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cycle state = 0x1
[ 2567.082384] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue segment = 000000006c31f892 (virtual)
[ 2567.082386] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue pointer = 0x4587f2200 (DMA)
[ 2567.082387] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Queueing new dequeue state
[ 2567.082389] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set TR Deq Ptr cmd, new deq seg = 000000006c31f892 (0x4587f2000 dma), new deq ptr = 000000006f709260 (0x4587f2200 dma), new cycle = 1
[ 2567.082391] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2567.082395] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000007c755c16, len = 0, expected = 13, status = -32
[ 2567.082398] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Ignoring reset ep completion code of 1
[ 2567.082400] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @4587f2200
[ 2567.082595] xhci_hcd:process_bulk_intr_td: xhci_hcd 0000:00:14.0: ep 0x81 - asked for 192 bytes, 124 bytes untransferred
[ 2567.082597] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 00000000b751a34e, len = 68, expected = 192, status = 0
[ 2567.082634] xhci_hcd:handle_tx_event: xhci_hcd 0000:00:14.0: Stalled endpoint for slot 1 ep 2
[ 2567.082636] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cleaning up stalled endpoint ring
[ 2567.082637] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Finding endpoint context
[ 2567.082639] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Cycle state = 0x1
[ 2567.082640] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue segment = 000000006c31f892 (virtual)
[ 2567.082641] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: New dequeue pointer = 0x4587f2230 (DMA)
[ 2567.082643] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Queueing new dequeue state
[ 2567.082645] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Set TR Deq Ptr cmd, new deq seg = 000000006c31f892 (0x4587f2000 dma), new deq ptr = 000000007e2dd3a1 (0x4587f2230 dma), new cycle = 1
[ 2567.082646] xhci_hcd:xhci_ring_cmd_db: xhci_hcd 0000:00:14.0: // Ding dong!
[ 2567.082650] xhci_hcd:xhci_td_cleanup: xhci_hcd 0000:00:14.0: Giveback URB 000000007c755c16, len = 0, expected = 13, status = -32
[ 2567.082653] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Ignoring reset ep completion code of 1
[ 2567.082676] xhci_hcd:xhci_dbg_trace: xhci_hcd 0000:00:14.0: Successful Set TR Deq Ptr cmd, deq = @4587f2230
[ 2567.082790] sd 6:0:0:0: [sdb] Attached SCSI removable disk

There is an additional auto-resume => auto-suspend cycle without:

diff --git a/core/hub.c b/core/hub.c
index 1d1e61e..cb41cc9 100644
--- a/core/hub.c
+++ b/core/hub.c
@@ -3563,7 +3563,7 @@ int usb_remote_wakeup(struct usb_device *udev)
 	if (udev->state == USB_STATE_SUSPENDED) {
 		dev_dbg(&udev->dev, "usb %sresume\n", "wakeup-");
 		status = usb_autoresume_device(udev);
-		if (status == 0) {
+		if (status != 0) {
 			/* Let the drivers do their thing, then... */
 			usb_autosuspend_device(udev);
 		}