✨ Improve logging in core components

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):

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."""

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."""

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:

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:

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.info("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))
 
 

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)
 
 

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")
+
         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,18 +86,21 @@ 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(
                     "acapy_agent.tails.anoncreds_tails_server.AnonCredsTailsServer",
                 ),
             )
         else:
+            LOGGER.debug("Using Indy tails server")
             context.injector.bind_provider(
                 BaseTailsServer,
                 ClassProvider(
@@ -105,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"
-                #    ),
-                # )
             ),
         )
 
@@ -127,6 +129,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", [])
         )
@@ -137,19 +140,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",
@@ -165,26 +168,34 @@ 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")
 
-        if wallet_type == "askar-anoncreds":
-            register_anoncreds_plugins()
-        else:
-            register_askar_plugins()
+        register_plugins(default_plugins, "default")
 
         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()
+        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", []):
+            LOGGER.debug("Registering external plugin: %s", plugin_path)
             plugin_registry.register_plugin(plugin_path)
 
         # Register message protocols