Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
1 task done
mill1000 opened this issue Mar 18, 2023 · 15 comments
Closed
1 task done

Comments

@mill1000
Copy link

mill1000 commented Mar 18, 2023

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
Copy link
Owner

mikebrady commented Mar 18, 2023

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
Copy link
Author

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
Copy link

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.

@github-actions github-actions bot added the Stale label May 19, 2023
@mill1000
Copy link
Author

Not stale as far as I know.

@github-actions github-actions bot removed the Stale label May 20, 2023
@mikebrady
Copy link
Owner

I haven’t forgotten!

@mikebrady
Copy link
Owner

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
Copy link
Owner

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
Copy link

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.

@github-actions github-actions bot added the Stale label Aug 26, 2023
@mill1000
Copy link
Author

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

@mikebrady
Copy link
Owner

Thanks for the update. No reason -- it should be there, but let me check!

@github-actions github-actions bot removed the Stale label Aug 27, 2023
@mikebrady
Copy link
Owner

You’re right — it’s not working yet 😬. I’ll try again.

@mikebrady
Copy link
Owner

Hello again. I've tried an alternative approach that looks like it works. If you got a chance to try it, that would be appreciated.

@mill1000
Copy link
Author

mill1000 commented Aug 27, 2023

That one seemed to do this trick! Thanks

Got SIGTERM, quitting.
Leaving mDNS multicast group on interface docker0.IPv4 with address 172.17.0.1.
         0.627887656 "mdns_avahi.c:296" avahi: client failure: Daemon connection failed
         0.000101198 "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.
avahi-daemon 0.8 exiting.
         0.011428385 "mdns_avahi.c:324" avahi: received AVAHI_CLIENT_CONNECTING
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
         0.012956823 "shairport.c:1751" exit on SIGTERM
         0.000261979 "rtsp.c:5377" rtsp_listen_loop_cleanup_handler called.
         0.000050729 "rtsp.c:734" Connection 2: cancelled.
         0.000120938 "rtsp.c:5048" Connection 2: rtsp_conversation_thread_func_cleanup_function called.
         0.000519479 "audio_alsa.c:1811" alsa: do_close()
         0.000659687 "mdns_avahi.c:296" avahi: client failure: Daemon connection failed
         0.000048855 "mdns_avahi.c:299" avahi client -- we have been disconnected, so let's reconnect.
         0.000577656 "mdns_avahi.c:310" *warning: avahi: failed to create client object: Daemon not running
s6-rc: info: service syslogd-log successfully stopped
s6-rc: info: service syslogd-prepare: stopping
s6-rc: info: service s6rc-fdholder: stopping
s6-rc: info: service syslogd-prepare successfully stopped
         0.009159114 "audio_alsa.c:1824" alsa: do_close() -- closing alsa handle
         0.000538177 "player.c:1859" Cancelling AP1 timing, control and audio threads...
         0.001095417 "rtp.c:320" Control Receiver Cleanup Done.
s6-rc: info: service s6rc-fdholder successfully stopped
         0.005917813 "player.c:433" 2048 buffers allocated, 2048 buffers released.
         0.000294166 "player.c:1907" Connection 2: player terminated.
         0.000956042 "rtsp.c:550" Connection 2: release play lock.
         0.000049844 "rtsp.c:556" Connection 2: play lock released.
         0.000092656 "rtsp.c:5083" Connection 2: terminating -- closing RTSP connection socket 15: from 10.100.1.121:48076 to self at 10.100.1.4:5000.
         0.000010208 "mqtt.c:108" [MQTT]: publishing under devberry/shairport/play_end
         0.000173750 "dbus-service.c:226" Build metadata
         0.000688021 "rtsp.c:5146" Connection 2: Closed.
         0.000684219 "rtsp.c:743" Connection 2: joined.
         0.000209271 "rtsp.c:5383" closing socket 10.
         0.000235208 "rtsp.c:5383" closing socket 11.
         0.000437396 "shairport.c:1588" exit function called...
         0.000079271 "shairport.c:1598" Stopping the activity monitor.
         0.000022291 "activity_monitor.c:243" activity_monitor_stop begin. state: 2, player_state: 0.
         0.000049636 "activity_monitor.c:84" aend
         0.000356094 "mqtt.c:108" [MQTT]: publishing under devberry/shairport/active_end
         0.000635052 "mpris-service.c:167" Build metadata
         0.000016354 "activity_monitor.c:250" activity_monitor_stop complete
         0.000095260 "shairport.c:1600" Stopping the activity monitor done.
         0.000046979 "shairport.c:1603" Stopping DACP Monitor
         0.000459688 "dacp.c:991" dacp_monitor_stop
         0.000566458 "shairport.c:1605" Stopping DACP Monitor Done
         0.000065313 "dbus-service.c:226" Build metadata
         0.000011614 "shairport.c:1616" Stopping D-Bus service
         0.000063802 "dbus-service.c:1218" stopping dbus service
         0.000050573 "shairport.c:1618" Stopping D-Bus service done
         0.000044167 "shairport.c:1621" Stopping D-Bus Loop Thread
         0.000636094 "mpris-service.c:167" Build metadata
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
         0.055184166 "shairport.c:1751" exit on SIGTERM

