Python logging 日志重复打印排查：为什么一条记录输出了两遍

Python 项目里经常会遇到一个看起来很小、但很影响排查的问题：明明只调用了一次 logger.info()，终端或日志文件里却出现两条甚至更多相同记录。线上排查时，如果每条业务日志都重复打印，告警数量、日志费用和问题判断都会被放大。

这篇文章用一个最小复现，按“问题现场 -> 初步判断 -> 动手验证 -> 定位原因 -> 修复方案 -> 验证结果”的顺序，排查 logging 重复打印的常见原因。

问题现场：一条日志为什么出现两遍

先看一个常见现象。业务代码只写了一句：

logger.info("order created")

终端里却输出了两次：

2026-06-27 22:30:01 INFO order created
2026-06-27 22:30:01 INFO order created

这种问题通常不是 info() 调用了两遍，而是同一条日志被多个输出器处理了。我们先不要改业务代码，先看 logging 配置。

初步判断：先看 logger 身上有几个 handler

logging 里真正负责输出的是 handler。一个 logger 可以挂多个 handler；子 logger 还可能把日志继续传给父 logger。只要链路里出现多个输出器，一条记录就可能打印多次。

可以先加一段临时检查代码：

import logging

logger = logging.getLogger("app.order")

print("logger handlers:", logger.handlers)
print("root handlers:", logging.getLogger().handlers)
print("propagate:", logger.propagate)

重点看三个结果：

• logger.handlers 是否越来越多。
• root logger 是否已经有控制台输出器。
• propagate 是否为 True，导致日志继续向上传播。

动手验证：复现重复 addHandler 的问题

下面这个例子会稳定复现重复输出。原因是每次调用 setup_logger() 都会重新挂一个 StreamHandler。

import logging

def setup_logger() -> logging.Logger:
    logger = logging.getLogger("app.order")
    logger.setLevel(logging.INFO)

    handler = logging.StreamHandler()
    formatter = logging.Formatter("%(asctime)s %(levelname)s %(message)s")
    handler.setFormatter(formatter)
    logger.addHandler(handler)
    return logger

logger = setup_logger()
logger = setup_logger()

logger.info("order created")

运行后你会看到同一条日志输出两次。这里不是 info() 调用了两次，而是同一个 logger 上挂了两个控制台输出器。

定位原因：basicConfig 和传播链一起生效

还有一种常见情况：项目入口调用了 logging.basicConfig()，某个模块又给自己的 logger 加了 handler，同时 propagate 还是默认的 True。结果就是模块 logger 输出一次，父 logger 再输出一次。

import logging

logging.basicConfig(
    level=logging.INFO,
    format="%(asctime)s %(levelname)s %(message)s",
)

logger = logging.getLogger("app.order")
logger.setLevel(logging.INFO)

handler = logging.StreamHandler()
logger.addHandler(handler)

logger.info("order created")

这段代码的问题是输出路径重叠：root logger 已经能输出，app.order 又额外挂了一个输出器，并且还会继续向上传播。

修复方案：集中初始化并阻止重复挂载

修复思路有两个：日志配置集中初始化；每个 logger 挂 handler 前先判断是否已有 handler。下面是一个更稳的写法。

import logging

def get_app_logger(name: str) -> logging.Logger:
    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)
    logger.propagate = False

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

    return logger

logger = get_app_logger("app.order")
logger = get_app_logger("app.order")

logger.info("order created")

这个版本做了两件事：

• if not logger.handlers 防止重复挂载输出器。
• logger.propagate = False 防止记录继续交给父 logger 再输出一次。

如果团队已经规定所有日志都交给 root logger 统一处理，那就不要在业务模块里单独 addHandler。保持一种风格，比到处修补更稳定。

验证结果和排查清单

修复后重新运行，预期只输出一条：

2026-06-27 22:30:01 INFO order created

最后给一份排查清单：

• 同一个 logger 是否被多次调用初始化函数。
• 挂 handler 前是否判断过 logger.handlers。
• 是否同时使用了 basicConfig 和业务模块自定义 handler。
• 子 logger 的 propagate 是否符合预期。
• Web 框架或任务框架是否已经接管日志配置。

总结一下：Python logging 重复打印，通常不是业务代码重复运行，而是输出器重复挂载或传播链重叠。先看 handler 数量，再看 root 配置，最后检查 propagate，基本就能把问题定位清楚。