ALSA playback fails when outputting to dshares since v0.23.0

[polara413]

Describe the bug
Snapclient cannot playback via ALSA PCM when the output device (-s) is a dshare. Snapclient will report repeated messages suggesting the PCM device is in an invalid state. Bug can be traced to the change to alsa_player.cpp at commit 273ad96. Bug persists through the current commit. Commenting out the offending code block from the current commit restores playback functionality.

Steps to Reproduce

1. Set up a dshare in /etc/asound.conf to split a USB sound card into multiple outputs
2. Run snapclient and target a dshare output device.
3. Observe no playback and error messages in the logfile.

Environment details

• OS: Raspbian Bullseye on Pi3B+ with external USB 7.1 sound card
• Snapcast version 0.23.0 and up since 273ad96.
• Installed from a package, self compiled, ... - Either.

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

Clean startup with working v0.22.0 Release (installed from package)

$ sudo snapclient -s src2 -h 192.168.1.10 -p 1234 -i 3 --logfilter *:trace --debug
2023-08-31 14-08-58.962 [Info] (Connection) Resolving host IP for: 192.168.1.10
2023-08-31 14-08-58.962 [Info] (Connection) Connecting
2023-08-31 14-08-58.967 [Notice] (Connection) Connected to 192.168.1.10
2023-08-31 14-08-58.968 [Info] (Connection) My MAC: "b8:[redacted]", socket: 8
2023-08-31 14-08-59.199 [Debug] (Connection) outstanding async_write
2023-08-31 14-08-59.199 [Trace] (Connection) Wrote 247 bytes to socket
2023-08-31 14-08-59.199 [Trace] (Connection) Wrote 34 bytes to socket
2023-08-31 14-08-59.205 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2023-08-31 14-08-59.209 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2023-08-31 14-08-59.209 [Info] (Player) Player name: alsa, device: src2_dshare, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2023-08-31 14-08-59.209 [Info] (Player) Mixer mode: software, parameters: <none>
2023-08-31 14-08-59.209 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2023-08-31 14-08-59.215 [Debug] (Alsa) PCM name: src2_dshare
2023-08-31 14-08-59.215 [Debug] (Alsa) PCM state: PREPARED
2023-08-31 14-08-59.215 [Debug] (Alsa) channels: 2
2023-08-31 14-08-59.215 [Debug] (Alsa) rate: 48000 bps
2023-08-31 14-08-59.215 [Debug] (Alsa) frames: 1024
2023-08-31 14-08-59.215 [Debug] (Alsa) period time: 21333
2023-08-31 14-08-59.216 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2023-08-31 14-08-59.216 [Debug] (Alsa) Resizing buffer from 0 to 12288
2023-08-31 14-08-59.216 [Info] (Stream) no chunks available
2023-08-31 14-08-59.216 [Info] (Alsa) Failed to get chunk

Bad startup with failing v0.23.0 Release (installed from package)

$ snapclient -s src2 -h 192.168.1.10 -p 1234 -i 3 --logfilter *:trace --debug
2023-08-31 14-13-55.099 [Info] (Connection) Resolving host IP for: 192.168.1.10
2023-08-31 14-13-55.100 [Info] (Connection) Connecting
2023-08-31 14-13-55.115 [Notice] (Connection) Connected to 192.168.1.10
2023-08-31 14-13-55.116 [Info] (Connection) My MAC: "b8:[redacted]", socket: 8
2023-08-31 14-13-55.342 [Debug] (Connection) outstanding async_write
2023-08-31 14-13-55.342 [Trace] (Connection) Wrote 247 bytes to socket
2023-08-31 14-13-55.343 [Trace] (Connection) Wrote 34 bytes to socket
2023-08-31 14-13-55.348 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2023-08-31 14-13-55.353 [Info] (Controller) Codec: flac, sampleformat: 48000:16:2
2023-08-31 14-13-55.353 [Info] (Player) Player name: alsa, device: src2_dshare, description: <none>, idx: 3, sharing mode: unspecified, parameters: <none>
2023-08-31 14-13-55.353 [Info] (Player) Mixer mode: software, parameters: <none>
2023-08-31 14-13-55.353 [Info] (Player) Sampleformat: 48000:16:2, stream: 48000:16:2
2023-08-31 14-13-55.353 [Info] (Alsa) Using buffer_time: 80 ms, fragments: 4
2023-08-31 14-13-55.361 [Info] (Alsa) PCM name: src2_dshare, sample rate: 48000 Hz, channels: 2, buffer time: 85333 us, periods: 4, period time: 21333 us, period frames: 1024
2023-08-31 14-13-55.362 [Debug] (Player) setVolume exp with base 10: 1 => 1
2023-08-31 14-13-55.362 [Debug] (Player) snd_pcm_avail_delay failed: File descriptor in bad state (-77), avail: 0, delay: -1472036457, using snd_pcm_avail amd snd_pcm_delay.
2023-08-31 14-13-55.363 [Trace] (Connection) Wrote 34 bytes to socket
2023-08-31 14-13-55.363 [Debug] (Alsa) snd_pcm_avail failed: File descriptor in bad state (-77), using 1024
2023-08-31 14-13-55.363 [Debug] (Alsa) Resizing buffer from 0 to 4096
2023-08-31 14-13-55.364 [Info] (Stream) No chunks available
2023-08-31 14-13-55.364 [Info] (Alsa) Failed to get chunk

