nicokaiser / rpi-audio-receiver

Raspberry Pi Audio Receiver with Bluetooth A2DP, AirPlay 2, and Spotify Connect
MIT License
1.37k stars 148 forks source link

Bluetooth: Not starting at all #108

Closed Flacedoo closed 2 years ago

Flacedoo commented 3 years ago

Hi, Today I tried getting this project to work on my Raspberry Pi 3 Model B, but unfortunately I never was able to get Bluetooth to work.. I tried with different versions of the current Raspi OS (lite, full), and same with older Raspbian releases.

Basically I always ended up with no bluetooth device showing up. When checking service bluetooth status, it always seems to respond the following:

● 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 21:36:47 BST; 55s ago
           └─ ConditionPathIsDirectory=/sys/class/bluetooth was not met
     Docs: man:bluetoothd(8)

May 21 21:36:46 rpitv systemd[1]: Condition check resulted in Bluetooth service being skipped.
May 21 21:36:47 rpitv systemd[1]: Condition check resulted in Bluetooth service being skipped.

Do you have any idea how I could resolve this? Thanks!

Edit: On my fresh install, the output of service bluetooth status is as following:

● bluetooth.service - Bluetooth service
   Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled)
   Active: active (running) since Fri 2021-05-21 22:14:33 BST; 1min 5s ago
     Docs: man:bluetoothd(8)
 Main PID: 478 (bluetoothd)
   Status: "Running"
    Tasks: 1 (limit: 2062)
   CGroup: /system.slice/bluetooth.service
           └─478 /usr/lib/bluetooth/bluetoothd

May 21 22:14:33 musicpi-tv systemd[1]: Starting Bluetooth service...
May 21 22:14:33 musicpi-tv bluetoothd[478]: Bluetooth daemon 5.50
May 21 22:14:33 musicpi-tv systemd[1]: Started Bluetooth service.
May 21 22:14:33 musicpi-tv bluetoothd[478]: Starting SDP server
May 21 22:14:33 musicpi-tv bluetoothd[478]: Bluetooth management interface 1.18 initialized
May 21 22:14:33 musicpi-tv bluetoothd[478]: Sap driver initialization failed.
May 21 22:14:33 musicpi-tv bluetoothd[478]: sap-server: Operation not permitted (1)
May 21 22:14:33 musicpi-tv bluetoothd[478]: Failed to set privacy: Rejected (0x0b)
bruennlein commented 3 years ago

Hi guys,

I got the same problem. The service is running just after installation, but when I try to restart the service, the "systemctl restart bluetooth"-command just hangs. For testing-reasons, I added root to the bluetooth-group and started bluetoothd from the CLI. It started and I was able to start bluetoothctl and also started a connection-attempt from my phone, which ended-up in an unsuccessful authentication-attempt.

After that I was able to start the bluetooth-service again and got the following status: bluetooth.service - Bluetooth service Loaded: loaded (/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled) Active: active (running) since Fri 2021-05-28 09:30:41 BST; 10s ago Docs: man:bluetoothd(8) Main PID: 765 (bluetoothd) Status: "Running" Tasks: 1 (limit: 2181) CGroup: /system.slice/bluetooth.service └─765 /usr/lib/bluetooth/bluetoothd

Mai 28 09:30:41 raspicast systemd[1]: Starting Bluetooth service... Mai 28 09:30:41 raspicast bluetoothd[765]: Bluetooth daemon 5.50 Mai 28 09:30:41 raspicast systemd[1]: Started Bluetooth service. Mai 28 09:30:41 raspicast bluetoothd[765]: Starting SDP server Mai 28 09:30:41 raspicast bluetoothd[765]: Bluetooth management interface 1.18 initialized Mai 28 09:30:41 raspicast bluetoothd[765]: Sap driver initialization failed. Mai 28 09:30:41 raspicast bluetoothd[765]: sap-server: Operation not permitted (1)

After reboot, the service is stopped again. I cannot restart (hangs), but starting bluetoothd and then starting the service works.

I have no idea, what this means and what to do. Any suggestions?

lostmyshape commented 3 years ago

Yes! This happened to me after the latest update to bluetoothd a week or so ago. I think this update did something to the order of service startup in systemd. At first I thought it was just me because I've done some customization to get bluetooth to work with snapcast. But what @bruennlein lists above are the same symptoms as I had. Here's what happened to me if you want to check to see if it's the same for you:

For some reason the bthelper@ service is trying to start before the rest of the bluetooth stack and holding it up because it runs "bluetoothctl discoverable on" (as added by rpi-audio-receiver in "/etc/systemd/system/bthelper@.service.d/override.conf"). You can confirm this by running "systemctl list-jobs" after reboot. If this is the problem, you'll see something like:

JOB UNIT                                 TYPE  STATE  
113 systemd-update-utmp-runlevel.service start waiting
106 bt-agent.service                     start waiting
 77 bluetooth.service                    start waiting
317 bluetooth.target                     start waiting
256 bthelper@hci0.service                start running
  1 multi-user.target                    start waiting
 75 bluealsa-aplay.service               start waiting
 76 bluealsa.service                     start waiting

"bthelper@hci0.service" is "running" (ie., hanging) and the other services are waiting for it to complete to run.

This seems to be because "bluetoothctl" hangs if "bluetoothd" isn't running, instead of failing. So "bthelper@" can't complete because "bluetoothd" isn't running but "bluetoothd" can't start until "bthelper@" completes. So everything is stuck.

If you are experiencing the same thing, after reboot you should be able to run "sudo systemctl stop bthelper@hciX.service" and the rest of the stack will start up properly. Then you can "sudo systemctl start bthelper@hciX.service" (for some reason "restart" just hangs).

OR, you can comment out "ExecStartPost=/usr/bin/bluetoothctl discoverable on" in "/etc/systemd/system/bthelper@.service.d/override.conf", then "systemctl daemon-reload" and everything will start again at reboot. Of course, then you need to script "bluetoothctl discoverable on" somewhere else or do it manually.

I don't have a spare rpi to test to see if this is a repeatable issue (and I don't want to mess with the one that's working now!), so YMMV. I also don't know/understand enough about the bluetoothd update or systemd to suggest a long-term fix for this either. Anyway, hope this helps!!!

bruennlein commented 3 years ago

Hi @lostmyshape , thanks for investigating. As I´m new on this RaspiCast-topic and have nothing to loose, I decided to start from the scratch and try this here: image

So unfortunately, I can´t do any investigation on my system, because I already installed a fresh Rasbian. But if I get back to this project, I´ll get back to you.

See you...

sebPomme commented 3 years ago

Hi,

When the service bluetooth is stuck, I figure out that the command bluetoothctl does'not works too. Some details.

root@rpi-test-haut:~# systemctl status bthelper@hci0.service 
● bthelper@hci0.service - Raspberry Pi bluetooth helper
   Loaded: loaded (/lib/systemd/system/bthelper@.service; static; vendor preset: enabled)
  Drop-In: /etc/systemd/system/bthelper@.service.d
           └─override.conf
   Active: activating (start-post) since Wed 2021-06-02 11:01:38 BST; 3min 59s ago
  Process: 525 ExecStart=/usr/bin/bthelper hci0 (code=exited, status=0/SUCCESS)
 Main PID: 525 (code=exited, status=0/SUCCESS); Control PID: 535 (bluetoothctl)
    Tasks: 3 (limit: 2062)
   Memory: 1.1M
   CGroup: /system.slice/system-bthelper.slice/bthelper@hci0.service
           ├─533 /bin/sh /usr/bin/bthelper hci0
           ├─535 /usr/bin/bluetoothctl discoverable on
           └─627 /usr/bin/bluetoothctl power off

Jun 02 11:01:38 rpi-test-haut systemd[1]: Starting Raspberry Pi bluetooth helper...
Jun 02 11:01:38 rpi-test-haut bthelper[525]: Raspberry Pi BDADDR already set

I see their are some recent changes on bthelper https://github.com/RPi-Distro/pi-bluetooth/commit/ae2efdeee8e53e4e256782963f868bd5bb335514 .

Now, the command (/usr/bin/bluetoothctl discoverable on) in /etc/systemd/system/bthelper@.service.d/override.conf run nearly at the same time than /bluetoothctl power off, and get stuck together.

lostmyshape commented 3 years ago

Hey @sebPomme looks like you encountered the same thing as me and figured out the reason why! I'm getting a new pi on Monday and can test to confirm that this happens on a fresh system before setting the pi up for my intended purpose.

sebPomme commented 3 years ago

I will try to move

ExecStartPost=/usr/bin/bluetoothctl discoverable on
ExecStartPost=/bin/hciconfig %I piscan
ExecStartPost=/bin/hciconfig %I sspmode 1

in bt-agent.service and move bt-agent.service to bt-agent@hci0.service to enable the %I variable.

