From 682d66e08fbc9d6949a8eb1fc187f2923ccf24f6 Mon Sep 17 00:00:00 2001 From: Storm Dragon Date: Thu, 3 Apr 2025 22:10:48 -0400 Subject: [PATCH] Fix to stop the screen reader from hanging when plugins fail. --- src/cthulhu/cthulhuVersion.py | 2 +- src/cthulhu/plugin_system_manager.py | 143 ++++++++++++++++++--------- 2 files changed, 99 insertions(+), 46 deletions(-) diff --git a/src/cthulhu/cthulhuVersion.py b/src/cthulhu/cthulhuVersion.py index ff8827e..991b00b 100644 --- a/src/cthulhu/cthulhuVersion.py +++ b/src/cthulhu/cthulhuVersion.py @@ -24,4 +24,4 @@ # Original source: https://gitlab.gnome.org/GNOME/orca version = "2025.04.03" -codeName = "testing" +codeName = "plugins" diff --git a/src/cthulhu/plugin_system_manager.py b/src/cthulhu/plugin_system_manager.py index a02c06b..5224d8d 100644 --- a/src/cthulhu/plugin_system_manager.py +++ b/src/cthulhu/plugin_system_manager.py @@ -12,6 +12,8 @@ import os import inspect import importlib.util import logging +import threading +import time from enum import IntEnum # Import pluggy if available @@ -151,6 +153,8 @@ class PluginSystemManager: self._plugins[name].loaded = True self._plugins[name].instance = old_info.instance self._plugins[name].module = old_info.module + + logger.info(f"Rescanned plugins, found {len(self._plugins)} plugins") def _scan_plugins_in_directory(self, directory): """Scan for plugins in a directory.""" @@ -159,44 +163,49 @@ class PluginSystemManager: return logger.info(f"Scanning for plugins in directory: {directory}") - for item in os.listdir(directory): - plugin_dir = os.path.join(directory, item) - if not os.path.isdir(plugin_dir): - continue + try: + for item in os.listdir(directory): + plugin_dir = os.path.join(directory, item) + if not os.path.isdir(plugin_dir): + continue - # Check for the traditional structure first (plugin.py & plugin.info) - plugin_file = os.path.join(plugin_dir, "plugin.py") - metadata_file = os.path.join(plugin_dir, "plugin.info") + # Check for the traditional structure first (plugin.py & plugin.info) + plugin_file = os.path.join(plugin_dir, "plugin.py") + metadata_file = os.path.join(plugin_dir, "plugin.info") - # Fall back to [PluginName].py if plugin.py doesn't exist - if not os.path.isfile(plugin_file): - alternative_plugin_file = os.path.join(plugin_dir, f"{item}.py") - if os.path.isfile(alternative_plugin_file): - plugin_file = alternative_plugin_file - logger.info(f"Using alternative plugin file: {alternative_plugin_file}") + # Fall back to [PluginName].py if plugin.py doesn't exist + if not os.path.isfile(plugin_file): + alternative_plugin_file = os.path.join(plugin_dir, f"{item}.py") + if os.path.isfile(alternative_plugin_file): + plugin_file = alternative_plugin_file + logger.info(f"Using alternative plugin file: {alternative_plugin_file}") - # Check if we have any valid plugin file - if os.path.isfile(plugin_file): - # Extract plugin info - module_name = os.path.basename(plugin_dir) - logger.info(f"Found plugin: {module_name} in {plugin_dir}") - metadata = self._load_plugin_metadata(metadata_file) + # Check if we have any valid plugin file + if os.path.isfile(plugin_file): + # Extract plugin info + module_name = os.path.basename(plugin_dir) + logger.info(f"Found plugin: {module_name} in {plugin_dir}") + metadata = self._load_plugin_metadata(metadata_file) - plugin_info = PluginInfo( - metadata.get('name', module_name), - module_name, - plugin_dir, - metadata - ) + plugin_info = PluginInfo( + metadata.get('name', module_name), + module_name, + plugin_dir, + metadata + ) - # Check if it's a built-in or hidden plugin - plugin_info.builtin = metadata.get('builtin', 'false').lower() == 'true' - plugin_info.hidden = metadata.get('hidden', 'false').lower() == 'true' + # Check if it's a built-in or hidden plugin + plugin_info.builtin = metadata.get('builtin', 'false').lower() == 'true' + plugin_info.hidden = metadata.get('hidden', 'false').lower() == 'true' - logger.info(f"Adding plugin to registry: {module_name}") - self._plugins[module_name] = plugin_info - else: - logger.warning(f"No plugin file found in directory: {plugin_dir}") + logger.info(f"Adding plugin to registry: {module_name}") + self._plugins[module_name] = plugin_info + else: + logger.warning(f"No plugin file found in directory: {plugin_dir}") + except Exception as e: + logger.error(f"Error scanning directory {directory}: {e}") + import traceback + logger.error(traceback.format_exc()) def _load_plugin_metadata(self, metadata_file): """Load plugin metadata from a file.""" @@ -231,6 +240,10 @@ class PluginSystemManager: logger.info("No plugins found, rescanning...") self.rescanPlugins() + # Double-check we found plugins after rescanning + if not self._plugins and activePlugins: + logger.warning("No plugins found after rescanning but active plugins requested. Continuing anyway.") + self._active_plugins = activePlugins # Log active vs available plugins @@ -242,8 +255,13 @@ class PluginSystemManager: missing_plugins = [p for p in self._active_plugins if p not in available_plugins] if missing_plugins: logger.warning(f"Active plugins not found: {missing_plugins}") - - self.syncAllPluginsActive() + + try: + self.syncAllPluginsActive() + except Exception as e: + logger.error(f"Error syncing plugins: {e}") + import traceback + logger.error(traceback.format_exc()) def setPluginActive(self, pluginInfo, active): """Set the active state of a plugin.""" @@ -302,6 +320,11 @@ class PluginSystemManager: if not PLUGGY_AVAILABLE: logger.warning("Pluggy not available, skipping plugin sync") return + + # Skip if no plugins found - don't waste time trying to sync nothing + if not self._plugins: + logger.warning("No plugins found, skipping plugin sync") + return # Log plugin status before syncing if PLUGIN_DEBUG: @@ -311,18 +334,20 @@ class PluginSystemManager: logger.debug(f"Plugin {pluginInfo.get_module_name()}: active={is_active}, loaded={is_loaded}") try: + # Create plans first, then execute to avoid changing collection during iteration + to_unload = [p for p in self.plugins if not self.isPluginActive(p) and p.loaded] + to_load = [p for p in self.plugins if self.isPluginActive(p) and not p.loaded] + # First unload inactive plugins - for pluginInfo in self.plugins: - if not self.isPluginActive(pluginInfo) and pluginInfo.loaded: - logger.info(f"Unloading inactive plugin: {pluginInfo.get_module_name()}") - self.unloadPlugin(pluginInfo) + for pluginInfo in to_unload: + logger.info(f"Unloading inactive plugin: {pluginInfo.get_module_name()}") + self.unloadPlugin(pluginInfo) # Then load active plugins - for pluginInfo in self.plugins: - if self.isPluginActive(pluginInfo) and not pluginInfo.loaded: - logger.info(f"Loading active plugin: {pluginInfo.get_module_name()}") - result = self.loadPlugin(pluginInfo) - logger.info(f"Plugin {pluginInfo.get_module_name()} load result: {result}") + for pluginInfo in to_load: + logger.info(f"Loading active plugin: {pluginInfo.get_module_name()}") + result = self.loadPlugin(pluginInfo) + logger.info(f"Plugin {pluginInfo.get_module_name()} load result: {result}") # Log final plugin status active_plugins = [p.get_module_name() for p in self.plugins if p.loaded] @@ -342,12 +367,25 @@ class PluginSystemManager: return False module_name = pluginInfo.get_module_name() - logger.info(f"Attempting to load plugin: {module_name}") + logger.debug(f"===== PLUGIN LOADING START: {module_name} =====") + + # Setup timeout for plugin loading + load_timeout = 5 # seconds + load_completed = False + + def timeout_handler(): + nonlocal load_completed + if not load_completed: + logger.error(f"Plugin loading timed out for {module_name}") + + timer = threading.Timer(load_timeout, timeout_handler) + timer.start() try: # Already loaded? if pluginInfo.loaded: logger.info(f"Plugin {module_name} already loaded, skipping") + load_completed = True return True # Try to find the plugin file @@ -366,12 +404,14 @@ class PluginSystemManager: if not os.path.exists(plugin_file): logger.error(f"Plugin file not found: {plugin_file}") + load_completed = True return False logger.info(f"Loading plugin from: {plugin_file}") spec = importlib.util.spec_from_file_location(module_name, plugin_file) if spec is None: logger.error(f"Failed to create spec for plugin: {module_name}") + load_completed = True return False module = importlib.util.module_from_spec(spec) @@ -391,6 +431,7 @@ class PluginSystemManager: if not plugin_class: logger.error(f"No plugin class found in {module_name}") + load_completed = True return False # Create and initialize plugin instance @@ -410,9 +451,15 @@ class PluginSystemManager: plugin_instance.set_plugin_info(pluginInfo) logger.info(f"Called set_plugin_info() for plugin: {module_name}") + # Log plugin methods for debugging + if PLUGIN_DEBUG: + logger.debug(f"Plugin instance methods: {[m for m in dir(plugin_instance) if not m.startswith('_')]}") + logger.debug(f"Checking for activate method: {'activate' in dir(plugin_instance)}") + # Register with pluggy and activate if self.plugin_manager is None: logger.error(f"Plugin manager is None when loading {module_name}") + load_completed = True return False logger.info(f"Registering plugin with pluggy: {module_name}") @@ -425,17 +472,23 @@ class PluginSystemManager: logger.error(f"Error activating plugin {module_name}: {e}") import traceback logger.error(traceback.format_exc()) + load_completed = True return False pluginInfo.loaded = True - logger.info(f"Successfully loaded plugin: {module_name}") + logger.debug(f"===== PLUGIN LOADING SUCCESS: {module_name} =====") + load_completed = True return True except Exception as e: logger.error(f"Failed to load plugin {module_name}: {e}") import traceback logger.error(traceback.format_exc()) + logger.debug(f"===== PLUGIN LOADING FAILED: {module_name} =====") + load_completed = True return False + finally: + timer.cancel() def unloadPlugin(self, pluginInfo): """Unload a plugin."""