shairport-sync 🚀 - Very choppy?

Hi there and thanks for the report. I also have Shairport Sync running on a C.H.I.P. without problems. The usual culprit is either a poor network, strange firewall configurations (especially in Windows, which sets firewall settings depending on the kind of network you say you are connecting to) or a poor quality router – you should not need to tune buffers. You can turn on logging by setting the log_verbosity to 1 or 2 to get some diagnostics. Let us know how you do!

mikebrady on 23 Jul 2016

Hmmm. I doubled the buffers and saw a marked improvement (though it now crackles). I will get those pesky diagnostics and get back to you. I will (yes) turn buffer back to defaults so as not to confound the story.

Thanks for the quick response.

cheers
B

Bazmundi on 23 Jul 2016

buffers exhausted, loss of sync, first packet late, ad nausium.

Bazmundi on 23 Jul 2016

Yep, sounds like a network problem. Is it possible that WiFi power management on the C.H.I.P. is on?

$$ sudo iw wlan0 get power_save

It must be off.

mikebrady on 23 Jul 2016

Whoops, forgot to comment out buffer tuning. Now getting ALSA device in incorrect state (4) for play, broken pipe, lost sync with source for 4 consecutive packets (flush and resync).

Bazmundi on 23 Jul 2016

Yep, power safe is on. I will poke around to work out how to turn it off and get back to you - huge t-bone steak waiting on my dinner table as well which will slow me up for a short while.

Bazmundi on 23 Jul 2016

The steak is worth delaying for. I think the command should be:

$ sudo iw wlan0 set power_save off

mikebrady on 23 Jul 2016

Steak great. Powersafe off and now it is worse somehow?

Bazmundi on 23 Jul 2016

