Bluetooth (btintel) stops working after suspend/resume

[Bas Zoetekouw]

I run cosmic on my Dell Latitude E7470, which has an intel usb bluetooth device (8087:0a2b).

Sometimes (not every time) after a suspend/resume cycle, my laptop's bluetooth stops working. hciconfig shows:

hci0: Type: Primary Bus: USB
 BD Address: 00:00:00:00:00:00 ACL MTU: 0:0 SCO MTU: 0:0
 DOWN
 RX bytes:0 acl:0 sco:0 events:0 errors:0
 TX bytes:3 acl:0 sco:0 commands:1 errors:0

and dmesg tells me (various combinations of):

[237660.728312] Bluetooth: hci0: command tx timeout
[237732.339965] Bluetooth: hci0: command 0xfc05 tx timeout
[237925.202500] Bluetooth: hci0: Reading Intel version information failed (-110)

Trying to reinitialize the device by reloading the driver has no effect:

╰─▶ modprobe -r btusb; modprobe -r btintel; modprobe btintel; modprobe btusb

shows in dmesg:

[237938.219190] usbcore: deregistering interface driver btusb
[237938.601731] usbcore: registered new interface driver btusb
[237940.626392] Bluetooth: hci0: Reading Intel version information failed (-110)
[237940.626426] Bluetooth: hci0: command tx timeout

Strangely enough, reloading the module sometimes does work, upon which the kernel tells me :
aug 20 15:36:08 regan kernel: usbcore: deregistering interface driver btusb
aug 20 15:36:30 regan kernel: Bluetooth: hci0: Bootloader revision 0.0 build 2 week 52 2014
aug 20 15:36:30 regan kernel: usbcore: registered new interface driver btusb
aug 20 15:36:30 regan kernel: Bluetooth: hci0: Device revision is 5
aug 20 15:36:30 regan kernel: Bluetooth: hci0: Secure boot is enabled
aug 20 15:36:30 regan kernel: Bluetooth: hci0: OTP lock is enabled
aug 20 15:36:30 regan kernel: Bluetooth: hci0: API lock is enabled
aug 20 15:36:30 regan kernel: Bluetooth: hci0: Debug lock is disabled
aug 20 15:36:30 regan kernel: Bluetooth: hci0: Minimum firmware build 1 week 10 2014
aug 20 15:36:30 regan kernel: Bluetooth: hci0: Found device firmware: intel/ibt-11-5.sfi
aug 20 15:36:31 regan kernel: Bluetooth: hci0: Waiting for firmware download to complete
aug 20 15:36:31 regan kernel: Bluetooth: hci0: Firmware loaded in 1590852 usecs
aug 20 15:36:31 regan kernel: Bluetooth: hci0: Waiting for device to boot
aug 20 15:36:31 regan kernel: Bluetooth: hci0: Device booted in 11654 usecs
aug 20 15:36:31 regan kernel: Bluetooth: hci0: Found Intel DDC parameters: intel/ibt-11-5.ddc
aug 20 15:36:31 regan kernel: Bluetooth: hci0: Applying Intel DDC parameters completed

Looking further back in the kernel log, the difference between failed and successful resumes seems to be this:

Resume with broken bt:
[236481.370814] Restarting tasks ...
[236491.580841] Bluetooth: hci0: Reading Intel boot parameters failed (-110)

Resume with working bt:
[16562.706263] Restarting tasks ...
[16562.709034] Bluetooth: hci0: Bootloader revision 0.0 build 2 week 52 2014
[16562.716050] Bluetooth: hci0: Device revision is 5
[16562.716052] Bluetooth: hci0: Secure boot is enabled
[16562.716053] Bluetooth: hci0: OTP lock is enabled
[16562.716054] Bluetooth: hci0: API lock is enabled
[16562.716055] Bluetooth: hci0: Debug lock is disabled
[16562.716056] Bluetooth: hci0: Minimum firmware build 1 week 10 2014
[16562.716404] Bluetooth: hci0: Found device firmware: intel/ibt-11-5.sfi
[16564.202470] Bluetooth: hci0: Waiting for firmware download to complete
[16564.203017] Bluetooth: hci0: Firmware loaded in 1459449 usecs
[16564.203091] Bluetooth: hci0: Waiting for device to boot
[16564.215021] Bluetooth: hci0: Device booted in 11693 usecs
[16564.215080] Bluetooth: hci0: Found Intel DDC parameters: intel/ibt-11-5.ddc
[16564.219033] Bluetooth: hci0: Applying Intel DDC parameters completed

