Skip to content

Commit abc31d3

Browse files
ff137swcurran
andauthored
✨ Improve logging in core components (openwallet-foundation#3332)
* 🎨 Refactor `register_plugin` steps for maintainability Signed-off-by: ff137 <[email protected]> * 🎨 improve logging in register_package Signed-off-by: ff137 <[email protected]> * 🎨 Rename method and remove redundant main call Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> * 🔊 Add debug logging to Context Builder Signed-off-by: ff137 <[email protected]> * 🎨 Deduplicate registering list of plugins Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> * 🔊 Add debug logging to init_context Signed-off-by: ff137 <[email protected]> * 🔊 Add debug logging to load_protocol_version Signed-off-by: ff137 <[email protected]> * 🔊 Add debug logging to load_protocols Signed-off-by: ff137 <[email protected]> * 🔊 Add debug logging to register_admin_routes Signed-off-by: ff137 <[email protected]> * 🔊 Add debug logging to register_protocol_events Signed-off-by: ff137 <[email protected]> * 🔊 Add debug logging to post_process_routes Signed-off-by: ff137 <[email protected]> * 🎨 Replace print statements with info logs Signed-off-by: ff137 <[email protected]> * 🎨 Replace almost all print statements with info logs Signed-off-by: ff137 <[email protected]> * 🔊 Expand logging for Conductor setup Signed-off-by: ff137 <[email protected]> * 🎨 Correct to uphold previous "Module doesn't exist" log behaviour Signed-off-by: ff137 <[email protected]> * Revert "🎨 Rename method and remove redundant main call" This reverts commit 2f6526d. Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> * ✅ Fix test by adding __name__ to mock object Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> * ✨ Add custom trace log level Signed-off-by: ff137 <[email protected]> * 🎨 Ensure trace level can only be added once Signed-off-by: ff137 <[email protected]> * 🎨 Add Logger Signed-off-by: ff137 <[email protected]> * 🎨 Update newly added logs to be trace level instead of debug Signed-off-by: ff137 <[email protected]> * 🎨 Update newly added logs to be trace level instead of debug Signed-off-by: ff137 <[email protected]> * 🔊 Expand logging for Conductor start and stop Signed-off-by: ff137 <[email protected]> * ✅ Add unit tests for adding trace level functionality Signed-off-by: ff137 <[email protected]> * ✅ Reset the logging states before and after TestLoggingUtils is run Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> * 🐛 Handle case that load_module return type is Optional Signed-off-by: ff137 <[email protected]> * 🔊 Expand logging for ClassLoader Signed-off-by: ff137 <[email protected]> * 🔊 Log a warning if resource not found, instead of passing Signed-off-by: ff137 <[email protected]> * 🎨 Signed-off-by: ff137 <[email protected]> * 🎨 Enable trace logs for remaining modules Signed-off-by: ff137 <[email protected]> * 🐛 Fix registering and loading of modules Signed-off-by: ff137 <[email protected]> * 🔊 Expand logging for Ledger Configuration Signed-off-by: ff137 <[email protected]> * ⏪ Revert `trace` log changes, and move to debug level Signed-off-by: ff137 <[email protected]> * ✨ Add caching to ClassLoader.load_module Signed-off-by: ff137 <[email protected]> * 🎨 Improve log Signed-off-by: ff137 <[email protected]> * 🎨 Reduce log verbosity Signed-off-by: ff137 <[email protected]> * ✨ Add `lru_cache` to load_class and set maxsize Signed-off-by: ff137 <[email protected]> * ⏪ Revert addition of lru caching Signed-off-by: ff137 <[email protected]> * 🎨 Update logs / reduce verbosity Signed-off-by: ff137 <[email protected]> * 🎨 Reduce repetition Signed-off-by: ff137 <[email protected]> * 🎨 Log warning when StorageNotFoundError encountered, instead of exception stacktrace Signed-off-by: ff137 <[email protected]> * 🎨 Set Shutdown log level to fatal, with exc_info Signed-off-by: ff137 <[email protected]> * 🎨 Log warning for bad credential format, instead of always exception stacktrace Signed-off-by: ff137 <[email protected]> * 🚧 Add exc_info to error log for debugging Signed-off-by: ff137 <[email protected]> * 🎨 Replace AskarError with ProfileError Signed-off-by: ff137 <[email protected]> * 🔊 Reduce noisy debug logs Signed-off-by: ff137 <[email protected]> * 🎨 Re-add some worthwhile comments Signed-off-by: ff137 <[email protected]> * 🎨 Still log "Incoming request" for status checks Signed-off-by: ff137 <[email protected]> --------- Signed-off-by: ff137 <[email protected]> Co-authored-by: Stephen Curran <[email protected]>
1 parent 38f3af8 commit abc31d3

File tree

22 files changed

+460
-203
lines changed

22 files changed

+460
-203
lines changed

acapy_agent/__main__.py

Lines changed: 9 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,8 +1,11 @@
11
"""acapy_agent package entry point."""
22

3+
import logging
34
import os
45
import sys
56

7+
LOGGER = logging.getLogger(__name__)
8+
69

710
def init_debug(args):
811
"""Initialize debugging environment."""
@@ -26,16 +29,18 @@ def init_debug(args):
2629
import debugpy
2730

2831
debugpy.listen((DAP_HOST, DAP_PORT))
29-
print(f"=== Waiting for debugger to attach to {DAP_HOST}:{DAP_PORT} ===")
32+
LOGGER.info(
33+
f"=== Waiting for debugger to attach to {DAP_HOST}:{DAP_PORT} ==="
34+
)
3035
debugpy.wait_for_client()
3136
except ImportError:
32-
print("debugpy library was not found")
37+
LOGGER.error("debugpy library was not found")
3338

3439
if ENABLE_PYDEVD_PYCHARM or "--debug-pycharm" in args:
3540
try:
3641
import pydevd_pycharm
3742

38-
print(
43+
LOGGER.info(
3944
"aca-py remote debugging to "
4045
f"{PYDEVD_PYCHARM_HOST}:{PYDEVD_PYCHARM_AGENT_PORT}"
4146
)
@@ -47,7 +52,7 @@ def init_debug(args):
4752
suspend=False,
4853
)
4954
except ImportError:
50-
print("pydevd_pycharm library was not found")
55+
LOGGER.error("pydevd_pycharm library was not found")
5156

5257

5358
def run(args):

acapy_agent/admin/server.py

Lines changed: 8 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -226,11 +226,14 @@ async def upgrade_middleware(request: web.BaseRequest, handler: Coroutine):
226226
async def debug_middleware(request: web.BaseRequest, handler: Coroutine):
227227
"""Show request detail in debug log."""
228228

229-
if LOGGER.isEnabledFor(logging.DEBUG):
230-
LOGGER.debug(f"Incoming request: {request.method} {request.path_qs}")
231-
LOGGER.debug(f"Match info: {request.match_info}")
232-
body = await request.text() if request.body_exists else None
233-
LOGGER.debug(f"Body: {body}")
229+
if LOGGER.isEnabledFor(logging.DEBUG): # Skipped if DEBUG is not enabled
230+
LOGGER.debug("Incoming request: %s %s", request.method, request.path_qs)
231+
is_status_check = str(request.rel_url).startswith("/status/")
232+
if not is_status_check: # Don't log match info for status checks; reduces noise
233+
LOGGER.debug("Match info: %s", request.match_info)
234+
235+
if request.body_exists: # Only log body if it exists
236+
LOGGER.debug("Body: %s", await request.text())
234237

235238
return await handler(request)
236239

acapy_agent/anoncreds/default/did_indy/registry.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,7 @@ def supported_identifiers_regex(self) -> Pattern:
4242

4343
async def setup(self, context: InjectionContext):
4444
"""Setup."""
45-
print("Successfully registered DIDIndyRegistry")
45+
LOGGER.info("Successfully registered DIDIndyRegistry")
4646

4747
async def get_schema(self, profile: Profile, schema_id: str) -> GetSchemaResult:
4848
"""Get a schema from the registry."""

acapy_agent/anoncreds/default/did_web/registry.py

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
"""DID Web Registry."""
22

3+
import logging
34
import re
45
from typing import Optional, Pattern, Sequence
56

@@ -18,6 +19,8 @@
1819
from ...models.schema import AnonCredsSchema, GetSchemaResult, SchemaResult
1920
from ...models.schema_info import AnoncredsSchemaInfo
2021

22+
LOGGER = logging.getLogger(__name__)
23+
2124

2225
class DIDWebRegistry(BaseAnonCredsResolver, BaseAnonCredsRegistrar):
2326
"""DIDWebRegistry."""
@@ -41,7 +44,7 @@ def supported_identifiers_regex(self) -> Pattern:
4144

4245
async def setup(self, context: InjectionContext):
4346
"""Setup."""
44-
print("Successfully registered DIDWebRegistry")
47+
LOGGER.info("Successfully registered DIDWebRegistry")
4548

4649
async def get_schema(self, profile, schema_id: str) -> GetSchemaResult:
4750
"""Get a schema from the registry."""

acapy_agent/anoncreds/default/legacy_indy/registry.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -145,7 +145,7 @@ def supported_identifiers_regex(self) -> Pattern:
145145

146146
async def setup(self, context: InjectionContext):
147147
"""Setup."""
148-
print("Successfully registered LegacyIndyRegistry")
148+
LOGGER.info("Successfully registered LegacyIndyRegistry")
149149

150150
@staticmethod
151151
def make_schema_id(schema: AnonCredsSchema) -> str:

acapy_agent/commands/provision.py

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
"""Provision command for setting up agent settings before starting."""
22

33
import asyncio
4+
import logging
45
from typing import Sequence
56

67
from configargparse import ArgumentParser
@@ -22,6 +23,8 @@
2223
from ..storage.base import BaseStorage
2324
from . import PROG
2425

26+
LOGGER = logging.getLogger(__name__)
27+
2528

2629
class ProvisionError(BaseError):
2730
"""Base exception for provisioning errors."""
@@ -58,9 +61,9 @@ async def provision(settings: dict):
5861
)
5962

