Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Chris Murphy]

Found this thread google searching.


4.13.0-0.rc4.git1.1.fc27.x86_64  Problem sometimes happens with this kernel.
This translates to git 623ce3456671.

4.13.0-0.rc3.git0.1.fc27.x86_64 But not this kernel, which translates
to the actual rc3 release (clean).

It seems to be a regression between those two. The problem only
happens when waking from suspend to RAM, but it doesn't always happen.


    Product Name: HP Spectre Notebook
    SKU Number: W2K28UA#ABA


dmesg, with bluetooth firmware warning and call trace only
https://drive.google.com/open?id=0B_2Asp8DGjJ9eDFsbHNMelVzelE

dmesg, normal boot
https://drive.google.com/open?id=0B_2Asp8DGjJ9X3gzYTdTNE4ydm8


-- 
Chris Murphy

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Kai-Heng Feng]

On Wed, Aug 16, 2017 at 11:26 PM, Chris Murphy <chris@colorremedies.com> wrote:
> Found this thread google searching.
>
>
> 4.13.0-0.rc4.git1.1.fc27.x86_64  Problem sometimes happens with this kernel.
> This translates to git 623ce3456671.
>
> 4.13.0-0.rc3.git0.1.fc27.x86_64 But not this kernel, which translates
> to the actual rc3 release (clean).
>
> It seems to be a regression between those two. The problem only
> happens when waking from suspend to RAM, but it doesn't always happen.

My theory is that if you request firmware when firmware_class is in
cache mode consecutively, and the device is changed, you will hit this
issue.
Can you give this patch a try?

diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
index bfbe1e154128..910dce498f53 100644
--- a/drivers/base/firmware_class.c
+++ b/drivers/base/firmware_class.c
@@ -1177,6 +1177,9 @@ _request_firmware_prepare(struct firmware
**firmware_p, const char *name,

        ret = fw_lookup_and_allocate_buf(name, &fw_cache, &buf, dbuf, size);

+       if (!firmware_enabled() && device && (ret == 0 || ret == 1))
+               fw_add_devm_name(device, buf->fw_id);
+
        /*
         * bind with 'buf' now to avoid warning in failure path
         * of requesting firmware.


>
>
>     Product Name: HP Spectre Notebook
>     SKU Number: W2K28UA#ABA
>
>
> dmesg, with bluetooth firmware warning and call trace only
> https://drive.google.com/open?id=0B_2Asp8DGjJ9eDFsbHNMelVzelE
>
> dmesg, normal boot
> https://drive.google.com/open?id=0B_2Asp8DGjJ9X3gzYTdTNE4ydm8
>
>
> --
> Chris Murphy
> --
> To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Marcel Holtmann]

Hi Kai-Heng,

>> Found this thread google searching.
>> 
>> 
>> 4.13.0-0.rc4.git1.1.fc27.x86_64  Problem sometimes happens with this kernel.
>> This translates to git 623ce3456671.
>> 
>> 4.13.0-0.rc3.git0.1.fc27.x86_64 But not this kernel, which translates
>> to the actual rc3 release (clean).
>> 
>> It seems to be a regression between those two. The problem only
>> happens when waking from suspend to RAM, but it doesn't always happen.
> 
> My theory is that if you request firmware when firmware_class is in
> cache mode consecutively, and the device is changed, you will hit this
> issue.
> Can you give this patch a try?
> 
> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
> index bfbe1e154128..910dce498f53 100644
> --- a/drivers/base/firmware_class.c
> +++ b/drivers/base/firmware_class.c
> @@ -1177,6 +1177,9 @@ _request_firmware_prepare(struct firmware
> **firmware_p, const char *name,
> 
>        ret = fw_lookup_and_allocate_buf(name, &fw_cache, &buf, dbuf, size);
> 
> +       if (!firmware_enabled() && device && (ret == 0 || ret == 1))
> +               fw_add_devm_name(device, buf->fw_id);
> +
>        /*
>         * bind with 'buf' now to avoid warning in failure path
>         * of requesting firmware.

if a fix in firmware_class can handle this, then I assume we also do not need all the per driver / hardware workarounds for firmware caching? Or are these other patches also needed?

Regards

Marcel

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Kai-Heng Feng]

Hi Marcel,

On Mon, Aug 28, 2017 at 10:17 PM, Marcel Holtmann <marcel@holtmann.org> wrote:
> Hi Kai-Heng,
>
>>
>> My theory is that if you request firmware when firmware_class is in
>> cache mode consecutively, and the device is changed, you will hit this
>> issue.
>> Can you give this patch a try?
>>
>> diff --git a/drivers/base/firmware_class.c b/drivers/base/firmware_class.c
>> index bfbe1e154128..910dce498f53 100644
>> --- a/drivers/base/firmware_class.c
>> +++ b/drivers/base/firmware_class.c
>> @@ -1177,6 +1177,9 @@ _request_firmware_prepare(struct firmware
>> **firmware_p, const char *name,
>>
>>        ret = fw_lookup_and_allocate_buf(name, &fw_cache, &buf, dbuf, size);
>>
>> +       if (!firmware_enabled() && device && (ret == 0 || ret == 1))
>> +               fw_add_devm_name(device, buf->fw_id);
>> +
>>        /*
>>         * bind with 'buf' now to avoid warning in failure path
>>         * of requesting firmware.
>
> if a fix in firmware_class can handle this, then I assume we also do not need all the per driver / hardware workarounds for firmware caching? Or are these other patches also needed?

There are two issues:
The first one, which can be quite easily to reproduce after a warm
boot, is similar to this one.

The driver checks the update status of the device which is always on
during reboot, finds that it's already updated hence no need for
firmware, happily ends the setup function after that.
In this case, request_firmware() never gets called, so firmware_class
doesn't know the firmware is required for caching.
My patches for btusb.c/ath3k.c is to address this issue.
I just find out that btusb_setup_intel_new() also skips calling
request_firmware(), so I should send new patches to address the issue.


The second case [1], which is a corner case, is found when I ran some
stress tests for the first case. The scenario is like this:
1. The driver called request_firmware(). firmware_request() calls
fw_add_devm_name() to add the firmware name to device's revres.
2. After system suspends/resumes, the device might be treated as a new device.
3. request_firmware() can find the firmware because it's in the cache.
But fw_add_devm_name() for the new 'device' is not being called.
4. The second time system suspends, the firmware will not be cached
because the firmware name is not in the devres list anymore.
5. The system resumes, request_firmware() cannot find firmware in the
cache, hit the WARN_ON.

So these two patches are for separate issues.

[1] https://lkml.org/lkml/2017/8/22/123

>
> Regards
>
> Marcel
>

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Kai-Heng Feng]

Hi Marcel,

On Tue, Aug 29, 2017 at 2:59 AM, Kai-Heng Feng
<kai.heng.feng@canonical.com> wrote:
> Hi Marcel,
>
> On Mon, Aug 28, 2017 at 10:17 PM, Marcel Holtmann <marcel@holtmann.org> wrote:
>> Hi Kai-Heng,
>>
>>
>> if a fix in firmware_class can handle this, then I assume we also do not need all the per driver / hardware workarounds for firmware caching? Or are these other patches also needed?
>
> There are two issues:
> The first one, which can be quite easily to reproduce after a warm
> boot, is similar to this one.
>
> The driver checks the update status of the device which is always on
> during reboot, finds that it's already updated hence no need for
> firmware, happily ends the setup function after that.
> In this case, request_firmware() never gets called, so firmware_class
> doesn't know the firmware is required for caching.
> My patches for btusb.c/ath3k.c is to address this issue.
> I just find out that btusb_setup_intel_new() also skips calling
> request_firmware(), so I should send new patches to address the issue.
>
>
> The second case [1], which is a corner case, is found when I ran some
> stress tests for the first case. The scenario is like this:
> 1. The driver called request_firmware(). firmware_request() calls
> fw_add_devm_name() to add the firmware name to device's revres.
> 2. After system suspends/resumes, the device might be treated as a new device.
> 3. request_firmware() can find the firmware because it's in the cache.
> But fw_add_devm_name() for the new 'device' is not being called.
> 4. The second time system suspends, the firmware will not be cached
> because the firmware name is not in the devres list anymore.
> 5. The system resumes, request_firmware() cannot find firmware in the
> cache, hit the WARN_ON.
>
> So these two patches are for separate issues.
>
> [1] https://lkml.org/lkml/2017/8/22/123

Does the explanation make the situation clear?
Do you any concern about the approach?

>
>>
>> Regards
>>
>> Marcel
>>

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Vlastimil Babka]

On 08/28/2017 02:45 PM, Vlastimil Babka wrote:
> On 08/28/2017 01:50 PM, Vlastimil Babka wrote:
>> On 08/15/2017 01:41 PM, Richard Weinberger wrote:
>>> Marcel,
>>>
>>> Am Dienstag, 15. August 2017, 12:22:27 CEST schrieb Marcel Holtmann:
>>>>> Is this known?
>>>>
>>>> It is not known, but it is also unclear why this happens. Basically the card
>>>> looses power and thus ends up in bootloader mode.
>>>>
>>>
>>> Hm, maybe a BIOS issue?
>>
>> Same here on a T460, also happens on resume from suspend to RAM. Looks
>> like a regression though. First instance I found in the logs is from
>> 4.13-rc2. Looks like previously I've been running 4.11, and managed to
>> skip 4.12 on this laptop. Can check 4.12, though.
> 
> Yep, seems to work on 4.12.8, this after resume:
> 
> [  178.837204] PM: Finishing wakeup.
> [  178.837207] OOM killer enabled.
> [  178.837211] Restarting tasks ... done.
> [  178.844792] thermal thermal_zone3: failed to read out thermal zone (-5)
> [  178.849009] [drm] RC6 on
> [  178.851064] Bluetooth: hci0: Bootloader revision 0.0 build 2 week 52 2014
> [  178.858072] Bluetooth: hci0: Device revision is 5
> [  178.858076] Bluetooth: hci0: Secure boot is enabled
> [  178.858077] Bluetooth: hci0: OTP lock is enabled
> [  178.858078] Bluetooth: hci0: API lock is enabled
> [  178.858078] Bluetooth: hci0: Debug lock is disabled
> [  178.858079] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
> [  178.858082] Bluetooth: hci0: Found device firmware: intel/ibt-11-5.sfi
> 
> ...
> 
> [  180.402942] Bluetooth: hci0: Waiting for firmware download to complete
> [  180.403039] Bluetooth: hci0: Firmware loaded in 1516730 usecs
> [  180.403048] Bluetooth: hci0: Waiting for device to boot
> [  180.414070] Bluetooth: hci0: Device booted in 10769 usecs
> [  180.414074] Bluetooth: hci0: Found Intel DDC parameters: intel/ibt-11-5.ddc
> [  180.418111] Bluetooth: hci0: Applying Intel DDC parameters completed

And for completeness, 4.13 from my laptop:

[   76.875780] PM: Finishing wakeup.
[   76.875783] OOM killer enabled.
[   76.875789] Restarting tasks ... 
[   76.876808] Bluetooth: hci0: Bootloader revision 0.0 build 2 week 52 2014
[   76.883842] Bluetooth: hci0: Device revision is 5
[   76.883852] Bluetooth: hci0: Secure boot is enabled
[   76.883857] Bluetooth: hci0: OTP lock is enabled
[   76.883861] Bluetooth: hci0: API lock is enabled
[   76.883865] Bluetooth: hci0: Debug lock is disabled
[   76.883870] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[   76.883879] firmware request while host is not available
[   76.883911] ------------[ cut here ]------------
[   76.883927] WARNING: CPU: 0 PID: 2760 at ../drivers/base/firmware_class.c:1243 _request_firmware+0x409/0x8e0
[   76.883931] Modules linked in: ccm rfcomm af_packet nf_log_ipv6 xt_comment nf_log_ipv4 nf_log_common xt_LOG xt_limit ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 ipt_REJECT nf_reject_ipv4 xt_pkttype xt_tcpudp iptable_filter ip6table_mangle nf_conntrack_ipv4 nf_defrag_ipv4 ip_tables xt_conntrack nf_conntrack libcrc32c ip6table_filter ip6_tables x_tables bnep msr dm_crypt algif_skcipher af_alg btusb uvcvideo btrtl videobuf2_vmalloc btbcm videobuf2_memops btintel videobuf2_v4l2 videobuf2_core videodev bluetooth ecdh_generic arc4 snd_hda_codec_hdmi snd_hda_codec_realtek intel_rapl snd_hda_codec_generic x86_pkg_temp_thermal intel_powerclamp snd_soc_skl coretemp snd_soc_skl_ipc snd_soc_sst_ipc snd_soc_sst_dsp snd_hda_ext_core kvm_intel snd_soc_sst_match snd_soc_core snd_compress kvm snd_pcm_dmaengine
[   76.884034]  irqbypass nls_iso8859_1 crct10dif_pclmul nls_cp437 crc32_pclmul vfat dm_mod fat ghash_clmulni_intel pcbc iwlmvm snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep mac80211 iTCO_wdt snd_pcm iTCO_vendor_support wmi_bmof mei_wdt snd_timer iwlwifi aesni_intel aes_x86_64 crypto_simd thinkpad_acpi glue_helper cryptd rtsx_pci_ms snd cfg80211 e1000e ptp memstick tpm_tis pcspkr joydev i2c_i801 tpm_tis_core pps_core soundcore shpchp tpm rfkill battery thermal ac wmi mei_me mei intel_pch_thermal btrfs xor rtsx_pci_sdmmc mmc_core raid6_pq crc32c_intel i915 xhci_pci xhci_hcd i2c_algo_bit serio_raw drm_kms_helper syscopyarea sysfillrect sysimgblt rtsx_pci fb_sys_fops video button drm usbcore sg efivarfs
[   76.884154] CPU: 0 PID: 2760 Comm: kworker/u9:4 Not tainted 4.13.0-rc6-2.g43edc52-default #1
[   76.884159] Hardware name: LENOVO 20FMS27W03/20FMS27W03, BIOS R06ET42W (1.16 ) 09/20/2016
[   76.884203] Workqueue: hci0 hci_power_on [bluetooth]
[   76.884210] task: ffff916ffa7fc0c0 task.stack: ffff9f260314c000
[   76.884222] RIP: 0010:_request_firmware+0x409/0x8e0
[   76.884227] RSP: 0000:ffff9f260314fcd0 EFLAGS: 00010286
[   76.884234] RAX: 000000000000002c RBX: ffff9f260314fd88 RCX: 0000000000000006
[   76.884239] RDX: 0000000000000007 RSI: 0000000000000082 RDI: ffff91706140e290
[   76.884244] RBP: ffff9f260314fd70 R08: 0000000000000000 R09: 00000000000003b7
[   76.884249] R10: ffff9f260314fcc0 R11: ffffffff8f4b022d R12: ffff9170469d3800
[   76.884253] R13: ffff917057217900 R14: ffff917057217908 R15: ffff9170475ae3c8
[   76.884259] FS:  0000000000000000(0000) GS:ffff917061400000(0000) knlGS:0000000000000000
[   76.884265] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   76.884270] CR2: 00005589d52fc000 CR3: 0000000217cbd000 CR4: 00000000003406f0
[   76.884274] Call Trace:
[   76.884289]  ? snprintf+0x36/0x40
[   76.884300]  request_firmware+0x32/0x50
[   76.884313]  btusb_setup_intel_new+0x206/0x750 [btusb]
[   76.884323]  ? __pm_runtime_idle+0x48/0x60
[   76.884363]  hci_dev_do_open+0x3ac/0x540 [bluetooth]
[   76.884375]  ? finish_task_switch+0x75/0x200
[   76.884410]  hci_power_on+0x3e/0x1e0 [bluetooth]
[   76.884419]  ? __schedule+0x286/0x880
[   76.884427]  process_one_work+0x17c/0x3b0
[   76.884436]  worker_thread+0x4a/0x390
[   76.884444]  ? process_one_work+0x3b0/0x3b0
[   76.884453]  kthread+0x118/0x130
[   76.884462]  ? kthread_create_on_node+0x40/0x40
[   76.884471]  ret_from_fork+0x25/0x30
[   76.884479] Code: 08 49 83 fd 28 74 4c 49 8b 8d 60 c9 88 8e e9 36 ff ff ff 48 c7 c7 e0 01 ef 8e e8 93 10 20 00 48 c7 c7 18 fd a9 8e e8 12 61 b7 ff <0f> ff 41 bd 90 ff ff ff 49 8b 7c 24 18 e9 45 fd ff ff 48 c7 44 
[   76.884577] ---[ end trace 513808fe832cf154 ]---
[   76.884586] Bluetooth: hci0: Failed to load Intel firmware file (-112)
[   76.887685] done.
[   76.891479] [drm] RC6 on
[   76.894256] thermal thermal_zone3: failed to read out thermal zone (-5)

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Vlastimil Babka]

On 08/28/2017 01:50 PM, Vlastimil Babka wrote:
> On 08/15/2017 01:41 PM, Richard Weinberger wrote:
>> Marcel,
>>
>> Am Dienstag, 15. August 2017, 12:22:27 CEST schrieb Marcel Holtmann:
>>>> Is this known?
>>>
>>> It is not known, but it is also unclear why this happens. Basically the card
>>> looses power and thus ends up in bootloader mode.
>>>
>>
>> Hm, maybe a BIOS issue?
> 
> Same here on a T460, also happens on resume from suspend to RAM. Looks
> like a regression though. First instance I found in the logs is from
> 4.13-rc2. Looks like previously I've been running 4.11, and managed to
> skip 4.12 on this laptop. Can check 4.12, though.

Yep, seems to work on 4.12.8, this after resume:

[  178.837204] PM: Finishing wakeup.
[  178.837207] OOM killer enabled.
[  178.837211] Restarting tasks ... done.
[  178.844792] thermal thermal_zone3: failed to read out thermal zone (-5)
[  178.849009] [drm] RC6 on
[  178.851064] Bluetooth: hci0: Bootloader revision 0.0 build 2 week 52 2014
[  178.858072] Bluetooth: hci0: Device revision is 5
[  178.858076] Bluetooth: hci0: Secure boot is enabled
[  178.858077] Bluetooth: hci0: OTP lock is enabled
[  178.858078] Bluetooth: hci0: API lock is enabled
[  178.858078] Bluetooth: hci0: Debug lock is disabled
[  178.858079] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[  178.858082] Bluetooth: hci0: Found device firmware: intel/ibt-11-5.sfi

...

[  180.402942] Bluetooth: hci0: Waiting for firmware download to complete
[  180.403039] Bluetooth: hci0: Firmware loaded in 1516730 usecs
[  180.403048] Bluetooth: hci0: Waiting for device to boot
[  180.414070] Bluetooth: hci0: Device booted in 10769 usecs
[  180.414074] Bluetooth: hci0: Found Intel DDC parameters: intel/ibt-11-5.ddc
[  180.418111] Bluetooth: hci0: Applying Intel DDC parameters completed

>> Thanks,
>> //richard
>>
> 

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Vlastimil Babka]

On 08/15/2017 01:41 PM, Richard Weinberger wrote:
> Marcel,
> 
> Am Dienstag, 15. August 2017, 12:22:27 CEST schrieb Marcel Holtmann:
>>> Is this known?
>>
>> It is not known, but it is also unclear why this happens. Basically the card
>> looses power and thus ends up in bootloader mode.
>>
> 
> Hm, maybe a BIOS issue?

Same here on a T460, also happens on resume from suspend to RAM. Looks
like a regression though. First instance I found in the logs is from
4.13-rc2. Looks like previously I've been running 4.11, and managed to
skip 4.12 on this laptop. Can check 4.12, though.

> Thanks,
> //richard
> 

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Richard Weinberger]

Marcel,

Am Dienstag, 15. August 2017, 12:22:27 CEST schrieb Marcel Holtmann:
> > Is this known?
> 
> It is not known, but it is also unclear why this happens. Basically the card
> looses power and thus ends up in bootloader mode.
> 

Hm, maybe a BIOS issue?

Thanks,
//richard

-- 
sigma star gmbh - Eduard-Bodem-Gasse 6 - 6020 Innsbruck - Austria
ATU66964118 - FN 374287y

Re: WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Marcel Holtmann]

Hi Richard,

> My new Thinkpad T470p regularly triggers this warning.
> Seems to happy only after resuming from suspend.
> 
> [147242.220708] PM: Finishing wakeup.
> [147242.220711] OOM killer enabled.
> [147242.220711] Restarting tasks ... 
> [147242.221908] Bluetooth: hci0: Bootloader revision 0.0 build 26 week 38 2015
> [147242.222888] [drm] RC6 on
> [147242.227695] Bluetooth: hci0: Device revision is 16
> [147242.227696] Bluetooth: hci0: Secure boot is enabled
> [147242.227697] Bluetooth: hci0: OTP lock is enabled
> [147242.227697] Bluetooth: hci0: API lock is enabled
> [147242.227698] Bluetooth: hci0: Debug lock is disabled
> [147242.227698] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
> [147242.227701] firmware request while host is not available

seems like the hardware looses power and has to do a full reload of the firmware. Why the firmware is not cached or why the Bluetooth controller looses its power is unclear to me.

> [147242.227708] ------------[ cut here ]------------
> [147242.227713] WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890
> [147242.227713] Modules linked in: rndis_wlan rndis_host cdc_ether cdc_phonet usbnet phonet mii cdc_acm nls_utf8 udf crc_itu_t msr fuse tun ppp_deflate bsd_comp ppp_async ppp_generic slhc sr_mod cdrom uas usb_storage option usb_wwan usbserial ctr ccm rfcomm nf_log_ipv6 xt_comment nf_log_ipv4 nf_log_common xt_LOG xt_limit af_packet binfmt_misc ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 ipt_REJECT nf_reject_ipv4 xt_pkttype xt_tcpudp iptable_filter ip6table_mangle nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_ipv4 nf_defrag_ipv4 ip_tables xt_conntrack nf_conntrack libcrc32c ip6table_filter ip6_tables x_tables bnep snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic arc4 btusb hci_uart btrtl btbcm btqca btintel bluetooth snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep
> [147242.227739]  snd_pcm iwlmvm mac80211 snd_timer intel_rapl x86_pkg_temp_thermal iwlwifi intel_powerclamp cfg80211 coretemp e1000e mei_me ptp kvm_intel iTCO_wdt rtsx_pci_ms thinkpad_acpi iTCO_vendor_support memstick kvm snd irqbypass drbg pcspkr joydev wmi_bmof i2c_i801 pps_core mei shpchp intel_pch_thermal soundcore battery ac ansi_cprng ecdh_generic rfkill crc16 pinctrl_sunrisepoint pinctrl_intel thermal intel_lpss_acpi intel_lpss tpm_crb acpi_pad btrfs xor raid6_pq dm_crypt crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel pcbc rtsx_pci_sdmmc mmc_core aesni_intel aes_x86_64 crypto_simd glue_helper cryptd serio_raw nvme nvme_core i915 xhci_pci rtsx_pci mfd_core i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops xhci_hcd drm usbcore wmi video i2c_hid button dm_mirror
> [147242.227767]  dm_region_hash dm_log dm_mod sg scsi_mod efivarfs autofs4
> [147242.227771] CPU: 3 PID: 2952 Comm: kworker/u9:0 Tainted: G        W       4.13.0-rc4-rw+ #5
> [147242.227772] Hardware name: LENOVO 20J6CTO1WW/20J6CTO1WW, BIOS R0FET34W (1.14 ) 06/30/2017
> [147242.227783] Workqueue: hci0 hci_power_on [bluetooth]
> [147242.227784] task: ffff88011e47cb00 task.stack: ffffc90008294000
> [147242.227786] RIP: 0010:_request_firmware+0x329/0x890
> [147242.227786] RSP: 0018:ffffc90008297c88 EFLAGS: 00010286
> [147242.227787] RAX: 000000000000002c RBX: ffffc90008297d58 RCX: 0000000000000006
> [147242.227788] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff88041f58e010
> [147242.227788] RBP: ffffc90008297ce8 R08: 0000000000000000 R09: 0000000000000ba3
> [147242.227789] R10: 0000000000000004 R11: 0000000000000ba2 R12: ffff8803a731dd40
> [147242.227789] R13: ffffc90008297d40 R14: 0000000000000000 R15: ffffffff81ae61b0
> [147242.227790] FS:  0000000000000000(0000) GS:ffff88041f580000(0000) knlGS:0000000000000000
> [147242.227791] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [147242.227791] CR2: 00007f8f905bb2d8 CR3: 000000032225d000 CR4: 00000000003406e0
> [147242.227792] Call Trace:
> [147242.227795]  request_firmware+0x37/0x50
> [147242.227798]  btusb_setup_intel_new+0x257/0x7c0 [btusb]
> [147242.227806]  ? usb_autopm_put_interface+0x30/0x40 [usbcore]
> [147242.227812]  hci_dev_do_open+0x3ff/0x530 [bluetooth]
> [147242.227814]  ? __switch_to+0x21a/0x440
> [147242.227819]  hci_power_on+0x43/0x220 [bluetooth]
> [147242.227821]  ? __schedule+0x29a/0x8c0
> [147242.227823]  process_one_work+0x13f/0x3a0
> [147242.227824]  worker_thread+0x4d/0x3d0
> [147242.227825]  kthread+0x114/0x150
> [147242.227826]  ? rescuer_thread+0x350/0x350
> [147242.227828]  ? kthread_park+0x60/0x60
> [147242.227829]  ? do_syscall_64+0x6e/0x160
> [147242.227831]  ret_from_fork+0x25/0x30
> [147242.227831] Code: ff 8b 55 c4 48 8b 75 c8 4c 89 e7 e8 12 fb ff ff 41 89 c1 e9 11 ff ff ff e8 25 9c 1c 00 48 c7 c7 18 4e aa 81 31 c0 e8 9a a3 bc ff <0f> ff 41 b9 90 ff ff ff e9 0e fd ff ff 4c 89 f7 e8 72 e8 1b 00 
> [147242.227848] ---[ end trace 2d0d21cf844f8a8d ]---
> 
> Is this known?

It is not known, but it is also unclear why this happens. Basically the card looses power and thus ends up in bootloader mode.

Regards

Marcel

WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890

[Richard Weinberger]

Hi!

My new Thinkpad T470p regularly triggers this warning.
Seems to happy only after resuming from suspend.

[147242.220708] PM: Finishing wakeup.
[147242.220711] OOM killer enabled.
[147242.220711] Restarting tasks ... 
[147242.221908] Bluetooth: hci0: Bootloader revision 0.0 build 26 week 38 2015
[147242.222888] [drm] RC6 on
[147242.227695] Bluetooth: hci0: Device revision is 16
[147242.227696] Bluetooth: hci0: Secure boot is enabled
[147242.227697] Bluetooth: hci0: OTP lock is enabled
[147242.227697] Bluetooth: hci0: API lock is enabled
[147242.227698] Bluetooth: hci0: Debug lock is disabled
[147242.227698] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[147242.227701] firmware request while host is not available
[147242.227708] ------------[ cut here ]------------
[147242.227713] WARNING: CPU: 3 PID: 2952 at drivers/base/firmware_class.c:1225 _request_firmware+0x329/0x890
[147242.227713] Modules linked in: rndis_wlan rndis_host cdc_ether cdc_phonet usbnet phonet mii cdc_acm nls_utf8 udf crc_itu_t msr fuse tun ppp_deflate bsd_comp ppp_async ppp_generic slhc sr_mod cdrom uas usb_storage option usb_wwan usbserial ctr ccm rfcomm nf_log_ipv6 xt_comment nf_log_ipv4 nf_log_common xt_LOG xt_limit af_packet binfmt_misc ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 ipt_REJECT nf_reject_ipv4 xt_pkttype xt_tcpudp iptable_filter ip6table_mangle nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_ipv4 nf_defrag_ipv4 ip_tables xt_conntrack nf_conntrack libcrc32c ip6table_filter ip6_tables x_tables bnep snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic arc4 btusb hci_uart btrtl btbcm btqca btintel bluetooth snd_hda_intel snd_hda_codec snd_hda_core snd_hwdep
[147242.227739]  snd_pcm iwlmvm mac80211 snd_timer intel_rapl x86_pkg_temp_thermal iwlwifi intel_powerclamp cfg80211 coretemp e1000e mei_me ptp kvm_intel iTCO_wdt rtsx_pci_ms thinkpad_acpi iTCO_vendor_support memstick kvm snd irqbypass drbg pcspkr joydev wmi_bmof i2c_i801 pps_core mei shpchp intel_pch_thermal soundcore battery ac ansi_cprng ecdh_generic rfkill crc16 pinctrl_sunrisepoint pinctrl_intel thermal intel_lpss_acpi intel_lpss tpm_crb acpi_pad btrfs xor raid6_pq dm_crypt crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel pcbc rtsx_pci_sdmmc mmc_core aesni_intel aes_x86_64 crypto_simd glue_helper cryptd serio_raw nvme nvme_core i915 xhci_pci rtsx_pci mfd_core i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops xhci_hcd drm usbcore wmi video i2c_hid button dm_mirror
[147242.227767]  dm_region_hash dm_log dm_mod sg scsi_mod efivarfs autofs4
[147242.227771] CPU: 3 PID: 2952 Comm: kworker/u9:0 Tainted: G        W       4.13.0-rc4-rw+ #5
[147242.227772] Hardware name: LENOVO 20J6CTO1WW/20J6CTO1WW, BIOS R0FET34W (1.14 ) 06/30/2017
[147242.227783] Workqueue: hci0 hci_power_on [bluetooth]
[147242.227784] task: ffff88011e47cb00 task.stack: ffffc90008294000
[147242.227786] RIP: 0010:_request_firmware+0x329/0x890
[147242.227786] RSP: 0018:ffffc90008297c88 EFLAGS: 00010286
[147242.227787] RAX: 000000000000002c RBX: ffffc90008297d58 RCX: 0000000000000006
[147242.227788] RDX: 0000000000000000 RSI: 0000000000000082 RDI: ffff88041f58e010
[147242.227788] RBP: ffffc90008297ce8 R08: 0000000000000000 R09: 0000000000000ba3
[147242.227789] R10: 0000000000000004 R11: 0000000000000ba2 R12: ffff8803a731dd40
[147242.227789] R13: ffffc90008297d40 R14: 0000000000000000 R15: ffffffff81ae61b0
[147242.227790] FS:  0000000000000000(0000) GS:ffff88041f580000(0000) knlGS:0000000000000000
[147242.227791] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[147242.227791] CR2: 00007f8f905bb2d8 CR3: 000000032225d000 CR4: 00000000003406e0
[147242.227792] Call Trace:
[147242.227795]  request_firmware+0x37/0x50
[147242.227798]  btusb_setup_intel_new+0x257/0x7c0 [btusb]
[147242.227806]  ? usb_autopm_put_interface+0x30/0x40 [usbcore]
[147242.227812]  hci_dev_do_open+0x3ff/0x530 [bluetooth]
[147242.227814]  ? __switch_to+0x21a/0x440
[147242.227819]  hci_power_on+0x43/0x220 [bluetooth]
[147242.227821]  ? __schedule+0x29a/0x8c0
[147242.227823]  process_one_work+0x13f/0x3a0
[147242.227824]  worker_thread+0x4d/0x3d0
[147242.227825]  kthread+0x114/0x150
[147242.227826]  ? rescuer_thread+0x350/0x350
[147242.227828]  ? kthread_park+0x60/0x60
[147242.227829]  ? do_syscall_64+0x6e/0x160
[147242.227831]  ret_from_fork+0x25/0x30
[147242.227831] Code: ff 8b 55 c4 48 8b 75 c8 4c 89 e7 e8 12 fb ff ff 41 89 c1 e9 11 ff ff ff e8 25 9c 1c 00 48 c7 c7 18 4e aa 81 31 c0 e8 9a a3 bc ff <0f> ff 41 b9 90 ff ff ff e9 0e fd ff ff 4c 89 f7 e8 72 e8 1b 00 
[147242.227848] ---[ end trace 2d0d21cf844f8a8d ]---

Is this known?

Thanks,
//richard

-- 
sigma star gmbh - Eduard-Bodem-Gasse 6 - 6020 Innsbruck - Austria
ATU66964118 - FN 374287y