https://readthedocs.org/projects/reconplogger/badge/?version=stable https://codecov.io/gh/omni-us/reconplogger/branch/main/graph/badge.svg https://badge.fury.io/py/reconplogger.svg https://img.shields.io/badge/contributions-welcome-brightgreen.svg

reconplogger - omni:us python logger

Docs: https://reconplogger.readthedocs.io/ | Source: https://github.com/omni-us/reconplogger/

This repository contains the code of reconplogger, a python package intended to ease the standardization of logging within omni:us. The main design decision of reconplogger is to allow total freedom to reconfigure loggers without hard coding anything.

The package contains essentially the following things:

  • A default logging configuration.

  • A function for loading logging configuration for regular python code.

  • A function for loading logging configuration for flask-based microservices.

  • Root logger configuration via LOGGER_ROOT_HANDLER with independent LOGGER_ROOT_LEVEL control.

  • Singleton logger setup (logger_setup); call reset_configs before reconfiguring.

  • Automatic correlation ID management in Flask services via flask_app_logger_setup.

  • An inheritable class to add a logger property.

  • A context manager to set and get the correlation id.

  • Lower level functions for:

    • Loading logging configuration from any of: config file, environment variable, or default.

    • Replacing the handlers of an existing Logger object.

    • Function to add a file handler to a logger.

How to use

There are two main use cases reconplogger targets. One is for logging in regular generic python code and the second one is logging in microservices. See the two standardizing sections below for a detailed explanation of the two use cases.

Add as requirement

The first step to use reconplogger is adding it as a requirement in the respective package where it will be used. This means adding it in the file pyproject.toml as an item in dependencies or in [project.optional-dependencies] depending on whether reconplogger is intended to be a core or an optional requirement.

Note: It is highly discouraged to develop packages in which requirements are added directly to setup.py or to have an ambiguous requirements.txt file. See the setup.cfg file in the reconplogger source code for reference.

Default logging configuration

A feature that reconplogger provides is the possibility of externally setting the logging configuration without having to change code or implement any parsing of configuration. However, if a logging configuration is not given externally, reconplogger provides a default configuration.

The default configuration defines three handlers, two of which are stream handlers and are set to DEBUG log level. The first handler called plain_handler uses a simple plain text formatter, and the second handler called json_handler as the name suggests outputs in json format, using the logmatic JsonFormatter class. The third handler called null_handler is useful to disable all logging.

For each handler the default configuration defines a corresponding logger: plain_logger, json_logger and null_logger.

Standardizing logging in regular python

One objective of reconplogger is to ease the use of logging and standardize the way it is done across all omni:us python code. The use of reconplogger comes down to calling one function to get the logger object. For regular python code (i.e. not a microservice) the function to use is reconplogger.logger_setup().

The following code snippet illustrates the use:

import reconplogger

# Default plain logger
logger = reconplogger.logger_setup()
logger.info('My log message')

# Json logger
logger = reconplogger.logger_setup('json_logger')
logger.info('My log message in json format')

This function gives you the ability to set the default logger to use (logger_name argument whose default value is plain_logger) and optionally provide a logging config and/or a logging level that overrides the level in the config.

All of these values can be overridden via the LOGGER_CFG, LOGGER_NAME and LOGGER_LEVEL environment variables. When LOGGER_ROOT_HANDLER is in use, the root logger level can be controlled separately via LOGGER_ROOT_LEVEL.

For functions or classes that receive logger object as an argument, it might be desired to set a non-logging default so that it can be called without specifying one. For this reconplogger defines null logger that could be used as follows:

from reconplogger import null_logger

...

def my_func(arg1, arg2, logger=null_logger):

...

Standardizing logging in flask-based microservices

The most important objective of reconplogger is to allow standardization of a structured logging format for all microservices developed. Thus, the logging from all microservices should be configured like explained here. The use is analogous to the previous case, but using the function reconplogger.flask_app_logger_setup() instead, and giving as first argument the flask app object.

Additional to the previous case, this function:

  • Replaces the flask app and werkzeug loggers to use a reconplogger configured one.

  • Add to the logs the correlation_id

  • Add before and after request functions to log request completion in access-log style

  • Patch the requests library forwarding the correlation id in any call to other microservices

What is the correlation ID? In a system build with microservices we need a way to correlate logs coming from different microservices to the same “external” call. For example when a user of our system do a call to the MicroserviceA this could need to retrieve some information from the MicroserviceB, if there is an error and we want to check the logs of the MicroserviceB related to the user call we don’t have a way to correlate them, to solve this we use the correlation id! It is a unique string that is passed in the headers of the REST calls and will be forwarded automatically when we do calls with the library requests. All of this is taken care in the background by this library. If the correlation id its not present in the request headers, it will not be generated. It is up to developers to explicitly create a correlation id.

The usage would be as follows:

import reconplogger
from flask import Flask

...

app = Flask(__name__)

...

logger = reconplogger.flask_app_logger_setup(app, level='DEBUG')

## NOTE: do not change logger beyond this point!

