Python Logging: a Practical Guide

For most of junior developers, they integrate a team with a project already on track with core parts of the project already set. Thus, they don’t have many opportunities in the professional field to practice or elaborate over the matter.

Among those core parts, there is logging. So I was pretty excited to finally have the opportunities to carry on a personal project big enough to have a legit use of logging.

Of course the first thing I did was to read, a lot. And I noticed that most of content on internet dealing with logging implementation miss the point. They are not questioning the right aspects :

• implementation, how to efficiently implement a logger ;
• structure, how to structure logs easy to read ;

This article discusses those questions and propose answers to them.

How to efficiently implement a logger ?

A logger properly implemented required at minimum 2 things : a handler and a formatter.

The illustration below doesn’t work but provide a general idea :

formatter = logging.Formatter(
  fmt = '%(asctime)s - %(message)s'
)

handler = logging.StreamHandler()
handler.setFormatter(formatter)

logger = logging.getLogger(__name__)
logger.addHandler(handler)

The purpose of this part is to introduce an elegant and simple way to improve the implementation.

The structure of loggers

The logging library organizes loggers with a hierarchy like a tree structure. At the highest level, there is root logger. Root logger is called when none loggers exist or has not been implemented properly.

Root logger is the last logger able to handle a log.

This behaviour is controlled by the attribute propagate which provides an interesting note :

If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger — if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

The configuration of loggers

There are 3 ways to configure loggers :

• a config file ;
• a dictionnary ;
• in code ;

The last one is my first choice because it is the one providing the more liberty over configuration. And I did point out a very specific configuration : the basicConfig. It is the configuration for the root logger. I believe you know where this is leading.

A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

Not only this is simple, but also elegant. As it enables to standardize the output of every loggers in the application. Moreover, the use of loggers can be as trivial as this :

# a python module in an application

# a python module with an instance of logger with basicConfig() attributes
from utils.logging import logger

logger.info('it works and is fully configured')

I can feel in some readers concerns or fears, well stated on internet and summarized here :

The default logger is accessible and configurable through module-level methods on the logging module (such as logging.info(), logging.basicConfig()). However, it is generally considered a bad idea to log in this manner due to a number of reasons:

1. Namespace collisions: If multiple modules in your application use the root logger, you risk having messages from different modules logged under the same name, which can make it more difficult to understand where log messages are coming from.
2. Lack of control: When using the root logger, it can be difficult to control the log level for different aspects of your application. This can lead to logging too much information or not enough information, depending on your needs.
3. Loss of context: Log messages generated by the root logger may not contain enough information to provide context about where the log message came from, which can make it difficult to determine the source of issues in your application.

In the next part, I will demonstrate in a pedagogic way that my approach can adress pretty well those 3 problems.

How to properly configure loggers ?

Before that, why even bothering configure them ?

What are logs used for ? Display information to the developers who are developing features for the application or to the users who are interacting with the application.

This is not a small matter, there is no point in logging informations if you can’t read them. So it is important to adress the readability of logs.

The readability of any texts takes into account :

• the behaviour of the reader ;
• the human perception of sight ;
• the rules of the language (punctuation) ;

The behaviour of the reader

Read a terminal is a skill on its own : it is a cold ambient with multiples, hundreds of lines passing on the terminal at some time an absurd speed. Obviously, finding a specific information in this context appears like a challenge. Fortunately, the human specie can cope with its own assets.

The human perception of sight

Without diving, not even a toe, onto the Gestalt theory, we are able to associate shapes relativaly equal together and “create sense” in what we see. That’s the phenomen that helps developer to browse among a huge json file and manage to find the information. The more symmetrical the shapes, the easier it is to read.

The rules of the language (punctuation)

You are reading this paragraph right now. And without knowing you, I would bet that you appreciate very much the attention paid to my english, but also the punctuation. It separates ideas, structure sentences, add more senses to words. Logs are not an exception.

Configuration best practices

Time formatting

The time format provided by default by the logging library has the right temporal precision. But it separates seconds and milliseconds with a comma instead of a dot. Although small, this is a friction that make the reading harder.

The best way to change it is to format date to seconds, then add milliseconds thanks to the %(msecs)s attribute, truncated to 3 digits so that the readability is improved.

Levelname

Levelname is also an essential field to log. But they are not of same size. Fortunately, it is possible to create spaces around fields. This feature combined with punctuation [ ] provides an equivalent frame for every levelname.