and everything works fine after that.

The first kernel on which this error occurred was 4.17.0-6-generic. Before that, I used 4.15.0-25-generic which works perfectly.
---
ProblemType: Bug
ApportVersion: 2.20.10-0ubuntu9
Architecture: amd64
AudioDevicesInUse:
 USER PID ACCESS COMMAND
 /dev/snd/pcmC0D0p: bas 4871 F...m pulseaudio
 /dev/snd/controlC0: bas 4871 F.... pulseaudio
CurrentDesktop: GNOME
DistroRelease: Ubuntu 18.10
HibernationDevice:
 RESUME=UUID=16195e13-9fb3-41b2-9671-fb4e1df1ff93
 #RESUME=/dev/dm-2
 #RESUME=/dev/mapper/regan-swap
InstallationDate: Installed on 2016-12-22 (619 days ago)
InstallationMedia: Ubuntu 16.10 "Yakkety Yak" - Release amd64 (20161012.2)
MachineType: Dell Inc. Latitude E7470
Package: linux (not installed)
ProcFB: 0 inteldrmfb
ProcKernelCmdLine: BOOT_IMAGE=/vmlinuz-4.17.0-7-generic root=/dev/mapper/hostname-root ro resume=/dev/mapper/hostname-swap nosplash acpi_backlight=vendor
ProcVersionSignature: Ubuntu 4.17.0-7.8-generic 4.17.12
RelatedPackageVersions:
 linux-restricted-modules-4.17.0-7-generic N/A
 linux-backports-modules-4.17.0-7-generic N/A
 linux-firmware 1.174
Tags: cosmic
Uname: Linux 4.17.0-7-generic x86_64
UnreportableReason: This report is about a package that is not installed.
UpgradeStatus: Upgraded to cosmic on 2017-09-18 (349 days ago)
UserGroups: adm cdrom dialout dip docker libvirt lp lpadmin lxd plugdev sambashare scanner src sudo tss wireshark
_MarkForUpload: False
dmi.bios.date: 12/11/2017
dmi.bios.vendor: Dell Inc.
dmi.bios.version: 1.18.5
dmi.board.name: 0T6HHJ
dmi.board.vendor: Dell Inc.
dmi.board.version: A00
dmi.chassis.type: 9
dmi.chassis.vendor: Dell Inc.
dmi.modalias: dmi:bvnDellInc.:bvr1.18.5:bd12/11/2017:svnDellInc.:pnLatitudeE7470:pvr:rvnDellInc.:rn0T6HHJ:rvrA00:cvnDellInc.:ct9:cvr:
dmi.product.family: Latitude
dmi.product.name: Latitude E7470
dmi.sys.vendor: Dell Inc.

[Ubuntu Kernel Bot (ubuntu-kernel-bot)]

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1790454

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Bas Zoetekouw (baszoetekouw)]

apport information

[Joseph Salisbury (jsalisbury)]

Did this issue start happening after an update/upgrade? Was there a prior kernel version where you were not having this particular problem?

Would it be possible for you to test the latest upstream kernel? Refer to https://wiki.ubuntu.com/KernelMainlineBuilds . Please test the latest v4.19 kernel[0].

If this bug is fixed in the mainline kernel, please add the following tag 'kernel-fixed-upstream'.

If the mainline kernel does not fix this bug, please add the tag: 'kernel-bug-exists-upstream'.

Once testing of the upstream kernel is complete, please mark this bug as "Confirmed".

Thanks in advance.

[0] http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.19-rc2

[Bas Zoetekouw (baszoetekouw)]

I can confirm that the bug still occurs in 4.19.0-041900rc5-generic.

The first kernel on which this error occurred was 4.17.0-6-generic. Before that, I used 4.15.0-25-generic which works perfectly.

[Bas Zoetekouw (baszoetekouw)]

Adding to that, there is a (somewhat) reliable way to get bluetooth back. It involves goign to the following process _twice_: stopping the bluetooth service, unloading all relevant modules, suspending the laptop, resuming, reloading all modules, starting the bluetooth service.
Rather cumbersome, but it might help other experiencing this issue.

I use the following script for "convenience" (en remeber to run it twice to get bt back):

#!/bin/bash
if [[ $EUID -ne 0 ]]; then
 exec /usr/bin/sudo $0
