From 8e9b0f2e96eb6f125278eb8e610a4fa82c2e8747 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Fri, 8 Sep 2023 04:14:00 +0530 Subject: [PATCH] WIP - rework with contextvar Signed-off-by: Shaanjot Gill --- Logging.md | 2 + aries_cloudagent/config/argparse.py | 63 ------- .../default_per_tenant_logging_config.ini | 27 +++ .../default_per_tenant_logging_config.yml | 23 +++ aries_cloudagent/config/ledger.py | 17 +- aries_cloudagent/config/logging.py | 177 ++++++++---------- .../config/tests/test_argparse.py | 33 ---- aries_cloudagent/config/tests/test_logging.py | 58 +++--- aries_cloudagent/config/util.py | 25 +-- aries_cloudagent/connections/base_manager.py | 32 ++-- aries_cloudagent/core/event_bus.py | 18 +- aries_cloudagent/core/oob_processor.py | 44 ++--- aries_cloudagent/indy/credx/holder.py | 9 +- aries_cloudagent/indy/credx/issuer.py | 15 +- aries_cloudagent/indy/credx/verifier.py | 10 +- aries_cloudagent/indy/sdk/issuer.py | 16 +- aries_cloudagent/indy/sdk/verifier.py | 18 +- aries_cloudagent/indy/verifier.py | 20 +- aries_cloudagent/ledger/indy.py | 10 +- .../ledger/multiple_ledger/indy_manager.py | 15 +- .../multiple_ledger/indy_vdr_manager.py | 14 +- aries_cloudagent/ledger/routes.py | 15 +- aries_cloudagent/multitenant/base.py | 14 +- aries_cloudagent/multitenant/cache.py | 8 +- aries_cloudagent/multitenant/route_manager.py | 15 +- .../v1_0/handlers/menu_request_handler.py | 7 - .../v1_0/handlers/perform_handler.py | 7 - .../protocols/actionmenu/v1_0/routes.py | 22 +-- .../v1_0/handlers/basicmessage_handler.py | 7 - .../handlers/connection_request_handler.py | 11 +- .../handlers/connection_response_handler.py | 9 +- .../protocols/connections/v1_0/manager.py | 9 +- .../v1_0/handlers/keylist_handler.py | 15 +- .../v1_0/handlers/keylist_query_handler.py | 9 +- .../v1_0/handlers/keylist_update_handler.py | 9 +- .../keylist_update_response_handler.py | 12 -- .../v1_0/handlers/mediation_deny_handler.py | 9 +- .../v1_0/handlers/mediation_grant_handler.py | 9 +- .../handlers/mediation_request_handler.py | 7 - .../coordinate_mediation/v1_0/manager.py | 12 +- .../v1_0/route_manager.py | 16 +- .../v1_0/tests/test_mediation_manager.py | 65 +++---- .../v1_0/handlers/complete_handler.py | 9 +- .../v1_0/handlers/request_handler.py | 11 +- .../v1_0/handlers/response_handler.py | 10 +- .../protocols/didexchange/v1_0/manager.py | 9 +- .../v1_0/handlers/disclose_handler.py | 8 +- .../discovery/v1_0/handlers/query_handler.py | 8 +- .../protocols/discovery/v1_0/manager.py | 9 +- .../v2_0/handlers/disclosures_handler.py | 8 +- .../v2_0/handlers/queries_handler.py | 8 +- .../protocols/discovery/v2_0/manager.py | 9 +- .../endorsed_transaction_response_handler.py | 8 +- .../refused_transaction_response_handler.py | 8 +- .../transaction_acknowledgement_handler.py | 8 +- .../handlers/transaction_cancel_handler.py | 8 +- .../transaction_job_to_send_handler.py | 8 +- .../handlers/transaction_request_handler.py | 8 +- .../handlers/transaction_resend_handler.py | 8 +- .../endorse_transaction/v1_0/routes.py | 8 +- .../introduction/v0_1/demo_service.py | 12 +- .../handlers/forward_invitation_handler.py | 8 +- .../v0_1/handlers/invitation_handler.py | 8 - .../handlers/invitation_request_handler.py | 8 +- .../protocols/introduction/v0_1/routes.py | 9 +- .../v1_0/handlers/credential_ack_handler.py | 8 +- .../v1_0/handlers/credential_issue_handler.py | 6 - .../v1_0/handlers/credential_offer_handler.py | 7 +- .../credential_problem_report_handler.py | 7 - .../handlers/credential_proposal_handler.py | 6 - .../handlers/credential_request_handler.py | 6 - .../issue_credential/v1_0/manager.py | 30 ++- .../v1_0/models/credential_exchange.py | 10 +- .../issue_credential/v2_0/formats/handler.py | 7 +- .../v2_0/handlers/cred_ack_handler.py | 8 +- .../v2_0/handlers/cred_issue_handler.py | 8 +- .../v2_0/handlers/cred_offer_handler.py | 9 +- .../handlers/cred_problem_report_handler.py | 7 - .../v2_0/handlers/cred_proposal_handler.py | 9 +- .../v2_0/handlers/cred_request_handler.py | 9 +- .../issue_credential/v2_0/manager.py | 10 +- .../v2_0/models/cred_ex_record.py | 10 +- .../v2_0/models/tests/test_cred_ex_record.py | 13 +- .../protocols/issue_credential/v2_0/routes.py | 65 +------ .../v2_0/tests/test_manager.py | 26 +-- .../v1_0/handlers/problem_report_handler.py | 8 +- .../v1_0/handlers/reuse_accept_handler.py | 8 +- .../v1_0/handlers/reuse_handler.py | 8 +- .../protocols/out_of_band/v1_0/manager.py | 41 ++-- .../present_proof/dif/pres_exch_handler.py | 16 +- .../present_proof/indy/pres_exch_handler.py | 10 +- .../v1_0/handlers/presentation_ack_handler.py | 8 +- .../v1_0/handlers/presentation_handler.py | 6 - .../presentation_problem_report_handler.py | 7 - .../handlers/presentation_proposal_handler.py | 6 - .../handlers/presentation_request_handler.py | 6 - .../protocols/present_proof/v1_0/manager.py | 14 +- .../v1_0/models/presentation_exchange.py | 10 +- .../present_proof/v2_0/formats/handler.py | 7 +- .../v2_0/handlers/pres_ack_handler.py | 8 +- .../v2_0/handlers/pres_handler.py | 8 +- .../handlers/pres_problem_report_handler.py | 7 - .../v2_0/handlers/pres_proposal_handler.py | 9 +- .../v2_0/handlers/pres_request_handler.py | 9 +- .../protocols/present_proof/v2_0/manager.py | 12 +- .../v2_0/models/pres_exchange.py | 10 +- .../v2_0/models/tests/test_record.py | 14 +- .../protocols/problem_report/v1_0/handler.py | 7 - .../v1_0/handlers/revoke_handler.py | 7 - .../revocation_notification/v1_0/routes.py | 12 +- .../v2_0/handlers/revoke_handler.py | 7 - .../revocation_notification/v2_0/routes.py | 12 +- .../routing/v1_0/handlers/forward_handler.py | 7 - .../protocols/routing/v1_0/manager.py | 28 +-- .../trustping/v1_0/handlers/ping_handler.py | 7 - .../v1_0/handlers/ping_response_handler.py | 8 +- .../resolver/default/universal.py | 11 +- aries_cloudagent/revocation/indy.py | 12 +- .../models/issuer_rev_reg_record.py | 41 ++-- aries_cloudagent/wallet/routes.py | 18 +- demo/runners/agent_container.py | 27 --- demo/runners/performance.py | 27 +-- demo/runners/support/agent.py | 14 -- demo/runners/support/utils.py | 6 +- 124 files changed, 479 insertions(+), 1396 deletions(-) create mode 100644 aries_cloudagent/config/default_per_tenant_logging_config.ini create mode 100644 aries_cloudagent/config/default_per_tenant_logging_config.yml diff --git a/Logging.md b/Logging.md index 66373e56df..7892409afc 100644 --- a/Logging.md +++ b/Logging.md @@ -12,6 +12,8 @@ Other log levels fall back to `WARNING`. * `--log-level` - The log level to log on std out. * `--log-file` - Path to a file to log to. + +## WIP - add config file details * `--log-handler-config` - Specifies `when`, `interval`, `backupCount` for the `TimedRotatingFileMultiProcessHandler`. These 3 attributes are passed as a `;` seperated string. For example, `when` of d (days), `interval` of 7 and `backupCount` of 1 will be passed as `D;7;1`. Note: `backupCount` of 0 will mean all backup log files will be retained and not deleted at all. More details about these attributes can be found [here](https://docs.python.org/3/library/logging.handlers.html#timedrotatingfilehandler). `TimedRotatingFileMultiProcessHandler` supports the ability to cleanup logs by time and mantain backup logs and a custom JSON formatter for logs. * `--log-fmt-pattern` - Specifies logging.Formatter pattern to override default patterns. * `--log-json-fmt` - Specifies whether to use JSON logging formatter or text logging formatter. Defaults to `False`. diff --git a/aries_cloudagent/config/argparse.py b/aries_cloudagent/config/argparse.py index ac38895254..143a521da6 100644 --- a/aries_cloudagent/config/argparse.py +++ b/aries_cloudagent/config/argparse.py @@ -1013,46 +1013,6 @@ def add_arguments(self, parser: ArgumentParser): "('debug', 'info', 'warning', 'error', 'critical')" ), ) - parser.add_argument( - "--log-handler-config", - dest="log_handler_config", - type=str, - metavar="", - default=None, - env_var="ACAPY_LOG_HANDLER_CONFIG", - help=( - "Specifies when, interval, backupCount for the " - "TimedRotatingFileHandler. These attributes are " - "passed as a ; seperated string. For example, " - "when of D (days), interval of 7 and backupCount " - "of 1 will be passed as 'D;7;1'. Note: " - "backupCount of 0 will mean all backup log files " - "will be retained and not deleted at all." - ), - ) - parser.add_argument( - "--log-fmt-pattern", - dest="log_fmt_pattern", - type=str, - metavar="", - default=None, - env_var="ACAPY_LOG_FMT_PATTERN", - help=( - "Specifies logging formatter pattern as string. Examples are included " - "in 'Logging.md'. For information regarding different attributes " - "supported in the pattern, please look at " - "https://docs.python.org/3/library/logging.html#logrecord-attributes." - ), - ) - parser.add_argument( - "--log-json-fmt", - action="store_true", - env_var="ACAPY_LOG_JSON_FMT", - help=( - "Specifies whether to use JSON logging formatter or " - "text logging formatter." - ), - ) def get_settings(self, args: Namespace) -> dict: """Extract logging settings.""" @@ -1063,29 +1023,6 @@ def get_settings(self, args: Namespace) -> dict: settings["log.file"] = args.log_file if args.log_level: settings["log.level"] = args.log_level - if args.log_handler_config: - try: - handler_config_attribs = (args.log_handler_config).split(";") - settings["log.handler_when"] = handler_config_attribs[0] - settings["log.handler_interval"] = int(handler_config_attribs[1]) - settings["log.handler_bakcount"] = int(handler_config_attribs[2]) - except IndexError: - raise ArgsParseError( - "With --log-handler-config, the provided argument must be " - "in 'when;interval;backupCount' format. Each of the 3 " - "attributes for TimedRotatingFileHandler must be specified." - ) - except ValueError: - raise ArgsParseError( - "With --log-handler-config, 'interval' and 'backupCount' " - "should be a number [int]" - ) - if args.log_fmt_pattern: - settings["log.fmt_pattern"] = args.log_fmt_pattern - if args.log_json_fmt: - settings["log.json_fmt"] = True - else: - settings["log.json_fmt"] = False return settings diff --git a/aries_cloudagent/config/default_per_tenant_logging_config.ini b/aries_cloudagent/config/default_per_tenant_logging_config.ini new file mode 100644 index 0000000000..8f207bb6a0 --- /dev/null +++ b/aries_cloudagent/config/default_per_tenant_logging_config.ini @@ -0,0 +1,27 @@ +[loggers] +keys=root + +[handlers] +keys=stream_handler, timed_file_handler + +[formatters] +keys=formatter + +[logger_root] +level=ERROR +handlers=stream_handler, timed_file_handler + +[handler_stream_handler] +class=StreamHandler +level=DEBUG +formatter=formatter +args=(sys.stderr,) + +[handler_timed_file_handler] +class=logging.handlers.TimedRotatingFileMultiProcessHandler +level=DEBUG +formatter=formatter +args=('acapy.log', 'd', 7, 1,) + +[formatter_formatter] +format=%(asctime)s %(wallet_id)s %(levelname)s %(pathname)s:%(lineno)d %(message)s \ No newline at end of file diff --git a/aries_cloudagent/config/default_per_tenant_logging_config.yml b/aries_cloudagent/config/default_per_tenant_logging_config.yml new file mode 100644 index 0000000000..3978766e48 --- /dev/null +++ b/aries_cloudagent/config/default_per_tenant_logging_config.yml @@ -0,0 +1,23 @@ +version: 1 +formatters: + default: + format: '%(asctime)s %(wallet_id)s %(levelname)s %(pathname)s:%(lineno)d %(message)s' +handlers: + console: + class: logging.StreamHandler + level: DEBUG + formatter: default + stream: ext://sys.stderr + rotating_file: + class: logging.handlers.TimedRotatingFileMultiProcessHandler + level: DEBUG + filename: 'acapy.log' + when: 'd' + interval: 7 + backupCount: 1 + formatter: default +root: + level: INFO + handlers: + - console + - rotating_file \ No newline at end of file diff --git a/aries_cloudagent/config/ledger.py b/aries_cloudagent/config/ledger.py index bce2985775..0007ecdba6 100644 --- a/aries_cloudagent/config/ledger.py +++ b/aries_cloudagent/config/ledger.py @@ -12,7 +12,6 @@ from prompt_toolkit.eventloop.defaults import use_asyncio_event_loop from prompt_toolkit.formatted_text import HTML -from ..config.logging import get_adapted_logger_inst from ..config.settings import Settings from ..core.profile import Profile from ..ledger.base import BaseLedger @@ -129,14 +128,9 @@ async def ledger_config( """Perform Indy ledger configuration.""" session = await profile.session() - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) ledger = session.inject_or(BaseLedger) if not ledger: - _logger.info("Ledger instance not provided") + LOGGER.info("Ledger instance not provided") return False async with ledger: @@ -257,11 +251,6 @@ async def accept_taa( mechanisms = taa_info["aml_record"]["aml"] mechanism = None - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) taa_acceptance_mechanism = profile.settings.get("ledger.taa_acceptance_mechanism") taa_acceptance_version = profile.settings.get("ledger.taa_acceptance_version") @@ -287,13 +276,13 @@ async def accept_taa( elif sys.stdout.isatty(): mechanism = await select_aml_tty(taa_info, provision) else: - _logger.warning( + LOGGER.warning( "Cannot accept TAA without interactive terminal or taa accept config" ) if not mechanism: return False - _logger.debug(f"Accepting the TAA using mechanism '{mechanism}'") + LOGGER.debug(f"Accepting the TAA using mechanism '{mechanism}'") await ledger.accept_txn_author_agreement(taa_info["taa_record"], mechanism) return True diff --git a/aries_cloudagent/config/logging.py b/aries_cloudagent/config/logging.py index cb673a6581..7dc6b9be96 100644 --- a/aries_cloudagent/config/logging.py +++ b/aries_cloudagent/config/logging.py @@ -1,16 +1,18 @@ """Utilities related to logging.""" +from contextvars import ContextVar from datetime import datetime, timedelta from io import TextIOWrapper import logging -from logging.config import fileConfig +from logging.config import fileConfig, dictConfig from logging.handlers import BaseRotatingHandler import os from random import randint import re import sys +import yaml import time as mod_time -from typing import Tuple, TextIO +from typing import TextIO import pkg_resources from portalocker import LOCK_EX, lock, unlock @@ -21,6 +23,7 @@ from .banner import Banner DEFAULT_LOGGING_CONFIG_PATH = "aries_cloudagent.config:default_logging_config.ini" +DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH = "./aries_cloudagent/config/default_per_tenant_logging_config.yml" LOG_FORMAT_FILE_ALIAS_PATTERN = ( "%(asctime)s %(wallet_id)s %(levelname)s %(pathname)s:%(lineno)d %(message)s" ) @@ -28,6 +31,24 @@ "%(asctime)s %(levelname)s %(pathname)s:%(lineno)d %(message)s" ) +context_wallet_id: ContextVar[str] = ContextVar("context_wallet_id") + + +class ContextFilter(logging.Filter): + """Custom logging Filter to adapt logs with contextual wallet_id.""" + + def __init__(self): + super(ContextFilter, self).__init__() + + def filter(self, record): + try: + wallet_id = context_wallet_id.get() + record.wallet_id= wallet_id + return True + except LookupError: + record.wallet_id= None + return True + def load_resource(path: str, encoding: str = None) -> TextIO: """Open a resource file located in a python package or the local filesystem. @@ -58,6 +79,8 @@ def configure( cls, logging_config_path: str = None, log_level: str = None, + log_file: str = None, + multitenant: bool = False, ): """Configure logger. @@ -66,77 +89,70 @@ def configure( :param log_level: str: (Default value = None) """ + is_dict_config = False if logging_config_path is not None: config_path = logging_config_path else: config_path = DEFAULT_LOGGING_CONFIG_PATH - - log_config = load_resource(config_path, "utf-8") - if log_config: - with log_config: - fileConfig(log_config, disable_existing_loggers=False) + if ".yml" in config_path or ".yaml" in config_path: + is_dict_config = True + with open(config_path, "r") as stream: + log_config = yaml.safe_load(stream) else: - logging.basicConfig(level=logging.WARNING) - logging.root.warning(f"Logging config file not found: {config_path}") - if log_level: - log_level = log_level.upper() - logging.root.setLevel(log_level) - - @classmethod - def configure_per_tenant( - cls, - logging_config_path: str = None, - log_level: str = None, - log_file: str = None, - log_interval: int = None, - log_bak_count: int = None, - log_at_when: str = None, - log_fmt_pattern: str = None, - log_json_fmt: bool = False, - ): - """ - Configure logger with time rotated file and stream log handlers. - - :param logging_config_path: str: (Default value = None) Optional path to - custom logging config - - :param log_level: str: (Default value = None) - :param log_file: str: (Default value = None) - :param log_interval: int: (Default value = None) - :param log_bak_count: int: (Default value = None) - :param log_at_when: str: (Default value = None) - :param log_fmt_pattern: str: (Default value = None) - :param log_json_fmt: bool: (Default value = None) - """ - if logging_config_path is not None: - config_path = logging_config_path - else: - config_path = DEFAULT_LOGGING_CONFIG_PATH - - log_config = load_resource(config_path, "utf-8") + log_config = load_resource(config_path, "utf-8") if log_config: - with log_config: - fileConfig(log_config, disable_existing_loggers=False) + if is_dict_config: + dictConfig(log_config) + else: + with log_config: + fileConfig(log_config, disable_existing_loggers=False) else: logging.basicConfig(level=logging.WARNING) logging.root.warning(f"Logging config file not found: {config_path}") - if log_file: - logging.root.handlers.clear() - timed_file_handler, std_out_handler = get_log_file_handlers( - log_file, log_interval, log_bak_count, log_at_when - ) - file_handler_pattern = log_fmt_pattern - if not file_handler_pattern: - file_handler_pattern = LOG_FORMAT_FILE_ALIAS_PATTERN - if log_json_fmt: + if log_file and multitenant: + file_handler_set = False + handler_pattern = None + # Create context filter to adapt wallet_id in logger messages + _cf = ContextFilter() + for _handler in logging.root.handlers: + if isinstance(_handler, TimedRotatingFileMultiProcessHandler): + file_handler_set = True + handler_pattern = _handler.formatter._fmt + # Set Json formatter for rotated file handler which + # cannot be set with config file. By default this will + # be set up. + _handler.setFormatter( + jsonlogger.JsonFormatter(handler_pattern) + ) + # Add context filter to handlers + _handler.addFilter(_cf) + if not file_handler_set: + file_path = os.path.join( + os.path.dirname(os.path.realpath(__file__)).replace( + "aries_cloudagent/config", "" + ), + log_file, + ) + # If configuration is not provided within .ini or dict config file + # then by default the rotated file handler will have interval=7, + # when=d and backupCount=1 configuration + timed_file_handler = TimedRotatingFileMultiProcessHandler( + filename=file_path, + interval=7, + when="d", + backupCount=1, + ) + timed_file_handler.addFilter(_cf) + # By default this will be set up. timed_file_handler.setFormatter( - jsonlogger.JsonFormatter(file_handler_pattern) + jsonlogger.JsonFormatter(LOG_FORMAT_FILE_ALIAS_PATTERN) ) - else: - timed_file_handler.setFormatter(logging.Formatter(file_handler_pattern)) - std_out_handler.setFormatter(logging.Formatter(LOG_FORMAT_STREAM_PATTERN)) - logging.root.handlers.append(timed_file_handler) - logging.root.handlers.append(std_out_handler) + logging.root.handlers.append(timed_file_handler) + elif log_file and not multitenant: + # Don't go with rotated file handler when not in multitenant mode. + logging.root.handlers.append( + logging.FileHandler(log_file, encoding="utf-8") + ) if log_level: log_level = log_level.upper() logging.root.setLevel(log_level) @@ -550,39 +566,4 @@ def doRollover(self): self.stream = self._open() self.release() - -def get_log_file_handlers( - log_file_name: str, - log_interval: int = None, - log_bak_count: int = None, - log_at_when: str = None, -) -> Tuple[TimedRotatingFileMultiProcessHandler, logging.StreamHandler]: - """Get TimedRotatingFileMultiProcessHandler and StreamHandler.""" - file_path = os.path.join( - os.path.dirname(os.path.realpath(__file__)).replace( - "aries_cloudagent/config", "" - ), - log_file_name, - ) - timed_file_handler = TimedRotatingFileMultiProcessHandler( - filename=file_path, - interval=log_interval or 7, - when=log_at_when or "d", - backupCount=log_bak_count or 1, - ) - std_out_handler = logging.StreamHandler(sys.stdout) - return (timed_file_handler, std_out_handler) - - -def get_adapted_logger_inst( - logger: logging.Logger, - log_file: str = None, - wallet_id: str = None, -) -> logging.Logger: - """Get adapted logger, formatted with wallet_id if applicable.""" - _logger = None - if log_file and wallet_id: - _logger = logging.LoggerAdapter(logger, {"wallet_id": wallet_id}) - else: - _logger = logger - return _logger +logging.handlers.TimedRotatingFileMultiProcessHandler = TimedRotatingFileMultiProcessHandler diff --git a/aries_cloudagent/config/tests/test_argparse.py b/aries_cloudagent/config/tests/test_argparse.py index 32f9de4ebf..0c52c12ef7 100644 --- a/aries_cloudagent/config/tests/test_argparse.py +++ b/aries_cloudagent/config/tests/test_argparse.py @@ -332,10 +332,6 @@ async def test_logging(self): "test_file.log", "--log-level", "INFO", - "--log-handler-config", - "d;7;1", - "--log-fmt-pattern", - "%(asctime)s %(levelname)s %(filename)s %(lineno)d %(message)s", ] ) @@ -343,35 +339,6 @@ async def test_logging(self): assert settings.get("log.file") == "test_file.log" assert settings.get("log.level") == "INFO" - assert settings.get("log.handler_when") == "d" - assert settings.get("log.handler_interval") == 7 - assert settings.get("log.handler_bakcount") == 1 - assert ( - settings.get("log.fmt_pattern") - == "%(asctime)s %(levelname)s %(filename)s %(lineno)d %(message)s" - ) - assert not settings.get("log.json_fmt") - - result = parser.parse_args( - [ - "--log-file", - "test_file.log", - "--log-level", - "INFO", - "--log-handler-config", - "d;7;1", - "--log-json-fmt", - ] - ) - - settings = group.get_settings(result) - - assert settings.get("log.file") == "test_file.log" - assert settings.get("log.level") == "INFO" - assert settings.get("log.handler_when") == "d" - assert settings.get("log.handler_interval") == 7 - assert settings.get("log.handler_bakcount") == 1 - assert settings.get("log.json_fmt") async def test_error_raised_when_multitenancy_used_and_no_jwt_provided(self): """Test that error is raised if no jwt_secret is provided with multitenancy.""" diff --git a/aries_cloudagent/config/tests/test_logging.py b/aries_cloudagent/config/tests/test_logging.py index 53509fa260..ef81af1404 100644 --- a/aries_cloudagent/config/tests/test_logging.py +++ b/aries_cloudagent/config/tests/test_logging.py @@ -40,33 +40,13 @@ def test_configure_default_no_resource(self): test_module.LoggingConfigurator.configure() def test_configure_default_file(self): + log_file = NamedTemporaryFile() with async_mock.patch.object( test_module, "load_resource", async_mock.MagicMock() ) as mock_load: mock_load.return_value = None - test_module.LoggingConfigurator.configure(log_level="ERROR") - - def test_configure_per_tenant(self): - mock_log_handlers = ( - async_mock.MagicMock(setFormatter=async_mock.MagicMock()), - async_mock.MagicMock(setFormatter=async_mock.MagicMock()), - ) - with async_mock.patch.object( - test_module, "logging", autospec=True - ), async_mock.patch.object( - test_module, "load_resource", async_mock.MagicMock() - ) as mock_load, async_mock.patch.object( - test_module, - "get_log_file_handlers", - async_mock.MagicMock(return_value=mock_log_handlers), - ): - mock_load.return_value = None - test_module.LoggingConfigurator.configure_per_tenant( - log_level="ERROR", - log_file="test.log", - log_interval=1, - log_json_fmt=True, - log_at_when="m", + test_module.LoggingConfigurator.configure( + log_level="ERROR", log_file=log_file.name ) @async_mock.patch.object(test_module, "load_resource", autospec=True) @@ -119,14 +99,24 @@ def test_load_resource(self): ) as mock_res_stream: test_module.load_resource("abc:def", encoding=None) - def test_get_log_file_handlers(self): - with async_mock.patch.object( - test_module, "TimedRotatingFileMultiProcessHandler", async_mock.MagicMock() - ) as mock_file_handler, async_mock.patch.object( - test_module.logging, "StreamHandler", async_mock.MagicMock() - ) as mock_stream_handler: - ret_file_handler, ret_stream_handler = test_module.get_log_file_handlers( - "test.log", 1, 1, "m" - ) - assert ret_file_handler - assert ret_stream_handler + def test_get_logger_with_handlers(self): + profile = InMemoryProfile.test_profile() + profile.settings["log.file"] = "test_file.log" + logger = logging.getLogger(__name__) + logger = test_module.get_logger_with_handlers( + settings=profile.settings, + logger=logger, + at_when="m", + interval=1, + backup_count=1, + ) + assert logger + logger = test_module.get_logger_with_handlers( + settings=profile.settings, + logger=logger, + did_ident="tenant_did_123", + at_when="m", + interval=1, + backup_count=1, + ) + assert logger diff --git a/aries_cloudagent/config/util.py b/aries_cloudagent/config/util.py index 4d79a30497..00f9af8654 100644 --- a/aries_cloudagent/config/util.py +++ b/aries_cloudagent/config/util.py @@ -15,24 +15,13 @@ def common_config(settings: Mapping[str, Any]): log_config = settings.get("log.config") log_level = settings.get("log.level") or os.getenv("LOG_LEVEL") log_file = settings.get("log.file") - log_interval = settings.get("log.handler_interval") - log_bak_count = settings.get("log.handler_bakcount") - log_at_when = settings.get("log.handler_when") - log_fmt_pattern = settings.get("log.fmt_pattern") - log_json_fmt = settings.get("log.json_fmt") - if not log_file: - LoggingConfigurator.configure(log_config, log_level) - else: - LoggingConfigurator.configure_per_tenant( - log_config, - log_level, - log_file, - log_interval, - log_bak_count, - log_at_when, - log_fmt_pattern, - log_json_fmt, - ) + multitenant_enabled = settings.get("multitenant.enabled") or False + LoggingConfigurator.configure( + logging_config_path=log_config, + log_level=log_level, + log_file=log_file, + multitenant=multitenant_enabled, + ) class BoundedInt: diff --git a/aries_cloudagent/connections/base_manager.py b/aries_cloudagent/connections/base_manager.py index 5a4aa708da..247fa3e93d 100644 --- a/aries_cloudagent/connections/base_manager.py +++ b/aries_cloudagent/connections/base_manager.py @@ -20,7 +20,6 @@ ) from ..cache.base import BaseCache from ..config.base import InjectionError -from ..config.logging import get_adapted_logger_inst from ..core.error import BaseError from ..core.profile import Profile from ..did.did_key import DIDKey @@ -73,11 +72,6 @@ def __init__(self, profile: Profile): """ self._profile = profile self._route_manager = profile.inject(RouteManager) - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) async def create_did_document( self, @@ -228,7 +222,7 @@ async def add_key_for_did(self, did: str, key: str): except StorageNotFoundError: await storage.add_record(record) except StorageDuplicateError: - self._logger.warning( + LOGGER.warning( "Key already associated with DID: %s; this is likely caused by " "routing keys being erroneously stored in the past", key, @@ -358,10 +352,10 @@ async def resolve_connection_targets( their_label: Optional[str] = None, ) -> List[ConnectionTarget]: """Resolve connection targets for a DID.""" - self._logger.debug("Resolving connection targets for DID %s", did) + LOGGER.debug("Resolving connection targets for DID %s", did) doc, didcomm_services = await self.resolve_didcomm_services(did) - self._logger.debug("Resolved DID document: %s", doc) - self._logger.debug("Resolved DIDComm services: %s", didcomm_services) + LOGGER.debug("Resolved DID document: %s", doc) + LOGGER.debug("Resolved DIDComm services: %s", didcomm_services) targets = [] for service in didcomm_services: try: @@ -386,7 +380,7 @@ async def resolve_connection_targets( ) ) except ResolverError: - self._logger.exception( + LOGGER.exception( "Failed to resolve service details while determining " "connection targets; skipping service" ) @@ -547,7 +541,7 @@ async def fetch_connection_targets( """ if not connection.my_did: - self._logger.debug("No local DID associated with connection") + LOGGER.debug("No local DID associated with connection") return [] async with self._profile.session() as session: @@ -564,7 +558,7 @@ async def fetch_connection_targets( ) if not connection.their_did: - self._logger.debug("No target DID associated with connection") + LOGGER.debug("No target DID associated with connection") return [] return await self.resolve_connection_targets( @@ -595,7 +589,7 @@ async def get_connection_targets( if cache: async with cache.acquire(cache_key) as entry: if entry.result: - self._logger.debug("Connection targets retrieved from cache") + LOGGER.debug("Connection targets retrieved from cache") targets = [ ConnectionTarget.deserialize(row) for row in entry.result ] @@ -612,12 +606,12 @@ async def get_connection_targets( # Only set cache if connection has reached completed state # Otherwise, a replica that participated early in exchange # may have bad data set in cache. - self._logger.debug("Caching connection targets") + LOGGER.debug("Caching connection targets") await entry.set_result( [row.serialize() for row in targets], 3600 ) else: - self._logger.debug( + LOGGER.debug( "Not caching connection targets for connection in " f"state ({connection.state})" ) @@ -803,7 +797,7 @@ async def resolve_inbound_connection( try: receipt.sender_did = await self.find_did_for_key(receipt.sender_verkey) except StorageNotFoundError: - self._logger.warning( + LOGGER.warning( "No corresponding DID found for sender verkey: %s", receipt.sender_verkey, ) @@ -819,13 +813,13 @@ async def resolve_inbound_connection( if "posted" in my_info.metadata and my_info.metadata["posted"] is True: receipt.recipient_did_public = True except InjectionError: - self._logger.warning( + LOGGER.warning( "Cannot resolve recipient verkey, no wallet defined by " "context: %s", receipt.recipient_verkey, ) except WalletNotFoundError: - self._logger.warning( + LOGGER.warning( "No corresponding DID found for recipient verkey: %s", receipt.recipient_verkey, ) diff --git a/aries_cloudagent/core/event_bus.py b/aries_cloudagent/core/event_bus.py index 3d76252bb4..d314bb3c3f 100644 --- a/aries_cloudagent/core/event_bus.py +++ b/aries_cloudagent/core/event_bus.py @@ -19,8 +19,6 @@ ) from functools import partial -from ..config.logging import get_adapted_logger_inst - if TYPE_CHECKING: # To avoid circular import error from .profile import Profile @@ -99,12 +97,7 @@ async def notify(self, profile: "Profile", event: Event): # TODO don't block notifier until subscribers have all been called? # TODO trigger each processor but don't await? # TODO log errors but otherwise ignore? - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug("Notifying subscribers: %s", event) + LOGGER.debug("Notifying subscribers: %s", event) partials = [] for pattern, subscribers in self.topic_patterns_to_subscribers.items(): @@ -126,7 +119,7 @@ async def notify(self, profile: "Profile", event: Event): try: await processor() except Exception: - _logger.exception("Error occurred while processing event") + LOGGER.exception("Error occurred while processing event") def subscribe(self, pattern: Pattern, processor: Callable): """Subscribe to an event. @@ -174,12 +167,7 @@ def wait_for_event( async def _handle_single_event(profile, event): """Handle the single event.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug( + LOGGER.debug( "wait_for_event event listener with event %s and profile %s", event, profile, diff --git a/aries_cloudagent/core/oob_processor.py b/aries_cloudagent/core/oob_processor.py index 9d8b97b0f0..c7b29b16d9 100644 --- a/aries_cloudagent/core/oob_processor.py +++ b/aries_cloudagent/core/oob_processor.py @@ -5,7 +5,6 @@ from typing import Any, Callable, Dict, List, Optional, cast from ..messaging.agent_message import AgentMessage -from ..config.logging import get_adapted_logger_inst from ..connections.models.conn_record import ConnRecord from ..connections.models.connection_target import ConnectionTarget from ..messaging.decorators.service_decorator import ServiceDecorator @@ -72,11 +71,6 @@ async def find_oob_target_for_outbound_message( self, profile: Profile, outbound_message: OutboundMessage ) -> Optional[ConnectionTarget]: """Find connection target for the outbound message.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) try: async with profile.session() as session: # Try to find the oob record for the outbound message: @@ -84,7 +78,7 @@ async def find_oob_target_for_outbound_message( session, {"attach_thread_id": outbound_message.reply_thread_id} ) - _logger.debug( + LOGGER.debug( "extracting their service from oob record %s", oob_record.their_service, ) @@ -94,7 +88,7 @@ async def find_oob_target_for_outbound_message( # Attach ~service decorator so other message can respond message = json.loads(outbound_message.payload) if not message.get("~service"): - _logger.debug( + LOGGER.debug( "Setting our service on the message ~service %s", oob_record.our_service, ) @@ -107,7 +101,7 @@ async def find_oob_target_for_outbound_message( outbound_message.payload = json.dumps(message) - _logger.debug( + LOGGER.debug( "Sending oob message payload %s", outbound_message.payload ) @@ -127,16 +121,11 @@ async def find_oob_record_for_inbound_message( message_type = context.message._type oob_record = None profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) async with context.profile.session() as session: # First try to find the oob record based on the associated pthid if context.message_receipt.parent_thread_id: try: - _logger.debug( + LOGGER.debug( "Retrieving OOB record using pthid " f"{context.message_receipt.parent_thread_id} " f"for message type {message_type}" @@ -160,7 +149,7 @@ async def find_oob_record_for_inbound_message( and context.message_receipt.recipient_verkey ): try: - _logger.debug( + LOGGER.debug( "Retrieving OOB record using thid " f"{context.message_receipt.thread_id} and recipient verkey" f" {context.message_receipt.recipient_verkey} for " @@ -181,7 +170,7 @@ async def find_oob_record_for_inbound_message( if not oob_record: return None - _logger.debug( + LOGGER.debug( f"Found out of band record for inbound message with type {message_type}" f": {oob_record.oob_id}" ) @@ -197,14 +186,14 @@ async def find_oob_record_for_inbound_message( and context.connection_record and context.connection_record.connection_id != oob_record.connection_id ): - _logger.debug( + LOGGER.debug( f"Oob record connection id {oob_record.connection_id} is different from" f" inbound message connection {context.connection_record.connection_id}", ) # Mismatch in connection id's in only allowed in state await response # (connection id can change bc of reuse) if oob_record.state != OobRecord.STATE_AWAIT_RESPONSE: - _logger.debug( + LOGGER.debug( "Inbound message has incorrect connection_id " f"{context.connection_record.connection_id}. Oob record " f"{oob_record.oob_id} associated with connection id " @@ -219,7 +208,7 @@ async def find_oob_record_for_inbound_message( oob_record.invitation.requests_attach and oob_record.state == OobRecord.STATE_AWAIT_RESPONSE ): - _logger.debug( + LOGGER.debug( f"Removing stale connection {oob_record.connection_id} due " "to connection reuse" ) @@ -244,7 +233,7 @@ async def find_oob_record_for_inbound_message( ] if context.message_receipt.thread_id not in allowed_thread_ids: - _logger.debug( + LOGGER.debug( "Inbound message is for not allowed thread " f"{context.message_receipt.thread_id}. Allowed " f"threads are {allowed_thread_ids}" @@ -256,7 +245,7 @@ async def find_oob_record_for_inbound_message( oob_record.attach_thread_id and context.message_receipt.thread_id != oob_record.attach_thread_id ): - _logger.debug( + LOGGER.debug( f"Inbound message thread id {context.message_receipt.thread_id} does not" f" match oob record thread id {oob_record.attach_thread_id}" ) @@ -283,7 +272,7 @@ async def find_oob_record_for_inbound_message( ) ) ): - _logger.debug( + LOGGER.debug( "Inbound message sender verkey does not match stored service on oob" " record" ) @@ -292,7 +281,7 @@ async def find_oob_record_for_inbound_message( # If the message has a ~service decorator we save it in the oob record so we # can reply to this message if context._message._service: - _logger.debug( + LOGGER.debug( "Storing service decorator in oob record %s", context.message._service.serialize(), ) @@ -320,11 +309,6 @@ async def handle_message( their_service: Optional[ServiceDecorator] = None, ): """Message handler for inbound messages.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) supported_types = [ CREDENTIAL_OFFER, @@ -365,7 +349,7 @@ async def handle_message( if not oob_record.connection_id: oob_record.attach_thread_id = self.get_thread_id(message) if their_service: - _logger.debug( + LOGGER.debug( "Storing their service in oob record %s", their_service ) oob_record.their_service = their_service.serialize() diff --git a/aries_cloudagent/indy/credx/holder.py b/aries_cloudagent/indy/credx/holder.py index fa16598304..d593838319 100644 --- a/aries_cloudagent/indy/credx/holder.py +++ b/aries_cloudagent/indy/credx/holder.py @@ -20,13 +20,13 @@ ) from ...askar.profile import AskarProfile -from ...config.logging import get_adapted_logger_inst from ...ledger.base import BaseLedger from ...wallet.error import WalletNotFoundError from ..holder import IndyHolder, IndyHolderError LOGGER = logging.getLogger(__name__) + CATEGORY_CREDENTIAL = "credential" CATEGORY_LINK_SECRET = "master_secret" @@ -61,11 +61,6 @@ def __init__(self, profile: AskarProfile): """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) @property def profile(self) -> AskarProfile: @@ -143,7 +138,7 @@ async def create_credential_request( cred_req_metadata.to_json(), ) - self._logger.debug( + LOGGER.debug( "Created credential request. " "credential_request_json=%s credential_request_metadata_json=%s", cred_req_json, diff --git a/aries_cloudagent/indy/credx/issuer.py b/aries_cloudagent/indy/credx/issuer.py index a383425bc1..6150d9d9ca 100644 --- a/aries_cloudagent/indy/credx/issuer.py +++ b/aries_cloudagent/indy/credx/issuer.py @@ -21,7 +21,6 @@ ) from ...askar.profile import AskarProfile -from ...config.logging import get_adapted_logger_inst from ..issuer import ( IndyIssuer, @@ -32,6 +31,7 @@ ) LOGGER = logging.getLogger(__name__) + CATEGORY_CRED_DEF = "credential_def" CATEGORY_CRED_DEF_PRIVATE = "credential_def_private" CATEGORY_CRED_DEF_KEY_PROOF = "credential_def_key_proof" @@ -54,11 +54,6 @@ def __init__(self, profile: AskarProfile): """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) @property def profile(self) -> AskarProfile: @@ -453,7 +448,7 @@ async def revoke_credentials( for rev_id in cred_revoc_ids: rev_id = int(rev_id) if rev_id < 1 or rev_id > max_cred_num: - self._logger.error( + LOGGER.error( "Skipping requested credential revocation" "on rev reg id %s, cred rev id=%s not in range", revoc_reg_id, @@ -461,7 +456,7 @@ async def revoke_credentials( ) failed_crids.add(rev_id) elif rev_id > rev_info["curr_id"]: - self._logger.warn( + LOGGER.warn( "Skipping requested credential revocation" "on rev reg id %s, cred rev id=%s not yet issued", revoc_reg_id, @@ -469,7 +464,7 @@ async def revoke_credentials( ) failed_crids.add(rev_id) elif rev_id in used_ids: - self._logger.warn( + LOGGER.warn( "Skipping requested credential revocation" "on rev reg id %s, cred rev id=%s already revoked", revoc_reg_id, @@ -505,7 +500,7 @@ async def revoke_credentials( CATEGORY_REV_REG_INFO, revoc_reg_id, for_update=True ) if not rev_reg_upd or not rev_reg_info: - self._logger.warn( + LOGGER.warn( "Revocation registry missing, skipping update: {}", revoc_reg_id, ) diff --git a/aries_cloudagent/indy/credx/verifier.py b/aries_cloudagent/indy/credx/verifier.py index a641096b31..0911009144 100644 --- a/aries_cloudagent/indy/credx/verifier.py +++ b/aries_cloudagent/indy/credx/verifier.py @@ -8,7 +8,6 @@ from indy_credx import CredxError, Presentation from ...core.profile import Profile -from ...config.logging import get_adapted_logger_inst from ..verifier import IndyVerifier, PresVerifyMsg @@ -26,11 +25,6 @@ def __init__(self, profile: Profile): """ self.profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self.profile.settings.get("log.file"), - wallet_id=self.profile.settings.get("wallet.id"), - ) async def verify_presentation( self, @@ -66,7 +60,7 @@ async def verify_presentation( except ValueError as err: s = str(err) msgs.append(f"{PresVerifyMsg.PRES_VALUE_ERROR.value}::{s}") - self._logger.error( + LOGGER.error( f"Presentation on nonce={pres_req['nonce']} " f"cannot be validated: {str(err)}" ) @@ -87,7 +81,7 @@ async def verify_presentation( except CredxError as err: s = str(err) msgs.append(f"{PresVerifyMsg.PRES_VERIFY_ERROR.value}::{s}") - self._logger.exception( + LOGGER.exception( f"Validation of presentation on nonce={pres_req['nonce']} " "failed with error" ) diff --git a/aries_cloudagent/indy/sdk/issuer.py b/aries_cloudagent/indy/sdk/issuer.py index 56891cbc4f..8ac62b8637 100644 --- a/aries_cloudagent/indy/sdk/issuer.py +++ b/aries_cloudagent/indy/sdk/issuer.py @@ -8,7 +8,6 @@ import indy.blob_storage from indy.error import AnoncredsRevocationRegistryFullError, IndyError, ErrorCode -from ...config.logging import get_adapted_logger_inst from ...indy.sdk.profile import IndySdkProfile from ...messaging.util import encode from ...storage.error import StorageError @@ -38,11 +37,6 @@ def __init__(self, profile: IndySdkProfile): """ self.profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self.profile.settings.get("log.file"), - wallet_id=self.profile.settings.get("wallet.id"), - ) async def create_schema( self, @@ -217,7 +211,7 @@ async def create_credential( tails_reader_handle, ) except AnoncredsRevocationRegistryFullError: - self._logger.warning( + LOGGER.warning( "Revocation registry %s is full: cannot create credential", rev_reg_id, ) @@ -229,7 +223,7 @@ async def create_credential( err, "Error when issuing credential", IndyIssuerError ) from err except StorageError as err: - self._logger.warning( + LOGGER.warning( ( "Created issuer cred rev record for " "Could not store issuer cred rev record for " @@ -278,7 +272,7 @@ async def revoke_credentials( ) except IndyError as err: if err.error_code == ErrorCode.AnoncredsInvalidUserRevocId: - self._logger.error( + LOGGER.error( ( "Abstaining from revoking credential on " "rev reg id %s, cred rev id=%s: " @@ -288,7 +282,7 @@ async def revoke_credentials( cred_rev_id, ) else: - self._logger.error( + LOGGER.error( IndyErrorHandler.wrap_error( err, "Revocation error", IndyIssuerError ).roll_up @@ -296,7 +290,7 @@ async def revoke_credentials( failed_crids.add(int(cred_rev_id)) continue except StorageError as err: - self._logger.warning( + LOGGER.warning( ( "Revoked credential on rev reg id %s, cred rev id %s " "without corresponding issuer cred rev record: %s" diff --git a/aries_cloudagent/indy/sdk/verifier.py b/aries_cloudagent/indy/sdk/verifier.py index 59c3815f43..81bdc5a601 100644 --- a/aries_cloudagent/indy/sdk/verifier.py +++ b/aries_cloudagent/indy/sdk/verifier.py @@ -9,7 +9,6 @@ from indy.error import IndyError from ...core.profile import Profile -from ...config.logging import get_adapted_logger_inst from ..verifier import IndyVerifier, PresVerifyMsg @@ -27,11 +26,6 @@ def __init__(self, profile: Profile): """ self.profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self.profile.settings.get("log.file"), - wallet_id=self.profile.settings.get("wallet.id"), - ) async def verify_presentation( self, @@ -53,8 +47,8 @@ async def verify_presentation( rev_reg_entries: revocation registry entries """ - self._logger.debug(f">>> received presentation: {pres}") - self._logger.debug(f">>> for pres_req: {pres_req}") + LOGGER.debug(f">>> received presentation: {pres}") + LOGGER.debug(f">>> for pres_req: {pres_req}") msgs = [] try: msgs += self.non_revoc_intervals(pres_req, pres, credential_definitions) @@ -65,14 +59,14 @@ async def verify_presentation( except ValueError as err: s = str(err) msgs.append(f"{PresVerifyMsg.PRES_VALUE_ERROR.value}::{s}") - self._logger.error( + LOGGER.error( f"Presentation on nonce={pres_req['nonce']} " f"cannot be validated: {str(err)}" ) return (False, msgs) - self._logger.debug(f">>> verifying presentation: {pres}") - self._logger.debug(f">>> for pres_req: {pres_req}") + LOGGER.debug(f">>> verifying presentation: {pres}") + LOGGER.debug(f">>> for pres_req: {pres_req}") try: verified = await indy.anoncreds.verifier_verify_proof( json.dumps(pres_req), @@ -85,7 +79,7 @@ async def verify_presentation( except IndyError as err: s = str(err) msgs.append(f"{PresVerifyMsg.PRES_VERIFY_ERROR.value}::{s}") - self._logger.exception( + LOGGER.exception( f"Validation of presentation on nonce={pres_req['nonce']} " "failed with error" ) diff --git a/aries_cloudagent/indy/verifier.py b/aries_cloudagent/indy/verifier.py index 1da88f8c17..0b7dd5f536 100644 --- a/aries_cloudagent/indy/verifier.py +++ b/aries_cloudagent/indy/verifier.py @@ -7,7 +7,6 @@ from time import time from typing import Mapping, Tuple -from ..config.logging import get_adapted_logger_inst from ..core.profile import Profile from ..ledger.multiple_ledger.ledger_requests_executor import ( GET_CRED_DEF, @@ -124,19 +123,14 @@ async def check_timestamps( pres: indy proof request rev_reg_defs: rev reg defs by rev reg id, augmented with transaction times """ - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) msgs = [] now = int(time()) non_revoc_intervals = indy_proof_req2non_revoc_intervals(pres_req) - _logger.debug(f">>> got non-revoc intervals: {non_revoc_intervals}") + LOGGER.debug(f">>> got non-revoc intervals: {non_revoc_intervals}") # timestamp for irrevocable credential cred_defs = [] for index, ident in enumerate(pres["identifiers"]): - _logger.debug(f">>> got (index, ident): ({index},{ident})") + LOGGER.debug(f">>> got (index, ident): ({index},{ident})") cred_def_id = ident["cred_def_id"] multitenant_mgr = profile.inject_or(BaseMultitenantManager) if multitenant_mgr: @@ -196,8 +190,8 @@ async def check_timestamps( if (timestamp is not None) ^ bool( non_revoc_intervals.get(uuid) ): - _logger.debug(f">>> uuid: {uuid}") - _logger.debug( + LOGGER.debug(f">>> uuid: {uuid}") + LOGGER.debug( f">>> revealed_attrs[uuid]: {revealed_attrs[uuid]}" ) raise ValueError( @@ -214,7 +208,7 @@ async def check_timestamps( f"{PresVerifyMsg.TSTMP_OUT_NON_REVOC_INTRVAL.value}::" f"{uuid}" ) - _logger.info( + LOGGER.info( f"Timestamp {timestamp} from ledger for item" f"{uuid} falls outside non-revocation interval " f"{non_revoc_intervals[uuid]}" @@ -255,7 +249,7 @@ async def check_timestamps( f"{PresVerifyMsg.TSTMP_OUT_NON_REVOC_INTRVAL.value}::" f"{uuid}" ) - _logger.warning( + LOGGER.warning( f"Timestamp {timestamp} from ledger for item" f"{uuid} falls outside non-revocation interval " f"{non_revoc_intervals[uuid]}" @@ -284,7 +278,7 @@ async def check_timestamps( msgs.append( f"{PresVerifyMsg.TSTMP_OUT_NON_REVOC_INTRVAL.value}::" f"{uuid}" ) - _logger.warning( + LOGGER.warning( f"Best-effort timestamp {timestamp} " "from ledger falls outside non-revocation interval " f"{non_revoc_intervals[uuid]}" diff --git a/aries_cloudagent/ledger/indy.py b/aries_cloudagent/ledger/indy.py index c66d4edf12..34e216339a 100644 --- a/aries_cloudagent/ledger/indy.py +++ b/aries_cloudagent/ledger/indy.py @@ -16,7 +16,6 @@ from ..cache.base import BaseCache from ..config.base import BaseInjector, BaseProvider, BaseSettings -from ..config.logging import get_adapted_logger_inst from ..indy.sdk.error import IndyErrorHandler from ..storage.base import StorageRecord from ..storage.indy import IndySdkStorage @@ -277,11 +276,6 @@ def __init__( """ self.pool = pool self.profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self.profile.settings.get("log.file"), - wallet_id=self.profile.settings.get("wallet.id"), - ) @property def pool_handle(self): @@ -1063,7 +1057,7 @@ async def get_revoc_reg_def(self, revoc_reg_id: str) -> dict: found_def["txnTime"] = json.loads(response_json)["result"]["txnTime"] except IndyError as e: - self._logger.error( + LOGGER.error( f"get_revoc_reg_def failed with revoc_reg_id={revoc_reg_id} - " f"{e.error_code}: {getattr(e, 'message', '[no message]')}" ) @@ -1087,7 +1081,7 @@ async def get_revoc_reg_entry(self, revoc_reg_id: str, timestamp: int): ledger_timestamp, ) = await indy.ledger.parse_get_revoc_reg_response(response_json) except IndyError as e: - self._logger.error( + LOGGER.error( f"get_revoc_reg_entry failed with revoc_reg_id={revoc_reg_id} - " f"{e.error_code}: {getattr(e, 'message', '[no message]')}" ) diff --git a/aries_cloudagent/ledger/multiple_ledger/indy_manager.py b/aries_cloudagent/ledger/multiple_ledger/indy_manager.py index df25db9b78..cf379b7913 100644 --- a/aries_cloudagent/ledger/multiple_ledger/indy_manager.py +++ b/aries_cloudagent/ledger/multiple_ledger/indy_manager.py @@ -1,5 +1,4 @@ """Multiple IndySdkLedger Manager.""" - import asyncio import concurrent.futures import logging @@ -10,7 +9,6 @@ from ...cache.base import BaseCache from ...core.profile import Profile -from ...config.logging import get_adapted_logger_inst from ...ledger.base import BaseLedger from ...ledger.error import LedgerError from ...wallet.crypto import did_is_self_certified @@ -55,11 +53,6 @@ def __init__( self.endorser_map = endorser_map self.executor = concurrent.futures.ThreadPoolExecutor(max_workers=5) self.cache_ttl = cache_ttl - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self.profile.settings.get("log.file"), - wallet_id=self.profile.settings.get("wallet.id"), - ) async def get_write_ledgers(self) -> List[str]: """Return the write IndySdkLedger instance.""" @@ -131,7 +124,7 @@ async def _get_ledger_by_did( response = json.loads(response_json) data = response.get("result", {}).get("data") if not data: - self._logger.warning(f"Did {did} not posted to ledger {ledger_id}") + LOGGER.warning(f"Did {did} not posted to ledger {ledger_id}") return None if isinstance(data, str): data = json.loads(data) @@ -139,7 +132,7 @@ async def _get_ledger_by_did( expected_value=prepare_for_state_read(response), proof_nodes=get_proof_nodes(response), ): - self._logger.warning( + LOGGER.warning( f"State Proof validation failed for Did {did} " f"and ledger {ledger_id}" ) @@ -148,13 +141,13 @@ async def _get_ledger_by_did( return (ledger_id, indy_sdk_ledger, True) return (ledger_id, indy_sdk_ledger, False) except asyncio.TimeoutError: - self._logger.exception( + LOGGER.exception( f"get-nym request timedout for Did {did} and " f"ledger {ledger_id}, reply not received within 10 sec" ) return None except LedgerError as err: - self._logger.error( + LOGGER.error( "Exception when building and submitting get-nym request, " f"for Did {did} and ledger {ledger_id}, {err}" ) diff --git a/aries_cloudagent/ledger/multiple_ledger/indy_vdr_manager.py b/aries_cloudagent/ledger/multiple_ledger/indy_vdr_manager.py index 5c8a51e61b..8d2c51c576 100644 --- a/aries_cloudagent/ledger/multiple_ledger/indy_vdr_manager.py +++ b/aries_cloudagent/ledger/multiple_ledger/indy_vdr_manager.py @@ -9,7 +9,6 @@ from ...cache.base import BaseCache from ...core.profile import Profile -from ...config.logging import get_adapted_logger_inst from ...ledger.base import BaseLedger from ...ledger.error import LedgerError from ...wallet.crypto import did_is_self_certified @@ -54,11 +53,6 @@ def __init__( self.endorser_map = endorser_map self.executor = concurrent.futures.ThreadPoolExecutor(max_workers=5) self.cache_ttl = cache_ttl - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self.profile.settings.get("log.file"), - wallet_id=self.profile.settings.get("wallet.id"), - ) async def get_write_ledgers(self) -> List[str]: """Return the write IndyVdrLedger instance.""" @@ -136,7 +130,7 @@ async def _get_ledger_by_did( else: data = response.get("data") if not data: - self._logger.warning(f"Did {did} not posted to ledger {ledger_id}") + LOGGER.warning(f"Did {did} not posted to ledger {ledger_id}") return None if isinstance(data, str): data = json.loads(data) @@ -144,7 +138,7 @@ async def _get_ledger_by_did( expected_value=prepare_for_state_read(response), proof_nodes=get_proof_nodes(response), ): - self._logger.warning( + LOGGER.warning( f"State Proof validation failed for Did {did} " f"and ledger {ledger_id}" ) @@ -153,13 +147,13 @@ async def _get_ledger_by_did( return (ledger_id, indy_vdr_ledger, True) return (ledger_id, indy_vdr_ledger, False) except asyncio.TimeoutError: - self._logger.exception( + LOGGER.exception( f"get-nym request timedout for Did {did} and " f"ledger {ledger_id}, reply not received within 10 sec" ) return None except LedgerError as err: - self._logger.error( + LOGGER.error( "Exception when building and submitting get-nym request, " f"for Did {did} and ledger {ledger_id}, {err}" ) diff --git a/aries_cloudagent/ledger/routes.py b/aries_cloudagent/ledger/routes.py index a45fc85a7f..46aa2612fe 100644 --- a/aries_cloudagent/ledger/routes.py +++ b/aries_cloudagent/ledger/routes.py @@ -15,7 +15,6 @@ from marshmallow import fields, validate from ..admin.request_context import AdminRequestContext -from ..config.logging import get_adapted_logger_inst from ..connections.models.conn_record import ConnRecord from ..messaging.models.base import BaseModelError from ..messaging.models.openapi import OpenAPISchema @@ -647,7 +646,6 @@ async def ledger_accept_taa(request: web.BaseRequest): """ context: AdminRequestContext = request["context"] - profile = context.profile async with context.profile.session() as session: ledger = session.inject_or(BaseLedger) if not ledger: @@ -657,12 +655,7 @@ async def ledger_accept_taa(request: web.BaseRequest): raise web.HTTPForbidden(reason=reason) accept_input = await request.json() - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.info(">>> accepting TAA with: %s", accept_input) + LOGGER.info(">>> accepting TAA with: %s", accept_input) async with ledger: try: taa_info = await ledger.get_txn_author_agreement() @@ -670,14 +663,14 @@ async def ledger_accept_taa(request: web.BaseRequest): raise web.HTTPBadRequest( reason=f"Ledger {ledger.pool_name} TAA not available" ) - _logger.info("TAA on ledger: ", taa_info) + LOGGER.info("TAA on ledger: ", taa_info) # this is a bit of a hack, but the "\ufeff" code is included in the # ledger TAA and digest calculation, so it needs to be included in the # TAA text that the user is accepting # (if you copy the TAA text using swagger it won't include this character) if taa_info["taa_record"]["text"].startswith("\ufeff"): if not accept_input["text"].startswith("\ufeff"): - _logger.info( + LOGGER.info( ">>> pre-pending -endian character to TAA acceptance text" ) accept_input["text"] = "\ufeff" + accept_input["text"] @@ -690,7 +683,7 @@ async def ledger_accept_taa(request: web.BaseRequest): ), } taa_record_digest = taa_record["digest"] - _logger.info(">>> accepting with digest: %s", taa_record_digest) + LOGGER.info(">>> accepting with digest: %s", taa_record_digest) await ledger.accept_txn_author_agreement( taa_record, accept_input["mechanism"] ) diff --git a/aries_cloudagent/multitenant/base.py b/aries_cloudagent/multitenant/base.py index 40a59d3001..832aaf9e7c 100644 --- a/aries_cloudagent/multitenant/base.py +++ b/aries_cloudagent/multitenant/base.py @@ -8,7 +8,7 @@ import jwt from ..config.injection_context import InjectionContext -from ..config.logging import get_adapted_logger_inst +from ..config.logging import context_wallet_id from ..core.error import BaseError from ..core.profile import Profile, ProfileSession from ..protocols.coordinate_mediation.v1_0.manager import ( @@ -43,11 +43,6 @@ def __init__(self, profile: Profile): self._profile = profile if not profile: raise MultitenantManagerError("Missing profile") - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) @property @abstractmethod @@ -110,7 +105,7 @@ def get_webhook_urls( if dispatch_type == "both": webhook_urls = list(set(base_webhook_urls) | set(subwallet_webhook_urls)) if not webhook_urls: - self._logger.warning( + LOGGER.warning( "No webhook URLs in context configuration " f"nor wallet record {wallet_id}, but wallet record " f"configures dispatch type {dispatch_type}" @@ -118,7 +113,7 @@ def get_webhook_urls( elif dispatch_type == "default": webhook_urls = subwallet_webhook_urls if not webhook_urls: - self._logger.warning( + LOGGER.warning( f"No webhook URLs in nor wallet record {wallet_id}, but " f"wallet record configures dispatch type {dispatch_type}" ) @@ -207,6 +202,9 @@ async def create_wallet( await profile.inject(RouteManager).route_verkey( profile, public_did_info.verkey ) + # add wallet id contextVar for logging + wallet_id = profile.settings.get("wallet.id") + context_wallet_id.set(wallet_id) except Exception: await wallet_record.delete_record(session) raise diff --git a/aries_cloudagent/multitenant/cache.py b/aries_cloudagent/multitenant/cache.py index f9b5625a1f..1fb3f37e3c 100644 --- a/aries_cloudagent/multitenant/cache.py +++ b/aries_cloudagent/multitenant/cache.py @@ -5,7 +5,6 @@ from typing import Optional from weakref import WeakValueDictionary -from ..config.logging import get_adapted_logger_inst from ..core.profile import Profile LOGGER = logging.getLogger(__name__) @@ -55,13 +54,8 @@ def get(self, key: str) -> Optional[Profile]: """ value = self.profiles.get(key) if value: - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=value.settings.get("log.file"), - wallet_id=value.settings.get("wallet.id"), - ) if key not in self._cache: - _logger.debug( + LOGGER.debug( f"Rescuing profile {key} from eviction from cache; profile " "will be reinserted into cache" ) diff --git a/aries_cloudagent/multitenant/route_manager.py b/aries_cloudagent/multitenant/route_manager.py index c664eddfef..954b3c98f9 100644 --- a/aries_cloudagent/multitenant/route_manager.py +++ b/aries_cloudagent/multitenant/route_manager.py @@ -4,7 +4,6 @@ import logging from typing import List, Optional, Tuple -from ..config.logging import get_adapted_logger_inst from ..connections.models.conn_record import ConnRecord from ..core.profile import Profile from ..messaging.responder import BaseResponder @@ -49,13 +48,8 @@ async def _route_for_key( skip_if_exists: bool = False, replace_key: Optional[str] = None, ): - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) wallet_id = profile.settings["wallet.id"] - _logger.info( + LOGGER.info( f"Add route record for recipient {recipient_key} to wallet {wallet_id}" ) routing_mgr = RoutingManager(self.root_profile) @@ -140,12 +134,7 @@ async def connection_from_recipient_key( for sub wallets, we check the sub wallet's connections before the base wallet. """ - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug("Retrieving connection for recipient key for multitenant wallet") + LOGGER.debug("Retrieving connection for recipient key for multitenant wallet") manager = profile.inject(BaseMultitenantManager) profile_to_search = ( await manager.get_profile_for_key( diff --git a/aries_cloudagent/protocols/actionmenu/v1_0/handlers/menu_request_handler.py b/aries_cloudagent/protocols/actionmenu/v1_0/handlers/menu_request_handler.py index e7806ee596..905e039ce8 100644 --- a/aries_cloudagent/protocols/actionmenu/v1_0/handlers/menu_request_handler.py +++ b/aries_cloudagent/protocols/actionmenu/v1_0/handlers/menu_request_handler.py @@ -1,6 +1,5 @@ """Action menu request message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -21,12 +20,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: request context responder: responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("MenuRequestHandler called with context %s", context) assert isinstance(context.message, MenuRequest) diff --git a/aries_cloudagent/protocols/actionmenu/v1_0/handlers/perform_handler.py b/aries_cloudagent/protocols/actionmenu/v1_0/handlers/perform_handler.py index 83f1dd2254..5e38bc90f3 100644 --- a/aries_cloudagent/protocols/actionmenu/v1_0/handlers/perform_handler.py +++ b/aries_cloudagent/protocols/actionmenu/v1_0/handlers/perform_handler.py @@ -1,6 +1,5 @@ """Action menu perform request message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -21,12 +20,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: request context responder: responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("PerformHandler called with context %s", context) assert isinstance(context.message, Perform) diff --git a/aries_cloudagent/protocols/actionmenu/v1_0/routes.py b/aries_cloudagent/protocols/actionmenu/v1_0/routes.py index d2ebc1be04..c9c94af9d6 100644 --- a/aries_cloudagent/protocols/actionmenu/v1_0/routes.py +++ b/aries_cloudagent/protocols/actionmenu/v1_0/routes.py @@ -8,7 +8,6 @@ from marshmallow import fields from ....admin.request_context import AdminRequestContext -from ....config.logging import get_adapted_logger_inst from ....connections.models.conn_record import ConnRecord from ....messaging.models.base import BaseModelError from ....messaging.models.openapi import OpenAPISchema @@ -179,19 +178,14 @@ async def actionmenu_request(request: web.BaseRequest): """ context: AdminRequestContext = request["context"] - profile = context.profile connection_id = request.match_info["conn_id"] outbound_handler = request["outbound_message_router"] - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + try: async with context.profile.session() as session: connection = await ConnRecord.retrieve_by_id(session, connection_id) except StorageNotFoundError as err: - _logger.debug("Connection not found for action menu request: %s", connection_id) + LOGGER.debug("Connection not found for action menu request: %s", connection_id) raise web.HTTPNotFound(reason=err.roll_up) from err if connection.is_ready: @@ -214,27 +208,21 @@ async def actionmenu_send(request: web.BaseRequest): """ context: AdminRequestContext = request["context"] - profile = context.profile connection_id = request.match_info["conn_id"] outbound_handler = request["outbound_message_router"] menu_json = await request.json() - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug("Received send-menu request: %s %s", connection_id, menu_json) + LOGGER.debug("Received send-menu request: %s %s", connection_id, menu_json) try: msg = Menu.deserialize(menu_json["menu"]) except BaseModelError as err: - _logger.exception("Exception deserializing menu: %s", err.roll_up) + LOGGER.exception("Exception deserializing menu: %s", err.roll_up) raise web.HTTPBadRequest(reason=err.roll_up) from err try: async with context.profile.session() as session: connection = await ConnRecord.retrieve_by_id(session, connection_id) except StorageNotFoundError as err: - _logger.debug( + LOGGER.debug( "Connection not found for action menu send request: %s", connection_id ) raise web.HTTPNotFound(reason=err.roll_up) from err diff --git a/aries_cloudagent/protocols/basicmessage/v1_0/handlers/basicmessage_handler.py b/aries_cloudagent/protocols/basicmessage/v1_0/handlers/basicmessage_handler.py index c84f218b20..93bd91760f 100644 --- a/aries_cloudagent/protocols/basicmessage/v1_0/handlers/basicmessage_handler.py +++ b/aries_cloudagent/protocols/basicmessage/v1_0/handlers/basicmessage_handler.py @@ -1,6 +1,5 @@ """Basic message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -20,12 +19,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: request context responder: responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("BasicMessageHandler called with context %s", context) assert isinstance(context.message, BasicMessage) diff --git a/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py b/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py index d4ed484743..73efd9ecf8 100644 --- a/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py +++ b/aries_cloudagent/protocols/connections/v1_0/handlers/connection_request_handler.py @@ -1,10 +1,8 @@ """Connection request handler.""" -from .....config.logging import get_adapted_logger_inst from .....connections.models.conn_record import ConnRecord from .....messaging.base_handler import BaseHandler, BaseResponder, RequestContext from ....coordinate_mediation.v1_0.manager import MediationManager - from ..manager import ConnectionManager, ConnectionManagerError from ..messages.connection_request import ConnectionRequest from ..messages.problem_report import ConnectionProblemReport @@ -20,14 +18,11 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug(f"ConnectionRequestHandler called with context {context}") assert isinstance(context.message, ConnectionRequest) + + profile = context.profile mgr = ConnectionManager(profile) mediation_id = None diff --git a/aries_cloudagent/protocols/connections/v1_0/handlers/connection_response_handler.py b/aries_cloudagent/protocols/connections/v1_0/handlers/connection_response_handler.py index c542a72a9f..5bb79269db 100644 --- a/aries_cloudagent/protocols/connections/v1_0/handlers/connection_response_handler.py +++ b/aries_cloudagent/protocols/connections/v1_0/handlers/connection_response_handler.py @@ -1,6 +1,5 @@ """Connection response handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -23,14 +22,10 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug(f"ConnectionResponseHandler called with context {context}") assert isinstance(context.message, ConnectionResponse) + + profile = context.profile mgr = ConnectionManager(profile) try: connection = await mgr.accept_response( diff --git a/aries_cloudagent/protocols/connections/v1_0/manager.py b/aries_cloudagent/protocols/connections/v1_0/manager.py index a05db729c1..fe33e1dac3 100644 --- a/aries_cloudagent/protocols/connections/v1_0/manager.py +++ b/aries_cloudagent/protocols/connections/v1_0/manager.py @@ -5,7 +5,6 @@ from ....core.oob_processor import OobMessageProcessor -from ....config.logging import get_adapted_logger_inst from ....connections.base_manager import BaseConnectionManager from ....connections.models.conn_record import ConnRecord from ....core.error import BaseError @@ -26,8 +25,6 @@ from .messages.problem_report import ProblemReportReason from .models.connection_detail import ConnectionDetail -LOGGER = logging.getLogger(__name__) - class ConnectionManagerError(BaseError): """Connection error.""" @@ -43,11 +40,7 @@ def __init__(self, profile: Profile): profile: The profile for this connection manager """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) + self._logger = logging.getLogger(__name__) super().__init__(self._profile) @property diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_handler.py index 3567feeea0..de00566498 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_handler.py @@ -1,6 +1,6 @@ """Handler for keylist message.""" +import logging -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -10,17 +10,14 @@ from ..models.mediation_record import MediationRecord +LOG = logging.getLogger(__name__) + + class KeylistHandler(BaseHandler): """Handler for keylist message.""" async def handle(self, context: RequestContext, responder: BaseResponder): """Handle keylist message.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "%s called with context %s", self.__class__.__name__, context ) @@ -35,11 +32,11 @@ async def handle(self, context: RequestContext, responder: BaseResponder): session, context.connection_record.connection_id ) except StorageNotFoundError as err: - self._logger.warning( + LOG.warning( "Received keylist from connection that is not acting as mediator: %s", err, ) return # TODO verify our keylist matches? - self._logger.info("Keylist received: %s", context.message) + LOG.info("Keylist received: %s", context.message) diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_query_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_query_handler.py index 047af97ed7..7d47296b64 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_query_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_query_handler.py @@ -1,6 +1,5 @@ """Handler for keylist-query message.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -17,12 +16,6 @@ class KeylistQueryHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle keylist-query message.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "%s called with context %s", self.__class__.__name__, context ) @@ -30,6 +23,8 @@ async def handle(self, context: RequestContext, responder: BaseResponder): if not context.connection_ready: raise HandlerException("Invalid keylist query: no active connection") + + profile = context.profile mgr = MediationManager(profile) try: async with profile.session() as session: diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_handler.py index 37e7066682..20c63a5e15 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_handler.py @@ -1,6 +1,5 @@ """Handler for keylist-update messages.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -17,12 +16,6 @@ class KeylistUpdateHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle keylist-update messages.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "%s called with context %s", self.__class__.__name__, context ) @@ -30,6 +23,8 @@ async def handle(self, context: RequestContext, responder: BaseResponder): if not context.connection_ready: raise HandlerException("Cannot update routes: no active connection") + + profile = context.profile mgr = MediationManager(profile) try: async with profile.session() as session: diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_response_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_response_handler.py index f45cef4fba..d2c33704d8 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_response_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/keylist_update_response_handler.py @@ -1,6 +1,5 @@ """Handler for keylist-update-response message.""" -from .....config.logging import get_adapted_logger_inst from .....core.profile import Profile from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext @@ -17,12 +16,6 @@ class KeylistUpdateResponseHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle keylist-update-response message.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "%s called with context %s", self.__class__.__name__, context ) @@ -43,11 +36,6 @@ async def notify_keylist_updated( self, profile: Profile, connection_id: str, response: KeylistUpdateResponse ): """Notify of keylist update response received.""" - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) route_manager = profile.inject(RouteManager) self._logger.debug( "Retrieving connection ID from route manager of type %s", diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_deny_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_deny_handler.py index e0406195af..7a27a8fdce 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_deny_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_deny_handler.py @@ -1,6 +1,5 @@ """Handler for mediate-deny message.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -16,12 +15,6 @@ class MediationDenyHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle mediate-deny message.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "%s called with context %s", self.__class__.__name__, context ) @@ -29,6 +22,8 @@ async def handle(self, context: RequestContext, responder: BaseResponder): if not context.connection_ready: raise HandlerException("Received mediation deny from inactive connection") + + profile = context.profile mgr = MediationManager(profile) try: async with profile.session() as session: diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_grant_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_grant_handler.py index af13775852..fc597b63c7 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_grant_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_grant_handler.py @@ -1,6 +1,5 @@ """Handler for mediate-grant message.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -17,12 +16,6 @@ class MediationGrantHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle mediate-grant message.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "%s called with context %s", self.__class__.__name__, context ) @@ -30,6 +23,8 @@ async def handle(self, context: RequestContext, responder: BaseResponder): if not context.connection_ready: raise HandlerException("Received mediation grant from inactive connection") + + profile = context.profile mgr = MediationManager(profile) try: async with profile.session() as session: diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_request_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_request_handler.py index 2a017d9852..fedd7da258 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_request_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/mediation_request_handler.py @@ -1,6 +1,5 @@ """Handler for mediate-request message.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -15,12 +14,6 @@ class MediationRequestHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle mediate-request message.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "%s called with context %s", self.__class__.__name__, context ) diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/manager.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/manager.py index 92cb5a0bac..8a5a1143ec 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/manager.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/manager.py @@ -5,7 +5,6 @@ from ....core.error import BaseError from ....core.profile import Profile, ProfileSession -from ....config.logging import get_adapted_logger_inst from ....storage.base import BaseStorage from ....storage.error import StorageNotFoundError from ....storage.record import StorageRecord @@ -68,11 +67,6 @@ def __init__(self, profile: Profile): self._profile = profile if not profile: raise MediationManagerError("Missing profile") - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) # Role: Server {{{ @@ -586,7 +580,7 @@ async def store_update_results( for updated in results: if updated.result != KeylistUpdated.RESULT_SUCCESS: # TODO better handle different results? - self._logger.warning( + LOGGER.warning( "Keylist update failure: %s(%s): %s", updated.action, updated.recipient_key, @@ -620,13 +614,13 @@ async def store_update_results( }, ) except StorageNotFoundError as err: - self._logger.error( + LOGGER.error( "No route found while processing keylist update response: %s", err, ) else: if len(records) > 1: - self._logger.error( + LOGGER.error( f"Too many ({len(records)}) routes found " "while processing keylist update response" ) diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/route_manager.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/route_manager.py index 84e7ce05a0..990252cd5a 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/route_manager.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/route_manager.py @@ -8,7 +8,6 @@ import logging from typing import List, Optional, Tuple -from ....config.logging import get_adapted_logger_inst from ....connections.models.conn_record import ConnRecord from ....core.profile import Profile from ....messaging.responder import BaseResponder @@ -23,6 +22,7 @@ from .models.mediation_record import MediationRecord from .normalization import normalize_from_did_key + LOGGER = logging.getLogger(__name__) @@ -129,12 +129,7 @@ async def route_connection_as_invitee( mediation_record: Optional[MediationRecord] = None, ) -> Optional[KeylistUpdate]: """Set up routing for a new connection when we are the invitee.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug("Routing connection as invitee") + LOGGER.debug("Routing connection as invitee") my_info = await self.get_or_create_my_did(profile, conn_record) return await self._route_for_key( profile, my_info.verkey, mediation_record, skip_if_exists=True @@ -147,12 +142,7 @@ async def route_connection_as_inviter( mediation_record: Optional[MediationRecord] = None, ) -> Optional[KeylistUpdate]: """Set up routing for a new connection when we are the inviter.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug("Routing connection as inviter") + LOGGER.debug("Routing connection as inviter") my_info = await self.get_or_create_my_did(profile, conn_record) replace_key = conn_record.invitation_key diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/tests/test_mediation_manager.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/tests/test_mediation_manager.py index 4ca42c8e04..5ccab85c5f 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/tests/test_mediation_manager.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/tests/test_mediation_manager.py @@ -375,12 +375,9 @@ async def test_add_remove_key_mix(self, manager): async def test_store_update_results( self, session: ProfileSession, + manager: MediationManager, ): """test_store_update_results.""" - profile = session.profile - profile.settings["log.file"] = "test.log" - profile.settings["wallet.id"] = "test123" - mock_logger = async_mock.MagicMock(error=async_mock.MagicMock()) await RouteRecord( role=RouteRecord.ROLE_CLIENT, connection_id=TEST_CONN_ID, @@ -398,49 +395,41 @@ async def test_store_update_results( result=KeylistUpdated.RESULT_SUCCESS, ), ] + await manager.store_update_results(TEST_CONN_ID, results) + routes = await RouteRecord.query(session) + + assert len(routes) == 1 + assert routes[0].recipient_key == TEST_ROUTE_VERKEY + + results = [ + KeylistUpdated( + recipient_key=TEST_VERKEY, + action=KeylistUpdateRule.RULE_REMOVE, + result=KeylistUpdated.RESULT_SUCCESS, + ), + ] + with async_mock.patch.object( - test_module, - "get_adapted_logger_inst", - async_mock.MagicMock(return_value=mock_logger), - ): - manager = MediationManager(profile) + RouteRecord, "query", async_mock.CoroutineMock() + ) as mock_route_rec_query, async_mock.patch.object( + test_module.LOGGER, "error", async_mock.MagicMock() + ) as mock_logger_error: + mock_route_rec_query.side_effect = StorageNotFoundError("no record") + await manager.store_update_results(TEST_CONN_ID, results) - routes = await RouteRecord.query(session) - - assert len(routes) == 1 - assert routes[0].recipient_key == TEST_ROUTE_VERKEY - - results = [ - KeylistUpdated( - recipient_key=TEST_VERKEY, - action=KeylistUpdateRule.RULE_REMOVE, - result=KeylistUpdated.RESULT_SUCCESS, - ), - ] - - with async_mock.patch.object( - RouteRecord, "query", async_mock.CoroutineMock() - ) as mock_route_rec_query: - mock_route_rec_query.side_effect = StorageNotFoundError("no record") - await manager.store_update_results(TEST_CONN_ID, results) - assert mock_logger.error.call_count == 1 - - del profile.settings["log.file"] - del profile.settings["wallet.id"] - mock_logger = async_mock.MagicMock(error=async_mock.MagicMock()) + mock_logger_error.assert_called_once() + with async_mock.patch.object( RouteRecord, "query", async_mock.CoroutineMock() ) as mock_route_rec_query, async_mock.patch.object( - test_module, - "get_adapted_logger_inst", - async_mock.MagicMock(return_value=mock_logger), - ): + test_module.LOGGER, "error", async_mock.MagicMock() + ) as mock_logger_error: mock_route_rec_query.return_value = [ async_mock.MagicMock(delete_record=async_mock.CoroutineMock()) ] * 2 - manager = MediationManager(profile) + await manager.store_update_results(TEST_CONN_ID, results) - assert mock_logger.error.call_count == 1 + mock_logger_error.assert_called_once() async def test_store_update_results_exists_relay(self, session, manager): """test_store_update_results_record_exists_relay.""" diff --git a/aries_cloudagent/protocols/didexchange/v1_0/handlers/complete_handler.py b/aries_cloudagent/protocols/didexchange/v1_0/handlers/complete_handler.py index 0af0452e43..72122aa62f 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/handlers/complete_handler.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/handlers/complete_handler.py @@ -1,6 +1,5 @@ """Connection complete handler under RFC 23 (DID exchange).""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -21,14 +20,10 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug(f"DIDXCompleteHandler called with context {context}") assert isinstance(context.message, DIDXComplete) + + profile = context.profile mgr = DIDXManager(profile) try: await mgr.accept_complete(context.message, context.message_receipt) diff --git a/aries_cloudagent/protocols/didexchange/v1_0/handlers/request_handler.py b/aries_cloudagent/protocols/didexchange/v1_0/handlers/request_handler.py index faf7131224..b4b85eb1dc 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/handlers/request_handler.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/handlers/request_handler.py @@ -3,8 +3,6 @@ from aries_cloudagent.protocols.didexchange.v1_0.messages.problem_report import ( DIDXProblemReport, ) - -from .....config.logging import get_adapted_logger_inst from .....connections.models.conn_record import ConnRecord from .....messaging.base_handler import BaseHandler, BaseResponder, RequestContext from ....coordinate_mediation.v1_0.manager import MediationManager @@ -22,14 +20,11 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug(f"DIDXRequestHandler called with context {context}") assert isinstance(context.message, DIDXRequest) + + profile = context.profile mgr = DIDXManager(profile) mediation_id = None diff --git a/aries_cloudagent/protocols/didexchange/v1_0/handlers/response_handler.py b/aries_cloudagent/protocols/didexchange/v1_0/handlers/response_handler.py index 0efbd0ec34..c2c094320a 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/handlers/response_handler.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/handlers/response_handler.py @@ -3,8 +3,6 @@ from aries_cloudagent.protocols.didexchange.v1_0.messages.problem_report import ( DIDXProblemReport, ) - -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -27,14 +25,10 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug(f"DIDXResponseHandler called with context {context}") assert isinstance(context.message, DIDXResponse) + + profile = context.profile mgr = DIDXManager(profile) try: conn_rec = await mgr.accept_response( diff --git a/aries_cloudagent/protocols/didexchange/v1_0/manager.py b/aries_cloudagent/protocols/didexchange/v1_0/manager.py index a1440940dc..0db2702e51 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/manager.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/manager.py @@ -8,7 +8,6 @@ from pydid import BaseDIDDocument as ResolvedDocument from pydid import DIDCommService -from ....config.logging import get_adapted_logger_inst from ....connections.base_manager import BaseConnectionManager from ....connections.models.conn_record import ConnRecord from ....connections.models.diddoc import DIDDoc @@ -40,8 +39,6 @@ from .messages.request import DIDXRequest from .messages.response import DIDXResponse -LOGGER = logging.getLogger(__name__) - class DIDXManagerError(BaseError): """Connection error.""" @@ -57,11 +54,7 @@ def __init__(self, profile: Profile): profile: The profile for this did exchange manager """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) + self._logger = logging.getLogger(__name__) super().__init__(self._profile) @property diff --git a/aries_cloudagent/protocols/discovery/v1_0/handlers/disclose_handler.py b/aries_cloudagent/protocols/discovery/v1_0/handlers/disclose_handler.py index c547ab1096..7c5a313fc4 100644 --- a/aries_cloudagent/protocols/discovery/v1_0/handlers/disclose_handler.py +++ b/aries_cloudagent/protocols/discovery/v1_0/handlers/disclose_handler.py @@ -1,6 +1,5 @@ """Handler for incoming disclose messages.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -17,18 +16,13 @@ class DiscloseHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("DiscloseHandler called with context %s", context) assert isinstance(context.message, Disclose) if not context.connection_ready: raise HandlerException( "Received disclosures message from inactive connection" ) + profile = context.profile mgr = V10DiscoveryMgr(profile) await mgr.receive_disclose( context.message, connection_id=context.connection_record.connection_id diff --git a/aries_cloudagent/protocols/discovery/v1_0/handlers/query_handler.py b/aries_cloudagent/protocols/discovery/v1_0/handlers/query_handler.py index 0defd19c6a..0336b01351 100644 --- a/aries_cloudagent/protocols/discovery/v1_0/handlers/query_handler.py +++ b/aries_cloudagent/protocols/discovery/v1_0/handlers/query_handler.py @@ -1,6 +1,5 @@ """Handler for incoming query messages.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -16,14 +15,9 @@ class QueryHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("QueryHandler called with context %s", context) assert isinstance(context.message, Query) + profile = context.profile mgr = V10DiscoveryMgr(profile) reply = await mgr.receive_query(context.message) reply.assign_thread_from(context.message) diff --git a/aries_cloudagent/protocols/discovery/v1_0/manager.py b/aries_cloudagent/protocols/discovery/v1_0/manager.py index f90c0f94e5..c01093f631 100644 --- a/aries_cloudagent/protocols/discovery/v1_0/manager.py +++ b/aries_cloudagent/protocols/discovery/v1_0/manager.py @@ -5,7 +5,6 @@ from typing import Optional -from ....config.logging import get_adapted_logger_inst from ....core.error import BaseError from ....core.profile import Profile from ....core.protocol_registry import ProtocolRegistry @@ -16,8 +15,6 @@ from .messages.query import Query from .models.discovery_record import V10DiscoveryExchangeRecord -LOGGER = logging.getLogger(__name__) - class V10DiscoveryMgrError(BaseError): """Discover feature v1_0 error.""" @@ -33,11 +30,7 @@ def __init__(self, profile: Profile): profile: The profile for this manager """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) + self._logger = logging.getLogger(__name__) @property def profile(self) -> Profile: diff --git a/aries_cloudagent/protocols/discovery/v2_0/handlers/disclosures_handler.py b/aries_cloudagent/protocols/discovery/v2_0/handlers/disclosures_handler.py index e3a59f0519..adab14bf3e 100644 --- a/aries_cloudagent/protocols/discovery/v2_0/handlers/disclosures_handler.py +++ b/aries_cloudagent/protocols/discovery/v2_0/handlers/disclosures_handler.py @@ -1,6 +1,5 @@ """Handler for incoming disclose messages.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -17,18 +16,13 @@ class DisclosuresHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("DiscloseHandler called with context %s", context) assert isinstance(context.message, Disclosures) if not context.connection_ready: raise HandlerException( "Received disclosures message from inactive connection" ) + profile = context.profile mgr = V20DiscoveryMgr(profile) await mgr.receive_disclose( context.message, connection_id=context.connection_record.connection_id diff --git a/aries_cloudagent/protocols/discovery/v2_0/handlers/queries_handler.py b/aries_cloudagent/protocols/discovery/v2_0/handlers/queries_handler.py index 4c843c7d7e..e970ad0c6f 100644 --- a/aries_cloudagent/protocols/discovery/v2_0/handlers/queries_handler.py +++ b/aries_cloudagent/protocols/discovery/v2_0/handlers/queries_handler.py @@ -1,6 +1,5 @@ """Handler for incoming queries messages.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -16,14 +15,9 @@ class QueriesHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("QueryHandler called with context %s", context) assert isinstance(context.message, Queries) + profile = context.profile mgr = V20DiscoveryMgr(profile) reply = await mgr.receive_query(context.message) reply.assign_thread_from(context.message) diff --git a/aries_cloudagent/protocols/discovery/v2_0/manager.py b/aries_cloudagent/protocols/discovery/v2_0/manager.py index 7ee18f6efd..05609e3c09 100644 --- a/aries_cloudagent/protocols/discovery/v2_0/manager.py +++ b/aries_cloudagent/protocols/discovery/v2_0/manager.py @@ -9,7 +9,6 @@ from ....core.profile import Profile from ....core.protocol_registry import ProtocolRegistry from ....core.goal_code_registry import GoalCodeRegistry -from ....config.logging import get_adapted_logger_inst from ....storage.error import StorageNotFoundError from ....messaging.responder import BaseResponder @@ -17,8 +16,6 @@ from .messages.queries import QueryItem, Queries from .models.discovery_record import V20DiscoveryExchangeRecord -LOGGER = logging.getLogger(__name__) - class V20DiscoveryMgrError(BaseError): """Discover feature v2_0 error.""" @@ -34,11 +31,7 @@ def __init__(self, profile: Profile): profile: The profile for this manager """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) + self._logger = logging.getLogger(__name__) @property def profile(self) -> Profile: diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/endorsed_transaction_response_handler.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/endorsed_transaction_response_handler.py index d3910e5291..88dff4f6e8 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/endorsed_transaction_response_handler.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/endorsed_transaction_response_handler.py @@ -1,6 +1,5 @@ """Endorsed transaction response handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -23,12 +22,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug( f"EndorsedTransactionResponseHandler called with context {context}" ) diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/refused_transaction_response_handler.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/refused_transaction_response_handler.py index b327557566..46da51853e 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/refused_transaction_response_handler.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/refused_transaction_response_handler.py @@ -1,6 +1,5 @@ """Refused transaction response handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug( f"RefusedTransactionResponseHandler called with context {context}" ) diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_acknowledgement_handler.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_acknowledgement_handler.py index 1294ef710f..0803a7216b 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_acknowledgement_handler.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_acknowledgement_handler.py @@ -1,6 +1,5 @@ """Transaction acknowledgement message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug( f"TransactionAcknowledgementHandler called with context {context}" ) diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_cancel_handler.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_cancel_handler.py index e194cf710e..0154b4e723 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_cancel_handler.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_cancel_handler.py @@ -1,6 +1,5 @@ """Cancel transaction request handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug(f"TransactionCancelHandler called with context {context}") assert isinstance(context.message, CancelTransaction) diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_job_to_send_handler.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_job_to_send_handler.py index 3a95958e1c..35e1d50bed 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_job_to_send_handler.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_job_to_send_handler.py @@ -1,6 +1,5 @@ """Transaction Job to send handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -21,12 +20,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug(f"TransactionJobToSendHandler called with context {context}") assert isinstance(context.message, TransactionJobToSend) diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_request_handler.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_request_handler.py index 66da217863..bc60a9a69b 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_request_handler.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_request_handler.py @@ -1,6 +1,5 @@ """Transaction request handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -25,12 +24,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug(f"TransactionRequestHandler called with context {context}") assert isinstance(context.message, TransactionRequest) diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_resend_handler.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_resend_handler.py index 1fe373b793..268b3f85f2 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_resend_handler.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/handlers/transaction_resend_handler.py @@ -1,6 +1,5 @@ """Transaction resend handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug(f"TransactionResendHandler called with context {context}") assert isinstance(context.message, TransactionResend) diff --git a/aries_cloudagent/protocols/endorse_transaction/v1_0/routes.py b/aries_cloudagent/protocols/endorse_transaction/v1_0/routes.py index 5a349232b4..25405cd9e5 100644 --- a/aries_cloudagent/protocols/endorse_transaction/v1_0/routes.py +++ b/aries_cloudagent/protocols/endorse_transaction/v1_0/routes.py @@ -15,7 +15,6 @@ from marshmallow import fields, validate from ....admin.request_context import AdminRequestContext -from ....config.logging import get_adapted_logger_inst from ....connections.models.conn_record import ConnRecord from ....core.event_bus import Event, EventBus from ....core.profile import Profile @@ -720,11 +719,6 @@ def register_events(event_bus: EventBus): async def on_startup_event(profile: Profile, event: Event): """Handle any events we need to support.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) # auto setup is only for authors if not is_author_role(profile): return @@ -801,7 +795,7 @@ async def on_startup_event(profile: Profile, event: Event): except Exception: # log the error, but continue - _logger.exception( + LOGGER.exception( "Error accepting endorser invitation/configuring endorser connection: %s", ) diff --git a/aries_cloudagent/protocols/introduction/v0_1/demo_service.py b/aries_cloudagent/protocols/introduction/v0_1/demo_service.py index 95a0e9b09a..3f54dd6f8c 100644 --- a/aries_cloudagent/protocols/introduction/v0_1/demo_service.py +++ b/aries_cloudagent/protocols/introduction/v0_1/demo_service.py @@ -3,7 +3,6 @@ import json import logging -from ....config.logging import get_adapted_logger_inst from ....connections.models.conn_record import ConnRecord from ....core.profile import ProfileSession from ....storage.base import ( @@ -111,12 +110,7 @@ async def return_invitation( outbound_handler: The outbound handler coroutine for sending a message """ thread_id = invitation._thread_id - profile = session.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + tag_filter = {"target_connection_id": target_connection_id} storage = session.inject(BaseStorage) records = await storage.find_all_records( @@ -140,8 +134,8 @@ async def return_invitation( init_connection_id = row.tags["init_connection_id"] await outbound_handler(msg, connection_id=init_connection_id) found = True - _logger.info("Forwarded fwd-invitation to %s", init_connection_id) + LOGGER.info("Forwarded fwd-invitation to %s", init_connection_id) break if not found: - _logger.error("Could not forward invitation, no pending introduction found") + LOGGER.error("Could not forward invitation, no pending introduction found") diff --git a/aries_cloudagent/protocols/introduction/v0_1/handlers/forward_invitation_handler.py b/aries_cloudagent/protocols/introduction/v0_1/handlers/forward_invitation_handler.py index 99a02c3006..2b6cbeadba 100644 --- a/aries_cloudagent/protocols/introduction/v0_1/handlers/forward_invitation_handler.py +++ b/aries_cloudagent/protocols/introduction/v0_1/handlers/forward_invitation_handler.py @@ -1,6 +1,5 @@ """Handler for incoming forward invitation messages.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -19,12 +18,6 @@ class ForwardInvitationHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("ForwardInvitationHandler called with context %s", context) assert isinstance(context.message, ForwardInvitation) @@ -34,6 +27,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): ) # Store invitation + profile = context.profile connection_mgr = ConnectionManager(profile) try: diff --git a/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_handler.py b/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_handler.py index bf69f9a9fe..3244d2e338 100644 --- a/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_handler.py +++ b/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_handler.py @@ -1,8 +1,6 @@ """Handler for incoming invitation messages.""" from typing import Optional - -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -19,12 +17,6 @@ class InvitationHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("InvitationHandler called with context %s", context) assert isinstance(context.message, IntroInvitation) diff --git a/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_request_handler.py b/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_request_handler.py index 508e082d85..c1d284c1f3 100644 --- a/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_request_handler.py +++ b/aries_cloudagent/protocols/introduction/v0_1/handlers/invitation_request_handler.py @@ -1,6 +1,5 @@ """Handler for incoming invitation request messages.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -19,12 +18,6 @@ class InvitationRequestHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("InvitationRequestHandler called with context %s", context) assert isinstance(context.message, IntroInvitationRequest) @@ -37,6 +30,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): if context.settings.get("auto_accept_intro_invitation_requests"): # Create a new connection invitation and send it back in an IntroInvitation + profile = context.profile connection_mgr = ConnectionManager(profile) _connection, invite = await connection_mgr.create_invitation() response = IntroInvitation( diff --git a/aries_cloudagent/protocols/introduction/v0_1/routes.py b/aries_cloudagent/protocols/introduction/v0_1/routes.py index 6a670e4422..ed1e9ea226 100644 --- a/aries_cloudagent/protocols/introduction/v0_1/routes.py +++ b/aries_cloudagent/protocols/introduction/v0_1/routes.py @@ -9,7 +9,6 @@ from marshmallow import fields from ....admin.request_context import AdminRequestContext -from ....config.logging import get_adapted_logger_inst from ....messaging.models.openapi import OpenAPISchema from ....messaging.valid import UUID4_EXAMPLE from ....storage.error import StorageError @@ -61,14 +60,8 @@ async def introduction_start(request: web.BaseRequest): request: aiohttp request object """ + LOGGER.info("Introduction requested") context: AdminRequestContext = request["context"] - profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.info("Introduction requested") outbound_handler = request["outbound_message_router"] init_connection_id = request.match_info["conn_id"] target_connection_id = request.query.get("target_connection_id") diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_ack_handler.py b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_ack_handler.py index 9a4da7c1a8..1c7f2f7d87 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_ack_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_ack_handler.py @@ -1,6 +1,5 @@ """Credential ack message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): responder: responder callback """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("CredentialAckHandler called with context %s", context) assert isinstance(context.message, CredentialAck) self._logger.info( diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_issue_handler.py b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_issue_handler.py index 3a3a005677..778a9985aa 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_issue_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_issue_handler.py @@ -1,6 +1,5 @@ """Credential issue message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....indy.holder import IndyHolderError from .....messaging.base_handler import BaseHandler, HandlerException @@ -29,11 +28,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("CredentialHandler called with context %s", context) assert isinstance(context.message, CredentialIssue) self._logger.info( diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_offer_handler.py b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_offer_handler.py index 2719813057..f2e1b0e324 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_offer_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_offer_handler.py @@ -1,6 +1,6 @@ """Credential offer message handler.""" -from .....config.logging import get_adapted_logger_inst + from .....wallet.util import default_did_from_verkey from .....core.oob_processor import OobMessageProcessor from .....indy.holder import IndyHolderError @@ -31,11 +31,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("CredentialOfferHandler called with context %s", context) assert isinstance(context.message, CredentialOffer) self._logger.info( diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_problem_report_handler.py b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_problem_report_handler.py index 6a23734851..3936dece50 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_problem_report_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_problem_report_handler.py @@ -1,6 +1,5 @@ """Credential problem report message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -20,12 +19,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: request context responder: responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "Issue-credential v1.0 problem report handler called with context %s", context, diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_proposal_handler.py b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_proposal_handler.py index c1c355ecfd..5b4ff0b1ce 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_proposal_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_proposal_handler.py @@ -1,6 +1,5 @@ """Credential proposal message handler.""" -from .....config.logging import get_adapted_logger_inst from .....indy.issuer import IndyIssuerError from .....ledger.error import LedgerError from .....messaging.base_handler import BaseHandler, HandlerException @@ -29,11 +28,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("CredentialProposalHandler called with context %s", context) assert isinstance(context.message, CredentialProposal) diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_request_handler.py b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_request_handler.py index 6cbaa247bc..02794bca6f 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_request_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/handlers/credential_request_handler.py @@ -1,6 +1,5 @@ """Credential request message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....indy.issuer import IndyIssuerError from .....ledger.error import LedgerError @@ -30,11 +29,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("CredentialRequestHandler called with context %s", context) assert isinstance(context.message, CredentialRequest) self._logger.info( diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/manager.py b/aries_cloudagent/protocols/issue_credential/v1_0/manager.py index fc3ba0a366..f0dabfedff 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/manager.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/manager.py @@ -8,7 +8,6 @@ from ....cache.base import BaseCache from ....connections.models.conn_record import ConnRecord -from ....config.logging import get_adapted_logger_inst from ....core.error import BaseError from ....core.profile import Profile from ....indy.holder import IndyHolder, IndyHolderError @@ -62,11 +61,6 @@ def __init__(self, profile: Profile): profile: The profile instance for this credential manager """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) @property def profile(self) -> Profile: @@ -445,7 +439,7 @@ async def _create(): } if cred_ex_record.state == V10CredentialExchange.STATE_REQUEST_SENT: - self._logger.warning( + LOGGER.warning( "create_request called multiple times for v1.0 credential exchange: %s", cred_ex_record.credential_exchange_id, ) @@ -547,7 +541,7 @@ async def receive_request( "Indy issue credential format can't start from credential request" ) from None if cred_ex_record.state != V10CredentialExchange.STATE_OFFER_SENT: - self._logger.error( + LOGGER.error( "Skipping credential request; exchange state is %s (id=%s)", cred_ex_record.state, cred_ex_record.credential_exchange_id, @@ -586,7 +580,7 @@ async def issue_credential( credential_ser = None if cred_ex_record.credential: - self._logger.warning( + LOGGER.warning( "issue_credential called multiple times for v1.0 credential exchange %s", cred_ex_record.credential_exchange_id, ) @@ -631,7 +625,7 @@ async def issue_credential( for attempt in range(max(retries, 1)): if attempt > 0: - self._logger.info( + LOGGER.info( "Waiting 2s before retrying credential issuance " "for cred def '%s'", cred_def_id, @@ -836,9 +830,7 @@ async def store_credential( rev_reg_def=revoc_reg_def, ) except IndyHolderError as e: - self._logger.error( - "Error storing credential: %s: %s", e.error_code, e.message - ) + LOGGER.error("Error storing credential: %s: %s", e.error_code, e.message) raise e credential_json = await holder.get_credential(credential_id) @@ -892,7 +884,7 @@ async def send_credential_ack( txn, cred_ex_record.credential_exchange_id, for_update=True ) except StorageNotFoundError: - self._logger.warning( + LOGGER.warning( "Skipping credential exchange ack, record not found: '%s'", cred_ex_record.credential_exchange_id, ) @@ -902,7 +894,7 @@ async def send_credential_ack( cred_ex_record.state != V10CredentialExchange.STATE_CREDENTIAL_RECEIVED ): - self._logger.warning( + LOGGER.warning( "Skipping credential exchange ack, state is '%s' for record '%s'", cred_ex_record.state, cred_ex_record.credential_exchange_id, @@ -918,7 +910,7 @@ async def send_credential_ack( await cred_ex_record.delete_record(session) # all done: delete except StorageError: - self._logger.exception( + LOGGER.exception( "Error updating credential exchange" ) # holder still owes an ack: carry on @@ -929,7 +921,7 @@ async def send_credential_ack( connection_id=cred_ex_record.connection_id, ) else: - self._logger.warning( + LOGGER.warning( "Configuration has no BaseResponder: cannot ack credential on %s", cred_ex_record.thread_id, ) @@ -959,7 +951,7 @@ async def receive_credential_ack( ) ) except StorageNotFoundError: - self._logger.warning( + LOGGER.warning( "Skip ack message on credential exchange, record not found %s", message._thread_id, ) @@ -996,7 +988,7 @@ async def receive_problem_report( ) ) except StorageNotFoundError: - self._logger.warning( + LOGGER.warning( "Skip problem report on credential exchange, record not found %s", message._thread_id, ) diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/models/credential_exchange.py b/aries_cloudagent/protocols/issue_credential/v1_0/models/credential_exchange.py index 4d2cf0ab95..2137d04986 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/models/credential_exchange.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/models/credential_exchange.py @@ -5,7 +5,6 @@ from marshmallow import fields, validate -from .....config.logging import get_adapted_logger_inst from .....core.profile import ProfileSession from .....indy.models.cred import IndyCredential, IndyCredentialSchema from .....indy.models.cred_abstract import IndyCredAbstract, IndyCredAbstractSchema @@ -207,12 +206,7 @@ async def save_error_state( log_params: Additional parameters to log override: Override configured logging regimen, print to stderr instead """ - profile = session.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + if self._last_state == state: # already done return @@ -228,7 +222,7 @@ async def save_error_state( log_override=log_override, ) except StorageError: - _logger.exception("Error saving credential exchange error state") + LOGGER.exception("Error saving credential exchange error state") # Override async def emit_event(self, session: ProfileSession, payload: Any = None): diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/formats/handler.py b/aries_cloudagent/protocols/issue_credential/v2_0/formats/handler.py index ee56a933d9..183ecbf0a0 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/formats/handler.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/formats/handler.py @@ -7,7 +7,6 @@ from .....core.error import BaseError from .....core.profile import Profile -from .....config.logging import get_adapted_logger_inst from .....messaging.decorators.attach_decorator import AttachDecorator from ..messages.cred_format import V20CredFormat @@ -18,6 +17,7 @@ from ..models.cred_ex_record import V20CredExRecord LOGGER = logging.getLogger(__name__) + CredFormatAttachment = Tuple[V20CredFormat, AttachDecorator] @@ -35,11 +35,6 @@ def __init__(self, profile: Profile): super().__init__() self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) @property def profile(self) -> Profile: diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_ack_handler.py b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_ack_handler.py index 7912644363..26f5d10498 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_ack_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_ack_handler.py @@ -1,6 +1,5 @@ """Credential ack message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): responder: responder callback """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20CredAckHandler called with context %s", context) assert isinstance(context.message, V20CredAck) self._logger.info( diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_issue_handler.py b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_issue_handler.py index 47de99eb69..f3c5704252 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_issue_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_issue_handler.py @@ -1,6 +1,5 @@ """Credential issue message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....indy.holder import IndyHolderError from .....messaging.base_handler import BaseHandler, HandlerException @@ -28,12 +27,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20CredIssueHandler called with context %s", context) assert isinstance(context.message, V20CredIssue) self._logger.info( diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_offer_handler.py b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_offer_handler.py index dcc4a0e965..3184b79b55 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_offer_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_offer_handler.py @@ -1,6 +1,5 @@ """Credential offer message handler.""" -from .....config.logging import get_adapted_logger_inst from .....wallet.util import default_did_from_verkey from .....core.oob_processor import OobMessageProcessor from .....indy.holder import IndyHolderError @@ -30,12 +29,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20CredOfferHandler called with context %s", context) assert isinstance(context.message, V20CredOffer) self._logger.info( @@ -64,6 +58,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): else None ) + profile = context.profile cred_manager = V20CredManager(profile) cred_ex_record = await cred_manager.receive_offer( context.message, connection_id diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py index b3078298ba..d3b85ecacd 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_problem_report_handler.py @@ -1,6 +1,5 @@ """Credential problem report message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -20,12 +19,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: request context responder: responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "Issue-credential v2.0 problem report handler called with context %s", context, diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_proposal_handler.py b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_proposal_handler.py index f95a562518..4ff09f70aa 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_proposal_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_proposal_handler.py @@ -1,6 +1,5 @@ """Credential proposal message handler.""" -from .....config.logging import get_adapted_logger_inst from .....indy.issuer import IndyIssuerError from .....ledger.error import LedgerError from .....messaging.base_handler import BaseHandler, HandlerException @@ -28,12 +27,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20CredProposalHandler called with context %s", context) assert isinstance(context.message, V20CredProposal) self._logger.info( @@ -49,6 +43,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): "Connectionless not supported for credential proposal" ) + profile = context.profile cred_manager = V20CredManager(profile) cred_ex_record = await cred_manager.receive_proposal( context.message, context.connection_record.connection_id diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_request_handler.py b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_request_handler.py index 4df7e55905..ecf0d6fb15 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_request_handler.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/handlers/cred_request_handler.py @@ -1,6 +1,5 @@ """Credential request message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....indy.issuer import IndyIssuerError from .....ledger.error import LedgerError @@ -29,12 +28,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20CredRequestHandler called with context %s", context) assert isinstance(context.message, V20CredRequest) self._logger.info( @@ -58,6 +52,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): " request" ) + profile = context.profile cred_manager = V20CredManager(profile) cred_ex_record = await cred_manager.receive_request( context.message, context.connection_record, oob_record diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/manager.py b/aries_cloudagent/protocols/issue_credential/v2_0/manager.py index d699d66592..fe737c27f6 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/manager.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/manager.py @@ -5,7 +5,6 @@ from typing import Mapping, Optional, Tuple from ....connections.models.conn_record import ConnRecord -from ....config.logging import get_adapted_logger_inst from ....core.oob_processor import OobRecord from ....core.error import BaseError from ....core.profile import Profile @@ -39,11 +38,6 @@ def __init__(self, profile: Profile): profile: The profile instance for this credential manager """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) @property def profile(self) -> Profile: @@ -655,7 +649,7 @@ async def send_cred_ack( await self.delete_cred_ex_record(cred_ex_record.cred_ex_id) except StorageError: - self._logger.exception( + LOGGER.exception( "Error sending credential ack" ) # holder still owes an ack: carry on @@ -666,7 +660,7 @@ async def send_cred_ack( connection_id=cred_ex_record.connection_id, ) else: - self._logger.warning( + LOGGER.warning( "Configuration has no BaseResponder: cannot ack credential on %s", cred_ex_record.thread_id, ) diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/models/cred_ex_record.py b/aries_cloudagent/protocols/issue_credential/v2_0/models/cred_ex_record.py index 8fa2a8557a..1eece14bac 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/models/cred_ex_record.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/models/cred_ex_record.py @@ -5,7 +5,6 @@ from marshmallow import Schema, fields, validate -from .....config.logging import get_adapted_logger_inst from .....core.profile import ProfileSession from .....messaging.models.base_record import BaseExchangeRecord, BaseExchangeSchema from .....messaging.valid import UUID4_EXAMPLE @@ -163,12 +162,7 @@ async def save_error_state( log_params: Additional parameters to log override: Override configured logging regimen, print to stderr instead """ - profile = session.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + if self._last_state == state: # already done return @@ -184,7 +178,7 @@ async def save_error_state( log_override=log_override, ) except StorageError as err: - _logger.exception(err) + LOGGER.exception(err) # Override async def emit_event(self, session: ProfileSession, payload: Any = None): diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/models/tests/test_cred_ex_record.py b/aries_cloudagent/protocols/issue_credential/v2_0/models/tests/test_cred_ex_record.py index 2a6c3efdd4..d46fd498d7 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/models/tests/test_cred_ex_record.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/models/tests/test_cred_ex_record.py @@ -118,23 +118,18 @@ def test_serde(self): async def test_save_error_state(self): session = InMemoryProfile.test_session() - profile = session.profile - profile.settings["log.file"] = "test_file.log" - profile.settings["wallet.id"] = "test123" record = V20CredExRecord(state=None) assert record._last_state is None await record.save_error_state(session) # cover short circuit record.state = V20CredExRecord.STATE_PROPOSAL_RECEIVED await record.save(session) - mock_logger = async_mock.MagicMock(exception=async_mock.MagicMock()) + with async_mock.patch.object( record, "save", async_mock.CoroutineMock() ) as mock_save, async_mock.patch.object( - test_module, - "get_adapted_logger_inst", - async_mock.MagicMock(return_value=mock_logger), - ): + test_module.LOGGER, "exception", async_mock.MagicMock() + ) as mock_log_exc: mock_save.side_effect = test_module.StorageError() await record.save_error_state(session, reason="test") - assert mock_logger.exception.call_count == 1 + mock_log_exc.assert_called_once() diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/routes.py b/aries_cloudagent/protocols/issue_credential/v2_0/routes.py index 2a63a366e9..721128b4ae 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/routes.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/routes.py @@ -16,7 +16,6 @@ from marshmallow import ValidationError, fields, validate, validates_schema from ....admin.request_context import AdminRequestContext -from ....config.logging import get_adapted_logger_inst from ....connections.models.conn_record import ConnRecord from ....core.profile import Profile from ....indy.holder import IndyHolderError @@ -681,11 +680,6 @@ async def credential_exchange_send(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] body = await request.json() @@ -749,7 +743,7 @@ async def credential_exchange_send(request: web.BaseRequest): V20CredManagerError, V20CredFormatError, ) as err: - _logger.exception("Error preparing credential offer") + 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) @@ -796,11 +790,6 @@ async def credential_exchange_send_proposal(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] body = await request.json() @@ -842,7 +831,7 @@ async def credential_exchange_send_proposal(request: web.BaseRequest): result = cred_ex_record.serialize() except (BaseModelError, StorageError) as err: - _logger.exception("Error preparing credential proposal") + LOGGER.exception("Error preparing credential proposal") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) @@ -933,11 +922,7 @@ async def credential_exchange_create_free_offer(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + body = await request.json() auto_issue = body.get( @@ -970,7 +955,7 @@ async def credential_exchange_create_free_offer(request: web.BaseRequest): V20CredFormatError, V20CredManagerError, ) as err: - _logger.exception("Error creating free credential offer") + LOGGER.exception("Error creating free credential offer") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) @@ -1007,11 +992,6 @@ async def credential_exchange_send_free_offer(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] body = await request.json() @@ -1058,7 +1038,7 @@ async def credential_exchange_send_free_offer(request: web.BaseRequest): V20CredFormatError, V20CredManagerError, ) as err: - _logger.exception("Error preparing free credential offer") + LOGGER.exception("Error preparing free credential offer") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) @@ -1106,11 +1086,6 @@ async def credential_exchange_send_bound_offer(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] body = await request.json() if request.body_exists else {} @@ -1169,7 +1144,7 @@ async def credential_exchange_send_bound_offer(request: web.BaseRequest): V20CredFormatError, V20CredManagerError, ) as err: - _logger.exception("Error preparing bound credential offer") + LOGGER.exception("Error preparing bound credential offer") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) @@ -1218,11 +1193,6 @@ async def credential_exchange_send_free_request(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] body = await request.json() @@ -1278,7 +1248,7 @@ async def credential_exchange_send_free_request(request: web.BaseRequest): StorageError, V20CredManagerError, ) as err: - _logger.exception("Error preparing free credential request") + LOGGER.exception("Error preparing free credential request") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) @@ -1323,11 +1293,6 @@ async def credential_exchange_send_bound_request(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] try: @@ -1399,7 +1364,7 @@ async def credential_exchange_send_bound_request(request: web.BaseRequest): V20CredFormatError, V20CredManagerError, ) as err: - _logger.exception("Error preparing bound credential request") + LOGGER.exception("Error preparing bound credential request") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) @@ -1446,11 +1411,6 @@ async def credential_exchange_issue(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] body = await request.json() @@ -1497,7 +1457,7 @@ async def credential_exchange_issue(request: web.BaseRequest): V20CredFormatError, V20CredManagerError, ) as err: - _logger.exception("Error preparing issued credential") + LOGGER.exception("Error preparing issued credential") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) @@ -1544,11 +1504,6 @@ async def credential_exchange_store(request: web.BaseRequest): context: AdminRequestContext = request["context"] profile = context.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) outbound_handler = request["outbound_message_router"] try: @@ -1588,7 +1543,7 @@ async def credential_exchange_store(request: web.BaseRequest): StorageError, V20CredManagerError, ) as err: # treat failure to store as mangled on receipt hence protocol error - _logger.exception("Error storing issued credential") + LOGGER.exception("Error storing issued credential") if cred_ex_record: async with profile.session() as session: await cred_ex_record.save_error_state(session, reason=err.roll_up) diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/tests/test_manager.py b/aries_cloudagent/protocols/issue_credential/v2_0/tests/test_manager.py index 0c76972f94..b1ed8216ea 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/tests/test_manager.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/tests/test_manager.py @@ -1280,33 +1280,25 @@ async def test_send_cred_ack(self): trace=False, auto_remove=True, ) - mock_logger = async_mock.MagicMock( - warning=async_mock.MagicMock(), - exception=async_mock.MagicMock(), - ) - self.profile.settings["log.file"] = "test.log" - self.profile.settings["wallet.id"] = "test123" + with async_mock.patch.object( V20CredExRecord, "save", autospec=True ) as mock_save_ex, async_mock.patch.object( V20CredExRecord, "delete_record", autospec=True ) as mock_delete_ex, async_mock.patch.object( - test_module, - "get_adapted_logger_inst", - async_mock.MagicMock(return_value=mock_logger), - ): + test_module.LOGGER, "exception", async_mock.MagicMock() + ) as mock_log_exception, async_mock.patch.object( + test_module.LOGGER, "warning", async_mock.MagicMock() + ) as mock_log_warning: mock_delete_ex.side_effect = test_module.StorageError() - manager = V20CredManager(self.profile) - (_, ack) = await manager.send_cred_ack(stored_exchange) + (_, ack) = await self.manager.send_cred_ack(stored_exchange) assert ack._thread - assert ( - mock_logger.exception.call_count == 1 - ) # cover exception log-and-continue - assert mock_logger.warning.call_count == 1 # no BaseResponder + mock_log_exception.assert_called_once() # cover exception log-and-continue + mock_log_warning.assert_called_once() # no BaseResponder mock_responder = MockResponder() # cover with responder self.context.injector.bind_instance(BaseResponder, mock_responder) - (cx_rec, ack) = await manager.send_cred_ack(stored_exchange) + (cx_rec, ack) = await self.manager.send_cred_ack(stored_exchange) assert ack._thread assert cx_rec.state == V20CredExRecord.STATE_DONE diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/handlers/problem_report_handler.py b/aries_cloudagent/protocols/out_of_band/v1_0/handlers/problem_report_handler.py index cfb2da0309..9602d5ce7d 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/handlers/problem_report_handler.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/handlers/problem_report_handler.py @@ -1,6 +1,5 @@ """OOB Problem Report Message Handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -22,17 +21,12 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( f"OOBProblemReportMessageHandler called with context {context}" ) assert isinstance(context.message, OOBProblemReport) + profile = context.profile mgr = OutOfBandManager(profile) try: await mgr.receive_problem_report( diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_accept_handler.py b/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_accept_handler.py index 9e29ceec38..ae19d16441 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_accept_handler.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_accept_handler.py @@ -1,6 +1,5 @@ """Handshake Reuse Accepted Message Handler under RFC 0434.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -19,17 +18,12 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( f"HandshakeReuseAcceptMessageHandler called with context {context}" ) assert isinstance(context.message, HandshakeReuseAccept) + profile = context.profile mgr = OutOfBandManager(profile) try: await mgr.receive_reuse_accepted_message( diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_handler.py b/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_handler.py index db558cd061..a312a2af1f 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_handler.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/handlers/reuse_handler.py @@ -1,6 +1,5 @@ """Handshake Reuse Message Handler under RFC 0434.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -19,17 +18,12 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: Request context responder: Responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( f"HandshakeReuseMessageHandler called with context {context}" ) assert isinstance(context.message, HandshakeReuse) + profile = context.profile mgr = OutOfBandManager(profile) try: await mgr.receive_reuse_message( diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/manager.py b/aries_cloudagent/protocols/out_of_band/v1_0/manager.py index b59cb6df8f..007b43a675 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/manager.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/manager.py @@ -6,12 +6,12 @@ from typing import Mapping, Optional, Sequence, Union, Text import uuid + from ....messaging.decorators.service_decorator import ServiceDecorator from ....core.event_bus import EventBus from ....core.util import get_version_from_message from ....connections.base_manager import BaseConnectionManager from ....connections.models.conn_record import ConnRecord -from ....config.logging import get_adapted_logger_inst from ....core.error import BaseError from ....core.oob_processor import OobMessageProcessor from ....core.profile import Profile @@ -63,11 +63,6 @@ def __init__(self, profile: Profile): profile: The profile for this out of band manager """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) super().__init__(self._profile) @property @@ -464,7 +459,7 @@ async def receive_invitation( if ( public_did is not None and use_existing_connection ): # invite has public DID: seek existing connection - self._logger.debug( + LOGGER.debug( "Trying to find existing connection for oob invitation with " f"did {public_did}" ) @@ -487,7 +482,7 @@ async def receive_invitation( oob_record, conn_rec, get_version_from_message(invitation) ) - self._logger.warning( + LOGGER.warning( f"Connection reuse request finished with state {oob_record.state}" ) @@ -508,7 +503,7 @@ async def receive_invitation( mediation_id=mediation_id, service_accept=service_accept, ) - self._logger.debug( + LOGGER.debug( f"Performed handshake with connection {oob_record.connection_id}" ) # re-fetch connection record @@ -532,7 +527,7 @@ async def receive_invitation( # Handle any attachments if invitation.requests_attach: - self._logger.debug( + LOGGER.debug( f"Process attached messages for oob exchange {oob_record.oob_id} " f"(connection_id {oob_record.connection_id})" ) @@ -584,9 +579,9 @@ async def _process_request_attach(self, oob_record: OobRecord): service = oob_record.invitation.services[0] their_service = await self._service_decorator_from_service(service) if their_service: - self._logger.debug("Found service for oob record %s", their_service) + LOGGER.debug("Found service for oob record %s", their_service) else: - self._logger.debug("No service decorator obtained from %s", service) + LOGGER.debug("No service decorator obtained from %s", service) await message_processor.handle_message( self.profile, messages, oob_record=oob_record, their_service=their_service @@ -631,7 +626,7 @@ async def _service_decorator_from_service( routing_keys=routing_keys, ) else: - self._logger.warning( + LOGGER.warning( "Unexpected type `%s` passed to `_service_decorator_from_service`", type(service), ) @@ -677,11 +672,9 @@ async def _wait_for_state() -> OobRecord: ]: return oob_record - self._logger.debug( - f"Wait for oob {oob_id} to receive reuse accepted mesage" - ) + LOGGER.debug(f"Wait for oob {oob_id} to receive reuse accepted mesage") event = await await_event - self._logger.debug("Received reuse response message") + LOGGER.debug("Received reuse response message") return OobRecord.deserialize(event.payload) try: @@ -703,7 +696,7 @@ async def _wait_for_conn_rec_active( "^acapy::record::connections::(active|completed|response)$" ) - self._logger.debug(f"Wait for connection {connection_id} to become active") + LOGGER.debug(f"Wait for connection {connection_id} to become active") async def _wait_for_state() -> ConnRecord: event = self.profile.inject(EventBus) @@ -722,9 +715,7 @@ async def _wait_for_state() -> ConnRecord: if conn_record.is_ready: return conn_record - self._logger.debug( - f"Wait for connection {connection_id} to become active" - ) + LOGGER.debug(f"Wait for connection {connection_id} to become active") # Wait for connection record to be in state event = await await_event return ConnRecord.deserialize(event.payload) @@ -736,9 +727,7 @@ async def _wait_for_state() -> ConnRecord: ) except asyncio.TimeoutError: - self._logger.warning( - f"Connection for connection_id {connection_id} not ready" - ) + LOGGER.warning(f"Connection for connection_id {connection_id} not ready") return None async def _handle_hanshake_reuse( @@ -751,7 +740,7 @@ async def _handle_hanshake_reuse( # Wait for the reuse accepted message oob_record = await self._wait_for_reuse_response(oob_record.oob_id) - self._logger.debug( + LOGGER.debug( f"Oob reuse for oob id {oob_record.oob_id} with connection " f"{oob_record.connection_id} finished with state {oob_record.state}" ) @@ -836,7 +825,7 @@ async def _perform_handshake( } ) - self._logger.debug(f"Creating connection with public did {public_did}") + LOGGER.debug(f"Creating connection with public did {public_did}") conn_record = None for protocol in supported_handshake_protocols: diff --git a/aries_cloudagent/protocols/present_proof/dif/pres_exch_handler.py b/aries_cloudagent/protocols/present_proof/dif/pres_exch_handler.py index 4a98d73fa7..46492d8e87 100644 --- a/aries_cloudagent/protocols/present_proof/dif/pres_exch_handler.py +++ b/aries_cloudagent/protocols/present_proof/dif/pres_exch_handler.py @@ -23,7 +23,6 @@ from ....core.error import BaseError from ....core.profile import Profile -from ....config.logging import get_adapted_logger_inst from ....storage.vc_holder.vc_record import VCRecord from ....vc.ld_proofs import ( Ed25519Signature2018, @@ -59,13 +58,13 @@ PresentationSubmission, ) -LOGGER = logging.getLogger(__name__) PRESENTATION_SUBMISSION_JSONLD_CONTEXT = ( "https://identity.foundation/presentation-exchange/submission/v1" ) PRESENTATION_SUBMISSION_JSONLD_TYPE = "PresentationSubmission" PYTZ_TIMEZONE_PATTERN = re.compile(r"(([a-zA-Z]+)(?:\/)([a-zA-Z]+))") LIST_INDEX_PATTERN = re.compile(r"\[(\W+)\]|\[(\d+)\]") +LOGGER = logging.getLogger(__name__) class DIFPresExchError(BaseError): @@ -112,11 +111,6 @@ def __init__( self.proof_type = proof_type self.is_holder = False self.reveal_doc_frame = reveal_doc - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self.profile.settings.get("log.file"), - wallet_id=self.profile.settings.get("wallet.id"), - ) async def _get_issue_suite( self, @@ -791,7 +785,7 @@ def exclusive_minimum_check(self, val: any, _filter: Filter) -> bool: val = self.is_numeric(val) return val > _filter.exclusive_min except DIFPresExchError as err: - self._logger.error(err) + LOGGER.error(err) return False except (TypeError, ValueError, ParserError): return False @@ -821,7 +815,7 @@ def exclusive_maximum_check(self, val: any, _filter: Filter) -> bool: val = self.is_numeric(val) return val < _filter.exclusive_max except DIFPresExchError as err: - self._logger.error(err) + LOGGER.error(err) return False except (TypeError, ValueError, ParserError): return False @@ -851,7 +845,7 @@ def maximum_check(self, val: any, _filter: Filter) -> bool: val = self.is_numeric(val) return val <= _filter.maximum except DIFPresExchError as err: - self._logger.error(err) + LOGGER.error(err) return False except (TypeError, ValueError, ParserError): return False @@ -881,7 +875,7 @@ def minimum_check(self, val: any, _filter: Filter) -> bool: val = self.is_numeric(val) return val >= _filter.minimum except DIFPresExchError as err: - self._logger.error(err) + LOGGER.error(err) return False except (TypeError, ValueError, ParserError): return False diff --git a/aries_cloudagent/protocols/present_proof/indy/pres_exch_handler.py b/aries_cloudagent/protocols/present_proof/indy/pres_exch_handler.py index c21fc57f0f..4bff88cc89 100644 --- a/aries_cloudagent/protocols/present_proof/indy/pres_exch_handler.py +++ b/aries_cloudagent/protocols/present_proof/indy/pres_exch_handler.py @@ -5,7 +5,6 @@ from typing import Union, Tuple -from ....config.logging import get_adapted_logger_inst from ....core.error import BaseError from ....core.profile import Profile from ....indy.holder import IndyHolder, IndyHolderError @@ -39,11 +38,6 @@ def __init__( """Initialize PresExchange Handler.""" super().__init__() self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) async def return_presentation( self, @@ -89,7 +83,7 @@ async def return_presentation( if not credentials[req_item["cred_id"]].get( "rev_reg_id" ) and req_item.pop("timestamp", None): - self._logger.info( + LOGGER.info( f"Removed superfluous timestamp from requested_credentials {r} " f"{reft} for non-revocable credential {req_item['cred_id']}" ) @@ -196,7 +190,7 @@ async def return_presentation( ) ) except IndyHolderError as e: - self._logger.error( + LOGGER.error( f"Failed to create revocation state: {e.error_code}, {e.message}" ) raise e diff --git a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_ack_handler.py b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_ack_handler.py index cb08a48828..6a3dfa9eef 100644 --- a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_ack_handler.py +++ b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_ack_handler.py @@ -1,6 +1,5 @@ """Presentation ack message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): responder: responder callback """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("PresentationAckHandler called with context %s", context) assert isinstance(context.message, PresentationAck) self._logger.info( diff --git a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_handler.py b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_handler.py index 270c9b0b1b..7aa96f7f27 100644 --- a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_handler.py +++ b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_handler.py @@ -1,6 +1,5 @@ """Presentation message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....ledger.error import LedgerError from .....messaging.base_handler import BaseHandler, HandlerException @@ -29,11 +28,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("PresentationHandler called with context %s", context) assert isinstance(context.message, Presentation) self._logger.info( diff --git a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_problem_report_handler.py b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_problem_report_handler.py index b49651d8fc..56ca1a6848 100644 --- a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_problem_report_handler.py +++ b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_problem_report_handler.py @@ -1,6 +1,5 @@ """Presentation problem report message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -20,12 +19,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: request context responder: responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "Present-proof v1.0 problem report handler called with context %s", context, diff --git a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_proposal_handler.py b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_proposal_handler.py index c202c9dd70..d513123258 100644 --- a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_proposal_handler.py +++ b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_proposal_handler.py @@ -1,6 +1,5 @@ """Presentation proposal message handler.""" -from .....config.logging import get_adapted_logger_inst from .....ledger.error import LedgerError from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.models.base import BaseModelError @@ -28,11 +27,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "PresentationProposalHandler called with context %s", context ) diff --git a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_request_handler.py b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_request_handler.py index f08fc385f7..a34cdde4cd 100644 --- a/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_request_handler.py +++ b/aries_cloudagent/protocols/present_proof/v1_0/handlers/presentation_request_handler.py @@ -1,6 +1,5 @@ """Presentation request message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....indy.holder import IndyHolder, IndyHolderError from .....indy.models.xform import indy_proof_req_preview2indy_requested_creds @@ -33,11 +32,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("PresentationRequestHandler called with context %s", context) assert isinstance(context.message, PresentationRequest) diff --git a/aries_cloudagent/protocols/present_proof/v1_0/manager.py b/aries_cloudagent/protocols/present_proof/v1_0/manager.py index a58ea8787a..b5a85278f9 100644 --- a/aries_cloudagent/protocols/present_proof/v1_0/manager.py +++ b/aries_cloudagent/protocols/present_proof/v1_0/manager.py @@ -4,17 +4,14 @@ import logging from typing import Optional +from ...out_of_band.v1_0.models.oob_record import OobRecord from ....connections.models.conn_record import ConnRecord -from ....config.logging import get_adapted_logger_inst from ....core.error import BaseError from ....core.profile import Profile from ....indy.verifier import IndyVerifier from ....messaging.decorators.attach_decorator import AttachDecorator from ....messaging.responder import BaseResponder from ....storage.error import StorageNotFoundError - -from ...out_of_band.v1_0.models.oob_record import OobRecord - from ..indy.pres_exch_handler import IndyPresExchHandler from .messages.presentation_ack import PresentationAck @@ -46,11 +43,6 @@ def __init__(self, profile: Profile): """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) async def create_exchange_for_proposal( self, @@ -477,7 +469,7 @@ async def send_presentation_ack( except StorageNotFoundError: # This can happen in AIP1 style connectionless exchange. ACA-PY only # supported this for receiving a presentation - self._logger.error( + LOGGER.error( "Unable to send connectionless presentation ack without associated " "oob record. This can happen if proof request was sent without " "wrapping it in an out of band invitation (AIP1-style)." @@ -506,7 +498,7 @@ async def send_presentation_ack( async with self._profile.session() as session: await presentation_exchange_record.delete_record(session) else: - self._logger.warning( + LOGGER.warning( "Configuration has no BaseResponder: cannot ack presentation on %s", presentation_exchange_record.thread_id, ) diff --git a/aries_cloudagent/protocols/present_proof/v1_0/models/presentation_exchange.py b/aries_cloudagent/protocols/present_proof/v1_0/models/presentation_exchange.py index 6d3858c27b..a32c1355eb 100644 --- a/aries_cloudagent/protocols/present_proof/v1_0/models/presentation_exchange.py +++ b/aries_cloudagent/protocols/present_proof/v1_0/models/presentation_exchange.py @@ -5,7 +5,6 @@ from marshmallow import fields, validate -from .....config.logging import get_adapted_logger_inst from .....core.profile import ProfileSession from .....indy.models.proof import IndyProof, IndyProofSchema from .....indy.models.proof_request import IndyProofRequest, IndyProofRequestSchema @@ -177,12 +176,7 @@ async def save_error_state( log_params: Additional parameters to log override: Override configured logging regimen, print to stderr instead """ - profile = session.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + if self._last_state == state: # already done return @@ -198,7 +192,7 @@ async def save_error_state( log_override=log_override, ) except StorageError as err: - _logger.exception(err) + LOGGER.exception(err) # Override async def emit_event(self, session: ProfileSession, payload: Any = None): diff --git a/aries_cloudagent/protocols/present_proof/v2_0/formats/handler.py b/aries_cloudagent/protocols/present_proof/v2_0/formats/handler.py index 6adbbaa2cf..1d8a2e5d07 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/formats/handler.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/formats/handler.py @@ -4,7 +4,6 @@ from typing import Tuple -from .....config.logging import get_adapted_logger_inst from .....core.error import BaseError from .....core.profile import Profile from .....messaging.decorators.attach_decorator import AttachDecorator @@ -14,6 +13,7 @@ from ..models.pres_exchange import V20PresExRecord LOGGER = logging.getLogger(__name__) + PresFormatAttachment = Tuple[V20PresFormat, AttachDecorator] @@ -30,11 +30,6 @@ def __init__(self, profile: Profile): """Initialize PresExchange Handler.""" super().__init__() self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) @property def profile(self) -> Profile: diff --git a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_ack_handler.py b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_ack_handler.py index ad71766dfc..2534a65c4f 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_ack_handler.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_ack_handler.py @@ -1,6 +1,5 @@ """Presentation ack message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.request_context import RequestContext @@ -22,12 +21,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): responder: responder callback """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20PresAckHandler called with context %s", context) assert isinstance(context.message, V20PresAck) self._logger.info( diff --git a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_handler.py b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_handler.py index 2ee7682ae5..9a93d68cc0 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_handler.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_handler.py @@ -1,6 +1,5 @@ """Presentation message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....ledger.error import LedgerError from .....messaging.base_handler import BaseHandler, HandlerException @@ -28,12 +27,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20PresHandler called with context %s", context) assert isinstance(context.message, V20Pres) self._logger.info( diff --git a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py index 2e2f150d5f..32c5e23e0a 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_problem_report_handler.py @@ -1,6 +1,5 @@ """Presentation problem report message handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -20,12 +19,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): context: request context responder: responder callback """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "Present-proof v2.0 problem report handler called with context %s", context, diff --git a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_proposal_handler.py b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_proposal_handler.py index bdd2fa6f8b..23b16c0ebf 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_proposal_handler.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_proposal_handler.py @@ -1,6 +1,5 @@ """Presentation proposal message handler.""" -from .....config.logging import get_adapted_logger_inst from .....ledger.error import LedgerError from .....messaging.base_handler import BaseHandler, HandlerException from .....messaging.models.base import BaseModelError @@ -27,12 +26,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20PresProposalHandler called with context %s", context) assert isinstance(context.message, V20PresProposal) self._logger.info( @@ -50,6 +44,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): "Connection used for presentation proposal not ready" ) + profile = context.profile pres_manager = V20PresManager(profile) pres_ex_record = await pres_manager.receive_pres_proposal( context.message, context.connection_record diff --git a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_request_handler.py b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_request_handler.py index 22902a9c26..abac0f7398 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_request_handler.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/handlers/pres_request_handler.py @@ -1,6 +1,5 @@ """Presentation request message handler.""" -from .....config.logging import get_adapted_logger_inst from .....core.oob_processor import OobMessageProcessor from .....indy.holder import IndyHolderError from .....ledger.error import LedgerError @@ -32,12 +31,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): """ r_time = get_timer() - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("V20PresRequestHandler called with context %s", context) assert isinstance(context.message, V20PresRequest) self._logger.info( @@ -66,6 +60,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): else None ) + profile = context.profile pres_manager = V20PresManager(profile) # Get pres ex record (holder initiated via proposal) diff --git a/aries_cloudagent/protocols/present_proof/v2_0/manager.py b/aries_cloudagent/protocols/present_proof/v2_0/manager.py index 43dafbbec4..083dcac5ac 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/manager.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/manager.py @@ -4,14 +4,12 @@ from typing import Optional, Tuple +from ...out_of_band.v1_0.models.oob_record import OobRecord from ....connections.models.conn_record import ConnRecord -from ....config.logging import get_adapted_logger_inst from ....core.error import BaseError from ....core.profile import Profile from ....messaging.responder import BaseResponder -from ...out_of_band.v1_0.models.oob_record import OobRecord - from .messages.pres import V20Pres from .messages.pres_ack import V20PresAck from .messages.pres_format import V20PresFormat @@ -20,6 +18,7 @@ from .messages.pres_request import V20PresRequest from .models.pres_exchange import V20PresExRecord + LOGGER = logging.getLogger(__name__) @@ -38,11 +37,6 @@ def __init__(self, profile: Profile): """ self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) async def create_exchange_for_proposal( self, @@ -446,7 +440,7 @@ async def send_pres_ack( async with self._profile.session() as session: await pres_ex_record.delete_record(session) else: - self._logger.warning( + LOGGER.warning( "Configuration has no BaseResponder: cannot ack presentation on %s", pres_ex_record.thread_id, ) diff --git a/aries_cloudagent/protocols/present_proof/v2_0/models/pres_exchange.py b/aries_cloudagent/protocols/present_proof/v2_0/models/pres_exchange.py index ae429f35a4..06f43036ea 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/models/pres_exchange.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/models/pres_exchange.py @@ -5,7 +5,6 @@ from marshmallow import Schema, fields, validate -from .....config.logging import get_adapted_logger_inst from .....core.profile import ProfileSession from .....messaging.models.base_record import BaseExchangeRecord, BaseExchangeSchema from .....messaging.valid import UUID4_EXAMPLE @@ -163,12 +162,7 @@ async def save_error_state( log_params: Additional parameters to log override: Override configured logging regimen, print to stderr instead """ - profile = session.profile - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + if self._last_state == state: # already done return @@ -184,7 +178,7 @@ async def save_error_state( log_override=log_override, ) except StorageError as err: - _logger.exception(err) + LOGGER.exception(err) # Override async def emit_event(self, session: ProfileSession, payload: Any = None): diff --git a/aries_cloudagent/protocols/present_proof/v2_0/models/tests/test_record.py b/aries_cloudagent/protocols/present_proof/v2_0/models/tests/test_record.py index 3d506447df..ba27e20f45 100644 --- a/aries_cloudagent/protocols/present_proof/v2_0/models/tests/test_record.py +++ b/aries_cloudagent/protocols/present_proof/v2_0/models/tests/test_record.py @@ -120,21 +120,17 @@ async def test_record(self): async def test_save_error_state(self): session = InMemoryProfile.test_session() record = V20PresExRecord(state=None) - profile = session.profile - profile.settings["log.file"] = "test_file.log" - profile.settings["wallet.id"] = "test123" assert record._last_state is None await record.save_error_state(session) # cover short circuit + record.state = V20PresExRecord.STATE_PROPOSAL_RECEIVED await record.save(session) - mock_logger = async_mock.MagicMock(exception=async_mock.MagicMock()) + with async_mock.patch.object( record, "save", async_mock.CoroutineMock() ) as mock_save, async_mock.patch.object( - test_module, - "get_adapted_logger_inst", - async_mock.MagicMock(return_value=mock_logger), - ): + test_module.LOGGER, "exception", async_mock.MagicMock() + ) as mock_log_exc: mock_save.side_effect = test_module.StorageError() await record.save_error_state(session, reason="testing") - assert mock_logger.exception.call_count == 1 + mock_log_exc.assert_called_once() diff --git a/aries_cloudagent/protocols/problem_report/v1_0/handler.py b/aries_cloudagent/protocols/problem_report/v1_0/handler.py index 9949c5170c..99e1c1d179 100644 --- a/aries_cloudagent/protocols/problem_report/v1_0/handler.py +++ b/aries_cloudagent/protocols/problem_report/v1_0/handler.py @@ -1,6 +1,5 @@ """Generic problem report handler.""" -from ....config.logging import get_adapted_logger_inst from ....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -21,12 +20,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): responder: Responder used to reply """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("ProblemReportHandler called with context %s", context) assert isinstance(context.message, ProblemReport) diff --git a/aries_cloudagent/protocols/revocation_notification/v1_0/handlers/revoke_handler.py b/aries_cloudagent/protocols/revocation_notification/v1_0/handlers/revoke_handler.py index cf0e1733ec..366cbcd6c2 100644 --- a/aries_cloudagent/protocols/revocation_notification/v1_0/handlers/revoke_handler.py +++ b/aries_cloudagent/protocols/revocation_notification/v1_0/handlers/revoke_handler.py @@ -1,6 +1,5 @@ """Handler for revoke message.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -17,12 +16,6 @@ class RevokeHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle revoke message.""" assert isinstance(context.message, Revoke) - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "Received notification of revocation for cred issued in thread %s " "with comment: %s", diff --git a/aries_cloudagent/protocols/revocation_notification/v1_0/routes.py b/aries_cloudagent/protocols/revocation_notification/v1_0/routes.py index f3a2d820d2..cdefdaf642 100644 --- a/aries_cloudagent/protocols/revocation_notification/v1_0/routes.py +++ b/aries_cloudagent/protocols/revocation_notification/v1_0/routes.py @@ -2,7 +2,6 @@ import logging import re -from ....config.logging import get_adapted_logger_inst from ....core.event_bus import Event, EventBus from ....core.profile import Profile from ....messaging.responder import BaseResponder @@ -31,12 +30,7 @@ def register_events(event_bus: EventBus): async def on_revocation_published(profile: Profile, event: Event): """Handle issuer revoke event.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug("Sending notification of revocation to recipient: %s", event.payload) + LOGGER.debug("Sending notification of revocation to recipient: %s", event.payload) responder = profile.inject(BaseResponder) crids = event.payload.get("crids") or [] @@ -56,12 +50,12 @@ async def on_revocation_published(profile: Profile, event: Event): ) except StorageNotFoundError: - _logger.info( + LOGGER.info( "No revocation notification record found for revoked credential; " "no notification will be sent" ) except StorageError: - _logger.exception("Failed to retrieve revocation notification record") + LOGGER.exception("Failed to retrieve revocation notification record") async def on_pending_cleared(profile: Profile, event: Event): diff --git a/aries_cloudagent/protocols/revocation_notification/v2_0/handlers/revoke_handler.py b/aries_cloudagent/protocols/revocation_notification/v2_0/handlers/revoke_handler.py index 188530affd..f2ffafe7e0 100644 --- a/aries_cloudagent/protocols/revocation_notification/v2_0/handlers/revoke_handler.py +++ b/aries_cloudagent/protocols/revocation_notification/v2_0/handlers/revoke_handler.py @@ -1,6 +1,5 @@ """Handler for revoke message.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import BaseHandler from .....messaging.request_context import RequestContext from .....messaging.responder import BaseResponder @@ -17,12 +16,6 @@ class RevokeHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Handle revoke message.""" assert isinstance(context.message, Revoke) - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug( "Received notification of revocation for %s cred %s with comment: %s", context.message.revocation_format, diff --git a/aries_cloudagent/protocols/revocation_notification/v2_0/routes.py b/aries_cloudagent/protocols/revocation_notification/v2_0/routes.py index 7604528e7c..83ba81fe63 100644 --- a/aries_cloudagent/protocols/revocation_notification/v2_0/routes.py +++ b/aries_cloudagent/protocols/revocation_notification/v2_0/routes.py @@ -2,7 +2,6 @@ import logging import re -from ....config.logging import get_adapted_logger_inst from ....core.event_bus import Event, EventBus from ....core.profile import Profile from ....messaging.responder import BaseResponder @@ -31,12 +30,7 @@ def register_events(event_bus: EventBus): async def on_revocation_published(profile: Profile, event: Event): """Handle issuer revoke event.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) - _logger.debug("Sending notification of revocation to recipient: %s", event.payload) + LOGGER.debug("Sending notification of revocation to recipient: %s", event.payload) should_notify = profile.settings.get("revocation.notify", False) responder = profile.inject(BaseResponder) @@ -58,12 +52,12 @@ async def on_revocation_published(profile: Profile, event: Event): ) except StorageNotFoundError: - _logger.info( + LOGGER.info( "No revocation notification record found for revoked credential; " "no notification will be sent" ) except StorageError: - _logger.exception("Failed to retrieve revocation notification record") + LOGGER.exception("Failed to retrieve revocation notification record") async def on_pending_cleared(profile: Profile, event: Event): diff --git a/aries_cloudagent/protocols/routing/v1_0/handlers/forward_handler.py b/aries_cloudagent/protocols/routing/v1_0/handlers/forward_handler.py index 91852a3369..47654fc5b0 100644 --- a/aries_cloudagent/protocols/routing/v1_0/handlers/forward_handler.py +++ b/aries_cloudagent/protocols/routing/v1_0/handlers/forward_handler.py @@ -2,7 +2,6 @@ import json -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -19,12 +18,6 @@ class ForwardHandler(BaseHandler): async def handle(self, context: RequestContext, responder: BaseResponder): """Message handler implementation.""" - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug("ForwardHandler called with context %s", context) assert isinstance(context.message, Forward) diff --git a/aries_cloudagent/protocols/routing/v1_0/manager.py b/aries_cloudagent/protocols/routing/v1_0/manager.py index cafa757e87..a5fe48c924 100644 --- a/aries_cloudagent/protocols/routing/v1_0/manager.py +++ b/aries_cloudagent/protocols/routing/v1_0/manager.py @@ -4,7 +4,6 @@ import logging from typing import Sequence -from ....config.logging import get_adapted_logger_inst from ....core.error import BaseError from ....core.profile import Profile from ....storage.error import ( @@ -14,7 +13,9 @@ from .models.route_record import RouteRecord + LOGGER = logging.getLogger(__name__) + RECIP_ROUTE_PAUSE = 0.1 RECIP_ROUTE_RETRY = 10 @@ -41,11 +42,6 @@ def __init__(self, profile: Profile): self._profile = profile if not profile: raise RoutingManagerError("Missing profile") - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) async def get_recipient(self, recip_verkey: str) -> RouteRecord: """Resolve the recipient for a verkey. @@ -64,28 +60,20 @@ async def get_recipient(self, recip_verkey: str) -> RouteRecord: record = None while not record: try: - self._logger.info( - ">>> fetching routing record for verkey: " + recip_verkey - ) + LOGGER.info(">>> fetching routing record for verkey: " + recip_verkey) async with self._profile.session() as session: record = await RouteRecord.retrieve_by_recipient_key( session, recip_verkey ) - self._logger.info( - ">>> FOUND routing record for verkey: " + recip_verkey - ) + LOGGER.info(">>> FOUND routing record for verkey: " + recip_verkey) return record except StorageDuplicateError: - self._logger.info( - ">>> DUPLICATE routing record for verkey: " + recip_verkey - ) + LOGGER.info(">>> DUPLICATE routing record for verkey: " + recip_verkey) raise RouteNotFoundError( f"More than one route record found with recipient key: {recip_verkey}" ) except StorageNotFoundError: - self._logger.info( - ">>> NOT FOUND routing record for verkey: " + recip_verkey - ) + LOGGER.info(">>> NOT FOUND routing record for verkey: " + recip_verkey) i += 1 if i > RECIP_ROUTE_RETRY: raise RouteNotFoundError( @@ -157,7 +145,7 @@ async def create_route_record( ) if not recipient_key: raise RoutingManagerError("Missing recipient_key") - self._logger.info(">>> creating routing record for verkey: " + recipient_key) + LOGGER.info(">>> creating routing record for verkey: " + recipient_key) route = RouteRecord( connection_id=client_connection_id, wallet_id=internal_wallet_id, @@ -165,5 +153,5 @@ async def create_route_record( ) async with self._profile.session() as session: await route.save(session, reason="Created new route") - self._logger.info(">>> CREATED routing record for verkey: " + recipient_key) + LOGGER.info(">>> CREATED routing record for verkey: " + recipient_key) return route diff --git a/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_handler.py b/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_handler.py index 0828c8bb2a..7963109e43 100644 --- a/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_handler.py +++ b/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_handler.py @@ -1,6 +1,5 @@ """Ping handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -22,12 +21,6 @@ async def handle(self, context: RequestContext, responder: BaseResponder): responder: Responder used to reply """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) self._logger.debug(f"PingHandler called with context {context}") assert isinstance(context.message, Ping) diff --git a/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_response_handler.py b/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_response_handler.py index e002c08ca8..c66c68158a 100644 --- a/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_response_handler.py +++ b/aries_cloudagent/protocols/trustping/v1_0/handlers/ping_response_handler.py @@ -1,6 +1,5 @@ """Ping response handler.""" -from .....config.logging import get_adapted_logger_inst from .....messaging.base_handler import ( BaseHandler, BaseResponder, @@ -21,12 +20,7 @@ async def handle(self, context: RequestContext, responder: BaseResponder): responder: Responder used to reply """ - profile = context.profile - self._logger = get_adapted_logger_inst( - logger=self._logger, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + self._logger.debug("PingResponseHandler called with context: %s", context) assert isinstance(context.message, PingResponse) diff --git a/aries_cloudagent/resolver/default/universal.py b/aries_cloudagent/resolver/default/universal.py index 19b77a8fba..2efee46009 100644 --- a/aries_cloudagent/resolver/default/universal.py +++ b/aries_cloudagent/resolver/default/universal.py @@ -7,12 +7,11 @@ import aiohttp from ...config.injection_context import InjectionContext -from ...config.logging import get_adapted_logger_inst from ...core.profile import Profile from ..base import BaseDIDResolver, DIDNotFound, ResolverError, ResolverType -DEFAULT_ENDPOINT = "https://dev.uniresolver.io/1.0" LOGGER = logging.getLogger(__name__) +DEFAULT_ENDPOINT = "https://dev.uniresolver.io/1.0" def _compile_supported_did_regex(patterns: Iterable[Union[str, Pattern]]): @@ -85,17 +84,13 @@ async def _resolve( service_accept: Optional[Sequence[Text]] = None, ) -> dict: """Resolve DID through remote universal resolver.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=_profile.settings.get("log.file"), - wallet_id=_profile.settings.get("wallet.id"), - ) + async with aiohttp.ClientSession(headers=self.__default_headers) as session: async with session.get(f"{self._endpoint}/identifiers/{did}") as resp: if resp.status == 200: doc = await resp.json() did_doc = doc["didDocument"] - _logger.info("Retrieved doc: %s", did_doc) + LOGGER.info("Retrieved doc: %s", did_doc) return did_doc if resp.status == 404: raise DIDNotFound(f"{did} not found by {self.__class__.__name__}") diff --git a/aries_cloudagent/revocation/indy.py b/aries_cloudagent/revocation/indy.py index 6b571ae3b9..622ef3f583 100644 --- a/aries_cloudagent/revocation/indy.py +++ b/aries_cloudagent/revocation/indy.py @@ -3,7 +3,6 @@ from typing import Optional, Sequence, Tuple from uuid import uuid4 -from ..config.logging import get_adapted_logger_inst from ..core.profile import Profile from ..ledger.base import BaseLedger from ..ledger.multiple_ledger.ledger_requests_executor import ( @@ -39,11 +38,6 @@ class IndyRevocation: def __init__(self, profile: Profile): """Initialize the IndyRevocation instance.""" self._profile = profile - self._logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=self._profile.settings.get("log.file"), - wallet_id=self._profile.settings.get("wallet.id"), - ) async def init_issuer_registry( self, @@ -131,9 +125,9 @@ async def decommission_registry(self, cred_def_id: str): ) for rec in recs: - self._logger.debug(f"decommission {rec.state} rev. reg.") - self._logger.debug(f"revoc_reg_id: {rec.revoc_reg_id}") - self._logger.debug(f"cred_def_id: {cred_def_id}") + LOGGER.debug(f"decommission {rec.state} rev. reg.") + LOGGER.debug(f"revoc_reg_id: {rec.revoc_reg_id}") + LOGGER.debug(f"cred_def_id: {cred_def_id}") # decommission active registry, we need to init a replacement init = IssuerRevRegRecord.STATE_ACTIVE == rec.state await self._set_registry_status( diff --git a/aries_cloudagent/revocation/models/issuer_rev_reg_record.py b/aries_cloudagent/revocation/models/issuer_rev_reg_record.py index 541e0daf49..ccb47e63ed 100644 --- a/aries_cloudagent/revocation/models/issuer_rev_reg_record.py +++ b/aries_cloudagent/revocation/models/issuer_rev_reg_record.py @@ -12,7 +12,6 @@ from marshmallow import fields, validate -from ...config.logging import get_adapted_logger_inst from ...core.profile import Profile, ProfileSession from ...indy.issuer import IndyIssuer, IndyIssuerError from ...indy.models.revocation import ( @@ -43,6 +42,7 @@ from .revocation_registry import RevocationRegistry DEFAULT_REGISTRY_SIZE = 1000 + LOGGER = logging.getLogger(__name__) @@ -184,11 +184,6 @@ def _check_url(self, url) -> None: async def generate_registry(self, profile: Profile): """Create the revocation registry definition and tails file.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) if not self.tag: self.tag = self._id or str(uuid.uuid4()) @@ -202,7 +197,7 @@ async def generate_registry(self, profile: Profile): issuer = profile.inject(IndyIssuer) tails_hopper_dir = indy_client_dir(join("tails", ".hopper"), create=True) - _logger.debug("Creating revocation registry with size: %d", self.max_cred_num) + LOGGER.debug("Creating revocation registry with size: %d", self.max_cred_num) try: ( @@ -290,11 +285,6 @@ async def send_entry( endorser_did: str = None, ) -> dict: """Send a registry entry to the ledger.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) if not ( self.revoc_reg_id and self.revoc_def_type @@ -335,27 +325,27 @@ async def send_entry( # Ledger rejected transaction request: client request invalid: # InvalidClientRequest(...) # In this scenario we try to post a correction - _logger.warn("Retry ledger update/fix due to error") - _logger.warn(err) + LOGGER.warn("Retry ledger update/fix due to error") + LOGGER.warn(err) (_, _, res) = await self.fix_ledger_entry( profile, True, ledger.pool.genesis_txns, ) rev_entry_res = {"result": res} - _logger.warn("Ledger update/fix applied") + LOGGER.warn("Ledger update/fix applied") elif "InvalidClientTaaAcceptanceError" in err.roll_up: # if no write access (with "InvalidClientTaaAcceptanceError") # e.g. aries_cloudagent.ledger.error.LedgerTransactionError: # Ledger rejected transaction request: client request invalid: # InvalidClientTaaAcceptanceError(...) - _logger.error("Ledger update failed due to TAA issue") - _logger.error(err) + LOGGER.error("Ledger update failed due to TAA issue") + LOGGER.error(err) raise err else: # not sure what happened, raise an error - _logger.error("Ledger update failed due to unknown issue") - _logger.error(err) + LOGGER.error("Ledger update failed due to unknown issue") + LOGGER.error(err) raise err if self.state == IssuerRevRegRecord.STATE_POSTED: self.state = IssuerRevRegRecord.STATE_ACTIVE # initial entry activates @@ -374,11 +364,6 @@ async def fix_ledger_entry( ) -> Tuple[dict, dict, dict]: """Fix the ledger entry to match wallet-recorded credentials.""" # get rev reg delta (revocations published to ledger) - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) ledger = profile.inject(BaseLedger) async with ledger: (rev_reg_delta, _) = await ledger.get_revoc_reg_delta(self.revoc_reg_id) @@ -402,12 +387,12 @@ async def fix_ledger_entry( # await rec.set_state(session, IssuerCredRevRecord.STATE_ISSUED) rec_count += 1 - _logger.debug(">>> fixed entry recs count = %s", rec_count) - _logger.debug( + LOGGER.debug(">>> fixed entry recs count = %s", rec_count) + LOGGER.debug( ">>> rev_reg_record.revoc_reg_entry.value: %s", self.revoc_reg_entry.value, ) - _logger.debug( + LOGGER.debug( '>>> rev_reg_delta.get("value"): %s', rev_reg_delta.get("value") ) @@ -427,7 +412,7 @@ async def fix_ledger_entry( ) recovery_txn = json.loads(calculated_txn.to_json()) - _logger.debug(">>> apply_ledger_update = %s", apply_ledger_update) + LOGGER.debug(">>> apply_ledger_update = %s", apply_ledger_update) if apply_ledger_update: ledger = session.inject_or(BaseLedger) if not ledger: diff --git a/aries_cloudagent/wallet/routes.py b/aries_cloudagent/wallet/routes.py index 2ca3a23306..20dd8727c1 100644 --- a/aries_cloudagent/wallet/routes.py +++ b/aries_cloudagent/wallet/routes.py @@ -10,7 +10,6 @@ from marshmallow import fields, validate from ..admin.request_context import AdminRequestContext -from ..config.logging import get_adapted_logger_inst from ..connections.models.conn_record import ConnRecord from ..core.event_bus import Event, EventBus from ..core.profile import Profile @@ -1049,11 +1048,7 @@ def register_events(event_bus: EventBus): async def on_register_nym_event(profile: Profile, event: Event): """Handle any events we need to support.""" - _logger = get_adapted_logger_inst( - logger=LOGGER, - log_file=profile.settings.get("log.file"), - wallet_id=profile.settings.get("wallet.id"), - ) + # after the nym record is written, promote to wallet public DID if is_author_role(profile) and profile.context.settings.get_value( "endorser.auto_promote_author_did" @@ -1066,7 +1061,7 @@ async def on_register_nym_event(profile: Profile, event: Event): ) except Exception as err: # log the error, but continue - _logger.exception( + LOGGER.exception( "Error promoting to public DID: %s", err, ) @@ -1079,8 +1074,9 @@ async def on_register_nym_event(profile: Profile, event: Event): ) except StorageError as err: # log the error, but continue - _logger.exception( - "Error accepting endorser invitation/configuring endorser connection: %s", + LOGGER.exception( + "Error accepting endorser invitation/configuring endorser" + " connection: %s", err, ) return @@ -1096,7 +1092,7 @@ async def on_register_nym_event(profile: Profile, event: Event): ) except (StorageError, TransactionManagerError) as err: # log the error, but continue - _logger.exception( + LOGGER.exception( "Error creating endorser transaction request: %s", err, ) @@ -1110,7 +1106,7 @@ async def on_register_nym_event(profile: Profile, event: Event): connection_id=connection_id, ) else: - _logger.warning( + LOGGER.warning( "Configuration has no BaseResponder: cannot update " "ATTRIB record on DID: %s", did, diff --git a/demo/runners/agent_container.py b/demo/runners/agent_container.py index e237061b8b..879d01e104 100644 --- a/demo/runners/agent_container.py +++ b/demo/runners/agent_container.py @@ -1322,25 +1322,6 @@ def arg_parser(ident: str = None, port: int = 8020): "('debug', 'info', 'warning', 'error', 'critical')" ), ) - parser.add_argument( - "--log-handler-config", - type=str, - metavar="", - help=( - "Specifies when, interval, backupCount for the TimedRotatingFileHandler." - ), - ) - parser.add_argument( - "--log-fmt-pattern", - type=str, - metavar="", - help="Specifies logging formatter pattern as string.", - ) - parser.add_argument( - "--log-json-fmt", - action="store_true", - help="JSON logging formatter.", - ) return parser @@ -1374,11 +1355,6 @@ async def create_agent_with_args(args, ident: str = None): log_file = args.log_file or os.getenv("ACAPY_LOG_FILE") log_level = args.log_level - log_handler_config = args.log_handler_config or os.getenv( - "ACAPY_LOG_HANDLER_CONFIG" - ) - log_fmt_pattern = args.log_fmt_pattern or os.getenv("ACAPY_LOG_FMT_PATTERN") - log_json_fmt = args.log_json_fmt or False # if we don't have a tails server url then guess it if ("revocation" in args and args.revocation) and not tails_server_base_url: # assume we're running in docker @@ -1457,9 +1433,6 @@ async def create_agent_with_args(args, ident: str = None): taa_accept=args.taa_accept, anoncreds_legacy_revocation=anoncreds_legacy_revocation, log_file=log_file, - log_handler_config=log_handler_config, - log_fmt_pattern=log_fmt_pattern, - log_json_fmt=log_json_fmt, log_level=log_level, ) diff --git a/demo/runners/performance.py b/demo/runners/performance.py index cbbed96d03..9deba03609 100644 --- a/demo/runners/performance.py +++ b/demo/runners/performance.py @@ -139,7 +139,10 @@ async def check_received_creds(self) -> Tuple[int, int]: return pending, total async def update_creds(self): - await self.credential_event.wait() + try: + await self.credential_event.wait() + except asyncio.exceptions.CancelledError: + pass async def check_received_pings(self) -> Tuple[int, int]: while True: @@ -767,25 +770,6 @@ async def check_received_pings(agent, issue_count, pb): "('debug', 'info', 'warning', 'error', 'critical')" ), ) - parser.add_argument( - "--log-handler-config", - type=str, - metavar="", - help=( - "Specifies when, interval, backupCount for the TimedRotatingFileHandler." - ), - ) - parser.add_argument( - "--log-fmt-pattern", - type=str, - metavar="", - help=("Specifies logging formatter pattern as string."), - ) - parser.add_argument( - "--log-json-fmt", - action="store_true", - help=("JSON logging formatter."), - ) args = parser.parse_args() if args.did_exchange and args.mediation: @@ -825,9 +809,6 @@ async def check_received_pings(agent, issue_count, pb): args.wallet_type, args.arg_file, args.log_file, - args.log_handler_config, - args.log_fmt_pattern, - args.log_json_fmt, args.log_level, ) ) diff --git a/demo/runners/support/agent.py b/demo/runners/support/agent.py index 2ee9d7b27d..b040361a5a 100644 --- a/demo/runners/support/agent.py +++ b/demo/runners/support/agent.py @@ -361,26 +361,12 @@ def get_agent_args(self): ("--log-file", self.log_file), ] ) - if self.log_handler_config: - result.extend( - [ - ("--log-handler-config", self.log_handler_config), - ] - ) - if self.log_fmt_pattern: - result.extend( - [ - ("--log-fmt-pattern", self.log_fmt_pattern), - ] - ) if self.log_level: result.extend( [ ("--log-level", self.log_level), ] ) - if self.log_json_fmt: - result.append("--log-json-fmt") if self.aip == 20: result.append("--emit-new-didcomm-prefix") if self.multitenant: diff --git a/demo/runners/support/utils.py b/demo/runners/support/utils.py index 0056686fbf..45ef1b733e 100644 --- a/demo/runners/support/utils.py +++ b/demo/runners/support/utils.py @@ -122,8 +122,10 @@ def output_reader(handle, callback, *args, **kwargs): def log_msg(*msg, color="fg:ansimagenta", **kwargs): - run_in_terminal(lambda: print_ext(*msg, color=color, **kwargs)) - + try: + run_in_terminal(lambda: print_ext(*msg, color=color, **kwargs)) + except AssertionError: + pass def log_json(data, **kwargs): run_in_terminal(lambda: print_json(data, **kwargs))