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:
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);
}
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 <[email protected]>
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
