Python 框架指南 · 第 13 章

日志 loguru

本章你将学会 - 为什么 print 不能当日志用(无级别、无时间、无上下文、不能关),标准 logging 又输在哪(配置繁琐、堆栈不直观) - loguru 核心用法:logger.add 装配 sink、级别…

约 55 分钟22,005 字37 个代码示例

本章你将学会

  • 为什么 print 不能当日志用(无级别、无时间、无上下文、不能关),标准 logging 又输在哪(配置繁琐、堆栈不直观)
  • loguru 核心用法:logger.add 装配 sink、级别过滤、文件轮转 rotation / 保留 retention / 压缩 compression、序列化 serialize
  • bind / contextualize 给日志挂上 request_id「行李牌」,一条日志 tracing 到一次请求
  • logger.opt(exception=True) 把异常堆栈记全,lazy 省掉白干的消息拼接,diagnose 看变量值(以及它为什么在生产必须关)
  • InterceptHandler 把标准 logging(uvicorn、SQLAlchemy 用的那套)收编进 loguru,全项目一个格式
  • FastAPI 集成:中间件注入 request_id + contextvars(兑现第 10 章「只进不出」怪癖的预告)、异常处理器里记堆栈(兑现第 09 章「堆栈只进终端」的伏笔)
  • 生产建议:本地文本、生产 JSON,日志分级策略,敏感信息脱敏

第 09 章统一异常时留了个尾巴:未知异常的完整堆栈只进 uvicorn 终端,重启终端就没了;第 10 章讲中间件时又预告过 contextvars「只进不出」的怪癖会在这章回收。这两笔账本章一起清——用 loguru 给墨集 inkhub 搭一套像样的日志系统:发布文章的每一步都有据可查,炸了能顺着 request_id 把病历单捞出来。


1. print 为什么不行:喊一嗓子不算记录

作用:把「随手 print」和「正经日志」的区别钉死,后面所有 API 才有意义。

墨集的发布接口上线第一周,运营反馈「昨天有篇文章发布失败了」。你打开代码一看:

def publish_article(article_id: int) -> None:
    print("开始发布")
    print(article_id)
    ...
    print("发布完成")  # 到底执行到哪一句了?几点执行的?哪个请求触发的?

print 是对着办公室喊一嗓子:喊的时候在场的人听见了,没在场的人(未来的你)什么都没留下。它有四宗罪:

缺什么 后果 日志系统怎么救
级别 「文章发布成功」和「数据库挂了」长得一模一样,没法筛选 DEBUG / INFO / ERROR 分级,要粗要细随取随用
时间 不知道哪天几点发生的,排障全靠猜 每条自动带高精度时间戳
上下文 几十个并发请求的输出交错在一起,分不清哪行属于哪次请求 绑定 request_id,一串日志追一次请求
开关 上线了想让 DEBUG 消失?只能挨个删代码 一处配置关级别,代码一行不动

还有第五宗:print 只会往 stdout 写,落不了盘、进不了采集系统——磁盘满了、数据库慢查询、凌晨三点的 500,全都无处追溯。

常见坑:print 不是要一刀切戒掉——写一次性脚本调试、__main__ 里输出个结果,它依然是最快的。要戒的是「把 print 当日志系统用」。


2. 标准 logging:功能全都有,用起来像手动挡

作用:知道标准库 logging 痛在哪,才懂 loguru 为什么火。

公平地说,标准 logging 功能是全的——级别、格式、轮转、分级 handler 一应俱全。问题是「把日志打对」的成本太高。墨集想要「终端出 INFO、文件出 DEBUG、文件按大小轮转」,标准写法长这样:

import logging
import logging.handlers

logger = logging.getLogger("inkhub")

formatter = logging.Formatter(
    "%(asctime)s | %(levelname)-7s | %(message)s",
    datefmt="%Y-%m-%d %H:%M:%S",
)

console = logging.StreamHandler()
console.setLevel(logging.INFO)
console.setFormatter(formatter)

file_handler = logging.handlers.RotatingFileHandler(
    "inkhub.log", maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8",
)
file_handler.setLevel(logging.DEBUG)
file_handler.setFormatter(formatter)

logger.setLevel(logging.DEBUG)
logger.addHandler(console)
logger.addHandler(file_handler)

十行起步,还没算按时间轮转(得换 TimedRotatingFileHandler,参数又是另一套)。三大痛点:

  1. 配置繁琐:handler、formatter、level 三样东西要分别构造再手动接线,每个项目重抄一遍。
  2. 异常堆栈不直观:想带堆栈得记得写 logger.error("发布失败", exc_info=True)——忘了就是一行光秃秃的消息;堆栈格式是纯文本,跟消息挤在一起。
  3. 到处 getLogger:每个文件开头 logger = logging.getLogger(__name__),忘了配 propagate 和 root handler,日志就「神秘消失」。

打个比方:标准 logging 是手动挡卡车——什么路况都能跑,但起步要踩离合、挂挡、给油三步操作。loguru 是自动挡:上车踩油门就走,老司机想手动调(它也支持),但日常场景全都自动完成。