fi
modules=(btusb btintel btbcm bnep rfcomm bluetooth)
/bin/systemctl stop bluetooth
for (( i=0; i<${#modules[@]}; i++ ))
do
 /sbin/modprobe -r "${modules[i]}"
done
/bin/systemctl suspend
for (( i=${#modules[@]}-1; i>=0; i-- ))
do
 /sbin/modprobe "${modules[i]}"
done
/bin/systemctl start bluetooth
exit 0

[Kai-Heng Feng (kaihengfeng)]

Can you attach full dmesg with `usbcore.dyndbg=+p`?

[Bas Zoetekouw (baszoetekouw)]

Do you need a dmesg when the bug is triggered, or does a regular boot log suffice? It's hard to trigger the bug manually (but it occurs every couple of days).

[Kai-Heng Feng (kaihengfeng)]

When the bug is triggered.

[Bas Zoetekouw (baszoetekouw)]

The bug triggered again this morning:

> modprobe -r btusb

gives

[ 6998.064598] usbcore: deregistering interface driver btusb
[ 6998.064608] usb usb1: usb auto-resume
[ 6998.064639] hub 1-0:1.0: hub_resume
[ 6998.064659] usb usb1-port2: status 0507 change 0000
[ 6998.064674] usb usb1-port7: status 0107 change 0000
[ 6998.064677] usb usb1-port8: status 0107 change 0000
[ 6998.064680] usb usb1-port9: status 0107 change 0000
[ 6998.064694] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.064741] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.091617] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.111570] usb 1-8: usb auto-resume
[ 6998.111600] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0100
[ 6998.179602] usb 1-8: Waited 0ms for CONNECT
[ 6998.179603] usb 1-8: finish resume
[ 6998.203699] usb 1-8: usb auto-suspend, wakeup 0
[ 6998.227621] hub 1-0:1.0: hub_suspend
[ 6998.227635] usb usb1: bus auto-suspend, wakeup 1

subsequent "modprobe btusb":

[ 6998.064598] usbcore: deregistering interface driver btusb
[ 6998.064608] usb usb1: usb auto-resume
[ 6998.064639] hub 1-0:1.0: hub_resume
[ 6998.064659] usb usb1-port2: status 0507 change 0000
[ 6998.064674] usb usb1-port7: status 0107 change 0000
[ 6998.064677] usb usb1-port8: status 0107 change 0000
[ 6998.064680] usb usb1-port9: status 0107 change 0000
[ 6998.064694] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.064741] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.091617] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.111570] usb 1-8: usb auto-resume
[ 6998.111600] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0100
[ 6998.179602] usb 1-8: Waited 0ms for CONNECT
[ 6998.179603] usb 1-8: finish resume
[ 6998.203699] usb 1-8: usb auto-suspend, wakeup 0
[ 6998.227621] hub 1-0:1.0: hub_suspend
[ 6998.227635] usb usb1: bus auto-suspend, wakeup 1

I'll attach the complete journal. Sequence there is as follows:
 - BT is working on oct 7th
 - suspend at oct 7th, 22:44
 - resume oct 8th, 8:33, BT stopped working
 - 08:48:42 modprobe -r btusb
 - 08:48:50 modprobe btusb
 - 08:52:04 ran bt-reset script as referenced in #21 (so, unload bt modules, suspend, resume, load bt modules)
 - 08:52:26 BT is working again

[Bas Zoetekouw (baszoetekouw)]

Hmm, I guess the dmesg above was mispasted.

"modprobe -r btusb" gives

[ 6998.064598] usbcore: deregistering interface driver btusb
[ 6998.064608] usb usb1: usb auto-resume
[ 6998.064639] hub 1-0:1.0: hub_resume
[ 6998.064659] usb usb1-port2: status 0507 change 0000
[ 6998.064674] usb usb1-port7: status 0107 change 0000
[ 6998.064677] usb usb1-port8: status 0107 change 0000
[ 6998.064680] usb usb1-port9: status 0107 change 0000
[ 6998.064694] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.064741] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.091617] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 6998.111570] usb 1-8: usb auto-resume
[ 6998.111600] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0100
[ 6998.179602] usb 1-8: Waited 0ms for CONNECT
[ 6998.179603] usb 1-8: finish resume
[ 6998.203699] usb 1-8: usb auto-suspend, wakeup 0
[ 6998.227621] hub 1-0:1.0: hub_suspend
[ 6998.227635] usb usb1: bus auto-suspend, wakeup 1

subsequent "modprobe btusb" gives:

