Bug 203535

Summary: Bluetooth: command tx timeout with Intel Corporation Wireless 7260 in A2DP mode
Product: Drivers Reporter: ValdikSS (iam)
Component: BluetoothAssignee: linux-bluetooth (linux-bluetooth)
Status: NEW ---    
Severity: normal CC: abhishekpandit, de99like, kalmaevlv, leho, me, polynomial-c, tnielsen
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 5.5.13 Tree: Mainline
Regression: No

Description ValdikSS 2019-05-07 00:23:59 UTC
I have Intel Corporation Wireless 7260 (rev 73) with 8087:07dc Intel Corp. Bluetooth module.
From time to time, pausing and playing audio over A2DP causes Bluetooth stack to stall with the following in kernel log:

Bluetooth: hci0: command 0x041f tx timeout
Bluetooth: hci0: command 0x0406 tx timeout
Bluetooth: hci0: command 0x0c03 tx timeout
Bluetooth: hci0: HCI reset during shutdown failed
Bluetooth: hci0: urb 0000000044e22bee failed to resubmit (113)
Bluetooth: hci0: urb 00000000fc976241 failed to resubmit (113)
Bluetooth: hci0: urb 00000000a59b126a failed to resubmit (113)
Bluetooth: hci0: urb 00000000215e997b failed to resubmit (113)

Note that "HCI reset during shutdown failed" happened when I tried to disable Bluetooth and enable it again.
Removing btusb and btintel modules and inserting them again helps.

Bluetooth: hci0: read Intel version: 370710018002030d57
Bluetooth: hci0: Intel device is already patched. patch num: 57

Kernel version: 5.0.11. Happened on 4.9-4.19 as well.
Fedora's firmware package: linux-firmware.noarch 20190416-95.fc30
Comment 1 ValdikSS 2020-04-05 15:53:38 UTC
The problem still occurs frequently, on a recent Linux kernel 5.5.13 and Bluetooth firmware file intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq

If anyone knows how to debug this issue and how can I provide more debug information to you, please respond.
The issue happens with many different headphones and speakers.
Comment 2 Thomas Nielsen 2020-05-25 10:30:22 UTC
Hello I believe this is the same problem (i took out all the plasma and networkmanager messages.
In short my jabra 65t looses connection after very short audio usage (and as a bonus kills my mouse as well if i use bt mouse) The jabra headset works fine with my phone(-s)

(uname -a
Linux linux-jn76 5.6.12-1-default #1 SMP Tue May 12 17:44:12 UTC 2020 (9bff61b) x86_64 x86_64 x86_64 GNU/Linux)

May 25 12:04:49 linux-jn76 kernel: input: Jabra Elite 65t (AVRCP) as /devices/virtual/input/input33
May 25 12:04:49 linux-jn76 obexd[2100]: CONNECT(0x0), <unknown>(0xff)
May 25 12:04:49 linux-jn76 obexd[2100]: CONNECT(0x0), <unknown>(0x0)
May 25 12:04:49 linux-jn76 obexd[2100]: SETPATH(0x5), <unknown>(0xff)
May 25 12:04:49 linux-jn76 obexd[2100]: stat(/root/phonebook/): No such file or directory (2)
May 25 12:04:49 linux-jn76 obexd[2100]: SETPATH(0x5), Not Found(0x44)
May 25 12:04:49 linux-jn76 systemd-logind[1161]: Watching system buttons on /dev/input/event19 (Jabra Elite 65t (AVRCP))
May 25 12:05:51 linux-jn76 kwin_x11[1876]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 4207, resource id: 2>
May 25 12:05:51 linux-jn76 kwin_x11[1876]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 4235, resource id: 3>
May 25 12:06:53 linux-jn76 kio_http_cache_cleaner[6486]: QIODevice::skip (QBuffer): WriteOnly device
May 25 12:06:53 linux-jn76 kio_http_cache_cleaner[6486]: QIODevice::skip (QBuffer): WriteOnly device
May 25 12:09:14 linux-jn76 kernel: usb 2-1.3: reset full-speed USB device number 5 using ehci-pci
May 25 12:09:36 linux-jn76 kernel: usb 2-1.3: Failed to suspend device, error -32
May 25 12:09:36 linux-jn76 obexd[2100]: disconnected: Transport got disconnected
May 25 12:09:36 linux-jn76 kernel: usb 2-1.3: USB disconnect, device number 5
May 25 12:09:36 linux-jn76 kded5[1833]: bluedevil: Removed Obex session is not ours "/org/bluez/obex/server/session3"
May 25 12:09:36 linux-jn76 dbus-daemon[1119]: [system] Rejected send message, 0 matched rules; type="method_return", sender=":1.22" (uid=0 pid=1764 comm="/us>
May 25 12:09:36 linux-jn76 bluetoothd[1439]: Unable to get io data for Headset Voice gateway: getpeername: Transport endpoint is not connected (107)
May 25 12:09:36 linux-jn76 bluetoothd[1439]: Unable to get io data for Phone Book Access: getpeername: Transport endpoint is not connected (107)
May 25 12:09:36 linux-jn76 bluetoothd[1439]: Endpoint unregistered: sender=:1.22 path=/MediaEndpoint/A2DPSink/sbc
May 25 12:09:36 linux-jn76 bluetoothd[1439]: Endpoint unregistered: sender=:1.22 path=/MediaEndpoint/A2DPSource/sbc
May 25 12:09:36 linux-jn76 systemd[1]: Starting Load/Save RF Kill Switch Status...
May 25 12:09:36 linux-jn76 systemd[1755]: Stopped target Bluetooth.
May 25 12:09:36 linux-jn76 systemd[1]: Stopped target Bluetooth.
May 25 12:09:36 linux-jn76 systemd[1]: Started Load/Save RF Kill Switch Status.
May 25 12:09:36 linux-jn76 kernel: usb 2-1.3: new full-speed USB device number 6 using ehci-pci
May 25 12:09:36 linux-jn76 kernel: usb 2-1.3: New USB device found, idVendor=8087, idProduct=07dc, bcdDevice= 0.01
May 25 12:09:36 linux-jn76 kernel: usb 2-1.3: New USB device strings: Mfr=0, Product=0, SerialNumber=0
May 25 12:09:36 linux-jn76 kernel: Bluetooth: hci0: read Intel version: 3707100180012d0d2a
May 25 12:09:36 linux-jn76 kernel: Bluetooth: hci0: Intel device is already patched. patch num: 2a
May 25 12:09:36 linux-jn76 bluetoothd[1439]: Endpoint registered: sender=:1.22 path=/MediaEndpoint/A2DPSink/sbc
May 25 12:09:36 linux-jn76 bluetoothd[1439]: Endpoint registered: sender=:1.22 path=/MediaEndpoint/A2DPSource/sbc
May 25 12:09:37 linux-jn76 systemd[1755]: Reached target Bluetooth.
May 25 12:09:37 linux-jn76 systemd[1]: Reached target Bluetooth.
May 25 12:09:42 linux-jn76 systemd[1]: systemd-rfkill.service: Succeeded.
May 25 12:09:53 linux-jn76 kernel: usb 1-1.2: new full-speed USB device number 6 using ehci-pci
May 25 12:09:53 linux-jn76 kernel: usb 1-1.2: New USB device found, idVendor=046d, idProduct=c52f, bcdDevice=22.01
May 25 12:09:53 linux-jn76 kernel: usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
May 25 12:09:53 linux-jn76 kernel: usb 1-1.2: Product: USB Receiver
May 25 12:09:53 linux-jn76 kernel: usb 1-1.2: Manufacturer: Logitech
May 25 12:09:53 linux-jn76 kernel: logitech-djreceiver 0003:046D:C52F.0007: hidraw0: USB HID v1.11 Mouse [Logitech USB Receiver] on usb-0000:00:1a.0-1.2/inpu>
May 25 12:09:53 linux-jn76 kernel: logitech-djreceiver 0003:046D:C52F.0008: hiddev96,hidraw1: USB HID v1.11 Device [Logitech USB Receiver] on usb-0000:00:1a.>
May 25 12:09:53 linux-jn76 kernel: logitech-djreceiver 0003:046D:C52F.0008: device of type eQUAD step 4 DJ (0x04) connected on slot 1
May 25 12:09:53 linux-jn76 kernel: input: Logitech M187 as /devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2/1-1.2:1.1/0003:046D:C52F.0008/0003:046D:4019.0009/>
May 25 12:09:53 linux-jn76 kernel: logitech-hidpp-device 0003:046D:4019.0009: input,hidraw3: USB HID v1.11 Mouse [Logitech M187] on usb-0000:00:1a.0-1.2/inpu>
May 25 12:09:53 linux-jn76 mtp-probe[7435]: checking bus 1, device 6: "/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2"
May 25 12:09:53 linux-jn76 mtp-probe[7435]: bus: 1, device: 6 was not an MTP device
May 25 12:09:53 linux-jn76 mtp-probe[7462]: checking bus 1, device 6: "/sys/devices/pci0000:00/0000:00:1a.0/usb1/1-1/1-1.2"
May 25 12:09:53 linux-jn76 mtp-probe[7462]: bus: 1, device: 6 was not an MTP device
May 25 12:09:53 linux-jn76 upowerd[1986]: failed to coldplug unifying device: Unable to read response from device: Resource temporarily unavailable
May 25 12:09:54 linux-jn76 systemd-logind[1161]: Watching system buttons on /dev/input/event17 (Logitech M187)
May 25 12:09:54 linux-jn76 kcminit[7470]: Initializing  "kcm_mouse" :  "kcminit_mouse"
May 25 12:09:54 linux-jn76 kwin_x11[1876]: qt.qpa.xcb: QXcbConnection: XCB error: 3 (BadWindow), sequence: 61320, resource id: 132120581, major code: 18 (Cha>
May 25 12:09:58 linux-jn76 bluetoothd[1439]: a2dp-sink profile connect failed for 74:5C:4B:30:12:01: Device or resource busy
May 25 12:09:58 linux-jn76 obexd[2100]: CONNECT(0x0), <unknown>(0xff)
May 25 12:09:58 linux-jn76 obexd[2100]: CONNECT(0x0), <unknown>(0x0)
May 25 12:09:58 linux-jn76 obexd[2100]: SETPATH(0x5), <unknown>(0xff)
May 25 12:09:58 linux-jn76 obexd[2100]: stat(/root/phonebook/): No such file or directory (2)
May 25 12:09:58 linux-jn76 obexd[2100]: SETPATH(0x5), Not Found(0x44)
Comment 3 Chris Wales 2020-06-26 15:08:54 UTC
Reporting the same issue here: in my case, an Intel AX 200 chip (device: 8087:0029)

I get a whole host of the following from dmesg:

[68815.214110] Bluetooth: hci0: No way to reset. Ignoring and continuing
[68817.230103] Bluetooth: hci0: command 0x0c2d tx timeout
[68817.230105] Bluetooth: hci0: No way to reset. Ignoring and continuing
[68819.246103] Bluetooth: hci0: command 0x1405 tx timeout
[68819.246106] Bluetooth: hci0: No way to reset. Ignoring and continuing
[68821.102115] Bluetooth: hci0: HCI reset during shutdown failed
[68833.927095] Bluetooth: hci0: urb 00000000da5061f1 failed to resubmit (113)
[68843.971063] Bluetooth: hci0: urb 000000001871b752 failed to resubmit (113)
[68857.915087] Bluetooth: hci0: urb 00000000ac41a64d failed to resubmit (113)
[68901.639104] Bluetooth: hci0: urb 00000000cabd03b6 failed to resubmit (113)
[68983.475090] Bluetooth: hci0: urb 00000000586c564c failed to resubmit (113)

As with the poster above, removing btusb and btintel modules and inserting them again helps.
Comment 4 Chris Wales 2020-06-26 15:09:32 UTC
(In reply to Chris Wales from comment #3)
> Reporting the same issue here: in my case, an Intel AX 200 chip (device:
> 8087:0029)
> 
> I get a whole host of the following from dmesg:
> 
> [68815.214110] Bluetooth: hci0: No way to reset. Ignoring and continuing
> [68817.230103] Bluetooth: hci0: command 0x0c2d tx timeout
> [68817.230105] Bluetooth: hci0: No way to reset. Ignoring and continuing
> [68819.246103] Bluetooth: hci0: command 0x1405 tx timeout
> [68819.246106] Bluetooth: hci0: No way to reset. Ignoring and continuing
> [68821.102115] Bluetooth: hci0: HCI reset during shutdown failed
> [68833.927095] Bluetooth: hci0: urb 00000000da5061f1 failed to resubmit (113)
> [68843.971063] Bluetooth: hci0: urb 000000001871b752 failed to resubmit (113)
> [68857.915087] Bluetooth: hci0: urb 00000000ac41a64d failed to resubmit (113)
> [68901.639104] Bluetooth: hci0: urb 00000000cabd03b6 failed to resubmit (113)
> [68983.475090] Bluetooth: hci0: urb 00000000586c564c failed to resubmit (113)
> 
> As with the poster above, removing btusb and btintel modules and inserting
> them again helps.

Sorry, should add - using kernel 5.4.14
Comment 5 Abhishek Pandit-Subedi 2020-07-06 20:53:16 UTC
There's a recovery mechanism via `cmd_timeout` that the btusb driver uses to recover from these issues. For Intel chipsets, this requires having a reset gpio available and listed in the ACPI/DeviceTree. From the logs above, it looks like that's not the case.

I've had some success on a QCA chipset (6174A) by just resetting the port when this happens (see https://patchwork.kernel.org/patch/11624041/)

If you don't mind patching your kernel, you could try the following and see if it helps (you will need the series I linked above as well if you're not using bluetooth-next master branch).

diff --git a/drivers/bluetooth/btusb.c b/drivers/bluetooth/btusb.c
index 0e143c0cecf2a1..cf86104fd62018 100644
--- a/drivers/bluetooth/btusb.c
+++ b/drivers/bluetooth/btusb.c
@@ -511,6 +511,7 @@ struct btusb_data {
        unsigned cmd_timeout_cnt;
 };

+static void btusb_qca_cmd_timeout(struct hci_dev *hdev);
 static void btusb_intel_cmd_timeout(struct hci_dev *hdev)
 {
        struct btusb_data *data = hci_get_drvdata(hdev);
@@ -520,7 +521,8 @@ static void btusb_intel_cmd_timeout(struct hci_dev *hdev)
                return;

        if (!reset_gpio) {
-               bt_dev_err(hdev, "No way to reset. Ignoring and continuing");
+               bt_dev_err(hdev, "No reset gpio. Resetting usb instead.");
+               btusb_qca_cmd_timeout(hdev);
                return;
        }
Comment 6 A. M. 2020-10-03 08:28:24 UTC
hi

I have the same problem with a different chipset 8087:0029 

I also got a kernel backtrace

kernel: kobject_add_internal failed for hci0:256 with -EEXIST, don't try to register things with the same name in the same directory.
kernel: Bluetooth: hci0: failed to register connection device
kernel: Bluetooth: hci0: link tx timeout
kernel: Bluetooth: hci0: killing stalled connection 75:ab:d6:65:ea:56
kernel: BUG: unable to handle kernel NULL pointer dereference at 0000000000000020
kernel: IP: klist_next+0x1c/0x100
kernel: PGD 0 P4D 0 
kernel: Oops: 0000 [#1] SMP NOPTI
kernel: Modules linked in: rfcomm pci_stub vboxpci(OE) vboxnetadp(OE) vboxnetflt(OE) vboxdrv(OE) ccm cmac bnep binfmt_misc dm_crypt algif_skcipher af_alg cdc_ether usbnet r8152 mii uvcvideo videobuf2_vmalloc videobuf2_memops btusb videobuf2_v4l2 btrtl btbcm videobuf2_core btintel videodev bluetooth media ecdh_generic snd_hda_codec_hdmi snd_hda_codec_realtek snd_hda_codec_generic hid_multitouch arc4 dell_laptop intel_rapl x86_pkg_temp_thermal intel_powerclamp coretemp kvm_intel kvm nls_iso8859_1 irqbypass crct10dif_pclmul crc32_pclmul ghash_clmulni_intel pcbc snd_hda_intel aesni_intel snd_hda_codec aes_x86_64 snd_hda_core crypto_simd glue_helper snd_hwdep cryptd intel_cstate snd_pcm intel_rapl_perf iwlmvm(OE) snd_seq_midi snd_seq_midi_event dell_wmi mac80211(OE) joydev input_leds dell_smbios snd_rawmidi
kernel:  serio_raw dcdbas snd_seq iwlwifi(OE) snd_seq_device snd_timer dell_wmi_descriptor wmi_bmof snd idma64 intel_wmi_thunderbolt virt_dma cfg80211(OE) soundcore rtsx_pci_ms compat(OE) memstick ucsi_acpi intel_lpss_pci intel_lpss typec_ucsi processor_thermal_device intel_soc_dts_iosf typec int3403_thermal int340x_thermal_zone intel_hid mac_hid int3400_thermal sparse_keymap acpi_thermal_rel acpi_pad sch_fq_codel parport_pc ppdev lp parport ip_tables x_tables autofs4 btrfs zstd_compress raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear hid_generic usbhid i915 i2c_algo_bit drm_kms_helper rtsx_pci_sdmmc syscopyarea psmouse thunderbolt sysfillrect sysimgblt fb_sys_fops rtsx_pci drm wmi i2c_hid hid video
kernel: CPU: 3 PID: 17609 Comm: kworker/u17:3 Tainted: G        W  OE    4.15.0-1097-oem #107-Ubuntu
kernel: Hardware name: Dell Inc. XPS 13 7390/0G2D0W, BIOS 1.6.0 07/07/2020
kernel: Workqueue: hci0 hci_rx_work [bluetooth]
kernel: RIP: 0010:klist_next+0x1c/0x100
kernel: RSP: 0018:ffffbf86c742fc80 EFLAGS: 00010282
kernel: RAX: 0000000000000000 RBX: ffff996fce487000 RCX: 0000000000000000
kernel: RDX: ffffffffc0f4b230 RSI: ffffbf86c742fcc0 RDI: 0000000000000000
kernel: RBP: ffffbf86c742fcb0 R08: 0000377d840d5913 R09: ffff996ffbf49818
kernel: R10: 0000000000000000 R11: 00007fe43cbf3014 R12: ffffbf86c742fcc0
kernel: R13: 0000000000000000 R14: ffff996ff532c000 R15: ffff996fce487000
kernel: FS:  0000000000000000(0000) GS:ffff99700e4c0000(0000) knlGS:0000000000000000
kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
kernel: CR2: 0000000000000020 CR3: 00000001a320a002 CR4: 00000000003606e0
kernel: Call Trace:
kernel:  ? bt_link_release+0x20/0x20 [bluetooth]
kernel:  device_find_child+0x5c/0xb0
kernel:  ? bt_link_release+0x20/0x20 [bluetooth]
kernel:  hci_conn_del_sysfs+0x54/0xa0 [bluetooth]
kernel:  hci_conn_cleanup+0x92/0x140 [bluetooth]
kernel:  hci_conn_del+0xf1/0x1f0 [bluetooth]
kernel:  hci_event_packet+0x1155/0x2d60 [bluetooth]
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  ? __switch_to_asm+0x41/0x70
kernel:  ? __switch_to_asm+0x35/0x70
kernel:  hci_rx_work+0x199/0x390 [bluetooth]
kernel:  ? hci_rx_work+0x199/0x390 [bluetooth]
kernel:  process_one_work+0x1de/0x420
kernel:  worker_thread+0x32/0x410
kernel:  kthread+0x121/0x140
kernel:  ? process_one_work+0x420/0x420
kernel:  ? kthread_create_worker_on_cpu+0x70/0x70
kernel:  ret_from_fork+0x1f/0x40
kernel: Code: 41 5c 41 5d 5d c3 66 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 57 41 56 41 55 41 54 49 89 fc 53 48 83 ec 08 48 8b 3f 4d 8b 6c 24 08 <4c> 8b 77 20 e8 db 24 02 00 4d 85 ed 0f 84 84 00 00 00 49 8b 4d 
kernel: RIP: klist_next+0x1c/0x100 RSP: ffffbf86c742fc80
kernel: CR2: 0000000000000020
kernel: ---[ end trace e0cb46d230eda351 ]---
Comment 7 Leonid Kalmaev 2020-12-12 14:56:52 UTC
hi, i am seeing the same problem. I think the reason is the automatic saving of energy.
In my case, if you use the powertop tool and carefully look at the Tunables tab, you can find Autosuspend for unknown USB device 1-1.3 (8087: 07dc)
change the state to bad and the problem no longer persists until the next system reboot.

uname -a
Linux dns-book 5.8.0-33-generic #36~20.04.1-Ubuntu SMP Wed Dec 9 17:01:13 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux

lspci 
07:00.0 Network controller: Intel Corporation Wireless 7260 (rev bb)

lsusb
Bus 001 Device 003: ID 8087:07dc Intel Corp.
Comment 8 ValdikSS 2020-12-14 20:15:55 UTC
(In reply to Leonid Kalmaev from comment #7)
> hi, i am seeing the same problem. I think the reason is the automatic saving
> of energy.

Maybe you're right. I had autosuspend disabled for this device but for unknown reason it automatically re-enabled, probably after laptop suspend-resume cycle.
Right now I'm running Bluetooth audio for 2 days with automatic suspend disabled, so far so good.

I'll check whether the bug happens during the week and close the bug with detailed autosuspend disabling procedure description.
Comment 9 ValdikSS 2020-12-26 17:19:16 UTC
It's been 12 days without any issues.

Workaround this bug by executing the following command, which disables Bluetooth autosuspend:

    echo 'options btusb enable_autosuspend=0' | sudo tee /etc/modprobe.d/bluetooth.conf

Reboot afterwards.
Comment 10 Leonid Kalmaev 2021-01-02 07:19:14 UTC
(In reply to ValdikSS from comment #9)
> It's been 12 days without any issues.
> 
> Workaround this bug by executing the following command, which disables
> Bluetooth autosuspend:
> 
>     echo 'options btusb enable_autosuspend=0' | sudo tee
> /etc/modprobe.d/bluetooth.conf
> 
> Reboot afterwards.

Hi. This does not work for some reason in the case of sleep. After waking up from sleep in powertop I see a good state again. Can you advise on more options for this to work correctly?
Comment 11 ValdikSS 2021-01-14 16:59:07 UTC
(In reply to Leonid Kalmaev from comment #10)

> Hi. This does not work for some reason in the case of sleep. After waking up
> from sleep in powertop I see a good state again. Can you advise on more
> options for this to work correctly?

It seems there's a bug (or a feature) in kernel, which switches the devices in power save mode after suspend, without triggering UDEV events. Here's what tlp developer says: https://github.com/linrunner/TLP/issues/545

>Imho the kernel never issued udev new device events for existing devices after
>resume. You may look into it yourself by enabling TLP's trace mode with
>TLP_DEBUG="run udev usb".

I use tlp software, with bluetooth module powersave blacklist configured and patch which is mentioned in the URL above applied (`set_usb_suspend 0 auto` in tlp resume handler)