2885 字
约 9 分钟
13
S06-X11 · 日志框架选型与 MDC 链路

线上报障,用户说"下单失败",你在日志里搜订单号,找到三条记录:一条来自网关、一条来自订单服务、一条来自库存服务。三条都只写了 order failed,没有请求 ID、没有用户 ID、没有耗时。定位靠猜。

日志这件事的价值只在两处:出事时能还原现场,没出事时不占资源。这篇按"绑定关系 → 级别 → 写法 → 上下文 → 落盘"拆开。


1. SLF4J 门面与实现绑定

代码里只应出现 org.slf4j.Logger,实现由 classpath 上的 binding 决定。Spring Boot 3.x 默认带 Logback,一旦引入的第三方库把 log4j-to-slf4j、slf4j-log4j12、slf4j-simple 一起带进来,启动就会打印:

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:.../logback-classic-1.5.6.jar!/...]
SLF4J: Found binding in [jar:file:.../slf4j-simple-1.7.36.jar!/...]
现象 含义 处理
multiple SLF4J bindings 两个 binding 共存,实际只用一个(谁先被加载谁赢) 排除多余 binding,保留 logback-classic
Failed to load class org.slf4j.impl.StaticLoggerBinder 无 binding,SLF4J 退化为 NOP 补一个实现
Class path contains multiple SLF4J bindings 但日志正常 非致命的警告 仍应清理,否则行为依赖 jar 顺序
日志同时写两处 有两个 binding 同时生效(少见) 同上
<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-web</artifactId>
  <exclusions>
    <exclusion>
      <groupId>org.springframework.boot</groupId>
      <artifactId>spring-boot-starter-logging</artifactId>
    </exclusion>
  </exclusions>
</dependency>

<!-- 需要 Log4j2 时换成 starter-log4j2,且必须先排除 logging -->
<dependency>
  <groupId>org.springframework.boot</groupId>
  <artifactId>spring-boot-starter-log4j2</artifactId>
</dependency>

排除的粒度是整个 starter,而不是单个 logback-classic——后者会导致 spring-jcl 找不到桥接。Boot 3.x 用 spring-jcl 统一了 commons-logging,所以不需要再手工排除它。


2. 级别不是"严重程度",是"谁来看"

级别 触发条件 保留期 典型内容
ERROR 需要人介入:数据不一致、依赖不可用、需要回滚 长 异常堆栈 + 关键入参 + 请求 ID
WARN 可自愈或已降级:重试成功、缓存击穿、限流触发 中 一次一行,含重试次数
INFO 状态变化:启动完成、任务开始/结束、开关切换 短 不含每请求明细
DEBUG 排障时临时开:分支走向、参数快照 极短 只在使用期打开
TRACE 协议级细节 基本不用 只在本地

判据只有一句:这条日志会不会有人去读。没人读的 INFO 在 QPS 上千的服务里就是磁盘杀手。生产默认 INFO,通过 /actuator/loggers 按包临时抬到 DEBUG,用完立刻降回来:

$ curl -X POST localhost:8080/actuator/loggers/com.example.order \
  -H 'Content-Type: application/json' -d '{"configuredLevel":"DEBUG"}'

这个接口的坑是:它改的是运行期状态,重启即失效,也不会写进配置文件。临时排障可以,别当常规手段。


3. 参数化日志:占位符与拼接的差别

// 正确:只有实际输出时才做 toString / 字符串拼接
log.debug("order={} status={} cost={}ms", orderId, status, cost);

// 错误一:永远先拼字符串,DEBUG 关闭时也白算
log.debug("order=" + orderId + " status=" + status);

// 错误二:丢堆栈
log.error("create order failed: " + e.getMessage());   // 堆栈没了
log.error("create order failed, order={}", orderId, e); // 正确:异常作为最后一个参数
写法 关闭 DEBUG 时的开销 异常堆栈
log.debug("x={}", x) 仅参数装箱 保留(最后一个参数为 Throwable 时)
log.debug("x=" + x) 完整字符串拼接 + toString() 不涉及
log.error("msg", e) 正常 完整堆栈
log.error(e.getMessage()) 正常 丢失
log.error("msg {} {}", a, b) 正常 括号数与参数数不匹配时抛异常或丢参