3. loguru 上手:add 一个 sink,日志就有家了

作用:装好 loguru,理解它最核心的模型——logger 是分发台,sink 是出口。

uv add loguru

loguru 开箱即用,from loguru import logger 直接打,默认往终端输出。但它真正的用法是先「装配」——把输出接到哪儿、收到什么级别、什么格式,全由 add 说了算:

签名(挑常用的讲):

logger.add(
    sink,                    # 出口:终端 / 文件路径 / 文件对象 / 自定义函数 / 协程……
    level="DEBUG",           # 这个 sink 只接收该级别及以上的消息
    format="{time} | {level} | {message}",   # 格式模板
    filter=None,             # 过滤器:更细粒度地决定哪些消息进来(第 4 节)
    serialize=False,         # True 则每条日志序列化成一行 JSON(第 6 节)
    backtrace=True,          # 异常链完整展开(第 8 节)
    diagnose=True,           # 堆栈里标注变量值(第 8 节,生产要关!)
    enqueue=False,           # True 则走队列写入,多进程安全(第 11 节)
    # sink 是文件路径时,还能透传这些文件专属参数(第 5 节):
    # rotation=..., retention=..., compression=..., encoding=...
) -> int                     # 返回 sink 的 id,remove 时要用

一个 logger 可以 add 多个 sink:同一条消息,终端一份、文件一份、采集系统一份——分发台模式:消息只发一次,出口随便接多少个。

最小示例(墨集的最小装配):

import sys
from loguru import logger

logger.remove()  # 撤掉默认的终端 sink(不可定制,留着它日志会双份)
logger.configure(extra={"request_id": "-"})  # 给 extra 设默认值,见第 4 节的坑

logger.add(sys.stderr, level="INFO",
           format="<green>{time:HH:mm:ss}</green> | <level>{level: <7}</level> | {message}")

logger.add("logs/inkhub_{time:YYYYMMDD}.log", level="DEBUG",
           rotation="100 MB", retention="30 days", encoding="utf-8")

logger.info("墨集日志系统装配完成")
logger.success("文章发布完成:article_id=101")

顺路认识七级日志——loguru 比 logging 多了两个「人性化」级别:

级别 数值 什么时候用(墨集口径)
TRACE 5 追查疑难杂症时的细粒度流水(进来时打开,查完关)
DEBUG 10 开发排障细节:生成的 slug、SQL 参数、中间变量
INFO 20 业务里程碑:收到请求、发布完成
SUCCESS 25 INFO 的「办成了」变体:任务成功、支付到账
WARNING 30 不对劲但没死:重试了一次、缓存失效回源
ERROR 40 出错了:发布失败、下游超时
CRITICAL 50 服务要不行了:数据库连不上、磁盘满

常见坑:

  • add 调一次就多一个出口。在函数里写 logger.add(...),函数被调 3 次就是 3 个出口,一条日志打印 3 遍——装配代码只在启动时执行一次,别塞进请求处理路径里。
  • logger.remove() 不带参数删全部 sink,带 id 删单个(add 的返回值)。几乎所有项目开头都有一句 remove():默认 sink 的格式不能定制,撤了自己装。
  • rotation / retention / compression 是文件 sink 专属参数——sink 是路径时才有效,传给 sys.stderr 这种对象 sink 会直接报错。它们不在 add 的签名里,是被透传给文件 sink 的。

4. 级别与过滤:同一批日志,各取所需

作用:让不同 sink 吃不同范围的日志——终端别刷屏、文件要详尽、特殊日志单独归档。

4.1 sink 级别:出口的门槛

logger.add(sys.stderr, level="INFO")            # 终端:INFO 起步,DEBUG 刷屏免了
logger.add("logs/inkhub.log", level="DEBUG")    # 文件:DEBUG 起步,排障要的细节都在

logger.debug("生成 slug:loguru-十分钟上手")   # 只进文件
logger.info("文章发布完成")                     # 终端 + 文件都进

一句话:消息够不够格,看级别;够格了去哪些出口,看各 sink 的门槛。

4.2 filter:级别之外的第二道闸

level 只能按级别一刀切,filter 能按任意条件分流。三种写法:

# ① 函数:接收 record 字典,返回 True 才放行
logger.add("logs/billing.log",
           filter=lambda record: record["extra"].get("billing"))

# ② 字符串:只收某个模块(按 logger 名)的日志
logger.add("logs/payment.log", filter="inkhub.payment")

# ③ 字典:不同模块给不同级别(模块名 → 门槛)
logger.add(sys.stderr, filter={"inkhub": "INFO", "sqlalchemy.engine": "WARNING"})

墨集的用法:计费日志单独归档。调用处 logger.bind(billing=True).info(...) 打标记(第 7 节细讲 bind),billing.log 这个 sink 用 filter 只收带标记的——以后财务对账,翻这一个文件就够,不用在海量业务日志里捞针。

