Hook-based volume setter scripts run concurrently and potentially out-of-order

[christianglodt]

It seems the hook-based volume setting command is sometimes not run.

In my setup, I run sendspin in a systemd unit via uvx:

uvx sendspin@7.5.0 daemon --audio-device=mydevice --hook-set-volume /usr/local/bin/set-alsa-volume.sh --name "myname" --id myid --disable-mpris --port 12345

My set-alsa-volume.sh script looks like this:

#!/bin/sh
exec systemd-cat -t "sendspin-triggered-amixer" amixer -D "$ALSA_DEVICE" sset "$ALSA_MIXER_CTL" "$1"%

(Note: The systemd-cat command ensures the output of the amixer command is sent to the journal of the sendspin systemd unit.)

Here's an example I managed to log where an expected call of the script does not occur:

Aug 04 14:36:10 server uvx[3235267]: INFO:sendspin.daemon.daemon:Server set player volume: 43%
Aug 04 14:36:10 server sendspin-triggered-amixer[294409]: Simple mixer control 'Master',0
Aug 04 14:36:10 server sendspin-triggered-amixer[294409]:   Capabilities: volume cswitch
Aug 04 14:36:10 server sendspin-triggered-amixer[294409]:   Playback channels: Front Left - Front Right
Aug 04 14:36:10 server sendspin-triggered-amixer[294409]:   Capture channels: Front Left - Front Right
Aug 04 14:36:10 server sendspin-triggered-amixer[294409]:   Limits: -50 - 100
Aug 04 14:36:10 server sendspin-triggered-amixer[294409]:   Front Left: 14 [43%] [-25.80dB] Capture [on]
Aug 04 14:36:10 server sendspin-triggered-amixer[294409]:   Front Right: 14 [43%] [-25.80dB] Capture [on]
Aug 04 14:36:11 server uvx[3235267]: INFO:sendspin.daemon.daemon:Server set player volume: 46%
Aug 04 14:36:11 server sendspin-triggered-amixer[294411]: Simple mixer control 'Master',0
Aug 04 14:36:11 server sendspin-triggered-amixer[294411]:   Capabilities: volume cswitch
Aug 04 14:36:11 server sendspin-triggered-amixer[294411]:   Playback channels: Front Left - Front Right
Aug 04 14:36:11 server sendspin-triggered-amixer[294411]:   Capture channels: Front Left - Front Right
Aug 04 14:36:11 server sendspin-triggered-amixer[294411]:   Limits: -50 - 100
Aug 04 14:36:11 server sendspin-triggered-amixer[294411]:   Front Left: 19 [46%] [-24.30dB] Capture [on]
Aug 04 14:36:11 server sendspin-triggered-amixer[294411]:   Front Right: 19 [46%] [-24.30dB] Capture [on]
Aug 04 14:36:14 server uvx[3235267]: INFO:sendspin.daemon.daemon:Server set player volume: 78%
Aug 04 14:36:14 server sendspin-triggered-amixer[294526]: Simple mixer control 'Master',0
Aug 04 14:36:14 server sendspin-triggered-amixer[294526]:   Capabilities: volume cswitch
Aug 04 14:36:14 server sendspin-triggered-amixer[294526]:   Playback channels: Front Left - Front Right
Aug 04 14:36:14 server sendspin-triggered-amixer[294526]:   Capture channels: Front Left - Front Right
Aug 04 14:36:14 server sendspin-triggered-amixer[294526]:   Limits: -50 - 100
Aug 04 14:36:14 server sendspin-triggered-amixer[294526]:   Front Left: 67 [78%] [-9.90dB] Capture [on]
Aug 04 14:36:14 server sendspin-triggered-amixer[294526]:   Front Right: 67 [78%] [-9.90dB] Capture [on]
Aug 04 14:36:16 server uvx[3235267]: INFO:sendspin.daemon.daemon:Server set player volume: 68%
<expected call of set-alsa-volume.sh does not occur here>

The example was produced by quickly changing the volume many times in the Music-Assistant web UI using the volume slider. The last setting (68%) does not result in a corresponding call of the volume setter hook.

Could the problem be a race condition between some internal state that represents the current volume and some check that decides whether to call the script?

EDIT: I've changed the title of the issue to better reflect the findings in my additional comment below.

[christianglodt]

I had a hunch that if several set-volume requests come in quickly, several hook commands might run concurrently, resulting in scheduler-induced random ordering. I think this is the case.

To verify, enable DEBUG logging (--log-level DEBUG), and use the following set-volume-hook script:

#!/bin/sh
RANDOM_DELAY=$(shuf -i 1-5 -n 1)
sleep $RANDOM_DELAY
echo "Slept for $RANDOM_DELAY then set volume to $1%"

This simulates a set-volume command that randomly takes 1-5 seconds.

Triggering several volume changes quickly results in the following log output:

Aug 05 09:48:49 server uvx[1987811]: DEBUG:sendspin.hook_volume:Running volume hook /usr/local/bin/set-alsa-volume.sh with effective volume 75
Aug 05 09:48:49 server uvx[1987811]: INFO:sendspin.daemon.daemon:Server set player volume: 75%
Aug 05 09:48:50 server uvx[1987811]: DEBUG:sendspin.hook_volume:Running volume hook /usr/local/bin/set-alsa-volume.sh with effective volume 70
Aug 05 09:48:50 server uvx[1987811]: INFO:sendspin.daemon.daemon:Server set player volume: 70%
Aug 05 09:48:50 server uvx[1987811]: DEBUG:sendspin.hook_volume:Running volume hook /usr/local/bin/set-alsa-volume.sh with effective volume 65
Aug 05 09:48:50 server uvx[1987811]: INFO:sendspin.daemon.daemon:Server set player volume: 65%
Aug 05 09:48:50 server uvx[1987811]: DEBUG:sendspin.hook_volume:Running volume hook /usr/local/bin/set-alsa-volume.sh with effective volume 60
Aug 05 09:48:50 server uvx[1987811]: INFO:sendspin.daemon.daemon:Server set player volume: 60%
Aug 05 09:48:53 server uvx[1987811]: DEBUG:sendspin.hook_volume:Volume hook output: stdout=Slept for 3 then set volume to 70% stderr=(empty)
Aug 05 09:48:54 server uvx[1987811]: DEBUG:sendspin.hook_volume:Volume hook output: stdout=Slept for 4 then set volume to 60% stderr=(empty)
Aug 05 09:48:54 server uvx[1987811]: DEBUG:sendspin.hook_volume:Volume hook output: stdout=Slept for 5 then set volume to 75% stderr=(empty)
Aug 05 09:48:55 server uvx[1987811]: DEBUG:sendspin.hook_volume:Volume hook output: stdout=Slept for 5 then set volume to 65% stderr=(empty)

As can be seen, the hooks complete in a different order from the requests. In the end, this leaves the volume at an unexpected level.

The "Volume hook output" log messages come after the "Server set player volume" messages, meaning new set-volume requests are handled before currently running ones are finished. This can also be seen in audio_connector.py line 427, where the task to set the volume is created but not awaited.