Can you show some of the log? (To format it, put ``` on a line above and below it.)

mikebrady on 23 Jul 2016

PCM handle name = 'hw:0'
alsa device parameters:
access type = RW_INTERLEAVED
format = 'S16_LE' (Signed 16 bit Little Endian)
subformat = 'STD' (Standard)
number of channels = 2
number of significant bits = 16
rate = 44100 frames per second (precisely).
precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
period_time = 5804 us (>).
period_size = 256 frames (precisely).
buffer_time = 2972154 us (>).
buffer_size = 131072 frames (>).
periods_per_buffer = 512 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds: 7861.0, 18872.1, 196576.0.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Buffers exhausted.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 44975.
syncing to seqno 29451.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29497.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29515.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29528.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29541.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29576.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29597.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29694.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 119722.
syncing to seqno 29761.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29779.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29821.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 29978.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30012.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30026.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30039.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30056.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30074.
syncing to seqno 30083.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30098.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Buffers exhausted.
Error -- ALSA device in incorrect state (4) for play.
Buffers exhausted.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 28543.
syncing to seqno 30161.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30294.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: -6139.
syncing to seqno 30395.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3910.
syncing to seqno 30430.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30443.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30456.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30469.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30482.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30495.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30508.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30521.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30534.
First packet is late! It should have played before now. Flushing 0.1 seconds
syncing to seqno 30547.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Buffers exhausted.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2444.

Bazmundi on 23 Jul 2016

I am playing some of my wife's punk, which I think might be part of the problem lol

Bazmundi on 23 Jul 2016

😄1

Hang on, I jumped straight into this after burning the image onto my new C.H.I.P. and missed the audio setup step on Debian so I will sort that and try again. Way too excited to get this going obviously roflmao.

Bazmundi on 23 Jul 2016

Okay.

I am playing some of my wife's punk, which I think might be part of the problem lol

That's a serious problem right there, but I can't help you with that – you're on your own there.

mikebrady on 23 Jul 2016

😄4

BTW, I just used the installation of Linux that came with the C.H.I.P. I didn't install anything else, except what's listed in the Shairport Sync README.md. Have you a different installation?

mikebrady on 23 Jul 2016

DOH! I bombed it with Headless 4.4 Debian. I have four other boards so I will try one straight out of the box. Double DOH!

... must have red wine!

Leave it with me, it'll be another slow build et al.

Thanks again for talking me through.

Bazmundi on 23 Jul 2016

Sure thing. I think you are taking the right approach alright. Let me know how it goes...

mikebrady on 23 Jul 2016

Alas no. With OS installed on C.H.I.P. out of box same same (with wifi powersafe off) - even when not using punk!

Bazmundi on 23 Jul 2016

That's too bad. Have you tried moving the C.H.I.P. around, to see if it makes any difference to WiFi reception. I've just checked – running iTunes on Windows 10 inside VMWare Fusion on an iMac to a C.H.I.P. and it's fine... I'll get some log entries in a few minutes.

mikebrady on 23 Jul 2016

Moving it around might be a fun prospect but I was rather thinking of ceiling mounting speakers with a small 12W amp and a C.H.I.P.

I am stuck with a Telco supplier wifi router at the moment and I am only a room away - although it is an older house with brick inner walls. Might have to play with wifi extenders etc.

Bazmundi on 23 Jul 2016

Sure, I understand, but just for troubleshooting purposes...
Offhand, I would not have thought the distance was a problem. Are there any settings in the router, e.g. firewall, Windows Multimedia something-or-other?

mikebrady on 23 Jul 2016

Here are some stats from the aforementioned Windows 10 playing to the C.H.I.P., with statistics enabled too – there's useful information there too. The results of $ uname -a is:

Linux chip 4.3.0 #10 SMP Sat Nov 14 19:10:05 PST 2015 armv7l GNU/Linux

Here is the log:

Jul 23 15:25:09 chip shairport-sync[25979]: New RTSP connection from 192.168.2.43:49818 to self at 192.168.2.40:5000.
Jul 23 15:25:10 chip shairport-sync[25979]: Play connection from user agent "iTunes/12.4.2 (Windows; Microsoft Windows 10.0 x64 (Build 9200); x64)".
Jul 23 15:25:10 chip shairport-sync[25979]: Active-Remote string seen: "1910806697".
Jul 23 15:25:10 chip shairport-sync[25979]: DACP-ID string seen: "7C64447EFFFC48B8".
Jul 23 15:25:10 chip shairport-sync[25979]: User-Agent is iTunes 10 or better, (actual version is 12); selecting the iTunes latency of -1 frames.
Jul 23 15:25:10 chip shairport-sync[25979]: rtp_setup: cport=6001 tport=6002.
Jul 23 15:25:10 chip shairport-sync[25979]: Set up play connection from 192.168.2.43 to self at 192.168.2.40.
Jul 23 15:25:10 chip shairport-sync[25979]: listening for audio, control and timing on ports 6001, 6002, 6003.
Jul 23 15:25:10 chip shairport-sync[25979]: sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Jul 23 15:25:10 chip shairport-sync[25979]: Audio receiver -- Server RTP thread starting.
Jul 23 15:25:10 chip shairport-sync[25979]: Control receiver -- Server RTP thread starting.
Jul 23 15:25:10 chip shairport-sync[25979]: Timing receiver -- Server RTP thread starting.
Jul 23 15:25:10 chip shairport-sync[25979]: Timing sender thread starting.
Jul 23 15:25:10 chip shairport-sync[25979]: volume: -18.571629
Jul 23 15:25:10 chip shairport-sync[25979]: Setting volume db to -2442.893143.
Jul 23 15:25:10 chip shairport-sync[25979]: volume: -18.571629
Jul 23 15:25:10 chip shairport-sync[25979]: Setting volume db to -2442.893143.
Jul 23 15:25:10 chip shairport-sync[25979]: syncing to seqno 51235.
Jul 23 15:25:10 chip shairport-sync[25979]: Open Mixer
Jul 23 15:25:10 chip shairport-sync[25979]: Setting volume db to -2442.893143.
Jul 23 15:25:10 chip shairport-sync[25979]: received metadata tags in SET_PARAMETER request.
Jul 23 15:25:22 chip shairport-sync[25979]: New RTSP connection from 192.168.2.12:57665 to self at 192.168.2.40:5000.
Jul 23 15:25:22 chip shairport-sync[25979]: Closing down RTSP conversation thread...
Jul 23 15:25:22 chip shairport-sync[25979]: RTSP conversation thread terminated.
Jul 23 15:25:30 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.4,     7217.3,    40494.0.
Jul 23 15:25:42 chip shairport-sync[25979]: 64.6,    -180.2,     180.2,        3758,      0,      0,      0,      0,   4697,  259,  268
Jul 23 15:25:50 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7983.6,     7204.8,    36192.0.
Jul 23 15:26:10 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.7,     7147.0,    41465.0.
Jul 23 15:26:12 chip shairport-sync[25979]: 66.4,    -241.9,     241.9,        7516,      0,      0,      0,      0,   5882,  257,  265
Jul 23 15:26:30 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,     7529.8,    64475.0.
Jul 23 15:26:42 chip shairport-sync[25979]: 67.7,    -262.3,     262.3,       11274,      0,      0,      0,      0,   6164,  259,  265
Jul 23 15:26:50 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.8,     7083.0,    33466.0.
Jul 23 15:27:10 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.7,     7151.5,    34117.0.
Jul 23 15:27:12 chip shairport-sync[25979]: 66.7,    -221.5,     221.5,       15032,      0,      0,      0,      0,   6028,  260,  265
Jul 23 15:27:30 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,     7176.7,    31890.0.
Jul 23 15:27:42 chip shairport-sync[25979]: 68.5,    -245.7,     245.7,       18790,      0,      0,      0,      0,   6100,  220,  265
Jul 23 15:27:50 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,    10223.9,   348151.0.
Jul 23 15:28:10 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7984.4,     7111.5,    42034.0.
Jul 23 15:28:12 chip shairport-sync[25979]: 68.0,    -235.1,     235.1,       22548,      0,      0,      0,      0,   6113,  259,  265
Jul 23 15:28:30 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7984.0,     7111.5,    22077.0.
Jul 23 15:28:42 chip shairport-sync[25979]: 68.6,    -241.9,     241.9,       26306,      0,      0,      0,      0,   6136,  261,  265
Jul 23 15:28:49 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.5,     7140.7,    27007.0.
Jul 23 15:29:09 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.0,     7079.6,    33098.0.
Jul 23 15:29:12 chip shairport-sync[25979]: 68.7,    -242.7,     242.7,       30064,      0,      0,      0,      0,   6105,  260,  265
Jul 23 15:29:29 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.0,     7116.9,    35830.0.
Jul 23 15:29:42 chip shairport-sync[25979]: 67.3,    -226.0,     226.0,       33822,      0,      0,      0,      0,   5995,  260,  265
Jul 23 15:29:49 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.9,     7155.7,    36925.0.
Jul 23 15:30:09 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7983.2,     7040.6,    36858.0.
Jul 23 15:30:12 chip shairport-sync[25979]: 68.2,    -252.5,     252.5,       37580,      0,      0,      0,      0,   5991,  259,  265
Jul 23 15:30:29 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7985.2,     7165.9,    37961.0.
Jul 23 15:30:42 chip shairport-sync[25979]: 68.7,    -243.4,     243.4,       41338,      0,      0,      0,      0,   6141,  260,  265
Jul 23 15:30:44 chip wpa_supplicant[370]: wlan0: WPA: Group rekeying completed with f4:ec:38:e6:70:82 [GTK=CCMP]
Jul 23 15:30:49 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.8,     7085.6,    37568.0.
Jul 23 15:31:09 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.7,     7077.6,    25446.0.
Jul 23 15:31:12 chip shairport-sync[25979]: 68.7,    -241.2,     241.2,       45096,      0,      0,      0,      0,   6065,  261,  265
Jul 23 15:31:29 chip shairport-sync[25979]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.6,     7051.2,    25668.0.

mikebrady on 23 Jul 2016

Switched PC and CHIP over to a wifi extender on my desk so server, client
and wifi router connection in same room. One loss of sync pop in first
song but otherwise good for 4 songs. Went away to brag to Wife. Came back
playing had stopped. Had to try multiple times to reconnect from iTunes
but it did (eventually). Some quote from Keats in the log output (about
silence), et cetera:

Buffers exhausted.
New RTSP connection from 192.168.0.3:50459 to self at 192.168.0.9:5000.
Already playing.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
As Yeats almost said, "Too long a silence / can make a stone of the heart"
Request to shut down all rtsp conversation threads
asking playing threads to stop
RTSP shutdown requested.
Closing down RTSP conversation thread...
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.

Then after a couple of attempts at iTunes failed it connected again and all
good. So as long as I have the punk pummelling my eardrums it runs, but
seems to sulk when I go away from my desk.

So PC, extender and C.H.I.P. within a metre of one another. So, you were
saying about router or firewall settings? Any hints?

Cheers,
B

PS I have no metal plates in my head, that might possibly be causing the problem, though I do understand they would counteract the effects of punk on my neurons.

Bazmundi on 24 Jul 2016

I'm at a wedding – not mine – so I might have to wait a bit...

Il giorno 24 lug 2016, alle ore 08:57, Asterion Daedalus [email protected] ha scritto:

Switched PC and CHIP over to a wifi extender on my desk so server, client
and wifi router connection in same room. One loss of sync pop in first
song but otherwise good for 4 songs. Went away to brag to Wife. Came back
playing had stopped. Had to try multiple times to reconnect from iTunes
but it did (eventually). Some quote from Keats in the log output (about
silence), et cetera:

Buffers exhausted.
New RTSP connection from 192.168.0.3:50459 to self at 192.168.0.9:5000.
Already playing.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
Error sendto-ing to timing socket: Invalid argument
As Yeats almost said, "Too long a silence / can make a stone of the heart"
Request to shut down all rtsp conversation threads
asking playing threads to stop
RTSP shutdown requested.
Closing down RTSP conversation thread...
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.

Then after a couple of attempts at iTunes failed it connected again and all
good. So as long as I have the punk pummelling my eardrums it runs, but
seems to sulk when I go away from my desk.

So PC, extender and C.H.I.P. within a metre of one another. So, you were
saying about router or firewall settings? Any hints?

Cheers,
B
—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.

mikebrady on 24 Jul 2016

🎉1

Had fun at wedding I hope? My last wedding was the best many people felt they had ever gone to (or so they politely said). My first wedding was great, marriage not so much.

So with my trusty Netgear scanner app I appear to get 100% signal at my hobby desk with average 117Mbps from the main router remote in the lounge and 100% signal and 130Mbps from my wifi extender sitting local on my desk. Not exactly sure then why it goes from all chop with occasional song to all song with rare chop with only marginal improvement in bps when swapping from remote to local router. Best I seem to get in middle of living room is 156bps!

So, question becomes what bps does the OOTB setup for shairport-sync assume - given all the magical buffer settings? At least what is the brown-out bps?

I might yet get a super-duper wifi extender but if the problem is somewhere else ... hmmm.

Cheers,
B

Bazmundi on 25 Jul 2016

The wedding was great, thanks. Your problem is definitely not the speed – even 2 Mbps is fine. It's got to be something else. In my network, there are no Windows devices, so all firewall settings are off. Also, all QoS (Quality of Service) stuff if disabled. Is it possible to change the settings in your Telco-provided router at all? (What kind of router is it anyway?) If you could turn off all those kinds of things, even temporarily, to see if the problem goes away, that might be useful.

mikebrady on 25 Jul 2016

I'm also experiencing choppy sound. The client device is a Macbook Pro (mid 2010). Playback with the Mac via cable to the speaker works, and playback with the C.H.I.P.s via cable to speaker also works, so the speaker is fine.

The two C.H.I.P.s used are both brand new, and the flash hasn't been touched upon; so, they both run the stock Debian image which sits on the flash preinstalled. Haven't done anything but ran apt-get update && apt-get -y install shairport-sync and created a couple of users.

To further narrow down this, I think the network is not the problem. It's not perfect, but not horrible either. I tried with two different Wi-Fi access points too.

64 bytes from 172.16.69.212: icmp_seq=3 ttl=64 time=6.190 ms
64 bytes from 172.16.69.212: icmp_seq=4 ttl=64 time=7.861 ms
64 bytes from 172.16.69.212: icmp_seq=5 ttl=64 time=7.500 ms
64 bytes from 172.16.69.212: icmp_seq=6 ttl=64 time=4.248 ms
64 bytes from 172.16.69.212: icmp_seq=7 ttl=64 time=6.413 ms
64 bytes from 172.16.69.212: icmp_seq=8 ttl=64 time=6.719 ms
64 bytes from 172.16.69.212: icmp_seq=9 ttl=64 time=6.543 ms
64 bytes from 172.16.69.212: icmp_seq=10 ttl=64 time=6.619 ms
64 bytes from 172.16.69.212: icmp_seq=11 ttl=64 time=6.562 ms
64 bytes from 172.16.69.212: icmp_seq=12 ttl=64 time=21.179 ms
64 bytes from 172.16.69.212: icmp_seq=13 ttl=64 time=8.623 ms
64 bytes from 172.16.69.212: icmp_seq=14 ttl=64 time=6.737 ms
64 bytes from 172.16.69.212: icmp_seq=15 ttl=64 time=9.604 ms
64 bytes from 172.16.69.212: icmp_seq=16 ttl=64 time=10.154 ms
64 bytes from 172.16.69.212: icmp_seq=17 ttl=64 time=10.202 ms
64 bytes from 172.16.69.212: icmp_seq=18 ttl=64 time=6.541 ms
64 bytes from 172.16.69.212: icmp_seq=19 ttl=64 time=12.403 ms
64 bytes from 172.16.69.212: icmp_seq=20 ttl=64 time=6.290 ms
64 bytes from 172.16.69.212: icmp_seq=21 ttl=64 time=6.796 ms
64 bytes from 172.16.69.212: icmp_seq=22 ttl=64 time=9.398 ms
64 bytes from 172.16.69.212: icmp_seq=23 ttl=64 time=10.834 ms
64 bytes from 172.16.69.212: icmp_seq=24 ttl=64 time=6.233 ms
64 bytes from 172.16.69.212: icmp_seq=25 ttl=64 time=6.935 ms
64 bytes from 172.16.69.212: icmp_seq=26 ttl=64 time=7.732 ms
64 bytes from 172.16.69.212: icmp_seq=27 ttl=64 time=7.865 ms
64 bytes from 172.16.69.212: icmp_seq=28 ttl=64 time=8.402 ms
64 bytes from 172.16.69.212: icmp_seq=29 ttl=64 time=6.527 ms
64 bytes from 172.16.69.212: icmp_seq=30 ttl=64 time=11.861 ms

64 bytes from 172.16.69.212: icmp_seq=0 ttl=64 time=5.440 ms
64 bytes from 172.16.69.212: icmp_seq=1 ttl=64 time=5.482 ms
64 bytes from 172.16.69.212: icmp_seq=2 ttl=64 time=6.388 ms
64 bytes from 172.16.69.212: icmp_seq=3 ttl=64 time=5.690 ms
64 bytes from 172.16.69.212: icmp_seq=4 ttl=64 time=3.428 ms
64 bytes from 172.16.69.212: icmp_seq=5 ttl=64 time=6.865 ms
64 bytes from 172.16.69.212: icmp_seq=6 ttl=64 time=5.875 ms
64 bytes from 172.16.69.212: icmp_seq=7 ttl=64 time=5.465 ms
64 bytes from 172.16.69.212: icmp_seq=8 ttl=64 time=7.118 ms
64 bytes from 172.16.69.212: icmp_seq=9 ttl=64 time=5.641 ms
64 bytes from 172.16.69.212: icmp_seq=10 ttl=64 time=5.668 ms
64 bytes from 172.16.69.212: icmp_seq=11 ttl=64 time=7.091 ms
64 bytes from 172.16.69.212: icmp_seq=12 ttl=64 time=5.684 ms
64 bytes from 172.16.69.212: icmp_seq=13 ttl=64 time=5.751 ms
64 bytes from 172.16.69.212: icmp_seq=14 ttl=64 time=5.274 ms
64 bytes from 172.16.69.212: icmp_seq=15 ttl=64 time=5.720 ms
64 bytes from 172.16.69.212: icmp_seq=16 ttl=64 time=8.943 ms
64 bytes from 172.16.69.212: icmp_seq=17 ttl=64 time=9.277 ms
64 bytes from 172.16.69.212: icmp_seq=18 ttl=64 time=3.415 ms
64 bytes from 172.16.69.212: icmp_seq=19 ttl=64 time=6.240 ms
64 bytes from 172.16.69.212: icmp_seq=20 ttl=64 time=6.136 ms

The log_verbosity = 2 doesn't produce errors:

Looking for the configuration file "/etc/shairport-sync.conf".
Output device name is "hw:0".
Version: "2.8.4-OpenSSL-Avahi-ALSA-pulse-dummy-stdout-pipe-soxr-metadata"
statistics_requester status is 0.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "A".
Audio Output name is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
stuffing option is "0" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
metdata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: request to add "_raop._tcp" service without metadata
avahi: service '7FC56270E7A7@A' successfully added.
New RTSP connection from 172.16.69.112:50246 to self at 172.16.69.212:5000.
Play connection from device named "macbook".
Play connection from user agent "AirPlay/200.34.4".
Active-Remote string seen: "2672155989".
DACP-ID string seen: "CE4271E37F643A76".
Set up play connection from 172.16.69.112 to self at 172.16.69.212.
RTSP shutdown requested.
Closing down RTSP conversation thread...
Shut down audio, control and timing threads
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
Audio receiver -- Server RTP thread interrupted. terminating.
audio thread joined
control thread joined
Player thread exit
^Cshutdown requested...
avahi: avahi_unregister.
Request to shut down all rtsp conversation threads

A fairly /etc/shairport-sync.conf goes with the setup:

general =
{
  log_verbosity = 2;
  name = "A";
};

alsa =
{
  output_device = "hw:0";
};

Any ideas?

ghost on 29 Jul 2016

I am running shairport-sync on a CHIP and it streams without any problems. I do not use the Debian image, but a custom image build with Buildroot. And I use the rtl8723bs wifi driver from hadess instead of the NTC one.

# shairport-sync -V
2.8.4-PolarSSL-tinysvcmdns-ALSA-stdout-pipe-soxr-metadata

No changes in the shairport-sync.conf file.

I am using sun4i-codec as audio driver:

# modprobe sun4i-codec

My alsa mixer settings:

# amixer 
Simple mixer control 'Left Mixer Left DAC',0
  Capabilities: pswitch pswitch-joined
  Playback channels: Mono
  Mono: Playback [on]
Simple mixer control 'Power Amplifier',0
  Capabilities: volume volume-joined
  Playback channels: Mono
  Capture channels: Mono
  Limits: 0 - 63
  Mono: 63 [100%] [0.00dB]
Simple mixer control 'Power Amplifier DAC',0
  Capabilities: pswitch pswitch-joined
  Playback channels: Mono
  Mono: Playback [on]
Simple mixer control 'Power Amplifier Mixer',0
  Capabilities: pswitch pswitch-joined
  Playback channels: Mono
  Mono: Playback [on]
Simple mixer control 'Power Amplifier Mute',0
  Capabilities: pswitch pswitch-joined
  Playback channels: Mono
  Mono: Playback [on]
Simple mixer control 'Right Mixer Left DAC',0
  Capabilities: pswitch pswitch-joined
  Playback channels: Mono
  Mono: Playback [on]
Simple mixer control 'Right Mixer Right DAC',0
  Capabilities: pswitch pswitch-joined
  Playback channels: Mono
  Mono: Playback [on]

Some statistics:

sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy

      72.0,    -273.4,     273.4,        3758,      0,      0,      0,      0,   4563,  226,  238
      69.5,    -347.0,     347.0,        7516,      0,      0,      0,      0,   6052,  228,  237
      65.2,    -347.0,     348.5,       11274,      0,      0,      0,      0,   6111,  230,  237
      69.3,    -329.6,     329.6,       15032,      0,      0,      0,      0,   6093,  230,  237
      69.3,    -355.3,     356.8,       18790,      0,      3,      0,      3,   6045,  173,  237
      68.7,    -337.2,     337.2,       22548,      0,      3,      0,      3,   6083,  229,  237
      68.3,    -342.5,     342.5,       26306,      0,      3,      0,      3,   6090,  229,  237
      98.9,    -672.8,     672.8,       30064,      0,      3,      0,      3,   6083,  229,  237
      66.9,    -327.3,     327.3,       33822,      0,      7,      0,      7,   6095,  218,  237
      68.7,    -338.7,     338.7,       37580,      0,      7,      0,      7,   6082,  229,  237

joerg-krause on 29 Jul 2016

👎1

@samilaine @Bazmundi Please check this thread, especially the last post:

I also found when using the builtin sound from the CHIP, that you have to use the provided 3.5mm to RCA cable. If you use a standard stereo (i.e. no video) RCA cable, the video signal is applied to one of the audio channels and it makes the sound crackly and poor quality.

Basically, you need a splitter cable which splits off the left+right audio from the video/microphone signal for safety:

Splitter cable

joerg-krause on 29 Jul 2016

👎1

@joerg-krause my C.H.I.P. came with

Not to mention C.H.I.P. site says: http://docs.getchip.com/chip.html#headphones

I am also in discussion on this thread with the person who ported the code and who suggested it should run on an unmodified C.H.I.P. (it doesn't for me but does for him). Adding any other variables into the mix is never a good approach. Though I do appreciated your brain storming.

I will progress with 1) trying what Mike has suggested and 2) I have a video extender nearby the wifi router and have not as yet experimented with turning that off (as I suspect it is in same frequency band).

Bazmundi on 30 Jul 2016

@Bazmundi Yes, I have the same colourful composite cable from C.H.I.P.

I flashed my C.H.I.P. with a fresh Debian image and installed shairport-sync. And it streams without problems like my custom Buildroot image. I can confirm that standard headphone plug-in works, too. This elimates that the problem comes from:

headphone jack
wireless driver
shairport-sync

I remember I tested a C.H.I.P. with the Buildroot image from NTC some time ago where I experienced this choppy sound output, too. That's why I thought it might be something else as a network issue.

joerg-krause on 30 Jul 2016

@joerg-krause so now you use the Debian image whereas before you did not, so all points to my actual wifi setup. I changed channel (seaming to be sharing same channel with neighbors) and turned off the 2.4GHz video extender and got through full album of wife's punk with one spat of loss of sync. In fact, today I was on router in lounge (rather than local wifi extender) and all was generally good (without fiddling with parameters) so who knows ... sun spots maybe.

I think also, realistically, giving the problem of time synchronisation one can't expect no drops out all (I assume) but the first day of experiment was shocking with more dropouts than music getting through - but it all seems to have come good without doing anything different on the C.H.I.P. config side.

Although, I did also have an episode today where the iTunes on my PC did not detect the C.H.I.P. and I had to restart my PC and then restart the C.H.I.P. to get for the system to connect again so perhaps its a Windoze thing?

As the target environment will be my Wife's iPad as source of noise I might try that without the PC as the server to take out the Windoze factor.

I am not brave enough (yet) to turn off my firewall and that can't be the normal operating environment for obvious reasons.

Any now I am dizzy from hunger so left over pizza and mowing lawns before I have permission from Wife to fiddle with this again today lol

Bazmundi on 31 Jul 2016

Thanks for keeping us up to date on this. It looks like you are making progress, hunger, punk music, lawn mowing and Windows notwithstanding. Just FYI, when it's all working, you should expect no dropouts. For clarification, when you say "the PC as the server", do you mean (simply) that you are using iTunes on it to play to the CHIP? Would Wife be impressed by a request to show you some clemency if it came from the Internet?

mikebrady on 31 Jul 2016

😕1

@samilaine, those logs look fine to me, except that the log_verbosity = 2 log doesn't show any playing – it shows a play request and then a play termination request. Did music actually play in that interval? An idle thought is to download a reasonably long audio track and play it via aplay. It would be important to ensure it's at 44,100 samples per second and 16-bit LE interleaved stereo, i.e. CD quality.

mikebrady on 31 Jul 2016

The music does play during the interval show in the excerpt, though, as said, in a slightly choppy way. It seems that the cable is working fine because I can get clean audio output from one of my Macbooks with it.

This time I've got a C.H.I.P. right next to a Macbook (within the same SSID on the wireless network). I can play out Bach's Cello Suite n:o 1 prelude locally with sox play (and aplay) from a pair of (very old) Apple earbuds and an external speaker with male-to-male connection cable. However, when running the same audio through shairport-sync, it sounds like one quarter out of every second is chopped out regardless of the cable used.

I cranked out a little more verbose output from shairport-sync with -vv. Also, I'm running Mavericks on the client side (yes, I know, I should be busy updating).

Looking for the configuration file "/etc/shairport-sync.conf".
Looking for configuration file at full path "/etc/shairport-sync.conf"
Output device name is "hw:0".
The processor is running little-endian.
Version: "2.8.4-OpenSSL-Avahi-ALSA-pulse-dummy-stdout-pipe-soxr-metadata"
statistics_requester status is 0.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "A".
Audio Output name is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "0" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
metdata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: service '7FC56270E7A7@A' group is not yet committed.
avahi: request to add "_raop._tcp" service without metadata
avahi: service '7FC56270E7A7@A' group is registering.
avahi: service '7FC56270E7A7@A' successfully added.
New RTSP connection from 172.16.69.112:50690 to self at 172.16.69.212:5000.
Play connection from device named "macbook".
Play connection from user agent "AirPlay/200.34.4".
Active-Remote string seen: "350167130".
DACP-ID string seen: "31341B1CCAF25EC6".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=63760 tport=57566.
Set up play connection from 172.16.69.112 to self at 172.16.69.212.
listening for audio, control and timing on ports 6001, 6002, 6003.
Audio receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing receiver -- Server RTP thread starting.
Timing sender thread starting.
volume: 0.000000

syncing to seqno 6397.
PCM handle name = 'hw:0'
alsa device parameters:
  access type = RW_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 5804 us (>).
  period_size = 256 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 512 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.8,    15665.1,   538589.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.6,    21307.7,   536846.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    18250.6,   511540.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    15641.2,   535501.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.5,    18480.4,   535501.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7991.5,    18543.4,   538323.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.7,    18488.4,   537428.0.
RTSP shutdown requested.
Closing down RTSP conversation thread...
Shut down audio, control and timing threads
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
Audio receiver -- Server RTP thread interrupted. terminating.
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.

I tried this with another wi-fi router, with no other devices that the Macbook and the C.H.I.P. connected, yet the results are identical. It looks like packets are not getting through to the C.H.I.P. or the wi-fi on it is semibroken (the Macbook seems to be doing fine with other peers), don't you think?

ghost on 1 Aug 2016

So YES to iTunes running on PC (aka "The Server"). Night time here so no sunspots. Got through four songs then crackle ... pop ... nothing ... and iTunes on my PC drops the Airplay connection to my chip.

As for Wife, turns out her iPad is the one "without Airplay" (she says), although for an iPad without Airplay Ahhh Santana! So, she thinks I am a brainiac because I "installed" Airplay!

So, I am grooving off the music streaming on her iPad to test the "Windoze is the Kulprit" story.

Stay tuned for next episode.

Bazmundi on 1 Aug 2016

GAG! Probably 10 songs in, running off iPad, a splutter for a second, but the connection held.

Bazmundi on 1 Aug 2016

"Ha! hold my Brain; be still my beating Heart." ;)

mikebrady on 1 Aug 2016

20160802_212005
So, story goes it ran off PC server for entire punk album. I had given up the other day with setting up the alsamixer as it came up with a different codec default, different "menu" layout, and up/down arrows did not work as suggested (from getchip page on audio setup). Today I managed to set the left/right mixer DAC to ON with 'm' key?? Likely just my terminal set-up.

In any event, I don't believe at all that fixed the buffer drop outs (just coincidental), there is something flaky I am still working out with my network setup.

However, photo above is the temporary setup with a not bad $100 speaker from Target. Driven by my Wife's iPad with Airplay "installed". When it started it was too loud (apparently) so did you know you can adjust the volume from your Airplay "installed" iPad LOL?

Just need a trip to the hardware store for some sticky velcro patches.

In any event. Thanks for the good humour and support.

PS: Does anyone know how to turn that pesky LED off? That'll bug her, I just know it will ROFLMAO.

The down-side, there is rhythmic pulsing warble with a crackle over top the music that is also there when you hit stop on the player. Audio on that horrible pink cable is the white and pink (pretending to be red) banded wires yes? The yellow is the video yes? I am powering the board with the USB charger output on the speaker. I will try a second source of power.

And yes, she noticed the warble so the LED is not bothering her ... yet.

Bazmundi on 2 Aug 2016

Yep, I used a phone charger to power the board, instead of the charger output of the speaker. Looks like there was some feedback loopiddydooping. A nuisance as Madam will not like two power outlets being used. Still, likely just a issue with that Target speaker design. Fingers crossed as I reach into the deep pocket to get a couple of other speakers to spread around the house with the rest of the C.H.I.P. in my parts drawer.

You were saying about the LED? I might just use a patch of electricians tape ... sssh! She'll never know the difference.

Bazmundi on 2 Aug 2016

Yeah, the LED is really bright. It might be worth asking the CHIP guys. You may be right about the power supply as a possible source of noise – great to try another one to see if it makes a difference.

mikebrady on 2 Aug 2016

@samilaine, thanks for the update. Two things are interesting about this – first, Shairport Sync is not reporting any problems like underruns, which I think it would if it was running out of audio frames. This makes me think that it is processing audio relatively normally. Given that it sounds choppy, I guess it would sound choppy but with the audible parts remaining in sync with when there should be heard. The second thing is the relatively high maximum packet interval – just over half a second. It's a high number. I don't know if it's causing a problem, but it might be indicative of a slight fault in the network somewhere.

A possible mechanism for the choppy sound is if Shairport Sync is interpolating missing packets – a packet contains 352 audio frames – with silence. It will do this when individual packets are lost. If you enable statistics, you'd get an idea of packet loss and synchronization activity. I think that would be interesting.

mikebrady on 4 Aug 2016

Hi there. Any further developments or instalments of the continuing story... :) ?

mikebrady on 11 Oct 2016

Hi there,

first of all many thanks for the work and for the support.

I installed shairport-sync on C.H.I.P. following the guide right after flashing. Sound quality seems very good to me. The only issue (but quite annoying) is that every 1 or 2 minutes (or less, it's very random) the sound pauses for 2 or 3 seconds. Then it resumes with a bit of stuttering and goes back to the normal audio stream. I am streaming from an Ipad to a pc speaker via C.H.I.P. However, if I stream to my Sony sound system (which supports Airplay) this does not happen (to be fair, it can happen once every hour for a few seconds, much more tolerable though).
As you suggested in previous posts I disabled the auto wifi off thing, but it did not help. One thing that helped was disabling the router option that changes the wifi channel automatically to find the best one. But still it is not perfect. Is there anything else I can do?
Many thanks.

vitospinelli on 29 Nov 2016

Thanks for the post. Would it be possible to post a log with log_verbosity=2 including the very start and also around the time of a pause and restart?

mikebrady on 30 Nov 2016

Sorry for my late reply. Bush week at work. Sorry for the vero noob question. How do I do it? I just typed your command and nothing happened...

vitospinelli on 2 Dec 2016

You need to put that setting into the configuration file. This will cause Shairport Sync to put lots of information into the system log file.

mikebrady on 3 Dec 2016

Hi, I was just about to post...

I did some research online.. I did, as you say, change the configuration file and then run the command as below... whenever the audio stuttered I got an error>

chip@chip-studio:~$ shairport-sync -a "chip-studio" -v -- -d default 
Looking for the configuration file "/usr/local/etc/shairport-sync.conf".
Output device name is "default".
Version: "2.8.6-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 0.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "chip-studio".
Audio Output name is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
stuffing option is "1" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
use_mmap_if_available is 1.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
metdata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: request to add "_raop._tcp" service without metadata
avahi: service 'EEE5F4C98F05@chip-studio' successfully added.
New RTSP connection from 192.168.1.6:55375 to self at 192.168.1.54:5000.
Play connection from user agent "AirPlay/280.33".
Active-Remote string seen: "3577188247".
DACP-ID string seen: "182CA52027BCC862".
Set up play connection from 192.168.1.6 to self at 192.168.1.54.
Output written using MMAP
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 writing 351 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2410.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2411.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3567.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3548.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2359.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3159.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3030.
RTSP shutdown requested.
Closing down RTSP conversation thread...
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
^Cshutdown requested...
avahi: avahi_unregister.
Request to shut down all rtsp conversation threads
chip@chip-studio:~$

vitospinelli on 3 Dec 2016

Ok, I think I understand... I run a song for about 4-5 minutes...

Here's what I get:

hip@chip-studio:~$ shairport-sync -a "chip-studio" -vv -- -d default
Looking for the configuration file "/usr/local/etc/shairport-sync.conf".
Looking for configuration file at full path "/usr/local/etc/shairport-sync.conf"
Output device name is "default".
The processor is running little-endian.
Version: "2.8.6-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 0.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "chip-studio".
Audio Output name is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
use_mmap_if_available is 1.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
metdata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: service 'EEE5F4C98F05@chip-studio' group is not yet commited.
avahi: request to add "_raop._tcp" service without metadata
avahi: service 'EEE5F4C98F05@chip-studio' group is registering.
avahi: service 'EEE5F4C98F05@chip-studio' successfully added.
New RTSP connection from [fe80::c17:677c:db20:bd65]:55623 to self at [fe80::3aa2:8cff:fe5e:88df]:5000.
New RTSP connection from 192.168.1.6:55624 to self at 192.168.1.54:5000.
Play connection from user agent "AirPlay/280.33".
Active-Remote string seen: "3803707937".
DACP-ID string seen: "6261CA7DA38EE986".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=62004 tport=61678.
Set up play connection from fe80::c17:677c:db20:bd65 to self at fe80::3aa2:8cff:fe5e:88df.
listening for audio, control and timing on ports 6001, 6002, 6003.
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing sender thread starting.
Audio receiver -- Server RTP thread starting.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.
volume: -16.145039

syncing to seqno 31457.
Output written using MMAP
PCM handle name = 'default'
alsa device parameters:
  access type = MMAP_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 23219 us (>).
  period_size = 1024 frames (precisely).
  buffer_time = 185759 us (>).
  buffer_size = 8192 frames (>).
  periods_per_buffer = 8 (precisely).
syncing to seqno 31469.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8020.4,    23412.9,   484549.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.6,    20500.9,   452384.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8128.7,    17636.7,   509611.0.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 351 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 6203.
syncing to seqno 39610.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
syncing to seqno 39864.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2745.
syncing to seqno 40405.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 writing 50 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
syncing to seqno 40596.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Error -32 getting dac_delay in buffer_get_frame.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7853.2,    25300.3,   536607.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7993.0,    22547.6,   538822.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8006.7,    21735.8,   541470.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8004.8,    27607.6,   535112.0.
Error -32 writing 351 samples in play(): "Broken pipe".
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8013.1,    24421.5,   532148.0.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 351 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 5115.
syncing to seqno 51996.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8001.2,    19231.6,   525984.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.8,    14288.4,   359151.0.
RTSP shutdown requested.
Closing down RTSP conversation thread...
Shut down audio, control and timing threads
Audio receiver -- Server RTP thread interrupted. terminating.
Control RTP thread interrupted. terminating.
Timing thread interrupted. terminating.
rtp_timing_sender thread interrupted. terminating.
Closed and terminated timer requester thread.
Timing RTP thread terminated.
timing thread joined
audio thread joined
control thread joined
Player thread exit
shutting down RTP thread
RTSP conversation thread terminated.
^Cshutdown requested...
avahi: avahi_unregister.
Request to shut down all rtsp conversation threads
asking playing threads to stop
chip@chip-studio:~$

I hope this helps figuring out what the issue is. I appreciate your support. Many thanks.

vitospinelli on 3 Dec 2016

Thanks for the posts – you're getting the hang of it! So, looking at entries like:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8001.2,    19231.6,   525984.0.

I am reading a story of a troubled network connection. Each packet contains 352 frames of audio, which should last 352/44100 of a second, i.e. 7981.86 microseconds approximately – here you see the average interval is measured at 8001.2 microseconds, not too bad. The second is the standard deviation, which is a measure of the spread of actual values around the average. The bigger the standard deviation, the more the amount of variation. It is not too bad either. The third is the longest interval between packets. Remember they should come in on average approximately every 8 milliseconds. This is saying that the longest interval is over half a second. So it looks like there might be periodic dropouts on your network connection. What is causing them is hard to work out. Sometimes it might be just a weak signal. Sometimes it's an incorrect setting somewhere. Sometimes it's a poor quality router.

Here is what I get when I connect from an iPhone 6 using its Music app to a CHIP:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7955.1,    14621.0,   141445.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,    16502.9,   155795.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.4,    16412.4,   153678.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7986.0,    14876.1,   148424.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7971.3,    15981.4,   149085.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.1,    16610.1,   144160.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7991.6,    16500.0,   151074.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7966.4,    14373.7,   146602.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.3,    15745.2,   143435.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.8,    15255.2,   141727.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,    16326.6,   156970.0.

It would be worthwhile turning on statistics too, just to see what the story is...

mikebrady on 3 Dec 2016

Hey. I have the same issue with my CHIP
sample log:

Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.5,     3662.5,    65940.0.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.1,     3576.7,    34642.0.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 6043.
syncing to seqno 14933.
Open Mixer
Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.7,     3762.2,    65483.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.0,     2488.9,    35116.0.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 13096.
syncing to seqno 20203.
Open Mixer
Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.5,     2418.7,    31465.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.2,     2271.5,    26495.0.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 7810.
syncing to seqno 25479.
Open Mixer
Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.8,     2582.8,    38116.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.9,     3041.4,    43592.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.7,     4903.7,   196276.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.2,     2787.7,    31775.0.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 11798.
syncing to seqno 35972.
Open Mixer
Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.8,     7312.9,   295190.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.2,     3488.7,    61315.0.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 7354.
syncing to seqno 41232.
Open Mixer
Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.9,     5938.1,   180213.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7984.0,     2966.6,    31169.0.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 10372.
syncing to seqno 46512.
Open Mixer
Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.5,     5607.9,   226088.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.8,     2944.9,    49189.0.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 7309.
syncing to seqno 51743.
Open Mixer
Setting volume db to -2921.401737.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.4,     5975.2,   245333.0.

No issues while playing on the RPi tought (from iTunes, multiple sources selected).

even when I create AP on CHIP I get stutters:

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.8,     1242.5,    15544.0.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 6349.
syncing to seqno 38395.
Open Mixer
Setting volume db to -3162.530731.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.1,     1581.8,    50432.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.4,    10248.7,   509902.0.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 8389.
syncing to seqno 43655.
Open Mixer
Setting volume db to -3162.530731.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.9,     3758.0,   114432.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.9,     1879.6,    32260.0.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 10843.
syncing to seqno 48863.
Open Mixer
Setting volume db to -3162.530731.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.4,     8353.9,   412887.0.

roblan on 11 Dec 2016

hi mike,

i seem to be having a similar issue at my site. i'm using moodeaudio on my raspberry pi 1b with shairplay-sync and a hifiberry dac. playback works fine with mpd as audio source, but interrupts every few minutes with airplay.
i just yesterday upgraded from a cheap usb soundcard to the dac. i didn't have any interruption issues with airplay before, so one could assume it's hardware-related, but from this github thread and the log of shairplay-sync, i get a different impression.
the rpi is connected via ethernet, the airplay sources are a macbook (2010) and an iphone se, both via wifi.

output of one play session (see first line for all the params) below. i copied the command line args that moodeaudio uses to launch shairplay-sync to have its configuration as close as possible to the real use before/later within moodeaudio.
i also monitored cpu usage while playing and it low (less than 15%) until the interruption happens - presumably, resyncing costs some extra cycles?

any ideas what could be wrong?

pi@rasputin:~ $ sudo /usr/local/bin/shairport-sync --statistics -vv -a "rasputin Airplay" -S soxr -w -B /var/www/command/spspre.sh -E /var/www/command/spspost.sh --metadata-pipename=/tmp/shairport-sync-metadata --get-coverart -- -d hw:0
Looking for the configuration file "/usr/local/etc/shairport-sync.conf".
Can't resolve the configuration file "/usr/local/etc/shairport-sync.conf".
Output device name is "hw:0".
The processor is running little-endian.
Version: "2.8.6-OpenSSL-Avahi-ALSA-stdout-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "rasputin Airplay".
Audio Output name is "(null)".
on-start action is "/var/www/command/spspre.sh".
on-stop action is "/var/www/command/spspost.sh".
wait-cmd status is 1.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
use_mmap_if_available is 1.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/usr/local/etc/shairport-sync.conf" can not be resolved.
metdata enabled is 1.
metadata pipename is "/tmp/shairport-sync-metadata".
metadata socket address is "(null)" port 0.
metadata socket packet size is "0".
get-coverart is 1.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: service 'F03D95B30599@rasputin Airplay' group is not yet commited.
avahi: request to add "_raop._tcp" service with metadata
avahi: service 'F03D95B30599@rasputin Airplay' group is registering.
avahi: service 'F03D95B30599@rasputin Airplay' successfully added.
New RTSP connection from [fe80::183e:2599:9813:db59]:50059 to self at [fe80::3a4b:3731:db3:170f]:5000.
Play connection from user agent "AirPlay/310.15".
Active-Remote string seen: "2718286547".
DACP-ID string seen: "67981759B1569357".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=62454 tport=62869.
Set up play connection from fe80::183e:2599:9813:db59 to self at fe80::3a4b:3731:db3:170f.
listening for audio, control and timing on ports 6001, 6002, 6003.
sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Audio receiver -- Server RTP thread starting.
Timing sender thread starting.
volume: -1.803533

syncing to seqno 13544.
Output written with RW
PCM handle name = 'hw:0'
alsa device parameters:
  access type = RW_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 23219 us (>).
  period_size = 1024 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 128 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.3,    11889.4,    45012.0.
     -70.1,      17.4,      17.4,        3758,      0,      0,      0,      0,   4342,  223,  233
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.8,    12052.0,    75580.0.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.8,    12126.6,    60083.0.
     -29.6,    -123.2,     183.7,        7516,      0,      0,      0,      0,      0,  221,  248
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.5,    11973.2,    59348.0.
      39.2,       0.0,       0.0,       11274,      0,      0,      0,      0,   6145,  223,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.2,    11991.2,    60893.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8074.4,    15925.7,   541917.0.
     -23.4,       0.0,       0.0,       15032,      0,     31,      0,     31,   5657,  163,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.1,    12044.9,    83838.0.
     -79.4,      35.5,      35.5,       18790,      0,     31,      0,     31,   4699,  220,  235
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.8,    12013.8,    68375.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,    11874.6,    52072.0.
     -83.4,      46.9,      46.9,       22548,      0,     31,      0,     31,   3250,  222,  238
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.4,    11951.7,    61513.0.
     -84.1,      49.9,      49.9,       26306,      0,     31,      0,     31,   1727,  221,  242
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7975.5,    11976.9,    68388.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8073.5,    15866.1,   529798.0.
     -83.0,      46.1,      46.1,       30064,      0,     60,      0,     60,   4760,  164,  232
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.0,    11918.4,    76633.0.
     -83.4,      57.5,      57.5,       33822,      0,     60,      0,     60,    711,  220,  244
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.3,    12000.9,    66798.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.6,    11961.8,    51597.0.
     -84.0,      52.9,      52.9,       37580,      0,     62,      0,     62,   4524,  222,  235
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.5,    12157.8,    97456.0.
     -83.3,      48.4,      48.4,       41338,      0,     62,      0,     62,   2985,  218,  239
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.1,    11898.0,    54476.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.8,    11955.4,    61718.0.
     -83.1,      51.4,      51.4,       45096,      0,     62,      0,     62,   1560,  221,  243
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.0,    11857.7,    43804.0.
     -84.1,      48.4,      48.4,       48854,      0,     62,      0,     62,   3214,  223,  238
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.2,    11897.1,    50988.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7968.7,    11915.9,    46099.0.
     -80.9,      53.7,      53.7,       52612,      0,     62,      0,     62,    499,  222,  244
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.0,    11958.9,    61221.0.
     -84.2,      51.4,      51.4,       56370,      0,     62,      0,     62,   4169,  222,  234
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,    11945.2,    52716.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.0,    11938.7,    65873.0.
     -84.1,      53.7,      53.7,       60128,      0,     62,      0,     62,    395,  222,  245
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.7,    12022.1,    75315.0.
     -84.1,      48.4,      48.4,       63886,      0,     62,      0,     62,   3217,  221,  237
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.5,    11954.4,    51085.0.
Error -- ALSA device in incorrect state (4) for play.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: -2463.
syncing to seqno 14538.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.3,    11933.3,    52563.0.
     -74.8,      46.9,      46.9,       67644,      0,     62,      0,     62,      0,  220,  247
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7969.3,    12006.6,    93193.0.
     -48.2,       6.0,       6.0,       71402,      0,     62,      0,     62,   4965,  218,  232
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    11940.5,    49440.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.1,    12079.9,    53764.0.
     -83.2,      47.6,      47.6,       75160,      0,     62,      0,     62,   2187,  222,  241
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8063.4,    15986.1,   544424.0.
     -82.7,      55.2,      55.2,       78918,      0,     90,      0,     90,   2908,  163,  239
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.8,    11956.5,    53732.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.4,    12231.6,    67880.0.
     -82.3,      49.1,      49.1,       82676,      0,     91,      0,     91,   1090,  220,  244
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.4,    12133.1,    56047.0.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: -2388.
syncing to seqno 33322.
     -72.8,      42.3,      42.3,       86434,      0,     91,      0,     91,      0,  222,  246
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.2,    11994.6,    57266.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.9,    12102.1,    64822.0.
     -62.7,      12.1,      12.1,       90192,      0,     91,      0,     91,   4356,  222,  234
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.6,    11934.2,    62545.0.
     -79.9,      43.8,      43.8,       93950,      0,     91,      0,     91,   1673,  222,  242
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.9,    11911.2,    57661.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.0,    11894.3,    58255.0.
     -79.3,      52.2,      52.2,       97708,      0,     91,      0,     91,   2463,  220,  240
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.3,    11960.6,    75595.0.
     -84.1,      60.5,      60.5,      101466,      0,     91,      0,     91,    913,  220,  243
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.8,    12072.7,    60735.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.0,    11913.8,    61262.0.
     -83.9,      46.9,      46.9,      105224,      0,     91,      0,     91,   3097,  216,  238
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.8,    12090.6,   107989.0.
     -83.9,      59.7,      59.7,      108982,      0,     91,      0,     91,   1893,  223,  240
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.4,    12004.5,    56254.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.0,    12182.5,    49435.0.
     -83.6,      45.4,      45.4,      112740,      0,     91,      0,     91,   4557,  222,  234
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.1,    12225.7,    65833.0.
     -84.1,      54.4,      54.4,      116498,      0,     91,      0,     91,   3786,  223,  236
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.2,    12140.7,    54610.0.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: -2314.
syncing to seqno 1264.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.7,    12183.8,    71147.0.

jonastr on 1 Mar 2017

Hi Jonas. Thanks for the interesting post. Could you see if turning stuffing back to "basic" makes a difference? The minimum size of the queue does seems to drop away quite a bit – maybe the Pi is a bit overloaded. Can't think how changing the output device might make any difference but it's worth checking anyhow, I think. (?)

mikebrady on 1 Mar 2017

hi mike,
thanks for the lighting-fast reply on this one!

just checked with the macbook connected via ethernet. so all devices, rpi and macbook on the same switched network. seems to works really fine, as far as i can tell so far. also the stddev and max are way more close to the mean then. :)

back on wifi, the trouble is back real soon (after a half a minute or so). i switched wifi channels in between, but apparently that doesn't help either.

so i doubt it's a load issue.. on first sight, it's a wifi issue, only that i didn't touch it for quite some time and it still works fine for everything except airplay. :) all devices are in the same room, so that should be easy for the wifi, too.

where can i check the min size of the queue?
will try with the stuffing option and post the results.

cheers

jonastr on 1 Mar 2017

hi mike,

here's two more logs with 'basic' and soxr stuffing. i'm about to call it a day, so didn't try for too long, but at least basic achieved like 8 minutes of continuous play without issues, soxr interrupted again within the first minute. first, find the log for 'basic' stuffing, second another log with 'soxr' stuffing. this seems to make a difference on wifi - but didn't via ethernet.
looks strange to me - if the pi would generally be overloaded, it should not depend on wifi/no-wifi. or should it, because worse connection means more stuffing?

basic stuffing:

pi@rasputin:~ $ /usr/local/bin/shairport-sync --statistics -vv -a "rasputin Airplay" -S basic -w -B /var/www/command/spspre.sh -E /var/www/command/spspost.sh --metadata-pipename=/tmp/shairport-sync-metadata --get-coverart -- -d hw:0
Looking for the configuration file "/usr/local/etc/shairport-sync.conf".
Can't resolve the configuration file "/usr/local/etc/shairport-sync.conf".
Output device name is "hw:0".
The processor is running little-endian.
Version: "2.8.6-OpenSSL-Avahi-ALSA-stdout-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "rasputin Airplay".
Audio Output name is "(null)".
on-start action is "/var/www/command/spspre.sh".
on-stop action is "/var/www/command/spspost.sh".
wait-cmd status is 1.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "0" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
use_mmap_if_available is 1.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/usr/local/etc/shairport-sync.conf" can not be resolved.
metdata enabled is 1.
metadata pipename is "/tmp/shairport-sync-metadata".
metadata socket address is "(null)" port 0.
metadata socket packet size is "0".
get-coverart is 1.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: service 'F03D95B30599@rasputin Airplay' group is not yet commited.
avahi: request to add "_raop._tcp" service with metadata
avahi: service 'F03D95B30599@rasputin Airplay' group is registering.
avahi: service 'F03D95B30599@rasputin Airplay' successfully added.
New RTSP connection from [fe80::183e:2599:9813:db59]:50523 to self at [fe80::3a4b:3731:db3:170f]:5000.
Play connection from user agent "AirPlay/310.15".
Active-Remote string seen: "846992014".
DACP-ID string seen: "7D9C92886A08CEF5".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=54494 tport=65477.
Set up play connection from fe80::183e:2599:9813:db59 to self at fe80::3a4b:3731:db3:170f.
listening for audio, control and timing on ports 6001, 6002, 6003.
sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Audio receiver -- Server RTP thread starting.
Timing sender thread starting.
volume: -7.180439

syncing to seqno 49073.
Output written with RW
PCM handle name = 'hw:0'
alsa device parameters:
  access type = RW_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 23219 us (>).
  period_size = 1024 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 128 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,    11969.7,    62528.0.
     -34.0,       0.0,       0.0,        3758,      0,      0,      0,      0,   4631,  222,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.0,    11912.9,    60478.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.6,    11874.3,    49126.0.
     -81.6,      37.0,      37.0,        7516,      0,      0,      0,      0,   5880,  222,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.2,    11985.5,    57550.0.
     -83.9,      53.7,      53.7,       11274,      0,      0,      0,      0,   5840,  223,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.2,    11971.8,    65488.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.2,    11972.1,    57087.0.
     -83.9,      49.1,      49.1,       15032,      0,      0,      0,      0,   5920,  222,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7990.2,    12102.0,    77404.0.
     -84.0,      49.9,      49.9,       18790,      0,      0,      0,      0,   5935,  221,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.1,    11987.0,    55228.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.7,    11953.9,    53522.0.
     -83.9,      61.2,      61.2,       22548,      0,      0,      0,      0,   6051,  223,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7989.5,    12081.0,    49345.0.
     -83.8,      46.9,      46.9,       26306,      0,      0,      0,      0,   5773,  222,  231
volume: -8.519375

volume: -10.102999

volume: -12.041201

Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.8,    11869.3,    40914.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7988.9,    11939.4,    57014.0.
     -84.1,      52.2,      52.2,       30064,      0,      0,      0,      0,   5610,  223,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.3,    11975.6,    65121.0.
     -83.6,      55.2,      55.2,       33822,      0,      0,      0,      0,   5854,  221,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8086.4,    15928.3,   541698.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8087.2,    15499.8,   504531.0.
     -83.9,      48.4,      48.4,       37580,      0,     67,      0,     67,   5645,  162,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.8,    12004.2,    57715.0.
     -83.9,      50.6,      50.6,       41338,      0,     67,      0,     67,   5745,  223,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,    11936.6,    48713.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    11924.6,    48577.0.
     -81.1,      55.2,      55.2,       45096,      0,     67,      0,     67,   5963,  221,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.2,    11911.4,    62566.0.
     -79.3,      49.9,      49.9,       48854,      0,     67,      0,     67,   5955,  222,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.8,    11882.3,    52457.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,    12049.5,    76211.0.
     -81.7,      48.4,      48.4,       52612,      0,     67,      0,     67,   5863,  220,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7977.6,    11965.8,   104604.0.
     -84.0,      51.4,      51.4,       56370,      0,     67,      0,     67,   5823,  216,  230
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.1,    11866.0,    52103.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.6,    11966.8,    61474.0.
     -84.0,      55.2,      55.2,       60128,      0,     67,      0,     67,   5903,  222,  230
^Cshutdown requested...
avahi: avahi_unregister.
Request to shut down all rtsp conversation threads
asking playing threads to stop
RTSP shutdown requested.
Closing down RTSP conversation thread...
Playback Stopped. Total playing time 00:08:17

soxr stuffing:

pi@rasputin:~ $ /usr/local/bin/shairport-sync --statistics -vv -a "rasputin Airplay" -S soxr -w -B /var/www/command/spspre.sh -E /var/www/command/spspost.sh --metadata-pipename=/tmp/shairport-sync-metadata --get-coverart -- -d hw:0
Looking for the configuration file "/usr/local/etc/shairport-sync.conf".
Can't resolve the configuration file "/usr/local/etc/shairport-sync.conf".
Output device name is "hw:0".
The processor is running little-endian.
Version: "2.8.6-OpenSSL-Avahi-ALSA-stdout-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "rasputin Airplay".
Audio Output name is "(null)".
on-start action is "/var/www/command/spspre.sh".
on-stop action is "/var/www/command/spspost.sh".
wait-cmd status is 1.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
use_mmap_if_available is 1.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/usr/local/etc/shairport-sync.conf" can not be resolved.
metdata enabled is 1.
metadata pipename is "/tmp/shairport-sync-metadata".
metadata socket address is "(null)" port 0.
metadata socket packet size is "0".
get-coverart is 1.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: service 'F03D95B30599@rasputin Airplay' group is not yet commited.
avahi: request to add "_raop._tcp" service with metadata
avahi: service 'F03D95B30599@rasputin Airplay' group is registering.
avahi: service 'F03D95B30599@rasputin Airplay' successfully added.
New RTSP connection from [fe80::183e:2599:9813:db59]:50574 to self at [fe80::3a4b:3731:db3:170f]:5000.
Play connection from user agent "AirPlay/310.15".
Active-Remote string seen: "366971512".
DACP-ID string seen: "75BFFB9486227B47".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=54760 tport=50630.
Set up play connection from fe80::183e:2599:9813:db59 to self at fe80::3a4b:3731:db3:170f.
listening for audio, control and timing on ports 6001, 6002, 6003.
sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Audio receiver -- Server RTP thread starting.volume: -12.041201

Sync packet received before we got a timing packet back.

Timing sender thread starting.
syncing to seqno 38194.
Output written with RW
PCM handle name = 'hw:0'
alsa device parameters:
  access type = RW_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 23219 us (>).
  period_size = 1024 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 128 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.3,    11984.5,    57212.0.
     -36.8,       0.0,       0.0,        3758,      0,      0,      0,      0,   4379,  222,  232
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.0,    11953.5,    55366.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.4,    11967.1,    53823.0.
     -82.4,      39.3,      39.3,        7516,      0,      0,      0,      0,   4150,  223,  235
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Error -32 writing 351 samples in play(): "Broken pipe".
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.6,    12179.6,    62768.0.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 351 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 4899.
syncing to seqno 48511.
^Cshutdown requested...
avahi: avahi_unregister.
Request to shut down all rtsp conversation threads
asking playing threads to stop
RTSP shutdown requested.
Closing down RTSP conversation thread...
Playback Stopped. Total playing time 00:01:33

jonastr on 1 Mar 2017

hi mike,

sorry for spamming a bit. 😁 i did another round with the previous USB sound card. changed nothing else, only the output and that seems to work fine gain, although i also see some spikes in the "max" reception values.

what i find otherwise interesting is that the stats it outputs at startup suggest there's a bigger buffer in alsa for the USB device than for the I2S DAC. can you confirm that? any chance tweaking that might help? and how to to tweak it? :)

USB

  period_size = 256 frames (precisely).
  buffer_time = 5944308 us (>).
  buffer_size = 262144 frames (>).
  periods_per_buffer = 1024 (precisely).

I2S:

  period_size = 1024 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 128 (precisely).

pi@rasputin:~ $ /usr/local/bin/shairport-sync --statistics -vv -a "rasputin Airplay" -S soxr -w -B /var/www/command/spspre.sh -E /var/www/command/spspost.sh --metadata-pipename=/tmp/shairport-sync-metadata --get-coverart -- -d hw:1 -c Speaker
Looking for the configuration file "/usr/local/etc/shairport-sync.conf".
Can't resolve the configuration file "/usr/local/etc/shairport-sync.conf".
Output device name is "hw:1".
Open Mixer
Hardware mixer has dB volume from -28.370000 to -0.060000.
Has mute ability.
The processor is running little-endian.
Version: "2.8.6-OpenSSL-Avahi-ALSA-stdout-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 1.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "rasputin Airplay".
Audio Output name is "(null)".
on-start action is "/var/www/command/spspre.sh".
on-stop action is "/var/www/command/spspost.sh".
wait-cmd status is 1.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 2205.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 88 frames.
password is "(null)".
ignore_volume_control is 0.
playback_mode is 0 (0-stereo, 1-mono).
disable_synchronization is 0.
use_mmap_if_available is 1.
audio backend desired buffer length is 6615.
audio backend latency offset is 0.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
configuration file name "/usr/local/etc/shairport-sync.conf" can not be resolved.
metdata enabled is 1.
metadata pipename is "/tmp/shairport-sync-metadata".
metadata socket address is "(null)" port 0.
metadata socket packet size is "0".
get-coverart is 1.
Successful Startup
avahi: avahi_register.
avahi: register_service.
avahi: service 'F03D95B30599@rasputin Airplay' group is not yet commited.
avahi: request to add "_raop._tcp" service with metadata
avahi: service 'F03D95B30599@rasputin Airplay' group is registering.
avahi: service 'F03D95B30599@rasputin Airplay' successfully added.
New RTSP connection from [fe80::1055:fc8e:1f48:6550]:49297 to self at [fe80::3a4b:3731:db3:170f]:5000.
New RTSP connection from 192.168.5.28:49298 to self at 192.168.5.26:5000.
Play connection from user agent "AirPlay/310.15".
Active-Remote string seen: "1258851165".
DACP-ID string seen: "85245A80EB95BAC1".
User-Agent is AirPlay; selecting the AirPlay latency of -1 frames.
rtp_setup: cport=58307 tport=65426.
Set up play connection from fe80::1055:fc8e:1f48:6550 to self at fe80::3a4b:3731:db3:170f.
listening for audio, control and timing on ports 6001, 6002, 6003.
Closing down RTSP conversation thread...
RTSP conversation thread terminated.
sync error in frames, net correction in ppm, corrections in ppm, total packets, missing packets, late packets, too late packets, resend requests, min DAC queue size, min buffer occupancy, max buffer occupancy
Timing receiver -- Server RTP thread starting.volume: -1.803533

Setting volume db to -91.066638.
Control receiver -- Server RTP thread starting.
Sync packet received before we got a timing packet back.

Audio receiver -- Server RTP thread starting.
Timing sender thread starting.
syncing to seqno 27711.
Output written using MMAP
PCM handle name = 'hw:1'
alsa device parameters:
  access type = MMAP_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 5804 us (>).
  period_size = 256 frames (precisely).
  buffer_time = 5944308 us (>).
  buffer_size = 262144 frames (>).
  periods_per_buffer = 1024 (precisely).
Open Mixer
Setting volume db to -91.066638.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.9,    11856.8,    47853.0.
      33.0,     -15.3,      15.3,        3758,      0,      0,      0,      0,   4520,  224,  233
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7980.4,    11818.9,    45726.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7988.7,    15576.9,   517868.0.
      67.3,     -96.0,      96.0,        7516,      0,      2,      0,      2,   5892,  164,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.4,    11832.0,    37542.0.
      66.2,     -70.3,      70.3,       11274,      0,      2,      0,      2,   5618,  224,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.8,    11876.0,    44101.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.3,    11883.8,    45331.0.
      66.3,     -86.2,      87.7,       15032,      0,      2,      0,      2,   4392,  224,  234
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.2,    11822.6,    42035.0.
      67.4,     -99.0,      99.0,       18790,      0,      2,      0,      2,   4981,  225,  232
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7981.7,    11845.3,    39630.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7976.3,    11835.2,    41729.0.
      63.2,     -62.7,      62.7,       22548,      0,      2,      0,      2,   5804,  224,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.9,    11903.0,    40481.0.
      62.6,     -78.6,      78.6,       26306,      0,      2,      0,      2,   5323,  225,  232
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.8,    11874.1,    44870.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8038.7,    15963.4,   542517.0.
      61.2,     -90.7,      90.7,       30064,      0,     21,      0,     21,   5808,  163,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.6,    12141.2,    57230.0.
      66.8,     -82.4,      82.4,       33822,      0,     21,      0,     21,   5859,  220,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.8,    12258.6,    49252.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7979.9,    11757.8,    40766.0.
      67.0,     -81.6,      81.6,       37580,      0,     21,      0,     21,   5929,  223,  231
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7978.2,    11794.3,    53995.0.
      67.1,     -80.1,      81.6,       41338,      0,     21,      0,     21,   4565,  223,  232

jonastr on 2 Mar 2017

hi mike,

for the record:
i tinkered around with various settings in shairport-sync.conf to increase the device's buffer, but to no avail. i suppose these are hardware limits.
but then i managed to resolve this issue by increasing the backend buffer for alsa using shairport-sync.conf. for the usual sampling rate used by airplay, i set the buffer to cover a second of playback.

alsa =
{
  audio_backend_buffer_desired_length = 44100
};

this apparently gives the wifi more time to recover in case of hickups and so shairport does not even need to start stuffing every now and then.

best thanks much for your help!
jonas

jonastr on 4 Mar 2017

👍1

Thanks Jonas – I wasn't a lot of help, I'm afraid. I'm glad it worked out.

mikebrady on 4 Mar 2017

Dears,

I had exactly the same issue. Here's what helped me so far.
I am using a RPi 1 with HiFiBerry and Edimax WiFi, with Shairport-Sync 3.0.2. on piCorePlayer. On the same Pi I do run Squeezelite listening to Flac - no issue at all. So, I switched off the blame on Wifi.
With Mike's help, I have turned off all the synchronization settings in the config file, and I gave a 1 sec buffer for the stream. The sound flows now smoothly, juhuuu. Still, I did some double checking, and run _top_ in parallel with the "old" config. It looks like the delay analysis takes a lot of CPU, which my RPi 1 cannot deliver (above 80%) which is immediately audible.

Here's my config, I hope it helps:

// General Settings                                                                                                                                           
general =                                                                                                                                                     
{                                                                                                                                                             
        name = "%H"; // This means "Hostname" -- see below. This is the name the service will advertise to iTunes.                                            
//              The default is "Hostname" -- i.e. the machine's hostname with the first letter capitalised (ASCII only.)                                      
//              You can use the following substitutions:                                                                                                      
//                              %h for the hostname,                                                                                                          
//                              %H for the Hostname (i.e. with first letter capitalised (ASCII only)),                                                        
//                              %v for the version number, e.g. 3.0 and                                                                                       
//                              %V for the full version string, e.g. 3.0-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc                                     
//              Overall length can not exceed 50 characters. Example: "Shairport Sync %v on %H".                                                              
//      password = "secret"; // leave this commented out if you don't want to require a password                                                              
        interpolation = "soxr"; // aka "stuffing". Default is "basic", alternative is "soxr". Use "soxr" only if you have a reasonably fast processor.        
        output_backend = "alsa"; // Run "shairport-sync -h" to get a list of all output_backends, e.g. "alsa", "pipe", "stdout". The default is the first one.
//      mdns_backend = "avahi"; // Run "shairport-sync -h" to get a list of all mdns_backends. The default is the first one.                                  
//      port = 5000; // Listen for service requests on this port                                                                                              
//      udp_port_base = 6001; // start allocating UDP ports from this port number when needed                                                                 
//      udp_port_range = 100; // look for free ports in this number of places, starting at the UDP port base (only three are needed).                         
//      statistics = "no"; // set to "yes" to print statistics in the log                                                                                     
//      drift_tolerance_in_seconds = 0.002; // allow a timing error of this number of seconds of drift away from exact synchronisation before attempting to co
        resync_threshold_in_seconds = 0.0; // 0.050; // a synchronisation error greater than this number of seconds will cause resynchronisation; 0 disables i
        log_verbosity = 1; // "0" means no debug verbosity, "3" is most verbose.                                                                              
        ignore_volume_control = "yes"; // set this to "yes" if you want the volume to be at 100% no matter what the source's volume control is set to.        
//      volume_range_db = 60 ; // use this advanced setting to set the range, in dB, you want between the maximum volume and the minimum volume. Range is 30 t
//      volume_max_db = 0.0 ; // use this advanced setting, which must have a decimal point in it, to set the maximum volume, in dB, you wish to use.         
//              The setting is for the hardware mixer, if chosen, or the software mixer otherwise. The value must be in the mixer's range (0.0 to -96.2 for th
//              Leave it commented out to use mixer's maximum volume.                                                                                         
//      regtype = "_raop._tcp"; // Use this advanced setting to set the service type and transport to be advertised by Zeroconf/Bonjour. Default is "_raop._tc
//      playback_mode = "stereo"; // This can be "stereo", "mono", "reverse stereo", "both left" or "both right". Default is "stereo".                        
//      alac_decoder = "hammerton"; // This can be "hammerton" or "apple". This advanced setting allows you to choose                                         
//              the original Shairport decoder by David Hammerton or the Apple Lossless Audio Codec (ALAC) decoder written by Apple.                          
//      interface = "name"; // Use this advanced setting to specify the interface on which Shairport Sync should provide its service. Leave it commented out t
};                                                                                                                                                            

// How to deal with metadata, including artwork                                                                                                               
metadata =                                                                                                                                                    
{                                                                                                                                                             
        enabled = "no"; // set this to yes to get Shairport Sync to solicit metadata from the source and to pass it on via a pipe                             
//      include_cover_art = "no"; // set to "yes" to get Shairport Sync to solicit cover art from the source and pass it via the pipe. You must also set "enab
//      pipe_name = "/tmp/shairport-sync-metadata";                                                                                                           
//      pipe_timeout = 5000; // wait for this number of milliseconds for a blocked pipe to unblock before giving up                                           
//      socket_address = "226.0.0.1"; // if set to a host name or IP address, UDP packets containing metadata will be sent to this address. May be a multicast
//      socket_port = 5555; // if socket_address is set, the port to send UDP packets to                                                                      
//      socket_msglength = 65000; // the maximum packet size for any UDP metadata. This will be clipped to be between 500 or 65000. The default is 500.       
};                                                                                                                                                            

// Advanced parameters for controlling how a Shairport Sync runs                                                                                              
sessioncontrol =                                                                                                                                              
{                                                                                                                                                             
//      run_this_before_play_begins = "/full/path/to/application and args"; // make sure the application has executable permission. It it's a script, include 
//      run_this_after_play_ends = "/full/path/to/application and args"; // make sure the application has executable permission. It it's a script, include the
//      wait_for_completion = "no"; // set to "yes" to get Shairport Sync to wait until the "run_this..." applications have terminated before continuing      
//      allow_session_interruption = "no"; // set to "yes" to allow another device to interrupt Shairport Sync while it's playing from an existing audio sourc
        session_timeout = 3; // wait for this number of seconds after a source disappears before terminating the session and becoming available again.        
};                                                                                                                                                            

// Back End Settings                                                                                                                                          

// These are parameters for the "alsa" audio back end, the only back end that supports synchronised audio.                                                    
alsa =                                                                                                                                                        
{                                                                                                                                                             
    output_device = "hw:CARD=sndrpihifiberry"; // the name of the alsa output device. Use "alsamixer" or "aplay" to find out the names of devices, mixers, etc
//  mixer_control_name = "PCM"; // the name of the mixer to use to adjust output volume. If not specified, volume in adjusted in software.                    
//  mixer_device = "default"; // the mixer_device default is whatever the output_device is. Normally you wouldn't have to use this.                           
//  output_rate = 44100; // can be 44100, 88200, 176400 or 352800, but the device must have the capability.                                                   
//  output_format = "S16"; // can be "U8", "S8", "S16", "S24", "S24_3LE", "S24_3BE" or "S32", but the device must have the capability. Except where stated usi
//  audio_backend_latency_offset_in_seconds = 0.0; // Set this offset to compensate for a fixed delay in the audio back end. E.g. if the output device delays 
    audio_backend_buffer_desired_length_in_seconds = 1; // If set too small, buffer underflow occurs on low-powered machines. Too long and the response times 
    disable_synchronization = "yes"; // Set to "yes" to disable synchronization. Default is "no".                                                             
//  period_size = <number>; // Use this optional advanced setting to set the alsa period size near to this value                                              
//  buffer_size = <number>; // Use this optional advanced setting to set the alsa buffer size near to this value                                              
//  use_mmap_if_available = "yes"; // Use this optional advanced setting to control whether MMAP-based output is used to communicate  with the DAC. Default is
};

Here is the output log when running with those settings:

Output device name is "hw:CARD=sndrpihifiberry".
The processor is running little-endian.
Version: "3.0.2-OpenSSL-tinysvcmdns-ALSA-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 0.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "RpiSauna".
Audio Output name is "alsa".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 0.000000 seconds.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 0.001995 seconds.
password is "(null)".
ignore_volume_control is 1.
volume_max_db is not set
playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
disable_synchronization is 1.
use_mmap_if_available is 1.
output_rate is 44100.
output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
audio backend desired buffer length is 0.150000 seconds.
audio backend latency offset is 0.000000 seconds.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
no special mdns service interface was requested.
configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
metdata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
Successful Startup
New RTSP connection from 192.168.178.117:49990 to self at 192.168.178.95:5000.
Play connection from user agent "iTunes/10.6 (Macintosh; Intel Mac OS X 10.7.3) AppleWebKit/535.18.5".
Active-Remote string seen: "1986535575".
DACP-ID string seen: "56B29BB6CB904862".
User-Agent is iTunes 10 or better, (actual version is 10); selecting the iTunes latency of 0 frames.
rtp_setup: cport=58324 tport=61519.
Set up play connection from 192.168.178.117 to self at 192.168.178.95.
listening for audio, control and timing on ports 6001, 6002, 6003.
Output sample ratio is 1.
Output frame bytes is 4.
Output bit depth is 16.
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Audio receiver -- Server RTP thread starting.
Timing sender thread starting.
syncing to seqno 33554.
Hammerton Decoder used on unencrypted audio.
Output sample ratio is 1
Output written using MMAP
PCM handle name = 'hw:CARD=sndrpihifiberry'
alsa device parameters:
  access type = MMAP_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 5804 us (>).
  period_size = 256 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 512 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7174.5,    18953.3,   521836.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     6920.1,    16743.2,   413264.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7149.6,    28335.8,  1081084.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7115.7,    21339.4,   579634.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7117.3,    18103.6,   389438.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.1,    20144.5,   513441.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7107.6,    21456.1,   526559.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7158.8,    26564.0,   986590.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.0,    21084.5,   510594.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7115.1,    19176.6,   515010.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7118.2,    20524.1,   589323.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7114.3,    15712.7,   378314.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7127.8,    22368.8,   584251.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7253.7,    19075.0,   508424.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     6992.6,    16769.6,   510611.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7104.7,    20432.9,   533435.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7110.0,    19803.5,   508311.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7112.3,    17617.2,   480492.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7118.1,    16876.3,   331831.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7114.5,    18640.2,   512755.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7120.7,    21722.2,   527385.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7111.7,    18004.5,   505524.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7209.3,    29249.3,  1095733.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7105.0,    21871.2,   528628.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7133.5,    18781.3,   522858.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7107.8,    22437.6,   521836.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7116.7,    19842.8,   521102.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7117.2,    19595.4,   515892.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7112.1,    21301.3,   505432.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7120.8,    21787.1,   516960.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7104.0,    20182.0,   530225.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7106.4,    21251.0,   521443.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7159.8,    28394.9,  1083804.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7110.2,    18619.7,   506724.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7111.6,    14885.8,   315756.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7110.6,    21032.2,   517698.0.
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7112.6,    17634.8,   531454.0._

And, just for the records, the log before (check for "Delay error -32 when checking running latency") :

Output device name is "hw:CARD=sndrpihifiberry".
The processor is running little-endian.
Version: "3.0.2-OpenSSL-tinysvcmdns-ALSA-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 0.
daemon status is 0.
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
Shairport Sync player name is "RpiSauna".
Audio Output name is "alsa".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
mdns backend "(null)".
userSuppliedLatency is 0.
AirPlayLatency is -1.
iTunesLatency is -1.
forkedDaapdLatency is -1.
stuffing option is "1" (0-basic, 1-soxr).
resync time is 0.000000 seconds.
allow a session to be interrupted: 0.
busy timeout time is 120.
drift tolerance is 0.001995 seconds.
password is "(null)".
ignore_volume_control is 1.
volume_max_db is not set
playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
disable_synchronization is 0.
use_mmap_if_available is 1.
output_rate is 44100.
output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
audio backend desired buffer length is 0.150000 seconds.
audio backend latency offset is 0.000000 seconds.
volume range in dB (zero means use the range specified by the mixer): 0.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
no special mdns service interface was requested.
configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
metdata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
Successful Startup
New RTSP connection from 192.168.178.117:54774 to self at 192.168.178.95:5000.
Play connection from user agent "iTunes/10.6 (Macintosh; Intel Mac OS X 10.7.3) AppleWebKit/535.18.5".
Active-Remote string seen: "1986535575".
DACP-ID string seen: "56B29BB6CB904862".
User-Agent is iTunes 10 or better, (actual version is 10); selecting the iTunes latency of 0 frames.
rtp_setup: cport=55901 tport=63489.
Set up play connection from 192.168.178.117 to self at 192.168.178.95.
listening for audio, control and timing on ports 6001, 6002, 6003.
Output sample ratio is 1.
Output frame bytes is 4.
Output bit depth is 16.
Timing receiver -- Server RTP thread starting.
Control receiver -- Server RTP thread starting.
Timing sender thread starting.
Audio receiver -- Server RTP thread starting.
unrecognised parameter: "SET_PARAMETER rtsp://192.168.178.117/3245095222 RTSP/1.0" (56)

unrecognised parameter: "User-Agent: iTunes/10.6 (Macintosh; Intel Mac OS X 10.7.3) AppleWebKit/535.18.5" (79)

unrecognised parameter: "Client-Instance: 14a7d91245a15af2" (33)

unrecognised parameter: "DACP-IDID91245a15af2
DACP-ID
DACP-IDance: 14a7d91245a15af2
DACP-IDaf2
DACP-ID: 14a7d91245a15af2
DACP-ID: 14a7d91245a15af2
DACP-IDInstance: 14a7d91245a15af2
DACP-IDMac OS X 10.7.3) AppleWebKit/535.18.5
Client-Instance: 14a7d91245a15af2
DACP-IDebKit/535.18.5
Client-Instance: 14a7d91245a15af2
DACP-I?" (311)

no RTSP header received
rtsp_read_request error 2, packet ignored.
syncing to seqno 39382.
Hammerton Decoder used on unencrypted audio.
Output sample ratio is 1
Output written using MMAP
PCM handle name = 'hw:CARD=sndrpihifiberry'
alsa device parameters:
  access type = MMAP_INTERLEAVED
  format = 'S16_LE' (Signed 16 bit Little Endian)
  subformat = 'STD' (Standard)
  number of channels = 2
  number of significant bits = 16
  rate = 44100 frames per second (precisely).
  precise (rational) rate = 0.000 frames per second (i.e. 0/1088784512).
  period_time = 5804 us (>).
  period_size = 256 frames (precisely).
  buffer_time = 2972154 us (>).
  buffer_size = 131072 frames (>).
  periods_per_buffer = 512 (precisely).
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7114.6,    18677.3,   522235.0.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7114.0,    21899.5,   522528.0.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 352 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Error -- ALSA device in incorrect state (4) for play.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 237 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames.
Delay error -32 when checking running latency.
Error -32 writing 353 samples in play(): "Broken pipe".
Error -32 writing 353 samples in play(): "Broken pipe".
Error -- ALSA device in incorrect state (4) for play.
Error -32 in delay(): "Broken pipe". Delay reported is 0 frames._

sergiuburian on 6 May 2017

Thanks for this. One thing I would suggest is to turn off soxr stuffing, as it can really slow the processor down if a lot of stuffing is needed and if the processor is not very powerful.

mikebrady on 8 May 2017

Hi Mike,

Having the soxr stuffing ON but with the disabled synchronization, the CPU smoothly runs at 8%. Turning synchronization on brings the CPU loat to 50-80% most of the time. Does soxr have an impact on the synchronization algorithms, i.e. would synchronization run smoother with basic than with soxr ?

Thanks,
Sergiu

sergiuburian on 9 May 2017

Yes – soxr Is veryvprocessor intensive.

mikebrady on 9 May 2017

I've been having choppiness issues for quite some time. I'd be really grateful if someone would give me a hand troubleshooting :)

Symptoms

The connection seldom drops outright, the source usually just keeps playing, but sound output cuts in and out (sometimes with long periods of silence). Sometimes I get long periods of time in which playback works great, but eventually the choppiness returns (within a matter of hours). I wonder if it's a Wi-Fi interference issue as the problem seems to get worse after about 5pm (when my neighbours get home). Playback is also anecdotally more robust from my phone and iPad, compared to my laptop (which has much older Wi-Fi hardware). But having said that, none of these devices really struggle to stream video, even at times when shairport playback is choppy.

Setup

Wi-Fi router is a Huawei HG659b. I have access to the config panel and can tweak things if necessary, but I don't believe there are any weird settings enabled at present.
Raspberry Pi 3 (network connection is the built-in Wi-Fi only).
Raspbian, Jessie (8.0)
Output via headphone jack.
Wi-Fi power management is off.
My Pi is using the new, better, experimental audio drivers (audio_pwm_mode=2). However, I encountered the same issues with choppiness with the default drivers too.
Audio source devices: MacBook Pro (7 years old, so fairly old Wi-Fi hardware), iPad/iPhone (new, so modern Wi-Fi hardware).
Settings:

general = {
  name = "Pi";
  drift_tolerance_in_seconds = 0.010;
  volume_range_db = 30;
  log_verbosity = 2;
  statistics = "yes";
};

alsa = {
  output_device = "hw:0";
  mixer_control_name = "PCM";
};

Logs

Here's some log output in which you can see shairport-sync starting up. The pulseaudio error seems odd to me, as I built shairport with the --with-alsa option.

Jul 05 03:44:41 raspberrypi systemd[1]: Starting ShairportSync AirTunes receiver...
Jul 05 03:44:41 raspberrypi systemd[1]: Started ShairportSync AirTunes receiver.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Output device name is "hw:0".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Open Mixer
Jul 05 03:44:41 raspberrypi pulseaudio[23126]: [pulseaudio] server-lookup.c: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11
Jul 05 03:44:41 raspberrypi pulseaudio[23126]: [pulseaudio] main.c: Unable to contact D-Bus: org.freedesktop.DBus.Error.NotSupported: Unable to autolaunch a dbus-daemon without a $DISPLAY for X11
Jul 05 03:44:41 raspberrypi pulseaudio[23126]: [pulseaudio] bluez4-util.c: org.bluez.Manager.GetProperties() failed: org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" with signature "" on interface "org.bl
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Lowest dB value is a mute -- try minimum volume +1
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Hardware mixer has dB volume from -102.380000 to 4.000000.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Has mute ability.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: The processor is running little-endian.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Version: "3.0.2-OpenSSL-Avahi-ALSA-sysconfdir:/usr/local/etc"
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: statistics_requester status is 1.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: daemon status is 0.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: rtsp listening port is 5000.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: udp base port is 6001.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: udp port range is 100.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Shairport Sync player name is "Pi".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Audio Output name is "(null)".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: on-start action is "(null)".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: on-stop action is "(null)".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: wait-cmd status is 0.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: mdns backend "(null)".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: userSuppliedLatency is 0.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: AirPlayLatency is -1.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: iTunesLatency is -1.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: forkedDaapdLatency is -1.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: stuffing option is "0" (0-basic, 1-soxr).
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: resync time is 0.050000 seconds.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: allow a session to be interrupted: 0.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: busy timeout time is 120.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: drift tolerance is 0.010000 seconds.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: password is "(null)".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: ignore_volume_control is 0.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: volume_max_db is not set
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: disable_synchronization is 0.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: use_mmap_if_available is 1.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: output_rate is 44100.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: audio backend desired buffer length is 0.150000 seconds.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: audio backend latency offset is 0.000000 seconds.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: volume range in dB (zero means use the range specified by the mixer): 30.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: zeroconf regtype is "_raop._tcp".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: decoders_supported field is 3.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: use_apple_decoder is 0.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: no special mdns service interface was requested.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: configuration file name "/usr/local/etc/shairport-sync.conf" resolves to "/usr/local/etc/shairport-sync.conf".
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: Successful Startup
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: avahi: avahi_register.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: avahi: register_service.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: avahi: service '127125672F1E@Pi' group is not yet commited.
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: avahi: request to add "_raop._tcp" service without metadata
Jul 05 03:44:41 raspberrypi shairport-sync[23119]: avahi: service '127125672F1E@Pi' group is registering.
Jul 05 03:44:42 raspberrypi shairport-sync[23119]: avahi: service '127125672F1E@Pi' successfully added.
Jul 05 03:44:43 raspberrypi shairport-sync[23119]: New RTSP connection from 192.168.1.74:53404 to self at 192.168.1.73:5000.
Jul 05 03:44:44 raspberrypi shairport-sync[23119]: Closing down RTSP conversation thread...
Jul 05 03:44:44 raspberrypi shairport-sync[23119]: RTSP conversation thread terminated.

Here's some log output for a period in which I had playback issues. In this sample there are a lot of "buffers exhausted" lines, but I've also seen samples with lots (LOTS) of "first packet is late" lines and few "buffers exhausted".

raspberrypi:Downloads$ sudo journalctl -u shairport-sync.service --since 3:29
-- Logs begin at Mon 2017-07-03 00:17:01 UTC, end at Wed 2017-07-05 03:30:13 UTC. --
Jul 05 03:29:10 raspberrypi shairport-sync[19996]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7982.2,    10209.7,   134457.0.
Jul 05 03:29:22 raspberrypi shairport-sync[19996]: -5.4,      47.0,      47.0,        3758,      0,     98,      0,     60,   5082,  228,  268
Jul 05 03:29:30 raspberrypi shairport-sync[19996]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8017.3,    29337.2,   871829.0.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2821.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: syncing to seqno 65454.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: First packet is late! It should have played before now. Flushing 0.1 seconds
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: syncing to seqno 65467.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: First packet is late! It should have played before now. Flushing 0.1 seconds
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: syncing to seqno 65480.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Open Mixer
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Setting volume db to -112.679291.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:40 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 2435.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: syncing to seqno 190.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: First packet is late! It should have played before now. Flushing 0.1 seconds
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: syncing to seqno 203.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: First packet is late! It should have played before now. Flushing 0.1 seconds
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: syncing to seqno 216.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: First packet is late! It should have played before now. Flushing 0.1 seconds
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: syncing to seqno 229.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Open Mixer
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Setting volume db to -112.679291.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:42 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:51 raspberrypi shairport-sync[19996]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     8360.1,    32479.0,   728014.0.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:52 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:29:53 raspberrypi shairport-sync[19996]: 4.2,     -15.9,     294.1,        7516,     53,    281,    142,    317,      0,    0,  264
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:00 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Buffers exhausted.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 5479.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: syncing to seqno 2525.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: First packet is late! It should have played before now. Flushing 0.1 seconds
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: syncing to seqno 2538.
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Open Mixer
Jul 05 03:30:01 raspberrypi shairport-sync[19996]: Setting volume db to -112.679291.
Jul 05 03:30:04 raspberrypi shairport-sync[19996]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: -5786.
Jul 05 03:30:04 raspberrypi shairport-sync[19996]: syncing to seqno 2947.
Jul 05 03:30:04 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:30:04 raspberrypi shairport-sync[19996]: Open Mixer
Jul 05 03:30:04 raspberrypi shairport-sync[19996]: Setting volume db to -112.679291.
Jul 05 03:30:06 raspberrypi shairport-sync[19996]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3818.
Jul 05 03:30:06 raspberrypi shairport-sync[19996]: syncing to seqno 3288.
Jul 05 03:30:06 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:30:06 raspberrypi shairport-sync[19996]: Open Mixer
Jul 05 03:30:06 raspberrypi shairport-sync[19996]: Setting volume db to -112.679291.
Jul 05 03:30:08 raspberrypi shairport-sync[19996]: syncing to seqno 3661.
Jul 05 03:30:08 raspberrypi shairport-sync[19996]: Output sample ratio is 1
Jul 05 03:30:08 raspberrypi shairport-sync[19996]: Open Mixer
Jul 05 03:30:08 raspberrypi shairport-sync[19996]: Setting volume db to -112.679291.
Jul 05 03:30:10 raspberrypi shairport-sync[19996]: Packet reception interval stats: mean, standard deviation and max for the last 2,500 packets in microseconds:     7826.2,    23853.0,   441885.0.

AndrewC-B on 5 Jul 2017

Thanks for the post. The only thing that jumps out is the very long maximum packet reception intervals -- almost half a second in one case and almost three quarters of a second in the other. The interval should nominally be 7.9 milliseconds. If it was possible, even temporarily, to use another router, it would help to narrow the problem down, I think.

mikebrady on 5 Jul 2017

Thanks for the reply 😊 Hmmm. That may not be easily accomplished, but I'll see what I can do. Thanks!

AndrewC-B on 5 Jul 2017

Yeah, I can imagine. The reason for suggesting it is to try to eliminate the router as a potential problem.
Along the same lines, it might be worth checking to see if there are firmware updates for the router.

I've used same Pi configuration you are using (though I'm using Jessie Lite, so PulseAudio isn't installed) both with the new and older audio drivers (new is unconditionally better, IMHO).

Maybe if you had a spare Pi lying around, you could set it up temporarily as an Access Point – though it would be quite a bit of work if you haven't done it before – and connect the devices over it.

mikebrady on 5 Jul 2017

I set my laptop up to share its wifi connection with the Pi via Ethernet and shut the Pi’s wlan interface down. It seems a bit backwards, but my theory is that my 7 year old Mac has better wifi hardware than my new Pi. So far, playback has been flawless. I’ll continue testing it out tomorrow.

So, assuming the issue is that the wifi signal isn’t quite strong enough for the Pi, what are my options? I could get a USB wifi adaptor for my Pi and hope it’s better than the built-in antenna, but that sounds like work :P Can I increase the size of a buffer in shairport instead? I don’t mind if it takes an extra second or two to start playing.

AndrewC-B on 5 Jul 2017

By setting the alsa audio_backend_latency_offset_in_seconds to a positive value, you lengthen the buffer by that number of seconds. The limit is 1.5 – i.e. an extra 1.5 seconds of samples.

Hmm, there might be something else going on in the Pi. is there anything in the logs that is suspicious w.r.t. networking?

If you turn on the Mac as a WiFi access point and connect the Pi to it, how are things?

mikebrady on 6 Jul 2017

Nothing apart from “buffer exhausted”, but you already implied that that’s not especially noteworthy.

I set up a 2nd gen AirPort Express (I can’t substitute this for my regular router for reasons which aren’t relevant here) for AirPlay in the same location as the Pi. Interestingly, playback via the AirPort drops in and out just as badly as it did on the Pi, although the AirPort seems to prefer to silence all audio for long periods, rather than “stuttering” the way Shairport does on the Pi (but this feels like an implementation difference to me).

So this much makes it feel like a signal quality issue, but then again, I can stream video (and audio) no problem, and my download and upload speeds in this location are excellent.

Setting the Mac up as an access point will require a little more disruption to my set up than I want to deal with today, but I’ll give it a shot over the weekend. I expect it to be much the same as when I set it up as a wired access point for the Pi (flawless playback, but only the Mac can AirPlay to the Pi with this set up, presumably because of NAT).

AndrewC-B on 7 Jul 2017

If you connect, say, an iPhone to the WiFi network created by the Mac, it should see the Pi. By the way, I'm talking about setting up the Mac as a full Access Point.

mikebrady on 7 Jul 2017

I actually tried the low-tech option of moving the router a little and was surprised to see the situation greatly improve. I'll keep testing for a few more days before I call it solved, but if this is all it took I'll be sorry to have bothered you! I appreciate your help.

AndrewC-B on 9 Jul 2017

That's very encouraging. Please keep us posted!

mikebrady on 9 Jul 2017

Since I opened this issue I might take the opportunity to close it.
I did two things, I opted to switch interpolation back to basic.
I also set the alsa parameter audio_backend_buffer_desired_length_in_seconds = 0.5.
I have no more dropouts, although whether it was cpu load (soxr choking) or wifi I will leave that for the gods.

Bazmundi on 23 Jul 2017

Thanks. I'm sorry to say that I didn't think of a soxr problem. If it continues to work well, it would be nice to let the buffer length in seconds go back to 0.15 and see how stable it remaims.

mikebrady on 23 Jul 2017

Yeah, well it ran fine last night.

I got home tonight, was bragging to wife that I "fixed" it.

It dropped then out for a couple of seconds.

But, all in all not at all as bad as it was as it would drop out every couple of songs previously. So I might leave it as is to monitor the frequency of dropout. I guess, as I changed two parameters, I have confounded the story somewhat. Otherwise I have finally got a couple of sub$50 soundbars so I might also set the other nodes with different parameters to get a feel for the best setup.

One thing I noted, version 3 brags multiple room audio? I think I noticed on my wife's old laptop iTunes that you could select more than one client connection. Her iPad seems only to allow one and only one?? Other than that, we aren't audiophiles and I haven't had to fork out for 3 BOSE wifi speakers so I am happy.

Thanks again.

Bazmundi on 24 Jul 2017

Yeah, the multiple room audio facility depends on the client – iTunes can do it, but iOS can not. Apple are bringing multi-room Audio in iOS 11, but it may not be compatible with this version of AirPlay. We are waiting with bated breath to find out.

mikebrady on 24 Jul 2017

So, are you thinking what I am thinking?

An audio server? shairport-cast?

Bazmundi on 27 Jul 2017

I really hope that Apple allows iOS to go multi-room audio in the same way as iTunes works on macOS. If not, then we'll have to start thinking about alternatives.

mikebrady on 27 Jul 2017

Shairport-sync: Very choppy?

Most helpful comment

All 77 comments

Symptoms

Setup

Logs

Related issues