常见坑:

  • filter 函数里读 extra 字段必须用 .get():record["extra"]["billing"] 这种写法,遇到没 bind 过的普通日志直接 KeyError,炸的是日志系统本身——排障工具比业务先倒下,就很讽刺了。
  • format 模板里引用 {extra[request_id]},前提是这个字段有默认值。任何一条没绑过 request_id 的日志(比如启动日志)都会因为字段不存在而报错。解法就一句:
    logger.configure(extra={"request_id": "-"})  # 全局默认值,没绑的日志显示 "-"
    
  • sink 还可以是自定义函数(收到 record 后想干嘛干嘛)——第 12 章写测试时,把日志记进一个 list,断言「ERROR 是否出现」就有了着落。

5. 文件轮转三板斧:rotation、retention、compression

作用:日志文件不能无限长。这三个参数把「一个文件写爆磁盘」变成「档案柜自动换抽屉、定期扔旧档、旧档抽真空」。

签名(都是 add() 传给文件 sink 的参数):

logger.add(
    "logs/inkhub_{time:YYYYMMDD}.log",
    rotation="100 MB",       # ① 什么时候换新文件
    retention="30 days",     # ② 旧文件留多久
    compression="zip",       # ③ 退下来的旧文件压成压缩包
)

① rotation——换抽屉的触发条件。三种触发方式:

rotation="100 MB"     # 按大小:写满 100 MB 就换新文件(最常用)
rotation="00:00"      # 按时刻:每天零点换("midnight" 等价)
rotation="1 week"     # 按间隔:每 7 天换("Monday" 表示每周一换)

文件名里的 {time:YYYYMMDD} 占位符会被替换成 add 时刻的时间戳——每次轮转生成的新文件名都不同,绝不含糊。

② retention——保洁阿姨多久来一趟。旧的轮转文件留多少:

retention="30 days"   # 只留最近 30 天的旧档
retention=10          # 只留最近 10 个旧档

③ compression——退下来的旧档抽真空:

compression="zip"     # 旧档自动压成 .zip("gz" 也常用)

顺序是固定的:写满 → 换新文件 → 超龄的旧档被删 → 剩下的旧档压成 zip。一行配置,磁盘永远体面。

最小示例(墨集生产配置长这样):

logger.add(
    "logs/inkhub_{time:YYYYMMDD_HHmmss}.log",
    level="DEBUG",
    rotation="100 MB",       # 单文件最多 100 MB
    retention="30 days",     # 旧档留一个月
    compression="zip",       # 旧档压缩,磁盘占用再砍一刀
    encoding="utf-8",
)

常见坑:

  • 演示时把阈值调小(比如 rotation="2 KB"),跑几条日志就能看见轮转发生;阈值 100 MB 的话,演示要写到天荒地老。本章 demo 就是这么干的。
  • 按时间轮转("00:00")判断的是本地时间,服务器时区和你们团队时区不一致时,「每天的日志」切分点可能出乎意料。
  • retention 删除的是匹配文件名模式的旧档——文件名模板别中途改,改了之后旧模式的文件成了「无主档案」,retention 永远清不到它。

6. serialize:一行一条 JSON,喂给采集系统

作用:终端给人看,文件给机器看。生产环境的日志最终要进 ELK / Loki 这类采集系统,人家只吃 JSON。

logger.add("logs/inkhub.json", serialize=True, level="INFO")

之后每条日志是一行合法 JSON(JSON Lines 格式):

{"text": "2026-08-27 10:32:11.402 | INFO    | req-a1b2c3 | 文章发布完成:article_id=101\n", "record": {"elapsed": {"repr": "...", "seconds": 3.2}, "exception": null, "extra": {"request_id": "req-a1b2c3"}, "file": {"name": "publish.py", "path": "..."}, "function": "publish_article", "level": {"icon": "ℹ️", "name": "INFO", "no": 20}, "line": 42, "message": "文章发布完成:article_id=101", "module": "publish", "name": "inkhub.publish", "process": {"id": 90367, "name": "MainProcess"}, "thread": {"id": 1, "name": "MainThread"}, "time": {"repr": "...", "timestamp": 1770000000.0}}}

text 是渲染好的整行文本;record 是结构化原始数据——级别、模块、函数、行号、extra 里的 request_id,全都是独立字段。采集系统按 record.extra.request_id 建索引,一次请求的全部日志一秒筛出来。

本地开发用不上它(人眼看 JSON 累),第 11 节会给「本地文本、生产 JSON」的切换模板。

常见坑:serialize 的是 loguru 自己的 record 结构,不是你想像的 {"level": ..., "msg": ...} 轻量格式。接采集系统时字段路径写对(消息在 record.message,上下文在 record.extra),别按直觉猜。


7. bind 与 contextualize:给日志挂行李牌

作用:解决第 1 节的第三宗罪——并发请求的日志交错,谁也分不清哪行属于哪次请求。给同一次请求的所有日志挂同一张「行李牌」:request_id。

loguru 有一整套「上下文」工具,按出场顺序:

① logger.bind()——手动挂一张牌:

