Detecting when the OctoPrint service is stopping

Development
1

I'm having difficulty telling when OctoPrint is being stopped.

  • The ShutdownPlugin mixin doesn't appear to be working from what I've seen; the on_shutdown() doesn't seem to be firing off when I want it to
  • I tried adding a def __del__(): function in my main plugin class but that's not firing off.
  • I added on_event() but there doesn't appear to be an event fired off for the service being stopped or restarted.

I really need to gracefully close something that's brought up with subprocess.Popen() but I'm running without radar on this.

I've been using sudo service octoprint stop and I expect to see something logging this activity within any of my attempts to detect shutdown.

2

Seems to work properly for me.

Do you have a code sample?
Does it work when sending SIGTERM?

3

I'm guessing that the mixin works when you choose to shutdown from the OctoPrint system menu.

Here is the stop section of OctoPrint's service handler /etc/init.d/octoprint:

do_stop()
{
   # Return
   #   0 if daemon has been stopped
   #   1 if daemon was already stopped
   #   2 if daemon could not be stopped
   #   other if a failure occurred

   start-stop-daemon --stop --quiet --retry=TERM/30/KILL/5 --user $OCTOPRINT_USER --pidfile $PIDFILE
   RETVAL="$?"
   [ "$RETVAL" = "2" ] && return 2

   rm -f $PIDFILE

   [ "$RETVAL" = "0"  ] && return 0 || return 1
}

This means that the service handler already uses SIGTERM with a 30-second timeout then changes to SIGKILL if that didn't work.

Here's a bit of code which isn't firing off within my own class. So the plugin isn't getting asked to die, for example. Earlier, this was just def on_shutdown(self): and the mixin mentioned was added in the class creation line.

    def __del__(self):
        self._logger.info('Setting stop flag and closing USB receiver...')
        self.bStop =                        True
        self.joy.close()

It's basically related to this old request issue which was closed by me a long time ago.

4

Why not use the event plugin mixin and react to server shutdown?

https://docs.octoprint.org/en/master/events/index.html#server

5

Can you enable DEBUG logging for octoprint.plugin, try the shutdown, upload the logs (if needed)?

You should see something like this from a built-in plugin:
2020-04-19 16:41:40,944 - octoprint.plugin - DEBUG - Calling on_shutdown on tracking

6

It is using the event mixin as well and it's not firing off the shutdown message unless you choose the restart on the web interface. If you choose the service handler for OctoPrint, it's not firing off.

7

I'll give this a try. But I'm pretty sure it's not firing this off if the service is being SIGTERM'd outside of the web interface.

8

Alright, I turned on DEBUG logging for octoprint.server and octoprint.events, restarting OP from the system menu option:

As seen from the system menu version:

2020-04-20 09:39:26,776 - octoprint.server.api.system - INFO - Performing command for core:restart: sudo service octoprint restart
2020-04-20 09:39:26,981 - octoprint.server - DEBUG - SIGTERM received...
2020-04-20 09:39:26,983 - octoprint.server - DEBUG - Shutting down tornado's IOLoop...
2020-04-20 09:39:26,984 - octoprint.server - DEBUG - Tornado's IOLoop stopped
2020-04-20 09:39:26,985 - octoprint.server - INFO - Shutting down...
2020-04-20 09:39:27,349 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2020-04-20 09:39:27,350 - octoprint.events.fire - DEBUG - Firing event: Shutdown (Payload: None)
2020-04-20 09:39:27,350 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x6af4c9f0>>
2020-04-20 09:39:27,355 - octoprint.events - INFO - Event loop shut down
2020-04-20 09:39:27,366 - octoprint.server - INFO - Goodbye!

As seen from the service handler:

# This is my promiscuously-logging on_event() handler to log all events seen
2020-04-20 09:39:48,711 - octoprint.plugins.xbox - INFO - on_event FirmwareData
...
# I then sudo service octoprint stop from the command line:
2020-04-20 09:40:21,082 - octoprint.server - DEBUG - SIGTERM received...
2020-04-20 09:40:21,083 - octoprint.server - DEBUG - Shutting down tornado's IOLoop...
2020-04-20 09:40:21,084 - octoprint.server - DEBUG - Tornado's IOLoop stopped
9

