The Dev World – Sergio Lema

In this article I will show how to use the Logging library in Python. I will show how to configure the Logging library for many Handlers, Formatters and Filters.

Content

• The Logging Library
• Components
• Use Case 1: Stream Logs to a file
• Use Case 2: Send Logs to a remote server

If you’re looking for more details, watch this video.

All the code of this article is available in the following repository.

The Logging Library

To start using the logging library in Python, just one line is necessary.

import logging
logging.info("This is a log")

That’s it, I just need to use the logging module everywhere I want to log something and nothing more. But the logging library can do a lot more for me.

There are five log levels.

• Critical for unrecoverable errors which lead to a shutdown.
• Error for unrecoverable errors but the applications can continue.
• Warning for a user misuse of the application or for a degraded behavior.
• Info to trace a normal usage of the application.
• And debug to obtain a detailed information for debug purpose.

With no configuration that’s all I can do. And here is the printed log.

INFO:root:This is a log

I will of course have a formatted log record with the module and the log level. For most of the cases this can be enough. But…

But what if I need to store my logs in some files? What if I generate too many files and I need to backup the files? Or to send the logs to external servers to aggregate with multiple applications? Or to send an email to the development team when some specific error appears?

Components

There are three main components in the logging library: handlers, filters and formatters. The handlers tell me how a log will be handled: printed into a file, sent via http, send via email or more. The filters will specify which log will reach each handler. And the formatter will pretty print a log.

Within the logging library, each line of log comes into an object called LogRecord. Each LogRecord can have associated a list of handlers depending on the logger name. Then, the LogRecord will be filtered depending on the log level and some custom filters. Finally the LogRecord reaches the formatting associated to the handler.

This gives me a lot of possibilities. Let’s see two scenarios. In the first one, a typical one, I want to stream my logs into a file, but the file must be saved back into separated files every day. And in the second scenario, I want the application to send all the logs to an external server via http requests.

Use case 1: Stream Logs to a file

There are multiple ways to configure the loggers. I will use a dictionary because it’s the most recent way and it accepts more customizations.

dictConfig(Config.LOGGING)

class Config:

    LOGGING = {
        "version": 1,
        "disable_existing_loggers": False,
    }

At the moment of the video, only the first version is accepted (line 4). And the other option at line 5 is to maintain all the implicit loggers. Let’s start configuring the logger.

class Config:

    LOGGING = {
        "version": 1,
        "disable_existing_loggers": False,
        "filters": {

        },
        "formatters": {

        },
        "handlers": {

        },
        "loggers": {

        },
    }

At line 6 we’ll be located the filters, at line 9 the formatters and at line 12 the handlers. In the last part at line 15 I assigned to each logger, to each module, the handler to be used.

        "filters": {
            "backend_filter": {
                "backend_module": "backend",
            }
        },

This way, I only filtered the logs coming from the backend module. This can be very useful when applying an expensive handler to the logs, as sending an email. I may just want to send an email with logs from the error module or from the critical module.

        "formatters": {
            "standard": {"format": "%(asctime)s %(name)-12s %(levelname)-8s %(message)s"},
            "compact": {"format": "%(asctime)s %(message)s"},
        },

I can declare multiple formatters, then, in the handlers, I will choose which one to use. To configure a formatter I have about 20 parameters to use (asctime, created, filename, funcName, levelname…). And finally, the numbers -12s and -8s allows me to create some columns of characters. This means that the value of the name attribute won’t go over 12 characters. The same of levelname, it won’t go over 8 characters. This ensures me that the next parameter is always at the same column in the screen, which is easier to read.

        "handlers": {
            "console": {
                "class": "logging.StreamHandler",
                "level": "DEBUG",
                "formatter": "standard",
                "stream": "ext://sys.stdout",
                "filters": ["backend_filter"],
            },
            "file": {
                "class": "logging.handlers.TimedRotatingFileHandler",
                "level": "DEBUG",
                "filename": "backend.log",
                "when": "D",
                "interval": 1,
                "formatter": "standard",
            },
        },

I’ve configured two handlers. The first one, console, is the most used, just stream the logs to the console. I indicate until which log level the handler will print and which format it will use. The second handler, file, will save the logs into files, into time rotating files. This means that the file will rotate into a backup. This will be done depending on the units, D (day), and the interval, 1.

        "loggers": {
            "": {"handlers": ["console", "file"], "level": "DEBUG"},
            "flask": {"level": "WARNING"},
            "sqlalchemy": {"level": "WARNING"},
            "werkzeug": {"level": "WARNING"},
        },

Finally, I indicate which handler and log level will use each logger. The empty key is the root logger, the parent logger. All the loggers will inherit from it. Then, for some external loggers, as Flask, SQLAlchemy, or Werkzeug, I only want warning or higher logs.

Use Case 2: Send Logs to a remote server

This was my first scenario: saving my logs into files. Let’s go now with my second scenario: streaming my logs to an external server.

        "handlers": {
            "console": {
                "class": "logging.StreamHandler",
                "level": "DEBUG",
                "formatter": "standard",
                "stream": "ext://sys.stdout",
                "filters": ["backend_filter"],
            },
            "http": {
                "class": "logging.handlers.HTTPHandler",
                "host": "localhost:5001",
                "url": "/log",
                "method": "POST",
            },
            "z_buffer": {
                "class": "logging.handlers.MemoryHandler",
                "capacity": 3,
                "target": "http",
            },
        },

I maintain the console handler. It’s always good to have this one for debug purpose. Then, I’ve created an http handler. In this handler will be located the HTTP server where will be sent the logs with the combination of the host and the URL. I will use the POST method to send the logs to the server. I have some other configurations as the credentials and the ssl certificate. If I indicate a GET method, the LogRecord will send all the values in a query string. Using the post method, they will be sent using the application/x-www-form-urlencoded content type.

And I have another handler, the z_buffer. The HTTP requests may take some time to be sent. If my application generates a lot of logs and the http requests are not fast enough, the application will slow down progressively, maybe saturating the network. For that, I’ve created a buffer, a memory buffer, which accumulates a given number of log records, capacity, and send them to the specified handler, the http handler. This creates asynchronous requests. But why this Z in the name? The logging library isn’t smart enough to detect that the buffer handler depends on the http handler. The logging library just sorts them alphabetically and builds them.

        "loggers": {
            "": {"handlers": ["console", "z_buffer"], "level": "DEBUG"},
            "flask": {"level": "WARNING"},
            "sqlalchemy": {"level": "WARNING"},
            "werkzeug": {"level": "WARNING"},
        },

Finally, I indicate which handler to use. The http handler will be used by the z_buffer.

Conclusion

• To add a logger into a module, just use this declaration: logging.info(“This is a log”).
• By default, the logging library already formats my logs adding the module name and the level. Nevertheless, only the console handler is available by default.
• To configure the loggers, I’ve used the dictionary configuration, dictConfig.
• I can configure filters to indicate which LogRecord will be handled.
• I can configure multiple formatters with multiple fields of the LogRecord.
• Then indicate at the handler level which formatter to use.
• Then, I can configure multiple handlers: console, memory buffer, http handler, queues handlers, email handlers, file handlers, etc.
• And finally, choose which handler will use each logger.

References

• https://docs.python.org/3/library/logging.html
• https://docs.python.org/3/library/logging.html#logrecord-attributes

Repository