log = logger.bind(request_id="req-a1b2c3")
log.info("收到发布请求")        # 这两条日志的 extra 里有 request_id
log.success("文章发布完成")     # 这条也是
logger.info("另一条普通日志")    # 这条没有——bind 只作用于返回的那个 log 对象

适合小范围使用;全项目每处都 bind 一遍?不现实。

② logger.contextualize()——作用域内全程自动挂:

with logger.contextualize(request_id="req-a1b2c3"):
    logger.info("请求开始")            # 自动带 request_id
    publish_article(101, "...")        # 函数内部所有 logger 调用都带(不用传参!)
    logger.info("请求结束")            # 还是带
logger.info("出了作用域")              # 不带了

with 块里所有日志调用自动带上字段——业务函数一行都不用改。它底层就是 contextvars 实现的,所以在 asyncio 里天然安全(每个并发任务各拿各的上下文副本,互不串门)。

③ logger.configure(extra=...)——给所有人发默认牌:第 4 节已经出场,没绑定的日志兜底显示 "-",防 format 报错。

④ logger.configure(patcher=...)——全局盖章机(进阶姿势):

import contextvars

request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar(
    "request_id", default="-"
)

logger.configure(patcher=lambda record: record["extra"].update(
    request_id=request_id_var.get()
))

每条日志落盘前,patcher 都被调用一次,从 contextvar 里捞当前值盖进 extra。好处:不管日志从哪来(哪怕是被第 9 节收编的标准 logging),只要它跑在「设置过 contextvar 的上下文」里,就自动带牌。第 10 节的 FastAPI 实战会看到这个好处值多少钱。

常见坑:

  • bind 和 filter 是配套的:filter 里用 record["extra"].get("billing") 判断的标记,正是 bind(billing=True) 挂上去的。挂标记的和消费标记的要约好字段名。
  • contextualize 是 with 语句,异常穿出 with 时上下文会被恢复——这个细节在第 10.3 节会变成一个真实的坑,先记下。

8. opt():堆栈、lazy 与调用深度

作用:logger.opt() 是「本条日志的特殊选项」,一次调用可以同时开好几个挂件。三个最值钱的:exception、lazy、depth。

8.1 exception=True:把病历单打全

第 09 章的家规:堆栈进日志、不进响应。loguru 里这么写:

def publish_article(article_id: int) -> None:
    try:
        sync_to_search(article_id)
    except TypeError:
        # 显式带上堆栈——不需要在 except 块里,任何地方都能用
        logger.opt(exception=True).error("同步搜索引擎失败:article_id={}", article_id)

logger.exception("...") 是它的快捷方式(等价于 opt(exception=True).error),但只能在 except 块里用;opt(exception=True) 还能显式传异常对象——opt(exception=exc),第 10.3 节在异常处理器里就靠它。

输出长这样(loguru 的招牌):

10:32:11 | ERROR | req-g7h8i9 | 同步搜索引擎失败:article_id=103
Traceback (most recent call last):

  File "publish.py", line 93, in publish_article
    sync_to_search(slug, article_id)
    │              │     └ 103
    │              └ 'loguru-十分钟上手'
    └ <function sync_to_search at 0x1096a2790>

  File "publish.py", line 83, in sync_to_search
    url = "/search/index/" + article_id
                             └ 103

TypeError: can only concatenate str (not "int") to str

注意堆栈里那些 └ 103——每个变量的值直接标在旁边,一眼看出 article_id 是 int 才炸的。这是 diagnose=True 的功劳。

8.2 backtrace 与 diagnose:堆栈的两档火力

这两个是 add() 的 sink 级参数(不是 opt 的!),控制堆栈渲染的详细程度:

参数 默认 管什么
backtrace True 异常链(raise ... from ... 的因果链)是否完整展开
diagnose True 堆栈里是否标注变量值

坑(本章最大的安全坑):diagnose 默认是开的,而变量值里可能有密码、token、用户手机号——生产环境写文件 sink 时必须显式关掉:

logger.add("logs/inkhub.log", diagnose=False)   # 生产:堆栈照打,变量值不打

开发环境留着它,是排障神器;生产环境关掉它,是安全底线。

8.3 lazy:消息没人收,参数就不求值

作用:高频 DEBUG 日志的性能保险。消息级别低于所有 sink 的门槛时,这条日志注定被丢弃——那为它拼接字符串就是纯浪费。lazy=True 让参数延迟到「确定要记」才求值:

def build_tracking_payload(article_id: int) -> str:
    ...  # 读缓存、拼 JSON,一套昂贵操作

# 生产 sink 是 INFO 起步:这条 DEBUG 没人收,lambda 根本不执行,零开销
logger.opt(lazy=True).debug("埋点:{}", lambda: build_tracking_payload(101))

# 万一临时把 sink 调到 DEBUG 排障,lambda 自动开始执行,一个字不用改

参数写成 lambda,loguru 只在「至少有一个 sink 要收这条消息」时才调用它。本章 demo 实测过:TRACE 级别没人收,lambda 静默跳过;DEBUG 级别有文件 sink 收,lambda 如约执行。

