search

badaix / snapcast

Synchronous multiroom audio player
GNU General Public License v3.0
6.18k stars 457 forks source link

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

Open ettom opened 1 year ago

ettom commented 1 year ago

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 specific 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

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 commented 7 months ago

Please retry with the current version

ettom commented 7 months ago

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.