Am 30.01.19 um 15:58 schrieb Mathias Nyman:
> 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.
I saw this too (chg 0000 evt 0000). I tried following the change_bits and event_bits
handling and fix it somewhere else, but then realized the port_event was never triggered,
which I expected. And also not the bits handling code in hub_activate.
> 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 */
This is just the plug code. I skipped the module load code, as there was no additional output.
[ 485.284810] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: Port Status Change Event for port 19
[ 485.284820] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: resume root hub
[ 485.284835] xhci_hcd:handle_port_status: xhci_hcd 0000:00:14.0: handle_port_status: starting port polling.
[ 485.284850] usb usb2: usb_hcd_poll_rh_status, length 1, hcd->flags 0x195, status_urb NULL
[ 485.284909] usbcore:usb_remote_wakeup: usb usb2: usb wakeup-resume
[ 485.284917] usbcore:hcd_bus_resume: usb usb2: usb auto-resume
[ 485.284937] usbcore:hub_resume: hub 2-0:1.0: hub_resume
[ 485.284950] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 0 status = 0x2a0
[ 485.284961] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.284995] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 1 status = 0x2a0
[ 485.285004] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.285020] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status = 0x4002c0
[ 485.285025] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x4002c0
[ 485.285040] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 3 status = 0x2a0
[ 485.285049] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.285069] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 4 status = 0x2a0
[ 485.285074] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.285088] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 5 status = 0x2a0
[ 485.285092] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.285116] usbcore:hub_event: hub 2-0:1.0: state 7 ports 6 chg 0000 evt 0000
[ 485.285132] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 0 status = 0xe0002a0
[ 485.285154] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 1 status = 0xe0002a0
[ 485.285171] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 2 status = 0xe4002c0
[ 485.285192] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 3 status = 0xe0002a0
[ 485.285209] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 4 status = 0xe0002a0
[ 485.285230] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 5 status = 0xe0002a0
[ 485.285243] usbcore:hub_suspend: hub 2-0:1.0: hub_suspend
[ 485.285259] usbcore:hcd_bus_suspend: usb usb2: bus auto-suspend, wakeup 1
[ 485.285279] usbcore:hcd_bus_suspend: usb usb2: suspend raced with wakeup event
[ 485.285283] usbcore:hcd_bus_resume: usb usb2: usb auto-resume
[ 485.285774] usb usb2: usb_hcd_poll_rh_status, length 1, hcd->flags 0x18d, status_urb NULL
[ 485.301806] usbcore:hub_resume: hub 2-0:1.0: hub_resume
[ 485.301819] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 0 status = 0x2a0
[ 485.301823] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.301846] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 1 status = 0x2a0
[ 485.301850] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.301863] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 2 status = 0x4002c0
[ 485.301867] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x4002c0
[ 485.301881] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 3 status = 0x2a0
[ 485.301885] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.301896] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 4 status = 0x2a0
[ 485.301900] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.301913] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: get port status, actual port 5 status = 0x2a0
[ 485.301916] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: Get port status returned 0x2a0
[ 485.301936] usbcore:hub_event: hub 2-0:1.0: state 7 ports 6 chg 0000 evt 0000
[ 485.301952] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 0 status = 0xe0002a0
[ 485.301968] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 1 status = 0xe0002a0
[ 485.301982] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 2 status = 0xe4002c0
[ 485.301996] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 3 status = 0xe0002a0
[ 485.302010] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 4 status = 0xe0002a0
[ 485.302024] xhci_hcd:xhci_hub_control: xhci_hcd 0000:00:14.0: set port remote wake mask, actual port 5 status = 0xe0002a0
[ 485.302034] usbcore:hub_suspend: hub 2-0:1.0: hub_suspend
[ 485.302048] usbcore:hcd_bus_suspend: usb usb2: bus auto-suspend, wakeup 1
[ 485.302067] usbcore:hcd_bus_suspend: usb usb2: suspend raced with wakeup event
[ 485.302071] usbcore:hcd_bus_resume: usb usb2: usb auto-resume
[ 485.309765] usb usb2: usb_hcd_poll_rh_status, length 1, hcd->flags 0x18d, status_urb NULL
...
Jan-Marek
P.S. I'm currently hanging out as jmux in #kernelnewbies, if IRC would help.
