From cd76760d9f6272a4b33de1201f787420a34dce02 Mon Sep 17 00:00:00 2001 From: Storm Dragon Date: Fri, 4 Apr 2025 02:15:26 -0400 Subject: [PATCH] Try to get around plugins causing the screen reader to hang in infinite loop. --- src/cthulhu/cthulhu.py | 35 ++- src/cthulhu/cthulhuVersion.py | 2 +- src/cthulhu/plugin_system_manager.py | 396 ++++++++++++++++++++++----- 3 files changed, 354 insertions(+), 79 deletions(-) diff --git a/src/cthulhu/cthulhu.py b/src/cthulhu/cthulhu.py index fcf628b..db19e07 100644 --- a/src/cthulhu/cthulhu.py +++ b/src/cthulhu/cthulhu.py @@ -610,8 +610,39 @@ def loadUserSettings(script=None, inputEvent=None, skipReloadMessage=False): _storeXmodmap(_cthulhuModifiers) _createCthulhuXmodmap() - activePlugins = list(_settingsManager.getSetting('activePlugins')) - cthulhuApp.getPluginSystemManager().setActivePlugins(activePlugins) + # Make plugin loading more robust by handling potential exceptions + try: + activePlugins = list(_settingsManager.getSetting('activePlugins')) + logger.info(f"CTHULHU: Loading active plugins: {activePlugins}") + + # Setup a timeout for plugin activation to prevent hanging + import threading + import time + + activation_completed = [False] + + def activate_plugins_with_timeout(): + try: + cthulhuApp.getPluginSystemManager().setActivePlugins(activePlugins) + activation_completed[0] = True + except Exception as e: + logger.error(f"CTHULHU: Error activating plugins: {e}") + import traceback + logger.error(traceback.format_exc()) + + plugin_thread = threading.Thread(target=activate_plugins_with_timeout) + plugin_thread.daemon = True # Make thread daemonic so it doesn't block program exit + plugin_thread.start() + + # Give plugins up to 30 seconds to load, then continue regardless + plugin_thread.join(30) + + if not activation_completed[0]: + logger.error("CTHULHU: Plugin activation timed out - continuing without all plugins") + except Exception as e: + logger.error(f"CTHULHU: Error setting up plugin activation: {e}") + import traceback + logger.error(traceback.format_exc()) _scriptManager.activate() _eventManager.activate() diff --git a/src/cthulhu/cthulhuVersion.py b/src/cthulhu/cthulhuVersion.py index 991b00b..1eeff06 100644 --- a/src/cthulhu/cthulhuVersion.py +++ b/src/cthulhu/cthulhuVersion.py @@ -23,5 +23,5 @@ # Fork of Orca Screen Reader (GNOME) # Original source: https://gitlab.gnome.org/GNOME/orca -version = "2025.04.03" +version = "2025.04.04" codeName = "plugins" diff --git a/src/cthulhu/plugin_system_manager.py b/src/cthulhu/plugin_system_manager.py index 6eb9dbd..c109671 100644 --- a/src/cthulhu/plugin_system_manager.py +++ b/src/cthulhu/plugin_system_manager.py @@ -232,49 +232,122 @@ class PluginSystemManager: return self._active_plugins def setActivePlugins(self, activePlugins): - """Set active plugins and sync their state.""" + """Set active plugins and sync their state with robust error handling.""" logger.info(f"Setting active plugins: {activePlugins}") - # Make sure we have scanned for plugins first + # Set a timeout for the entire operation + operation_timeout = 60 # seconds + start_time = time.time() + + # Make sure we have scanned for plugins first, with timeout if not self._plugins: logger.info("No plugins found, rescanning...") - self.rescanPlugins() + try: + # Use a separate thread with timeout for rescanning + rescan_success = [False] + + def rescan_with_timeout(): + try: + self.rescanPlugins() + rescan_success[0] = True + except Exception as e: + logger.error(f"Error in plugin rescan thread: {e}") + import traceback + logger.error(traceback.format_exc()) + + rescan_thread = threading.Thread(target=rescan_with_timeout) + rescan_thread.daemon = True + rescan_thread.start() + rescan_thread.join(10) # 10 second timeout for rescanning + + if not rescan_success[0]: + logger.error("Plugin rescan timed out or failed, continuing with whatever plugins were found") + except Exception as e: + logger.error(f"Error setting up plugin rescan: {e}") + import traceback + logger.error(traceback.format_exc()) + + # Check if the operation has already timed out + if time.time() - start_time > operation_timeout: + logger.error("Plugin activation operation timed out during rescan, continuing with empty plugin list") + self._active_plugins = [] + return # Create a clean list of valid active plugins - available_plugins = [p.get_module_name() for p in self.plugins] - valid_active_plugins = [] - - for plugin_name in activePlugins: - # Check for exact match first - if plugin_name in available_plugins: - valid_active_plugins.append(plugin_name) - continue - - # Try case-insensitive match - plugin_name_lower = plugin_name.lower() - matched = False - for available in available_plugins: - if available.lower() == plugin_name_lower: - # Use the correctly cased name from available plugins - valid_active_plugins.append(available) - matched = True - logger.info(f"Case-insensitive match: requested '{plugin_name}', using '{available}'") - break - - if not matched: - logger.warning(f"Plugin '{plugin_name}' not found, skipping") - - # Only use valid plugins - self._active_plugins = valid_active_plugins - - logger.info(f"Using verified active plugins: {self._active_plugins}") - - try: - self.syncAllPluginsActive() + try: + available_plugins = [p.get_module_name() for p in self.plugins] + valid_active_plugins = [] + + for plugin_name in activePlugins: + # Check for exact match first + if plugin_name in available_plugins: + valid_active_plugins.append(plugin_name) + continue + + # Try case-insensitive match + plugin_name_lower = plugin_name.lower() + matched = False + for available in available_plugins: + if available.lower() == plugin_name_lower: + # Use the correctly cased name from available plugins + valid_active_plugins.append(available) + matched = True + logger.info(f"Case-insensitive match: requested '{plugin_name}', using '{available}'") + break + + if not matched: + logger.warning(f"Plugin '{plugin_name}' not found, skipping") + + # Only use valid plugins + self._active_plugins = valid_active_plugins + + logger.info(f"Using verified active plugins: {self._active_plugins}") except Exception as e: - logger.error(f"Error syncing plugins: {e}") + logger.error(f"Error validating active plugins: {e}") import traceback logger.error(traceback.format_exc()) + # Continue with an empty plugin list in case of error + self._active_plugins = [] + + # Check if the operation has already timed out + if time.time() - start_time > operation_timeout: + logger.error("Plugin activation operation timed out during validation, skipping sync") + return + + # Now sync the plugins with timeout protection + try: + # Use a separate thread with timeout for syncing + sync_success = [False] + + def sync_with_timeout(): + try: + self.syncAllPluginsActive() + sync_success[0] = True + except Exception as e: + logger.error(f"Error in plugin sync thread: {e}") + import traceback + logger.error(traceback.format_exc()) + + # Make sure we don't exceed our overall operation timeout + remaining_time = operation_timeout - (time.time() - start_time) + if remaining_time <= 0: + logger.error("No time remaining for plugin sync, skipping") + return + + sync_thread = threading.Thread(target=sync_with_timeout) + sync_thread.daemon = True + sync_thread.start() + sync_thread.join(min(30, remaining_time)) # Use either 30 seconds or remaining time, whichever is less + + if not sync_success[0]: + logger.error("Plugin sync timed out or failed, some plugins may not be properly loaded") + except Exception as e: + logger.error(f"Error setting up plugin sync: {e}") + import traceback + logger.error(traceback.format_exc()) + + logger.info("Plugin activation operation completed") + return def setPluginActive(self, pluginInfo, active): """Set the active state of a plugin.""" @@ -339,6 +412,10 @@ class PluginSystemManager: logger.warning("No plugins found, skipping plugin sync") return + # Set an overall timeout for the sync operation to prevent the screen reader from hanging + sync_timeout = 30 # seconds + sync_start_time = time.time() + # Log plugin status before syncing if PLUGIN_DEBUG: for pluginInfo in self.plugins: @@ -353,14 +430,55 @@ class PluginSystemManager: # First unload inactive plugins for pluginInfo in to_unload: + # Check if we've exceeded our total sync timeout + if time.time() - sync_start_time > sync_timeout: + logger.error("Plugin sync operation timed out, continuing with partially synced plugins") + break + logger.info(f"Unloading inactive plugin: {pluginInfo.get_module_name()}") - self.unloadPlugin(pluginInfo) + try: + unload_result = self.unloadPlugin(pluginInfo) + logger.info(f"Plugin {pluginInfo.get_module_name()} unload result: {unload_result}") + except Exception as e: + logger.error(f"Error unloading plugin {pluginInfo.get_module_name()}: {e}") + import traceback + logger.error(traceback.format_exc()) + # Continue with other plugins even if this one fails # Then load active plugins for pluginInfo in to_load: + # Check if we've exceeded our total sync timeout + if time.time() - sync_start_time > sync_timeout: + logger.error("Plugin sync operation timed out, continuing with partially synced plugins") + break + 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}") + + # Use a separate thread with timeout to load each plugin + # This prevents any single plugin from hanging the sync operation + load_success = [False] + load_result = [False] + + def load_plugin_with_timeout(): + try: + result = self.loadPlugin(pluginInfo) + load_result[0] = result + load_success[0] = True + except Exception as e: + logger.error(f"Error in plugin loading thread for {pluginInfo.get_module_name()}: {e}") + import traceback + logger.error(traceback.format_exc()) + + # Each plugin gets up to 5 seconds to load + load_thread = threading.Thread(target=load_plugin_with_timeout) + load_thread.daemon = True + load_thread.start() + load_thread.join(5) # 5 second timeout per plugin + + if load_success[0]: + logger.info(f"Plugin {pluginInfo.get_module_name()} load result: {load_result[0]}") + else: + logger.error(f"Plugin {pluginInfo.get_module_name()} load timed out or failed") # Log final plugin status active_plugins = [p.get_module_name() for p in self.plugins if p.loaded] @@ -371,6 +489,9 @@ class PluginSystemManager: logger.error(f"Error syncing plugins: {e}") import traceback logger.error(traceback.format_exc()) + + logger.info("Plugin sync operation completed") + return def loadPlugin(self, pluginInfo): """Load a plugin.""" @@ -382,14 +503,18 @@ class PluginSystemManager: module_name = pluginInfo.get_module_name() logger.debug(f"===== PLUGIN LOADING START: {module_name} =====") - # Setup timeout for plugin loading + # Setup timeout for plugin loading with a proper handler that interrupts the process load_timeout = 5 # seconds load_completed = False + load_timed_out = False def timeout_handler(): - nonlocal load_completed + nonlocal load_completed, load_timed_out if not load_completed: + load_timed_out = True logger.error(f"Plugin loading timed out for {module_name}") + # When we time out, we want to mark this as a failed plugin + # but still allow the screen reader to continue timer = threading.Timer(load_timeout, timeout_handler) timer.start() @@ -401,6 +526,10 @@ class PluginSystemManager: load_completed = True return True + # Check for timeout on every critical step + if load_timed_out: + return False + # Try to find the plugin file module_name = pluginInfo.get_module_name() plugin_dir = pluginInfo.get_module_dir() @@ -420,54 +549,132 @@ class PluginSystemManager: 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 + # Check for timeout again + if load_timed_out: return False - module = importlib.util.module_from_spec(spec) - spec.loader.exec_module(module) - pluginInfo.module = module + logger.info(f"Loading plugin from: {plugin_file}") + try: + 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) + + # Use a separate thread with timeout to execute the module + # This prevents hanging on problematic module imports + exec_success = [False] + + def exec_module_with_timeout(): + try: + spec.loader.exec_module(module) + exec_success[0] = True + except Exception as e: + logger.error(f"Error executing module {module_name}: {e}") + import traceback + logger.error(traceback.format_exc()) + + exec_thread = threading.Thread(target=exec_module_with_timeout) + exec_thread.daemon = True # Make thread daemonic so it doesn't block program exit + exec_thread.start() + exec_thread.join(3) # 3 second timeout for module execution + + if not exec_success[0]: + logger.error(f"Module execution timed out or failed for {module_name}") + load_completed = True + return False + + pluginInfo.module = module + except Exception as e: + logger.error(f"Failed to load module {module_name}: {e}") + import traceback + logger.error(traceback.format_exc()) + load_completed = True + return False + + # Check for timeout + if load_timed_out: + return False - # Find Plugin class + # Find Plugin class - limit the time we spend searching + start_time = time.time() plugin_class = None - for attr_name in dir(module): - attr = getattr(module, attr_name) - if (inspect.isclass(attr) and - attr.__module__ == module.__name__ and - hasattr(attr, 'activate')): - plugin_class = attr - logger.info(f"Found plugin class: {attr.__name__} in {module_name}") - break - + try: + for attr_name in dir(module): + # Prevent infinite loops or excessive time in dir() operation + if time.time() - start_time > 2: # 2 second timeout + logger.error(f"Finding plugin class timed out for {module_name}") + break + + try: + attr = getattr(module, attr_name) + if (inspect.isclass(attr) and + attr.__module__ == module.__name__ and + hasattr(attr, 'activate')): + plugin_class = attr + logger.info(f"Found plugin class: {attr.__name__} in {module_name}") + break + except Exception as e: + logger.error(f"Error checking attribute {attr_name} in {module_name}: {e}") + continue + except Exception as e: + logger.error(f"Error finding plugin class in {module_name}: {e}") + if not plugin_class: logger.error(f"No plugin class found in {module_name}") load_completed = True return False - # Create and initialize plugin instance - logger.info(f"Creating instance of plugin class: {plugin_class.__name__}") - plugin_instance = plugin_class() - pluginInfo.instance = plugin_instance + # Check for timeout + if load_timed_out: + return False + + # Create and initialize plugin instance with error handling + try: + logger.info(f"Creating instance of plugin class: {plugin_class.__name__}") + plugin_instance = plugin_class() + pluginInfo.instance = plugin_instance + except Exception as e: + logger.error(f"Failed to create instance of plugin class {plugin_class.__name__}: {e}") + import traceback + logger.error(traceback.format_exc()) + load_completed = True + return False + + # Check for timeout + if load_timed_out: + return False # Ensure plugins have a reference to the app - plugin_instance.app = self.getApp() - logger.info(f"Set app reference for plugin: {module_name}") - - if hasattr(plugin_instance, 'set_app'): - plugin_instance.set_app(self.getApp()) - logger.info(f"Called set_app() for plugin: {module_name}") + try: + plugin_instance.app = self.getApp() + logger.info(f"Set app reference for plugin: {module_name}") + + if hasattr(plugin_instance, 'set_app'): + plugin_instance.set_app(self.getApp()) + logger.info(f"Called set_app() for plugin: {module_name}") - if hasattr(plugin_instance, 'set_plugin_info'): - plugin_instance.set_plugin_info(pluginInfo) - logger.info(f"Called set_plugin_info() for plugin: {module_name}") + if hasattr(plugin_instance, 'set_plugin_info'): + plugin_instance.set_plugin_info(pluginInfo) + logger.info(f"Called set_plugin_info() for plugin: {module_name}") + except Exception as e: + logger.error(f"Error setting up plugin instance for {module_name}: {e}") + import traceback + logger.error(traceback.format_exc()) + + # Check for timeout + if load_timed_out: + return False # 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)}") + try: + 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)}") + except Exception as e: + logger.error(f"Error logging plugin debug info for {module_name}: {e}") # Register with pluggy and activate if self.plugin_manager is None: @@ -475,12 +682,49 @@ class PluginSystemManager: load_completed = True return False - logger.info(f"Registering plugin with pluggy: {module_name}") - self.plugin_manager.register(plugin_instance) - + # Check for timeout + if load_timed_out: + return False + try: + logger.info(f"Registering plugin with pluggy: {module_name}") + self.plugin_manager.register(plugin_instance) + except Exception as e: + logger.error(f"Error registering plugin {module_name} with pluggy: {e}") + import traceback + logger.error(traceback.format_exc()) + load_completed = True + return False + + # Check for timeout + if load_timed_out: + return False + + try: + # Use a separate thread with timeout to activate the plugin + activation_success = [False] + + def activate_with_timeout(): + try: + self.plugin_manager.hook.activate(plugin=plugin_instance) + activation_success[0] = True + except Exception as e: + logger.error(f"Error in plugin activation thread for {module_name}: {e}") + import traceback + logger.error(traceback.format_exc()) + logger.info(f"Activating plugin: {module_name}") - self.plugin_manager.hook.activate(plugin=plugin_instance) + activate_thread = threading.Thread(target=activate_with_timeout) + activate_thread.daemon = True + activate_thread.start() + activate_thread.join(3) # 3 second timeout for activation + + if not activation_success[0]: + logger.error(f"Plugin activation timed out or failed for {module_name}") + # We still consider this partially successful - the plugin is loaded + # but not activated. Mark it as not loaded, but don't halt the program. + load_completed = True + return False except Exception as e: logger.error(f"Error activating plugin {module_name}: {e}") import traceback