Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

dropouts on 1 of 2 almost identical rpi3 clients, none on any other clients #765

Closed
lucianm opened this issue Jan 6, 2021 · 5 comments
Closed

Comments

@lucianm
Copy link

lucianm commented Jan 6, 2021

Hi there, a Happy New Year!

After finally getting around to send back my then (#573) faulty, randomly loudly popping HifiBerry AMP2 and getting 2 brand new replacements and another new RPI3 just few days ago, I reactivated and updated my kitchen client and built an identical one for my home office room.

The only differences between them is that the kitchen one was updated to DietPi v6.34.3 with snapclient 0.22 and is hooked up to my LAN via WiFi and the all new office client has a brand new DietPi DietPi v6.34.3 installation which I tried to configure the same as the kitchen one and is hooked up to the LAN over Gigabit Ethernet. Initially it used the same snapclient version 0.22, now I'm also trying with the development version from Actions (0.23, unfortunately pulling in like 17 new dependencies, some of which are X11-related), but on this one, hooked over Ethernet, I'm getting annoying audio dropouts, sometimes like 2 within a minute, but mostly just several minutes apart, and it feels like the development version handles this a bit better, while on the kitchen client hooked up over WiFi I do not get them at all, even with 0.22. Also, I did not hear them on any other clients, like a debian x64 client running on the OMV NAS on which also the server runs, on Android / Snap.NET / Snap.Web or two CoreELEC / OdroidN2 clients hooked to TVs, of which all of them are connected via Gigabit LAN, except the Android Smartphones or a Tablet also.

It also makes no difference if the stream is LibreSpot or Mopidy. Because of LibreSpot, I configured my streams and audio outputs to 44100:16:2 sampling.

Log from the kitchen client, with everything ok:

Please observe the output about PCM name and also PCM state: PREPARED. Other than that, the log goes on and on the same, all good:

Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: (Browser) CACHE_EXHAUSTED
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         nas-omv.local:1704 (192.168.177.41)
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         TXT=
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         Proto=0
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         cookie is 0
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         is_local: 0
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         our_own: 0
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         wide_area: 0
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         multicast: 1
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]:         cached: 1
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Found server 192.168.177.41:1704
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Resolving host IP for: 192.168.177.41
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Connecting
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Connected to 192.168.177.41
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: My MAC: "b8:27:eb:39:8a:25", socket: 8
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: outstanding async_write
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: ServerSettings - buffer: 1000, latency: 0, volume: 70, muted: 0
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: metadata:{"STREAM":"Lucian_Librespot"}
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Codec: flac, sampleformat: 44100:16:2
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Player name: alsa, device: sysdefault:CARD=sndrpihifiberry, description: snd_rpi_hifiberry_dacplus, HiFiBerry DAC+ HiFi pcm512x-hifi-0
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Mixer mode: software, parameters: <none>
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Sampleformat: 44100:16:2, stream: 44100:16:2
Jan 06 12:07:44 DietPi-Kitchen kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: PCM name: sysdefault:CARD=sndrpihifiberry
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: PCM state: PREPARED
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: channels: 2
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: rate: 44100 bps
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: frames: 662
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: period time: 15011
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Resizing buffer from 0 to 10592
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: setVolume exp with base 10: 0.7 => 0.445764
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: no chunks available
Jan 06 12:07:44 DietPi-Kitchen snapclient[852]: Failed to get chunk
Jan 06 12:07:45 DietPi-Kitchen snapclient[852]: diff to server [ms]: 2.39947e+09
Jan 06 12:07:45 DietPi-Kitchen snapclient[852]: Silent frames: 511, frames: 1320, age: -11.599
Jan 06 12:07:45 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        1        44        0
Jan 06 12:07:46 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        9        30        0
Jan 06 12:07:47 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        59        44        0
Jan 06 12:07:48 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        108        44        0
Jan 06 12:07:49 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        159        30        0
Jan 06 12:07:50 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        208        44        0
Jan 06 12:07:51 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        258        30        0
Jan 06 12:07:52 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        309        30        0
Jan 06 12:07:53 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        358        44        0
Jan 06 12:07:54 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        408        30        0
Jan 06 12:07:55 DietPi-Kitchen snapclient[852]: Chunk: -1        0        0        0        458        44        0
Jan 06 12:07:56 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        44        0
Jan 06 12:07:57 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:07:58 DietPi-Kitchen snapclient[852]: Chunk: -1        0        0        0        500        44        0
Jan 06 12:07:59 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        44        0
Jan 06 12:08:00 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:01 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        44        0
Jan 06 12:08:02 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        44        0
Jan 06 12:08:03 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:04 DietPi-Kitchen snapclient[852]: Chunk: -1        0        0        0        500        44        0
Jan 06 12:08:05 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        44        0
Jan 06 12:08:06 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:07 DietPi-Kitchen snapclient[852]: Chunk: -1        0        0        0        500        44        0
Jan 06 12:08:08 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:09 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:10 DietPi-Kitchen snapclient[852]: Chunk: -1        0        0        0        500        44        0
Jan 06 12:08:11 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:12 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:13 DietPi-Kitchen snapclient[852]: Chunk: -1        0        0        0        500        44        0
Jan 06 12:08:14 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:15 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0
Jan 06 12:08:16 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        44        0
Jan 06 12:08:17 DietPi-Kitchen snapclient[852]: Chunk: 0        0        0        0        500        30        0

