search

RPi-Distro / pi-bluetooth

Loads BCM43430A1 firmware on boot
42 stars 34 forks source link

regression from 0.8 to 0.9 -- BLE connection fails until bluetooth service is restarted #8

Closed ecc1 closed 2 years ago

ecc1 commented 5 years ago

After upgrading from 0.8 to 0.9, I can no longer connect to a BLE-based medical device (the BLE Connect or Pair operation times out with no response). The problem is still there with version 0.10.

If I do "systemctl restart bluetooth" some time after the system has already booted, it then works. I haven't determined how soon I can do this (in rc.local for example); so far it's been after the system comes up, I ssh in, and run that command from the command line.

So there's something related to the timing or initialization of the bluetooth service that's the issue. The BLE connection attempts after the Pi comes up are failing until I restart bluetooth, and then they all succeed.

Basic BT commands like discovery do work as soon as the system boots, just not the BLE connection ones that I'm using (Connect and Pair, I think).

If there's a particular kind of logging or sniffing I can capture to help debug this, please let me know.

XECDesign commented 5 years ago

Looking at what has changed, nothing obvious jumps out: https://github.com/RPi-Distro/pi-bluetooth/compare/0dffacec9452b975ed7c17b530e4f230ea17b727...8eb959ccd9490a390cb63c120a021a588a663795

The main change is using udev to start the service, but if basic commands work, then we know the service was started. It shouldn't matter how.

ecc1 commented 5 years ago

But clearly when it's started does make a difference, completely repeatably.

XECDesign commented 5 years ago

Yup, I'm not doubting that there's an issue, it's just trickier than I initially thought.

@pelwell will know if there's any sniffing mechanism.

pelwell commented 5 years ago

Which model of Pi is this? You neglected to mention.

ecc1 commented 5 years ago

Pi Zero W, running stock Raspbian stretch. I reproduced the problem on a couple of them.

JohnRucker commented 5 years ago

I have this exact same issue but I'm running bluez version 5.50 on my Pi Zero W. Here is a post on the details. When I restart bluetooth everything works fine. My issue is around resolving a bound public bluetooth LE device address. I wonder if your medical device was bound and you are seeing the same problem. I'm thinking it has something to do with the boot order of bluetooth. What is the status of this issue?

chickenburgers commented 5 years ago

Same problem (RPi3, 4.9.35 kernel, BlueZ 5.50)

After much digging, I noticed that this problem is caused by the state the bluetooth chip is in at the time BlueZ is fired up (you can check the state with hciconfig hci0). If it's in "UP RUNNING" state or in "UP RUNNING PSCAN ISCAN" state, BlueZ complains with one or more of these:

Failed to set mode: Rejected (0x0b) Failed to set mode: Rejected (0x0b) Failed to set privacy: Rejected (0x0b)

But if it's in "DOWN" state, BlueZ starts with no issues. So, you first have to do hciconfig hci0 down before the bluetooth service starts up. But before you can use hciconfig, you also need to ensure the sys-subsystem-bluetooth-devices-hci0.device service has started! I ended up disabling the automatic boot sequence, and run this script instead:

systemctl start sys-subsystem-bluetooth-devices-hci0.device; hciconfig hci0 down; systemctl start bluetooth

bwindsor commented 5 years ago

Same problem (RPi3, 4.9.98 kernel, BlueZ 5.50)

Delaying the running of bthelper by a couple of seconds fixed this issue for me, without me having to disable the automatic boot sequence and run any manual commands.

I added an ExecStartPre line to /lib/systemd/system/bthelper@.service such that the Service section now looks like this:

[Service]
Type=simple
ExecStartPre=/bin/sleep 2
ExecStart=/usr/bin/bthelper %I

Adding a delay feels a bit hacky, but if people think it's legitimate I'll make a PR.

