Snapclient blocks soundcard/ALSA and stops playing after changing radio station

[schniepp]

I have a Pi 5 running Music Assistant. To test, I used a second Pi5 as client, which worked perfectly. For the final installation, I switched the client to a Pi Zero 2W, on which I am running a vanilla installation of Ubuntu 24.04 server.

Directly after booting the snapclient works well — until I change the radio station. Sometimes, I can change the station 2-3 times, sometimes, the problem will show up after changing the station for the first time: the player stops playing music, and it won't even make sounds following a simple aplay -r 22050 -c 1 -f S16_LE Front_Right.wav (which works directly after boot). The command never finishes and is stuck.

If I run a journalctl -u snapclient.service -n 50, I get this

Jun 18 05:24:14 kitchen snapclient[813]: Codec: flac, sampleformat: 48000:16:2
Jun 18 05:24:14 kitchen snapclient[813]: Player name: alsa, device: default, description: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
Jun 18 05:24:14 kitchen snapclient[813]: Mixer mode: software, parameters: <none>
Jun 18 05:24:14 kitchen snapclient[813]: Sampleformat: 48000:16:2, stream: 48000:16:2
Jun 18 05:24:14 kitchen snapclient[813]: Using default buffer_time: 80 ms, default fragments: 4
Jun 18 05:24:14 kitchen snapclient[813]: Period time too small, changing from 20000 to 21333
Jun 18 05:24:14 kitchen snapclient[813]: PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 85333 us, periods: 4, period time: 21333 us, period frames: 1024
Jun 18 05:24:14 kitchen snapclient[813]: No chunks available
Jun 18 05:24:14 kitchen snapclient[813]: Failed to get chunk
Jun 18 05:24:19 kitchen snapclient[813]: No chunk received for 5000ms. Closing ALSA.

Strangely, in the case where ALSA ends up being blocked, the log looks almost the same, except that the last line with "Closing ALSA." is missing. Does that mean that ALSA is not properly released, and that is why no more sound can be played on this machine after? How can I force a release of ALSA?

Steps to Reproduce

1. Boot client
2. Start internet radio station, radio will play
3. Change station a few times, no more music will play — from radio, or from any file in the album collection. Not even directly, a file can be sent to the sound card.

Environment details

• Client: OS: Ubuntu server 24.04 on a Pi Zero 2W, snapclient 0.27.0+dfsg-1build2
• Server: Music Assistant 2.0.4, running as docker image

Logfile When I do snapclient --logfilter debug in "stuck" mode, I get this:

2024-06-18 05-46-12.405 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2024-06-18 05-46-12.857 [Info] (Snapclient) Version 0.27.0
2024-06-18 05-46-12.883 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2024-06-18 05-46-12.886 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2024-06-18 05-46-13.283 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2024-06-18 05-46-13.284 [Info] (Avahi)  homeserver.local:1704 (192.168.0.200)
2024-06-18 05-46-13.284 [Debug] (Avahi)         TXT="is_mass=true"
2024-06-18 05-46-13.284 [Debug] (Avahi)         Proto=0
2024-06-18 05-46-13.284 [Debug] (Avahi)         cookie is 0
2024-06-18 05-46-13.284 [Debug] (Avahi)         is_local: 0
2024-06-18 05-46-13.284 [Debug] (Avahi)         our_own: 0
2024-06-18 05-46-13.284 [Debug] (Avahi)         wide_area: 0
2024-06-18 05-46-13.284 [Debug] (Avahi)         multicast: 1
2024-06-18 05-46-13.284 [Debug] (Avahi)         cached: 1
2024-06-18 05-46-13.290 [Info] (Controller) Found server 192.168.0.200:1704
2024-06-18 05-46-13.290 [Info] (Connection) Resolving host IP for: 192.168.0.200
2024-06-18 05-46-13.290 [Info] (Connection) Connecting
2024-06-18 05-46-13.310 [Notice] (Connection) Connected to 192.168.0.200
2024-06-18 05-46-13.311 [Info] (Connection) My MAC: "d8:3a:dd:92:34:3e", socket: 8
2024-06-18 05-46-13.461 [Debug] (Connection) outstanding async_write
2024-06-18 05-46-13.465 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 12, muted: 0
2024-06-18 05-46-13.468 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2024-06-18 05-46-13.468 [Info] (Player) Player name: alsa, device: default, description: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
2024-06-18 05-46-13.468 [Info] (Player) Mixer mode: software, parameters: <none>
2024-06-18 05-46-13.468 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2024-06-18 05-46-13.468 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2024-06-18 05-46-13.489 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2024-06-18 05-46-13.489 [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
2024-06-18 05-46-13.489 [Debug] (Alsa) SUBFORMAT:  STD MSBITS_MAX MSBITS_20 MSBITS_24
2024-06-18 05-46-13.489 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2024-06-18 05-46-13.489 [Debug] (Alsa) FRAME_BITS: [4 640000]
2024-06-18 05-46-13.489 [Debug] (Alsa) CHANNELS: [1 10000]
2024-06-18 05-46-13.489 [Debug] (Alsa) RATE: [4000 4294967295)
2024-06-18 05-46-13.489 [Debug] (Alsa) PERIOD_TIME: (21333 21334)
2024-06-18 05-46-13.489 [Debug] (Alsa) PERIOD_SIZE: (85 91628833)
2024-06-18 05-46-13.489 [Debug] (Alsa) PERIOD_BYTES: (42 4294967295)
2024-06-18 05-46-13.489 [Debug] (Alsa) PERIODS: (0 17247242)
2024-06-18 05-46-13.489 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2024-06-18 05-46-13.489 [Debug] (Alsa) BUFFER_SIZE: [170 1466015503]
2024-06-18 05-46-13.489 [Debug] (Alsa) BUFFER_BYTES: [85 4294967295]
2024-06-18 05-46-13.489 [Debug] (Alsa) TICK_TIME: ALL
2024-06-18 05-46-13.491 [Info] (Alsa) Period time too small, changing from 20000 to 21333
2024-06-18 05-46-13.491 [Info] (Alsa) PCM name: default, sample rate: 48000 Hz, channels: 2, buffer time: 85333 us, periods: 4, period time: 21333 us, period frames: 1024
2024-06-18 05-46-13.492 [Debug] (Alsa) setVolume exp with base 10: 0.12 => 0.0353619
2024-06-18 05-46-13.492 [Debug] (Alsa) Resizing buffer from 0 to 16384
2024-06-18 05-46-13.493 [Info] (Stream) No chunks available
2024-06-18 05-46-13.493 [Info] (Alsa) Failed to get chunk
2024-06-18 05-46-13.744 [Info] (Controller) diff to server [ms]: 1.44791e+08
^C2024-06-18 05-46-42.174 [Info] (Snapclient) Received signal 2: Interrupt
2024-06-18 05-46-42.190 [Debug] (Connection) Disconnecting
2024-06-18 05-46-42.191 [Debug] (Connection) Disconnected
2024-06-18 05-46-42.191 [Notice] (Snapclient) Snapclient terminated.