Merge pull request #2659 from shaangill025/fix_per_tenant_log

Improve Per Tenant Logging: Fix issues around default log file path

.gitignore

@@ -58,6 +58,7 @@ test-reports/
 
 # Django stuff:
 *.log
+*.lock
 local_settings.py
 db.sqlite3
 

Logging.md

@@ -8,19 +8,22 @@ Acapy's logging is based on python's [logging lib](https://docs.python.org/3/how
 Log levels `DEBUG`, `INFO` and `WARNING` are available.
 Other log levels fall back to `WARNING`.
 
+## Per Tenant Logging
+
+Supports writing of log messages to a file with `wallet_id` as the tenant identifier for each. To enable this, both multitenant mode [`--multitenant`] and writing to log file option [`--log-file`] are required. If both `--multitenant` and `--log-file` are not passed when starting up ACA-Py, then it will use `default_logging_config.ini` config [backward compatible] and not log at a per tenant level.
+
 ## Command Line Arguments
 
-* `--log-level` - The log level to log on std out.
-* `--log-file` - Path to a file to log to.
+* `--log-level` - The log level to log on std out
+* `--log-file` - Enables writing of logs to file. The provided value becomes path to a file to log to. If no value or empty string is provided then it will try to get the path from the config file
 * `--log-config` - Specifies a custom logging configuration file
 
-
 Example:
 
 ```sh
 ./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
+./bin/aca-py start --log-level debug --log-file --multitenant --log-config ./aries_cloudagent/config/default_per_tenant_logging_config.yml
 ```
 
 ## Environment Variables

aries_cloudagent/config/argparse.py

@@ -992,13 +992,15 @@ def add_arguments(self, parser: ArgumentParser):
         parser.add_argument(
             "--log-file",
             dest="log_file",
-            type=str,
             metavar="<log-file>",
+            nargs="?",
+            const="",
             default=None,
             env_var="ACAPY_LOG_FILE",
             help=(
-                "Overrides the output destination for the root logger (as defined "
-                "by the log config file) to the named <log-file>."
+                "--log-file enables writing of logs to file, if a value is "
+                "provided then it uses that as log file location, otherwise "
+                "the default location in log config file is used."
             ),
         )
         parser.add_argument(
@@ -1019,7 +1021,7 @@ def get_settings(self, args: Namespace) -> dict:
         settings = {}
         if args.log_config:
             settings["log.config"] = args.log_config
-        if args.log_file:
+        if args.log_file or args.log_file == "":
             settings["log.file"] = args.log_file
         if args.log_level:
             settings["log.level"] = args.log_level

aries_cloudagent/config/logging.py

@@ -1,21 +1,26 @@
 """Utilities related to logging."""
-
-from configparser import ConfigParser
-from contextvars import ContextVar
-from datetime import datetime, timedelta
-from io import TextIOWrapper
+import configparser
+import io
 import logging
-from logging.config import dictConfig, fileConfig
-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 TextIO
-
 import pkg_resources
+
+from contextvars import ContextVar
+from datetime import datetime, timedelta
+from logging.config import (
+    dictConfigClass,
+    _create_formatters,
+    _clearExistingHandlers,
+    _install_handlers,
+    _install_loggers,
+)
+from logging.handlers import BaseRotatingHandler
+from random import randint
+from typing import TextIO
 from portalocker import LOCK_EX, lock, unlock
 from pythonjsonlogger import jsonlogger
 
@@ -67,12 +72,64 @@ def load_resource(path: str, encoding: str = None) -> TextIO:
         else:
             bstream = pkg_resources.resource_stream(components[0], components[1])
             if encoding:
-                return TextIOWrapper(bstream, encoding=encoding)
+                return io.TextIOWrapper(bstream, encoding=encoding)
             return bstream
     except IOError:
         pass
 
 
+def dictConfig(config, new_file_path=None):
+    """Custom dictConfig, https://github.com/python/cpython/blob/main/Lib/logging/config.py."""
+    if new_file_path:
+        config["handlers"]["rotating_file"]["filename"] = f"{new_file_path}"
+    dictConfigClass(config).configure()
+
+
+def fileConfig(
+    fname,
+    new_file_path=None,
+    defaults=None,
+    disable_existing_loggers=True,
+    encoding=None,
+):
+    """Custom fileConfig to update filepath in ConfigParser file handler section."""
+    if isinstance(fname, str):
+        if not os.path.exists(fname):
+            raise FileNotFoundError(f"{fname} doesn't exist")
+        elif not os.path.getsize(fname):
+            raise RuntimeError(f"{fname} is an empty file")
+    if isinstance(fname, configparser.RawConfigParser):
+        cp = fname
+    else:
+        try:
+            cp = configparser.ConfigParser(defaults)
+            if hasattr(fname, "readline"):
+                cp.read_file(fname)
+            else:
+                encoding = io.text_encoding(encoding)
+                cp.read(fname, encoding=encoding)
+        except configparser.ParsingError as e:
+            raise RuntimeError(f"{fname} is invalid: {e}")
+    if new_file_path:
+        cp.set(
+            "handler_timed_file_handler",
+            "args",
+            str(
+                (
+                    f"{new_file_path}",
+                    "d",
+                    7,
+                    1,
+                )
+            ),
+        )
+    formatters = _create_formatters(cp)
+    with logging._lock:
+        _clearExistingHandlers()
+        handlers = _install_handlers(cp, formatters)
+        _install_loggers(cp, handlers, disable_existing_loggers)
+
+
 class LoggingConfigurator:
     """Utility class used to configure logging and print an informative start banner."""
 
@@ -92,50 +149,41 @@ def configure(
         :param log_level: str: (Default value = None)
         """
         is_dict_config = False
+        if log_file:
+            write_to_log_file = True
+        elif log_file == "":
+            log_file = None
+            write_to_log_file = True
+        else:
+            write_to_log_file = False
         if logging_config_path is not None:
             config_path = logging_config_path
         else:
-            if multitenant:
+            if multitenant and write_to_log_file:
                 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],
-                    )
-                    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 write_to_log_file and not log_file:
+                    raise ValueError(
+                        "log_file (--log-file) must be provided "
+                        "as config does not specify it."
+                    )
         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:
             if is_dict_config:
-                dictConfig(log_config)
+                dictConfig(log_config, new_file_path=log_file)
             else:
                 with log_config:
-                    fileConfig(log_config, disable_existing_loggers=False)
+                    fileConfig(
+                        log_config,
+                        new_file_path=log_file if multitenant else None,
+                        disable_existing_loggers=False,
+                    )
         else:
             logging.basicConfig(level=logging.WARNING)
             logging.root.warning(f"Logging config file not found: {config_path}")

aries_cloudagent/config/tests/test_logging.py

@@ -24,7 +24,9 @@ def test_configure_default(self, mock_file_config, mock_load_resource):
             test_module.DEFAULT_LOGGING_CONFIG_PATH, "utf-8"
         )
         mock_file_config.assert_called_once_with(
-            mock_load_resource.return_value, disable_existing_loggers=False
+            mock_load_resource.return_value,
+            disable_existing_loggers=False,
+            new_file_path=None,
         )
 
     def test_configure_with_per_tenant_config_file(self):
@@ -107,7 +109,9 @@ def test_configure_path(self, mock_file_config, mock_load_resource):
 
         mock_load_resource.assert_called_once_with(path, "utf-8")
         mock_file_config.assert_called_once_with(
-            mock_load_resource.return_value, disable_existing_loggers=False
+            mock_load_resource.return_value,
+            disable_existing_loggers=False,
+            new_file_path=None,
         )
 
     def test_banner_did(self):
@@ -140,7 +144,7 @@ def test_load_resource(self):
         with mock.patch.object(
             test_module.pkg_resources, "resource_stream", mock.MagicMock()
         ) as mock_res_stream, mock.patch.object(
-            test_module, "TextIOWrapper", mock.MagicMock()
+            test_module.io, "TextIOWrapper", mock.MagicMock()
         ) as mock_text_io_wrapper:
             test_module.load_resource("abc:def", encoding="utf-8")
 

demo/features/0160-connection.feature

@@ -13,12 +13,12 @@ Feature: RFC 0160 Aries agent connection functions
 
       @GHA @WalletType_Askar
       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                        | --multitenant                        |
+         | --public-did --mediation --multitenant --log-file | --mediation --multitenant --log-file |
 
       @GHA @WalletType_Askar_AnonCreds
       Examples:

demo/features/0453-issue-credential.feature

@@ -18,7 +18,7 @@ Feature: RFC 0453 Aries agent issue credential
        | --public-did                           |                           | driverslicense | Data_DL_NormalizedValues |
        | --public-did --did-exchange            | --did-exchange            | driverslicense | Data_DL_NormalizedValues |
        | --public-did --mediation               | --mediation               | driverslicense | Data_DL_NormalizedValues |
-       | --public-did --multitenant             | --multitenant             | driverslicense | Data_DL_NormalizedValues |
+       | --public-did --multitenant             | --multitenant --log-file  | driverslicense | Data_DL_NormalizedValues |
 
     @GHA @WalletType_Askar_AnonCreds
     Examples:
@@ -127,11 +127,11 @@ Feature: RFC 0453 Aries agent issue credential
 
     @GHA @WalletType_Askar
     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 | --multitenant             | driverslicense | Data_DL_NormalizedValues |
 
     @GHA @WalletType_Askar_AnonCreds
     Examples:

demo/run_bdd

@@ -21,6 +21,10 @@ fi
 
 for i in "$@"
 do
+  # Demo agent with --multitenant requires the ../log dir to exist and write access to it
+  if [ ! -d "../log" ]; then
+    mkdir ../log && chmod -R uga+rws ../log
+  fi
   if [ ! -z "$SKIP" ]; then
     SKIP=""
     continue
@@ -73,12 +77,9 @@ do
       continue
     ;;
   --timing)
-    if [ ! -d "../logs" ]; then
-      mkdir ../logs && chmod -R uga+rws ../logs
-    fi
-    if [ "$(ls -ld ../logs | grep dr..r..rwx)" == "" ]; then
-      echo "Error: To use the --timing parameter, the directory '../logs' must exist and all users must be able to write to it."
-      echo "For example, to create the directory and then set the permissions use: 'mkdir ../logs; chmod uga+rws ../logs'"
+    if [ "$(ls -ld ../log | grep dr..r..rwx)" == "" ]; then
+      echo "Error: To use the --timing parameter, the directory '../log' must exist and all users must be able to write to it."
+      echo "For example, to create the directory and then set the permissions use: 'mkdir ../log; chmod uga+rws ../log'"
       exit 1
     fi
     continue
@@ -236,6 +237,6 @@ DOCKER=${DOCKER:-docker}
 $DOCKER run --name $AGENT --rm ${DOCKER_OPTS} \
   --network=${DOCKER_NET} \
   -p 0.0.0.0:$AGENT_PORT_RANGE:$AGENT_PORT_RANGE \
-  -v "/$(pwd)/../logs:/home/aries/logs" \
+  -v "/$(pwd)/../log:/home/aries/log" \
   $DOCKER_ENV \
   aries-bdd-image $ARGS

demo/run_demo

@@ -25,6 +25,11 @@ j=1
 for i in "$@"
 do
   ((j++))
+  # Demo agent with --multitenant requires the ../log dir to exist and write access to it
+  if [ ! -d "../log" ]; then
+    mkdir ../log && chmod -R uga+rws ../log
+    DOCKER_VOL="${DOCKER_VOL} -v /$(pwd)/../log:/home/aries/log"
+  fi
   if [ ! -z "$SKIP" ]; then
     SKIP=""
     continue
@@ -77,15 +82,11 @@ do
       continue
     ;;
   --timing)
-    if [ ! -d "../logs" ]; then
-      mkdir ../logs && chmod -R uga+rws ../logs
-    fi
-    if [ "$(ls -ld ../logs | grep dr..r..rwx)" == "" ]; then
-      echo "Error: To use the --timing parameter, the directory '../logs' must exist and all users must be able to write to it."
-      echo "For example, to create the directory and then set the permissions use: 'mkdir ../logs; chmod uga+rws ../logs'"
+    if [ "$(ls -ld ../log | grep dr..r..rwx)" == "" ]; then
+      echo "Error: To use the --timing parameter, the directory '../log' must exist and all users must be able to write to it."
+      echo "For example, to create the directory and then set the permissions use: 'mkdir ../log; chmod uga+rws ../log'"
       exit 1
     fi
-    DOCKER_VOL="${DOCKER_VOL} -v /$(pwd)/../logs:/home/aries/logs"
     continue
   ;;
   --bg)