第 19 章日志：logging 模块与结构化

点题：把 print 调试扔进垃圾桶，用 logging 拿到带级别、带上下文、能轮转、能机器解析的日志，这是线上排障的命脉。

老哥，我先问你一个扎心的问题：你线上服务出问题的时候，是靠在代码里 print 一堆东西，然后盯着终端刷屏来找原因的吗？

老哥：……开发的时候会，线上当然不敢。但说实话，本地调试我确实经常 print 一下就完事。

墨叔：本地 print 一时爽，但 print 有三个致命毛病，它永远治不了。第一，没有级别，错误和调试信息混在一起，线上你没法「只看 ERROR」。第二，没有上下文，出了错你不知道这是哪个请求、哪个用户、哪个 goroutine 打的。第三，写不进文件、不能轮转、不能被日志系统采集。你 Go 里用 zap 或 logrus，一个 WithField("req_id", ...) 就把上下文带上了，JSON 一行一条直接喂给 ES。Python 的 print 连这门槛都迈不过。这章我把 Python 的 logging 体系讲透，让你写出能和 Go 日志栈平起平坐的东西。

一、logging 到底是什么，怎么用

Python 的 logging 模块是一套「分级 + 多出口 + 可格式化」的日志框架，核心四个零件：Logger（记录器，你调用的入口）、Handler（处理器，决定日志去哪：控制台/文件/网络）、Formatter（格式器，决定长什么样）、Level（级别，过滤噪音）。

最小可运行例子：

import logging
 
logging.basicConfig(
    level=logging.INFO,                       # 低于 INFO 的不打印
    format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
)
logger = logging.getLogger("order_svc")       # 取一个具名 logger
 
logger.debug("这条看不到，INFO 挡住了")
logger.info("订单创建 user=%s order=%s", 1001, "o_8821")
logger.warning("库存偏低 sku=%s", "sku_33")
logger.error("扣款失败 order=%s reason=%s", "o_8821", "timeout")

级别从低到高是 DEBUG < INFO < WARNING < ERROR < CRITICAL。basicConfig 是一次性的全局基础配置，生产里一般不用它，而是自己搭 logger + handler（下面第四节）。注意 logger.info("... %s", x) 这种延迟格式化写法——参数只在真的要输出时才拼字符串，比 f"..." 提前拼好更省（被级别过滤掉的日志不会白白做字符串拼接），这点跟 Go 里 sprintf 的代价是一个道理。

老哥：那 logger 名字有什么讲究？我随便起 getLogger("a") 不行吗？

墨叔：讲究大了。logger 是树状层级的，名字用点号分层，比如 "myapp.order"、"myapp.pay"。你在根或父节点设的级别、handler 会被子节点继承。所以规范做法是按模块取 logging.getLogger(__name__)，__name__ 正好是包路径，天然形成层级。这样你能在线上「只把 myapp.pay 调到 DEBUG，其它保持 INFO」，精准打点而不被噪音淹没——这跟 Go 里按包设日志级别是同一个工程直觉。

二、什么场景该用它，对照 Go 怎么选

对照你的 Go 经验：logging.Logger ≈ zap 的 Logger；Handler ≈ zap 的 Core/writer；Formatter ≈ Encoder（console / json）；级别机制跟 zap 的 InfoLevel/DebugLevel 一一对应。logrus 的 WithField 给日志加上下文字段，Python 里对应的是 LoggerAdapter 或 extra 参数。

什么场景必须上 logging 而非 print？答案是只要代码可能跑在不是你眼前终端的地方——也就是服务、定时任务、worker、任何会被部署的东西。本地一次性脚本 print 无伤大雅；但凡是「别人（或未来的你）要排障」的代码，print 就是失职。

还有个 Go 老兵容易踩的坑：Python 的异常默认不会自动进日志。你在 Go 里 log.Error(err) 是显式的；Python 里程序崩了抛 traceback 到 stderr，但如果你用了 logging 却没配置，可能啥也看不到。所以生产环境一定要给 root logger 配一个 handler，并且用 logger.exception(...) 在 except 块里记录——它会自动把当前 traceback 附上，这是排障金矿：

try:
    pay_order(order)
except Exception:
    logger.exception("扣款异常 order=%s", order.id)   # 自动带完整堆栈

