线上报障,用户说"下单失败",你在日志里搜订单号,找到三条记录:一条来自网关、一条来自订单服务、一条来自库存服务。三条都只写了 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. 自测
SLF4J: Class path contains multiple SLF4J bindings说明了什么?实际生效的是哪一个?log.error("create failed: " + e.getMessage())丢了什么?正确写法是什么?- 占位符比参数多、或者参数里混着
Throwable,输出会怎样? - MDC 在线程池里为什么会失效?两种修复方式分别是什么?
discardingThreshold=0与neverBlock=true组合的实际语义是什么?maxHistory、maxFileSize、totalSizeCap三个参数怎样共同决定磁盘占用?