Unclean termination of a snapclient causes audio to not play on next startup

[ettom]

Describe the bug Unclean termination of a snapclient causes audio to not play on next startup. I could reproduce this both with the pulse backend and the alsa backend. It's a rather specifc set of actions for reproducing this.

Steps to Reproduce

1. Unmute snapclient.
2. Do a hard shutdown for the machine running snapclient (pull the plug). There's probably a better way to simulate this though.
3. The snapclient doesn't disappear from the snapweb UI. Mute it.
4. Start up the machine running snapclient, snapweb will show that it's muted.
5. Unmute snapclient. No audio output. Restarting either the snapserver or snapclient will fix it.

Environment details

• OS: NixOS
• Snapcast version v0.26.0
• Installed from the official NixOS package

Attach logfile if applicable

When the snapclient reconnects, the snapserver log looks like this:

Jan 15 18:40:14 snacast-server snapserver[2106644]: onMessageReceived: Time, size: 8, id: 1732, refers: 0, sent: 3347704,22514, recv: 340061,212454
Jan 15 18:40:15 snacast-server snapserver[2106644]: StreamServer::NewConnection: ::ffff:192.168.0.8
Jan 15 18:40:15 snacast-server snapserver[2106644]: getNextMessage: Hello, size: 210, id: 2, refers: 0
Jan 15 18:40:15 snacast-server snapserver[2106644]: onMessageReceived: Hello, size: 210, id: 2, refers: 0, sent: 9,50606, recv: 340061,752923
Jan 15 18:40:15 snacast-server snapserver[2106644]: Hello from snapcast-client, host: snapcast-client, v0.26.0, ClientName: Snapclient, OS: NixOS 22.11 (Raccoon), Arch: x86_64, Protocol version: 2
Jan 15 18:40:15 snacast-server snapserver[2106644]: Sending ServerSettings to snapcast-client
Jan 15 18:40:15 snacast-server snapserver[2106644]: Group: 24b6f53b-25ba-b638-536d-9c6358129100, stream: Birdsong
Jan 15 18:40:15 snacast-server snapserver[2106644]: Sending codec header to snapcast-client
Jan 15 18:40:15 snacast-server snapserver[2106644]: Removing 1 inactive session(s), active sessions: 7
Jan 15 18:40:15 snacast-server snapserver[2106644]: getNextMessage: Time, size: 8, id: 3, refers: 0
Jan 15 18:40:15 snacast-server snapserver[2106644]: onMessageReceived: Time, size: 8, id: 3, refers: 0, sent: 9,50769, recv: 340061,755357

Snapclient log after the reboot (no audio at this point, even after unmuting):

