arkq
4.3.0: org.freedesktop.DBus.Error.NoReply
Hello!
Please read the troubleshooting guide before raising a new issue.
Did that.
Problem
Ok, first of all we talk a totally borked Philips TV that offers playing audio sent to it via bluetooth. I use bluez-alsa for this task for about five years. That is, there were often problems in the past (music stuttering, connection losses), but that improved over time with new bluez-alsa releases and/or Linux kernel changes (first 4.19, then 5.10, now 6.1).
However, since upgrade to bluez-alsa 4.3.0, i can only play music for a couple of minutes, ie, here is complete bluetooth connection establishment / end-of-the-story syslog entry:
Aug 19 17:52:46 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd3: fd(25) ready Aug 19 17:52:46 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd4: fd(25) ready Aug 19 17:56:56 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd5: fd(25) ready Aug 19 17:56:57 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd6: fd(25) ready Aug 19 18:00:50 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd7: fd(25) ready Aug 19 18:00:51 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd8: fd(25) ready Aug 19 18:06:38 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd9: fd(25) ready Aug 19 18:06:38 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd10: fd(25) ready Aug 19 18:12:50 kent bluetoothd[13142]: profiles/audio/media.c:endpoint_reply() Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply
On the application side we then see (of course)
$ ALSAPCM=bt ogg123 -q can-ege_bamyasi.ogg ALSA lib ../../../src/asound/bluealsa-pcm.c:1540:(_snd_pcm_bluealsa_open) Couldn't get BlueALSA PCM: PCM not found ERROR: Cannot open device alsa.
Now, it must be said that the above "fd ready" messages are completely new, at least in this non-unique variant. Ie, the entire August 14th with elder bluez-alsa is
Aug 14 19:30:36 kent /root/bin/zzz.sh: /etc/rc.d/bluetoothd start Aug 14 19:30:36 kent /root/bin/zzz.sh: /etc/rc.d/bluealsa start Aug 14 19:30:36 kent bluetoothd[25786]: Bluetooth daemon 5.77 Aug 14 19:30:36 kent bluetoothd[25786]: Starting SDP server Aug 14 19:30:36 kent bluetoothd[25786]: src/plugin.c:init_plugin() System does not support ccp plugin Aug 14 19:30:36 kent bluetoothd[25786]: Bluetooth management interface 1.22 initialized Aug 14 19:30:36 kent bluetoothd[25786]: Battery Provider Manager created Aug 14 19:30:36 kent bluetoothd[25786]: Adv Monitor Manager created with supported features:0x00000001, enabled features:0x00000001, max number of supported monitors:32, max number of support ed patterns:16 Aug 14 19:30:36 kent bluetoothd[25786]: Failed to set mode: Failed (0x03) Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/sink/1 Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/sink/2 Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/source/1 Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/source/2 Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/sink/1 Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/sink/2 Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/source/2 Aug 14 19:30:36 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/source/1 ... Aug 14 19:32:01 kent bluetoothd[25786]: Endpoint registered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/source/3 Aug 14 19:32:08 kent bluetoothd[25786]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd0: fd(25) ready ... Aug 15 02:51:35 kent bluetoothd[25786]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd1: fd(25) ready Aug 15 04:44:06 kent /root/bin/zzz.sh: /etc/rc.d/bluealsa stop Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/sink/1 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/sink/2 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/source/1 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/sink/1 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/sink/2 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/source/2 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/AAC/source/1 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/source/3 Aug 15 04:44:06 kent bluetoothd[25786]: Endpoint unregistered: sender=:1.266 path=/org/bluez/hci0/A2DP/SBC/source/2 Aug 15 04:44:06 kent /root/bin/zzz.sh: /etc/rc.d/bluetoothd stop
Reproduction steps
That is all i know. (I never deal directly with all the settings, i only use the ALSAPCM environment variable to switch in between devices.) The asound.conf is years old
pcm.!default {
type plug; slave.pcm { @func getenv; vars [ ALSAPCM ]; default "xmix"; }
}
ctl.!default { type hw; card 0; }
pcm.xmix {
type dmix
ipc_key 1024; ipc_gid audio; ipc_perm 0660
slave {
#rate 48000; periods 256; period_time 0; period_size 2048; buffer_size 16384
pcm "hw:0,0" }
}
pcm.bt {
type plug
slave.pcm { type bluealsa; device "00:F4:8D:33:38:FA"; profile "a2dp" }
hint { show on; description "ptv, Frau Antje Bluetooth" }
}
ctl.bt { type bluealsa }
Setup
- the OS distribution and version CRUX-Linux.
- the version of BlueALSA (
bluealsa --version) 4.3.0- the version of BlueZ (
bluetoothd --version) 5.77 (installed since July 13th)- the version of ALSA (
aplay --version) 1.2.12 (alsa-utils, alsa-lib, installed since June 15th)- if self-built from source, please state the branch and commit (
git log -1 --oneline), and the used configure options.
(ok maybe the note on fd ready log entries is stupid, i very often hear music sets which are 3 to 7 hours, which could be a reason. I do not know.)
(P.S.: i am happy to try out patches or help debugging by sprinkling syslog() things or what. Thanks for bluez-alsa! (Only a shame that dmix requires a "real hw" OR an in-kernel approach to aid in that problem is not provided, .. but i do not .. and cannot that myself, so, hm.)
Could you compile bluez-alsa with debug enabled and provide some logs from bluealsa deamon and client application?
Hello! Sure, i will compile with
--enable-aac --enable-lame --enable-mpg123 --enable-debug --enable-debug-time
in a minute and hm will look what this brings in the next days. (It broke twice yesterday and once today, but for now the music is running in a stream ok.) Btw i see quite a lot of fds, bluetooth (only used by bluealsa) now has 29, and bluealsa has 21 fds open, is this normal? Well for Bluealsa, maybe it talks with its threads, dunno. But, say, can it be that bluetoothd still has the sockets open for the failed bluealsa connections? (Not that it is as simple as some fd-maximum being excessed?)
Wait, see, the log above for example said fd3-10 for the first bluealsa connection, and these sockets still exist:
lr-x------ 1 root root 64 Aug 19 23:18 9 -> /proc/sys/kernel/hostname lrwx------ 1 root root 64 Aug 19 23:18 8 -> 'socket:[43418]'= lrwx------ 1 root root 64 Aug 19 23:18 7 -> 'socket:[43417]'= lrwx------ 1 root root 64 Aug 19 23:18 6 -> 'socket:[43416]'= lrwx------ 1 root root 64 Aug 19 23:18 5 -> 'socket:[43415]'= lrwx------ 1 root root 64 Aug 19 23:18 4 -> 'socket:[43414]'= lrwx------ 1 root root 64 Aug 19 23:18 3 -> 'anon_inode:[eventfd]' lrwx------ 1 root root 64 Aug 19 23:18 25 -> 'socket:[87690]'= lrwx------ 1 root root 64 Aug 19 23:18 24 -> 'socket:[85795]'= lrwx------ 1 root root 64 Aug 19 23:18 23 -> 'socket:[41564]'= lrwx------ 1 root root 64 Aug 19 23:18 22 -> 'socket:[43428]'= lrwx------ 1 root root 64 Aug 19 23:18 21 -> 'socket:[43427]'= lrwx------ 1 root root 64 Aug 19 23:18 20 -> 'socket:[43426]'= l-wx------ 1 root root 64 Aug 19 23:18 2 -> /dev/null lrwx------ 1 root root 64 Aug 19 23:18 19 -> 'socket:[43425]'= lrwx------ 1 root root 64 Aug 19 23:18 18 -> 'socket:[43424]'= lrwx------ 1 root root 64 Aug 19 23:18 17 -> 'socket:[43423]'= lrwx------ 1 root root 64 Aug 19 23:18 16 -> 'socket:[43422]'= lrwx------ 1 root root 64 Aug 19 23:18 15 -> 'socket:[43421]'= lr-x------ 1 root root 64 Aug 19 23:18 14 -> /dev/urandom lrwx------ 1 root root 64 Aug 19 23:18 13 -> 'socket:[43420]'= lrwx------ 1 root root 64 Aug 19 23:18 12 -> 'anon_inode:[signalfd]' lrwx------ 1 root root 64 Aug 19 23:18 11 -> /dev/rfkill lrwx------ 1 root root 64 Aug 19 23:18 10 -> 'socket:[43419]'= l-wx------ 1 root root 64 Aug 19 23:18 1 -> /dev/null lr-x------ 1 root root 64 Aug 19 23:18 0 -> /dev/null
this after the last bluealsa music start
Aug 19 22:57:13 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd18: fd(25) ready Aug 19 22:57:14 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd19: fd(25) ready Aug 19 22:58:06 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd20: fd(25) ready Aug 19 22:58:06 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd21: fd(25) ready
and bluealsa now has
lr-x------ 1 root root 64 Aug 19 23:19 9 -> 'pipe:[86726]'| lr-x------ 1 root root 64 Aug 19 23:19 8 -> 'pipe:[86723]'| lrwx------ 1 root root 64 Aug 19 23:19 7 -> 'anon_inode:[eventfd]' lrwx------ 1 root root 64 Aug 19 23:19 6 -> 'socket:[41558]'= lrwx------ 1 root root 64 Aug 19 23:19 5 -> 'anon_inode:[eventfd]' lrwx------ 1 root root 64 Aug 19 23:19 4 -> 'anon_inode:[eventfd]' l-wx------ 1 root root 64 Aug 19 23:19 3 -> /dev/null l-wx------ 1 root root 64 Aug 19 23:19 2 -> /dev/null lrwx------ 1 root root 64 Aug 19 23:19 19 -> 'socket:[87690]'= lrwx------ 1 root root 64 Aug 19 23:19 18 -> 'socket:[87690]'= lrwx------ 1 root root 64 Aug 19 23:19 16 -> 'socket:[86727]'= l-wx------ 1 root root 64 Aug 19 23:19 14 -> 'pipe:[86725]'| lr-x------ 1 root root 64 Aug 19 23:19 13 -> 'pipe:[86725]'| l-wx------ 1 root root 64 Aug 19 23:19 12 -> 'pipe:[86724]'| lr-x------ 1 root root 64 Aug 19 23:19 11 -> 'pipe:[86724]'| l-wx------ 1 root root 64 Aug 19 23:19 10 -> 'pipe:[86723]'| l-wx------ 1 root root 64 Aug 19 23:19 1 -> /dev/null lr-x------ 1 root root 64 Aug 19 23:19 0 -> /dev/null
Can it be that bluetoothd keeps sockets lingering somehow, which it did not before bluealsa 4.3.0? I have zero idea of DBUS etc..
Will compile now.. Ciao
(nah, forget that idiotic fd thing. after restart with debug-enabled bluealsa situation is the same.. i will report shall anything happen that i understand)
Aug 19 22:57:13 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd18: fd(25) ready Aug 19 22:57:14 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd19: fd(25) ready Aug 19 22:58:06 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd20: fd(25) ready Aug 19 22:58:06 kent bluetoothd[13142]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd21: fd(25) ready
Are you playing a lot of short audio tracks (up to 1 minute long) or one long one? I was newer using ogg123 before, maybe this app has some issues with the latest release, I will try to check that.
ogg123 (version 1.4.2) works fine here with bluealsa v4.3.0. I used:
ogg123 --device alsa -o dev:bluealsa music.ogg
tested with AAC , aptX and SBC my test file is:
music.ogg: Ogg data, Vorbis audio, stereo, 44100 Hz, ~112000 bps
and bluealsa is started as:
/usr/bin/bluealsa -S -p a2dp-source -p a2dp-sink -c aptx -c aac --loglevel=error
bluez 5.72
alsa 1.2.11
Yes, in that case short files. (Desertshore of Nico iirc.) And no, that has nothing to do with ogg123, i mostly have to deal with play(1) aka sox at the moment.
So maybe this should be closed, at the moment it just works, it was a total no-go on Sunday evening after booting into the new kernel 6.1.105 (and the new bluealsa), and yesterday it failed first, but after daemon restarts etc it is fine ever since.
That is: maybe it is in fact kernel related. When i look at "lynx https://git.kernel.org/stable/ds/v6.1.105/v6.1.103" i see two bluetooth entries. So why i have opened this issue? Surely because i thought "this time it is not the kernel" because of this completely new log message in the subject line. Anyway -- i keep on running the debug-enabled variant, and if anything happens, i will reopen this issue, ok?
Thank you!!
Yes, please keep running debug version, but in case nothing happens in let say a week/month, please switch to non-debug build. There might be a race which occurs only in release build. I will check that on my side as well, because I'm mostly running debug builds, so I could miss something.
There is also one more thing that you check and post the results here. Check for sampling rates and number of channels for all possible audio files that you've been playing just before the failure. If all the files have the same number of channels and sampling rate, then I'm not sure what might have happened. But if you've been playing all different files, than something indeed might be wrong with BlueALSA. The part that worries me is the message that there was no reply from endpoint. It definitely looks like a hangup in bluealsa daemon...
sox play definitely has a problem with bluealsa v4.3.0. Running
AUDIODEV=bluealsa play test-2-48000.ogg
I get bluez error:
Aug 21 09:37:31 MacBookAir bluetoothd[121913]: /org/bluez/hci0/dev_5C_F3_70_9B_FB_1A/sep2/fd117: fd(38) ready
Aug 21 09:37:35 MacBookAir bluetoothd[121913]: profiles/audio/media.c:endpoint_reply() Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply
But playing the same file with ogg123 is OK:
ogg123 --device alsa -o dev:bluealsa test-2-48000.ogg
I will try sox play with previous bluealsa release later today and compare the bluealsa debug logs.
However these tests have shown that there is a different bug in bluealsa v4.3.0. If I play a 6 channel file with ogg123 then bluealsa aborts with an assertion failure:
ERROR:../../../src/io.c:123:io_pcm_scale: assertion failed (channels <= ARRAYSIZE(pcm_volume_ch_scales)): (6 <= 2)
Bail out! ERROR:../../../src/io.c:123:io_pcm_scale: assertion failed (channels <= ARRAYSIZE(pcm_volume_ch_scales)): (6 <= 2)
Aborted
sox play definitely has a problem with bluealsa v4.3.0. Running
Many thanks for testing! I will look at this on weekend (I hope).
However these tests have shown that there is a different bug in bluealsa v4.3.0. If I play a 6 channel file with ogg123 then bluealsa aborts with an assertion failure
Yes, this bug is specific to AAC with allows more then 2 channel. This is not resolved yet, because it requires D-Bus API changes. I need to change D-Bus API for volume (now it's not scalable). Also, I need to add channels mapping to PCMs and for bluealsa ALSA PCM. I will do this for the next major release. Since this might be a real issue for 4.3.0 release, maybe it would be a good idea to cap channels to stereo until this issue not resolved?
maybe it would be a good idea to cap channels to stereo until this issue resolved?
Agreed - bluealsa should not offer any configuration which is guaranteed to cause denial-of-service!
Unfortunately, I was not able to trigger this issue. The fd counter in bluetoothd reached fd101 and no NoReply error:
Aug 21 21:17:33 raspberrypi bluetoothd[924]: /org/bluez/hci0/dev_1C_48_F9_9D_81_5C/sep1/fd101: fd(28) ready
I've checked that with debug enabled and without by playing 10s 2 channels 48k ogg audio in a loop. But maybe my host is too slow to trigger something... I've been checking it on my RPi4. I'm using BlueZ 5.66, though... So, maybe it's a bug in BlueZ.
OK, I will also look at other Bluez versions next week. With my current setup (Bluez 5.72) sox play fails every time (I only need to run it once). The unique aspect of sox is that it first opens the PCM with hw_params:
format:S8
channels:1
rate:8000
which, with bluealsa 4.3.0 using AAC codec, plug converts to:
format:S16_LE
channels:1
rate:8000
play then writes a brief burst of silence, then drains and closes the PCM. It then re-opens the PCM, and attemps to set the hw_params to those of the source file:
format:16_LE
channels:2
rate:48000
the call to snd_pcm_hw_params() fails with
ALSA lib ../../../../src/asound/bluealsa-pcm.c:590:(bluealsa_hw_params) Couldn't change BlueALSA PCM configuration: Input/output error
play FAIL formats: can't open output file `bluealsa': snd_pcm_hw_params error: Input/output error
and the org.freedesktop.DBus.Error.NoReply message appears in the bluetooth log.
I now have bluealsa logs from both 4.3.0 and 4.2.0 and will compare them over the next few days.
:flushed: I am testing on a machine with which I use pipewire with bluealsa. I thought I had disabled pipewire for these tests, but I was wrong. Now that the pipewire integration really is disabled then sox works every time and I am no longer able to reproduce the org.freedesktop.DBus.Error.NoReply error.
So I am no longer able to reproduce this. I have tried with bluez 5.72 and bluez 5.66. Sorry for the confusion and time wasted.
Hmm... So, maybe @sdaoden case is exactly the same. I've tried on my side with BlueZ 5.77 and I can not see any issues either.
There is clearly the potential for problems when 2 or more clients are active at the same time, because I had to disconnect and re-connect the remote speaker to recover. So I will continue to look at this, but now with more awareness of what to look for!
By two clients you mean two BlueALSA clients or two applications registered in BlueZ?
I'm not sure right now. Will look at it more next week. My pipewire integration relies on wireplumber to disable pipewire's own bluetooth. I need to establish whether or not wireplumber was running when the problem was occuring. If it was, then the problem was 2 bluealsa clients. If wireplumber was not running, then the problem was 2 applications registered in bluez. So many logs to look through and so little time available!
I am not using pipewire, i have only ALSA. I use apulse in order to have some sound in firefox-bin as of mozilla (only to laptop speakers thus, .. mostly, with the music muted or paused). (And no graphics otherwise here, no wayland, no seat, only firefox, mupdf, imagemagick, and a terminal etc etc).
It has not happened again here; i could imagine that the Linux device reinitialization after the "echo mem > /sys/power/state" and the wakeup does its thing to that. (I only boot the laptop once a week.) I do not know enough to tell. All i know is
# grep -Fri 'error.noreply' . ./messages:Aug 18 23:27:46 kent bluetoothd[637]: profiles/audio/media.c:endpoint_reply() Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply ./messages:Aug 19 01:59:01 kent bluetoothd[637]: profiles/audio/media.c:endpoint_reply() Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply ./messages:Aug 19 18:12:50 kent bluetoothd[13142]: profiles/audio/media.c:endpoint_reply() Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply
Here is one with debug (not much though):
$ playbt sade-no_ordinary_love.ogg 0.000335: [8319] D: ../../../src/asound/bluealsa-pcm.c:1536: Getting BlueALSA PCM: PLAYBACK 00:F4:8D:33:38:FA a2dp 0.001002: [8319] D: ../../../src/asound/bluealsa-pcm.c:1296: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Setting constraints play WARN alsa: can't encode 0-bit Unknown or not applicable 0.004421: [8319] D: ../../../src/asound/bluealsa-pcm.c:566: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing HW 0.004471: [8319] D: ../../../src/asound/bluealsa-pcm.c:580: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Changing BlueALSA PCM configuration: 2 ch, 44100 Hz -> 1 ch, 16000 Hz ALSA lib ../../../src/asound/bluealsa-pcm.c:590:(bluealsa_hw_params) Couldn't change BlueALSA PCM configuration: Input/output error Floating point exception
Aug Aug 23 00:02:34 kent bluetoothd[1312]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd56: fd(25) ready 23 00:21:44 kent bluetoothd[1312]: profiles/audio/media.c:endpoint_reply() Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply Aug 23 00:22:38 kent rfkill: unblock set for type wlan
(ie nothing before and after, and i immediately go here now)
kernel only said
Aug 23 00:21:44 kent kernel: traps: play[8319] trap divide error ip:7f54aef1ad22 sp:7ffc0cd8ed70 error:0 in libsox.so.3.0.0[7f54aeecc000+5a000]
Ok, and if rfkill bluetooth and thus restart the Philips TV, and redo (without restarting bluealsa or bluez):
Aug 23 00:26:34 kent rfkill: block set for type bluetooth Aug 23 00:27:11 kent bluetoothd[1312]: Failed to set mode: Failed (0x03) Aug 23 00:27:11 kent bluetoothd[1312]: Path / reserved for Adv Monitor app :1.842 Aug 23 00:27:11 kent bluetoothd[1312]: Adv Monitor app :1.842 disconnected from D-Bus Aug 23 00:27:23 kent rfkill: unblock set for type bluetooth Aug 23 00:27:25 kent bluetoothd[1312]: Path / reserved for Adv Monitor app :1.843 Aug 23 00:27:25 kent bluetoothd[1312]: Adv Monitor app :1.843 disconnected from D-Bus Aug 23 00:27:32 kent bluetoothd[1312]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd59: fd(25) ready Aug 23 00:27:33 kent bluetoothd[1312]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd60: fd(25) ready
And this time it runs (again, like on Sunday):
$ playbt sade-no_ordinary_love.ogg 0.001651: [9296] D: ../../../src/asound/bluealsa-pcm.c:1536: Getting BlueALSA PCM: PLAYBACK 00:F4:8D:33:38:FA a2dp 0.003792: [9296] D: ../../../src/asound/bluealsa-pcm.c:1296: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Setting constraints play WARN alsa: can't encode 0-bit Unknown or not applicable 0.019141: [9296] D: ../../../src/asound/bluealsa-pcm.c:566: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing HW 0.019193: [9296] D: ../../../src/asound/bluealsa-pcm.c:580: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Changing BlueALSA PCM configuration: 2 ch, 48000 Hz -> 1 ch, 16000 Hz 0.614371: [9296] D: ../../../src/asound/bluealsa-pcm.c:631: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: FIFO buffer size: 2048 frames 0.614423: [9296] D: ../../../src/asound/bluealsa-pcm.c:636: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Selected HW buffer: 8 periods x 16384 bytes == 131072 bytes 0.614484: [9296] D: ../../../src/asound/bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing SW 0.614594: [9296] D: ../../../src/asound/bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing SW 0.614628: [9296] D: ../../../src/asound/bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing SW 0.614662: [9296] D: ../../../src/asound/bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing SW 0.614701: [9296] D: ../../../src/asound/bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Prepared 0.614734: [9296] D: ../../../src/asound/bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Prepared 0.614831: [9296] D: ../../../src/asound/bluealsa-pcm.c:723: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Draining 0.614858: [9296] D: ../../../src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Starting 0.615190: [9300] D: ../../../src/asound/bluealsa-pcm.c:235: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Starting IO loop: 7 0.615236: [9300] D: ../../../src/asound/bluealsa-pcm.c:244: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Pausing IO thread 0.915695: [9296] D: ../../../src/asound/bluealsa-pcm.c:428: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Stopping 0.916305: [9300] D: ../../../src/asound/bluealsa-pcm.c:171: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: IO thread cleanup 0.916685: [9296] D: ../../../src/asound/bluealsa-pcm.c:428: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Stopping 0.916890: [9296] D: ../../../src/asound/bluealsa-pcm.c:646: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Freeing HW 0.916958: [9296] D: ../../../src/asound/bluealsa-pcm.c:475: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Closing 0.929397: [9296] D: ../../../src/asound/bluealsa-pcm.c:1536: Getting BlueALSA PCM: PLAYBACK 00:F4:8D:33:38:FA a2dp 0.932105: [9296] D: ../../../src/asound/bluealsa-pcm.c:1296: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Setting constraints 0.940237: [9296] D: ../../../src/asound/bluealsa-pcm.c:566: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing HW 0.940252: [9296] D: ../../../src/asound/bluealsa-pcm.c:580: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Changing BlueALSA PCM configuration: 1 ch, 16000 Hz -> 2 ch, 48000 Hz 1.529400: [9296] D: ../../../src/asound/bluealsa-pcm.c:631: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: FIFO buffer size: 1024 frames 1.529450: [9296] D: ../../../src/asound/bluealsa-pcm.c:636: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Selected HW buffer: 8 periods x 8192 bytes == 65536 bytes 1.529500: [9296] D: ../../../src/asound/bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing SW 1.529577: [9296] D: ../../../src/asound/bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing SW 1.529608: [9296] D: ../../../src/asound/bluealsa-pcm.c:667: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Initializing SW 1.529641: [9296] D: ../../../src/asound/bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Prepared 1.529675: [9296] D: ../../../src/asound/bluealsa-pcm.c:717: /org/bluealsa/hci0/dev_00_F4_8D_33_38_FA/a2dpsrc/sink: Prepared
Here is one with debug (not much though)
Do you have logs from bluealsa daemon? I'm mostly interested in these logs.
No only what i gave you. Did not think about that, 'would have thought a debug-enabled build does something like that by default maybe.
Actually i did not know that -S needs to be given, where does this thing log otherwise?
So i added -S and -l to
OPTS="-S -l debug -p a2dp-sink -p a2dp-source -c AAC"
but it silently simply does not start then.
So i dropped "-l debug" again, and then it starts and has debug level by default it seems.
Aug 23 23:04:13 kent bluealsa: ../../src/a2dp-aac.c:702: FDK-AAC encoder capabilities: aac=0x410b1 sbr=0x22 Aug 23 23:04:13 kent bluealsa: ../../src/a2dp-aac.c:790: FDK-AAC decoder capabilities: aac=0x1a4ffff sbr=0x1bf dmx=0x7f Aug 23 23:04:13 kent bluealsa: ../../src/storage.c:90: Initializing persistent storage: /usr/var/lib/bluealsa Aug 23 23:04:13 kent bluealsa: ../../src/main.c:663: Starting main dispatching loop Aug 23 23:04:13 kent bluealsa: ../../src/main.c:118: Acquired D-Bus service name: org.bluealsa Aug 23 23:04:13 kent bluealsa: ../../src/bluealsa-dbus.c:358: Registering BlueALSA D-Bus manager: /org/bluealsa Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:153: Registering media application: /org/bluez/hci0 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/AAC/source/1 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/AAC/source/2 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/AAC/sink/1 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/AAC/sink/2 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/1 Aug 23 23:04:13 kent bluealsa: ../../src/bluez.c:743: Exporting media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/2
Wonderful. Shall something happen again i can give you those logs, too :) :-( Anyhow i did not tick and did not try to play something again, but instead re-paired the bluetooth thing directly. So .. (i hope this does not log soo much now.. By the way, where does it log to without -S, there is no possibility to specify a file target?? Thanks and Ciao, hopefully less than three days for next lock.. o/
By default bluealsa logs to stderr like most applications. If you are running it via systemd then logs are in journalctl. Otherwise, it depends on used init system.
@sdaoden
By the way, where does it log to without -S
It logs to stderr, but clearly from your earlier comment your init script is redirecting stdout and stderr to /dev/null
l-wx------ 1 root root 64 Aug 19 23:19 1 -> /dev/null l-wx------ 1 root root 64 Aug 19 23:19 2 -> /dev/null
So you need to modify your init script if you want stderr redirected to a file.
@arkq
I have now confirmed that pipewire bluetooth modules are disabled, so this issue is occurring for me when two or more clients interact with the same bluealsa PCM at the same time. Only one (sox) is calling org.bluealsa.PCM1.Open(), the others do call org.bluealsa.PCM1.SelectCodec(). I still have not determined the exact sequence of events and timing that trigger it.
Only one (sox) is calling org.bluealsa.PCM1.Open(), the others do call org.bluealsa.PCM1.SelectCodec().
OK, I'll try to test that on my side. Anyway, in current form of bluealsa PCM plugin, I think that there is a race in case where more than one client tries to operate the same PCM. In the bluealsa_hw_params() functions there is call for codec reconfiguration (if needed) and PCM open. But these two operations are not atomic. So, currently it's not guaranteed that after PCM open, the configuration is correct... I think that params verification after PCM open might mitigate that particular issue. But there might be more issues like that in the code. To definitely solve this problem some sort of PCM "lock" in BlueALSA service is required, I think.