Python logging 怎样为每个请求附加上下文

请求日志一多，最先失去价值的通常不是时间戳，而是“这条日志属于哪个请求”。Python logging 可以把 request_id、user_id 等字段放进每条 LogRecord，但要先选对上下文边界：字段由调用方明确持有时用 LoggerAdapter，字段需要在线程和 asyncio 任务之间隔离时，用 ContextVar 配合 Filter。

官方文档入口：https://docs.python.org/3/library/logging.html。下面按“固定字段”和“动态请求范围”两种压力拆开，给出只依赖标准库的写法，并把 Formatter 缺字段、上下文串号和清理责任一起说明。

请求量上来后，为什么日志会丢掉 request_id

最简单的做法是每次调用日志时手工写 extra。它在小函数里没有问题，但请求经过多层服务后，调用方要么反复传递字段，要么把请求信息塞进模块级变量。前者让函数签名变重，后者在并发请求下很容易把 A 请求的字段带到 B 请求的日志里。

可以先把需求分成三类：

这三个选项不是互斥开关，而是不同的所有权表达。先确定字段由谁持有，再决定如何注入，比先写一个“全局日志工具”更稳。

先用 LoggerAdapter 解决固定请求字段

LoggerAdapter 包装一个普通 logger，并持有一个类似字典的 extra 对象。调用适配器的 info()、warning() 或 exception() 时，字段会进入对应的 LogRecord，因此格式化字符串可以直接使用 %(request_id)s。

# adapter_logging.py：把请求字段固定在一个适配器上，供下层函数复用。
import logging

logger = logging.getLogger("service")
logger.setLevel(logging.INFO)

# 这里的字段必须和 Formatter 中的占位符保持一致。
handler = logging.StreamHandler()
handler.setFormatter(logging.Formatter(
    "%(levelname)s request_id=%(request_id)s user_id=%(user_id)s %(message)s"
))
logger.addHandler(handler)

def load_profile(log: logging.LoggerAdapter, user_id: str) -> None:
    # 下层函数只接收适配器，不需要重复接收 request_id。
    log.info("开始读取用户资料 user=%s", user_id)

def handle_request(request_id: str, user_id: str) -> None:
    # 每个请求创建自己的上下文字典，避免修改共享状态。
    request_log = logging.LoggerAdapter(
        logger,
        {"request_id": request_id, "user_id": user_id},
    )
    request_log.info("请求进入")
    load_profile(request_log, user_id)
    request_log.info("请求完成")

这个方案的边界很明确：request_log 是请求范围内的对象，下层函数继续使用它即可。不要在每个连接或用户永久创建一个新的底层 Logger；Python 的 Logging Cookbook 也提醒，按无限增长的粒度创建 logger 会让管理变得困难。

还要注意格式化字符串。如果某一条记录没有 request_id，而 Handler 的 Formatter 又强行读取这个字段，输出阶段可能出现格式化错误。实践中可以让同一个 Handler 只接收已经补齐字段的记录，或者在 Filter 中给缺省值；不要把“偶尔缺字段”留到线上才发现。

异步请求用 ContextVar 保留上下文

当业务函数很多、又不想把 logger 一层层传下去时，可以把当前请求的上下文放入 ContextVar。它保存的是当前上下文，而不是一个所有协程共享的普通全局变量；Python 文档说明，这类上下文变量适合同时面对线程和 asyncio 的并发代码。

# context_logging.py：让 Filter 从当前请求上下文补齐 LogRecord 字段。
import asyncio
import contextvars
import logging

request_id_var = contextvars.ContextVar("request_id", default="-")

class RequestContextFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        # 每条记录都读取当前任务的值，不读取共享可变字典。
        record.request_id = request_id_var.get()
        return True

logger = logging.getLogger("async-service")
logger.setLevel(logging.INFO)
handler = logging.StreamHandler()
handler.addFilter(RequestContextFilter())
handler.setFormatter(logging.Formatter(
    "%(levelname)s request_id=%(request_id)s %(message)s"
))
logger.addHandler(handler)

async def query_cache() -> None:
    # 业务函数不需要知道 request_id 从哪里来。
    logger.info("查询缓存")
    await asyncio.sleep(0)

async def handle_request(request_id: str) -> None:
    # 保存 Token，finally 中恢复进入本函数前的上下文。
    token = request_id_var.set(request_id)
    try:
        logger.info("请求进入")
        await query_cache()
        logger.info("请求完成")
    finally:
        # 恢复上下文，避免当前任务后续复用旧的请求字段。
        request_id_var.reset(token)

这里的关键链路是“入口设置—Filter 读取—记录补字段—请求结束恢复”。ContextVar.set() 返回的 Token 不是装饰品，它保存了恢复前的状态。没有 finally 的清理，长生命周期任务或复用执行上下文的代码就可能把旧请求信息带到后续日志中。

如果请求入口本身是异步框架的任务边界，ContextVar 的值会随任务上下文工作；如果跨越线程池、队列或手工创建的新执行上下文，则应确认上下文是否被显式复制。不要把“同一个进程”误认为“所有代码天然共享同一份请求上下文”。

Formatter、Filter 和清理责任要放在同一张图里

请求日志的实现通常有三个位置：入口负责写入上下文，Filter 负责把上下文变成记录字段，Formatter 负责输出字段。三者任意一个缺位，日志就会出现“值没设置”“字段名对不上”或“异常发生在格式化阶段”的问题。

如果应用接入了第三方库，它们可能直接使用自己的 logger，不一定带有业务字段。更稳的方式是让 Handler 上的 Filter 为缺失字段提供默认值，或者把业务日志和库日志分到不同 Handler；这样一条库日志不会因为缺少 request_id 让整个输出链路报错。

按并发模型选择最小方案

可以用下面的判断收口：

1. 请求字段只在少数函数之间传递：优先使用 LoggerAdapter，对象所有权清楚，测试也容易替换。
2. 大量下层代码都要读取当前请求：使用 ContextVar，在 Handler 的 Filter 中注入记录字段，减少业务函数参数。
3. 既需要统一上下文，又需要临时字段：让 Filter 提供稳定的默认字段，特殊日志再使用单次 extra，同时避免覆盖同名字段。
4. 跨线程、队列或进程传递：把 request_id 当作显式消息字段传递，到了新边界重新设置 ContextVar，不要假设上下文自动穿透所有执行器。

这套安排的取舍是：Adapter 更显式，ContextVar 更省参数但更依赖边界清理；Filter 让业务代码干净，却会把字段完整性责任集中到日志配置。规模越大，越要把“谁创建、谁读取、谁恢复”写成约定，而不是只保留一段能打印的示例。

常见问题

LoggerAdapter 和直接写 extra 有什么区别？ 直接写 extra 适合一条特殊日志；LoggerAdapter 把同一组上下文绑定到一个可传递的日志对象，适合一个请求中的多次记录。

ContextVar 可以替代所有请求参数吗？ 不建议。它适合日志、追踪标识这类横切上下文；业务决策依赖的数据仍应通过参数或明确对象传递，否则调用关系会变得隐式。

为什么设置了 request_id，Formatter 仍然报字段不存在？ 可能是 Filter 没挂在实际处理该记录的 Handler 上，也可能是第三方 logger 没有经过同一条处理链。先确认记录流向，再为缺失字段提供默认值。

最终可以记成一句话：固定字段用 LoggerAdapter，异步请求范围用 ContextVar，记录补字段交给 Filter，输出前由 Formatter 统一格式化，结束时一定 reset。这比在每个日志调用点手写 request_id 更容易扩展，也更容易解释并发下的字段归属。