Interrupting shairport-sync leads to crash

[PeterPablo]

playing from android smartphone, trying to interrupt from tablet (config option is set in shairport-sync.conf)

shairport-sync --version
2.7.3-openssl-Avahi-ALSA-soxr-metadata

Dec 11 18:24:35 rpi2 systemd[1]: Started ShairportSync AirTunes receiver.
Dec 11 18:24:35 rpi2 rsyslogd-2007: action 'action 17' suspended, next retry is Fri Dec 11 18:26:05 2015 [try http://www.rsyslog.com/e/2007 ]
Dec 11 18:24:48 rpi2 shairport-sync[13418]: RTSP shutdown requested.
Dec 11 18:24:48 rpi2 shairport-sync[13418]: closing RTSP connection.
Dec 11 18:24:48 rpi2 shairport-sync[13418]: Audio receiver -- Server RTP thread interrupted. terminating.
Dec 11 18:24:48 rpi2 shairport-sync[13418]: Control RTP thread interrupted. terminating.
Dec 11 18:24:48 rpi2 shairport-sync[13418]: Timing RTP thread interrupted. terminating.
Dec 11 18:24:48 rpi2 shairport-sync[13418]: rtp_timing_sender thread interrupted. terminating.
Dec 11 18:24:48 rpi2 shairport-sync[13418]: Closed and terminated timer requester thread.
Dec 11 18:24:48 rpi2 shairport-sync[13418]: Timing RTP thread terminated.
Dec 11 18:24:50 rpi2 shairport-sync[13418]: new RTSP connection.
Dec 11 18:24:50 rpi2 shairport-sync[13418]: Play connection from user agent "iTunes/11.3.1 (Macintosh; OS X 10.9.4) AppleWebKit/537.77.4".
Dec 11 18:24:50 rpi2 shairport-sync[13418]: Connection from IPv4: 192.168.1.12:59983
Dec 11 18:24:50 rpi2 shairport-sync[13418]: shairport-sync: player.c:246: alac_decode: Assertion `outsize == (4 * frame_size)' failed.
Dec 11 18:24:50 rpi2 systemd[1]: shairport-sync.service: main process exited, code=killed, status=6/ABRT
Dec 11 18:24:50 rpi2 systemd[1]: Unit shairport-sync.service entered failed state.

[PeterPablo]

To clarify: This crash does not happen, if allow_session_interruption = "false".

Then I see: Dez 11 18:31:00 rpi2 shairport-sync[13687]: new RTSP connection. Dez 11 18:31:01 rpi2 shairport-sync[13687]: Already playing. and playback continues from first device.

-- in any case: a big thank you for your effort!

[mikebrady]

Hi Peter. Thanks for this. I guess it's the same as #160. I haven't gotten around to testing this out yet, but i haven't forgotten, promise!

[PeterPablo]

My report seems to be identical to #160, with the difference that I am using two Android devices that both use AirAudio. I am also using ALSA (default) with an HifiBerry DAC+ on a Raspberry Pi 2 with Jessie.

[charleypaulus]

Hi Peter and Mike,

I seem to have a similar problem with shairport-sync, and I would like to inverstigate. Could you please explain me how to get logs like the one posted in the first message of this thread (e.g. "Dec 11 18:24:48 rpi2 shairport-sync[13418]: RTSP shutdown requested.")?

Thank you.

[mikebrady]

Set the log_verbosity to 1 or 2 in /etc/shairport-sync.conf. Make sure to enable it by uncommenting the line...

[ben-willmore]

I see similar crashes when interrupting sessions.

$ shairport-sync --version
3.2.2-OpenSSL-Avahi-ALSA-sysconfdir:/etc

Here is log output for two example crashes -- one just fails with SEGV, the other is more informative Feb 2 14:53:25 pi-dining shairport-sync[404]: *** Error in '/usr/local/bin/shairport-sync': double free or corruption (!prev): 0xb5c00ba8 ***

Feb  2 14:53:19 pi-dining shairport-sync[404]: RTSP Conversation thread 2 already playing when asked by thread 4.
Feb  2 14:53:19 pi-dining shairport-sync[404]: ANNOUNCE: playing connection 2 being interrupted by connection 4.
Feb  2 14:53:19 pi-dining shairport-sync[404]: RTSP Channel unexpectedly closed or a serious error occured -- closing the player thread.
Feb  2 14:53:19 pi-dining shairport-sync[404]: player_put_packet discarded packet 12053 because the player thread was locked.
Feb  2 14:53:19 pi-dining shairport-sync[404]: player_put_packet discarded packet 12054 because the player thread was locked.
Feb  2 14:53:19 pi-dining shairport-sync[404]: player_put_packet discarded packet 12055 because the player thread was locked.
Feb  2 14:53:19 pi-dining shairport-sync[404]: player_put_packet discarded packet 12056 because the player thread was locked.
Feb  2 14:53:19 pi-dining shairport-sync[404]: player_put_packet discarded packet 12057 because the player thread was locked.
Feb  2 14:53:19 pi-dining shairport-sync[404]: player_put_packet discarded packet 12058 because the player thread was locked.
Feb  2 14:53:19 pi-dining shairport-sync[404]: shutdown timing socket.
Feb  2 14:53:19 pi-dining shairport-sync[404]: close timing socket.
Feb  2 14:53:19 pi-dining shairport-sync[404]: shutdown control socket.
Feb  2 14:53:19 pi-dining shairport-sync[404]: close control socket.
Feb  2 14:53:19 pi-dining shairport-sync[404]: shutdown audio socket.
Feb  2 14:53:19 pi-dining shairport-sync[404]: close audio socket.
Feb  2 14:53:20 pi-dining shairport-sync[404]: Try to get the player now
Feb  2 14:53:20 pi-dining shairport-sync[404]: Dithering will be enabled because the output volume is being altered in software
Feb  2 14:53:20 pi-dining shairport-sync[404]: FIXME: Not enough space if the output buffer for audio frame - E2.
Feb  2 14:53:20 pi-dining shairport-sync[404]: FIXME: unhandled prediction type for compressed case: 2
Feb  2 14:53:20 pi-dining shairport-sync[404]: FIXME: unhandled prediction type for compressed case: 12
Feb  2 14:53:21 pi-dining shairport-sync[404]: Switching off socket 1
Feb  2 14:53:22 pi-dining shairport-sync[404]: Switching on socket 1
Feb  2 14:53:25 pi-dining shairport-sync[404]: shutdown timing socket.
Feb  2 14:53:25 pi-dining shairport-sync[404]: close timing socket.
Feb  2 14:53:25 pi-dining shairport-sync[404]: shutdown control socket.
Feb  2 14:53:25 pi-dining shairport-sync[404]: close control socket.
Feb  2 14:53:25 pi-dining shairport-sync[404]: shutdown audio socket.
Feb  2 14:53:25 pi-dining shairport-sync[404]: close audio socket.
Feb  2 14:53:25 pi-dining shairport-sync[404]: *** Error in `/usr/local/bin/shairport-sync': double free or corruption (!prev): 0xb5c00ba8 ***
Feb  2 14:53:25 pi-dining systemd[1]: shairport-sync.service: Main process exited, code=killed, status=6/ABRT
Feb  2 14:53:25 pi-dining systemd[1]: shairport-sync.service: Unit entered failed state.

Feb  2 14:58:12 pi-dining shairport-sync[877]: RTSP Conversation thread 3 already playing when asked by thread 4.
Feb  2 14:58:12 pi-dining shairport-sync[877]: ANNOUNCE: playing connection 3 being interrupted by connection 4.
Feb  2 14:58:12 pi-dining shairport-sync[877]: RTSP Channel unexpectedly closed or a serious error occured -- closing the player thread.
Feb  2 14:58:12 pi-dining shairport-sync[877]: player_put_packet discarded packet 10336 because the player thread was locked.
Feb  2 14:58:12 pi-dining shairport-sync[877]: player_put_packet discarded packet 10337 because the player thread was locked.
Feb  2 14:58:12 pi-dining shairport-sync[877]: player_put_packet discarded packet 10338 because the player thread was locked.
Feb  2 14:58:12 pi-dining shairport-sync[877]: shutdown timing socket.
Feb  2 14:58:12 pi-dining shairport-sync[877]: close timing socket.
Feb  2 14:58:12 pi-dining shairport-sync[877]: shutdown control socket.
Feb  2 14:58:12 pi-dining shairport-sync[877]: close control socket.
Feb  2 14:58:12 pi-dining shairport-sync[877]: shutdown audio socket.
Feb  2 14:58:12 pi-dining shairport-sync[877]: close audio socket.
Feb  2 14:58:13 pi-dining shairport-sync[877]: Try to get the player now
Feb  2 14:58:13 pi-dining shairport-sync[877]: Dithering will be enabled because the output volume is being altered in software
Feb  2 14:58:13 pi-dining shairport-sync[877]: Switching off socket 1
Feb  2 14:58:15 pi-dining shairport-sync[877]: Switching on socket 1
Feb  2 14:58:24 pi-dining shairport-sync[877]: RTSP Conversation thread 4 already playing when asked by thread 5.
Feb  2 14:58:24 pi-dining shairport-sync[877]: ANNOUNCE: playing connection 4 being interrupted by connection 5.
Feb  2 14:58:24 pi-dining shairport-sync[877]: RTSP Channel unexpectedly closed or a serious error occured -- closing the player thread.
Feb  2 14:58:24 pi-dining shairport-sync[877]: player_put_packet discarded packet 21051 because the player thread was locked.
Feb  2 14:58:24 pi-dining shairport-sync[877]: shutdown timing socket.
Feb  2 14:58:24 pi-dining shairport-sync[877]: close timing socket.
Feb  2 14:58:24 pi-dining shairport-sync[877]: shutdown control socket.
Feb  2 14:58:24 pi-dining shairport-sync[877]: close control socket.
Feb  2 14:58:24 pi-dining shairport-sync[877]: player_put_packet discarded packet 21052 because the player thread was locked.
Feb  2 14:58:24 pi-dining shairport-sync[877]: player_put_packet discarded packet 21053 because the player thread was locked.
Feb  2 14:58:24 pi-dining shairport-sync[877]: player_put_packet discarded packet 21054 because the player thread was locked.
Feb  2 14:58:24 pi-dining shairport-sync[877]: player_put_packet discarded packet 21055 because the player thread was locked.
Feb  2 14:58:24 pi-dining shairport-sync[877]: player_put_packet discarded packet 21056 because the player thread was locked.
Feb  2 14:58:24 pi-dining shairport-sync[877]: player_put_packet discarded packet 21057 because the player thread was locked.
Feb  2 14:58:24 pi-dining shairport-sync[877]: shutdown audio socket.
Feb  2 14:58:24 pi-dining shairport-sync[877]: close audio socket.
Feb  2 14:58:25 pi-dining shairport-sync[877]: Try to get the player now
Feb  2 14:58:25 pi-dining shairport-sync[877]: FIXME: Not enough space if the output buffer for audio frame - E2.
Feb  2 14:58:25 pi-dining shairport-sync[877]: FIXME: unhandled prediction type on channel 1: 8
Feb  2 14:58:25 pi-dining shairport-sync[877]: FIXME: unhandled prediction type on channel 2: 11
Feb  2 14:58:25 pi-dining shairport-sync[877]: FIXME: Not enough space if the output buffer for audio frame - E3.
Feb  2 14:58:25 pi-dining shairport-sync[877]: FIXME: Not enough space if the output buffer for audio frame - E2.
Feb  2 14:58:25 pi-dining systemd[1]: shairport-sync.service: Main process exited, code=killed, status=11/SEGV

[mikebrady]

Thanks for the post. This has been a problem for quite a while, and I'm pretty sure it is caused by packets of audio, in flight from the previous session, enter the audio stream of the new session. The problem is that they will have been encrypted with the previous session's key and decrypted with the new sessions's key, resulting in garbage and crashing the Hammerton decoder -- the Apple decoder is a bit more resistant. The FIXME messages are coming from David Hammerton's decoder when it encounters unexpected code sequences.

A solution, which is now on the development branch, is simply to use a different set of ports whenever a new session interrupts an old one. Then any in-flight packets are heading for no-longer-used ports and are discarded. So, if you'd care to try it, and let us know how it's going, that would be great.

There's also an unstable branch if you'd care to live dangerously.

[ben-willmore]

Hi Mike. Many thanks for your response! The development branch seems to fix this for me -- I just switched between devices 15 times in a row without a crash. Previously, I would get a crash on ~75% of switches. [On two occasions, the switch didn't work -- the iOS device and the shairport logs both indicated playback was happening, but no sound came out. This was resolved by reselecting the shairport device from the iOS device menu. But this is a massive improvement over the previous crashes.].

[mikebrady]

Thanks for trying it out. Not sure where the sound is disappearing to on those two occasions though. If you have a firewall running anywhere, give it room for some extra ports — I’d say a minimum range of 10.

[ben-willmore]

I tried another 20 switches. The first 19 worked correctly. On the 20th, the sound disappeared again. There's no firewall between the shairport device (a raspberry pi). Here is the log -- connection 38 is the one that failed:

Feb  2 16:37:52 pi-dining shairport-sync[5094]: Connection 17: SETUP with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Feb  2 16:38:15 pi-dining shairport-sync[5094]: Connection 18: SETUP with UDP ports Control: 6007, Timing: 6008 and Audio: 6009.
Feb  2 16:38:24 pi-dining shairport-sync[5094]: Connection 19: SETUP with UDP ports Control: 6010, Timing: 6001 and Audio: 6002.
Feb  2 16:38:44 pi-dining shairport-sync[5094]: Connection 20: SETUP with UDP ports Control: 6003, Timing: 6004 and Audio: 6005.
Feb  2 16:38:52 pi-dining shairport-sync[5094]: Connection 21: SETUP with UDP ports Control: 6006, Timing: 6007 and Audio: 6008.
Feb  2 16:39:08 pi-dining shairport-sync[5094]: Connection 22: SETUP with UDP ports Control: 6009, Timing: 6010 and Audio: 6001.
Feb  2 16:39:15 pi-dining shairport-sync[5094]: Connection 23: SETUP with UDP ports Control: 6002, Timing: 6003 and Audio: 6004.
Feb  2 16:39:30 pi-dining shairport-sync[5094]: Connection 24: SETUP with UDP ports Control: 6005, Timing: 6006 and Audio: 6007.
Feb  2 16:39:37 pi-dining shairport-sync[5094]: Connection 25: SETUP with UDP ports Control: 6008, Timing: 6009 and Audio: 6010.
Feb  2 16:39:57 pi-dining shairport-sync[5094]: Connection 26: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb  2 16:40:35 pi-dining shairport-sync[5094]: Connection 27: SETUP with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Feb  2 16:40:55 pi-dining shairport-sync[5094]: Connection 29: SETUP with UDP ports Control: 6007, Timing: 6008 and Audio: 6009.
Feb  2 16:41:06 pi-dining shairport-sync[5094]: Connection 30: SETUP with UDP ports Control: 6010, Timing: 6001 and Audio: 6002.
Feb  2 16:41:21 pi-dining shairport-sync[5094]: Connection 31: SETUP with UDP ports Control: 6003, Timing: 6004 and Audio: 6005.
Feb  2 16:41:28 pi-dining shairport-sync[5094]: Connection 32: SETUP with UDP ports Control: 6006, Timing: 6007 and Audio: 6008.
Feb  2 16:41:45 pi-dining shairport-sync[5094]: Connection 33: SETUP with UDP ports Control: 6009, Timing: 6010 and Audio: 6001.
Feb  2 16:41:53 pi-dining shairport-sync[5094]: Connection 35: SETUP with UDP ports Control: 6002, Timing: 6003 and Audio: 6004.
Feb  2 16:42:10 pi-dining shairport-sync[5094]: Connection 36: SETUP with UDP ports Control: 6005, Timing: 6006 and Audio: 6007.
Feb  2 16:42:23 pi-dining shairport-sync[5094]: Connection 37: SETUP with UDP ports Control: 6008, Timing: 6009 and Audio: 6010.
Feb  2 16:42:35 pi-dining shairport-sync[5094]: Connection 38: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.

[ben-willmore]

I now realise the disappearing audio is likely to be problem with my setup, not shairport-sync itself -- the speaker probably got switched off due to a race condition. Please ignore!

[mikebrady]

Thanks again. Please keep us posted on any developments.

Another thing that's coming up, in the unstable branch at present, is an new set of hooks for calling programs at the start and end on a newly-defined "active" period. An active period starts when a play session starts and then, when the play stops or is interrupted, Shairport Sync remains active for up to 10 seconds, waiting for play to resume or another play to start. If that happens, it stays active, otherwise activity is deemed to end. There are program hooks at the start and end -- maybe that's useful.

[ben-willmore]

Thanks for the info -- run_this_before_entering_active_mode and run_this_after_exiting_active_mode in the unstable branch work perfectly to switch my speakers on and off. This is what I originally wanted, and saves a lot of unnecessary switching in some situations. It took me a while to realise that 300 isn't a valid value for active_mode_timeout and I needed 300.0 instead.

[mikebrady]

That’s good! Will have to work on the documentation a bit...

[mikebrady]

Actually, a small thing, I've made the configuration reader less fussy about reading numbers. It should accept 300 now.

[ben-willmore]

I've been running with allow_session_interruption = "yes" for a week or so, and the crashes have completely stopped, which is a great improvement. However, I do still have problems if two streams start in quick succession. This often results in neither stream playing, and shaiport-sync failing to accept any new streams. This is a typical log:

Feb 11 07:20:31 pi-dining shairport-sync[384]: Connection 8: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 11 07:20:33 pi-dining shairport-sync[384]: Connection 9: SETUP with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Feb 11 07:20:34 pi-dining shairport-sync[384]: Switching on socket 1
Feb 11 07:20:34 pi-dining forked-daapd[408]: [  LOG]     raop: RECORD request failed in session startup: 0 (null)
Feb 11 07:21:04 pi-dining shairport-sync[384]: Connection 10: failed because a connection is already playing.
Feb 11 07:21:04 pi-dining forked-daapd[408]: [  LOG]     raop: ANNOUNCE request failed in session startup: 453 Unauthorized
Feb 11 07:21:23 pi-dining shairport-sync[384]: Connection 11 TEARDOWN received without having the player (no ANNOUNCE?)
Feb 11 07:21:23 pi-dining forked-daapd[408]: [  LOG]     raop: TEARDOWN request failed in session shutdown: 451 Unauthorized
Feb 11 07:22:32 pi-dining shairport-sync[384]: Connection 9: As Yeats almost said, "Too long a silence / can make a stone of the heart".
Feb 11 07:22:36 pi-dining shairport-sync[384]: an unrecoverable error, "unable_to_cancel_play_session", has been detected.

No stream played in this case.

I don't know why two streams sometimes start in quick succession like connections 8 and 9. This happens often when I play a track (once, not twice!) in forked-daapd, once the system has been idle for a while (10 hours or so). Perhaps the double-play is a bug in forked-daapd, or even a network problem, but ideally shairport-sync would not lock up when this happens.

[mikebrady]

Thanks. What is that “switching on socket 1” message coming from? Do you have a script running at play start? If so, how long does it take?

[mikebrady]

Okay, so, from your description, I can guess that it’s a message coming from a script to power up an amplifier. Have you set Shairport Sync to wait for a script to complete? If so, it would be interesting to know how long the script takes to run...

[ben-willmore]

Yes, the message comes from a script to power on an amplifier. It's set to run using run_this_before_entering_active_mode(not run_this_before_play_begins) so it only runs in this situation. wait_for_completion is yes. The script is surprisingly slow -- it takes reliably takes 1.3sec to run.

[mikebrady]

Thanks. Let me think about the possible scenarios. Shairport Sync should not hang up, that's true. But it may also be that forked-daapd becomes unhappy if it doesn't get a response in a reasonably short time.

[mikebrady]

Have you set up the Shairport Sync service to require a password?

[mikebrady]

Actually, forget that -- a return of 453 from ANNOUNCE means the device is already playing, not that it is not authorized. Similarly, a return of 451 from TEARDOWN merely means that the thread did not have the player -- all consisted with Connection 9 holding on to the player.

[mikebrady]

I guess it's worth asking -- if you set wait_for_completion to no does this lockup not happen?

[mikebrady]

So, if you would be kind enough to download the just-updated transit branch and, leaving wait_for_completion at yes, get this to happen again. At the Too long a silence... point, it will turn the debug verbosity up to max, so that we might see what happens in a little more detail.

[ben-willmore]

OK, I've installed the transit branch on two machines with wait_for_completion = "yes" and I'll keep an eye on them. I had some confusion over active_mode (in stable) and active_state (in transit) but that's now sorted. I also noticed run_this_if_an_unfixable_error _is_detected which sounds like it would add some robustness. Can I use this to just restart shairport-sync when an unfixable error happens?

[ben-willmore]

I got the double--play and the lockup, and the log is below, but I don't see any extra messages:

Feb 18 10:15:50 pi-sitting shairport-sync-1[6898]: avahi: service 'D5E872D7E26D@Sitting Room' successfully added.
Feb 18 10:28:43 pi-sitting shairport-sync-1[6898]: Connection 3: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 18 10:28:44 pi-sitting shairport-sync-1[6898]: Connection 4: SETUP with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Feb 18 10:28:45 pi-sitting shairport-sync-1[6898]: Switching on socket 1
Feb 18 10:29:34 pi-sitting shairport-sync-1[6898]: Connection 5 TEARDOWN received without having the player (no ANNOUNCE?)
Feb 18 10:30:44 pi-sitting shairport-sync-1[6898]: Connection 4: As Yeats almost said, "Too long a silence / can make a stone of the heart".
Feb 18 10:30:48 pi-sitting shairport-sync-1[6898]: an unrecoverable error, "unable_to_cancel_play_session", has been detected.
Feb 18 10:30:51 pi-sitting shairport-sync[7035]: fatal error: Could not establish a service on port 5000 -- program terminating. Is another instance of Shairport Sync running on this device?
Feb 18 10:30:52 pi-sitting systemd[1]: shairport-sync.service: Service hold-off time over, scheduling restart.
[more messages from systemd]

[ben-willmore]

Here is a log with allow_session_interruption = "no". The double-play still happens, the second connection is rejected, and the music plays just fine. I wonder what that second connection is!

Feb 18 10:38:30 pi-sitting shairport-sync-1[7197]: avahi: service 'D5E872D7E26D@Sitting Room' successfully added.
Feb 18 10:39:29 pi-sitting shairport-sync-1[7197]: Connection 4: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 18 10:39:30 pi-sitting shairport-sync-1[7197]: Connection 5: failed because a connection is already playing.
Feb 18 10:39:30 pi-sitting forked-daapd[498]: [  LOG]     raop: ANNOUNCE request failed in session startup: 453 Unauthorized
Feb 18 10:39:31 pi-sitting shairport-sync-1[7197]: Switching on socket 1
Feb 18 10:39:31 pi-sitting shairport-sync-1[7197]: keep_dac_busy is now 1

[ben-willmore]

Sorry for the repeated messages. I can now reliably reproduce the lockup on a minimal Pi Zero setup.

With the transit branch and the following settings, if I connect and reconnect a music player (forked-daapd) to the shairport speaker quickly and repeatedly (to simulate the rapid double-play), I get the lockup every time:

sessioncontrol =
{
  run_this_before_entering_active_state = "/bin/sleep 5";
  run_this_after_exiting_active_state = "/bin/sleep 5";
  active_state_timeout = 300;
  wait_for_completion = "yes";
  allow_session_interruption = "yes";
};

With wait_for_completion = "no", the lockup does not happen. If wait_for_completion = "yes" and the sleep is very short (0.1 sec), the lockup happens sometimes.

[mikebrady]

That's very helpful, thanks. I'll try to reproduce it here. It looks like the forked-daapd instance is running on the same device -- am I right?

[ben-willmore]

Most of my testing has been with forked-daapd and shairport-sync on different devices. But you're right there is one log above where they are both on the same device, so I guess it happens both ways.

[mikebrady]

What version of forked-daapd are you using, please? Did you compile it from source?

[ben-willmore]

$ forked-daapd --version
forked-daapd 26.4

I used ejurgensen's package, I didn't compile it myself.

[mikebrady]

Thanks. Can you explain a bit more how you "connect and reconnect a music player (forked-daapd) to the shairport speaker quickly and repeatedly"? What precisely are you doing? Are you using the web interface or something else?

[ben-willmore]

Hi --- My method for reproducing this is to select two shairport-sync speakers in admin page of the forked-daapd web interface, then press play. Then go back to the admin page, and click the checkbox repeatedly to enable and disable one of the speakers. This rapidly causes connects and disconnects without stopping the player.

[mikebrady]

Thanks again, and apologies for all the question. I do have another one -- have you set a password on the errant shairport-sync device?

[ben-willmore]

No password. The whole config file is:

general =
{
  name = "Dining Room";
  volume_range_db = 60;
};

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

sessioncontrol =
{
  run_this_before_entering_active_state = "/usr/local/bin/energenie --on 1";
  run_this_after_exiting_active_state = "/usr/local/bin/energenie --off 1";
  active_state_timeout = 300;
  wait_for_completion = "no";
  allow_session_interruption = "yes";
};

diagnostics =
{
  log_verbosity = 1;
};

[mikebrady]

Thanks again.

[mikebrady]

Well, I can't reproduce the problem yet, but I have noticed a situation that might cause a session to hang up. I've put a fix in the unstable branch, so it you got a chance, it would be great if you could test it.

The situation is that it might be possible that a session might be hanging up trying to respond to a client after the client has disappeared. I am just not certain that the timeout I [think I] put on the attempt to respond is being honoured, so I've tried a slightly different approach.

[ben-willmore]

I tried the transit branch which I think contains the same fix (ca325d0459) and it made no difference. By the way, the config file I posted yesterday is missing the crucial wait_for_completion = "yes";. As posted, it works fine (except that I lose the first couple of seconds of the first track because the amp isn't on when streaming starts).

[mikebrady]

Many thanks for trying! Yeah, I noticed the wait_for_completion setting alright and guessed it was your working version of the settings. I'll keep digging.

[mikebrady]

This is what I'm getting...

Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000555151|alsa: disable_standby_mode is 2.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000060259|alsa: output device name is "hw:0".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000303539|software version: "3.3d54-OpenSSL-Avahi-ALSA-soxr-sysconfdir:/etc"
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000111300|log verbosity is 1.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000082135|disable resend requests is off.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000042604|diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000016198|keep_dac_busy is now 1
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000047968|statistics_requester status is 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000038124|rtsp listening port is 5000.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000055312|udp base port is 6001.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000048385|udp port range is 10.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000055885|player name is "RaspberryPi3B".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000056458|backend is "(null)".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000038853|run_this_before_play_begins action is "(null)".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036771|run_this_after_play_ends action is "(null)".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036666|wait-cmd status is 1.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000037135|run_this_before_play_begins may return output is 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000038021|run_this_if_an_unfixable_error_is_detected action is "(null)".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000037395|run_this_before_entering_active_state action is  "/bin/sleep 5".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000038073|run_this_after_exiting_active_state action is  "/bin/sleep 5".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000037499|active_state_timeout is  300.000000 seconds.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000044895|mdns backend "(null)".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000035781|stuffing option is "1" (0-basic, 1-soxr).
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036406|resync time is 0.050000 seconds.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000038489|allow a session to be interrupted: 1.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000043125|busy timeout time is 120.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036406|drift tolerance is 0.001995 seconds.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000039583|password is "(null)".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000035364|ignore_volume_control is 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000035624|volume_max_db is not set
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000035365|volume range in dB (zero means use the range specified by the mixer): 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000035937|volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036718|playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right).
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000037343|disable_synchronization is 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036250|use_mmap_if_available is 1.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000035989|output_rate is 44100.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036614|output_format is 3 (0-unknown, 1-S8, 2-U8, 3-S16, 4-S24, 5-S24_3LE, 6-S24_3BE, 7-S32).
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036927|audio backend desired buffer length is 0.200000 seconds.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000038593|audio backend latency offset is 0.000000 seconds.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000039375|audio backend silence lead-in time is -1.000000 seconds. A value -1.0 means use the default.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000040208|zeroconf regtype is "_raop._tcp".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000040676|decoders_supported field is 1.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000037188|use_apple_decoder is 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036197|alsa_use_hardware_mute is 1.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000036406|no special mdns service interface was requested.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000063228|configuration file name "/etc/shairport-sync.conf" resolves to "/etc/shairport-sync.conf".
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000041823|loudness is 0.
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000038177|loudness reference level is -20.000000
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.005514054|Lowest dB value is a mute
Feb 25 10:59:09 RaspberryPi3B shairport-sync[11877]:          0.000096770|Hardware mixer has dB volume from -102.380000 to 4.000000.
Feb 25 10:59:10 RaspberryPi3B shairport-sync[11877]:          0.864708721|avahi: service '43774DD40C57@RaspberryPi3B' successfully added.
Feb 25 11:02:01 RaspberryPi3B shairport-sync[11877]:        171.270750768|Connection 2: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:02:06 RaspberryPi3B shairport-sync[11877]:          5.013906441|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:02:07 RaspberryPi3B shairport-sync[11877]:          0.484592418|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:02:07 RaspberryPi3B shairport-sync[11877]:          0.000660097|unrecognised parameter: "progress: 2291748066/2291763426/2312620256" (42)
Feb 25 11:06:33 RaspberryPi3B shairport-sync[11877]:        266.399448707|Connection 3: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:33 RaspberryPi3B shairport-sync[11877]:          0.006118330|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.484563825|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.000615880|unrecognised parameter: "progress: 2291748066/2303526914/2312620256" (42)
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.071794131|Connection 4: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.003555749|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.482259525|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.000634525|unrecognised parameter: "progress: 2291748066/2303554722/2312620256" (42)
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.106379074|Connection 5: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:34 RaspberryPi3B shairport-sync[11877]:          0.004565791|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:35 RaspberryPi3B shairport-sync[11877]:          0.482277963|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:35 RaspberryPi3B shairport-sync[11877]:          0.000442652|unrecognised parameter: "progress: 2291748066/2303579714/2312620256" (42)
Feb 25 11:06:35 RaspberryPi3B shairport-sync[11877]:          0.262638316|Connection 6: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:35 RaspberryPi3B shairport-sync[11877]:          0.004975995|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.482214891|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.000416351|unrecognised parameter: "progress: 2291748066/2303612450/2312620256" (42)
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.074049476|Connection 7: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.003827569|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.482011873|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.001314779|unrecognised parameter: "progress: 2291748066/2303638850/2312620256" (42)
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.185588920|Connection 8: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:36 RaspberryPi3B shairport-sync[11877]:          0.004649436|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.483270821|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.000625723|unrecognised parameter: "progress: 2291748066/2303665602/2312620256" (42)
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.071749081|Connection 9: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.003003514|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.482203330|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.001057178|unrecognised parameter: "progress: 2291748066/2303693058/2312620256" (42)
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.103464883|Connection 10: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:37 RaspberryPi3B shairport-sync[11877]:          0.003100857|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:38 RaspberryPi3B shairport-sync[11877]:          0.481661983|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:38 RaspberryPi3B shairport-sync[11877]:          0.000608275|unrecognised parameter: "progress: 2291748066/2303718050/2312620256" (42)
Feb 25 11:06:38 RaspberryPi3B shairport-sync[11877]:          0.198991662|Connection 11: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Feb 25 11:06:38 RaspberryPi3B shairport-sync[11877]:          0.005021621|received unknown Content-Type "application/x-dmap-tagged" in SET_PARAMETER request.
Feb 25 11:06:39 RaspberryPi3B shairport-sync[11877]:          0.482352758|received unknown Content-Type "image/png" in SET_PARAMETER request.
Feb 25 11:06:39 RaspberryPi3B shairport-sync[11877]:          0.001649099|unrecognised parameter: "progress: 2291748066/2303749026/2312620256" (42)
Feb 25 11:06:39 RaspberryPi3B shairport-sync[11877]:          0.119070522|Connection 12: SETUP with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.

So, I've added a little bit of diagnostics to the transit branch. At your leisure, I'd be grateful if you'd try it and post up the log please. I'm vaguely thinking of some IPv6 / IPv4 thing going on.

[ben-willmore]

I can now reproduce this fairly reliably on an intel machine with Ubuntu 18.04, forked-daapd 26.4 and shairport-sync transit branch.

shairport-sync.conf:

general =
{
  name = "Test";
  output_backend = "stdout";
};

sessioncontrol =
{
  run_this_before_entering_active_state = "/bin/sleep 5";
  run_this_after_exiting_active_state = "/bin/sleep 5";
  wait_for_completion = "yes";
  allow_session_interruption = "yes";
};

diagnostics =
{
  log_verbosity = 1;
};

Launch forked-daapd then launch shairport-sync with:

shairport-sync -c shairport-sync.conf >/dev/null

Go to forked-daapd web interface and enable both "Test" and the "Computer" speakers (the "Computer" speaker is just to keep forked-daapd playing while we experiment with shairport-sync). Press play. Then, in the forked-daapd admin page, repeatedly click the "Test" button to start and stop streaming to shairport-sync.

For good measure, slow the machine down with cat /dev/zero > /dev/null, and/or use nice so that the cat process runs at higher priority than shairport-sync.

This fails about 75% of the time, with log output like this:

ben@ubuntu:~$ shairport-sync -c shairport-sync.conf > /dev/null
software version: "3.3d54-OpenSSL-Avahi-ALSA-stdout-pipe-metadata-sysconfdir:/etc"
log verbosity is 1.
disable resend requests is off.
diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
statistics_requester status is 0.
daemon status is 0.
deamon pid file path is "/var/run/shairport-sync/shairport-sync.pid".
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 10.
player name is "Test".
backend is "stdout".
run_this_before_play_begins action is "(null)".
run_this_after_play_ends action is "(null)".
wait-cmd status is 1.
run_this_before_play_begins may return output is 0.
run_this_if_an_unfixable_error_is_detected action is "(null)".
run_this_before_entering_active_state action is  "/bin/sleep 5".
run_this_after_exiting_active_state action is  "/bin/sleep 5".
active_state_timeout is  10.000000 seconds.
mdns backend "(null)".
stuffing option is "0" (0-basic, 1-soxr).
resync time is 0.050000 seconds.
allow a session to be interrupted: 1.
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
volume range in dB (zero means use the range specified by the mixer): 0.
volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
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 1.000000 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.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
alsa_use_hardware_mute is 0.
no special mdns service interface was requested.
configuration file name "shairport-sync.conf" resolves to "/home/ben/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
avahi: service '0CBC6611F554@Test' successfully added.
Connection 3: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Connection 4: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 6 ANNOUNCE is waiting for connection 4 to shut down.
Connection 7 ANNOUNCE is waiting for connection 4 to shut down.
Connection 5: DACP-ID "(null)" on  failed because a connection is already playing.
Connection 6: DACP-ID "(null)" on  failed because a connection is already playing.
Connection 7: DACP-ID "(null)" on  failed because a connection is already playing.
Connection 8 TEARDOWN received without having the player (no ANNOUNCE?)
Connection 4: As Yeats almost said, "Too long a silence / can make a stone of the heart".
an unrecoverable error, "unable_to_cancel_play_session", has been detected.

If I set wait_for_completion = "no", the connections succeed every time with log output like:

ben@ubuntu:~$ shairport-sync -c shairport-sync.conf > /dev/null
software version: "3.3d54-OpenSSL-Avahi-ALSA-stdout-pipe-metadata-sysconfdir:/etc"
log verbosity is 1.
disable resend requests is off.
diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately.
statistics_requester status is 0.
daemon status is 0.
deamon pid file path is "/var/run/shairport-sync/shairport-sync.pid".
rtsp listening port is 5000.
udp base port is 6001.
udp port range is 10.
player name is "Test".
backend is "stdout".
run_this_before_play_begins action is "(null)".
run_this_after_play_ends action is "(null)".
wait-cmd status is 0.
run_this_before_play_begins may return output is 0.
run_this_if_an_unfixable_error_is_detected action is "(null)".
run_this_before_entering_active_state action is  "/bin/sleep 5".
run_this_after_exiting_active_state action is  "/bin/sleep 5".
active_state_timeout is  10.000000 seconds.
mdns backend "(null)".
stuffing option is "0" (0-basic, 1-soxr).
resync time is 0.050000 seconds.
allow a session to be interrupted: 1.
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
volume range in dB (zero means use the range specified by the mixer): 0.
volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0.
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 1.000000 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.
zeroconf regtype is "_raop._tcp".
decoders_supported field is 1.
use_apple_decoder is 0.
alsa_use_hardware_mute is 0.
no special mdns service interface was requested.
configuration file name "shairport-sync.conf" resolves to "/home/ben/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
avahi: service '0CBC6611F554@Test' successfully added.
Connection 3: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6001, Timing: 6002 and Audio: 6003.
Connection 4: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 5: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 6: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 7: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 8: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 9: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 10: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 11: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 12: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 13: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 14: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 15: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 16: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.
Connection 17: SETUP DACP-ID "5B3716D2285E6F19" from 172.16.227.184 to 172.16.227.184 with UDP ports Control: 6004, Timing: 6005 and Audio: 6006.

[mikebrady]

Thanks, Ben. I'm glad to see that it doesn't appear to be some odd network issue that's causing the original misbehaviour. My tests have been on a Pi 3B+, so I'll move over to a Pi Zero, as horsepower seems to be potentially important, and I'll experiment with the other suggestions you make. Otherwise, I've been following your procedure pretty closely, AFAIK.

If I may make a suggestion for the next time (!) -- could you set the diagnostic log_show_time_since_last_message to "yes", please? Sometimes the interval between the debug messages is useful information.

[mikebrady]

Ben, I notice you're sending to stdout. Does that make any difference, in your experience?

[mikebrady]

I think I got it, by heaven.

[mikebrady]

Okay, to I found a definite bug which I think would completely account for the problem. If a run_this_before_entering_active_state script was running when the play session that caused it was interrupted by a new play session, then a mutex would be left locked. Then, the next play session would wait forever for the mutex to be unlocked.

The bug has been fixed in the latest update to the transit branch. Would you mind giving it a try at your leisure, please?

[ben-willmore]

Awesome -- I can no longer manually reproduce the bug either on my ubuntu test setup or any of my raspberry pis. I will observe for a few days and see if it happens spontaneously but I'm pretty sure it won't. By the way, apart from this little issue, shairport-sync has been working brilliantly for me. Thanks for your work on this and shairport-sync in general!

[mikebrady]

Great, thanks.