Exception on shutdown because of thread started in plugin

singultus · April 21, 2020, 8:49pm

Hi friends!
I'm developing my first plugin, it should communicate with my main python script on my RPi using queues and the Manager class from the multiprocessing library (https://docs.python.org/3/library/multiprocessing.html#using-a-remote-manager). This works as intended, however, octoprint crashes during shutdown:

Terminal after Ctrl+C for aborting (initally started with "octoprint serve"). The first Ctrl+C kind of deadlocks, the second shows the error:

^C^CException ignored in: <module 'threading' from '/usr/lib/python3.7/threading.py'>
Traceback (most recent call last):
  File "/usr/lib/python3.7/threading.py", line 1281, in _shutdown
    t.join()
  File "/usr/lib/python3.7/threading.py", line 1032, in join
    self._wait_for_tstate_lock()
  File "/usr/lib/python3.7/threading.py", line 1048, in _wait_for_tstate_lock
    elif lock.acquire(block, timeout):
KeyboardInterrupt
2020-04-21 22:13:02,444 - octoprint.server - INFO - Shutting down...

Simplified init.py
During start up a process with the manager class from multiprocessing is started. The subsequent loop usually waits for an update in the queue, however, the queue was removed for testing purposes.
I tried to solve the problem both with a "finally" statement in on_after_startup and in on_shutdown. But octoprint deadlocks with this _wait_for_tstate_lock before either is called.

#!/usr/bin/python3

import octoprint.plugin
from multiprocessing.managers import BaseManager
from multiprocessing import Process, Queue, active_children
from time import sleep

class NabuPlugin(octoprint.plugin.TemplatePlugin,
                 octoprint.plugin.AssetPlugin,
                 octoprint.plugin.SimpleApiPlugin,
                 octoprint.plugin.StartupPlugin,
                 octoprint.plugin.ShutdownPlugin):


    def _start_queue_server(self):
        class QueueManager(BaseManager): pass
        m = QueueManager(address=('', 33334), authkey=b'prusaprinter')
        s = m.get_server()
        s.serve_forever()


    def get_api_commands(self):
        return dict(
            nabu=[]
        )

    def on_after_startup(self):
        self._logger.info("Nabu started, start server!!!!!!!!!!!!!!!!!!!!!!!!!!!!")

        try:
            # start server for feedback
            proc = Process(target=self._start_queue_server)  
            proc.start()

            while True:
                sleep(10)
                self._logger.info("Loop")

        except:
            self._logger.info("unexpected exception!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!")

        finally:
            # close all processes (i. e. server process)
            for sub in active_children():
                self._logger.info("shutting down process !!!!!!!!!!!!!!!!!!!!!!!!!!!", sub)
                sub.terminate()
                sub.join()
            self._logger.info("all done !!!!!!!!!!!!!!!!!!!!!!!!!!!!")

    def on_shutdown(self):
        for sub in active_children():
            self._logger.info("Nabu shutting down process", sub)
            sub.terminate()
            sub.join()


__plugin_name__ = "NaBu - Navbar Button"
__plugin_pythoncompat__ = ">=3,<4"

def __plugin_load__():
    global __plugin_implementation__
    __plugin_implementation__ = NabuPlugin()

The octoprint log is silent:

