Python Logging

Part 1: Why do We Need logging?

Using logging, you can:

1. Control message level to log only required ones
2. Control where to show or save the logs
3. Control how to format the logs with built-in message templates
4. Know which module the messages is coming from

Part 2: How to Configure Log Files?

Each log handler has 2 important fields:

• A formatter which adds context information to a log.
• A log level that filters out logs whose levels are inferior. So a log handler with the INFO level will not handle DEBUG logs.

Log Message Format

The printed log messages follow the default format: {LEVEL}:{LOGGER}:{MESSAGE}.

import logging
logging.basicConfig(level=logging.INFO, format='%(asctime)s :: %(levelname)s :: %(message)s')
logging.info("Just like that!")
#> 2019-02-17 11:40:38,254 :: INFO :: Just like that!

Log Level

1. DEBUG: Detailed information, for diagnosing problems. Value=10.
2. INFO: Confirm things are working as expected. Value=20.
3. WARNING: Something unexpected happened, or indicative of some problem. But the software is still working as expected. Value=30. (default)
4. ERROR: More serious problem, the software is not able to perform some function. Value=40
5. CRITICAL: A serious error, the program itself may be unable to continue running. Value=50

import logging
logging.basicConfig(level=logging.INFO) 
logging.info("hello the world")

Part 3: Root Logger: Should We Use it?

A logger is unique by name, meaning that if a logger with the name “toto” has been created, the consequent calls of logging.getLogger("toto") will return the same object:

assert id(logging.getLogger("toto")) == id(logging.getLogger("toto"))

As you might have guessed, loggers have a hierarchy. On top of the hierarchy is the root logger, which can be accessed via logging.root. This logger is called when methods like logging.debug() is used. By default, the root log level is WARN, so every log with lower level (for example via logging.info("info")) will be ignored. Another particularity of the root logger is that its default handler will be created the first time a log with a level greater than WARN is logged. Using the root logger directly or indirectly via methods like logging.debug() is generally not recommended.

• Configure the root logger but never use it in your code — e.g., never call a function like logging.info(), which actually calls the root logger behind the scene. If you want to catch error messages from libraries you use, make sure to configure the root logger to write to a file, for example, to make the debugging easier. By default, the root logger only outputs to stderr, so the log can get lost easily.
• To use the logging, make sure to create a new logger by using logging.getLogger(logger name). I usually use __name__ as the logger name, but anything can be used, as long as it is consistent. To add more handlers, I usually have a method that returns a logger

Using root logger, however, has proved to be the most convenient choice for me. I have tried to use logging.getLogger(logger name). For me it makes sense if your struct the project in their way.

Part 4: Handlers

The list of handlers that a log will be sent to when it arrives to a logger. This allows a flexible log handling — for example, you can have a file log handler that logs all DEBUG logs and an email log handler that will only be used for CRITICAL logs. In this regard, the logger-handler relationship is similar to a publisher-consumer one: A log will be broadcast to all handlers once it passes the logger level check.

A FileHandler is used to make your custom logger to log in to a different file. Likewise, a Formatter is used to change the format of your logged messages.

import logging

# Gets or creates a logger
logger = logging.getLogger(__name__)  

# set log level
logger.setLevel(logging.WARNING)

# define file handler and set formatter
file_handler = logging.FileHandler('logfile.log')
formatter    = logging.Formatter('%(asctime)s : %(levelname)s : %(name)s : %(message)s')
file_handler.setFormatter(formatter)

# add file handler to logger
logger.addHandler(file_handler)

StreamHandler will send output to the console. File handlers send info to an output file. The most dynamic handlers are the QueueHandler and QueueListener, but more on those later.

It is possible to set different handlers at different levels (debug, warning, error…), but we must set the logger’s level to the “lowest”, see How to set different levels for different python log handlers

Part 5: Trace Exception

Besides ‘debug‘, ‘info‘, ‘warning‘, ‘error‘, and ‘critical‘ messages, you can log exceptions that will include any associated traceback information.

With logger.exception, you can log traceback information should the code encounter any error. logger.exception will log the message provided in its arguments as well as the error message traceback info.

import logging

# Create or get the logger
logger = logging.getLogger(__name__)  

# set log level
logger.setLevel(logging.INFO)

def divide(x, y):
    try:
        out = x / y
    except ZeroDivisionError:
        logger.exception("Division by zero problem")
    else:
        return out

# Logs
logger.error("Divide {x} / {y} = {c}".format(x=10, y=0, c=divide(10,0)))

#> ERROR:__main__:Division by zero problem
#> Traceback (most recent call last):
#>   File "<ipython-input-16-a010a44fdc0a>", line 12, in divide
#>     out = x / y
#> ZeroDivisionError: division by zero
#> ERROR:__main__:None

Part 6: Logging Enhancement

madzak/python-json-logger

    import logging
    from pythonjsonlogger import jsonlogger

    logger = logging.getLogger()

    logHandler = logging.StreamHandler()
    formatter = jsonlogger.JsonFormatter()
    logHandler.setFormatter(formatter)
    logger.addHandler(logHandler)

Reference

Blogs

• Python Logging — Simplest Guide with Full Code and Examples
• Python Logging: An In-Depth Tutorial
• Power-Up Your Python Logging

Codes

• log.py