8.4 depth:谁记的这条日志

opt(depth=N) 让 loguru 把「日志来源」算到 N 层之外的调用者头上。平时用不着,但第 9 节的 InterceptHandler 全靠它——不然所有被收编的第三方日志,来源都写着 logging/__init__.py。


9. InterceptHandler:收编标准 logging

作用:FastAPI 生态里不只有你的代码在打日志——uvicorn 的访问日志、SQLAlchemy 的 SQL 日志、第三方 SDK,全用标准 logging。不收编的话,终端上两种格式打架,文件里只有你自己的日志,「统一日志系统」名存实亡。

思路:标准 logging 的每条消息最终都要过某个 handler——那就在 root logger 上装一个「转发器」,把消息原封不动转给 loguru。这就是官方推荐的 InterceptHandler:

import inspect
import logging
from loguru import logger


class InterceptHandler(logging.Handler):
    """标准 logging → loguru 的摆渡人。"""

    def emit(self, record: logging.LogRecord) -> None:
        # ① 级别映射:标准 logging 的级别名转成 loguru 的名字;
        #    对不上号(loguru 特有的 TRACE/SUCCESS)就退回数字级别
        try:
            level: str | int = logger.level(record.levelname).name
        except ValueError:
            level = record.levelno

        # ② 栈深度探测:往上翻调用栈,跳过 logging 模块自己的帧,
        #    让 loguru 显示的「文件:行号」是真正发起调用的地方
        frame, depth = inspect.currentframe(), 0
        while frame and (depth == 0 or frame.f_code.co_filename == logging.__file__):
            frame = frame.f_back
            depth += 1

        # ③ 转发:带上原始堆栈(record.exc_info),按探测到的深度记录
        logger.opt(depth=depth, exception=record.exc_info).log(
            level, record.getMessage()
        )

装到 root logger 上,全项目的标准 logging 一次性改道:

logging.basicConfig(handlers=[InterceptHandler()], level=0, force=True)

level=0 保证 root 不拦截任何级别(放行权交给 loguru 的各 sink);force=True 拆掉可能已存在的旧配置,保证我们的摆渡人是唯一的。

收编前后对比(墨集终端,实测):

# 收编前:uvicorn 的原生格式,跟 loguru 的格式打架
INFO:     127.0.0.1:5173 - "POST /api/articles HTTP/1.1" 201 Created

# 收编后:uvicorn 的日志也走 loguru 格式,进 loguru 的所有 sink
10:32:11 | INFO    | - | 127.0.0.1:5173 - "POST /api/articles HTTP/1.1" 201

常见坑:

  • logging.basicConfig 要在 uvicorn.run() 之前执行(放模块顶层或 create_app 里都行)。uvicorn 启动时会自己配置一遍日志,晚了就被覆盖。
  • uvicorn 默认给 uvicorn、uvicorn.error、uvicorn.access 三个 logger 挂自己的 handler 且 propagate=False——消息到不了 root,摆渡人白装。最省事的解法是启动时加一个参数:
    uvicorn.run(app, log_config=None)   # 禁止 uvicorn 摆弄 logging 配置,全权交给 InterceptHandler
    

10. FastAPI 集成:request_id 贯穿全链路

前面都是零件,这节组装成墨集的完整方案:一次请求从进门到出门,所有日志带同一个 request_id;出了异常,堆栈也能顺着 request_id 捞出来。

10.1 总装配

import logging
import sys

from loguru import logger


def setup_logging() -> None:
    """墨集日志总装:终端看 INFO,文件收 DEBUG,标准 logging 全部收编。"""
    logger.remove()
    logger.configure(extra={"request_id": "-"})

    # 终端:短格式,开发时盯屏幕
    logger.add(
        sys.stderr,
        level="INFO",
        format="<green>{time:HH:mm:ss}</green> | <level>{level: <7}</level> "
               "| {extra[request_id]} | {message}",
    )

    # 文件:长格式,带轮转(参数含义见第 5 节)
    logger.add(
        "logs/inkhub_{time:YYYYMMDD_HHmmss}.log",
        level="DEBUG",
        format="{time:YYYY-MM-DD HH:mm:ss.SSS} | {level: <7} "
               "| {extra[request_id]} | {name}:{function}:{line} | {message}",
        rotation="100 MB",
        retention="30 days",
        compression="zip",
        encoding="utf-8",
        diagnose=False,          # 生产环境:堆栈要,变量值不要(第 8.2 节的坑)
    )

    # 收编标准 logging(第 9 节)
    logging.basicConfig(handlers=[InterceptHandler()], level=0, force=True)

10.2 中间件注入 request_id:兑现第 10 章的预告

第 10 章 3.4 节埋的雷:BaseHTTPMiddleware 的 contextvars「只进不出」——中间件设置的 contextvar,端点能读到;端点设置的,中间件在 call_next 之后读不到。现在到引爆的时候了,先说结论:

