From 42926e1af83b9270b6e7b5676a8bd63c23568761 Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 6 Nov 2024 20:27:33 +0200 Subject: [PATCH 01/51] :art: Refactor `register_plugin` steps for maintainability Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 144 ++++++++++++++++------------ 1 file changed, 84 insertions(+), 60 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index b3fa709386..43aacdb810 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -117,70 +117,94 @@ def validate_version(self, version_list, module_name): return True - def register_plugin(self, module_name: str) -> ModuleType: + def register_plugin(self, module_name: str) -> Optional[ModuleType]: """Register a plugin module.""" - if module_name in self._plugins: - mod = self._plugins[module_name] - elif module_name in self._blocklist: - LOGGER.debug(f"Blocked {module_name} from loading due to blocklist") + if self._is_already_registered(module_name): + return self._plugins.get(module_name) + + if self._is_blocked(module_name): return None - else: - try: - mod = ClassLoader.load_module(module_name) - LOGGER.debug(f"Loaded module: {module_name}") - except ModuleLoadError as e: - LOGGER.error(f"Error loading plugin module: {e}") - return None - # Module must exist - if not mod: - LOGGER.error(f"Module doesn't exist: {module_name}") - return None - - # Any plugin with a setup method is considered valid. - if hasattr(mod, "setup"): - self._plugins[module_name] = mod - return mod - - # Make an exception for non-protocol modules - # that contain admin routes and for old-style protocol - # modules without version support - routes = ClassLoader.load_module("routes", module_name) - message_types = ClassLoader.load_module("message_types", module_name) - if routes or message_types: - self._plugins[module_name] = mod - return mod - - definition = ClassLoader.load_module("definition", module_name) - - # definition.py must exist in protocol - if not definition: - LOGGER.error(f"Protocol does not include definition.py: {module_name}") - return None - - # definition.py must include versions attribute - if not hasattr(definition, "versions"): - LOGGER.error( - "Protocol definition does not include " - f"versions attribute: {module_name}" - ) - return None + mod = self._load_module(module_name) + if not mod: + return None - # Definition list must not be malformed - try: - self.validate_version(definition.versions, module_name) - except ProtocolDefinitionValidationError as e: - LOGGER.error(f"Protocol versions definition is malformed. {e}") - return None - - self._plugins[module_name] = mod - return mod - - # # Load each version as a separate plugin - # for version in definition.versions: - # mod = ClassLoader.load_module(f"{module_name}.{version['path']}") - # self._plugins[module_name] = mod - # return mod + if self._is_valid_plugin(mod, module_name): + self._plugins[module_name] = mod + LOGGER.debug("Registered plugin: %s", module_name) + return mod + + LOGGER.debug("Failed to register plugin: %s", module_name) + return None + + def _is_already_registered(self, module_name: str) -> bool: + """Check if the plugin is already registered.""" + if module_name in self._plugins: + LOGGER.debug("Plugin %s is already registered.", module_name) + return True + return False + + def _is_blocked(self, module_name: str) -> bool: + """Check if the plugin is in the blocklist.""" + if module_name in self._blocklist: + LOGGER.debug("Blocked %s from loading due to blocklist.", module_name) + return True + return False + + def _load_module(self, module_name: str) -> Optional[ModuleType]: + """Load the plugin module using ClassLoader.""" + try: + mod = ClassLoader.load_module(module_name) + LOGGER.debug("Successfully loaded module: %s", module_name) + return mod + except ModuleLoadError as e: + LOGGER.error("Error loading plugin module '%s': %s", module_name, e) + return None + + 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 + # This makes an exception for non-protocol modules that contain admin routes + # and for old-style protocol modules without version support + 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 + definition = ClassLoader.load_module("definition", module_name) + if not definition: + LOGGER.error( + "Protocol does not include 'definition.py' for module: %s", + module_name, + ) + return False + + if not hasattr(definition, "versions"): + LOGGER.error( + "Protocol definition does not include versions attribute for module: %s", + module_name, + ) + return False + + # 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( + "Protocol versions definition is malformed for module '%s': %s", + module_name, + e, + ) + return False def register_package(self, package_name: str) -> Sequence[ModuleType]: """Register all modules (sub-packages) under a given package name.""" From 1c096722fd30f35ce5622a4a276a91602a141125 Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 6 Nov 2024 20:36:43 +0200 Subject: [PATCH 02/51] :art: improve logging in register_package Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 26 ++++++++++++++++---------- 1 file changed, 16 insertions(+), 10 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 43aacdb810..3a97d50ee4 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -208,21 +208,27 @@ def _is_valid_plugin(self, mod: ModuleType, module_name: str) -> bool: def register_package(self, package_name: str) -> Sequence[ModuleType]: """Register all modules (sub-packages) under a given package name.""" + LOGGER.debug("Registering package: %s", package_name) try: module_names = ClassLoader.scan_subpackages(package_name) except ModuleLoadError: LOGGER.error("Plugin module package not found: %s", package_name) module_names = [] - return list( - filter( - None, - ( - self.register_plugin(module_name) - for module_name in module_names - if module_name.split(".")[-1] != "tests" - ), - ) - ) + + registered_plugins = [] + 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) + + return registered_plugins async def init_context(self, context: InjectionContext): """Call plugin setup methods on the current context.""" From 6fcd026de983423e9b1f16392054368009c32145 Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 6 Nov 2024 21:07:22 +0200 Subject: [PATCH 03/51] :art: Rename method and remove redundant main call Signed-off-by: ff137 --- acapy_agent/commands/provision.py | 11 +++-------- acapy_agent/commands/tests/test_provision.py | 15 ++++++++++----- 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/acapy_agent/commands/provision.py b/acapy_agent/commands/provision.py index 962b38dc8e..a463dd6e48 100644 --- a/acapy_agent/commands/provision.py +++ b/acapy_agent/commands/provision.py @@ -67,7 +67,7 @@ async def provision(settings: dict): raise ProvisionError("Error during provisioning") from e -def execute(argv: Sequence[str] = None): +def execute_provision(argv: Sequence[str] = None): """Entrypoint.""" parser = arg.create_argument_parser(prog=PROG) parser.prog += " provision" @@ -84,10 +84,5 @@ def execute(argv: Sequence[str] = None): loop.run_until_complete(provision(settings)) -def main(): - """Execute the main line.""" - if __name__ == "__main__": - execute() - - -main() +if __name__ == "__main__": + execute_provision() diff --git a/acapy_agent/commands/tests/test_provision.py b/acapy_agent/commands/tests/test_provision.py index ed50bb9eb8..8453222557 100644 --- a/acapy_agent/commands/tests/test_provision.py +++ b/acapy_agent/commands/tests/test_provision.py @@ -14,10 +14,10 @@ class TestProvision(IsolatedAsyncioTestCase): def test_bad_calls(self): with self.assertRaises(ArgsParseError): - test_module.execute([]) + test_module.execute_provision([]) with self.assertRaises(SystemExit): - test_module.execute(["bad"]) + test_module.execute_provision(["bad"]) async def test_provision_ledger_configured(self): profile = mock.MagicMock(close=mock.CoroutineMock()) @@ -46,12 +46,17 @@ async def test_provision_config_x(self): with self.assertRaises(test_module.ProvisionError): await test_module.provision({}) - def test_main(self): + def test_main_entry_point(self): + """Test that the execute_provision function is called when the module is run as main.""" with ( mock.patch.object(test_module, "__name__", "__main__"), - mock.patch.object(test_module, "execute", mock.MagicMock()) as mock_execute, + mock.patch.object( + test_module, "execute_provision", mock.MagicMock() + ) as mock_execute, ): - test_module.main() + import importlib + + importlib.reload(test_module) # Reload the module to trigger the main guard mock_execute.assert_called_once async def test_provision_should_store_provided_mediation_invite(self): From eeeead6d8ff03ab8d4521f75764012e1400353bf Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 6 Nov 2024 21:08:48 +0200 Subject: [PATCH 04/51] :art: Signed-off-by: ff137 --- acapy_agent/config/argparse.py | 2 +- acapy_agent/config/default_context.py | 10 ++++----- acapy_agent/core/plugin_registry.py | 30 +++++++++++++-------------- 3 files changed, 20 insertions(+), 22 deletions(-) diff --git a/acapy_agent/config/argparse.py b/acapy_agent/config/argparse.py index f667aec4d4..86f5b9cb1c 100644 --- a/acapy_agent/config/argparse.py +++ b/acapy_agent/config/argparse.py @@ -63,7 +63,7 @@ def get_registered(cls, category: Optional[str] = None): def create_argument_parser(*, prog: Optional[str] = None): - """Create am instance of an arg parser, force yaml format for external config.""" + """Create an instance of an arg parser, force yaml format for external config.""" return ArgumentParser(config_file_parser_class=YAMLConfigFileParser, prog=prog) diff --git a/acapy_agent/config/default_context.py b/acapy_agent/config/default_context.py index f405a5e807..57bd10333e 100644 --- a/acapy_agent/config/default_context.py +++ b/acapy_agent/config/default_context.py @@ -173,15 +173,15 @@ def register_anoncreds_plugins(): for plugin in anoncreds_plugins: plugin_registry.register_plugin(plugin) - if wallet_type == "askar-anoncreds": - register_anoncreds_plugins() - else: - register_askar_plugins() - if context.settings.get("multitenant.admin_enabled"): plugin_registry.register_plugin("acapy_agent.multitenant.admin") register_askar_plugins() register_anoncreds_plugins() + else: + if wallet_type == "askar-anoncreds": + register_anoncreds_plugins() + else: + register_askar_plugins() # Register external plugins for plugin_path in self.settings.get("external_plugins", []): diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 3a97d50ee4..61ea440f74 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -3,7 +3,7 @@ import logging from collections import OrderedDict from types import ModuleType -from typing import Iterable, Optional, Sequence +from typing import Optional, Sequence, Set from ..config.injection_context import InjectionContext from ..core.event_bus import EventBus @@ -18,10 +18,10 @@ class PluginRegistry: """Plugin registry for indexing application plugins.""" - def __init__(self, blocklist: Iterable[str] = []): + def __init__(self, blocklist: Optional[Set[str]] = None): """Initialize a `PluginRegistry` instance.""" - self._plugins = OrderedDict() - self._blocklist = set(blocklist) + self._plugins: OrderedDict[str, ModuleType] = OrderedDict() + self._blocklist: Set[str] = set(blocklist) if blocklist else set() @property def plugin_names(self) -> Sequence[str]: @@ -57,7 +57,6 @@ def validate_version(self, version_list, module_name): for version_dict in version_list: # Dicts must have correct format - try: if not ( isinstance(version_dict["major_version"], int) @@ -89,8 +88,8 @@ def validate_version(self, version_list, module_name): > version_dict["current_minor_version"] ): raise ProtocolDefinitionValidationError( - "Minimum supported minor version cannot" - + " be greater than current minor version" + "Minimum supported minor version cannot " + "be greater than current minor version" ) # There can only be one definition per major version @@ -102,7 +101,7 @@ def validate_version(self, version_list, module_name): if count > 1: raise ProtocolDefinitionValidationError( "There can only be one definition per major version. " - + f"Found {count} for major version {major_version}." + f"Found {count} for major version {major_version}." ) # Specified module must be loadable @@ -111,8 +110,7 @@ def validate_version(self, version_list, module_name): if not mod: raise ProtocolDefinitionValidationError( - "Version module path is not " - + f"loadable: {module_name}, {version_path}" + f"Version module path is not loadable: {module_name}, {version_path}" ) return True @@ -230,7 +228,7 @@ def register_package(self, package_name: str) -> Sequence[ModuleType]: return registered_plugins - async def init_context(self, context: InjectionContext): + async def init_context(self, context: InjectionContext) -> None: """Call plugin setup methods on the current context.""" for plugin in self._plugins.values(): if hasattr(plugin, "setup"): @@ -246,7 +244,7 @@ async def load_protocol_version( context: InjectionContext, mod: ModuleType, version_definition: Optional[dict] = None, - ): + ) -> None: """Load a particular protocol version.""" protocol_registry = context.inject(ProtocolRegistry) goal_code_registry = context.inject(GoalCodeRegistry) @@ -258,7 +256,7 @@ async def load_protocol_version( protocol_registry.register_controllers(mod.CONTROLLERS) goal_code_registry.register_controllers(mod.CONTROLLERS) - async def load_protocols(self, context: InjectionContext, plugin: ModuleType): + async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> None: """For modules that don't implement setup, register protocols manually.""" # If this module contains message_types, then assume that @@ -293,7 +291,7 @@ async def load_protocols(self, context: InjectionContext, plugin: ModuleType): LOGGER.error("Error loading plugin module message types: %s", e) return - async def register_admin_routes(self, app): + async def register_admin_routes(self, app) -> None: """Call route registration methods on the current context.""" for plugin in self._plugins.values(): definition = ClassLoader.load_module("definition", plugin.__name__) @@ -319,7 +317,7 @@ async def register_admin_routes(self, app): if mod and hasattr(mod, "register"): await mod.register(app) - def register_protocol_events(self, context: InjectionContext): + def register_protocol_events(self, context: InjectionContext) -> None: """Call route register_events methods on the current context.""" event_bus = context.inject_or(EventBus) if not event_bus: @@ -349,7 +347,7 @@ def register_protocol_events(self, context: InjectionContext): if mod and hasattr(mod, "register_events"): mod.register_events(event_bus) - def post_process_routes(self, app): + def post_process_routes(self, app) -> None: """Call route binary file response OpenAPI fixups if applicable.""" for plugin in self._plugins.values(): definition = ClassLoader.load_module("definition", plugin.__name__) From 7e793c2e6c5f5f99ae9fbee72e9188308ba57f47 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 11:42:14 +0200 Subject: [PATCH 05/51] :loud_sound: Add debug logging to Context Builder Signed-off-by: ff137 --- acapy_agent/config/default_context.py | 20 +++++++++++++++----- 1 file changed, 15 insertions(+), 5 deletions(-) diff --git a/acapy_agent/config/default_context.py b/acapy_agent/config/default_context.py index 57bd10333e..f1384d83cb 100644 --- a/acapy_agent/config/default_context.py +++ b/acapy_agent/config/default_context.py @@ -1,5 +1,7 @@ """Classes for configuring the default injection context.""" +import logging + from ..anoncreds.registry import AnonCredsRegistry from ..cache.base import BaseCache from ..cache.in_memory import InMemoryCache @@ -27,17 +29,22 @@ from .injection_context import InjectionContext from .provider import CachedProvider, ClassProvider +LOGGER = logging.getLogger(__name__) + class DefaultContextBuilder(ContextBuilder): """Default context builder.""" async def build_context(self) -> InjectionContext: """Build the base injection context; set DIDComm prefix to emit.""" + LOGGER.debug("Building new injection context with settings: %s", self.settings) + context = InjectionContext(settings=self.settings) context.settings.set_default("default_label", "Aries Cloud Agent") if context.settings.get("timing.enabled"): timing_log = context.settings.get("timing.log_file") + LOGGER.debug("Enabling timing collector with log file: %s", timing_log) collector = Collector(log_path=timing_log) context.injector.bind_instance(Collector, collector) @@ -64,11 +71,8 @@ async def build_context(self) -> InjectionContext: # DIDComm Messaging if context.settings.get("experiment.didcomm_v2"): - from didcomm_messaging import ( - CryptoService, - PackagingService, - RoutingService, - ) + LOGGER.info("DIDComm v2 experimental mode enabled") + from didcomm_messaging import CryptoService, PackagingService, RoutingService from didcomm_messaging.crypto.backend.askar import AskarCryptoService context.injector.bind_instance(CryptoService, AskarCryptoService()) @@ -82,11 +86,13 @@ async def build_context(self) -> InjectionContext: async def bind_providers(self, context: InjectionContext): """Bind various class providers.""" + LOGGER.debug("Begin binding providers to context") context.injector.bind_provider(ProfileManager, ProfileManagerProvider()) wallet_type = self.settings.get("wallet.type") if wallet_type == "askar-anoncreds": + LOGGER.debug("Using AnonCreds tails server") context.injector.bind_provider( BaseTailsServer, ClassProvider( @@ -94,6 +100,7 @@ async def bind_providers(self, context: InjectionContext): ), ) else: + LOGGER.debug("Using Indy tails server") context.injector.bind_provider( BaseTailsServer, ClassProvider( @@ -127,6 +134,7 @@ async def bind_providers(self, context: InjectionContext): async def load_plugins(self, context: InjectionContext): """Set up plugin registry and load plugins.""" + LOGGER.debug("Initializing plugin registry") plugin_registry = PluginRegistry( blocklist=self.settings.get("blocked_plugins", []) ) @@ -174,6 +182,7 @@ def register_anoncreds_plugins(): plugin_registry.register_plugin(plugin) if context.settings.get("multitenant.admin_enabled"): + LOGGER.debug("Multitenant admin enabled - registering additional plugins") plugin_registry.register_plugin("acapy_agent.multitenant.admin") register_askar_plugins() register_anoncreds_plugins() @@ -185,6 +194,7 @@ def register_anoncreds_plugins(): # Register external plugins for plugin_path in self.settings.get("external_plugins", []): + LOGGER.debug("Registering external plugin: %s", plugin_path) plugin_registry.register_plugin(plugin_path) # Register message protocols From a98986a02d9ca255200e2344dccfe6cc816437f0 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 11:42:34 +0200 Subject: [PATCH 06/51] :art: Deduplicate registering list of plugins Signed-off-by: ff137 --- acapy_agent/config/default_context.py | 40 +++++++++++++++------------ 1 file changed, 23 insertions(+), 17 deletions(-) diff --git a/acapy_agent/config/default_context.py b/acapy_agent/config/default_context.py index f1384d83cb..7828ffb9c5 100644 --- a/acapy_agent/config/default_context.py +++ b/acapy_agent/config/default_context.py @@ -145,19 +145,19 @@ async def load_plugins(self, context: InjectionContext): if not self.settings.get("transport.disabled"): plugin_registry.register_package("acapy_agent.protocols") - # Currently providing admin routes only - plugin_registry.register_plugin("acapy_agent.holder") - - plugin_registry.register_plugin("acapy_agent.ledger") - - plugin_registry.register_plugin("acapy_agent.connections") - plugin_registry.register_plugin("acapy_agent.messaging.jsonld") - plugin_registry.register_plugin("acapy_agent.resolver") - plugin_registry.register_plugin("acapy_agent.settings") - plugin_registry.register_plugin("acapy_agent.vc") - plugin_registry.register_plugin("acapy_agent.vc.data_integrity") - plugin_registry.register_plugin("acapy_agent.wallet") - plugin_registry.register_plugin("acapy_agent.wallet.keys") + # Define plugin groups + default_plugins = [ + "acapy_agent.holder", + "acapy_agent.ledger", + "acapy_agent.connections", + "acapy_agent.messaging.jsonld", + "acapy_agent.resolver", + "acapy_agent.settings", + "acapy_agent.vc", + "acapy_agent.vc.data_integrity", + "acapy_agent.wallet", + "acapy_agent.wallet.keys", + ] anoncreds_plugins = [ "acapy_agent.anoncreds", @@ -173,13 +173,19 @@ async def load_plugins(self, context: InjectionContext): "acapy_agent.revocation", ] - def register_askar_plugins(): - for plugin in askar_plugins: + def register_plugins(plugins: list[str], plugin_type: str): + """Register a group of plugins with logging.""" + LOGGER.debug("Registering %s plugins", plugin_type) + for plugin in plugins: plugin_registry.register_plugin(plugin) + def register_askar_plugins(): + register_plugins(askar_plugins, "askar") + def register_anoncreds_plugins(): - for plugin in anoncreds_plugins: - plugin_registry.register_plugin(plugin) + register_plugins(anoncreds_plugins, "anoncreds") + + register_plugins(default_plugins, "default") if context.settings.get("multitenant.admin_enabled"): LOGGER.debug("Multitenant admin enabled - registering additional plugins") From 07f6a24688d138775a30251b3ae51affb62c8672 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 11:45:36 +0200 Subject: [PATCH 07/51] :art: Signed-off-by: ff137 --- acapy_agent/config/default_context.py | 5 ----- 1 file changed, 5 deletions(-) diff --git a/acapy_agent/config/default_context.py b/acapy_agent/config/default_context.py index 7828ffb9c5..4ceb81933a 100644 --- a/acapy_agent/config/default_context.py +++ b/acapy_agent/config/default_context.py @@ -112,12 +112,7 @@ async def bind_providers(self, context: InjectionContext): context.injector.bind_provider( BaseWireFormat, CachedProvider( - # StatsProvider( ClassProvider("acapy_agent.transport.pack_format.PackWireFormat"), - # ( - # "encode_message", "parse_message" - # ), - # ) ), ) From 9b3d4c7e1e80a4875106e979323e93c63cd15602 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:23:58 +0200 Subject: [PATCH 08/51] :loud_sound: Add debug logging to init_context Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 61ea440f74..be58ba0661 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -230,10 +230,17 @@ def register_package(self, package_name: str) -> Sequence[ModuleType]: async def init_context(self, context: InjectionContext) -> None: """Call plugin setup methods on the current context.""" + 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 From d32cd968188b852fcf89845b014c1996cf7e5d8e Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:24:10 +0200 Subject: [PATCH 09/51] :loud_sound: Add debug logging to load_protocol_version Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index be58ba0661..1ad320e2d4 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -255,11 +255,18 @@ async def load_protocol_version( """Load a particular 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) From 06f7072b4255e1c89c3a091767646cecf2eb5ca2 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:25:30 +0200 Subject: [PATCH 10/51] :loud_sound: Add debug logging to load_protocols Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 31 +++++++++++++++++++---------- 1 file changed, 21 insertions(+), 10 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 1ad320e2d4..d21eebeb66 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -272,37 +272,48 @@ async def load_protocol_version( 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: - mod = ClassLoader.load_module(plugin.__name__ + ".message_types") + 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 + # Otherwise, try check for definition.py for versioned protocol packages try: - definition = ClassLoader.load_module(plugin.__name__ + ".definition") + 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: - mod = ClassLoader.load_module( - f"{plugin.__name__}.{protocol_version['path']}" - + ".message_types" - ) + LOGGER.debug("Loading message types from: %s", version_path) + mod = ClassLoader.load_module(version_path) await self.load_protocol_version(context, mod, protocol_version) - except ModuleLoadError as e: - LOGGER.error("Error loading plugin module message types: %s", e) + LOGGER.error( + "Error loading plugin module message types from %s: %s", + version_path, + e, + ) return async def register_admin_routes(self, app) -> None: From 902eedeef3c1b775139b5f7a73477fce347e4c75 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:25:52 +0200 Subject: [PATCH 11/51] :loud_sound: Add debug logging to register_admin_routes Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 32 +++++++++++++++++++---------- 1 file changed, 21 insertions(+), 11 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index d21eebeb66..909bac2436 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -318,29 +318,39 @@ async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> async def register_admin_routes(self, app) -> None: """Call route registration methods on the current context.""" + LOGGER.debug("Registering admin routes for %d plugins", len(self._plugins)) + for plugin in self._plugins.values(): - definition = ClassLoader.load_module("definition", plugin.__name__) + 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: - mod = ClassLoader.load_module( - f"{plugin.__name__}.{plugin_version['path']}.routes" - ) + LOGGER.debug("Loading routes from: %s", version_path) + mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: - LOGGER.error("Error loading admin routes: %s", e) + LOGGER.error( + "Error loading admin routes from %s: %s", version_path, e + ) continue - if mod and hasattr(mod, "register"): - await mod.register(app) else: # Load plugin routes that aren't in a versioned package. + routes_path = f"{plugin_name}.routes" try: - mod = ClassLoader.load_module(f"{plugin.__name__}.routes") + 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: %s", e) + LOGGER.error("Error loading admin routes from %s: %s", routes_path, e) continue - if mod and hasattr(mod, "register"): - await mod.register(app) + + if mod and hasattr(mod, "register"): + LOGGER.debug("Registering routes from: %s", version_path) + await mod.register(app) def register_protocol_events(self, context: InjectionContext) -> None: """Call route register_events methods on the current context.""" From 2f4c4dc5c778b14177121185f752214927f73a90 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:26:17 +0200 Subject: [PATCH 12/51] :loud_sound: Add debug logging to register_protocol_events Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 31 +++++++++++++++++++---------- 1 file changed, 20 insertions(+), 11 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 909bac2436..302a409062 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -354,33 +354,42 @@ async def register_admin_routes(self, app) -> None: def register_protocol_events(self, context: InjectionContext) -> None: """Call route register_events methods on the current context.""" + LOGGER.debug("Registering protocol events for %d plugins", len(self._plugins)) + event_bus = context.inject_or(EventBus) if not event_bus: LOGGER.error("No event bus in context") return + for plugin in self._plugins.values(): - definition = ClassLoader.load_module("definition", plugin.__name__) + 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: - mod = ClassLoader.load_module( - f"{plugin.__name__}.{plugin_version['path']}.routes" - ) + LOGGER.debug("Loading events from: %s", version_path) + mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: - LOGGER.error("Error loading admin routes: %s", e) + LOGGER.error("Error loading events from %s: %s", version_path, e) continue - if mod and hasattr(mod, "register_events"): - mod.register_events(event_bus) else: # Load plugin routes that aren't in a versioned package. + routes_path = f"{plugin_name}.routes" try: - mod = ClassLoader.load_module(f"{plugin.__name__}.routes") + LOGGER.debug("Loading non-versioned events from: %s", routes_path) + mod = ClassLoader.load_module(routes_path) except ModuleLoadError as e: - LOGGER.error("Error loading admin routes: %s", e) + LOGGER.error("Error loading events from %s: %s", routes_path, e) continue - if mod and hasattr(mod, "register_events"): - mod.register_events(event_bus) + + 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: """Call route binary file response OpenAPI fixups if applicable.""" From 2ae3d8342d2c29e75624d3066fcea93df3e3e43a Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:26:40 +0200 Subject: [PATCH 13/51] :loud_sound: Add debug logging to post_process_routes Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 30 ++++++++++++++++++----------- 1 file changed, 19 insertions(+), 11 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 302a409062..b4094e4e19 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -393,29 +393,37 @@ def register_protocol_events(self, context: InjectionContext) -> None: def post_process_routes(self, app) -> None: """Call route binary file response OpenAPI fixups if applicable.""" + LOGGER.debug("Post-processing routes for %d plugins", len(self._plugins)) + for plugin in self._plugins.values(): - definition = ClassLoader.load_module("definition", plugin.__name__) + 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: - mod = ClassLoader.load_module( - f"{plugin.__name__}.{plugin_version['path']}.routes" - ) + LOGGER.debug("Loading routes from: %s", version_path) + mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: - LOGGER.error("Error loading admin routes: %s", e) + LOGGER.error("Error loading routes from %s: %s", version_path, e) continue - if mod and hasattr(mod, "post_process_routes"): - mod.post_process_routes(app) else: # Set binary file responses for routes not in a versioned package. + routes_path = f"{plugin_name}.routes" try: - mod = ClassLoader.load_module(f"{plugin.__name__}.routes") + 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: %s", e) + LOGGER.error("Error loading routes from %s: %s", routes_path, e) continue - if mod and hasattr(mod, "post_process_routes"): - mod.post_process_routes(app) + + if mod and hasattr(mod, "post_process_routes"): + LOGGER.debug("Post-processing routes from: %s", version_path) + mod.post_process_routes(app) def __repr__(self) -> str: """Return a string representation for this class.""" From f0b08a021c8c5706697c64a7b5c3836b05025316 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:38:00 +0200 Subject: [PATCH 14/51] :art: Replace print statements with info logs Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index eea46cd716..57fd69569b 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -397,18 +397,19 @@ async def start(self) -> None: their_endpoint=their_endpoint, alias="test-suite", ) - print("Created static connection for test suite") - print(" - My DID:", test_conn.my_did) - print(" - Their DID:", test_conn.their_did) - print(" - Their endpoint:", their_endpoint) - print() + LOGGER.info( + "Created static connection for test suite\n" + f" - My DID: {test_conn.my_did}\n" + f" - Their DID: {test_conn.their_did}\n" + f" - Their endpoint: {their_endpoint}\n" + ) del mgr # Clear default mediator if context.settings.get("mediation.clear"): mediation_mgr = MediationManager(self.root_profile) await mediation_mgr.clear_default_mediator() - print("Default mediator cleared.") + LOGGER.info("Default mediator cleared.") # Clear default mediator # Set default mediator by id @@ -417,7 +418,7 @@ async def start(self) -> None: mediation_mgr = MediationManager(self.root_profile) try: await mediation_mgr.set_default_mediator_by_id(default_mediator_id) - print(f"Default mediator set to {default_mediator_id}") + LOGGER.info(f"Default mediator set to {default_mediator_id}") except Exception: LOGGER.exception("Error updating default mediator") @@ -436,8 +437,7 @@ async def start(self) -> None: ) base_url = context.settings.get("invite_base_url") invite_url = invi_rec.invitation.to_url(base_url) - print("Invitation URL:") - print(invite_url, flush=True) + LOGGER.info(f"Invitation URL:\n{invite_url}") qr = QRCode(border=1) qr.add_data(invite_url) qr.print_ascii(invert=True) @@ -485,7 +485,7 @@ async def start(self) -> None: session, MediationManager.SET_TO_DEFAULT_ON_GRANTED, True ) - print("Attempting to connect to mediator...") + LOGGER.info("Attempting to connect to mediator...") del mgr except Exception: LOGGER.exception("Error accepting mediation invitation") From 18e8a13351d7db43165b40b25210bcb653c12d62 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 12:58:06 +0200 Subject: [PATCH 15/51] :art: Replace almost all print statements with info logs Signed-off-by: ff137 --- acapy_agent/__main__.py | 13 +++++++---- .../anoncreds/default/did_indy/registry.py | 2 +- .../anoncreds/default/did_web/registry.py | 5 ++++- .../anoncreds/default/legacy_indy/registry.py | 2 +- acapy_agent/commands/provision.py | 7 ++++-- acapy_agent/commands/start.py | 4 ++-- acapy_agent/config/wallet.py | 22 +++++++++---------- acapy_agent/transport/v2_pack_format.py | 3 +-- acapy_agent/vc/vc_di/prove.py | 5 ++++- acapy_agent/wallet/crypto.py | 5 ++++- 10 files changed, 42 insertions(+), 26 deletions(-) diff --git a/acapy_agent/__main__.py b/acapy_agent/__main__.py index bd0c964705..9669588b83 100644 --- a/acapy_agent/__main__.py +++ b/acapy_agent/__main__.py @@ -1,8 +1,11 @@ """acapy_agent package entry point.""" +import logging import os import sys +LOGGER = logging.getLogger(__name__) + def init_debug(args): """Initialize debugging environment.""" @@ -26,16 +29,18 @@ def init_debug(args): import debugpy debugpy.listen((DAP_HOST, DAP_PORT)) - print(f"=== Waiting for debugger to attach to {DAP_HOST}:{DAP_PORT} ===") + LOGGER.info( + f"=== Waiting for debugger to attach to {DAP_HOST}:{DAP_PORT} ===" + ) debugpy.wait_for_client() except ImportError: - print("debugpy library was not found") + LOGGER.error("debugpy library was not found") if ENABLE_PYDEVD_PYCHARM or "--debug-pycharm" in args: try: import pydevd_pycharm - print( + LOGGER.info( "aca-py remote debugging to " f"{PYDEVD_PYCHARM_HOST}:{PYDEVD_PYCHARM_AGENT_PORT}" ) @@ -47,7 +52,7 @@ def init_debug(args): suspend=False, ) except ImportError: - print("pydevd_pycharm library was not found") + LOGGER.error("pydevd_pycharm library was not found") def run(args): diff --git a/acapy_agent/anoncreds/default/did_indy/registry.py b/acapy_agent/anoncreds/default/did_indy/registry.py index 6bd6cae693..0234196571 100644 --- a/acapy_agent/anoncreds/default/did_indy/registry.py +++ b/acapy_agent/anoncreds/default/did_indy/registry.py @@ -42,7 +42,7 @@ def supported_identifiers_regex(self) -> Pattern: async def setup(self, context: InjectionContext): """Setup.""" - print("Successfully registered DIDIndyRegistry") + LOGGER.info("Successfully registered DIDIndyRegistry") async def get_schema(self, profile: Profile, schema_id: str) -> GetSchemaResult: """Get a schema from the registry.""" diff --git a/acapy_agent/anoncreds/default/did_web/registry.py b/acapy_agent/anoncreds/default/did_web/registry.py index 718b624842..4eeb0e710f 100644 --- a/acapy_agent/anoncreds/default/did_web/registry.py +++ b/acapy_agent/anoncreds/default/did_web/registry.py @@ -1,5 +1,6 @@ """DID Web Registry.""" +import logging import re from typing import Optional, Pattern, Sequence @@ -18,6 +19,8 @@ from ...models.schema import AnonCredsSchema, GetSchemaResult, SchemaResult from ...models.schema_info import AnoncredsSchemaInfo +LOGGER = logging.getLogger(__name__) + class DIDWebRegistry(BaseAnonCredsResolver, BaseAnonCredsRegistrar): """DIDWebRegistry.""" @@ -41,7 +44,7 @@ def supported_identifiers_regex(self) -> Pattern: async def setup(self, context: InjectionContext): """Setup.""" - print("Successfully registered DIDWebRegistry") + LOGGER.info("Successfully registered DIDWebRegistry") async def get_schema(self, profile, schema_id: str) -> GetSchemaResult: """Get a schema from the registry.""" diff --git a/acapy_agent/anoncreds/default/legacy_indy/registry.py b/acapy_agent/anoncreds/default/legacy_indy/registry.py index aad288d053..950ce434a6 100644 --- a/acapy_agent/anoncreds/default/legacy_indy/registry.py +++ b/acapy_agent/anoncreds/default/legacy_indy/registry.py @@ -145,7 +145,7 @@ def supported_identifiers_regex(self) -> Pattern: async def setup(self, context: InjectionContext): """Setup.""" - print("Successfully registered LegacyIndyRegistry") + LOGGER.info("Successfully registered LegacyIndyRegistry") @staticmethod def make_schema_id(schema: AnonCredsSchema) -> str: diff --git a/acapy_agent/commands/provision.py b/acapy_agent/commands/provision.py index a463dd6e48..6d86d412b6 100644 --- a/acapy_agent/commands/provision.py +++ b/acapy_agent/commands/provision.py @@ -1,6 +1,7 @@ """Provision command for setting up agent settings before starting.""" import asyncio +import logging from typing import Sequence from configargparse import ArgumentParser @@ -22,6 +23,8 @@ from ..storage.base import BaseStorage from . import PROG +LOGGER = logging.getLogger(__name__) + class ProvisionError(BaseError): """Base exception for provisioning errors.""" @@ -58,9 +61,9 @@ async def provision(settings: dict): ) if await ledger_config(root_profile, public_did and public_did.did, True): - print("Ledger configured") + LOGGER.info("Ledger configured") else: - print("Ledger not configured") + LOGGER.warning("Ledger not configured") await root_profile.close() except BaseError as e: diff --git a/acapy_agent/commands/start.py b/acapy_agent/commands/start.py index f30fc5c582..ee256f1e4c 100644 --- a/acapy_agent/commands/start.py +++ b/acapy_agent/commands/start.py @@ -31,7 +31,7 @@ async def start_app(conductor: Conductor): async def shutdown_app(conductor: Conductor): """Shut down.""" - print("\nShutting down") + LOGGER.warning("Shutting down") await conductor.stop() @@ -59,7 +59,7 @@ def execute(argv: Sequence[str] = None): # Run the application if uvloop: uvloop.install() - print("uvloop installed") + LOGGER.info("uvloop installed") run_loop(start_app(conductor), shutdown_app(conductor)) diff --git a/acapy_agent/config/wallet.py b/acapy_agent/config/wallet.py index ce5beb8fc3..24a523b785 100644 --- a/acapy_agent/config/wallet.py +++ b/acapy_agent/config/wallet.py @@ -62,11 +62,11 @@ async def wallet_config( if provision: if profile.created: - print("Created new profile") + LOGGER.info("Created new profile") else: - print("Opened existing profile") - print("Profile backend:", profile.backend) - print("Profile name:", profile.name) + LOGGER.info("Opened existing profile") + LOGGER.info("Profile backend:", profile.backend) + LOGGER.info("Profile name:", profile.name) wallet_seed = context.settings.get("wallet.seed") wallet_local_did = context.settings.get("wallet.local_did") @@ -85,8 +85,8 @@ async def wallet_config( ) public_did = replace_did_info.did await wallet.set_public_did(public_did) - print(f"Created new public DID: {public_did}") - print(f"Verkey: {replace_did_info.verkey}") + LOGGER.info(f"Created new public DID: {public_did}") + LOGGER.info(f"Verkey: {replace_did_info.verkey}") else: # If we already have a registered public did and it doesn't match # the one derived from `wallet_seed` then we error out. @@ -108,20 +108,20 @@ async def wallet_config( ) local_did = local_did_info.did if provision: - print(f"Created new local DID: {local_did}") - print(f"Verkey: {local_did_info.verkey}") + LOGGER.info(f"Created new local DID: {local_did}") + LOGGER.info(f"Verkey: {local_did_info.verkey}") else: public_did_info = await wallet.create_public_did( method=SOV, key_type=ED25519, seed=wallet_seed ) public_did = public_did_info.did if provision: - print(f"Created new public DID: {public_did}") - print(f"Verkey: {public_did_info.verkey}") + LOGGER.info(f"Created new public DID: {public_did}") + LOGGER.info(f"Verkey: {public_did_info.verkey}") # wait until ledger config to set public DID endpoint - wallet goes first if provision and not wallet_local_did and not public_did: - print("No public DID") + LOGGER.info("No public DID") # Debug settings test_seed = context.settings.get("debug.seed") diff --git a/acapy_agent/transport/v2_pack_format.py b/acapy_agent/transport/v2_pack_format.py index 266c0b8b08..92e26da698 100644 --- a/acapy_agent/transport/v2_pack_format.py +++ b/acapy_agent/transport/v2_pack_format.py @@ -63,8 +63,7 @@ async def parse_message( try: message_unpack = await messaging.unpack(message_json) except CryptoServiceError: - LOGGER.debug("Message unpack failed, falling back to JSON") - print("HIT CRTYPTO SER ERR EXCEPT BLOC") + LOGGER.info("Message unpack failed, falling back to JSON") else: # Set message_dict to be the dictionary that we unpacked message_dict = message_unpack.message diff --git a/acapy_agent/vc/vc_di/prove.py b/acapy_agent/vc/vc_di/prove.py index 33c94fa544..acba4359fe 100644 --- a/acapy_agent/vc/vc_di/prove.py +++ b/acapy_agent/vc/vc_di/prove.py @@ -1,6 +1,7 @@ """Verifiable Credential and Presentation proving methods.""" import asyncio +import logging import re from hashlib import sha256 from typing import Any, Optional, Tuple @@ -20,6 +21,8 @@ from ...core.profile import Profile from ..ld_proofs import LinkedDataProofException, ProofPurpose +LOGGER = logging.getLogger(__name__) + async def create_signed_anoncreds_presentation( *, @@ -311,7 +314,7 @@ async def prepare_data_for_presentation( # issuer_id = field["filter"]["const"] pass else: - print("... skipping:", path) + LOGGER.info("... skipping: %s", path) return anoncreds_proofrequest, w3c_creds_metadata diff --git a/acapy_agent/wallet/crypto.py b/acapy_agent/wallet/crypto.py index 0ceef63a91..37ddeb7a13 100644 --- a/acapy_agent/wallet/crypto.py +++ b/acapy_agent/wallet/crypto.py @@ -1,5 +1,6 @@ """Cryptography functions used by BasicWallet.""" +import logging import re from collections import OrderedDict from typing import Callable, List, Optional, Sequence, Tuple, Union @@ -20,6 +21,8 @@ from .key_type import BLS12381G2, ED25519, KeyType from .util import b58_to_bytes, b64_to_bytes, bytes_to_b58, random_seed +LOGGER = logging.getLogger(__name__) + def create_keypair( key_type: KeyType, seed: Optional[bytes] = None @@ -423,7 +426,7 @@ def decode_pack_message_outer(enc_message: bytes) -> Tuple[dict, dict, bool]: try: wrapper = JweEnvelope.from_json(enc_message) except ValidationError as err: - print(err) + LOGGER.error(err) raise ValueError("Invalid packed message") alg = wrapper.protected.get("alg") From 6964339dd5c7070e4457f17863f91cf1ec840e42 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 13:05:40 +0200 Subject: [PATCH 16/51] :loud_sound: Expand logging for Conductor setup Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 49 ++++++++++++++++++++++++++++++++--- 1 file changed, 45 insertions(+), 4 deletions(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index 57fd69569b..c3788c66d6 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -119,41 +119,62 @@ def context(self) -> InjectionContext: async def setup(self): """Initialize the global request context.""" + LOGGER.debug("Starting setup of the Conductor") context = await self.context_builder.build_context() + LOGGER.debug("Context built successfully") if self.force_agent_anoncreds: + LOGGER.debug( + "Force agent anoncreds is enabled. " + "Setting wallet type to 'askar-anoncreds'." + ) context.settings.set_value("wallet.type", "askar-anoncreds") # Fetch genesis transactions if necessary if context.settings.get("ledger.ledger_config_list"): + LOGGER.debug( + "Ledger config list found. Loading multiple genesis transactions" + ) await load_multiple_genesis_transactions_from_config(context.settings) if ( context.settings.get("ledger.genesis_transactions") or context.settings.get("ledger.genesis_file") or context.settings.get("ledger.genesis_url") ): + LOGGER.debug( + "Genesis transactions/configurations found. Fetching genesis transactions" + ) await get_genesis_transactions(context.settings) # Configure the root profile + LOGGER.debug("Configuring the root profile and setting up public DID") self.root_profile, self.setup_public_did = await wallet_config(context) context = self.root_profile.context + LOGGER.debug("Root profile configured successfully") # Multiledger Setup if ( context.settings.get("ledger.ledger_config_list") and len(context.settings.get("ledger.ledger_config_list")) > 0 ): + LOGGER.debug("Setting up multiledger manager") context.injector.bind_provider( BaseMultipleLedgerManager, MultiIndyLedgerManagerProvider(self.root_profile), ) if not (context.settings.get("ledger.genesis_transactions")): ledger = context.injector.inject(BaseLedger) + LOGGER.debug( + "Ledger backend: %s, Profile backend: %s", + ledger.BACKEND_NAME, + self.root_profile.BACKEND_NAME, + ) if ( self.root_profile.BACKEND_NAME == "askar" and ledger.BACKEND_NAME == "indy-vdr" ): + LOGGER.debug("Binding IndyCredxVerifier for 'askar' backend.") context.injector.bind_provider( IndyVerifier, ClassProvider( @@ -165,6 +186,9 @@ async def setup(self): self.root_profile.BACKEND_NAME == "askar-anoncreds" and ledger.BACKEND_NAME == "indy-vdr" ): + LOGGER.debug( + "Binding IndyCredxVerifier for 'askar-anoncreds' backend." + ) context.injector.bind_provider( IndyVerifier, ClassProvider( @@ -173,6 +197,7 @@ async def setup(self): ), ) else: + LOGGER.error("Unsupported ledger backend for multiledger setup.") raise MultipleLedgerManagerError( "Multiledger is supported only for Indy SDK or Askar " "[Indy VDR] profile" @@ -185,10 +210,13 @@ async def setup(self): if not await ledger_config( self.root_profile, self.setup_public_did and self.setup_public_did.did ): - LOGGER.warning("No ledger configured") + LOGGER.warning("No ledger configured.") + else: + LOGGER.debug("Ledger configured successfully.") if not context.settings.get("transport.disabled"): # Register all inbound transports if enabled + LOGGER.debug("Transport not disabled. Setting up inbound transports.") self.inbound_transport_manager = InboundTransportManager( self.root_profile, self.inbound_message_router, self.handle_not_returned ) @@ -196,45 +224,55 @@ async def setup(self): context.injector.bind_instance( InboundTransportManager, self.inbound_transport_manager ) + LOGGER.debug("Inbound transports registered successfully.") if not context.settings.get("transport.disabled"): # Register all outbound transports + LOGGER.debug("Transport not disabled. Setting up outbound transports.") self.outbound_transport_manager = OutboundTransportManager( self.root_profile, self.handle_not_delivered ) await self.outbound_transport_manager.setup() + LOGGER.debug("Outbound transports registered successfully.") # Initialize dispatcher + LOGGER.debug("Initializing dispatcher.") self.dispatcher = Dispatcher(self.root_profile) await self.dispatcher.setup() + LOGGER.debug("Dispatcher initialized successfully.") wire_format = context.inject_or(BaseWireFormat) if wire_format and hasattr(wire_format, "task_queue"): wire_format.task_queue = self.dispatcher.task_queue + LOGGER.debug("Wire format task queue bound to dispatcher.") # Bind manager for multitenancy related tasks if context.settings.get("multitenant.enabled"): + LOGGER.debug("Multitenant is enabled. Binding MultitenantManagerProvider.") context.injector.bind_provider( BaseMultitenantManager, MultitenantManagerProvider(self.root_profile) ) # Bind route manager provider + LOGGER.debug("Binding RouteManagerProvider.") context.injector.bind_provider( RouteManager, RouteManagerProvider(self.root_profile) ) - # Bind oob message processor to be able to receive and process un-encrypted - # messages + # Bind oob message processor to be able to receive and process un-encrypted messages + LOGGER.debug("Binding OobMessageProcessor.") context.injector.bind_instance( OobMessageProcessor, OobMessageProcessor(inbound_message_router=self.inbound_message_router), ) # Bind default PyLD document loader + LOGGER.debug("Binding default DocumentLoader.") context.injector.bind_instance(DocumentLoader, DocumentLoader(self.root_profile)) # Admin API if context.settings.get("admin.enabled"): + LOGGER.debug("Admin API is enabled. Attempting to register admin server.") try: admin_host = context.settings.get("admin.host", "0.0.0.0") admin_port = context.settings.get("admin.port", "80") @@ -250,13 +288,15 @@ async def setup(self): self.get_stats, ) context.injector.bind_instance(BaseAdminServer, self.admin_server) + LOGGER.debug("Admin server registered on %s:%s.", admin_host, admin_port) except Exception: - LOGGER.exception("Unable to register admin server") + LOGGER.exception("Unable to register admin server.") raise # Fetch stats collector, if any collector = context.inject_or(Collector) if collector: + LOGGER.debug("Stats collector found. Wrapping methods for collection.") # add stats to our own methods collector.wrap( self, @@ -275,6 +315,7 @@ async def setup(self): "find_inbound_connection", ), ) + LOGGER.debug("Methods wrapped with stats collector.") async def start(self) -> None: """Start the agent.""" From dddae7063aaa4cdd35d1aec9045e09e41809afec Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 13:30:26 +0200 Subject: [PATCH 17/51] :art: Correct to uphold previous "Module doesn't exist" log behaviour Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index b4094e4e19..e1743afb0c 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -125,6 +125,7 @@ def register_plugin(self, module_name: str) -> Optional[ModuleType]: mod = self._load_module(module_name) if not mod: + LOGGER.error("Module doesn't exist: %s", module_name) return None if self._is_valid_plugin(mod, module_name): @@ -153,7 +154,6 @@ def _load_module(self, module_name: str) -> Optional[ModuleType]: """Load the plugin module using ClassLoader.""" try: mod = ClassLoader.load_module(module_name) - LOGGER.debug("Successfully loaded module: %s", module_name) return mod except ModuleLoadError as e: LOGGER.error("Error loading plugin module '%s': %s", module_name, e) From 0119934e4b24c1d7d6fe5118720660bb9366b75f Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 13:51:54 +0200 Subject: [PATCH 18/51] Revert ":art: Rename method and remove redundant main call" This reverts commit 2f6526d108b3a8df527d2694c9ce3c46e438f963. Signed-off-by: ff137 --- acapy_agent/commands/provision.py | 11 ++++++++--- acapy_agent/commands/tests/test_provision.py | 20 +++++++------------- 2 files changed, 15 insertions(+), 16 deletions(-) diff --git a/acapy_agent/commands/provision.py b/acapy_agent/commands/provision.py index 6d86d412b6..f0fb7cf561 100644 --- a/acapy_agent/commands/provision.py +++ b/acapy_agent/commands/provision.py @@ -70,7 +70,7 @@ async def provision(settings: dict): raise ProvisionError("Error during provisioning") from e -def execute_provision(argv: Sequence[str] = None): +def execute(argv: Sequence[str] = None): """Entrypoint.""" parser = arg.create_argument_parser(prog=PROG) parser.prog += " provision" @@ -87,5 +87,10 @@ def execute_provision(argv: Sequence[str] = None): loop.run_until_complete(provision(settings)) -if __name__ == "__main__": - execute_provision() +def main(): + """Execute the main line.""" + if __name__ == "__main__": + execute() + + +main() diff --git a/acapy_agent/commands/tests/test_provision.py b/acapy_agent/commands/tests/test_provision.py index 8453222557..27da42cfd4 100644 --- a/acapy_agent/commands/tests/test_provision.py +++ b/acapy_agent/commands/tests/test_provision.py @@ -14,10 +14,10 @@ class TestProvision(IsolatedAsyncioTestCase): def test_bad_calls(self): with self.assertRaises(ArgsParseError): - test_module.execute_provision([]) + test_module.execute([]) with self.assertRaises(SystemExit): - test_module.execute_provision(["bad"]) + test_module.execute(["bad"]) async def test_provision_ledger_configured(self): profile = mock.MagicMock(close=mock.CoroutineMock()) @@ -46,17 +46,11 @@ async def test_provision_config_x(self): with self.assertRaises(test_module.ProvisionError): await test_module.provision({}) - def test_main_entry_point(self): - """Test that the execute_provision function is called when the module is run as main.""" - with ( - mock.patch.object(test_module, "__name__", "__main__"), - mock.patch.object( - test_module, "execute_provision", mock.MagicMock() - ) as mock_execute, - ): - import importlib - - importlib.reload(test_module) # Reload the module to trigger the main guard + def test_main(self): + with mock.patch.object(test_module, "__name__", "__main__"), mock.patch.object( + test_module, "execute", mock.MagicMock() + ) as mock_execute: + test_module.main() mock_execute.assert_called_once async def test_provision_should_store_provided_mediation_invite(self): From 8c69f3cb5e043a25d46e1a74662ee6e7b04ef215 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 13:55:19 +0200 Subject: [PATCH 19/51] :art: Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 2 +- acapy_agent/core/plugin_registry.py | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index c3788c66d6..b930cfa787 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -259,7 +259,7 @@ async def setup(self): RouteManager, RouteManagerProvider(self.root_profile) ) - # Bind oob message processor to be able to receive and process un-encrypted messages + # Bind OobMessageProcessor to be able to receive and process unencrypted messages LOGGER.debug("Binding OobMessageProcessor.") context.injector.bind_instance( OobMessageProcessor, diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index e1743afb0c..08f4edb2bd 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -422,7 +422,7 @@ def post_process_routes(self, app) -> None: continue if mod and hasattr(mod, "post_process_routes"): - LOGGER.debug("Post-processing routes from: %s", version_path) + LOGGER.debug("Post-processing routes for %s", plugin_name) mod.post_process_routes(app) def __repr__(self) -> str: From 5f387674adcf2c9a2355f601d38aeef6b1f34dd1 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 14:15:39 +0200 Subject: [PATCH 20/51] :white_check_mark: Fix test by adding __name__ to mock object Signed-off-by: ff137 --- acapy_agent/core/tests/test_plugin_registry.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/acapy_agent/core/tests/test_plugin_registry.py b/acapy_agent/core/tests/test_plugin_registry.py index b5727a4546..4e870fbdfb 100644 --- a/acapy_agent/core/tests/test_plugin_registry.py +++ b/acapy_agent/core/tests/test_plugin_registry.py @@ -537,6 +537,7 @@ async def test_load_protocols_load_mod(self): mock_mod = mock.MagicMock() mock_mod.MESSAGE_TYPES = mock.MagicMock() mock_mod.CONTROLLERS = mock.MagicMock() + mock_mod.__name__ = "test_mod" with mock.patch.object( ClassLoader, "load_module", mock.MagicMock() @@ -595,6 +596,7 @@ async def test_load_protocols_no_mod_def_message_types(self): mock_mod = mock.MagicMock() mock_mod.MESSAGE_TYPES = mock.MagicMock() mock_mod.CONTROLLERS = mock.MagicMock() + mock_mod.__name__ = "test_mod" with mock.patch.object( ClassLoader, "load_module", mock.MagicMock() From 5314ec5ffc396e56c4a1b2e0205c51c48d13952a Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 14:17:10 +0200 Subject: [PATCH 21/51] :art: Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 13 ++++++------- acapy_agent/core/plugin_registry.py | 2 +- 2 files changed, 7 insertions(+), 8 deletions(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index b930cfa787..b96ae84daf 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -154,16 +154,14 @@ async def setup(self): LOGGER.debug("Root profile configured successfully") # Multiledger Setup - if ( - context.settings.get("ledger.ledger_config_list") - and len(context.settings.get("ledger.ledger_config_list")) > 0 - ): + ledger_config_list = context.settings.get("ledger.ledger_config_list") + if ledger_config_list and len(ledger_config_list) > 0: LOGGER.debug("Setting up multiledger manager") context.injector.bind_provider( BaseMultipleLedgerManager, MultiIndyLedgerManagerProvider(self.root_profile), ) - if not (context.settings.get("ledger.genesis_transactions")): + if not context.settings.get("ledger.genesis_transactions"): ledger = context.injector.inject(BaseLedger) LOGGER.debug( "Ledger backend: %s, Profile backend: %s", @@ -207,9 +205,10 @@ async def setup(self): ) # Configure the ledger - if not await ledger_config( + ledger_configured = await ledger_config( self.root_profile, self.setup_public_did and self.setup_public_did.did - ): + ) + if not ledger_configured: LOGGER.warning("No ledger configured.") else: LOGGER.debug("Ledger configured successfully.") diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 08f4edb2bd..cd4942ffa3 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -349,7 +349,7 @@ async def register_admin_routes(self, app) -> None: continue if mod and hasattr(mod, "register"): - LOGGER.debug("Registering routes from: %s", version_path) + LOGGER.debug("Registering routes for: %s", plugin_name) await mod.register(app) def register_protocol_events(self, context: InjectionContext) -> None: From fc3a9d56be9e08b1bd7ba8b35a4507897a0c9441 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 14:59:43 +0200 Subject: [PATCH 22/51] :sparkles: Add custom trace log level Signed-off-by: ff137 --- acapy_agent/config/logging/configurator.py | 5 ++ acapy_agent/config/logging/utils.py | 98 ++++++++++++++++++++++ 2 files changed, 103 insertions(+) create mode 100644 acapy_agent/config/logging/utils.py diff --git a/acapy_agent/config/logging/configurator.py b/acapy_agent/config/logging/configurator.py index 680fb92c2e..2ca573e519 100644 --- a/acapy_agent/config/logging/configurator.py +++ b/acapy_agent/config/logging/configurator.py @@ -31,6 +31,11 @@ from .timed_rotating_file_multi_process_handler import ( TimedRotatingFileMultiProcessHandler, ) +from .utils import add_trace_level + + +# Add TRACE level to logging before any configuration +add_trace_level() def load_resource(path: str, encoding: Optional[str] = None): diff --git a/acapy_agent/config/logging/utils.py b/acapy_agent/config/logging/utils.py new file mode 100644 index 0000000000..20f76e00b7 --- /dev/null +++ b/acapy_agent/config/logging/utils.py @@ -0,0 +1,98 @@ +"""Logging utilities.""" + +import logging +from functools import partial, partialmethod +from typing import Optional + + +def add_logging_level( + level_name: str, level_num: int, method_name: Optional[str] = None +) -> None: + """Add a custom logging level to the `logging` module. + + Comprehensively adds a new logging level to the `logging` module and the + currently configured logging class. + + `level_name` becomes an attribute of the `logging` module with the value + `level_num`. + `methodName` becomes a convenience method for both `logging` itself + and the class returned by `logging.getLoggerClass()` (usually just + `logging.Logger`). + If `methodName` is not specified, `levelName.lower()` is used. + + To avoid accidental clobberings of existing attributes, this method will + raise an `AttributeError` if the level name is already an attribute of the + `logging` module or if the method name is already present + + Example: + ------- + >>> add_logging_level('TRACE', logging.DEBUG - 5) + >>> logging.getLogger(__name__).setLevel('TRACE') + >>> logging.getLogger(__name__).trace('that worked') + >>> logging.trace('so did this') + >>> logging.TRACE + 5 + + References: + - https://stackoverflow.com/a/35804945 + """ + if not method_name: + method_name = level_name.lower() + + if hasattr(logging, level_name): + raise AttributeError(f"{level_name} already defined in logging module") + if hasattr(logging, method_name): + raise AttributeError(f"{method_name} already defined in logging module") + if hasattr(logging.getLoggerClass(), method_name): + raise AttributeError(f"{method_name} already defined in logger class") + + # Add the new logging level + logging.addLevelName(level_num, level_name) + setattr(logging, level_name, level_num) + setattr( + logging.getLoggerClass(), + method_name, + partialmethod(logging.getLoggerClass().log, level_num), + ) + setattr(logging, method_name, partial(logging.log, level_num)) + + +def add_trace_level() -> None: + """Add the TRACE level to the logging module safely. + + This function adds a TRACE level to the logging module if it hasn't been added yet. + It handles the case where TRACE is already defined, avoiding duplicate additions. + + Returns: + None + """ + TRACE_LEVEL_NUM = logging.DEBUG - 5 + TRACE_LEVEL_NAME = "TRACE" + TRACE_METHOD_NAME = "trace" + + # Check if TRACE level is already defined + level_exists = ( + hasattr(logging, TRACE_LEVEL_NAME) + and getattr(logging, TRACE_LEVEL_NAME) == TRACE_LEVEL_NUM + ) + + method_exists = hasattr(logging, TRACE_METHOD_NAME) and callable( + getattr(logging, TRACE_METHOD_NAME) + ) + + if not level_exists or not method_exists: + try: + add_logging_level(TRACE_LEVEL_NAME, TRACE_LEVEL_NUM, TRACE_METHOD_NAME) + logging.getLogger(__name__).debug( + f"{TRACE_LEVEL_NAME} level added to logging module." + ) + except AttributeError as e: + # Log a warning if TRACE level already exists + logging.getLogger(__name__).warning( + f"{TRACE_LEVEL_NAME} level already exists: {e}" + ) + else: + # Optionally, you can log that TRACE level is already present + logging.getLogger(__name__).debug( + f"{TRACE_LEVEL_NAME} level is already present in the logging module." + ) From 059d25323f2b0a391cf8ae9142db31624d2534d1 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 15:00:11 +0200 Subject: [PATCH 23/51] :art: Ensure trace level can only be added once Signed-off-by: ff137 --- acapy_agent/config/logging/utils.py | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/acapy_agent/config/logging/utils.py b/acapy_agent/config/logging/utils.py index 20f76e00b7..e6527aa852 100644 --- a/acapy_agent/config/logging/utils.py +++ b/acapy_agent/config/logging/utils.py @@ -3,6 +3,7 @@ import logging from functools import partial, partialmethod from typing import Optional +_TRACE_LEVEL_ADDED = False def add_logging_level( @@ -66,6 +67,11 @@ def add_trace_level() -> None: Returns: None """ + global _TRACE_LEVEL_ADDED + + if _TRACE_LEVEL_ADDED: + return + TRACE_LEVEL_NUM = logging.DEBUG - 5 TRACE_LEVEL_NAME = "TRACE" TRACE_METHOD_NAME = "trace" @@ -96,3 +102,5 @@ def add_trace_level() -> None: logging.getLogger(__name__).debug( f"{TRACE_LEVEL_NAME} level is already present in the logging module." ) + + _TRACE_LEVEL_ADDED = True From 4f341384ec2ce994d2ba77e4f27ddc9fdf35b63d Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 15:00:22 +0200 Subject: [PATCH 24/51] :art: Add Logger Signed-off-by: ff137 --- acapy_agent/config/logging/utils.py | 14 ++++++-------- 1 file changed, 6 insertions(+), 8 deletions(-) diff --git a/acapy_agent/config/logging/utils.py b/acapy_agent/config/logging/utils.py index e6527aa852..5ee6108607 100644 --- a/acapy_agent/config/logging/utils.py +++ b/acapy_agent/config/logging/utils.py @@ -3,6 +3,8 @@ import logging from functools import partial, partialmethod from typing import Optional + +LOGGER = logging.getLogger(__name__) _TRACE_LEVEL_ADDED = False @@ -89,18 +91,14 @@ def add_trace_level() -> None: if not level_exists or not method_exists: try: add_logging_level(TRACE_LEVEL_NAME, TRACE_LEVEL_NUM, TRACE_METHOD_NAME) - logging.getLogger(__name__).debug( - f"{TRACE_LEVEL_NAME} level added to logging module." - ) + LOGGER.debug("%s level added to logging module.", TRACE_LEVEL_NAME) except AttributeError as e: # Log a warning if TRACE level already exists - logging.getLogger(__name__).warning( - f"{TRACE_LEVEL_NAME} level already exists: {e}" - ) + LOGGER.warning("%s level already exists: %s", TRACE_LEVEL_NAME, e) else: # Optionally, you can log that TRACE level is already present - logging.getLogger(__name__).debug( - f"{TRACE_LEVEL_NAME} level is already present in the logging module." + LOGGER.debug( + "%s level is already present in the logging module.", TRACE_LEVEL_NAME ) _TRACE_LEVEL_ADDED = True From ea66fb190d042da6c3614c2ab5b988872cafce1c Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 15:08:53 +0200 Subject: [PATCH 25/51] :art: Update newly added logs to be trace level instead of debug Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 78 +++++++++++++++-------------- 1 file changed, 40 insertions(+), 38 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index cd4942ffa3..f86495291e 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -6,6 +6,7 @@ from typing import Optional, Sequence, Set from ..config.injection_context import InjectionContext +from ..config.logging.utils import add_trace_level from ..core.event_bus import EventBus from ..utils.classloader import ClassLoader, ModuleLoadError from .error import ProtocolDefinitionValidationError @@ -13,6 +14,7 @@ from .protocol_registry import ProtocolRegistry LOGGER = logging.getLogger(__name__) +add_trace_level() # Allow trace logs from this module class PluginRegistry: @@ -130,7 +132,7 @@ def register_plugin(self, module_name: str) -> Optional[ModuleType]: if self._is_valid_plugin(mod, module_name): self._plugins[module_name] = mod - LOGGER.debug("Registered plugin: %s", module_name) + LOGGER.trace("Registered plugin: %s", module_name) return mod LOGGER.debug("Failed to register plugin: %s", module_name) @@ -139,7 +141,7 @@ def register_plugin(self, module_name: str) -> Optional[ModuleType]: def _is_already_registered(self, module_name: str) -> bool: """Check if the plugin is already registered.""" if module_name in self._plugins: - LOGGER.debug("Plugin %s is already registered.", module_name) + LOGGER.trace("Plugin %s is already registered.", module_name) return True return False @@ -163,7 +165,7 @@ 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) + LOGGER.trace("Plugin %s has a 'setup' method.", module_name) return True # Check for 'routes' or 'message_types' modules @@ -172,7 +174,7 @@ 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) + LOGGER.trace("Plugin %s has 'routes' or 'message_types'.", module_name) return True # Check for 'definition' module with 'versions' attribute @@ -194,7 +196,7 @@ 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) + LOGGER.trace("Plugin %s has valid versions.", module_name) return True except ProtocolDefinitionValidationError as e: LOGGER.error( @@ -206,7 +208,7 @@ def _is_valid_plugin(self, mod: ModuleType, module_name: str) -> bool: def register_package(self, package_name: str) -> Sequence[ModuleType]: """Register all modules (sub-packages) under a given package name.""" - LOGGER.debug("Registering package: %s", package_name) + LOGGER.trace("Registering package: %s", package_name) try: module_names = ClassLoader.scan_subpackages(package_name) except ModuleLoadError: @@ -217,28 +219,28 @@ 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) + LOGGER.trace("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.trace("Failed to register %s under %s", module_name, package_name) return registered_plugins async def init_context(self, context: InjectionContext) -> None: """Call plugin setup methods on the current context.""" - LOGGER.debug("Initializing plugin context for %d plugins", len(self._plugins)) + LOGGER.trace("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) + LOGGER.trace("Running setup for plugin: %s", plugin_name) await plugin.setup(context) else: - LOGGER.debug( + LOGGER.trace( "Loading protocols for plugin without setup: %s", plugin_name ) await self.load_protocols(context, plugin) @@ -257,55 +259,55 @@ async def load_protocol_version( goal_code_registry = context.inject(GoalCodeRegistry) module_name = mod.__name__ - LOGGER.debug("Loading protocol version for module: %s", module_name) + LOGGER.trace("Loading protocol version for module: %s", module_name) if hasattr(mod, "MESSAGE_TYPES"): - LOGGER.debug("Registering message types for: %s", module_name) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("Loading message types from: %s", version_path) mod = ClassLoader.load_module(version_path) await self.load_protocol_version(context, mod, protocol_version) except ModuleLoadError as e: @@ -318,20 +320,20 @@ async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> async def register_admin_routes(self, app) -> None: """Call route registration methods on the current context.""" - LOGGER.debug("Registering admin routes for %d plugins", len(self._plugins)) + LOGGER.trace("Registering admin routes for %d plugins", len(self._plugins)) for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.debug("Processing routes for plugin: %s", plugin_name) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("Loading routes from: %s", version_path) mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: LOGGER.error( @@ -342,19 +344,19 @@ async def register_admin_routes(self, app) -> None: # 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) + LOGGER.trace("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) + LOGGER.trace("Registering routes for: %s", plugin_name) await mod.register(app) def register_protocol_events(self, context: InjectionContext) -> None: """Call route register_events methods on the current context.""" - LOGGER.debug("Registering protocol events for %d plugins", len(self._plugins)) + LOGGER.trace("Registering protocol events for %d plugins", len(self._plugins)) event_bus = context.inject_or(EventBus) if not event_bus: @@ -363,16 +365,16 @@ 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) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("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) @@ -381,32 +383,32 @@ def register_protocol_events(self, context: InjectionContext) -> None: # 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) + LOGGER.trace("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) + LOGGER.trace("Registering events from: %s", version_path) mod.register_events(event_bus) def post_process_routes(self, app) -> None: """Call route binary file response OpenAPI fixups if applicable.""" - LOGGER.debug("Post-processing routes for %d plugins", len(self._plugins)) + LOGGER.trace("Post-processing routes for %d plugins", len(self._plugins)) for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.debug("Post-processing routes for plugin: %s", plugin_name) + LOGGER.trace("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) + LOGGER.trace("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) + LOGGER.trace("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) @@ -415,14 +417,14 @@ def post_process_routes(self, app) -> None: # 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) + LOGGER.trace("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) + LOGGER.trace("Post-processing routes for %s", plugin_name) mod.post_process_routes(app) def __repr__(self) -> str: From 0f415558746fdcfc9d41913e6c455a584315e7c0 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 15:14:10 +0200 Subject: [PATCH 26/51] :art: Update newly added logs to be trace level instead of debug Signed-off-by: ff137 --- acapy_agent/config/default_context.py | 20 +++++++------ acapy_agent/core/conductor.py | 41 +++++++++++++-------------- 2 files changed, 31 insertions(+), 30 deletions(-) diff --git a/acapy_agent/config/default_context.py b/acapy_agent/config/default_context.py index 4ceb81933a..5efa7bdfc5 100644 --- a/acapy_agent/config/default_context.py +++ b/acapy_agent/config/default_context.py @@ -5,6 +5,7 @@ from ..anoncreds.registry import AnonCredsRegistry from ..cache.base import BaseCache from ..cache.in_memory import InMemoryCache +from ..config.logging.utils import add_trace_level from ..connections.base_manager import BaseConnectionManager from ..core.event_bus import EventBus from ..core.goal_code_registry import GoalCodeRegistry @@ -30,6 +31,7 @@ from .provider import CachedProvider, ClassProvider LOGGER = logging.getLogger(__name__) +add_trace_level() # Allow trace logs from this module class DefaultContextBuilder(ContextBuilder): @@ -37,14 +39,14 @@ class DefaultContextBuilder(ContextBuilder): async def build_context(self) -> InjectionContext: """Build the base injection context; set DIDComm prefix to emit.""" - LOGGER.debug("Building new injection context with settings: %s", self.settings) + LOGGER.trace("Building new injection context with settings: %s", self.settings) context = InjectionContext(settings=self.settings) context.settings.set_default("default_label", "Aries Cloud Agent") if context.settings.get("timing.enabled"): timing_log = context.settings.get("timing.log_file") - LOGGER.debug("Enabling timing collector with log file: %s", timing_log) + LOGGER.trace("Enabling timing collector with log file: %s", timing_log) collector = Collector(log_path=timing_log) context.injector.bind_instance(Collector, collector) @@ -86,13 +88,13 @@ async def build_context(self) -> InjectionContext: async def bind_providers(self, context: InjectionContext): """Bind various class providers.""" - LOGGER.debug("Begin binding providers to context") + LOGGER.trace("Begin binding providers to context") context.injector.bind_provider(ProfileManager, ProfileManagerProvider()) wallet_type = self.settings.get("wallet.type") if wallet_type == "askar-anoncreds": - LOGGER.debug("Using AnonCreds tails server") + LOGGER.trace("Using AnonCreds tails server") context.injector.bind_provider( BaseTailsServer, ClassProvider( @@ -100,7 +102,7 @@ async def bind_providers(self, context: InjectionContext): ), ) else: - LOGGER.debug("Using Indy tails server") + LOGGER.trace("Using Indy tails server") context.injector.bind_provider( BaseTailsServer, ClassProvider( @@ -129,7 +131,7 @@ async def bind_providers(self, context: InjectionContext): async def load_plugins(self, context: InjectionContext): """Set up plugin registry and load plugins.""" - LOGGER.debug("Initializing plugin registry") + LOGGER.trace("Initializing plugin registry") plugin_registry = PluginRegistry( blocklist=self.settings.get("blocked_plugins", []) ) @@ -170,7 +172,7 @@ async def load_plugins(self, context: InjectionContext): def register_plugins(plugins: list[str], plugin_type: str): """Register a group of plugins with logging.""" - LOGGER.debug("Registering %s plugins", plugin_type) + LOGGER.trace("Registering %s plugins", plugin_type) for plugin in plugins: plugin_registry.register_plugin(plugin) @@ -183,7 +185,7 @@ def register_anoncreds_plugins(): register_plugins(default_plugins, "default") if context.settings.get("multitenant.admin_enabled"): - LOGGER.debug("Multitenant admin enabled - registering additional plugins") + LOGGER.trace("Multitenant admin enabled - registering additional plugins") plugin_registry.register_plugin("acapy_agent.multitenant.admin") register_askar_plugins() register_anoncreds_plugins() @@ -195,7 +197,7 @@ def register_anoncreds_plugins(): # Register external plugins for plugin_path in self.settings.get("external_plugins", []): - LOGGER.debug("Registering external plugin: %s", plugin_path) + LOGGER.trace("Registering external plugin: %s", plugin_path) plugin_registry.register_plugin(plugin_path) # Register message protocols diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index b96ae84daf..ea5f88c32f 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -122,7 +122,7 @@ async def setup(self): LOGGER.debug("Starting setup of the Conductor") context = await self.context_builder.build_context() - LOGGER.debug("Context built successfully") + LOGGER.trace("Context built successfully") if self.force_agent_anoncreds: LOGGER.debug( @@ -148,15 +148,15 @@ async def setup(self): await get_genesis_transactions(context.settings) # Configure the root profile - LOGGER.debug("Configuring the root profile and setting up public DID") + LOGGER.trace("Configuring the root profile and setting up public DID") self.root_profile, self.setup_public_did = await wallet_config(context) context = self.root_profile.context - LOGGER.debug("Root profile configured successfully") + LOGGER.trace("Root profile configured successfully") # Multiledger Setup ledger_config_list = context.settings.get("ledger.ledger_config_list") if ledger_config_list and len(ledger_config_list) > 0: - LOGGER.debug("Setting up multiledger manager") + LOGGER.trace("Setting up multiledger manager") context.injector.bind_provider( BaseMultipleLedgerManager, MultiIndyLedgerManagerProvider(self.root_profile), @@ -172,7 +172,7 @@ async def setup(self): self.root_profile.BACKEND_NAME == "askar" and ledger.BACKEND_NAME == "indy-vdr" ): - LOGGER.debug("Binding IndyCredxVerifier for 'askar' backend.") + LOGGER.trace("Binding IndyCredxVerifier for 'askar' backend.") context.injector.bind_provider( IndyVerifier, ClassProvider( @@ -184,7 +184,7 @@ async def setup(self): self.root_profile.BACKEND_NAME == "askar-anoncreds" and ledger.BACKEND_NAME == "indy-vdr" ): - LOGGER.debug( + LOGGER.trace( "Binding IndyCredxVerifier for 'askar-anoncreds' backend." ) context.injector.bind_provider( @@ -223,55 +223,54 @@ async def setup(self): context.injector.bind_instance( InboundTransportManager, self.inbound_transport_manager ) - LOGGER.debug("Inbound transports registered successfully.") + LOGGER.trace("Inbound transports registered successfully.") - if not context.settings.get("transport.disabled"): # Register all outbound transports - LOGGER.debug("Transport not disabled. Setting up outbound transports.") + LOGGER.debug("Setting up outbound transports.") self.outbound_transport_manager = OutboundTransportManager( self.root_profile, self.handle_not_delivered ) await self.outbound_transport_manager.setup() - LOGGER.debug("Outbound transports registered successfully.") + LOGGER.trace("Outbound transports registered successfully.") # Initialize dispatcher - LOGGER.debug("Initializing dispatcher.") + LOGGER.trace("Initializing dispatcher.") self.dispatcher = Dispatcher(self.root_profile) await self.dispatcher.setup() - LOGGER.debug("Dispatcher initialized successfully.") + LOGGER.trace("Dispatcher initialized successfully.") wire_format = context.inject_or(BaseWireFormat) if wire_format and hasattr(wire_format, "task_queue"): wire_format.task_queue = self.dispatcher.task_queue - LOGGER.debug("Wire format task queue bound to dispatcher.") + LOGGER.trace("Wire format task queue bound to dispatcher.") # Bind manager for multitenancy related tasks if context.settings.get("multitenant.enabled"): - LOGGER.debug("Multitenant is enabled. Binding MultitenantManagerProvider.") + LOGGER.trace("Multitenant is enabled. Binding MultitenantManagerProvider.") context.injector.bind_provider( BaseMultitenantManager, MultitenantManagerProvider(self.root_profile) ) # Bind route manager provider - LOGGER.debug("Binding RouteManagerProvider.") + LOGGER.trace("Binding RouteManagerProvider.") context.injector.bind_provider( RouteManager, RouteManagerProvider(self.root_profile) ) # Bind OobMessageProcessor to be able to receive and process unencrypted messages - LOGGER.debug("Binding OobMessageProcessor.") + LOGGER.trace("Binding OobMessageProcessor.") context.injector.bind_instance( OobMessageProcessor, OobMessageProcessor(inbound_message_router=self.inbound_message_router), ) # Bind default PyLD document loader - LOGGER.debug("Binding default DocumentLoader.") + LOGGER.trace("Binding default DocumentLoader.") context.injector.bind_instance(DocumentLoader, DocumentLoader(self.root_profile)) # Admin API if context.settings.get("admin.enabled"): - LOGGER.debug("Admin API is enabled. Attempting to register admin server.") + LOGGER.trace("Admin API is enabled. Attempting to register admin server.") try: admin_host = context.settings.get("admin.host", "0.0.0.0") admin_port = context.settings.get("admin.port", "80") @@ -287,7 +286,7 @@ async def setup(self): self.get_stats, ) context.injector.bind_instance(BaseAdminServer, self.admin_server) - LOGGER.debug("Admin server registered on %s:%s.", admin_host, admin_port) + LOGGER.debug("Admin server registered on %s:%s", admin_host, admin_port) except Exception: LOGGER.exception("Unable to register admin server.") raise @@ -295,7 +294,7 @@ async def setup(self): # Fetch stats collector, if any collector = context.inject_or(Collector) if collector: - LOGGER.debug("Stats collector found. Wrapping methods for collection.") + LOGGER.trace("Stats collector found. Wrapping methods for collection.") # add stats to our own methods collector.wrap( self, @@ -314,7 +313,7 @@ async def setup(self): "find_inbound_connection", ), ) - LOGGER.debug("Methods wrapped with stats collector.") + LOGGER.trace("Methods wrapped with stats collector.") async def start(self) -> None: """Start the agent.""" From 641d3819745fb85f4679c645e9146c5a042e1965 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 15:22:01 +0200 Subject: [PATCH 27/51] :loud_sound: Expand logging for Conductor start and stop Signed-off-by: ff137 --- acapy_agent/commands/tests/test_provision.py | 7 +- acapy_agent/core/conductor.py | 91 +++++++++++++++++--- 2 files changed, 82 insertions(+), 16 deletions(-) diff --git a/acapy_agent/commands/tests/test_provision.py b/acapy_agent/commands/tests/test_provision.py index 27da42cfd4..ed50bb9eb8 100644 --- a/acapy_agent/commands/tests/test_provision.py +++ b/acapy_agent/commands/tests/test_provision.py @@ -47,9 +47,10 @@ async def test_provision_config_x(self): await test_module.provision({}) def test_main(self): - with mock.patch.object(test_module, "__name__", "__main__"), mock.patch.object( - test_module, "execute", mock.MagicMock() - ) as mock_execute: + with ( + mock.patch.object(test_module, "__name__", "__main__"), + mock.patch.object(test_module, "execute", mock.MagicMock()) as mock_execute, + ): test_module.main() mock_execute.assert_called_once diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index ea5f88c32f..b2dcb9e7fe 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -317,30 +317,37 @@ async def setup(self): async def start(self) -> None: """Start the agent.""" - + LOGGER.debug("Starting the Conductor agent.") assert self.root_profile, "root_profile is not set" context = self.root_profile.context await self.check_for_valid_wallet_type(self.root_profile) + LOGGER.trace("Wallet type validated.") if not context.settings.get("transport.disabled"): # Start up transports if enabled try: + LOGGER.trace("Transport not disabled. Starting inbound transports.") await self.inbound_transport_manager.start() + LOGGER.trace("Inbound transports started successfully.") except Exception: - LOGGER.exception("Unable to start inbound transports") + LOGGER.exception("Unable to start inbound transports.") raise try: + LOGGER.trace("Starting outbound transports.") await self.outbound_transport_manager.start() + LOGGER.trace("Outbound transports started successfully.") except Exception: - LOGGER.exception("Unable to start outbound transports") + LOGGER.exception("Unable to start outbound transports.") raise # Start up Admin server if self.admin_server: + LOGGER.trace("Admin server present. Starting admin server.") try: await self.admin_server.start() + LOGGER.debug("Admin server started successfully.") except Exception: - LOGGER.exception("Unable to start administration API") + LOGGER.exception("Unable to start administration API.") # Make admin responder available during message parsing # This allows webhooks to be called when a connection is marked active, # for example @@ -349,9 +356,11 @@ async def start(self) -> None: self.admin_server.outbound_message_router, ) context.injector.bind_instance(BaseResponder, responder) + LOGGER.trace("Admin responder bound to injector.") # Get agent label default_label = context.settings.get("default_label") + LOGGER.debug("Agent label: %s", default_label) if context.settings.get("transport.disabled"): LoggingConfigurator.print_banner( @@ -376,6 +385,7 @@ async def start(self) -> None: from_version_storage = None from_version = None agent_version = f"v{__version__}" + LOGGER.trace("Recording ACA-Py version in wallet if needed.") async with self.root_profile.session() as session: storage: BaseStorage = session.context.inject(BaseStorage) try: @@ -390,10 +400,16 @@ async def start(self) -> None: ) except StorageNotFoundError: LOGGER.warning("Wallet version storage record not found.") + from_version_config = self.root_profile.settings.get("upgrade.from_version") force_upgrade_flag = ( self.root_profile.settings.get("upgrade.force_upgrade") or False ) + LOGGER.trace( + "Force upgrade flag: %s, From version config: %s", + force_upgrade_flag, + from_version_config, + ) if force_upgrade_flag and from_version_config: if from_version_storage: @@ -405,8 +421,13 @@ async def start(self) -> None: from_version = from_version_storage else: from_version = from_version_config + LOGGER.trace( + "Determined from_version based on force_upgrade: %s", from_version + ) else: from_version = from_version_storage or from_version_config + LOGGER.trace("Determined from_version: %s", from_version) + if not from_version: LOGGER.warning( ( @@ -417,17 +438,27 @@ async def start(self) -> None: ) from_version = DEFAULT_ACAPY_VERSION self.root_profile.settings.set_value("upgrade.from_version", from_version) + LOGGER.trace("Set upgrade.from_version to default: %s", from_version) + config_available_list = get_upgrade_version_list( config_path=self.root_profile.settings.get("upgrade.config_path"), from_version=from_version, ) + LOGGER.trace("Available upgrade versions: %s", config_available_list) + if len(config_available_list) >= 1: + LOGGER.info("Upgrade configurations available. Initiating upgrade.") await upgrade(profile=self.root_profile) elif not (from_version_storage and from_version_storage == agent_version): + LOGGER.debug("No upgrades needed. Adding version record.") await add_version_record(profile=self.root_profile, version=agent_version) # Create a static connection for use by the test-suite if context.settings.get("debug.test_suite_endpoint"): + LOGGER.debug( + "Test suite endpoint configured. " + "Creating static connection for test suite." + ) mgr = BaseConnectionManager(self.root_profile) their_endpoint = context.settings["debug.test_suite_endpoint"] _, _, test_conn = await mgr.create_static_connection( @@ -443,26 +474,31 @@ async def start(self) -> None: f" - Their endpoint: {their_endpoint}\n" ) del mgr + LOGGER.debug("Static connection for test suite created and manager deleted.") # Clear default mediator if context.settings.get("mediation.clear"): + LOGGER.debug("Mediation clear flag set. Clearing default mediator.") mediation_mgr = MediationManager(self.root_profile) await mediation_mgr.clear_default_mediator() LOGGER.info("Default mediator cleared.") - # Clear default mediator # Set default mediator by id default_mediator_id = context.settings.get("mediation.default_id") if default_mediator_id: + LOGGER.debug("Setting default mediator to ID: %s", default_mediator_id) mediation_mgr = MediationManager(self.root_profile) try: await mediation_mgr.set_default_mediator_by_id(default_mediator_id) LOGGER.info(f"Default mediator set to {default_mediator_id}") except Exception: - LOGGER.exception("Error updating default mediator") + LOGGER.exception("Error updating default mediator.") # Print an invitation to the terminal if context.settings.get("debug.print_invitation"): + LOGGER.debug( + "Debug flag for printing invitation is set. Creating invitation." + ) try: mgr = OutOfBandManager(self.root_profile) invi_rec = await mgr.create_invitation( @@ -481,11 +517,13 @@ async def start(self) -> None: qr.add_data(invite_url) qr.print_ascii(invert=True) del mgr + LOGGER.trace("Invitation created and QR code printed.") except Exception: - LOGGER.exception("Error creating invitation") + LOGGER.exception("Error creating invitation.") # mediation connection establishment provided_invite: str = context.settings.get("mediation.invite") + LOGGER.debug("Mediation invite provided: %s", provided_invite) try: async with self.root_profile.session() as session: @@ -493,19 +531,28 @@ async def start(self) -> None: mediation_invite_record = await invite_store.get_mediation_invite_record( provided_invite ) + LOGGER.debug("Mediation invite record retrieved successfully.") except Exception: - LOGGER.exception("Error retrieving mediator invitation") + LOGGER.exception("Error retrieving mediator invitation.") mediation_invite_record = None # Accept mediation invitation if one was specified or stored if mediation_invite_record is not None: + LOGGER.debug( + "Mediation invite record found. " + "Attempting to accept mediation invitation." + ) try: if not mediation_invite_record.used: - # clear previous mediator configuration before establishing a - # new one + # clear previous mediator configuration before establishing a new one + LOGGER.trace( + "Mediation invite not used. " + "Clearing default mediator before accepting new invite." + ) await MediationManager(self.root_profile).clear_default_mediator() mgr = OutOfBandManager(self.root_profile) + LOGGER.debug("Receiving mediation invitation.") record = await mgr.receive_invitation( invitation=InvitationMessage.from_url( mediation_invite_record.invite @@ -516,6 +563,7 @@ async def start(self) -> None: await MediationInviteStore( session.context.inject(BaseStorage) ).mark_default_invite_as_used() + LOGGER.trace("Marked mediation invite as used.") await record.metadata_set( session, MediationManager.SEND_REQ_AFTER_CONNECTION, True @@ -523,48 +571,65 @@ async def start(self) -> None: await record.metadata_set( session, MediationManager.SET_TO_DEFAULT_ON_GRANTED, True ) + LOGGER.trace("Set mediation metadata after connection.") LOGGER.info("Attempting to connect to mediator...") del mgr + LOGGER.trace("Mediation manager deleted after setting up mediator.") except Exception: - LOGGER.exception("Error accepting mediation invitation") + LOGGER.exception("Error accepting mediation invitation.") try: + LOGGER.debug("Checking for wallet upgrades in progress.") await self.check_for_wallet_upgrades_in_progress() + LOGGER.debug("Wallet upgrades check completed.") except Exception: LOGGER.exception( - "An exception was caught while checking for wallet upgrades in progress" + "An exception was caught while checking for wallet upgrades in progress." ) # notify protocols of startup status + LOGGER.trace("Notifying protocols of startup status.") await self.root_profile.notify(STARTUP_EVENT_TOPIC, {}) + LOGGER.debug("Startup notification sent.") async def stop(self, timeout=1.0): """Stop the agent.""" + LOGGER.info("Stopping the Conductor agent.") # notify protocols that we are shutting down if self.root_profile: + LOGGER.debug("Notifying protocols of shutdown.") await self.root_profile.notify(SHUTDOWN_EVENT_TOPIC, {}) + LOGGER.debug("Shutdown notification sent.") shutdown = TaskQueue() if self.dispatcher: + LOGGER.trace("Initiating shutdown of dispatcher.") shutdown.run(self.dispatcher.complete()) if self.admin_server: + LOGGER.trace("Initiating shutdown of admin server.") shutdown.run(self.admin_server.stop()) if self.inbound_transport_manager: + LOGGER.trace("Initiating shutdown of inbound transport manager.") shutdown.run(self.inbound_transport_manager.stop()) if self.outbound_transport_manager: + LOGGER.trace("Initiating shutdown of outbound transport manager.") shutdown.run(self.outbound_transport_manager.stop()) if self.root_profile: # close multitenant profiles multitenant_mgr = self.context.inject_or(BaseMultitenantManager) if multitenant_mgr: + LOGGER.debug("Closing multitenant profiles.") for profile in multitenant_mgr.open_profiles: + LOGGER.trace("Closing profile: %s", profile.name) shutdown.run(profile.close()) - + LOGGER.debug("Closing root profile.") shutdown.run(self.root_profile.close()) + LOGGER.trace("Waiting for shutdown tasks to complete with timeout=%f.", timeout) await shutdown.complete(timeout) + LOGGER.info("Conductor agent stopped successfully.") def inbound_message_router( self, From 2bf4de7de8327b2753a1935f29d1b689c30a5ff5 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 16:03:20 +0200 Subject: [PATCH 28/51] :white_check_mark: Add unit tests for adding trace level functionality Signed-off-by: ff137 --- acapy_agent/config/tests/test_logging.py | 115 +++++++++++++++++++++++ 1 file changed, 115 insertions(+) diff --git a/acapy_agent/config/tests/test_logging.py b/acapy_agent/config/tests/test_logging.py index 0f027b2124..9f24142d84 100644 --- a/acapy_agent/config/tests/test_logging.py +++ b/acapy_agent/config/tests/test_logging.py @@ -1,9 +1,11 @@ import contextlib +import logging from io import BufferedReader, StringIO, TextIOWrapper from tempfile import NamedTemporaryFile from unittest import IsolatedAsyncioTestCase, mock from ..logging import configurator as test_module +from ..logging import utils class TestLoggingConfigurator(IsolatedAsyncioTestCase): @@ -163,3 +165,116 @@ def test_load_resource(self): mock_files.return_value.joinpath.assert_called_once_with("def") mock_resource_path.open.assert_called_once_with("rb") assert result == mock_resource_handle # Verify the returned binary stream + + +class TestLoggingUtils(IsolatedAsyncioTestCase): + def setUp(self): + # Backup existing logging attributes to restore after tests + self.original_levels = { + attr: getattr(logging, attr) for attr in dir(logging) if attr.isupper() + } + self.original_logger_methods = { + attr: getattr(logging.getLoggerClass(), attr, None) + for attr in dir(logging.getLoggerClass()) + if not attr.startswith("_") + } + # Reset TRACE level if it exists + if hasattr(logging, "TRACE"): + delattr(logging, "TRACE") + if hasattr(logging.getLoggerClass(), "trace"): + delattr(logging.getLoggerClass(), "trace") + # Ensure _TRACE_LEVEL_ADDED is False before each test + self._trace_level_added_patcher = mock.patch( + "acapy_agent.config.logging.utils._TRACE_LEVEL_ADDED", False + ) + self.mock_trace_level_added = self._trace_level_added_patcher.start() + + def tearDown(self): + # Restore original logging levels + for attr, value in self.original_levels.items(): + setattr(logging, attr, value) + # Restore original logger methods + for attr, method in self.original_logger_methods.items(): + if method is not None: + setattr(logging.getLoggerClass(), attr, method) + elif hasattr(logging.getLoggerClass(), attr): + delattr(logging.getLoggerClass(), attr) + # Remove TRACE if it was added during tests + if hasattr(logging, "TRACE"): + delattr(logging, "TRACE") + if hasattr(logging.getLoggerClass(), "trace"): + delattr(logging.getLoggerClass(), "trace") + # Stop patching _TRACE_LEVEL_ADDED + self._trace_level_added_patcher.stop() + + @mock.patch("acapy_agent.config.logging.utils.LOGGER") + @mock.patch("acapy_agent.config.logging.utils.logging.addLevelName") + def test_add_logging_level_success(self, mock_addLevelName, mock_logger): + utils.add_logging_level("CUSTOM", 2) + + mock_addLevelName.assert_called_once_with(2, "CUSTOM") + self.assertTrue(hasattr(logging, "CUSTOM")) + self.assertEqual(logging.CUSTOM, 2) + + logger = logging.getLogger(__name__) + self.assertTrue(hasattr(logger, "custom")) + self.assertTrue(callable(logger.custom)) + + self.assertTrue(hasattr(logging, "custom")) + self.assertTrue(callable(logging.custom)) + + def test_add_logging_level_existing_level_name(self): + # Add a level named 'DEBUG' which already exists + with self.assertRaises(AttributeError) as context: + utils.add_logging_level("DEBUG", 15) + self.assertIn("DEBUG already defined in logging module", str(context.exception)) + + def test_add_logging_level_existing_method_name(self): + # Add a logging method that already exists ('debug') + with self.assertRaises(AttributeError) as context: + utils.add_logging_level("CUSTOM", 25, method_name="debug") + self.assertIn("debug already defined in logging module", str(context.exception)) + + @mock.patch("acapy_agent.config.logging.utils.add_logging_level") + @mock.patch("acapy_agent.config.logging.utils.LOGGER") + def test_add_trace_level_new(self, mock_logger, mock_add_logging_level): + # Ensure _TRACE_LEVEL_ADDED is False + utils.add_trace_level() + + mock_add_logging_level.assert_called_once_with( + "TRACE", logging.DEBUG - 5, "trace" + ) + + # Verify logger.debug was called + mock_logger.debug.assert_called_with("%s level added to logging module.", "TRACE") + + # Check that _TRACE_LEVEL_ADDED is now True + self.assertTrue(utils._TRACE_LEVEL_ADDED) + + @mock.patch("acapy_agent.config.logging.utils.LOGGER") + @mock.patch( + "acapy_agent.config.logging.utils.add_logging_level", + side_effect=AttributeError("TRACE already exists"), + ) + def test_add_trace_level_already_exists_exception( + self, mock_add_logging_level, mock_logger + ): + utils.add_trace_level() + + # Verify logger.warning was called + mock_logger.warning.assert_called_with( + "%s level already exists: %s", "TRACE", mock_add_logging_level.side_effect + ) + + @mock.patch("acapy_agent.config.logging.utils.LOGGER") + @mock.patch("acapy_agent.config.logging.utils.add_logging_level") + def test_add_trace_level_already_present(self, mock_add_logging_level, mock_logger): + # Manually set _TRACE_LEVEL_ADDED to True to simulate already added TRACE level + with mock.patch("acapy_agent.config.logging.utils._TRACE_LEVEL_ADDED", True): + utils.add_trace_level() + + # add_logging_level should not be called since TRACE level is already added + mock_add_logging_level.assert_not_called() + + # Verify logger.debug was not called + mock_logger.debug.assert_not_called() From cefafa9069c9e842d0baddb680cd9039989dd0eb Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 17:06:32 +0200 Subject: [PATCH 29/51] :white_check_mark: Reset the logging states before and after TestLoggingUtils is run Signed-off-by: ff137 --- acapy_agent/config/tests/test_logging.py | 53 +++++++++++++++--------- 1 file changed, 34 insertions(+), 19 deletions(-) diff --git a/acapy_agent/config/tests/test_logging.py b/acapy_agent/config/tests/test_logging.py index 9f24142d84..7f4a09e687 100644 --- a/acapy_agent/config/tests/test_logging.py +++ b/acapy_agent/config/tests/test_logging.py @@ -169,43 +169,58 @@ def test_load_resource(self): class TestLoggingUtils(IsolatedAsyncioTestCase): def setUp(self): - # Backup existing logging attributes to restore after tests + """Set up test environment by backing up logging states and resetting TRACE level.""" + # Backup existing logging attributes (e.g., DEBUG, INFO) self.original_levels = { attr: getattr(logging, attr) for attr in dir(logging) if attr.isupper() } + + # Backup existing logger class methods (e.g., debug, info) self.original_logger_methods = { attr: getattr(logging.getLoggerClass(), attr, None) for attr in dir(logging.getLoggerClass()) if not attr.startswith("_") } - # Reset TRACE level if it exists + + # Remove TRACE level and 'trace' method if they exist if hasattr(logging, "TRACE"): delattr(logging, "TRACE") if hasattr(logging.getLoggerClass(), "trace"): delattr(logging.getLoggerClass(), "trace") - # Ensure _TRACE_LEVEL_ADDED is False before each test - self._trace_level_added_patcher = mock.patch( + + # Patch the TRACE_LEVEL_ADDED flag to False before each test + self.trace_level_added_patcher = mock.patch( "acapy_agent.config.logging.utils._TRACE_LEVEL_ADDED", False ) - self.mock_trace_level_added = self._trace_level_added_patcher.start() + self.mock_trace_level_added = self.trace_level_added_patcher.start() def tearDown(self): - # Restore original logging levels + """Restore original logging states after each test.""" + # Stop patching TRACE_LEVEL_ADDED + self.trace_level_added_patcher.stop() + + # Restore original logging level attributes for attr, value in self.original_levels.items(): setattr(logging, attr, value) - # Restore original logger methods - for attr, method in self.original_logger_methods.items(): - if method is not None: - setattr(logging.getLoggerClass(), attr, method) - elif hasattr(logging.getLoggerClass(), attr): - delattr(logging.getLoggerClass(), attr) - # Remove TRACE if it was added during tests - if hasattr(logging, "TRACE"): - delattr(logging, "TRACE") - if hasattr(logging.getLoggerClass(), "trace"): - delattr(logging.getLoggerClass(), "trace") - # Stop patching _TRACE_LEVEL_ADDED - self._trace_level_added_patcher.stop() + + # Identify and remove any new uppercase attributes added during tests (e.g., TRACE) + current_levels = {attr for attr in dir(logging) if attr.isupper()} + for attr in current_levels - set(self.original_levels.keys()): + delattr(logging, attr) + + # Restore original logger class methods + LoggerClass = logging.getLoggerClass() + for attr, value in self.original_logger_methods.items(): + if value is not None: + setattr(LoggerClass, attr, value) + else: + if hasattr(LoggerClass, attr): + delattr(LoggerClass, attr) + + # Identify and remove any new logger methods added during tests (e.g., trace) + current_methods = {attr for attr in dir(LoggerClass) if not attr.startswith("_")} + for attr in current_methods - set(self.original_logger_methods.keys()): + delattr(LoggerClass, attr) @mock.patch("acapy_agent.config.logging.utils.LOGGER") @mock.patch("acapy_agent.config.logging.utils.logging.addLevelName") From 368cbf2e07eec4e338c7d4f28d4149578947c96d Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 17:17:42 +0200 Subject: [PATCH 30/51] :art: Signed-off-by: ff137 --- acapy_agent/commands/start.py | 2 +- acapy_agent/config/logging/utils.py | 2 -- 2 files changed, 1 insertion(+), 3 deletions(-) diff --git a/acapy_agent/commands/start.py b/acapy_agent/commands/start.py index ee256f1e4c..fb8652314c 100644 --- a/acapy_agent/commands/start.py +++ b/acapy_agent/commands/start.py @@ -31,7 +31,7 @@ async def start_app(conductor: Conductor): async def shutdown_app(conductor: Conductor): """Shut down.""" - LOGGER.warning("Shutting down") + LOGGER.info("Shutting down") await conductor.stop() diff --git a/acapy_agent/config/logging/utils.py b/acapy_agent/config/logging/utils.py index 5ee6108607..10092d261a 100644 --- a/acapy_agent/config/logging/utils.py +++ b/acapy_agent/config/logging/utils.py @@ -93,10 +93,8 @@ def add_trace_level() -> None: add_logging_level(TRACE_LEVEL_NAME, TRACE_LEVEL_NUM, TRACE_METHOD_NAME) LOGGER.debug("%s level added to logging module.", TRACE_LEVEL_NAME) except AttributeError as e: - # Log a warning if TRACE level already exists LOGGER.warning("%s level already exists: %s", TRACE_LEVEL_NAME, e) else: - # Optionally, you can log that TRACE level is already present LOGGER.debug( "%s level is already present in the logging module.", TRACE_LEVEL_NAME ) From 84963eaaae4fb0c40a15196cf0d45dd0cfd3d05b Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 20:15:18 +0200 Subject: [PATCH 31/51] :art: Signed-off-by: ff137 --- acapy_agent/config/tests/test_logging.py | 4 ++-- acapy_agent/config/wallet.py | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/acapy_agent/config/tests/test_logging.py b/acapy_agent/config/tests/test_logging.py index 7f4a09e687..105173e95e 100644 --- a/acapy_agent/config/tests/test_logging.py +++ b/acapy_agent/config/tests/test_logging.py @@ -224,10 +224,10 @@ def tearDown(self): @mock.patch("acapy_agent.config.logging.utils.LOGGER") @mock.patch("acapy_agent.config.logging.utils.logging.addLevelName") - def test_add_logging_level_success(self, mock_addLevelName, mock_logger): + def test_add_logging_level_success(self, mock_add_level_name, mock_logger): utils.add_logging_level("CUSTOM", 2) - mock_addLevelName.assert_called_once_with(2, "CUSTOM") + mock_add_level_name.assert_called_once_with(2, "CUSTOM") self.assertTrue(hasattr(logging, "CUSTOM")) self.assertEqual(logging.CUSTOM, 2) diff --git a/acapy_agent/config/wallet.py b/acapy_agent/config/wallet.py index 24a523b785..c0a91741e3 100644 --- a/acapy_agent/config/wallet.py +++ b/acapy_agent/config/wallet.py @@ -65,8 +65,8 @@ async def wallet_config( LOGGER.info("Created new profile") else: LOGGER.info("Opened existing profile") - LOGGER.info("Profile backend:", profile.backend) - LOGGER.info("Profile name:", profile.name) + LOGGER.info("Profile backend: %s", profile.backend) + LOGGER.info("Profile name: %s", profile.name) wallet_seed = context.settings.get("wallet.seed") wallet_local_did = context.settings.get("wallet.local_did") From 59a491d3e83267810c77df78cf335c80858677f7 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 20:58:12 +0200 Subject: [PATCH 32/51] :bug: Handle case that load_module return type is Optional Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 6 +++++- acapy_agent/utils/classloader.py | 4 +++- 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index f86495291e..47617a047d 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -309,7 +309,6 @@ async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> try: LOGGER.trace("Loading message types from: %s", version_path) mod = ClassLoader.load_module(version_path) - await self.load_protocol_version(context, mod, protocol_version) except ModuleLoadError as e: LOGGER.error( "Error loading plugin module message types from %s: %s", @@ -318,6 +317,11 @@ async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> ) return + if mod: + await self.load_protocol_version(context, mod, protocol_version) + else: + LOGGER.debug("Failed to load %s", version_path) + async def register_admin_routes(self, app) -> None: """Call route registration methods on the current context.""" LOGGER.trace("Registering admin routes for %d plugins", len(self._plugins)) diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index 09d4799aea..a7163e64f6 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -22,7 +22,9 @@ class ClassLoader: """Class used to load classes from modules dynamically.""" @classmethod - def load_module(cls, mod_path: str, package: Optional[str] = None) -> ModuleType: + def load_module( + cls, mod_path: str, package: Optional[str] = None + ) -> Optional[ModuleType]: """Load a module by its absolute path. Args: From 14cb6866f242c329cfdf70bec9a771b8b838f4c5 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 7 Nov 2024 21:37:52 +0200 Subject: [PATCH 33/51] :loud_sound: Expand logging for ClassLoader Signed-off-by: ff137 --- acapy_agent/utils/classloader.py | 88 ++++++++++++++++++++++++++++++-- 1 file changed, 84 insertions(+), 4 deletions(-) diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index a7163e64f6..ee4c5014f0 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -1,6 +1,7 @@ """The classloader provides utilities to dynamically load classes and modules.""" import inspect +import logging import sys from importlib import import_module, resources from importlib.util import find_spec, resolve_name @@ -9,6 +10,8 @@ from ..core.error import BaseError +LOGGER = logging.getLogger(__name__) + class ModuleLoadError(BaseError): """Module load error.""" @@ -38,36 +41,52 @@ def load_module( ModuleLoadError: If there was an error loading the module """ + LOGGER.trace("Attempting to load module: %s with package: %s", mod_path, package) + if package: + LOGGER.trace("Preloading parent package: %s", package) # preload parent package if not cls.load_module(package): + LOGGER.trace("Failed to preload parent package: %s", package) return None # must treat as a relative import if not mod_path.startswith("."): mod_path = f".{mod_path}" + LOGGER.trace("Adjusted mod_path for relative import: %s", mod_path) full_path = resolve_name(mod_path, package) + LOGGER.trace("Resolved full module path: %s", full_path) + if full_path in sys.modules: + LOGGER.trace("Module %s is already loaded", full_path) return sys.modules[full_path] if "." in mod_path: parent_mod_path, mod_name = mod_path.rsplit(".", 1) + LOGGER.trace( + "Parent module path: %s, Module name: %s", parent_mod_path, mod_name + ) if parent_mod_path and parent_mod_path[-1] != ".": parent_mod = cls.load_module(parent_mod_path, package) if not parent_mod: + LOGGER.trace("Failed to load parent module: %s", parent_mod_path) return None package = parent_mod.__name__ mod_path = f".{mod_name}" + LOGGER.trace("Adjusted mod_path after loading parent: %s", mod_path) # Load the module spec first - # this means that a later ModuleNotFoundError indicates a code issue + LOGGER.trace("Finding spec for module: %s with package: %s", mod_path, package) spec = find_spec(mod_path, package) if not spec: + LOGGER.trace("Module spec not found for: %s", mod_path) return None try: + LOGGER.trace("Importing module: %s with package: %s", mod_path, package) return import_module(mod_path, package) except ModuleNotFoundError as e: + LOGGER.warning("Module %s not found during import", full_path) raise ModuleLoadError(f"Unable to import module {full_path}: {str(e)}") from e @classmethod @@ -93,29 +112,53 @@ def load_class( """ + LOGGER.trace( + "Attempting to load class: %s with default_module: %s and package: %s", + class_name, + default_module, + package, + ) + if "." in class_name: # import module and find class mod_path, class_name = class_name.rsplit(".", 1) + LOGGER.trace( + "Extracted module path: %s, class name: %s from full class path", + mod_path, + class_name, + ) elif default_module: mod_path = default_module + LOGGER.trace("No module in class name, using default_module: %s", mod_path) else: + LOGGER.warning( + "Cannot resolve class name %s with no default module", class_name + ) raise ClassNotFoundError( f"Cannot resolve class name with no default module: {class_name}" ) mod = cls.load_module(mod_path, package) if not mod: - raise ClassNotFoundError(f"Module '{mod_path}' not found") + LOGGER.warning( + "Module %s not found when loading class %s", mod_path, class_name + ) + raise ClassNotFoundError(f"Module {mod_path} not found") resolved = getattr(mod, class_name, None) if not resolved: + LOGGER.warning("Class %s not found in module %s", class_name, mod_path) raise ClassNotFoundError( f"Class '{class_name}' not defined in module: {mod_path}" ) if not isinstance(resolved, type): + LOGGER.warning( + "Resolved attribute %s in module %s is not a class", class_name, mod_path + ) raise ClassNotFoundError( f"Resolved value is not a class: {mod_path}.{class_name}" ) + LOGGER.trace("Successfully loaded class %s from module %s", class_name, mod_path) return resolved @classmethod @@ -138,18 +181,45 @@ def load_subclass_of( """ + LOGGER.trace( + "Attempting to load subclass of %s from module %s with package %s", + base_class.__name__, + mod_path, + package, + ) + mod = cls.load_module(mod_path, package) if not mod: + LOGGER.warning( + "Module %s not found when loading subclass of %s", + mod_path, + base_class.__name__, + ) raise ClassNotFoundError(f"Module '{mod_path}' not found") - # Find an the first declared class that inherits from + # Find the first declared class that inherits from the base_class try: + LOGGER.trace( + "Inspecting classes in module %s for subclasses of %s", + mod_path, + base_class.__name__, + ) imported_class = next( obj for name, obj in inspect.getmembers(mod, inspect.isclass) if issubclass(obj, base_class) and obj is not base_class ) + LOGGER.trace( + "Found subclass %s of base class %s", + imported_class.__name__, + base_class.__name__, + ) except StopIteration: + LOGGER.trace( + "No subclass of %s found in module %s", + base_class.__name__, + mod_path, + ) raise ClassNotFoundError( f"Could not resolve a class that inherits from {base_class}" ) from None @@ -158,25 +228,35 @@ def load_subclass_of( @classmethod def scan_subpackages(cls, package: str) -> Sequence[str]: """Return a list of sub-packages defined under a named package.""" + LOGGER.debug("Scanning subpackages under package %s", package) if "." in package: package, sub_pkg = package.split(".", 1) + LOGGER.trace("Extracted main package: %s, sub-package: %s", package, sub_pkg) else: sub_pkg = "." + LOGGER.trace("No sub-package provided, defaulting to %s", sub_pkg) try: package_path = resources.files(package) + LOGGER.trace("Found package path: %s", package_path) except FileNotFoundError: + LOGGER.warning("Package %s not found during subpackage scan", package) raise ModuleLoadError(f"Undefined package {package}") if not (package_path / sub_pkg).is_dir(): + LOGGER.warning("Sub-package %s is not a directory under %s", sub_pkg, package) raise ModuleLoadError(f"Undefined package {package}") found = [] joiner = "" if sub_pkg == "." else f"{sub_pkg}." sub_path = package_path / sub_pkg + LOGGER.trace("Iterating over items in sub-package path: %s", sub_path) for item in sub_path.iterdir(): if (item / "__init__.py").exists(): - found.append(f"{package}.{joiner}{item.name}") + subpackage = f"{package}.{joiner}{item.name}" + found.append(subpackage) + LOGGER.trace("Found sub-package: %s", subpackage) + LOGGER.debug("Total sub-packages found under %s: %s", package, found) return found From ef1d729e6c945b72a45d17e2c35fa41e27ef4099 Mon Sep 17 00:00:00 2001 From: ff137 Date: Mon, 11 Nov 2024 10:22:16 +0200 Subject: [PATCH 34/51] :loud_sound: Log a warning if resource not found, instead of passing Signed-off-by: ff137 --- acapy_agent/config/logging/configurator.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/acapy_agent/config/logging/configurator.py b/acapy_agent/config/logging/configurator.py index 2ca573e519..8f44935b69 100644 --- a/acapy_agent/config/logging/configurator.py +++ b/acapy_agent/config/logging/configurator.py @@ -34,6 +34,8 @@ from .utils import add_trace_level +LOGGER = logging.getLogger(__name__) + # Add TRACE level to logging before any configuration add_trace_level() @@ -62,7 +64,8 @@ def load_resource(path: str, encoding: Optional[str] = None): return io.TextIOWrapper(bstream, encoding=encoding) return bstream except IOError: - pass + LOGGER.warning("Resource not found: %s", path) + return None def dictConfig(config, new_file_path=None): From e473304186a3d98ef14ff8784446ac45b38c8fa3 Mon Sep 17 00:00:00 2001 From: ff137 Date: Mon, 11 Nov 2024 10:22:45 +0200 Subject: [PATCH 35/51] :art: Signed-off-by: ff137 --- acapy_agent/config/logging/configurator.py | 13 +------------ 1 file changed, 1 insertion(+), 12 deletions(-) diff --git a/acapy_agent/config/logging/configurator.py b/acapy_agent/config/logging/configurator.py index 8f44935b69..7188908024 100644 --- a/acapy_agent/config/logging/configurator.py +++ b/acapy_agent/config/logging/configurator.py @@ -103,18 +103,7 @@ def fileConfig( raise RuntimeError(f"{fname} is invalid: {e}") if new_file_path and cp.has_section("handler_timed_file_handler"): - cp.set( - "handler_timed_file_handler", - "args", - str( - ( - f"{new_file_path}", - "d", - 7, - 1, - ) - ), - ) + cp.set("handler_timed_file_handler", "args", str((new_file_path, "d", 7, 1))) formatters = _create_formatters(cp) with logging._lock: From 4f42f406acbe25e3f6a2ce13da3d0323fb2870bc Mon Sep 17 00:00:00 2001 From: ff137 Date: Mon, 11 Nov 2024 10:53:30 +0200 Subject: [PATCH 36/51] :art: Enable trace logs for remaining modules Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 3 +++ acapy_agent/utils/classloader.py | 2 ++ 2 files changed, 5 insertions(+) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index b2dcb9e7fe..137f231201 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -27,6 +27,7 @@ load_multiple_genesis_transactions_from_config, ) from ..config.logging import LoggingConfigurator +from ..config.logging.utils import add_trace_level from ..config.provider import ClassProvider from ..config.wallet import wallet_config from ..connections.base_manager import BaseConnectionManager, BaseConnectionManagerError @@ -79,6 +80,8 @@ from .util import SHUTDOWN_EVENT_TOPIC, STARTUP_EVENT_TOPIC LOGGER = logging.getLogger(__name__) +add_trace_level() # Allow trace logs from this module + # Refer ACA-Py issue #2197 # When the from version is not found DEFAULT_ACAPY_VERSION = "v0.7.5" diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index ee4c5014f0..cac6135d3d 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -8,9 +8,11 @@ from types import ModuleType from typing import Optional, Sequence, Type +from ..config.logging.utils import add_trace_level from ..core.error import BaseError LOGGER = logging.getLogger(__name__) +add_trace_level() # Allow trace logs from this module class ModuleLoadError(BaseError): From 84764d5a75fe118a53e87c380458376fd8e60b62 Mon Sep 17 00:00:00 2001 From: ff137 Date: Tue, 12 Nov 2024 11:04:16 +0200 Subject: [PATCH 37/51] :bug: Fix registering and loading of modules Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 30 ++++++++++++++++++++--------- 1 file changed, 21 insertions(+), 9 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 47617a047d..542203c819 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -344,6 +344,10 @@ async def register_admin_routes(self, app) -> None: "Error loading admin routes from %s: %s", version_path, e ) continue + + if mod and hasattr(mod, "register"): + LOGGER.trace("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" @@ -354,9 +358,9 @@ async def register_admin_routes(self, app) -> None: LOGGER.error("Error loading admin routes from %s: %s", routes_path, e) continue - if mod and hasattr(mod, "register"): - LOGGER.trace("Registering routes for: %s", plugin_name) - await mod.register(app) + if mod and hasattr(mod, "register"): + LOGGER.trace("Registering routes for: %s", plugin_name) + await mod.register(app) def register_protocol_events(self, context: InjectionContext) -> None: """Call route register_events methods on the current context.""" @@ -383,6 +387,10 @@ def register_protocol_events(self, context: InjectionContext) -> None: except ModuleLoadError as e: LOGGER.error("Error loading events from %s: %s", version_path, e) continue + + if mod and hasattr(mod, "register_events"): + LOGGER.trace("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" @@ -393,9 +401,9 @@ def register_protocol_events(self, context: InjectionContext) -> None: LOGGER.error("Error loading events from %s: %s", routes_path, e) continue - if mod and hasattr(mod, "register_events"): - LOGGER.trace("Registering events from: %s", version_path) - mod.register_events(event_bus) + if mod and hasattr(mod, "register_events"): + LOGGER.trace("Registering events from: %s", version_path) + mod.register_events(event_bus) def post_process_routes(self, app) -> None: """Call route binary file response OpenAPI fixups if applicable.""" @@ -417,6 +425,10 @@ def post_process_routes(self, app) -> None: 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.trace("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" @@ -427,9 +439,9 @@ def post_process_routes(self, app) -> None: LOGGER.error("Error loading routes from %s: %s", routes_path, e) continue - if mod and hasattr(mod, "post_process_routes"): - LOGGER.trace("Post-processing routes for %s", plugin_name) - mod.post_process_routes(app) + if mod and hasattr(mod, "post_process_routes"): + LOGGER.trace("Post-processing routes for %s", plugin_name) + mod.post_process_routes(app) def __repr__(self) -> str: """Return a string representation for this class.""" From f17c8ed01351c44a315742264691158dccfa275b Mon Sep 17 00:00:00 2001 From: ff137 Date: Tue, 12 Nov 2024 13:01:19 +0200 Subject: [PATCH 38/51] :loud_sound: Expand logging for Ledger Configuration Signed-off-by: ff137 --- acapy_agent/config/ledger.py | 30 +++++++++++++++++++++++++++++- 1 file changed, 29 insertions(+), 1 deletion(-) diff --git a/acapy_agent/config/ledger.py b/acapy_agent/config/ledger.py index e8a4791e38..507113d531 100644 --- a/acapy_agent/config/ledger.py +++ b/acapy_agent/config/ledger.py @@ -34,14 +34,18 @@ async def fetch_genesis_transactions(genesis_url: str) -> str: # https://github.com/openwallet-foundation/acapy/issues/1745 return await fetch(genesis_url, headers=headers, max_attempts=20) except FetchError as e: + LOGGER.error("Error retrieving genesis transactions from %s: %s", genesis_url, e) raise ConfigError("Error retrieving ledger genesis transactions") from e async def get_genesis_transactions(settings: Settings) -> str: """Fetch genesis transactions if necessary.""" + LOGGER.debug("Getting genesis transactions from settings") txns = settings.get("ledger.genesis_transactions") + LOGGER.debug("Genesis transactions from settings: %s", "found" if txns else "absent") if not txns: + LOGGER.debug("No genesis transactions found in settings") if settings.get("ledger.genesis_url"): txns = await fetch_genesis_transactions(settings["ledger.genesis_url"]) elif settings.get("ledger.genesis_file"): @@ -51,8 +55,10 @@ async def get_genesis_transactions(settings: Settings) -> str: with open(genesis_path, "r") as genesis_file: txns = genesis_file.read() except IOError as e: + LOGGER.error("Failed to read genesis file: %s", str(e)) raise ConfigError("Error reading ledger genesis transactions") from e if txns: + LOGGER.debug("Storing genesis transactions in settings") settings["ledger.genesis_transactions"] = txns return txns @@ -63,6 +69,8 @@ async def load_multiple_genesis_transactions_from_config(settings: Settings): ledger_config_list = settings.get("ledger.ledger_config_list") ledger_txns_list = [] write_ledger_set = False + LOGGER.debug("Processing %d ledger configs", len(ledger_config_list)) + for config in ledger_config_list: txns = None if "genesis_transactions" in config: @@ -74,11 +82,12 @@ async def load_multiple_genesis_transactions_from_config(settings: Settings): try: genesis_path = config.get("genesis_file") LOGGER.info( - "Reading ledger genesis transactions from: %s", genesis_path + "Reading ledger genesis transactions from file: %s", genesis_path ) with open(genesis_path, "r") as genesis_file: txns = genesis_file.read() except IOError as e: + LOGGER.error("Failed to read genesis file: %s", str(e)) raise ConfigError("Error reading ledger genesis transactions") from e is_write_ledger = ( False if config.get("is_write") is None else config.get("is_write") @@ -119,6 +128,7 @@ async def load_multiple_genesis_transactions_from_config(settings: Settings): " genesis_file and genesis_transactions provided." ) settings["ledger.ledger_config_list"] = ledger_txns_list + LOGGER.debug("Processed %d ledger configs successfully", len(ledger_txns_list)) async def ledger_config( @@ -126,6 +136,10 @@ async def ledger_config( ) -> bool: """Perform Indy ledger configuration.""" + LOGGER.debug( + "Configuring ledger for profile %s and public_did %s", profile.name, public_did + ) + session = await profile.session() ledger = session.inject_or(BaseLedger) @@ -136,32 +150,46 @@ async def ledger_config( async with ledger: # Check transaction author agreement acceptance if not ledger.read_only: + LOGGER.debug("Checking transaction author agreement") taa_info = await ledger.get_txn_author_agreement() if taa_info["taa_required"] and public_did: + LOGGER.debug("TAA acceptance required") taa_accepted = await ledger.get_latest_txn_author_acceptance() if ( not taa_accepted or taa_info["taa_record"]["digest"] != taa_accepted["digest"] ): + LOGGER.info("TAA acceptance needed - performing acceptance") if not await accept_taa(ledger, profile, taa_info, provision): + LOGGER.warning("TAA acceptance failed") return False + LOGGER.info("TAA acceptance completed") # Publish endpoints if necessary - skipped if TAA is required but not accepted endpoint = session.settings.get("default_endpoint") if public_did: wallet = session.inject(BaseWallet) try: + LOGGER.debug("Setting DID endpoint to: %s", endpoint) await wallet.set_did_endpoint(public_did, endpoint, ledger) except LedgerError as x_ledger: + LOGGER.error("Error setting DID endpoint: %s", x_ledger.message) raise ConfigError(x_ledger.message) from x_ledger # e.g., read-only # Publish profile endpoint if ledger is NOT read-only profile_endpoint = session.settings.get("profile_endpoint") if profile_endpoint and not ledger.read_only: + LOGGER.debug( + "Publishing profile endpoint: %s for DID: %s", + profile_endpoint, + public_did, + ) await ledger.update_endpoint_for_did( public_did, profile_endpoint, EndpointType.PROFILE ) + LOGGER.info("Profile endpoint published successfully") + LOGGER.info("Ledger configuration complete") return True From d28c80b018d77ac30e0a35ca3c5c9da48a768674 Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 27 Nov 2024 13:17:23 +0200 Subject: [PATCH 39/51] :rewind: Revert `trace` log changes, and move to debug level Signed-off-by: ff137 --- acapy_agent/config/default_context.py | 20 ++-- acapy_agent/config/logging/configurator.py | 5 - acapy_agent/config/logging/utils.py | 102 ---------------- acapy_agent/config/tests/test_logging.py | 130 --------------------- acapy_agent/core/conductor.py | 88 +++++++------- acapy_agent/core/plugin_registry.py | 84 +++++++------ acapy_agent/utils/classloader.py | 54 ++++----- 7 files changed, 119 insertions(+), 364 deletions(-) delete mode 100644 acapy_agent/config/logging/utils.py diff --git a/acapy_agent/config/default_context.py b/acapy_agent/config/default_context.py index 5efa7bdfc5..c30134a8ba 100644 --- a/acapy_agent/config/default_context.py +++ b/acapy_agent/config/default_context.py @@ -5,7 +5,6 @@ from ..anoncreds.registry import AnonCredsRegistry from ..cache.base import BaseCache from ..cache.in_memory import InMemoryCache -from ..config.logging.utils import add_trace_level from ..connections.base_manager import BaseConnectionManager from ..core.event_bus import EventBus from ..core.goal_code_registry import GoalCodeRegistry @@ -31,7 +30,6 @@ from .provider import CachedProvider, ClassProvider LOGGER = logging.getLogger(__name__) -add_trace_level() # Allow trace logs from this module class DefaultContextBuilder(ContextBuilder): @@ -39,14 +37,14 @@ class DefaultContextBuilder(ContextBuilder): async def build_context(self) -> InjectionContext: """Build the base injection context; set DIDComm prefix to emit.""" - LOGGER.trace("Building new injection context with settings: %s", self.settings) + LOGGER.debug("Building new injection context") context = InjectionContext(settings=self.settings) context.settings.set_default("default_label", "Aries Cloud Agent") if context.settings.get("timing.enabled"): timing_log = context.settings.get("timing.log_file") - LOGGER.trace("Enabling timing collector with log file: %s", timing_log) + LOGGER.debug("Enabling timing collector with log file: %s", timing_log) collector = Collector(log_path=timing_log) context.injector.bind_instance(Collector, collector) @@ -88,13 +86,13 @@ async def build_context(self) -> InjectionContext: async def bind_providers(self, context: InjectionContext): """Bind various class providers.""" - LOGGER.trace("Begin binding providers to context") + LOGGER.debug("Begin binding providers to context") context.injector.bind_provider(ProfileManager, ProfileManagerProvider()) wallet_type = self.settings.get("wallet.type") if wallet_type == "askar-anoncreds": - LOGGER.trace("Using AnonCreds tails server") + LOGGER.debug("Using AnonCreds tails server") context.injector.bind_provider( BaseTailsServer, ClassProvider( @@ -102,7 +100,7 @@ async def bind_providers(self, context: InjectionContext): ), ) else: - LOGGER.trace("Using Indy tails server") + LOGGER.debug("Using Indy tails server") context.injector.bind_provider( BaseTailsServer, ClassProvider( @@ -131,7 +129,7 @@ async def bind_providers(self, context: InjectionContext): async def load_plugins(self, context: InjectionContext): """Set up plugin registry and load plugins.""" - LOGGER.trace("Initializing plugin registry") + LOGGER.debug("Initializing plugin registry") plugin_registry = PluginRegistry( blocklist=self.settings.get("blocked_plugins", []) ) @@ -172,7 +170,7 @@ async def load_plugins(self, context: InjectionContext): def register_plugins(plugins: list[str], plugin_type: str): """Register a group of plugins with logging.""" - LOGGER.trace("Registering %s plugins", plugin_type) + LOGGER.debug("Registering %s plugins", plugin_type) for plugin in plugins: plugin_registry.register_plugin(plugin) @@ -185,7 +183,7 @@ def register_anoncreds_plugins(): register_plugins(default_plugins, "default") if context.settings.get("multitenant.admin_enabled"): - LOGGER.trace("Multitenant admin enabled - registering additional plugins") + LOGGER.debug("Multitenant admin enabled - registering additional plugins") plugin_registry.register_plugin("acapy_agent.multitenant.admin") register_askar_plugins() register_anoncreds_plugins() @@ -197,7 +195,7 @@ def register_anoncreds_plugins(): # Register external plugins for plugin_path in self.settings.get("external_plugins", []): - LOGGER.trace("Registering external plugin: %s", plugin_path) + LOGGER.debug("Registering external plugin: %s", plugin_path) plugin_registry.register_plugin(plugin_path) # Register message protocols diff --git a/acapy_agent/config/logging/configurator.py b/acapy_agent/config/logging/configurator.py index 7188908024..5f7de2e37e 100644 --- a/acapy_agent/config/logging/configurator.py +++ b/acapy_agent/config/logging/configurator.py @@ -31,14 +31,9 @@ from .timed_rotating_file_multi_process_handler import ( TimedRotatingFileMultiProcessHandler, ) -from .utils import add_trace_level - LOGGER = logging.getLogger(__name__) -# Add TRACE level to logging before any configuration -add_trace_level() - def load_resource(path: str, encoding: Optional[str] = None): """Open a resource file located in a python package or the local filesystem. diff --git a/acapy_agent/config/logging/utils.py b/acapy_agent/config/logging/utils.py deleted file mode 100644 index 10092d261a..0000000000 --- a/acapy_agent/config/logging/utils.py +++ /dev/null @@ -1,102 +0,0 @@ -"""Logging utilities.""" - -import logging -from functools import partial, partialmethod -from typing import Optional - -LOGGER = logging.getLogger(__name__) -_TRACE_LEVEL_ADDED = False - - -def add_logging_level( - level_name: str, level_num: int, method_name: Optional[str] = None -) -> None: - """Add a custom logging level to the `logging` module. - - Comprehensively adds a new logging level to the `logging` module and the - currently configured logging class. - - `level_name` becomes an attribute of the `logging` module with the value - `level_num`. - `methodName` becomes a convenience method for both `logging` itself - and the class returned by `logging.getLoggerClass()` (usually just - `logging.Logger`). - If `methodName` is not specified, `levelName.lower()` is used. - - To avoid accidental clobberings of existing attributes, this method will - raise an `AttributeError` if the level name is already an attribute of the - `logging` module or if the method name is already present - - Example: - ------- - >>> add_logging_level('TRACE', logging.DEBUG - 5) - >>> logging.getLogger(__name__).setLevel('TRACE') - >>> logging.getLogger(__name__).trace('that worked') - >>> logging.trace('so did this') - >>> logging.TRACE - 5 - - References: - - https://stackoverflow.com/a/35804945 - """ - if not method_name: - method_name = level_name.lower() - - if hasattr(logging, level_name): - raise AttributeError(f"{level_name} already defined in logging module") - if hasattr(logging, method_name): - raise AttributeError(f"{method_name} already defined in logging module") - if hasattr(logging.getLoggerClass(), method_name): - raise AttributeError(f"{method_name} already defined in logger class") - - # Add the new logging level - logging.addLevelName(level_num, level_name) - setattr(logging, level_name, level_num) - setattr( - logging.getLoggerClass(), - method_name, - partialmethod(logging.getLoggerClass().log, level_num), - ) - setattr(logging, method_name, partial(logging.log, level_num)) - - -def add_trace_level() -> None: - """Add the TRACE level to the logging module safely. - - This function adds a TRACE level to the logging module if it hasn't been added yet. - It handles the case where TRACE is already defined, avoiding duplicate additions. - - Returns: - None - """ - global _TRACE_LEVEL_ADDED - - if _TRACE_LEVEL_ADDED: - return - - TRACE_LEVEL_NUM = logging.DEBUG - 5 - TRACE_LEVEL_NAME = "TRACE" - TRACE_METHOD_NAME = "trace" - - # Check if TRACE level is already defined - level_exists = ( - hasattr(logging, TRACE_LEVEL_NAME) - and getattr(logging, TRACE_LEVEL_NAME) == TRACE_LEVEL_NUM - ) - - method_exists = hasattr(logging, TRACE_METHOD_NAME) and callable( - getattr(logging, TRACE_METHOD_NAME) - ) - - if not level_exists or not method_exists: - try: - add_logging_level(TRACE_LEVEL_NAME, TRACE_LEVEL_NUM, TRACE_METHOD_NAME) - LOGGER.debug("%s level added to logging module.", TRACE_LEVEL_NAME) - except AttributeError as e: - LOGGER.warning("%s level already exists: %s", TRACE_LEVEL_NAME, e) - else: - LOGGER.debug( - "%s level is already present in the logging module.", TRACE_LEVEL_NAME - ) - - _TRACE_LEVEL_ADDED = True diff --git a/acapy_agent/config/tests/test_logging.py b/acapy_agent/config/tests/test_logging.py index 105173e95e..0f027b2124 100644 --- a/acapy_agent/config/tests/test_logging.py +++ b/acapy_agent/config/tests/test_logging.py @@ -1,11 +1,9 @@ import contextlib -import logging from io import BufferedReader, StringIO, TextIOWrapper from tempfile import NamedTemporaryFile from unittest import IsolatedAsyncioTestCase, mock from ..logging import configurator as test_module -from ..logging import utils class TestLoggingConfigurator(IsolatedAsyncioTestCase): @@ -165,131 +163,3 @@ def test_load_resource(self): mock_files.return_value.joinpath.assert_called_once_with("def") mock_resource_path.open.assert_called_once_with("rb") assert result == mock_resource_handle # Verify the returned binary stream - - -class TestLoggingUtils(IsolatedAsyncioTestCase): - def setUp(self): - """Set up test environment by backing up logging states and resetting TRACE level.""" - # Backup existing logging attributes (e.g., DEBUG, INFO) - self.original_levels = { - attr: getattr(logging, attr) for attr in dir(logging) if attr.isupper() - } - - # Backup existing logger class methods (e.g., debug, info) - self.original_logger_methods = { - attr: getattr(logging.getLoggerClass(), attr, None) - for attr in dir(logging.getLoggerClass()) - if not attr.startswith("_") - } - - # Remove TRACE level and 'trace' method if they exist - if hasattr(logging, "TRACE"): - delattr(logging, "TRACE") - if hasattr(logging.getLoggerClass(), "trace"): - delattr(logging.getLoggerClass(), "trace") - - # Patch the TRACE_LEVEL_ADDED flag to False before each test - self.trace_level_added_patcher = mock.patch( - "acapy_agent.config.logging.utils._TRACE_LEVEL_ADDED", False - ) - self.mock_trace_level_added = self.trace_level_added_patcher.start() - - def tearDown(self): - """Restore original logging states after each test.""" - # Stop patching TRACE_LEVEL_ADDED - self.trace_level_added_patcher.stop() - - # Restore original logging level attributes - for attr, value in self.original_levels.items(): - setattr(logging, attr, value) - - # Identify and remove any new uppercase attributes added during tests (e.g., TRACE) - current_levels = {attr for attr in dir(logging) if attr.isupper()} - for attr in current_levels - set(self.original_levels.keys()): - delattr(logging, attr) - - # Restore original logger class methods - LoggerClass = logging.getLoggerClass() - for attr, value in self.original_logger_methods.items(): - if value is not None: - setattr(LoggerClass, attr, value) - else: - if hasattr(LoggerClass, attr): - delattr(LoggerClass, attr) - - # Identify and remove any new logger methods added during tests (e.g., trace) - current_methods = {attr for attr in dir(LoggerClass) if not attr.startswith("_")} - for attr in current_methods - set(self.original_logger_methods.keys()): - delattr(LoggerClass, attr) - - @mock.patch("acapy_agent.config.logging.utils.LOGGER") - @mock.patch("acapy_agent.config.logging.utils.logging.addLevelName") - def test_add_logging_level_success(self, mock_add_level_name, mock_logger): - utils.add_logging_level("CUSTOM", 2) - - mock_add_level_name.assert_called_once_with(2, "CUSTOM") - self.assertTrue(hasattr(logging, "CUSTOM")) - self.assertEqual(logging.CUSTOM, 2) - - logger = logging.getLogger(__name__) - self.assertTrue(hasattr(logger, "custom")) - self.assertTrue(callable(logger.custom)) - - self.assertTrue(hasattr(logging, "custom")) - self.assertTrue(callable(logging.custom)) - - def test_add_logging_level_existing_level_name(self): - # Add a level named 'DEBUG' which already exists - with self.assertRaises(AttributeError) as context: - utils.add_logging_level("DEBUG", 15) - self.assertIn("DEBUG already defined in logging module", str(context.exception)) - - def test_add_logging_level_existing_method_name(self): - # Add a logging method that already exists ('debug') - with self.assertRaises(AttributeError) as context: - utils.add_logging_level("CUSTOM", 25, method_name="debug") - self.assertIn("debug already defined in logging module", str(context.exception)) - - @mock.patch("acapy_agent.config.logging.utils.add_logging_level") - @mock.patch("acapy_agent.config.logging.utils.LOGGER") - def test_add_trace_level_new(self, mock_logger, mock_add_logging_level): - # Ensure _TRACE_LEVEL_ADDED is False - utils.add_trace_level() - - mock_add_logging_level.assert_called_once_with( - "TRACE", logging.DEBUG - 5, "trace" - ) - - # Verify logger.debug was called - mock_logger.debug.assert_called_with("%s level added to logging module.", "TRACE") - - # Check that _TRACE_LEVEL_ADDED is now True - self.assertTrue(utils._TRACE_LEVEL_ADDED) - - @mock.patch("acapy_agent.config.logging.utils.LOGGER") - @mock.patch( - "acapy_agent.config.logging.utils.add_logging_level", - side_effect=AttributeError("TRACE already exists"), - ) - def test_add_trace_level_already_exists_exception( - self, mock_add_logging_level, mock_logger - ): - utils.add_trace_level() - - # Verify logger.warning was called - mock_logger.warning.assert_called_with( - "%s level already exists: %s", "TRACE", mock_add_logging_level.side_effect - ) - - @mock.patch("acapy_agent.config.logging.utils.LOGGER") - @mock.patch("acapy_agent.config.logging.utils.add_logging_level") - def test_add_trace_level_already_present(self, mock_add_logging_level, mock_logger): - # Manually set _TRACE_LEVEL_ADDED to True to simulate already added TRACE level - with mock.patch("acapy_agent.config.logging.utils._TRACE_LEVEL_ADDED", True): - utils.add_trace_level() - - # add_logging_level should not be called since TRACE level is already added - mock_add_logging_level.assert_not_called() - - # Verify logger.debug was not called - mock_logger.debug.assert_not_called() diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index 137f231201..33c50313f1 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -27,7 +27,6 @@ load_multiple_genesis_transactions_from_config, ) from ..config.logging import LoggingConfigurator -from ..config.logging.utils import add_trace_level from ..config.provider import ClassProvider from ..config.wallet import wallet_config from ..connections.base_manager import BaseConnectionManager, BaseConnectionManagerError @@ -80,8 +79,6 @@ from .util import SHUTDOWN_EVENT_TOPIC, STARTUP_EVENT_TOPIC LOGGER = logging.getLogger(__name__) -add_trace_level() # Allow trace logs from this module - # Refer ACA-Py issue #2197 # When the from version is not found DEFAULT_ACAPY_VERSION = "v0.7.5" @@ -125,7 +122,7 @@ async def setup(self): LOGGER.debug("Starting setup of the Conductor") context = await self.context_builder.build_context() - LOGGER.trace("Context built successfully") + LOGGER.debug("Context built successfully") if self.force_agent_anoncreds: LOGGER.debug( @@ -151,15 +148,15 @@ async def setup(self): await get_genesis_transactions(context.settings) # Configure the root profile - LOGGER.trace("Configuring the root profile and setting up public DID") + LOGGER.debug("Configuring the root profile and setting up public DID") self.root_profile, self.setup_public_did = await wallet_config(context) context = self.root_profile.context - LOGGER.trace("Root profile configured successfully") + LOGGER.debug("Root profile configured successfully") # Multiledger Setup ledger_config_list = context.settings.get("ledger.ledger_config_list") if ledger_config_list and len(ledger_config_list) > 0: - LOGGER.trace("Setting up multiledger manager") + LOGGER.debug("Setting up multiledger manager") context.injector.bind_provider( BaseMultipleLedgerManager, MultiIndyLedgerManagerProvider(self.root_profile), @@ -175,7 +172,7 @@ async def setup(self): self.root_profile.BACKEND_NAME == "askar" and ledger.BACKEND_NAME == "indy-vdr" ): - LOGGER.trace("Binding IndyCredxVerifier for 'askar' backend.") + LOGGER.debug("Binding IndyCredxVerifier for 'askar' backend.") context.injector.bind_provider( IndyVerifier, ClassProvider( @@ -187,7 +184,7 @@ async def setup(self): self.root_profile.BACKEND_NAME == "askar-anoncreds" and ledger.BACKEND_NAME == "indy-vdr" ): - LOGGER.trace( + LOGGER.debug( "Binding IndyCredxVerifier for 'askar-anoncreds' backend." ) context.injector.bind_provider( @@ -226,7 +223,7 @@ async def setup(self): context.injector.bind_instance( InboundTransportManager, self.inbound_transport_manager ) - LOGGER.trace("Inbound transports registered successfully.") + LOGGER.debug("Inbound transports registered successfully.") # Register all outbound transports LOGGER.debug("Setting up outbound transports.") @@ -234,46 +231,46 @@ async def setup(self): self.root_profile, self.handle_not_delivered ) await self.outbound_transport_manager.setup() - LOGGER.trace("Outbound transports registered successfully.") + LOGGER.debug("Outbound transports registered successfully.") # Initialize dispatcher - LOGGER.trace("Initializing dispatcher.") + LOGGER.debug("Initializing dispatcher.") self.dispatcher = Dispatcher(self.root_profile) await self.dispatcher.setup() - LOGGER.trace("Dispatcher initialized successfully.") + LOGGER.debug("Dispatcher initialized successfully.") wire_format = context.inject_or(BaseWireFormat) if wire_format and hasattr(wire_format, "task_queue"): wire_format.task_queue = self.dispatcher.task_queue - LOGGER.trace("Wire format task queue bound to dispatcher.") + LOGGER.debug("Wire format task queue bound to dispatcher.") # Bind manager for multitenancy related tasks if context.settings.get("multitenant.enabled"): - LOGGER.trace("Multitenant is enabled. Binding MultitenantManagerProvider.") + LOGGER.debug("Multitenant is enabled. Binding MultitenantManagerProvider.") context.injector.bind_provider( BaseMultitenantManager, MultitenantManagerProvider(self.root_profile) ) # Bind route manager provider - LOGGER.trace("Binding RouteManagerProvider.") + LOGGER.debug("Binding RouteManagerProvider.") context.injector.bind_provider( RouteManager, RouteManagerProvider(self.root_profile) ) # Bind OobMessageProcessor to be able to receive and process unencrypted messages - LOGGER.trace("Binding OobMessageProcessor.") + LOGGER.debug("Binding OobMessageProcessor.") context.injector.bind_instance( OobMessageProcessor, OobMessageProcessor(inbound_message_router=self.inbound_message_router), ) # Bind default PyLD document loader - LOGGER.trace("Binding default DocumentLoader.") + LOGGER.debug("Binding default DocumentLoader.") context.injector.bind_instance(DocumentLoader, DocumentLoader(self.root_profile)) # Admin API if context.settings.get("admin.enabled"): - LOGGER.trace("Admin API is enabled. Attempting to register admin server.") + LOGGER.debug("Admin API is enabled. Attempting to register admin server.") try: admin_host = context.settings.get("admin.host", "0.0.0.0") admin_port = context.settings.get("admin.port", "80") @@ -297,7 +294,7 @@ async def setup(self): # Fetch stats collector, if any collector = context.inject_or(Collector) if collector: - LOGGER.trace("Stats collector found. Wrapping methods for collection.") + LOGGER.debug("Stats collector found. Wrapping methods for collection.") # add stats to our own methods collector.wrap( self, @@ -316,7 +313,7 @@ async def setup(self): "find_inbound_connection", ), ) - LOGGER.trace("Methods wrapped with stats collector.") + LOGGER.debug("Methods wrapped with stats collector.") async def start(self) -> None: """Start the agent.""" @@ -324,28 +321,28 @@ async def start(self) -> None: assert self.root_profile, "root_profile is not set" context = self.root_profile.context await self.check_for_valid_wallet_type(self.root_profile) - LOGGER.trace("Wallet type validated.") + LOGGER.debug("Wallet type validated.") if not context.settings.get("transport.disabled"): # Start up transports if enabled try: - LOGGER.trace("Transport not disabled. Starting inbound transports.") + LOGGER.debug("Transport not disabled. Starting inbound transports.") await self.inbound_transport_manager.start() - LOGGER.trace("Inbound transports started successfully.") + LOGGER.debug("Inbound transports started successfully.") except Exception: LOGGER.exception("Unable to start inbound transports.") raise try: - LOGGER.trace("Starting outbound transports.") + LOGGER.debug("Starting outbound transports.") await self.outbound_transport_manager.start() - LOGGER.trace("Outbound transports started successfully.") + LOGGER.debug("Outbound transports started successfully.") except Exception: LOGGER.exception("Unable to start outbound transports.") raise # Start up Admin server if self.admin_server: - LOGGER.trace("Admin server present. Starting admin server.") + LOGGER.debug("Admin server present. Starting admin server.") try: await self.admin_server.start() LOGGER.debug("Admin server started successfully.") @@ -359,7 +356,7 @@ async def start(self) -> None: self.admin_server.outbound_message_router, ) context.injector.bind_instance(BaseResponder, responder) - LOGGER.trace("Admin responder bound to injector.") + LOGGER.debug("Admin responder bound to injector.") # Get agent label default_label = context.settings.get("default_label") @@ -388,7 +385,7 @@ async def start(self) -> None: from_version_storage = None from_version = None agent_version = f"v{__version__}" - LOGGER.trace("Recording ACA-Py version in wallet if needed.") + LOGGER.debug("Recording ACA-Py version in wallet if needed.") async with self.root_profile.session() as session: storage: BaseStorage = session.context.inject(BaseStorage) try: @@ -408,7 +405,7 @@ async def start(self) -> None: force_upgrade_flag = ( self.root_profile.settings.get("upgrade.force_upgrade") or False ) - LOGGER.trace( + LOGGER.debug( "Force upgrade flag: %s, From version config: %s", force_upgrade_flag, from_version_config, @@ -424,12 +421,12 @@ async def start(self) -> None: from_version = from_version_storage else: from_version = from_version_config - LOGGER.trace( + LOGGER.debug( "Determined from_version based on force_upgrade: %s", from_version ) else: from_version = from_version_storage or from_version_config - LOGGER.trace("Determined from_version: %s", from_version) + LOGGER.debug("Determined from_version: %s", from_version) if not from_version: LOGGER.warning( @@ -441,13 +438,13 @@ async def start(self) -> None: ) from_version = DEFAULT_ACAPY_VERSION self.root_profile.settings.set_value("upgrade.from_version", from_version) - LOGGER.trace("Set upgrade.from_version to default: %s", from_version) + LOGGER.debug("Set upgrade.from_version to default: %s", from_version) config_available_list = get_upgrade_version_list( config_path=self.root_profile.settings.get("upgrade.config_path"), from_version=from_version, ) - LOGGER.trace("Available upgrade versions: %s", config_available_list) + LOGGER.debug("Available upgrade versions: %s", config_available_list) if len(config_available_list) >= 1: LOGGER.info("Upgrade configurations available. Initiating upgrade.") @@ -520,7 +517,6 @@ async def start(self) -> None: qr.add_data(invite_url) qr.print_ascii(invert=True) del mgr - LOGGER.trace("Invitation created and QR code printed.") except Exception: LOGGER.exception("Error creating invitation.") @@ -548,7 +544,7 @@ async def start(self) -> None: try: if not mediation_invite_record.used: # clear previous mediator configuration before establishing a new one - LOGGER.trace( + LOGGER.debug( "Mediation invite not used. " "Clearing default mediator before accepting new invite." ) @@ -566,7 +562,7 @@ async def start(self) -> None: await MediationInviteStore( session.context.inject(BaseStorage) ).mark_default_invite_as_used() - LOGGER.trace("Marked mediation invite as used.") + LOGGER.debug("Marked mediation invite as used.") await record.metadata_set( session, MediationManager.SEND_REQ_AFTER_CONNECTION, True @@ -574,11 +570,11 @@ async def start(self) -> None: await record.metadata_set( session, MediationManager.SET_TO_DEFAULT_ON_GRANTED, True ) - LOGGER.trace("Set mediation metadata after connection.") + LOGGER.debug("Set mediation metadata after connection.") LOGGER.info("Attempting to connect to mediator...") del mgr - LOGGER.trace("Mediation manager deleted after setting up mediator.") + LOGGER.debug("Mediation manager deleted after setting up mediator.") except Exception: LOGGER.exception("Error accepting mediation invitation.") @@ -592,7 +588,7 @@ async def start(self) -> None: ) # notify protocols of startup status - LOGGER.trace("Notifying protocols of startup status.") + LOGGER.debug("Notifying protocols of startup status.") await self.root_profile.notify(STARTUP_EVENT_TOPIC, {}) LOGGER.debug("Startup notification sent.") @@ -607,16 +603,16 @@ async def stop(self, timeout=1.0): shutdown = TaskQueue() if self.dispatcher: - LOGGER.trace("Initiating shutdown of dispatcher.") + LOGGER.debug("Initiating shutdown of dispatcher.") shutdown.run(self.dispatcher.complete()) if self.admin_server: - LOGGER.trace("Initiating shutdown of admin server.") + LOGGER.debug("Initiating shutdown of admin server.") shutdown.run(self.admin_server.stop()) if self.inbound_transport_manager: - LOGGER.trace("Initiating shutdown of inbound transport manager.") + LOGGER.debug("Initiating shutdown of inbound transport manager.") shutdown.run(self.inbound_transport_manager.stop()) if self.outbound_transport_manager: - LOGGER.trace("Initiating shutdown of outbound transport manager.") + LOGGER.debug("Initiating shutdown of outbound transport manager.") shutdown.run(self.outbound_transport_manager.stop()) if self.root_profile: @@ -625,12 +621,12 @@ async def stop(self, timeout=1.0): if multitenant_mgr: LOGGER.debug("Closing multitenant profiles.") for profile in multitenant_mgr.open_profiles: - LOGGER.trace("Closing profile: %s", profile.name) + LOGGER.debug("Closing profile: %s", profile.name) shutdown.run(profile.close()) LOGGER.debug("Closing root profile.") shutdown.run(self.root_profile.close()) - LOGGER.trace("Waiting for shutdown tasks to complete with timeout=%f.", timeout) + LOGGER.debug("Waiting for shutdown tasks to complete with timeout=%f.", timeout) await shutdown.complete(timeout) LOGGER.info("Conductor agent stopped successfully.") diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 542203c819..4b6b31d99e 100644 --- a/acapy_agent/core/plugin_registry.py +++ b/acapy_agent/core/plugin_registry.py @@ -6,7 +6,6 @@ from typing import Optional, Sequence, Set from ..config.injection_context import InjectionContext -from ..config.logging.utils import add_trace_level from ..core.event_bus import EventBus from ..utils.classloader import ClassLoader, ModuleLoadError from .error import ProtocolDefinitionValidationError @@ -14,7 +13,6 @@ from .protocol_registry import ProtocolRegistry LOGGER = logging.getLogger(__name__) -add_trace_level() # Allow trace logs from this module class PluginRegistry: @@ -132,7 +130,7 @@ def register_plugin(self, module_name: str) -> Optional[ModuleType]: if self._is_valid_plugin(mod, module_name): self._plugins[module_name] = mod - LOGGER.trace("Registered plugin: %s", module_name) + LOGGER.debug("Registered plugin: %s", module_name) return mod LOGGER.debug("Failed to register plugin: %s", module_name) @@ -141,7 +139,7 @@ def register_plugin(self, module_name: str) -> Optional[ModuleType]: def _is_already_registered(self, module_name: str) -> bool: """Check if the plugin is already registered.""" if module_name in self._plugins: - LOGGER.trace("Plugin %s is already registered.", module_name) + LOGGER.debug("Plugin %s is already registered.", module_name) return True return False @@ -165,7 +163,7 @@ 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.trace("Plugin %s has a 'setup' method.", module_name) + LOGGER.debug("Plugin %s has a 'setup' method.", module_name) return True # Check for 'routes' or 'message_types' modules @@ -174,7 +172,7 @@ 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.trace("Plugin %s has 'routes' or 'message_types'.", module_name) + LOGGER.debug("Plugin %s has 'routes' or 'message_types'.", module_name) return True # Check for 'definition' module with 'versions' attribute @@ -196,7 +194,7 @@ def _is_valid_plugin(self, mod: ModuleType, module_name: str) -> bool: # Validate the 'versions' attribute try: self.validate_version(definition.versions, module_name) - LOGGER.trace("Plugin %s has valid versions.", module_name) + LOGGER.debug("Plugin %s has valid versions.", module_name) return True except ProtocolDefinitionValidationError as e: LOGGER.error( @@ -208,7 +206,7 @@ def _is_valid_plugin(self, mod: ModuleType, module_name: str) -> bool: def register_package(self, package_name: str) -> Sequence[ModuleType]: """Register all modules (sub-packages) under a given package name.""" - LOGGER.trace("Registering package: %s", package_name) + LOGGER.debug("Registering package: %s", package_name) try: module_names = ClassLoader.scan_subpackages(package_name) except ModuleLoadError: @@ -219,28 +217,28 @@ 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.trace("Skipping test module: %s", module_name) + LOGGER.debug("Skipping test module: %s", module_name) continue plugin = self.register_plugin(module_name) if plugin: registered_plugins.append(plugin) else: - LOGGER.trace("Failed to register %s under %s", module_name, package_name) + LOGGER.debug("Failed to register %s under %s", module_name, package_name) return registered_plugins async def init_context(self, context: InjectionContext) -> None: """Call plugin setup methods on the current context.""" - LOGGER.trace("Initializing plugin context for %d plugins", len(self._plugins)) + 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.trace("Running setup for plugin: %s", plugin_name) + LOGGER.debug("Running setup for plugin: %s", plugin_name) await plugin.setup(context) else: - LOGGER.trace( + LOGGER.debug( "Loading protocols for plugin without setup: %s", plugin_name ) await self.load_protocols(context, plugin) @@ -259,55 +257,55 @@ async def load_protocol_version( goal_code_registry = context.inject(GoalCodeRegistry) module_name = mod.__name__ - LOGGER.trace("Loading protocol version for module: %s", module_name) + LOGGER.debug("Loading protocol version for module: %s", module_name) if hasattr(mod, "MESSAGE_TYPES"): - LOGGER.trace("Registering message types for: %s", module_name) + 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.trace("Registering controllers for: %s", module_name) + 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.trace("Loading protocols for plugin: %s", 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.trace("Attempting to load message types from: %s", message_types_path) + 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.trace("Found non-versioned message types for: %s", plugin_name) + 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.trace("Attempting to load definition from: %s", definition_path) + 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.trace("Loading versioned protocols for: %s", plugin_name) + 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.trace("Loading message types from: %s", version_path) + LOGGER.debug("Loading message types from: %s", version_path) mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: LOGGER.error( @@ -324,20 +322,20 @@ async def load_protocols(self, context: InjectionContext, plugin: ModuleType) -> async def register_admin_routes(self, app) -> None: """Call route registration methods on the current context.""" - LOGGER.trace("Registering admin routes for %d plugins", len(self._plugins)) + LOGGER.debug("Registering admin routes for %d plugins", len(self._plugins)) for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.trace("Processing routes for plugin: %s", 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.trace("Loading versioned routes for: %s", plugin_name) + 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.trace("Loading routes from: %s", version_path) + LOGGER.debug("Loading routes from: %s", version_path) mod = ClassLoader.load_module(version_path) except ModuleLoadError as e: LOGGER.error( @@ -346,25 +344,25 @@ async def register_admin_routes(self, app) -> None: continue if mod and hasattr(mod, "register"): - LOGGER.trace("Registering routes for: %s", plugin_name) + 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.trace("Loading non-versioned routes from: %s", routes_path) + 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.trace("Registering routes for: %s", plugin_name) + LOGGER.debug("Registering routes for: %s", plugin_name) await mod.register(app) def register_protocol_events(self, context: InjectionContext) -> None: """Call route register_events methods on the current context.""" - LOGGER.trace("Registering protocol events for %d plugins", len(self._plugins)) + LOGGER.debug("Registering protocol events for %d plugins", len(self._plugins)) event_bus = context.inject_or(EventBus) if not event_bus: @@ -373,74 +371,74 @@ def register_protocol_events(self, context: InjectionContext) -> None: for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.trace("Processing events for plugin: %s", 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.trace("Loading versioned events for: %s", plugin_name) + 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.trace("Loading events from: %s", version_path) + 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.trace("Registering events from: %s", version_path) + 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.trace("Loading non-versioned events from: %s", routes_path) + 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.trace("Registering events from: %s", version_path) + LOGGER.debug("Registering events from: %s", version_path) mod.register_events(event_bus) def post_process_routes(self, app) -> None: """Call route binary file response OpenAPI fixups if applicable.""" - LOGGER.trace("Post-processing routes for %d plugins", len(self._plugins)) + LOGGER.debug("Post-processing routes for %d plugins", len(self._plugins)) for plugin in self._plugins.values(): plugin_name = plugin.__name__ - LOGGER.trace("Post-processing routes for plugin: %s", 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.trace("Processing versioned routes for: %s", plugin_name) + 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.trace("Loading routes from: %s", version_path) + 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.trace("Post-processing routes for %s", plugin_name) + 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.trace("Loading non-versioned routes from: %s", routes_path) + 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.trace("Post-processing routes for %s", plugin_name) + 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 cac6135d3d..f9d1bc0c3d 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -8,11 +8,9 @@ from types import ModuleType from typing import Optional, Sequence, Type -from ..config.logging.utils import add_trace_level from ..core.error import BaseError LOGGER = logging.getLogger(__name__) -add_trace_level() # Allow trace logs from this module class ModuleLoadError(BaseError): @@ -43,49 +41,53 @@ def load_module( ModuleLoadError: If there was an error loading the module """ - LOGGER.trace("Attempting to load module: %s with package: %s", mod_path, package) + LOGGER.debug( + "Attempting to load module: %s%s", + mod_path, + f" with package: {package}" if package else "", + ) if package: - LOGGER.trace("Preloading parent package: %s", package) + LOGGER.debug("Preloading parent package: %s", package) # preload parent package if not cls.load_module(package): - LOGGER.trace("Failed to preload parent package: %s", package) + LOGGER.debug("Failed to preload parent package: %s", package) return None # must treat as a relative import if not mod_path.startswith("."): mod_path = f".{mod_path}" - LOGGER.trace("Adjusted mod_path for relative import: %s", mod_path) + LOGGER.debug("Adjusted mod_path for relative import: %s", mod_path) full_path = resolve_name(mod_path, package) - LOGGER.trace("Resolved full module path: %s", full_path) + LOGGER.debug("Resolved full module path: %s", full_path) if full_path in sys.modules: - LOGGER.trace("Module %s is already loaded", full_path) + LOGGER.debug("Module %s is already loaded", full_path) return sys.modules[full_path] if "." in mod_path: parent_mod_path, mod_name = mod_path.rsplit(".", 1) - LOGGER.trace( + LOGGER.debug( "Parent module path: %s, Module name: %s", parent_mod_path, mod_name ) if parent_mod_path and parent_mod_path[-1] != ".": parent_mod = cls.load_module(parent_mod_path, package) if not parent_mod: - LOGGER.trace("Failed to load parent module: %s", parent_mod_path) + LOGGER.debug("Failed to load parent module: %s", parent_mod_path) return None package = parent_mod.__name__ mod_path = f".{mod_name}" - LOGGER.trace("Adjusted mod_path after loading parent: %s", mod_path) + LOGGER.debug("Adjusted mod_path after loading parent: %s", mod_path) # Load the module spec first - LOGGER.trace("Finding spec for module: %s with package: %s", mod_path, package) + LOGGER.debug("Finding spec for module: %s with package: %s", mod_path, package) spec = find_spec(mod_path, package) if not spec: - LOGGER.trace("Module spec not found for: %s", mod_path) + LOGGER.debug("Module spec not found for: %s", mod_path) return None try: - LOGGER.trace("Importing module: %s with package: %s", mod_path, package) + LOGGER.debug("Importing module: %s with package: %s", mod_path, package) return import_module(mod_path, package) except ModuleNotFoundError as e: LOGGER.warning("Module %s not found during import", full_path) @@ -114,7 +116,7 @@ def load_class( """ - LOGGER.trace( + LOGGER.debug( "Attempting to load class: %s with default_module: %s and package: %s", class_name, default_module, @@ -124,14 +126,14 @@ def load_class( if "." in class_name: # import module and find class mod_path, class_name = class_name.rsplit(".", 1) - LOGGER.trace( + LOGGER.debug( "Extracted module path: %s, class name: %s from full class path", mod_path, class_name, ) elif default_module: mod_path = default_module - LOGGER.trace("No module in class name, using default_module: %s", mod_path) + LOGGER.debug("No module in class name, using default_module: %s", mod_path) else: LOGGER.warning( "Cannot resolve class name %s with no default module", class_name @@ -160,7 +162,7 @@ def load_class( raise ClassNotFoundError( f"Resolved value is not a class: {mod_path}.{class_name}" ) - LOGGER.trace("Successfully loaded class %s from module %s", class_name, mod_path) + LOGGER.debug("Successfully loaded class %s from module %s", class_name, mod_path) return resolved @classmethod @@ -183,7 +185,7 @@ def load_subclass_of( """ - LOGGER.trace( + LOGGER.debug( "Attempting to load subclass of %s from module %s with package %s", base_class.__name__, mod_path, @@ -201,7 +203,7 @@ def load_subclass_of( # Find the first declared class that inherits from the base_class try: - LOGGER.trace( + LOGGER.debug( "Inspecting classes in module %s for subclasses of %s", mod_path, base_class.__name__, @@ -211,13 +213,13 @@ def load_subclass_of( for name, obj in inspect.getmembers(mod, inspect.isclass) if issubclass(obj, base_class) and obj is not base_class ) - LOGGER.trace( + LOGGER.debug( "Found subclass %s of base class %s", imported_class.__name__, base_class.__name__, ) except StopIteration: - LOGGER.trace( + LOGGER.debug( "No subclass of %s found in module %s", base_class.__name__, mod_path, @@ -233,14 +235,14 @@ def scan_subpackages(cls, package: str) -> Sequence[str]: LOGGER.debug("Scanning subpackages under package %s", package) if "." in package: package, sub_pkg = package.split(".", 1) - LOGGER.trace("Extracted main package: %s, sub-package: %s", package, sub_pkg) + LOGGER.debug("Extracted main package: %s, sub-package: %s", package, sub_pkg) else: sub_pkg = "." - LOGGER.trace("No sub-package provided, defaulting to %s", sub_pkg) + LOGGER.debug("No sub-package provided, defaulting to %s", sub_pkg) try: package_path = resources.files(package) - LOGGER.trace("Found package path: %s", package_path) + LOGGER.debug("Found package path: %s", package_path) except FileNotFoundError: LOGGER.warning("Package %s not found during subpackage scan", package) raise ModuleLoadError(f"Undefined package {package}") @@ -252,12 +254,10 @@ def scan_subpackages(cls, package: str) -> Sequence[str]: found = [] joiner = "" if sub_pkg == "." else f"{sub_pkg}." sub_path = package_path / sub_pkg - LOGGER.trace("Iterating over items in sub-package path: %s", sub_path) for item in sub_path.iterdir(): if (item / "__init__.py").exists(): subpackage = f"{package}.{joiner}{item.name}" found.append(subpackage) - LOGGER.trace("Found sub-package: %s", subpackage) LOGGER.debug("Total sub-packages found under %s: %s", package, found) return found From 7b109c2bdbe7ab0b957e1fbb6609b2623313754c Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 27 Nov 2024 13:25:37 +0200 Subject: [PATCH 40/51] :sparkles: Add caching to ClassLoader.load_module Signed-off-by: ff137 --- acapy_agent/utils/classloader.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index f9d1bc0c3d..13e9d716f6 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -3,6 +3,7 @@ import inspect import logging import sys +from functools import lru_cache from importlib import import_module, resources from importlib.util import find_spec, resolve_name from types import ModuleType @@ -25,6 +26,7 @@ class ClassLoader: """Class used to load classes from modules dynamically.""" @classmethod + @lru_cache def load_module( cls, mod_path: str, package: Optional[str] = None ) -> Optional[ModuleType]: From f94192d59d0e0073c5906b587228a4a034d9a092 Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 27 Nov 2024 13:41:16 +0200 Subject: [PATCH 41/51] :art: Improve log Signed-off-by: ff137 --- acapy_agent/utils/classloader.py | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index 13e9d716f6..4bb6f18fec 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -119,10 +119,10 @@ def load_class( """ LOGGER.debug( - "Attempting to load class: %s with default_module: %s and package: %s", + "Attempting to load class: %s%s%s", class_name, - default_module, - package, + f", with default_module: {default_module}" if default_module else "", + f", with package: {package}" if package else "", ) if "." in class_name: From 9d64d0f3713605ac1dbfa3918e69a04840d1c64a Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 27 Nov 2024 23:36:35 +0200 Subject: [PATCH 42/51] :art: Reduce log verbosity Signed-off-by: ff137 --- acapy_agent/utils/classloader.py | 37 +------------------------------- 1 file changed, 1 insertion(+), 36 deletions(-) diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index 4bb6f18fec..3f1d35cf7f 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -50,46 +50,34 @@ def load_module( ) if package: - LOGGER.debug("Preloading parent package: %s", package) # preload parent package if not cls.load_module(package): - LOGGER.debug("Failed to preload parent package: %s", package) return None # must treat as a relative import if not mod_path.startswith("."): mod_path = f".{mod_path}" - LOGGER.debug("Adjusted mod_path for relative import: %s", mod_path) full_path = resolve_name(mod_path, package) - LOGGER.debug("Resolved full module path: %s", full_path) if full_path in sys.modules: - LOGGER.debug("Module %s is already loaded", full_path) return sys.modules[full_path] if "." in mod_path: parent_mod_path, mod_name = mod_path.rsplit(".", 1) - LOGGER.debug( - "Parent module path: %s, Module name: %s", parent_mod_path, mod_name - ) if parent_mod_path and parent_mod_path[-1] != ".": parent_mod = cls.load_module(parent_mod_path, package) if not parent_mod: - LOGGER.debug("Failed to load parent module: %s", parent_mod_path) return None package = parent_mod.__name__ mod_path = f".{mod_name}" - LOGGER.debug("Adjusted mod_path after loading parent: %s", mod_path) # Load the module spec first - LOGGER.debug("Finding spec for module: %s with package: %s", mod_path, package) spec = find_spec(mod_path, package) if not spec: - LOGGER.debug("Module spec not found for: %s", mod_path) return None try: - LOGGER.debug("Importing module: %s with package: %s", mod_path, package) + LOGGER.debug("Importing package: %s, module: %s", package, mod_path) return import_module(mod_path, package) except ModuleNotFoundError as e: LOGGER.warning("Module %s not found during import", full_path) @@ -128,11 +116,6 @@ def load_class( if "." in class_name: # import module and find class mod_path, class_name = class_name.rsplit(".", 1) - LOGGER.debug( - "Extracted module path: %s, class name: %s from full class path", - mod_path, - class_name, - ) elif default_module: mod_path = default_module LOGGER.debug("No module in class name, using default_module: %s", mod_path) @@ -187,13 +170,6 @@ def load_subclass_of( """ - LOGGER.debug( - "Attempting to load subclass of %s from module %s with package %s", - base_class.__name__, - mod_path, - package, - ) - mod = cls.load_module(mod_path, package) if not mod: LOGGER.warning( @@ -205,21 +181,11 @@ def load_subclass_of( # Find the first declared class that inherits from the base_class try: - LOGGER.debug( - "Inspecting classes in module %s for subclasses of %s", - mod_path, - base_class.__name__, - ) imported_class = next( obj for name, obj in inspect.getmembers(mod, inspect.isclass) if issubclass(obj, base_class) and obj is not base_class ) - LOGGER.debug( - "Found subclass %s of base class %s", - imported_class.__name__, - base_class.__name__, - ) except StopIteration: LOGGER.debug( "No subclass of %s found in module %s", @@ -244,7 +210,6 @@ def scan_subpackages(cls, package: str) -> Sequence[str]: try: package_path = resources.files(package) - LOGGER.debug("Found package path: %s", package_path) except FileNotFoundError: LOGGER.warning("Package %s not found during subpackage scan", package) raise ModuleLoadError(f"Undefined package {package}") From f1b8f7534988c4765b919c7a78dcb477758c9024 Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 27 Nov 2024 23:39:10 +0200 Subject: [PATCH 43/51] :sparkles: Add `lru_cache` to load_class and set maxsize Signed-off-by: ff137 --- acapy_agent/utils/classloader.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index 3f1d35cf7f..46cc21cf08 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -26,7 +26,7 @@ class ClassLoader: """Class used to load classes from modules dynamically.""" @classmethod - @lru_cache + @lru_cache(maxsize=1024) def load_module( cls, mod_path: str, package: Optional[str] = None ) -> Optional[ModuleType]: @@ -84,6 +84,7 @@ def load_module( raise ModuleLoadError(f"Unable to import module {full_path}: {str(e)}") from e @classmethod + @lru_cache(maxsize=1024) def load_class( cls, class_name: str, From 5f4c1e35dafdca61e4d0b18ac7d36c5277a97311 Mon Sep 17 00:00:00 2001 From: ff137 Date: Mon, 2 Dec 2024 10:55:34 +0200 Subject: [PATCH 44/51] :rewind: Revert addition of lru caching Signed-off-by: ff137 --- acapy_agent/utils/classloader.py | 3 --- 1 file changed, 3 deletions(-) diff --git a/acapy_agent/utils/classloader.py b/acapy_agent/utils/classloader.py index 46cc21cf08..d18ba458d8 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -3,7 +3,6 @@ import inspect import logging import sys -from functools import lru_cache from importlib import import_module, resources from importlib.util import find_spec, resolve_name from types import ModuleType @@ -26,7 +25,6 @@ class ClassLoader: """Class used to load classes from modules dynamically.""" @classmethod - @lru_cache(maxsize=1024) def load_module( cls, mod_path: str, package: Optional[str] = None ) -> Optional[ModuleType]: @@ -84,7 +82,6 @@ def load_module( raise ModuleLoadError(f"Unable to import module {full_path}: {str(e)}") from e @classmethod - @lru_cache(maxsize=1024) def load_class( cls, class_name: str, From c646d6849bfa02f9bd3f727067ac9d76bdf442e1 Mon Sep 17 00:00:00 2001 From: ff137 Date: Mon, 2 Dec 2024 10:59:27 +0200 Subject: [PATCH 45/51] :art: Update logs / reduce verbosity Signed-off-by: ff137 --- acapy_agent/core/plugin_registry.py | 44 +++-------------------------- acapy_agent/utils/classloader.py | 15 +--------- 2 files changed, 5 insertions(+), 54 deletions(-) diff --git a/acapy_agent/core/plugin_registry.py b/acapy_agent/core/plugin_registry.py index 4b6b31d99e..55bf1d08a1 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( @@ -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 d18ba458d8..0889f50dc8 100644 --- a/acapy_agent/utils/classloader.py +++ b/acapy_agent/utils/classloader.py @@ -41,11 +41,6 @@ def load_module( ModuleLoadError: If there was an error loading the module """ - LOGGER.debug( - "Attempting to load module: %s%s", - mod_path, - f" with package: {package}" if package else "", - ) if package: # preload parent package @@ -75,7 +70,6 @@ def load_module( return None try: - LOGGER.debug("Importing package: %s, module: %s", package, mod_path) return import_module(mod_path, package) except ModuleNotFoundError as e: LOGGER.warning("Module %s not found during import", full_path) @@ -104,13 +98,6 @@ def load_class( """ - LOGGER.debug( - "Attempting to load 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) @@ -223,7 +210,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 From 7f7b7d0792695b53187c114f3639b77af9cd2414 Mon Sep 17 00:00:00 2001 From: ff137 Date: Wed, 4 Dec 2024 15:06:39 +0200 Subject: [PATCH 46/51] :art: Reduce repetition Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index 33c50313f1..daf5dd21de 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -671,21 +671,18 @@ def dispatch_complete(self, message: InboundMessage, completed: CompletedTask): """Handle completion of message dispatch.""" if completed.exc_info: LOGGER.exception("Exception in message handler:", exc_info=completed.exc_info) - if isinstance(completed.exc_info[1], LedgerConfigError) or isinstance( - completed.exc_info[1], LedgerTransactionError - ): + exc_class, exc, _ = completed.exc_info + if isinstance(exc, (LedgerConfigError, LedgerTransactionError)): LOGGER.error( "%shutdown on ledger error %s", "S" if self.admin_server else "No admin server to s", - str(completed.exc_info[1]), + str(exc), ) if self.admin_server: self.admin_server.notify_fatal_error() else: LOGGER.error( - "DON'T shutdown on %s %s", - completed.exc_info[0].__name__, - str(completed.exc_info[1]), + "DON'T shutdown on %s %s", exc_class.__name__, str(exc) ) self.inbound_transport_manager.dispatch_complete(message, completed) From 199d5bbd2db64b4f8a0ad2473814dadeebb6b505 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 5 Dec 2024 11:50:27 +0200 Subject: [PATCH 47/51] :art: Log warning when StorageNotFoundError encountered, instead of exception stacktrace Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 13 ++++++++++--- .../v2_0/handlers/cred_problem_report_handler.py | 8 ++++++-- .../v2_0/handlers/pres_problem_report_handler.py | 8 ++++++-- 3 files changed, 22 insertions(+), 7 deletions(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index daf5dd21de..a7c2792e7d 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -13,6 +13,7 @@ import logging from typing import Optional +from aries_askar import AskarError from packaging import version as package_version from qrcode import QRCode @@ -670,7 +671,6 @@ def inbound_message_router( def dispatch_complete(self, message: InboundMessage, completed: CompletedTask): """Handle completion of message dispatch.""" if completed.exc_info: - LOGGER.exception("Exception in message handler:", exc_info=completed.exc_info) exc_class, exc, _ = completed.exc_info if isinstance(exc, (LedgerConfigError, LedgerTransactionError)): LOGGER.error( @@ -680,9 +680,16 @@ def dispatch_complete(self, message: InboundMessage, completed: CompletedTask): ) if self.admin_server: self.admin_server.notify_fatal_error() + elif isinstance(exc, (AskarError, StorageNotFoundError)): + LOGGER.warning( + "Storage error occurred in message handler: %s: %s", + exc_class.__name__, + str(exc), + exc_info=completed.exc_info, + ) else: - LOGGER.error( - "DON'T shutdown on %s %s", exc_class.__name__, str(exc) + LOGGER.exception( + "Exception in message handler:", exc_info=completed.exc_info ) self.inbound_transport_manager.dispatch_complete(message, completed) diff --git a/acapy_agent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py b/acapy_agent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py index b8f56f119d..f513496c79 100644 --- a/acapy_agent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py +++ b/acapy_agent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py @@ -40,7 +40,11 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context.message, context.connection_record.connection_id, ) - except (StorageError, StorageNotFoundError): + except StorageNotFoundError: + self._logger.warning( + "Record not found while processing issue-credential v2.0 problem report" + ) + except StorageError: self._logger.exception( - "Error processing issue-credential v2.0 problem report message" + "Storage error while processing issue-credential v2.0 problem report" ) diff --git a/acapy_agent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py b/acapy_agent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py index be4aab8620..e10df27e2e 100644 --- a/acapy_agent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py +++ b/acapy_agent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py @@ -34,7 +34,11 @@ async def handle(self, context: RequestContext, responder: BaseResponder): else None ), ) - except (StorageError, StorageNotFoundError): + except StorageNotFoundError: + self._logger.warning( + "Record not found while processing present-proof v2.0 problem report" + ) + except StorageError: self._logger.exception( - "Error processing present-proof v2.0 problem report message" + "Storage error while processing present-proof v2.0 problem report" ) From a108fb42bf976cfd648804d10436e1b97f1d7be4 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 5 Dec 2024 11:50:47 +0200 Subject: [PATCH 48/51] :art: Set Shutdown log level to fatal, with exc_info Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index a7c2792e7d..0fb7ab1cac 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -673,10 +673,11 @@ def dispatch_complete(self, message: InboundMessage, completed: CompletedTask): if completed.exc_info: exc_class, exc, _ = completed.exc_info if isinstance(exc, (LedgerConfigError, LedgerTransactionError)): - LOGGER.error( + LOGGER.fatal( "%shutdown on ledger error %s", "S" if self.admin_server else "No admin server to s", str(exc), + exc_info=completed.exc_info, ) if self.admin_server: self.admin_server.notify_fatal_error() From 88b23d1d6bb1e40313896851d92b6395fc4ebe56 Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 5 Dec 2024 11:53:50 +0200 Subject: [PATCH 49/51] :art: Log warning for bad credential format, instead of always exception stacktrace Signed-off-by: ff137 --- acapy_agent/protocols/issue_credential/v2_0/routes.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/acapy_agent/protocols/issue_credential/v2_0/routes.py b/acapy_agent/protocols/issue_credential/v2_0/routes.py index f1517cc0ed..c5eafc79ee 100644 --- a/acapy_agent/protocols/issue_credential/v2_0/routes.py +++ b/acapy_agent/protocols/issue_credential/v2_0/routes.py @@ -860,7 +860,12 @@ async def credential_exchange_send(request: web.BaseRequest): V20CredManagerError, V20CredFormatError, ) as err: - LOGGER.exception("Error preparing credential offer") + # Only log full exception for unexpected errors + if isinstance(err, (V20CredFormatError, V20CredManagerError)): + LOGGER.warning(f"Error preparing credential offer: {err.roll_up}") + else: + LOGGER.exception("Error preparing credential offer") + if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) From 5bb62373f793796e59a2287ba6f82308a1cca7fd Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 5 Dec 2024 11:54:12 +0200 Subject: [PATCH 50/51] :construction: Add exc_info to error log for debugging Signed-off-by: ff137 --- acapy_agent/core/dispatcher.py | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/acapy_agent/core/dispatcher.py b/acapy_agent/core/dispatcher.py index 962b69d97c..dfa476e444 100644 --- a/acapy_agent/core/dispatcher.py +++ b/acapy_agent/core/dispatcher.py @@ -176,9 +176,6 @@ async def handle_v1_message( inbound_message: The inbound message instance send_outbound: Async function to send outbound messages - # Raises: - # MessageParseError: If the message type version is not supported - Returns: The response from the handler @@ -193,7 +190,9 @@ async def handle_v1_message( except ProblemReportParseError: pass # avoid problem report recursion except MessageParseError as e: - self.logger.error(f"Message parsing failed: {str(e)}, sending problem report") + self.logger.error( + f"Message parsing failed: {str(e)}, sending problem report", exc_info=e + ) error_result = ProblemReport( description={ "en": str(e), From 143b9babc912afcafdf9d97a47bc792ef9a86d6f Mon Sep 17 00:00:00 2001 From: ff137 Date: Thu, 5 Dec 2024 14:33:54 +0200 Subject: [PATCH 51/51] :art: Replace AskarError with ProfileError Signed-off-by: ff137 --- acapy_agent/core/conductor.py | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-) diff --git a/acapy_agent/core/conductor.py b/acapy_agent/core/conductor.py index 0fb7ab1cac..a333f2c305 100644 --- a/acapy_agent/core/conductor.py +++ b/acapy_agent/core/conductor.py @@ -13,7 +13,6 @@ import logging from typing import Optional -from aries_askar import AskarError from packaging import version as package_version from qrcode import QRCode @@ -75,7 +74,7 @@ from ..wallet.anoncreds_upgrade import upgrade_wallet_to_anoncreds_if_requested from ..wallet.did_info import DIDInfo from .dispatcher import Dispatcher -from .error import StartupError +from .error import ProfileError, StartupError from .oob_processor import OobMessageProcessor from .util import SHUTDOWN_EVENT_TOPIC, STARTUP_EVENT_TOPIC @@ -681,7 +680,7 @@ def dispatch_complete(self, message: InboundMessage, completed: CompletedTask): ) if self.admin_server: self.admin_server.notify_fatal_error() - elif isinstance(exc, (AskarError, StorageNotFoundError)): + elif isinstance(exc, (ProfileError, StorageNotFoundError)): LOGGER.warning( "Storage error occurred in message handler: %s: %s", exc_class.__name__,