PyDev unittesting：如何在“捕获的输出”中捕获记录到 logging.Logger 的文本

Posted 2023-04-14

【中文标题】PyDev unittesting：如何在“捕获的输出”中捕获记录到 logging.Logger 的文本

【英文标题】：PyDev unittesting: How to capture text logged to a logging.Logger in "Captured Output"

【发布时间】：2011-11-20 08:00:09

【问题描述】：

我正在使用 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是：

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

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

【参考方案1】：

问题是unittest runner 在测试开始之前替换了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)

【讨论】：

为了完整性：我的所有单元测试都需要这种重定向。对我来说最好的解决方案是在 setUp-method 中添加新的处理程序并在 tearDown-method 中删除它。

很好的答案，我将 expanded 这个 __metaclass__ 所以包装好的 setUp 和 tearDown 自动包含这个

为什么添加/删除处理程序而不是将它们保留在测试用例之外更好？

我认为它更好，因为您可以为特定功能自定义它或添加更多信息（而不必为每次调用更新处理程序流）。最终的解决方案无论如何都会使用装饰器或元类来包装测试，因此，您并没有真正输入更多代码，只是提供了一些可能更可定制的东西......

这是否比仅在测试中使用打印来获取用户反馈更好？

【参考方案2】：

我厌倦了必须手动将Fabio's great code 添加到所有setUps，因此我将unittest.TestCase 子类化为一些__metaclass__ing：

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__ 行并在测试中定义logger 或稍作修改的LogThisTestCase。

【讨论】：

@Randy 谢谢，在阅读了this great explanation of __metaclass__ 之后，我只是不得不使用它...

上周我发现自己阅读了相同的答案，并且它也已经进入了我的代码库。

不错的解决方案，但纯粹出于提供信息的目的，您可以创建一个超类并继承 run() 来进行自定义设置，调用原始 run() 然后进行自定义拆解（如果需要无需调用 setUp/tearDown 即可创建子类）——并不是说元类没有用，但我认为最终代码会变得更加复杂；）

@FabioZadrozny 是的，虽然正如当时提到的，我只是不得不使用元类;)

【参考方案3】：

我建议使用 LogCapture 并测试您是否确实在记录您期望记录的内容：

http://testfixtures.readthedocs.org/en/latest/logging.html

【讨论】：

我很高兴有一个包可以处理它，因此不需要为明显的常见问题编写代码。但不幸的是，当我通常使用记录器时，我在使用我没有的“print(l)”时遇到了 UTF 问题。所以我的方法是“sys.stdout.buffer.write(l.__str__().encode('utf8'))”。这很好，所以我想分享它。

@IwanLD - 现在我推荐使用LogCapture().check()。你怎么不能用呢？

虽然此链接可能会回答问题，但最好在此处包含答案的基本部分并提供链接以供参考。如果链接页面发生更改，仅链接答案可能会失效。 - From Review

@BearBrown - 链接已经工作了 10 多年了，作为它的作者，我不打算改变它;-) 我还温和地建议如果它确实改变了，'编辑'功能可以用来纠正它...

注意：如果你在 Django 中使用这个包，请阅读这里的文档：testfixtures.readthedocs.io/en/latest/django.html

【参考方案4】：

在阅读了本文和其他一些相关主题中的答案（谢谢！）之后，这是我放在一起的上下文管理器，它将捕获记录器的输出（如果已发送）。

from io import StringIO
import logging
class CaptureLogger:
    """Context manager to capture `logging` streams

    Args:
        - logger: 'logging` logger object

    Results:
        The captured output is available via `self.out`

    """

    def __init__(self, logger):
        self.logger = logger
        self.io = StringIO()
        self.sh = logging.StreamHandler(self.io)
        self.out = ''

    def __enter__(self):
        self.logger.addHandler(self.sh)
        return self

    def __exit__(self, *exc):
        self.logger.removeHandler(self.sh)
        self.out = self.io.getvalue()

    def __repr__(self):
        return f"captured: self.out\n"

使用示例：

logger = logging.getLogger()
msg = "Testing 1, 2, 3"
with CaptureLogger(logger) as cl:
    logger.error(msg)
assert cl.out, msg+"\n"

由于 OP 要求将其放入捕获的 stdout 流中，您可以将其打印到 __exit__ 中的 stdout，因此添加一行如下：

    def __exit__(self, *exc):
        self.logger.removeHandler(self.sh)
        self.out = self.io.getvalue()
        print(self.out)

这个解决方案的不同之处在于它会收集日志输出，并在所有正常的print() 调用（如果有）之后一次性将其全部转出。所以它可能是也可能不是 OP 所追求的，但这对我的需求很有效。

【参考方案5】：

有些人可能会访问此线程以找到将测试期间创建的日志转发到控制台或 PyDev 的方法。以上答案已经提供了一些解决方案。

如果想在实际测试中捕获特定日志，我发现从 Python 3.4 开始，unittest.TestCase 提供了assertLogs()，它返回一个捕获当前日志消息的上下文管理器。来自unittest 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'])

消息在cm.output 中捕获。如需更多详细信息（如时间、文件、行号等，cm.records 包含LogRecords 的列表。

所有这些都没有直接解决面对 PyDev 的 OP，而是提供了一种以编程方式检查创建的消息的方法。

对于熟悉pytest 的用户，可以使用--log-cli-level=LEVEL 标志（例如pytest --log-cli-level=info）将格式精美的日志消息转发到控制台。

【参考方案6】：

我也遇到过这个问题。我最终继承了 StreamHandler，并使用获取 sys.stdout 的属性覆盖了流属性。这样，处理程序将使用 unittest.TestCase 已交换到 sys.stdout 的流：

class CapturableHandler(logging.StreamHandler):

    @property
    def stream(self):
        return sys.stdout

    @stream.setter
    def stream(self, value):
        pass

然后您可以在运行测试之前设置日志处理程序（这会将自定义处理程序添加到根记录器）：

def setup_capturable_logging():
    if not logging.getLogger().handlers:
        logging.getLogger().addHandler(CapturableHandler())

如果像我一样，您在单独的模块中进行测试，您可以在每个单元测试模块的导入后放置一行，以确保在运行测试之前设置日志记录：

import logutil

logutil.setup_capturable_logging()

这可能不是最干净的方法，但它非常简单并且对我来说效果很好。

【参考方案7】：

如果您有不同的初始化模块用于测试、开发和生产，那么您可以禁用任何东西或在初始化程序中重定向它。

我有 local.py、test.py 和 production.py，它们都继承自 common.y

common.py 完成所有主要配置，包括这个 sn-p ：

    LOGGING = 
    'version': 1,
    'disable_existing_loggers': False,
    'formatters': 
        'django.server': 
            '()': 'django.utils.log.ServerFormatter',
            'format': '[%(server_time)s] %(message)s',
        ,
        'verbose': 
            'format': '%(levelname)s %(asctime)s %(module)s %(process)d %(thread)d %(message)s'
        ,
        'simple': 
            'format': '%(levelname)s %(message)s'
        ,
    ,
    'filters': 
        'require_debug_true': 
            '()': 'django.utils.log.RequireDebugTrue',
        ,
    ,
    'handlers': 
        'django.server': 
            'level': 'INFO',
            'class': 'logging.StreamHandler',
            'formatter': 'django.server',
        ,
        'console': 
            'level': 'DEBUG',
            'class': 'logging.StreamHandler',
            'formatter': 'simple'
        ,
        'mail_admins': 
            'level': 'ERROR',
            'class': 'django.utils.log.AdminEmailHandler'
        
    ,
    'loggers': 
        'django': 
            'handlers': ['console'],
            'level': 'INFO',
            'propagate': True,
        ,
        'celery.tasks': 
            'handlers': ['console'],
            'level': 'DEBUG',
            'propagate': True,
        ,
        'django.server': 
            'handlers': ['django.server'],
            'level': 'INFO',
            'propagate': False,
        ,
    

然后在 test.py 我有这个：

console_logger = Common.LOGGING.get('handlers').get('console')
console_logger['class'] = 'logging.FileHandler
console_logger['filename'] = './unitest.log

这将控制台处理程序替换为 FileHandler，这意味着仍然可以获取日志记录，但我不必接触生产代码库。

【参考方案8】：

这是一个小技巧，但对我有用。当您想要显示捕获的日志时添加此代码。不需要后将其删除。

self.assertEqual(1, 0)

例子：

def test_test_awesome_function():
    print("Test 1")
    logging.info("Test 2")
    logging.warning("Test 3")

    self.assertEqual(1, 0)

更新：

顺便说一句，这不是一个长期的解决方案，当您想快速调试目标函数上的某些内容时，此解决方案很有帮助。

一旦断言失败，unittest 将抛出哪些函数出现错误，并捕获并显示 print、logging.* 内容。

【讨论】：

虽然这会触发 unittest 输出中的日志显示，但如果您忘记删除它们，添加无意义的错误可能会产生意想不到的副作用。这是不好的形式，不需要解决问题。

这里不清楚你的意思。 print 可能会通过，logging 被unittest 捕获。对吗？

一旦assert 失败，unittest 将抛出哪些函数出错，并捕获并显示print、logging.* 内容。