From 4d23ba9708a56f769dca19a31e43ba87e10d8774 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Tue, 17 Oct 2023 19:25:26 +0530 Subject: [PATCH 01/12] per tenant logging impl Signed-off-by: Shaanjot Gill --- Logging.md | 75 +++++- aries_cloudagent/admin/server.py | 6 + aries_cloudagent/config/argparse.py | 63 ----- .../default_per_tenant_logging_config.ini | 27 ++ .../default_per_tenant_logging_config.yml | 23 ++ aries_cloudagent/config/logging.py | 237 +++++++----------- .../config/tests/test_argparse.py | 33 --- aries_cloudagent/config/tests/test_logging.py | 144 +++++------ aries_cloudagent/config/util.py | 8 +- aries_cloudagent/connections/base_manager.py | 6 +- aries_cloudagent/core/dispatcher.py | 6 +- aries_cloudagent/core/oob_processor.py | 43 ++-- .../indy/sdk/tests/test_profile.py | 25 +- .../handlers/tests/test_keylist_handler.py | 34 +-- .../messages/tests/test_problem_report.py | 12 +- .../v1_0/tests/test_mediation_manager.py | 14 +- .../messages/tests/test_problem_report.py | 11 +- .../tests/test_credential_problem_report.py | 12 +- .../tests/test_cred_problem_report.py | 10 +- .../messages/tests/test_problem_report.py | 12 +- demo/runners/agent_container.py | 43 ++++ demo/runners/alice.py | 9 + demo/runners/faber.py | 9 + demo/runners/performance.py | 91 ++++++- demo/runners/support/agent.py | 24 ++ demo/runners/support/utils.py | 5 +- 26 files changed, 553 insertions(+), 429 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 c8f778a801..1935db7814 100644 --- a/Logging.md +++ b/Logging.md @@ -12,14 +12,14 @@ 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. -* `--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`. +* `--log-config` - Specifies a custom logging configuration file Example: ```sh -./bin/aca-py start --log-level debug --log-file acapy.log --log-handler-config "d;7;1" --log-fmt-pattern "%(asctime)s [%(did)s] %(filename)s %(lineno)d %(message)s" --log-json-fmt +./bin/aca-py start --log-level debug --log-file acapy.log --log-config aries_cloudagent.config:default_per_tenant_logging_config.ini + +./bin/aca-py start --log-level debug --log-file acapy.log --log-config ./aries_cloudagent/config/default_per_tenant_logging_config.yml ``` ## Environment Variables @@ -27,14 +27,11 @@ Example: The log level can be configured using the environment variable `ACAPY_LOG_LEVEL`. The log file can be set by `ACAPY_LOG_FILE`. The log config can be set by `ACAPY_LOG_CONFIG`. -The log rotating file handler config can be set by `ACAPY_LOG_HANDLER_CONFIG`. -The log formatter pattern can be set by `ACAPY_LOG_FMT_PATTERN`. -The log json formatter flag can be set by `ACAPY_LOG_JSON_FMT`. Example: ```sh -ACAPY_LOG_LEVEL=info ACAPY_LOG_FILE=./acapy.log ACAPY_LOG_CONFIG=./acapy_log.ini ACAPY_LOG_HANDLER_CONFIG="d;7;1" ./bin/aca-py start +ACAPY_LOG_LEVEL=info ACAPY_LOG_FILE=./acapy.log ACAPY_LOG_CONFIG=./acapy_log.ini ./bin/aca-py start ``` ## Acapy Config File @@ -53,6 +50,68 @@ Also if log-level is set to WARNING, connections and presentations will be logge ## Log config file +The path to config file is provided via `--log-config`. + Find an example in [default_logging_config.ini](aries_cloudagent/config/default_logging_config.ini). You can find more detail description in the [logging documentation](https://docs.python.org/3/howto/logging.html#configuring-logging). + +For per tenant logging, find an example in [default_per_tenant_logging_config.ini](aries_cloudagent/config/default_per_tenant_logging_config.ini), which sets up `TimedRotatingFileMultiProcessHandler` and `StreamHandler` handlers. Custom `TimedRotatingFileMultiProcessHandler` handler supports the ability to cleanup logs by time and mantain backup logs and a custom JSON formatter for logs. The arguments for it such as `file name`, `when`, `interval` and `backupCount` can be passed as `args=('acapy.log', 'd', 7, 1,)` [also shown below]. 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) + +``` +[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 +``` + +For `DictConfig` [`dict` logging config file], find an example in [default_per_tenant_logging_config.yml](aries_cloudagent/config/default_per_tenant_logging_config.yml) with same attributes as `default_per_tenant_logging_config.ini` file. + +``` +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 +``` diff --git a/aries_cloudagent/admin/server.py b/aries_cloudagent/admin/server.py index 61b3b61630..9521a991b8 100644 --- a/aries_cloudagent/admin/server.py +++ b/aries_cloudagent/admin/server.py @@ -22,6 +22,7 @@ from marshmallow import fields from ..config.injection_context import InjectionContext +from ..config.logging import context_wallet_id from ..core.event_bus import Event, EventBus from ..core.plugin_registry import PluginRegistry from ..core.profile import Profile @@ -407,6 +408,11 @@ async def setup_context(request: web.Request, handler): ) = self.multitenant_manager.get_wallet_details_from_token( token=token ) + try: + context_wallet_id.get() + except LookupError: + wallet_id = profile.settings.get("wallet.id") + context_wallet_id.set(wallet_id) meta_data = { "wallet_id": walletid, "wallet_key": walletkey, diff --git a/aries_cloudagent/config/argparse.py b/aries_cloudagent/config/argparse.py index 9be7794a77..9e1da6410e 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/logging.py b/aries_cloudagent/config/logging.py index f3bd59217d..7c31996963 100644 --- a/aries_cloudagent/config/logging.py +++ b/aries_cloudagent/config/logging.py @@ -1,30 +1,57 @@ """Utilities related to logging.""" -import asyncio + +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 Optional, TextIO +from typing import TextIO import pkg_resources from portalocker import LOCK_EX, lock, unlock from pythonjsonlogger import jsonlogger from ..config.settings import Settings -from ..core.profile import Profile from ..version import __version__ -from ..wallet.base import BaseWallet, DIDInfo from .banner import Banner -from .base import BaseSettings - DEFAULT_LOGGING_CONFIG_PATH = "aries_cloudagent.config:default_logging_config.ini" +# DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH_YAML = ( +# "./aries_cloudagent/config/default_per_tenant_logging_config.yml" +# ) +DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH_INI = ( + "aries_cloudagent.config:default_per_tenant_logging_config.ini" +) +LOG_FORMAT_FILE_ALIAS_PATTERN = ( + "%(asctime)s %(wallet_id)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): + """Initialize an instance of Custom logging.Filter.""" + super(ContextFilter, self).__init__() + + def filter(self, record): + """Filter LogRecords and add wallet id to them.""" + 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: @@ -57,6 +84,7 @@ def configure( logging_config_path: str = None, log_level: str = None, log_file: str = None, + multitenant: bool = False, ): """Configure logger. @@ -65,28 +93,75 @@ 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 multitenant: + config_path = DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH_INI + else: + config_path = DEFAULT_LOGGING_CONFIG_PATH + 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: + 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() + if 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 log_level: + _handler.setLevel(log_level.upper()) + if not file_handler_set and log_file: + 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(LOG_FORMAT_FILE_ALIAS_PATTERN) + ) + 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) + logging.root.setLevel(log_level.upper()) @classmethod def print_banner( @@ -498,128 +573,6 @@ def doRollover(self): self.release() -LOG_FORMAT_FILE_ALIAS_PATTERN = ( - "%(asctime)s [%(did)s] %(levelname)s %(filename)s %(lineno)d %(message)s" +logging.handlers.TimedRotatingFileMultiProcessHandler = ( + TimedRotatingFileMultiProcessHandler ) - -LOG_FORMAT_FILE_NO_ALIAS_PATTERN = ( - "%(asctime)s %(levelname)s %(filename)s %(lineno)d %(message)s" -) - -LOG_FORMAT_STREAM_PATTERN = ( - "%(asctime)s %(levelname)s %(filename)s %(lineno)d %(message)s" -) - - -def clear_prev_handlers(logger: logging.Logger) -> logging.Logger: - """Remove all handler classes associated with logger instance.""" - iter_count = 0 - num_handlers = len(logger.handlers) - while iter_count < num_handlers: - logger.removeHandler(logger.handlers[0]) - iter_count = iter_count + 1 - return logger - - -def get_logger_inst(profile: Profile, logger_name) -> logging.Logger: - """Return a logger instance with provided name and handlers.""" - did_ident = get_did_ident(profile) - if did_ident: - logger_name = f"{logger_name}_{did_ident}" - return get_logger_with_handlers( - settings=profile.settings, - logger=logging.getLogger(logger_name), - did_ident=did_ident, - interval=profile.settings.get("log.handler_interval") or 7, - backup_count=profile.settings.get("log.handler_bakcount") or 1, - at_when=profile.settings.get("log.handler_when") or "d", - ) - - -def get_did_ident(profile: Profile) -> Optional[str]: - """Get public did identifier for logging, if applicable.""" - did_ident = None - if profile.settings.get("log.file"): - - async def _fetch_did() -> Optional[str]: - async with profile.session() as session: - wallet = session.inject(BaseWallet) - req_did_info: DIDInfo = await wallet.get_public_did() - if not req_did_info: - req_did_info: DIDInfo = (await wallet.get_local_dids())[0] - if req_did_info: - did_ident = req_did_info.did - return did_ident - - loop = asyncio.get_event_loop() - did_ident = loop.run_until_complete(_fetch_did()) - return did_ident - - -def get_logger_with_handlers( - settings: BaseSettings, - logger: logging.Logger, - at_when: str = None, - interval: int = None, - backup_count: int = None, - did_ident: str = None, -) -> logging.Logger: - """Return logger instance with necessary handlers if required.""" - if settings.get("log.file"): - # Clear handlers set previously for this logger instance - logger = clear_prev_handlers(logger) - # log file handler - file_path = settings.get("log.file") - file_handler = TimedRotatingFileMultiProcessHandler( - filename=file_path, - interval=interval, - when=at_when, - backupCount=backup_count, - ) - if did_ident: - if settings.get("log.json_fmt"): - file_handler.setFormatter( - jsonlogger.JsonFormatter( - settings.get("log.fmt_pattern") or LOG_FORMAT_FILE_ALIAS_PATTERN - ) - ) - else: - file_handler.setFormatter( - logging.Formatter( - settings.get("log.fmt_pattern") or LOG_FORMAT_FILE_ALIAS_PATTERN - ) - ) - else: - if settings.get("log.json_fmt"): - file_handler.setFormatter( - jsonlogger.JsonFormatter( - settings.get("log.fmt_pattern") - or LOG_FORMAT_FILE_NO_ALIAS_PATTERN - ) - ) - else: - file_handler.setFormatter( - logging.Formatter( - settings.get("log.fmt_pattern") - or LOG_FORMAT_FILE_NO_ALIAS_PATTERN - ) - ) - logger.addHandler(file_handler) - # stream console handler - std_out_handler = logging.StreamHandler(sys.stdout) - std_out_handler.setFormatter( - logging.Formatter( - settings.get("log.fmt_pattern") or LOG_FORMAT_STREAM_PATTERN - ) - ) - logger.addHandler(std_out_handler) - if did_ident: - logger = logging.LoggerAdapter(logger, {"did": did_ident}) - # set log level - logger_level = ( - (settings.get("log.level")).upper() - if settings.get("log.level") - else logging.INFO - ) - logger.setLevel(logger_level) - return logger 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 853b723692..848c8267bb 100644 --- a/aries_cloudagent/config/tests/test_logging.py +++ b/aries_cloudagent/config/tests/test_logging.py @@ -1,5 +1,4 @@ import contextlib -import logging from io import StringIO @@ -8,11 +7,6 @@ from .. import logging as test_module -from ...core.in_memory import InMemoryProfile -from ...wallet.base import BaseWallet -from ...wallet.did_method import SOV, DIDMethods -from ...wallet.key_type import ED25519 - class TestLoggingConfigurator(AsyncTestCase): agent_label_arg_value = "Aries Cloud Agent" @@ -32,6 +26,62 @@ def test_configure_default(self, mock_file_config, mock_load_resource): mock_load_resource.return_value, disable_existing_loggers=False ) + def test_configure_with_per_tenant_config_file(self): + with async_mock.patch.object( + test_module, + "logging", + async_mock.MagicMock( + basicConfig=async_mock.MagicMock(), + FileHandler=async_mock.MagicMock(), + root=async_mock.MagicMock( + warning=async_mock.MagicMock(), + handlers=[], + ), + ), + ): + test_module.LoggingConfigurator.configure( + logging_config_path="aries_cloudagent.config:default_per_tenant_logging_config.ini", + log_file="test.log", + multitenant=True, + ) + + def test_configure_with_per_tenant_yml_file(self): + with async_mock.patch.object( + test_module, + "logging", + async_mock.MagicMock( + basicConfig=async_mock.MagicMock(), + FileHandler=async_mock.MagicMock(), + root=async_mock.MagicMock( + warning=async_mock.MagicMock(), + handlers=[], + ), + ), + ): + test_module.LoggingConfigurator.configure( + logging_config_path="aries_cloudagent/config/default_per_tenant_logging_config.yml", + log_file="test.log", + multitenant=True, + ) + + def test_configure_with_default_config(self): + with async_mock.patch.object( + test_module, + "logging", + async_mock.MagicMock( + basicConfig=async_mock.MagicMock(), + FileHandler=async_mock.MagicMock(), + root=async_mock.MagicMock( + warning=async_mock.MagicMock(), + handlers=[], + ), + ), + ): + test_module.LoggingConfigurator.configure( + log_file="test.log", + multitenant=True, + ) + def test_configure_default_no_resource(self): with async_mock.patch.object( test_module, "load_resource", async_mock.MagicMock() @@ -98,85 +148,3 @@ def test_load_resource(self): test_module.pkg_resources, "resource_stream", async_mock.MagicMock() ) as mock_res_stream: test_module.load_resource("abc:def", encoding=None) - - 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 - - async def test_get_logger_inst(self): - profile = InMemoryProfile.test_profile() - logger = test_module.get_logger_inst( - profile=profile, - logger_name=__name__, - ) - assert logger - # public did - profile.settings["log.file"] = "test_file.log" - profile.context.injector.bind_instance(DIDMethods, DIDMethods()) - async with profile.session() as session: - wallet: BaseWallet = session.inject_or(BaseWallet) - await wallet.create_local_did( - SOV, - ED25519, - did="DJGEjaMunDtFtBVrn1qJMT", - ) - await wallet.set_public_did("DJGEjaMunDtFtBVrn1qJMT") - logger = test_module.get_logger_inst( - profile=profile, - logger_name=__name__, - ) - # public did, json_fmt, pattern - profile.settings["log.file"] = "test_file.log" - profile.settings["log.json_fmt"] = True - profile.settings[ - "log.fmt_pattern" - ] = "%(asctime)s [%(did)s] %(lineno)d %(message)s" - logger = test_module.get_logger_inst( - profile=profile, - logger_name=__name__, - ) - assert logger - # not public did - profile = InMemoryProfile.test_profile() - profile.settings["log.file"] = "test_file.log" - profile.settings["log.json_fmt"] = False - profile.context.injector.bind_instance(DIDMethods, DIDMethods()) - async with profile.session() as session: - wallet: BaseWallet = session.inject_or(BaseWallet) - await wallet.create_local_did( - SOV, - ED25519, - did="DJGEjaMunDtFtBVrn1qJMT", - ) - logger = test_module.get_logger_inst( - profile=profile, - logger_name=__name__, - ) - assert logger - # not public did, json_fmt, pattern - profile.settings["log.file"] = "test_file.log" - profile.settings["log.json_fmt"] = True - profile.settings["log.fmt_pattern"] = "%(asctime)s %(lineno)d %(message)s" - logger = test_module.get_logger_inst( - profile=profile, - logger_name=__name__, - ) - assert logger diff --git a/aries_cloudagent/config/util.py b/aries_cloudagent/config/util.py index 00a7d5c534..00f9af8654 100644 --- a/aries_cloudagent/config/util.py +++ b/aries_cloudagent/config/util.py @@ -15,7 +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") - LoggingConfigurator.configure(log_config, log_level, log_file) + 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 f1d2ce9fa8..d2659d5370 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_logger_inst from ..core.error import BaseError from ..core.profile import Profile from ..did.did_key import DIDKey @@ -71,10 +70,7 @@ def __init__(self, profile: Profile): """ self._profile = profile self._route_manager = profile.inject(RouteManager) - self._logger: logging.Logger = get_logger_inst( - profile=self._profile, - logger_name=__name__, - ) + self._logger = logging.getLogger(__name__) async def create_did_document( self, diff --git a/aries_cloudagent/core/dispatcher.py b/aries_cloudagent/core/dispatcher.py index 66664474fe..b8660ab568 100644 --- a/aries_cloudagent/core/dispatcher.py +++ b/aries_cloudagent/core/dispatcher.py @@ -13,7 +13,6 @@ from aiohttp.web import HTTPException -from ..config.logging import get_logger_inst from ..connections.base_manager import BaseConnectionManager from ..connections.models.conn_record import ConnRecord from ..core.profile import Profile @@ -52,10 +51,7 @@ def __init__(self, profile: Profile): self.collector: Collector = None self.profile = profile self.task_queue: TaskQueue = None - self.logger: logging.Logger = get_logger_inst( - profile=self.profile, - logger_name=__name__, - ) + self.logger: logging.Logger = logging.getLogger(__name__) async def setup(self): """Perform async instance setup.""" diff --git a/aries_cloudagent/core/oob_processor.py b/aries_cloudagent/core/oob_processor.py index ccecc1a606..d1305aca3a 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_logger_inst from ..connections.models.conn_record import ConnRecord from ..connections.models.connection_target import ConnectionTarget from ..messaging.decorators.service_decorator import ServiceDecorator @@ -23,6 +22,8 @@ from .error import BaseError from .profile import Profile +LOGGER = logging.getLogger(__name__) + class OobMessageProcessorError(BaseError): """Base error for OobMessageProcessor.""" @@ -70,10 +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: logging.Logger = get_logger_inst( - profile=profile, - logger_name=__name__, - ) try: async with profile.session() as session: # Try to find the oob record for the outbound message: @@ -81,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, ) @@ -91,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, ) @@ -104,7 +101,7 @@ async def find_oob_target_for_outbound_message( outbound_message.payload = json.dumps(message) - logger.debug("Sending oob message payload %s", outbound_message.payload) + LOGGER.debug("Sending oob message payload %s", outbound_message.payload) return ConnectionTarget( endpoint=their_service.endpoint, @@ -121,15 +118,11 @@ async def find_oob_record_for_inbound_message( """Find oob record for inbound message.""" message_type = context.message._type oob_record = None - logger: logging.Logger = get_logger_inst( - profile=context.profile, - logger_name=__name__, - ) 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}" @@ -153,7 +146,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 " @@ -174,7 +167,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}" ) @@ -190,14 +183,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 " @@ -212,7 +205,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" ) @@ -237,7 +230,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}" @@ -249,7 +242,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}" ) @@ -276,7 +269,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" ) @@ -285,7 +278,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(), ) @@ -313,10 +306,6 @@ async def handle_message( their_service: Optional[ServiceDecorator] = None, ): """Message handler for inbound messages.""" - logger: logging.Logger = get_logger_inst( - profile=profile, - logger_name=__name__, - ) supported_types = [ CREDENTIAL_OFFER, @@ -357,7 +346,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/sdk/tests/test_profile.py b/aries_cloudagent/indy/sdk/tests/test_profile.py index 9440adc605..0c9f2e2e94 100644 --- a/aries_cloudagent/indy/sdk/tests/test_profile.py +++ b/aries_cloudagent/indy/sdk/tests/test_profile.py @@ -1,5 +1,3 @@ -import logging - from asynctest import mock as async_mock import pytest @@ -11,6 +9,8 @@ from ..profile import IndySdkProfile from ..wallet_setup import IndyOpenWallet, IndyWalletConfig +from .. import profile as test_module + @pytest.fixture async def open_wallet(): @@ -118,12 +118,15 @@ def test_read_only(open_wallet): ro_profile = IndySdkProfile(open_wallet, context) -def test_finalizer(open_wallet, caplog): - def _smaller_scope(): - profile = IndySdkProfile(open_wallet) - assert profile - - with caplog.at_level(logging.DEBUG): - _smaller_scope() - - assert "finalizer called" in caplog.text +def test_finalizer(open_wallet): + profile = IndySdkProfile(open_wallet) + assert profile + with async_mock.patch.object( + test_module, "LOGGER", async_mock.MagicMock() + ) as mock_logger: + mock_logger.debug = async_mock.MagicMock() + profile._finalizer() + assert mock_logger.debug.call_count == 1 + mock_logger.debug.assert_called_once_with( + "Profile finalizer called; closing wallet" + ) diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py index 695629cf91..62649002b2 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py @@ -1,8 +1,8 @@ """Test keylist handler.""" -import logging - import pytest +from asynctest import mock as async_mock + from ......connections.models.conn_record import ConnRecord from ......messaging.base_handler import HandlerException from ......messaging.request_context import RequestContext @@ -11,6 +11,8 @@ from ...models.mediation_record import MediationRecord from ..keylist_handler import KeylistHandler +from .. import keylist_handler as test_module + TEST_CONN_ID = "conn-id" pytestmark = pytest.mark.asyncio @@ -44,16 +46,20 @@ async def test_handler_no_active_connection(self, context): await handler.handle(context, responder) assert "inactive connection" in exc.value - async def test_handler_no_record(self, context, caplog): - caplog.set_level(logging.INFO) - handler, responder = KeylistHandler(), MockResponder() - await handler.handle(context, responder) - assert "not acting as mediator" in caplog.text - assert "Keylist received: " not in caplog.text + async def test_handler_no_record(self, context): + with async_mock.patch.object( + test_module, "LOG", async_mock.MagicMock() + ) as mock_logger: + handler, responder = KeylistHandler(), MockResponder() + await handler.handle(context, responder) + assert mock_logger.warning.call_count == 1 + assert mock_logger.info.call_count == 0 - async def test_handler(self, context, session, caplog): - caplog.set_level(logging.INFO) - handler, responder = KeylistHandler(), MockResponder() - await MediationRecord(connection_id=TEST_CONN_ID).save(session) - await handler.handle(context, responder) - assert "Keylist received: " in caplog.text + async def test_handler(self, context, session): + with async_mock.patch.object( + test_module, "LOG", async_mock.MagicMock() + ) as mock_logger: + handler, responder = KeylistHandler(), MockResponder() + await MediationRecord(connection_id=TEST_CONN_ID).save(session) + await handler.handle(context, responder) + assert mock_logger.info.call_count == 1 diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py index 322ae27f5a..29a2da6595 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" -import logging import pytest +from asynctest import mock as async_mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -13,6 +13,8 @@ ValidationError, ) +from .. import problem_report as test_module + class TestCMProblemReportMessage(TestCase): """Test problem report.""" @@ -53,6 +55,8 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - self._caplog.set_level(logging.WARNING) - CMProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", async_mock.MagicMock() + ) as mock_logger: + CMProblemReportSchema().validate_fields(data) + assert mock_logger.warning.call_count == 1 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 188f600c99..2ebca54939 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 @@ -1,5 +1,4 @@ """Test MediationManager.""" -import logging from typing import AsyncIterable, Iterable from asynctest import mock as async_mock @@ -438,9 +437,8 @@ async def test_store_update_results_exists_relay(self, session, manager): assert route.wallet_id == "test_wallet" assert route.connection_id == TEST_CONN_ID - async def test_store_update_results_errors(self, caplog, manager): + async def test_store_update_results_errors(self, manager): """test_store_update_results with errors.""" - caplog.set_level(logging.WARNING) results = [ KeylistUpdated( recipient_key=TEST_VERKEY, @@ -458,11 +456,11 @@ async def test_store_update_results_errors(self, caplog, manager): result=KeylistUpdated.RESULT_CLIENT_ERROR, ), ] - await manager.store_update_results(TEST_CONN_ID, results) - assert "no_change" in caplog.text - assert "client_error" in caplog.text - assert "server_error" in caplog.text - print(caplog.text) + with async_mock.patch.object( + test_module, "LOGGER", async_mock.MagicMock() + ) as mock_logger: + await manager.store_update_results(TEST_CONN_ID, results) + assert mock_logger.warning.call_count == 3 async def test_get_my_keylist(self, session, manager): """test_get_my_keylist.""" diff --git a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py index 03af260b1a..34fa28421c 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py @@ -1,10 +1,13 @@ import pytest +from asynctest import mock as async_mock + from ......messaging.models.base import BaseModelError from .....didcomm_prefix import DIDCommPrefix from ...message_types import PROBLEM_REPORT from ..problem_report import DIDXProblemReport +from .. import problem_report as test_module THID = "dummy-thid" PTHID = "dummy-pthid" @@ -31,9 +34,11 @@ def test_missing_code(): DIDXProblemReport.deserialize({"description": {"en": "test"}}) -def test_unrecognized_code(caplog): - with caplog.at_level("DEBUG"): +def test_unrecognized_code(): + with async_mock.patch.object( + test_module, "LOGGER", async_mock.MagicMock() + ) as mock_logger: DIDXProblemReport.deserialize( {"description": {"code": "unknown", "en": "test"}} ) - assert "Unexpected error code received" in caplog.text + assert mock_logger.warning.call_count == 1 diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py index fc87a911fa..97d14785d7 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py @@ -1,6 +1,6 @@ -import logging import pytest +from asynctest import mock as async_mock from unittest import mock, TestCase from ......messaging.models.base import BaseModelError @@ -16,6 +16,8 @@ ValidationError, ) +from .. import credential_problem_report as test_module + class TestCredentialProblemReport(TestCase): """Problem report tests.""" @@ -105,6 +107,8 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - self._caplog.set_level(logging.WARNING) - CredentialProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", async_mock.MagicMock() + ) as mock_logger: + CredentialProblemReportSchema().validate_fields(data) + assert mock_logger.warning.call_count == 1 diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py index 2389668065..aff6f7f798 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py @@ -1,6 +1,7 @@ import logging import pytest +from asynctest import mock as async_mock from unittest import mock, TestCase from ......messaging.models.base import BaseModelError @@ -16,6 +17,8 @@ ValidationError, ) +from .. import cred_problem_report as test_module + class TestCredProblemReport(TestCase): """Problem report tests.""" @@ -100,8 +103,11 @@ def test_validate_and_logger(self): }, ).serialize() self._caplog.set_level(logging.WARNING) - V20CredProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", async_mock.MagicMock() + ) as mock_logger: + V20CredProblemReportSchema().validate_fields(data) + assert mock_logger.warning.call_count == 1 def test_validate_x(self): """Exercise validation requirements.""" diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py index 831d109b9f..17dc35ef4e 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" -import logging import pytest +from asynctest import mock as async_mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -13,6 +13,8 @@ ValidationError, ) +from .. import problem_report as test_module + class TestOOBProblemReportMessage(TestCase): """Test problem report.""" @@ -70,9 +72,11 @@ def test_validate_and_logger(self): ) data.assign_thread_id(thid="test_thid", pthid="test_pthid") data = data.serialize() - self._caplog.set_level(logging.WARNING) - OOBProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", async_mock.MagicMock() + ) as mock_logger: + OOBProblemReportSchema().validate_fields(data) + assert mock_logger.warning.call_count == 1 def test_assign_msg_type_version_to_model_inst(self): test_msg = OOBProblemReport() diff --git a/demo/runners/agent_container.py b/demo/runners/agent_container.py index b50a569134..3eb88f575b 100644 --- a/demo/runners/agent_container.py +++ b/demo/runners/agent_container.py @@ -56,6 +56,9 @@ def __init__( endorser_role: str = None, revocation: bool = False, anoncreds_legacy_revocation: str = None, + log_file: str = None, + log_config: str = None, + log_level: str = None, **kwargs, ): extra_args = [] @@ -81,6 +84,9 @@ def __init__( endorser_role=endorser_role, revocation=revocation, extra_args=extra_args, + log_file=log_file, + log_config=log_config, + log_level=log_level, **kwargs, ) self.connection_id = None @@ -679,6 +685,9 @@ def __init__( reuse_connections: bool = False, taa_accept: bool = False, anoncreds_legacy_revocation: str = None, + log_file: str = None, + log_config: str = None, + log_level: str = None, ): # configuration parameters self.genesis_txns = genesis_txns @@ -702,6 +711,9 @@ def __init__( self.endorser_agent = None self.endorser_role = endorser_role self.anoncreds_legacy_revocation = anoncreds_legacy_revocation + self.log_file = log_file + self.log_config = log_config + self.log_level = log_level if endorser_role: # endorsers and authors need public DIDs (assume cred_type is Indy) if endorser_role == "author" or endorser_role == "endorser": @@ -748,6 +760,9 @@ async def initialize( aip=self.aip, arg_file=self.arg_file, endorser_role=self.endorser_role, + log_file=self.log_file, + log_config=self.log_config, + log_level=self.log_level, ) else: self.agent = the_agent @@ -1281,6 +1296,28 @@ def arg_parser(ident: str = None, port: int = 8020): action="store_true", help="Accept the ledger's TAA, if required", ) + parser.add_argument( + "--log-file", + type=str, + metavar="", + help="Output destination for the root logger.", + ) + parser.add_argument( + "--log-config", + type=str, + metavar="", + help="File path for logging configuration.", + ) + parser.add_argument( + "--log-level", + type=str, + metavar="", + default=None, + help=( + "Specifies a custom logging level as one of: " + "('debug', 'info', 'warning', 'error', 'critical')" + ), + ) return parser @@ -1312,6 +1349,9 @@ async def create_agent_with_args(args, ident: str = None): with open(arg_file) as f: arg_file_dict = yaml.safe_load(f) + log_file = args.log_file or os.getenv("ACAPY_LOG_FILE") + log_config = args.log_config or os.getenv("ACAPY_LOG_CONFIG") + log_level = args.log_level # 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 @@ -1389,6 +1429,9 @@ async def create_agent_with_args(args, ident: str = None): reuse_connections=reuse_connections, taa_accept=args.taa_accept, anoncreds_legacy_revocation=anoncreds_legacy_revocation, + log_file=log_file, + log_config=log_config, + log_level=log_level, ) return agent diff --git a/demo/runners/alice.py b/demo/runners/alice.py index 8bea579d29..31f85d0bea 100644 --- a/demo/runners/alice.py +++ b/demo/runners/alice.py @@ -36,6 +36,9 @@ def __init__( no_auto: bool = False, aip: int = 20, endorser_role: str = None, + log_file: str = None, + log_config: str = None, + log_level: str = None, **kwargs, ): super().__init__( @@ -47,6 +50,9 @@ def __init__( seed=None, aip=aip, endorser_role=endorser_role, + log_file=log_file, + log_config=log_config, + log_level=log_level, **kwargs, ) self.connection_id = None @@ -130,6 +136,9 @@ async def main(args): wallet_type=alice_agent.wallet_type, aip=alice_agent.aip, endorser_role=alice_agent.endorser_role, + log_file=alice_agent.log_file, + log_config=alice_agent.log_config, + log_level=alice_agent.log_level, ) await alice_agent.initialize(the_agent=agent) diff --git a/demo/runners/faber.py b/demo/runners/faber.py index 5a26eb2669..4d05c939ad 100644 --- a/demo/runners/faber.py +++ b/demo/runners/faber.py @@ -47,6 +47,9 @@ def __init__( endorser_role: str = None, revocation: bool = False, anoncreds_legacy_revocation: str = None, + log_file: str = None, + log_config: str = None, + log_level: str = None, **kwargs, ): super().__init__( @@ -58,6 +61,9 @@ def __init__( endorser_role=endorser_role, revocation=revocation, anoncreds_legacy_revocation=anoncreds_legacy_revocation, + log_file=log_file, + log_config=log_config, + log_level=log_level, **kwargs, ) self.connection_id = None @@ -403,6 +409,9 @@ async def main(args): aip=faber_agent.aip, endorser_role=faber_agent.endorser_role, anoncreds_legacy_revocation=faber_agent.anoncreds_legacy_revocation, + log_file=faber_agent.log_file, + log_config=faber_agent.log_config, + log_level=faber_agent.log_level, ) faber_schema_name = "degree schema" diff --git a/demo/runners/performance.py b/demo/runners/performance.py index 4c79bf6437..26daf4a87d 100644 --- a/demo/runners/performance.py +++ b/demo/runners/performance.py @@ -32,11 +32,23 @@ def __init__( ident: str, port: int, prefix: str = None, + log_file: str = None, + log_config: str = None, + log_level: str = None, **kwargs, ): if prefix is None: prefix = ident - super().__init__(ident, port, port + 1, prefix=prefix, **kwargs) + super().__init__( + ident, + port, + port + 1, + prefix=prefix, + log_file=log_file, + log_config=log_config, + log_level=log_level, + **kwargs, + ) self._connection_id = None self._connection_ready = None self.credential_state = {} @@ -123,7 +135,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: @@ -158,8 +173,23 @@ def check_task_exception(self, fut: asyncio.Task): class AliceAgent(BaseAgent): - def __init__(self, port: int, **kwargs): - super().__init__("Alice", port, seed=None, **kwargs) + def __init__( + self, + port: int, + log_file: str = None, + log_config: str = None, + log_level: str = None, + **kwargs, + ): + super().__init__( + "Alice", + port, + seed=None, + log_file=log_file, + log_config=log_config, + log_level=log_level, + **kwargs, + ) self.extra_args = [ "--auto-accept-invites", "--auto-accept-requests", @@ -195,8 +225,23 @@ async def propose_credential( class FaberAgent(BaseAgent): - def __init__(self, port: int, **kwargs): - super().__init__("Faber", port, seed="random", **kwargs) + def __init__( + self, + port: int, + log_file: str = None, + log_config: str = None, + log_level: str = None, + **kwargs, + ): + super().__init__( + "Faber", + port, + seed="random", + log_file=log_file, + log_config=log_config, + log_level=log_level, + **kwargs, + ) self.extra_args = [ "--auto-accept-invites", "--auto-accept-requests", @@ -282,6 +327,9 @@ async def main( batch_size: int = 30, wallet_type: str = None, arg_file: str = None, + log_file: str = None, + log_config: str = None, + log_level: str = None, ): if multi_ledger: genesis = None @@ -310,6 +358,9 @@ async def main( mediation=mediation, wallet_type=wallet_type, arg_file=arg_file, + log_file=log_file, + log_config=log_config, + log_level=log_level, ) await alice.listen_webhooks(start_port + 2) @@ -323,6 +374,9 @@ async def main( mediation=mediation, wallet_type=wallet_type, arg_file=arg_file, + log_file=log_file, + log_config=log_config, + log_level=log_level, ) await faber.listen_webhooks(start_port + 5) await faber.register_did() @@ -682,6 +736,28 @@ async def check_received_pings(agent, issue_count, pb): metavar="", help="Specify a file containing additional aca-py parameters", ) + parser.add_argument( + "--log-file", + type=str, + metavar="", + help=("Output destination for the root logger."), + ) + parser.add_argument( + "--log-config", + type=str, + metavar="", + help=("File path for logging configuration."), + ) + parser.add_argument( + "--log-level", + type=str, + metavar="", + default=None, + help=( + "Specifies a custom logging level as one of: " + "('debug', 'info', 'warning', 'error', 'critical')" + ), + ) args = parser.parse_args() if args.did_exchange and args.mediation: @@ -720,6 +796,9 @@ async def check_received_pings(agent, issue_count, pb): args.batch, args.wallet_type, args.arg_file, + args.log_file, + args.log_config, + args.log_level, ) ) except KeyboardInterrupt: diff --git a/demo/runners/support/agent.py b/demo/runners/support/agent.py index 26563fe6f5..9011efd8ad 100644 --- a/demo/runners/support/agent.py +++ b/demo/runners/support/agent.py @@ -138,6 +138,9 @@ def __init__( arg_file: str = None, endorser_role: str = None, extra_args=None, + log_file: str = None, + log_config: str = None, + log_level: str = None, **params, ): self.ident = ident @@ -169,6 +172,9 @@ def __init__( self.mediator_request_id = None self.aip = aip self.arg_file = arg_file + self.log_file = log_file + self.log_config = log_config + self.log_level = log_level self.admin_url = f"http://{self.internal_host}:{admin_port}" if AGENT_ENDPOINT: @@ -345,6 +351,24 @@ def get_agent_args(self): "--public-invites", # ("--log-level", "debug"), ] + if self.log_file: + result.extend( + [ + ("--log-file", self.log_file), + ] + ) + if self.log_config: + result.extend( + [ + ("--log-config", self.log_config), + ] + ) + if self.log_level: + result.extend( + [ + ("--log-level", self.log_level), + ] + ) 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..77e5d7792f 100644 --- a/demo/runners/support/utils.py +++ b/demo/runners/support/utils.py @@ -122,7 +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): From ab29497227b467a4b7edb180b13fc359e233a432 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Tue, 17 Oct 2023 19:33:45 +0530 Subject: [PATCH 02/12] cleanup Signed-off-by: Shaanjot Gill --- Logging.md | 1 + 1 file changed, 1 insertion(+) diff --git a/Logging.md b/Logging.md index 1935db7814..0bdd483701 100644 --- a/Logging.md +++ b/Logging.md @@ -14,6 +14,7 @@ Other log levels fall back to `WARNING`. * `--log-file` - Path to a file to log to. * `--log-config` - Specifies a custom logging configuration file + Example: ```sh From c46c4d0880b9d77e26521e9ea3d4502976c7c6a7 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Fri, 20 Oct 2023 22:00:03 +0530 Subject: [PATCH 03/12] override handlers from config if --log-file provided Signed-off-by: Shaanjot Gill --- aries_cloudagent/config/logging.py | 41 +++++++++++++++++++++++++----- 1 file changed, 34 insertions(+), 7 deletions(-) diff --git a/aries_cloudagent/config/logging.py b/aries_cloudagent/config/logging.py index 7c31996963..7ea8b4a5b0 100644 --- a/aries_cloudagent/config/logging.py +++ b/aries_cloudagent/config/logging.py @@ -121,18 +121,45 @@ def configure( handler_pattern = None # Create context filter to adapt wallet_id in logger messages _cf = ContextFilter() + _new_handler = None + _to_remove_handler = None 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)) + # Override the existing handler with new handler with provided + # log file path + if log_file: + _new_handler = TimedRotatingFileMultiProcessHandler( + filename=log_file, + interval=_handler.interval + if (_handler.interval < 14 and _handler.when == "D") + else 7, + when=_handler.when, + backupCount=_handler.backupCount, + ) + _to_remove_handler = _handler + # Setup new handler + _new_handler.setFormatter( + jsonlogger.JsonFormatter(handler_pattern) + ) + _new_handler.addFilter(_cf) + if log_level: + _new_handler.setLevel(log_level.upper()) + else: + # 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)) + # Setup existing handlers from config file # Add context filter to handlers - _handler.addFilter(_cf) - if log_level: - _handler.setLevel(log_level.upper()) + if _handler != _to_remove_handler: + _handler.addFilter(_cf) + if log_level: + _handler.setLevel(log_level.upper()) + if _new_handler and _to_remove_handler: + logging.root.handlers.remove(_to_remove_handler) + logging.root.handlers.append(_new_handler) if not file_handler_set and log_file: file_path = os.path.join( os.path.dirname(os.path.realpath(__file__)).replace( From 98c22efda83fe10546ae063749a9f1327d80cf71 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Mon, 23 Oct 2023 20:31:34 +0530 Subject: [PATCH 04/12] feedback and revert caplog test changes Signed-off-by: Shaanjot Gill --- aries_cloudagent/admin/server.py | 7 ++--- .../handlers/tests/test_keylist_handler.py | 30 ++++++++----------- .../messages/tests/test_problem_report.py | 12 +++----- .../v1_0/tests/test_mediation_manager.py | 14 +++++---- .../messages/tests/test_problem_report.py | 11 ++----- .../tests/test_credential_problem_report.py | 12 +++----- .../tests/test_cred_problem_report.py | 10 ++----- .../messages/tests/test_problem_report.py | 12 +++----- 8 files changed, 40 insertions(+), 68 deletions(-) diff --git a/aries_cloudagent/admin/server.py b/aries_cloudagent/admin/server.py index 9521a991b8..53f8890546 100644 --- a/aries_cloudagent/admin/server.py +++ b/aries_cloudagent/admin/server.py @@ -408,11 +408,8 @@ async def setup_context(request: web.Request, handler): ) = self.multitenant_manager.get_wallet_details_from_token( token=token ) - try: - context_wallet_id.get() - except LookupError: - wallet_id = profile.settings.get("wallet.id") - context_wallet_id.set(wallet_id) + wallet_id = profile.settings.get("wallet.id") + context_wallet_id.set(wallet_id) meta_data = { "wallet_id": walletid, "wallet_key": walletkey, diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py index 62649002b2..a8bebf6121 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py @@ -1,8 +1,7 @@ """Test keylist handler.""" +import logging import pytest -from asynctest import mock as async_mock - from ......connections.models.conn_record import ConnRecord from ......messaging.base_handler import HandlerException from ......messaging.request_context import RequestContext @@ -11,7 +10,6 @@ from ...models.mediation_record import MediationRecord from ..keylist_handler import KeylistHandler -from .. import keylist_handler as test_module TEST_CONN_ID = "conn-id" pytestmark = pytest.mark.asyncio @@ -46,20 +44,18 @@ async def test_handler_no_active_connection(self, context): await handler.handle(context, responder) assert "inactive connection" in exc.value - async def test_handler_no_record(self, context): - with async_mock.patch.object( - test_module, "LOG", async_mock.MagicMock() - ) as mock_logger: - handler, responder = KeylistHandler(), MockResponder() + async def test_handler_no_record(self, context, caplog): + handler, responder = KeylistHandler(), MockResponder() + logging.propagate = True + with caplog.at_level(logging.INFO): await handler.handle(context, responder) - assert mock_logger.warning.call_count == 1 - assert mock_logger.info.call_count == 0 + assert "not acting as mediator" in caplog.text + assert "Keylist received: " not in caplog.text - async def test_handler(self, context, session): - with async_mock.patch.object( - test_module, "LOG", async_mock.MagicMock() - ) as mock_logger: - handler, responder = KeylistHandler(), MockResponder() - await MediationRecord(connection_id=TEST_CONN_ID).save(session) + async def test_handler(self, context, session, caplog): + handler, responder = KeylistHandler(), MockResponder() + await MediationRecord(connection_id=TEST_CONN_ID).save(session) + logging.propagate = True + with caplog.at_level(logging.INFO): await handler.handle(context, responder) - assert mock_logger.info.call_count == 1 + assert "Keylist received: " in caplog.text diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py index 29a2da6595..322ae27f5a 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" +import logging import pytest -from asynctest import mock as async_mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -13,8 +13,6 @@ ValidationError, ) -from .. import problem_report as test_module - class TestCMProblemReportMessage(TestCase): """Test problem report.""" @@ -55,8 +53,6 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - with async_mock.patch.object( - test_module, "LOGGER", async_mock.MagicMock() - ) as mock_logger: - CMProblemReportSchema().validate_fields(data) - assert mock_logger.warning.call_count == 1 + self._caplog.set_level(logging.WARNING) + CMProblemReportSchema().validate_fields(data) + assert "Unexpected error code received" in self._caplog.text 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 95349e2ef8..5848c59063 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 @@ -1,4 +1,5 @@ """Test MediationManager.""" +import logging from typing import AsyncIterable, Iterable from asynctest import mock as async_mock @@ -448,8 +449,9 @@ async def test_store_update_results_exists_relay(self, session, manager): assert route.wallet_id == "test_wallet" assert route.connection_id == TEST_CONN_ID - async def test_store_update_results_errors(self, manager): + async def test_store_update_results_errors(self, caplog, manager): """test_store_update_results with errors.""" + caplog.set_level(logging.WARNING) results = [ KeylistUpdated( recipient_key=TEST_VERKEY, @@ -467,11 +469,11 @@ async def test_store_update_results_errors(self, manager): result=KeylistUpdated.RESULT_CLIENT_ERROR, ), ] - with async_mock.patch.object( - test_module, "LOGGER", async_mock.MagicMock() - ) as mock_logger: - await manager.store_update_results(TEST_CONN_ID, results) - assert mock_logger.warning.call_count == 3 + await manager.store_update_results(TEST_CONN_ID, results) + assert "no_change" in caplog.text + assert "client_error" in caplog.text + assert "server_error" in caplog.text + print(caplog.text) async def test_get_my_keylist(self, session, manager): """test_get_my_keylist.""" diff --git a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py index 34fa28421c..03af260b1a 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py @@ -1,13 +1,10 @@ import pytest -from asynctest import mock as async_mock - from ......messaging.models.base import BaseModelError from .....didcomm_prefix import DIDCommPrefix from ...message_types import PROBLEM_REPORT from ..problem_report import DIDXProblemReport -from .. import problem_report as test_module THID = "dummy-thid" PTHID = "dummy-pthid" @@ -34,11 +31,9 @@ def test_missing_code(): DIDXProblemReport.deserialize({"description": {"en": "test"}}) -def test_unrecognized_code(): - with async_mock.patch.object( - test_module, "LOGGER", async_mock.MagicMock() - ) as mock_logger: +def test_unrecognized_code(caplog): + with caplog.at_level("DEBUG"): DIDXProblemReport.deserialize( {"description": {"code": "unknown", "en": "test"}} ) - assert mock_logger.warning.call_count == 1 + assert "Unexpected error code received" in caplog.text diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py index 97d14785d7..fc87a911fa 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py @@ -1,6 +1,6 @@ +import logging import pytest -from asynctest import mock as async_mock from unittest import mock, TestCase from ......messaging.models.base import BaseModelError @@ -16,8 +16,6 @@ ValidationError, ) -from .. import credential_problem_report as test_module - class TestCredentialProblemReport(TestCase): """Problem report tests.""" @@ -107,8 +105,6 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - with async_mock.patch.object( - test_module, "LOGGER", async_mock.MagicMock() - ) as mock_logger: - CredentialProblemReportSchema().validate_fields(data) - assert mock_logger.warning.call_count == 1 + self._caplog.set_level(logging.WARNING) + CredentialProblemReportSchema().validate_fields(data) + assert "Unexpected error code received" in self._caplog.text diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py index aff6f7f798..2389668065 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py @@ -1,7 +1,6 @@ import logging import pytest -from asynctest import mock as async_mock from unittest import mock, TestCase from ......messaging.models.base import BaseModelError @@ -17,8 +16,6 @@ ValidationError, ) -from .. import cred_problem_report as test_module - class TestCredProblemReport(TestCase): """Problem report tests.""" @@ -103,11 +100,8 @@ def test_validate_and_logger(self): }, ).serialize() self._caplog.set_level(logging.WARNING) - with async_mock.patch.object( - test_module, "LOGGER", async_mock.MagicMock() - ) as mock_logger: - V20CredProblemReportSchema().validate_fields(data) - assert mock_logger.warning.call_count == 1 + V20CredProblemReportSchema().validate_fields(data) + assert "Unexpected error code received" in self._caplog.text def test_validate_x(self): """Exercise validation requirements.""" diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py index 17dc35ef4e..831d109b9f 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" +import logging import pytest -from asynctest import mock as async_mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -13,8 +13,6 @@ ValidationError, ) -from .. import problem_report as test_module - class TestOOBProblemReportMessage(TestCase): """Test problem report.""" @@ -72,11 +70,9 @@ def test_validate_and_logger(self): ) data.assign_thread_id(thid="test_thid", pthid="test_pthid") data = data.serialize() - with async_mock.patch.object( - test_module, "LOGGER", async_mock.MagicMock() - ) as mock_logger: - OOBProblemReportSchema().validate_fields(data) - assert mock_logger.warning.call_count == 1 + self._caplog.set_level(logging.WARNING) + OOBProblemReportSchema().validate_fields(data) + assert "Unexpected error code received" in self._caplog.text def test_assign_msg_type_version_to_model_inst(self): test_msg = OOBProblemReport() From ebe6df33742b4719b86b6ac9f0ad66b796cde171 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Thu, 26 Oct 2023 00:10:25 +0530 Subject: [PATCH 05/12] update default log file path Signed-off-by: Shaanjot Gill --- aries_cloudagent/config/default_per_tenant_logging_config.ini | 2 +- aries_cloudagent/config/default_per_tenant_logging_config.yml | 2 +- docker/Dockerfile.run | 2 +- 3 files changed, 3 insertions(+), 3 deletions(-) diff --git a/aries_cloudagent/config/default_per_tenant_logging_config.ini b/aries_cloudagent/config/default_per_tenant_logging_config.ini index 8f207bb6a0..63afe2f447 100644 --- a/aries_cloudagent/config/default_per_tenant_logging_config.ini +++ b/aries_cloudagent/config/default_per_tenant_logging_config.ini @@ -21,7 +21,7 @@ args=(sys.stderr,) class=logging.handlers.TimedRotatingFileMultiProcessHandler level=DEBUG formatter=formatter -args=('acapy.log', 'd', 7, 1,) +args=('./log/acapy-agent.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 index 3978766e48..7fa910bb05 100644 --- a/aries_cloudagent/config/default_per_tenant_logging_config.yml +++ b/aries_cloudagent/config/default_per_tenant_logging_config.yml @@ -11,7 +11,7 @@ handlers: rotating_file: class: logging.handlers.TimedRotatingFileMultiProcessHandler level: DEBUG - filename: 'acapy.log' + filename: './log/acapy-agent.log' when: 'd' interval: 7 backupCount: 1 diff --git a/docker/Dockerfile.run b/docker/Dockerfile.run index ad4fde5622..524607f22a 100644 --- a/docker/Dockerfile.run +++ b/docker/Dockerfile.run @@ -9,7 +9,7 @@ RUN pip install --no-cache-dir poetry RUN mkdir -p aries_cloudagent && touch aries_cloudagent/__init__.py ADD pyproject.toml poetry.lock README.md ./ -RUN mkdir -p logs && chmod -R ug+rw logs +RUN mkdir -p log && chmod -R ug+rw log RUN poetry install -E "askar bbs" From 6789763b8b6ff7a00538befb7333ae2ea773893e Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Thu, 26 Oct 2023 00:43:46 +0530 Subject: [PATCH 06/12] change dockerfile logs dir to log Signed-off-by: Shaanjot Gill --- docker/Dockerfile.demo | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docker/Dockerfile.demo b/docker/Dockerfile.demo index fae85cc937..a1c0bd846f 100644 --- a/docker/Dockerfile.demo +++ b/docker/Dockerfile.demo @@ -22,7 +22,7 @@ ADD scripts ./scripts RUN pip3 install --no-cache-dir -e . -RUN mkdir demo logs && chown -R aries:aries demo logs && chmod -R ug+rw demo logs +RUN mkdir demo log && chown -R aries:aries demo log && chmod -R ug+rw demo log # Add and install demo code ADD demo/requirements.txt ./demo/requirements.txt From 39e09c09fea0518932af321ce0e3f00138418a13 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Fri, 10 Nov 2023 21:26:53 +0530 Subject: [PATCH 07/12] unit test fixes without caplog + fixes Signed-off-by: Shaanjot Gill --- aries_cloudagent/config/logging.py | 72 +++++++++---------- aries_cloudagent/config/tests/test_logging.py | 1 - .../v1_0/handlers/keylist_handler.py | 4 +- .../handlers/tests/test_keylist_handler.py | 8 +-- .../messages/tests/test_problem_report.py | 27 ++++--- .../v1_0/tests/test_mediation_manager.py | 18 +++-- .../messages/tests/test_problem_report.py | 9 ++- .../tests/test_credential_problem_report.py | 16 ++--- .../tests/test_cred_problem_report.py | 16 ++--- .../messages/tests/test_problem_report.py | 16 ++--- docker/Dockerfile.demo | 2 +- docker/Dockerfile.run | 2 +- 12 files changed, 92 insertions(+), 99 deletions(-) diff --git a/aries_cloudagent/config/logging.py b/aries_cloudagent/config/logging.py index 7ea8b4a5b0..d7993e2371 100644 --- a/aries_cloudagent/config/logging.py +++ b/aries_cloudagent/config/logging.py @@ -1,10 +1,11 @@ """Utilities related to logging.""" +from configparser import ConfigParser from contextvars import ContextVar from datetime import datetime, timedelta from io import TextIOWrapper import logging -from logging.config import fileConfig, dictConfig +from logging.config import dictConfig, fileConfig from logging.handlers import BaseRotatingHandler import os from random import randint @@ -23,9 +24,6 @@ from .banner import Banner DEFAULT_LOGGING_CONFIG_PATH = "aries_cloudagent.config:default_logging_config.ini" -# DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH_YAML = ( -# "./aries_cloudagent/config/default_per_tenant_logging_config.yml" -# ) DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH_INI = ( "aries_cloudagent.config:default_per_tenant_logging_config.ini" ) @@ -99,12 +97,37 @@ def configure( else: if multitenant: config_path = DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH_INI + if log_file: + parsed = ConfigParser() + config_file_path = ( + f"./{(config_path.split(':')[0]).replace('.', '/')}" + f"/{config_path.split(':')[1]}" + ) + parsed.read(config_file_path) + parsed.set( + "handler_timed_file_handler", + "args", + str( + ( + log_file, + "d", + 7, + 1, + ) + ), + ) + with open(config_file_path, "w") as configfile: + parsed.write(configfile) else: config_path = DEFAULT_LOGGING_CONFIG_PATH 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) + if log_file: + log_config["handlers"]["rotating_file"]["filename"] = log_file + with open(config_path, "w") as fp: + yaml.dump(log_config, fp) else: log_config = load_resource(config_path, "utf-8") if log_config: @@ -121,45 +144,18 @@ def configure( handler_pattern = None # Create context filter to adapt wallet_id in logger messages _cf = ContextFilter() - _new_handler = None - _to_remove_handler = None for _handler in logging.root.handlers: if isinstance(_handler, TimedRotatingFileMultiProcessHandler): file_handler_set = True handler_pattern = _handler.formatter._fmt - # Override the existing handler with new handler with provided - # log file path - if log_file: - _new_handler = TimedRotatingFileMultiProcessHandler( - filename=log_file, - interval=_handler.interval - if (_handler.interval < 14 and _handler.when == "D") - else 7, - when=_handler.when, - backupCount=_handler.backupCount, - ) - _to_remove_handler = _handler - # Setup new handler - _new_handler.setFormatter( - jsonlogger.JsonFormatter(handler_pattern) - ) - _new_handler.addFilter(_cf) - if log_level: - _new_handler.setLevel(log_level.upper()) - else: - # 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)) - # Setup existing handlers from config file + # 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 - if _handler != _to_remove_handler: - _handler.addFilter(_cf) - if log_level: - _handler.setLevel(log_level.upper()) - if _new_handler and _to_remove_handler: - logging.root.handlers.remove(_to_remove_handler) - logging.root.handlers.append(_new_handler) + _handler.addFilter(_cf) + if log_level: + _handler.setLevel(log_level.upper()) if not file_handler_set and log_file: file_path = os.path.join( os.path.dirname(os.path.realpath(__file__)).replace( diff --git a/aries_cloudagent/config/tests/test_logging.py b/aries_cloudagent/config/tests/test_logging.py index 848c8267bb..ac2f90b39b 100644 --- a/aries_cloudagent/config/tests/test_logging.py +++ b/aries_cloudagent/config/tests/test_logging.py @@ -40,7 +40,6 @@ def test_configure_with_per_tenant_config_file(self): ), ): test_module.LoggingConfigurator.configure( - logging_config_path="aries_cloudagent.config:default_per_tenant_logging_config.ini", log_file="test.log", multitenant=True, ) 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 de00566498..6d7225a64d 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 @@ -32,11 +32,11 @@ async def handle(self, context: RequestContext, responder: BaseResponder): session, context.connection_record.connection_id ) except StorageNotFoundError as err: - LOG.warning( + self._logger.warning( "Received keylist from connection that is not acting as mediator: %s", err, ) return # TODO verify our keylist matches? - LOG.info("Keylist received: %s", context.message) + self._logger.info("Keylist received: %s", context.message) diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py index a8bebf6121..8c2b837aac 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/handlers/tests/test_keylist_handler.py @@ -47,8 +47,8 @@ async def test_handler_no_active_connection(self, context): async def test_handler_no_record(self, context, caplog): handler, responder = KeylistHandler(), MockResponder() logging.propagate = True - with caplog.at_level(logging.INFO): - await handler.handle(context, responder) + caplog.set_level(logging.INFO) + await handler.handle(context, responder) assert "not acting as mediator" in caplog.text assert "Keylist received: " not in caplog.text @@ -56,6 +56,6 @@ async def test_handler(self, context, session, caplog): handler, responder = KeylistHandler(), MockResponder() await MediationRecord(connection_id=TEST_CONN_ID).save(session) logging.propagate = True - with caplog.at_level(logging.INFO): - await handler.handle(context, responder) + caplog.set_level(logging.INFO) + await handler.handle(context, responder) assert "Keylist received: " in caplog.text diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py index 322ae27f5a..0a73935689 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" -import logging import pytest +from asynctest import mock as async_mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -13,25 +13,20 @@ ValidationError, ) +from .. import problem_report as test_module + class TestCMProblemReportMessage(TestCase): """Test problem report.""" - def setUp(self): - self.problem_report = CMProblemReport( + def test_make_model(self): + """Make problem report model.""" + data = CMProblemReport( description={ "en": "Insufficient credit", "code": ProblemReportReason.MEDIATION_NOT_GRANTED.value, } - ) - - @pytest.fixture(autouse=True) - def inject_fixtures(self, caplog): - self._caplog = caplog - - def test_make_model(self): - """Make problem report model.""" - data = self.problem_report.serialize() + ).serialize() model_instance = CMProblemReport.deserialize(data) assert isinstance(model_instance, CMProblemReport) @@ -53,6 +48,8 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - self._caplog.set_level(logging.WARNING) - CMProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", autospec=True + ) as mock_logger: + CMProblemReportSchema().validate_fields(data) + mock_logger.warning.assert_called_once() 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 5848c59063..7a1b0ed863 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 @@ -1,9 +1,8 @@ """Test MediationManager.""" -import logging -from typing import AsyncIterable, Iterable +import pytest from asynctest import mock as async_mock -import pytest +from typing import AsyncIterable, Iterable from .. import manager as test_module from .....core.event_bus import EventBus, MockEventBus @@ -449,9 +448,8 @@ async def test_store_update_results_exists_relay(self, session, manager): assert route.wallet_id == "test_wallet" assert route.connection_id == TEST_CONN_ID - async def test_store_update_results_errors(self, caplog, manager): + async def test_store_update_results_errors(self, manager): """test_store_update_results with errors.""" - caplog.set_level(logging.WARNING) results = [ KeylistUpdated( recipient_key=TEST_VERKEY, @@ -469,11 +467,11 @@ async def test_store_update_results_errors(self, caplog, manager): result=KeylistUpdated.RESULT_CLIENT_ERROR, ), ] - await manager.store_update_results(TEST_CONN_ID, results) - assert "no_change" in caplog.text - assert "client_error" in caplog.text - assert "server_error" in caplog.text - print(caplog.text) + with async_mock.patch.object( + test_module, "LOGGER", autospec=True + ) as mock_logger: + await manager.store_update_results(TEST_CONN_ID, results) + assert mock_logger.warning.call_count == 3 async def test_get_my_keylist(self, session, manager): """test_get_my_keylist.""" diff --git a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py index 03af260b1a..8ec1823c27 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py @@ -1,10 +1,13 @@ import pytest +from asynctest import mock as async_mock + from ......messaging.models.base import BaseModelError from .....didcomm_prefix import DIDCommPrefix from ...message_types import PROBLEM_REPORT from ..problem_report import DIDXProblemReport +from .. import problem_report as test_module THID = "dummy-thid" PTHID = "dummy-pthid" @@ -31,9 +34,9 @@ def test_missing_code(): DIDXProblemReport.deserialize({"description": {"en": "test"}}) -def test_unrecognized_code(caplog): - with caplog.at_level("DEBUG"): +def test_unrecognized_code(): + with async_mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: DIDXProblemReport.deserialize( {"description": {"code": "unknown", "en": "test"}} ) - assert "Unexpected error code received" in caplog.text + mock_logger.warning.assert_called_once() diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py index fc87a911fa..ffcb3a536f 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py @@ -1,6 +1,6 @@ -import logging import pytest +from asynctest import mock as async_mock from unittest import mock, TestCase from ......messaging.models.base import BaseModelError @@ -16,6 +16,8 @@ ValidationError, ) +from .. import credential_problem_report as test_module + class TestCredentialProblemReport(TestCase): """Problem report tests.""" @@ -31,10 +33,6 @@ def test_init_type(self): ) assert prob._type == DIDCommPrefix.qualify_current(CREDENTIAL_PROBLEM_REPORT) - @pytest.fixture(autouse=True) - def inject_fixtures(self, caplog): - self._caplog = caplog - @mock.patch( f"{PROTOCOL_PACKAGE}.messages.credential_problem_report." "CredentialProblemReportSchema.load" @@ -105,6 +103,8 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - self._caplog.set_level(logging.WARNING) - CredentialProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", autospec=True + ) as mock_logger: + CredentialProblemReportSchema().validate_fields(data) + assert mock_logger.warning.call_count == 1 diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py index 2389668065..0a8829215c 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py @@ -1,6 +1,6 @@ -import logging import pytest +from asynctest import mock as async_mock from unittest import mock, TestCase from ......messaging.models.base import BaseModelError @@ -16,14 +16,12 @@ ValidationError, ) +from .. import cred_problem_report as test_module + class TestCredProblemReport(TestCase): """Problem report tests.""" - @pytest.fixture(autouse=True) - def inject_fixtures(self, caplog): - self._caplog = caplog - def test_init_type(self): """Test initializer.""" @@ -99,9 +97,11 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - self._caplog.set_level(logging.WARNING) - V20CredProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", autospec=True + ) as mock_logger: + V20CredProblemReportSchema().validate_fields(data) + assert mock_logger.warning.call_count == 1 def test_validate_x(self): """Exercise validation requirements.""" diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py index 831d109b9f..72e8245255 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" -import logging import pytest +from asynctest import mock as async_mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -13,14 +13,12 @@ ValidationError, ) +from .. import problem_report as test_module + class TestOOBProblemReportMessage(TestCase): """Test problem report.""" - @pytest.fixture(autouse=True) - def inject_fixtures(self, caplog): - self._caplog = caplog - def setUp(self): self.problem_report = OOBProblemReport( description={ @@ -70,9 +68,11 @@ def test_validate_and_logger(self): ) data.assign_thread_id(thid="test_thid", pthid="test_pthid") data = data.serialize() - self._caplog.set_level(logging.WARNING) - OOBProblemReportSchema().validate_fields(data) - assert "Unexpected error code received" in self._caplog.text + with async_mock.patch.object( + test_module, "LOGGER", autospec=True + ) as mock_logger: + OOBProblemReportSchema().validate_fields(data) + assert mock_logger.warning.call_count == 1 def test_assign_msg_type_version_to_model_inst(self): test_msg = OOBProblemReport() diff --git a/docker/Dockerfile.demo b/docker/Dockerfile.demo index a1c0bd846f..fae85cc937 100644 --- a/docker/Dockerfile.demo +++ b/docker/Dockerfile.demo @@ -22,7 +22,7 @@ ADD scripts ./scripts RUN pip3 install --no-cache-dir -e . -RUN mkdir demo log && chown -R aries:aries demo log && chmod -R ug+rw demo log +RUN mkdir demo logs && chown -R aries:aries demo logs && chmod -R ug+rw demo logs # Add and install demo code ADD demo/requirements.txt ./demo/requirements.txt diff --git a/docker/Dockerfile.run b/docker/Dockerfile.run index 524607f22a..ad4fde5622 100644 --- a/docker/Dockerfile.run +++ b/docker/Dockerfile.run @@ -9,7 +9,7 @@ RUN pip install --no-cache-dir poetry RUN mkdir -p aries_cloudagent && touch aries_cloudagent/__init__.py ADD pyproject.toml poetry.lock README.md ./ -RUN mkdir -p log && chmod -R ug+rw log +RUN mkdir -p logs && chmod -R ug+rw logs RUN poetry install -E "askar bbs" From 067ec3ad27affe4175df806dc0d821edeb2d742d Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Fri, 10 Nov 2023 22:18:55 +0530 Subject: [PATCH 08/12] fix async_mock import with unit tests Signed-off-by: Shaanjot Gill --- aries_cloudagent/config/tests/test_logging.py | 36 +++++++++---------- .../indy/sdk/tests/test_profile.py | 4 +-- .../messages/tests/test_problem_report.py | 6 ++-- .../v1_0/tests/test_mediation_manager.py | 4 +-- .../messages/tests/test_problem_report.py | 4 +-- .../tests/test_credential_problem_report.py | 8 ++--- .../tests/test_cred_problem_report.py | 8 ++--- .../messages/tests/test_problem_report.py | 6 ++-- 8 files changed, 32 insertions(+), 44 deletions(-) diff --git a/aries_cloudagent/config/tests/test_logging.py b/aries_cloudagent/config/tests/test_logging.py index d61854d8d3..0bd6d7c514 100644 --- a/aries_cloudagent/config/tests/test_logging.py +++ b/aries_cloudagent/config/tests/test_logging.py @@ -28,14 +28,14 @@ def test_configure_default(self, mock_file_config, mock_load_resource): ) def test_configure_with_per_tenant_config_file(self): - with async_mock.patch.object( + with mock.patch.object( test_module, "logging", - async_mock.MagicMock( - basicConfig=async_mock.MagicMock(), - FileHandler=async_mock.MagicMock(), - root=async_mock.MagicMock( - warning=async_mock.MagicMock(), + mock.MagicMock( + basicConfig=mock.MagicMock(), + FileHandler=mock.MagicMock(), + root=mock.MagicMock( + warning=mock.MagicMock(), handlers=[], ), ), @@ -46,14 +46,14 @@ def test_configure_with_per_tenant_config_file(self): ) def test_configure_with_per_tenant_yml_file(self): - with async_mock.patch.object( + with mock.patch.object( test_module, "logging", - async_mock.MagicMock( - basicConfig=async_mock.MagicMock(), - FileHandler=async_mock.MagicMock(), - root=async_mock.MagicMock( - warning=async_mock.MagicMock(), + mock.MagicMock( + basicConfig=mock.MagicMock(), + FileHandler=mock.MagicMock(), + root=mock.MagicMock( + warning=mock.MagicMock(), handlers=[], ), ), @@ -65,14 +65,14 @@ def test_configure_with_per_tenant_yml_file(self): ) def test_configure_with_default_config(self): - with async_mock.patch.object( + with mock.patch.object( test_module, "logging", - async_mock.MagicMock( - basicConfig=async_mock.MagicMock(), - FileHandler=async_mock.MagicMock(), - root=async_mock.MagicMock( - warning=async_mock.MagicMock(), + mock.MagicMock( + basicConfig=mock.MagicMock(), + FileHandler=mock.MagicMock(), + root=mock.MagicMock( + warning=mock.MagicMock(), handlers=[], ), ), diff --git a/aries_cloudagent/indy/sdk/tests/test_profile.py b/aries_cloudagent/indy/sdk/tests/test_profile.py index ddef3ef26d..660641e4d7 100644 --- a/aries_cloudagent/indy/sdk/tests/test_profile.py +++ b/aries_cloudagent/indy/sdk/tests/test_profile.py @@ -122,9 +122,7 @@ def test_read_only(open_wallet): def test_finalizer(open_wallet): profile = IndySdkProfile(open_wallet) assert profile - with mock.patch.object( - test_module, "LOGGER", autospec=True - ) as mock_logger: + with mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: profile._finalizer() assert mock_logger.debug.call_count == 1 mock_logger.debug.assert_called_once_with( diff --git a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py index 0a73935689..fe0b5a8722 100644 --- a/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/coordinate_mediation/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" import pytest -from asynctest import mock as async_mock +from unittest import mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -48,8 +48,6 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - with async_mock.patch.object( - test_module, "LOGGER", autospec=True - ) as mock_logger: + with mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: CMProblemReportSchema().validate_fields(data) mock_logger.warning.assert_called_once() 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 2b552f8f68..05e39d6686 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 @@ -467,9 +467,7 @@ async def test_store_update_results_errors(self, manager): result=KeylistUpdated.RESULT_CLIENT_ERROR, ), ] - with mock.patch.object( - test_module, "LOGGER", autospec=True - ) as mock_logger: + with mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: await manager.store_update_results(TEST_CONN_ID, results) assert mock_logger.warning.call_count == 3 diff --git a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py index 8ec1823c27..6d4a700ae7 100644 --- a/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/didexchange/v1_0/messages/tests/test_problem_report.py @@ -1,6 +1,6 @@ import pytest -from asynctest import mock as async_mock +from unittest import mock from ......messaging.models.base import BaseModelError from .....didcomm_prefix import DIDCommPrefix @@ -35,7 +35,7 @@ def test_missing_code(): def test_unrecognized_code(): - with async_mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: + with mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: DIDXProblemReport.deserialize( {"description": {"code": "unknown", "en": "test"}} ) diff --git a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py index 89099e65e3..86a8ef4c2c 100644 --- a/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v1_0/messages/tests/test_credential_problem_report.py @@ -1,7 +1,7 @@ import pytest -from aries_cloudagent.tests import mock -from unittest import mock, TestCase +from unittest import mock +from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -103,8 +103,6 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - with mock.patch.object( - test_module, "LOGGER", autospec=True - ) as mock_logger: + with mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: CredentialProblemReportSchema().validate_fields(data) assert mock_logger.warning.call_count == 1 diff --git a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py index cd680f5386..4459ec4bc9 100644 --- a/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py +++ b/aries_cloudagent/protocols/issue_credential/v2_0/messages/tests/test_cred_problem_report.py @@ -1,7 +1,7 @@ import pytest -from aries_cloudagent.tests import mock -from unittest import mock, TestCase +from unittest import mock +from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -97,9 +97,7 @@ def test_validate_and_logger(self): "code": "invalid_code", }, ).serialize() - with mock.patch.object( - test_module, "LOGGER", autospec=True - ) as mock_logger: + with mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: V20CredProblemReportSchema().validate_fields(data) assert mock_logger.warning.call_count == 1 diff --git a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py index 72e8245255..4adfd23602 100644 --- a/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py +++ b/aries_cloudagent/protocols/out_of_band/v1_0/messages/tests/test_problem_report.py @@ -1,7 +1,7 @@ """Test Problem Report Message.""" import pytest -from asynctest import mock as async_mock +from unittest import mock from unittest import TestCase from ......messaging.models.base import BaseModelError @@ -68,9 +68,7 @@ def test_validate_and_logger(self): ) data.assign_thread_id(thid="test_thid", pthid="test_pthid") data = data.serialize() - with async_mock.patch.object( - test_module, "LOGGER", autospec=True - ) as mock_logger: + with mock.patch.object(test_module, "LOGGER", autospec=True) as mock_logger: OOBProblemReportSchema().validate_fields(data) assert mock_logger.warning.call_count == 1 From eeab299861bf01679034f45ce3d5b1e1c734fcff Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Fri, 10 Nov 2023 23:41:24 +0530 Subject: [PATCH 09/12] specify --log-file for some bdd test scenarios Signed-off-by: Shaanjot Gill --- demo/features/0160-connection.feature | 12 ++++----- demo/features/0453-issue-credential.feature | 28 ++++++++++----------- 2 files changed, 20 insertions(+), 20 deletions(-) diff --git a/demo/features/0160-connection.feature b/demo/features/0160-connection.feature index beccc4df34..e5f41a66bc 100644 --- a/demo/features/0160-connection.feature +++ b/demo/features/0160-connection.feature @@ -12,9 +12,9 @@ Feature: RFC 0160 Aries agent connection functions And "Bob" has an active connection Examples: - | Acme_capabilities | Bob_capabilities | - | --public-did | | - | --public-did --did-exchange | --did-exchange | - | --public-did --mediation | --mediation | - | --public-did --multitenant | --multitenant | - | --public-did --mediation --multitenant | --mediation --multitenant | + | Acme_capabilities | Bob_capabilities | + | --public-did | | + | --public-did --did-exchange | --did-exchange | + | --public-did --mediation | --mediation | + | --public-did --multitenant --log-file ./logs/acapy-agent.log | --multitenant | + | --public-did --mediation --multitenant --log-file ./logs/acapy-agent.log | --mediation --multitenant | diff --git a/demo/features/0453-issue-credential.feature b/demo/features/0453-issue-credential.feature index 89187af6a9..d15c73ba59 100644 --- a/demo/features/0453-issue-credential.feature +++ b/demo/features/0453-issue-credential.feature @@ -88,11 +88,11 @@ Feature: RFC 0453 Aries agent issue credential Then "Bob" has the json-ld credential issued Examples: - | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | - | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --multitenant | --multitenant | driverslicense | Data_DL_NormalizedValues | + | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | + | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --multitenant --log-file ./logs/acapy-agent.log | --multitenant | driverslicense | Data_DL_NormalizedValues | @T003.1-RFC0453 @GHA @@ -108,11 +108,11 @@ Feature: RFC 0453 Aries agent issue credential Then "Bob" has the json-ld credential issued Examples: - | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | - | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --multitenant | --multitenant | driverslicense | Data_DL_NormalizedValues | + | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | + | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --multitenant --log-file ./logs/acapy-agent.log | --multitenant | driverslicense | Data_DL_NormalizedValues | @T004-RFC0453 @GHA @@ -127,10 +127,10 @@ Feature: RFC 0453 Aries agent issue credential And "Bob" has the credential issued Examples: - | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | - | --revocation --public-did | | driverslicense | Data_DL_NormalizedValues | - | --revocation --public-did --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | - | --revocation --public-did --multitenant | --multitenant | driverslicense | Data_DL_NormalizedValues | + | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | + | --revocation --public-did | | driverslicense | Data_DL_NormalizedValues | + | --revocation --public-did --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | + | --revocation --public-did --multitenant --log-file ./logs/acapy-agent.log | --multitenant | driverslicense | Data_DL_NormalizedValues | @T004.1-RFC0453 Scenario Outline: Issue a credential with revocation, with the Issuer beginning with an offer, and then revoking the credential From 3e7ae1149a6beddaf7779928585b457800afe2e4 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Sat, 11 Nov 2023 01:13:48 +0530 Subject: [PATCH 10/12] bdd test fixes Signed-off-by: Shaanjot Gill --- .../default_per_tenant_logging_config.ini | 2 +- .../default_per_tenant_logging_config.yml | 2 +- aries_cloudagent/config/logging.py | 6 ++-- demo/features/0160-connection.feature | 12 ++++---- demo/features/0453-issue-credential.feature | 28 +++++++++---------- 5 files changed, 26 insertions(+), 24 deletions(-) diff --git a/aries_cloudagent/config/default_per_tenant_logging_config.ini b/aries_cloudagent/config/default_per_tenant_logging_config.ini index 63afe2f447..bb763dd56f 100644 --- a/aries_cloudagent/config/default_per_tenant_logging_config.ini +++ b/aries_cloudagent/config/default_per_tenant_logging_config.ini @@ -21,7 +21,7 @@ args=(sys.stderr,) class=logging.handlers.TimedRotatingFileMultiProcessHandler level=DEBUG formatter=formatter -args=('./log/acapy-agent.log', 'd', 7, 1,) +args=('/home/aries/log/acapy-agent.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 index 7fa910bb05..dc7c0e53d0 100644 --- a/aries_cloudagent/config/default_per_tenant_logging_config.yml +++ b/aries_cloudagent/config/default_per_tenant_logging_config.yml @@ -11,7 +11,7 @@ handlers: rotating_file: class: logging.handlers.TimedRotatingFileMultiProcessHandler level: DEBUG - filename: './log/acapy-agent.log' + filename: '/home/aries/log/acapy-agent.log' when: 'd' interval: 7 backupCount: 1 diff --git a/aries_cloudagent/config/logging.py b/aries_cloudagent/config/logging.py index d7993e2371..9bf63c3c64 100644 --- a/aries_cloudagent/config/logging.py +++ b/aries_cloudagent/config/logging.py @@ -100,8 +100,10 @@ def configure( if log_file: parsed = ConfigParser() config_file_path = ( - f"./{(config_path.split(':')[0]).replace('.', '/')}" - f"/{config_path.split(':')[1]}" + os.path.join( + os.path.dirname(os.path.realpath(__file__)), + config_path.split(':')[1], + ) ) parsed.read(config_file_path) parsed.set( diff --git a/demo/features/0160-connection.feature b/demo/features/0160-connection.feature index e5f41a66bc..49dc16093b 100644 --- a/demo/features/0160-connection.feature +++ b/demo/features/0160-connection.feature @@ -12,9 +12,9 @@ Feature: RFC 0160 Aries agent connection functions And "Bob" has an active connection Examples: - | Acme_capabilities | Bob_capabilities | - | --public-did | | - | --public-did --did-exchange | --did-exchange | - | --public-did --mediation | --mediation | - | --public-did --multitenant --log-file ./logs/acapy-agent.log | --multitenant | - | --public-did --mediation --multitenant --log-file ./logs/acapy-agent.log | --mediation --multitenant | + | Acme_capabilities | Bob_capabilities | + | --public-did | | + | --public-did --did-exchange | --did-exchange | + | --public-did --mediation | --mediation | + | --public-did --multitenant --log-file /home/aries/log/acapy-agent.log | --multitenant | + | --public-did --mediation --multitenant | --mediation --multitenant | diff --git a/demo/features/0453-issue-credential.feature b/demo/features/0453-issue-credential.feature index d15c73ba59..89187af6a9 100644 --- a/demo/features/0453-issue-credential.feature +++ b/demo/features/0453-issue-credential.feature @@ -88,11 +88,11 @@ Feature: RFC 0453 Aries agent issue credential Then "Bob" has the json-ld credential issued Examples: - | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | - | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --multitenant --log-file ./logs/acapy-agent.log | --multitenant | driverslicense | Data_DL_NormalizedValues | + | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | + | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --multitenant | --multitenant | driverslicense | Data_DL_NormalizedValues | @T003.1-RFC0453 @GHA @@ -108,11 +108,11 @@ Feature: RFC 0453 Aries agent issue credential Then "Bob" has the json-ld credential issued Examples: - | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | - | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | - | --public-did --cred-type json-ld --multitenant --log-file ./logs/acapy-agent.log | --multitenant | driverslicense | Data_DL_NormalizedValues | + | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | + | --public-did --cred-type json-ld | | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --mediation | --mediation | driverslicense | Data_DL_NormalizedValues | + | --public-did --cred-type json-ld --multitenant | --multitenant | driverslicense | Data_DL_NormalizedValues | @T004-RFC0453 @GHA @@ -127,10 +127,10 @@ Feature: RFC 0453 Aries agent issue credential And "Bob" has the credential issued Examples: - | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | - | --revocation --public-did | | driverslicense | Data_DL_NormalizedValues | - | --revocation --public-did --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | - | --revocation --public-did --multitenant --log-file ./logs/acapy-agent.log | --multitenant | driverslicense | Data_DL_NormalizedValues | + | Acme_capabilities | Bob_capabilities | Schema_name | Credential_data | + | --revocation --public-did | | driverslicense | Data_DL_NormalizedValues | + | --revocation --public-did --did-exchange | --did-exchange | driverslicense | Data_DL_NormalizedValues | + | --revocation --public-did --multitenant | --multitenant | driverslicense | Data_DL_NormalizedValues | @T004.1-RFC0453 Scenario Outline: Issue a credential with revocation, with the Issuer beginning with an offer, and then revoking the credential From 42990706903c7e94156389d1750aa94e1dd503b7 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Sat, 11 Nov 2023 01:27:45 +0530 Subject: [PATCH 11/12] black fmt change Signed-off-by: Shaanjot Gill --- aries_cloudagent/config/logging.py | 8 +++----- 1 file changed, 3 insertions(+), 5 deletions(-) diff --git a/aries_cloudagent/config/logging.py b/aries_cloudagent/config/logging.py index 9bf63c3c64..8fcc845b1f 100644 --- a/aries_cloudagent/config/logging.py +++ b/aries_cloudagent/config/logging.py @@ -99,11 +99,9 @@ def configure( config_path = DEFAULT_PER_TENANT_LOGGING_CONFIG_PATH_INI if log_file: parsed = ConfigParser() - config_file_path = ( - os.path.join( - os.path.dirname(os.path.realpath(__file__)), - config_path.split(':')[1], - ) + config_file_path = os.path.join( + os.path.dirname(os.path.realpath(__file__)), + config_path.split(":")[1], ) parsed.read(config_file_path) parsed.set( From 72291dabccfb3f1a04804bba111d10737374dc11 Mon Sep 17 00:00:00 2001 From: Shaanjot Gill Date: Sat, 11 Nov 2023 10:07:37 +0530 Subject: [PATCH 12/12] revert change in 0160 bdd test scenario Signed-off-by: Shaanjot Gill --- demo/features/0160-connection.feature | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/demo/features/0160-connection.feature b/demo/features/0160-connection.feature index 49dc16093b..beccc4df34 100644 --- a/demo/features/0160-connection.feature +++ b/demo/features/0160-connection.feature @@ -12,9 +12,9 @@ Feature: RFC 0160 Aries agent connection functions And "Bob" has an active connection Examples: - | Acme_capabilities | Bob_capabilities | - | --public-did | | - | --public-did --did-exchange | --did-exchange | - | --public-did --mediation | --mediation | - | --public-did --multitenant --log-file /home/aries/log/acapy-agent.log | --multitenant | - | --public-did --mediation --multitenant | --mediation --multitenant | + | Acme_capabilities | Bob_capabilities | + | --public-did | | + | --public-did --did-exchange | --did-exchange | + | --public-did --mediation | --mediation | + | --public-did --multitenant | --multitenant | + | --public-did --mediation --multitenant | --mediation --multitenant |