这个怪癖是单向阀:上游写、下游读,畅通;下游写、上游读,是幻影。 而日志绑定恰好只需要「中间件(上游)写、业务代码(下游)读」——方向完全顺流,怪癖伤不到它。

姿势一(推荐起步):contextualize 包住 call_next:

import uuid
from collections.abc import Awaitable, Callable

from fastapi import Request, Response


@app.middleware("http")
async def request_id_middleware(
    request: Request, call_next: Callable[[Request], Awaitable[Response]]
) -> Response:
    rid = uuid.uuid4().hex[:8]          # 每次请求一枚新牌子
    with logger.contextualize(request_id=rid):
        logger.info("请求进来:{} {}", request.method, request.url.path)
        response = await call_next(request)   # 下游所有日志自动带 rid
        logger.info("请求结束:{} {}", request.url.path, response.status_code)
    response.headers["X-Request-Id"] = rid    # 回写响应头,用户报障时报这个号
    return response

实测效果(墨集终端):

10:32:11 | INFO    | cc3fbd41 | 请求进来:GET /api/articles/1
10:32:11 | INFO    | cc3fbd41 | 查询文章:article_id=1
10:32:11 | INFO    | cc3fbd41 | 请求结束:/api/articles/1 200
10:32:11 | INFO    | -        | 127.0.0.1:62149 - "GET /api/articles/1 HTTP/1.1" 200

三行业务日志同牌 cc3fbd41;最后一行是 uvicorn 的访问日志——它跑在协议层(比中间件更外层的任务里),看不到 contextvar,只能显示默认的 -。这不是 bug:访问日志本来就记录连接级信息,业务上下文由你自己的日志负责。

姿势二(进阶):contextvar + patcher 全局盖章。7 节 ④ 的配置,中间件只负责 set:

import contextvars

request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar(
    "request_id", default="-"
)

@app.middleware("http")
async def request_id_middleware(request: Request, call_next):
    request_id_var.set(uuid.uuid4().hex[:8])   # 入口 set,下游全可见
    response = await call_next(request)
    response.headers["X-Request-Id"] = request_id_var.get()
    return response

它的杀手锏在 10.3 节揭晓——先卖个关子。

常见坑:

  • 别把 set 写反方向。第 10 章实测过:在端点里 rid.set(...)、中间件在 call_next 之后读——读到的永远是旧值("unset")。单向阀只认顺流。
  • X-Request-Id 回写响应头用的是中间件自己的局部变量 rid,不依赖 contextvar 回读——天然避开怪癖。想让前端 JS 读到它,记得按第 10 章 CORS 的规矩登记进 expose_headers。

10.3 异常处理器里记堆栈:兑现第 09 章的伏笔

第 09 章的遗留问题:未捕获异常的完整堆栈只在 uvicorn 终端闪一下,服务重启就没了。现在把它变成带 request_id、进文件、可轮转可检索的正式记录。

直觉写法——在第 09 章的兜底 handler 里记:

@app.exception_handler(Exception)
async def unknown_exception_handler(request: Request, exc: Exception) -> JSONResponse:
    logger.opt(exception=exc).error("未处理异常:{}", request.url.path)
    return JSONResponse(status_code=500,
                        content={"code": "500000", "message": "服务器开小差了,请稍后重试"})

但实测发现一个意外:这条 ERROR 日志的 request_id 是 -,不是本次请求的牌子!原因藏得很深——Starlette 把注册给 Exception(和 500)的 handler 分给了洋葱最外层的 ServerErrorMiddleware,其余 handler(业务异常、HTTPException、校验异常)才交给最内层的 ExceptionMiddleware。第 10 章那张洋葱图说的「异常处理器住最内层」对业务异常成立;而 Exception 兜底 handler 住在最外面——异常一路穿出中间件、退出 contextualize 的 with 块(上下文被恢复)之后,才轮到它执行。所以姿势一在这里掉了牌子。

两条补救路线,任选其一:

路线 A(最稳):日志中间件自己接住再放行。反正异常必然穿过中间件,就在门口记:

@app.middleware("http")
async def request_id_middleware(
    request: Request, call_next: Callable[[Request], Awaitable[Response]]
) -> Response:
    rid = uuid.uuid4().hex[:8]
    with logger.contextualize(request_id=rid):
        try:
            response = await call_next(request)
        except Exception:
            # 还在 with 作用域内:堆栈带 request_id,记完放行给兜底 handler 变 500
            logger.opt(exception=True).error("未处理异常:{} {}", request.method, request.url.path)
            raise
        response.headers["X-Request-Id"] = rid
        return response

实测日志(毒丸接口 /api/boom,故意 KeyError):

10:32:12 | INFO    | 63732cef | 请求进来:GET /api/boom
10:32:12 | INFO    | 63732cef | [端点] 毒丸路由
10:32:12 | ERROR   | 63732cef | 未处理异常:GET /api/boom      ← 带 request_id 的完整堆栈

业务异常 handler(第 09 章的 BusinessException 体系)住最内层、没退出 with,天然就带 request_id,不用任何处理——实测 req-api-biz 全程在牌。