...

## Use logger in code
myclass = MyClass(..., logger=logger)

...

## User logger in a flask request
@app.route('/')
def hello_world():
    logger.info('i like logs')
    correlation_id = reconplogger.get_correlation_id()
    logger.info('correlation id for this request: '+correlation_id)
    return 'Hello, World!'

...

As illustrated in the previous example the get_correlation_id() function can be used to get the correlation id for the current application context. However, there are cases in which it is desired to set the correlation id, instead of getting a randomly generated one. In this case the get_correlation_id() function is used, for example as follows:

@app.route('/')
def hello_world():
    reconplogger.set_correlation_id('my_correlation_id')
    logger.info('i like logs')
    return 'Hello, World!'

An important note is that after configuring the logger, the code should not modify the logger configuration. For example, the logging level should not be modified. Adding an additional handler to the logger is not a problem. This could be desired for example to additionally log to a file.

In the helm values.yaml file of the microservice, the default values for the environment variables should be set as:

LOGGER_CFG:
LOGGER_NAME: json_logger
LOGGER_LEVEL: INFO
LOGGER_ROOT_HANDLER: json_handler
LOGGER_ROOT_LEVEL: INFO

Setting LOGGER_ROOT_HANDLER is the recommended way to ensure that log records from third-party libraries (SQLAlchemy, werkzeug, urllib3, etc.) are also captured and formatted as JSON. See Capturing third-party library logs below for details.

With the json_logger logger, the format of the logs should look something like the following:

{"asctime": "2018-09-05 17:38:38,137", "levelname": "INFO", "filename": "test_formatter.py", "lineno": 5, "message": "Hello world"}
{"asctime": "2018-09-05 17:38:38,137", "levelname": "DEBUG", "filename": "test_formatter.py", "lineno": 9, "message": "Hello world"}
{"asctime": "2018-09-05 17:38:38,137", "levelname": "ERROR", "filename": "test_formatter.py", "lineno": 13, "message": "Hello world"}
{"asctime": "2018-09-05 17:38:38,137", "levelname": "CRITICAL", "filename": "test_formatter.py", "lineno": 17, "message": "Hello world"}
{"asctime": "2018-09-05 17:38:38,137", "levelname": "ERROR", "filename": "test_formatter.py", "lineno": 25, "message": "division by zero"}
{"asctime": "2018-09-05 17:38:38,138", "levelname": "ERROR", "filename": "test_formatter.py", "lineno": 33, "message": "Exception has occurred", "exc_info": "Traceback (most recent call last):\n  File \"reconplogger/tests/test_formatter.py\", line 31, in test_exception_with_trace\n    b = 100 / 0\nZeroDivisionError: division by zero"}
{"asctime": "2018-09-05 17:38:38,138", "levelname": "INFO", "filename": "test_formatter.py", "lineno": 37, "message": "Hello world", "context check": "check"}

{"asctime": "2020-09-02 17:20:16,428", "levelname": "INFO", "filename": "hello.py", "lineno": 12, "message": "i like logs", "correlation_id": "3958f378-5d48-4e1c-b83b-3c6d9f95faec"}
{"asctime": "2020-09-02 17:20:16,428", "levelname": "INFO", "filename": "reconplogger.py", "lineno": 271, "message": "127.0.0.1 GET / HTTP/1.1 200", "correlation_id": "3958f378-5d48-4e1c-b83b-3c6d9f95faec"}

Capturing third-party library logs

By default reconplogger only configures the named logger returned by logger_setup(). Third-party libraries (SQLAlchemy, werkzeug, urllib3, httpx, …) create their own named loggers that propagate records up to Python’s root logger, which reconplogger does not touch unless instructed to.

To capture every log record in the process under the same handler — with no code changes — set the LOGGER_ROOT_HANDLER environment variable to the name of the handler you want to use as the single root handler:

LOGGER_NAME=json_logger
LOGGER_LEVEL=INFO
LOGGER_ROOT_HANDLER=json_handler
LOGGER_ROOT_LEVEL=INFO

When LOGGER_ROOT_HANDLER is set:

  1. The named handler is installed on the root logger.

  2. The root logger’s level is set to LOGGER_ROOT_LEVEL (or the handler’s

    own level if LOGGER_ROOT_LEVEL is absent).

  3. logging.captureWarnings(True) is called so warnings.warn(...) calls are also captured.

  4. The named logger (e.g. json_logger) has its stream handlers removed and

    propagate=True set so records flow to the single root handler without duplicate stream output.

  5. All other named loggers in the config also have their stream handlers

    removed for the same reason, while non-stream handlers such as file handlers remain attached.

  6. Subsequent calls to logger_setup() return the same primary logger (singleton behaviour).

  7. To apply a new configuration after the first call, run

    reset_configs() and then call logger_setup() again.

flask_app_logger_setup manages correlation ID handling internally for Flask, including request lifecycle setup and response header propagation.

Use of the logger object

The logger objects returned by the setup functions are normal python logging.Logger objects, so all the standard logging functionalities should be used. Please refer to the logging package documentation for details.

