Software stuck after network event

[mcurcio]

I keep bumping into an issue where I can't connect to the server with the "Unable to connect to ..." message on my iPhone. I have tried every setting I can think of that would allow new connections to boot old connections, but that doesn't seem to help in this case. When it works, it definitely works. I only get in this wonky state when the streaming device disconnects from WiFi while connected to shairport.

Is there a setting that I am missing that will absolutely override any existing connections?

Mac 11.2 (via brew)

Version:

> shairport-sync --version
3.3.7-libdaemon-OpenSSL-dns_sd-ao-pa-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc/shairport-syn

Logs:

``` 0.000453435 "shairport.c:1729" Started! 0.000100175 "shairport.c:1756" software version: "3.3.7-libdaemon-OpenSSL-dns_sd-ao-pa-stdout-pipe-soxr-metadata-sysconfdir:/usr/local/etc/shairport-sync" 0.000030081 "shairport.c:1762" log verbosity is 1. 0.000081219 "audio_pipe.c:132" audio pipe name is "./pipe" 0.000044649 "shairport.c:1810" disable resend requests is off. 0.000061506 "shairport.c:1814" diagnostic_drop_packet_fraction is 0.000000. A value of 0.0 means no packets will be dropped deliberately. 0.000025919 "shairport.c:1815" statistics_requester status is 0. 0.000020268 "shairport.c:1817" daemon status is 0. 0.000024228 "shairport.c:1818" daemon pid file path is "/usr/local/var/run/shairport-sync.pid". 0.000019950 "shairport.c:1820" rtsp listening port is 5002. 0.000020242 "shairport.c:1821" udp base port is 6001. 0.000023750 "shairport.c:1822" udp port range is 10. 0.000023120 "shairport.c:1823" player name is "Great Room Speakers". 0.000022920 "shairport.c:1824" backend is "pipe". 0.000022987 "shairport.c:1825" run_this_before_play_begins action is "(null)". 0.000023036 "shairport.c:1826" run_this_after_play_ends action is "(null)". 0.000022425 "shairport.c:1827" wait-cmd status is 0. 0.000019564 "shairport.c:1828" run_this_before_play_begins may return output is 0. 0.000018928 "shairport.c:1829" run_this_if_an_unfixable_error_is_detected action is "(null)". 0.000018939 "shairport.c:1830" run_this_before_entering_active_state action is "(null)". 0.000018912 "shairport.c:1831" run_this_after_exiting_active_state action is "(null)". 0.000018752 "shairport.c:1832" active_state_timeout is 1.000000 seconds. 0.000019008 "shairport.c:1833" mdns backend "(null)". 0.000018799 "shairport.c:1837" interpolation setting is "auto". 0.000018900 "shairport.c:1838" interpolation soxr_delay_threshold is 30. 0.000018998 "shairport.c:1839" resync time is 0.050000 seconds. 0.000019110 "shairport.c:1840" allow a session to be interrupted: 1. 0.000025412 "shairport.c:1841" busy timeout time is 1. 0.000020372 "shairport.c:1842" drift tolerance is 0.001995 seconds. 0.000018682 "shairport.c:1843" password is "(null)". 0.000018360 "shairport.c:1844" ignore_volume_control is 0. 0.000018474 "shairport.c:1848" volume_max_db is not set 0.000018459 "shairport.c:1850" volume range in dB (zero means use the range specified by the mixer): 80. 0.000022581 "shairport.c:1854" volume_range_combined_hardware_priority (1 means hardware mixer attenuation is used first) is 0. 0.000019046 "shairport.c:1856" playback_mode is 0 (0-stereo, 1-mono, 1-reverse_stereo, 2-both_left, 3-both_right). 0.000018914 "shairport.c:1857" disable_synchronization is 0. 0.000018813 "shairport.c:1858" use_mmap_if_available is 1. 0.000018832 "shairport.c:1860" output_format automatic selection is enabled. 0.000018685 "shairport.c:1864" output_rate automatic selection is enabled. 0.000019503 "shairport.c:1868" audio backend desired buffer length is 1.000000 seconds. 0.000018866 "shairport.c:1870" audio_backend_buffer_interpolation_threshold_in_seconds is 0.000000 seconds. 0.000019101 "shairport.c:1871" audio backend latency offset is 0.000000 seconds. 0.000018923 "shairport.c:1876" audio backend silence lead-in time is 0.000000 seconds. 0.000019279 "shairport.c:1877" zeroconf regtype is "_raop._tcp". 0.000019351 "shairport.c:1878" decoders_supported field is 1. 0.000019539 "shairport.c:1879" use_apple_decoder is 0. 0.000022788 "shairport.c:1880" alsa_use_hardware_mute is 0. 0.000022812 "shairport.c:1884" no special mdns service interface was requested. 0.000072393 "shairport.c:1888" configuration file name "shairport.conf" resolves to "/private/var/lib/shairport/great_room/shairport.conf". 0.000031588 "shairport.c:1894" metadata enabled is 1. 0.000020389 "shairport.c:1895" metadata pipename is "/tmp/shairport-sync-metadata". 0.000020127 "shairport.c:1897" metadata socket address is "(null)" port 0. 0.000022681 "shairport.c:1898" metadata socket packet size is "500". 0.000074260 "shairport.c:1899" get-coverart is 1. 0.000026870 "shairport.c:1917" loudness is 0. 0.000024259 "shairport.c:1918" loudness reference level is -20.000000 0.000120994 "rtsp.c:1665" metadata pipe name is "/tmp/shairport-sync-metadata". 1.500004640 "shairport.c:201" "soxr" interpolation has been chosen. 15.218803586 "rtsp.c:1062" Connection 1: SETUP DACP-ID "3041B6E0EC09847C" from fe80::1011:187f:f2c0:1dbb to fe80::100f:ee8f:dfe6:a37e with UDP ports Control: 6001, Timing: 6002 and Audio: 6003. <-- Lost wifi connection 2.434657055 "rtp.c:821" Time ping turnaround time: 203815415 ns -- it looks like a timing ping was lost. <-- Regained wifi and tried to reconnect; all of the below connections resulted in error message 26.660545651 "rtsp.c:1062" Connection 2: SETUP DACP-ID "EDDE77F617D37DF5" from fe80::1024:8cdc:51d7:fe06 to fe80::100f:ee8f:dfe6:a37e with UDP ports Control: 6004, Timing: 6005 and Audio: 6006. 13.931053169 "rtsp.c:1062" Connection 3: SETUP DACP-ID "66D2047C98F25ECE" from fe80::1011:187f:f2c0:1dbb to fe80::100f:ee8f:dfe6:a37e with UDP ports Control: 6007, Timing: 6008 and Audio: 6009. 2.068353047 "rtp.c:821" Time ping turnaround time: 205206846 ns -- it looks like a timing ping was lost. 21.872801678 "rtp.c:821" Time ping turnaround time: 204163988 ns -- it looks like a timing ping was lost. 17043.194218422 "rtsp.c:1062" Connection 4: SETUP DACP-ID "B67115BE62872387" from fe80::1483:cce7:ddfb:1ede to fe80::100f:ee8f:dfe6:a37e with UDP ports Control: 6001, Timing: 6002 and Audio: 6003. 45916.819347614 "rtsp.c:1062" Connection 5: SETUP DACP-ID "41076C4527768C55" from fe80::1024:8cdc:51d7:fe06 to fe80::100f:ee8f:dfe6:a37e with UDP ports Control: 6001, Timing: 6002 and Audio: 6003. 74.265472926 "rtp.c:821" Time ping turnaround time: 2365375540 ns -- it looks like a timing ping was lost. 2.487958997 "rtsp.c:338" Connection 5: As Yeats almost said, "Too long a silence / can make a stone of the heart". 21.153252225 "rtsp.c:1062" Connection 6: SETUP DACP-ID "4ABACDF8E5F7F732" from fe80::1024:8cdc:51d7:fe06 to fe80::100f:ee8f:dfe6:a37e with UDP ports Control: 6001, Timing: 6002 and Audio: 6003. 61.921669913 "rtsp.c:338" Connection 6: As Yeats almost said, "Too long a silence / can make a stone of the heart". 4.295882095 "rtsp.c:347" *warning: an unrecoverable error, "unable_to_cancel_play_session", has been detected. 5.905593343 "rtp.c:821" Time ping turnaround time: 214146075 ns -- it looks like a timing ping was lost. 12.672183188 "rtp.c:821" Time ping turnaround time: 302680681 ns -- it looks like a timing ping was lost. 35.065849021 "rtsp.c:1972" Connection 7 ANNOUNCE is waiting for connection 6 to shut down. 0.891426276 "rtsp.c:338" Connection 7: As Yeats almost said, "Too long a silence / can make a stone of the heart". 13.997147079 "rtsp.c:338" Connection 8: As Yeats almost said, "Too long a silence / can make a stone of the heart". 57.524468820 "rtsp.c:1972" Connection 9 ANNOUNCE is waiting for connection 6 to shut down. 1.770438319 "rtsp.c:338" Connection 9: As Yeats almost said, "Too long a silence / can make a stone of the heart". 118728.786337228 "rtsp.c:1972" Connection 10 ANNOUNCE is waiting for connection 6 to shut down. 1.796489294 "rtsp.c:338" Connection 10: As Yeats almost said, "Too long a silence / can make a stone of the heart". 6.613957950 "rtsp.c:338" Connection 11: As Yeats almost said, "Too long a silence / can make a stone of the heart". 80647.580618671 "rtsp.c:338" Connection 13: As Yeats almost said, "Too long a silence / can make a stone of the heart". 27.266723999 "rtsp.c:338" Connection 15: As Yeats almost said, "Too long a silence / can make a stone of the heart". ```

