为何设置RotatingFileHandler的maxBytes会让DerivedFormatter.format被调用两次？

当给RotatingFileHandler设置maxBytes参数后，每条日志记录都会导致自定义DerivedFormatter的format()方法被调用两次，但最终只有一条日志写入文件。如果注释掉maxBytes的设置，format()就只会被调用一次。需要解释这个现象，并且找到避免重复执行format()中逻辑的方法。

示例代码 #

# Python 3.10.6
import logging
from logging.handlers import RotatingFileHandler

class DerivedFormatter(logging.Formatter):
    def __init__(self, fmt=None, datefmt=None, style='%'):
        super().__init__(fmt, datefmt, style)

    def format(self, record):
        print("format_override called.")
        return super().format(record)


format = '%(asctime)s | %(levelname)-8s | %(filename)s | %(message)s'
log_file = "fubar.log"

Log = logging.getLogger()
Log.handlers.clear()
Log.setLevel(logging.DEBUG)

fhandler = RotatingFileHandler(log_file)
fhandler.maxBytes = 102400 # comment this line
fhandler.backupCount = 1
fhandler.setFormatter(DerivedFormatter(format))
Log.addHandler(fhandler)

Log.info("something happened")

原因分析 #

当设置了maxBytes时，RotatingFileHandler的逻辑会在真正写入日志前先检查当前日志文件的大小是否已经达到阈值。为了准确计算写入当前日志记录后文件是否会超过maxBytes，Handler会先调用format()方法得到格式化后的日志内容，计算它的字节长度——这是第一次format()调用。

确认文件不需要滚动后，Handler会再次调用format()获取内容并写入文件，这就触发了第二次调用。

如果没有设置maxBytes，Handler不需要做这个预检查，只会在写入时调用一次format()。

解决方法 #

1. 转移有副作用的逻辑 #

不要在format()方法里执行那些不能重复执行的逻辑（比如修改外部状态、发送请求等），把这些逻辑转移到其他日志流程节点：

• 可以自定义logging.Filter，在filter()方法里处理这些逻辑（每个日志记录只会经过一次filter）
• 或者重写RotatingFileHandler的emit()方法，在格式化前执行逻辑

2. 缓存格式化结果 #

在format()方法里给日志记录（record对象）添加一个自定义属性，标记是否已经完成格式化，第二次调用时直接返回缓存结果：

class DerivedFormatter(logging.Formatter):
    def format(self, record):
        # 检查是否已经格式化过
        if hasattr(record, '_formatted_message'):
            return record._formatted_message
        
        print("format_override called.")
        formatted = super().format(record)
        # 缓存结果到record对象
        record._formatted_message = formatted
        return formatted

注意：record对象可能会被多个Handler处理，所以如果有多个Handler共享同一个Formatter，需要确保这个自定义属性不会引发冲突。

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