如何临时重定向Python中的日志输出？

Question

这里已经有一个问题回答了如何处理 sys.stdout 和 sys.stderr 的相关内容，具体可以查看这个链接：https://stackoverflow.com/a/14197079/198348

不过，这个方法并不适用于所有情况。日志模块似乎会输出到 sys.stdout 和 sys.stderr，但我用上面的上下文管理器却无法捕捉到这些输出。

在下面的示例代码中，我试图在上下文管理器内部捕捉所有输出，但对于日志记录的语句却没有成功：

from __future__ import print_function
import contextlib
import sys
import logging
from StringIO import StringIO

# taken from https://stackoverflow.com/a/14197079/198348
@contextlib.contextmanager
def stdout_redirect(where):
    prev_stdout = sys.stdout
    prev_stderr = sys.stderr
    prev_stdout.flush()
    sys.stdout = where
    sys.stderr = where
    try:
        yield where
    finally:
        where.flush()
        sys.stdout = prev_stdout
        sys.stderr = prev_stderr

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

print("\t\tOUTSIDE: stdout", file=sys.stdout)
print("\t\tOUTSIDE: stderr", file=sys.stderr)
logger.info("\tOUTSIDE: info")
logger.debug("\tOUTSIDE: debug")
logger.warn("\tOUTSIDE: warn")
logger.error("\tOUTSIDE: error")
logger.critical("\tOUTSIDE: critical")

print("=============== DIVIDER ================")

s = ""
with stdout_redirect(StringIO()) as new_stdout:
    print("\t\tINSIDE: stdout", file=sys.stdout)
    print("\t\tINSIDE: stderr", file=sys.stderr)
    logger.info("\tINSIDE: info")
    logger.debug("\tINSIDE: debug")
    logger.warn("\tINSIDE: warn")
    logger.error("\tINSIDE: error")
    logger.critical("\tINSIDE: critical")


print("=============== DIVIDER ===============")
print(new_stdout.getvalue())

print("=============== LOGGING ===============")

print(logger.handlers)
print(logger.root.handlers)

我该如何临时重定向日志记录器的输出，让它们输出到标准输出（stdout）并捕捉到这些输出呢？我查看了 logging/init.py，但它并没有直接告诉我该怎么做。

我这样做的原因是，我想给一个老旧的大代码库添加测试，每个测试都要捕捉到它所产生的多余的日志输出。我可以捕捉外部程序的输出，但似乎无法捕捉到我在 nose 中运行的测试。

现在重写那些冗长的部分不是一个选项，但这绝对是我未来的目标。

编辑，关于ubuntu

这是我尝试用 nosetests 运行的内容：

from __future__ import print_function
import sys

def test_funky_shurane():
    import logging
    logging.basicConfig(level=logging.DEBUG)
    logging.info("===== shurane info")
    logging.warn("===== shurane warn")
    logging.error("===== shurane error")
    logging.critical("===== shurane critical")
    print("===== shurane stdout", file=sys.stdout)
    print("===== shurane stderr", file=sys.stderr)
    assert True

然后用以下内容运行上面的代码：

nosetests test_logging.py
nosetests --nocapture test_logging.py

Answer 1

重定向没有生效，因为你最开始设置的日志记录器直接指向了标准输出（stdout）。下面是具体情况。

logging_test.py

import logging
import sys

SIMPLE_LOG_FORMAT = '[%(asctime)s] {%(filename)s:%(lineno)d} %(levelname)s - %(message)s'
logger = logging.getLogger(__name__)
logger.setLevel(logging.INFO)
formatter = logging.Formatter(SIMPLE_LOG_FORMAT)
console_handler = logging.StreamHandler(sys.stdout)
console_handler.setFormatter(formatter)
logger.addHandler(console_handler)

logger.info("Message before redirecting stdout and stderr")
# Checking what logger is writing to
logger.info('Before Redirection. logger writing to {} '.format(logger.handlers[0].stream))

log_file = open('log_file.log', 'w')
sys.stdout = log_file
sys.stderr = log_file
# Checking what logger is writing to
logger.info('After Redirection. logger writing to {} '.format(logger.handlers[0].stream))
logger.info("Message after redirecting stdout and stderr")

log_file.close()

输出结果：

[2018-06-01 16:27:10,670] {logging_test.py:12} INFO - Message before redirecting stdout and stderr
[2018-06-01 16:27:10,670] {logging_test.py:14} INFO - Before Redirection. logger writing to <open file '<stdout>', mode 'w' at 0x10cd74150> 
[2018-06-01 16:27:10,670] {logging_test.py:20} INFO - After Redirection. logger writing to <open file '<stdout>', mode 'w' at 0x10cd74150> 
[2018-06-01 16:27:10,670] {logging_test.py:21} INFO - Message after redirecting stdout and stderr

从输出的第二行和第三行可以看到，日志记录器仍然是直接指向标准输出的。

解决这个问题的一种方法是这样做：

logger.handlers[0].stream = open('log_file.log', 'w')

需要注意的是，如果你在使用多个线程，那么在一个线程中做这样的改变，会导致其他线程的输出也开始重定向。

Answer 2

logging.basicConfig() 是一个很方便的工具，可以简单地设置日志记录的方式。如果你需要的功能比这个多一点，那就不应该使用 basicConfig()。这也没什么大不了的，因为它的功能其实并不复杂。我们需要的是为两个输出流配置日志记录；

import logging, sys
fmt = logging.Formatter(BASIC_FORMAT)

hdlr_stderr = logging.StreamHandler(sys.stderr)
hdlr_stderr.setFormatter(fmt)
hdlr_stdout = logging.StreamHandler(sys.stdout)
hdlr_stdout.setFormatter(fmt)
root.addHandler(hdlr_stderr)
root.addHandler(hdlr_stdout)
root.setLevel(logging.DEBUG)

默认情况下，日志记录器会记录它收到的所有消息；但一开始，我们并不想把任何消息记录到 sys.stdout 上：

hdlr_stdout.level = float('inf')  # larger than any log level; nothing gets logged

然后，你的上下文管理器可能看起来像这样：

@contextlib.contextmanager
def redirect_stderr_logging(where):
    hdlr_stderr.level = float('inf')
    hdlr_stdout.level = logging.NOTSET
    try:
        yield where
    finally:
        hdlr_stderr.level = logging.NOTSET
        hdlr_stdout.level = float('inf')