Copy link

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

@mill1000
Copy link
Author

Oops never closed this.

mtremer pushed a commit to ipfire/ipfire-2.x that referenced this issue Sep 3, 2024
- Update from version 4.3.2 to 4.3.4
- Update of rootfile
- Changelog is only defined for 4.3, 4.2 etc so the below changelog is for all of 4.3
   Cannot determine which things were alreday fixed in 4.3.2 and earlier and which are
   from 4.3.3 onwards.
    4.3
**Security Updates**
	* A crashing bug in NQPTP has been fixed.
	* The communications protocol used between NQPTP and Shairport Sync has been
	  revised and made more resilient to attempted misuse.
	* In Linux systems, NQPTP no longer runs as `root` -- instead it runs as the
	  restriced user `nqptp`, with access to ports 319 and 320 set by the installer
	  via the `setcap` utility.
**Enhancements**
	* A new volume control profile called `dasl-tapered` has been added in which
	  halving the volume control setting halves the output level.
	  For example, moving the volume slider from full to half reduces the output
	  level by 10dB, which roughly corresponds with a perceived halving of the audio
	  volume level.
	  Moving the volume slider from half to a quarter reduces the output level by a
	  a further 10dB.
	  The tapering rate is slightly modified at the lower end of the range if the
	  device's attenuation range is restricted (less than about 55dB).
	  To activate the `dasl-tapered` profile, set the `volume_control_profile` to
	  `"dasl_tapered"` in the configuration file and restart Shairport Sync.
	  Many thanks to David Leibovic, aka [dasl-](https://github.com/dasl-), for this.
	* On graceful shutdown, an `active_end` signal should now be generated if the
	  system was in the active state. Addresses issue
	  [#1647](mikebrady/shairport-sync#1647). Thanks to
	  [Tucker Kern](https://github.com/mill1000) for raising the issue.
**Bug Fixes**
	* Fixed a bug that causes the Docker image to crash occasionally when OwnTone
	  interrupted an existing iOS session. Thanks to
	  [aaronk6](https://github.com/aaronk6) for the report.
	* Fixed a cross-compliation error caused by not looking for the correct version
	  of the `ar` tool. The fix was to substitute the correct version during the
	  `autoreconf` phase. Thanks to
	  [sternenseemann](https://github.com/sternenseemann) for raising the
	  [issue](mikebrady/shairport-sync#1705) and the
	  [PR](mikebrady/shairport-sync#1706) containing the fix.
	* Updated the mDNS strings for the Classic AirPlay feature of AP2, so that it
	  does not appear to provide MFi authentication. Addresses
	  [this discussion](mikebrady/shairport-sync#1691).
	* Always uses a revision number of 1 when looking for status updates on the DACP
	  remote control port. This follows a suggestion in
	  [Issue #1658](mikebrady/shairport-sync#1658). Thanks
	  to [ejurgensen](https://github.com/ejurgensen), as ever, for the report and
	  the suggested fix.
	* Fixed a `statistics` bug (the minimum buffer size was incorrectly logged) and
	  also tidy up the statistics logging interval logic for resetting min and max
	  counters.
	* Added an important missing format string argument to a call in the Jack Audio
	  backend. Many thanks to [michieldwitte] for their
	  [PR](mikebrady/shairport-sync#1693).
**Maintenance**
	* Stopped using a deprecated FFmpeg data structure reference.
	* Stopped using deprecated OpenSSL calls. Thanks to [yubiuser] for their
	  [PR](mikebrady/shairport-sync#1684) -- which did some
	  of the updating -- and for their guidance.
	* Run workflow-based tests on PRs automatically. Thanks to [yubiuser]
	  for their [PR](mikebrady/shairport-sync#1687).

Signed-off-by: Adolf Belka <[email protected]>
Signed-off-by: Michael Tremer <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants