snapcast icon indicating copy to clipboard operation
snapcast copied to clipboard
verified publisher icon badaix

Cannot use hardware mixer in combination with Bluealsa

Open Matthijsy opened this issue 11 months ago • 11 comments

Describe the bug I am trying to use the hardware mixer in combination with Bluealsa in my snapclient configuration. My system has a Bluetooth speaker connected, which uses bluealsa and works fine when using the software mixer. However as soon as I try the following it give an error.

snapclient -h <host> -s bluealsa --mixer hardware:'<device name>'

The error is as follows:

[Fatal] (Snapclient) Exception: assign: Bad file descriptor [system:9 at ./boost_1_85_0/boost/asio/detail/impl/reactive_descriptor_service.ipp:120 in function 'assign']
[Notice] (Snapclient) Snapclient terminated.

Environment details

  • OS: Debian 12
  • Snapcast version: v0.29.0
  • Installed from Github releases

Attach logfile if applicable Generate logs with snapclient --logfilter debug or snapserver --logging.filter debug if possible and paste them in the following codeblock

2025-01-01 21-09-08.075 [Info] (Snapclient) Version 0.29.0, revision 208066e5
2025-01-01 21-09-08.075 [Info] (Connection) Resolving host IP for: <redacted>
2025-01-01 21-09-08.075 [Info] (Connection) Connecting to <redacted>:1704
2025-01-01 21-09-08.076 [Notice] (Connection) Connected to <redacted>
2025-01-01 21-09-08.076 [Info] (Connection) My MAC: "<redacted>", socket: 8
2025-01-01 21-09-08.083 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2025-01-01 21-09-08.084 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2025-01-01 21-09-08.084 [Info] (Player) Player name: alsa, device: bluealsa, description: Bluetooth Audio Hub, idx: 4, sharing mode: unspecified, parameters: <none>
2025-01-01 21-09-08.084 [Info] (Player) Mixer mode: hardware, parameters: SRS-XB100 - A2DP
2025-01-01 21-09-08.084 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2025-01-01 21-09-08.084 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
D: bluealsa-pcm.c:1309: Getting BlueALSA PCM: PLAYBACK 00:A4:1C:20:5C:A7 a2dp
D: bluealsa-pcm.c:1062: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Setting constraints
D: bluealsa-pcm.c:532: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Initializing HW
D: bluealsa-pcm.c:567: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: FIFO buffer size: 1024 frames
D: bluealsa-pcm.c:581: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Selected HW buffer: 4 periods x 3840 bytes == 15360 bytes
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Prepared
2025-01-01 21-09-08.272 [Info] (Alsa) PCM name: bluealsa, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Initializing SW
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/rfcomm”
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/rfcomm”
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:592: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Freeing HW
D: bluealsa-pcm.c:443: /org/bluealsa/hci0/dev_00_A4_1C_20_5C_A7/a2dpsrc/sink: Closing
2025-01-01 21-09-08.277 [Fatal] (Snapclient) Exception: assign: Bad file descriptor [system:9 at ./boost_1_85_0/boost/asio/detail/impl/reactive_descriptor_service.ipp:120 in function 'assign']
2025-01-01 21-09-08.277 [Notice] (Snapclient) Snapclient terminated.

Matthijsy avatar Jan 01 '25 21:01 Matthijsy

Just came across this post while looking for something else. I am not a regular snapcast user, but have some experience with bluealsa.

snapclient's --mixer hardware: option was designed specifically for use with sound cards where the mixer card name is the same as the PCM card name, and therefore the --soundcard option is shared with both PCM and mixer. To make that assumption work with bluealsa, I recommend that you add to your alsa config:

defaults.bluealsa.ctl.device "00:00:00:00:00:00"
defaults.bluealsa.ctl.dynamic "no"

then run snapclient as

snapclient --soundcard bluealsa --mixer hardware:A2DP

borine avatar Apr 20 '25 18:04 borine

Just came across this post while looking for something else. I am not a regular snapcast user, but have some experience with bluealsa.

snapclient's --mixer hardware: option was designed specifically for use with sound cards where the mixer card name is the same as the PCM card name, and therefore the --soundcard option is shared with both PCM and mixer. To make that assumption work with bluealsa, I recommend that you add to your alsa config:

defaults.bluealsa.ctl.device "00:00:00:00:00:00"
defaults.bluealsa.ctl.dynamic "no"

then run snapclient as

snapclient --soundcard bluealsa --mixer hardware:A2DP

This does sadly not work for me. Snapclient deos start with those options, but the volume level of the bluetooth speaker is not controlled by snapclient.