lostmyshape commented 3 years ago

Not sure it's a help now, but I can confirm that with the 2021-05-07 RPi OS Lite, and updates, I can replicate exactly what @sebPomme describes above. After boot, stopping bt-agent@hci0.service, then starting it again, resolves the bluetooth service hang.

@sebPomme did the changes you made fix the problem at boot?

lostmyshape commented 3 years ago

Thanks @sebPomme. Just tested these changes (manually added them) and everything seems to work as expected now! You are awesome!

TwizzyDizzy commented 3 years ago

After boot, stopping bt-agent@hci0.service, then starting it again, resolves the bluetooth service hang.

I think you meant bthelper@hci0.service, if I'm not mistaken. I can confirm the issue overall, but I'm not quite sure whether the bthelper is the issue.

With my observation it seems more likely that ConditionPathIsDirectory=/sys/class/bluetooth is the culprit:

Have a look at 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 Wed 2021-06-23 00:45:44 CEST; 1min 6s ago
           └─ ConditionPathIsDirectory=/sys/class/bluetooth was not met
     Docs: man:bluetoothd(8)

Jun 23 00:45:43 bath systemd[1]: Condition check resulted in Bluetooth service being skipped.
Jun 23 00:45:44 bath systemd[1]: Condition check resulted in Bluetooth service being skipped.

Theory 1

So this means that at the time bluetooth.service would have been startet in the boot order, /sys/class/bluetooth does not yet exist, as it seems. This means bthelper@hci0.service is most likely to also wait for bluetooth.service.

The arch wiki then related this to the kernel module bluetooth not being loaded (CTRL+F "Condition check resulted in Bluetooth service being skipped")... then I found this Debian bug: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=853207

My guess at this point is, that that the initialization of the internal bluetooth chip is happening differntly than the initialization of usb hci adapters. Hence, at the time the systemd-udev.service is started, the BT chip is not ready, hence the kernel module bluetooth is not loaded, hence /sys/class/bluetooth does not exist, hence bluetooth.service does not start.

Theory 2

Another theory I developed while digging: hciuart.service. This service also seems to be involved in setting up BT devices. Disabling it systemctl disable hciuart.service; reboot seems to also fix the issue.

Maybe I'll dig even deeper if I find the time. I'm more leaning towards theory 2 vs. the initialization of the bluetooth chip itself.

This would explain, why my two Raspberry Pi 2B's (using USB BT dongles) don't experience the problem while my Raspberry Pi 3 (having an onboard Bluetooth chip) does have the problem.

So could all of those affected by this issue check:

EDIT: one last remark: I also did a systemd-analyze while the issue was not fixed yet. The plot show, that bluetooth.service comes up directly after I stopped the hciuart.service unit. (You cannot see me stopping the service in the plot, but I did it right before bluetooth.service came up - bottom right corner of the image).

Plot: plot

Cheers so far, Thomas

starfunkel commented 3 years ago

Can confirm @sebPomme workaround works. Thank you very much!

FraH90 commented 3 years ago

I will try to move

ExecStartPost=/usr/bin/bluetoothctl discoverable on
ExecStartPost=/bin/hciconfig %I piscan
ExecStartPost=/bin/hciconfig %I sspmode 1

in bt-agent.service and move bt-agent.service to bt-agent@hci0.service to enable the %I variable.

Hi, I have the same problem that is described in this issue, after having installed the bluealsa module (no bluetooth device showing up, I guess bluetooth isn't starting)

Could you please explain me better the steps that I need to do? In which file I need to write those things? Thank you!

TwizzyDizzy commented 3 years ago

Actually the diff in the linked PR (https://github.com/nicokaiser/rpi-audio-receiver/pull/109) describes exactly what to do where. You need to apply those changes before you execute install-bluetooth.sh. Unfortunately, the PR isn't merged yet.

Should it get merged soon, you would only need to pull main and then execute install-bluetooth.sh.

Cheers Thomas

FraH90 commented 3 years ago

Actually the diff in the linked PR (https://github.com/nicokaiser/rpi-audio-receiver/pull/109) describes exactly what to do where. You need to apply those changes before you execute install-bluetooth.sh. Unfortunately, the PR isn't merged yet.

Should it get merged soon, you would only need to pull main and then execute install-bluetooth.sh.

Cheers Thomas

Oh I get it. I've already installed it 😅 Good that I've made a backup-image before doing it 😅

Hope it will get merged soon