How should I verify a log message when testing Python code under nose?

Question

I'm trying to write a simple unit test that will verify that, under a certain condition, a class in my application will log an error via the standard logging API. I can't work out what the cleanest way to test this situation is.

I know that nose already captures logging output through it's logging plugin, but this seems to be intended as a reporting and debugging aid for failed tests.

The two ways to do this I can see are:

• Mock out the logging module, either in a piecemeal way (mymodule.logging = mockloggingmodule) or with a proper mocking library.
• Write or use an existing nose plugin to capture the output and verify it.

If I go for the former approach, I'd like to know what the cleanest way to reset the global state to what it was before I mocked out the logging module.

Looking forward to your hints and tips on this one...

Lynn

There is now a built in way to do this: docs.python.org/3/library/… – Grouping

pypi: testfixtures & Testing logging. Provided from link-only answer. – Poodle

Mocking logging module for unittests from another link-only answer. – Poodle

Answer 1

I used to mock loggers, but in this situation I found best to use logging handlers, so I wrote this one based on the document suggested by jkp(now dead, but cached on Internet Archive)

class MockLoggingHandler(logging.Handler):
    """Mock logging handler to check for expected logs."""

    def __init__(self, *args, **kwargs):
        self.reset()
        logging.Handler.__init__(self, *args, **kwargs)

    def emit(self, record):
        self.messages[record.levelname.lower()].append(record.getMessage())

    def reset(self):
        self.messages = {
            'debug': [],
            'info': [],
            'warning': [],
            'error': [],
            'critical': [],
        }

Hippocras

The above link is dead, and I was wondering if someone could post on how to use this code. When I try to add this logging handler I keep getting the error when trying to use it as AttributeError: class MockLoggingHandler has no attribute 'level'. – Percheron

Answer 2

From python 3.4 on, the standard unittest library offers a new test assertion context manager, assertLogs. From the docs:

with self.assertLogs('foo', level='INFO') as cm:
    logging.getLogger('foo').info('first message')
    logging.getLogger('foo.bar').error('second message')
    self.assertEqual(cm.output, ['INFO:foo:first message',
                                 'ERROR:foo.bar:second message'])

Handwriting

Small change suggestion is to swap the place of the expected result variable and the actual output variable. Because unittest expects the first argument to be the 'Expected' result. – Hemingway

Just curios, what does cm stand for? – Endo

@JohnnyMetz, in this case it stands for "context manager". – Sharitasharity

What does foo represent in this case? - the log message or function or? – Prothesis

It is an optional argument. If given, it should be a logging.Logger object or a str with the name of a logger. If not given it will default to the "root" logger (capturing all messages). – Sharitasharity

I would also suggest using self.assertListEqual([...], cm.output) for the final assert, which will give a cleaner message on errors (and obeys the self.assert*(expected, actual) unittest pattern mentioned by @hfm) – Disyllable

Answer 3

UPDATE: No longer any need for the answer below. Use the built-in Python way instead!

This answer extends the work done in https://mcmap.net/q/186314/-how-should-i-verify-a-log-message-when-testing-python-code-under-nose. The handler is largely the same (the constructor is more idiomatic, using super). Further, I add a demonstration of how to use the handler with the standard library's unittest.

class MockLoggingHandler(logging.Handler):
    """Mock logging handler to check for expected logs.

    Messages are available from an instance's ``messages`` dict, in order, indexed by
    a lowercase log level string (e.g., 'debug', 'info', etc.).
    """

    def __init__(self, *args, **kwargs):
        self.messages = {'debug': [], 'info': [], 'warning': [], 'error': [],
                         'critical': []}
        super(MockLoggingHandler, self).__init__(*args, **kwargs)

    def emit(self, record):
        "Store a message from ``record`` in the instance's ``messages`` dict."
        try:
            self.messages[record.levelname.lower()].append(record.getMessage())
        except Exception:
            self.handleError(record)

    def reset(self):
        self.acquire()
        try:
            for message_list in self.messages.values():
                message_list.clear()
        finally:
            self.release()

