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

Question

我正在尝试编写一个简单的单元测试，该测试将验证在特定条件下，我的应用程序中的类是否会通过标准日志记录 API 记录错误。 我无法弄清楚测试这种情况的最干净的方法是什么。

我知道鼻子已经通过它的日志插件捕获日志输出，但这似乎旨在作为失败测试的报告和调试辅助。

我可以看到的两种方法是：

• 模拟日志记录模块，要么以零碎的方式（mymodule.logging = mockloggingmodule），要么使用适当的模拟库。
• 编写或使用现有的鼻子插件来捕获输出并验证它。

如果我采用前一种方法，我想知道在模拟日志模块之前将全局状态重置为最干净的方法是什么。

期待您对此的提示和技巧......

Answer 1

从 python 3.4 开始，标准 unittest 库提供了一个新的测试断言上下文管理器，assertLogs。 来自 文档：

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

更新：不再需要下面的答案。 请使用内置 Python 方式！

这个答案扩展了 https://stackoverflow.com/a/1049375/1286628 中完成的工作。 处理程序基本上是相同的（构造函数更惯用，使用 super）。 此外，我添加了如何将处理程序与标准库的 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()

然后您可以在标准库 unittest.TestCase 中使用处理程序，如下所示：

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

我曾经模拟记录器，但在这种情况下，我发现最好使用日志记录处理程序，因此我基于 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 4

最简单的答案是

Pytest 有一个名为 caplog 的内置装置。 无需设置。

def test_foo(foo, caplog, expected_msgs):

    foo.bar()

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

我希望在浪费 6 小时之前就了解 caplog。

但是警告 - 它会重置，因此您需要在对 caplog 做出断言的同一测试中执行 SUT 操作。

就我个人而言，我希望我的控制台输出干净，所以我喜欢这样让 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

如果你厌倦了可怕的单元测试代码，那么 pytest 装置有很多值得喜欢的地方。

Answer 5

Brandon 的回答：

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)

注意：上面的内容与调用 nosetests 并获取该工具的 logCapture 插件的输出并不冲突

Answer 6

作为 Reef 回答的后续，我随意使用 pymox 编写了一个示例。
它引入了一些额外的辅助函数，使存根函数和方法变得更加容易。

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

Answer 7

如果您定义这样的辅助方法：

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

那么您可以编写如下测试代码：

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

Answer 8

您应该使用模拟，因为有一天您可能想将您的记录器更改为数据库记录器。 如果它在鼻子测试期间尝试连接到数据库，您将不会高兴。

即使标准输出被抑制，模拟也会继续工作。

我使用了 pyMox 的存根。 请记住在测试后取消设置存根。

Answer 9

在tornado中实现的ExpectLog类是一个很棒的实用程序：

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

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

Answer 10

关闭@Reef的答案，我确实尝试了下面的代码。 它对于 Python 2.7（如果您安装 mock）和 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()