dflvunoooooo avatar Apr 23 '25 13:04 dflvunoooooo

the bluetooth speaker is not controlled by snapclient.

Please can you post the version of bluealsa that you are running and the command line that you use to start it. Also the same log from snapclient with the updated alsa config would be helpful for debugging.

borine avatar Apr 23 '25 15:04 borine

Of cause. bluez-alsa-utils has version Version: 4.0.0-2 and gets started with systemd via systemctl status bluealsa. The service file contains

[Unit]
Description=BlueALSA service
Documentation=man:bluealsa(8)
Requisite=dbus.service
After=bluetooth.service

# In order to customize BlueALSA D-Bus service one should create an override
# for this systemd unit file. Please note, that in the override file one will
# have to explicitly clear the ExecStart before setting it again. See the
# bluez-alsa wiki for more options.
#
# $ sudo systemctl edit bluealsa
# [Service]
# ExecStart=
# ExecStart=/usr/bin/bluealsa --keep-alive=5 -p a2dp-sink

[Service]
Type=dbus
BusName=org.bluealsa
ExecStart=/usr/bin/bluealsa -p a2dp-source -p a2dp-sink
Restart=on-failure

# Sandboxing
CapabilityBoundingSet=
IPAddressDeny=any
LockPersonality=true
MemoryDenyWriteExecute=true
NoNewPrivileges=true
PrivateDevices=true
PrivateTmp=true
PrivateUsers=true
ProtectControlGroups=true
ProtectHome=true
ProtectHostname=true
ProtectKernelLogs=true
ProtectKernelModules=true
ProtectKernelTunables=true
ProtectSystem=strict
RestrictAddressFamilies=AF_UNIX AF_BLUETOOTH
RestrictNamespaces=true
RestrictRealtime=true
RestrictSUIDSGID=true
SystemCallArchitectures=native
SystemCallErrorNumber=EPERM
SystemCallFilter=@system-service
SystemCallFilter=~@resources @privileged
UMask=0077

[Install]
WantedBy=bluetooth.target

Snapclient has version 0.31.0-1 and gets started with the dafault systemcd service und the snapclient options --user snapclient --host X.X.X.X --hostID raspi-bluetooth --soundcard bluealsa --a2dp-force-mono --mixer hardware:A2DP". I found the --a2dp-force-mono option in another issue relating bluetooth. But it doesn't matter if it is there or not for this issue.

Tha alsa config is

defaults.bluealsa {
    ctl.device "00:00:00:00:00:00"
    ctl.dynamic "no"
}

Edit: I am using Raspberry Pi Os Lite, which means Bookworm, in the 64 bit version on a Raspberry Pi 4, if that matters.

dflvunoooooo avatar Apr 24 '25 07:04 dflvunoooooo

So I've just built and installed bluealsa 4.0.0. snapclient is started as

snapclient --soundcard bluealsa --mixer hardware:A2DP

Using snapweb to control the volume I can see the bluetooth volume change using

alsamixer -D bluealsa

and can hear the volume changes on the connected bluetooth speaker.

Please can you post the snapclient debug log as in your original post so that we can compare the effect of the new alsa settings with your original?

borine avatar Apr 24 '25 10:04 borine

oh - one more thought, please can you post the version of bluez (bluetoothd --version). Some versions of bluez have broken AVRCP volume control.

borine avatar Apr 24 '25 10:04 borine

Of cause, here you are bluetoothd --version 5.66.

The log from snapclient, though I am not the initiator of this issue, with reducing the volume once and setting it back to 100% from the snapweb interface, is this