f-string style instead of % style

This is a matter of preference, but I like the control provided by the more recent feature f-string to manage spaces around fields. Some of those features are detailed in this article.

In the current stage, a minimal configuration following best practices to improve readability has been set. But we do not have any handlers attached yet to this configuration.

The 3 main handlers : console, log file and json file

There are 3 main outputs for logs :

• the console, the closest a human can be to a program ;
• log files, easier to read and manipulate than console logs ;
• json files, not meant to be read but for log archiving ;

Console and log files handlers for daily coding

Regarding console, there is not much to change since the format is already satisfying. But it is possible to add another layer of information to ease the readability of logs : colours.

When a developer is looking for an error among hundreds of line of logs, the common behaviour is to scroll as fast as possible to find it. The actions taken earlier in the demonstration ease the search. But looking specifically for red lines or bold font is a nice adding.

colorlog is one of those libraries that provide an easy and customizable way to color logs. I think a screenshot speaks more than words :

Unfortunately, as colours are under the hood materialized with ansi escape code, the choices are limited to black, red, green, yellow, blue, purple, cyan and white.

As for log files, the handler is quite easier to craft :

Json files handler for archiving

Most of solution for log archiving are fond with structured format and json is a very spread one. Archiving logs will bring a technical challenge : when a developer is interacting with a console, a context is present : the name of the app, the task to accomplish, the information to look for, etc…

This context no longer exist when logs are consulted from the archives. So the information logged specifically for the json format needs to be enriched.

Among the available choices for json formatting, I chose python-json-logger for its implementation feeling more natural and close to logging library than the others.

Unfortunately formatting logs into json is a process that leads off the beaten track, a bit complicated and poorly documented. Let’s break it down piece by piece.

Creation of the formatter

The library put to use a JsonFormatter. But it is not usable as it is.

{"asctime": "2023-10-30 00:58:04", "msecs": 51.0, "levelname": "DEBUG", "message": "debug message : \u342c", "module": "logger", "funcName": "<module>"}
{"asctime": "2023-10-30 00:58:04", "msecs": 52.0, "levelname": "INFO", "message": "info message", "module": "logger", "funcName": "<module>"}
{"asctime": "2023-10-30 00:58:04", "msecs": 53.0, "levelname": "WARNING", "message": "warn message", "module": "logger", "funcName": "<module>"}
{"asctime": "2023-10-30 00:58:04", "msecs": 53.0, "levelname": "ERROR", "message": "error message", "module": "logger", "funcName": "<module>"}
{"asctime": "2023-10-30 00:58:04", "msecs": 53.0, "levelname": "CRITICAL", "message": "critical message", "module": "logger", "funcName": "<module>"}

On this sample, there are 4 problems :

• the datetime format is not good and split into 2 different fields ;
• mecs field is of type float and not systematically on 3 digits ;
• 㐬 is encoded in bytes ;
• source of log is now split into 2 different fields ;

The good practice is to create a CustomJsonFormatter inheriting from JsonFormatter. Doing so allows us to override the add_fields method. While this field is meant to add fields and enrich information, it also is the perfect location to manipulate dict object used to create the json.

class CustomJsonFormatter(jsonlogger.JsonFormatter):

    def add_fields(self, log_record, record, message_dict):
        super(CustomJsonFormatter, self).add_fields(log_record, record, message_dict)
        log_record['asctime'] = f"{log_record['asctime']}.{int(log_record['msecs']):03d}"
        del log_record['msecs']

        log_record['source'] = f"{log_record['module']}.{log_record['funcName']}"
        del log_record['module']
        del log_record['funcName']

        log_record['service'] = 'app'

json_file_handler = logging.FileHandler(
    filename = 'logs.json',
    encoding = 'utf-8'
)
json_file_handler.setFormatter(
    CustomJsonFormatter(
        fmt = '%(asctime)s %(msecs)s %(levelname)s %(message)s %(module)s %(funcName)s',
        datefmt = '%Y-%m-%d %H:%M:%S',
        style = '%'
    )
)

