snapcast Dropouts on multiple clients with pBuffer->full() && (abs(median

Dropouts on multiple clients with pBuffer->full() && (abs(median_) > 2)

Open jwals23 opened this issue 1 year ago • 1 comments

I'm running into issues with dropouts similar to #774 and #855 but the main solutions offered there (modifying buffer_time and fragments, and switching from a FIFO to a loopback device) haven't worked for me, or at least I haven't been able to find the right combination. I'm running snapserver v0.26.0 and Mopidy v3.3.0 on a Raspberry Pi 4, with the official Raspberry Pi OS Lite 64-bit. I'm running snapclient v0.26.0 on the same Pi (connected to a DAC to my stereo) and for now just another snapclient on my laptop (Ubuntu 20.04.4). Both clients give the pBuffer->full() && (abs(median_) > 2): message, which results in audible dropouts (at least when playing over the laptop -- sometimes the dropouts aren't audible from the Pi connected to stereo, even when pBuffer->full() && (abs(median_) > 2): happens). Some of my relevant config files and logs are below. I'm happy to provide more info and test things, and any help is very much appreciated!

mopidy.conf

[http]
hostname = 0.0.0.0

[audio]
#output = audioresample ! audioconvert ! audio/x-raw,rate=48000,channels=2,format=S16LE ! wavenc ! filesink location=/tmp/snapfifo
output = audioresample ! audioconvert ! audio/x-raw,rate=44100,channels=2,format=S16LE ! alsasink device=hw:0,0,0
#output = audioresample ! audioconvert ! audio/x-raw,rate=441000,channels=2,format=S16LE ! wavenc ! tcpclientsink host=127.0.0.1 port=4953

snapserver.conf

[stream]
#source = pipe:///tmp/snapfifo?name=default
source = alsa://?name=mopidy&device=hw:0,1,0&sampleformat=44100:16:2
#source = tcp://127.0.0.1?name=mopidy_tcp
#source = tcp://127.0.0.1?name=mopidy&port=4953&sampleformat=44100:16:2

snapserver log

jason@musicbox:~ $ snapserver 
2022-08-04 11-01-19.786 [Info] (Snapserver) Version 0.26.0, revision e30a9f33
2022-08-04 11-01-19.786 [Info] (Snapserver) Adding source: alsa://?name=mopidy&device=hw:0,1,0&sampleformat=44100:16:2
2022-08-04 11-01-19.786 [Notice] (init) Settings file: "/home/jason/.config/snapserver/server.json"
2022-08-04 11-01-19.788 [Info] (Snapserver) Using HTTP host name: musicbox
2022-08-04 11-01-19.797 [Info] (Avahi) Adding service 'Snapcast'
2022-08-04 11-01-19.806 [Info] (PcmStream) PcmStream: mopidy, sampleFormat: 44100:16:2
2022-08-04 11-01-19.806 [Info] (Server) Stream: {"fragment":"","host":"","path":"","query":{"chunk_ms":"20","codec":"flac","device":"hw:0,1,0","name":"mopidy","sampleformat":"44100:16:2"},"raw":"alsa:///?chunk_ms=20&codec=flac&device=hw:0,1,0&name=mopidy&sampleformat=44100:16:2","scheme":"alsa"}
2022-08-04 11-01-19.817 [Info] (FlacEnc) Init - compression level: 2
2022-08-04 11-01-19.818 [Info] (AlsaStream) No data availabale, playing silence.
2022-08-04 11-01-19.818 [Info] (ControlServer) Creating TCP acceptor for address: 0.0.0.0, port: 1705
2022-08-04 11-01-19.818 [Info] (ControlServer) Creating HTTP acceptor for address: 0.0.0.0, port: 1780
2022-08-04 11-01-19.818 [Info] (StreamServer) Creating stream acceptor for address: 0.0.0.0, port: 1704
2022-08-04 11-01-19.819 [Info] (Snapserver) Number of threads: 4, hw threads: 4
2022-08-04 11-01-20.679 [Notice] (StreamServer) StreamServer::NewConnection: 10.0.0.202
2022-08-04 11-01-20.682 [Info] (Server) Hello from 0c:96:e6:7b:c4:11, host: jason-ideapad, v0.26.0, ClientName: Snapclient, OS: Ubuntu 20.04.4 LTS, Arch: x86_64, Protocol version: 2
2022-08-04 11-01-20.697 [Notice] (ControlServer) ControlServer::NewConnection: 10.0.0.202
2022-08-04 11-01-20.733 [Info] (Server) Hello from 169fe5c6-d8e3-4343-ac8e-cfecab4b038e, host: Snapweb client, v0.1.0, ClientName: Snapweb, OS: Linux x86_64, Arch: web, Protocol version: 2
2022-08-04 11-01-20.734 [Info] (ControlServer) Removing 1 inactive session(s), active sessions: 0
2022-08-04 11-01-20.857 [Info] (Avahi) Service 'Snapcast' successfully established.
2022-08-04 11-01-22.358 [Info] (PcmStream) State changed: mopidy, state: idle => playing
2022-08-04 11-01-22.358 [Info] (Server) onStateChanged (mopidy): playing
2022-08-04 11-01-23.700 [Notice] (ControlServer) ControlServer::NewConnection: 10.0.0.202
2022-08-04 11-01-24.472 [Notice] (StreamServer) StreamServer::NewConnection: 10.0.0.220
2022-08-04 11-01-24.580 [Info] (Server) Hello from e4:5f:01:08:02:2a, host: musicbox, v0.26.0, ClientName: Snapclient, OS: Debian GNU/Linux 11 (bullseye), Arch: aarch64, Protocol version: 2
2022-08-04 11-01-24.581 [Info] (ControlServer) Removing 1 inactive session(s), active sessions: 1
2022-08-04 11-01-27.042 [Notice] (StreamServer) StreamServer::NewConnection: 10.0.0.202
2022-08-04 11-01-27.082 [Info] (Server) Hello from 0c:96:e6:7b:c4:11, host: jason-ideapad, v0.26.0, ClientName: Snapclient, OS: Ubuntu 20.04.4 LTS, Arch: x86_64, Protocol version: 2
2022-08-04 11-02-01.846 [Error] (StreamSessionTCP) Error reading message header of length 0: End of file
2022-08-04 11-02-01.846 [Info] (StreamServer) onDisconnect: 0c:96:e6:7b:c4:11
2022-08-04 11-02-01.847 [Error] (StreamSessionTCP) Error in socket shutdown: Transport endpoint is not connected
2022-08-04 11-02-05.422 [Error] (StreamSessionTCP) Error reading message header of length 0: End of file
2022-08-04 11-02-05.422 [Info] (StreamServer) onDisconnect: e4:5f:01:08:02:2a
2022-08-04 11-02-05.423 [Error] (StreamSessionTCP) Error in socket shutdown: Transport endpoint is not connected
2022-08-04 11-02-10.329 [Info] (PcmStream) State changed: mopidy, state: playing => idle
2022-08-04 11-02-10.330 [Info] (Server) onStateChanged (mopidy): idle
^C2022-08-04 11-02-11.506 [Info] (Snapserver) Received signal 2: Interrupt
2022-08-04 11-02-11.507 [Info] (Snapserver) Stopping streamServer
2022-08-04 11-02-11.518 [Info] (Snapserver) done
2022-08-04 11-02-11.521 [Notice] (Snapserver) Snapserver terminated.

snapclient on Pi

jason@musicbox:~ $ snapclient -s default:CARD=S3 --logfilter *:debug
2022-08-04 11-01-24.402 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default:CARD=S3
2022-08-04 11-01-24.454 [Info] (Snapclient) Version 0.26.0, revision e30a9f33
2022-08-04 11-01-24.468 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2022-08-04 11-01-24.469 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2022-08-04 11-01-24.469 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2022-08-04 11-01-24.470 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2022-08-04 11-01-24.470 [Info] (Avahi) 	musicbox.local:1704 (10.0.0.220)
2022-08-04 11-01-24.470 [Debug] (Avahi) 	TXT=
2022-08-04 11-01-24.470 [Debug] (Avahi) 	Proto=0
2022-08-04 11-01-24.470 [Debug] (Avahi) 	cookie is 0
2022-08-04 11-01-24.470 [Debug] (Avahi) 	is_local: 1
2022-08-04 11-01-24.470 [Debug] (Avahi) 	our_own: 0
2022-08-04 11-01-24.470 [Debug] (Avahi) 	wide_area: 0
2022-08-04 11-01-24.470 [Debug] (Avahi) 	multicast: 1
2022-08-04 11-01-24.470 [Debug] (Avahi) 	cached: 1
2022-08-04 11-01-24.471 [Info] (Controller) Found server 10.0.0.220:1704
2022-08-04 11-01-24.471 [Info] (Connection) Resolving host IP for: 10.0.0.220
2022-08-04 11-01-24.471 [Info] (Connection) Connecting
2022-08-04 11-01-24.471 [Notice] (Connection) Connected to 10.0.0.220
2022-08-04 11-01-24.472 [Info] (Connection) My MAC: "e4:5f:01:08:02:2a", socket: 8
2022-08-04 11-01-24.580 [Debug] (Connection) outstanding async_write
2022-08-04 11-01-24.581 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2022-08-04 11-01-24.581 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2022-08-04 11-01-24.581 [Info] (Player) Player name: alsa, device: default:CARD=S3, description: Schiit Modi 3+, USB Audio
2022-08-04 11-01-24.581 [Info] (Player) Default Audio Device, idx: 23, sharing mode: unspecified, parameters: <none>
2022-08-04 11-01-24.582 [Info] (Player) Mixer mode: software, parameters: <none>
2022-08-04 11-01-24.582 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2022-08-04 11-01-24.582 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2022-08-04 11-01-24.591 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2022-08-04 11-01-24.591 [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
2022-08-04 11-01-24.591 [Debug] (Alsa) SUBFORMAT:  STD
2022-08-04 11-01-24.591 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2022-08-04 11-01-24.591 [Debug] (Alsa) FRAME_BITS: [4 640000]
2022-08-04 11-01-24.591 [Debug] (Alsa) CHANNELS: [1 10000]
2022-08-04 11-01-24.591 [Debug] (Alsa) RATE: [4000 4294967295)
2022-08-04 11-01-24.591 [Debug] (Alsa) PERIOD_TIME: (21333 21334)
2022-08-04 11-01-24.591 [Debug] (Alsa) PERIOD_SIZE: (85 91628833)
2022-08-04 11-01-24.591 [Debug] (Alsa) PERIOD_BYTES: (42 4294967295)
2022-08-04 11-01-24.591 [Debug] (Alsa) PERIODS: (0 17247242)
2022-08-04 11-01-24.591 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2022-08-04 11-01-24.591 [Debug] (Alsa) BUFFER_SIZE: [170 1466015503]
2022-08-04 11-01-24.591 [Debug] (Alsa) BUFFER_BYTES: [85 4294967295]
2022-08-04 11-01-24.591 [Debug] (Alsa) TICK_TIME: ALL
2022-08-04 11-01-24.592 [Info] (Alsa) Period time too small, changing from 20000 to 21333
2022-08-04 11-01-24.593 [Info] (Alsa) PCM name: default:CARD=S3, sample rate: 44100 Hz, channels: 2, buffer time: 85328 us, periods: 4, period time: 21333 us, period frames: 940
2022-08-04 11-01-24.593 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2022-08-04 11-01-24.593 [Debug] (Alsa) Resizing buffer from 0 to 15052
2022-08-04 11-01-24.593 [Info] (Stream) No chunks available
2022-08-04 11-01-24.612 [Info] (Controller) diff to server [ms]: 0
2022-08-04 11-01-25.499 [Debug] (Stream) Silent frames: 787, frames: 942, age: -17.857
2022-08-04 11-01-25.520 [Debug] (Stats) Chunk: 1	1	1	1	1	64	0
2022-08-04 11-01-26.011 [Debug] (Stats) Chunk: 4	2	2	2	24	63	0
2022-08-04 11-01-27.014 [Debug] (Stats) Chunk: 13	12	7	7	71	64	0
2022-08-04 11-01-28.016 [Debug] (Stats) Chunk: 21	20	13	12	118	63	-5
2022-08-04 11-01-29.019 [Debug] (Stats) Chunk: 26	26	21	16	165	63	-22
2022-08-04 11-01-30.022 [Debug] (Stats) Chunk: 30	30	27	20	212	63	-23
2022-08-04 11-01-31.025 [Debug] (Stats) Chunk: 35	33	30	22	259	64	-22
2022-08-04 11-01-32.006 [Debug] (Stats) Chunk: 37	37	34	24	305	63	-21
2022-08-04 11-01-33.009 [Debug] (Stats) Chunk: 42	40	38	28	352	64	-22
2022-08-04 11-01-34.011 [Debug] (Stats) Chunk: 44	44	41	30	399	63	-22
2022-08-04 11-01-35.014 [Debug] (Stats) Chunk: 47	47	44	31	446	63	-23
2022-08-04 11-01-36.017 [Debug] (Stats) Chunk: 51	51	48	33	493	63	-22
2022-08-04 11-01-36.187 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 3340
2022-08-04 11-01-36.209 [Debug] (Stream) age > 0: 5ms, dropping old chunks
2022-08-04 11-01-36.209 [Debug] (Stream) age: -18, requested chunk_duration: 21, duration: 26
2022-08-04 11-01-36.209 [Debug] (Stream) Silent frames: 797, frames: 937, age: -18.079
2022-08-04 11-01-37.019 [Debug] (Stats) Chunk: 3	2	0	0	38	63	-3
2022-08-04 11-01-38.022 [Debug] (Stats) Chunk: 11	10	5	5	85	63	0
2022-08-04 11-01-39.025 [Debug] (Stats) Chunk: 18	17	11	9	132	63	-7
2022-08-04 11-01-40.006 [Debug] (Stats) Chunk: 23	21	18	13	178	64	-23
2022-08-04 11-01-41.009 [Debug] (Stats) Chunk: 25	24	21	16	225	63	-22
2022-08-04 11-01-42.011 [Debug] (Stats) Chunk: 28	27	25	18	272	63	-22
2022-08-04 11-01-43.014 [Debug] (Stats) Chunk: 32	31	28	20	319	64	-22
2022-08-04 11-01-44.017 [Debug] (Stats) Chunk: 37	35	32	22	366	64	-22
2022-08-04 11-01-45.019 [Debug] (Stats) Chunk: 39	39	36	24	413	63	-22
2022-08-04 11-01-46.022 [Debug] (Stats) Chunk: 43	42	39	25	460	64	-22
2022-08-04 11-01-46.897 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2576
2022-08-04 11-01-46.918 [Debug] (Stream) age > 0: 4ms, dropping old chunks
2022-08-04 11-01-46.918 [Debug] (Stream) age: -18, requested chunk_duration: 21, duration: 26
2022-08-04 11-01-46.918 [Debug] (Stream) Silent frames: 836, frames: 936, age: -18.975
2022-08-04 11-01-47.025 [Debug] (Stats) Chunk: -1	-2	-2	-2	5	63	-19
2022-08-04 11-01-48.006 [Debug] (Stats) Chunk: 7	4	1	1	51	64	0
2022-08-04 11-01-49.009 [Debug] (Stats) Chunk: 15	14	6	6	98	63	0
2022-08-04 11-01-50.011 [Debug] (Stats) Chunk: 21	20	15	11	145	64	-12
2022-08-04 11-01-51.014 [Debug] (Stats) Chunk: 24	24	21	15	192	63	-22
2022-08-04 11-01-52.017 [Debug] (Stats) Chunk: 28	28	25	18	239	64	-23
2022-08-04 11-01-53.019 [Debug] (Stats) Chunk: 32	31	28	21	286	63	-22
2022-08-04 11-01-54.022 [Debug] (Stats) Chunk: 35	35	32	23	333	63	-22
2022-08-04 11-01-55.025 [Debug] (Stats) Chunk: 41	39	36	25	380	64	-22
2022-08-04 11-01-56.006 [Debug] (Stats) Chunk: 43	43	39	27	426	64	-21
2022-08-04 11-01-57.009 [Debug] (Stats) Chunk: 47	46	43	28	473	63	-23
2022-08-04 11-01-57.606 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2881
2022-08-04 11-01-57.627 [Debug] (Stream) age > 0: 4ms, dropping old chunks
2022-08-04 11-01-57.627 [Debug] (Stream) age: -19, requested chunk_duration: 21, duration: 26
2022-08-04 11-01-57.628 [Debug] (Stream) Silent frames: 873, frames: 937, age: -19.816
2022-08-04 11-01-58.011 [Debug] (Stats) Chunk: 2	1	1	1	18	63	-13
2022-08-04 11-01-59.014 [Debug] (Stats) Chunk: 10	9	5	5	65	64	0
2022-08-04 11-02-00.017 [Debug] (Stats) Chunk: 18	17	10	9	112	63	-2
2022-08-04 11-02-01.020 [Debug] (Stats) Chunk: 22	21	18	14	159	63	-23
2022-08-04 11-02-02.022 [Debug] (Stats) Chunk: 26	25	22	17	206	64	-22
2022-08-04 11-02-03.025 [Debug] (Stats) Chunk: 30	29	26	20	253	64	-22
2022-08-04 11-02-04.006 [Debug] (Stats) Chunk: 32	32	29	21	299	63	-22
2022-08-04 11-02-05.009 [Debug] (Stats) Chunk: 37	36	32	23	346	64	-22
^C2022-08-04 11-02-05.400 [Info] (Snapclient) Received signal 2: Interrupt
2022-08-04 11-02-05.422 [Debug] (Connection) Disconnecting
2022-08-04 11-02-05.422 [Debug] (Connection) Disconnected
2022-08-04 11-02-05.423 [Notice] (Snapclient) Snapclient terminated.

snapclient on laptop

jason@jason-ideapad:~$ snapclient --logfilter *:debug 
2022-08-04 11-01-27.012 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2022-08-04 11-01-27.037 [Info] (Snapclient) Version 0.26.0, revision e30a9f33
2022-08-04 11-01-27.040 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2022-08-04 11-01-27.040 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2022-08-04 11-01-27.040 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2022-08-04 11-01-27.040 [Info] (Avahi) 	musicbox.local:1704 (10.0.0.220)
2022-08-04 11-01-27.040 [Debug] (Avahi) 	TXT=
2022-08-04 11-01-27.040 [Debug] (Avahi) 	Proto=0
2022-08-04 11-01-27.040 [Debug] (Avahi) 	cookie is 0
2022-08-04 11-01-27.040 [Debug] (Avahi) 	is_local: 0
2022-08-04 11-01-27.040 [Debug] (Avahi) 	our_own: 0
2022-08-04 11-01-27.040 [Debug] (Avahi) 	wide_area: 0
2022-08-04 11-01-27.040 [Debug] (Avahi) 	multicast: 1
2022-08-04 11-01-27.040 [Debug] (Avahi) 	cached: 1
2022-08-04 11-01-27.041 [Info] (Controller) Found server 10.0.0.220:1704
2022-08-04 11-01-27.041 [Info] (Connection) Resolving host IP for: 10.0.0.220
2022-08-04 11-01-27.041 [Info] (Connection) Connecting
2022-08-04 11-01-27.045 [Notice] (Connection) Connected to 10.0.0.220
2022-08-04 11-01-27.045 [Info] (Connection) My MAC: "0c:96:e6:7b:c4:11", socket: 8
2022-08-04 11-01-27.086 [Debug] (Connection) outstanding async_write
2022-08-04 11-01-27.092 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
2022-08-04 11-01-27.093 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2022-08-04 11-01-27.093 [Info] (Player) Player name: alsa, device: default, description: Playback/recording through the PulseAudio sound server, idx: 0, sharing mode: unspecified, parameters: <none>
2022-08-04 11-01-27.093 [Info] (Player) Mixer mode: software, parameters: <none>
2022-08-04 11-01-27.093 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2022-08-04 11-01-27.093 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2022-08-04 11-01-27.094 [Debug] (Alsa) ACCESS:  RW_INTERLEAVED
2022-08-04 11-01-27.094 [Debug] (Alsa) FORMAT:  U8 S16_LE S16_BE S24_LE S24_BE S32_LE S32_BE FLOAT_LE FLOAT_BE MU_LAW A_LAW S24_3LE S24_3BE
2022-08-04 11-01-27.094 [Debug] (Alsa) SUBFORMAT:  STD
2022-08-04 11-01-27.094 [Debug] (Alsa) SAMPLE_BITS: [8 32]
2022-08-04 11-01-27.094 [Debug] (Alsa) FRAME_BITS: [8 1024]
2022-08-04 11-01-27.094 [Debug] (Alsa) CHANNELS: [1 32]
2022-08-04 11-01-27.094 [Debug] (Alsa) RATE: [1 384000]
2022-08-04 11-01-27.094 [Debug] (Alsa) PERIOD_TIME: (2 4294967295)
2022-08-04 11-01-27.094 [Debug] (Alsa) PERIOD_SIZE: [1 1398102)
2022-08-04 11-01-27.094 [Debug] (Alsa) PERIOD_BYTES: [128 1398102)
2022-08-04 11-01-27.094 [Debug] (Alsa) PERIODS: [3 1024]
2022-08-04 11-01-27.094 [Debug] (Alsa) BUFFER_TIME: (7 4294967295]
2022-08-04 11-01-27.094 [Debug] (Alsa) BUFFER_SIZE: [3 4194304]
2022-08-04 11-01-27.094 [Debug] (Alsa) BUFFER_BYTES: [384 4194304]
2022-08-04 11-01-27.094 [Debug] (Alsa) TICK_TIME: ALL
2022-08-04 11-01-27.095 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
2022-08-04 11-01-27.095 [Debug] (Alsa) Resizing buffer from 0 to 28220
2022-08-04 11-01-27.095 [Debug] (Alsa) setVolume exp with base 10: 1 => 1
2022-08-04 11-01-27.095 [Info] (Stream) No chunks available
2022-08-04 11-01-27.095 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-27.388 [Info] (Controller) diff to server [ms]: -2.43268e+06
2022-08-04 11-01-27.987 [Debug] (Stream) Silent frames: 581, frames: 1048, age: -13.196
2022-08-04 11-01-28.009 [Debug] (Stats) Chunk: 0	0	0	0	1	70	0
2022-08-04 11-01-29.025 [Debug] (Stats) Chunk: -37	-32	-22	-22	47	66	0
2022-08-04 11-01-29.431 [Info] (Stream) Exception: Not enough frames available, requested frames: 896, available: 77
2022-08-04 11-01-29.432 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-29.532 [Debug] (Alsa) Waiting for chunk
2022-08-04 11-01-30.385 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 896, delay: 3017, using snd_pcm_avail amd snd_pcm_delay.
2022-08-04 11-01-30.386 [Debug] (Alsa) snd_pcm_avail failed: Broken pipe (-32), using 882
2022-08-04 11-01-30.386 [Debug] (Stream) age > 0: 885ms, dropping old chunks
2022-08-04 11-01-30.386 [Debug] (Stream) age: 885, requested chunk_duration: 20, duration: 26
2022-08-04 11-01-30.386 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.445 [Error] (Alsa) XRUN while waiting for PCM: Broken pipe
2022-08-04 11-01-30.446 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error (-5), avail: 882, delay: 232, using snd_pcm_avail amd snd_pcm_delay.
2022-08-04 11-01-30.447 [Debug] (Stream) age > 0: 941ms, dropping old chunks
2022-08-04 11-01-30.447 [Debug] (Stream) age: 915, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.447 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.463 [Debug] (Stream) age > 0: 931ms, dropping old chunks
2022-08-04 11-01-30.463 [Debug] (Stream) age: 905, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.463 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.463 [Debug] (Stream) age > 0: 905ms, dropping old chunks
2022-08-04 11-01-30.463 [Debug] (Stream) age: 879, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.463 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.464 [Debug] (Stream) age > 0: 879ms, dropping old chunks
2022-08-04 11-01-30.464 [Debug] (Stream) age: 853, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.464 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.489 [Debug] (Stream) age > 0: 878ms, dropping old chunks
2022-08-04 11-01-30.489 [Debug] (Stream) age: 852, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.489 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.491 [Debug] (Stream) age > 0: 854ms, dropping old chunks
2022-08-04 11-01-30.491 [Debug] (Stream) age: 828, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.491 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.491 [Debug] (Stream) age > 0: 828ms, dropping old chunks
2022-08-04 11-01-30.491 [Debug] (Stream) age: 802, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.491 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.491 [Debug] (Stream) age > 0: 802ms, dropping old chunks
2022-08-04 11-01-30.491 [Debug] (Stream) age: 776, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.491 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.491 [Debug] (Stream) age > 0: 776ms, dropping old chunks
2022-08-04 11-01-30.491 [Debug] (Stream) age: 750, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.491 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.491 [Debug] (Stream) age > 0: 750ms, dropping old chunks
2022-08-04 11-01-30.491 [Debug] (Stream) age: 724, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.491 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.498 [Debug] (Stream) age > 0: 731ms, dropping old chunks
2022-08-04 11-01-30.498 [Debug] (Stream) age: 705, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.498 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.502 [Debug] (Stream) age > 0: 709ms, dropping old chunks
2022-08-04 11-01-30.502 [Debug] (Stream) age: 683, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.502 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.551 [Debug] (Stream) age > 0: 732ms, dropping old chunks
2022-08-04 11-01-30.551 [Debug] (Stream) age: 705, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.551 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.551 [Debug] (Stream) age > 0: 706ms, dropping old chunks
2022-08-04 11-01-30.551 [Debug] (Stream) age: 680, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.551 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.552 [Debug] (Stream) age > 0: 681ms, dropping old chunks
2022-08-04 11-01-30.552 [Debug] (Stream) age: 655, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.552 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.555 [Debug] (Stream) age > 0: 658ms, dropping old chunks
2022-08-04 11-01-30.556 [Debug] (Stream) age: 632, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.556 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.556 [Debug] (Stream) age > 0: 632ms, dropping old chunks
2022-08-04 11-01-30.556 [Debug] (Stream) age: 606, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.556 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.556 [Debug] (Stream) age > 0: 606ms, dropping old chunks
2022-08-04 11-01-30.556 [Debug] (Stream) age: 580, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.556 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.573 [Debug] (Stream) age > 0: 597ms, dropping old chunks
2022-08-04 11-01-30.573 [Debug] (Stream) age: 571, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.573 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.573 [Debug] (Stream) age > 0: 571ms, dropping old chunks
2022-08-04 11-01-30.573 [Debug] (Stream) age: 545, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.574 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.574 [Debug] (Stream) age > 0: 545ms, dropping old chunks
2022-08-04 11-01-30.574 [Debug] (Stream) age: 519, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.574 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.582 [Debug] (Stream) age > 0: 528ms, dropping old chunks
2022-08-04 11-01-30.583 [Debug] (Stream) age: 502, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.583 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.584 [Debug] (Stream) age > 0: 503ms, dropping old chunks
2022-08-04 11-01-30.584 [Debug] (Stream) age: 477, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.584 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.584 [Debug] (Stream) age > 0: 477ms, dropping old chunks
2022-08-04 11-01-30.584 [Debug] (Stream) age: 451, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.584 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.586 [Debug] (Stream) age > 0: 454ms, dropping old chunks
2022-08-04 11-01-30.587 [Debug] (Stream) age: 428, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.587 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.590 [Debug] (Stream) age > 0: 431ms, dropping old chunks
2022-08-04 11-01-30.590 [Debug] (Stream) age: 196, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.590 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.590 [Debug] (Stream) age > 0: 196ms, dropping old chunks
2022-08-04 11-01-30.590 [Debug] (Stream) age: 170, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.590 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.592 [Debug] (Stream) age > 0: 172ms, dropping old chunks
2022-08-04 11-01-30.592 [Debug] (Stream) age: 146, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.592 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.592 [Debug] (Stream) age > 0: 146ms, dropping old chunks
2022-08-04 11-01-30.592 [Debug] (Stream) age: 120, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.592 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.592 [Debug] (Stream) age > 0: 120ms, dropping old chunks
2022-08-04 11-01-30.593 [Debug] (Stream) age: 94, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.593 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.594 [Debug] (Stream) age > 0: 95ms, dropping old chunks
2022-08-04 11-01-30.594 [Debug] (Stream) age: 69, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.594 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.596 [Debug] (Stream) age > 0: 71ms, dropping old chunks
2022-08-04 11-01-30.596 [Debug] (Stream) age: 45, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.596 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.597 [Debug] (Stream) age > 0: 46ms, dropping old chunks
2022-08-04 11-01-30.597 [Debug] (Stream) age: 20, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-30.597 [Info] (Stream) Exception: Not enough frames available, requested frames: 3528, available: 264
2022-08-04 11-01-30.597 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.597 [Debug] (Stream) Silent frames: 254, frames: 3528, age: -5.772
2022-08-04 11-01-30.597 [Info] (Stream) Exception: Not enough frames available, requested frames: 3274, available: 1152
2022-08-04 11-01-30.597 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.611 [Debug] (Stream) Silent frames: 764, frames: 3528, age: -17.341
2022-08-04 11-01-30.612 [Info] (Stream) Exception: Not enough frames available, requested frames: 2764, available: 1152
2022-08-04 11-01-30.612 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.613 [Debug] (Stream) Silent frames: 1836, frames: 3528, age: -41.649
2022-08-04 11-01-30.613 [Info] (Stream) Exception: Not enough frames available, requested frames: 1692, available: 1152
2022-08-04 11-01-30.613 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-30.613 [Debug] (Stream) Silent frames: 2976, frames: 3528, age: -67.497
2022-08-04 11-01-30.630 [Debug] (Stats) Chunk: 28	28	28	28	1	66	0
2022-08-04 11-01-31.028 [Debug] (Stats) Chunk: 29	29	29	29	19	65	0
2022-08-04 11-01-32.022 [Debug] (Stats) Chunk: 25	26	27	27	64	67	0
2022-08-04 11-01-33.022 [Debug] (Stats) Chunk: 23	24	26	26	109	64	-3
2022-08-04 11-01-34.018 [Debug] (Stats) Chunk: 16	17	24	25	155	66	-22
2022-08-04 11-01-35.010 [Debug] (Stats) Chunk: 10	11	17	24	200	64	-22
2022-08-04 11-01-36.005 [Debug] (Stats) Chunk: 7	8	10	21	245	65	-22
2022-08-04 11-01-37.013 [Debug] (Stats) Chunk: 0	2	7	17	291	67	-22
2022-08-04 11-01-38.021 [Debug] (Stats) Chunk: -1	0	1	14	337	65	0
2022-08-04 11-01-39.014 [Debug] (Stats) Chunk: -3	-3	0	11	382	64	0
2022-08-04 11-01-40.023 [Debug] (Stats) Chunk: -3	-3	-3	10	428	66	0
2022-08-04 11-01-41.007 [Debug] (Stats) Chunk: -3	-3	-3	8	473	66	6
2022-08-04 11-01-42.004 [Debug] (Stats) Chunk: -2	-2	-3	4	500	66	7
2022-08-04 11-01-43.006 [Debug] (Stats) Chunk: -5	-4	-3	0	500	65	7
2022-08-04 11-01-44.013 [Debug] (Stats) Chunk: -4	-5	-4	-2	500	65	6
2022-08-04 11-01-45.003 [Debug] (Stats) Chunk: -1	-1	-4	-2	500	64	9
2022-08-04 11-01-46.007 [Debug] (Stats) Chunk: -1	-1	-1	-2	500	66	9
2022-08-04 11-01-47.010 [Debug] (Stats) Chunk: -1	-1	-1	-2	500	66	2
2022-08-04 11-01-48.017 [Debug] (Stats) Chunk: 0	0	-1	-2	500	67	1
2022-08-04 11-01-49.011 [Debug] (Stats) Chunk: -4	-3	-1	-2	500	67	2
2022-08-04 11-01-50.009 [Debug] (Stats) Chunk: -4	-5	-4	-3	500	65	2
2022-08-04 11-01-51.007 [Debug] (Stats) Chunk: -1	-1	-4	-2	500	65	10
2022-08-04 11-01-52.022 [Debug] (Stats) Chunk: -1	-1	-1	-2	500	66	9
2022-08-04 11-01-53.012 [Debug] (Stats) Chunk: -2	-2	-1	-2	500	65	2
2022-08-04 11-01-54.025 [Debug] (Stats) Chunk: -3	-3	-2	-2	500	64	2
2022-08-04 11-01-55.019 [Debug] (Stats) Chunk: 0	-1	-3	-1	500	67	5
2022-08-04 11-01-56.018 [Debug] (Stats) Chunk: 0	0	-1	-1	500	65	4
2022-08-04 11-01-57.020 [Debug] (Stats) Chunk: -2	-2	0	-1	500	64	2
2022-08-04 11-01-58.009 [Debug] (Stats) Chunk: -1	-2	-1	-2	500	64	0
2022-08-04 11-01-59.023 [Debug] (Stats) Chunk: -2	-2	-2	-2	500	64	2
2022-08-04 11-01-59.531 [Info] (Stream) Exception: Not enough frames available, requested frames: 1032, available: 96
2022-08-04 11-01-59.531 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.631 [Debug] (Alsa) Waiting for chunk
2022-08-04 11-01-59.738 [Warn] (Alsa) snd_pcm_avail_delay failed: Broken pipe (-32), avail: 1032, delay: 2865, using snd_pcm_avail amd snd_pcm_delay.
2022-08-04 11-01-59.740 [Debug] (Alsa) snd_pcm_avail failed: Broken pipe (-32), using 882
2022-08-04 11-01-59.740 [Debug] (Stream) age > 0: 145ms, dropping old chunks
2022-08-04 11-01-59.740 [Debug] (Stream) age: 146, requested chunk_duration: 20, duration: 26
2022-08-04 11-01-59.740 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.745 [Error] (Alsa) XRUN while waiting for PCM: Broken pipe
2022-08-04 11-01-59.747 [Warn] (Alsa) snd_pcm_avail_delay failed: Input/output error (-5), avail: 882, delay: 213, using snd_pcm_avail amd snd_pcm_delay.
2022-08-04 11-01-59.748 [Debug] (Stream) age > 0: 150ms, dropping old chunks
2022-08-04 11-01-59.749 [Debug] (Stream) age: 124, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-59.749 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.769 [Debug] (Stream) age > 0: 144ms, dropping old chunks
2022-08-04 11-01-59.769 [Debug] (Stream) age: 118, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-59.769 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.771 [Debug] (Stream) age > 0: 120ms, dropping old chunks
2022-08-04 11-01-59.771 [Debug] (Stream) age: 94, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-59.772 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.772 [Debug] (Stream) age > 0: 94ms, dropping old chunks
2022-08-04 11-01-59.772 [Debug] (Stream) age: 68, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-59.772 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.802 [Debug] (Stream) age > 0: 99ms, dropping old chunks
2022-08-04 11-01-59.802 [Debug] (Stream) age: 73, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-59.802 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.803 [Debug] (Stream) age > 0: 74ms, dropping old chunks
2022-08-04 11-01-59.803 [Debug] (Stream) age: 48, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-59.803 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.806 [Debug] (Stream) age > 0: 51ms, dropping old chunks
2022-08-04 11-01-59.806 [Debug] (Stream) age: 25, requested chunk_duration: 80, duration: 26
2022-08-04 11-01-59.807 [Info] (Stream) Exception: Not enough frames available, requested frames: 3528, available: 43
2022-08-04 11-01-59.807 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.807 [Debug] (Stream) Silent frames: 33, frames: 3528, age: -0.763
2022-08-04 11-01-59.807 [Info] (Stream) Exception: Not enough frames available, requested frames: 3495, available: 1152
2022-08-04 11-01-59.807 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.808 [Debug] (Stream) Silent frames: 1108, frames: 3528, age: -25.13
2022-08-04 11-01-59.809 [Info] (Stream) Exception: Not enough frames available, requested frames: 2420, available: 1152
2022-08-04 11-01-59.809 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.809 [Debug] (Stream) Silent frames: 2246, frames: 3528, age: -50.939
2022-08-04 11-01-59.809 [Info] (Stream) Exception: Not enough frames available, requested frames: 1282, available: 1152
2022-08-04 11-01-59.809 [Info] (Alsa) Failed to get chunk
2022-08-04 11-01-59.821 [Debug] (Stream) Silent frames: 2864, frames: 3528, age: -64.954
2022-08-04 11-02-00.013 [Debug] (Stats) Chunk: 30	30	30	30	9	65	3
2022-08-04 11-02-01.021 [Debug] (Stats) Chunk: 24	23	25	25	55	66	0
^C2022-08-04 11-02-01.785 [Info] (Snapclient) Received signal 2: Interrupt
2022-08-04 11-02-01.799 [Debug] (Connection) Disconnecting
2022-08-04 11-02-01.800 [Debug] (Connection) Disconnected
2022-08-04 11-02-01.800 [Notice] (Snapclient) Snapclient terminated.

Aug 04 '22 15:08 jwals23

It turns out (I think) it was actually a WiFi issue. I seem to have eliminated the dropouts by setting buffer = 3000 in the [stream] section of /etc/snapserver.conf. Thanks to https://github.com/badaix/snapcast/issues/774#issuecomment-785906540 for pointing me in the right direction and thanks Johannes for this great piece of software!

Aug 06 '22 16:08 jwals23

snapcast snapcast copied to clipboard

Dropouts on multiple clients with pBuffer->full() && (abs(median_) > 2)

snapcast
snapcast copied to clipboard