当在鼻子底下测试 Python 代码时，我应该如何验证日志消息？

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.

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

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

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)

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

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

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

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

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

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.