2018-01-23 17:31 GMT+01:00 Alan Stern <stern@xxxxxxxxxxxxxxxxxxx>: > On Tue, 23 Jan 2018, Samuel Sadok wrote: > >> Thanks Alan, >> >> While I was at it I also enabled debug logs for xhci_hcd and xhci_pci. >> >> $ echo module usbcore =p > /sys/kernel/debug/dynamic_debug/control >> $ echo module xhci_hcd =p > /sys/kernel/debug/dynamic_debug/control >> $ echo module xhci_pci =p > /sys/kernel/debug/dynamic_debug/control >> $ modprobe usbmon >> $ cat /sys/kernel/debug/usb/usbmon/0u > /tmp/usbmon.log >> $ # press power button >> >> dmesg: https://gist.github.com/anonymous/29b81574abf40605f999cfeefe98e341 >> usbmon: https://gist.github.com/anonymous/55b6d9bbf8b8c8627230b10d2b09dcb6 >> >> Both logs were collected at the same time so the timestamps should match. > > In fact they do, quite closely. But there is a noticeable gap in the > usbmon trace, between lines 197 and 198 (the timestamp jumps from > 35923531 to 38925126) and there obviously was a lot of activity on bus > 1 in between. Yes you're right, that's inconvenient because the "failed to disable LTM" message occurs exactly in this gap. Are gaps like this expected / known? Any ideas on how to mitigate them? (I kinda want to avoid soldering an external bus monitor to the mainboard :) ) > >> Resume starts at dmesg line 1255. >> As far as I can judge, the earliest indication of something going >> wrong is line 1514: >> [ 36.087176] xhci_hcd 0000:00:14.0: xHCI xhci_urb_enqueue called with >> unaddressed device >> [ 36.087180] usb 2-4: Disable of device-initiated U1 failed. >> [ 36.087212] xhci_hcd 0000:00:14.0: xHCI xhci_urb_enqueue called with >> unaddressed device >> [ 36.087224] usb 2-4: Disable of device-initiated U2 failed. >> [ 36.087226] xhci_hcd 0000:00:14.0: xHCI xhci_urb_enqueue called with >> unaddressed device >> [ 36.087227] usb 2-4: usb_reset_and_verify_device Failed to disable LTM > > Yes, that's where the problem first seems to show up. Apparently > usb_disable_ltm() fails because it can't communicate with the device, > and usb_reset_and_verify_device() then aborts because of that failure. > It shouldn't do this; after all, one very good reason for resetting the > device is because we're unable to communicate with it. > > You could try editing the source code for usb_reset_and_verify_device() > in drivers/usb/core/hub.c, to see what happens if it doesn't give up > after usb_disable_ltm() fails. For the following logs I modified the "Failed to disable LTM" message and commented out the goto in the line below. Also I used kernel version 4.15-rc9 this time. I omitted upgrading the out-of-tree modules broadcom-wl and nouveau-fw, so don't mind errors related to that. The SD card reader is still missing after resume. dmesg & usbmon: https://gist.github.com/anonymous/fc597612d5ebbac40d7bef9f8f0b579a `usb_reset_and_verify_device()` is executed around dmesg line 1524. Again, the usbmon log has a major gap around that time. -- To unsubscribe from this list: send the line "unsubscribe linux-usb" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
