Bug 172271 - WARNING: CPU: 1 PID: 274 at drivers/base/firmware_class.c:1124 _request_firmware+0x465/0xaf0
Summary: WARNING: CPU: 1 PID: 274 at drivers/base/firmware_class.c:1124 _request_firmw...
Status: NEW
Alias: None
Product: Drivers
Classification: Unclassified
Component: Bluetooth (show other bugs)
Hardware: x86-64 Linux
: P1 low
Assignee: linux-bluetooth@vger.kernel.org
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2016-09-19 21:36 UTC by wolf
Modified: 2017-11-22 03:27 UTC (History)
4 users (show)

See Also:
Kernel Version: 4.7.2
Subsystem:
Regression: No
Bisected commit-id:


Attachments
dmesg (58.69 KB, text/plain)
2017-09-03 17:33 UTC, chr()
Details
dmesg with firmware-loader debugging of two suspend/resume cycle (62.42 KB, text/plain)
2017-11-21 22:11 UTC, chr()
Details

Description wolf 2016-09-19 21:36:08 UTC
Overview: Warning appears in journal after each sleep/wake-up.

Steps to reproduce:

1) Put computer to sleep.
2) Wake up computer.

Actual results:

Following warning appears in journal.

	Sep 16 18:16:41 ts kernel: ------------[ cut here ]------------
	Sep 16 18:16:41 ts kernel: WARNING: CPU: 1 PID: 274 at drivers/base/firmware_class.c:1124 _request_firmware+0x465/0xaf0
	Sep 16 18:16:41 ts kernel: Modules linked in: ipt_MASQUERADE nf_nat_masquerade_ipv4 xfrm_user xfrm_algo iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 xt_addrtype iptable_filter xt_conntrack nf_nat nf_conntrack br_netfilter bridge stp llc nls_iso8859_1 nls_cp437 vfat fat ext4 jbd2 mbcache snd_hda_codec_hdmi intel_rapl snd_hda_codec_realtek intel_soc_dts_thermal arc4 snd_hda_codec_generic intel_powerclamp mousedev joydev coretemp hid_multitouch iTCO_wdt btusb iwlmvm kvm_intel mac80211 btrtl btbcm snd_hda_intel acer_wmi btintel iTCO_vendor_support input_leds snd_hda_codec kvm irqbypass iwlwifi sparse_keymap bluetooth intel_cstate r8169 crc16 led_class pcspkr battery thermal cfg80211 mii snd_hda_core rfkill snd_hwdep snd_pcm snd_timer snd soundcore fjes i2c_hid processor_thermal_device int3403_thermal int340x_thermal_zone
	Sep 16 18:16:41 ts kernel:  intel_soc_dts_iosf int3406_thermal int3400_thermal acpi_thermal_rel hid evdev lpc_ich wmi shpchp tpm_tis tpm spi_pxa2xx_platform ac i2c_designware_platform i2c_i801 i2c_designware_core mac_hid mei_txe mei sch_fq_codel ip_tables x_tables btrfs xor raid6_pq xts gf128mul algif_skcipher af_alg dm_crypt dm_mod sd_mod serio_raw atkbd libps2 crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel cryptd ahci libahci xhci_pci xhci_hcd libata usbcore usb_common scsi_mod i8042 serio i915 video button intel_gtt i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm jitterentropy_rng sha256_ssse3 sha256_generic hmac drbg ansi_cprng
	Sep 16 18:16:41 ts kernel: CPU: 1 PID: 274 Comm: kworker/u9:0 Not tainted 4.7.2-1-ARCH #1
	Sep 16 18:16:41 ts kernel: Hardware name: Acer TravelMate B115-M/Roxy, BIOS V1.22 08/27/2014
	Sep 16 18:16:41 ts kernel: Workqueue: hci0 hci_power_on [bluetooth]
	Sep 16 18:16:41 ts kernel:  0000000000000286 000000009abb2381 ffff880036cb3bb0 ffffffff812eb132
	Sep 16 18:16:41 ts kernel:  0000000000000000 0000000000000000 ffff880036cb3bf0 ffffffff8107a3ab
	Sep 16 18:16:41 ts kernel:  000004648108ef08 ffff880036cb3d10 ffff880036cb3cf8 ffff880076d45ae0
	Sep 16 18:16:41 ts kernel: Call Trace:
	Sep 16 18:16:41 ts kernel:  [<ffffffff812eb132>] dump_stack+0x63/0x81
	Sep 16 18:16:41 ts kernel:  [<ffffffff8107a3ab>] __warn+0xcb/0xf0
	Sep 16 18:16:41 ts kernel:  [<ffffffff8107a4dd>] warn_slowpath_null+0x1d/0x20
	Sep 16 18:16:41 ts kernel:  [<ffffffff8143a5b5>] _request_firmware+0x465/0xaf0
	Sep 16 18:16:41 ts kernel:  [<ffffffff8143ac71>] request_firmware+0x31/0x50
	Sep 16 18:16:41 ts kernel:  [<ffffffffa0873e24>] btusb_setup_intel+0x164/0x660 [btusb]
	Sep 16 18:16:41 ts kernel:  [<ffffffff8142f158>] ? rpm_idle+0x58/0x2b0
	Sep 16 18:16:41 ts kernel:  [<ffffffffa0293460>] ? usb_autopm_put_interface+0x30/0x40 [usbcore]
	Sep 16 18:16:41 ts kernel:  [<ffffffffa067f2a1>] hci_dev_do_open+0x411/0x5a0 [bluetooth]
	Sep 16 18:16:41 ts kernel:  [<ffffffff8102c76f>] ? __switch_to+0x2bf/0x4b0
	Sep 16 18:16:41 ts kernel:  [<ffffffffa0682f0a>] hci_power_on+0x5a/0x240 [bluetooth]
	Sep 16 18:16:41 ts kernel:  [<ffffffff815da5e5>] ? __schedule+0x2f5/0x7a0
	Sep 16 18:16:41 ts kernel:  [<ffffffff81093615>] process_one_work+0x1e5/0x480
	Sep 16 18:16:41 ts kernel:  [<ffffffff810938f8>] worker_thread+0x48/0x4e0
	Sep 16 18:16:41 ts kernel:  [<ffffffff810938b0>] ? process_one_work+0x480/0x480
	Sep 16 18:16:41 ts kernel:  [<ffffffff81099598>] kthread+0xd8/0xf0
	Sep 16 18:16:41 ts kernel:  [<ffffffff815de9bf>] ret_from_fork+0x1f/0x40
	Sep 16 18:16:41 ts kernel:  [<ffffffff810994c0>] ? kthread_worker_fn+0x170/0x170
	Sep 16 18:16:41 ts kernel: ---[ end trace 16f83920a4b80ed2 ]---
	Sep 16 18:16:41 ts kernel: bluetooth hci0: firmware: intel/ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq will not be loaded
	Sep 16 18:16:41 ts kernel: Bluetooth: hci0 failed to open Intel firmware file: intel/ibt-hw-37.7.10-fw-1.80.1.2d.d.bseq(-11)
	Sep 16 18:16:41 ts kernel: ------------[ cut here ]------------
	Sep 16 18:16:41 ts kernel: WARNING: CPU: 1 PID: 274 at drivers/base/firmware_class.c:1124 _request_firmware+0x465/0xaf0
	Sep 16 18:16:41 ts kernel: Modules linked in: ipt_MASQUERADE nf_nat_masquerade_ipv4 xfrm_user xfrm_algo iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 xt_addrtype iptable_filter xt_conntrack nf_nat nf_conntrack br_netfilter bridge stp llc nls_iso8859_1 nls_cp437 vfat fat ext4 jbd2 mbcache snd_hda_codec_hdmi intel_rapl snd_hda_codec_realtek intel_soc_dts_thermal arc4 snd_hda_codec_generic intel_powerclamp mousedev joydev coretemp hid_multitouch iTCO_wdt btusb iwlmvm kvm_intel mac80211 btrtl btbcm snd_hda_intel acer_wmi btintel iTCO_vendor_support input_leds snd_hda_codec kvm irqbypass iwlwifi sparse_keymap bluetooth intel_cstate r8169 crc16 led_class pcspkr battery thermal cfg80211 mii snd_hda_core rfkill snd_hwdep snd_pcm snd_timer snd soundcore fjes i2c_hid processor_thermal_device int3403_thermal int340x_thermal_zone
	Sep 16 18:16:41 ts kernel:  intel_soc_dts_iosf int3406_thermal int3400_thermal acpi_thermal_rel hid evdev lpc_ich wmi shpchp tpm_tis tpm spi_pxa2xx_platform ac i2c_designware_platform i2c_i801 i2c_designware_core mac_hid mei_txe mei sch_fq_codel ip_tables x_tables btrfs xor raid6_pq xts gf128mul algif_skcipher af_alg dm_crypt dm_mod sd_mod serio_raw atkbd libps2 crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel cryptd ahci libahci xhci_pci xhci_hcd libata usbcore usb_common scsi_mod i8042 serio i915 video button intel_gtt i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops drm jitterentropy_rng sha256_ssse3 sha256_generic hmac drbg ansi_cprng
	Sep 16 18:16:41 ts kernel: CPU: 1 PID: 274 Comm: kworker/u9:0 Tainted: G        W       4.7.2-1-ARCH #1
	Sep 16 18:16:41 ts kernel: Hardware name: Acer TravelMate B115-M/Roxy, BIOS V1.22 08/27/2014
	Sep 16 18:16:41 ts kernel: Workqueue: hci0 hci_power_on [bluetooth]
	Sep 16 18:16:41 ts kernel:  0000000000000286 000000009abb2381 ffff880036cb3bb0 ffffffff812eb132
	Sep 16 18:16:41 ts kernel:  0000000000000000 0000000000000000 ffff880036cb3bf0 ffffffff8107a3ab
	Sep 16 18:16:41 ts kernel:  000004648108ef08 ffff880036cb3d10 ffff880036cb3cf8 ffff880076d45ae0
	Sep 16 18:16:41 ts kernel: Call Trace:
	Sep 16 18:16:41 ts kernel:  [<ffffffff812eb132>] dump_stack+0x63/0x81
	Sep 16 18:16:41 ts kernel:  [<ffffffff8107a3ab>] __warn+0xcb/0xf0
	Sep 16 18:16:41 ts kernel:  [<ffffffff8107a4dd>] warn_slowpath_null+0x1d/0x20
	Sep 16 18:16:41 ts kernel:  [<ffffffff8143a5b5>] _request_firmware+0x465/0xaf0
	Sep 16 18:16:41 ts kernel:  [<ffffffff8143ac71>] request_firmware+0x31/0x50
	Sep 16 18:16:41 ts kernel:  [<ffffffffa087411c>] btusb_setup_intel+0x45c/0x660 [btusb]
	Sep 16 18:16:41 ts kernel:  [<ffffffff8142f158>] ? rpm_idle+0x58/0x2b0
	Sep 16 18:16:41 ts kernel:  [<ffffffffa0293460>] ? usb_autopm_put_interface+0x30/0x40 [usbcore]
	Sep 16 18:16:41 ts kernel:  [<ffffffffa067f2a1>] hci_dev_do_open+0x411/0x5a0 [bluetooth]
	Sep 16 18:16:41 ts kernel:  [<ffffffff8102c76f>] ? __switch_to+0x2bf/0x4b0
	Sep 16 18:16:41 ts kernel:  [<ffffffffa0682f0a>] hci_power_on+0x5a/0x240 [bluetooth]
	Sep 16 18:16:41 ts kernel:  [<ffffffff815da5e5>] ? __schedule+0x2f5/0x7a0
	Sep 16 18:16:41 ts kernel:  [<ffffffff81093615>] process_one_work+0x1e5/0x480
	Sep 16 18:16:41 ts kernel:  [<ffffffff810938f8>] worker_thread+0x48/0x4e0
	Sep 16 18:16:41 ts kernel:  [<ffffffff810938b0>] ? process_one_work+0x480/0x480
	Sep 16 18:16:41 ts kernel:  [<ffffffff81099598>] kthread+0xd8/0xf0
	Sep 16 18:16:41 ts kernel:  [<ffffffff815de9bf>] ret_from_fork+0x1f/0x40
	Sep 16 18:16:41 ts kernel:  [<ffffffff810994c0>] ? kthread_worker_fn+0x170/0x170
	Sep 16 18:16:41 ts kernel: ---[ end trace 16f83920a4b80ed3 ]---
	Sep 16 18:16:41 ts kernel: bluetooth hci0: firmware: intel/ibt-hw-37.7.bseq will not be loaded
	Sep 16 18:16:41 ts kernel: Bluetooth: hci0 failed to open default Intel fw file: intel/ibt-hw-37.7.bseq

