现场是这样的。structlog 24.1 加 uvicorn 0.30,启动后每条 access log 出现两次,一条带 trace_id 一条不带,日志文件体积翻倍。

中间走过弯路,把「reload 模式起了两个进程」当成主因,改完现象没变。

把日志和配置对完,能解释这个现象的基本就这几处。uvicorn 自己的 logger 没有关掉 propagate;structlog 和标准库同时挂了 handler;中间件里又手动打了一次访问日志。

动手时先看重复两行的字段差异

python -c "print('trace_id' in open('app.log',encoding='utf-8').readline())"

随后关掉 uvicorn 的日志传播

python -c "import logging;logging.getLogger('uvicorn.access').propagate=False;print('off')"

只保留 structlog 的处理器

python -c "import structlog;structlog.configure(processors=[structlog.processors.JSONRenderer()]);print(structlog.get_logger().info('x'))"

等前面都确认过,再统计单请求日志行数

python -c "print(sum(1 for l in open('app.log',encoding='utf-8') if '/health' in l))"

同一份数据我导出了两份,一份留底,一份拿来试。

这类问题以前遇到过,但这次的触发条件和上次不一样。

怎么算真的好了,看的是同一批现象。同一请求只出现一条访问日志,trace_id 字段齐全,日志文件增速回到原来的一半。

提醒一点。接第三方框架时先看它有没有自己的 handler,重复输出多半是两条链路在写同一个 sink。报错文案容易误导,真正的原因往往在相邻那一层的日志里。

作者 9823189