Plugin reload mechanism (inventree#5649)

* Plugin reload mechanism

- Wrap reload_plugins with mutex lock
- Add methods for calculating plugin registry hash

* Perform plugin reload at critical entry points to the registry

- Background worker will correctly reload registry before performing tasks
- Ensures that the background worker plugin regsistry is up  to date

InvenTree/InvenTree/config.py

@@ -319,7 +319,7 @@ def get_secret_key():
         key = ''.join([random.choice(options) for i in range(100)])
         secret_key_file.write_text(key)
 
-    logger.info("Loading SECRET_KEY from '%s'", secret_key_file)
+    logger.debug("Loading SECRET_KEY from '%s'", secret_key_file)
 
     key_data = secret_key_file.read_text().strip()
 

InvenTree/plugin/apps.py

@@ -42,9 +42,8 @@ def ready(self):
                 except Exception:  # pragma: no cover
                     pass
 
-                # get plugins and init them
-                registry.plugin_modules = registry.collect_plugins()
-                registry.load_plugins()
+                # Perform a full reload of the plugin registry
+                registry.reload_plugins(full_reload=True, force_reload=True, collect=True)
 
                 # drop out of maintenance
                 # makes sure we did not have an error in reloading and maintenance is still active

InvenTree/plugin/base/integration/ScheduleMixin.py

@@ -57,7 +57,7 @@ def __init__(self):
     @classmethod
     def _activate_mixin(cls, registry, plugins, *args, **kwargs):
         """Activate scheudles from plugins with the ScheduleMixin."""
-        logger.info('Activating plugin tasks')
+        logger.debug('Activating plugin tasks')
 
         from common.models import InvenTreeSetting
 

InvenTree/plugin/base/integration/SettingsMixin.py

@@ -37,7 +37,7 @@ def _activate_mixin(cls, registry, plugins, *args, **kwargs):
         Add all defined settings form the plugins to a unified dict in the registry.
         This dict is referenced by the PluginSettings for settings definitions.
         """
-        logger.info('Activating plugin settings')
+        logger.debug('Activating plugin settings')
 
         registry.mixins_settings = {}
 
@@ -49,7 +49,7 @@ def _activate_mixin(cls, registry, plugins, *args, **kwargs):
     @classmethod
     def _deactivate_mixin(cls, registry, **kwargs):
         """Deactivate all plugin settings."""
-        logger.info('Deactivating plugin settings')
+        logger.debug('Deactivating plugin settings')
         # clear settings cache
         registry.mixins_settings = {}
 

InvenTree/plugin/registry.py

@@ -10,6 +10,7 @@
 import os
 import time
 from pathlib import Path
+from threading import Lock
 from typing import Any, Dict, List, OrderedDict
 
 from django.apps import apps
@@ -58,15 +59,25 @@ def __init__(self) -> None:
 
         self.errors = {}                                        # Holds discovering errors
 
+        self.loading_lock = Lock()                              # Lock to prevent multiple loading at the same time
+
         # flags
-        self.is_loading = False                                 # Are plugins being loaded right now
         self.plugins_loaded = False                             # Marks if the registry fully loaded and all django apps are reloaded
         self.apps_loading = True                                # Marks if apps were reloaded yet
 
         self.installed_apps = []                                # Holds all added plugin_paths
 
+    @property
+    def is_loading(self):
+        """Return True if the plugin registry is currently loading"""
+        return self.loading_lock.locked()
+
     def get_plugin(self, slug):
         """Lookup plugin by slug (unique key)."""
+
+        # Check if the registry needs to be reloaded
+        self.check_reload()
+
         if slug not in self.plugins:
             logger.warning("Plugin registry has no record of plugin '%s'", slug)
             return None
@@ -80,6 +91,10 @@ def set_plugin_state(self, slug, state):
             slug (str): Plugin slug
             state (bool): Plugin state - true = active, false = inactive
         """
+
+        # Check if the registry needs to be reloaded
+        self.check_reload()
+
         if slug not in self.plugins_full:
             logger.warning("Plugin registry has no record of plugin '%s'", slug)
             return
@@ -96,6 +111,10 @@ def call_plugin_function(self, slug, func, *args, **kwargs):
 
         Instead, any error messages are returned to the worker.
         """
+
+        # Check if the registry needs to be reloaded
+        self.check_reload()
+
         plugin = self.get_plugin(slug)
 
         if not plugin:
@@ -105,9 +124,35 @@ def call_plugin_function(self, slug, func, *args, **kwargs):
 
         return plugin_func(*args, **kwargs)
 
-    # region public functions
+    # region registry functions
+    def with_mixin(self, mixin: str, active=None, builtin=None):
+        """Returns reference to all plugins that have a specified mixin enabled."""
+
+        # Check if the registry needs to be loaded
+        self.check_reload()
+
+        result = []
+
+        for plugin in self.plugins.values():
+            if plugin.mixin_enabled(mixin):
+
+                if active is not None:
+                    # Filter by 'active' status of plugin
+                    if active != plugin.is_active():
+                        continue
+
+                if builtin is not None:
+                    # Filter by 'builtin' status of plugin
+                    if builtin != plugin.is_builtin:
+                        continue
+
+                result.append(plugin)
+
+        return result
+    # endregion
+
     # region loading / unloading
-    def load_plugins(self, full_reload: bool = False):
+    def _load_plugins(self, full_reload: bool = False):
         """Load and activate all IntegrationPlugins.
 
         Args:
@@ -175,7 +220,7 @@ def load_plugins(self, full_reload: bool = False):
             from plugin.events import trigger_event
             trigger_event('plugins_loaded')
 
-    def unload_plugins(self, force_reload: bool = False):
+    def _unload_plugins(self, force_reload: bool = False):
         """Unload and deactivate all IntegrationPlugins.
 
         Args:
@@ -202,7 +247,9 @@ def unload_plugins(self, force_reload: bool = False):
         logger.info('Finished unloading plugins')
 
     def reload_plugins(self, full_reload: bool = False, force_reload: bool = False, collect: bool = False):
-        """Safely reload.
+        """Reload the plugin registry.
+
+        This should be considered the single point of entry for loading plugins!
 
         Args:
             full_reload (bool, optional): Reload everything - including plugin mechanism. Defaults to False.
@@ -211,21 +258,25 @@ def reload_plugins(self, full_reload: bool = False, force_reload: bool = False,
         """
         # Do not reload when currently loading
         if self.is_loading:
-            return  # pragma: no cover
+            logger.debug("Skipping reload - plugin registry is currently loading")
+            return
+
+        if self.loading_lock.acquire(blocking=False):
 
-        logger.info('Start reloading plugins')
+            logger.info('Plugin Registry: Reloading plugins')
 
-        with maintenance_mode_on():
-            if collect:
-                logger.info('Collecting plugins')
-                self.plugin_modules = self.collect_plugins()
+            with maintenance_mode_on():
+                if collect:
+                    logger.info('Collecting plugins')
+                    self.plugin_modules = self.collect_plugins()
 
-            self.plugins_loaded = False
-            self.unload_plugins(force_reload=force_reload)
-            self.plugins_loaded = True
-            self.load_plugins(full_reload=full_reload)
+                self.plugins_loaded = False
+                self._unload_plugins(force_reload=force_reload)
+                self.plugins_loaded = True
+                self._load_plugins(full_reload=full_reload)
 
-        logger.info('Finished reloading plugins')
+            self.loading_lock.release()
+            logger.info('Plugin Registry: Loaded %s plugins', len(self.plugins))
 
     def plugin_dirs(self):
         """Construct a list of directories from where plugins can be loaded"""
@@ -360,30 +411,6 @@ def install_plugin_file(self):
 
     # endregion
 
-    # region registry functions
-    def with_mixin(self, mixin: str, active=None, builtin=None):
-        """Returns reference to all plugins that have a specified mixin enabled."""
-        result = []
-
-        for plugin in self.plugins.values():
-            if plugin.mixin_enabled(mixin):
-
-                if active is not None:
-                    # Filter by 'active' status of plugin
-                    if active != plugin.is_active():
-                        continue
-
-                if builtin is not None:
-                    # Filter by 'builtin' status of plugin
-                    if builtin != plugin.is_builtin:
-                        continue
-
-                result.append(plugin)
-
-        return result
-    # endregion
-    # endregion
-
     # region general internal loading /activating / deactivating / deloading
     def _init_plugins(self, disabled: str = None):
         """Initialise all found plugins.
@@ -540,7 +567,7 @@ def _try_reload(self, cmd, *args, **kwargs):
             cmd(*args, **kwargs)
             return True, []
         except Exception as error:  # pragma: no cover
-            handle_error(error)
+            handle_error(error, do_raise=False)
 
     def _reload_apps(self, force_reload: bool = False, full_reload: bool = False):
         """Internal: reload apps using django internal functions.
@@ -549,9 +576,7 @@ def _reload_apps(self, force_reload: bool = False, full_reload: bool = False):
             force_reload (bool, optional): Also reload base apps. Defaults to False.
             full_reload (bool, optional): Reload everything - including plugin mechanism. Defaults to False.
         """
-        # If full_reloading is set to true we do not want to set the flag
-        if not full_reload:
-            self.is_loading = True  # set flag to disable loop reloading
+
         if force_reload:
             # we can not use the built in functions as we need to brute force the registry
             apps.app_configs = OrderedDict()
@@ -560,7 +585,6 @@ def _reload_apps(self, force_reload: bool = False, full_reload: bool = False):
             self._try_reload(apps.populate, settings.INSTALLED_APPS)
         else:
             self._try_reload(apps.set_installed_apps, settings.INSTALLED_APPS)
-        self.is_loading = False
 
     def _clean_installed_apps(self):
         for plugin in self.installed_apps:
@@ -601,6 +625,68 @@ def _update_urls(self):
         clear_url_caches()
     # endregion
 
+    # region plugin registry hash calculations
+    def update_plugin_hash(self):
+        """When the state of the plugin registry changes, update the hash"""
+
+        from common.models import InvenTreeSetting
+
+        plg_hash = self.calculate_plugin_hash()
+
+        try:
+            old_hash = InvenTreeSetting.get_setting("_PLUGIN_REGISTRY_HASH", "", create=False, cache=False)
+        except Exception:
+            old_hash = ""
+
+        if old_hash != plg_hash:
+            try:
+                logger.debug("Updating plugin registry hash: %s", str(plg_hash))
+                InvenTreeSetting.set_setting("_PLUGIN_REGISTRY_HASH", plg_hash, change_user=None)
+            except Exception as exc:
+                logger.exception("Failed to update plugin registry hash: %s", str(exc))
+
+    def calculate_plugin_hash(self):
+        """Calculate a 'hash' value for the current registry
+
+        This is used to detect changes in the plugin registry,
+        and to inform other processes that the plugin registry has changed
+        """
+
+        from hashlib import md5
+
+        data = md5()
+
+        # Hash for all loaded plugins
+        for slug, plug in self.plugins.items():
+            data.update(str(slug).encode())
+            data.update(str(plug.version).encode())
+            data.update(str(plug.is_active).encode())
+
+        return str(data.hexdigest())
+
+    def check_reload(self):
+        """Determine if the registry needs to be reloaded"""
+
+        from common.models import InvenTreeSetting
+
+        if settings.TESTING:
+            # Skip if running during unit testing
+            return
+
+        logger.debug("Checking plugin registry hash")
+
+        try:
+            reg_hash = InvenTreeSetting.get_setting("_PLUGIN_REGISTRY_HASH", "", create=False, cache=False)
+        except Exception as exc:
+            logger.exception("Failed to retrieve plugin registry hash: %s", str(exc))
+            return
+
+        if reg_hash and reg_hash != self.calculate_plugin_hash():
+            logger.info("Plugin registry hash has changed - reloading")
+            self.reload_plugins(full_reload=True, force_reload=True, collect=True)
+
+    # endregion
+
 
 registry: PluginsRegistry = PluginsRegistry()