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

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

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.

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

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

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.