奇怪：记录器只在异常时使用第一个处理器的格式化器

Question

我发现日志模块的表现有点奇怪。是不是我漏掉了什么？

我通常会设置两个处理器：一个是StreamHandler，用来在控制台上记录INFO级别及以上的信息；另一个是FileHandler，用来记录所有的DEBUG信息。

这之前都没问题，直到我想给异常设置不同的格式。我希望在文件中能看到完整的堆栈跟踪，但在控制台上只显示异常的类型和信息。因为处理器有一个setFormatter的功能，而且写一个logging.Formatter的子类似乎很简单，所以我以为这样可以实现。

控制台处理器和文件处理器都有各自的格式化器。代码中的打印语句证明了这一点。然而，logger.exception的调用只会使用第一个添加的处理器的formatException，这就导致异常在文件中以控制台应该有的格式被记录。只要改变logger.addHandler的顺序，那么文件处理器的formatException就会在所有地方被使用。

import logging
import sys

class ConsoleFormatter(logging.Formatter):
    def formatException(self, exc_info):
        # Ugly but obvious way to see who's talking.
        return "CONSOLE EXCEPTION %s: %s" % exc_info[:2]

def setup(path):
    logger = logging.getLogger()
    #
    file_handler = logging.FileHandler(path, mode='w')
    if __debug__:
        file_handler.setLevel(logging.DEBUG)
    else:
        file_handler.setLevel(logging.INFO)
    formatter = logging.Formatter("%(asctime)s %(levelname)-8s "
                                  "%(name)-16s %(message)s "
                                  "[%(filename)s@%(lineno)d in %(funcName)s]")
    file_handler.setFormatter(formatter)

    #
    console_handler = logging.StreamHandler(sys.stderr)
    console_handler.setLevel(logging.INFO)
    console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s")
    console_handler.setFormatter(console_formatter)

    # >>> FUN HAPPENS HERE <<<
    # Only the formatter of the first handler is used !  Both on the console
    # and in the file.  Change the order of these two lines to see.
    logger.addHandler(console_handler)
    logger.addHandler(file_handler)
    #
    # Proof that the two handlers have different formatters:
    print logger.handlers
    print file_handler.formatter.formatException
    print console_formatter.formatException
    #
    logger.setLevel(logging.DEBUG)
    logger.info("Logger ready.")

setup('test.log')
logger = logging.getLogger()
logger.debug("Only visible in the file.")
try:
    1/0
except ZeroDivisionError:
    logger.exception("boom")

这是怎么回事呢？

补充：顺便说一下，我使用的是python 2.6。补充：代码中关于"console_formatter"变量名的拼写错误已更正。

Answer 1

我第一次运行你的代码时，出现了一个错误追踪信息：

Traceback (most recent call last):
  File "logger.py", line 42, in <module>
    setup('test.log')
  File "logger.py", line 37, in setup
    print console_formatter.formatException
NameError: global name 'console_formatter' is not defined

这可能就是问题的根源。当我修改了 console_handler 的代码后，格式就正确了：

console_handler = logging.StreamHandler(sys.stderr)
console_handler.setLevel(logging.INFO)
console_formatter = ConsoleFormatter("%(levelname)-8s - %(message)s")
console_handler.setFormatter(console_formatter)

Answer 2

这是我写的代码。它能完成任务 :).

class CachelessFormatter(logging.Formatter):
    # I came up with that after reading the answers to
    #     http://stackoverflow.com/questions/5875225/
    # which pointed me to
    #     http://bugs.python.org/issue6435
    # I still think Vinay Sajip has a bit of an attitude :p.
    def format(self, record):
        # Disable the caching of the exception text.
        backup = record.exc_text
        record.exc_text = None
        s = logging.Formatter.format(self, record)
        record.exc_text = backup
        return s

class ConsoleFormatter(CachelessFormatter):
    def formatException(self, exc_info):
        return "           %s: %s" % exc_info[:2]

def setup(path):
    file_handler = logging.FileHandler(path, mode='w')
    file_handler.setLevel(logging.DEBUG)
    formatter = CachelessFormatter("%(asctime)s %(levelname)-8s "
                                   "%(name)-16s %(message)s "
                                   "[%(filename)s@%(lineno)d in %(funcName)s]")
    file_handler.setFormatter(formatter)

    console_handler = logging.StreamHandler(sys.stderr)
    console_handler.setLevel(logging.INFO)
    formatter = ConsoleFormatter("%(levelname)-8s - %(message)s")
    console_handler.setFormatter(formatter)

    logger = logging.getLogger()
    logger.addHandler(file_handler)
    logger.addHandler(console_handler)
    if __debug__:
        logger.setLevel(logging.DEBUG)
    else:
        logger.setLevel(logging.INFO)
    logger.info("Logger ready.")

if __name__ == '__main__':
    setup('test.log')
    logger = logging.getLogger()
    logger.debug("Only shows in the file")
    try:
        1 / 0
    except ZeroDivisionError:
        pass
    logger.exception("boom")

Answer 3

我找到了你的问题！如果你查看一下 logger/__init__.py 文件中 Formatter.format 的源代码，在第440行（对于py2.6版本），你会看到以下内容：

        if record.exc_info:
            # Cache the traceback text to avoid converting it multiple times
            # (it's constant anyway)
            if not record.exc_text:
                record.exc_text = self.formatException(record.exc_info)

在你的情况下，这个说法是不正确的，因为你重写了 formatException。如果你把 if not record.exc_text 这一行注释掉（并相应调整缩进），似乎就能按预期工作了。

这个bug似乎已经在这里报告过了： http://bugs.python.org/issue6435