Repeating dropouts on 2 different clients at 44100

[thanxx]

Hi,
I am asking for help in resolving the issue.
I have a snapserver with the following config:

source = pipe:///tmp/snapfifo?name=spotify&sampleformat=44100:16:2
source = pipe:///tmp/mopidyfifo?name=mopidy&sampleformat=44100:16:2

And I have clients, two of them have the following problem: the audio clicks every 10 seconds or so.
One device is a router with OpenWrt + USB sound, the other is a TV box running Ubuntu + USB card. Both running client v25. (I tried also 19 and 20 with the same result).
Here's what is interesting: the issue is gone when I change to 48000. But I can't switch to 48000 because librespot/spocon plays only at 44100. Android clients also play without issues at both rates.

I see no errors in the server log.

Here's debug output from the client.
When I hear clicks I see these lines repeating

2021-12-04 18-07-46.509 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2670
2021-12-04 18-07-46.531 [Debug] (Stream) age > 0: 4ms, dropping old chunks
2021-12-04 18-07-46.533 [Debug] (Stream) age: -7, requested chunk_duration: 21, duration: 26
2021-12-04 18-07-46.536 [Debug] (Stream) Silent frames: 316, frames: 969, age: -7.179

Full log:

root@LEDE:~# snapclient -h 192.168.1.167  --logfilter *:debug
2021-12-04 18-07-34.475 [Debug] (Snapclient) Trying to get PCM device for player: alsa, parameter: , card: default
2021-12-04 18-07-34.841 [Info] (Snapclient) Version 0.25.0
2021-12-04 18-07-34.843 [Info] (Connection) Resolving host IP for: 192.168.1.167
2021-12-04 18-07-34.845 [Info] (Connection) Connecting
2021-12-04 18-07-34.848 [Notice] (Connection) Connected to 192.168.1.167
2021-12-04 18-07-34.851 [Info] (Connection) My MAC: "", socket: 7
2021-12-04 18-07-34.908 [Debug] (Connection) outstanding async_write
2021-12-04 18-07-34.914 [Info] (Controller) ServerSettings - buffer: 1000, latency: 0, volume: 96, muted: 0
metadata:{"STREAM":"spotify"}
2021-12-04 18-07-34.919 [Info] (Controller) Codec: flac, sampleformat: 44100:16:2
2021-12-04 18-07-34.921 [Info] (Player) Player name: alsa, device: default, description: Default Audio Device, idx: 0, sharing mode: unspecified, parameters: <none>
2021-12-04 18-07-34.924 [Info] (Player) Mixer mode: software, parameters: <none>
2021-12-04 18-07-34.926 [Info] (Player) Sampleformat: 44100:16:2, stream: 44100:16:2
2021-12-04 18-07-34.928 [Info] (Alsa) Using default buffer_time: 80 ms, default fragments: 4
2021-12-04 18-07-34.991 [Debug] (Alsa) ACCESS:  MMAP_INTERLEAVED MMAP_NONINTERLEAVED MMAP_COMPLEX RW_INTERLEAVED RW_NONINTERLEAVED
2021-12-04 18-07-34.991 [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-12-04 18-07-34.991 [Debug] (Alsa) SUBFORMAT:  STD
2021-12-04 18-07-34.991 [Debug] (Alsa) SAMPLE_BITS: [4 64]
2021-12-04 18-07-34.991 [Debug] (Alsa) FRAME_BITS: [4 640000]
2021-12-04 18-07-34.991 [Debug] (Alsa) CHANNELS: [1 10000]
2021-12-04 18-07-34.991 [Debug] (Alsa) RATE: [4000 4294967295)
2021-12-04 18-07-34.991 [Debug] (Alsa) PERIOD_TIME: (21333 21334)
2021-12-04 18-07-34.991 [Debug] (Alsa) PERIOD_SIZE: (85 91628833)
2021-12-04 18-07-34.991 [Debug] (Alsa) PERIOD_BYTES: (42 4294967295)
2021-12-04 18-07-34.991 [Debug] (Alsa) PERIODS: (0 17247242)
2021-12-04 18-07-34.991 [Debug] (Alsa) BUFFER_TIME: [1 4294967295]
2021-12-04 18-07-34.991 [Debug] (Alsa) BUFFER_SIZE: [170 1466015503]
2021-12-04 18-07-34.991 [Debug] (Alsa) BUFFER_BYTES: [85 4294967295]
2021-12-04 18-07-34.991 [Debug] (Alsa) TICK_TIME: ALL
2021-12-04 18-07-35.028 [Info] (Alsa) Period time too small, changing from 20000 to 21333
2021-12-04 18-07-35.033 [Info] (Alsa) PCM name: default, sample rate: 44100 Hz, channels: 2, buffer time: 85328 us, periods: 4, period time: 21333 us, period frames: 940
2021-12-04 18-07-35.037 [Debug] (Player) setVolume exp with base 10: 0.96 => 0.902234
2021-12-04 18-07-35.050 [Debug] (Alsa) Resizing buffer from 0 to 15052
2021-12-04 18-07-35.292 [Info] (Controller) diff to server [ms]: -4.17616e+07
2021-12-04 18-07-35.822 [Debug] (Stream) Silent frames: 310, frames: 925, age: -7.044
2021-12-04 18-07-35.843 [Debug] (Stats) Chunk: -9       -9      -9      -9      1       63      0
2021-12-04 18-07-36.013 [Debug] (Stats) Chunk: -8       -9      -9      -9      9       64      0
2021-12-04 18-07-37.016 [Debug] (Stats) Chunk: 0        -1      -3      -3      56      64      0
2021-12-04 18-07-38.020 [Debug] (Stats) Chunk: 8        7       0       0       103     63      0
2021-12-04 18-07-39.003 [Debug] (Stats) Chunk: 42       16      9       4       149     64      0
2021-12-04 18-07-40.004 [Debug] (Stats) Chunk: 21       20      17      9       196     63      -19
2021-12-04 18-07-41.006 [Debug] (Stats) Chunk: 24       24      21      14      243     64      -22
2021-12-04 18-07-42.012 [Debug] (Stats) Chunk: 28       28      25      18      290     64      -22
2021-12-04 18-07-43.012 [Debug] (Stats) Chunk: 32       31      29      20      337     63      -22
2021-12-04 18-07-44.015 [Debug] (Stats) Chunk: 35       35      32      22      384     64      -22
2021-12-04 18-07-45.018 [Debug] (Stats) Chunk: 39       38      36      24      431     64      -22
2021-12-04 18-07-46.025 [Debug] (Stats) Chunk: 42       42      40      26      478     63      -23
2021-12-04 18-07-46.509 [Info] (Stream) pBuffer->full() && (abs(median_) > 2): 2670
2021-12-04 18-07-46.531 [Debug] (Stream) age > 0: 4ms, dropping old chunks
2021-12-04 18-07-46.533 [Debug] (Stream) age: -7, requested chunk_duration: 21, duration: 26
2021-12-04 18-07-46.536 [Debug] (Stream) Silent frames: 316, frames: 969, age: -7.179
2021-12-04 18-07-47.003 [Debug] (Stats) Chunk: 13       -17     -17     -17     22      64      -10
2021-12-04 18-07-48.003 [Debug] (Stats) Chunk: -7       -8      -12     -12     69      63      0
2021-12-04 18-07-49.006 [Debug] (Stats) Chunk: 1        0       -6      -8      116     64      2

[thanxx]

turns out it's not related to Snapcast.
the problem is gone when I changed alsa device index

[c-MM]

Hi, thanks for posting th discussion. I'm stuck with the same problem.

I use 44100:16:2 on the snapserver fed from mpd via /tmp/snapfifo since most of my Music is from CDs I own in flac 44100 samplerate.
I have snapclients on Kodi, Debian Desktop and the server that is also running snapserver. These clients work flawless.

But trying to use snapclients on an OpenWRT AP and on an raspberry Pi zero W both with an USB soundcard (Behringer UCA202 Burr-Brown PCM2902 chip), I get the above message every 9-11 seconds and small dropout ins sound. When I plug the soundcard into my Laptop it works fine.

What card index are you using to get it working?

[thanxx]

Hi,
looks like I use the similar USB card,
I use 12th index, but please note this is optical out

12: iec958:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
IEC958 (S/PDIF) Digital Audio Output

[c-MM]

Thanks so much!

The alsa installation on openwrt 21.02 gives me 12 indexes for this card:

root@OpenWrt:~# snapclient -l
0: null
Discard all samples (playback) or generate zero samples (capture)

1: default
Default Audio Device

2: sysdefault
Default Audio Device

3: default:CARD=CODEC
USB Audio CODEC, USB Audio
Default Audio Device

4: sysdefault:CARD=CODEC
USB Audio CODEC, USB Audio
Default Audio Device

5: front:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
Front output / input

6: surround21:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
2.1 Surround output to Front and Subwoofer speakers

7: surround40:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
4.0 Surround output to Front and Rear speakers

8: surround41:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
4.1 Surround output to Front, Rear and Subwoofer speakers

9: surround50:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
5.0 Surround output to Front, Center and Rear speakers

10: surround51:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
5.1 Surround output to Front, Center, Rear and Subwoofer speakers

11: surround71:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
7.1 Surround output to Front, Center, Side, Rear and Woofer speakers

12: iec958:CARD=CODEC,DEV=0
USB Audio CODEC, USB Audio
IEC958 (S/PDIF) Digital Audio Output

Index 1,2,3 and 4 give me the buffer errors.
Index 6, 8, 9, 10 and 11 give an error from snapclient: [Fatal] (Snapclient) Exception: Can't fill params: Invalid argument
Index 5,7 and 12 work flawlessly, providing sound to cinch and headphone outputs (I can't test SPDIF).

I hope this information helps someone in the future. I struggled with this for 2 days, compiling different versions of snapclient for openwrt.

Thanks to badaix for this wonderfull piece of software, I discovered just a couple of days ago!