[ 7006.302906] usb usb1: usb auto-resume
[ 7006.302938] hub 1-0:1.0: hub_resume
[ 7006.302959] usb usb1-port2: status 0507 change 0000
[ 7006.302973] usb usb1-port7: status 0107 change 0000
[ 7006.302977] usb usb1-port8: status 0107 change 0000
[ 7006.302980] usb usb1-port9: status 0107 change 0000
[ 7006.302994] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 7006.303044] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 7006.351578] usb 1-8: usb auto-resume
[ 7006.351666] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0100
[ 7006.423565] usb 1-8: Waited 0ms for CONNECT
[ 7006.423567] usb 1-8: finish resume
[ 7006.423797] btusb 1-8:1.0: usb_probe_interface
[ 7006.423799] btusb 1-8:1.0: usb_probe_interface - got id
[ 7006.424039] usbcore: registered new interface driver btusb
[ 7008.443419] Bluetooth: hci0: command 0xfc05 tx timeout
[ 7008.443427] Bluetooth: hci0: Reading Intel version information failed (-110)
[ 7008.463483] usb 1-8: usb auto-suspend, wakeup 0
[ 7008.483434] hub 1-0:1.0: hub_suspend
[ 7008.483473] usb usb1: bus auto-suspend, wakeup 1
[ 7200.187930] usbcore: deregistering interface driver btusb
[ 7200.187940] usb usb1: usb auto-resume
[ 7200.187963] hub 1-0:1.0: hub_resume
[ 7200.187979] usb usb1-port2: status 0507 change 0000
[ 7200.187993] usb usb1-port7: status 0107 change 0000
[ 7200.187996] usb usb1-port8: status 0107 change 0000
[ 7200.188000] usb usb1-port9: status 0107 change 0000
[ 7200.188014] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 7200.188058] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 7200.206254] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0000
[ 7200.234035] hub 1-0:1.0: state 7 ports 12 chg 0000 evt 0100
[ 7200.234040] usb 1-8: usb auto-resume
[ 7200.302166] usb 1-8: Waited 0ms for CONNECT
[ 7200.302168] usb 1-8: finish resume
[ 7200.326073] usb 1-8: usb auto-suspend, wakeup 0
[ 7200.346253] hub 1-0:1.0: hub_suspend
[ 7200.346260] usb usb1: bus auto-suspend, wakeup 1
[ 7200.490109] NET: Unregistered protocol family 31
[ 7200.560277] Bluetooth: Core ver 2.22
[ 7200.560294] NET: Registered protocol family 31
[ 7200.560294] Bluetooth: HCI device and connection manager initialized
[ 7200.560310] Bluetooth: HCI socket layer init...

[Kai-Heng Feng (kaihengfeng)]

Is it possible for you to attach full dmesg? i.e. everything from boot. I'd like to check if LPM is enabled for this device.

[Bas Zoetekouw (baszoetekouw)]

Sure, here it is.

[Kai-Heng Feng (kaihengfeng)]

Ok, please use v4.19-rc6 or rc7, and boot with kernel parameter "usbcore.quirks=8087:0a2b:k" which disables LPM for the Bluetooth device, and see if this issue still persists.

[Bas Zoetekouw (baszoetekouw)]

With kernel 4.19rc7 and the kernel parameter as you prescribed, the BT adapter won't work at all. The timeouts that would only occur sporadically after resume, are now present from boot, and the previous unload-modules/suspend/resume/load-modules cycle no longer works to get BT back on.
Dmesg is attached.

[Kai-Heng Feng (kaihengfeng)]

Hmmm, do you still see this if you cold boot with the quirk?

[Bas Zoetekouw (baszoetekouw)]

Ah yes, cold boot seems to fix it for now. I'll need to wait and see if the bug now occurs during normal operation.

[Bas Zoetekouw (baszoetekouw)]

Problem still occurs. Dmesg is attached.

[Kai-Heng Feng (kaihengfeng)]

Is it possible for you to try this patch?
https://patchwork.kernel.org/patch/10624303/

[Bas Zoetekouw (baszoetekouw)]

Ok, running a patched kernel now. Let's see if I can still trigger the bug.

[Bas Zoetekouw (baszoetekouw)]

Sorry, bug is still occurring, even with the patch. Dmesg is attached.

[Kai-Heng Feng (kaihengfeng)]

I've seen similar things recently, and seems like increase the delay after reset can alleviate the issue.

Can you try something like 100ms or 200ms instead of (10 + 40)ms in [1]?