对照 Go：Go 没有 try/except，错误是返回值，你 log.Errorw("pay failed", "order", id, "err", err)（zap）手动带 err；Python 是异常机制，logger.exception 帮你把堆栈自动打包——两种哲学，但「出错了要留完整现场」这条铁律一模一样。

三、用它的收益与代价，以及高级玩法

logging 的代价几乎为零——它是标准库、零依赖、性能足够。收益却是全方位的：级别过滤省 IO、多 handler 同时落盘+上控制台、Formatter 统一格式、还能被 logging.handlers 里的轮转处理器接管。

输出到文件并轮转。线上日志不能写一个文件写到天荒地老把磁盘撑爆，得轮转。RotatingFileHandler 按大小切，TimedRotatingFileHandler 按时间切：

import logging
from logging.handlers import RotatingFileHandler
 
logger = logging.getLogger("svc")
logger.setLevel(logging.INFO)
 
file_handler = RotatingFileHandler(
    "svc.log", maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8"
)
file_handler.setFormatter(logging.Formatter(
    "%(asctime)s [%(levelname)s] %(name)s: %(message)s"
))
console = logging.StreamHandler()            # 同时打到控制台
console.setLevel(logging.WARNING)            # 控制台只看警告以上
 
logger.addHandler(file_handler)
logger.addHandler(console)

maxBytes=10MB, backupCount=5 表示单个文件到 10MB 就滚成 svc.log.1、最多留 5 份旧文件，超出的自动删。对照 Go：zap 配 lumberjack 做轮转，思路完全一致——「日志轮转」是跨语言的运维常识，不是 Python 特色。

结构化日志（JSON）。机器要消费你的日志（喂 ES、Loki、Splunk），每行必须是一条结构化记录而不是一段人读的文本。手写 JSON 最稳，不依赖第三方：

import json, logging
 
class JsonFormatter(logging.Formatter):
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": self.formatTime(record),
            "level": record.levelname,
            "logger": record.name,
            "msg": record.getMessage(),
        }
        # 把 extra 里塞进来的业务字段也带上
        for key, val in record.__dict__.items():
            if key not in _RESERVED:
                payload[key] = val
        return json.dumps(payload, ensure_ascii=False)
 
_RESERVED = {
    "args", "asctime", "created", "exc_info", "exc_text", "filename",
    "funcName", "levelname", "levelno", "lineno", "module", "msecs",
    "message", "msg", "name", "pathname", "process", "processName",
    "relativeCreated", "stack_info", "thread", "threadName",
}
 
logger = logging.getLogger("svc")
handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())
logger.addHandler(handler)
logger.info("order paid", extra={"user_id": 1001, "order": "o_8821", "amount": 99.0})
# 输出: {"ts": "...", "level": "INFO", "logger": "svc", "msg": "order paid", "user_id": 1001, "order": "o_8821", "amount": 99.0}

extra={...} 就是把业务字段塞进日志记录，格式化时一起吐成 JSON 字段。这样一条日志在 Kibana 里就能按 user_id 精确检索——这就是 Go 里 zap.With(zap.Int("user_id", ...)) 干的事，只不过 Python 用 extra + 自定义 Formatter 实现。社区也有 structlog 这个库把这套做得更优雅（支持上下文穿透、管道式处理），项目复杂了可以直接上，但原理就是上面这套 JSON Formatter，理解了就不怕换库。

给一批日志自动带上下文（比如 request_id）。别每次手传 extra，用 LoggerAdapter 或 contextvars 把请求级上下文透传：

import logging, contextvars
 
req_id = contextvars.ContextVar("req_id", default="-")
 
class ReqFilter(logging.Filter):
    def filter(self, record: logging.LogRecord) -> bool:
        record.req_id = req_id.get()     # 每条日志自动带上当前请求 ID
        return True
 
logger = logging.getLogger("svc")
logger.addFilter(ReqFilter())
# 在请求入口：req_id.set("req_abc123")，之后所有日志自动带 req_id

这对应 Go 里「用 context 存 trace/req id，zap 的 With 透传」的模式。Python 3.7+ 的 contextvars 能在线程/asyncio 任务间正确隔离，是做请求级上下文的官方正解（详见第 5 章上下文管理器）。

四、一个贴近项目的例子

给你一个「可复用的日志接入模块」，直接拷进项目就能用：同时落盘（带轮转）+ 控制台 + JSON 结构化，并支持请求上下文。

import json, logging, contextvars
from logging.handlers import TimedRotatingFileHandler
 