Expected result:

No warning produced.

Build & Hardware:

Archlinux kernel 4.7.2-1

$ lspci
00:00.0 Host bridge: Intel Corporation Atom Processor Z36xxx/Z37xxx Series SoC Transaction Register (rev 0e)
00:02.0 VGA compatible controller: Intel Corporation Atom Processor Z36xxx/Z37xxx Series Graphics & Display (rev 0e)
00:13.0 SATA controller: Intel Corporation Atom Processor E3800 Series SATA AHCI Controller (rev 0e)
00:14.0 USB controller: Intel Corporation Atom Processor Z36xxx/Z37xxx, Celeron N2000 Series USB xHCI (rev 0e)
00:1a.0 Encryption controller: Intel Corporation Atom Processor Z36xxx/Z37xxx Series Trusted Execution Engine (rev 0e)
00:1b.0 Audio device: Intel Corporation Atom Processor Z36xxx/Z37xxx Series High Definition Audio Controller (rev 0e)
00:1c.0 PCI bridge: Intel Corporation Atom Processor E3800 Series PCI Express Root Port 1 (rev 0e)
00:1c.1 PCI bridge: Intel Corporation Atom Processor E3800 Series PCI Express Root Port 2 (rev 0e)
00:1c.2 PCI bridge: Intel Corporation Atom Processor E3800 Series PCI Express Root Port 3 (rev 0e)
00:1f.0 ISA bridge: Intel Corporation Atom Processor Z36xxx/Z37xxx Series Power Control Unit (rev 0e)
00:1f.3 SMBus: Intel Corporation Atom Processor E3800 Series SMBus Controller (rev 0e)
02:00.0 Network controller: Intel Corporation Wireless 7260 (rev bb)
03:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168/8411 PCI Express Gigabit Ethernet Controller (rev 0c)