Jan 15 18:39:57 snapcast-client systemd[1]: Started snapclient.service.
Jan 15 18:39:57 snapcast-client snapclient[820]: 2023-01-15 18-39-57.890 [Debug] (Snapclient) Trying to get PCM device for player: pulse, parameter: , card: default
Jan 15 18:39:57 snapcast-client snapclient[820]: Failed to load cookie file from cookie: No such file or directory
Jan 15 18:39:57 snapcast-client snapclient[820]: 2023-01-15 18-39-57.920 [Info] (Snapclient) Version 0.26.0
Jan 15 18:39:57 snapcast-client snapclient[820]: 2023-01-15 18-39-57.920 [Info] (Connection) Resolving host IP for: 192.168.0.2
Jan 15 18:39:57 snapcast-client snapclient[820]: 2023-01-15 18-39-57.920 [Info] (Connection) Connecting
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.879 [Notice] (Connection) Connected to 192.168.0.2
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.879 [Info] (Connection) My MAC: "redacted", socket: 8
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.919 [Debug] (Connection) outstanding async_write
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.921 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 60, muted: 1
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (Resampler) Resampling from 44100:16:2 to 48000:16:2
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (Player) Player name: pulse, device: default, description: Let PulseAudio server choose the device, idx: 1, sharing mode: unspecified, parameters: <none>
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (Player) Mixer mode: software, parameters: <none>
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (Player) Sampleformat: 48000:16:0, stream: 48000:16:2
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (PulsePlayer) Setting property "application.icon_name" to "snapcast"
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (PulsePlayer) Setting property "media.role" to "music"
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (PulsePlayer) Using buffer_time: 100 ms, server: default
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (PulsePlayer) Start
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.923 [Info] (PulsePlayer) Connecting to pulse
Jan 15 18:39:59 snapcast-client snapclient[820]: Failed to load cookie file from cookie: No such file or directory
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.924 [Debug] (PulsePlayer) State changed 2: authorizing
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.930 [Debug] (PulsePlayer) State changed 3: setting name
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.933 [Debug] (PulsePlayer) State changed 4: ready
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.935 [Debug] (Player) setVolume exp with base 10: 0.6 => 0.33123
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.943 [Info] (Stream) outputBufferDacTime > bufferMs: 140424559722 > 1000
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.943 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:39:59 snapcast-client snapclient[820]: 2023-01-15 18-39-59.943 [Info] (Stream) No chunks available
Jan 15 18:40:00 snapcast-client snapclient[820]: 2023-01-15 18-40-00.008 [Info] (Stream) No chunks available
Jan 15 18:40:00 snapcast-client snapclient[820]: 2023-01-15 18-40-00.040 [Info] (Controller) diff to server [ms]: 3.40053e+08
Jan 15 18:40:00 snapcast-client snapclient[820]: 2023-01-15 18-40-00.946 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:40:01 snapcast-client snapclient[820]: 2023-01-15 18-40-01.016 [Info] (Stream) No chunks available
Jan 15 18:40:01 snapcast-client snapclient[820]: 2023-01-15 18-40-01.967 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:40:02 snapcast-client snapclient[820]: 2023-01-15 18-40-02.013 [Info] (Stream) No chunks available
Jan 15 18:40:02 snapcast-client snapclient[820]: 2023-01-15 18-40-02.976 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:40:03 snapcast-client snapclient[820]: 2023-01-15 18-40-03.012 [Info] (Stream) No chunks available
Jan 15 18:40:03 snapcast-client snapclient[820]: 2023-01-15 18-40-03.989 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:40:04 snapcast-client snapclient[820]: 2023-01-15 18-40-04.019 [Info] (Stream) No chunks available
Jan 15 18:40:04 snapcast-client snapclient[820]: 2023-01-15 18-40-04.947 [Info] (PulsePlayer) No chunk received for 5000ms, disconnecting from pulse.
Jan 15 18:40:04 snapcast-client snapclient[820]: 2023-01-15 18-40-04.947 [Info] (PulsePlayer) Disconnecting from pulse
Jan 15 18:40:04 snapcast-client snapclient[820]: 2023-01-15 18-40-04.947 [Debug] (PulsePlayer) State changed 6: terminated
Jan 15 18:40:05 snapcast-client snapclient[820]: 2023-01-15 18-40-05.048 [Debug] (PulsePlayer) Waiting for a chunk to become available before reconnecting
...
Jan 15 18:44:14 snapcast-client snapclient[820]: 2023-01-15 18-44-14.824 [Debug] (PulsePlayer) Waiting for a chunk to become available before reconnecting
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.733 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 4800 bytes
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.734 [Info] (PulsePlayer) Chunk available, reconnecting to pulse
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.734 [Info] (PulsePlayer) Connecting to pulse
Jan 15 18:44:15 snapcast-client snapclient[820]: Failed to load cookie file from cookie: No such file or directory
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.735 [Debug] (PulsePlayer) State changed 2: authorizing
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.742 [Debug] (PulsePlayer) State changed 3: setting name
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.745 [Debug] (PulsePlayer) State changed 4: ready
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.754 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 5760 bytes
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.760 [Info] (Stream) outputBufferDacTime > bufferMs: 140424559772 > 1000
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.760 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.814 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 6720 bytes
Jan 15 18:44:15 snapcast-client snapclient[820]: 2023-01-15 18-44-15.894 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 7680 bytes
Jan 15 18:44:16 snapcast-client snapclient[820]: 2023-01-15 18-44-16.602 [Debug] (Stream) Silent frames: 155, frames: 1120, age: -3.248
Jan 15 18:44:16 snapcast-client snapclient[820]: 2023-01-15 18-44-16.625 [Debug] (Stats) Chunk: -11	-11	-11	-11	1	71	0
Jan 15 18:44:17 snapcast-client snapclient[820]: 2023-01-15 18-44-17.001 [Debug] (Stats) Chunk: -11	-11	-11	-11	17	69	0
Jan 15 18:44:18 snapcast-client snapclient[820]: 2023-01-15 18-44-18.022 [Debug] (Stats) Chunk: -10	-10	-10	-10	61	72	0
Jan 15 18:44:19 snapcast-client snapclient[820]: 2023-01-15 18-44-19.018 [Debug] (Stats) Chunk: -9	-10	-10	-10	104	76	1
Jan 15 18:44:20 snapcast-client snapclient[820]: 2023-01-15 18-44-20.022 [Debug] (Stats) Chunk: -4	-5	-9	-10	147	72	24
Jan 15 18:44:21 snapcast-client snapclient[820]: 2023-01-15 18-44-21.022 [Debug] (Stats) Chunk: 0	0	-5	-10	190	72	16
Jan 15 18:44:22 snapcast-client snapclient[820]: 2023-01-15 18-44-22.019 [Debug] (Stats) Chunk: 0	0	0	-8	233	76	0
Jan 15 18:44:23 snapcast-client snapclient[820]: 2023-01-15 18-44-23.002 [Debug] (Stats) Chunk: -1	0	0	-5	275	73	0
Jan 15 18:44:24 snapcast-client snapclient[820]: 2023-01-15 18-44-24.002 [Debug] (Stats) Chunk: 0	0	0	-2	318	74	0
Jan 15 18:44:25 snapcast-client snapclient[820]: 2023-01-15 18-44-25.006 [Debug] (Stats) Chunk: -1	-1	-1	-1	361	72	0
Jan 15 18:44:26 snapcast-client snapclient[820]: 2023-01-15 18-44-26.001 [Debug] (Stats) Chunk: -1	0	-1	-1	404	75	2
Jan 15 18:44:27 snapcast-client snapclient[820]: 2023-01-15 18-44-27.011 [Debug] (Stats) Chunk: 0	0	-1	-1	447	69	2
Jan 15 18:44:28 snapcast-client snapclient[820]: 2023-01-15 18-44-28.006 [Debug] (Stats) Chunk: -4	-4	-1	-1	490	71	3
Jan 15 18:44:29 snapcast-client snapclient[820]: 2023-01-15 18-44-29.002 [Debug] (Stats) Chunk: -6	-4	-4	-1	500	73	2
Jan 15 18:44:30 snapcast-client snapclient[820]: 2023-01-15 18-44-30.003 [Debug] (Stats) Chunk: -4	-4	-4	-1	500	73	12
Jan 15 18:44:31 snapcast-client snapclient[820]: 2023-01-15 18-44-31.007 [Debug] (Stats) Chunk: -2	-2	-4	-1	500	71	9
Jan 15 18:44:32 snapcast-client snapclient[820]: 2023-01-15 18-44-32.003 [Debug] (Stats) Chunk: 0	-1	-2	-1	500	74	8
Jan 15 18:44:33 snapcast-client snapclient[820]: 2023-01-15 18-44-33.005 [Debug] (Stats) Chunk: 0	0	0	-1	500	73	0
Jan 15 18:44:34 snapcast-client snapclient[820]: 2023-01-15 18-44-34.004 [Debug] (Stats) Chunk: -3	-3	0	-1	500	73	0
Jan 15 18:44:35 snapcast-client snapclient[820]: 2023-01-15 18-44-35.003 [Debug] (Stats) Chunk: -4	-4	-3	-1	500	73	0
Jan 15 18:44:36 snapcast-client snapclient[820]: 2023-01-15 18-44-36.003 [Debug] (Stats) Chunk: -3	-3	-3	-2	500	73	7
Jan 15 18:44:37 snapcast-client snapclient[820]: 2023-01-15 18-44-37.008 [Debug] (Stats) Chunk: 0	0	-3	-3	500	70	6
Jan 15 18:44:38 snapcast-client snapclient[820]: 2023-01-15 18-44-38.004 [Debug] (Stats) Chunk: 2	0	0	-3	500	73	2
Jan 15 18:44:38 snapcast-client snapclient[820]: 2023-01-15 18-44-38.309 [Info] (Stream) abs(age > 500): 543828
Jan 15 18:44:38 snapcast-client snapclient[820]: 2023-01-15 18-44-38.309 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:44:38 snapcast-client snapclient[820]: 2023-01-15 18-44-38.816 [Debug] (Stream) Silent frames: 960, frames: 1080, age: -20.011
Jan 15 18:44:39 snapcast-client snapclient[820]: 2023-01-15 18-44-39.006 [Debug] (Stats) Chunk: 0	0	0	0	8	72	0
Jan 15 18:44:40 snapcast-client snapclient[820]: 2023-01-15 18-44-40.004 [Debug] (Stats) Chunk: 1	1	1	1	51	74	0
Jan 15 18:44:41 snapcast-client snapclient[820]: 2023-01-15 18-44-41.003 [Debug] (Stats) Chunk: 3	1	1	1	94	76	0
Jan 15 18:44:42 snapcast-client snapclient[820]: 2023-01-15 18-44-42.014 [Debug] (Stats) Chunk: 2	3	2	1	137	68	-2
Jan 15 18:44:43 snapcast-client snapclient[820]: 2023-01-15 18-44-43.009 [Debug] (Stats) Chunk: 3	3	3	2	180	71	-5
Jan 15 18:44:44 snapcast-client snapclient[820]: 2023-01-15 18-44-44.002 [Debug] (Stats) Chunk: 2	2	2	2	223	75	-7
Jan 15 18:44:45 snapcast-client snapclient[820]: 2023-01-15 18-44-45.002 [Debug] (Stats) Chunk: 1	2	2	2	266	74	-4
Jan 15 18:44:46 snapcast-client snapclient[820]: 2023-01-15 18-44-46.011 [Debug] (Stats) Chunk: 1	1	1	2	309	70	-5
Jan 15 18:44:47 snapcast-client snapclient[820]: 2023-01-15 18-44-47.004 [Debug] (Stats) Chunk: 0	1	1	1	352	76	-2
Jan 15 18:44:47 snapcast-client snapclient[820]: 2023-01-15 18-44-47.058 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 8640 bytes
Jan 15 18:44:47 snapcast-client snapclient[820]: 2023-01-15 18-44-47.827 [Info] (Stream) pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -327916
Jan 15 18:44:48 snapcast-client snapclient[820]: 2023-01-15 18-44-48.193 [Debug] (Stream) Silent frames: 283, frames: 1160, age: -5.911
Jan 15 18:44:48 snapcast-client snapclient[820]: 2023-01-15 18-44-48.217 [Debug] (Stats) Chunk: 0	0	0	0	1	73	-2

