How should I verify a log message when testing Pyt

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...

Answer 1

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'])

Answer 2

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

This answer extends the work done in https://stackoverflow.com/a/1049375/1286628. 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)

Answer 3

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.

Answer 4

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()

Answer 5

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:

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': [],
        }

Answer 6

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