Config:

``` general = { name = "Great Room Speakers"; output_backend = "pipe"; port = 5002; # audio_backend_latency_offset_in_seconds = -0.5 audio_backend_silent_lead_in_time = 0 volume_control_profile = "flat"; volume_range_db = 80; } sessioncontrol = { active_state_timeout = 1; allow_session_interruption = "yes"; session_timeout = 1; } pipe = { name = "./pipe"; } ```

[mikebrady]

Thanks for the post, and apologies for the delay in responding. So it looks like you network temporarily disconnects and then Shairport Sync can't clear the connection and cancel the play session so as to be able to start again.

Obviously, it would be great to find where Shairport Sync is hanging, presumably on some network connection somewhere, but in the meantime, it does have a last-ditch facility -- the run_this_if_an_unfixable_error_is_detected hook. A program (such as a shell script) attached to this hook will run when that *warning: an unrecoverable error… event occurs. You could use it to run a script to kill Shairport Sync and restart it. However, it's quite tricky. Most probably the program will require root privilege, so you'd need to equip it with password-less sudo privileges to be able to do the job.

[luckman212]

@mikebrady can you please tell a bit more info of how to trap or hook this run_this_if_an_unfixable_error_is_detected in a shell script? I found my shairport-sync was wedged and eating 100% cpu this morning too, not sure why. I had to kill it manually.

[mikebrady]

If Shairport Sync detects one of two conditions, it will execute the program you specify with the run_this_if_an_unfixable_error_is_detected portion in the configuration file. The two conditions are (1) the output ALSA device stops accepting samples for a prolonged period and (2) a play session with no audio can not be terminated. It doesn't detect any other conditions.

[mcurcio]

Thanks @mikebrady! I have two sort of follow up questions based on your notes:

1. Is there a built-in way to simply kill shairport when run_this_if_an_unfixable_error_is_detected would normally run? I am using launchd to control the process anyway, so the simplest solution for me would be something like shutdown_if_an_unfixable_error_is_detected.
2. The *warning: an unrecoverable error… printed after almost 17 hours of "stuck-ness". Is there a setting that might make that detected sooner?

[mikebrady]

1. Yes, you could write a shell script to kill Shairport Sync. But like I wrote above, if Shairport Sync is not running as root, then you might have to dot some sudo magic on the script; otherwise it won't be allowed to kill Shairport Sync.
2. I don't know what is causing the problem, I'm afraid, so I wouldn't know how to detect it sooner.

[github-actions[bot]]

This issue has been inactive for 60 days so will be closed 7 days from now. To prevent this, please remove the "stale" label or post a comment.