Bug 215528 - Excessive logging from Intel Bluetooth "Bluetooth: hci0: sending frame failed" "hci0: urb 00000000xxxxxxxx submission failed (90)"
Summary: Excessive logging from Intel Bluetooth "Bluetooth: hci0: sending frame failed...
Status: RESOLVED CODE_FIX
Alias: None
Product: Drivers
Classification: Unclassified
Component: Bluetooth (show other bugs)
Hardware: x86-64 Linux
: P1 high
Assignee: linux-bluetooth@vger.kernel.org
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2022-01-24 21:55 UTC by Artem S. Tashkinov
Modified: 2022-03-25 18:26 UTC (History)
4 users (show)

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


Attachments
/sys/kernel/debug/usb/devices (7.35 KB, text/plain)
2022-01-25 10:15 UTC, Artem S. Tashkinov
Details
dmesg (13.43 KB, application/x-xz)
2022-01-25 10:42 UTC, Artem S. Tashkinov
Details

Description Artem S. Tashkinov 2022-01-24 21:55:43 UTC
Sometimes bluetooth here fails spectacularly for no reasons and I get literally thousands of lines in dmesg log.

PLEASE implement rate limiting or something.

$ journalctl -b | grep hci0 | wc -l
4257

This is all within three seconds!

...
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
...


Bluetooth: Core ver 2.22
NET: Registered PF_BLUETOOTH protocol family
Bluetooth: HCI device and connection manager initialized
Bluetooth: HCI socket layer initialized
Bluetooth: L2CAP socket layer initialized
Bluetooth: SCO socket layer initialized
Bluetooth: hci0: Found device firmware: intel/ibt-18-16-1.sfi
Bluetooth: hci0: Boot Address: 0x40800
Bluetooth: hci0: Firmware Version: 207-35.21
Bluetooth: hci0: Firmware already loaded

The device is: Bus 003 Device 002: ID 8087:0025 Intel Corp. Wireless-AC 9260 Bluetooth Adapter
Comment 1 Artem S. Tashkinov 2022-01-24 21:58:08 UTC
Would be great if the CC'ed people addressed this bug.
Comment 2 Artem S. Tashkinov 2022-01-24 22:27:34 UTC
This happens when I try to connect my BT headphones and then something goes awry. Maybe 1 out of 50 attempts fail this way.
Comment 3 Paul Menzel 2022-01-25 07:48:43 UTC
Is this a regression? Please attach the full output of `dmesg`, and `hciconfig`, and `lsusb` and `/sys/kernel/debug/usb/devices`.
Comment 4 Artem S. Tashkinov 2022-01-25 10:15:56 UTC
Created attachment 300316 [details]
/sys/kernel/debug/usb/devices

