Unit testing and logging

I’ve had questions in the past about using logging and unit testing together – what’s the best way of doing it?

Beyond the choice of unit testing frameworks (e.g. unittest, nose, py.test), unit testing appears to be one of those things (like configuration) where people have strong, and differing, opinions about how they like to do it. This is one reason there is no specific support for unit testing in logging. Besides, logging is one area where functionally, your application should work in exactly the same way no matter how logging is configured, and even if logging is completely switched off (because there are no handlers configured, or the verbosity thresholds are set to be above CRITICAL). I am of course distinguishing here between application logging and request logging as practiced by web servers – the latter is part of the function of the web server, whereas application logging is meant as a operational and diagnostic aid for developers, system administrators and support teams, and orthogonal to the application’s functionality. There are of course scenarios where logging is used to output messages to end users (typically, INFO or WARNING level messages), but it should be borne in mind that the application should keep going even if logging verbosity is turned off.

There are two things that would be useful when using logging and unit testing together:

• Some way of capturing all the messages which are logged by the code being unit tested.
• Some way of verifying that certain expectations with respect to logged messages are met.

Logging already provides a BufferingHandler class which allows you to capture LogRecords generated by logging activity. You can, for example, subclass this to store the LogRecord.__dict__ values rather than the LogRecords themselves – this will facilitate checking whether expectations are met. You typically don’t want to flush anything until the end of the test, though, so a handler which facilitates testing might look like this:

from logging.handlers import BufferingHandler

class TestHandler(BufferingHandler):
    def __init__(self):
        # BufferingHandler takes a "capacity" argument
        # so as to know when to flush. As we're overriding
        # shouldFlush anyway, we can set a capacity of zero.
        # You can call flush() manually to clear out the
        # buffer.
        BufferingHandler.__init__(self, 0)

    def shouldFlush(self):
        return False

    def emit(self, record):
        self.buffer.append(record.__dict__)

Now let’s consider the checking of expectations about what’s been logged. We could implement this in the TestHandler class directly, but it’s the sort of area where different people may want to do different things. The bare minimum we need in TestHandler would be something that looks for some kind of match between what’s been logged (the buffer of dictionaries) and the expected values. So as an idea, let’s delegate the details of matching to a separate Matcher class, which must have a matches method. Because matching of dictionaries is likely to crop up in tests other than to do with logging, creating a separate Matcher class allows us to deploy the functionality in other scenarios. So, we can develop the TestHandler class a little:

from logging.handlers import BufferingHandler

class TestHandler(BufferingHandler):
    def __init__(self, matcher):
        # BufferingHandler takes a "capacity" argument
        # so as to know when to flush. As we're overriding
        # shouldFlush anyway, we can set a capacity of zero.
        # You can call flush() manually to clear out the
        # buffer.
        BufferingHandler.__init__(self, 0)
        self.matcher = matcher

    def shouldFlush(self):
        return False

    def emit(self, record):
        self.buffer.append(record.__dict__)

    def matches(self, **kwargs):
        """
        Look for a saved dict whose keys/values match the supplied arguments.
        """
        for d in self.buffer:
            if self.matcher.matches(d, **kwargs):
                result = True
                break
        return result

The signature for the matches method allows us to pass just the keys we want to test for in the call. In implementing the Matcher class, we could do whatever we wanted – regular expression matching, for example – but we’ll keep it simple. Let’s assume that we want to either match values exactly, or else do partial matches for string values such as messages. (In order to ensure that a formatted message appears in a LogRecord’s __dict__, we need to call self.format(record) in the emit method.)

To decide which keys to do partial matches on, we can store a set of the relevant keys in a _partial_matches attribute. This is defined in the Matcher class, but you can replace it in a subclass or even an instance of Matcher if you need to. Here’s the Matcher class:

class Matcher(object):

    _partial_matches = ('msg', 'message')

    def matches(self, d, **kwargs):
        """
        Try to match a single dict with the supplied arguments.

        Keys whose values are strings and which are in self._partial_matches
        will be checked for partial (i.e. substring) matches. You can extend
        this scheme to (for example) do regular expression matching, etc.
        """
        result = True
        for k in kwargs:
            v = kwargs[k]
            dv = d.get(k)
            if not self.match_value(k, dv, v):
                result = False
                break
        return result

    def match_value(self, k, dv, v):
        """
        Try to match a single stored value (dv) with a supplied value (v).
        """
        if type(v) != type(dv):
            result = False
        elif type(dv) is not str or k not in self._partial_matches:
            result = (v == dv)
        else:
            result = dv.find(v) >= 0
        return result

Notice that the class is independent of logging and might prove useful elsewhere. Also note the use of str in the match_value method – you may want to replace this with basestring for Python 2.x. (Of course, I could have used isinstance, too.)

Now we can consider what a typical test case using TestHandler and Matcher might look like (some imports omitted):

import unittest

class LoggingTest(unittest.TestCase):
    def setUp(self):
        self.handler = h = TestHandler(Matcher())
        self.logger = l = logging.getLogger()
        l.addHandler(h)
        
    def tearDown(self):
        self.logger.removeHandler(self.handler)
        self.handler.close()
        
    def test_simple(self):
        "Simple test of logging test harness."
        # Just as a demo, let's log some messages.
        # Only one should show up in the log.
        self.logger.debug("This won't show up.")
        self.logger.info("Neither will this.")
        self.logger.warning("But this will.")
        h = self.handler
        self.assertTrue(h.matches(levelno=logging.WARNING))
        self.assertFalse(h.matches(levelno=logging.DEBUG))
        self.assertFalse(h.matches(levelno=logging.INFO))

    def test_partial(self):
        "Test of partial matching in logging test harness."
        # Just as a demo, let's log some messages.
        # Only one should show up in the log.
        self.logger.debug("This won't show up.")
        self.logger.info("Neither will this.")
        self.logger.warning("But this will.")
        h = self.handler
        self.assertTrue(h.matches(msg="ut th")) # from "But this will"
        self.assertTrue(h.matches(message="ut th")) # from "But this will"
        self.assertFalse(h.matches(message="either"))
        self.assertFalse(h.matches(message="won't"))

    def test_multiple(self):
        "Test of matching multiple values in logging test harness."
        # Just as a demo, let's log some messages.
        # Only one should show up in the log.
        self.logger.debug("This won't show up.")
        self.logger.info("Neither will this.")
        self.logger.warning("But this will.")
        self.logger.error("And so will this.")
        h = self.handler
        self.assertTrue(h.matches(levelno=logging.WARNING,
                                  funcName='test_multiple'))
        self.assertTrue(h.matches(levelno=logging.ERROR,
                                  funcName='test_multiple'))
        self.assertFalse(h.matches(levelno=logging.INFO))

if __name__ == '__main__':
    unittest.main()

The whole script is here, and if you run it, you should have no errors:

vinay@eta-jaunty:~/projects/scratch$ python2.7 testhdlr.py
...
----------------------------------------------------------------------
Ran 3 tests in 0.001s

OK
vinay@eta-jaunty:~/projects/scratch$ python3.2 testhdlr.py
...
----------------------------------------------------------------------
Ran 3 tests in 0.001s

OK

Is there anything I’ve missed? Anything you don’t like about these suggestions? Please feel free to comment. Thanks for reading.