I've modified the OctoPrint code on my printer.

octoprint/server/__init__.py:

                def sigterm_handler(*args, **kwargs):
                        # will stop tornado on SIGTERM, making the program exit cleanly
                        def shutdown_tornado():
                                self._logger.debug("Shutting down tornado's IOLoop...")
                                ioloop.stop()
                        self._logger.debug("SIGTERM received...")
                        ioloop.add_callback_from_signal(shutdown_tornado)
                        on_shutdown() # Added
                        self._logger.debug("past on_shutdown() call") # Added
                signal.signal(signal.SIGTERM, sigterm_handler)

sudo service octoprint stop:

2020-04-20 17:49:46,076 - octoprint.server - DEBUG - SIGTERM received...
2020-04-20 17:49:46,076 - octoprint.server - INFO - Shutting down...
2020-04-20 17:49:46,442 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2020-04-20 17:49:46,443 - octoprint.events.fire - DEBUG - Firing event: Shutdown (Payload: None)
2020-04-20 17:49:46,443 - octoprint.events - DEBUG - Sending action to <bound method PrinterStateConnection._onEvent of <octoprint.server.util.sockjs.PrinterStateConnection object at 0x69c757b0>>
2020-04-20 17:49:46,446 - octoprint.plugins.xbox - INFO - on_event Shutdown
2020-04-20 17:49:46,449 - octoprint.events - INFO - Event loop shut down
2020-04-20 17:49:46,457 - octoprint.server - INFO - Goodbye!
2020-04-20 17:49:46,458 - octoprint.server - DEBUG - past on_shutdown() call
2020-04-20 17:49:46,467 - octoprint.server - DEBUG - Shutting down tornado's IOLoop...
2020-04-20 17:49:46,469 - octoprint.server - DEBUG - Tornado's IOLoop stopped
2020-04-20 17:49:52,521 - octoprint.plugins.tracking - INFO - Sent tracking event shutdown, payload: {}

I'm not sure if this is the perfect location for it since the ordering appears to be a little off but I note:

  • My xbox plugin is now seeing the fired Shutdown event
  • The event loop is shut down after this
  • It looks like tornado is now being shutdown where it wasn't before
  • It looks like the tracking plugin is also doing some housekeeping which it wasn't before
10

My hybrid solution is to patch OctoPrint in place (adding the call to on_shutdown() to the sigterm_handler() function) as well as to edit my own code:

  • Added a script which does a pkill xbox, basically
  • Added an /etc/sudoers.d file for this script
  • Added the following to my code:
    def on_event(self, event, payload):
        if event == 'Shutdown':
            self.shutdown_handler()
            return

    def shutdown_handler(self):
        self._logger.info('Shutdown received...')
        self.bStop =                        True
        subprocess.run(["sudo", "/home/pi/scripts/killxbox"])

So I now receive the event as expected from an external SIGTERM and I'm able to properly terminate a subprocess Popen'd with sudo since the xbox receiver needed that to run.

11

Looks like maybe an issue and apparently a PR is in order...

12

So the shutdown events/hooks are done here. I can't seem to make the problem happen but am also having an issue with the debugger at that point in the process. Perhaps there is a race condition that is occurring but am not sure yet.

Could you provide environment info and versions?

13

Alright, I can do the PR but I think it would be good to establish where in the ordering this could/should happen.

I inserted the call to on_shutdown() at the top of this function in the server part before the tornado shutdown definition.

14

Basically, I think that my earlier post was the smoking gun: externally SIGTERM'ing the octoprint service doesn't reach the on_shutdown() code so it doesn't fire the related event. Exercising the web interface instead starts with on_shutdown() so everything fires as expected.

OctoPrint v1.4.0, OctoPi 0.17.0, Raspberry Pi 3B

15

Right but I can't reproduce it when sending SIGTERM. Seems to work either way on my end.

16

Weird. I've tried it in Safe Mode so it's not my plugins which are doing anything. Not sure how to explain it.

17

@OutsourcedGuru open up a bug report. Can work on this from there. :smiley:

18

Here you go. Thanks.