Shairport "dies" after a few hours

[MCUdude]

Hi! I've been using Shairport-sync for years now, and I've updated it from time to time just to catch up.

I recently updated to 3.3.2, but I'm having some issues. After starting shairport-sync by running

sudo service shairport-sync start

I usually get an error message like this

Process 30717 died: No such process; trying to remove PID file. (/var/run/shairport-sync/shairport-sync.pid)

Shairport-sync starts just fine, but after a few hours, it crashes again. The operating system it runs on is quite old, Ubuntu 14.04, but that shouldn't really be the problem, right?

How can I find the root cause of what's causing it to crash? And after that, what can be done to fix it? Thanks!

[mikebrady]

Thanks for the post. Let me suggest that you set the log_verbosity in the setting file to 1. This will cause shairport-sync to generate log entries, and they might give a clue as to what’s happening... TBH it hasn’t been tested extensively on 14.04, so there might be some subtle problem.

[MCUdude]

Great! I turned log_verbosity on by editing /etc/shairport-sync.conf. I'm now waiting for it to crash. So when that happens, how do I extract the log?

[mikebrady]

Well, the logs should be written in the system log. I’m not near a machine for another week or so, so I can’t check, but from memory it could be the file /var/log/messages or /var/log/system or maybe /var/log/syslog — you’ll be able to see entries tagged with shairport-sync.

[MCUdude]

Awesome! I found everything under /var/log/syslog. I'll keep you updated!

[MCUdude]