2025-04-25 13-53-46.242 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: bluealsa
2025-04-25 13-53-46.267 [Info] (Snapclient) Version 0.31.0, revision cf2be071
2025-04-25 13-53-46.267 [Info] (Connection) Resolving host IP for: 192.168.0.13
2025-04-25 13-53-46.267 [Debug] (Connection) Resolved IP: 192.168.0.13
2025-04-25 13-53-46.267 [Info] (Connection) Connecting to 192.168.0.13:1704
2025-04-25 13-53-46.271 [Notice] (Connection) Connected to 192.168.0.13
2025-04-25 13-53-46.271 [Info] (Connection) My MAC: "dc:a6:32:08:34:6c", socket: 8
2025-04-25 13-53-46.308 [Debug] (Connection) outstanding async_write
2025-04-25 13-53-46.311 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2025-04-25 13-53-46.312 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2025-04-25 13-53-46.312 [Info] (Player) Player name: alsa, device: bluealsa, description: Bluetooth Audio Hub, idx: 4, sharing mode: unspecified, parameters: <none>
2025-04-25 13-53-46.312 [Info] (Player) Mixer mode: hardware, parameters: A2DP
2025-04-25 13-53-46.313 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2025-04-25 13-53-46.313 [Debug] (Alsa) Mixer: A2DP, device: bluealsa
2025-04-25 13-53-46.313 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
D: bluealsa-pcm.c:1309: Getting BlueALSA PCM: PLAYBACK 00:00:00:00:00:00 a2dp
D: bluealsa-pcm.c:1062: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Setting constraints
2025-04-25 13-53-46.321 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2025-04-25 13-53-46.321 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2025-04-25 13-53-46.321 [Debug] (Alsa) SUBFORMAT:  STD
2025-04-25 13-53-46.321 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2025-04-25 13-53-46.321 [Debug] (Alsa) FRAME_BITS: [4 640000]
2025-04-25 13-53-46.321 [Debug] (Alsa) CHANNELS: [1 10000]
2025-04-25 13-53-46.321 [Debug] (Alsa) RATE: [4000 4294967295)
2025-04-25 13-53-46.321 [Debug] (Alsa) PERIOD_TIME: [10000 5461334)
2025-04-25 13-53-46.321 [Debug] (Alsa) PERIOD_SIZE: [40 4294967295)
2025-04-25 13-53-46.321 [Debug] (Alsa) PERIOD_BYTES: [20 4294967295)
2025-04-25 13-53-46.321 [Debug] (Alsa) PERIODS: (0 107374183)
2025-04-25 13-53-46.321 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2025-04-25 13-53-46.321 [Debug] (Alsa) BUFFER_SIZE: [80 4294967294]
2025-04-25 13-53-46.321 [Debug] (Alsa) BUFFER_BYTES: [40 4294967295]
2025-04-25 13-53-46.321 [Debug] (Alsa) TICK_TIME: ALL
D: bluealsa-pcm.c:532: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing HW
D: bluealsa-pcm.c:567: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: FIFO buffer size: 1024 frames
D: bluealsa-pcm.c:581: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Selected HW buffer: 4 periods x 3840 bytes == 15360 bytes
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Prepared
2025-04-25 13-53-46.338 [Info] (Alsa) PCM name: bluealsa, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting
D: bluealsa-pcm.c:226: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting IO loop: 13
D: bluealsa-pcm.c:231: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Pausing IO thread
2025-04-25 13-53-46.339 [Debug] (Alsa) initMixer
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/rfcomm”
2025-04-25 13-53-46.349 [Debug] (Alsa) Filled -22 poll descriptors, poll descriptor count: 3, fd: 15
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/rfcomm”
2025-04-25 13-53-46.358 [Debug] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 0, delay: 0, using snd_pcm_avail amd snd_pcm_delay.
2025-04-25 13-53-46.358 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 1, mixer volume: 0
2025-04-25 13-53-46.359 [Warn] (Alsa) snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 7267
D: bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Prepared
2025-04-25 13-53-46.370 [Debug] (Alsa) Resizing buffer from 0 to 15360
D: bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting
D: bluealsa-pcm.c:245: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: IO thread resumed
2025-04-25 13-53-46.532 [Info] (Controller) diff to server [ms]: 6.98764e+08
2025-04-25 13-53-47.051 [Debug] (Stream) Silent frames: 821, frames: 960, age: -17.112
2025-04-25 13-53-47.071 [Debug] (Stats) Chunk: 0        0       0       0       1       211     0
2025-04-25 13-53-48.011 [Debug] (Stats) Chunk: 0        0       0       0       48      211     0
2025-04-25 13-53-49.011 [Debug] (Stats) Chunk: 0        0       0       0       98      211     0
2025-04-25 13-53-50.011 [Debug] (Stats) Chunk: 0        0       0       0       148     211     0
2025-04-25 13-53-51.011 [Debug] (Stats) Chunk: 0        0       0       0       198     211     0
2025-04-25 13-53-52.011 [Debug] (Stats) Chunk: -1       0       0       0       248     211     0
2025-04-25 13-53-53.011 [Debug] (Stats) Chunk: -1       -1      0       0       298     211     0
2025-04-25 13-53-54.011 [Debug] (Stats) Chunk: -1       -1      -1      0       348     211     0
2025-04-25 13-53-55.011 [Debug] (Stats) Chunk: -1       -1      -1      0       398     211     3
2025-04-25 13-53-56.011 [Debug] (Stats) Chunk: 0        0       -1      0       448     211     3
2025-04-25 13-53-57.011 [Debug] (Stats) Chunk: 0        0       0       0       498     211     0
2025-04-25 13-53-58.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     0
2025-04-25 13-53-59.011 [Debug] (Stats) Chunk: -1       -1      0       0       500     211     0
2025-04-25 13-54-00.011 [Debug] (Stats) Chunk: -1       -1      -1      0       500     211     0
2025-04-25 13-54-01.011 [Debug] (Stats) Chunk: -1       -1      -1      -1      500     211     3
2025-04-25 13-54-02.011 [Debug] (Stats) Chunk: 0        0       -1      -1      500     211     3
2025-04-25 13-54-03.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     0
2025-04-25 13-54-04.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     1
2025-04-25 13-54-05.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     0
2025-04-25 13-54-05.830 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 24, muted: 0
2025-04-25 13-54-05.830 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.25909, mixer volume: -3519.29
2025-04-25 13-54-06.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     0
2025-04-25 13-54-07.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     0
2025-04-25 13-54-08.011 [Debug] (Stats) Chunk: -1       -1      0       0       500     211     0
2025-04-25 13-54-08.283 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 25, muted: 0
2025-04-25 13-54-08.283 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.268839, mixer volume: -3423.04
2025-04-25 13-54-08.298 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 26, muted: 0
2025-04-25 13-54-08.298 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.278588, mixer volume: -3330.23
2025-04-25 13-54-08.329 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 28, muted: 0
2025-04-25 13-54-08.330 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.298086, mixer volume: -3153.95
2025-04-25 13-54-08.347 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 29, muted: 0
2025-04-25 13-54-08.347 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.307834, mixer volume: -3070.1
2025-04-25 13-54-08.364 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 31, muted: 0
2025-04-25 13-54-08.365 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.327332, mixer volume: -2910.07
2025-04-25 13-54-08.380 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 36, muted: 0
2025-04-25 13-54-08.380 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.376076, mixer volume: -2548.35
2025-04-25 13-54-08.400 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 41, muted: 0
2025-04-25 13-54-08.400 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.42482, mixer volume: -2230.77
2025-04-25 13-54-08.412 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 45, muted: 0
2025-04-25 13-54-08.412 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.463815, mixer volume: -2001.93
2025-04-25 13-54-08.430 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 48, muted: 0
2025-04-25 13-54-08.430 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.493062, mixer volume: -1842.59
2025-04-25 13-54-08.455 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 57, muted: 0
2025-04-25 13-54-08.456 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.580801, mixer volume: -1415.84
2025-04-25 13-54-08.463 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 58, muted: 0
2025-04-25 13-54-08.463 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.59055, mixer volume: -1372.46
2025-04-25 13-54-08.480 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 61, muted: 0
2025-04-25 13-54-08.480 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.619796, mixer volume: -1246.51
2025-04-25 13-54-08.483 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 63, muted: 0
2025-04-25 13-54-08.484 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.639294, mixer volume: -1165.8
2025-04-25 13-54-08.498 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 67, muted: 0
2025-04-25 13-54-08.498 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.678289, mixer volume: -1011.51
2025-04-25 13-54-08.513 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 75, muted: 0
2025-04-25 13-54-08.514 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.75628, mixer volume: -727.905
2025-04-25 13-54-08.531 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 76, muted: 0
2025-04-25 13-54-08.531 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.766029, mixer volume: -694.53
2025-04-25 13-54-08.547 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 81, muted: 0
2025-04-25 13-54-08.547 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.814773, mixer volume: -533.782
2025-04-25 13-54-08.565 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 85, muted: 0
2025-04-25 13-54-08.565 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.853768, mixer volume: -411.961
2025-04-25 13-54-08.580 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 89, muted: 0
2025-04-25 13-54-08.580 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.892763, mixer volume: -295.583
2025-04-25 13-54-08.597 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 95, muted: 0
2025-04-25 13-54-08.597 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.951256, mixer volume: -130.216
2025-04-25 13-54-08.613 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 98, muted: 0
2025-04-25 13-54-08.613 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.980502, mixer volume: -51.3081
2025-04-25 13-54-08.629 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2025-04-25 13-54-08.629 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 1, mixer volume: 0
2025-04-25 13-54-09.011 [Debug] (Stats) Chunk: -1       -1      -1      0       500     211     0
2025-04-25 13-54-10.011 [Debug] (Stats) Chunk: -1       -1      -1      0       500     211     2
2025-04-25 13-54-11.011 [Debug] (Stats) Chunk: 0        0       -1      0       500     211     3
2025-04-25 13-54-12.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     2
2025-04-25 13-54-13.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     0
2025-04-25 13-54-14.011 [Debug] (Stats) Chunk: 0        0       0       0       500     211     0
^C2025-04-25 13-54-14.710 [Info] (Snapclient) Received signal 2: Interrupt
2025-04-25 13-54-14.711 [Debug] (Alsa) uninitMixer
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:161: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: IO thread cleanup
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:592: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Freeing HW
D: bluealsa-pcm.c:443: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Closing
2025-04-25 13-54-14.714 [Debug] (Connection) Disconnecting
2025-04-25 13-54-14.715 [Debug] (Connection) Disconnected
2025-04-25 13-54-14.715 [Notice] (Snapclient) Snapclient terminated.