6063
if await ledger_config(root_profile, public_did and public_did.did, True):
61-
print("Ledger configured")
64+
LOGGER.info("Ledger configured")
6265
else:
63-
print("Ledger not configured")
66+
LOGGER.warning("Ledger not configured")
6467

6568
await root_profile.close()
6669
except BaseError as e:

acapy_agent/commands/start.py

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,7 +31,7 @@ async def start_app(conductor: Conductor):
3131

3232
async def shutdown_app(conductor: Conductor):
3333
"""Shut down."""
34-
print("\nShutting down")
34+
LOGGER.info("Shutting down")
3535
await conductor.stop()
3636

3737

@@ -59,7 +59,7 @@ def execute(argv: Sequence[str] = None):
5959
# Run the application
6060
if uvloop:
6161
uvloop.install()
62-
print("uvloop installed")
62+
LOGGER.info("uvloop installed")
6363
run_loop(start_app(conductor), shutdown_app(conductor))
6464

6565

acapy_agent/config/argparse.py

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,7 @@ def get_registered(cls, category: Optional[str] = None):
6363

6464

6565
def create_argument_parser(*, prog: Optional[str] = None):
66-
"""Create am instance of an arg parser, force yaml format for external config."""
66+
"""Create an instance of an arg parser, force yaml format for external config."""
6767
return ArgumentParser(config_file_parser_class=YAMLConfigFileParser, prog=prog)
6868

