2960 字
约 9 分钟
20
S04-A08 · 日志埋点的位置:在哪一层记录什么

故障来了,日志里翻出几百行 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. 自测

  1. 四种用途各由哪一层负责,哪种不该用日志承载?
  2. 为什么"记决策不记流程"?三种例外为什么成立?
  3. 日志级别的判据是什么,用户输入非法该用哪一级?
  4. 异步与线程池场景下上下文为什么会丢?
  5. 故障时日志量暴增的因果链怎么打断?
  6. 静态检查能覆盖日志规范的哪些部分,哪些只能进评审?
S04-A08 · 日志埋点的位置:在哪一层记录什么
https://www.clxhxhhr.top/posts/6239/
作者
clxstart
发布于
2024-12-31
许可协议
CC BY-NC-SA 4.0
评论
0 条
还没有评论,先写一条吧。