PyDev单元测试：如何在“捕获的输出”中捕获logging.Logger记录的文本

Question

我正在使用PyDev来开发和测试我的Python应用程序。在单元测试方面，一切都运行得很好，唯一的问题是没有任何内容被记录到日志框架中。PyDev的“捕获输出”没有捕捉到日志记录器的内容。

我已经像这样将所有记录的内容转发到标准输出：

import sys
logger = logging.getLogger()
logger.level = logging.DEBUG
logger.addHandler(logging.StreamHandler(sys.stdout))

然而，“捕获输出”并没有显示记录到日志记录器的内容。

这里有一个单元测试脚本的例子：test.py

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG
logger.addHandler(logging.StreamHandler(sys.stdout))

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        print("AA")
        logging.getLogger().info("BB")

控制台输出是：

Finding files... done.
Importing test modules ... done.

testSimpleMsg (itf.lowlevel.tests.hl7.TestCase) ... AA
2011-09-19 16:48:00,755 - root - INFO - BB
BB
ok

----------------------------------------------------------------------
Ran 1 test in 0.001s

OK

但是测试的捕获输出是：

======================== CAPTURED OUTPUT =========================
AA

有没有人知道如何在执行这个测试期间捕获所有记录到logging.Logger的内容？

Answer 1

有些人可能会来这个帖子寻找把测试过程中产生的日志转发到控制台或PyDev的方法。上面的回答已经提供了一些解决方案。

如果想在实际测试中捕获特定的日志，从Python 3.4开始，unittest.TestCase提供了一个叫assertLogs()的功能，它可以返回一个上下文管理器，用来捕获当前的日志信息。根据unittest文档：

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

这些信息会被保存在cm.output里。如果需要更详细的信息（比如时间、文件、行号等），可以查看cm.records，它包含了一系列的LogRecords。

这些内容虽然没有直接解决OP在PyDev中遇到的问题，但提供了一种编程方式来检查生成的日志信息。

对于熟悉pytest的人，可以使用--log-cli-level=LEVEL这个选项，把格式良好的日志信息转发到控制台，比如可以用pytest --log-cli-level=info。

Answer 2

我厌倦了每次都要手动把Fabio的好代码加到所有的setUp方法里，所以我创建了一个新的类，继承自unittest.TestCase，并做了一些__metaclass__的调整：

class LoggedTestCase(unittest.TestCase):
    __metaclass__ = LogThisTestCase
    logger = logging.getLogger("unittestLogger")
    logger.setLevel(logging.DEBUG) # or whatever you prefer

class LogThisTestCase(type):
    def __new__(cls, name, bases, dct):
        # if the TestCase already provides setUp, wrap it
        if 'setUp' in dct:
            setUp = dct['setUp']
        else:
            setUp = lambda self: None
            print "creating setUp..."

        def wrappedSetUp(self):
            # for hdlr in self.logger.handlers:
            #    self.logger.removeHandler(hdlr)
            self.hdlr = logging.StreamHandler(sys.stdout)
            self.logger.addHandler(self.hdlr)
            setUp(self)
        dct['setUp'] = wrappedSetUp

        # same for tearDown
        if 'tearDown' in dct:
            tearDown = dct['tearDown']
        else:
            tearDown = lambda self: None

        def wrappedTearDown(self):
            tearDown(self)
            self.logger.removeHandler(self.hdlr)
        dct['tearDown'] = wrappedTearDown

        # return the class instance with the replaced setUp/tearDown
        return type.__new__(cls, name, bases, dct)

现在，你的测试用例只需要继承自LoggedTestCase，也就是说，你可以写成class TestCase(LoggedTestCase)，而不是class TestCase(unittest.TestCase)，这样就搞定了。或者，你也可以加上__metaclass__这一行，并在测试中或者稍微修改过的LogThisTestCase里定义logger。

Answer 3

问题在于，unittest 测试框架在测试开始之前就把 sys.stdout 和 sys.stderr 替换掉了，而 StreamHandler 仍然在写入原来的 sys.stdout。

如果你把当前的 sys.stdout 赋值给处理器，它应该就能正常工作了（见下面的代码）。

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG
stream_handler = logging.StreamHandler(sys.stdout)
logger.addHandler(stream_handler)

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        stream_handler.stream = sys.stdout
        print("AA")
        logging.getLogger().info("BB")

不过，更好的方法是在测试过程中添加或移除这个处理器：

import sys
import unittest
import logging

logger = logging.getLogger()
logger.level = logging.DEBUG

class TestCase(unittest.TestCase):
    def testSimpleMsg(self):
        stream_handler = logging.StreamHandler(sys.stdout)
        logger.addHandler(stream_handler)
        try:
            print("AA")
            logging.getLogger().info("BB")
        finally:
            logger.removeHandler(stream_handler)