6969

acapy_agent/config/default_context.py

Lines changed: 7 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -36,11 +36,14 @@ class DefaultContextBuilder(ContextBuilder):
3636

3737
async def build_context(self) -> InjectionContext:
3838
"""Build the base injection context; set DIDComm prefix to emit."""
39+
LOGGER.debug("Building new injection context")
40+
3941
context = InjectionContext(settings=self.settings)
4042
context.settings.set_default("default_label", "Aries Cloud Agent")
4143

4244
if context.settings.get("timing.enabled"):
4345
timing_log = context.settings.get("timing.log_file")
46+
LOGGER.debug("Enabling timing collector with log file: %s", timing_log)
4447
collector = Collector(log_path=timing_log)
4548
context.injector.bind_instance(Collector, collector)
4649

@@ -67,6 +70,7 @@ async def build_context(self) -> InjectionContext:
6770

6871
# DIDComm Messaging
6972
if context.settings.get("experiment.didcomm_v2"):
73+
LOGGER.info("DIDComm v2 experimental mode enabled")
7074
from didcomm_messaging import CryptoService, PackagingService, RoutingService
7175
from didcomm_messaging.crypto.backend.askar import AskarCryptoService
7276

@@ -81,19 +85,15 @@ async def build_context(self) -> InjectionContext:
8185

