Python日志处理器传播问题：日志消息重复输出求助

问题背景 #

我正在为模块配置日志功能，编写了最小可复现代码，但遇到日志重复输出的问题：无论设置何种日志级别，LOGGER.error()都会被输出四次，LOGGER.warning()输出三次，LOGGER.info()输出两次，LOGGER.debug()输出一次。日志级别筛选逻辑正常，但无法定位重复输出的原因。已将logger的propagate设为False，Python版本为3.10.9。

原代码示例 #

import sys
from pathlib import Path
from datetime import datetime
import logging
start = datetime.now()
LOG_CONFIG = logging.basicConfig(
    filename=Path().cwd().stem + f"-{start.strftime('%Y-%m-%d-%H-%M-%S')}.log", filemode="w"
)
LOG_FORMATTER = logging.Formatter(
    fmt="[I %(levelname)-8s : %(message)s]"
)
LOG_DEBUG_FORMATTER = logging.Formatter(
    fmt="[D %(levelname)-8s : %(message)s]"
)
LOG_ERROR_FORMATTER = logging.Formatter(
    fmt="[E %(levelname)-8s : %(message)s]"
)
LOG_WARNING_FORMATTER = logging.Formatter(
    fmt="[W %(levelname)-8s : %(message)s]"
)
LOGGER_NAME = "test"

def setup_logger(log_name: str = LOGGER_NAME) -> logging.Logger:
    out_stream_handler = logging.StreamHandler(sys.stdout)
    out_stream_handler.propagate = False
    out_stream_handler.setLevel(logging.INFO)
    out_stream_handler.setFormatter(LOG_FORMATTER)
    debug_stream_handler = logging.StreamHandler(sys.stderr)
    debug_stream_handler.propagate = False
    debug_stream_handler.setLevel(logging.DEBUG)
    debug_stream_handler.setFormatter(LOG_DEBUG_FORMATTER)
    err_stream_handler = logging.StreamHandler(sys.stderr)
    err_stream_handler.propagate = False
    err_stream_handler.setLevel(logging.ERROR)
    err_stream_handler.setFormatter(LOG_ERROR_FORMATTER)
    warning_stream_handler = logging.StreamHandler(sys.stderr)
    warning_stream_handler.propagate = False
    warning_stream_handler.setLevel(logging.WARNING)
    warning_stream_handler.setFormatter(LOG_WARNING_FORMATTER)
    logger = logging.getLogger(log_name)
    logger.setLevel(logging.INFO)
    logger.propagate = False
    if logger.hasHandlers():
        logger.handlers = []
    if not logger.handlers:
        logger.addHandler(out_stream_handler)
        logger.addHandler(debug_stream_handler)
        logger.addHandler(err_stream_handler)
        logger.addHandler(warning_stream_handler)

    return logger

测试代码 #

LOGGER = setup_logger(log_name=LOGGER_NAME)
LEVELS = {"ERROR": logging.ERROR,
          "WARNING": logging.WARNING,
          "INFO": logging.INFO,
          "DEBUG": logging.DEBUG}
for key, value in LEVELS.items():
    print(f"################### setLevel : {key}")
    LOGGER.setLevel(value)
    LOGGER.error("ERROR Message")
    LOGGER.warning("WARNING Message")
    LOGGER.info("INFO Message")
    LOGGER.debug("DEBUG Message")

实际输出 #