[1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/tree/drivers/usb/core/hub.c#n2889

[Bas Zoetekouw (baszoetekouw)]

ok, will do

[Bas Zoetekouw (baszoetekouw)]

I've changed the delay to 200ms, but now I get

[16936.380848] Bluetooth: hci0: Device boot timeout

in addition to the original symptons.

Dmesg is attached.

[Kai-Heng Feng (kaihengfeng)]

Hmm, can you try removing iwlwifi before suspend, not sure if there's an internal race happen inside the Intel wireless module.

[Bas Zoetekouw (baszoetekouw)]

Also doesn't seem to make any difference...
Dmesg (attached) shows that iwlwifi is loading after initial btusb initialization, but it still fails about 2/3 of the time.

[Bas Zoetekouw (baszoetekouw)]

Hmm, running the current setup (200ms sleep+iwlwifi unload-on-suspend), I must say that the bt loading has become more reliable. It still doesn't work 100% of the time, but it definitely is working more often than before (maybe 75% of the time it works ok now).

[Kai-Heng Feng (kaihengfeng)]

My bad, I didn't saw it works on 4.15 but fails since 4.17.

Before doing a kernel bisect, can you try if "btusb.enable_autosuspend=0" helps?

[Bas Zoetekouw (baszoetekouw)]

I'm happy to report that everything seems stable now.
I'm now running the following config
 - kernel 4.19.0-041900rc7-generic
 - delay after reset set to 200ms (see #38)
 - unload iwlwifi on suspend/sleep
 - btusb.enable_autosuspend=0

Should I try with a regular kernel and only btusb.enable_autosuspend=0 ?

[Kai-Heng Feng (kaihengfeng)]

Yes please.

Or even better, do a full kernel bisection between v4.15 and v4.17 to make sure btusb.enable_autosuspend introduced the regression.

[Radu Andries (hardc0de)]

Same issue here.

Adding this to options + cold boot seems to have fixed it.

% cat /etc/modprobe.d/btusb.conf
options btusb enable_autosuspend=0
~ % uname -r
4.18.19-041819-generic

[Bas Zoetekouw (baszoetekouw)]

I'm still planning to run a bisect to find the offending commit, but havne't found the time yet.

[DH (dave-higherform)]

I am having a similar issue with Intel 8260. Wifi and BT works correctly after cold boot. Wifi works correctly after suspend, but BT was showing no adapters available in KDE plasma widget. dmesg would report "[ 150.064149] Bluetooth: hci0: Failed to send firmware data (-38)" after each resume.

My 8260 was not listed in lsusb, but is listed in lspci.

Fix in #47 did not work for me. However, adding a systemd service to rmmod and modprobe btusb after each resume seems to have the BT adapter working correctly now.

uname -a:
Linux uranus 4.18.0-13-generic #14-Ubuntu SMP Wed Dec 5 09:04:24 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

[Bas Zoetekouw (baszoetekouw)]

If the enable_autosuspend option doesn't fix your issue, I think you are encountering a different bug (with overlapping symptoms). For clarity, it might be best to open a separate bug report for your issue.

[Kai-Heng Feng (kaihengfeng)]

DH, I think this can workaround your issue:

[1] https://github.com/endlessm/linux/pull/424

[Kai-Heng Feng (kaihengfeng)]

Bas,

Does "enable_autosuspend=0" alone fix your issue?

[Bas Zoetekouw (baszoetekouw)]

Yeah, "enable_autosuspend=0" by itself fixes the issue.

[Kai-Heng Feng (kaihengfeng)]

Bas,

Please test this patch, thanks!

[Emiliano (retorquere)]

"enable_autosuspend=0" did not fix the issue for me.

[Kai-Heng Feng (kaihengfeng)]

Emiliano,

That means it's a different issue. Please file a new bug.

[Kai-Heng Feng (kaihengfeng)]

Please test this patch.

[Stan Janssen (finetuned)]

I am running into exactly the same problem as Bas Zoetekouw. I added the enable_autosuspend=0 option:

stan@stan-desktop:~$ cat /etc/modprobe.d/btusb.conf
options btusb enable_autosuspend=0

But I see the following in dmesg after reboot:

[ 4.026743] btusb: unknown parameter 'enable_autosuspend' ignored

And the problem still occurs.

Do I need to do something else beside adding this line to /etc/modprobe.d/btusb.conf?

[Kai-Heng Feng (kaihengfeng)]

Stan,
Please file a separate bug so logs can be collected.