A couple of logging features that should be very commonly used are the following. To add additional structured information to a log, the extra argument should be used. A simple example could be:

logger.info('Successfully processed document', extra={'uuid': uuid})

When an exception occurs the exc_info=True argument should be used, for example:

try:
    ...
except:
    logger.critical('Failed to run task', exc_info=True)

Adding a file handler

In some circumstances it is desired to add to a logger a file handler so that the logging messages are also saved to a file. This normally requires at least three lines of code, thus to simplify things reconplogger provides the reconplogger.add_file_handler() function to do the same with a single line of code. The use is quite straightforward as:

reconplogger.add_file_handler(logger, '/path/to/log/file.log')

Adding a logging property

When implementing classes it is common to add logging support to it. For this an inheritable class RLoggerProperty is included in reconplogger to add an rlogger property to easily set and get the reconplogger logger. An example of use is the following:

from reconplogger import RLoggerProperty

class MyClass(RLoggerProperty):
    def __init__(self, **kwargs):
        super().__init__(**kwargs)
    def my_method(self):
        self.rlogger.error('my_method was called')

MyClass(rlogger=True).my_method()

Overriding logging configuration

An important feature of reconplogger is that the logging configuration of apps that use it can be easily changed via the environment variables. First set the environment variables with the desired logging configuration and logger name:

export LOGGER_NAME="example_logger"

export LOGGER_CFG='{
    "version": 1,
    "formatters": {
        "verbose": {
            "format": "%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s"
        }
    },
    "handlers": {
        "console":{
            "level":"DEBUG",
            "class":"logging.StreamHandler",
            "formatter": "verbose"
        }
    },
    "loggers": {
        "example_logger": {
            "handlers": ["console"],
            "level": "ERROR",
        }
    }
}'

Then, in the python code the logger would be used as follows:

>>> import reconplogger
>>> logger = reconplogger.logger_setup()
>>> logger.error('My error message')
ERROR 2019-10-18 14:45:22,629 <stdin> 16876 139918773925696 My error message

Low level functions

Loading configuration

The reconplogger.load_config() function allows loading of a python logging configuration. The format config can be either json or yaml. The loading of configuration can be from a file (giving its path), from an environment variable (giving the variable name), a raw configuration string, or loading the default configuration that comes with reconplogger. See below examples of loading for each of the cases:

import reconplogger

## Load from config file
reconplogger.load_config('/path/to/config.yaml')

## Load from environment variable
reconplogger.load_config('LOGGER_CFG')

## Load default config
reconplogger.load_config('reconplogger_default_cfg')

Replacing logger handlers

In some cases it might be needed to replace the handlers of some already existing logger. For this reconplogger provides the reconplogger.replace_logger_handlers() function. To use it, simply provide the logger in which to replace the handlers and the logger from where to get the handlers. The procedure would be as follows:

import reconplogger

logger = reconplogger.logger_setup('json_logger')
reconplogger.replace_logger_handlers('some_logger_name', logger)

Contributing

Contributions to this package are very welcome. If you intend to work with the source code, note that this project does not include any requirements.txt file. This is by intention. To make it very clear what are the requirements for different use cases, all the requirements of the project are stored in the file pyproject.toml. The basic runtime requirements are defined in dependencies. Requirements for optional features are stored in [project.optional-dependencies]. Also in the same section there are requirements for testing, development and documentation building: test, dev and doc.

The recommended way to work with the source code is the following. First clone the repository, then create a virtual environment, activate it and finally install the development requirements. More precisely the steps would be:

git clone https://github.com/omni-us/reconplogger.git
cd reconplogger
virtualenv -p python3 venv
. venv/bin/activate

The crucial step is installing the requirements which would be done by running:

pip3 install --editable ".[dev]"

Running the unit tests can be done either using using tox or pytest. The unit tests are also installed with the package, thus can be used to in a production system.

tox                             # Run tests using tox
pytest --cov --cov-report=html  # Run tests and generate coverage report
python3 -m reconplogger_tests   # Run tests for installed package

When writing tests that call logger_setup(), call reset_configs() in setUp / tearDown to restore a clean state between test cases:

import reconplogger

class MyTest(unittest.TestCase):
    def setUp(self):
        reconplogger.reset_configs()

Pull requests

  • To contribute it is required to create and push to a new branch and issue a pull request.

  • A pull request will only be accepted if:

    • pre-commit hooks have been applied.

    • All unit tests run successfully.

    • New code has docstrings and gets included in the html documentation.

  • When developing, please run pre-commit install so that the hooks get run when you commit and push.

Using bump version

Only the maintainer of this repo should bump versions and this should be done only on the main branch. To bump the version it is required to use the bumpversion command that should already be installed if pip3 install --editable .[dev,maintainer] was run.

bumpversion major/minor/patch

Push the tags to the repository as well.

git push; git push --tags

When the version tags are pushed, the workflows will automatically build the wheel file, test it and if successful, push the package to pypi.

Documentation Contents

Indices and tables