Testing log output

ATTRIBUTION: This post was inspired by Domen’s Mocking logging module for unittests post back from 2009. Most of the code below is from him, with some added Plone specific bits and pieces.

I was recently debugging an installation of our niteoweb.click2sell and had the need for more verbose error handling. After adding support for it in the code I wondered if and how I should test what was written to the log under different scenarios. The final result of my research looks like this:

  • Create a logger handler that stores all records in a list.
  • Add this handler to the logger on layer setup.
  • Use it in tests to assert log output.
  • Reset its list on test teardown.

First, let’s look at the code for the logger handler, that you would likely put in the same module as where you define your test cases and such (base.py in my case):

class MockedLoggingHandler(logging.Handler):

    debug = []
    warning = []
    info = []
    error = []

    def emit(self, record):
        getattr(self.__class__, record.levelname.lower()).append(record.getMessage())

    @classmethod
    def reset(cls):
        for attr in dir(cls):
            if isinstance(getattr(cls, attr), list):
                setattr(cls, attr, [])

Now, assuming you use plone.app.testing, add the following lines somewhere in your layer setup (setUpPloneSite() in my case):

logger = logging.getLogger('your.package')
logger.addHandler(MockedLoggingHandler())

You are ready to assert log output in your tests:

def test_log_output(self):
    some_method_that_prints_to_log()
    from your.package.tests.base import MockedLoggingHandler as logger
    self.assertEqual(logger.error[0], "Error occured!")

Finally, remember to clear the list of log records in your test teardown:

def tearDown(self):
    logger.reset()

To see this code in a context of a working package, take a peek into niteoweb.click2sell’s tests.

Happy testing!