Hi,
a user is seeing a hang in fprintd while enumerating devices which
appears to be caused by an interaction of:
* system is resuming from S3
* btusb starts loading firmware
* bluetooth device disappears (probably thinkpad_acpi rfkill)
* libusb enumerates USB devices (fprintd in this case)
When this happens, the firmware load fails after a timeout of 10s. It
appears that if userspace queries information about the root hub in
question during this time, it will hang until the btusb firmware load
has timed out.
Attaching the full kernel log, below an excerpt, you can see:
* At :12 device removal: "usb 5-4: USB disconnect, device number 33"
* libusb enumeration retrieves information about the usb5 root hub,
and blocks on this
* At :14 there is a tx timeout on hci0
* At :23 the firmware load finally fails
* Then usb_disable_device happens
* libusb/fprintd gets the usb5 HUB information and continues its
enumeration
As I see it, there may be two issues:
1. userspace should not block due to the firmware load hanging
2. btusb should give up more quickly when the device disappears
Does anyone have a good idea about the possible cause or how we can fix
the problem?
Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857
Benjamin
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: enable port 4 USB2 hardware LPM
...
[Mi Nov 3 11:55:12 2021] usb 5-4: udev 33, busnum 5, minor = 544
[Mi Nov 3 11:55:12 2021] usb 5-4: New USB device found, idVendor=8087, idProduct=0032, bcdDevice= 0.00
[Mi Nov 3 11:55:12 2021] usb 5-4: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[Mi Nov 3 11:55:12 2021] usb 5-4: usb_probe_device
[Mi Nov 3 11:55:12 2021] usb 5-4: configuration #1 chosen from 1 choice
...
[Mi Nov 3 11:55:12 2021] usb 5-4: adding 5-4:1.0 (config #1, interface 0)
[Mi Nov 3 11:55:12 2021] btusb 5-4:1.0: usb_probe_interface
[Mi Nov 3 11:55:12 2021] btusb 5-4:1.0: usb_probe_interface - got id
[Mi Nov 3 11:55:12 2021] usb 5-4: adding 5-4:1.1 (config #1, interface 1)
[Mi Nov 3 11:55:12 2021] Generic FE-GE Realtek PHY r8169-0-200:00: attached PHY driver (mii_bus:phy_addr=r8169-0-200:00, irq=MAC)
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x81 - asked for 64 bytes, 32 bytes untransferred
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Device revision is 0
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Secure boot is enabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: OTP lock is enabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: API lock is enabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Debug lock is disabled
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Bootloader timestamp 2019.40 buildtype 1 build 38
[Mi Nov 3 11:55:12 2021] psmouse serio1: synaptics: queried max coordinates: x [..5678], y [..4694]
[Mi Nov 3 11:55:12 2021] Bluetooth: hci0: Found device firmware: intel/ibt-0041-0041.sfi
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: ep 0x82 - asked for 1028 bytes, 1022 bytes untransferred
...
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Port change event, 5-4, id 4, portsc: 0x202a0
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: handle_port_status: starting port polling.
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
...
[Mi Nov 3 11:55:12 2021] usb 5-4: USB disconnect, device number 33
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
...
[Mi Nov 3 11:55:12 2021] usb 5-4: unregistering device
[Mi Nov 3 11:55:12 2021] usb 5-4: unregistering interface 5-4:1.0
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 3 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Transfer error for slot 2 ep 4 on endpoint
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
[Mi Nov 3 11:55:12 2021] xhci_hcd 0000:07:00.4: Ignoring reset ep completion code of 1
...
[Mi Nov 3 11:55:14 2021] Bluetooth: hci0: command 0xfc09 tx timeout
...
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Failed to send firmware data (-110)
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: sending frame failed (-19)
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Intel reset sent to retry FW download
[Mi Nov 3 11:55:23 2021] usb 5-4: unregistering interface 5-4:1.1
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: disable port 4 USB2 hardware LPM
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: Set up evaluate context for LPM MEL change.
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: // Ding dong!
[Mi Nov 3 11:55:23 2021] xhci_hcd 0000:07:00.4: Successful evaluate context command
[Mi Nov 3 11:55:23 2021] usb 5-4: usb_disable_device nuking all URBs
On Wed, Nov 03, 2021 at 03:55:31PM +0100, Benjamin Berg wrote:
> Hi,
>
> a user is seeing a hang in fprintd while enumerating devices which
> appears to be caused by an interaction of:
>
> * system is resuming from S3
> * btusb starts loading firmware
> * bluetooth device disappears (probably thinkpad_acpi rfkill)
> * libusb enumerates USB devices (fprintd in this case)
>
> When this happens, the firmware load fails after a timeout of 10s. It
> appears that if userspace queries information about the root hub in
> question during this time, it will hang until the btusb firmware load
> has timed out.
>
> Attaching the full kernel log, below an excerpt, you can see:
> * At :12 device removal: "usb 5-4: USB disconnect, device number 33"
> * libusb enumeration retrieves information about the usb5 root hub,
> and blocks on this
> * At :14 there is a tx timeout on hci0
> * At :23 the firmware load finally fails
> * Then usb_disable_device happens
> * libusb/fprintd gets the usb5 HUB information and continues its
> enumeration
>
> As I see it, there may be two issues:
> 1. userspace should not block due to the firmware load hanging
> 2. btusb should give up more quickly when the device disappears
>
> Does anyone have a good idea about the possible cause or how we can fix
> the problem?
>
> Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857
I'm not familiar with the btusb driver, so someone on the
linux-bluetooth mailing list would have a better idea about this.
However, it does look as though btusb keeps the device locked during the
entire 10-second period while it tries to send over the firmware, and it
doesn't abort the procedure when it starts getting disconnection errors
but instead persists until a timeout expires. Keeping the device locked
would certainly block lsusb.
In general, locking the device during a firmware upload seems like
the right thing to do -- you don't want extraneous transfers from
other processes messing up the firmware! So overall, it appears that
the whole problem would be solved if the firmware transfer were
aborted as soon as the -ENODEV errors start appearing.
Alan Stern
Hi Alan,
>> a user is seeing a hang in fprintd while enumerating devices which
>> appears to be caused by an interaction of:
>>
>> * system is resuming from S3
>> * btusb starts loading firmware
>> * bluetooth device disappears (probably thinkpad_acpi rfkill)
>> * libusb enumerates USB devices (fprintd in this case)
>>
>> When this happens, the firmware load fails after a timeout of 10s. It
>> appears that if userspace queries information about the root hub in
>> question during this time, it will hang until the btusb firmware load
>> has timed out.
>>
>> Attaching the full kernel log, below an excerpt, you can see:
>> * At :12 device removal: "usb 5-4: USB disconnect, device number 33"
>> * libusb enumeration retrieves information about the usb5 root hub,
>> and blocks on this
>> * At :14 there is a tx timeout on hci0
>> * At :23 the firmware load finally fails
>> * Then usb_disable_device happens
>> * libusb/fprintd gets the usb5 HUB information and continues its
>> enumeration
>>
>> As I see it, there may be two issues:
>> 1. userspace should not block due to the firmware load hanging
>> 2. btusb should give up more quickly when the device disappears
>>
>> Does anyone have a good idea about the possible cause or how we can fix
>> the problem?
>>
>> Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857
>
> I'm not familiar with the btusb driver, so someone on the
> linux-bluetooth mailing list would have a better idea about this.
> However, it does look as though btusb keeps the device locked during the
> entire 10-second period while it tries to send over the firmware, and it
> doesn't abort the procedure when it starts getting disconnection errors
> but instead persists until a timeout expires. Keeping the device locked
> would certainly block lsusb.
>
> In general, locking the device during a firmware upload seems like
> the right thing to do -- you don't want extraneous transfers from
> other processes messing up the firmware! So overall, it appears that
> the whole problem would be solved if the firmware transfer were
> aborted as soon as the -ENODEV errors start appearing.
the problem seems to be that we hitting HCI command timeout. So the firmware download is done via HCI commands. These commands are send to the transport driver btusb.c via hdev->send (as btusb_send_frame). This triggers the usb_submit_urb or queues them via data->deferred anchor. All this reports back the error properly except that nobody does anything with it.
See hci_send_frame() last portion:
err = hdev->send(hdev, skb);
if (err < 0) {
bt_dev_err(hdev, "sending frame failed (%d)", err);
kfree_skb(skb);
}
And that is it. We are not checking for ENODEV or any error here. That means the failure of the HCI command gets only caught via the HCI command timeout. I don’t know how to do this yet, but you would have to look there to fail HCI command right away instead of waiting for the timeout.
Regards
Marcel
On Wed, Nov 03, 2021 at 08:31:03PM +0100, Marcel Holtmann wrote:
> Hi Alan,
>
> >> a user is seeing a hang in fprintd while enumerating devices which
> >> appears to be caused by an interaction of:
> >>
> >> * system is resuming from S3
> >> * btusb starts loading firmware
> >> * bluetooth device disappears (probably thinkpad_acpi rfkill)
> >> * libusb enumerates USB devices (fprintd in this case)
> >>
> >> When this happens, the firmware load fails after a timeout of 10s. It
> >> appears that if userspace queries information about the root hub in
> >> question during this time, it will hang until the btusb firmware load
> >> has timed out.
> >>
> >> Attaching the full kernel log, below an excerpt, you can see:
> >> * At :12 device removal: "usb 5-4: USB disconnect, device number 33"
> >> * libusb enumeration retrieves information about the usb5 root hub,
> >> and blocks on this
> >> * At :14 there is a tx timeout on hci0
> >> * At :23 the firmware load finally fails
> >> * Then usb_disable_device happens
> >> * libusb/fprintd gets the usb5 HUB information and continues its
> >> enumeration
> >>
> >> As I see it, there may be two issues:
> >> 1. userspace should not block due to the firmware load hanging
> >> 2. btusb should give up more quickly when the device disappears
> >>
> >> Does anyone have a good idea about the possible cause or how we can fix
> >> the problem?
> >>
> >> Downstream issue: https://bugzilla.redhat.com/show_bug.cgi?id=2019857
> >
> > I'm not familiar with the btusb driver, so someone on the
> > linux-bluetooth mailing list would have a better idea about this.
> > However, it does look as though btusb keeps the device locked during the
> > entire 10-second period while it tries to send over the firmware, and it
> > doesn't abort the procedure when it starts getting disconnection errors
> > but instead persists until a timeout expires. Keeping the device locked
> > would certainly block lsusb.
> >
> > In general, locking the device during a firmware upload seems like
> > the right thing to do -- you don't want extraneous transfers from
> > other processes messing up the firmware! So overall, it appears that
> > the whole problem would be solved if the firmware transfer were
> > aborted as soon as the -ENODEV errors start appearing.
>
> the problem seems to be that we hitting HCI command timeout. So the
> firmware download is done via HCI commands. These commands are send to
> the transport driver btusb.c via hdev->send (as btusb_send_frame).
> This triggers the usb_submit_urb or queues them via data->deferred
> anchor. All this reports back the error properly except that nobody
> does anything with it.
>
> See hci_send_frame() last portion:
>
> err = hdev->send(hdev, skb);
> if (err < 0) {
> bt_dev_err(hdev, "sending frame failed (%d)", err);
> kfree_skb(skb);
> }
>
> And that is it. We are not checking for ENODEV or any error here. That
> means the failure of the HCI command gets only caught via the HCI
> command timeout. I don’t know how to do this yet, but you would have
> to look there to fail HCI command right away instead of waiting for
> the timeout.
I have no idea how all the different layers work here. Clearly
something has to signal hdev->req_wait_q after setting hdev->req_status
to some appropriate value. Can this be done in btusb.c, either when the
URB is submitted or when it completes? Or in hci_send_frame?
Alan Stern
Hi Marcel and Alan,
On Wed, 2021-11-03 at 20:31 +0100, Marcel Holtmann wrote:
> > I'm not familiar with the btusb driver, so someone on the
> > linux-bluetooth mailing list would have a better idea about this.
> > However, it does look as though btusb keeps the device locked during the
> > entire 10-second period while it tries to send over the firmware, and it
> > doesn't abort the procedure when it starts getting disconnection errors
> > but instead persists until a timeout expires. Keeping the device locked
> > would certainly block lsusb.
> >
> > In general, locking the device during a firmware upload seems like
> > the right thing to do -- you don't want extraneous transfers from
> > other processes messing up the firmware! So overall, it appears that
> > the whole problem would be solved if the firmware transfer were
> > aborted as soon as the -ENODEV errors start appearing.
>
> the problem seems to be that we hitting HCI command timeout. So the
> firmware download is done via HCI commands. These commands are send
> to the transport driver btusb.c via hdev->send (as btusb_send_frame).
> This triggers the usb_submit_urb or queues them via data->deferred
> anchor. All this reports back the error properly except that nobody
> does anything with it.
>
> See hci_send_frame() last portion:
>
> err = hdev->send(hdev, skb);
> if (err < 0) {
> bt_dev_err(hdev, "sending frame failed (%d)", err);
> kfree_skb(skb);
> }
>
> And that is it. We are not checking for ENODEV or any error here.
> That means the failure of the HCI command gets only caught via the
> HCI command timeout. I don’t know how to do this yet, but you would
> have to look there to fail HCI command right away instead of waiting
> for the timeout.
Hmm, true, I don't see a "sending frame failed" error message during
the firmware download though. You are right that this codepath is
loosing the error, but this does not seem to be the scenario we are
running into while loading the firmware. This error only happens later
on from the btintel_reset_to_bootloader function.
What seems to happen in the posted log is that the URB is initially
submitted just fine and the transfer errors out afterwards.
Unfortunately, the btusb_tx_complete is only used for statistics
(stat.err_tx is increased) and has no further error handling that could
abort the firmware upload.
Benjamin
On Thu, Nov 04, 2021 at 10:34:22AM +0100, Benjamin Berg wrote:
> Hi Marcel and Alan,
>
> On Wed, 2021-11-03 at 20:31 +0100, Marcel Holtmann wrote:
> > > I'm not familiar with the btusb driver, so someone on the
> > > linux-bluetooth mailing list would have a better idea about this.
> > > However, it does look as though btusb keeps the device locked during the
> > > entire 10-second period while it tries to send over the firmware, and it
> > > doesn't abort the procedure when it starts getting disconnection errors
> > > but instead persists until a timeout expires. Keeping the device locked
> > > would certainly block lsusb.
> > >
> > > In general, locking the device during a firmware upload seems like
> > > the right thing to do -- you don't want extraneous transfers from
> > > other processes messing up the firmware! So overall, it appears that
> > > the whole problem would be solved if the firmware transfer were
> > > aborted as soon as the -ENODEV errors start appearing.
> >
> > the problem seems to be that we hitting HCI command timeout. So the
> > firmware download is done via HCI commands. These commands are send
> > to the transport driver btusb.c via hdev->send (as btusb_send_frame).
> > This triggers the usb_submit_urb or queues them via data->deferred
> > anchor. All this reports back the error properly except that nobody
> > does anything with it.
> >
> > See hci_send_frame() last portion:
> >
> > err = hdev->send(hdev, skb);
> > if (err < 0) {
> > bt_dev_err(hdev, "sending frame failed (%d)", err);
> > kfree_skb(skb);
> > }
> >
> > And that is it. We are not checking for ENODEV or any error here.
> > That means the failure of the HCI command gets only caught via the
> > HCI command timeout. I don’t know how to do this yet, but you would
> > have to look there to fail HCI command right away instead of waiting
> > for the timeout.
>
> Hmm, true, I don't see a "sending frame failed" error message during
> the firmware download though.
It is in the log you posted:
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Failed to send firmware data (-110)
[Mi Nov 3 11:55:23 2021] Bluetooth: hci0: sending frame failed (-19)
But this occurred after the timeout, so maybe you had in mind something
occurring earlier.
> You are right that this codepath is
> loosing the error, but this does not seem to be the scenario we are
> running into while loading the firmware. This error only happens later
> on from the btintel_reset_to_bootloader function.
>
> What seems to happen in the posted log is that the URB is initially
> submitted just fine and the transfer errors out afterwards.
> Unfortunately, the btusb_tx_complete is only used for statistics
> (stat.err_tx is increased) and has no further error handling that could
> abort the firmware upload.
While detecting the errors during URB completion would be nice, it isn't
necessary. Things would work just as well if the disconnect error were
detected during submission of the following URB.
Alan Stern
On Thu, 2021-11-04 at 09:28 -0400, Alan Stern wrote:
> On Thu, Nov 04, 2021 at 10:34:22AM +0100, Benjamin Berg wrote:
> > Hi Marcel and Alan,
> >
> > On Wed, 2021-11-03 at 20:31 +0100, Marcel Holtmann wrote:
> > > > I'm not familiar with the btusb driver, so someone on the
> > > > linux-bluetooth mailing list would have a better idea about this.
> > > > However, it does look as though btusb keeps the device locked during the
> > > > entire 10-second period while it tries to send over the firmware, and it
> > > > doesn't abort the procedure when it starts getting disconnection errors
> > > > but instead persists until a timeout expires. Keeping the device locked
> > > > would certainly block lsusb.
> > > >
> > > > In general, locking the device during a firmware upload seems like
> > > > the right thing to do -- you don't want extraneous transfers from
> > > > other processes messing up the firmware! So overall, it appears that
> > > > the whole problem would be solved if the firmware transfer were
> > > > aborted as soon as the -ENODEV errors start appearing.
> > >
> > > the problem seems to be that we hitting HCI command timeout. So the
> > > firmware download is done via HCI commands. These commands are send
> > > to the transport driver btusb.c via hdev->send (as btusb_send_frame).
> > > This triggers the usb_submit_urb or queues them via data->deferred
> > > anchor. All this reports back the error properly except that nobody
> > > does anything with it.
> > >
> > > See hci_send_frame() last portion:
> > >
> > > err = hdev->send(hdev, skb);
> > > if (err < 0) {
> > > bt_dev_err(hdev, "sending frame failed (%d)", err);
> > > kfree_skb(skb);
> > > }
> > >
> > > And that is it. We are not checking for ENODEV or any error here.
> > > That means the failure of the HCI command gets only caught via the
> > > HCI command timeout. I don’t know how to do this yet, but you would
> > > have to look there to fail HCI command right away instead of waiting
> > > for the timeout.
> >
> > Hmm, true, I don't see a "sending frame failed" error message during
> > the firmware download though.
>
> It is in the log you posted:
>
> [Mi Nov 3 11:55:23 2021] Bluetooth: hci0: Failed to send firmware data (-110)
> [Mi Nov 3 11:55:23 2021] Bluetooth: hci0: sending frame failed (-19)
>
> But this occurred after the timeout, so maybe you had in mind something
> occurring earlier.
Yep, that one happens when the driver tries to reset the device. We
need to catch the error earlier in order to avoid the 10s wait.
> > You are right that this codepath is
> > loosing the error, but this does not seem to be the scenario we are
> > running into while loading the firmware. This error only happens later
> > on from the btintel_reset_to_bootloader function.
> >
> > What seems to happen in the posted log is that the URB is initially
> > submitted just fine and the transfer errors out afterwards.
> > Unfortunately, the btusb_tx_complete is only used for statistics
> > (stat.err_tx is increased) and has no further error handling that could
> > abort the firmware upload.
>
> While detecting the errors during URB completion would be nice, it isn't
> necessary. Things would work just as well if the disconnect error were
> detected during submission of the following URB.
Ah, good point. The in-flight interrupt URB responsible of retrieving
the event from the device will fail. It should be sufficient to inject
a hardware error event at that point in order to fix this.
As such, a simple solution may be to call hci_reset_dev from inside
btusb_intr_complete and btusb_submit_intr_urb when the URB submission
fails (for "err != -EPERM").
Benjamin
Hi,
On Wed, 2021-11-03 at 16:11 -0400, Alan Stern wrote:
> On Wed, Nov 03, 2021 at 08:31:03PM +0100, Marcel Holtmann wrote:
> > the problem seems to be that we hitting HCI command timeout. So the
> > firmware download is done via HCI commands. These commands are send to
> > the transport driver btusb.c via hdev->send (as btusb_send_frame).
> > This triggers the usb_submit_urb or queues them via data->deferred
> > anchor. All this reports back the error properly except that nobody
> > does anything with it.
> >
> > See hci_send_frame() last portion:
> >
> > err = hdev->send(hdev, skb);
> > if (err < 0) {
> > bt_dev_err(hdev, "sending frame failed (%d)", err);
> > kfree_skb(skb);
> > }
> >
> > And that is it. We are not checking for ENODEV or any error here. That
> > means the failure of the HCI command gets only caught via the HCI
> > command timeout. I don’t know how to do this yet, but you would have
> > to look there to fail HCI command right away instead of waiting for
> > the timeout.
>
> I have no idea how all the different layers work here. Clearly
> something has to signal hdev->req_wait_q after setting hdev->req_status
> to some appropriate value. Can this be done in btusb.c, either when the
> URB is submitted or when it completes? Or in hci_send_frame?
I submitted
https://patchwork.kernel.org/project/bluetooth/list/?series=577565
for this now.
The patchset pretty much calls hci_req_sync_cancel to set req_status
and signal req_wait_q. Doing this and hooking it up in various location
appears to work reasonably well for the synchronous commands.
Benjamin
PS: The user now reported that TLP is blocking the rfkill switch after
resume. So an good workaround is to just not use TLP.