And the snapclient log with reducing the volume with alsamixer -D bluealsa is

g
2025-04-25 13-57-12.902 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: bluealsa
2025-04-25 13-57-12.926 [Info] (Snapclient) Version 0.31.0, revision cf2be071
2025-04-25 13-57-12.927 [Info] (Connection) Resolving host IP for: 192.168.0.13
2025-04-25 13-57-12.927 [Debug] (Connection) Resolved IP: 192.168.0.13
2025-04-25 13-57-12.927 [Info] (Connection) Connecting to 192.168.0.13:1704
2025-04-25 13-57-12.930 [Notice] (Connection) Connected to 192.168.0.13
2025-04-25 13-57-12.930 [Info] (Connection) My MAC: "dc:a6:32:08:34:6c", socket: 8
2025-04-25 13-57-12.968 [Debug] (Connection) outstanding async_write
2025-04-25 13-57-12.974 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2025-04-25 13-57-12.977 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2025-04-25 13-57-12.977 [Info] (Player) Player name: alsa, device: bluealsa, description: Bluetooth Audio Hub, idx: 4, sharing mode: unspecified, parameters: <none>
2025-04-25 13-57-12.977 [Info] (Player) Mixer mode: hardware, parameters: A2DP
2025-04-25 13-57-12.977 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2025-04-25 13-57-12.978 [Debug] (Alsa) Mixer: A2DP, device: bluealsa
2025-04-25 13-57-12.978 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
D: bluealsa-pcm.c:1309: Getting BlueALSA PCM: PLAYBACK 00:00:00:00:00:00 a2dp
D: bluealsa-pcm.c:1062: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Setting constraints
2025-04-25 13-57-12.988 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2025-04-25 13-57-12.988 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2025-04-25 13-57-12.988 [Debug] (Alsa) SUBFORMAT:  STD
2025-04-25 13-57-12.988 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2025-04-25 13-57-12.988 [Debug] (Alsa) FRAME_BITS: [4 640000]
2025-04-25 13-57-12.988 [Debug] (Alsa) CHANNELS: [1 10000]
2025-04-25 13-57-12.988 [Debug] (Alsa) RATE: [4000 4294967295)
2025-04-25 13-57-12.988 [Debug] (Alsa) PERIOD_TIME: [10000 5461334)
2025-04-25 13-57-12.988 [Debug] (Alsa) PERIOD_SIZE: [40 4294967295)
2025-04-25 13-57-12.988 [Debug] (Alsa) PERIOD_BYTES: [20 4294967295)
2025-04-25 13-57-12.988 [Debug] (Alsa) PERIODS: (0 107374183)
2025-04-25 13-57-12.988 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2025-04-25 13-57-12.988 [Debug] (Alsa) BUFFER_SIZE: [80 4294967294]
2025-04-25 13-57-12.988 [Debug] (Alsa) BUFFER_BYTES: [40 4294967295]
2025-04-25 13-57-12.988 [Debug] (Alsa) TICK_TIME: ALL
D: bluealsa-pcm.c:532: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing HW
D: bluealsa-pcm.c:567: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: FIFO buffer size: 1024 frames
D: bluealsa-pcm.c:581: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Selected HW buffer: 4 periods x 3840 bytes == 15360 bytes
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Prepared
2025-04-25 13-57-13.133 [Info] (Alsa) PCM name: bluealsa, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting
D: bluealsa-pcm.c:226: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting IO loop: 13
2025-04-25 13-57-13.134 [Debug] (Alsa) initMixer
D: bluealsa-pcm.c:231: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Pausing IO thread
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/rfcomm”
2025-04-25 13-57-13.144 [Debug] (Alsa) Filled -22 poll descriptors, poll descriptor count: 3, fd: 15
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/rfcomm”
2025-04-25 13-57-13.155 [Debug] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 0, delay: 0, using snd_pcm_avail amd snd_pcm_delay.
2025-04-25 13-57-13.155 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 1, mixer volume: 0
2025-04-25 13-57-13.156 [Warn] (Alsa) snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 7300
D: bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Prepared
2025-04-25 13-57-13.167 [Debug] (Alsa) Resizing buffer from 0 to 15360
D: bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting
D: bluealsa-pcm.c:245: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: IO thread resumed
2025-04-25 13-57-13.366 [Info] (Controller) diff to server [ms]: 6.98764e+08
2025-04-25 13-57-13.728 [Debug] (Stream) Silent frames: 163, frames: 960, age: -3.396
2025-04-25 13-57-13.748 [Debug] (Stats) Chunk: 0        0       0       0       1       212     0
2025-04-25 13-57-14.008 [Debug] (Stats) Chunk: 0        0       0       0       14      212     0
2025-04-25 13-57-15.008 [Debug] (Stats) Chunk: 0        0       0       0       64      212     0
2025-04-25 13-57-16.008 [Debug] (Stats) Chunk: 0        0       0       0       114     212     0
2025-04-25 13-57-17.008 [Debug] (Stats) Chunk: 0        0       0       0       164     212     0
2025-04-25 13-57-18.008 [Debug] (Stats) Chunk: 0        0       0       0       214     212     0
2025-04-25 13-57-19.008 [Debug] (Stats) Chunk: -1       -1      0       0       264     212     0
2025-04-25 13-57-20.008 [Debug] (Stats) Chunk: -1       -1      -1      0       314     212     0
2025-04-25 13-57-21.008 [Debug] (Stats) Chunk: -1       -1      -1      0       364     212     2
2025-04-25 13-57-22.008 [Debug] (Stats) Chunk: 0        0       -1      0       414     212     3
2025-04-25 13-57-23.008 [Debug] (Stats) Chunk: -1       0       0       0       464     212     1
2025-04-25 13-57-24.008 [Debug] (Stats) Chunk: 0        0       0       0       500     212     0
^C2025-04-25 13-57-24.978 [Info] (Snapclient) Received signal 2: Interrupt
2025-04-25 13-57-24.988 [Debug] (Alsa) uninitMixer
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:161: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: IO thread cleanup
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:592: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Freeing HW
D: bluealsa-pcm.c:443: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Closing
2025-04-25 13-57-24.990 [Debug] (Connection) Disconnecting
2025-04-25 13-57-24.991 [Debug] (Connection) Disconnected
2025-04-25 13-57-24.991 [Notice] (Snapclient) Snapclient terminated.

