search

Hexxeh / rpi-firmware

Firmware files for the Raspberry Pi
Other
775 stars 208 forks source link

Bluetooth stack broken on latest firmware #238

Open blacklight opened 3 years ago

blacklight commented 3 years ago

I ran an rpi-update a few days ago to test if it solved some SPI CS issues, and since then the Bluetooth stack on my Raspbian on RPi4 has been broken (although I can't completely rule out if it was broken before).

I've tried since then to roll back to the previous stable firmware version:

rpi-update 8382ece2b30be0beb87cac7f3b36824f194d01e9

But that hasn't fixed my Bluetooth issues.

I use four Bluetooth interfaces on my device - the onboard Bluetooth and three USB adapters. It seems however that only three interfaces are detected by hciconfig, two of them (hci0 and hci1) actually share the same address, and the fourth one (hci2) has 00:00:00:00:00:00 address and can't be brought up:

hci2:   Type: Primary  Bus: USB
        BD Address: 00:00:00:00:00:00  ACL MTU: 0:0  SCO MTU: 0:0
        DOWN
        RX bytes:581 acl:0 sco:0 events:82 errors:0
        TX bytes:20534 acl:0 sco:0 commands:83 errors:0

hci1:   Type: Primary  Bus: USB
        BD Address: B8:27:EB:10:B5:A7  ACL MTU: 1021:8  SCO MTU: 64:1
        UP RUNNING PSCAN
        RX bytes:2252 acl:0 sco:0 events:129 errors:0
        TX bytes:4782 acl:0 sco:0 commands:129 errors:0

hci0:   Type: Primary  Bus: USB
        BD Address: B8:27:EB:10:B5:A7  ACL MTU: 310:10  SCO MTU: 64:8
        UP RUNNING
        RX bytes:6877 acl:0 sco:0 events:112 errors:0
        TX bytes:8076 acl:115 sco:0 commands:252 errors:0

hciconfig hci2 up
Can't init device hci2: Cannot assign requested address (99)
btmgmt --index 2
[hci2]# auto-power
Found controller with index 2
Successfully enabled controller with index 2
(However, despite the message the controller is still marked as DOWN)

Some relevant dmesg lines:

[Sat Aug  8 13:41:52 2020] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[Sat Aug  8 13:41:52 2020] debugfs: File 'le_min_key_size' in directory 'hci1' already present!
[Sat Aug  8 13:41:52 2020] debugfs: File 'le_max_key_size' in directory 'hci1' already present!
[Sat Aug  8 13:41:52 2020] debugfs: File 'force_bredr_smp' in directory 'hci1' already present!
[Sat Aug  8 13:41:52 2020] debugfs: File 'le_min_key_size' in directory 'hci0' already present!
[Sat Aug  8 13:41:52 2020] debugfs: File 'le_max_key_size' in directory 'hci0' already present!
[Sat Aug  8 13:41:52 2020] debugfs: File 'force_bredr_smp' in directory 'hci0' already present!
...
[Sat Aug  8 13:41:55 2020] Bluetooth: hci2: RTL: download fw command failed (-110)
...
[Sat Aug  8 13:42:03 2020] usb 1-1.4: 1:1: cannot get freq at ep 0x3
[Sat Aug  8 13:42:03 2020] usb 1-1.4: 1:1: cannot get freq at ep 0x3

Then, upon hci2 unplug/plug:

[Sat Aug  8 13:50:28 2020] usb 1-1.2.2: new full-speed USB device number 15 using xhci_hcd
[Sat Aug  8 13:50:28 2020] usb 1-1.2.2: New USB device found, idVendor=0bda, idProduct=8771, bcdDevice= 2.00
[Sat Aug  8 13:50:28 2020] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[Sat Aug  8 13:50:28 2020] usb 1-1.2.2: Product: Bluetooth Radio
[Sat Aug  8 13:50:28 2020] usb 1-1.2.2: Manufacturer: Realtek
[Sat Aug  8 13:50:28 2020] usb 1-1.2.2: SerialNumber: 00E04C239987
[Sat Aug  8 13:50:28 2020] Bluetooth: hci2: RTL: examining hci_ver=0a hci_rev=000b lmp_ver=0a lmp_subver=8761
[Sat Aug  8 13:50:28 2020] Bluetooth: hci2: RTL: rom_version status=0 version=1
[Sat Aug  8 13:50:28 2020] Bluetooth: hci2: RTL: loading rtl_bt/rtl8761a_fw.bin
[Sat Aug  8 13:50:28 2020] Bluetooth: hci2: RTL: loading rtl_bt/rtl8761a_config.bin
[Sat Aug  8 13:50:28 2020] bluetooth hci2: Direct firmware load for rtl_bt/rtl8761a_config.bin failed with error -2
[Sat Aug  8 13:50:28 2020] Bluetooth: hci2: RTL: cfg_sz -2, total sz 20204
[Sat Aug  8 13:50:30 2020] Bluetooth: hci2: command 0xfc20 tx timeout
[Sat Aug  8 13:50:38 2020] Bluetooth: hci2: RTL: download fw command failed (-110)

Can anyone advise on what's going on here?

blacklight commented 3 years ago

Bump - even reverting the firmware and upgrading to the latest kernel (20200811) hasn't fixed the situation - one controller is missing, and one has 00:00:00:00:00:00 and can't be brought up.

pelwell commented 3 years ago

The bthelper script, which is intended to support the built-in Bluetooth interface, actually seems to be run for all Bluetooth interfaces. Previously this must have been relatively harmless, but the change to set the BDADDR (intended for when hciattach is bypassed by letting the kernel initialise Bluetooth on the UART) has inintentionally affected all interfaces.

I'm going to have to fix this, @XECDesign.

pelwell commented 3 years ago

It doesn't help that the ancient D-Link dongle I have ignores the address change (or bdaddr ignores it).

pelwell commented 3 years ago

What output do you get from the following?:

$ systemctl status hciuart
$ systemctl status bthelper@hci0
$ systemctl status bthelper@hci1
$ systemctl status bthelper@hci2
blacklight commented 3 years ago 
systemctl status hciuart
● hciuart.service - Configure Bluetooth Modems connected by UART
   Loaded: loaded (/lib/systemd/system/hciuart.service; enabled; vendor preset: enabled)
   Active: inactive (dead) since Sun 2020-08-16 23:28:06 CEST; 18h ago
  Process: 449 ExecStart=/usr/bin/btuart (code=exited, status=0/SUCCESS)

Aug 16 23:28:06 turing systemd[1]: Starting Configure Bluetooth Modems connected by UART...
Aug 16 23:28:06 turing systemd[1]: hciuart.service: Succeeded.
Aug 16 23:28:06 turing systemd[1]: Started Configure Bluetooth Modems connected by UART.
systemctl status bthelper@hci0
● bthelper@hci0.service - Raspberry Pi bluetooth helper
   Loaded: loaded (/lib/systemd/system/bthelper@.service; static; vendor preset: enabled)
   Active: failed (Result: exit-code) since Sun 2020-08-16 23:28:11 CEST; 18h ago
  Process: 567 ExecStart=/usr/bin/bthelper hci0 (code=exited, status=1/FAILURE)
 Main PID: 567 (code=exited, status=1/FAILURE)

Aug 16 23:28:07 turing systemd[1]: Started Raspberry Pi bluetooth helper.
Aug 16 23:28:11 turing bthelper[567]: Can't init device hci0: Cannot assign requested address (99)
Aug 16 23:28:11 turing systemd[1]: bthelper@hci0.service: Main process exited, code=exited, status=1/FAILURE
Aug 16 23:28:11 turing systemd[1]: bthelper@hci0.service: Failed with result 'exit-code'.
systemctl status bthelper@hci1                                                                                                            <<<
● bthelper@hci1.service - Raspberry Pi bluetooth helper
   Loaded: loaded (/lib/systemd/system/bthelper@.service; static; vendor preset: enabled)
   Active: inactive (dead) since Sun 2020-08-16 23:28:19 CEST; 18h ago
  Process: 565 ExecStart=/usr/bin/bthelper hci1 (code=exited, status=0/SUCCESS)
 Main PID: 565 (code=exited, status=0/SUCCESS)

Aug 16 23:28:07 turing systemd[1]: Started Raspberry Pi bluetooth helper.
Aug 16 23:28:07 turing bthelper[565]: Not a UART-attached BT Modem
Aug 16 23:28:07 turing bthelper[565]: Raspberry Pi BDADDR already set
Aug 16 23:28:08 turing bthelper[565]: Changing power off succeeded
Aug 16 23:28:08 turing bthelper[565]: [CHG] Controller B8:27:EB:10:B5:A7 Powered: no
Aug 16 23:28:08 turing bthelper[565]: [CHG] Controller B8:27:EB:10:B5:A7 Discovering: no
Aug 16 23:28:08 turing bthelper[565]: [CHG] Controller B8:27:EB:10:B5:A7 Class: 0x00000000
Aug 16 23:28:08 turing bthelper[565]: [CHG] Controller B8:27:EB:10:B5:A7 Class: 0x00480000
Aug 16 23:28:08 turing bthelper[565]: Changing power on succeeded
Aug 16 23:28:19 turing systemd[1]: bthelper@hci1.service: Succeeded.
systemctl status bthelper@hci2                                                                                                            <<<
● bthelper@hci2.service - Raspberry Pi bluetooth helper
   Loaded: loaded (/lib/systemd/system/bthelper@.service; static; vendor preset: enabled)
   Active: inactive (dead) since Sun 2020-08-16 23:28:08 CEST; 18h ago
  Process: 563 ExecStart=/usr/bin/bthelper hci2 (code=exited, status=0/SUCCESS)
 Main PID: 563 (code=exited, status=0/SUCCESS)

Aug 16 23:28:07 turing systemd[1]: Started Raspberry Pi bluetooth helper.
Aug 16 23:28:07 turing bthelper[563]: Not a UART-attached BT Modem
Aug 16 23:28:08 turing bthelper[563]: Manufacturer:   Broadcom Corporation (15)
Aug 16 23:28:08 turing bthelper[563]: Device address: 5C:F3:70:81:97:29 (CC&C Technologies, Inc)
Aug 16 23:28:08 turing bthelper[563]: New BD address: B8:27:EB:10:B5:A7 (Raspberry Pi Foundation)
Aug 16 23:28:08 turing bthelper[563]: Address changed - Reset device now
Aug 16 23:28:08 turing bthelper[563]: Changing power off succeeded
Aug 16 23:28:08 turing bthelper[563]: Changing power on succeeded
Aug 16 23:28:08 turing systemd[1]: bthelper@hci2.service: Succeeded.

The hci interface indexes change on each boot (btw is there a way to make the assignment static via udev?), so this is the current state:

hciconfig
hci2:   Type: Primary  Bus: USB
        BD Address: B8:27:EB:10:B5:A7  ACL MTU: 1021:8  SCO MTU: 64:1
        UP RUNNING
        RX bytes:21808 acl:0 sco:0 events:126 errors:0
        TX bytes:22382 acl:479 sco:0 commands:690 errors:0

hci1:   Type: Primary  Bus: USB
        BD Address: B8:27:EB:10:B5:A7  ACL MTU: 310:10  SCO MTU: 64:8
        UP RUNNING
        RX bytes:1880 acl:0 sco:0 events:115 errors:0
        TX bytes:4253 acl:0 sco:0 commands:116 errors:0

hci0:   Type: Primary  Bus: USB
        BD Address: 00:00:00:00:00:00  ACL MTU: 0:0  SCO MTU: 0:0
        DOWN
        RX bytes:581 acl:0 sco:0 events:82 errors:0
        TX bytes:20534 acl:0 sco:0 commands:83 errors:0

Note that hci1 and hci2 have the same address, and it seems that the initial address for hci2 is correct but it's overridden:

Aug 16 23:28:08 turing bthelper[563]: Device address: 5C:F3:70:81:97:29 (CC&C Technologies, Inc)
Aug 16 23:28:08 turing bthelper[563]: New BD address: B8:27:EB:10:B5:A7 (Raspberry Pi Foundation)

The error on hci0 (99 - Address not available) makes me speculate that the bthelper tries to assign that same address to the other adapter as well.

pelwell commented 3 years ago

There's a bug in the bthelper script that prevents the UART-attached BT modem restriction from working. If you're feeling brave, try this patch. With your favourite editor running, edit /usr/bin/bthelper as root, e.g. sudo nano /usr/bin/bthelper, and change:

/bin/hciconfig $dev | grep -q "Bus: UART" ||
    (echo Not a UART-attached BT Modem; exit 0)

to:

if ! /bin/hciconfig $dev | grep -q "Bus: UART"; then
    echo Not a UART-attached BT Modem
    exit 0
fi

Being in the sub-shell prevented the exit 0 from ending the script - it just ended the sub-shell, which was going to happen anyway.

blacklight commented 3 years ago

Ok, that apparently fixed the issue with the duplicate Bluetooth address, but I've still got the one with hci0 being down and without a valid address assigned:

hci2:   Type: Primary  Bus: USB
        BD Address: 5C:F3:70:81:97:29  ACL MTU: 1021:8  SCO MTU: 64:1
        UP RUNNING PSCAN
        RX bytes:2768 acl:0 sco:0 events:173 errors:0
        TX bytes:6301 acl:0 sco:0 commands:168 errors:0

hci1:   Type: Primary  Bus: USB
        BD Address: B8:27:EB:10:B5:A7  ACL MTU: 310:10  SCO MTU: 64:8
        UP RUNNING
        RX bytes:6960 acl:0 sco:0 events:77 errors:0
        TX bytes:8246 acl:134 sco:0 commands:232 errors:0

hci0:   Type: Primary  Bus: USB
        BD Address: 00:00:00:00:00:00  ACL MTU: 0:0  SCO MTU: 0:0
        DOWN
        RX bytes:581 acl:0 sco:0 events:82 errors:0
        TX bytes:20534 acl:0 sco:0 commands:83 errors:0
pelwell commented 3 years ago

I'm suspicious that hci1 appears to have kept it's Pi BDADDR (b8:27:eb:xx:yy:zz) - you might have to reprogram it to something unique like 5c:f4:70:81:97:2a.

hci2 looks to have a driver/firmware problem - there are other reports of the same errors: https://forums.linuxmint.com/viewtopic.php?p=1810390

The solution appears to be to back-port a patch from 5.8 - I'm doing that now - and grab the firmware from somewhere. There's a link in this README: https://gist.github.com/rometsch/dfd24fb09c85c1ad2f25223dc1481aaa Note that for Raspberry Pi OS the firmware has to go in /lib/firmware/rtl_bt/...

pelwell commented 3 years ago

The back-port is in rpi-5.4.y now, and will be in future builds.

blacklight commented 3 years ago

Thanks! Is it still required to keep the changes on bthelper or will they be included in the next release of pi-bluetooth as well?

If the next raspberrypi-kernel will include the firmware backport then I can wait for it to fix the issue with the other dongle - this is a machine I use for many critical things and I'd rather not play too much with custom kernel builds.

pelwell commented 3 years ago

The bthelper change (along with another) will be in the next pi-bluetooth package, which will overwrite your patched version. Likewise, the next raspberrypi-kernel package will include the driver back-port, but not the firmware - that's currently not in the kernel firmware repo, and we'd rather not take firmware from random places.

blacklight commented 3 years ago

I have run an upgrade on this machine and installed the latest kernel:

$ uname -r
5.4.51-v7l+

And I have copied the firmware files following the reported procedure.

However, I've still got this situation:

$ hciconfig
hci2:   Type: Primary  Bus: USB
        BD Address: 5C:F3:70:81:97:29  ACL MTU: 1021:8  SCO MTU: 64:1
        UP RUNNING PSCAN
        RX bytes:1596 acl:0 sco:0 events:88 errors:0
        TX bytes:4051 acl:0 sco:0 commands:88 errors:0

hci1:   Type: Primary  Bus: USB
        BD Address: B8:27:EB:10:B5:A7  ACL MTU: 310:10  SCO MTU: 64:8
        UP RUNNING
        RX bytes:1400 acl:0 sco:0 events:77 errors:0
        TX bytes:3660 acl:0 sco:0 commands:93 errors:0

hci0:   Type: Primary  Bus: USB
        BD Address: 00:00:00:00:00:00  ACL MTU: 0:0  SCO MTU: 0:0
        DOWN
        RX bytes:581 acl:0 sco:0 events:82 errors:0
        TX bytes:20540 acl:0 sco:0 commands:83 errors:0

dmesg:

$ dmesg -T | grep hci0
[Sat Aug 29 18:20:22 2020] Bluetooth: hci0: RTL: examining hci_ver=0a hci_rev=000b lmp_ver=0a lmp_subver=8761
[Sat Aug 29 18:20:22 2020] Bluetooth: hci0: RTL: rom_version status=0 version=1
[Sat Aug 29 18:20:22 2020] Bluetooth: hci0: RTL: loading rtl_bt/rtl8761a_fw.bin
[Sat Aug 29 18:20:22 2020] Bluetooth: hci0: RTL: loading rtl_bt/rtl8761a_config.bin
[Sat Aug 29 18:20:22 2020] Bluetooth: hci0: RTL: cfg_sz 6, total sz 20210
[Sat Aug 29 18:20:24 2020] Bluetooth: hci0: command 0xfc20 tx timeout
[Sat Aug 29 18:20:33 2020] Bluetooth: hci0: RTL: download fw command failed (-110)

Note this:

Bluetooth: hci0: RTL: loading rtl_bt/rtl8761a_fw.bin

While, according to what other users reported, it should be:

Bluetooth: hci0: RTL: loading rtl_bt/rtl8761b_fw.bin

So it's still trying to load the rtl8761a firmware, as reported here.

Has the driver been backported in the latest RPi kernel?

-- EDIT --

It seems indeed that the new firmware file isn't there:

$ strings /lib/modules/5.4.51-v7l+/kernel/drivers/bluetooth/btrtl.ko | grep rtl_bt/rtl8761a_fw.bin
firmware=rtl_bt/rtl8761a_fw.bin
rtl_bt/rtl8761a_fw.bin
$ strings /lib/modules/5.4.51-v7l+/kernel/drivers/bluetooth/btrtl.ko | grep rtl_bt/rtl8761b_fw.bin
$