Explanation: As @chickenburgers says, the "Rejected (0x0b)" error is related to the state of hci0. The service bthelper@hci0.service runs once the following two conditions are satisfied:

  1. hci0 is available as a device (enforced by udev rule located at /lib/udev/rules.d/90-pi-bluetooth.rules
  2. bluetooth.service is started (enforced by the Requires and After properties in the Unit section of /lib/systemd/system/bthelper@.service

The thing is, the moment bluetooth.service starts, so does bthelper@.service, it doesn't wait for the bluetooth service to be fully up and running, so by the time bluetoothd (started by bluetooth.service) runs whichever command is generating the error, bthelper has already run. Adding a delay allows bluetoothd to get its act together before hci0 up is run by bthelper

ecc1 commented 5 years ago

I can confirm that the 2-second sleep fixes the problem I initially reported.

The delay doesn't seem very systemd-ish, but I don't know what event could be used to wait "properly".

DrCWO commented 3 years ago

I ran into the same issue on a Pi4. On some units bluetoothd started fine on other units I got the error "Loading LTKs timed out for hci0" in the log. After trying to reproduce ist I found, that even on the same unit sometimes it works, sometimes it fails. Restart of bluetooth.service did not fix the issue. Your solution is the only one reliable :-) My guess it there is a racing condition between the Bluetooth transmitter and the ARM. As faster the ARM the earlier bluetoothd is started and sometimes the transmitter is not yet ready. Thanks's a lot for your patch. In my eyes this should be includes in the official Raspbian release.

chanjuping commented 3 years ago

I am using a Pi4 8GB with a fresh install of Raspberry Pi OS, kernel 5.10.17-v7l+ and found my way here after struggling with attempt to pair my mouse that worked just fine with a Pi4 2GB board that I also own.

Thanks for the solution here.

systemctl start sys-subsystem-bluetooth-devices-hci0.device; hciconfig hci0 down; systemctl start bluetooth

I tried the 2 second delay solution but it didn't work for me. Not even when I extended it to 8 seconds.

Instead running a simplified version of the hci0 solution above fixes it for me every time

hciconfig hci0 down; systemctl restart bluetooth

chanjuping commented 3 years ago

I just confirmed this is also an issue with Ubuntu Mate as well. Thankfully the manual solution also works.

mhalano commented 3 years ago

I'm trying to set LE privacy but I only can do it when the hci0 interface is down. I need LE privacy enabled so I can pair my Xbox Controller. Any tips? I posted here because it seems related with this issue.

JonLevin25 commented 3 years ago

Same problem (RPi3, 4.9.98 kernel, BlueZ 5.50)

Delaying the running of bthelper by a couple of seconds fixed this issue for me, without me having to disable the automatic boot sequence and run any manual commands.

I added an ExecStartPre line to /lib/systemd/system/bthelper@.service such that the Service section now looks like this:

[Service]
Type=simple
ExecStartPre=/bin/sleep 2
ExecStart=/usr/bin/bthelper %I

Adding a delay feels a bit hacky, but if people think it's legitimate I'll make a PR.

Explanation: As @chickenburgers says, the "Rejected (0x0b)" error is related to the state of hci0. The service bthelper@hci0.service runs once the following two conditions are satisfied:

  1. hci0 is available as a device (enforced by udev rule located at /lib/udev/rules.d/90-pi-bluetooth.rules
  2. bluetooth.service is started (enforced by the Requires and After properties in the Unit section of /lib/systemd/system/bthelper@.service

The thing is, the moment bluetooth.service starts, so does bthelper@.service, it doesn't wait for the bluetooth service to be fully up and running, so by the time bluetoothd (started by bluetooth.service) runs whichever command is generating the error, bthelper has already run. Adding a delay allows bluetoothd to get its act together before hci0 up is run by bthelper

Sorry to necro this- but trying to use this workaround, and my service type had oneshot as the default. The snippet above uses simple.

Is changing the service type relevant to the fix- or is it better to leave it be?

DrCWO commented 3 years ago

This is what I see in dmesg

[1142377.586319] microsoft 0005:045E:091B.0043: unsupported Resolution Multiplier 0

[1142377.673038] microsoft 0005:045E:091B.0043: unsupported Resolution Multiplier 3600

[1142377.673174] input: Surface Dial System Multi Axis as /devices/virtual/misc/uhid/0005:045E:091B.0043/input/input254

[1142377.673401] input: Surface Dial System Control as /devices/virtual/misc/uhid/0005:045E:091B.0043/input/input256

[1142377.673590] microsoft 0005:045E:091B.0043: input,hidraw5: BLUETOOTH HID v2.00 Device [Surface Dial] on B8:27:EB:7C:65:C8

Best DrCWO

Von: JonLevin25 @.> Gesendet: Montag, 13. September 2021 18:52 An: RPi-Distro/pi-bluetooth @.> Cc: DrCWO @.>; Comment @.> Betreff: Re: [RPi-Distro/pi-bluetooth] regression from 0.8 to 0.9 -- BLE connection fails until bluetooth service is restarted (#8)

Same problem (RPi3, 4.9.98 kernel, BlueZ 5.50)

Delaying the running of bthelper by a couple of seconds fixed this issue for me, without me having to disable the automatic boot sequence and run any manual commands.

I added an ExecStartPre line to @.*** such that the Service section now looks like this:

[Service] Type=simple ExecStartPre=/bin/sleep 2 ExecStart=/usr/bin/bthelper %I

Adding a delay feels a bit hacky, but if people think it's legitimate I'll make a PR.

Explanation: As @chickenburgers https://github.com/chickenburgers says, the "Rejected (0x0b)" error is related to the state of hci0. The service @.*** runs once the following two conditions are satisfied:

  1. hci0 is available as a device (enforced by udev rule located at /lib/udev/rules.d/90-pi-bluetooth.rules
  2. bluetooth.service is started (enforced by the Requires and After properties in the Unit section of @.***

The thing is, the moment bluetooth.service starts, so does @.***, it doesn't wait for the bluetooth service to be fully up and running, so by the time bluetoothd (started by bluetooth.service) runs whichever command is generating the error, bthelper has already run. Adding a delay allows bluetoothd to get its act together before hci0 up is run by bthelper

Sorry to necro this- but trying to use this workaround, and my service Type is oneshot. The snippet above has simple.

Is changing the service type relevant to the fix- or is it better to leave it be?

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/RPi-Distro/pi-bluetooth/issues/8#issuecomment-918382799 , or unsubscribe https://github.com/notifications/unsubscribe-auth/APRCIDTYENDPFXCLWPLUHR3UBYT25ANCNFSM4GHBAJ4A . Triage notifications on the go with GitHub Mobile for iOS https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Android https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub .

bwindsor commented 2 years ago

Since my last comment there have been some changes committed to the RPi repository. It appears that these changes are causing Failed to set privacy: Rejected (0x0b) to occur again.

Replying to @JonLevin25 The service type has changed to oneshot because of this commit but that is not the issue.

So now, I have changed my /lib/systemd/system/bthelper@.service to look like this and all is working again. Changes from the default are to add the ExecStartPre line (as in the previous solution) and then in the [Unit] section, remove the Before=bluetooth.service and add bluetooth.service to the After section.

[Unit]
Description=Raspberry Pi bluetooth helper
Requires=hciuart.service bluetooth.service
After=hciuart.service bluetooth.service

[Service]
Type=oneshot
ExecStartPre=/bin/sleep 2
ExecStart=/usr/bin/bthelper %I
RemainAfterExit=yes
defanator commented 2 years ago

@bwindsor I've been facing a similar issue on retropie (powered by Raspberry Pi 3) and Xbox Wireless Controller (model 1914). Your workaround described here worked fine, but I decided to proceed with systemd override instead of changing the unit directly, so I did systemctl edit bthelper@ and added the following:

[Unit]
After=hciuart.service bluetooth.service
Before=

[Service]
ExecStartPre=/bin/sleep 5

Now everything's good, controller gets connected almost instantly after every reboot.

(Override config shouldn't prevent package manager to update original unit in case of any future changes.)

Related topic at retropie site (JFTR): https://retropie.org.uk/forum/topic/28560/xbox-series-x-controller-wont-pair-with-rp4

pelwell commented 2 years ago

The change in the RPi Bluetooth scripts was triggered by the aim to also support Bluetooth when the modem is initialised by the kernel, instead of by hciattach (which has been deprecated for some time). That requires a different initialisation sequence, and in my testing the changes made seemed to support both modes of operation.

Those of you who are having problems might want to try adding dtparam=krnbt to config.txt, to see if that improves things.

icecube45 commented 2 years ago

For those still having issues, it might be worth using krnbt + bluez 5.63 I was having a ton of bluetooth connect issues (along with bluetoothd segfaults and the like), and drove myself near insane trying to find a workaround until I tried the above combo. (Truthfully the bluez upgrade is what I believe fixed it, but krnbt appears to have some boot speed improvements, maybe I'm imagining it).

I installed Bluez 5.63 with the following:

sudo apt-get install -y libdbus-1-dev libudev-dev libical-dev libreadline-dev libjson-c-dev
wget www.kernel.org/pub/linux/bluetooth/bluez-5.63.tar.xz
tar -xvf bluez-5.63.tar.xz bluez-5.63/
rm bluez-5.63.tar.xz
cd bluez-5.63
./configure --prefix=/usr --sysconfdir=/etc --localstatedir=/var --enable-library --disable-manpages --enable-deprecated
make
sudo make install
XECDesign commented 2 years ago

@pelwell IIRC you reworked some of the systemd services to fix the issue? Can this one be closed now or is it still an issue?

pelwell commented 2 years ago

I'm closing it because if there are any issues remaining they are different to those for which this issue was opened.

shawnnolanjr commented 2 years ago

Actually, I have a project that was working just fine connecting to my app (iPhone), and after doing an apt update it stopped working. Even trying to connect with LightBlue I get an error "failed to connect to the peripheral". I've been stuck on this for like a month now, and just stumbled upon this thread finally. Hopefully there's a fix, or some sort of solution outside of the bthelper.service file?

That being said, using hcidump I get the following:

HCI sniffer - Bluetooth packet analyzer ver 5.50
device: hci0 snap_len: 1500 filter: 0xffffffff
> HCI Event: Command Status (0x0f) plen 4
    LE Read Remote Used Features (0x08|0x0016) status 0x00 ncmd 1
> HCI Event: Command Complete (0x0e) plen 6
    LE Long Term Key Request Negative Reply (0x08|0x001b) ncmd 1
> HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 64 reason 0x13
    Reason: Remote User Terminated Connection
> HCI Event: Command Complete (0x0e) plen 4
    LE Set Advertise Enable (0x08|0x000a) ncmd 1
    status 0x00

I've tried manually changing the bthelper.service file as suggested above, but that did NOT work for me. Any other suggestions?

Also, just a side note, this is the "status" of bluetooth on the pi: 

pi@raspberrypi:~ $ sudo systemctl status bluetooth
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2022-04-07 21:49:44 PDT; 10h ago
     Docs: man:bluetoothd(8)
 Main PID: 1101 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 877)
   CGroup: /system.slice/bluetooth.service
           └─1101 /usr/lib/bluetooth/bluetoothd

Apr 07 21:49:44 raspberrypi systemd[1]: Starting Bluetooth service...
Apr 07 21:49:44 raspberrypi bluetoothd[1101]: Bluetooth daemon 5.50
Apr 07 21:49:44 raspberrypi systemd[1]: Started Bluetooth service.
Apr 07 21:49:44 raspberrypi bluetoothd[1101]: Starting SDP server
Apr 07 21:49:45 raspberrypi bluetoothd[1101]: Bluetooth management interface 1.18 initialized
Apr 07 21:49:45 raspberrypi bluetoothd[1101]: Sap driver initialization failed.
Apr 07 21:49:45 raspberrypi bluetoothd[1101]: sap-server: Operation not permitted (1)
Apr 07 21:50:17 raspberrypi bluetoothd[1101]: No cache for 5E:C3:4E:8E:4F:02
Apr 07 21:50:17 raspberrypi bluetoothd[1101]: gatt: bt_io_get: getpeername: Transport endpoint is not connected (107)
Apr 07 21:50:36 raspberrypi bluetoothd[1101]: No cache for 5E:C3:4E:8E:4F:02
jpwhiting commented 2 years ago

Actually, I have a project that was working just fine connecting to my app (iPhone), and after doing an apt update it stopped working. Even trying to connect with LightBlue I get an error "failed to connect to the peripheral". I've been stuck on this for like a month now, and just stumbled upon this thread finally. Hopefully there's a fix, or some sort of solution outside of the bthelper.service file?

That being said, using hcidump I get the following:

HCI sniffer - Bluetooth packet analyzer ver 5.50
device: hci0 snap_len: 1500 filter: 0xffffffff
> HCI Event: Command Status (0x0f) plen 4
    LE Read Remote Used Features (0x08|0x0016) status 0x00 ncmd 1
> HCI Event: Command Complete (0x0e) plen 6
    LE Long Term Key Request Negative Reply (0x08|0x001b) ncmd 1
> HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 64 reason 0x13
    Reason: Remote User Terminated Connection
> HCI Event: Command Complete (0x0e) plen 4
    LE Set Advertise Enable (0x08|0x000a) ncmd 1
    status 0x00

I've tried manually changing the bthelper.service file as suggested above, but that did NOT work for me. Any other suggestions?

Also, just a side note, this is the "status" of bluetooth on the pi:

pi@raspberrypi:~ $ sudo systemctl status bluetooth
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2022-04-07 21:49:44 PDT; 10h ago
     Docs: man:bluetoothd(8)
 Main PID: 1101 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 877)
   CGroup: /system.slice/bluetooth.service
           └─1101 /usr/lib/bluetooth/bluetoothd

Apr 07 21:49:44 raspberrypi systemd[1]: Starting Bluetooth service...
Apr 07 21:49:44 raspberrypi bluetoothd[1101]: Bluetooth daemon 5.50
Apr 07 21:49:44 raspberrypi systemd[1]: Started Bluetooth service.
Apr 07 21:49:44 raspberrypi bluetoothd[1101]: Starting SDP server
Apr 07 21:49:45 raspberrypi bluetoothd[1101]: Bluetooth management interface 1.18 initialized
Apr 07 21:49:45 raspberrypi bluetoothd[1101]: Sap driver initialization failed.
Apr 07 21:49:45 raspberrypi bluetoothd[1101]: sap-server: Operation not permitted (1)
Apr 07 21:50:17 raspberrypi bluetoothd[1101]: No cache for 5E:C3:4E:8E:4F:02
Apr 07 21:50:17 raspberrypi bluetoothd[1101]: gatt: bt_io_get: getpeername: Transport endpoint is not connected (107)
Apr 07 21:50:36 raspberrypi bluetoothd[1101]: No cache for 5E:C3:4E:8E:4F:02

I'm getting similar output from bluetooth.service on a pi 3b here also. After reading https://raspberrypi.stackexchange.com/questions/40839/sap-error-on-bluetooth-service-status I added --noplugin=sap to the bluetooth.service file which fixes the first 2 errors there, but I'm still getting the "Failed to set privacy: Rejected (0x0b)" error. so still cannot pair phone to pi.

vChavezB commented 2 years ago

@jpwhiting Did you manage to fix this error?

Failed to set privacy: Rejected (0x0b)

jpwhiting commented 2 years ago

I think reinstalling got around it. I regularly do apt updates lately and don't have any locally built sources. Sorry that's likely not very helpful.

vChavezB commented 2 years ago

I think reinstalling got around it. I regularly do apt updates lately and don't have any locally built sources. Sorry that's likely not very helpful.

Well coincidentally, I decided to reinstall the linux image and use the x64 version and so far I havent had this problem anymore. Still not sure where the error originated from.

sliterok commented 1 year ago

omg why reinstalling even an option? are we in the stone age? I'm also struggling with fixing this error...

BenjD90 commented 1 year ago

omg why reinstalling even an option? are we in the stone age? I'm also struggling with fixing this error...

Hello,

I've just followed this workaround and the error on startup has disappeared : https://github.com/RPi-Distro/pi-bluetooth/issues/8#issuecomment-988969020

I tried at first to uninstall/re-install the apt package, but nothing had changed.

OrangeDog commented 2 months ago

Some additional clarifications and findings (Bookworm images on ZeroW and Zero2).

you also need to ensure the sys-subsystem-bluetooth-devices-hci0.device service has started

The device is still not always immediately available after that unit is ready. I have to poll and retry hciconfig commands and I saw it take over a minute once before it was actually ready (after the kernel message Bluetooth: hci0: BCM43430B0 (002.001.012) build 0092 or whatever your firmware version is).

it doesn't wait for the bluetooth service to be fully up and running

A Type=simple is "ready" when it has started. A Type=oneshot is ready when it has finished. Type=dbus is ready when it specifically signals that it is. That was probably most of the problem.

I don't get any Rejected (0x0b) errors, but it appears that bthelper@hci0 is no longer triggered at all anyway. If it were, it now specifies Before=bluetooth.service.