Python Logging：不同Handler的Formatter为何相互干扰？

测试代码 #

import logging

def log_something():
    log.error("Normal error")
    try:
        raise RuntimeError("Exception!")
    except Exception as e:
        log.exception(e)

class MyFormatter(logging.Formatter):

    def formatException(self, exc_info):
        return "Too bad"

s_handler = logging.StreamHandler()
s_handler.setFormatter(MyFormatter(fmt="My formatter: %(message)s"))
f_handler = logging.FileHandler("log.txt")

log = logging.getLogger()
log.addHandler(f_handler) # first
log.addHandler(s_handler) # second -- why does the order matter?

log_something()

第一种添加顺序的输出 #

My formatter: Normal error
My formatter: Exception!
Traceback (most recent call last):
  File "exception.py", line 6, in log_something
    raise RuntimeError("Exception!")
RuntimeError: Exception!

此时自定义Formatter的formatException方法未被调用。

调换Handler添加顺序后的代码片段 #

log.addHandler(s_handler)
log.addHandler(f_handler)

调换顺序后的输出 #

My formatter: Normal error
My formatter: Exception!
Too bad

两种情况下文件和流的日志输出完全一致。

疑问 #

1. 为何先添加的Handler的Formatter会被后续Handler复用？原以为Formatter属于对应Handler，彼此不会干扰。
2. 为何format()方法在两种情况都会被调用，但formatException()仅在自定义Formatter的Handler先添加时生效？似乎第二个Handler的Formatter被忽略，始终使用第一个的Formatter，这是为何？本以为不同Handler可使用不同Formatter。

解答 #

核心原因：LogRecord的缓存机制 #

当调用log.exception()时，日志记录对象（LogRecord）会生成异常追踪内容，但**LogRecord会缓存格式化后的最终信息**，后续Handler处理时会直接读取缓存结果，不会再触发自身Formatter的formatException方法。

对两个疑问的具体解释

1. 并非Formatter复用，而是缓存机制跳过重复格式化
   每个Handler确实拥有独立的Formatter，但日志流程中，第一个处理该LogRecord的Handler会完成完整格式化（包括调用formatException处理异常），并将最终结果存入LogRecord的message属性。后续Handler处理时，会直接使用这个已缓存的message，不会再调用自身Formatter的formatException——除非Formatter显式配置了%(exc_text)s占位符，默认情况下不会触发。

   你代码中的f_handler未设置Formatter，会使用logging默认Formatter。当它先被添加时，会先把完整Traceback格式化后存入LogRecord，后续s_handler的自定义Formatter只能处理这个已生成的message，无法再调用自己的formatException。反之，s_handler先处理时，会把异常替换成"Too bad"并缓存，后续f_handler也只能复用这个结果。

2. format()与formatException()的调用时机差异

   • format()会被每个Handler调用，但它优先检查LogRecord是否已有缓存的message，有则直接使用；无则根据格式字符串生成内容。对于普通日志（如log.error("Normal error")），没有异常信息，每个Handler都会用自身Formatter生成message，所以你能看到s_handler的格式生效。
   • formatException()仅在LogRecord的exc_info不为空，且当前Handler是第一个处理该记录、未生成缓存message时才会触发。一旦第一个Handler完成格式化，message被缓存，后续Handler的formatException就没有执行机会了。

解决方法 #

如果需要让不同Handler用各自的Formatter独立处理异常，可采用以下方式：

• 给每个Handler的Formatter显式添加%(exc_text)s格式占位符，强制Formatter重新处理异常信息，而非复用缓存的message。示例：

  s_handler.setFormatter(MyFormatter(fmt="My formatter: %(message)s%(exc_text)s"))
  # 给文件Handler也配置Formatter
  f_handler.setFormatter(logging.Formatter(fmt="Default formatter: %(message)s%(exc_text)s"))
  

• 自定义Handler，在处理前重置LogRecord的message属性，不过这种方式复杂度较高，一般不推荐。

内容的提问来源于stack exchange，提问作者musbur