Log from the office client, with annoying dropouts from time to time:

Please observe the output about PCM name which now is more detailed, and instead of PCM state: PREPARED now it starts with Failed to start PCM: Broken pipe, but that is only the startup, the dropouts follow in form of XRUN while waiting for PCM: Broken pipe, I even saw some where the snapclient had to reconnect:

Jan 06 12:02:49 DietPi-Office snapclient[771]: (Browser) NEW: service 'Snapcast' of type '_snapcast._tcp' in domain 'local'
Jan 06 12:02:49 DietPi-Office snapclient[771]: (Browser) CACHE_EXHAUSTED
Jan 06 12:02:49 DietPi-Office snapclient[771]: Service 'Snapcast' of type '_snapcast._tcp' in domain 'local':
Jan 06 12:02:49 DietPi-Office snapclient[771]:         nas-omv.local:1704 (192.168.177.41)
Jan 06 12:02:49 DietPi-Office snapclient[771]:         TXT=
Jan 06 12:02:49 DietPi-Office snapclient[771]:         Proto=0
Jan 06 12:02:49 DietPi-Office snapclient[771]:         cookie is 0
Jan 06 12:02:49 DietPi-Office snapclient[771]:         is_local: 0
Jan 06 12:02:49 DietPi-Office snapclient[771]:         our_own: 0
Jan 06 12:02:49 DietPi-Office snapclient[771]:         wide_area: 0
Jan 06 12:02:49 DietPi-Office snapclient[771]:         multicast: 1
Jan 06 12:02:49 DietPi-Office snapclient[771]:         cached: 1
Jan 06 12:02:49 DietPi-Office snapclient[771]: Found server 192.168.177.41:1704
Jan 06 12:02:49 DietPi-Office snapclient[771]: Resolving host IP for: 192.168.177.41
Jan 06 12:02:49 DietPi-Office snapclient[771]: Connecting
Jan 06 12:02:49 DietPi-Office snapclient[771]: Connected to 192.168.177.41
Jan 06 12:02:49 DietPi-Office snapclient[771]: My MAC: "b8:27:eb:69:ac:9b", socket: 8
Jan 06 12:02:49 DietPi-Office snapclient[771]: outstanding async_write
Jan 06 12:02:49 DietPi-Office snapclient[771]: ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
Jan 06 12:02:49 DietPi-Office snapclient[771]: metadata:{"STREAM":"Lucian_Librespot"}
Jan 06 12:02:49 DietPi-Office snapclient[771]: Codec: flac, sampleformat: 44100:16:2
Jan 06 12:02:49 DietPi-Office snapclient[771]: Player name: alsa, device: sysdefault:CARD=sndrpihifiberry, description: snd_rpi_hifiberry_dacplus, HiFiBerry DAC+ HiFi pcm512x-hifi-0
Jan 06 12:02:49 DietPi-Office snapclient[771]: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
Jan 06 12:02:49 DietPi-Office snapclient[771]: Mixer mode: software, parameters: <none>
Jan 06 12:02:49 DietPi-Office snapclient[771]: Sampleformat: 44100:16:2, stream: 44100:16:2
Jan 06 12:02:49 DietPi-Office snapclient[771]: Using buffer_time: 80 ms, fragments: 4
Jan 06 12:02:49 DietPi-Office kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Jan 06 12:02:49 DietPi-Office snapclient[771]: PCM name: sysdefault:CARD=sndrpihifiberry, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
Jan 06 12:02:49 DietPi-Office snapclient[771]: Failed to start PCM: Broken pipe
Jan 06 12:02:49 DietPi-Office snapclient[771]: setVolume exp with base 10: 1 => 1
Jan 06 12:02:49 DietPi-Office snapclient[771]: Resizing buffer from 0 to 14112
Jan 06 12:02:49 DietPi-Office snapclient[771]: no chunks available
Jan 06 12:02:49 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:02:49 DietPi-Office snapclient[771]: diff to server [ms]: 2.40443e+09
Jan 06 12:02:50 DietPi-Office snapclient[771]: Silent frames: 718, frames: 1768, age: -16.299
Jan 06 12:02:50 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        1        40        0
Jan 06 12:02:51 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        19        40        0
Jan 06 12:02:52 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        44        39        0
Jan 06 12:02:53 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        69        40        0
Jan 06 12:02:54 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        94        39        0
Jan 06 12:02:55 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        119        40        0
Jan 06 12:02:56 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        144        39        0
Jan 06 12:02:57 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        169        40        0
Jan 06 12:02:58 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        194        39        0
Jan 06 12:02:59 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        219        40        0
Jan 06 12:03:00 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        244        39        0
Jan 06 12:03:01 DietPi-Office snapclient[771]: Chunk: 1        1        0        0        269        40        0
Jan 06 12:03:02 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        294        39        0
Jan 06 12:03:03 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        319        40        0
Jan 06 12:03:04 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        344        39        0
Jan 06 12:03:04 DietPi-Office snapclient[771]: Exception: 0
Jan 06 12:03:04 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:04 DietPi-Office snapclient[771]: Silent frames: 1510, frames: 2496, age: -34.263
Jan 06 12:03:05 DietPi-Office snapclient[771]: Chunk: 1        1        1        1        7        40        0
Jan 06 12:03:06 DietPi-Office snapclient[771]: Chunk: 0        1        1        1        32        39        0
Jan 06 12:03:07 DietPi-Office snapclient[771]: Chunk: 1        1        1        1        57        40        0
Jan 06 12:03:08 DietPi-Office snapclient[771]: Chunk: 0        1        1        1        82        39        0
Jan 06 12:03:09 DietPi-Office snapclient[771]: Chunk: 1        1        1        1        107        40        0
Jan 06 12:03:10 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        132        39        -1
Jan 06 12:03:11 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        157        40        0
Jan 06 12:03:12 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        182        39        0
Jan 06 12:03:13 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        207        40        0
Jan 06 12:03:14 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        232        39        0
Jan 06 12:03:15 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        257        40        0
Jan 06 12:03:16 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        282        39        0
Jan 06 12:03:17 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        307        40        0
Jan 06 12:03:18 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        332        39        0
Jan 06 12:03:19 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        357        40        0
Jan 06 12:03:20 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        382        39        0
Jan 06 12:03:21 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        407        40        0
Jan 06 12:03:22 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        432        39        0
Jan 06 12:03:23 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        457        40        0
Jan 06 12:03:24 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        482        39        0
Jan 06 12:03:25 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 12:03:26 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:27 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 12:03:28 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:29 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:30 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:31 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:32 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:33 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:34 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:35 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:36 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:37 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:38 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:39 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 12:03:40 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:41 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 12:03:42 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:43 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:44 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:45 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 12:03:46 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:47 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:48 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:49 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:50 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:51 DietPi-Office snapclient[771]: Chunk: 1        0        0        0        500        40        0
Jan 06 12:03:52 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:53 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 12:03:54 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        39        0
Jan 06 12:03:54 DietPi-Office snapclient[771]: Exception: 0
Jan 06 12:03:54 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:54 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:54 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: XRUN while waiting for PCM: Broken pipe
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 775ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 775, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 749, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 723, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 697, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 671, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 645, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 619, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 593, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 568, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 542, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 515, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 516ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 490, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 490ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 464, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 465ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 439, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 439ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 413, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 429ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 403, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 404ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 378, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 378ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 352, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 354ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 328, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 329ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 304, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 305ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 279, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 280ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 254, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 270ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 245, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 247ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 221, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 195, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 197ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 171, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 171ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 145, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 146ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 120, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 123ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 97, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 97ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 71, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 86ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 60, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 60ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 34, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: age > 0: 37ms, dropping old chunks
Jan 06 12:03:55 DietPi-Office snapclient[771]: age: 11, requested chunk_duration: 80, duration: 26
Jan 06 12:03:55 DietPi-Office snapclient[771]: Exception: 0
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Silent frames: 632, frames: 3528, age: -14.336
Jan 06 12:03:55 DietPi-Office snapclient[771]: Exception: 0
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Silent frames: 1761, frames: 3528, age: -39.943
Jan 06 12:03:55 DietPi-Office snapclient[771]: Exception: 0
Jan 06 12:03:55 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 12:03:55 DietPi-Office snapclient[771]: Silent frames: 2880, frames: 3528, age: -65.324
Jan 06 12:03:55 DietPi-Office snapclient[771]: Chunk: -6        -6        -6        -6        1        59        0
Jan 06 12:03:56 DietPi-Office snapclient[771]: Chunk: -6        -5        -5        -5        9        39        0
Jan 06 12:03:57 DietPi-Office snapclient[771]: Chunk: -5        -5        -5        -5        34        40        0
Jan 06 12:03:58 DietPi-Office snapclient[771]: Chunk: -5        -5        -5        -5        59        39        0
Jan 06 12:03:59 DietPi-Office snapclient[771]: Chunk: -5        -5        -5        -5        84        39        0
Jan 06 12:04:00 DietPi-Office snapclient[771]: Chunk: -4        -5        -5        -5        109        39        6
Jan 06 12:04:01 DietPi-Office snapclient[771]: Chunk: -1        -2        -5        -5        134        40        11
Jan 06 12:04:02 DietPi-Office snapclient[771]: Chunk: 0        0        -4        -5        159        39        7
Jan 06 12:04:03 DietPi-Office snapclient[771]: Chunk: 0        0        -1        -5        184        40        0