2020-04-21 22:12:29,852 - octoprint.startup - INFO - ******************************************************************************
2020-04-21 22:12:29,854 - octoprint.startup - INFO - Starting OctoPrint 1.4.0
2020-04-21 22:12:29,855 - octoprint.startup - INFO - ******************************************************************************
2020-04-21 22:12:30,249 - octoprint.util.connectivity_checker - INFO - Connectivity changed from offline to online
2020-04-21 22:12:30,253 - octoprint.startup - INFO - Blacklist processing done, adding 1 blacklisted plugin versions: roomtemp (any)
2020-04-21 22:12:30,302 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-04-21 22:12:30,393 - octoprint.plugin.core - INFO - Plugin Discovery is disabled.
2020-04-21 22:12:30,985 - octoprint.plugin.core - INFO - Plugin Virtual Printer is disabled.
2020-04-21 22:12:31,023 - octoprint.plugin.core - INFO - Plugin Anonymous Usage Tracking is disabled.
2020-04-21 22:12:31,135 - octoprint.plugin.core - INFO - Plugin Error Tracking is disabled.
2020-04-21 22:12:31,414 - octoprint.plugin.core - INFO - Found 16 plugin(s) providing 12 mixin implementations, 26 hook handlers
2020-04-21 22:12:31,543 - octoprint.server.heartbeat - INFO - Starting server heartbeat, 900.0s interval
2020-04-21 22:12:31,551 - octoprint.server - INFO - Intermediary server started
2020-04-21 22:12:31,551 - octoprint.plugin.core - INFO - Loading plugins from /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins, /home/pi/.octoprint/plugins and installed plugin packages...
2020-04-21 22:12:31,610 - octoprint.plugin.core - INFO - Found 16 plugin(s) providing 12 mixin implementations, 26 hook handlers
2020-04-21 22:12:31,659 - octoprint.filemanager.storage - INFO - Initializing the file metadata for /home/pi/.octoprint/uploads...
2020-04-21 22:12:31,918 - octoprint.filemanager.storage - INFO - ... file metadata for /home/pi/.octoprint/uploads initialized successfully.
2020-04-21 22:12:31,922 - octoprint.server - INFO - Added new permission from plugin action_command_prompt: PLUGIN_ACTION_COMMAND_PROMPT_INTERACT (needs: "Need(method='role', value='plugin_action_command_prompt_interact')")
2020-04-21 22:12:31,923 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_READ (needs: "Need(method='role', value='plugin_announcements_read')")
2020-04-21 22:12:31,923 - octoprint.server - INFO - Added new permission from plugin announcements: PLUGIN_ANNOUNCEMENTS_MANAGE (needs: "Need(method='role', value='plugin_announcements_read'), Need(method='role', value='plugin_announcements_manage')")
2020-04-21 22:12:31,924 - octoprint.server - INFO - Added new permission from plugin appkeys: PLUGIN_APPKEYS_ADMIN (needs: "Need(method='role', value='plugin_appkeys_admin')")
2020-04-21 22:12:31,924 - octoprint.server - INFO - Added new permission from plugin backup: PLUGIN_BACKUP_ACCESS (needs: "Need(method='role', value='plugin_backup_access')")
2020-04-21 22:12:31,925 - octoprint.server - INFO - Added new permission from plugin logging: PLUGIN_LOGGING_MANAGE (needs: "Need(method='role', value='plugin_logging_manage')")
2020-04-21 22:12:31,925 - octoprint.server - INFO - Added new permission from plugin pi_support: PLUGIN_PI_SUPPORT_STATUS (needs: "Need(method='role', value='plugin_pi_support_check')")
2020-04-21 22:12:31,925 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_MANAGE (needs: "Need(method='role', value='plugin_pluginmanager_manage')")
2020-04-21 22:12:31,926 - octoprint.server - INFO - Added new permission from plugin pluginmanager: PLUGIN_PLUGINMANAGER_INSTALL (needs: "Need(method='role', value='plugin_pluginmanager_install'), Need(method='role', value='plugin_pluginmanager_manage')")
2020-04-21 22:12:31,926 - octoprint.server - INFO - Added new permission from plugin printer_safety_check: PLUGIN_PRINTER_SAFETY_CHECK_DISPLAY (needs: "Need(method='role', value='plugin_printer_safety_check_display')")
2020-04-21 22:12:31,927 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_CHECK (needs: "Need(method='role', value='plugin_softwareupdate_check')")
2020-04-21 22:12:31,927 - octoprint.server - INFO - Added new permission from plugin softwareupdate: PLUGIN_SOFTWAREUPDATE_UPDATE (needs: "Need(method='role', value='plugin_softwareupdate_update')")
2020-04-21 22:12:32,833 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python3 -m pip" as command to invoke pip
2020-04-21 22:12:33,720 - octoprint.util.pip - INFO - Version of pip is 20.0.2
2020-04-21 22:12:33,722 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-04-21 22:12:33,723 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-04-21 22:12:33,753 - octoprint.plugins.softwareupdate - INFO - Loaded version cache from disk
2020-04-21 22:12:33,760 - octoprint.plugin.core - INFO - Initialized 12 plugin implementation(s)
2020-04-21 22:12:33,766 - octoprint.plugin.core - INFO - 16 plugin(s) registered with the system:
|  Action Command Prompt Support (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/action_command_prompt
|  Announcement Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/announcements
| !Anonymous Usage Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/tracking
|  Application Keys Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/appkeys
|  Backup & Restore (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/backup
|  Core Wizard (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/corewizard
| !Discovery (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/discovery
| !Error Tracking (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/errortracking
|  Logging (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/logging
|  Login UI (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/loginui
|  NaBu - Navbar Button (1.0.0) = /home/pi/OctoPrint-nabu/octoprint_nabu
|  Pi Support Plugin (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pi_support
|  Plugin Manager (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/pluginmanager
|  Printer Safety Check (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/printer_safety_check
|  Software Update (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/softwareupdate
| !Virtual Printer (bundled) = /home/pi/oprint/lib/python3.7/site-packages/octoprint/plugins/virtual_printer
Prefix legend: ! = disabled, # = blacklisted, * = incompatible
2020-04-21 22:12:33,779 - octoprint.environment - INFO - Detected environment is Python 3.7.3 under Linux (linux). Details:
|  hardware:
|      cores: 4
|      freq: 1400.0
|      ram: 917008384
|  os:
|      id: linux
|      platform: linux
|  plugins:
|      pi_support:
|          model: Raspberry Pi 3 Model B Plus Rev 1.3
|          octopi_version: 0.17.0
|  python:
|      pip: 20.0.2
|      version: 3.7.3
|      virtualenv: /home/pi/oprint
2020-04-21 22:12:33,787 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/webassets...
2020-04-21 22:12:33,790 - octoprint.server - INFO - Reset webasset folder /home/pi/.octoprint/generated/.webassets-cache...
2020-04-21 22:12:34,326 - octoprint.server - INFO - Shutting down intermediary server...
2020-04-21 22:12:34,468 - octoprint.server - INFO - Intermediary server shut down
2020-04-21 22:12:34,471 - octoprint.events - INFO - Processing startup event, this is our first event
2020-04-21 22:12:34,471 - octoprint.events - INFO - Adding 1 events to queue that were held back before startup event
2020-04-21 22:12:34,472 - octoprint.filemanager - INFO - Adding backlog items from all storage types to analysis queue...
2020-04-21 22:12:34,474 - octoprint.server - INFO - Autoconnect on startup is configured, trying to connect to the printer...
2020-04-21 22:12:34,481 - octoprint.filemanager - INFO - Added 0 items from storage type "local" to analysis queue
2020-04-21 22:12:34,522 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-04-21 22:12:35,594 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2020-04-21 22:12:35,611 - octoprint.server - INFO - Trying to connect to configured serial port None
2020-04-21 22:12:35,668 - octoprint.util.comm - INFO - Changing monitoring state from "Offline" to "Detecting serial port"
2020-04-21 22:12:35,673 - octoprint.server.util.watchdog - INFO - Running initial scan on watched folder...
2020-04-21 22:12:35,676 - octoprint.server.util.watchdog - INFO - ... initial scan done.
2020-04-21 22:12:35,707 - octoprint.server - INFO - Listening on http://0.0.0.0:5000 and http://[::]:5000
2020-04-21 22:12:35,758 - octoprint.plugins.pluginmanager - INFO - Loaded plugin repository data from disk, was still valid
2020-04-21 22:12:36,817 - octoprint.util.pip - INFO - Using "/home/pi/oprint/bin/python3 -m pip" as command to invoke pip
2020-04-21 22:12:36,824 - octoprint.util.pip - INFO - pip installs to /home/pi/oprint/lib/python3.7/site-packages (writable -> yes), --user flag needed -> no, virtual env -> yes
2020-04-21 22:12:36,824 - octoprint.util.pip - INFO - ==> pip ok -> yes
2020-04-21 22:12:36,892 - octoprint.plugins.nabu - INFO - Nabu started, start server!!!!!!!!!!!!!!!!!!!!!!!!!!!!
2020-04-21 22:12:37,059 - octoprint.plugins.pluginmanager - INFO - Loaded notice data from disk, was still valid
2020-04-21 22:12:37,101 - octoprint.server.util.sockjs - INFO - New connection from client: ::ffff:192.168.178.20
2020-04-21 22:12:37,170 - octoprint.server.util.flask - INFO - Passively logging in user _admin from ::ffff:192.168.178.20
2020-04-21 22:12:37,171 - octoprint.access.users - INFO - Logged in user: _admin
2020-04-21 22:12:38,050 - octoprint.server.util.sockjs - INFO - User _admin logged in on the socket from client ::ffff:192.168.178.20
2020-04-21 22:12:41,038 - octoprint.util.comm - INFO - Could not enter programming mode on /dev/ttyACM0: 'Timeout'
2020-04-21 22:12:41,046 - octoprint.util.comm - INFO - Could not enter programming mode on /dev/ttyS0: 'Failed to open serial port'
2020-04-21 22:12:41,049 - octoprint.util.comm - INFO - Changing monitoring state from "Detecting serial port" to "Error: Failed to autodetect serial port, please set it manually."
2020-04-21 22:12:46,957 - octoprint.plugins.nabu - INFO - Loop
2020-04-21 22:12:56,968 - octoprint.plugins.nabu - INFO - Loop
2020-04-21 22:13:02,444 - octoprint.server - INFO - Shutting down...
2020-04-21 22:13:02,697 - octoprint.events - INFO - Processing shutdown event, this will be our last event
2020-04-21 22:13:02,701 - octoprint.events - INFO - Event loop shut down
2020-04-21 22:13:02,703 - octoprint.server - INFO - Goodbye!

Any help would be appreciated, this is my first python project ever . The solution is probably very simple.

foosel · April 21, 2020, 8:54pm

That's not a crash, that's simply a (handled) exception being logged.

singultus · April 21, 2020, 9:04pm

True that, my bad. However, what's the problem? I have a nearly identical python script running on the other side of the intended communication. There this deadlock doesn't happen, Ctrl+C ends the script without further ado.... Any ideas?

OutsourcedGuru · April 21, 2020, 9:26pm

Sounds a bit like this. In my case, I'm doing a sudo service octoprint stop which is essentially throwing the same SIGTERM to OctoPrint.

In my case, I needed to hear the Shutdown event so that I could more gracefully shutdown some things that I'd started up. I asserted that OctoPrint's SIGTERM handler wasn't calling its own on_shutdown() function which kicks off the event propagation.

In your case, you'd want to hear that Shutdown event and inside your code you'd want to test for something like boolStop or similar.

singultus · April 22, 2020, 10:05am

Yes, that's exactly my problem as well. I'll keep my eye on your issue