占位符数量不匹配的行为值得记牢:参数多于占位符时,多余参数被忽略(若其中有 Throwable 也不会打堆栈);占位符多于参数时,缺的位置原样输出 {};{} 与 %s 混用会让 %s 变成字面量。SLF4J 2.x 里参数化消息的异常处理比 1.x 严格一些,具体表现按 slf4j-api 版本核对。

大对象是另一个坑:把整个 Order 或 List<Item> 塞进占位符,一是不一定实现了有意义的 toString,二是每次输出都要序列化。要么在 toString 里只保留 ID 与关键字段,要么只打 ID。


4. MDC 的机制与三处失效

MDC(Mapped Diagnostic Context)底层就是 ThreadLocal<Map<String, String>>,MDC.put("traceId", id) 后,pattern 里的 %X{traceId} 才取得到值。

失效场景 原因 现象 对策
线程池 任务跑在别的线程,ThreadLocal 不继承 子任务日志没有 traceId 包装 Runnable,提交时复制 MDC
@Async 同上,且 TaskDecorator 未配置 异步方法日志无 ID 配 TaskDecorator 拷贝 MDC
CompletableFuture 默认 ForkJoinPool,无上下文 回调里 ID 为空 提交前捕获 MDC,回调内恢复
响应式(WebFlux) 一个请求跨多个线程 ID 时有时无 用 Reactor Context,不用 MDC
未清理 线程复用,旧值残留 串号:A 请求的日志带 B 的 ID finally 里 MDC.clear()

InheritableThreadLocal 只能解决"新建线程"场景,对线程池无效——池里的线程是复用的,不会重新继承。

public class MdcTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable r) {
        Map<String, String> ctx = MDC.getCopyOfContextMap();
        return () -> {
            if (ctx != null) MDC.setContextMap(ctx);
            try { r.run(); } finally { MDC.clear(); }
        };
    }
}

Spring Boot 3.x 里把它注册成 ThreadPoolTaskExecutor 的 TaskDecorator,@Async 用的执行器才会带上上下文。自定义线程池里则要自己包装,框架不会替你做。


5. 在 Filter 里设置与清理

@Component
@Order(Ordered.HIGHEST_PRECEDENCE)
public class TraceMdcFilter extends OncePerRequestFilter {

    @Override
    protected void doFilterInternal(HttpServletRequest req, HttpServletResponse resp, FilterChain chain)
            throws ServletException, IOException {
        String traceId = req.getHeader("X-Trace-Id");
        if (traceId == null || traceId.isBlank()) {
            traceId = UUID.randomUUID().toString().replace("-", "");
        }
        MDC.put("traceId", traceId);
        MDC.put("uri", req.getRequestURI());
        resp.setHeader("X-Trace-Id", traceId);
        try {
            chain.doFilter(req, resp);
        } finally {
            MDC.clear();          // 必须:线程会回到池里复用
        }
    }
}

三个要点:finally 里 clear() 不是可选项,漏了就会出现"这条日志的 traceId 是上一个请求的";traceId 优先取上游传来的头,没有才生成,否则链路断开;@Order(HIGHEST_PRECEDENCE) 保证它在业务 Filter 之前执行,否则业务日志拿不到上下文。

MDC.clear() 比 MDC.remove(key) 更安全——后者漏掉新增的 key 就会残留。


6. 异步日志与磁盘 IO

同步日志意味着业务线程要等 write() 返回。AsyncAppender 把落盘挪到独立线程,代价是队列满时的丢弃策略。

参数 含义 建议
queueSize 队列容量,默认 256 1024–8192,按峰值 QPS 估
discardingThreshold 队列剩余比例低于此值时丢弃低级别事件(默认 20%) 保持默认;0 表示不丢弃
neverBlock 队列满时不阻塞,直接丢 生产建议 true,宁可丢日志也不拖垮请求
includeCallerData 是否采集调用栈信息 true 有明显开销,只在需要时开
maxFlushTime 关闭时等待刷新时间 与优雅停机时长对齐
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
  <queueSize>4096</queueSize>
  <discardingThreshold>0</discardingThreshold>
  <neverBlock>true</neverBlock>
  <appender-ref ref="FILE"/>
</appender>

discardingThreshold=0 配合 neverBlock=true 是常见组合:不主动丢,但队列满时不阻塞。代价是队列满时事件会被静默丢弃——如果日志用于审计,这条路不能走,得改成同步写或落消息队列。


7. 滚动与保留

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <file>logs/app.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
    <fileNamePattern>logs/app.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
    <maxFileSize>200MB</maxFileSize>
    <maxHistory>14</maxHistory>
    <totalSizeCap>10GB</totalSizeCap>
  </rollingPolicy>
  <encoder>
    <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] [%X{traceId}] %logger{36} - %msg%n</pattern>
  </encoder>
</appender>
参数 作用 漏配后果
maxFileSize 单文件上限,超过即切 单文件无限增长,tail 卡顿
maxHistory 保留天数 磁盘被历史日志吃满
totalSizeCap 全部归档总大小上限 归档期长 + 量大时仍然爆盘
fileNamePattern 中的 %i 同一天内多文件的序号 缺 %i 会覆盖同名文件
%X{traceId} MDC 取值 缺了就无法按请求串联

totalSizeCap 必须大于 maxFileSize,否则归档一生成就被清掉。三个参数共同决定"最多占多少磁盘",只配 maxHistory 是最常见的爆盘原因。


8. 结构化日志与脱敏

文本日志靠正则切,字段一多就崩。JSON 编码器让采集端直接按字段索引:

<encoder class="net.logstash.logback.encoder.LogstashEncoder">
  <includeMdcKeyName>traceId</includeMdcKeyName>
  <includeMdcKeyName>uri</includeMdcKeyName>
  <customFields>{"app":"clarity-web","env":"prod"}</customFields>
</encoder>
目标 手段
按 traceId 聚合 JSON 里带 traceId 字段,采集端做索引
按服务过滤 customFields 里写 app、env
避免日志爆炸 不记录请求体全文,只记长度与摘要
脱敏 手机号保留前 3 后 4,身份证只留后 4,密码/token 一律不打

脱敏要在写日志的地方做,而不是在采集端:采集端的正则可能漏,而日志文件已经落盘。简单做法是给敏感字段包一层 Masked 包装类型,toString() 输出掩码值——比在每个 log.info 里手工截断可靠。


9. 排错

现象 根因 处理
启动报 multiple SLF4J bindings 多个实现共存 排除多余的 binding,只留一个
日志完全不输出 无 binding(NOP)或 root level 过高 查 logback-classic 是否在类路径,logging.level.root=INFO
log.error(e.getMessage()) 丢堆栈 只传了字符串 改 log.error("msg", e)
日志里 traceId 是别人的 MDC 未清理,线程复用 finally 里 MDC.clear()
异步线程日志没有 traceId ThreadLocal 不跨线程 TaskDecorator 或手动复制上下文
磁盘被日志打满 缺 maxHistory / totalSizeCap 三个参数一起配,并加磁盘告警
开了 DEBUG 后磁盘暴涨 按请求打 DEBUG 只对特定包临时开,或用 /actuator/loggers 控制
日志里出现密码/token 打了整个请求体或配置对象 脱敏包装类型,禁止打印凭据字段

10. 边界

场景 更合适的做法 理由
需要按请求查询全链路 分布式追踪(Trace/Span),日志只带 ID MDC 只在单进程内有效
日志用于审计/计费 独立审计表或消息队列 日志可被丢弃、可被清理
高 QPS 的明细记录 采样 + 指标聚合 全量日志的存储成本不可控
排查偶发问题 动态日志级别 + 关键路径埋点 常开 DEBUG 不可行
多线程/响应式上下文传递 Reactor Context 或显式参数 MDC 依赖线程模型

一句话:MDC 适合"单线程内的一次请求",跨线程要靠装饰器,跨服务要靠追踪系统。把这三件事混为一谈,traceId 就会时有时无。


11. 自测

  1. SLF4J: Class path contains multiple SLF4J bindings 说明了什么?实际生效的是哪一个?
  2. log.error("create failed: " + e.getMessage()) 丢了什么?正确写法是什么?
  3. 占位符比参数多、或者参数里混着 Throwable,输出会怎样?
  4. MDC 在线程池里为什么会失效?两种修复方式分别是什么?
  5. discardingThreshold=0 与 neverBlock=true 组合的实际语义是什么?
  6. maxHistory、maxFileSize、totalSizeCap 三个参数怎样共同决定磁盘占用?
S06-X11 · 日志框架选型与 MDC 链路
https://www.clxhxhhr.top/posts/5847/
作者
clxstart
发布于
2024-12-31
许可协议
CC BY-NC-SA 4.0
评论
0 条
还没有评论,先写一条吧。