故障来了,日志里翻出几百行 enter method: createOrder、exit method: createOrder。业务主键、租户、耗时、失败原因一个没有;真正想知道的那件事——"这单为什么被判为不可支付"——没有任何一行记录。
问题不在日志太少,而在埋点位置错了:把日志当成了"代码走读的留痕",于是记的全是流程,缺的全是判断。埋点位置决定了日志能回答什么问题,写多少行是次要的。
1. 四种用途,各有负责层
"日志"是一个装四种不同需求的袋子。混在一起写,就会出现"审计看不全、故障查不到、指标算不出"。
| 用途 | 要回答的问题 | 负责层 | 形态 |
|---|---|---|---|
| 故障定位 | 这次为什么失败 | 领域层 + 外部调用层 | 带上下文的决策与结果 |
| 审计 | 谁在何时做了什么 | 接入层(统一产生) | 结构化、长期留存 |
| 度量 | 量级、分布、趋势 | 不进日志 | 计数/直方图 |
| 调试 | 变量当时是什么值 | 开发期 | 临时、可开关 |
后两类最容易越界:需要聚合的进指标,需要上下文的进日志。 用 grep 数"一天多少次超时"是拿日志当数据库,成本高且不准;把 trace id 塞进指标标签又会让基数爆炸。
审计必须由切面统一产生(谁、何时、做了什么、结果),不能由业务代码自由发挥;允许各处手写,审计就变成"希望大家都写全"。
2. 分层埋点的分工
| 层 | 该记 | 不该记 |
|---|---|---|
| 接入层 | 请求标识、路由、身份、响应码、耗时 | 业务细节、SQL |
| 领域层 | 关键判断与原因("库存不足") | 方法进出、循环内逐条 |
| 持久层 | 慢查询、批量规模、重试 | 全量 SQL 与参数 |
| 外部调用层 | 目标、耗时、结果码、重试 | 完整请求/响应体 |
一次"下单失败"的最小可用日志链:
INFO trace=7f3a user=U9 order=O12345 op=createOrder result=REJECTED reason=INSUFFICIENT_STOCK
WARN trace=7f3a order=O12345 db.query ms=812 sql=selectStockRows rows=3 # 只记慢查询
ERROR trace=7f3a order=O12345 ext=pay provider=PAY_X ms=3001 code=E_TIMEOUT retry=2
三行覆盖了"谁、做了什么、为什么被拒、慢在哪、外部是否背锅"。对照之下,enter/exit 那套在这三条信息上一无所有,成本却是它的十几倍。
3. 记决策不记流程,以及例外
原则:日志记录"分支选择了哪一条以及为什么",不记录"代码走到哪一行"。 流程是代码本身能表达的,决策才是运行时才知道的。
// 反例:流程日志,故障时无用
log.info("enter createOrder"); ... log.info("exit createOrder");
// 正例:决策日志
if (stock < qty) {
log.warn("order rejected: insufficient stock, orderId={}, need={}, actual={}",
orderId, qty, stock); // 记原因 + 三个可判定的值
return Result.reject(Reason.INSUFFICIENT_STOCK);
}
三种例外值得为流程埋点:跨团队排障("进入 A 服务"是定位归属的关键)、异步/消息链路(无同步栈可推,入口出口各一条)、分钟级长流程(阶段标记是判断"卡在哪一步"的唯一依据)。共同点是栈不可推:调用栈能告诉你的不必写日志,栈断掉处才需要标记。
4. 级别错配的四种典型
| 写法 | 问题 | 后果 |
|---|---|---|
正常流程写 INFO,每请求数条 |
INFO 成了调试通道 |
生产日志量按请求数放大,成本与噪声同步上升 |
排障信息写 DEBUG,生产不开 |
出事时没有数据 | 只能改级别重启,问题已错过 |
业务结果写 ERROR |
用户输入错误也算系统错误 | 告警疲劳,真正的故障被淹没 |
用 WARN 表达"我尽力了" |
语义模糊,无法告警 | 该告警的不告警 |
判据:级别由"是否需要人立刻处理"决定,不由"是不是坏消息"决定。 用户输入非法属正常业务流(配独立错误码),系统异常才是 ERROR。若告警挂在 ERROR 上,任何一处误用都会污染告警通道。
5. 结构化日志与上下文传递
| 维度 | 纯文本 | 结构化(JSON/键值) |
|---|---|---|
| 人读 | 快 | 慢(需工具渲染) |
| 机器解析 | 靠正则,脆弱 | 直接取字段 |
| 字段演进 | 改格式即破坏解析 | 加字段向后兼容 |
| 体积 | 小 | 大(键名重复) |
结论:面向人的少量日志用文本,进入聚合系统的用结构化;不要为了"好看"把结构化日志手工拼成字符串再输出。
上下文的传递与线程模型强绑定,这是埋点位置之外最容易出错的第二处:
// 线程池:MDC 不会自动继承,必须在提交任务时快照并恢复
Map<String,String> ctx = MDC.getCopyOfContextMap();
executor.submit(() -> {
MDC.setContextMap(ctx); // 手动传递,否则子线程日志丢失 trace
try { ... } finally { MDC.clear(); }
});
三条边界:切换线程时上下文会丢(显式传递或装饰器包装);消息消费的上下文来自消息头,不是当前请求;用户标识要脱敏,否则敏感信息被带到每条日志上。该放:trace id、业务主键、租户标识(按合规决定)。不该放:完整请求体、大对象、可变集合。
6. 日志量控制与故障时的暴增
故障与日志量是正反馈:外部服务变慢 → 每次调用一条 WARN → QPS × 重试 → 磁盘写满 → 更多失败 → 日志更多。这条链几十分钟就能跑完,中间往往还夹着"日志组件拖慢请求"。
| 手段 | 做法 | 代价 |
|---|---|---|
| 采样 | 成功路径记 N%,失败全记 | 丢失分布细节 |
| 限流 | 同类日志每单位时间最多 M 条 | 首条可能被压掉 |
| 去重聚合 | 相同指纹合并计数 | 丢失逐条上下文 |
| 异步落盘 | 缓冲 + 批量写 | 崩溃时丢尾部 |
| 动态调级 | 运行时改级别 | 忘记改回 → 日志翻倍 |
# 异步 + 丢弃策略:宁可丢日志,不要拖慢业务线程
appender:
type: async
queueSize: 8192
discardingThreshold: 0 # 满队列时丢弃低级别而不是阻塞
neverBlock: true
maxFlushTime: 2000
选型判据:日志可以丢,业务不能慢。 一旦把日志写成同步阻塞,日志组件就成了故障放大器;neverBlock 类配置的意义正在于此——用丢日志换稳定性。
7. 敏感信息的三条禁令
| 禁令 | 典型泄漏点 |
|---|---|
不记凭证(密码、密钥、Authorization 头、Cookie) |
请求日志、异常栈里的对象 toString() |
不记令牌(token、refresh_token、短信验证码) |
调试日志、第三方回调报文 |
| 不记完整证件号(身份证、银行卡、完整手机号) | 审计日志、SQL 参数 |
难点在于泄漏路径通常是间接的:直接 log.info(password) 谁都不会写,但 log.info("req={}", request) 会通过 toString() 把整个对象打出来;异常栈里的 SQLException 可能带完整语句与参数。
// 掩码应发生在序列化层,而不是"写日志时记得处理"
log.info("user register, phone={}", Mask.phone(phone)); // 138****1234
log.info("payment req, body={}", Mask.sensitive(payload)); // 递归掩码 + 键名白名单
结论:脱敏放在统一的序列化/输出环节,不依赖调用方自觉。 靠评审清单挡迟早会漏,靠框架挡只漏一次。
8. 规范可执行化与保留策略
日志规范写在文档里等于没有。能落地的只有两种形态:静态检查与评审项。
静态检查(checkstyle/PMD 自定义规则可覆盖的部分):
- 禁止 System.out / printStackTrace
- 禁止使用字符串拼接构造日志(必须用占位符 {})
- 禁止在日志中出现 password|token|secret|idCard 等键名
- 禁止 log.error 不带异常对象(丢栈)
评审项(无法静态判定的部分):
- 这条日志属于四种用途中的哪一种?负责层对不对?
- 去掉它,故障时还能不能定位?不能 → 保留;能 → 删除
- 它的字段里有没有外部输入?
第四行"log.error 不带异常对象"是最常见的静默缺陷:log.error("failed: " + e.getMessage()) 丢掉了栈,故障时只能看到一行文字。
保留策略与成本联动,分级是唯一可行的方式:
| 日志级别/用途 | 典型保留 | 存储特点 |
|---|---|---|
| 审计 | 长期(按月/年计) | 低频访问,可冷存 |
故障定位(WARN/ERROR) |
中(按周到月) | 需可搜索 |
常规业务(INFO) |
短(按天到周) | 量大,价值随时间快速衰减 |
调试(DEBUG) |
不落盘 | 只开窗口期 |
判据:保留期由"回溯需求"决定,不由"磁盘还剩多少"决定——后者会导致"钱不够就全部缩短",把审计一起砍掉。分级之后,高频短保留与低频长保留可以分别定价。
9. 排错:五种"日志很多却查不到"
| 现象 | 真实原因 | 处置 |
|---|---|---|
| 全是 enter/exit | 埋点在方法进出,不在决策点 | 改记分支原因与关键值 |
| 无法串起来 | 缺 trace id 或异步丢上下文 |
统一上下文 + 线程池装饰 |
| 故障时反而写不出 | 同步落盘 + 队列积压 | 异步 + neverBlock + 采样 |
| 日志量翻几倍 | 上线时开 DEBUG 忘关 |
动态调级加自动回退 |
| 存储告警后无法回溯 | 审计与常规日志同策略被缩短 | 分级保留,审计独立 |
10. 边界:可以精简甚至不写日志的场景
| 场景 | 说明 |
|---|---|
| 小工具、一次性脚本 | 出错即重跑,成本高于收益 |
| 秒级以内的批处理 | 无中间态可观察 |
| 链路追踪已覆盖到位 | 追踪回答"走到哪",日志只补"为什么" |
| 高频同质路径 | 指标答量级,日志只留异常样本 |
| 单机实验性代码 | 用调试器替代日志 |
这些场景的共同点是:日志要回答的问题已经被别的机制回答。链路追踪给时序,指标给量级,调试器给现场——三者任一覆盖到位,日志就不必重复承担。
11. 自测
- 四种用途各由哪一层负责,哪种不该用日志承载?
- 为什么"记决策不记流程"?三种例外为什么成立?
- 日志级别的判据是什么,用户输入非法该用哪一级?
- 异步与线程池场景下上下文为什么会丢?
- 故障时日志量暴增的因果链怎么打断?
- 静态检查能覆盖日志规范的哪些部分,哪些只能进评审?