req_id = contextvars.ContextVar("req_id", default="-")
 
class JsonFormatter(logging.Formatter):
    _reserved = frozenset((
        "args", "asctime", "created", "exc_info", "exc_text", "filename",
        "funcName", "levelname", "levelno", "lineno", "module", "msecs",
        "message", "msg", "name", "pathname", "process", "processName",
        "relativeCreated", "stack_info", "thread", "threadName", "req_id",
    ))
    def format(self, record: logging.LogRecord) -> str:
        payload = {
            "ts": self.formatTime(record),
            "level": record.levelname,
            "logger": record.name,
            "req_id": getattr(record, "req_id", "-"),
            "msg": record.getMessage(),
        }
        for key, val in record.__dict__.items():
            if key not in self._reserved:
                payload[key] = val
        if record.exc_info:
            payload["exc"] = self.formatException(record.exc_info)
        return json.dumps(payload, ensure_ascii=False)
 
def build_logger(name: str = "svc") -> logging.Logger:
    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)
    if logger.handlers:
        return logger                      # 避免重复 addHandler
 
    file_h = TimedRotatingFileHandler("svc.log", when="midnight", backupCount=7, encoding="utf-8")
    file_h.setFormatter(JsonFormatter())
 
    console_h = logging.StreamHandler()
    console_h.setLevel(logging.WARNING)
    console_h.setFormatter(logging.Formatter("%(asctime)s [%(levelname)s] %(message)s"))
 
    logger.addHandler(file_h)
    logger.addHandler(console_h)
    logger.propagate = False               # 不再向上冒泡到 root，避免重复输出
    return logger
 
if __name__ == "__main__":
    log = build_logger()
    req_id.set("req_xyz")
    log.info("start handle", extra={"user_id": 1001})
    try:
        1 / 0
    except Exception:
        log.exception("compute failed", extra={"step": "divide"})

几个工程要点：logger.propagate = False 防止日志既被你的 handler 处理、又被 root 的默认 handler 再打一遍（新手最常见的「日志重复输出」元凶）；if logger.handlers 守卫避免模块被重复 import 时叠加一堆 handler；TimedRotatingFileHandler(when="midnight") 按天切、留 7 天——这基本就是生产服务的标准配置。

老哥：所以一个正经 Python 服务，日志这块的开销也就这些，跟 Go 的 zap 栈是对等的？

墨叔：对等，甚至更灵活，因为 Formatter 是你自己写的，想怎么结构化都行。但我要提醒一句：logging 默认是同步的，每条日志落盘是阻塞的。超高 QPS 服务如果每条都同步写磁盘，会拖慢主流程——Go 的 zap 默认也是同步，但你们常会接异步 core。Python 里可以用 QueueHandler + QueueListener 把日志丢进队列、由单独线程消费，做到「业务线程不阻塞」。这是进阶玩法，记住有这条路，等真遇到日志成为瓶颈再上，别提前过度设计。

最后一句心法给你：日志是给「出事时的你」写的遗书。今天你觉得「这分支永远走不到」于是不打日志，三个月后它恰恰在生产炸了，而你两手空空。该打的关键路径、边界条件、异常现场，一个都别省；纯调试噪音用 DEBUG 级别，靠级别开关收放，而不是靠注释掉 print。

五、日志纪律、敏感信息与 Go 栈对照

光会把日志打出来还不够，怎么打、打多少、打什么，才是 senior 和初级的分水岭。给你几条纪律：

第一，级别要当回事，别全打 INFO。DEBUG 留给开发期细节（每次循环变量、内部状态），INFO 是正常业务里程碑（订单创建、支付成功），WARNING 是可恢复异常（重试、降级），ERROR 是处理失败（扣款失败、下游超时），CRITICAL 是服务级故障（连不上 DB）。线上默认 INFO，出事时把特定模块临时调到 DEBUG 抓现场——这正是第二节讲的层级 logger 的价值。你 Go 里用 zap 也是 AtomicLevel 动态调级，思路完全一致。

第二，高 QPS 别让日志把系统淹了。流量洪峰时，如果每请求打十几条日志，磁盘 IO 和采集带宽都会被日志吃光，反而拖垮主业务。做法有二：① 采样，比如「只记录 1% 的请求详情，或只记录慢请求（耗时 > 200ms）」；② 限流，用令牌桶控制日志输出速率。Go 的 zap 也有 Sampled 级别的概念，跨语言都是同一招。