Then you can use the handler in a standard-library unittest.TestCase like so:

import unittest
import logging
import foo

class TestFoo(unittest.TestCase):

    @classmethod
    def setUpClass(cls):
        super(TestFoo, cls).setUpClass()
        # Assuming you follow Python's logging module's documentation's
        # recommendation about naming your module's logs after the module's
        # __name__,the following getLogger call should fetch the same logger
        # you use in the foo module
        foo_log = logging.getLogger(foo.__name__)
        cls._foo_log_handler = MockLoggingHandler(level='DEBUG')
        foo_log.addHandler(cls._foo_log_handler)
        cls.foo_log_messages = cls._foo_log_handler.messages

    def setUp(self):
        super(TestFoo, self).setUp()
        self._foo_log_handler.reset() # So each test is independent

    def test_foo_objects_fromble_nicely(self):
        # Do a bunch of frombling with foo objects
        # Now check that they've logged 5 frombling messages at the INFO level
        self.assertEqual(len(self.foo_log_messages['info']), 5)
        for info_message in self.foo_log_messages['info']:
            self.assertIn('fromble', info_message)

Grouping

Thanks for explaining how to utilize Gustavo's answer and extending it. – Embosser

There is now a built in way to do this: docs.python.org/3/library/… – Grouping

In setUpClass, the foo_log.addHandler() call has a missing underscore before the foo_log_handler variable – Anatomist

This is still useful for python 2.x. – Tinkling

Presumably any code written in Python 2 that is still in use has already been tested by now. If you’re in the test writing phase of a project, probably better just to switch to Python 3 now. Python 2 will lose support (including security updates) in a year and a half or so. – Grouping

Thank you for updating, you save me a lot of time and no need to add package bloat to a project! – Propitiatory

This is still useful. I'm trying to steer away from the vastness of the unittest API and the cruddy test code that we've written with it. This enables much simpler assertions, and is easily consumed in a pytest fixture. – Loony

Answer 4

Simplest answer of all

Pytest has a built-in fixture called caplog. No setup needed.

def test_foo(foo, caplog, expected_msgs):

    foo.bar()

    assert [r.msg for r in caplog.records] == expected_msgs

I wish I'd known about caplog before I wasted 6 hours.

Warning, though - it resets, so you need to perform your SUT action in the same test where you make assertions about caplog.

Personally, I want my console output clean, so I like this to silence the log-to-stderr:

from logging import getLogger
from pytest import fixture


@fixture
def logger(caplog):

    logger = getLogger()
    _ = [logger.removeHandler(h) for h in logger.handlers if h != caplog.handler]       # type: ignore
    return logger


@fixture
def foo(logger):

    return Foo(logger=logger)


@fixture
def expected_msgs():

    # return whatever it is you expect from the SUT


def test_foo(foo, caplog, expected_msgs):

    foo.bar()

    assert [r.msg for r in caplog.records] == expected_msgs

There is a lot to like about pytest fixtures if you're sick of horrible unittest code.

Loony

Note that r.msg is the message BEFORE formatting. So if you log hi %s, msg will literally be "hi %s". To get the message after formatting, like "hi Stacy", you should use r.message – Detain

Answer 5

Brandon's answer:

pip install testfixtures

snippet:

import logging
from testfixtures import LogCapture
logger = logging.getLogger('')


with LogCapture() as logs:
    # my awesome code
    logger.error('My code logged an error')
assert 'My code logged an error' in str(logs)

Note: the above does not conflict with calling nosetests and getting the output of logCapture plugin of the tool

Sancho

Answer 6

As a follow up to Reef's answer, I took a liberty of coding up an example using pymox. It introduces some extra helper functions that make it easier to stub functions and methods.

import logging

# Code under test:

class Server(object):
    def __init__(self):
        self._payload_count = 0
    def do_costly_work(self, payload):
        # resource intensive logic elided...
        pass
    def process(self, payload):
        self.do_costly_work(payload)
        self._payload_count += 1
        logging.info("processed payload: %s", payload)
        logging.debug("payloads served: %d", self._payload_count)

