Crackles/pops during Spotify streaming on Pi 4

timglong commented 2 years ago

Describe the bug Persistent, regular crackles/pops during Spotify streaming. At first (distracted listening) I thought this was just a transient issue, however listening more closely the crackles/pops are audible at regular intervals in line with the messages in the logs. It unfortunately makes this setup unusable.

I really hope this can be fixed as Snapcast is amazing. I pieced together the below setup from comments in various places and was really pumped when I figured out the last issue (sample rate) and everything started working. Then I noticed the crackles and pops, and so far I haven't been able to figure out how to fix it, so it's back to single room audio for the moment.

Steps to Reproduce

Install Raspotify
Modify /usr/share/alsa/alsa.conf with defaults.ctl.card 1 and defaults.pcm.card 1 to enable USB DAC output
Set up watchdog.sh, this checks for Raspotify errors and runs systemctl restart raspotify if there are any errors (https://gist.github.com/JeremieRapin/bc35a2632c072a082d48f5503270df16)
Plug in your USB DAC (Schiit Modi 3+ and Topping D10s in my setup)
Use BACKEND_ARGS="--backend pipe --device /tmp/snapfifo" in /etc/default/raspotify
Install Snapserver
Use source = pipe:///tmp/snapfifo?name=default&sampleformat=44100:16:2 in /etc/snapserver.conf
Install Snapclient on your client(s), in my case PiOffice and PiDining
Use SNAPCLIENT_OPTS="-s 7" (in my case) in /etc/default/snapclient to specify output to USB DACs

Environment details

OS: Raspberry Pi OS Lite
Clients: Raspberry Pi 4 2GB
Server: Raspberry Pi 4 4GB/Raspberry Pi 4 2GB
Snapcast version 0.25.0
Snapcast installed from snapclient_0.25.0-1_without-pulse_armhf.deb and snapserver_0.25.0-1_armhf.deb
Raspotify version 0.16.0

Attempted Fixes/Notes

Bluetooth is disabled on both clients
PiOffice (server + client) is connected via Ethernet and WiFi is disabled
PiDining (client) is connected via WiFi
Pulseaudio is not installed on either PiOffice or PiDining
After noticing consistent WARN messages in librespot/Raspotify, I disabled volume normalization (didn't want this anyway!)
After noticing consistent WARN messages in librespot/Raspotify, I logged all clients into Spotify and disabled discovery to avoid any issues with mDNS and unbound
There are currently no errors in librespot/Raspotify
After initially installing Snapserver on a different Pi running Pi-hole, Unbound, and Steam Link (connected via Ethernet, WiFi disabled, Bluetooth enabled, Pulseaudio installed), I moved Snapserver to PiOffice; this had no impact
Raspotify works perfectly when not using Snapserver/Snapclient
PiOffice and PiDining are dedicated streamers, Raspotify and Snapcast/Snapclient are the only things installed after installing Raspberry Pi OS Lite
I disabled watchdog.sh to see if that might help, no change

Client debug log:

pi@PiOffice:~ $ snapclient --logfilter *:debug -s 7
2021-08-04 17-58-03.156 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: 7
2021-08-04 17-58-03.207 [Info] (Snapclient) Version 0.25.0, revision 2af5292f
2021-08-04 17-58-03.215 [Info] (Avahi) (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
2021-08-04 17-58-03.217 [Info] (Avahi) (Browser) CACHE_EXHAUSTED
2021-08-04 17-58-03.217 [Info] (Avahi) Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
2021-08-04 17-58-03.217 [Info] (Avahi)  PiOffice.local:1704 (192.168.xxx.xx)
2021-08-04 17-58-03.217 [Debug] (Avahi)         TXT=
2021-08-04 17-58-03.217 [Debug] (Avahi)         Proto=0
2021-08-04 17-58-03.217 [Debug] (Avahi)         cookie is 0
2021-08-04 17-58-03.217 [Debug] (Avahi)         is_local: 1
2021-08-04 17-58-03.217 [Debug] (Avahi)         our_own: 0
2021-08-04 17-58-03.217 [Debug] (Avahi)         wide_area: 0
2021-08-04 17-58-03.217 [Debug] (Avahi)         multicast: 1
2021-08-04 17-58-03.217 [Debug] (Avahi)         cached: 1
2021-08-04 17-58-03.219 [Info] (Controller) Found server 192.168.xxx.xx:1704
2021-08-04 17-58-03.219 [Info] (Connection) Resolving host IP for: 192.168.xxx.xx
2021-08-04 17-58-03.219 [Info] (Connection) Connecting
2021-08-04 17-58-03.220 [Notice] (Connection) Connected to 192.168.xxx.xx
2021-08-04 17-58-03.220 [Info] (Connection) My MAC: "xx:xx:xx:xx:xx:xx", socket: 8
2021-08-04 17-58-03.355 [Debug] (Connection) outstanding async_write
2021-08-04 17-58-03.357 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
metadata:{"STREAM":"default"}
2021-08-04 17-58-03.357 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-08-04 17-58-03.357 [Info] (Player) Player name: alsa, device: default:CARD=D10s, description: D10s, USB Audio
2021-08-04 17-58-03.357 [Info] (Player) Default Audio Device, idx: 7, sharing mode: unspecified, parameters: <none>
2021-08-04 17-58-03.357 [Info] (Player) Mixer mode: software, parameters: <none>
2021-08-04 17-58-03.357 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-08-04 17-58-03.357 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2021-08-04 17-58-03.366 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-08-04 17-58-03.366 [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
2021-08-04 17-58-03.366 [Debug] (Alsa) SUBFORMAT:  STD
2021-08-04 17-58-03.366 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-08-04 17-58-03.366 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-08-04 17-58-03.366 [Debug] (Alsa) CHANNELS: [1 10000]
2021-08-04 17-58-03.366 [Debug] (Alsa) RATE: [4000 4294967295)
2021-08-04 17-58-03.366 [Debug] (Alsa) PERIOD_TIME: (21333 21334)
2021-08-04 17-58-03.366 [Debug] (Alsa) PERIOD_SIZE: (85 91628833)
2021-08-04 17-58-03.366 [Debug] (Alsa) PERIOD_BYTES: (42 4294967295)
2021-08-04 17-58-03.366 [Debug] (Alsa) PERIODS: (0 17247242)
2021-08-04 17-58-03.366 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-08-04 17-58-03.366 [Debug] (Alsa) BUFFER_SIZE: [170 1466015503]
2021-08-04 17-58-03.366 [Debug] (Alsa) BUFFER_BYTES: [85 4294967295]
2021-08-04 17-58-03.366 [Debug] (Alsa) TICK_TIME: ALL
2021-08-04 17-58-03.366 [Info] (Alsa) Period time too small, changing from 20000 to 21333
2021-08-04 17-58-03.367 [Info] (Alsa) PCM name: default:CARD=D10s, sample rate: 44100 Hz, channels: 2, buffer time: 85328 us, periods: 4, period time: 21333 us, period frames: 940
2021-08-04 17-58-03.367 [Debug] (Player) setVolume exp with base 10: 1 => 1
2021-08-04 17-58-03.367 [Debug] (Alsa) Resizing buffer from 0 to 15052
2021-08-04 17-58-03.367 [Info] (Stream) No chunks available
2021-08-04 17-58-03.367 [Info] (Alsa) Failed to get chunk
2021-08-04 17-58-03.387 [Info] (Controller) diff to server [ms]: 0.01
2021-08-04 17-58-04.242 [Debug] (Stream) Silent frames: 767, frames: 942, age: -17.404
2021-08-04 17-58-04.263 [Debug] (Stats) Chunk: 0        0       0       0       1       63      0
2021-08-04 17-58-05.010 [Debug] (Stats) Chunk: 6        5       3       3       36      64      0
2021-08-04 17-58-06.013 [Debug] (Stats) Chunk: 15       13      8       8       82      63      0
2021-08-04 17-58-07.015 [Debug] (Stats) Chunk: 21       20      15      12      129     63      -10
2021-08-04 17-58-08.018 [Debug] (Stats) Chunk: 25       24      21      16      176     64      -22
2021-08-04 17-58-09.021 [Debug] (Stats) Chunk: 28       28      25      20      223     63      -22
2021-08-04 17-58-10.002 [Debug] (Stats) Chunk: 32       31      28      22      269     64      -22
2021-08-04 17-58-11.005 [Debug] (Stats) Chunk: 35       35      32      24      316     63      -22
2021-08-04 17-58-12.008 [Debug] (Stats) Chunk: 39       38      35      25      363     63      -22
2021-08-04 17-58-13.010 [Debug] (Stats) Chunk: 42       42      39      27      410     64      -22
2021-08-04 17-58-14.013 [Debug] (Stats) Chunk: 46       45      43      29      457     63      -22
2021-08-04 17-58-14.951 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2949
2021-08-04 17-58-14.973 [Debug] (Stream) age > 0: 5ms, dropping old chunks
2021-08-04 17-58-14.973 [Debug] (Stream) age: 3, requested chunk_duration: 21, duration: 26
2021-08-04 17-58-15.015 [Debug] (Stats) Chunk: 0        0       0       0       2       63      -21
2021-08-04 17-58-16.018 [Debug] (Stats) Chunk: 7        6       3       3       49      64      0
2021-08-04 17-58-17.021 [Debug] (Stats) Chunk: 16       15      7       7       96      63      0
2021-08-04 17-58-18.002 [Debug] (Stats) Chunk: 21       21      16      12      142     64      -13
2021-08-04 17-58-19.005 [Debug] (Stats) Chunk: 26       25      22      16      189     63      -22
2021-08-04 17-58-20.008 [Debug] (Stats) Chunk: 29       28      26      19      236     63      -22
2021-08-04 17-58-21.010 [Debug] (Stats) Chunk: 32       32      29      22      283     64      -23
2021-08-04 17-58-22.013 [Debug] (Stats) Chunk: 36       35      32      24      330     63      -22
2021-08-04 17-58-23.016 [Debug] (Stats) Chunk: 39       39      36      26      377     63      -22
2021-08-04 17-58-24.018 [Debug] (Stats) Chunk: 43       43      39      27      424     64      -22
2021-08-04 17-58-25.000 [Debug] (Stats) Chunk: 47       46      43      29      470     63      -21
2021-08-04 17-58-25.661 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2961
2021-08-04 17-58-25.682 [Debug] (Stream) age > 0: 5ms, dropping old chunks
2021-08-04 17-58-25.682 [Debug] (Stream) age: 2, requested chunk_duration: 21, duration: 26
2021-08-04 17-58-26.002 [Debug] (Stats) Chunk: 1        0       0       0       15      64      -15
2021-08-04 17-58-27.005 [Debug] (Stats) Chunk: 9        8       4       4       62      63      0
2021-08-04 17-58-28.008 [Debug] (Stats) Chunk: 17       16      9       8       109     63      -1
2021-08-04 17-58-29.010 [Debug] (Stats) Chunk: 23       21      18      13      156     64      -21
2021-08-04 17-58-30.013 [Debug] (Stats) Chunk: 25       25      22      17      203     63      -22
2021-08-04 17-58-31.016 [Debug] (Stats) Chunk: 29       28      25      19      250     63      -22
2021-08-04 17-58-32.018 [Debug] (Stats) Chunk: 33       32      29      21      297     64      -22
2021-08-04 17-58-33.000 [Debug] (Stats) Chunk: 36       35      32      23      343     63      -22
2021-08-04 17-58-34.003 [Debug] (Stats) Chunk: 41       39      36      25      390     64      -22
2021-08-04 17-58-35.005 [Debug] (Stats) Chunk: 43       43      40      27      437     63      -22
2021-08-04 17-58-36.008 [Debug] (Stats) Chunk: 47       46      43      29      484     63      -22
2021-08-04 17-58-36.370 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2915
2021-08-04 17-58-36.392 [Debug] (Stream) age > 0: 4ms, dropping old chunks
2021-08-04 17-58-36.392 [Debug] (Stream) age: 1, requested chunk_duration: 21, duration: 26
2021-08-04 17-58-37.010 [Debug] (Stats) Chunk: 5        2       2       2       29      64      -8
2021-08-04 17-58-38.013 [Debug] (Stats) Chunk: 12       11      5       5       76      63      0
2021-08-04 17-58-39.016 [Debug] (Stats) Chunk: 20       19      12      10      123     63      -5
2021-08-04 17-58-40.019 [Debug] (Stats) Chunk: 25       23      20      15      170     64      -23
2021-08-04 17-58-41.000 [Debug] (Stats) Chunk: 27       26      23      18      216     63      -21
2021-08-04 17-58-42.003 [Debug] (Stats) Chunk: 32       30      27      21      263     64      -22
2021-08-04 17-58-43.005 [Debug] (Stats) Chunk: 34       34      31      23      310     63      -22
2021-08-04 17-58-44.008 [Debug] (Stats) Chunk: 38       37      34      24      357     63      -22
2021-08-04 17-58-45.011 [Debug] (Stats) Chunk: 43       41      38      26      404     64      -23
2021-08-04 17-58-46.013 [Debug] (Stats) Chunk: 45       45      41      28      451     63      -22
2021-08-04 17-58-47.016 [Debug] (Stats) Chunk: 49       48      45      30      498     63      -22
2021-08-04 17-58-47.080 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 3020
2021-08-04 17-58-47.101 [Debug] (Stream) age > 0: 4ms, dropping old chunks
2021-08-04 17-58-47.102 [Debug] (Stream) age: 1, requested chunk_duration: 21, duration: 26
2021-08-04 17-58-48.019 [Debug] (Stats) Chunk: 0        -1      -4      -4      43      64      -1
2021-08-04 17-58-49.000 [Debug] (Stats) Chunk: 7        6       0       0       88      63      0
2021-08-04 17-58-50.003 [Debug] (Stats) Chunk: 17       15      7       4       135     64      0
2021-08-04 17-58-51.005 [Debug] (Stats) Chunk: 21       21      16      8       182     63      -15
2021-08-04 17-58-52.008 [Debug] (Stats) Chunk: 25       24      21      12      229     63      -22
2021-08-04 17-58-53.011 [Debug] (Stats) Chunk: 30       28      25      17      276     64      -23
2021-08-04 17-58-54.013 [Debug] (Stats) Chunk: 32       32      29      20      323     63      -22
2021-08-04 17-58-55.016 [Debug] (Stats) Chunk: 36       35      32      22      370     63      -22
2021-08-04 17-58-56.019 [Debug] (Stats) Chunk: 41       39      36      24      417     64      -22
2021-08-04 17-58-57.000 [Debug] (Stats) Chunk: 43       42      39      26      463     64      -21
2021-08-04 17-58-57.811 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2622
2021-08-04 17-58-57.832 [Debug] (Stream) age > 0: 4ms, dropping old chunks
2021-08-04 17-58-57.832 [Debug] (Stream) age: -4, requested chunk_duration: 21, duration: 26
2021-08-04 17-58-57.833 [Debug] (Stream) Silent frames: 179, frames: 937, age: -4.06
2021-08-04 17-58-58.003 [Debug] (Stats) Chunk: -3       -4      -4      -4      8       64      -18
2021-08-04 17-58-59.005 [Debug] (Stats) Chunk: 3        2       0       0       55      63      0
2021-08-04 17-59-00.008 [Debug] (Stats) Chunk: 12       11      3       3       102     64      0
2021-08-04 17-59-01.011 [Debug] (Stats) Chunk: 21       19      12      8       149     64      -6
2021-08-04 17-59-02.013 [Debug] (Stats) Chunk: 23       22      19      12      196     63      -24
2021-08-04 17-59-03.016 [Debug] (Stats) Chunk: 26       26      23      16      243     64      -22
^C
2021-08-04 17-59-03.096 [Info] (Snapclient) Received signal 2: Interrupt
2021-08-04 17-59-03.133 [Debug] (Connection) Disconnecting
2021-08-04 17-59-03.134 [Debug] (Connection) Disconnected
2021-08-04 17-59-03.134 [Notice] (Snapclient) Snapclient terminated.

Snapserver debug log:

pi@PiOffice:~ $ snapserver --logfilter *:debug
2021-08-04 17-50-22.088 [Info] (Snapserver) Version 0.25.0, revision 2af5292f
2021-08-04 17-50-22.088 [Info] (Snapserver) Adding source: pipe:///tmp/snapfifo?name=default&sampleformat=44100:16:2
2021-08-04 17-50-22.088 [Notice] (init) Settings file: "/home/pi/.config/snapserver/server.json"
2021-08-04 17-50-22.093 [Info] (Avahi) Adding service 'Snapcast'
2021-08-04 17-50-22.097 [Info] (PcmStream) PcmStream: default, sampleFormat: 44100:16:2
2021-08-04 17-50-22.097 [Info] (PcmStream) Stream: default, metadata={
2021-08-04 17-50-22.097 [Info] (PcmStream)     "STREAM": "default"
2021-08-04 17-50-22.097 [Info] (PcmStream) }
2021-08-04 17-50-22.097 [Info] (Server) onMetaChanged (default)
2021-08-04 17-50-22.097 [Info] (PipeStream) PipeStream mode: create
2021-08-04 17-50-22.097 [Info] (Server) Stream: {"fragment":"","host":"","path":"/tmp/snapfifo","query":{"chunk_ms":"20","codec":"flac",                                                                                                     "name":"default","sampleformat":"44100:16:2"},"raw":"pipe:////tmp/snapfifo?chunk_ms=20&codec=flac&name=default&sampleformat=44100:16:2",                                                                                                     "scheme":"pipe"}
2021-08-04 17-50-22.097 [Info] (FlacEnc) Init - compression level: 2
2021-08-04 17-50-22.098 [Info] (ControlServer) Creating TCP acceptor for address: 0.0.0.0, port: 1705
2021-08-04 17-50-22.098 [Info] (ControlServer) Creating HTTP acceptor for address: 0.0.0.0, port: 1780
2021-08-04 17-50-22.098 [Info] (StreamServer) Creating stream acceptor for address: 0.0.0.0, port: 1704
2021-08-04 17-50-22.098 [Info] (Snapserver) Number of threads: 4, hw threads: 4
2021-08-04 17-50-22.297 [Notice] (StreamServer) StreamServer::NewConnection: 192.168.xxx.xx
2021-08-04 17-50-22.303 [Info] (Server) Hello from xx:xx:xx:xx:xx:xx, host: PiOffice, v0.25.0, ClientName: Snapclient, OS: Raspbian GNU/                                                                                                     Linux 10 (buster), Arch: armv7l, Protocol version: 2
2021-08-04 17-50-22.322 [Notice] (StreamServer) StreamServer::NewConnection: 192.168.xxx.xx
2021-08-04 17-50-22.337 [Info] (Server) Hello from xx:xx:xx:xx:xx:xx, host: PiDining, v0.25.0, ClientName: Snapclient, OS: Raspbian GNU/                                                                                                     Linux 10 (buster), Arch: armv7l, Protocol version: 2
2021-08-04 17-50-22.618 [Info] (PcmStream) State changed: default, state: idle => playing
2021-08-04 17-50-22.618 [Info] (Server) onStateChanged (default): playing
2021-08-04 17-50-23.148 [Info] (Avahi) Service 'Snapcast' successfully established.

PiOffice Syslog

Aug  2 19:37:48 PiDining snapclient[405]: Period time too small, changing from 20000 to 21333
Aug  2 19:37:48 PiDining snapclient[405]: PCM name: default:CARD=S3, sample rate: 44100 Hz, channels: 2, buffer time: 85328 us, periods: 4, period time: 21333 us, period frames: 940
Aug  2 19:37:59 PiDining snapclient[405]: pBuffer->full() && (abs(median_) > 2): 2969
Aug  2 19:38:10 PiDining snapclient[405]: pBuffer->full() && (abs(median_) > 2): 2979
Aug  2 19:38:21 PiDining snapclient[405]: pBuffer->full() && (abs(median_) > 2): 2871

PiOffice Syslog

Aug  2 19:37:48 PiOffice snapclient[380]: Period time too small, changing from 20000 to 21333
Aug  2 19:37:48 PiOffice snapclient[380]: PCM name: default:CARD=D10s, sample rate: 44100 Hz, channels: 2, buffer time: 85328 us, periods: 4, period time: 21333 us, period frames: 940
Aug  2 19:37:59 PiOffice snapclient[380]: pBuffer->full() && (abs(median_) > 2): 3003
Aug  2 19:38:10 PiOffice snapclient[380]: pBuffer->full() && (abs(median_) > 2): 3022
Aug  2 19:38:21 PiOffice snapclient[380]: pBuffer->full() && (abs(median_) > 2): 2971

Syslog Notes The pBuffer->full() && (abs(median_) > 2): messages continue as long as Spotify is streaming.

timglong commented 2 years ago

I swear I searched for pBuffer->full() && (abs(median_) > 2) in issues but somehow I missed #781 ...

--sampleformat 48000:16:* fixed the issue and I'm back in multi-room business.

Thanks for this fantastic software and all your efforts!

Edit for posterity, this is the exact configuration I'm now using in /etc/default/snapclient

# Start the client, used only by the init.d script
START_SNAPCLIENT=true

# Additional command line options that will be passed to snapclient
# note that user/group should be configured in the init.d script or the systemd unit file
# For a list of available options, invoke "snapclient --help"
SNAPCLIENT_OPTS="-s 7 --sampleformat 48000:16:*"

c-MM commented 2 years ago

I also struggled with this problem for two days until I found the solution in https://github.com/badaix/snapcast/discussions/949#discussioncomment-1941407.

The main thing seems to be which device get's picked by snapclient. If the output from snapclient contains something like:

(Alsa) PCM name: hw:CARD=CODEC,DEV=0

or

(Alsa) PCM name: hw:CARD=U0x41e0x30d3,DEV=0

It works for me. If the

,DEV=X

part is missing, I get the sound dropouts and messages from the client.

Maybe it would be possible for snapclient to try to pick a device with a DEV= extension or it might make sense to put a hint on it in the message. Here you can see the difference on the builtin sounddevice of my libreelec system:

2022-01-11 00-43-03.843 [Info] (Player) Player name: alsa, device: sysdefault:CARD=PCH, description: HDA Intel PCH, ALC892 Analog
2022-01-11 00-43-03.843 [Info] (Player) Default Audio Device, idx: 7, sharing mode: unspecified, parameters: <none>
2022-01-11 00-43-03.843 [Info] (Player) Mixer mode: software, parameters: <none>
2022-01-11 00-43-03.843 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2022-01-11 00-43-03.844 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2022-01-11 00-43-03.846 [Info] (Alsa) Period time too small, changing from 20000 to 21333
2022-01-11 00-43-03.847 [Info] (Alsa) PCM name: sysdefault:CARD=PCH, sample rate: 44100 Hz, channels: 2, buffer time: 85328 us, periods: 4, period time: 21333 us, period frames: 940
2022-01-11 00-43-03.847 [Info] (Stream) No chunks available
2022-01-11 00-43-03.847 [Info] (Alsa) Failed to get chunk
2022-01-11 00-43-04.082 [Info] (Controller) diff to server [ms]: 2.68904e+08
2022-01-11 00-43-15.451 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2314
2022-01-11 00-43-26.159 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2243
2022-01-11 00-43-36.867 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2215
2022-01-11 00-43-47.575 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2323

and

2022-01-11 00-45-43.363 [Info] (Player) Player name: alsa, device: front:CARD=PCH,DEV=0, description: HDA Intel PCH, ALC892 Analog
2022-01-11 00-45-43.363 [Info] (Player) Front output / input, idx: 8, sharing mode: unspecified, parameters: <none>
2022-01-11 00-45-43.363 [Info] (Player) Mixer mode: software, parameters: <none>
2022-01-11 00-45-43.363 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2022-01-11 00-45-43.363 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2022-01-11 00-45-43.385 [Info] (Alsa) PCM name: front:CARD=PCH,DEV=0, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
2022-01-11 00-45-43.385 [Info] (Stream) No chunks available
2022-01-11 00-45-43.385 [Info] (Alsa) Failed to get chunk
2022-01-11 00-45-43.487 [Info] (Controller) diff to server [ms]: 2.68904e+08

In case of soundcard index 8 with the DEV=0 no errors get logged and no dropouts in sound.

ettom commented 1 year ago

Had the same problem and this fixed it, but using a card with the DEV=0 part seems to disable dmix. I needed dmix to work as I wanted programs besides snapclient to be able to output simultaneously. I also wanted to avoid pointless resampling to 48kHz. This asound.conf seems to be working for me:

pcm.dmix0 {
  type dmix
  ipc_key 1024          # Any unique value
  ipc_key_add_uid false # Let multiple users share
  ipc_perm 0666         # IPC permissions for multi-user sharing (octal, default 0600)
  slave {
    pcm "hw:1,0"
    rate 44100
  }
}

pcm.dsp0 {
  type plug
  slave.pcm "dmix0"
}

Run snapclient with -s dsp0.

badaix / snapcast

Crackles/pops during Spotify streaming on Pi 4 #898