(In reply to Paul Menzel from comment #3)
> Is this a regression? Please attach the full output of `dmesg`, and
> `hciconfig`, and `lsusb` and `/sys/kernel/debug/usb/devices`.

This is not a regression, I had this issue with previous kernels as well.

I'm not sure why you need all this info but whatever:

hci0:	Type: Primary  Bus: USB
	BD Address: 48:89:E7:XX:XX:XX  ACL MTU: 1021:4  SCO MTU: 96:6
	UP RUNNING PSCAN 
	RX bytes:1738 acl:0 sco:0 events:200 errors:0
	TX bytes:19726 acl:0 sco:0 commands:200 errors:0

Bus 008 Device 002: ID 2109:0813 VIA Labs, Inc. VL813 Hub
Bus 008 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 007 Device 004: ID 046d:c084 Logitech, Inc. G203 Gaming Mouse
Bus 007 Device 003: ID 046d:c31d Logitech, Inc. Media Keyboard K200
Bus 007 Device 002: ID 2109:2813 VIA Labs, Inc. VL813 Hub
Bus 007 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 006 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 005 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 004 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 003 Device 003: ID 0b05:18f3 ASUSTek Computer, Inc. AURA LED Controller
Bus 003 Device 004: ID 8087:0025 Intel Corp. Wireless-AC 9260 Bluetooth Adapter
Bus 003 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 002 Device 001: ID 1d6b:0003 Linux Foundation 3.0 root hub
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Comment 5 Artem S. Tashkinov 2022-01-25 10:20:18 UTC
dmesg will have to wait, I don't want to reboot yet.

After all these errors I've updated the firmware just in case:

...
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
Bluetooth: hci0: urb 000000001aab8aa3 submission failed (90)
Bluetooth: hci0: sending frame failed (-90)
usbcore: deregistering interface driver btusb
usbcore: registered new interface driver btusb
Bluetooth: hci0: Found device firmware: intel/ibt-18-16-1.sfi
Bluetooth: hci0: Boot Address: 0x40800
Bluetooth: hci0: Firmware Version: 207-35.21
Bluetooth: hci0: Firmware already loaded
show_signal_msg: 20 callbacks suppressed
Bluetooth: hci0: Ignoring error of Inquiry Cancel command
usbcore: deregistering interface driver btusb
Bluetooth: hci0: urb 000000009344aaa5 failed to resubmit (2)
usbcore: registered new interface driver btusb
Bluetooth: hci0: Found device firmware: intel/ibt-18-16-1.sfi
Bluetooth: hci0: Boot Address: 0x40800
Bluetooth: hci0: Firmware Version: 86-46.21
usb 3-5: USB disconnect, device number 2
Bluetooth: hci0: command 0xfc01 tx timeout
usbcore: deregistering interface driver btusb
Bluetooth: hci0: FW download error recovery failed (-110)
usb 3-5: new full-speed USB device number 4 using xhci_hcd
usb 3-5: New USB device found, idVendor=8087, idProduct=0025, bcdDevice= 0.02
usb 3-5: New USB device strings: Mfr=0, Product=0, SerialNumber=0
usbcore: registered new interface driver btusb
Bluetooth: hci0: Bootloader revision 0.1 build 42 week 52 2015
Bluetooth: hci0: Device revision is 2
Bluetooth: hci0: Secure boot is enabled
Bluetooth: hci0: OTP lock is enabled
Bluetooth: hci0: API lock is enabled
Bluetooth: hci0: Debug lock is disabled
Bluetooth: hci0: Minimum firmware build 1 week 10 2014
Bluetooth: hci0: Found device firmware: intel/ibt-18-16-1.sfi
Bluetooth: hci0: Waiting for firmware download to complete
Bluetooth: hci0: Firmware loaded in 1142406 usecs
Bluetooth: hci0: Waiting for device to boot
Bluetooth: hci0: Device booted in 14837 usecs
Bluetooth: hci0: Found Intel DDC parameters: intel/ibt-18-16-1.ddc
Bluetooth: hci0: Applying Intel DDC parameters completed
Bluetooth: hci0: Firmware revision 0.1 build 86 week 46 2021
usbcore: deregistering interface driver btusb
usbcore: registered new interface driver btusb
Bluetooth: hci0: Found device firmware: intel/ibt-18-16-1.sfi
Bluetooth: hci0: Boot Address: 0x40800
Bluetooth: hci0: Firmware Version: 86-46.21
Bluetooth: hci0: Firmware already loaded
Comment 6 Artem S. Tashkinov 2022-01-25 10:35:10 UTC
Looks like I have to reboot, now I get hundreds of messages like this:

Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 48
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 48
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 48
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 257
Bluetooth: hci0: SCO packet for unknown connection handle 257
Bluetooth: hci0: SCO packet for unknown connection handle 257

I'm kinda appalled by how logging in the BT module is handled. Has it ever occurred to anyone that there's no need to dump hundreds of nearly exactly the same messages?
Comment 7 Artem S. Tashkinov 2022-01-25 10:42:42 UTC
Created attachment 300317 [details]
dmesg

Had to reboot to revive the BT stack otherwise despite it working I continued to receive hundreds of messages per second.
Comment 8 Artem S. Tashkinov 2022-01-25 15:06:26 UTC
Here's another batch of errors when my BT headphones connected before they have been formally authorized:

Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 48
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 48
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 48
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 0
Bluetooth: hci0: SCO packet for unknown connection handle 257
Bluetooth: hci0: SCO packet for unknown connection handle 257
Bluetooth: hci0: SCO packet for unknown connection handle 257

What a bloody mess.
Comment 9 Artem S. Tashkinov 2022-01-25 15:13:02 UTC
After deauthorizing and unpairing and then connecting them manually, the errors stopped.
Comment 10 Artem S. Tashkinov 2022-02-15 11:32:26 UTC
Can you please rate limit these messages for Christ's sake?

Specially "SCO packet for unknown connection handle X" - I'm not even sure they should be logged in the first place unless debugging is enabled.
Comment 12 Artem S. Tashkinov 2022-02-16 22:50:20 UTC
Thank you.

I hope to see it in 5.15.
Comment 13 Artem S. Tashkinov 2022-03-25 10:48:18 UTC
@Luiz Von Dentz

Why doesn't Linux 5.17 include this patch? Could you please push it to stable?
Comment 14 Luiz Von Dentz 2022-03-25 18:24:45 UTC
(In reply to Artem S. Tashkinov from comment #12)
> Thank you.
> 
> I hope to see it in 5.15.

afaik the changes that caused this issue were introduced in 5.17 so 5.15 shouldn't be affected.
Comment 15 Luiz Von Dentz 2022-03-25 18:26:36 UTC
(In reply to Artem S. Tashkinov from comment #13)
> @Luiz Von Dentz
> 
> Why doesn't Linux 5.17 include this patch? Could you please push it to
> stable?

I thought Cc: stable@vger.kernel.org was just for severe bugs not something like this that has almost no effect other than spam dmesg.

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