In both cases above, the snapserver is not sending chunks yet. When chunks are sent, the failing client will repeatedly log:

2023-08-31 14-13-58.806 [Warn] (Alsa) snd_pcm_avail_delay failed: File descriptor in bad state (-77), avail: 1024, delay: 0, using snd_pcm_avail amd snd_pcm_delay.
2023-08-31 14-13-58.809 [Debug] (Alsa) snd_pcm_avail failed: File descriptor in bad state (-77), using 1024
2023-08-31 14-13-58.809 [Error] (Alsa) ERROR. Can't write to PCM device: File descriptor in bad state
2023-08-31 14-13-58.817 [Info] (Alsa) PCM name: src2_dshare, sample rate: 48000 Hz, channels: 2, buffer time: 85333 us, periods: 4, period time: 21333 us, period frames: 1024

as the chunks come in.

Contents of asound.conf:

# shared buffer for playback
pcm_slave.tdmshare {
#    pcm "surround71:ICUSBAUDIO7D,0" # define the sound card
    pcm "hw:ICUSBAUDIO7D,0"
    channels 8
    rate 48000          # fixed, because all dshare devices must use the same >
    format S16_LE
#    period_time 0
    period_size 1024
    buffer_size 4096
}

# src1 shared pcm device and corresponding virtual playback device
pcm.src1_dshare {
    type dshare
    ipc_key 43544553
    slave tdmshare
    bindings.0 0
    bindings.1 1
}
pcm.src1 {
    type plug
    slave.pcm "src1_dshare"
 hint {
                show {
                        @func refer
                        name defaults.namehint.basic
                }
                description "USB sound card FRONT output jack"
        }
}

# src2 shared pcm device and corresponding virtual playback device
pcm.src2_dshare {
    type dshare
    ipc_key 43544553
    slave tdmshare
    bindings.0 6
    bindings.1 7
}
pcm.src2 {
    type plug
    slave.pcm "src2_dshare"
 hint {
                show {
                        @func refer
                        name defaults.namehint.basic
                }
                description "USB sound card SURROUND output jack"
        }
}

# src3 shared pcm device and corresponding virtual playback device
pcm.src3_dshare {
    type dshare
    ipc_key 43544553
    slave tdmshare
    bindings.0 2
    bindings.1 3
}
pcm.src3 {
    type plug
    slave.pcm "src3_dshare"
 hint {
                show {
                        @func refer
                        name defaults.namehint.basic
                }
                description "USB sound card CENTER/BASS output jack"
        }
}

# src4 shared pcm device and corresponding virtual playback device
pcm.src4_dshare {
    type dshare
    ipc_key 43544553
    slave tdmshare
    bindings.0 4
    bindings.1 5
}
pcm.src4 {
    type plug
    slave.pcm "src4_dshare"
 hint {
                show {
                        @func refer
                        name defaults.namehint.basic
                }
                description "USB sound card BACK output jack"
        }
}

Issue does not occur when using non-dshare outputs such as the native headphone output from the Pi.
Perhaps it's an issue with how I've set up the dshare. I've yet to digest how those few lines of code in alsa_player are breaking the PCM output.
I did instrument one build to monitor the state, and snapclient reported it to be PREPARED the whole time it was choking on chunks.
Again, deleting lines 448-452 from the v0.27.0 release of alsa_player.cpp gives me a working build at the latest rev.

[graybiggins]

#847 Related