This is my first kernel bug report, so please don't get mad if something is missing/wrong.. :)
Comment 1 chr() 2017-09-03 17:31:13 UTC
Hi,

I was stuck with my netbook not resuming from suspend over the night. However, just after using a bluetooth once, and suspending for 5 seconds, I'll get the same mess.

Fresh boot up, suspend and resume works but:

[   97.397129] PM: resume of devices complete after 1018.677 msecs
[   97.397248] usb 1-5:1.0: rebind failed: -517
[   97.397272] usb 1-5:1.1: rebind failed: -517
[   97.427357] Bluetooth: hci0: read Intel version: 370810011003110e00
[   97.427373] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.8.10-fw-1.
[   97.470484] PM: Finishing wakeup.

Connect a bluetooth device, suspend and resume

Bluetooth: hci0 failed to open Intel firmware file: intel/ibt-hw-37.8.10-fw-1.10.3.11.e.bseq(-11)

Punchline: bluetooth still working after some seconds of suspend, but it locks up in the morning, suspended over the night.
Comment 2 chr() 2017-09-03 17:33:57 UTC
Created attachment 258177 [details]
dmesg

* fresh boot,
* suspend, resume,
* use bt device
* suspend resume again
Comment 3 Kai-Heng Feng 2017-09-21 08:14:07 UTC
Please give these two patch series a try:

https://lkml.org/lkml/2017/8/22/123
https://lkml.org/lkml/2017/8/25/58
Comment 4 chr() 2017-09-22 00:08:54 UTC
(In reply to Kai-Heng Feng from comment #3)
> Please give these two patch series a try:
> 
> https://lkml.org/lkml/2017/8/22/123
> https://lkml.org/lkml/2017/8/25/58

Hi,

thanks for the work.

I applied these patches on 4.9.50. The machine locks up on the way to suspend :(

Actually I was hardly able to reproduce this issue as easy as before, even with the 4.9.46.
It should be noted there was an update of the bluez package meanwhile ("BlueBorne" flaw).

As long the firmware loading happens after "Restarting tasks ... done" we're fine but still there is a chance to brick the machine on resume (1 of 20 tries).
Comment 5 Kai-Heng Feng 2017-09-22 01:41:01 UTC
(In reply to chr() from comment #4)
> (In reply to Kai-Heng Feng from comment #3)
> > Please give these two patch series a try:
> > 
> > https://lkml.org/lkml/2017/8/22/123
> > https://lkml.org/lkml/2017/8/25/58
> 
> Hi,
> 
> thanks for the work.
> 
> I applied these patches on 4.9.50. The machine locks up on the way to
> suspend :(

The patches should apply to mainline. I didn't test it on 4.9.

> 
> Actually I was hardly able to reproduce this issue as easy as before, even
> with the 4.9.46.
> It should be noted there was an update of the bluez package meanwhile
> ("BlueBorne" flaw).

This is a kernel bug, it shouldn't have anything to do with BlueZ.

> 
> As long the firmware loading happens after "Restarting tasks ... done" we're
> fine but still there is a chance to brick the machine on resume (1 of 20
> tries).

Probably try it on top of mainline?
Comment 6 chr() 2017-11-21 22:11:38 UTC
Created attachment 260775 [details]
dmesg with firmware-loader debugging of two suspend/resume cycle

Hi!

I was reading this:

btusb "firmware request while host is not available" at resume
https://lkml.org/lkml/2017/9/11/370

and I turned on the debugging of the firmware loader to check the caching.

The firmware cache works once but on second suspend it fails.

On the first resume there's an usb reset(!) and a call to fw_name_devm_release.
So on the second suspend the bt-firmware isn't loaded to the cache, resume Oops.
Comment 7 Kai-Heng Feng 2017-11-22 03:27:28 UTC
It should be solved in v4.14.

Note You need to log in before you can comment on or make changes to this bug.