search

mikebrady / shairport-sync

AirPlay and AirPlay 2 audio player
Other
7.2k stars 571 forks source link

Very choppy? #346

Closed Bazmundi closed 7 years ago

Bazmundi commented 8 years ago

Installed onto C.H.I.P. following instructions at: https://www.hackster.io/11798/c-h-i-p-play-speakers-7cebb9

Connects fine to my iTunes on my Windoze 10 pc.

Stutters and chops really badly.

What need I do to tune buffers or whatever is the problem please?

Cheers, B

mikebrady commented 8 years ago

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!

Bazmundi commented 8 years ago

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 commented 8 years ago

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

mikebrady commented 8 years ago

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.

Bazmundi commented 8 years ago

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 commented 8 years ago

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.

mikebrady commented 8 years ago

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

$ sudo iw wlan0 set power_save off
Bazmundi commented 8 years ago

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

mikebrady commented 8 years ago

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

Bazmundi commented 8 years ago

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 commented 8 years ago

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

Bazmundi commented 8 years ago

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.

mikebrady commented 8 years ago

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 commented 8 years ago

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?

Bazmundi commented 8 years ago

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.

mikebrady commented 8 years ago

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

Bazmundi commented 8 years ago

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

mikebrady commented 8 years ago

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.

Bazmundi commented 8 years ago

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.

mikebrady commented 8 years ago

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 commented 8 years ago

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.
Bazmundi commented 8 years ago

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.

mikebrady commented 8 years ago

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 notifications@github.com 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.

Bazmundi commented 8 years ago

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

mikebrady commented 8 years ago

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.

ghost commented 8 years ago

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?

joerg-krause commented 8 years ago

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 commented 8 years ago

@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

Bazmundi commented 8 years ago

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

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).

joerg-krause commented 8 years ago

@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:

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.

Bazmundi commented 8 years ago

@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

mikebrady commented 8 years ago

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 commented 8 years ago

@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.

ghost commented 8 years ago

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?

Bazmundi commented 8 years ago

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 commented 8 years ago

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

mikebrady commented 8 years ago

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

Bazmundi commented 8 years ago

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 commented 8 years ago

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.

mikebrady commented 8 years ago

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 commented 8 years ago

@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 commented 7 years ago

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

vitospinelli commented 7 years ago

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.

mikebrady commented 7 years ago

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?

vitospinelli commented 7 years ago

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...

mikebrady commented 7 years ago

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.

vitospinelli commented 7 years ago

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 commented 7 years ago

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.

mikebrady commented 7 years ago

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...

roblan commented 7 years ago

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.