8286
async def bind_providers(self, context: InjectionContext):
8387
"""Bind various class providers."""
88+
LOGGER.debug("Begin binding providers to context")
8489

8590
context.injector.bind_provider(ProfileManager, ProfileManagerProvider())
8691

8792
# Register default pack format
8893
context.injector.bind_provider(
8994
BaseWireFormat,
9095
CachedProvider(
91-
# StatsProvider(
9296
ClassProvider("acapy_agent.transport.pack_format.PackWireFormat"),
93-
# (
94-
# "encode_message", "parse_message"
95-
# ),
96-
# )
9797
),
9898
)
9999

@@ -110,6 +110,7 @@ async def bind_providers(self, context: InjectionContext):
110110
async def load_plugins(self, context: InjectionContext):
111111
"""Set up plugin registry and load plugins."""
112112

113+
LOGGER.debug("Initializing plugin registry")
113114
plugin_registry = PluginRegistry(
114115
blocklist=self.settings.get("blocked_plugins", [])
115116
)
@@ -183,6 +184,7 @@ def register_anoncreds_plugins():
183184

184185
# Register external plugins
185186
for plugin_path in self.settings.get("external_plugins", []):
187+
LOGGER.debug("Registering external plugin: %s", plugin_path)
186188
plugin_registry.register_plugin(plugin_path)
187189

188190
# Register message protocols

acapy_agent/config/ledger.py

Lines changed: 29 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -33,14 +33,18 @@ async def fetch_genesis_transactions(genesis_url: str) -> str:
3333
# https://github.com/openwallet-foundation/acapy/issues/1745
3434
return await fetch(genesis_url, headers=headers, max_attempts=20)
3535
except FetchError as e:
36+
LOGGER.error("Error retrieving genesis transactions from %s: %s", genesis_url, e)
3637
raise ConfigError("Error retrieving ledger genesis transactions") from e
3738

3839

3940
async def get_genesis_transactions(settings: Settings) -> str:
4041
"""Fetch genesis transactions if necessary."""
4142

43+
LOGGER.debug("Getting genesis transactions from settings")
4244
txns = settings.get("ledger.genesis_transactions")
45+
LOGGER.debug("Genesis transactions from settings: %s", "found" if txns else "absent")
4346
if not txns:
47+
LOGGER.debug("No genesis transactions found in settings")
4448
if settings.get("ledger.genesis_url"):
4549
txns = await fetch_genesis_transactions(settings["ledger.genesis_url"])
4650
elif settings.get("ledger.genesis_file"):
@@ -50,8 +54,10 @@ async def get_genesis_transactions(settings: Settings) -> str:
5054
with open(genesis_path, "r") as genesis_file:
5155
txns = genesis_file.read()
5256
except IOError as e:
57+
LOGGER.error("Failed to read genesis file: %s", str(e))
5358
raise ConfigError("Error reading ledger genesis transactions") from e
5459
if txns:
60+
LOGGER.debug("Storing genesis transactions in settings")
5561
settings["ledger.genesis_transactions"] = txns
5662
return txns
5763