################### setLevel : ERROR
I [ERROR    : ERROR Message]
D [ERROR    : ERROR Message]
E [ERROR    : ERROR Message]
W [ERROR    : ERROR Message]
################### setLevel : WARNING
I [ERROR    : ERROR Message]
D [ERROR    : ERROR Message]
E [ERROR    : ERROR Message]
W [ERROR    : ERROR Message]
I [WARNING  : WARNING Message]
D [WARNING  : WARNING Message]
W [WARNING  : WARNING Message]
################### setLevel : INFO
I [ERROR    : ERROR Message]
D [ERROR    : ERROR Message]
E [ERROR    : ERROR Message]
W [ERROR    : ERROR Message]
I [WARNING  : WARNING Message]
D [WARNING  : WARNING Message]
W [WARNING  : WARNING Message]
I [INFO     : INFO Message]
D [INFO     : INFO Message]
################### setLevel : DEBUG
I [ERROR    : ERROR Message]
D [ERROR    : ERROR Message]
E [ERROR    : ERROR Message]
W [ERROR    : ERROR Message]
I [WARNING  : WARNING Message]
D [WARNING  : WARNING Message]
W [WARNING  : WARNING Message]
I [INFO     : INFO Message]
D [INFO     : INFO Message]
D [DEBUG    : DEBUG Message]

原因分析 #

1. 多handler重复处理：你给logger添加了4个独立的StreamHandler，每个handler的setLevel()是设置最低处理级别，即该handler会处理所有≥此级别的日志：

   • out_stream_handler（INFO级别）：处理INFO、WARNING、ERROR级别的日志
   • debug_stream_handler（DEBUG级别）：处理所有级别的日志
   • err_stream_handler（ERROR级别）：仅处理ERROR级别
   • warning_stream_handler（WARNING级别）：处理WARNING、ERROR级别
     当调用LOGGER.error()时，这条日志满足所有4个handler的级别要求，因此会被输出4次，其他级别以此类推。

2. 无效的handler.propagate设置：只有logger对象拥有propagate属性，handler没有这个属性，你设置的out_stream_handler.propagate = False等代码完全无效，属于对文档的误解。

解决方案 #

不需要为每个级别单独创建handler，而是给每个handler添加级别过滤器，确保每个handler只处理对应级别的日志，同时移除无效的handler属性设置。修改后的代码如下：

import sys
from pathlib import Path
from datetime import datetime
import logging

start = datetime.now()
LOGGER_NAME = "test"

def setup_logger(log_name: str = LOGGER_NAME) -> logging.Logger:
    # 定义各日志级别对应的格式与输出流
    level_configs = [
        (logging.DEBUG, "[D %(levelname)-8s : %(message)s]", sys.stderr),
        (logging.INFO, "[I %(levelname)-8s : %(message)s]", sys.stdout),
        (logging.WARNING, "[W %(levelname)-8s : %(message)s]", sys.stderr),
        (logging.ERROR, "[E %(levelname)-8s : %(message)s]", sys.stderr),
    ]

    logger = logging.getLogger(log_name)
    logger.setLevel(logging.DEBUG)  # 将logger级别设为最低，交由handler过滤具体级别
    logger.propagate = False

    # 清空已有handler，避免重复添加
    if logger.hasHandlers():
        logger.handlers = []

    for level, fmt_str, stream in level_configs:
        handler = logging.StreamHandler(stream)
        formatter = logging.Formatter(fmt=fmt_str)
        handler.setFormatter(formatter)
        handler.setLevel(level)
        
        # 添加过滤器，确保handler仅处理当前指定级别的日志
        class LevelFilter(logging.Filter):
            def __init__(self, target_level):
                self.target_level = target_level
            def filter(self, record):
                return record.levelno == self.target_level
        
        handler.addFilter(LevelFilter(level))
        logger.addHandler(handler)

    # 添加文件日志handler（保留原功能）
    file_handler = logging.FileHandler(
        filename=Path().cwd().stem + f"-{start.strftime('%Y-%m-%d-%H-%M-%S')}.log",
        filemode="w"
    )
    file_formatter = logging.Formatter("%(asctime)s - %(levelname)-8s : %(message)s")
    file_handler.setFormatter(file_formatter)
    file_handler.setLevel(logging.DEBUG)
    logger.addHandler(file_handler)

    return logger

修改后，每个日志级别只会被对应的handler处理一次，比如LOGGER.error()只会输出[E ERROR : ERROR Message]，完全符合预期。

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