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:
- Download some content from a given url
- If the response status is not positive (200) the function will raise an exception
- Extract the file name from the url; if it has a trailing slash use index.html
- 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.