Does any of this make any sense? Should I also try connecting the client over WiFi (which I would actually want to avoid, even in the kitchen I'm about to finish mounting LAN outlets and switch to wired connection)?

Thank you,
Lucian

@lucianm lucianm added the bug label Jan 6, 2021
@lucianm
Copy link
Author

lucianm commented Jan 6, 2021

Here, another documented and very audible dropout, sapparently starting with some failed time sync request:

Jan 06 19:51:12 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 19:51:13 DietPi-Office snapclient[771]: Chunk: -1        0        0        0        500        39        0
Jan 06 19:51:14 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 19:51:15 DietPi-Office snapclient[771]: Chunk: -1        0        0        0        500        39        0
Jan 06 19:51:16 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        500        40        0
Jan 06 19:51:16 DietPi-Office snapclient[771]: Exception: 0
Jan 06 19:51:16 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:16 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:16 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:16 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Time sync request failed: Connection timed out
Jan 06 19:51:17 DietPi-Office snapclient[771]: Disconnecting
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Disconnected
Jan 06 19:51:17 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:17 DietPi-Office snapclient[771]: Error reading message body of length 1316: Operation canceled
Jan 06 19:51:17 DietPi-Office snapclient[771]: Disconnecting
Jan 06 19:51:17 DietPi-Office snapclient[771]: Not connected
Jan 06 19:51:18 DietPi-Office snapclient[771]: Resolving host IP for: 192.168.177.41
Jan 06 19:51:18 DietPi-Office snapclient[771]: Connecting
Jan 06 19:51:18 DietPi-Office snapclient[771]: Connected to 192.168.177.41
Jan 06 19:51:18 DietPi-Office snapclient[771]: My MAC: "b8:27:eb:69:ac:9b", socket: 8
Jan 06 19:51:18 DietPi-Office snapclient[771]: outstanding async_write
Jan 06 19:51:18 DietPi-Office snapclient[771]: ServerSettings - buffer: 1000, latency: 0, volume: 100, muted: 0
Jan 06 19:51:18 DietPi-Office snapclient[771]: Codec: flac, sampleformat: 44100:16:2
Jan 06 19:51:18 DietPi-Office snapclient[771]: metadata:{"STREAM":"Lucian_Mopidy"}
Jan 06 19:51:18 DietPi-Office snapclient[771]: Player name: alsa, device: sysdefault:CARD=sndrpihifiberry, description: snd_rpi_hifiberry_dacplus, HiFiBerry DAC+ HiFi pcm512x-hifi-0
Jan 06 19:51:18 DietPi-Office snapclient[771]: Default Audio Device, idx: 1, sharing mode: unspecified, parameters: <none>
Jan 06 19:51:18 DietPi-Office snapclient[771]: Mixer mode: software, parameters: <none>
Jan 06 19:51:18 DietPi-Office snapclient[771]: Sampleformat: 44100:16:2, stream: 44100:16:2
Jan 06 19:51:18 DietPi-Office snapclient[771]: Using buffer_time: 80 ms, fragments: 4
Jan 06 19:51:18 DietPi-Office kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Jan 06 19:51:18 DietPi-Office snapclient[771]: PCM name: sysdefault:CARD=sndrpihifiberry, sample rate: 44100 Hz, channels: 2, buffer time: 80000 us, periods: 4, period time: 20000 us, period frames: 882
Jan 06 19:51:18 DietPi-Office snapclient[771]: Failed to start PCM: Broken pipe
Jan 06 19:51:18 DietPi-Office snapclient[771]: setVolume exp with base 10: 1 => 1
Jan 06 19:51:18 DietPi-Office snapclient[771]: Resizing buffer from 0 to 14112
Jan 06 19:51:18 DietPi-Office snapclient[771]: no chunks available
Jan 06 19:51:18 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:19 DietPi-Office snapclient[771]: diff to server [ms]: 2.40443e+09
Jan 06 19:51:19 DietPi-Office snapclient[771]: Silent frames: 1058, frames: 1768, age: -24.003
Jan 06 19:51:19 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        1        40        0
Jan 06 19:51:20 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        5        40        0
Jan 06 19:51:21 DietPi-Office snapclient[771]: Chunk: 0        0        0        0        31        39        0
Jan 06 19:51:21 DietPi-Office snapclient[771]: Exception: 0
Jan 06 19:51:21 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:21 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:21 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: Waiting for chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: XRUN while waiting for PCM: Broken pipe
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 588ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 588, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 562, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 536, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 510, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 484, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 458, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 432, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 406, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 380, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 354, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 328, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 303, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 303ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 277, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 294ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 268, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 242, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 244ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 218, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 219ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 193, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 194ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 168, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 170ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 144, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 145ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 119, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 120ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 94, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 95ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 69, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 70ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 44, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: age > 0: 45ms, dropping old chunks
Jan 06 19:51:22 DietPi-Office snapclient[771]: age: 19, requested chunk_duration: 80, duration: 26
Jan 06 19:51:22 DietPi-Office snapclient[771]: Exception: 0
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: Silent frames: 236, frames: 3528, age: -5.372
Jan 06 19:51:22 DietPi-Office snapclient[771]: Exception: 0
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: Silent frames: 1353, frames: 3528, age: -30.69
Jan 06 19:51:22 DietPi-Office snapclient[771]: Exception: 0
Jan 06 19:51:22 DietPi-Office snapclient[771]: Failed to get chunk
Jan 06 19:51:22 DietPi-Office snapclient[771]: Silent frames: 2472, frames: 3528, age: -56.063
Jan 06 19:51:22 DietPi-Office snapclient[771]: Chunk: -2        -2        -2        -2        1        59        0
Jan 06 19:51:23 DietPi-Office snapclient[771]: Chunk: -2        -2        -2        -2        15        39        0
Jan 06 19:51:24 DietPi-Office snapclient[771]: Chunk: -1        -1        -1        -1        40        40        0
Jan 06 19:51:25 DietPi-Office snapclient[771]: Chunk: -2        -1        -1        -1        65        39        0
Jan 06 19:51:26 DietPi-Office snapclient[771]: Chunk: -1        -1        -1        -1        90        40        0
Jan 06 19:51:27 DietPi-Office snapclient[771]: Chunk: -2        -1        -1        -1        115        39        1

@badaix
Copy link
Owner

badaix commented Jan 6, 2021

The line Failed to start PCM: Broken pipe is just a debug message from a call to snd_pcm_start which might fix #722 and #727 (at least it fixes the problem on one of my test machines. Still waiting for feedback from the issue reporters @hp4 and @NDahlem) and can be ignored.
Snapclient v0.23 will depend on PulseAudio (libpulse), which introduces these indirect dependencies. You can build Snapclient on a machine without pulseaudio or disable it explicitly during compile time with -DBUILD_WITH_PULSE=OFF.
From your logs I would guess that the network connection is not stable (yes, it should run better over wired network than over WiFi). I would try to debug the network connection, e.g. by pinging the Snapserver host or taking a TCP dump and check for congestions or retransmissions.

@badaix badaix removed the bug label Jan 6, 2021
@lucianm
Copy link
Author

lucianm commented Jan 7, 2021

I think you were right 👍 . I had been grabbing a short black cable with RJ45 plugs from an older FritzBox router box lying around, that cable seemed to work but it must have been dodgy. After replacing it with a proper Ethernet cable from my colored short cables reserve bag I'm having in the basement anyway, the dropouts vanished, all good now!

One more thing about Snapcast dependencies. The current development 0.23 snapclient didn't actually require me to pull in pulseaudio, the DietPi package manager (Debian Buster) only hinted at it as being recommended, but not mandatory, seems to be only a runtime dependency which only kicks in if the user configures such usage, it must be related to the new feature you're adding. Are you going to change that and link against it, according to you mentioning the build flag and make it a build time dependency?

@badaix
Copy link
Owner

badaix commented Jan 7, 2021

That's the advantage of WiFi cables: they don't break.

Snapclient is linked dynamically against libpulse. I don't know what will happen when you start snapclient --player pulse without having PulseAudio installed. I thought that it won't start at all.

@lucianm
Copy link
Author

lucianm commented Jan 7, 2021

That seems to by runtime dynamic linking, so the program would not break right at startup as in loadtime dynamic linking, but only if the code path requiring the missing dynamic library is executed, which should only happen on specific request or configuration. That's ok, like it is now. If the user has no intention of using snapclient --player pulse, then not having pulseaudio installed should not bother him at all.

Meanwhile, my wired raspi3 client happily streamed for hours without dropping packets, so I will close this issue. Thanks again!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants