From 7ee124b499bccad4c40e3fcc528c39bd3bcc9066 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 28 Nov 2024 14:55:39 +0200 Subject: [PATCH] :art: Reduce log verbosity Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 46 ++++------------------------- acapy_agent/utils/classloader.py | 17 +---------- 2 files changed, 6 insertions(+), 57 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 4b6b31d99e..28f9880e72 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -133,7 +133,7 @@ def register_plugin(self, module_name: str) -> Optional[ModuleType]: LOGGER.debug("Registered plugin: %s", module_name) return mod - LOGGER.debug("Failed to register plugin: %s", module_name) + LOGGER.warning("Failed to register plugin: %s", module_name) return None def _is_already_registered(self, module_name: str) -> bool: @@ -163,7 +163,6 @@ def _is_valid_plugin(self, mod: ModuleType, module_name: str) -> bool: """Validate the plugin based on various criteria.""" # Check if the plugin has a 'setup' method if hasattr(mod, "setup"): - LOGGER.debug("Plugin %s has a 'setup' method.", module_name) return True # Check for 'routes' or 'message_types' modules @@ -172,7 +171,6 @@ def _is_valid_plugin(self, mod: ModuleType, module_name: str) -> bool: routes = ClassLoader.load_module("routes", module_name) message_types = ClassLoader.load_module("message_types", module_name) if routes or message_types: - LOGGER.debug("Plugin %s has 'routes' or 'message_types'.", module_name) return True # Check for 'definition' module with 'versions' attribute @@ -194,7 +192,6 @@ def _is_valid_plugin(self, mod: ModuleType, module_name: str) -> bool: # Validate the 'versions' attribute try: self.validate_version(definition.versions, module_name) - LOGGER.debug("Plugin %s has valid versions.", module_name) return True except ProtocolDefinitionValidationError as e: LOGGER.error( @@ -217,14 +214,15 @@ def register_package(self, package_name: str) -> Sequence[ModuleType]: for module_name in module_names: # Skip any module whose last segment is 'tests' if module_name.split(".")[-1] == "tests": - LOGGER.debug("Skipping test module: %s", module_name) continue plugin = self.register_plugin(module_name) if plugin: registered_plugins.append(plugin) else: - LOGGER.debug("Failed to register %s under %s", module_name, package_name) + LOGGER.warning( + "Failed to register %s under %s", module_name, package_name + ) return registered_plugins @@ -233,14 +231,9 @@ async def init_context(self, context: InjectionContext) -> None: LOGGER.debug("Initializing plugin context for %d plugins", len(self._plugins)) for plugin in self._plugins.values(): - plugin_name = plugin.__name__ if hasattr(plugin, "setup"): - LOGGER.debug("Running setup for plugin: %s", plugin_name) await plugin.setup(context) else: - LOGGER.debug( - "Loading protocols for plugin without setup: %s", plugin_name - ) await self.load_protocols(context, plugin) # register event handlers for each protocol, if provided @@ -256,56 +249,45 @@ async def load_protocol_version( protocol_registry = context.inject(ProtocolRegistry) goal_code_registry = context.inject(GoalCodeRegistry) - module_name = mod.__name__ - LOGGER.debug("Loading protocol version for module: %s", module_name) - if hasattr(mod, "MESSAGE_TYPES"): - LOGGER.debug("Registering message types for: %s", module_name) protocol_registry.register_message_types( mod.MESSAGE_TYPES, version_definition=version_definition ) if hasattr(mod, "CONTROLLERS"): - LOGGER.debug("Registering controllers for: %s", module_name) protocol_registry.register_controllers(mod.CONTROLLERS) goal_code_registry.register_controllers(mod.CONTROLLERS) async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> None: """For modules that don't implement setup, register protocols manually.""" plugin_name = plugin.__name__ - LOGGER.debug("Loading protocols for plugin: %s", plugin_name) # If this module contains message_types, then assume that # this is a valid module of the old style (not versioned) try: message_types_path = f"{plugin_name}.message_types" - LOGGER.debug("Attempting to load message types from: %s", message_types_path) mod = ClassLoader.load_module(message_types_path) except ModuleLoadError as e: LOGGER.error("Error loading plugin module message types: %s", e) return if mod: - LOGGER.debug("Found non-versioned message types for: %s", plugin_name) await self.load_protocol_version(context, mod) else: # Otherwise, try check for definition.py for versioned protocol packages try: definition_path = f"{plugin_name}.definition" - LOGGER.debug("Attempting to load definition from: %s", definition_path) definition = ClassLoader.load_module(definition_path) except ModuleLoadError as e: LOGGER.error("Error loading plugin definition module: %s", e) return if definition: - LOGGER.debug("Loading versioned protocols for: %s", plugin_name) for protocol_version in definition.versions: version_path = ( f"{plugin_name}.{protocol_version['path']}.message_types" ) try: - LOGGER.debug("Loading message types from: %s", version_path) mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: LOGGER.error( @@ -318,7 +300,7 @@ async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> if mod: await self.load_protocol_version(context, mod, protocol_version) else: - LOGGER.debug("Failed to load %s", version_path) + LOGGER.warning("Failed to load %s", version_path) async def register_admin_routes(self, app) -> None: """Call route registration methods on the current context.""" @@ -326,16 +308,13 @@ async def register_admin_routes(self, app) -> None: for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.debug("Processing routes for plugin: %s", plugin_name) mod = None definition = ClassLoader.load_module("definition", plugin_name) if definition: # Load plugin routes that are in a versioned package. - LOGGER.debug("Loading versioned routes for: %s", plugin_name) for plugin_version in definition.versions: version_path = f"{plugin_name}.{plugin_version['path']}.routes" try: - LOGGER.debug("Loading routes from: %s", version_path) mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: LOGGER.error( @@ -344,20 +323,17 @@ async def register_admin_routes(self, app) -> None: continue if mod and hasattr(mod, "register"): - LOGGER.debug("Registering routes for: %s", plugin_name) await mod.register(app) else: # Load plugin routes that aren't in a versioned package. routes_path = f"{plugin_name}.routes" try: - LOGGER.debug("Loading non-versioned routes from: %s", routes_path) mod = ClassLoader.load_module(routes_path) except ModuleLoadError as e: LOGGER.error("Error loading admin routes from %s: %s", routes_path, e) continue if mod and hasattr(mod, "register"): - LOGGER.debug("Registering routes for: %s", plugin_name) await mod.register(app) def register_protocol_events(self, context: InjectionContext) -> None: @@ -371,36 +347,30 @@ def register_protocol_events(self, context: InjectionContext) -> None: for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.debug("Processing events for plugin: %s", plugin_name) mod = None definition = ClassLoader.load_module("definition", plugin_name) if definition: # Load plugin routes that are in a versioned package. - LOGGER.debug("Loading versioned events for: %s", plugin_name) for plugin_version in definition.versions: version_path = f"{plugin_name}.{plugin_version['path']}.routes" try: - LOGGER.debug("Loading events from: %s", version_path) mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: LOGGER.error("Error loading events from %s: %s", version_path, e) continue if mod and hasattr(mod, "register_events"): - LOGGER.debug("Registering events from: %s", version_path) mod.register_events(event_bus) else: # Load plugin routes that aren't in a versioned package. routes_path = f"{plugin_name}.routes" try: - LOGGER.debug("Loading non-versioned events from: %s", routes_path) mod = ClassLoader.load_module(routes_path) except ModuleLoadError as e: LOGGER.error("Error loading events from %s: %s", routes_path, e) continue if mod and hasattr(mod, "register_events"): - LOGGER.debug("Registering events from: %s", version_path) mod.register_events(event_bus) def post_process_routes(self, app) -> None: @@ -409,36 +379,30 @@ def post_process_routes(self, app) -> None: for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.debug("Post-processing routes for plugin: %s", plugin_name) mod = None definition = ClassLoader.load_module("definition", plugin_name) if definition: # Set binary file responses for routes that are in a versioned package. - LOGGER.debug("Processing versioned routes for: %s", plugin_name) for plugin_version in definition.versions: version_path = f"{plugin_name}.{plugin_version['path']}.routes" try: - LOGGER.debug("Loading routes from: %s", version_path) mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: LOGGER.error("Error loading routes from %s: %s", version_path, e) continue if mod and hasattr(mod, "post_process_routes"): - LOGGER.debug("Post-processing routes for %s", plugin_name) mod.post_process_routes(app) else: # Set binary file responses for routes not in a versioned package. routes_path = f"{plugin_name}.routes" try: - LOGGER.debug("Loading non-versioned routes from: %s", routes_path) mod = ClassLoader.load_module(routes_path) except ModuleLoadError as e: LOGGER.error("Error loading routes from %s: %s", routes_path, e) continue if mod and hasattr(mod, "post_process_routes"): - LOGGER.debug("Post-processing routes for %s", plugin_name) mod.post_process_routes(app) def __repr__(self) -> str: diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index 3494011a92..208b8078d8 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -48,15 +48,8 @@ def load_module( # Check the cache cache_key = (mod_path, package) if cache_key in cls._module_cache: - LOGGER.debug("Module found in cache: %s", cache_key) return cls._module_cache[cache_key] - LOGGER.debug( - "Loading module: %s%s", - mod_path, - f" with package: {package}" if package else "", - ) - if package: # preload parent package if not cls.load_module(package): @@ -87,7 +80,6 @@ def load_module( return None try: - LOGGER.debug("Importing package: %s, module: %s", package, mod_path) module = import_module(mod_path, package) cls._module_cache[cache_key] = module # Cache the loaded module return module @@ -124,13 +116,6 @@ def load_class( LOGGER.debug("Class found in cache: %s", class_name) return cls._class_cache[cache_key] - LOGGER.debug( - "Loading class: %s%s%s", - class_name, - f", with default_module: {default_module}" if default_module else "", - f", with package: {package}" if package else "", - ) - if "." in class_name: # import module and find class mod_path, class_name = class_name.rsplit(".", 1) @@ -244,7 +229,7 @@ def scan_subpackages(cls, package: str) -> Sequence[str]: if (item / "__init__.py").exists(): subpackage = f"{package}.{joiner}{item.name}" found.append(subpackage) - LOGGER.debug("Total sub-packages found under %s: %s", package, found) + LOGGER.debug("%d sub-packages found under %s: %s", len(found), package, found) return found