Make the logging module more configurable and easier to use (#9)

By utilizing the threading local construct we can add the identifiers
at the start of each thread instead and all loggers within that thread
will use the same identifier automatically.
This also removes the need to execute the "get_logger" function in
each thread and requires a lot less logging adapters to be created

Author: t-persson

requirements.txt

@@ -7,3 +7,4 @@ cryptography==3.1
 redis==3.5.3
 eiffellib==1.1.0
 pydantic==1.6
+python-box==5.2.0

setup.cfg

@@ -33,6 +33,7 @@ install_requires =
     pydantic==1.6
     requests==2.24.0
     kubernetes==7.0.1
+    python-box==5.2.0
 
 # Require a specific Python version, e.g. Python 2.7 or >= 3.4
 python_requires = >=3.4

src/etos_lib/logging/default_config.conf

@@ -0,0 +1,5 @@
+logging:
+  stream:
+    loglevel: INFO
+  file:
+    loglevel: DEBUG

src/etos_lib/logging/default_config.yaml

@@ -20,7 +20,7 @@
 class EtosFilter(logging.Filter):  # pylint:disable=too-few-public-methods
     """Filter for adding extra application specific data to log messages."""
 
-    def __init__(self, application, version, environment):
+    def __init__(self, application, version, environment, local):
         """Initialize with a few ETOS application fields.
 
         :param application: Name of application.
@@ -29,10 +29,13 @@ def __init__(self, application, version, environment):
         :type version: str
         :param environment: In which environment is this executing.
         :type environment: str
+        :param local: Thread-local configuration information.
+        :type local: :obj:`threading.local`
         """
         self.application = application
         self.version = version
         self.environment = environment
+        self.local = local
         super().__init__()
 
     def filter(self, record):
@@ -43,9 +46,16 @@ def filter(self, record):
         :return: True
         :rtype: bool
         """
-        if not hasattr(record, "identifier"):
-            record.identifier = "Unknown"
         record.application = self.application
         record.version = self.version
         record.environment = self.environment
+
+        # Add each thread-local attribute to record.
+        for attr in dir(self.local):
+            if attr.startswith("__") and attr.endswith("__"):
+                continue
+            setattr(record, attr, getattr(self.local, attr))
+        if not hasattr(record, "identifier"):
+            record.identifier = "Unknown"
+
         return True

src/etos_lib/logging/filter.py

@@ -17,29 +17,108 @@
 
 Example::
 
+    import logging
     from uuid import uuid4
-    from etos_lib.logging.logger import setup_logging, get_logger
+    from etos_lib.logging.logger import setup_logging, FORMAT_CONFIG
 
+    FORMAT_CONFIG.identifier = str(uuid4())
     setup_logging("myApp", "1.0.0", "production")
-    logger = get_logger(__name__, str(uuid4()))
+    logger = logging.getLogger(__name__)
     logger.info("Hello!")
     >>> [2020-12-16 10:35:00][cb7c8cd9-40a6-4ecc-8321-a1eae6beae35] INFO: Hello!
 
 """
+import sys
 from pathlib import Path
+import threading
 import logging
 import logging.config
+from box import Box
 from etos_lib.logging.filter import EtosFilter
+from etos_lib.logging.formatter import EtosLogFormatter
 from etos_lib.lib.debug import Debug
-from etos_lib.lib.config import Config
 
-DEFAULT_CONFIG = Path(__file__).parent.joinpath("default_config.conf")
+DEFAULT_CONFIG = Path(__file__).parent.joinpath("default_config.yaml")
 DEFAULT_LOG_PATH = Debug().default_log_path
-DEFAULT_LOG_PATH.parent.mkdir(exist_ok=True, parents=True)
+
+FORMAT_CONFIG = threading.local()
+
+
+def setup_file_logging(config, log_filter):
+    """Set up logging to file using the ETOS log formatter.
+
+    Cofiguration file parameters ('file' must exist or no file handler is set up):
+
+        logging:
+          file:
+            # Log level for file logging. Default=DEBUG.
+            loglevel: INFO
+            # Where to store logfile. Default=/home/you/etos/output.log.json
+            logfile: path/to/log/file
+            # Maximum number of files to rotate. Default=10
+            max_files: 5
+            # Maximum number of bytes in each logfile. Default=1048576/1MB
+            max_bytes: 100
+
+    :param config: File logging configuration.
+    :type config: :obj:`Box`
+    :param log_filter: Logfilter to add to file handler.
+    :type log_filter: :obj:`EtosFilter`
+    """
+    loglevel = getattr(logging, config.get("loglevel", "DEBUG"))
+    logfile = Path(config.get("logfile", DEFAULT_LOG_PATH))
+    logfile.parent.mkdir(parents=True, exist_ok=True)
+
+    max_files = config.get("max_files", 10)
+    max_bytes = config.get("max_bytes", 10485760)  # Default is 10 MB
+    root_logger = logging.getLogger()
+
+    file_handler = logging.handlers.RotatingFileHandler(
+        logfile, maxBytes=max_bytes, backupCount=max_files
+    )
+    file_handler.setFormatter(EtosLogFormatter())
+    file_handler.setLevel(loglevel)
+    file_handler.addFilter(log_filter)
+    root_logger.addHandler(file_handler)
+
+
+def setup_stream_logging(config, log_filter):
+    """Set up logging to stdout stream.
+
+    Cofiguration file parameters ('stream' must exist or no stream handler is set up):
+
+        logging:
+          stream:
+            # Log level for stream logging. Default=INFO.
+            loglevel: ERROR
+            # Format to print logs with.
+            # Default: [%(asctime)s][%(identifier)s] %(levelname)s:%(name)s: %(message)s
+            logformat: %(message)s
+            # Dateformat for %(asctime) format. Default: %Y-%m-%d %H:%M:%S
+            dateformat: %Y-%d-%m %H:%M:%S
+
+    :param config: Stream logging configuration.
+    :type config: :obj:`Box`
+    :param log_filter: Logfilter to add to stream handler.
+    :type log_filter: :obj:`EtosFilter`
+    """
+    loglevel = getattr(logging, config.get("loglevel", "INFO"))
+
+    logformat = config.get(
+        "logformat",
+        "[%(asctime)s][%(identifier)s] %(levelname)s:%(name)s: %(message)s"
+    )
+    dateformat = config.get("dateformat", "%Y-%m-%d %H:%M:%S")
+    root_logger = logging.getLogger()
+    stream_handler = logging.StreamHandler(sys.stdout)
+    stream_handler.setFormatter(logging.Formatter(logformat, datefmt=dateformat))
+    stream_handler.setLevel(loglevel)
+    stream_handler.addFilter(log_filter)
+    root_logger.addHandler(stream_handler)
 
 
 def setup_logging(
-    application, version, environment, filename=DEFAULT_CONFIG, output=DEFAULT_LOG_PATH
+    application, version, environment, config_file=DEFAULT_CONFIG
 ):
     """Set up basic logging.
 
@@ -49,27 +128,25 @@ def setup_logging(
     :type version: str
     :param environment: Environment in which this application resides.
     :type environment: str
-    :param filename: Filename of logging configuration.
-    :type filename: str
-    :param output: Output filename for logging to file.
-    :type output: str
+    :param config_file: Filename of logging configuration.
+    :type config_file: str
     """
-    Config().set("log_filter", EtosFilter(application, version, environment))
-    logging.config.fileConfig(filename, defaults={"logfilename": output})
-    root_logger = logging.getLogger()
-    root_logger.addFilter(Config().get("log_filter"))
+    with open(config_file) as yaml_file:
+        config = Box.from_yaml(yaml_file)
+    logging_config = config.logging
 
+    log_filter = EtosFilter(application, version, environment, FORMAT_CONFIG)
 
-def get_logger(name, identifier):
-    """Get a logger adapter with attached identiifer.
+    # Create a default logger which will not propagate messages
+    # to the root logger. This logger will create records for all
+    # messages, but not print them to stdout. Stdout printing
+    # is setup in "setup_stream_logging" if the "stream" key exists
+    # in the configuration file.
+    root_logger = logging.getLogger()
+    root_logger.setLevel(logging.DEBUG)
+    root_logger.propagate = 0
 
-    :param name: Name of logger to get.
-    :type name: str
-    :param identifier: Unique identifier to attach to logger.
-    :type identifier: str
-    :return: LoggerAdapter instance.
-    :rtype: :obj:`logging.LoggerAdapter`
-    """
-    logger = logging.getLogger(name)
-    logger.addFilter(Config().get("log_filter"))
-    return logging.LoggerAdapter(logger, {"identifier": identifier})
+    if logging_config.get("stream"):
+        setup_stream_logging(logging_config.get("stream"), log_filter)
+    if logging_config.get("file"):
+        setup_file_logging(logging_config.get("file"), log_filter)