And the snapclient log with reducing the volume on the bluetooth speaker does not show any change in the log.

Edit: I just noticed a message after closing alsamixer, it says ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/rfcomm”.

dflvunoooooo avatar Apr 25 '25 11:04 dflvunoooooo

bluealsa v4.0.0 by default uses its own internal software volume control for A2DP; you need to add --a2dp-volume to the command line in the systemd system file if you want it to operate the remote device volume control. See man bluealsa.

When operating the volume control in snapclient, do you see the A2DP control move in alsamixer? If so then volume control is working. When operating the control in alsamixer, then it seems that snapclient does not pick up those changes. I do not know why. The sound level from the bluetooth speaker does change as expected for me.

Couldn't get device battery status

That's because battery status reporting requires HFP or HSP which you have not enabled. To get rid of that warning, add to your alsa config:

defaults.bluealsa.ctl.battery "no"

See man bluealsa-plugins

borine avatar Apr 25 '25 13:04 borine

Ah thank you for that hint. I can now control the volueme from the speaker with alsamixer -D bluealsa or a change on the speaker does change alsamixer volume. But, this is not represented on the snapclient volume. That does not change regardless what I do.

2025-04-25 16-02-33.959 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: bluealsa
2025-04-25 16-02-33.982 [Info] (Snapclient) Version 0.31.0, revision cf2be071
2025-04-25 16-02-33.983 [Info] (Connection) Resolving host IP for: 192.168.0.13
2025-04-25 16-02-33.983 [Debug] (Connection) Resolved IP: 192.168.0.13
2025-04-25 16-02-33.983 [Info] (Connection) Connecting to 192.168.0.13:1704
2025-04-25 16-02-33.986 [Notice] (Connection) Connected to 192.168.0.13
2025-04-25 16-02-33.986 [Info] (Connection) My MAC: "dc:a6:32:08:34:6c", socket: 8
2025-04-25 16-02-34.024 [Debug] (Connection) outstanding async_write
2025-04-25 16-02-34.028 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 22, muted: 0
2025-04-25 16-02-34.029 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2025-04-25 16-02-34.029 [Info] (Player) Player name: alsa, device: bluealsa, description: Bluetooth Audio Hub, idx: 4, sharing mode: unspecified, parameters: <none>
2025-04-25 16-02-34.030 [Info] (Player) Mixer mode: hardware, parameters: A2DP
2025-04-25 16-02-34.030 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2025-04-25 16-02-34.030 [Debug] (Alsa) Mixer: A2DP, device: bluealsa
2025-04-25 16-02-34.030 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
D: bluealsa-pcm.c:1309: Getting BlueALSA PCM: PLAYBACK 00:00:00:00:00:00 a2dp
D: bluealsa-pcm.c:1062: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Setting constraints
2025-04-25 16-02-34.037 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2025-04-25 16-02-34.037 [Debug] (Alsa) FORMAT:  S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE MU_LAW A_LAW IMA_ADPCM S20_LE S20_BE U20_LE U20_BE S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE U18_3BE
2025-04-25 16-02-34.037 [Debug] (Alsa) SUBFORMAT:  STD
2025-04-25 16-02-34.037 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2025-04-25 16-02-34.037 [Debug] (Alsa) FRAME_BITS: [4 640000]
2025-04-25 16-02-34.037 [Debug] (Alsa) CHANNELS: [1 10000]
2025-04-25 16-02-34.037 [Debug] (Alsa) RATE: [4000 4294967295)
2025-04-25 16-02-34.037 [Debug] (Alsa) PERIOD_TIME: [10000 5461334)
2025-04-25 16-02-34.037 [Debug] (Alsa) PERIOD_SIZE: [40 4294967295)
2025-04-25 16-02-34.037 [Debug] (Alsa) PERIOD_BYTES: [20 4294967295)
2025-04-25 16-02-34.037 [Debug] (Alsa) PERIODS: (0 107374183)
2025-04-25 16-02-34.037 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2025-04-25 16-02-34.037 [Debug] (Alsa) BUFFER_SIZE: [80 4294967294]
2025-04-25 16-02-34.037 [Debug] (Alsa) BUFFER_BYTES: [40 4294967295]
2025-04-25 16-02-34.037 [Debug] (Alsa) TICK_TIME: ALL
D: bluealsa-pcm.c:532: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing HW
D: bluealsa-pcm.c:567: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: FIFO buffer size: 1024 frames
D: bluealsa-pcm.c:581: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Selected HW buffer: 4 periods x 3840 bytes == 15360 bytes
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Prepared
2025-04-25 16-02-34.054 [Info] (Alsa) PCM name: bluealsa, sample rate: 48000 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 960
D: bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Initializing SW
D: bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting
D: bluealsa-pcm.c:226: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting IO loop: 13
D: bluealsa-pcm.c:231: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Pausing IO thread
2025-04-25 16-02-34.055 [Debug] (Alsa) initMixer
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/rfcomm”
2025-04-25 16-02-34.064 [Debug] (Alsa) Filled -22 poll descriptors, poll descriptor count: 3, fd: 15
ALSA lib bluealsa-ctl.c:205:(bluealsa_dev_fetch_battery) Couldn't get device battery status: Object does not exist at path “/org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/rfcomm”
2025-04-25 16-02-34.072 [Debug] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 0, delay: 0, using snd_pcm_avail amd snd_pcm_delay.
2025-04-25 16-02-34.072 [Debug] (Alsa) Mixer playback dB range [-9600, 0], volume: 0.239593, mixer volume: -3723.16
%Y-%m-%d %H-%M-%S.#ms [Warn] (Alsa) Wrote 34 bytes to socket
2025-04-25 16-02-34.073 [Warn] (Alsa) snd_pcm_delay failed: Broken pipe (-32), avail: -32, delay: 724
D: bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Prepared
2025-04-25 16-02-34.084 [Debug] (Alsa) Resizing buffer from 0 to 15360
D: bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Starting
D: bluealsa-pcm.c:245: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: IO thread resumed
2025-04-25 16-02-34.274 [Info] (Controller) diff to server [ms]: 6.98764e+08
2025-04-25 16-02-34.945 [Debug] (Stream) Silent frames: 462, frames: 960, age: -9.639
2025-04-25 16-02-34.965 [Debug] (Stats) Chunk: 0        0       0       0       1       75      0
2025-04-25 16-02-35.025 [Debug] (Stats) Chunk: 0        0       0       0       4       75      0
2025-04-25 16-02-36.025 [Debug] (Stats) Chunk: 0        0       0       0       54      75      0
2025-04-25 16-02-37.025 [Debug] (Stats) Chunk: -1       -1      0       0       104     75      0
2025-04-25 16-02-38.025 [Debug] (Stats) Chunk: -1       0       0       0       154     75      0
2025-04-25 16-02-39.025 [Debug] (Stats) Chunk: -1       -1      -1      0       204     75      0
2025-04-25 16-02-40.025 [Debug] (Stats) Chunk: 0        -1      -1      -1      254     75      2
2025-04-25 16-02-41.025 [Debug] (Stats) Chunk: 0        0       0       0       304     75      3
2025-04-25 16-02-42.024 [Debug] (Stats) Chunk: -1       0       0       0       354     75      0
2025-04-25 16-02-43.025 [Debug] (Stats) Chunk: 0        -1      0       0       404     75      0
2025-04-25 16-02-44.025 [Debug] (Stats) Chunk: -1       -1      -1      0       454     75      0
2025-04-25 16-02-45.024 [Debug] (Stats) Chunk: 0        -1      -1      -1      500     75      3
2025-04-25 16-02-46.025 [Debug] (Stats) Chunk: 0        0       0       -1      500     75      2
2025-04-25 16-02-47.024 [Debug] (Stats) Chunk: -1       -1      0       -1      500     75      0
2025-04-25 16-02-48.024 [Debug] (Stats) Chunk: -1       -1      -1      -1      500     75      0
2025-04-25 16-02-49.024 [Debug] (Stats) Chunk: -1       -1      -1      -1      500     75      3
2025-04-25 16-02-50.024 [Debug] (Stats) Chunk: 0        0       -1      -1      500     75      2
2025-04-25 16-02-51.024 [Debug] (Stats) Chunk: 0        0       0       -1      500     75      2
2025-04-25 16-02-52.024 [Debug] (Stats) Chunk: -1       0       0       -1      500     75      0
2025-04-25 16-02-53.024 [Debug] (Stats) Chunk: -1       -1      -1      -1      500     75      0
2025-04-25 16-02-54.024 [Debug] (Stats) Chunk: 0        -1      -1      -1      500     75      2
^C2025-04-25 16-02-54.573 [Info] (Snapclient) Received signal 2: Interrupt
2025-04-25 16-02-54.584 [Debug] (Alsa) uninitMixer
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:161: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: IO thread cleanup
D: bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Stopping
D: bluealsa-pcm.c:592: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Freeing HW
D: bluealsa-pcm.c:443: /org/bluealsa/hci0/dev_C0_28_8D_DB_B1_86/a2dpsrc/sink: Closing
2025-04-25 16-02-54.587 [Debug] (Connection) Disconnecting
2025-04-25 16-02-54.587 [Debug] (Connection) Disconnected
2025-04-25 16-02-54.587 [Notice] (Snapclient) Snapclient terminated.
alarm@raspi-stern:~ $

