Python logging 为什么重复输出：propagate、handler 和层级配置的排查方法

开发环境里最烦人的日志问题之一，是同一条 INFO 在终端出现两遍，甚至一条带时间、一条不带时间。很多人先去搜业务代码，怀疑某个函数被调用了两次；但在 Python logging 里，更常见的原因是子 logger 把记录交给自己的 handler 后，又沿层级传给了父 logger。

你开发时大概率碰到过这类场景：代码里明明只写了一次日志打印，终端却连续输出好几条完全相同的日志，排查半天业务逻辑也没找到重复调用，问题其实出在logging模块的层级传播和handler挂载规则上。

排查这类重复输出问题，优先按两个方向验证：第一检查当前日志记录是否同时被子logger和父/根logger的handler捕获，第二检查日志配置初始化函数有没有被多次执行重复添加handler。

先用一段最小代码复现重复日志

下面的代码故意把同一个消息交给两个层级。app.db 有自己的终端处理器，根 logger 也有一个处理器；默认情况下，子 logger 处理完还会继续向上冒泡。

import logging

root = logging.getLogger()
root.setLevel(logging.INFO)
root.addHandler(logging.StreamHandler())

db_logger = logging.getLogger("app.db")
db_logger.setLevel(logging.INFO)
db_logger.addHandler(logging.StreamHandler())

db_logger.info("连接池已准备")

你会看到两行相同的“连接池已准备”。这不代表 info() 被执行了两次，而是同一条 LogRecord 先被 app.db 的 handler 输出，再因为 propagate=True 交给根 logger 的 handler 输出。

重复输出的关键：logger、handler 和 propagate 各管什么

排查时不要把三个概念混成一个。logger 负责接收日志记录并决定级别，handler 负责把记录写到终端或文件，propagate 只决定记录是否继续交给父 logger 的 handler。

logger 名称决定层级关系

logging.getLogger("app.db") 的父级不是一个手动保存的对象，而是名称层级中的 app，再向上才是根 logger。只要没有显式设置，记录就可能一路传到根 logger。

handler 才是真正写出一行文字的地方

同一个 logger 上挂两个 StreamHandler，也会出现两行；父子 logger 各挂一个，也会出现两行。判断重复来源，最有效的是直接打印处理器数量，而不是猜业务调用链。

logger = logging.getLogger("app.db")
print("name=", logger.name)
print("handlers=", logger.handlers)
print("propagate=", logger.propagate)
print("parent=", logger.parent.name or "root")

三步排查：先数 handler，再看传播，最后查初始化

第一步：确认是谁挂了 handler

如果项目使用了多个模块，先把目标 logger 和根 logger 的处理器列出来。logger.handlers 只包含当前 logger 的处理器，不包含父级；这正好能帮助你区分“自己重复挂载”和“向上冒泡”两类问题。

def show_logging_path(name: str) -> None:
    logger = logging.getLogger(name)
    current = logger
    while current is not None:
        print(
            current.name or "root",
            "handlers=", len(current.handlers),
            "propagate=", getattr(current, "propagate", False),
        )
        current = current.parent

show_logging_path("app.db")

第二步：明确只保留一条输出路径

如果应用希望所有日志都由根 logger 统一格式化，子 logger 不要再添加输出 handler，只设置级别，然后保持 propagate=True。如果数据库模块必须写到独立文件，则保留子 logger 的 handler，并设置 propagate=False，避免它再回到根 logger。

第三步：检查配置函数是否重复进入

模块被重复导入通常不会重复执行同一个模块体，但配置函数可能在Web启动、测试夹具和热重载入口分别调用。最稳妥的做法是让配置函数具备幂等性：配置前先清理自己管理的 handler，或用明确的初始化标记。

def configure_db_logger() -> logging.Logger:
    logger = logging.getLogger("app.db")
    logger.setLevel(logging.INFO)
    logger.propagate = False

    if not logger.handlers:
        handler = logging.StreamHandler()
        handler.setFormatter(logging.Formatter("DB %(levelname)s %(message)s"))
        logger.addHandler(handler)
    return logger

这里的 if not logger.handlers 只适用于这个 logger 的 handler 确实由当前配置函数独占的场景。如果测试需要重新配置输出目标，应该显式移除旧 handler，而不是无条件追加新 handler。

两种常见架构，选对 handler 归属

几个容易误判的坑

把 level 当成去重开关

把子 logger 的级别调成 WARNING 只能过滤低级别记录，不能阻止已经通过过滤的记录继续冒泡。去重首先看 handler 归属和 propagate。

只看 logger.handlers，漏掉根 logger

子 logger 的处理器列表为空，不代表没有输出路径。它可能完全依赖父级；排查必须沿 parent 逐级检查，尤其是根 logger。

测试环境反复配置但没有清理

如果每个测试都向同一个 logger 追加一个处理器，单测越跑输出的日志行数越多。测试结束时移除本次创建的 handler，并关闭它；不要用全局清理破坏其他测试的日志设置。

修复后的验收方式

修复不是把终端里的两行看成一行就结束。给日志内容加一个唯一标识，在一次调用中记录它，然后核对：目标 logger 的 handler 数量、父级是否仍然存在输出 handler、propagate 值，以及捕获到的行数是否为 1。

logger = configure_db_logger()
logger.info("probe-logging-001")

# 预期：终端只出现一行 probe-logging-001
# 若仍出现两行，继续沿 logger.parent 检查 handler

相关问题

为什么 basicConfig 有时不生效？

默认情况下，根 logger 已经有 handler 时，basicConfig() 不会再次替换配置。调试启动顺序时，先看根 logger 当前是否已有处理器，再决定是否在明确场景下使用强制重配置。

关闭 propagate 会不会让日志丢失？

如果子 logger 自己没有可用 handler，关闭传播会让记录没有输出。关闭前必须确认子 logger 已经挂好目标 handler，并且级别和格式都符合预期。

文件 handler 和终端 handler 可以同时保留吗？

可以，但要明确这是“同一条记录写两个目的地”，不是重复故障。若只想终端或文件二选一，就让记录只经过对应的输出路径。

把日志配置收口，重复问题就不再靠猜

Python logging 的重复输出大多能归结为两件事：同一层级挂了多个 handler，或者子 logger 输出后又通过 propagate 传给了父级。把配置入口收口，明确 handler 的归属，再用唯一标识核对实际行数，通常比在业务函数里到处加打印更快。