第三，千万别往日志里打敏感信息。用户密码、身份证、手机号、token——这些东西一旦进日志，就被落盘、被采集系统全文索引、被运维同事肉眼可见，合规事故分分钟找上门。正确做法是打之前脱敏（手机号只留后四位、token 只打前缀），或在 Formatter 里加一个「敏感字段黑名单」自动遮蔽。这点是很多新手忽略、却最致命的一条。

第四，日志也要写测试。你 Go 里会给关键逻辑写单测，日志同理：用 caplog 这个 pytest 夹具（第 25 章会展开）可以断言「某函数是否以预期级别、预期消息打了日志」，防止有人把关键日志不小心删了还浑然不知。把「关键路径必须留痕」变成可执行的测试约束，比靠 code review 嘴上说靠谱得多。

再给你一张和 Go 的对照表，方便你把旧知识直接挂靠：

诉求	Go（zap / logrus）	Python（logging）
分级	`InfoLevel` / `ErrorLevel`	`INFO` / `ERROR` 等 Level
带上下文字段	`With(zap.String("k", v))`	`extra={...}` / `LoggerAdapter`
结构化 JSON	`zap.NewJSONEncoder`	自定义 `JsonFormatter`
文件轮转	`lumberjack`	`RotatingFileHandler` / `TimedRotatingFileHandler`
请求级透传	`context.Context`	`contextvars` + `Filter`
动态调级	`AtomicLevel`	改 logger `setLevel`
异步不阻塞	异步 core	`QueueHandler` + `QueueListener`

如果项目复杂、你想更优雅地做结构化日志，社区有 structlog 这个库，它把「上下文累积、处理器管道、JSON 输出」封装得非常好，写法和我们第四节手搓的 JSON Formatter 原理相通，只是更顺手。我的建议是：小项目手搓 formatter 够用，中大型直接上 structlog，别重复造轮子。

老哥：那照这么说，Python 的日志栈其实不比 Go 弱，只是默认太朴素，得自己配？

墨叔：一针见血。Python 的 logging 是「积木式」的——给你零件，自己拼。Go 的 zap 是「开箱精装」。但拼好了之后，能力是对等的：分级、结构化、轮转、上下文透传、异步，一样不缺。区别只在于 zap 帮你做了默认选择，logging 把选择权交给你。理解了这个，你就不会再迷恋 print，也不会觉得 Python 日志「不够用」了。

六、排障小剧场：一条日志怎么救回一次线上事故

给你一个真实味道的场景，体会日志的价值。某天凌晨告警：支付成功率掉到 60%。你登录 Kibana，没结构化日志时只能对着一堆 print 文本干瞪眼；有了我们这套 JSON 日志，你直接搜 level:ERROR AND msg:"扣款异常"，发现全集中在某个 user_id 段，再按 req_id 聚合，定位到是下游「风控服务」在特定地域返回了超时。

老哥：如果没有 req_id 透传，岂不是要在几十万行里肉眼找关联？

墨叔：对，那就是灾难。所以请求级 req_id 是结构化日志的灵魂——它让一条链路上的所有日志能被串成一条线，而不是散落一地。这也是为什么第三节花那么大力气讲 contextvars + Filter 自动注入：不是为了炫技，是为了出事时能「顺着一条线把整件事还原」。你 Go 里用 trace_id 做分布式追踪是同样的道理，日志里的 req_id 就是单服务内的 trace_id。

再补充一句：日志和指标、链路的边界要分清。日志记「发生了什么事件」（订单创建失败），metrics 记「聚合数值」（支付成功率、QPS），trace 记「一次请求的完整路径」。三者互补，别把日志当数据库用（有人往日志里塞全量业务数据，结果 ES 被撑爆）。日志是排障的「现场录像」，不是数据仓库。

【思考题】

你的服务出现了「同一条日志被打了两遍」的诡异现象。最可能是哪两个原因？分别怎么验证和修复？（提示：想想 logger 的层级冒泡和模块重复导入。）
你在 except 块里写了 logger.error("failed: %s", e)，上线后出问题，日志里只有一句 failed: SomeError()，没有堆栈，你没法定位是哪一行炸的。应该怎么改才能拿到完整 traceback？为什么 logger.error 不会自动带堆栈？
你们要把日志接入公司的 ELK，要求「一条日志一行 JSON、字段可检索」。请说明你会怎么设计 formatter，以及为什么用 extra/Filter 透传 req_id 比每次手写 logger.info(json.dumps({...})) 更好。如果服务是异步（asyncio）的，contextvars 在这里为什么比普通全局变量更合适？

