5.5-rc suspend/resume failure caused by patch a4f55d8b8c14 ("usb: hub: Check device descriptor before resusciation")

REGRESSION Paul Zimmerman 2 participants 6 messages Jan 22, 2020 – Jan 31, 2020 USB

Share & tools

Paul Zimmerman

author

2020-01-22 02:31 UTC #0 lore raw

Quoted 33 lines · On Mon, 20 Jan 2020 13:52:15 -0700 Paul Zimmerman <[email protected]> wrote:

Quoted 25 lines · On Mon, 20 Jan 2020 10:23:11 -0500 (EST) Alan Stern…
Quoted 11 lines · Paul Zimmerman
I reported this regression last week (see
https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
but I got no response to my email. Today I have retested with 5.5-rc7 and verified that the problem still exists. So I am resending with a different subject line to see if anyone responds.
The $subject patch causes a regression on my HP EliteBook laptop with a built-in USB bluetooth adapter. About 50% of the time, a suspend/resume cycle will cause the bluetooth adapter to stop working.
Quoted 7 lines
The dmesg log below shows two suspend/resume cycles. At time 63.928 you can see the bluetooth adapter being successfully resumed, and at time 140.969 you can see it fail. After reverting the patch, the bluetooth adapter resumes 100% of the time.
I also included below a lsusb -v of the bluetooth adapter. Is there any other debugging info you'd like me to send?
It looks like your dmesg log was made without enabling debugging messages in usbcore. Can you collect another log with debugging messages turned on?
Quoted 5 lines
echo 'module usbcore =p'
Quoted 1 line
/sys/kernel/debug/dynamic_debug/control
Also, it might not hurt to collect and post a usbmon trace for a bad suspend-resume cycle.

Quoted 6 lines

Hi Alan,
Thanks for responding. The new dmesg log and the usbmon trace are below. The dmesg shows a good suspend/resume followed by a bad one. The bluetooth device is usb 2-3.2 I believe. The usbmon trace is only for the failed suspend/resume case.

I did some more debugging on this using ftrace, here is an annotated log that shows what I think is happening on a failed resume. Note that hub_port_connect_change() is the function that the patch modified to call usb_get_device_descriptor() in some circumstances.

This first call to hub_port_connect_change() is for a different device, not the failing one. There are multiple other calls to that function in the trace, but they are not for the device in question:

     kworker/1:6-19987 [001]  7803.175058: funcgraph_entry:                      |  hub_port_connect_change() {
     kworker/1:6-19987 [001]  7803.175069: funcgraph_entry:      ! 11911.151 us  |    usb_get_device_descriptor();
     kworker/2:5-20675 [002]  7803.179333: funcgraph_entry:                      |  usb_probe_interface() {

Starting here is a worker thread that is trying to setup the bluetooth adapter after the resume:

   kworker/u17:1-3175  [002]  7803.179457: funcgraph_entry:                      |  hci_power_on() {
   kworker/u17:1-3175  [002]  7803.179458: funcgraph_entry:                      |    hci_dev_do_open() {
   kworker/u17:1-3175  [002]  7803.179468: funcgraph_entry:                      |      btusb_setup_intel() {
     kworker/2:5-20675 [002]  7803.179480: funcgraph_exit:       ! 147.596 us    |  }

And here is a worker thread that is handling the connect change on the USB port with the bluetooth device. This happens while the btusb_setup_intel() function called by the other thread above is still running:

     kworker/3:1-16790 [003]  7803.181323: funcgraph_entry:                      |  hub_port_connect_change() {
     kworker/3:1-16790 [003]  7803.181330: funcgraph_entry:                      |    usb_get_device_descriptor() {
     kworker/0:2-19962 [000]  7803.184885: funcgraph_entry:        6.016 us      |  hub_port_connect_change();
     kworker/0:2-19962 [000]  7803.187208: funcgraph_entry:        5.462 us      |  hub_port_connect_change();
     kworker/1:6-19987 [001]  7803.187835: funcgraph_exit:       ! 12776.810 us  |  }
     kworker/1:6-19987 [001]  7803.187846: funcgraph_entry:      ! 767445.344 us |  hub_port_connect_change();

By this point the failure has happened ("Bluetooth: hci0: Reading Intel version information failed (-110)") , and it looks like somebody queues another work to try setting up the bluetooth adapter again:

       hciconfig-21074 [000]  7803.193549: funcgraph_entry:                      |  hci_dev_open() {
     kworker/1:6-19987 [001]  7803.955315: funcgraph_entry:      ! 144039.307 us |  hub_port_connect_change();
   kworker/u17:1-3175  [003]  7805.203325: funcgraph_exit:       ! 2023855 us    |      }
   kworker/u17:1-3175  [003]  7805.211728: funcgraph_exit:       ! 2032269 us    |    }
   kworker/u17:1-3175  [003]  7805.211731: funcgraph_exit:       ! 2032273 us    |  }
       hciconfig-21074 [000]  7805.211760: funcgraph_entry:                      |    hci_dev_do_open() {
       hciconfig-21074 [000]  7805.211777: funcgraph_entry:      ! 3069605 us    |      btusb_setup_intel();

And here the usb_get_device_descriptor() call made by the USB worker thread finally completes. It also fails ("kworker/3:1 timed out on ep0in len=0/18"):

     kworker/3:1-16790 [003]  7808.277224: funcgraph_exit:       ! 5095893 us    |    }
       hciconfig-21074 [001]  7808.283313: funcgraph_exit:       ! 3071554 us    |    }
       hciconfig-21074 [001]  7808.283315: funcgraph_exit:       ! 5089767 us    |  }

So if I'm understanding this correctly, there are two threads that are trying to access the USB bluetooth device at the same time. I have no idea if that is how it's supposed to work.

Thanks,
Paul

Alan Stern

2020-01-22 19:31 UTC #1 lore raw

Quoted 35 lines · Paul Zimmerman

Quoted 33 lines · On Mon, 20 Jan 2020 13:52:15 -0700 Paul Zimmerman <[email protected]> wrote:
Quoted 30 lines · On Mon, 20 Jan 2020 10:23:11 -0500 (EST) Alan Stern…
Quoted 11 lines · Paul Zimmerman
I reported this regression last week (see
https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
but I got no response to my email. Today I have retested with 5.5-rc7 and verified that the problem still exists. So I am resending with a different subject line to see if anyone responds.
The $subject patch causes a regression on my HP EliteBook laptop with a built-in USB bluetooth adapter. About 50% of the time, a suspend/resume cycle will cause the bluetooth adapter to stop working.
Quoted 7 lines
The dmesg log below shows two suspend/resume cycles. At time 63.928 you can see the bluetooth adapter being successfully resumed, and at time 140.969 you can see it fail. After reverting the patch, the bluetooth adapter resumes 100% of the time.
I also included below a lsusb -v of the bluetooth adapter. Is there any other debugging info you'd like me to send?
It looks like your dmesg log was made without enabling debugging messages in usbcore. Can you collect another log with debugging messages turned on?
echo 'module usbcore =p'
Quoted 1 line
/sys/kernel/debug/dynamic_debug/control
Also, it might not hurt to collect and post a usbmon trace for a bad suspend-resume cycle.

Quoted 6 lines

Quoted 6 lines
Hi Alan,
Thanks for responding. The new dmesg log and the usbmon trace are below. The dmesg shows a good suspend/resume followed by a bad one. The bluetooth device is usb 2-3.2 I believe. The usbmon trace is only for the failed suspend/resume case.

It might be interesting to have a usbmon trace of a successful resume as well, for comparison. However I suspect it would just show that the new Get-Device-Descriptor request worked and everything else continued on normally.

Quoted 42 lines

I did some more debugging on this using ftrace, here is an annotated log that shows what I think is happening on a failed resume. Note that hub_port_connect_change() is the function that the patch modified to call usb_get_device_descriptor() in some circumstances.
This first call to hub_port_connect_change() is for a different device, not the failing one. There are multiple other calls to that function in the trace, but they are not for the device in question:
     kworker/1:6-19987 [001]  7803.175058: funcgraph_entry:                      |  hub_port_connect_change() {
     kworker/1:6-19987 [001]  7803.175069: funcgraph_entry:      ! 11911.151 us  |    usb_get_device_descriptor();
     kworker/2:5-20675 [002]  7803.179333: funcgraph_entry:                      |  usb_probe_interface() {
Starting here is a worker thread that is trying to setup the bluetooth adapter after the resume:
   kworker/u17:1-3175  [002]  7803.179457: funcgraph_entry:                      |  hci_power_on() {
   kworker/u17:1-3175  [002]  7803.179458: funcgraph_entry:                      |    hci_dev_do_open() {
   kworker/u17:1-3175  [002]  7803.179468: funcgraph_entry:                      |      btusb_setup_intel() {
     kworker/2:5-20675 [002]  7803.179480: funcgraph_exit:       ! 147.596 us    |  }
And here is a worker thread that is handling the connect change on the USB port with the bluetooth device. This happens while the btusb_setup_intel() function called by the other thread above is still running:
     kworker/3:1-16790 [003]  7803.181323: funcgraph_entry:                      |  hub_port_connect_change() {
     kworker/3:1-16790 [003]  7803.181330: funcgraph_entry:                      |    usb_get_device_descriptor() {
     kworker/0:2-19962 [000]  7803.184885: funcgraph_entry:        6.016 us      |  hub_port_connect_change();
     kworker/0:2-19962 [000]  7803.187208: funcgraph_entry:        5.462 us      |  hub_port_connect_change();
     kworker/1:6-19987 [001]  7803.187835: funcgraph_exit:       ! 12776.810 us  |  }
     kworker/1:6-19987 [001]  7803.187846: funcgraph_entry:      ! 767445.344 us |  hub_port_connect_change();
By this point the failure has happened ("Bluetooth: hci0: Reading Intel version information failed (-110)") , and it looks like somebody queues another work to try setting up the bluetooth adapter again:
       hciconfig-21074 [000]  7803.193549: funcgraph_entry:                      |  hci_dev_open() {
     kworker/1:6-19987 [001]  7803.955315: funcgraph_entry:      ! 144039.307 us |  hub_port_connect_change();
   kworker/u17:1-3175  [003]  7805.203325: funcgraph_exit:       ! 2023855 us    |      }
   kworker/u17:1-3175  [003]  7805.211728: funcgraph_exit:       ! 2032269 us    |    }
   kworker/u17:1-3175  [003]  7805.211731: funcgraph_exit:       ! 2032273 us    |  }
       hciconfig-21074 [000]  7805.211760: funcgraph_entry:                      |    hci_dev_do_open() {
       hciconfig-21074 [000]  7805.211777: funcgraph_entry:      ! 3069605 us    |      btusb_setup_intel();
And here the usb_get_device_descriptor() call made by the USB worker thread finally completes. It also fails ("kworker/3:1 timed out on ep0in len=0/18"):

Quoted 7 lines

     kworker/3:1-16790 [003]  7808.277224: funcgraph_exit:       ! 5095893 us    |    }
       hciconfig-21074 [001]  7808.283313: funcgraph_exit:       ! 3071554 us    |    }
       hciconfig-21074 [001]  7808.283315: funcgraph_exit:       ! 5089767 us    |  }
So if I'm understanding this correctly, there are two threads that are trying to access the USB bluetooth device at the same time. I have no idea if that is how it's supposed to work.

In fact it isn't, although in principle this shouldn't cause any trouble. It looks like your bluetooth device is deficient: It sometimes crashes if it receives a Get-Device-Descriptor request while it is busy with something else.

Still, since there was no real connection change at the port, there's no reason to call hub_port_connect_change() here. Let's see if the patch below fixes your problem.

Alan Stern

drivers/usb/core/hub.c +0 -5

Index: usb-devel/drivers/usb/core/hub.c
===================================================================
@@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
 #ifdef CONFIG_PM
 			udev->reset_resume = 1;
 #endif
-			/* Don't set the change_bits when the device
-			 * was powered off.
-			 */
-			if (test_bit(port1, hub->power_bits))
-				set_bit(port1, hub->change_bits);
 
 		} else {
 			/* The power session is gone; tell hub_wq */

Paul Zimmerman

author Tested-by

2020-01-22 23:55 UTC #2 lore raw

Quoted 48 lines · On Wed, 22 Jan 2020 14:31:29 -0500 (EST) Alan Stern…

Quoted 35 lines · Paul Zimmerman
Quoted 33 lines · On Mon, 20 Jan 2020 13:52:15 -0700 Paul Zimmerman <[email protected]> wrote:
Quoted 30 lines · On Mon, 20 Jan 2020 10:23:11 -0500 (EST) Alan Stern…
Quoted 11 lines · Paul Zimmerman
I reported this regression last week (see
https://lore.kernel.org/linux-usb/20200115153714.03d5b3aa@EliteBook/T/#u)
but I got no response to my email. Today I have retested with 5.5-rc7 and verified that the problem still exists. So I am resending with a different subject line to see if anyone responds.
The $subject patch causes a regression on my HP EliteBook laptop with a built-in USB bluetooth adapter. About 50% of the time, a suspend/resume cycle will cause the bluetooth adapter to stop working.
Quoted 7 lines
The dmesg log below shows two suspend/resume cycles. At time 63.928 you can see the bluetooth adapter being successfully resumed, and at time 140.969 you can see it fail. After reverting the patch, the bluetooth adapter resumes 100% of the time.
I also included below a lsusb -v of the bluetooth adapter. Is there any other debugging info you'd like me to send?
It looks like your dmesg log was made without enabling debugging messages in usbcore. Can you collect another log with debugging messages turned on?
echo 'module usbcore =p'
Quoted 1 line
/sys/kernel/debug/dynamic_debug/control
Also, it might not hurt to collect and post a usbmon trace for a bad suspend-resume cycle.
Quoted 6 lines
Quoted 6 lines
Hi Alan,
Thanks for responding. The new dmesg log and the usbmon trace are below. The dmesg shows a good suspend/resume followed by a bad one. The bluetooth device is usb 2-3.2 I believe. The usbmon trace is only for the failed suspend/resume case.
It might be interesting to have a usbmon trace of a successful resume as well, for comparison. However I suspect it would just show that the new Get-Device-Descriptor request worked and everything else continued on normally.

< snip >

Quoted 24 lines

Quoted 3 lines
So if I'm understanding this correctly, there are two threads that are trying to access the USB bluetooth device at the same time. I have no idea if that is how it's supposed to work.
In fact it isn't, although in principle this shouldn't cause any trouble. It looks like your bluetooth device is deficient: It sometimes crashes if it receives a Get-Device-Descriptor request while it is busy with something else.
Still, since there was no real connection change at the port, there's no reason to call hub_port_connect_change() here. Let's see if the patch below fixes your problem.
Alan Stern
Index: usb-devel/drivers/usb/core/hub.c
===================================================================
drivers/usb/core/hub.c +0 -0
@@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
 #ifdef CONFIG_PM

drivers/usb/core/hub.c static void hub_activate(struct usb_hub · line 1221

Quoted 10 lines

drivers/usb/core/hub.c +0 -5

 			udev->reset_resume = 1;
 #endif
-			/* Don't set the change_bits when the device
-			 * was powered off.
-			 */
-			if (test_bit(port1, hub->power_bits))
-				set_bit(port1, hub->change_bits);
 
 		} else {
 			/* The power session is gone; tell hub_wq */

I can confirm this fixes the issue for me, I did a couple dozen suspend/resume cycles without seeing a failure.

I see the code you removed was added by Lan Tianyu in commit ad493e5e5805 ("usb: add usb port auto power off mechanism"). I wonder if your patch would break that? I don't know what that is or how to test it.

In any case:

Tested-by Paul Zimmerman <[email protected]>

Alan Stern

2020-01-23 15:50 UTC #3 lore raw

Quoted 29 lines · Paul Zimmerman

Quoted 15 lines
Still, since there was no real connection change at the port, there's no reason to call hub_port_connect_change() here. Let's see if the patch below fixes your problem.
Alan Stern
Index: usb-devel/drivers/usb/core/hub.c
===================================================================
drivers/usb/core/hub.c +0 -0
@@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
 #ifdef CONFIG_PM
drivers/usb/core/hub.c static void hub_activate(struct usb_hub · line 1221
Quoted 10 lines
drivers/usb/core/hub.c +0 -5
 			udev->reset_resume = 1;
 #endif
-			/* Don't set the change_bits when the device
-			 * was powered off.
-			 */
-			if (test_bit(port1, hub->power_bits))
-				set_bit(port1, hub->change_bits);
 
 		} else {
 			/* The power session is gone; tell hub_wq */
I can confirm this fixes the issue for me, I did a couple dozen suspend/resume cycles without seeing a failure.

Quoted 2 lines

I see the code you removed was added by Lan Tianyu in commit ad493e5e5805 ("usb: add usb port auto power off mechanism"). I

No, not really. The set_bit() call was added by me in a much earlier commit (8808f00c7adf, merged in 2008). Lan Tianyu merely added the "if" test, so that set_bit() doesn't always get called. Now with this change, set_bit() never gets called.

Quoted 2 lines

wonder if your patch would break that? I don't know what that is or how to test it.

While some code review by people who are familiar with this material wouldn't hurt, I don't think you need to worry about any additional testing.

Quoted 2 lines

In any case:
Tested-by Paul Zimmerman <[email protected]>

Thank you. I'll submit the patch soon.

Alan Stern

Paul Zimmerman

author

2020-01-30 21:17 UTC #4 lore raw

Hi Alan,

Quoted 46 lines · Alan Stern

Quoted 29 lines · Paul Zimmerman
Quoted 15 lines
Still, since there was no real connection change at the port, there's no reason to call hub_port_connect_change() here. Let's see if the patch below fixes your problem.
Alan Stern
Index: usb-devel/drivers/usb/core/hub.c
===================================================================
drivers/usb/core/hub.c +0 -0
@@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
  #ifdef CONFIG_PM
drivers/usb/core/hub.c static void hub_activate(struct usb_hub · line 1221
Quoted 10 lines
drivers/usb/core/hub.c +0 -5
  			udev->reset_resume = 1;
  #endif
-			/* Don't set the change_bits when the device
-			 * was powered off.
-			 */
-			if (test_bit(port1, hub->power_bits))
-				set_bit(port1, hub->change_bits);
 
  		} else {
  			/* The power session is gone; tell hub_wq */
I can confirm this fixes the issue for me, I did a couple dozen suspend/resume cycles without seeing a failure.
Quoted 2 lines
I see the code you removed was added by Lan Tianyu in commit ad493e5e5805 ("usb: add usb port auto power off mechanism"). I
No, not really. The set_bit() call was added by me in a much earlier commit (8808f00c7adf, merged in 2008). Lan Tianyu merely added the "if" test, so that set_bit() doesn't always get called. Now with this change, set_bit() never gets called.
Quoted 2 lines
wonder if your patch would break that? I don't know what that is or how to test it.
While some code review by people who are familiar with this material wouldn't hurt, I don't think you need to worry about any additional testing.

Quoted 6 lines

Quoted 2 lines
In any case:
Tested-by Paul Zimmerman <[email protected]>
Thank you. I'll submit the patch soon.
Alan Stern

Ping? Unfortunately 5.5 was released with this regression, do you plan to submit this patch soon?

Signature · 1 line

Paul

Alan Stern

2020-01-31 15:37 UTC #5 lore raw

Quoted 52 lines · Paul Zimmerman

Hi Alan,
Quoted 49 lines · Alan Stern
Quoted 29 lines · Paul Zimmerman
Quoted 15 lines
Still, since there was no real connection change at the port, there's no reason to call hub_port_connect_change() here. Let's see if the patch below fixes your problem.
Alan Stern
Index: usb-devel/drivers/usb/core/hub.c
===================================================================
drivers/usb/core/hub.c +0 -0
@@ -1216,11 +1216,6 @@ static void hub_activate(struct usb_hub
  #ifdef CONFIG_PM
drivers/usb/core/hub.c static void hub_activate(struct usb_hub · line 1221
Quoted 10 lines
drivers/usb/core/hub.c +0 -5
  			udev->reset_resume = 1;
  #endif
-			/* Don't set the change_bits when the device
-			 * was powered off.
-			 */
-			if (test_bit(port1, hub->power_bits))
-				set_bit(port1, hub->change_bits);
 
  		} else {
  			/* The power session is gone; tell hub_wq */
I can confirm this fixes the issue for me, I did a couple dozen suspend/resume cycles without seeing a failure.
Quoted 2 lines
I see the code you removed was added by Lan Tianyu in commit ad493e5e5805 ("usb: add usb port auto power off mechanism"). I
No, not really. The set_bit() call was added by me in a much earlier commit (8808f00c7adf, merged in 2008). Lan Tianyu merely added the "if" test, so that set_bit() doesn't always get called. Now with this change, set_bit() never gets called.
Quoted 2 lines
wonder if your patch would break that? I don't know what that is or how to test it.
While some code review by people who are familiar with this material wouldn't hurt, I don't think you need to worry about any additional testing.
Quoted 2 lines
In any case:
Tested-by Paul Zimmerman <[email protected]>

Quoted 6 lines

Quoted 3 lines
Thank you. I'll submit the patch soon.
Alan Stern
Ping? Unfortunately 5.5 was released with this regression, do you plan to submit this patch soon?

Oops. It totally slipped my mind, sorry. Thanks for reminding me. Submission coming up...

Alan Stern