sdaoden
commented
3 months ago (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.)
Closed sdaoden closed 2 months ago
sdaoden
commented
3 months ago (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.)
sdaoden
commented
3 months ago (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.)
arkq
commented
3 months ago Could you compile bluez-alsa with debug enabled and provide some logs from bluealsa deamon and client application?
sdaoden
commented
3 months ago 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
sdaoden
commented
3 months ago (there are no log messages for sockets later than fd21, really.)
sdaoden
commented
3 months ago (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)
arkq
commented
3 months ago 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.
borine
commented
3 months ago ogg123 (version 1.4.2) works fine here with bluealsa v4.3.0. I used:
ogg123 --device alsa -o dev:bluealsa music.oggtested with AAC , aptX and SBC my test file is:
music.ogg: Ogg data, Vorbis audio, stereo, 44100 Hz, ~112000 bpsand bluealsa is started as:
/usr/bin/bluealsa -S -p a2dp-source -p a2dp-sink -c aptx -c aac --loglevel=errorbluez 5.72
alsa 1.2.11
sdaoden
commented
3 months ago 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!!
arkq
commented
3 months ago 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.
arkq
commented
3 months ago 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...
sdaoden
commented
3 months ago Good point, and 'will do!! Ciao!
borine
commented
3 months ago sox play definitely has a problem with bluealsa v4.3.0. Running
AUDIODEV=bluealsa play test-2-48000.oggI 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.NoReplyBut playing the same file with ogg123 is OK:
ogg123 --device alsa -o dev:bluealsa test-2-48000.oggI 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)
Abortedsox 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?
borine
commented
3 months ago 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!
arkq
commented
3 months ago 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) readyI'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.
borine
commented
3 months ago 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:8000which, with bluealsa 4.3.0 using AAC codec, plug converts to:
format:S16_LE
channels:1
rate:8000play 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:48000the 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 errorand 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.
borine
commented
3 months ago :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.
arkq
commented
3 months ago 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.
borine
commented
3 months ago 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!
arkq
commented
3 months ago By two clients you mean two BlueALSA clients or two applications registered in BlueZ?
borine
commented
3 months ago 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!
sdaoden
commented
3 months ago 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
sdaoden
commented
3 months ago 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]
sdaoden
commented
3 months ago 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
arkq
commented
3 months ago Here is one with debug (not much though)
Do you have logs from bluealsa daemon? I'm mostly interested in these logs.
sdaoden
commented
3 months ago 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/
arkq
commented
3 months ago 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.
borine
commented
3 months ago @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.
arkq
commented
3 months ago 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.
sdaoden
commented
3 months ago Thanks ;-))
That is your own fault, by not including a usable manual page with release tarballs! Yes, would be cool if you would do (again), btrfs-progs for example did. I will not install python3-docutils just to turn some .rst into a usable Unix manual page, this should really be part of a distribution tarball, in my opinion. Other than that i do things like
man=./ipcalc.1
cat > ./ipcalc.1 <<- \!
.Dd Nov 26, 2022
.Dt IPCALC 1
.Os
.
.Sh NAME
.Nm ipcalc
.Nd Calculate IP broadcast, host range etc
.
.Bd -literal
!
cat ipcalc.1.md >> ./ipcalc.1
echo '.Ed' >> ./ipcalc.1
for ipcalc, so i very well can do something like this for bluealsa, too. Will do. (My package for CRUX Linux is no longer official and part of "contrib", but nonetheless.) (I think github actions could do all that, when you release via there. But i have no idea, just thought now i have seen it somewhen.)
No here it is start-stop-daemon. I have now added -S to the package bluealsa.conf script. No i never looked. It just works (tm). Thank you.
I will report with log if anything happens.
sdaoden
commented
3 months ago (I took over the package once the original maintainer left, "as-is". If i recall correctly. Anyhow, now -S.)
sdaoden
commented
3 months ago ("Most applications", but bluealsa is a server. In the systemd or container world even those, however, maybe. I have now added this, it will be in the next release:
doc=
prt-get isinst python3-docutils >/dev/null 2>&1 && doc=y cnf=${cnf}' --enable-manpages'
(this is not new but doc=)
if [ -z "${doc}" ]; then
date=$(date +'%b %d, %Y')
umask 0022
for f in doc/*.[178].rst; do
m=${f%*.rst}
m=${m##*/}
s=${m##*.}
M=${m%.*}
x="${PKG}"/usr/share/man/man${s}
mkdir -m 0755 -p "${x}"
x=${x}/${m}
printf '.Dd %s\n.Dt %s %s\n.Os\n.\n.Sh NAME\n.Nm %s\n.Nd %s\n.\n.Bd -literal\n' \
"${date}" "${M}" "${s}" "${m}" "${m}" > "${x}"
cat ${f} >> "${x}"
echo '.Ed' >> "${x}"
chmod 0644 "${x}"
done
Looks horrifying, but will do.)
borine
commented
3 months ago @arkq here's a minimal script I can use to reproduce the NoReply bluez error:
#!/bin/bash
set -e
DEVICE="/org/bluealsa/hci0/dev_5C_F3_70_9B_FB_1A/a2dpsrc/sink"
while true ; do
bluealsa-cli codec -c1 -s8000 "$DEVICE" aac
dd if=/dev/zero bs=4 count=1024 | bluealsa-cli open "$DEVICE"
bluealsa-cli codec -c2 -s48000 "$DEVICE" aac
dd if=/dev/zero bs=4 count=1024 | bluealsa-cli open "$DEVICE"
doneIt can run for many minutes without failing, but if I start a second instance then failure occurs much more quickly. The logs are inconclusive - this could be a synchronization error in bluealsa, or it could be a failure in the bluetooth daemon.
arkq
commented
3 months ago Many thanks for that. Yesterday, I've been trying to trigger it but without a success. I'll try your script later today.
arkq
commented
3 months ago Unfortunately, I was not able to reproduce it with your script. It just keep running. Starting another script does not work because during the process of codec change, the PCM is unregistered from D-Bus, so bluealsa-cli complains that there is no PCM path...
borine
commented
3 months ago So in the end it appears the problem I'm seeing lies in the remote device. I've borrowed a different speaker with AAC support, and am unable to reproduce the failure with that. AFAICT the remote device is slow to respond to AVDTP SetConfiguration requests, and sometimes Bluez times out while waiting for the response. There does not seem to be any specific sequence of events that leads to this. When Bluez times out the request it closes the A2DP profile connection (AVRCP remains connected). So, assuming @sdaoden is no longer experiencing this problem, I think there is not much more that can be done by BlueALSA.
arkq
commented
3 months ago I've used all devices that I have and I was not able to reproduce it (with BlueZ 5.77). I've kept running this script for ~10 minutes for each device. So, unless some logs will be provided, which will at least point the direction, I'm afraid that I can do nothing about it... I will make a fixup release with found DDoS bugs, though.
arkq
commented
3 months ago That is your own fault, by not including a usable manual page with release tarballs!
Documentation is released in a rather readable reStructuredText format. However, it is a package maintainer responsibility to create distribution package (RPM, DEB, ebuild, or any other) which follows particular distribution standards (e.g. man pages). Also, you do not need to create man pages by yourself, but use the provided build system option --enable-manpages, which will build manual pages for you (release tarballs do not include executables either :D).
sdaoden
commented
3 months ago Ääh, i totally disagree. This is Unix, and it has a documentation system. I cannot install rst or whatever format into the well-known and established paths, as the documentation system in use is incapable of working with that. (Ie, try it..) Sure the big big binary creators. Well at least you do not require a rust crate for doing all that.. (My real opinion is really even worse btw; especially if releases are build on some complex external machinery for which creating real Unix tarballs is just a one or two line config setting.) But regardless. (I can tell you how happy i was once btrfs-progs restarted shipping real manuals, that much is plain.)
It did not happen again, with debug and logging, even though the music plays many hours a day. (Though: most often that is only a single track.)
I keep trying 'till say Tuesday next week, and then i rebuild without debug, but keep the log on (now default for the package), it has been off always until now.
Which --loglevel shall i use then, without debug-enabled build? Any other hints what i could do?
I mean, i could instrument the code when i recompile, for example, you know? It seemed to me you had an idea on what is going on.
Mind you, the note above regarding timeout rang a bell. Here around this flat there are "electro-mechanic engineers", you know, there is a university for these guys here. We have a lot of "electro smog" (i have no idea of that stuff).
One common failure of this Philips TV, or its relation with the Linux bluetooth stack and bluealsa is that it seems it runs out of sync, it is stuttering, you know, as if only every second sample is played.
The connection "breaks" then, bluealsa thinks the device is gone, but the device keeps signalling there is an existing connection.
We had this yesterday for example, we then get
Aug 29 01:51:00 kent bluealsa: ../../src/io.c:95: BT write error: Connection timed out Aug 29 01:51:06 kent bluetoothd[19602]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 00:F4:8D:33:38:FA: Host is down (112) Aug 29 01:51:31 kent bluetoothd[19602]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 00:F4:8D:33:38:FA: Operation already in progress (114) Aug 29 01:52:20 kent rfkill: block set for type bluetooth Aug 29 01:54:35 kent rfkill: unblock set for type bluetooth Aug 29 01:54:38 kent bluetoothd[19602]: Failed to set mode: Authentication Failed (0x05) Aug 29 01:54:39 kent bluetoothd[19602]: Path / reserved for Adv Monitor app :1.555 ======= Aug 29 01:52:20 kent kernel: Bluetooth: hci0: command 0x0c03 tx timeout Aug 29 01:52:20 kent kernel: Bluetooth: hci0: HCI reset during shutdown failed Aug 29 01:54:38 kent kernel: Bluetooth: hci0: Opcode 0x0c03 failed: -110 Aug 29 01:54:39 kent kernel: Bluetooth: hci0: unexpected event for opcode 0xfcf0 ======= Aug 29 01:51:00 kent bluealsa: ../../src/ba-transport-pcm.c:307: Closing BT socket duplicate [19]: 20 Aug 29 01:51:00 kent bluealsa: ../../src/a2dp-sbc.c:277: PCM IO loop: EXIT: a2dp_sbc_enc_thread: A2DP Source (SBC) Aug 29 01:51:00 kent bluealsa: ../../src/ba-transport.c:346: Releasing A2DP transport: 19 Aug 29 01:51:00 kent bluealsa: ../../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.ClearConfiguration() on /org/bluez/hci0/A2DP/SBC/source/1 Aug 29 01:51:00 kent bluealsa: ../../src/bluez.c:615: Disconnecting media endpoint: /org/bluez/hci0/A2DP/SBC/source/1 Aug 29 01:51:00 kent bluealsa: ../../src/ba-transport.c:381: Closing A2DP transport: 19 Aug 29 01:51:00 kent bluealsa: ../../src/ba-transport-pcm.c:257: Exiting IO thread [ba-a2dp-sbc]: A2DP Source (SBC) Aug 29 01:51:00 kent bluealsa: ../../src/ba-transport-pcm.c:453: Closing PCM: 10 Aug 29 01:51:00 kent bluealsa: ../../src/ba-transport.c:826: Freeing transport: A2DP Source (SBC) Aug 29 01:51:00 kent bluealsa: ../../src/storage.c:160: Saving storage: /usr/var/lib/bluealsa/00:F4:8D:33:38:FA Aug 29 01:51:00 kent bluealsa: ../../src/ba-device.c:143: Freeing device: 00:F4:8D:33:38:FA Aug 29 01:51:00 kent bluealsa: ../../src/bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd21, ...) Aug 29 01:51:00 kent bluealsa: ../../src/bluez.c:1393: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved(/org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1, ...) Aug 29 01:51:00 kent bluealsa: ../../src/bluez.c:1428: Removing Stream End-Point: 00:F4:8D:33:38:FA: SNK: SBC Aug 29 01:54:55 kent bluealsa: ../../src/bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1, ...) Aug 29 01:54:55 kent bluealsa: ../../src/bluez.c:1362: Adding new Stream End-Point: 00:F4:8D:33:38:FA: SNK: SBC Aug 29 01:54:55 kent bluealsa: ../../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/SBC/source/1 Aug 29 01:54:55 kent bluealsa: ../../src/bluez.c:429: A2DP peer capabilities blob [len=4]: ffff0235 Aug 29 01:54:55 kent bluealsa: ../../src/bluez.c:1290: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded(/org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd22, ...) Aug 29 01:54:55 kent bluealsa: ../../src/dbus.c:47: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/source/1 Aug 29 01:54:55 kent bluealsa: ../../src/a2dp-sbc.c:536: SBC: Selected bit-pool range: [2, 53] Aug 29 01:54:55 kent bluealsa: ../../src/storage.c:123: Loading storage: /usr/var/lib/bluealsa/00:F4:8D:33:38:FA Aug 29 01:54:55 kent bluealsa: ../../src/bluez.c:572: A2DP Source (SBC) configured for device 00:F4:8D:33:38:FA Aug 29 01:54:55 kent bluealsa: ../../src/bluez.c:575: A2DP selected configuration blob [len=4]: 11150235 Aug 29 01:54:55 kent bluealsa: ../../src/bluez.c:577: PCM configuration: channels: 2, sampling: 48000
borine
commented
3 months ago @sdaoden re manual pages. Perhaps you should confer with the Bluez package maintainer for your distribution. Bluez source has used rst format for its manual pages since release 5.59 in 2021, and its autoconf/automake build system uses rst2man to create installable man pages just like bluez-alsa does. So perhaps you could use the same approach as the Bluez maintainer does for installing manual pages. BTW if your distribution includes python, then the python-docutils really is quite a small addition and its hard to see how it constitutes an "iron crate". Of course that is just my own personal opinion and as such is no more or less valid than yours.
sdaoden
commented
3 months ago Yup, 4.3.1 without debug and within a day
Sep 3 00:39:53 kent bluetoothd[644]: /org/bluez/hci0/dev_00_F4_8D_33_38_FA/sep1/fd23: fd(25) ready Sep 3 00:51:42 kent bluetoothd[644]: profiles/audio/media.c:endpoint_reply() Endpoint replied with an error: org.freedesktop.DBus.Error.NoReply Sep 3 00:51:42 kent bluealsa: Couldn't set A2DP configuration: GDBus.Error:org.bluez.Error.Failed: Resource temporarily unavailable Sep 3 00:51:42 kent bluealsa: Couldn't select codec: SBC: Input/output error
sdaoden
commented
3 months ago The TV things it is still connected, and if i try to play another song there is simply nothing. No more syslog entry at all.
sdaoden
commented
3 months ago ie
Sep 3 00:51:43 kent kernel: traps: play[1558] trap divide error ip:7f05c6f3fd22 sp:7ffe75e9eea0 error:0 in libsox.so.3.0.0[7f05c6ef1000+5a000] Sep 3 00:53:02 kent kernel: overlayfs: "xino" feature enabled using 2 upper inode bits. Sep 3 00:54:03 kent kernel: traps: play[2328] trap divide error ip:7faf22091d22 sp:7ffe5bbb51b0 error:0 in libsox.so.3.0.0[7faf22043000+5a000]
But bluealsa is running with
lrwx------ 1 root root 64 Sep 3 00:57 8 -> 'socket:[172]'= lrwx------ 1 root root 64 Sep 3 00:57 7 -> 'anon_inode:[eventfd]' lrwx------ 1 root root 64 Sep 3 00:57 6 -> 'socket:[156]'= lrwx------ 1 root root 64 Sep 3 00:57 5 -> 'anon_inode:[eventfd]' lrwx------ 1 root root 64 Sep 3 00:57 4 -> 'anon_inode:[eventfd]' l-wx------ 1 root root 64 Sep 3 00:57 3 -> /dev/null l-wx------ 1 root root 64 Sep 3 00:57 2 -> /dev/null l-wx------ 1 root root 64 Sep 3 00:57 1 -> /dev/null lr-x------ 1 root root 64 Sep 3 00:57 0 -> /dev/null
sdaoden
commented
3 months ago @borine bluealsa is bluealsa, bluetoothd is bluetoothd. I know how it works, i have one program with a rst docu myself. (But still i do not have python-docutils not installed no more.) But it is his decision, and if he really refrains from doing i cannot help it.
sdaoden
commented
3 months ago Maybe EAGAIN should be retried somewhere once or twice? I have no idea, but am willing to test a patch and instrument the code further as necessary Good night!
sdaoden
commented
3 months ago and, looking into bluez_a2dp_set_configuration, i can assure you there is only one bluetooth device here. (It still thinks it is connected, but i break it now, nothing to learn from trying again.) I online-re-paired
$ ptv-pair doas (steffen@kent) password: [ptv]# power on [ptv]# connect 00:F4:8D:33:38:FA Attempting to connect to 00:F4:8D:33:38:FA hci0 new_settings: powered bondable ssp br/edr le secure-conn
which then
Sep 3 01:08:52 kent bluetoothd[644]: profiles/audio/a2dp.c:a2dp_select_capabilities() Unable to select SEP Sep 3 01:08:52 kent bluetoothd[644]: Path / reserved for Adv Monitor app :1.372 Sep 3 01:08:52 kent bluetoothd[644]: Adv Monitor app :1.372 disconnected from D-Bus
made the device go, so i make it hot again and it pairs!
$ ptv-pair [bluetooth]# power on bluetoothd... [bluetooth]# connect 00:F4:8D:33:38:FA Attempting to connect to 00:F4:8D:33:38:FA
And the music plays again. So maybe it is as easy as retrying a few times on EAGAIN? I have no idea of DBUS, by sheer luck.
borine
commented
3 months ago I think it is not necessary to unpair and repair to recover the A2DP profile; simply disconnect then connect should be sufficient:
bluetoothctl disconnect 00:F4:8D:33:38:FA
bluetoothctl connect 00:F4:8D:33:38:FASo maybe it is as easy as retrying a few times on EAGAIN?
I think the problem with re-retrying is that Bluez appears to have dropped the A2DP profile completely, so there are no endpoints remaining for bluealsa to retry with. The EAGAIN error confuses me, because I cannot see where in the code this is set. I am guessing it is set within the gio dbus library code, but have not checked that yet.
borine
commented
3 months ago I was wrong., EAGAIN is being set in the bluez avdtp code. Any error except EHOSTDOWN, ECONNABORTED, EBADE, and ECONNREFUSED is converted to EAGAIN before the error is returned to the client callback function. So the actual endpoint error "No Reply" that we see in the bluetoothd logs (which actually means that the timeout occured before any reply was received from the remote device) is being passed to bluealsa as EAGAIN.
borine
commented
2 months ago To avoid this error when using bluealsa 4.3.0 or later, you can force the ALSA plug plugin to do the rate conversion (to prevent bluealsa from trying to change the codec configuration) by slightly modifying your ~/.asoundrc entry; for example:
pcm.bt {
type plug
slave {
pcm { type bluealsa; device "00:F4:8D:33:38:FA"; profile "a2dp" }
channels 2
rate 44100
}
hint { show on; description "ptv, Frau Antje Bluetooth" }
}This example assumes that the device auto-selects rate 44100 on connecting, so you may have to use 48000 or 96000 or whatever the initially selected configuration may be.
Hello!
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:
On the application side we then see (of course)
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
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