# Here are some helper functions
# that are useful if you do a lot
# of pymox-y work.

import mox
import inspect
import contextlib
import unittest

def stub_all(self, *targets):
    for target in targets:
        if inspect.isfunction(target):
            module = inspect.getmodule(target)
            self.StubOutWithMock(module, target.__name__)
        elif inspect.ismethod(target):
            self.StubOutWithMock(target.im_self or target.im_class, target.__name__)
        else:
            raise NotImplementedError("I don't know how to stub %s" % repr(target))
# Monkey-patch Mox class with our helper 'StubAll' method.
# Yucky pymox naming convention observed.
setattr(mox.Mox, 'StubAll', stub_all)

@contextlib.contextmanager
def mocking():
    mocks = mox.Mox()
    try:
        yield mocks
    finally:
        mocks.UnsetStubs() # Important!
    mocks.VerifyAll()

# The test case example:

class ServerTests(unittest.TestCase):
    def test_logging(self):
        s = Server()
        with mocking() as m:
            m.StubAll(s.do_costly_work, logging.info, logging.debug)
            # expectations
            s.do_costly_work(mox.IgnoreArg()) # don't care, we test logging here.
            logging.info("processed payload: %s", 'hello')
            logging.debug("payloads served: %d", 1)
            # verified execution
            m.ReplayAll()
            s.process('hello')

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

Gnash

I like your innovative use of a contextmanager decorator to implement "scoped mocking". Nice. – Lynn

PS: it's a real shame about PyMOX's lack of pep8 conformance. – Lynn

Answer 7

If you define a helper method like this:

import logging

def capture_logging():
    records = []

    class CaptureHandler(logging.Handler):
        def emit(self, record):
            records.append(record)

        def __enter__(self):
            logging.getLogger().addHandler(self)
            return records

        def __exit__(self, exc_type, exc_val, exc_tb):
            logging.getLogger().removeHandler(self)

    return CaptureHandler()

Then you can write test code like this:

    with capture_logging() as log:
        ... # trigger some logger warnings
    assert len(log) == ...
    assert log[0].getMessage() == ...

Allyn

Answer 8

You should use mocking, as someday You might want to change Your logger to a, say, database one. You won't be happy if it'll try to connect to the database during nosetests.

Mocking will continue to work even if standard output will be suppressed.

I have used pyMox's stubs. Remember to unset the stubs after the test.

Olethea

+1 Some of the benefits of AOP. Rather than wrapping every backend in a generic-style class/object. – Prospector

Answer 9

The ExpectLog class implemented in tornado is a great utility:

with ExpectLog('channel', 'message regex'):
    do_it()

http://tornado.readthedocs.org/en/latest/_modules/tornado/testing.html#ExpectLog

Devest

Answer 10

Keying off @Reef's answer, I did tried the code below. It works well for me both for Python 2.7 (if you install mock) and for Python 3.4.

"""
Demo using a mock to test logging output.
"""

import logging
try:
    import unittest
except ImportError:
    import unittest2 as unittest

try:
    # Python >= 3.3
    from unittest.mock import Mock, patch
except ImportError:
    from mock import Mock, patch

logging.basicConfig()
LOG=logging.getLogger("(logger under test)")

class TestLoggingOutput(unittest.TestCase):
    """ Demo using Mock to test logging INPUT. That is, it tests what
    parameters were used to invoke the logging method, while still
    allowing actual logger to execute normally.

    """
    def test_logger_log(self):
        """Check for Logger.log call."""
        original_logger = LOG
        patched_log = patch('__main__.LOG.log',
                            side_effect=original_logger.log).start()

        log_msg = 'My log msg.'
        level = logging.ERROR
        LOG.log(level, log_msg)

        # call_args is a tuple of positional and kwargs of the last call
        # to the mocked function.
        # Also consider using call_args_list
        # See: https://docs.python.org/3/library/unittest.mock.html#unittest.mock.Mock.call_args
        expected = (level, log_msg)
        self.assertEqual(expected, patched_log.call_args[0])


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

Conduit