Thanks for the solution to avoid the battery warning.

dflvunoooooo avatar Apr 25 '25 14:04 dflvunoooooo

The reason that volume update events from bluealsa are not received by snapclient is a bug in the snapclient mixer initialization code. The call:

   err = snd_ctl_poll_descriptors(ctl_, fd_.get(), 1);

in AlsaPlayer::initMixer() passes an array of size 1, but bluealsa requires an array size of a least 4. The bluealsa code therefore writes beyond the end of the array, and from that point snapclient memory is corrupted.

The correct call sequence when using the ALSA ctl API for events is:

nfd_t nfds = snd_ctl_poll_descriptors_count(ctl);
/*
allocate an array of pollfd of size at least nfds
struct pollfd[nfds];
*/
 err = snd_ctl_poll_descriptors(ctl_, pollfd, nfds);

Probably bluealsa should check the value of nfds before filling the array and return EINVAL if nfds is too small, but that would be expensive and many applications call snd_ctl_poll_descriptors() before every call to poll(); in any case snapclient ignores the returned error code, but at least the memory corruption would not occur.

The snapclient code works for soundcard controls because they always have just one file descriptor to be monitored. However, the ALSA API does not guarantee that, it is just an implementation detail and could (in theory, but unlikely in practice) be changed in some future alsa-lib update. The code is not safe to use with software mixer controls so I now recommend that snapclient hardware volume control should not be used with bluealsa or any ALSA device other than hardware soundcards.

borine avatar Apr 26 '25 10:04 borine

I see, thank you. Than this issue can be closed, I think.

dflvunoooooo avatar Apr 28 '25 12:04 dflvunoooooo