fix service units, bluetooth.service not starting successfully

[va1entin]

Some of the changes in #21 made bluetooth.service stop working on my RPi 4. Only with the changes in this PR it began starting reliably again after rebooting.

I am no bluetooth guru and just debugged the problem using the info systemd and the service units gave me; please consider that when reviewing the changes. :smile:

[pelwell]

@va1entin, @jaharkema - I need to understand how and why your systems are behaving differently to mine. I see from #23 that @jaharkema is using Hassio, so that's one difference, but it might just be timing. Can you run this command when Bluetooth fails to start?:

$ grep -i -E "(bt|blue|\bhci)" /var/log/syslog | tail -100 > btlog.txt

Post the content of btlog.txt. The "tail -100" is a rough and ready attempt to ignore messages from previous boots. There will be a few extra lines at the start, but that's OK.

[va1entin]

@pelwell This is the output for my last reboot using the upstream version of /lib/systemd/system/bthelper@.service and my version of /lib/systemd/system/hciuart.service.

May 20 10:59:02 raspberrypi systemd[1]: Starting Configure Bluetooth Modems connected by UART...
May 20 10:59:09 raspberrypi kernel: [   14.112810] Bluetooth: Core ver 2.22
May 20 10:59:09 raspberrypi kernel: [   14.112910] Bluetooth: HCI device and connection manager initialized
May 20 10:59:09 raspberrypi kernel: [   14.112933] Bluetooth: HCI socket layer initialized
May 20 10:59:09 raspberrypi kernel: [   14.112950] Bluetooth: L2CAP socket layer initialized
May 20 10:59:09 raspberrypi kernel: [   14.112978] Bluetooth: SCO socket layer initialized
May 20 10:59:09 raspberrypi kernel: [   14.121485] Bluetooth: HCI UART driver ver 2.3
May 20 10:59:09 raspberrypi kernel: [   14.121503] Bluetooth: HCI UART protocol H4 registered
May 20 10:59:09 raspberrypi kernel: [   14.121584] Bluetooth: HCI UART protocol Three-wire (H5) registered
May 20 10:59:09 raspberrypi kernel: [   14.121826] Bluetooth: HCI UART protocol Broadcom registered
May 20 10:59:09 raspberrypi btuart[334]: bcm43xx_init
May 20 10:59:09 raspberrypi btuart[334]: Flash firmware /lib/firmware/brcm/BCM4345C0.hcd
May 20 10:59:09 raspberrypi btuart[334]: Set Controller UART speed to 3000000 bit/s
May 20 10:59:09 raspberrypi btuart[334]: Device setup complete
May 20 10:59:09 raspberrypi systemd[1]: Started Configure Bluetooth Modems connected by UART.
May 20 10:59:09 raspberrypi systemd[1]: Configuration file /etc/systemd/system/bthelper@.service.d/override.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
May 20 10:59:09 raspberrypi systemd[1]: Created slice system-bthelper.slice.
May 20 10:59:09 raspberrypi systemd[1]: Starting Raspberry Pi bluetooth helper...
May 20 10:59:09 raspberrypi bthelper[525]: Raspberry Pi BDADDR already set

bluetooth.service did not start

root@raspberrypi:~# systemctl status bluetooth.service
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: inactive (dead)
     Docs: man:bluetoothd(8)

[pelwell]

In that state, what happens if you sudo systemctl start bluetooth?

[jaharkema]

This is my output. I had a bunch of duplicate error lines from HomeAssistant (which runs in a Docker container) trying to find a bluetooth device. I have HomeAssistant turned off for now. hassio is the hostname of my Pi, just to have that clear.