路线 B:姿势二的 contextvar + patcher。contextvar 是任务级状态,中间件入口 set 之后(只要不在 finally 里 reset),同一个任务链上更外层的 ServerErrorMiddleware 执行兜底 handler 时照样读得到——实测兜底日志稳稳带上了 req-api-boom。这就是 10.2 节卖的关子:patcher 对「所有经过这条任务链的日志」生效,包括被收编的标准 logging 和兜底 handler。

最后一件小事:第 09 章提过「注册兜底后 uvicorn 终端还会再打一份堆栈」。收编之后这份冗余也在(不带 request_id,是协议层的裸堆栈)。一般留着无妨——它是最后一道保险;嫌吵可以调 uvicorn 相关 logger 的级别。

10.4 接线总览

uvicorn.run(app, log_config=None)          # uvicorn 不自己配日志
        │
        ▼
setup_logging()                            # remove 默认 → 终端 sink + 文件 sink
        │                                   # + basicConfig 装 InterceptHandler
        ▼
request_id 中间件(contextualize / contextvar)
        │  进门发牌 → 端点/业务异常 handler 自动带牌
        │  未捕获异常穿出时:中间件 catch 记堆栈(带牌)→ raise
        ▼
Exception 兜底 handler(最外层)           # 变 500 响应;contextvar 方案下也带牌
        │
        ▼
文件 sink(rotation/retention/compression)# 带牌日志落盘,按 request_id 检索

11. 生产环境建议

11.1 本地文本、生产 JSON

人看文本、机器看 JSON,一个环境变量切换:

import os
import sys

IS_PROD = os.getenv("INKHUB_ENV") == "prod"


def setup_logging() -> None:
    logger.remove()
    logger.configure(extra={"request_id": "-"})

    if IS_PROD:
        # 生产:JSON 文件(喂采集系统),INFO 起,关 diagnose
        logger.add("logs/inkhub.json", level="INFO", serialize=True,
                   rotation="100 MB", retention="30 days", compression="zip",
                   encoding="utf-8", diagnose=False, enqueue=True)
    else:
        # 本地:彩色文本终端,DEBUG 起,开着 diagnose 排障
        logger.add(sys.stderr, level="DEBUG", diagnose=True,
                   format="<green>{time:HH:mm:ss}</green> | <level>{level: <7}</level> "
                          "| {extra[request_id]} | {message}")

    logging.basicConfig(handlers=[InterceptHandler()], level=0, force=True)

11.2 日志分级策略

级别 生产默认 团队约定(墨集口径)
DEBUG 文件可选收 只写开发排障需要的细节,不进终端
INFO 收 业务里程碑:请求开始/结束、发布完成。一条请求别超过个位数
SUCCESS 收 INFO 的成功变体,别滥用——发布成功算,查询成功不算
WARNING 收 + 告警 系统在自愈:重试、降级、缓存击穿。攒多了说明该修了
ERROR 收 + 告警 功能受损:下游超时、发布失败。出现就该有人看
CRITICAL 收 + 电话/短信 服务不可用:数据库连不上、磁盘满

两条铁律:日志不是越多越好(INFO 刷成海,真事就被淹了);ERROR 必须有人认领(没人值守的 ERROR 级别不如改叫 WARNING)。

11.3 敏感信息脱敏

日志是给开发看的,但看日志的不一定是开发——日志会进采集系统、会被运维翻、会被贴进工单。墨集的三条军规:

def mask_secret(value: str, keep: int = 4) -> str:
    """token/密码类:只露尾巴几位。"""
    return value[:0] + "*" * max(len(value) - keep, 0) + value[-keep:]


def mask_phone(phone: str) -> str:
    """手机号:139****1234。"""
    return f"{phone[:3]}****{phone[-4:]}" if len(phone) == 11 else "***"


# ① 手里的敏感值,落笔前脱敏
logger.info("登录成功:token={}", mask_secret(access_token))
logger.info("作者手机号:{}", mask_phone(author.phone))

# ② 请求体别整包记——password 字段迟早混进去;
#    要记就挑白名单字段记
logger.info("创建文章:title={} author_id={}", body.title, body.author_id)

# ③ diagnose=True 的变量值标注是隐形泄密通道(第 8.2 节),生产必关

11.4 enqueue 与多进程

uvicorn --workers 4 起四个进程时,每个进程一套独立的 loguru、各写各的文件——同名的会互相覆盖,rotation 也会打架。两个办法:

# 办法一:enqueue=True——写入丢给后台线程队列,多线程/多进程安全,
# 顺带把「写盘慢拖慢请求」也解了(磁盘卡顿时日志先排队)
logger.add("logs/inkhub.json", enqueue=True, serialize=True, ...)

# 办法二(更彻底):多 worker 直接把日志发到采集系统(Loki/ELK 的 agent),
# 本地不落文件,谁也不跟谁抢

单 worker 部署(墨集现在的规模)用办法一即可。


12. 跑一下本章 demo

