2021 年我做一个后端服务,日志这件事我从没认真当回事。第一版我做得很省事:哪里觉得需要看一眼,就 print 一句;哪里觉得可能出错,就 print("出错了"),全打到一个文件里。本地开发时——真不错:程序一跑,屏幕上哗哗地滚,我想看的都看得见。我心里很踏实:"日志嘛,需要的地方 print 一句,出问题了翻一翻,不就行了。"可等这个服务真正上线、扛起真实流量,一串问题冒了出来。第一种最先把我打懵:某天线上一个接口出了故障,我满怀希望去翻日志,翻到的却是一行孤零零的 出错了——没有时间、没有是哪个用户、没有什么参数、没有错误细节,这行日志等于什么都没说。第二种最磨人:日志文件里什么都往里塞,正常的、异常的、调试用的全混在一起,我想找那条关键的报错,得在几十万行里大海捞针。第三种最致命:一个用户报错,我想看他这一次请求到底经历了什么,可这个请求的日志零零散散地散落在好几万行里,中间还插满了别的请求的日志,我根本没法把它们串起来。第四种最隐蔽:很久以后我才发现,日志里赫然打着用户的密码和登录 token——只因为我当初图省事,把整个请求体直接打进了日志。我盯着这一连串问题想了很久才彻底想明白,第一版错在一个根本的认知上:我以为"日志就是出问题随手记一句,需要时翻一翻"。这句话把日志当成了一个写给"当下的我"看的临时备忘。可它不是。日志真正的读者,是"未来某个时刻,正在排查一个线上故障、手忙脚乱的你"。那个你,没有现场、没有断点、不能复现,手里只有日志这一样东西。所以日志不是"随手记一句"那么简单,它是一套需要设计的系统:要分级,让重要的和不重要的分得开;要结构化,让机器能搜索、能按字段过滤;要带上下文,让一个请求的日志能被串成一条完整的线;还要脱敏,绝不能让密码、token 跟着日志泄露出去。真正做好应用日志,核心不是"在需要的地方 print 一句",而是理解日志是写给未来排查者的、做好日志分级、用结构化日志取代纯文本、用 trace id 把一次请求串起来、对敏感信息脱敏。这篇文章就把应用日志治理梳理一遍:为什么"出问题 print 一句"是错的、日志分级该怎么分、结构化日志怎么做、trace id 怎么把散落的日志串起来、敏感信息怎么脱敏,以及日志量与采样、异步写入、日志轮转这些把日志真正做扎实要避开的坑。
问题背景
先把那串问题的现象和我的误判讲清楚,后面所有的设计都是冲着纠正这个误判去的。
现象:一套"哪里需要就 print 一句"的日志,上线后冒出一串问题:出了故障去翻日志,翻到的是一行没有任何上下文的"出错了";日志什么都往里塞、不分轻重,关键报错淹没在几十万行里;一个请求的日志散落各处、被别的请求插得七零八落,串不成一条线;图省事把整个请求体打进日志,用户的密码和 token 也跟着进了日志文件。
我当时的错误认知:"日志就是出问题随手记一句,需要时翻一翻就行了。"
真相:这个认知错在一个根本的角色误判:它把日志,当成了写给"此刻、正在开发、手里有完整现场的你"看的东西。可日志真正的读者从来不是这个你。日志真正的读者,是"未来某个时刻——可能是几周后的半夜——正在排查一个线上故障的你"。那个你,处境和现在截然不同:你没有现场,故障已经过去了;你不能打断点,这是生产环境;你很可能无法复现,它只在特定的、你不知道的条件下发生过一次。那个你,手里唯一的线索,就是当时留下的日志。一旦你接受"日志是写给那个未来的、信息匮乏的你"这个定位,那串问题的答案就全有了:日志必须自带上下文(时间、用户、参数、错误细节),因为未来的你没有现场可问;日志必须分级,因为未来的你需要在海量信息里一眼锁定要紧的;日志必须能串成一条线,因为未来的你要还原"一次请求的完整经历";日志必须能被机器搜索和过滤,因为未来的你不可能用肉眼翻几十万行。这些不是锦上添花,而是"让未来的你还能排查得动"的最低要求。
要把应用日志治理做对,需要几块认知:
- 为什么"出问题 print 一句"是错的——日志是写给未来排查者的;
- 日志分级——用 DEBUG/INFO/WARN/ERROR 把轻重分开;
- 结构化日志——从纯文本变成机器可搜索、可过滤的字段;
- trace id——把一次请求散落的日志串成一条完整的线;
- 脱敏、采样、异步写入、日志轮转这些工程坑怎么处理。
一、为什么"出问题 print 一句"是错的
先把这件最根本的事钉死:print 和日志,看起来都是"往外打字",但它们是两种东西。print 是写给"现在的你"看的——你盯着屏幕,程序在跑,你想确认一下某个值,print 一下,看完就完了,它是即时的、一次性的。日志不是。日志是写给"未来的你"的一封信,而且你不知道这封信什么时候会被拆开、会在多慌乱的处境下被拆开。一封有用的信,得自己交代清楚:这是什么时候发生的、发生在谁身上、当时的关键数据是什么、出了什么岔子。一行 print 出来的"出错了",就是一封什么都没写的空信封——它在你写下它的此刻看着够用,因为现场都在你脑子里;可等未来的你拆开它,里面空空如也。
下面这段代码,就是我那个"上线就抓瞎"的第一版日志:
# 反面教材:用 print 当日志,出问题随手记一句
def handle_order(user_id, order_data):
print("开始处理订单") # 没时间、没级别、没上下文
try:
amount = order_data["amount"]
result = charge(user_id, amount)
print("处理完成")
return result
except Exception:
print("出错了") # 灾难:到底错在哪?谁的?
return None
# 破绽一:print 没有时间、没有级别,无法区分轻重。
# 破绽二:"出错了"不带任何上下文 —— 未来排查时等于一句空话。
# 破绽三:print 直达标准输出,无法分级、无法轮转、无法结构化。
这段代码在本地开发时表现不错,因为本地的你,有完整的现场:程序在你眼前跑,出错时异常栈直接糊在屏幕上,你想看什么再加一行 print 就是。print 的所有缺陷,都被"现场就在手边"这件事掩盖了。它的问题不在 print 这个函数上,而在一个被忽略的前提:它默认"读日志的人,和写日志的人,处在同一个有现场的时刻"。可线上排查时根本不是。于是那串问题就有了解释:翻到一句空话,是因为 print("出错了") 没带未来排查所必需的任何上下文;轻重不分,是因为 print 没有"级别"这个概念,一切输出一视同仁;串不成线,是因为每句 print 都是孤立的,不知道自己属于哪一次请求。问题的根子清楚了:做好日志的工程量,全在"承认日志是写给未来那个没有现场的排查者"之后——你不为他着想,他就只能对着空信封干瞪眼。先从最基础的一件事——把日志分级——说起。
二、日志分级:把要紧的和不要紧的分开
第一版日志最直接的毛病,是所有输出一视同仁——调试用的、正常流程的、出问题的,全挤在一起。解法是日志分级:几乎所有日志库,都把日志分成几个严重程度递增的级别,最常用的是 DEBUG / INFO / WARNING / ERROR。用 Python 标准库 logging 替换掉 print,第一步就是给每条日志标上级别:
import logging
logging.basicConfig(
level=logging.INFO, # 只输出 INFO 及以上级别
format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
)
logger = logging.getLogger("order")
def handle_order(user_id, order_data):
# DEBUG:开发期调试细节,生产环境通常关掉
logger.debug("收到订单数据: %s", order_data)
# INFO:正常的关键业务节点,用于还原"发生了什么"
logger.info("开始处理订单 user_id=%s", user_id)
try:
amount = order_data["amount"]
result = charge(user_id, amount)
logger.info("订单处理成功 user_id=%s amount=%s", user_id, amount)
return result
except KeyError as e:
# WARNING:不正常,但程序还能继续(比如参数缺失走了兜底)
logger.warning("订单数据缺字段 user_id=%s field=%s", user_id, e)
return None
except Exception:
# ERROR:真正的错误,exc_info=True 会带上完整异常栈
logger.error("订单处理失败 user_id=%s", user_id, exc_info=True)
return None
分好级别后,每个级别各司其职:DEBUG 是开发期的调试细节,生产环境一般关掉;INFO 记正常的关键业务节点,用来还原"系统正常时都做了什么";WARNING 记不正常、但还不致命的情况(走了兜底、参数缺失);ERROR 记真正出错、需要有人关注的事。分级最直接的好处,是你可以用一个开关,控制输出哪些级别——开发时开到 DEBUG 看个通透,生产环境设到 INFO 或 WARNING,把噪音挡在外面。这里的认知要点是:日志分级的本质,是给未来的排查者提供一个"信息浓度的旋钮"。线上排查时,他最怕的不是日志太少,而是日志太多、要紧的被淹没。分级让他可以先只看 ERROR——快速锁定"哪里炸了";再放出 INFO——还原"炸之前系统走到了哪一步";真要钻细节,才放出 DEBUG。一条日志该打成什么级别,你要问的不是"它重不重要",而是"未来排查的人,在哪个浓度下需要看到它"。级别分清楚了,但日志的内容形态还有个大问题——它还是一行纯文本,机器读不动。
三、结构化日志:从纯文本到机器可读
上面那条日志 开始处理订单 user_id=123,比 print 强多了,但它还有个硬伤:它是一行给人读的纯文本。当日志量大到要靠 ELK、Loki 这类日志系统来集中检索时,纯文本就很难办了——你想"筛出所有 user_id=123 的日志",机器得用正则去字符串里硬抠,又慢又脆。解法是结构化日志:把日志打成 JSON,每个信息都是一个独立的、带名字的字段:
import logging
import json
import time
class JsonFormatter(logging.Formatter):
"""把每条日志格式化成一行 JSON,每个信息都是独立字段。"""
def format(self, record):
log = {
"time": time.strftime("%Y-%m-%dT%H:%M:%S",
time.localtime(record.created)),
"level": record.levelname,
"logger": record.name,
"message": record.getMessage(),
}
# 业务字段:通过 extra 传进来的,统一并进 JSON
if hasattr(record, "context"):
log.update(record.context)
if record.exc_info:
log["exception"] = self.formatException(record.exc_info)
return json.dumps(log, ensure_ascii=False)
handler = logging.StreamHandler()
handler.setFormatter(JsonFormatter())
logger = logging.getLogger("order")
logger.addHandler(handler)
logger.setLevel(logging.INFO)
有了它,业务日志就把每个信息当成字段来打,而不是拼成一句话:
# 打日志时,业务信息通过 extra 作为独立字段传入
def handle_order(user_id, order_data):
logger.info("开始处理订单",
extra={"context": {"user_id": user_id,
"action": "order_start"}})
# 输出会是一行干净的 JSON:
# {"time":"2021-08-01T10:30:00","level":"INFO","logger":"order",
# "message":"开始处理订单","user_id":123,"action":"order_start"}
#
# 在日志系统里,就能直接按字段精确检索和聚合:
# level = "ERROR" —— 一键筛出所有错误
# user_id = 123 —— 精确捞出某个用户的全部日志
# action = "order_start" —— 统计某个业务动作的发生次数
这里的认知要点是:结构化日志,是把日志从"给人读的一句话",变成"给机器查的一条记录"。这个转变的分水岭,是日志量。日志少的时候,纯文本用肉眼扫一扫就行;可一旦日志多到必须交给日志系统去集中存储和检索,"字段"就成了刚需——机器擅长的是"按字段精确匹配和聚合",不是"在自由文本里猜正则"。结构化日志的代价,只是写日志时多花一点心思把信息拆成字段;它换来的,是未来排查时,你能用一句查询、在亿级日志里秒级定位。日志能按字段查了,但还差最关键的一步:怎么把一次请求散落各处的日志,串成一条线?
四、trace id:把一次请求的日志串成一条线
开头第三个问题——"一个请求的日志散落各处、串不起来"——是高并发下最折磨人的一个。线上同时有成百上千个请求在跑,它们的日志交错着写进同一个文件。你想看某一个请求的完整经历,却发现它的日志被几百个别的请求的日志,切得七零八落。解法是 trace id(也叫请求 ID、追踪 ID):在请求一进来时,就给它生成一个全局唯一的 ID;然后让这次请求产生的每一条日志,都自动带上这个 ID。这样一来,按这个 ID 一搜,这次请求的所有日志就被精确地聚到了一起。要让 trace id "自动"跟着请求走,靠的是 contextvars——它能在一次请求的整个调用链里,安全地共享一个值:
import contextvars
import uuid
import logging
# contextvars:每个请求/协程有自己独立的一份,互不串台
trace_id_var = contextvars.ContextVar("trace_id", default="-")
class TraceIdFilter(logging.Filter):
"""一个 logging 过滤器,给每条日志自动注入当前的 trace_id。"""
def filter(self, record):
record.trace_id = trace_id_var.get()
return True # 永远不过滤掉,只做注入
def new_trace_id():
"""生成一个新 trace id 并设入当前上下文。"""
tid = uuid.uuid4().hex[:16]
trace_id_var.set(tid)
return tid
然后在 Web 框架的中间件里,每个请求一进来就生成 trace id——之后这次请求里的任何日志,都会自动带上它:
# 在中间件里:每个请求进来就开一个 trace id
async def trace_middleware(request, call_next):
"""请求入口处生成 trace id,贯穿这次请求的所有日志。"""
tid = new_trace_id()
logger = logging.getLogger("app")
logger.info("请求开始 path=%s", request.url.path)
response = await call_next(request) # 期间所有日志都带上了 tid
logger.info("请求结束 status=%s", response.status_code)
response.headers["X-Trace-Id"] = tid # 把 id 回给客户端,便于报障
return response
下面这张图,把 trace id 从生成到把日志串起来的过程画出来:
这里的认知要点是:trace id 解决的,是"日志的连续性"问题。单条日志再详细,也只是一个孤立的点;而排查一个故障,你需要的是一条线——这次请求从进来到出错,中间一步步都发生了什么。trace id 就是把这些散落的点重新穿成线的那根针。它的关键在"自动":靠 contextvars 和日志过滤器,让 trace id 在请求入口处生成一次,之后无须任何人手动传递,就渗透进这次请求的每一条日志。在微服务架构里,这根针还能跨服务传递,把一次调用在好几个服务里的日志,串成一整条全链路。主链路讲完了,最后是几个真正上规模后才会撞见的工程坑——其中第一个,关乎安全。
五、工程坑:脱敏、采样、异步写入与日志轮转
主链路之外,还有几个工程坑,不处理就会让日志要么泄露机密、要么拖垮性能、要么撑爆磁盘。坑 1:日志必须脱敏,绝不能打印敏感信息。开头第四个问题——密码和 token 进了日志——就是图省事把整个请求体直接打进日志导致的。日志会被很多人看到、会被同步进日志系统,它绝不是放机密的地方。要有一个统一的脱敏环节,把敏感字段打码后再记:
# 脱敏:打日志前,把敏感字段统一打码
SENSITIVE_KEYS = {"password", "token", "id_card", "phone",
"card_no", "secret", "authorization"}
def desensitize(data):
"""递归地把字典里的敏感字段替换成掩码,再交给日志。"""
if isinstance(data, dict):
return {
k: ("***" if k.lower() in SENSITIVE_KEYS else desensitize(v))
for k, v in data.items()
}
if isinstance(data, list):
return [desensitize(x) for x in data]
return data
def handle_request(body):
# 关键:打的是脱敏后的副本,绝不是原始 body
logger.info("收到请求", extra={"context": {"body": desensitize(body)}})
坑 2:高频日志要采样,别让日志量自己拖垮自己。一个 QPS 很高的接口,每个请求都打好几条 INFO,日志量会大得惊人——既烧磁盘和带宽,也把真正有用的日志淹没。对高频且重复的日志,可以采样:只记其中一部分:
import random
# 高频日志采样:只记录其中一小部分,ERROR 永远全量
def log_sampled(logger, level, msg, sample_rate=0.1, **ctx):
"""INFO 类高频日志按比例采样;错误日志一律全记,绝不漏。"""
if level >= logging.WARNING:
logger.log(level, msg, extra={"context": ctx}) # 全量
elif random.random() < sample_rate:
ctx["sampled"] = True
logger.log(level, msg, extra={"context": ctx}) # 采样 10%
坑 3:日志写入别阻塞业务线程。日志最终要写磁盘、甚至发往远程日志系统,这是 IO 操作。如果在业务线程里同步写,日志一慢,业务就跟着卡。正确做法是用 异步日志:业务线程只把日志丢进一个内存队列,由单独的线程慢慢往外写:
import logging
import logging.handlers
import queue
# 异步日志:业务线程只管入队,真正的写出交给后台线程
_log_queue = queue.Queue(-1)
queue_handler = logging.handlers.QueueHandler(_log_queue)
# 真正干活的 handler(写文件 / 发远程),放到后台 listener 里
file_handler = logging.handlers.RotatingFileHandler(
"app.log", maxBytes=50 * 1024 * 1024, backupCount=10) # 坑 4:轮转
file_handler.setFormatter(JsonFormatter())
listener = logging.handlers.QueueListener(_log_queue, file_handler)
listener.start() # 后台线程:从队列取日志,真正写出
app_logger = logging.getLogger("app")
app_logger.addHandler(queue_handler) # 业务只对接入队,不碰 IO
上面那段代码顺手带出了坑 4:日志文件一定要轮转。RotatingFileHandler 让单个日志文件到了 maxBytes 就自动切一个新的,并只保留最近 backupCount 个。没有轮转,日志文件会无限增长,迟早把磁盘撑满、把服务搞垮。坑 5:生产代码里别再用 print 了。print 没有级别、没有时间、没有结构、不走 handler、不能被统一控制——它绕开了你辛苦搭起来的整套日志体系。定一条规矩:项目里只许用 logger,不许用 print。
关键概念速查
| 概念 / 手段 | 说明 |
|---|---|
| 日志分级 | DEBUG/INFO/WARNING/ERROR 按严重程度区分,可整体开关 |
| DEBUG | 开发期调试细节,生产环境通常关闭 |
| INFO | 正常关键业务节点,用于还原系统行为 |
| WARNING | 不正常但程序仍能继续的情况 |
| ERROR | 真正的错误,需附完整异常栈 |
| 结构化日志 | 日志打成 JSON,每个信息是独立字段,机器可检索 |
| trace id | 请求入口生成的唯一 ID,串起一次请求的全部日志 |
| contextvars | 在一次请求调用链内安全共享值,用于自动注入 trace id |
| 日志脱敏 | 打印前把密码、token 等敏感字段统一打码 |
| 日志轮转 | 文件到阈值自动切割并限量保留,防止磁盘被撑满 |
避坑清单
- 生产代码别用 print,统一用带级别的 logger。
- 日志是写给未来排查者的,每条都要自带足够上下文。
- 给日志分级,让 ERROR 与 INFO、DEBUG 能分开筛选。
- 错误日志要带完整异常栈(exc_info=True),别只记一句话。
- 日志量大时打成 JSON 结构化日志,让机器能按字段检索。
- 每个请求生成 trace id,自动注入它产生的每一条日志。
- 用 contextvars + 日志过滤器自动带 trace id,别手动传。
- 敏感字段(密码、token、身份证)打印前必须脱敏打码。
- 高频日志做采样,但错误日志必须全量,绝不采样掉。
- 日志异步写入别阻塞业务,文件务必配置轮转防止撑爆磁盘。
总结
回头看那串"翻到一句空话、轻重不分、串不成线、密码进了日志"的问题,以及我后来在日志上接连踩的坑,最该记住的不是某一个日志库的用法,而是我动手前那个想当然的判断——"日志就是出问题随手记一句,需要时翻一翻"。这句话错在它把日志的读者,默认成了"此刻、有完整现场的我"。我以为日志是写给现在的自己的临时备忘。可我忽略了一件事:日志真正会被人认真去读的那个时刻,恰恰是现场已经消失的时刻。那个未来的、正在排查线上故障的你,没有断点、不能复现、问不到现场,手里只有日志这一样东西——你此刻图省事少写的每一个上下文,都是在给那个未来的、已经够狼狈的自己,再抽掉一根救命稻草。
所以做好应用日志,真正的工程量不在"加一行打印"那件事上。那一行,谁都会写。真正的工程量,在于你要承认"日志是写给未来那个没有现场的排查者的",并据此把日志当成一个系统来设计:他需要在海量信息里分清轻重,你就给日志分级;他需要机器帮他在亿级日志里检索,你就把日志结构化成字段;他需要还原一次请求的完整经历,你就用 trace id 把散落的日志串成一条线;他绝不该在日志里看到用户的密码,你就在打印前做脱敏;日志本身不能反过来拖垮服务,你就给它配上采样、异步写入和轮转。这篇文章的几节,其实就是顺着这条线展开的:先想清楚"出问题 print 一句"为什么错,再讲日志怎么分级、怎么结构化、trace id 怎么串、敏感信息怎么脱敏,最后是采样、异步、轮转这几个把日志守扎实的工程细节。
你会发现,应用日志治理,和现实里"一架飞机的黑匣子"完全相通。飞机平稳飞行时,黑匣子安安静静,没人会去看它一眼——就像服务一切正常时,没人翻日志。可一旦出了事故,调查员赶到现场,飞机已经面目全非,飞行员可能也无法再开口——现场,没有了。这时候,调查员手里唯一可靠的东西,就是黑匣子。一个不合格的黑匣子会怎样?它只录下一句"出问题了"(这就是 print("出错了"));它把通话、仪表、引擎几百路信号录成混成一团的噪音,根本分不清哪个要紧(这就是不分级、不结构化);它这趟航班的数据和上一趟的混在了一起(这就是没有 trace id)。而一个合格的黑匣子怎么做?它每一条记录都带着精确的时间戳和来源(这就是带上下文的结构化日志);它把不同重要程度的信号分轨记录(这就是日志分级);它清清楚楚只属于这一个航班,能完整还原它从起飞到出事的每一秒(这就是 trace id 串起的一条线)。同样一场事故,可前者让调查员对着一团乱麻一筹莫展,后者让他几小时就还原出真相——差别不在事故本身,只在那个黑匣子,当初是不是被当成"给未来的调查者"而认真设计的。
最后想说,应用日志做没做对,差距永远不会在"本地开发、屏幕上日志哗哗滚"时暴露——本地你有完整的现场,程序在你眼前跑,出错时异常直接糊在屏幕上,日志写得糙不糙根本无所谓,你会觉得"需要的地方 print 一句"已经是全部。它只在真实的、故障已经过去、现场无法复现、你只能对着日志倒推的线上排查时刻才显形。那时候它会用最让人绝望的方式给你结账:做不好,你会翻遍几十万行日志,却拼不出故障到底是怎么发生的,会因为一句没上下文的"出错了"而彻底卡死,甚至哪天因为密码进了日志而出一场安全事故;而做对了,你会用一个 trace id 一搜,这次请求的完整经历就清清楚楚地铺在眼前:几点几分、哪个用户、走到哪一步、错在哪一行、异常栈是什么,一目了然。所以别等"线上炸了、你却对着日志干瞪眼"那一刻找上门,在你写下每一条日志的时候就该想清楚:它是写给未来那个没有现场的我的——它带上下文了吗、它的级别对吗、它能被搜到吗、它属于哪次请求、它会不会泄露机密,这一道道工序,我是不是都替那个未来的我想过了?这些问题有了答案,你写下的才不只是一行"当时能看见"的打印,而是一份故障来临时真正救得了命、经得起线上考验的可靠日志。
—— 别看了 · 2026