search

arkq / bluez-alsa

Bluetooth Audio ALSA Backend
MIT License
862 stars 189 forks source link

[Couldn't set audio object type: Invalid config] Problem reconnecting to earbuds after they had been connected to another device #609

Closed Galicarnax closed 1 year ago

Galicarnax commented 1 year ago

First, thanks for this little gem for minimalists. I've managed to connect my earbuds with Raspberry Pi using ALSA alone.

There is one problem that plagues me, though. I use the same earbuds with my laptop, and when I try to connect them back to RPi, things go wrong. They seem to connect, but in a few seconds they disconnect. Retries yield the same. Until I restart the bluetooth and bluealsa services. And restarting bluealsa after this situation happens takes about 1.5-2 minutes.

If I simply switch off the earbuds and then reconnect them to RPi, everything is Ok. The problem happens only if they were previously connected to my laptop. It's as if earbuds somehow keep information about last connected device, and this info interferes with the attempt to connect to RPi. By the way, connecting back to laptop after earbuds were connected to RPi happens without problems (on laptop I use pipewire and pipewire-pulse).

Here is more specific info from journalctl -u bluealsa:

Jan 01 00:29:15 raspi systemd[1]: Starting BlueALSA service...
Jan 01 00:29:15 raspi bluealsa[131225]: Couldn't create storage directory: No such file or directory
Jan 01 00:29:15 raspi systemd[1]: Started BlueALSA service.
Jan 01 00:29:48 raspi bluealsa[131225]: Couldn't save storage: Failed to create file “/usr/var/lib/bluealsa/B0:4A:6A:0F:87:94.93FCY1”: No such file or directory
Jan 01 00:30:40 raspi bluealsa[131225]: Couldn't save storage: Failed to create file “/usr/var/lib/bluealsa/B0:4A:6A:0F:87:94.NDL2X1”: No such file or directory
Jan 01 00:31:48 raspi bluealsa[131225]: Couldn't save storage: Failed to create file “/usr/var/lib/bluealsa/B0:4A:6A:0F:87:94.HK7IY1”: No such file or directory
Jan 01 00:36:06 raspi bluealsa[131225]: Couldn't set audio object type: Invalid config

The warning about being unable to create storage dir is always there when the service is started. The errors Failed to create file... also happen now and then, but they do not seem to affect connection to earbuds (and yes, there is no /usr/var/lib directory on my system; shouldn't it be /var/lib/... instead?). It is the last message that appears when I try to reconnect the buds from laptop:

Couldn't set audio object type: Invalid config

I had a rough time trying to find mentions of this message, including here in repo issues. And after this message the service takes minutes to restart. If that helps, I have Arch Linux ARM on my RPi, and bluealsa was installed from the package bluez-alsa-git from AUR. The earbuds are Samsung Galaxy Buds Live.

P.S. Don't pay attention to journal timestamps. When everyone goes crazy, I get bored and do things like troubleshooting bluealsa ;)

Galicarnax commented 1 year ago

It is the last message that appears when I try to reconnect the buds from laptop

Clarification: this message appears not at the moment when earbuds connect to RPi, but at the moment when I try to play music after that.

Also, I've tired other wireless buds, the situation seems to be the same.

arkq commented 1 year ago

And restarting bluealsa after this situation happens takes about 1.5-2 minutes.

It looks like a daedlock within bluealsa service. When it happens (you are not able to properly connect earbuds) do like this (as root, or use sudo):

gdb -p $(pgrep -x bluealsa) --ex 'thread apply all bt'

You can do the same thing (gather backtrace from all threads) if systemctl restart ... hangs. And post traces here.

and yes, there is no /usr/var/lib directory on my system; shouldn't it be /var/lib/... instead?

Yes, it should be /var/lib/..., maybe there is something wrong with Arch package... I will have to check that as well.

arkq commented 1 year ago

One more thing, try to build bluez-alsa from source with debug enabled ../configure --enable-debug. Maybe some debug log will help. Anyway, I'll try to reproduce your issue.

borine commented 1 year ago

Yes, it should be /var/lib/..., maybe there is something wrong with Arch package...

This is an inconsistency between GNU coding standards (https://www.gnu.org/prep/standards/html_node/Directory-Variables.html) and systemd (https://www.freedesktop.org/software/systemd/man/systemd.exec.html#RuntimeDirectory=)

GNU does not use /var/lib at all in its standard installation directories, whereas systemd always uses it for system state directories. A workaround is to configure with --localstatedir=/var whenever using the included systemd unti files. I'm not sure what the BlueALSA configure script can do to improve this.

arkq commented 1 year ago

This is an inconsistency between GNU coding standards

OK, so it seems that that fix should be on the Arch side.

Anyway, I'll try to reproduce your issue.

I've reproduced it on my side and indeed that's a deadlock in bluealsa code. I'll try to fix that deadlock. However, it will not resolve playback issue. It will simply fix bluealsa restart issue. In order to investigate playback issue I will need bluealsa debug logs, or at least the configuration blob which can be obtained with:

bluealsa-cli -v info /org/bluealsa/hci0/dev_B0_4A_6A_0F_87_94/a2dpsrc/sink
borine commented 1 year ago

I've just added some extra text to the installation wiki page to explain the --localstatedir= requirement for systemd.

Galicarnax commented 1 year ago

I have compiled bluealsa manually following instructions on your wiki (I used ../configure --enable-debug --enable-aac --enable-cli --enable-systemd). Now the error messages concerning wrong storage directories are gone. Still, the main problem and the error with Couldn't set audio object type: Invalid config remains.

Here are new debug logs. I put commets on relevant events:

  Jan 01 15:19:03 raspi systemd[1]: Starting BlueALSA service...
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/main.c:590: Starting main dispatching loop
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/main.c:114: Acquired D-Bus service name: org.bluealsa
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluealsa-dbus.c:372: Registering D-Bus manager: /org/bluealsa
  Jan 01 15:19:03 raspi systemd[1]: Started BlueALSA service.
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:770: Registering battery provider: /org/bluez/hci0/battery
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:790: BlueZ battery provider support not available
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/source/2
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/source/2
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/sink/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/sink/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/sink/2
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/sink/2
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/2
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/sink/1
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/2
  Jan 01 15:19:03 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/sink/2
--> Here I connect earbuds which were previously connected to RPi. Everything is Ok.
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1232: Adding new Stream End-Point: B0:4A:6A:0F:87:94: SBC
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1232: Adding new Stream End-Point: B0:4A:6A:0F:87:94: AAC
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1232: Adding new Stream End-Point: B0:4A:6A:0F:87:94: samsung-SC
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/storage.c:102: Loading storage: /var/lib/bluealsa/B0:4A:6A:0F:87:94
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:406: A2DP Source (AAC) configured for device B0:4A:6A:0F:87:94
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:409: A2DP selected configuration blob [len=6]: 400084035b60
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:411: PCM configuration: channels: 2, sampling: 48000
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:584: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/source/3
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:495: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/source/3
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1361: Skipping A2DP volume update: 77
  Jan 01 15:19:36 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Delay
--> Here I start playing music from MPD. Everything is Ok
  Jan 01 15:19:42 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_B0_4A_6A_0F_87_94/a2dpsrc/sink
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/ba-transport.c:651: New A2DP transport: 19
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/ba-transport.c:652: A2DP socket MTU: 19: R:672 W:679
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/ba-transport.c:1271: Starting transport: A2DP Source (AAC)
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/ba-transport.c:360: Created BT socket duplicate: [19]: 20
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/ba-transport.c:1622: Created new IO thread [ba-a2dp-aac]: A2DP Source (AAC)
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/a2dp-aac.c:326: IO loop: START: a2dp_aac_enc_thread: A2DP Source (AAC)
  Jan 01 15:19:43 raspi bluealsa[2935]: ../../src/ba-transport.c:1512: PCM resume: 15
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:1553: PCM drop: 15
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:1553: PCM drop: 15
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:1570: Closing PCM: 15
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:522: PCM clients check keep-alive: 0 ms
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:471: Stopping transport: No PCM clients
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:372: Closing BT socket duplicate [19]: 20
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:678: Releasing A2DP transport: 19
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:705: Closing A2DP transport: 19
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State
  Jan 01 15:19:54 raspi bluealsa[2935]: ../../src/ba-transport.c:1649: Exiting IO thread [ba-a2dp-aac]: A2DP Source (AAC)
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_B0_4A_6A_0F_87_94/a2dpsrc/sink
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/ba-transport.c:651: New A2DP transport: 19
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/ba-transport.c:652: A2DP socket MTU: 19: R:672 W:679
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/ba-transport.c:1271: Starting transport: A2DP Source (AAC)
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/ba-transport.c:360: Created BT socket duplicate: [19]: 20
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/ba-transport.c:1622: Created new IO thread [ba-a2dp-aac]: A2DP Source (AAC)
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/a2dp-aac.c:326: IO loop: START: a2dp_aac_enc_thread: A2DP Source (AAC)
  Jan 01 15:20:10 raspi bluealsa[2935]: ../../src/ba-transport.c:1512: PCM resume: 15
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:1553: PCM drop: 15
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:1553: PCM drop: 15
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:1570: Closing PCM: 15
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:522: PCM clients check keep-alive: 0 ms
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:471: Stopping transport: No PCM clients
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:372: Closing BT socket duplicate [19]: 20
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:678: Releasing A2DP transport: 19
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:705: Closing A2DP transport: 19
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State
  Jan 01 15:20:14 raspi bluealsa[2935]: ../../src/ba-transport.c:1649: Exiting IO thread [ba-a2dp-aac]: A2DP Source (AAC)
--> Somewhere here I disconnect earbuds from RPi and then connect them to laptop
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluez.MediaEndpoint1.ClearConfiguration() on /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/bluez.c:447: Disconnecting media endpoint: /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/ba-transport.c:993: Freeing transport: A2DP Source (AAC)
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/storage.c:132: Saving storage: /var/lib/bluealsa/B0:4A:6A:0F:87:94
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/ba-device.c:142: Freeing device: B0:4A:6A:0F:87:94
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
  Jan 01 15:20:22 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
--> Here I connect them to RPi again
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1232: Adding new Stream End-Point: B0:4A:6A:0F:87:94: SBC
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1232: Adding new Stream End-Point: B0:4A:6A:0F:87:94: AAC
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1232: Adding new Stream End-Point: B0:4A:6A:0F:87:94: samsung-SC
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:271: A2DP peer capabilities blob [len=6]: f0018c83e800
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1136: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/storage.c:102: Loading storage: /var/lib/bluealsa/B0:4A:6A:0F:87:94
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:406: A2DP Source (AAC) configured for device B0:4A:6A:0F:87:94
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:409: A2DP selected configuration blob [len=6]: 100084035b60
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:411: PCM configuration: channels: 2, sampling: 48000
  Jan 01 15:20:52 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Delay
  Jan 01 15:20:54 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: Volume
  Jan 01 15:20:54 raspi bluealsa[2935]: ../../src/bluez.c:1361: Skipping A2DP volume update: 77
--> Here I start playing music from MPD: Ooops! Doesn't work
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_B0_4A_6A_0F_87_94/a2dpsrc/sink
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:651: New A2DP transport: 19
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:652: A2DP socket MTU: 19: R:672 W:679
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:1271: Starting transport: A2DP Source (AAC)
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:360: Created BT socket duplicate: [19]: 20
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:1622: Created new IO thread [ba-a2dp-aac]: A2DP Source (AAC)
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/a2dp-aac.c:223: Couldn't set audio object type: Invalid config
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:372: Closing BT socket duplicate [19]: 20
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:678: Releasing A2DP transport: 19
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/bluez.c:1343: Signal: org.freedesktop.DBus.Properties.PropertiesChanged(): org.bluez.MediaTransport1: State
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:705: Closing A2DP transport: 19
  Jan 01 15:21:06 raspi bluealsa[2935]: ../../src/ba-transport.c:1649: Exiting IO thread [ba-a2dp-aac]: A2DP Source (AAC)
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/dbus.c:66: Called: org.bluez.MediaEndpoint1.ClearConfiguration() on /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/bluez.c:447: Disconnecting media endpoint: /org/bluez/hci0/A2DP/AAC/source/1
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/ba-transport.c:993: Freeing transport: A2DP Source (AAC)
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/storage.c:132: Saving storage: /var/lib/bluealsa/B0:4A:6A:0F:87:94
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/ba-device.c:142: Freeing device: B0:4A:6A:0F:87:94
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
  Jan 01 15:21:35 raspi bluealsa[2935]: ../../src/bluez.c:1247: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
arkq commented 1 year ago

OK, thank you very much for providing debug logs. Now I know what causes the issue with playback. The problem is with AAC codec configuration selection when the earbuds are connected for the second time (I do not know why, though). I will try to investigate this issues as well. I'm not sure when all fixes will be ready, because it might not be easy to fix them :D As a temporal workaround you can switch to SBC codec when using earbuds with RPi. You can use alsamixer -D bluealsa:EXT=on for that, or bluealsa-cli codec <PCM-path> SBC.

arkq commented 1 year ago

@Galicarnax I've pushed potential fix to the "test" branch: https://github.com/arkq/bluez-alsa/tree/test Could you test that branch whether it will work for you?

Galicarnax commented 1 year ago

It does work, hooray! I even have now a shortcut on my laptop that launches a bash script to automatically toggle the earbuds between the laptop and the RPi :) Many thanks for the nice job!

arkq commented 1 year ago

OK, great :) But just to be sure, can you confirm that the earbuds are using AAC codec? If you've switched to SBC (as a workaround) the selection might be remembered by earbuds, so now they might connect using SBC codec by default. You can check that in debug logs, or by using bluealsa-cli codec <PCM-path> - it will print currently selected codec.

Galicarnax commented 1 year ago

I didn't tried the workaround yet. And I am not sure what I am supposed to use for <PCM-path> in bluealsa-cli codec ... (in fact, bluealsa-cli list-pcms does not show anything, just empty output). But this debug log suggests that AAC codec is used:

bluealsa: [1129579] D: ../../src/bluez.c:406: A2DP Source (AAC) configured for device B0:4A:6A:0F:87:94
arkq commented 1 year ago

in fact, bluealsa-cli list-pcms does not show anything, just empty output

Hmm, that's strange.... It should print the list of available PCMs (PCM-paths) which can be used with other bluealsa-cli commands.

But this debug log suggests that AAC codec is used

OK, thanks for confirmation!

Galicarnax commented 1 year ago

Hmm, that's strange.... It should print the list of available PCMs (PCM-paths) which can be used with other bluealsa-cli commands.

Just have checked again, and now I see the output from bluealsa-cli list-pcms (and also see that AAC is indeed the selected coded for the earbuds' PCM path). Not sure why that was empty when I first checked (even though the earbuds were connected and playing music from RPi at that moment for sure). After that I switched the earbuds off and on again, and also re-logined into RPi, could be somehow affected... Now it's fine.