[SGHLT]s weblog
computer science without borders
[SGHLT]s weblog

Remove visual noise of logging code with python decorators

Share Tweet Share

In both simple and advanced python applications logging often has a bad influence on the appearance of your code. Logging artifacts are either constantly bloating your code or not present at all. Here is one simple approach to have both logging and sinker-code-free business logic using python decorators and the logdecorator library.

The Problem

Error handling [Logging...] (editor's note) is important, but if it obscures logic, it’s wrong.”

― Robert C. Martin, Clean Code: A Handbook of Agile Software Craftsmanship

First of all, what's wrong with logging anyway? The intuitive way of logging is to put it right before or right after an action. Because what you want a future reader to inform about is either that an action has been taken or is about to be taken. This will lead to logging code constantly downgrading your business logic and minimizing its maintainability.

The reason for that is that log statements does not belong to your business logic but must live near it. As an example I introduce to you a function which downloads a file from the web and saves it to the disk:

import requests

class DownloadFailedError(Exception):
    pass


def download(url):
    response = requests.get(url)

    if response.status_code != 200:
    raise DownloadFailedError

    file_name = url.split("/")[-1]
    file_name = file_name or "index.html"

    with open(file_name, "wb") as f:
    f.write(response.content)

What the above function does is pretty simple:

  1. Download some content from a given url
  2. If the response status is not positive (200) the function will raise an exception
  3. Extract the file name from the url; if it has a trailing slash use index.html
  4. Save the content into an actual file

So the truth is: the code above is more or less the business logic which is required to download some content into a file. Period. Logging does not belong to it and is not meant to be by definition.

Nevertheless the code lacks some logging. So leaving it as it is won't be an option. But if we naively add some logging code, we will probably end up with something as ugly as the following:

import requests
import logging

logger = logging.getLogger(__name__)


class DownloadFailedError(Exception):
    pass


def download(url):
    logger.debug("Starting to download {:s}".format(url))
    response = requests.get(url)

    if response.status_code != 200:
        logger.error("Download was not successful due to response status {:d}"
                 .format(response.status))
        raise DownloadFailedError

    filename = url.split("/")[-1]
    filename = filename or "index.html"
    logger.debug("Generated filename '{:s}' from url '{:s}'".format(filename, url))

    logger.debug("Writing downloaded content into file")
    with open(filename, "wb") as f:
        f.write(response.content)
    logger.info("Downloading of '{:s}' into file '{:s}' was successful"
                .format(url, filename))

The code has now approximately doubled its size and reading this is just a pain in the neck. To understand the underlying business logic your brain has to repeatedly check if a line is a log statement and eventually skip it. There is so much visual noise that our initially simple function has become much more complex without providing any uplift on a logical point of view.

Of course we can split the code into smaller pieces, but it's pretty obvious that this will not solve our underlying problem: the logging code will still feel like a foreign object.

The solution - Decorators for the rescue

Since logging code has to live near your business logic, not within it, we need a method to achive exactly that. In the past, python's decorators did a great job in preparing such friendly coexistence of separate intentions. Take pyramid's view_config decorator, django's auth decorators or python's lru_cache decorator as examples.

A simple debug decorator could look like the following:

import logging

logger = logging.getLogger()


def debug(fn):

    def wrapper(*args, **kwargs):
        logger.debug("Entering {:s}...".format(fn.__name__))
        result = fn(*args, **kwargs)
        logger.debug("Finished {:s}.".format(fn.__name__))
        return result

    return wrapper

We could now decorate our download function and get two lines of code as removal candidates, which already starts to clean up the code.

@debug
def download(url):
    response = requests.get(url)

    if response.status_code != 200:
        logger.error("Download was not successful due to response status {:d}"
                     .format(response.status_code))
        raise DownloadFailedError

    filename = url.split("/")[-1]
    filename = filename or "index.html"
    logger.debug("Generated filename '{:s}' from url '{:s}'".format(filename, url))

    logger.debug("Writing downloaded content into file")
    with open(filename, "wb") as f:
        f.write(response.content)

Since our debug decorator only traces entering and exiting a function we have to move code out of the download function into a separate subroutine.

@debug
def url_to_filename(url):
    filename = url.split("/")[-1]
    return filename or "index.html"


@debug
def download(url):
    response = requests.get(url)

    if response.status_code != 200:
        logger.error("Download was not successful due to response status {:d}"
                     .format(response.status))
        raise DownloadFailedError

    filename = url_to_filename(url)

    logger.debug("Writing downloaded content into file")
    with open(filename, "wb") as f:
        f.write(response.content)

The download function did not only shrink nearly to its initial size we were also forced to clean up the code in another sense, namely the separation of the url_to_filename logic. Additionaly we now have an extra line of logging which we skipped due to lazyness in the first place.

I hope you start getting a feeling what i am about to make clear: Moving your logging logic into decorators will lead to way more readable code. But there are still some things left to do:

  • Log into different logging levels
  • A way for customizing logging messages
  • Control when something is logged

logdecorators

While it shouldn't be a great deal to implement those tasks yourself and from then on having a set of great logging decorators, it might seem practical to use them in more than only one python project. For that reason I want to introduce you to the logging library logdecorator, which is also available on PyPi.

logdecorator provides three different built-in decorators:

  • log_on_start
  • log_on_end
  • log_on_error

whose behaviour corresponds to their names. Each of these decorators takes the following arguments:

log_level

The log level at which the message should be send

message

The message to log

on_exceptions (optional)

A list containing exception classes which should get caught and trigger the logging of the log_on_error decorator.

Default: tuple() (No exceptions will get caught)

logger (optional)

An alternative logger object. If no logger is given logdecorator creates a logger object with the name of the module the decorated function is in (decorated_function.__module__)

Default: Creates a new logger with the name decorated_function.__module__

reraise (optional)

Controls if caught exceptions should get reraised after logging

Default: False

result_format_variable (optional)

The variable name one can use in the message to reference the result of the decorated function e.g. @log_on_end(DEBUG, "Result was: {result!r}")

Default: "result"

exception_format_variable (optional)

The variable name one can use in the message to reference the caught exception raised in the decorated function e.g. @log_on_error(ERROR, "Error was: {e!r}", ...)

Default: "e"

Coming back to our initial code we are now able to move all the logging logic out of our business code and are also forced to follow the »one function - one purpose mantra«. The improved code could look like the following:

import requests
from logging import DEBUG, ERROR, INFO
from logdecorator import log_on_start, log_on_end, log_on_error

class DownloadFailedError(Exception):

    def __init__(self, *args, response, **kwargs):
        super().__init__(*args, **kwargs)
        self.response = response


@log_on_end(DEBUG, "Generated filename '{result:s}' from url '{url:s}'")
def url_to_filename(url):
    filename = url.split("/")[-1]
    return filename or "index.html"


@log_on_start(DEBUG, "Writing content into file")
def write_to_file(filename, content):
    with open(filename, "wb") as f:
        f.write(content)


@log_on_error(ERROR,
              "Download was not successful due "
              "to response status {e.response.status_code:d}",
              on_exceptions=[DownloadFailedError],
              reraise=True)
def content_from_url(url):
    response = requests.get(url)

    if response.status_code != 200:
        raise DownloadFailedError(response=response)

    return response.content


@log_on_start(DEBUG, "Starting to download {url:s}")
@log_on_end(INFO, "Downloading of '{url:s}' into file '{result:s}' was successful")
def download(url):
    content = content_from_url(url)
    filename = url_to_filename(url)

    write_to_file(filename, content)
    return filename

These smaller pieces seem much more appealing and the business logic is really obvious. The reader can decide between reading the actual logic of a function or reading some definitions about the function. Each statement in a function is meant to be there.


Receive Updates

ATOM

Contacts