OK, here's the output from syslog, 24 hours later.
Seems to me like the crash happend at 00:25:23.

Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.001677611|Started!
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000266776|software version: "3.3.2-libdaemon-OpenSSL-Avahi-ALSA-soxr-metadata-sysconfdir:/etc"
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000059141|log verbosity is 1.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000139718|alsa: alsa_maximum_stall_time of 0.200000 sec.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000098984|alsa: disable_standby_mode is "never".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000060760|alsa: disable_standby_mode_silence_threshold is 0.040000 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000027403|alsa: disable_standby_mode_silence_scan_interval is 0.004000 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000038409|alsa: output device name is "plughw:CARD=DAC".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000196930|disable resend requests is off.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000057207|diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000019039|statistics_requester status is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000013712|daemon status is 1.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000062309|deamon pid file path is "/var/run/shairport-sync/shairport-sync.pid".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000157854|rtsp listening port is 5000.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000049229|udp base port is 6001.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026246|udp port range is 10.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000032324|player name is "Shairport".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026562|backend is "(null)".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000024762|run_this_before_play_begins action is "/home/chromebox/Marantz_SR5008.sh".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000024898|run_this_after_play_ends action is "(null)".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000014142|wait-cmd status is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025169|run_this_before_play_begins may return output is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025068|run_this_if_an_unfixable_error_is_detected action is "(null)".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000030364|run_this_before_entering_active_state action is  "(null)".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026983|run_this_after_exiting_active_state action is  "(null)".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025088|active_state_timeout is  10.000000 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000030606|mdns backend "(null)".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025764|interpolation setting is "auto".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000014473|interpolation soxr_delay_threshold is 30.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000030055|resync time is 0.050000 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000029298|allow a session to be interrupted: 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025173|busy timeout time is 120.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000024602|drift tolerance is 0.001995 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000031011|password is "(null)".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026983|ignore_volume_control is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000024802|volume_max_db is not set
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000014764|volume range in dB (zero means use the range specified by the mixer): 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026621|volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025188|playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000030902|disable_synchronization is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026436|use_mmap_if_available is 1.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025303|output_format automatic selection is enabled.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025078|output_rate automatic selection is enabled.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000029544|audio backend desired buffer length is 0.200000 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000029643|audio_backend_buffer_interpolation_threshold_in_seconds is 0.120000 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000028220|audio backend latency offset is 0.000000 seconds.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000030922|audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000029112|zeroconf regtype is "_raop._tcp".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000025649|decoders_supported field is 1.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000014649|use_apple_decoder is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000029338|alsa_use_hardware_mute is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000027107|no special mdns service interface was requested.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000037452|configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000056872|metadata enabled is 1.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026074|metadata pipename is "/tmp/shairport-sync-metadata".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000030521|metadata socket address is "(null)" port 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000028175|metadata socket packet size is "500".
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026060|get-coverart is 1.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000029694|loudness is 0.
Aug 22 21:39:30 chromebox shairport-sync[7949]:          0.000026646|loudness reference level is -20.000000
Aug 22 21:39:31 chromebox shairport-sync[7949]:          1.010640818|avahi: service '2029E6B0BD56@Shairport' successfully added.
Aug 22 21:39:32 chromebox shairport-sync[7949]:          0.490841016|"soxr" interpolation has been chosen.
Aug 22 22:17:01 chromebox CRON[8881]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 22 23:17:01 chromebox CRON[10251]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 00:02:11 chromebox console-kit-daemon[1897]: GLib-CRITICAL: Source ID 179 was not found when attempting to remove it
Aug 23 00:02:11 chromebox console-kit-daemon[1897]: GLib-CRITICAL: Source ID 179 was not found when attempting to remove it
Aug 23 00:17:01 chromebox CRON[11624]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 00:25:23 chromebox dhclient: DHCPREQUEST of 192.168.0.20 on eth0 to 192.168.0.1 port 67 (xid=0x28fe019e)
Aug 23 00:25:23 chromebox dhclient: DHCPACK of 192.168.0.20 from 192.168.0.1
Aug 23 00:25:23 chromebox dhclient: bound to 192.168.0.20 -- renewal in 33328 seconds.
Aug 23 00:25:23 chromebox NetworkManager[967]: <info> (eth0): DHCPv4 state changed renew -> renew
Aug 23 00:25:23 chromebox NetworkManager[967]: <info>   address 192.168.0.20
Aug 23 00:25:23 chromebox NetworkManager[967]: <info>   prefix 24 (255.255.255.0)
Aug 23 00:25:23 chromebox NetworkManager[967]: <info>   gateway 192.168.0.1
Aug 23 00:25:23 chromebox NetworkManager[967]: <info>   hostname 'chromebox'
Aug 23 00:25:23 chromebox NetworkManager[967]: <info>   nameserver '109.247.114.4'
Aug 23 00:25:23 chromebox NetworkManager[967]: <info>   nameserver '92.220.228.70'
Aug 23 00:25:23 chromebox NetworkManager[967]: <info>   domain name 'home'
Aug 23 00:25:23 chromebox dbus[507]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Aug 23 00:25:23 chromebox dbus[507]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Aug 23 00:25:23 chromebox kernel: [351467.699424] shairport-sync[7957]: segfault at 37 ip 00007f540044771a sp 00007f53fd9ffce0 error 4 in libdbus-1.so.3.7.6[7f5400435000+44000]
Aug 23 01:17:01 chromebox CRON[12939]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 02:17:01 chromebox CRON[14223]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 03:17:01 chromebox CRON[15508]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 04:17:01 chromebox CRON[16792]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 05:17:01 chromebox CRON[18069]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 06:17:01 chromebox CRON[19362]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 06:25:01 chromebox CRON[19555]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Aug 23 07:17:01 chromebox CRON[20651]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 07:30:01 chromebox CRON[20956]: (root) CMD (start -q anacron || :)
Aug 23 07:30:01 chromebox anacron[20958]: Can't chdir to /var/spool/anacron: No such file or directory
Aug 23 07:30:01 chromebox kernel: [376955.862636] init: anacron main process (20958) terminated with status 1
Aug 23 07:30:01 chromebox CRON[20955]: (CRON) info (No MTA installed, discarding output)
Aug 23 08:17:01 chromebox CRON[21956]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 09:17:01 chromebox CRON[23216]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 09:40:51 chromebox dhclient: DHCPREQUEST of 192.168.0.20 on eth0 to 192.168.0.1 port 67 (xid=0x28fe019e)
Aug 23 09:40:52 chromebox dhclient: DHCPACK of 192.168.0.20 from 192.168.0.1
Aug 23 09:40:52 chromebox dhclient: bound to 192.168.0.20 -- renewal in 34976 seconds.
Aug 23 09:40:52 chromebox NetworkManager[967]: <info> (eth0): DHCPv4 state changed renew -> renew
Aug 23 09:40:52 chromebox NetworkManager[967]: <info>   address 192.168.0.20
Aug 23 09:40:52 chromebox NetworkManager[967]: <info>   prefix 24 (255.255.255.0)
Aug 23 09:40:52 chromebox NetworkManager[967]: <info>   gateway 192.168.0.1
Aug 23 09:40:52 chromebox NetworkManager[967]: <info>   hostname 'chromebox'
Aug 23 09:40:52 chromebox NetworkManager[967]: <info>   nameserver '109.247.114.4'
Aug 23 09:40:52 chromebox NetworkManager[967]: <info>   nameserver '92.220.228.70'
Aug 23 09:40:52 chromebox NetworkManager[967]: <info>   domain name 'home'
Aug 23 09:40:52 chromebox dbus[507]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Aug 23 09:40:52 chromebox dbus[507]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Aug 23 10:17:01 chromebox CRON[24563]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 11:17:01 chromebox CRON[26011]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 12:17:01 chromebox CRON[27507]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 13:17:01 chromebox CRON[29001]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 14:17:01 chromebox CRON[30250]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 15:17:01 chromebox CRON[31681]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 16:17:01 chromebox CRON[469]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 17:17:01 chromebox CRON[2104]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 18:17:01 chromebox CRON[3348]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 19:17:01 chromebox CRON[4644]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 19:23:48 chromebox dhclient: DHCPREQUEST of 192.168.0.20 on eth0 to 192.168.0.1 port 67 (xid=0x28fe019e)
Aug 23 19:23:48 chromebox dhclient: DHCPACK of 192.168.0.20 from 192.168.0.1
Aug 23 19:23:48 chromebox dhclient: bound to 192.168.0.20 -- renewal in 29779 seconds.
Aug 23 19:23:48 chromebox NetworkManager[967]: <info> (eth0): DHCPv4 state changed renew -> renew
Aug 23 19:23:48 chromebox NetworkManager[967]: <info>   address 192.168.0.20
Aug 23 19:23:48 chromebox NetworkManager[967]: <info>   prefix 24 (255.255.255.0)
Aug 23 19:23:48 chromebox NetworkManager[967]: <info>   gateway 192.168.0.1
Aug 23 19:23:48 chromebox NetworkManager[967]: <info>   hostname 'chromebox'
Aug 23 19:23:48 chromebox NetworkManager[967]: <info>   nameserver '109.247.114.4'
Aug 23 19:23:48 chromebox NetworkManager[967]: <info>   nameserver '92.220.228.70'
Aug 23 19:23:48 chromebox NetworkManager[967]: <info>   domain name 'home'
Aug 23 19:23:48 chromebox dbus[507]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Aug 23 19:23:48 chromebox dbus[507]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Aug 23 20:17:01 chromebox CRON[5916]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 21:17:01 chromebox CRON[7152]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Aug 23 22:17:01 chromebox CRON[8403]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)