May 20 11:09:28 hassio 65c7278dcf81[774]:   File "/usr/src/homeassistant/homeassistant/components/bluetooth_tracker/device_tracker.py", line 174, in update_bluetooth
May 20 11:09:28 hassio 65c7278dcf81[774]:     await perform_bluetooth_update()
May 20 11:09:28 hassio 65c7278dcf81[774]:   File "/usr/src/homeassistant/homeassistant/components/bluetooth_tracker/device_tracker.py", line 138, in perform_bluetooth_update
May 20 11:09:28 hassio 65c7278dcf81[774]:   File "/usr/src/homeassistant/homeassistant/components/bluetooth_tracker/device_tracker.py", line 56, in discover_devices
May 20 11:09:28 hassio 65c7278dcf81[774]:     result = bluetooth.discover_devices(
May 20 11:09:28 hassio 65c7278dcf81[774]:   File "/usr/local/lib/python3.8/site-packages/bluetooth/bluez.py", line 26, in discover_devices
May 20 11:09:28 hassio 65c7278dcf81[774]:     device_id = _bt.hci_get_route()
May 20 11:10:15 hassio bluetoothd[16990]: Terminating
May 20 11:10:15 hassio systemd[1]: Stopping Bluetooth service...
May 20 11:10:15 hassio bluetoothd[16990]: Stopping SDP server
May 20 11:10:15 hassio bluetoothd[16990]: Exit
May 20 11:10:15 hassio systemd[1]: bluetooth.service: Succeeded.
May 20 11:10:15 hassio systemd[1]: Stopped Bluetooth service.
May 20 11:10:15 hassio systemd[1]: Starting Bluetooth service...
May 20 11:10:15 hassio bluetoothd[22724]: Bluetooth daemon 5.50
May 20 11:10:15 hassio systemd[1]: Started Bluetooth service.
May 20 11:10:15 hassio bluetoothd[22724]: Starting SDP server
May 20 11:10:15 hassio dbus-daemon[367]: [system] Activating via systemd: service name='org.freedesktop.hostname1' unit='dbus-org.freedesktop.hostname1.service' requested by ':1.1293' (uid=0 pid=22724 comm="/usr/lib/bluetooth/bluetoothd ")
May 20 11:10:15 hassio bluetoothd[22724]: Bluetooth management interface 1.18 initialized
May 20 11:10:21 hassio systemd[1]: Starting Configure Bluetooth Modems connected by UART...
May 20 11:10:51 hassio btuart[22737]: Initialization timed out.
May 20 11:10:51 hassio btuart[22737]: bcm43xx_init
May 20 11:10:51 hassio systemd[1]: hciuart.service: Control process exited, code=exited, status=1/FAILURE
May 20 11:10:51 hassio systemd[1]: hciuart.service: Failed with result 'exit-code'.
May 20 11:10:51 hassio systemd[1]: Failed to start Configure Bluetooth Modems connected by UART.

In my case, the bluetooth service does start, but hciuart does not

$ sudo systemctl status bluetooth
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2021-05-20 11:10:15 CEST; 7min ago
     Docs: man:bluetoothd(8)
 Main PID: 22724 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/bluetooth.service
           └─22724 /usr/lib/bluetooth/bluetoothd

May 20 11:10:15 hassio systemd[1]: Starting Bluetooth service...
May 20 11:10:15 hassio bluetoothd[22724]: Bluetooth daemon 5.50
May 20 11:10:15 hassio systemd[1]: Started Bluetooth service.
May 20 11:10:15 hassio bluetoothd[22724]: Starting SDP server
May 20 11:10:15 hassio bluetoothd[22724]: Bluetooth management interface 1.18 initialized

$ sudo systemctl status hciuart.service
● hciuart.service - Configure Bluetooth Modems connected by UART
  Loaded: loaded (/lib/systemd/system/hciuart.service; enabled; vendor preset: enabled)
  Active: failed (Result: exit-code) since Thu 2021-05-20 11:10:51 CEST; 7min ago
 Process: 22737 ExecStart=/usr/bin/btuart (code=exited, status=1/FAILURE)

May 20 11:10:21 hassio systemd[1]: Starting Configure Bluetooth Modems connected by UART...
May 20 11:10:51 hassio btuart[22737]: Initialization timed out.
May 20 11:10:51 hassio btuart[22737]: bcm43xx_init
May 20 11:10:51 hassio systemd[1]: hciuart.service: Control process exited, code=exited, status=1/FAILURE
May 20 11:10:51 hassio systemd[1]: hciuart.service: Failed with result 'exit-code'.
May 20 11:10:51 hassio systemd[1]: Failed to start Configure Bluetooth Modems connected by UART.

[pelwell]

@jaharkema How are you going from "Stopped Bluetooth Service" to "Starting Bluetooth Service" in less than a minute? This does not look like a reboot.

(Note that I'm not saying that your use case is invalid or unsupported, just trying to work out what it is...)

[va1entin]

In that state, what happens if you sudo systemctl start bluetooth?

The command runs "forever" - I've let it run for a few minutes now. No output is being generated and I don't see anything happening with journalctl -xef.

@jaharkema Interesting how we have different services not working. Did you try it with this fix already? https://github.com/RPi-Distro/pi-bluetooth/pull/22/files#diff-3318d7f005738cbbcf14a9d287e6680bd11feba176194ccb322a368490c5028c Asking out of curiosity - on my Pi hicuart.service is starting successfully with and without the fix. I have HomeAssistant running in Docker as well by the way but did not give it access to bluetooth explicitly.

If I revert the fix linked to above, systemd says this about bluetooth.service

root@raspberrypi:~# systemctl status bluetooth.service
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: inactive (dead)
Condition: start condition failed at Thu 2021-05-20 11:28:54 CEST; 1min 35s ago
           └─ ConditionPathIsDirectory=/sys/class/bluetooth was not met
     Docs: man:bluetoothd(8)

May 20 11:28:53 raspberrypi systemd[1]: Condition check resulted in Bluetooth service being skipped.
May 20 11:28:54 raspberrypi systemd[1]: Condition check resulted in Bluetooth service being skipped.

[jaharkema]

@pelwell My bad. I merely restarted the services. Here's the output after a reboot:

May 20 11:31:51 hassio systemd[1]: Starting Configure Bluetooth Modems connected by UART...
May 20 11:31:51 hassio kernel: [    1.399820] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000030000000890
May 20 11:31:52 hassio NetworkManager[381]: <info>  [1621503112.3124] Loaded device plugin: NMBluezManager (/usr/lib/arm-linux-gnueabihf/NetworkManager/1.14.6/libnm-device-plugin-bluetooth.so)
May 20 11:31:58 hassio kernel: [   15.616733] Bluetooth: Core ver 2.22
May 20 11:31:58 hassio kernel: [   15.616862] Bluetooth: HCI device and connection manager initialized
May 20 11:31:58 hassio kernel: [   15.616892] Bluetooth: HCI socket layer initialized
May 20 11:31:58 hassio kernel: [   15.616915] Bluetooth: L2CAP socket layer initialized
May 20 11:31:58 hassio kernel: [   15.616950] Bluetooth: SCO socket layer initialized
May 20 11:31:58 hassio kernel: [   15.625950] Bluetooth: HCI UART driver ver 2.3
May 20 11:31:58 hassio kernel: [   15.625972] Bluetooth: HCI UART protocol H4 registered
May 20 11:31:58 hassio kernel: [   15.626076] Bluetooth: HCI UART protocol Three-wire (H5) registered
May 20 11:31:58 hassio kernel: [   15.626399] Bluetooth: HCI UART protocol Broadcom registered
May 20 11:31:58 hassio btuart[367]: bcm43xx_init
May 20 11:31:58 hassio btuart[367]: Flash firmware /lib/firmware/brcm/BCM4345C0.hcd
May 20 11:31:58 hassio btuart[367]: Set Controller UART speed to 3000000 bit/s
May 20 11:31:58 hassio btuart[367]: Device setup complete
May 20 11:31:58 hassio systemd[1]: Started Configure Bluetooth Modems connected by UART.
May 20 11:31:58 hassio systemd[1]: Created slice system-bthelper.slice.
May 20 11:31:58 hassio systemd[1]: Starting Raspberry Pi bluetooth helper...
May 20 11:31:58 hassio bthelper[551]: Raspberry Pi BDADDR already set
May 20 11:31:58 hassio systemd[1]: Started Raspberry Pi bluetooth helper.
May 20 11:31:58 hassio systemd[1]: Starting Bluetooth service...
May 20 11:31:58 hassio bluetoothd[562]: Bluetooth daemon 5.50
May 20 11:31:58 hassio systemd[1]: Started Bluetooth service.
May 20 11:31:58 hassio systemd[1]: Reached target Bluetooth.
May 20 11:31:58 hassio bluetoothd[562]: Starting SDP server
May 20 11:31:58 hassio kernel: [   15.954464] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
May 20 11:31:58 hassio kernel: [   15.954484] Bluetooth: BNEP filters: protocol multicast
May 20 11:31:58 hassio kernel: [   15.954519] Bluetooth: BNEP socket layer initialized
May 20 11:31:58 hassio bluetoothd[562]: Bluetooth management interface 1.18 initialized
May 20 11:31:58 hassio bluetoothd[562]: Sap driver initialization failed.
May 20 11:31:58 hassio bluetoothd[562]: sap-server: Operation not permitted (1)
May 20 11:31:58 hassio NetworkManager[381]: <info>  [1621503118.7163] bluez: use BlueZ version 5
May 20 11:31:58 hassio NetworkManager[381]: <info>  [1621503118.7277] bluez5: NAP: added interface DC:A6:32:72:36:F6
May 20 11:31:58 hassio bluetoothd[562]: Failed to set privacy: Rejected (0x0b)
May 20 11:32:03 hassio containerd[667]: time="2021-05-20T11:32:03.379533785+02:00" level=info msg="loading plugin \"io.containerd.snapshotter.v1.btrfs\"..." type=io.containerd.snapshotter.v1
May 20 11:32:03 hassio containerd[667]: time="2021-05-20T11:32:03.381543434+02:00" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.btrfs\"..." error="path /var/lib/containerd/io.containerd.snapshotter.v1.btrfs (ext4) must be a btrfs filesystem to be used with the btrfs snapshotter: skip plugin" type=io.containerd.snapshotter.v1
May 20 11:32:03 hassio bthelper[551]: Changing power off succeeded
May 20 11:32:03 hassio bthelper[551]: Changing power on succeeded

After the system reboot the bluetooth service is now running, but with the sap error which is also in the output above. This does not seem to affect anything so far. The hciuart service is running successfully. hcitool scan runs successfully again.

Looks like I should have rebooted, before opening the issue. I can provide more information if needed, but for now I'll leave you and va1entin to it.

[pelwell]

@jaharkema Thanks for the feedback. The behaviour when restarting individual services is perhaps something to consider in future, but for now I'll be happy if it boots and reboot correctly for everyone.

[pelwell]

@va1entin See #24 for a slight tweak that might work better for you.

[va1entin]

@va1entin See #24 for a slight tweak that might work better for you.

Thank you - I applied the tweak to my system. Booting seems to take a bit longer but bluetooth.service is not starting successfully with the same error that I've been getting with the upstream state from 0.1.16:

root@raspberrypi:~# systemctl status bluetooth.service 
● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: inactive (dead)
Condition: start condition failed at Fri 2021-05-21 12:12:37 CEST; 2min 17s ago
           └─ ConditionPathIsDirectory=/sys/class/bluetooth was not met
     Docs: man:bluetoothd(8)

May 21 11:12:36 raspberrypi systemd[1]: Condition check resulted in Bluetooth service being skipped.
May 21 11:12:37 raspberrypi systemd[1]: Condition check resulted in Bluetooth service being skipped.

[pelwell]

And what does the syslog say?

grep -i -E "(bt|blue|\bhci)" /var/log/syslog | tail -100

[va1entin]

And what does the syslog say?

grep -i -E "(bt|blue|\bhci)" /var/log/syslog | tail -100

May 21 16:06:13 raspberrypi kernel: [    1.400368] xhci_hcd 0000:01:00.0: hcc params 0x002841eb hci version 0x100 quirks 0x0000030000000890
May 21 16:06:13 raspberrypi systemd[1]: Condition check resulted in Bluetooth service being skipped.
May 21 16:06:13 raspberrypi systemd[1]: Started BluezALSA proxy.
May 21 16:06:13 raspberrypi systemd[1]: Starting Configure Bluetooth Modems connected by UART...
May 21 16:06:13 raspberrypi systemd[1]: Started Bluetooth Agent.
May 21 16:06:13 raspberrypi systemd[1]: Starting BlueALSA aplay...
May 21 16:06:13 raspberrypi dbus-daemon[336]: [system] Activating via systemd: service name='org.bluez' unit='dbus-org.bluez.service' requested by ':1.5' (uid=0 pid=323 comm="/usr/bin/bluealsa -i hci0 -p a2dp-sink ")
May 21 16:06:13 raspberrypi systemd[1]: Condition check resulted in Bluetooth service being skipped.
May 21 16:06:15 raspberrypi systemd[1]: Started BlueALSA aplay.
May 21 16:06:15 raspberrypi bluealsa-aplay[522]: /usr/bin/bluealsa-aplay: Couldn't get BlueALSA PCM list: The name org.bluealsa was not provided by any .service files
May 21 16:06:20 raspberrypi kernel: [   14.461632] Bluetooth: Core ver 2.22
May 21 16:06:20 raspberrypi kernel: [   14.461745] Bluetooth: HCI device and connection manager initialized
May 21 16:06:20 raspberrypi kernel: [   14.461770] Bluetooth: HCI socket layer initialized
May 21 16:06:20 raspberrypi kernel: [   14.461790] Bluetooth: L2CAP socket layer initialized
May 21 16:06:20 raspberrypi kernel: [   14.461819] Bluetooth: SCO socket layer initialized
May 21 16:06:20 raspberrypi kernel: [   14.471875] Bluetooth: HCI UART driver ver 2.3
May 21 16:06:20 raspberrypi kernel: [   14.471895] Bluetooth: HCI UART protocol H4 registered
May 21 16:06:20 raspberrypi kernel: [   14.471982] Bluetooth: HCI UART protocol Three-wire (H5) registered
May 21 16:06:20 raspberrypi kernel: [   14.472269] Bluetooth: HCI UART protocol Broadcom registered
May 21 16:06:20 raspberrypi btuart[346]: bcm43xx_init
May 21 16:06:20 raspberrypi btuart[346]: Flash firmware /lib/firmware/brcm/BCM4345C0.hcd
May 21 16:06:20 raspberrypi btuart[346]: Set Controller UART speed to 3000000 bit/s
May 21 16:06:20 raspberrypi btuart[346]: Device setup complete
May 21 16:06:20 raspberrypi systemd[1]: Started Configure Bluetooth Modems connected by UART.
May 21 16:06:20 raspberrypi systemd[1]: Configuration file /etc/systemd/system/bthelper@.service.d/override.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.
May 21 16:06:20 raspberrypi systemd[1]: Created slice system-bthelper.slice.
May 21 16:06:20 raspberrypi systemd[1]: Starting Raspberry Pi bluetooth helper...
May 21 16:06:20 raspberrypi bthelper[534]: Raspberry Pi BDADDR already set
May 21 16:06:27 raspberrypi containerd[618]: time="2021-05-21T16:06:27.712622588+02:00" level=info msg="loading plugin \"io.containerd.snapshotter.v1.btrfs\"..." type=io.containerd.snapshotter.v1
May 21 16:06:27 raspberrypi containerd[618]: time="2021-05-21T16:06:27.713299890+02:00" level=info msg="skip loading plugin \"io.containerd.snapshotter.v1.btrfs\"..." error="path /var/lib/containerd/io.containerd.snapshotter.v1.btrfs (ext4) must be a btrfs filesystem to be used with the btrfs snapshotter: skip plugin" type=io.containerd.snapshotter.v1
May 21 16:06:29 raspberrypi mysqld: 2021-05-21 16:06:29 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
May 21 16:06:29 raspberrypi mysqld: 2021-05-21 16:06:29 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
May 21 16:06:53 raspberrypi bluealsa[323]: /usr/bin/bluealsa: Couldn't get managed objects: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
May 21 16:06:53 raspberrypi bt-agent[352]: **
May 21 16:06:53 raspberrypi bt-agent[352]: ERROR:lib/helpers.c:319:intf_supported: assertion failed: (introspection_proxy != NULL)
May 21 16:06:53 raspberrypi systemd[1]: bt-agent.service: Main process exited, code=killed, status=6/ABRT
May 21 16:06:53 raspberrypi systemd[1]: bt-agent.service: Failed with result 'signal'.
May 21 16:06:58 raspberrypi systemd[1]: bt-agent.service: Service RestartSec=5s expired, scheduling restart.
May 21 16:06:58 raspberrypi systemd[1]: bt-agent.service: Scheduled restart job, restart counter is at 1.
May 21 16:06:58 raspberrypi systemd[1]: Stopped Bluetooth Agent.

[pelwell]

May 21 16:06:20 raspberrypi systemd[1]: Configuration file /etc/systemd/system/bthelper@.service.d/override.conf is marked world-inaccessible. This has no effect as configuration data is accessible via APIs without restrictions. Proceeding anyway.

Where has this file come from?

May 21 16:06:15 raspberrypi bluealsa-aplay[522]: /usr/bin/bluealsa-aplay: Couldn't get BlueALSA PCM list: The name org.bluealsa was not provided by any .service files
...
May 21 16:06:53 raspberrypi bluealsa[323]: /usr/bin/bluealsa: Couldn't get managed objects: GDBus.Error:org.freedesktop.DBus.Error.TimedOut: Failed to activate service 'org.bluez': timed out (service_start_timeout=25000ms)
May 21 16:06:53 raspberrypi bt-agent[352]: **
May 21 16:06:53 raspberrypi bt-agent[352]: ERROR:lib/helpers.c:319:intf_supported: assertion failed: (introspection_proxy != NULL)

bluealsa-play, bluealsa and bt-agent aren't standard components (any more?). What OS (and version) are you running? And what extra software have you installed?

[va1entin]

While going through the log I also stumbled upon my override. The configs are in the state you've posted in #24 now. The override at /etc/systemd/system/bthelper@.service.d/override.conf looks like this:

[Service]
ExecStartPost=/usr/bin/bluetoothctl discoverable on
ExecStartPost=/bin/hciconfig %I up
ExecStartPost=/bin/hciconfig %I piscan
ExecStartPost=/bin/hciconfig %I sspmode 1

After removing the override and rebooting, it is working again. I also restored the upstream state from 0.1.16 and it is in fact working after a reboot as well.

I am running Raspberry Pi OS / Raspbian:

root@raspberrypi:~# lsb_release -a
No LSB modules are available.
Distributor ID: Raspbian
Description:    Raspbian GNU/Linux 10 (buster)
Release:        10
Codename:       buster

My use case is playing audio via bluetooth using Hifiberry and I've set it up according to their official guide. Apparently that is outdated now - I'll go and have a look there to see if they still recommend to do it like this. Thank you very much for your support and sorry for not mentioning this earlier.

[pelwell]

That's OK. I'll still apply my modified version of the fix that you kindly provided.