{"asctime": "2023-10-30 01:07:04.095", "levelname": "DEBUG", "message": "debug message : \u342c", "source": "logger.<module>", "service": "app"}
{"asctime": "2023-10-30 01:07:04.095", "levelname": "INFO", "message": "info message", "source": "logger.<module>", "service": "app"}
{"asctime": "2023-10-30 01:07:04.096", "levelname": "WARNING", "message": "warn message", "source": "logger.<module>", "service": "app"}
{"asctime": "2023-10-30 01:07:04.096", "levelname": "ERROR", "message": "error message", "source": "logger.<module>", "service": "app"}
{"asctime": "2023-10-30 01:07:04.096", "levelname": "CRITICAL", "message": "critical message", "source": "logger.<module>", "service": "app"}

To explain what happened under the hood :

• the json_handler encountered a log and thus created a LogRecord instance following the given format by the formatter attached to it ;
• the log record is altered within add_fields() method. Since the format specified in fmt is only relevant for the creation of the LogRecord, it is possible to delete safely keys of log_record ;
• once the log record processed, it is output ;

Thanks to the new CustomJsonFormatter, 3 problems out of 4 were handled. But 㐬 is still encoded. Fortunately, the JsonFormatter also accepts as parameter a json encoder ; which is pretty convenient !

A json encoder is the part of json that encodes non-ascii characters into bytes with the parameter ensure_ascii set to True by default. If ensure_ascii is set to False, the json encoder ignores the encoding and leaves the character as it is.

class CustomJSONEncoder(json.JSONEncoder):
    def __init__(self, ensure_ascii, *args, **kwargs):
        super().__init__(ensure_ascii = False, *args, **kwargs)

json_file_handler = logging.FileHandler(
    filename = 'logs.json',
    encoding = 'utf-8'
)
json_file_handler.setFormatter(
    CustomJsonFormatter(
        fmt = '%(asctime)s %(msecs)s %(levelname)s %(message)s %(module)s %(funcName)s',
        datefmt = '%Y-%m-%d %H:%M:%S',
        style = '%',
        json_encoder = CustomJSONEncoder
    )
)

{"asctime": "2023-10-30 01:21:27.647", "levelname": "DEBUG", "message": "debug message : 㐬", "source": "logger.<module>", "service": "app"}

Now that loggers are properly configured with handlers and formatters set, it is time to assess the resilient of my design.

Setting different level of call for files

The behaviour of loggers when processing a log

While most of loggers value of configuration in handler or formatter are static, the behaviour of a logger might differ depending on the level of call.

logger = logging.getLogger()

logger.info('this is level of call info')
logger.debug('this is level of call debug')

The behaviour is well illustrated on this diagram from logging :

Illustration of a logger behaviour when encountering a log

Notice on the bottom-left the propagate behaviour.

If you ever encounter the issue of level conflict between a logger and its handler, watch the diagram above.

The technical challenge with one logger

Given the following environment :

I want logs from dep.py of level WARNING and those from app.py of level INFO.

How to handle logs from third-party libraries

Let’s import requests to send the value created somewhere.

There is a debug line emitted by requests when trying to send the value throught the url. As mentionned by Viney Sajip, one of the mainainer of the library logging, it is possible to manage the level of third party-libraries :

Find out the names of the top-level loggers for your third-party libraries from their documentation or source code (e.g. might be asyncua, tensorflow) and then set the level of those loggers to suit your need. Use level logging.CRITICAL + 1 to completely silence them (assuming they just use the standard logging levels).

Bonus : this is great, yet I want children

If you’re really into the “one module one logger” approach, illustrated again by Viney Sajip on this stackoverflow topic, mine is slightly different.

You can also notice the behaviour is different too : the first approach with one logger set level of call on files while this approach set level of call on modules. As a result, the log called in app.py that output “value <x> created !” is silent.

Keep also in mind that those loggers aren’t free, the more loggers the more resources are used. If there is one logger - or even more - per module, it might be impactful on the overall performance of the application. I just hope the granularity on informations are worth the price for your use case.

Conclusion

Even though this way of configuring logging hasn’t been exposed to a professional environment yet, I believe this is a pretty good start for any application. If there are any flaws or remarks, they are always welcome in comments.

In Plain English

Thank you for being a part of our community! Before you go:

• Be sure to clap and follow the writer! 👏
• You can find even more content at PlainEnglish.io 🚀
• Sign up for our free weekly newsletter. 🗞️
• Follow us: Twitter(X), LinkedIn, YouTube, Discord.
• Check out our other platforms: Stackademic, CoFeed, Venture.