[Problem]: No active_end published when Shairport is gracefully shutdown

[mill1000]

What happened?

When Shairport Sync is shutdown gracefully it publishes a play_end message via MQTT. Instead I would expect an active_end message to be published as a shutdown is more like termination of an session than the stopping of a track.

Relevant log output

         0.015104219 "shairport.c:1690" exit on SIGINT
         0.001073906 "rtsp.c:5294" rtsp_listen_loop_cleanup_handler called.
         0.000230781 "rtsp.c:724" Connection 2: cancelled.
         0.000078125 "rtsp.c:4973" Connection 2: rtsp_conversation_thread_func_cleanup_function called.
         0.004356979 "audio_alsa.c:1844" alsa: do_close()
         0.010486875 "audio_alsa.c:1857" alsa: do_close() -- closing alsa handle
         0.025824844 "player.c:1772" Cancelling AP1 timing, control and audio threads...
         0.000580365 "rtp.c:320" Control Receiver Cleanup Done.
         0.000747604 "player.c:1820" Connection 2: player terminated.
         0.000364791 "mqtt.c:108" [MQTT]: publishing under stereoberry/shairport/play_end
         0.000222188 "rtsp.c:540" Connection 2: release play lock.
         0.000029948 "rtsp.c:546" Connection 2: play lock released.
         0.000139531 "rtsp.c:5004" Connection 2 Closed by self: from 10.100.1.121:48964 to self at 10.100.1.3:5000.
         0.000373958 "rtsp.c:5063" Connection 2: Closed.
         0.000270417 "rtsp.c:733" Connection 2: joined.
         0.000035365 "rtsp.c:5300" closing socket 10.
         0.000228385 "rtsp.c:5300" closing socket 11.
         0.000307500 "shairport.c:1534" exit function called...
         0.000028021 "shairport.c:1557" Stopping D-Bus Loop Thread
         0.000088802 "shairport.c:1502" g_main_loop thread exit
         0.000573333 "shairport.c:1565" Stopping D-Bus Loop Thread Done
         0.000032396 "shairport.c:1570" Stopping DACP Monitor
         0.000023438 "dacp.c:990" dacp_monitor_stop
         0.000299531 "shairport.c:1572" Stopping DACP Monitor Done
         0.000101875 "shairport.c:1576" Stopping metadata hub
         0.000023958 "shairport.c:1578" Stopping metadata done
         0.000021979 "shairport.c:1582" Stopping metadata
         0.000021459 "rtsp.c:4159" metadata_stop called.
         0.000113073 "rtsp.c:380" Deleting metadata queue "mqtt".
         0.000301041 "rtsp.c:380" Deleting metadata queue "hub".
         0.000329792 "rtsp.c:380" Deleting metadata queue "multicast".
         0.000269010 "rtsp.c:380" Deleting metadata queue "pipe".
         0.000235625 "shairport.c:1584" Stopping metadata done
         0.000029115 "shairport.c:1586" Stopping the activity monitor.
         0.000213125 "activity_monitor.c:244" activity_monitor_stop complete
         0.000025365 "shairport.c:1588" Stopping the activity monitor done.
         0.000023020 "shairport.c:1591" Deinitialise the audio backend.
         0.000025730 "audio_alsa.c:1381" Cancel buffer monitor thread.
         0.000258958 "shairport.c:1593" Deinitialise the audio backend done.
         0.000028490 "shairport.c:1599" Waiting for SoXr timecheck to terminate...
         0.000111718 "shairport.c:1602" Waiting for SoXr timecheck to terminate done
         0.001338334 "mdns_avahi.c:517" avahi_dacp_monitor_stop Avahi DACP monitor successfully stopped
         0.000058854 "mdns_avahi.c:414" avahi_unregister.
         0.000025208 "mdns_avahi.c:416" avahi: stop the threaded poll.
         0.000555156 "mdns_avahi.c:420" avahi: free the client.
         0.000156355 "mdns_avahi.c:426" avahi: free the threaded poll.
         0.000065989 "mdns_avahi.c:434" avahi: free the service name.
         0.000023594 "mdns_avahi.c:441" avahi: free the ap2 service_name.
         0.000020781 "mdns_avahi.c:447" avahi free text_record_string_list
         0.000028490 "shairport.c:1670" normal exit

Configuration Information.

Linux StereoBerry 5.15.84-v7+ #1613 SMP Thu Jan 5 11:59:48 GMT 2023 armv7l GNU/Linux

4.1-alac-OpenSSL-Avahi-ALSA-soxr-metadata-mqtt-mpris-sysconfdir:/etc

How did you install Shairport Sync?

Built from source

Check previous issues

• Confirm

[mikebrady]

Thanks for this. The missing active_end is an oversight -- we'll look at incorporating it in a development version. The play_end will probably stay though. Normally, of course, Shairport Sync never stops 🙂.

[mill1000]

Ha yeah it doesn't come up in normal usage. As long as active_end comes after the play_end I'll be happy.

[github-actions]

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

[mill1000]

Not stale as far as I know.

[mikebrady]

I haven’t forgotten!

[mikebrady]

Hi there. An update has just been pushed to the development branch which should hopefully address this issue. If you got a chance to test it out, at your leisure, and report back, it would be appreciated. Apologies for the delay in doing this.

