audio after several hours. some pi's come back others don't

[vagend]

Hi Mike,

Thank you for the tremendous work you have done and for all the support you give. I hate open an issue for audio dropping out as I've searched and found others listed already but I need someone to point me in the right direction.

I just got my setup running this week so it has limited use so far.
I have a Pi3 , 2 Pi0W's and a Yamaha stereo as my multi room set up. All Pi's are setup identically. After considerable playback (I dont know a specific time) some Pi's will drop audio. They will come back in a few seconds usually but yesterday one has gone quiet and not come back. The Pi's are all accessible via VNC viewer. They all have wifi power management off. The (cat5 wired) yamaha stereo never drops.

eth0      no wireless extensions.

wlan0     IEEE 802.11  ESSID:"blahblahblah"  
          Mode:Managed  Frequency:2.457 GHz  Access Point: yaddayadda  
          Bit Rate=58.5 Mb/s   Tx-Power=31 dBm   
          Retry short limit:7   RTS thr:off   Fragment thr:off
          Power Management:off
          Link Quality=48/70  Signal level=-62 dBm  
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:1690  Invalid misc:0   Missed beacon:0

lo        no wireless extensions.

I did the shairport-sync installs and the alsa eq install using the add software gui in stretch.
I set the host names using the gui in stretch. The only change I made to the shairport-sync.conf was to enable interruptions allow_session_interruption = "yes"; because I would like to be able to hijack a room and play different music from the rest of the house by playing direct from my phone instead of the iTunes machine.

Thanks again.

[mikebrady]

Thanks for the post. Perhaps you could turn on logging in Shairport Sync, setting the log verbosity to 1 (not 2 or 3, as they generate too much diagnostics stuff to be useful over a long period). Then, when it happens again, have a look in the log at the right time and see what it says.

[vagend]

Thanks for the quick response. I've turned on the logging now so of its working fine now that its being watched. I'll see what happens this week. I have also changed a setting in my router that MIGHT help.

[leonmf]

Is this related to my problem where my rpi3 (2 of them) on wireless drops off after playing music for awhile and then refuses to let me reconnect via airplay because it's in use?

My current theory is that it's not handling the occasional wifi dropout but I haven't had a chance to investigate yet.

[mikebrady]

These problems can be very hard to understand and resolve, but yeah, your suggestion is very plausible. Turning on a low level of logging may help to find the cause.

[vagend]

How do I get the logs? Is it in var/log ?

[mikebrady]

For example, use something like $ sudo journalctl -n 100 -f to look at the last 100 lines of log entries and to follow any changes to the log. To enable Shairport Sync to output a low level of logging information to the log, set log verbosity=1 in its configuration file and restart it.

[vagend]

I did some googleing and have a little more data:

pi@The_Bar:/var/log $ sudo systemctl status shairport-sync
● shairport-sync.service - ShairportSync AirTunes receiver
   Loaded: loaded (/lib/systemd/system/shairport-sync.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2017-12-27 17:02:35 CST; 1 day 17h ago
     Docs: man:shairport-sync(7)
           file:///usr/share/doc/shairport-sync/README.md.gz
           https://github.com/mikebrady/shairport-sync
  Process: 372 ExecStart=/usr/bin/shairport-sync --daemon $DAEMON_ARGS (code=exited, status=0/SUCCESS)
 Main PID: 437 (shairport-sync)
   CGroup: /system.slice/shairport-sync.service
           └─437 /usr/bin/shairport-sync --daemon

Dec 29 10:34:08 The_Bar shairport-sync[437]: Control RTP thread interrupted. terminating.
Dec 29 10:34:08 The_Bar shairport-sync[437]: Audio receiver -- Server RTP thread interrupted. terminating.
Dec 29 10:34:08 The_Bar shairport-sync[437]: Timing thread interrupted. terminating.
Dec 29 10:34:08 The_Bar shairport-sync[437]: rtp_timing_sender thread interrupted. terminating.
Dec 29 10:34:08 The_Bar shairport-sync[437]: Closed and terminated timer requester thread.
Dec 29 10:34:08 The_Bar shairport-sync[437]: Timing RTP thread terminated.
Dec 29 10:34:08 The_Bar shairport-sync[437]: timing thread joined
Dec 29 10:34:08 The_Bar shairport-sync[437]: audio thread joined
Dec 29 10:34:08 The_Bar shairport-sync[437]: control thread joined
Dec 29 10:34:08 The_Bar shairport-sync[437]: Player thread exit
pi@The_Bar:/var/log $ 

[vagend]

The other zones are still working and my wife is using them right now, which I'm guessing is why the log on the dead zone is getting written too constantly.
I grabbed a snip of it

Dec 29 10:43:28 The_Bar shairport-sync[437]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3515.
Dec 29 10:43:28 The_Bar kernel: bcm2835-dma 3f007000.dma: DMA transfer could not be terminated
Dec 29 10:43:28 The_Bar kernel: pcm512x 1-004d: No SCLK, using BCLK: -2

[mikebrady]

Thanks. (I edited your posts to make their layout more readable.) Looking up the line bcm2835-dma 3f007000.dma: DMA transfer could not be terminated in Google seems to reveal concerns with the audio device driver, e.g. see here: raspberrypi/linux#1949.

[vagend]

Thanks for all the help. Looking at your link it says 4.9.24 fixed the issue. I'm on:
pi@The_Bar:~ $ uname -a
Linux The_Bar 4.9.59-v7+ #1047 SMP Sun Oct 29 12:19:23 GMT 2017 armv7l GNU/Linux
I guess I'll keep digging

[vagend]

do the logs persist through a reboot?

[mikebrady]

The logs do persist through a reboot, but a lot of stuff gets added. Separately though, it’s generally a good idea to stay up to date. Did you update the firmware using # rpi-update as well as the more usual # apt-get update and apt-get upgrade?

[vagend]

I don't recall running the rpi-update. I'll do that now.

[mikebrady]

Thanks. It might be important.

[vagend]

All my Pi's were due for a firmware update. Maybe that will do it.

[vagend]

After ensuring that all my Pi's have gone through all the updates, including firmware, I've had some issues again today.

My Pi 3 has dropped out a couple times but only for a couple seconds and came back.
One my Pi Zero's has dropped out and not come back. Its logs look that same as the logs I got yesterday from my Pi 3.

Dec 30 15:34:31 Balcony shairport-sync[327]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 3354.
Dec 30 15:34:31 Balcony kernel: bcm2835-dma 20007000.dma: DMA transfer could not be terminated
Dec 30 15:34:31 Balcony kernel: pcm512x 1-004d: No SCLK, using BCLK: -2

Also an interesting note, I have set power management off on my iwconfig settings and the Pi's are turning that back on by themselves. I have seen somewhere on the google that this power management is not really on even though it says that it is and that the statement is a bug but maybe that is not true and it is a problem.

[mikebrady]

Thanks. I’m pretty sure that I added a command to /etc/rc.local to turn off power management on startup. (I’m on a New Year break right now, so can’t check...)

Regarding the continuing issues, it would be great to try to separate the output device from the source to see what happens. As an experiment, one thing to try would be to use a cheap USB DAC instead of one of the I2S audio output devices, and see if the problem continued with that. My reasoning is that the USB device would not use the same code as the I2S device and if the fault lay in the I2S code, this would circumvent it. (It might even be possible to use the Pi’s built-in audio in the same way rather than the USB DAC. The sound is tolerable for testing purposes — there’s a paragraph or two on getting the most out of it in the README.)

[mikebrady]

Another quick thing is to check in the log to see if the “mmap” transfer mode is being used. If it is, turn it off with use_mmap_if_available = "no"; in the alsa part of the configuration file. Who knows, maybe it will turn off the use of the dma (Direct Memory Access) part of the I2S driver.

Remember to uncomment the configuration entry by removing the leading // characters!

[mikebrady]

A quick question — have you changed the output rate to the DACs? In other words, have you set the output rate at 88,200 or other frame rate?

[vagend]

I do have a usb sound card but no amp to run it to so that will be an issue.

I have not done ANYTHING to my hifiberry amp2. I just plugged it in and it worked (card 1). I don't actually know how to manipulate or check the status of the DAC conversion rate. I need to look into that.

I will did through the logs to see if I can find the mmap mode being used like your suggested.

Thanks a lot

[vagend]

Here is a log from one of the Pi zero's when it is working correctly. I don't see any mention of mmap.

Dec 31 10:17:26 Backstage sudo[3819]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Dec 31 10:21:58 Backstage sudo[3819]: pam_unix(sudo:session): session closed for user root
Dec 31 10:22:09 Backstage shairport-sync[777]: New RTSP connection from 192.168.1.22:52057 to self at 192.168.1.24:5000.
Dec 31 10:22:10 Backstage shairport-sync[777]: Closing down RTSP conversation thread...
Dec 31 10:22:10 Backstage shairport-sync[777]: New RTSP connection from 192.168.1.22:52058 to self at 192.168.1.24:5000.
Dec 31 10:22:11 Backstage shairport-sync[777]: Play connection from user agent "iTunes/12.7.1 (Windows; Microsoft Windows 7 x64 Home Premium Edition Service
Dec 31 10:22:11 Backstage shairport-sync[777]: Active-Remote string seen: "28564187".
Dec 31 10:22:11 Backstage shairport-sync[777]: DACP-ID string seen: "B1AEF4C503E8ABFC".
Dec 31 10:22:11 Backstage shairport-sync[777]: Set up play connection from 192.168.1.22 to self at 192.168.1.24.
Dec 31 10:22:11 Backstage smbd[3839]: pam_unix(samba:session): session closed for user nobody
Dec 31 10:22:11 Backstage kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Dec 31 10:22:23 Backstage sudo[3843]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl -n 50
Dec 31 10:22:23 Backstage sudo[3843]: pam_unix(sudo:session): session opened for user root by pi(uid=0)
Dec 31 10:23:25 Backstage sudo[3843]: pam_unix(sudo:session): session closed for user root
Dec 31 10:23:27 Backstage shairport-sync[777]: RTSP shutdown requested.
Dec 31 10:23:27 Backstage shairport-sync[777]: Closing down RTSP conversation thread...
Dec 31 10:23:27 Backstage shairport-sync[777]: Shut down audio, control and timing threads
Dec 31 10:23:27 Backstage shairport-sync[777]: Audio receiver -- Server RTP thread interrupted. terminating.
Dec 31 10:23:27 Backstage shairport-sync[777]: Control RTP thread interrupted. terminating.
Dec 31 10:23:27 Backstage shairport-sync[777]: Timing thread interrupted. terminating.
Dec 31 10:23:27 Backstage shairport-sync[777]: rtp_timing_sender thread interrupted. terminating.
Dec 31 10:23:27 Backstage shairport-sync[777]: Closed and terminated timer requester thread.
Dec 31 10:23:27 Backstage shairport-sync[777]: Timing RTP thread terminated.
Dec 31 10:23:27 Backstage shairport-sync[777]: timing thread joined
Dec 31 10:23:27 Backstage shairport-sync[777]: audio thread joined
Dec 31 10:23:27 Backstage shairport-sync[777]: control thread joined
Dec 31 10:23:27 Backstage shairport-sync[777]: Player thread exit
Dec 31 10:23:35 Backstage sudo[3854]:       pi : TTY=pts/0 ; PWD=/home/pi ; USER=root ; COMMAND=/bin/journalctl -n 50
Dec 31 10:23:35 Backstage sudo[3854]: pam_unix(sudo:session): session opened for user root by pi(uid=0)

[mikebrady]

Thanks. The question about frame rate was prompted by some of the discussion on the other thread, where it seemed that the problem manifested itself at 192,400 or higher. Since you're not doing anything special, the frame rate is 44,100.

Unfortunately, I don't have an I2S audio device to hand, but on the device I am using, this is what I get when I play a piece of audio:

New RTSP connection from 172.20.10.4:60906 to self at 172.20.10.2:5000 on conversation thread 1.
Play connection from user agent "iTunes/12.7.2 (Macintosh; OS X 10.13.2) (dt:1)" on RTSP conversation thread 1.
Active-Remote string seen: "3840976649".
DACP-ID string seen: "CDB5BB07DC38F7E9".
User-Agent is iTunes 10 or better, (actual version is 12); selecting the iTunes latency of -1 frames.
Set up play connection from 172.20.10.4 to self at 172.20.10.2 on RTSP conversation thread 1.
Output frame bytes is 4.
Output bit depth is 16.
Dithering will be enabled because the output volume is being altered in software
Set initial volume to -18.000000.
Hammerton Decoder used on encrypted audio.
Using negotiated latency of 88200 frames and a static latency correction of 11025
Using negotiated latency of 88553 frames and a static latency correction of 11025
Output written with RW

If you see the part where it says Output written with RW, if the device was capable of memory-mapped output, it would read Output written with MMAP. BTW, I'm using the latest version of Shairport Sync, 3.1.7.

[vagend]

one more data point. I looked in the log for one of the Pi's when it just does a quick drop out but comes back.

Dec 31 17:42:58 The_Bar shairport-sync[380]: Buffers exhausted.
Dec 31 17:42:59 The_Bar shairport-sync[380]: Lost sync with source for 4 consecutive packets -- flushing and resyncing. Error: 5896.
Dec 31 17:42:59 The_Bar kernel: pcm512x 1-004d: No SCLK, using BCLK: -2

I wonder if my PC(iTunes server) is somehow the issue? The Google showed me an issue you worked with a guy (#99) where his PC source was the issue but that was a couple years ago and it looks like you made an adjustment for it?

[mikebrady]

Thanks. In that case, the user’s PC was sending audio at a rate that was far outside the expected range of difference between the clocks — it was about 2,000 parts per million, and Shairport Sync had a limit of about 800 ppm. That has since been changed, so Shairport Sync will accommodate a drift of up to about 2,800 ppm. So I don’t think #99 is related to your case. If you want to enable the gathering of statistics in the log, you could get an idea of the drift rate — i’d be surprised if it was more than 200 ppm and it could be much less.

Another question — actually two questions: first, what version of Shairport Sync are you running (use $ shairport-Sync -V) and second, have you enabled soxr interpolation?

[vagend]

Mike, you're an awesome guy thanks so much for the help.

My shairport-sync -V

pi@Balcony:~ $ shairport-sync -V
2.8.6-OpenSSL-Avahi-ALSA-pulse-dummy-stdout-pipe-soxr-metadata-sysconfdir:/etc

I used the raspbian stretch gui to do the install. Is soxr interpolation enabled in the conf file?
I have only made two changes to the default shairport-sync.conf file.
I enabled the log and allow_session_interruption

// Sample Configuration File for Shairport Sync
// Commented out settings are generally the defaults, except where noted.

// 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. 2.8.5 and
//	%V for the full version string, e.g. 2.8.5-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 = "basic"; // 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 = 88; // allow this number of frames of drift away from exact synchronisation before attempting to correct it
//	resync_threshold = 2205; // a synchronisation error greater than this will cause resynchronisation; 0 disables it
	log_verbosity = 1; // "0" means no debug verbosity, "3" is most verbose.
//	ignore_volume_control = "no"; // 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 to set the range, in dB, you want between the maximum volume and the minimum volume. Range is 30 to 150 dB. Leave it commented out to use mixer's native range.
//	regtype = "_raop._tcp"; // Use this advanced setting to set the service type and transport to be advertised by Zeroconf/Bonjour. Default is "_raop._tcp".
//	playback_mode = "stereo"; // This can be "stereo" or "mono". Default is "stereo".
};

// How to deal with metadata, including artwork
metadata =
{
//	enabled = "no"; // et 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 "enabled" to "yes".
//	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 address. "socket-port" must be non-zero and "enabled" must be set to yes"
//      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 the #!... stuff on the first line
//	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 #!... stuff on the first line
//	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 = "yes"; // set to "yes" to allow another device to interrupt Shairport Sync while it's playing from an existing audio source
//	session_timeout = 120; // 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 = "default"; // 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.
//  audio_backend_latency_offset = 0; // Set this offset to compensate for a fixed delay in the audio back end. E.g. if the output device delays by 100 ms, set this to -4410.
//  audio_backend_buffer_desired_length = 6615; // If set too small, buffer underflow occurs on low-powered machines. Too long and the response times with software mixer become annoying.
//  disable_synchronization = "no"; // 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
//  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 "yes"
};

// These are parameters for the "pipe" audio back end, a back end that directs raw CD-style audio output to a pipe. No interpolation is done.
pipe =
{
//  name = "/path/to/pipe"; // there is no default pipe name for the output
//  audio_backend_latency_offset = 0; // Set this offset to compensate for a fixed delay in the audio back end. E.g. if the output device delays by 100 ms, set this to -4410.
//  audio_backend_buffer_desired_length = 44100; // Having started to send audio at the right time, send all subsequent audio this many frames ahead of time, creating a buffer this size.
};

// These are parameters for the "stdout" audio back end, a back end that directs raw CD-style audio output to stdout. No interpolation is done.
stdout =
{
//  audio_backend_latency_offset = 0; // Set this offset to compensate for a fixed delay in the audio back end. E.g. if the output device delays by 100 ms, set this to -4410.
//  audio_backend_buffer_desired_length = 44100; // Having started to send audio at the right time, send all subsequent audio this many frames ahead of time, creating a buffer this size.
};

// These are parameters for the "ao" audio back end. No interpolation is done.
ao =
{
//  audio_backend_latency_offset = 0; // Set this offset to compensate for a fixed delay in the audio back end. E.g. if the output device delays by 100 ms, set this to -4410.
//  audio_backend_buffer_desired_length = 44100; // Having started to send audio at the right time, send all subsequent audio this many frames ahead of time, creating a buffer this size.
};

// Static latency settings are deprecated and the settings have been removed. 

[mikebrady]

Sorry to drop this. I notice the version of Shairport Sync is 2.8.6, which is pretty old. Would there be any possibility of updating?

[vagend]

absolutely. I just have to figure out how to do that. I actually did the install using the gui in stretch. I wonder why it directs me to that version? I was thinking that the stretch add/remove program gui was really dumbing things down for the masses (like me) but maybe there is more care and feeding required than meets the eye.

[vagend]

3.1.7-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/usr/local/etc
I updated my Pi 3 as its the latest one to act up. Oddly my zero W's have been good for a while. I'll wait on updating those until they drop out and also see if the shairport-sync update was all I needed.
Coincidentally, as I followed your update instructions from here I discovered that by doing the install with the stretch gui, I was missing a lot of apt-get install's that I would have had if I had done a command line install like you instruct on your shairport-sync page.

[vagend]

The updated PI is still "locking up". My wife said she was using it until 10:30 ish then after around 11 she tried again and it wouldn't play.

Feb 09 09:40:33 Kitchen shairport-sync[443]: Buffers exhausted.
Feb 09 09:40:42 Kitchen shairport-sync[443]: RTSP shutdown requested.
Feb 09 09:40:42 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 09:40:42 Kitchen shairport-sync[443]: Shut down audio, control and timing threads
Feb 09 09:40:42 Kitchen shairport-sync[443]: Timing thread interrupted. terminating.
Feb 09 09:40:42 Kitchen shairport-sync[443]: Control RTP thread interrupted. terminating.
Feb 09 09:40:42 Kitchen shairport-sync[443]: Audio receiver -- Server RTP thread interrupted. terminating.
Feb 09 09:40:42 Kitchen shairport-sync[443]: rtp_timing_sender thread interrupted. terminating.
Feb 09 09:40:42 Kitchen shairport-sync[443]: Closed and terminated timer requester thread.
Feb 09 09:40:42 Kitchen shairport-sync[443]: Timing RTP thread terminated.
Feb 09 09:40:42 Kitchen shairport-sync[443]: timing thread joined
Feb 09 09:40:42 Kitchen shairport-sync[443]: audio thread joined
Feb 09 09:40:42 Kitchen shairport-sync[443]: control thread joined
Feb 09 09:40:42 Kitchen shairport-sync[443]: Player thread exit
Feb 09 09:46:50 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58351 to self at 192.168.1.14:5000.
Feb 09 09:46:50 Kitchen shairport-sync[443]: Play connection from user agent "iTunes/12.7.1 (Windows; Microsoft Windows 7 x64 Home Premium Edition Service Pack 1 (Build 7601); x64)".
Feb 09 09:46:50 Kitchen shairport-sync[443]: Active-Remote string seen: "1395612791".
Feb 09 09:46:50 Kitchen shairport-sync[443]: DACP-ID string seen: "B1AEF4C503E8ABFC".
Feb 09 09:46:50 Kitchen shairport-sync[443]: Set up play connection from 192.168.1.22 to self at 192.168.1.14.
Feb 09 09:46:51 Kitchen kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Feb 09 10:17:01 Kitchen CRON[1962]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb 09 10:17:01 Kitchen CRON[1966]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Feb 09 10:17:01 Kitchen CRON[1962]: pam_unix(cron:session): session closed for user root
Feb 09 10:22:17 Kitchen shairport-sync[443]: RTSP shutdown requested.
Feb 09 10:22:17 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 10:22:17 Kitchen shairport-sync[443]: Shut down audio, control and timing threads
Feb 09 10:22:17 Kitchen shairport-sync[443]: Audio receiver -- Server RTP thread interrupted. terminating.
Feb 09 10:22:17 Kitchen shairport-sync[443]: Control RTP thread interrupted. terminating.
Feb 09 10:22:17 Kitchen shairport-sync[443]: Timing thread interrupted. terminating.
Feb 09 10:22:17 Kitchen shairport-sync[443]: rtp_timing_sender thread interrupted. terminating.
Feb 09 10:22:17 Kitchen shairport-sync[443]: Closed and terminated timer requester thread.
Feb 09 10:22:17 Kitchen shairport-sync[443]: Timing RTP thread terminated.
Feb 09 10:22:17 Kitchen shairport-sync[443]: timing thread joined
Feb 09 10:22:17 Kitchen shairport-sync[443]: audio thread joined
Feb 09 10:22:17 Kitchen shairport-sync[443]: control thread joined
Feb 09 10:22:17 Kitchen shairport-sync[443]: Player thread exit
Feb 09 10:59:14 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58491 to self at 192.168.1.14:5000.
Feb 09 10:59:15 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 10:59:15 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58492 to self at 192.168.1.14:5000.
Feb 09 10:59:15 Kitchen shairport-sync[443]: Play connection from user agent "iTunes/12.7.1 (Windows; Microsoft Windows 7 x64 Home Premium Edition Service Pack 1 (Build 7601); x64)".
Feb 09 10:59:15 Kitchen shairport-sync[443]: Active-Remote string seen: "1674497284".
Feb 09 10:59:15 Kitchen shairport-sync[443]: DACP-ID string seen: "B1AEF4C503E8ABFC".
Feb 09 10:59:15 Kitchen shairport-sync[443]: Set up play connection from 192.168.1.22 to self at 192.168.1.14.
Feb 09 10:59:15 Kitchen kernel: pcm512x 1-004d: No SCLK, using BCLK: -2
Feb 09 11:00:33 Kitchen shairport-sync[443]: RTSP shutdown requested.
Feb 09 11:00:33 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 11:00:34 Kitchen shairport-sync[443]: Shut down audio, control and timing threads
Feb 09 11:00:34 Kitchen shairport-sync[443]: Timing thread interrupted. terminating.
Feb 09 11:00:34 Kitchen shairport-sync[443]: rtp_timing_sender thread interrupted. terminating.
Feb 09 11:00:34 Kitchen shairport-sync[443]: Closed and terminated timer requester thread.
Feb 09 11:00:34 Kitchen shairport-sync[443]: Timing RTP thread terminated.
Feb 09 11:00:34 Kitchen shairport-sync[443]: Control RTP thread interrupted. terminating.
Feb 09 11:00:34 Kitchen shairport-sync[443]: timing thread joined
Feb 09 11:00:34 Kitchen shairport-sync[443]: Audio receiver -- Server RTP thread interrupted. terminating.
Feb 09 11:00:34 Kitchen shairport-sync[443]: audio thread joined
Feb 09 11:00:34 Kitchen shairport-sync[443]: control thread joined
Feb 09 11:00:34 Kitchen shairport-sync[443]: Player thread exit
Feb 09 11:17:01 Kitchen CRON[2023]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb 09 11:17:01 Kitchen CRON[2027]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Feb 09 11:17:01 Kitchen CRON[2023]: pam_unix(cron:session): session closed for user root
Feb 09 12:17:01 Kitchen CRON[2080]: pam_unix(cron:session): session opened for user root by (uid=0)
Feb 09 12:17:01 Kitchen CRON[2084]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Feb 09 12:17:01 Kitchen CRON[2080]: pam_unix(cron:session): session closed for user root
Feb 09 12:41:01 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58669 to self at 192.168.1.14:5000.
Feb 09 12:41:01 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 12:41:01 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58670 to self at 192.168.1.14:5000.
Feb 09 12:41:02 Kitchen shairport-sync[443]: Play connection from user agent "iTunes/12.7.1 (Windows; Microsoft Windows 7 x64 Home Premium Edition Service Pack 1 (Build 7601); x64)".
Feb 09 12:41:02 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 12:41:11 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58673 to self at 192.168.1.14:5000.
Feb 09 12:41:12 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 12:41:31 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58675 to self at 192.168.1.14:5000.
Feb 09 12:41:32 Kitchen shairport-sync[443]: Try to get the player now
Feb 09 12:41:32 Kitchen shairport-sync[443]: Already playing.
Feb 09 12:41:32 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 12:41:34 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58676 to self at 192.168.1.14:5000.
Feb 09 12:41:36 Kitchen shairport-sync[443]: Try to get the player now
Feb 09 12:41:36 Kitchen shairport-sync[443]: Already playing.
Feb 09 12:41:36 Kitchen shairport-sync[443]: Closing down RTSP conversation thread...
Feb 09 12:41:45 Kitchen shairport-sync[443]: New RTSP connection from 192.168.1.22:58677 to self at 192.168.1.14:5000.
Feb 09 12:41:46 Kitchen shairport-sync[443]: Try to get the player now
Feb 09 12:41:46 Kitchen shairport-sync[443]: Already playing.

[vagend]

And here is my shairport-sync -v output in case this is usefull.

pi@Kitchen:~ $ shairport-sync -v
alsa output device name is "default".
Version: "3.1.7-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/usr/local/etc"
statistics_requester status is 0.
daemon status is 0.
deamon pid file is "/var/run/shairport-sync/shairport-sync.pid".
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 100.
player name is "Kitchen".
backend is "(null)".
on-start action is "(null)".
on-stop action is "(null)".
wait-cmd status is 0.
on-start returns output is 0.
mdns backend "(null)".
stuffing option is "0" (0-basic, 1-soxr).
resync time is 0.050000 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 0.
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.
audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
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.
alsa_use_playback_switch_for_mute 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".
metadata enabled is 0.
metadata pipename is "(null)".
metadata socket address is "(null)" port 0.
metadata socket packet size is "500".
get-coverart is 0.
loudness is 0.
loudness reference level is -20.000000
Successful Startup
Unable to listen on IPv4 port 5000. The error is: "Address already in use".
Unable to listen on IPv6 port 5000. The error is: "Address already in use".
fatal error: Could not establish a service on port 5000 -- program terminating. Is another instance of Shairport Sync running on this device?
Request to shut down all rtsp conversation threads
asking playing threads to stop
pi@Kitchen:~ $ 

[mikebrady]

Thanks for keeping working on this. I can see that you are getting that "already playing" thing a few times, but I can't see why the previous session is not closed down.

If you would be kind enough to install the latest development version, it has some changes and some extra diagnostics, so we might get to see more of what happening when it recurs. The instructions for updating are in UPDATING.md.

When you install Shairport Sync with $ sudo make install, a sample configuration file is installed at /etc/shairport.sync.sample. If you look at the new diagnostic section at the end of that file, you'll see how to enable relative and absolute time messaging in the log. I'd also suggest verbosity level of 2 and statistics enabled. It's a bit noisy, but it might help to see what's happening.

[leonmf]

I’m afraid I don’t have time to debug so I’m glad someone else is working on it. I’m having the same symptoms on WiFi connected Pis but wired ones never have a problem. Even using external adapter with full signal strength didn’t solve the problem. Fortunately, only the one that never gets used is still on WiFi but thought it important to confirm this isn’t unique to one user. Leon Grossman [email protected]

…

On Feb 10, 2018, at 8:50 AM, Mike Brady ***@***.***> wrote: Thanks for keeping working on this. I can see that you are getting that "already playing" thing a few times, but I can't see why the previous session is not closed down. If you would be kind enough to install the latest development version, it has some changes and some extra diagnostics, so we might get to see more of what happening when it recurs. The instructions for updating are in UPDATING.md. When you install Shairport Sync with $ sudo make install, a sample configuration file is installed at /etc/shairport.sync.sample. If you look at the new diagnostic section at the end of that file, you'll see how to enable relative and absolute time messaging in the log. I'd also suggest verbosity level of 2 and statistics enabled. It's a bit noisy, but it might help to see what's happening. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[sebkur1]

Hi Mike,

first, thanks for all the hard work on shairport-sync. It's an great project.
I think I'm running into the same issue. I can connect just fine and play music for a time, but after some time the playback just stops.
I'm using shairport-sync on an Raspberry Pi Zero W with latest Rasbian Strech on it. My sound device is an JustBoom Amp Zero pHAT. I believe it has something to do with the Amp, because I also run an squeezelite client on the same device and when shairport-sync fails, squeezelite stops also to work. Even stopping/restarting shairport-sync or squeezelite does not help. The only way to revive it is an system reboot.
My streaming device is an rooted Samsung Galaxy Note 3 Android 7.1 phone running the App "Airaudio".
I also run shairport-sync on an Pi3 via HDMI to an AV-receiver without any issues at all. Both devices are attached to the same WLAN.

As you requested I installed the latest dev version. -v shows Version: "3.2d27-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc and enabled the diagnostic options.
Attached the gathered log file.
The playback worked for two tracks (ca. 10 min). After it went mute I tried to reconnect to the player which was possible but ended with the line "0.002170988|Delay error -19 when checking running latency."
To clarify: Before the update to the development version could see the line "already playing" in my logs, but afterwards not anymore.

I hope this helps.

shairport-sync.log

[mikebrady]

Many thanks for this. I’ll reply tomorrow.

[mikebrady]

Well, first off, error -19 means"ENODEV", i.e. "No such device", which makes me think of a device error, i.e. a hardware error. I also see this:

Feb 13 21:46:30 lms kernel: bcm2835-i2s 20203000.i2s: I2S SYNC error!

which looks like the start of problems; it might be the point at which the device starts misbehaving. From that point, it looks as if the DAC is accepting data, but only very slowly, which is weird. Then, later on, when Shairport Sync tries to use it again, it comes up with ENODEV.

Troubleshooting stuff like this is very difficult. It could be hardware, firmware or software.

• Firmware: have you updated the firmware of the Pi with rpi-update recently?
• Hardware: could you remove and reseat the DAC? Do you have a duplicate or replacement? (I've used the Pimoroni pHAT in a few installations and it's been faultless, and I've used IQaudIO DACs and Amplifiers with great success.) Do you have another Pi you could try the DAC with? All this is to try to isolate the problem...
• Are there any credible and widespread reports of problems with these devices? (BTW, I don't think there are such reports, but I haven't looked hard.)
• Software: can you get this misbehaviour to happen without using Shairport Sync? You'd want to get a source that lasted long enough -- I think I see the log runs for about 15 minutes, so if you had a single source that lasted 30 minutes or more...

I'll keep looking at the logs during the day as I get time.

[sebkur1]

Yes, it does looks like a device error, but not like an defective unit.
I own three Pi Zeros and three JustBoom Amp Zero pHATs. Just installed shairport-sync on the second one. So different Pi and different Amp. It shows the same behavior, even worse... I can't even finish one track.
uname - a shows: Linux radiopi-wc 4.14.18+ #1093 Fri Feb 9 15:07:36 GMT 2018 armv6l GNU/Linux and rpi-update says there are no updates available.
I'm using all three of them every day since at least one year as receivers for a Logitech Media Server (sqeezelite software). I'm playing mostly online radio streams. Never had any problem with it, even after many hours playtime.
I think I will contact the Justboom support.

[mikebrady]

It’s really peculiar. I suppose the main thing that Shairport Sync does differently is that it continually checks the latency.

[sebkur1]

Hi Mike,

I found a workaround for my issue.
I looked at the CPU load of my Pi Zero. It was on the high side 60-70% with spikes to 100%. The Amp always failed at those 100% spices. Because of this I changed the interpolation option back to basic. Now the CPU load is between 20-30% and the issue didn't occur anymore.

For future reference:
If your are running into the same issue running shairport-sync on a Raspberry Pi Zeros W with a JustBoom Amp Zero pHATs.
Make sure you set interpolation = "basic"; in /etc/shairport-sync.conf.

[mikebrady]

That's very interesting, and I'm glad you found it. I've put a little reference to it in the TROUBLESHOOTING page.

[vagend]

But isn't interpolation = "basic"; the default setting. Meaning its commented out but is in effect and only required to be un-commented if you want to change it?

[mikebrady]

Yes indeed — basic is the default.

[ghost]

I'm seeing the same stuff:
[ 246.232730] bcm2835-dma 3f007000.dma: DMA transfer could not be terminated
[ 246.862356] arizona spi0.1: Mixer dropped sample
[ 246.863167] bcm2835-i2s 3f203000.i2s: I2S SYNC error!
[ 246.863679] bcm2835-i2s 3f203000.i2s: I2S SYNC error!

root@raspberrypi:~# uname -a
Linux raspberrypi 4.14.31-v7+ #2 SMP Fri Mar 30 15:13:21 BST 2018 armv7l GNU/Linux

root@raspberrypi:~# /opt/vc/bin/vcgencmd version
Mar 23 2018 16:31:10
Copyright (c) 2012 Broadcom
version d92349b3d22c277e44d508a2aae6af2b1e5bb224 (clean) (release)

[mikebrady]

Hmm, thanks. What output device were you using?

[ghost]

https://www.cirrus.com/applications/smart-home/digital-assistant/

[mikebrady]

Thanks. It does look like the same problem alright. On the face of it, it looks like a failure the I2S driver. The workaround discovered by @flyingblindonarocketcycle is suggestive of a race condition or a thread "collision" under heavy load, but it's really hard to know.

[vagend]

I have an update on the audio cutting out behavior. I have discovered that, if I have a remote handy when the audio cuts out on a zone, if I pause the playback for a few seconds and then hit play, the dead zone recovers. When it recovers its good for a while. When it cuts out it appears to be random and after recovery, it could be good for the day.... or not.

Don't try to disable and re-enable the zone, leave it alone and just pause the playback.

[mikebrady]

Thanks for the update. If you got a chance, you should update to the latest version — there have been a couple of important bug fixes. There’s a Release Candidate in the master branch right now, looking pretty good. TBH, I don’t think the fixes relate to your issues, but then again we don’t know for sure what’s causing them.

[mikebrady]

BTW @sebkur1, the Release Candidate has some fixes relating to AirAudio compatibility.

[mikebrady]

Pretty sure this has been addressed in more recent versions of Shairport Sync! Closing this inactive issue. Please open a new one if necessary.