完整代码在 demo/demo_loguru.py:纯脚本(不起服务),把本章核心 API 走一遍——装配 sink、request_id 行李牌、轮转三板斧、异常堆栈、lazy、收编标准 logging,示例全是墨集发布文章的业务日志。

uv add loguru
uv run demo/demo_loguru.py

实测输出节选(终端部分):

00:01:48 | INFO    | -         | 墨集日志系统装配完成,文件 sink 目录:.../demo/logs
00:01:48 | INFO    | req-a1b2c3 | 请求开始
00:01:48 | INFO    | req-a1b2c3 | 收到发布请求:author=陆墨 title=FastAPI 异步 SQLAlchemy 入门
00:01:48 | ERROR   | req-a1b2c3 | 同步搜索引擎失败:article_id=101
Traceback (most recent call last):
  ...
> File "demo_loguru.py", line 93, in publish_article
    sync_to_search(slug, article_id)
    │              │     └ 101
    │              └ 'fastapi-异步-sqlalchemy-入门'
TypeError: can only concatenate str (not "int") to str
00:01:48 | SUCCESS | req-a1b2c3 | 文章发布完成:article_id=101 slug=fastapi-异步-sqlalchemy-入门
00:01:48 | INFO    | req-d4e5f6 | 请求开始          ← 换了一枚牌子,行李牌各跟各的
...
00:01:48 | INFO    | - | 上一条 TRACE 被丢弃,lambda 没执行(终端没有『真的被调用了』)
00:01:48 | INFO    | - | >>> build_tracking_payload 真的被调用了(article_id=2)
00:01:48 | INFO    | - | 127.0.0.1:5173 - "POST /api/articles HTTP/1.1" 201   ← 标准 logging 被收编
00:01:48 | WARNING | - | SELECT articles WHERE id = 1 ... (0.8 ms)
00:01:48 | ERROR   | - | 计费回调验签失败:order=NO-1024
00:01:55 | INFO    | - | 演示结束,logs/ 目录产物:
00:01:55 | INFO    | - |   inkhub_20260828_000155.2026-08-28_00-01-55_562411.log.zip (940 bytes)
00:01:55 | INFO    | - |   inkhub_20260828_000155.2026-08-28_00-01-55_564721.log.zip (942 bytes)
00:01:55 | INFO    | - |   inkhub_20260828_000155.2026-08-28_00-01-55_566155.log.zip (938 bytes)
00:01:55 | INFO    | - |   inkhub_20260828_000155.log (739 bytes)

看点提示:ERROR 那条没打断发布流程(SUCCESS 照常出现)——堆栈记进日志、业务继续走,这正是第 09 章「不裸奔」家规的日志版;最后四行是轮转产物——三个 zip(被轮转压缩的旧档,retention=3 生效)加一个正在写的 .log。


13. 小结速查

需求 用法
撤默认 sink、自己装配 logger.remove() → logger.add(...)
一个出口收 INFO、另一个收 DEBUG add(sys.stderr, level="INFO") + add("f.log", level="DEBUG")
日志单独归档(如计费) logger.bind(billing=True).info(...) + filter=lambda r: r["extra"].get("billing")
文件轮转/保留/压缩 rotation="100 MB" / retention="30 days" / compression="zip"
生产喂采集系统 serialize=True(JSON Lines)
给日志挂 request_id with logger.contextualize(request_id=rid): ...
全局自动盖章 logger.configure(patcher=lambda r: r["extra"].update(request_id=request_id_var.get()))
extra 字段防 KeyError logger.configure(extra={"request_id": "-"})
记异常堆栈 logger.opt(exception=True).error(...)(handler 里用 opt(exception=exc))
堆栈看变量值 / 生产关掉 diagnose=True(add 参数,默认开!)/ 生产 diagnose=False
高频 DEBUG 防白拼 logger.opt(lazy=True).debug("{}", lambda: expensive())
收编标准 logging InterceptHandler + basicConfig(handlers=[...], level=0, force=True)
uvicorn 不抢日志配置 uvicorn.run(app, log_config=None)
request_id 中间件 进门 contextualize / contextvar.set,响应头回写 X-Request-Id
兜底 handler 丢 request_id Starlette 把 Exception handler 分给最外层;用「中间件 catch 记堆栈再 raise」或 contextvar+patcher
多进程安全写文件 enqueue=True

自测三问:

  1. logger.add() 被调用了两次、传了同一个文件路径,会发生什么?为什么装配代码只能跑一次?
  2. 第 10 章说 contextvars 在中间件里「只进不出」,为什么这章的 request_id 绑定不受影响?哪种方向的使用会踩坑?
  3. 生产环境哪两个配置必须显式设置,才能既保住安全又不丢排障能力?(提示:一个管变量值,一个管格式)

到这里,墨集的后端已经「说得清自己干过什么」了:每个请求有牌,每次异常有完整病历,uvicorn 和第三方库的日志也归于一统。最后一章,我们让后端「学会说话」——把内容流式地、实时地推到用户眼前。


下一章:14 · 流式响应 SSE 与 WebSocket