[mikebrady]

Many thanks for this — I’ll try to reproduce it. It looks like it is associated with the renewal of the DHCP ip number allocation. It will be the middle of the week before I can look at it though.

[mikebrady]

I can reproduce it alright. It may take a few days to track down the bug...

[MCUdude]

Wow, that is terrific news! Thank you for your effort 🎉

[mikebrady]

Still looking on this...

[MCUdude]

Thanks for the update! Waiting patiently

[mikebrady]

I think I know the general area of the bug, but no joy yet, I'm afraid. When I find it, it will be a "learning experience"!

[mikebrady]

I think I've fixed it. The problem seems to be related to having more than one avahi threaded polling loop (though, of course, this isn't documented anywhere). The fix was to consolidate the avahi stuff down to one threaded polling loop –– before this, there were two. Also I did a small bit of removal of obsolete code. It's been stable now for a full day, with DHCP renewals set to occur every two minutes. I'd be grateful if you would give it a try and let me know of any issues.

[mikebrady]

I shoulda said that I've pushed an update with the fixes into the development branch...

[MCUdude]

This is excellent news! I really appreciate it. I'll install the latest version from the development branch as soon as I get home from work.

[MCUdude]

Noob question: How do I pull the development branch? I tried to run git pull origin development but I only get some kind of merge conflict error.

[mikebrady]

It's covered on the UPDATING.md page.

[MCUdude]

Shairport-sync has been running for almost 24 hours now, and it hasn't crashed a single time. I'm pretty confident you've completely fixed it!

Thank you so much!

[mikebrady]

Many thanks. And thanks for your help identifying the problem.

[MCUdude]

So, are you as confident that you're willing to close this issue? I can always re-open it if I experience similar symptoms later. My Ubuntu 14.04 box is on and running Shairport-sync 24/7, so if there anything left from this bug I will sooner or later stumble over it.

[mikebrady]

Let us close it and we can reopen it if necessary?

[MCUdude]

Good idea!