Snapclient logs after restarting snapserver (starts playing at this point):

Jan 15 18:48:52 snapcast-client snapclient[820]: 2023-01-15 18-48-52.215 [Info] (PulsePlayer) Chunk available, reconnecting to pulse
Jan 15 18:48:52 snapcast-client snapclient[820]: 2023-01-15 18-48-52.215 [Info] (PulsePlayer) Connecting to pulse
Jan 15 18:48:52 snapcast-client snapclient[820]: Failed to load cookie file from cookie: No such file or directory
Jan 15 18:48:52 snapcast-client snapclient[820]: 2023-01-15 18-48-52.217 [Debug] (PulsePlayer) State changed 2: authorizing
Jan 15 18:48:52 snapcast-client snapclient[820]: 2023-01-15 18-48-52.223 [Debug] (PulsePlayer) State changed 3: setting name
Jan 15 18:48:52 snapcast-client snapclient[820]: 2023-01-15 18-48-52.226 [Debug] (PulsePlayer) State changed 4: ready
Jan 15 18:48:52 snapcast-client snapclient[820]: 2023-01-15 18-48-52.242 [Info] (Stream) outputBufferDacTime > bufferMs: 140424559744 > 1000
Jan 15 18:48:52 snapcast-client snapclient[820]: 2023-01-15 18-48-52.242 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:48:53 snapcast-client snapclient[820]: 2023-01-15 18-48-53.106 [Debug] (Stream) Silent frames: 406, frames: 1120, age: -8.467
Jan 15 18:48:53 snapcast-client snapclient[820]: 2023-01-15 18-48-53.129 [Debug] (Stats) Chunk: 0	0	0	0	1	71	2
Jan 15 18:48:54 snapcast-client snapclient[820]: 2023-01-15 18-48-54.008 [Debug] (Stats) Chunk: 400	400	400	400	39	75	0
Jan 15 18:48:55 snapcast-client snapclient[820]: 2023-01-15 18-48-55.017 [Debug] (Stats) Chunk: 401	401	400	400	82	70	0
Jan 15 18:48:55 snapcast-client snapclient[820]: 2023-01-15 18-48-55.463 [Info] (Stream) pShortBuffer->full() && (abs(shortMedian_) > 5): 40027
Jan 15 18:48:55 snapcast-client snapclient[820]: 2023-01-15 18-48-55.475 [Debug] (Stream) age > 0: 40ms, dropping old chunks
Jan 15 18:48:55 snapcast-client snapclient[820]: 2023-01-15 18-48-55.475 [Debug] (Stream) age: 9, requested chunk_duration: 20, duration: 18
Jan 15 18:48:56 snapcast-client snapclient[820]: 2023-01-15 18-48-56.014 [Debug] (Stats) Chunk: 0	0	0	0	23	73	0
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.022 [Debug] (Stats) Chunk: 2	2	0	0	66	69	0
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.206 [Error] (Connection) Error reading message header of length 0: End of file
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.206 [Debug] (Connection) Disconnecting
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.206 [Debug] (Connection) Disconnected
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.207 [Debug] (PulsePlayer) Destructor
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.207 [Info] (PulsePlayer) Stop
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.207 [Info] (PulsePlayer) Disconnecting from pulse
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.207 [Debug] (PulsePlayer) State changed 6: terminated
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.207 [Info] (PulsePlayer) Chunk available, reconnecting to pulse
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.207 [Info] (PulsePlayer) Connecting to pulse
Jan 15 18:48:57 snapcast-client snapclient[820]: Failed to load cookie file from cookie: No such file or directory
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.208 [Debug] (PulsePlayer) State changed 2: authorizing
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.214 [Debug] (PulsePlayer) State changed 3: setting name
Jan 15 18:48:57 snapcast-client snapclient[820]: 2023-01-15 18-48-57.218 [Debug] (PulsePlayer) State changed 4: ready
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.219 [Info] (Connection) Resolving host IP for: 192.168.0.2
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.219 [Info] (Connection) Connecting
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.222 [Notice] (Connection) Connected to 192.168.0.2
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.222 [Info] (Connection) My MAC: "redacted", socket: 12
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.244 [Debug] (Connection) outstanding async_write
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.255 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (Resampler) Resampling from 44100:16:2 to 48000:16:2
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (Player) Player name: pulse, device: default, description: Let PulseAudio server choose the device, idx: 1, sharing mode: unspecified, parameters: <none>
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (Player) Mixer mode: software, parameters: <none>
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (Player) Sampleformat: 48000:16:0, stream: 48000:16:2
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (PulsePlayer) Setting property "application.icon_name" to "snapcast"
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (PulsePlayer) Setting property "media.role" to "music"
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (PulsePlayer) Using buffer_time: 100 ms, server: default
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (PulsePlayer) Start
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.256 [Info] (PulsePlayer) Connecting to pulse
Jan 15 18:48:58 snapcast-client snapclient[820]: Failed to load cookie file from cookie: No such file or directory
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.257 [Debug] (PulsePlayer) State changed 2: authorizing
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.263 [Debug] (PulsePlayer) State changed 3: setting name
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.267 [Debug] (PulsePlayer) State changed 4: ready
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.268 [Debug] (Player) setVolume exp with base 10: 1 => 1
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.269 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 4800 bytes
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.269 [Info] (Stream) outputBufferDacTime > bufferMs: 140424559722 > 1000
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.269 [Debug] (Stream) Failed to get chunk, returning silence
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.307 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 5760 bytes
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.347 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 6720 bytes
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.379 [Info] (Controller) diff to server [ms]: 3.40053e+08
Jan 15 18:48:58 snapcast-client snapclient[820]: 2023-01-15 18-48-58.427 [Debug] (Resampler) Resample buffer completely filled, adding space for 5ms; new buffer size: 7680 bytes
Jan 15 18:48:59 snapcast-client snapclient[820]: 2023-01-15 18-48-59.132 [Debug] (Stream) Silent frames: 977, frames: 1160, age: -20.365
Jan 15 18:48:59 snapcast-client snapclient[820]: 2023-01-15 18-48-59.155 [Debug] (Stats) Chunk: 0	0	0	0	1	73	0
Jan 15 18:49:00 snapcast-client snapclient[820]: 2023-01-15 18-49-00.013 [Debug] (Stats) Chunk: -10	-10	-11	-11	38	71	0
Jan 15 18:49:01 snapcast-client snapclient[820]: 2023-01-15 18-49-01.009 [Debug] (Stats) Chunk: -10	-10	-10	-10	81	75	0

[badaix]

Please retry with the current version

[ettom]

Please retry with the current version

I can still reproduce this. Both the server and client on commit https://github.com/badaix/snapcast/commit/be083d2e8e38b0b7abae34adc598a9867caea681.