[mikebrady]

Update -- just pushed another relevant update to the development branch -- the metadata system was being shut down before the active_end message could be sent, duh.

[github-actions]

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

[mill1000]

I tried testing this on the development docker image and still saw no active_end message when shutting down the container.

Is there any reason the docker image wouldn't contain this fix?

Image

mikebrady/shairport-sync                development-classic   e721395bd111   4 weeks ago   72.8MB

Logs on shutdown

s6-rc: info: service legacy-services: stopping
s6-rc: info: service legacy-services successfully stopped
s6-rc: info: service syslogd: stopping
s6-rc: info: service 03-avahi: stopping
Got SIGTERM, quitting.
Leaving mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1.
         0.560527916 "mdns_avahi.c:296" avahi: client failure: Daemon connection failed
         0.000066042 "mdns_avahi.c:299" avahi client -- we have been disconnected, so let's reconnect.
Leaving mDNS multicast group on interface wlan0.IPv6 with address fe80::9232:1295:9af6:e9d6.
Leaving mDNS multicast group on interface wlan0.IPv4 with address 10.100.1.4.
Leaving mDNS multicast group on interface lo.IPv6 with address ::1.
Leaving mDNS multicast group on interface lo.IPv4 with address 127.0.0.1.
         0.007624167 "mdns_avahi.c:324" avahi: received AVAHI_CLIENT_CONNECTING
avahi-daemon 0.8 exiting.
s6-rc: info: service syslogd successfully stopped
s6-rc: info: service syslogd-log: stopping
s6-rc: info: service 03-avahi successfully stopped
s6-rc: info: service 02-dbus: stopping
s6-rc: info: service syslogd-log successfully stopped
         0.019645989 "shairport.c:1751" exit on SIGTERM
         0.000587188 "rtsp.c:5377" rtsp_listen_loop_cleanup_handler called.
         0.000219427 "rtsp.c:734" Connection 1: cancelled.
         0.001022604 "rtsp.c:5048" Connection 1: rtsp_conversation_thread_func_cleanup_function called.
s6-rc: info: service syslogd-prepare: stopping
         0.000621823 "mdns_avahi.c:296" avahi: client failure: Daemon connection failed
         0.000064792 "mdns_avahi.c:299" avahi client -- we have been disconnected, so let's reconnect.
         0.000528489 "mdns_avahi.c:310" *warning: avahi: failed to create client object: Daemon not running
s6-rc: info: service s6rc-fdholder: stopping
         0.003815313 "audio_alsa.c:1811" alsa: do_close()
s6-rc: info: service syslogd-prepare successfully stopped
         0.010385937 "audio_alsa.c:1824" alsa: do_close() -- closing alsa handle
         0.001094115 "player.c:1859" Cancelling AP1 timing, control and audio threads...
         0.001941510 "rtp.c:320" Control Receiver Cleanup Done.
s6-rc: info: service s6rc-fdholder successfully stopped
         0.003704323 "player.c:433" 1024 buffers allocated, 1024 buffers released.
         0.000119740 "player.c:1907" Connection 1: player terminated.
         0.000256771 "rtsp.c:550" Connection 1: release play lock.
         0.000155313 "rtsp.c:556" Connection 1: play lock released.
         0.000124219 "rtsp.c:5083" Connection 1: terminating -- closing RTSP connection socket 15: from 10.100.1.121:44942 to self at 10.100.1.4:5000.
         0.000032395 "mqtt.c:108" [MQTT]: publishing under devberry/shairport/play_end
         0.000354843 "dbus-service.c:226" Build metadata
         0.000414428 "mpris-service.c:167" Build metadata
         0.000745989 "rtsp.c:5146" Connection 1: Closed.
         0.001148073 "rtsp.c:743" Connection 1: joined.
         0.000120990 "rtsp.c:5383" closing socket 10.
         0.000084791 "rtsp.c:5383" closing socket 11.
         0.000136563 "shairport.c:1588" exit function called...
         0.000060469 "shairport.c:1598" Stopping the activity monitor.
         0.000171510 "activity_monitor.c:249" activity_monitor_stop complete
         0.000371094 "shairport.c:1600" Stopping the activity monitor done.
         0.000088437 "shairport.c:1603" Stopping DACP Monitor
         0.000069584 "dacp.c:991" dacp_monitor_stop
         0.000361250 "shairport.c:1605" Stopping DACP Monitor Done
         0.000039947 "shairport.c:1616" Stopping D-Bus service
         0.000063230 "dbus-service.c:1218" stopping dbus service
         0.000095260 "shairport.c:1618" Stopping D-Bus service done
         0.000046510 "shairport.c:1621" Stopping D-Bus Loop Thread
s6-rc: info: service 02-dbus successfully stopped
s6-rc: info: service 01-startup: stopping
s6-rc: info: service 01-startup successfully stopped
s6-rc: info: service legacy-cont-init: stopping
s6-rc: info: service legacy-cont-init successfully stopped
s6-rc: info: service fix-attrs: stopping
s6-rc: info: service fix-attrs successfully stopped
s6-rc: info: service s6rc-oneshot-runner: stopping
s6-rc: info: service s6rc-oneshot-runner successfully stopped