Audio stuttering using shairport-sync through Snapserver

[cbrenberg]

Describe the bug
Running airplay through snapserver results in frequent 'onResync' on the server, and 'pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50)' on the client, and the audio stutters.

This only happens when the shairport-sync process controlled by snapserver outputs to stdout. When I run shairport-sync independently from snapserver, with its output directed to ALSA (which outputs to a HifiBerryDac+), the audio plays with no stuttering. Switching between Airplay1 and Airplay2 builds of shairport-sync appears to make no difference.

I've also noticed the stuttering and dropouts are more common when playing certain audio files, especially those with silent or quiet portions (certain audiobook narrators, or if I try to airplay the audio from an online metronome when trying to sync up the latency on several snapclient instances).

It almost seems like shairport-sync isn't writing its data to stdout at a consistent rate, so snapserver isn't able to maintain a consistent buffer or something along those lines, but I'm just guessing at this point.

Steps to Reproduce

1. Install snapserver, snapclient, and shairport-sync on a dietpi system (Raspberry Pi 3B+ with HiFiBerry DAC+ in this case)
2. Configure an airplay pipe in snapserver
3. Play audio files from an iOS device to airplay (I don't have the ability to try other airplay sources at the moment)
4. Wait for audio to stutter.

Environment details

• OS: DietPi latest
• Snapcast version 0.28.0 (but this has been an issue for at least the last few versions)
• Installed using dietpi's software install utilities, which installs the deb package via apt

Attach logfile if applicable

SNAPCLIENT

Jan 01 14:45:59 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -423077
Jan 01 14:46:00 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -187552
Jan 01 14:46:01 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -220224
Jan 01 14:46:02 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -200861
Jan 01 14:46:03 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -188048
Jan 01 14:46:04 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -205228
Jan 01 14:46:06 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -200231
Jan 01 14:46:07 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -173537
Jan 01 14:46:08 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -182786
Jan 01 14:46:09 LivingRoom snapclient[44650]: pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): -182135

SNAPSERVER
note: this general pattern of 'onResync' followed by snapserver 'first read, updating timestamp', followed by airplay dropping packets before reporting out of sequence packets repeats about once every second while the airplay source is playing, and each time this repeats corresponds with the timestamp of each pMiniBuffer message from the client

Jan 01 14:46:00 LivingRoom snapserver[44911]: onResync (ALL): 214.474 ms
Jan 01 14:46:00 LivingRoom snapserver[44911]: onResync (airplay): 215.64 ms
Jan 01 14:46:00 LivingRoom snapserver[44911]: onResync: airplay, duration: 215.64 ms
Jan 01 14:46:00 LivingRoom snapserver[44911]: onResync (ALL): 215.64 ms
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.272834895 "player.c:1130" Dropping out of date packet 282 with timestamp 63810684. Lead time is -0.084717 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: first read, updating timestamp
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000066511 "player.c:1130" Dropping out of date packet 283 with timestamp 63811036. Lead time is -0.076735 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000018646 "player.c:1130" Dropping out of date packet 284 with timestamp 63811388. Lead time is -0.068753 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000018645 "player.c:1130" Dropping out of date packet 285 with timestamp 63811740. Lead time is -0.060771 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000016198 "player.c:1130" Dropping out of date packet 286 with timestamp 63812092. Lead time is -0.052789 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000016146 "player.c:1130" Dropping out of date packet 287 with timestamp 63812444. Lead time is -0.044807 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015990 "player.c:1130" Dropping out of date packet 288 with timestamp 63812796. Lead time is -0.036825 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015833 "player.c:1130" Dropping out of date packet 289 with timestamp 63813148. Lead time is -0.028844 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015938 "player.c:1130" Dropping out of date packet 290 with timestamp 63813500. Lead time is -0.020862 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015885 "player.c:1130" Dropping out of date packet 291 with timestamp 63813852. Lead time is -0.012880 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015469 "player.c:1130" Dropping out of date packet 292 with timestamp 63814204. Lead time is -0.004898 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000018229 "player.c:1130" Dropping out of date packet 293 with timestamp 63814556. Lead time is 0.003084 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000024219 "player.c:1130" Dropping out of date packet 294 with timestamp 63814908. Lead time is 0.011066 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000016302 "player.c:1130" Dropping out of date packet 295 with timestamp 63815260. Lead time is 0.019048 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000017708 "player.c:1130" Dropping out of date packet 296 with timestamp 63815612. Lead time is 0.027029 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000016094 "player.c:1130" Dropping out of date packet 297 with timestamp 63815964. Lead time is 0.035011 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000016094 "player.c:1130" Dropping out of date packet 298 with timestamp 63816316. Lead time is 0.042993 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015729 "player.c:1130" Dropping out of date packet 299 with timestamp 63816668. Lead time is 0.050975 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015833 "player.c:1130" Dropping out of date packet 300 with timestamp 63817020. Lead time is 0.058957 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015573 "player.c:1130" Dropping out of date packet 301 with timestamp 63817372. Lead time is 0.066939 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000016042 "player.c:1130" Dropping out of date packet 302 with timestamp 63817724. Lead time is 0.074921 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015833 "player.c:1130" Dropping out of date packet 303 with timestamp 63818076. Lead time is 0.082902 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015677 "player.c:1130" Dropping out of date packet 304 with timestamp 63818428. Lead time is 0.090884 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015990 "player.c:1130" Dropping out of date packet 305 with timestamp 63818780. Lead time is 0.098866 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015781 "player.c:1130" Dropping out of date packet 306 with timestamp 63819132. Lead time is 0.106848 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000015781 "player.c:1130" Dropping out of date packet 307 with timestamp 63819484. Lead time is 0.114830 seconds.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000029844 "player.c:2489" Player: packets out of sequence: expected: 282, got: 308, with ab_read: 309 and ab_write: 333.
Jan 01 14:46:00 LivingRoom snapserver[44911]: getNextMessage: Time, size: 8, id: 986, refers: 0
Jan 01 14:46:00 LivingRoom snapserver[44911]: onMessageReceived: Time, size: 8, id: 986, refers: 0, sent: 796124,369355, recv: 796124,369977
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.635995000 "metadata_hub.c:531" MH Metadata stream processing start.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000080885 "metadata_hub.c:376" MH Item ID seen: "ba2e02d7741efd88" of length 8.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.000043750 "metadata_hub.c:538" MH Metadata stream processing end without changes.
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.004290104 "metadata_hub.c:587" MH Progress String set to: "63713657/63847957/67109209"
Jan 01 14:46:00 LivingRoom snapserver[44911]: (airplay)          0.005335834 "metadata_hub.c:542" MH Picture received, length 0 bytes.
Jan 01 14:46:00 LivingRoom snapserver[44911]: setProperties, stream: airplay, properties: {"canControl":false,"canGoNext":false,"canGoPrevious":false,"canPause":false,"canPlay":false,"canSe>
Jan 01 14:46:00 LivingRoom snapserver[44911]: Properties changed, stream: airplay, properties: {
Jan 01 14:46:00 LivingRoom snapserver[44911]:    "canControl": false,
Jan 01 14:46:00 LivingRoom snapserver[44911]:    "canGoNext": false,