@@ -62,6 +68,8 @@ async def load_multiple_genesis_transactions_from_config(settings: Settings):
6268
ledger_config_list = settings.get("ledger.ledger_config_list")
6369
ledger_txns_list = []
6470
write_ledger_set = False
71+
LOGGER.debug("Processing %d ledger configs", len(ledger_config_list))
72+
6573
for config in ledger_config_list:
6674
txns = None
6775
if "genesis_transactions" in config:
@@ -73,11 +81,12 @@ async def load_multiple_genesis_transactions_from_config(settings: Settings):
7381
try:
7482
genesis_path = config.get("genesis_file")
7583
LOGGER.info(
76-
"Reading ledger genesis transactions from: %s", genesis_path
84+
"Reading ledger genesis transactions from file: %s", genesis_path
7785
)
7886
with open(genesis_path, "r") as genesis_file:
7987
txns = genesis_file.read()
8088
except IOError as e:
89+
LOGGER.error("Failed to read genesis file: %s", str(e))
8190
raise ConfigError("Error reading ledger genesis transactions") from e
8291
is_write_ledger = (
8392
False if config.get("is_write") is None else config.get("is_write")
@@ -118,13 +127,18 @@ async def load_multiple_genesis_transactions_from_config(settings: Settings):
118127
" genesis_file and genesis_transactions provided."
119128
)
120129
settings["ledger.ledger_config_list"] = ledger_txns_list
130+
LOGGER.debug("Processed %d ledger configs successfully", len(ledger_txns_list))
121131

122132

123133
async def ledger_config(
124134
profile: Profile, public_did: str, provision: bool = False
125135
) -> bool:
126136
"""Perform Indy ledger configuration."""
127137

138+
LOGGER.debug(
139+
"Configuring ledger for profile %s and public_did %s", profile.name, public_did
140+
)
141+
128142
session = await profile.session()
129143

130144
ledger = session.inject_or(BaseLedger)
@@ -135,32 +149,46 @@ async def ledger_config(
135149
async with ledger:
136150
# Check transaction author agreement acceptance
137151
if not ledger.read_only:
152+
LOGGER.debug("Checking transaction author agreement")
138153
taa_info = await ledger.get_txn_author_agreement()
139154
if taa_info["taa_required"] and public_did:
155+
LOGGER.debug("TAA acceptance required")
140156
taa_accepted = await ledger.get_latest_txn_author_acceptance()
141157
if (
142158
not taa_accepted
143159
or taa_info["taa_record"]["digest"] != taa_accepted["digest"]
144160
):
161+
LOGGER.info("TAA acceptance needed - performing acceptance")
145162
if not await accept_taa(ledger, profile, taa_info, provision):
163+
LOGGER.warning("TAA acceptance failed")
146164
return False
165+
LOGGER.info("TAA acceptance completed")
147166

148167
# Publish endpoints if necessary - skipped if TAA is required but not accepted
149168
endpoint = session.settings.get("default_endpoint")
150169
if public_did:
151170
wallet = session.inject(BaseWallet)
152171
try:
172+
LOGGER.debug("Setting DID endpoint to: %s", endpoint)
153173
await wallet.set_did_endpoint(public_did, endpoint, ledger)
154174
except LedgerError as x_ledger:
175+
LOGGER.error("Error setting DID endpoint: %s", x_ledger.message)
155176
raise ConfigError(x_ledger.message) from x_ledger # e.g., read-only
156177

157178
# Publish profile endpoint if ledger is NOT read-only
158179
profile_endpoint = session.settings.get("profile_endpoint")
159180
if profile_endpoint and not ledger.read_only:
181+
LOGGER.debug(
182+
"Publishing profile endpoint: %s for DID: %s",
183+
profile_endpoint,
184+
public_did,
185+
)
160186
await ledger.update_endpoint_for_did(
161187
public_did, profile_endpoint, EndpointType.PROFILE
162188
)
189+
LOGGER.info("Profile endpoint published successfully")
163190

191+
LOGGER.info("Ledger configuration complete")
164192
return True
165193

166194

0 commit comments

Comments
 (0)