Example code for testing Python log output

This is example code that shows how you can capture log messages using the Python logging module for tests (or other purposes). I wrote this code for a blog post, which you can also read below.

Testing Python log output

Imagine you have a module and want to make sure everything’s working, so you test. For functions the idea is usually pretty simple: Provide some inputs, see if the output looks as expected. But what the function is also supposed to write some log messages and you want to check if they look the way they should? I was asking myself that question on the weekend and found a solution that I think is fun: Adding a custom log handler!

Maybe you’ve already used the logging module? Logging messages is pretty simple, for example:

import logging
logger = logging.getLogger(__name__)

def add(*vargs):
    logger.debug('Calculating the sum of %s', vargs)
    res = sum(vargs)
    logger.debug('Result is %d', res)
    return res

Let’s assume you have that in a file add.py, and are going to write tests in a separate file. A simple unittest-based functionality test might look like this:

import add
import unittest

class AddTest(unittest.TestCase):
    def test_add(self):
        self.assertEqual(add.add(1, 2, 3), 6)

But what if you want to check if the debug messages are logged as expected? I realized you can tap into the logging framework for that! The logging module uses handlers to send log messages wherever they are supposed to go, and you can add as many as you want, so why not add one that sends output to the test?

First you’re going to need a logger for the target module:

        logger = logging.getLogger('add')
        logger.setLevel(logging.DEBUG)

Setting the level of the logger is necessary to ensure you really get all messages (unless that has been set elsewhere already), but keep in mind that that’s a process-wide setting. In a simple unit test like here that’s not going to cause trouble. Now that we have the logger we need to add a handler.

Also I want to have the input parameters and expected result in variables, so I can use them later for comparing with the log messages:

        params = (1, 2, 3)
        expected_sum = 6

Option one: A temporary log file

        with tempfile.SpooledTemporaryFile(mode='w+') as log:
            handler = logging.StreamHandler(stream=log)
            logger.addHandler(handler)
            try:
                self.assertEqual(add.add(*params), expected_sum)
            finally:
                logger.removeHandler(handler)
            log.seek(0)
            logdata = log.read()

The logging.StreamHandler can write to all sorts of streams, its default is sys.stderr. I’m using a tempfile.SpooledTemporaryFile as the target because it is automatically cleaned up as soon as it is closed, and the amount of log data will be small, so it makes sense to keep it in memory.

The try/finally block around the function I’m testing ensures the handler is always removed after the function call, even in case of an exception (including those from failed assertions).

In the end you just have to read the file and check if the output looks like it should.

        lines = logdata.splitlines()
        self.assertEqual(lines[0], f'Calculating the sum of {params!s}')
        self.assertEqual(lines[1], f'Result is {expected_sum}')

This also shows the disadvantages of this method: You end up with a wall of text that you have to parse. With two lines it’s not too bad, but with a lot of output it may get messy.

You can remedy that somewhat by attaching a Formatter to the handler, which as the name indicates lets you format the log messages, including adding some metadata.

Option two: A message queue

        q = queue.SimpleQueue()
        handler = logging.handlers.QueueHandler(q)
        logger.addHandler(handler)
        try:
            self.assertEqual(add.add(*params), expected_sum)
        finally:
            logger.removeHandler(handler)

This code is a bit shorter, because there’s no file to open. Instead the log messages are added to the queue, and I can retrieve them message by message:

        self.assertEqual(q.get_nowait().getMessage(),
                         f'Calculating the sum of {params!s}')
        self.assertEqual(q.get_nowait().getMessage(),
                         f'Result is {expected_sum}')

This has two advantages:

1. I always get complete messages, no need to worry about splitting lines and newlines in messages.
2. The objects in the queue are not strings, they are LogRecord objects, which hold all the metadata of the log message. Though in this example I’m just like “give me the message” and that’s it.

Conclusion

Turns out the Python logging module is easier to use than I had thought when I started figuring this out, and is fun to play with. Of course with more complex tests this kind of analysis might get more complex, too: You might not want to look at every message (maybe a Filter helps?), or you might not be sure which order they arrive in.

Have fun coding!