Re: bluetooth related firmware loader spew on resume.

[Takashi Iwai <tiwai@suse.de>]

At Wed, 26 Nov 2014 14:15:27 +0900,
Marcel Holtmann wrote:
> 
> Hi Takashi,
> 
> >> Since the addition of 10d4c6736ea "Bluetooth: btusb: Add Broadcom patch
> >> RAM support", I (and a number of other people[*]) have been seeing
> >> this trace on resume from suspend.
> >> 
> >> WARNING: CPU: 1 PID: 8565 at drivers/base/firmware_class.c:1127 _request_firmware+0x4c1/0x7c0()
> >> CPU: 1 PID: 8565 Comm: kworker/u17:0 Not tainted 3.17.2-200.fc20.x86_64 #1
> >> Hardware name: LENOVO 2356JK8/2356JK8, BIOS G7ET94WW (2.54 ) 04/30/2013
> >> Workqueue: hci0 hci_power_on [bluetooth]
> >> 0000000000000000 00000000f52a564b ffff8800a8c63be8 ffffffff817271cc
> >> 0000000000000000 ffff8800a8c63c20 ffffffff81094ced ffff8800a8c63d10
> >> ffff8801365ddf00 ffff8801387b4b00 ffff8800a8c63d08 00000000fffffff5
> >> Call Trace:
> >> [<ffffffff817271cc>] dump_stack+0x45/0x56
> >> [<ffffffff81094ced>] warn_slowpath_common+0x7d/0xa0
> >> [<ffffffff81094e1a>] warn_slowpath_null+0x1a/0x20
> >> [<ffffffff814965c1>] _request_firmware+0x4c1/0x7c0
> >> [<ffffffff8137b9b9>] ? snprintf+0x49/0x70
> >> [<ffffffff814968f1>] request_firmware+0x31/0x50
> >> [<ffffffffa0943bf3>] btusb_setup_bcm_patchram+0x83/0x550 [btusb]
> >> [<ffffffff8148ecf6>] ? rpm_idle+0xd6/0x2b0
> >> [<ffffffffa0649051>] hci_dev_do_open+0xe1/0xa60 [bluetooth]
> >> ACPI: \_SB_.PCI0.LPC_.EC__.BAT1: docking
> >> Restarting tasks ... 
> >> [<ffffffff810bcb3d>] ? ttwu_do_activate.constprop.90+0x5d/0x70
> >> [<ffffffffa064a1c0>] hci_power_on+0x40/0x1e0 [bluetooth]
> >> [<ffffffff810f53fb>] ? lock_timer_base.isra.34+0x2b/0x50
> >> [<ffffffff810acc39>] process_one_work+0x149/0x3d0
> >> [<ffffffff810ad2bb>] worker_thread+0x11b/0x490
> >> [<ffffffff810ad1a0>] ? rescuer_thread+0x2e0/0x2e0
> >> [<ffffffff810b2318>] kthread+0xd8/0xf0
> >> [<ffffffff810b2240>] ? kthread_create_on_node+0x190/0x190
> >> [<ffffffff8172e7bc>] ret_from_fork+0x7c/0xb0
> >> [<ffffffff810b2240>] ? kthread_create_on_node+0x190/0x190
> >> ---[ end trace 75a0e9c7f33ebb4c ]---
> >> bluetooth hci0: firmware: brcm/BCM20702A0-0a5c-21e6.hcd will not be loaded
> >> Bluetooth: hci0: BCM: patch brcm/BCM20702A0-0a5c-21e6.hcd not found
> >> 
> >> 
> >> At first I thought it was just over-reaction to the file being missing, but
> >> looking at the WARN_ON, it appears that we're trying to invoke the firmware
> >> loader before userspace is back up ?
> >> 
> >> In this (and probably other related) kernel, CONFIG_FW_LOADER_USER_HELPER is unset,
> >> in case that matters at all.
> > 
> > If it's the case where no matching firmware file is present, the patch
> > below might help.  It's only compile-tested.
> > 
> > 
> > Takashi
> > 
> > -- 8< --
> > From: Takashi Iwai <tiwai@suse.de>
> > Subject: [PATCH] btusb: Give up firmware loading once when failed
> > 
> > Otherwise it may trigger request_firmware() for the non-existing file
> > in the resume path, resulting in a warning.  For the success paths,
> > calling request_firmware() is fine, as it's cached properly at
> > suspend.  The problem is only for the error paths.
> > 
> > Signed-off-by: Takashi Iwai <tiwai@suse.de>
> > ---
> > drivers/bluetooth/btusb.c | 2 ++
> > 1 file changed, 2 insertions(+)
> > 
> > diff --git a/drivers/bluetooth/btusb.c b/drivers/bluetooth/btusb.c
> > index edfc17bfcd44..62d8e23fd3cb 100644
> > --- a/drivers/bluetooth/btusb.c
> > +++ b/drivers/bluetooth/btusb.c
> > @@ -1569,6 +1569,7 @@ static int btusb_setup_intel(struct hci_dev *hdev)
> > 	if (!fw) {
> > 		kfree_skb(skb);
> > 		btusb_check_bdaddr_intel(hdev);
> > +		hdev->setup = NULL;
> > 		return 0;
> > 	}
> > 	fw_ptr = fw->data;
> > @@ -1756,6 +1757,7 @@ static int btusb_setup_bcm_patchram(struct hci_dev *hdev)
> > 	ret = request_firmware(&fw, fw_name, &hdev->dev);
> > 	if (ret < 0) {
> > 		BT_INFO("%s: BCM: patch %s not found", hdev->name, fw_name);
> > +		hdev->setup = NULL;
> > 		return 0;
> > 	}
> 
> the hdev->setup callback is only called once for each new device found. This means that setting it back to NULL from the its own handler is not making any difference.

Indeed.  I misread the messages.

> Also the problem is that hdev->setup is really there to load firmware. Devices might work without the firmware, but then they run off an old ROM firmware which is not a good idea in most cases. So we can not just close our eyes and hope for the best. The firmware should really be loaded.
> 
> I think the problem is that the devices physically disappear from the USB bus during suspend and will show up as a newly attached device after resume. So we have the cold plug case here. And there we need to firmware. Plain and simple. As stated above hdev->setup is only after run once. The only way to run it a second time is by unplugging and replugging the device. A BIOS that takes the power of the Bluetooth USB device is essentially simulating this behavior.
> 
> We are seeing a hci_power_on call since that is triggered exactly once when the device is plugged in. If we wanted to be super smart, then we could delay that initial call until the first userspace opens any Bluetooth socket. In theory that would work, but could be also way to complicated to realized. However it would mean the initial firmware loading and setup of the device is delayed until bluetoothd has been started. For bluetoothd this will be not a problem since it can handle hotplug of Bluetooth controllers, but for all other command line tools it might be a real problem. 

Actually, there are a few other issues behind the scene:

- This warning happens only when the firmware loading fails.
  If the firmware was successfully loaded *before* suspend, the f/w
  loader retries to load the firmware and cache it at suspend and use
  it at resume in return.

- The usermodehelper_read_trylock() should be blocked at resume, but
  by some reason it didn't work.
  I thought I closed the race in the commit 4320f6b1d9db, but it seems
  incomplete or yet buggy.  Hmm..

In order to paper over this, we may also remember the failing firmware
and avoid loading it.  This might be an easer way than the endless
fight against UMH race...


Takashi