日志 loguru
本章你将学会 - 为什么 print 不能当日志用(无级别、无时间、无上下文、不能关),标准 logging 又输在哪(配置繁琐、堆栈不直观) - loguru 核心用法:logger.add 装配 sink、级别…
本章你将学会
- 为什么
logging又输在哪(配置繁琐、堆栈不直观)- loguru 核心用法:
logger.add装配 sink、级别过滤、文件轮转rotation/ 保留retention/ 压缩compression、序列化serializebind/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,参数又是另一套)。三大痛点:
- 配置繁琐:handler、formatter、level 三样东西要分别构造再手动接线,每个项目重抄一遍。
- 异常堆栈不直观:想带堆栈得记得写
logger.error("发布失败", exc_info=True)——忘了就是一行光秃秃的消息;堆栈格式是纯文本,跟消息挤在一起。 - 到处
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 |
自测三问:
logger.add()被调用了两次、传了同一个文件路径,会发生什么?为什么装配代码只能跑一次?- 第 10 章说 contextvars 在中间件里「只进不出」,为什么这章的 request_id 绑定不受影响?哪种方向的使用会踩坑?
- 生产环境哪两个配置必须显式设置,才能既保住安全又不丢排障能力?(提示:一个管变量值,一个管格式)
到这里,墨集的后端已经「说得清自己干过什么」了:每个请求有牌,每次异常有完整病历,uvicorn 和第三方库的日志也归于一统。最后一章,我们让后端「学会说话」——把内容流式地、实时地推到用户眼前。