现场是这样的。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。报错文案容易误导,真正的原因往往在相邻那一层的日志里。