【参考答案】

两个最常见原因：① 层级冒泡（propagate）。你给子 logger（如 myapp.order）加了 handler 落盘，但它默认还会把日志往父 logger 一路冒泡，如果父级（或 root）也配了 handler，同一条记录就被处理了两次。验证：打印 logger.propagate 和 logging.root.handlers，多半 root 有个默认 StreamHandler。修复：设 logger.propagate = False，或统一管理只在 root 配 handler、子 logger 只管级别。② 模块被重复 import / 多次调用配置函数，导致同一个 logger 被 addHandler 多次，于是一次 logging 触发多个 handler 各打一遍。验证：打印 len(logger.handlers)，若 >1 就是重复添加。修复：配置前用 if logger.handlers: return 守卫，或先 logger.handlers.clear()。实践中「重复输出」99% 是这两类，先查 propagate 再查 handlers 数量就能定位。
用 logger.exception("failed: %s", e) 替代 logger.error。logger.exception 只在 except 块内调用才有意义，它会读取当前活跃的异常（sys.exc_info()）并把完整 traceback 作为日志的一部分输出；而 logger.error 只是普通记录一条消息，不会自动附加堆栈——它不知道你正处在异常现场，也不会去抓 exc_info。所以正确写法是 except Exception: logger.exception("扣款失败 order=%s", order_id)，排障时就能看到精确到行的调用栈。延伸：如果你想在 logger.error 里也带堆栈，可以显式传 exc_info=True（logger.error("x", exc_info=True)），效果等同 exception，但 exception 语义更清楚且默认级别是 ERROR。一句话：排障现场永远用 exception，别用 error 裸打异常。
设计 formatter：自定义 Formatter 子类，在 format 里把 LogRecord 的元信息（时间、级别、logger 名、消息）和通过 extra 传入的业务字段，组装成一个 dict 再用 json.dumps(..., ensure_ascii=False) 输出单行 JSON（注意 ensure_ascii=False 让中文不被转义成 \uXXXX）。req_id 等请求级字段通过 logging.Filter 在 filter(record) 里 record.req_id = req_id.get() 自动注入，或调用时 extra={"req_id": ...}。为什么优于手写 logger.info(json.dumps({...}))：① 级别生效——JSON 字符串被当普通消息，级别过滤、handler 分流（如控制台只看 WARNING）仍正常工作；手写 dict 失去结构化意义且易拼错字段。② 统一格式——所有日志走同一 formatter，字段一致、可被采集端稳定解析；手写各处的 dict 格式会漂移。③ 上下文透传——Filter + contextvars 让 req_id 在请求内自动带上，调用方无需每次传，避免「忘了带上下文」导致的链路断点。为什么 asyncio 下 contextvars 优于普通全局变量：普通全局变量在线程/协程间共享且会互相覆盖——并发请求 A 设了 req_id="a"、请求 B 紧接着设成 "b"，A 的后续日志可能误带 B 的 id，造成链路错乱。contextvars.ContextVar 是按执行上下文隔离的，asyncio 的每次任务切换都会携带各自的 context 副本，协程 A 和 B 各自看到自己的 req_id，天然正确。这正对应 Go 里用 context.Context 透传 trace/req id 的做法——contextvars 就是 Python 的 context 等价物。

徐术挺-漫思录

探索

19-日志

第 19 章日志：logging 模块与结构化

一、logging 到底是什么，怎么用

二、什么场景该用它，对照 Go 怎么选

三、用它的收益与代价，以及高级玩法

四、一个贴近项目的例子

五、日志纪律、敏感信息与 Go 栈对照

六、排障小剧场：一条日志怎么救回一次线上事故

目录

徐术挺-漫思录

探索

19-日志

第 19 章 日志：logging 模块与结构化

一、logging 到底是什么，怎么用

二、什么场景该用它，对照 Go 怎么选

三、用它的收益与代价，以及高级玩法

四、一个贴近项目的例子

五、日志纪律、敏感信息与 Go 栈对照

六、排障小剧场：一条日志怎么救回一次线上事故

目录

第 19 章日志：logging 模块与结构化