日志体系:SLF4J 门面与 Logback 配置实战
System.out.println 也能输出,但它只会「往屏幕上打字」。真正的日志要同时做到五件事:能按级别关掉(生产不该刷 DEBUG)、能落到文件并自动滚动(磁盘不能被写满)、能带上上下文(这次请求是谁、traceId 多少)、能被机器检索(ELK 一行一条)、换实现不用改代码。这五项能力加起来才叫「日志体系」,而 Spring Boot 已经替你默认装好了整套。
先把六个词一句话解释(全文都会用到):
- 门面(Facade):只定义「怎么调用」的接口层,不干活。
org.slf4j.Logger就是门面 - 实现(Implementation):真正判级别、拼格式、写磁盘的那个库,比如 Logback、Log4j2
- 绑定(Binding):把门面和实现接起来的那根线,物理上就是 classpath 里那个
logback-classic.jar - 桥接包(Bridge):把某个老实现的输出偷偷引到门面上,例:
jul-to-slf4j - Appender:日志的「出口」——控制台、文件、异步队列各是一个 Appender
- MDC:绑在线程上的一个临时小本子,往里写的 key-value 会自动出现在每条日志里
日志门面就是出国用的电源转换头。你的电脑(业务代码)插头形状永远不变,到日本换个孔位、到英国换个方脚——设备没变,只是换了个转换头。直接 import org.apache.log4j.Logger 等于把电脑电源线剪断、焊死在英标插座上:搬家(换日志实现)那天,你只能把整屋线路重铺一遍。

学完这一篇,你应该能回答三个问题:
- 为什么我加了
log.debug(...)却什么都不打印?(两个最常见的答案,不是你以为的那两个) logback.xml和logback-spring.xml差一个字,差了多少功能?- 一次请求跨了五个服务、写了二十行日志,我怎么用十秒钟把它们串起来?
先看一个真实的翻车现场。某项目早期图省事,每个类都直接 import org.apache.log4j.Logger,把日志写死在实现上。后来 Log4j 爆出安全漏洞,全公司要求升级到 Log4j2,别的地方改一行依赖版本就完事,这个项目却要改几十个类、重跑全部测试——因为日志调用散落在每个文件里,跟具体实现耦合死了。
问题的根源是把「你要什么」和「谁能给你」绑在了一起。日志体系里有两类角色:
- 门面(Facade):只定义接口,比如
Logger.info(...)。业务代码只认它。 - 实现(Implementation):决定日志最终写到哪、格式如何。比如 Logback、Log4j2、JDK 自带的 JUL。
中间还可能夹着桥接包(Bridge):把某个老实现的输出重定向到门面,让新旧日志走到同一条流水线上。
| 角色 | 代表 | 交给它什么职责 |
|---|---|---|
| 门面 API | SLF4J、JCL | 业务只依赖它,调用形态永远不变 |
| 日志实现 | Logback、Log4j2、JUL | 真正决定级别判定、格式化、落盘 |
| 桥接包 | jul-to-slf4j、log4j-over-slf4j | 把第三方库散落的日志收拢到同一条链路 |
历史演进大致是:JCL(2002)→ 各家实现混战 → SLF4J(2006)一统门面。JCL 的失败在于它采用「运行时动态查找实现」,classpath 一乱就出现 NoClassDefFoundError 之类的诡异问题;SLF4J 改成「编译期静态绑定」,classpath 里没有实现时只打印一条警告,不会再崩。这就是为什么今天所有现代框架——Spring、Hibernate、MyBatis——内部用的都是 SLF4J。

开头那个翻车现场,值得用一条动图钉死——左边是「把线焊死在插座上」的代价,右边是「只换一个转换头」的代价,同一次漏洞公告、两种结局:

Spring Boot 的默认组合是 SLF4J(门面)+ Logback(实现),由 spring-boot-starter-logging 自动带入——它其实转依赖了 spring-boot-starter 里的日志 starter。只要你用了 spring-boot-starter-web,这套组合就已经就位,什么都不用配。

级别不是「重要性排序」,而是过滤门槛:logger 上设一个级别,只有不低于它的日志才会被放行。搞混这一点,就会出现「生产疯狂打 DEBUG 把磁盘写满」的事故。
| 级别 | 判断标准(问自己一句) | 生产建议 |
|---|---|---|
| ERROR | 已经影响到用户/业务,需要人介入 | 必开,且应触发告警 |
| WARN | 可恢复但值得关注,可能恶化 | 必开,定期巡检 |
| INFO | 关键业务事实:启动、开关、状态变更 | 必开,但别刷屏 |
| DEBUG | 排查问题时才需要的细节 | 默认关,按包临时开 |
| TRACE | 比 DEBUG 更细,几乎是逐帧 | 生产几乎永不开 |
Logback 的级别配置是一棵树。root 是树根,每个包/类是一条分支,没有显式配置的 logger 会向上寻找最近的祖先级别。所以:
logging: level: root: INFO # 兜底:所有未单独配置的走 INFO com.example.order: DEBUG # 只有订单包开 DEBUGcom.example.order.OrderService会命中com.example.order的 DEBUGcom.example.user.UserService没有匹配的 logger,往上找到 root,按 INFO 处理- 一次
log.debug调用在 root=INFO 时会被直接丢弃,连字符串格式化都不会发生
要点:级别放行发生在格式化之前,这是 SLF4J 性能模型的关键——被过滤的日志,代价几乎为零。这也解释了后面第三节那个常被搞错的 isDebugEnabled。
「谁离这个类最近,谁说了算」这套继承关系,用点的比用背的快。下面这张图从下往上一格一格点,重点是第 ③ 格和第 ⑤ 格:
// 反例:拼接在 log 之前就执行了,级别再低也白拼logger.debug("查询用户 id=" + userId + ", 名称=" + name + ", 耗时=" + cost + "ms");// 正例:只有级别放行时才真正做字符串替换logger.debug("查询用户 id={}, 名称={}, 耗时={}ms", userId, name, cost);- 反例里
+拼接是「调用参数」,会在debug()之前完成——哪怕生产把级别压到 INFO,这次拼接照样发生 - 正例传入的是「格式 + 参数」,SLF4J 先判级别,被过滤时一个字符串都不会拼
- 循环里打日志时,这个差异会被放大成千上万倍
try { orderService.create(order);} catch (Exception e) { // 异常对象放最后,SLF4J 自动识别并打印完整堆栈 log.error("创建订单失败 orderId={}, userId={}", order.getId(), order.getUserId(), e);}坑:很多人写成 log.error("创建订单失败: " + e.getMessage())。这样堆栈被彻底丢掉,线上只剩一行干巴巴的消息,你永远不知道是空指针还是超时。更糟的是 e.printStackTrace()——它把堆栈打到了标准错误,绕过了日志框架,既没有时间戳也没有 traceId,ELK 里根本搜不到。
老代码里常见这种写法:
if (logger.isDebugEnabled()) { logger.debug("state={}", expensiveToString(obj));}// 绝大多数情况下,这样写就够了logger.debug("state={}", obj);结论很明确:绝大多数场景不需要 isDebugEnabled。
- 参数只是普通变量或对象引用时,占位符方案已经帮你省掉了格式化,外层判断是纯粹的噪音
- 只有当「构造日志参数」本身很贵时才值得包一层——比如要遍历大集合并序列化、要计算一个聚合值。上面第一个例子里
expensiveToString即使日志被过滤也会执行,这时判断才有意义 - 代价是代码变长、可读性下降。默认不写,遇到真实性能问题再加,别凭想象提前优化
不用改任何代码,application.yml 里三个开关就能覆盖 80% 的日常需求:
logging: level: # ① 改级别:不改代码,按包精细控制 root: INFO com.example: DEBUG org.springframework.jdbc.core: DEBUG # 想看 SQL 参数时打开 com.zaxxer.hikari: INFO # 连接池日志别刷屏 file: name: ./logs/bee.log # ② 同时输出到文件(控制台依然保留) pattern: console: "%d{HH:mm:ss.SSS} %-5level [%X{traceId}] %logger{36} - %msg%n" file: "%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%X{traceId}] %logger{36} - %msg%n"logging.level:以包名为 key,值就是级别。改一行重启即生效,是最常用的开关logging.file.name:指定后,日志同时在控制台和文件输出;logging.file.path只指定目录,文件名固定叫spring.loglogging.pattern:控制格式。%X{traceId}就是为第七节的 MDC 预留的打印位
提示:logging.file.name 与 logging.file.path 只能二选一,两个都写时以 name 为准。生产上更推荐「只打控制台」交给容器或日志采集侧处理,理由见第八节。
这三行是「够用」的下限,实际项目里通常还要挂上 profile 和 Actuator。别抄别人的 yml——勾一遍,看它生成什么,尤其注意每一项后面那行注释为什么存在:
server:
port: 8080
spring:
application:
name: demo-service
logging:
level:
root: INFO
com.example.demoservice: DEBUG
org.springframework.jdbc.core.JdbcTemplate: DEBUG # 打 SQL 与参数
file:
name: logs/app.log
logback:
rollingpolicy: { max-file-size: 50MB, max-history: 14 }
---
spring:
config:
activate:
on-profile: prod
logging:
level: { root: WARN }
---
spring:
config:
activate:
on-profile: dev
spring:
jpa:
show-sql: truelogging.file.name 与第五节那份 logback-spring.xml 是两套出口配置,会互相覆盖。写了完整 XML 又配 logging.file.name,Boot 会把它自己的 appender 关掉、只保留你 XML 里那套——于是「明明配了文件路径却找不到文件」。定一个事实源:要么三件套,要么 XML。
排查线上问题,最怕的是「改配置要重启」。Spring Boot 2.0+ 的 actuator 暴露了 loggers 端点,能在线热改级别:
# 只把订单包临时调到 DEBUG,其他包不受影响curl -X POST http://localhost:8080/actuator/loggers/com.example.order \ -H 'Content-Type: application/json' \ -d '{"configuredLevel":"DEBUG"}'# 查当前生效级别curl http://localhost:8080/actuator/loggers/com.example.order- 支持
GET查看、POST修改,改完立即生效、无需重启 - 记得把
management.endpoints.web.exposure.include里加上loggers(或用*) - 用完务必改回去——这就是第十二节决策卡要讨论的事
当需求超过三件套的表达能力——按级别分流、异步、按大小+时间双滚动——就该写完整的配置文件了。放在 src/main/resources/logback-spring.xml:
<?xml version="1.0" encoding="UTF-8"?><configuration scan="true" scanPeriod="60 seconds"> <!-- 1. 变量:日志目录与文件前缀,改一处即可全局生效 --> <property name="LOG_HOME" value="./logs"/> <property name="APP_NAME" value="bee"/> <!-- 2. 控制台:开发时看的,带颜色高亮 --> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %highlight(%-5level) [%thread] %cyan(%logger{36}) - %msg%n</pattern> </encoder> </appender> <!-- 3. 文件:按天 + 按大小双维度滚动,历史 gzip 压缩 --> <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${LOG_HOME}/${APP_NAME}.log</file> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>${LOG_HOME}/${APP_NAME}.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern> <maxFileSize>100MB</maxFileSize> <maxHistory>30</maxHistory> <totalSizeCap>5GB</totalSizeCap> </rollingPolicy> <encoder> <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] [%X{traceId}] %logger{36} - %msg%n</pattern> </encoder> </appender> <!-- 4. 异步包装:业务线程只写队列,落盘交给后台线程 --> <appender name="ASYNC_FILE" class="ch.qos.logback.classic.AsyncAppender"> <queueSize>1024</queueSize> <discardingThreshold>0</discardingThreshold> <neverBlock>true</neverBlock> <appender-ref ref="FILE"/> </appender> <!-- 5. 按级别分流:ERROR 单独一封,方便告警系统直接 tail --> <appender name="ERROR_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${LOG_HOME}/${APP_NAME}-error.log</file> <filter class="ch.qos.logback.classic.filter.LevelFilter"> <level>ERROR</level> <onMatch>ACCEPT</onMatch> <onMismatch>DENY</onMismatch> </filter> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>${LOG_HOME}/${APP_NAME}-error.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern> <maxFileSize>50MB</maxFileSize> <maxHistory>60</maxHistory> </rollingPolicy> <encoder><pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%X{traceId}] %msg%n</pattern></encoder> </appender> <!-- 6. 包级别:自己的业务包放开,第三方框架压到 WARN --> <logger name="com.example" level="DEBUG"/> <logger name="org.apache.ibatis" level="WARN"/> <logger name="com.zaxxer.hikari" level="INFO"/> <root level="INFO"> <appender-ref ref="CONSOLE"/> <appender-ref ref="ASYNC_FILE"/> <appender-ref ref="ERROR_FILE"/> </root></configuration><property>:定义可复用变量,${LOG_HOME}在全文引用,迁移目录只改一行ConsoleAppender:%highlight只在支持 ANSI 的终端生效,写进文件时会自动变成纯文本RollingFileAppender:滚动策略见第六节,%i是同一天内多份文件的自增序号AsyncAppender:把真实 appender 包一层异步,appender-ref指向FILE即代表异步写文件LevelFilter:onMatch=ACCEPT放行 ERROR,onMismatch=DENY拦掉其它级别,于是 ERROR_FILE 只收错误root上是「兜底级别 + 出口列表」;logger上是更精细的覆盖,谁近谁生效
坑:文件名 logback-spring.xml 与 logback.xml 不是一回事。只有 logback-spring.xml 才支持 <springProfile>、<springProperty> 这些 Spring 扩展标签,也才能在配置里用 ${spring.application.name}。写成 logback.xml 会被 Logback 在 Spring 环境就绪前抢先加载,标签直接报错,profile 支持也没了。
上面那些 pattern 里的 % 记号是整份配置里唯一「写错了也不报错、只是不打字」的部分。来一局配对:左边是记号,右边点它真正打印什么——点错会当场告诉你代价:
logback-spring.xml 的杀手锏是按环境切换:
<springProfile name="dev"> <root level="DEBUG"><appender-ref ref="CONSOLE"/></root></springProfile><springProfile name="prod"> <root level="INFO"> <appender-ref ref="ASYNC_FILE"/> <appender-ref ref="ERROR_FILE"/> </root></springProfile>开发环境要 DEBUG 和控制台高亮,生产环境要 INFO 和异步落盘——同一份文件,两种行为,这是 logback.xml 做不到的。
日志文件不能无限长,必须滚动(rotate)。Logback 提供了三种滚动策略:
| 策略 | 触发条件 | 适用场景 |
|---|---|---|
TimeBasedRollingPolicy | 按时间(默认按天) | 只需按日归档 |
SizeAndTimeBasedRollingPolicy | 按时间 + 单文件大小 | 大流量,一天可能写几百 MB |
SizeAndTimeBasedFNATP(SizeAndTimeBasedFileNamingAndTriggeringPolicy)是「按大小 + 按时间」组合的核心组件,现在通常直接用 SizeAndTimeBasedRollingPolicy 简写形式:
<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>./logs/bee.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern> <maxFileSize>100MB</maxFileSize> <!-- 单文件超过 100MB 就滚,%i 递增 --> <maxHistory>30</maxHistory> <!-- 只保留最近 30 天 --> <totalSizeCap>5GB</totalSizeCap> <!-- 所有归档加起来不超过 5GB --></rollingPolicy>%d{yyyy-MM-dd}按天命名,%i是当天第几个分片(bee.2026-10-07.0.log.gz、.1.log.gz…)maxFileSize防止单文件过大——单文件过大的日志既难 tail 也难传输maxHistory控制时间维度的保留天数totalSizeCap是总磁盘上限,超过时从最旧的文件开始删;必须 ≥maxHistory的预期总量才有意义
说明:为什么需要 totalSizeCap?因为 maxHistory 只管「保留多少天」,管不了「一天写多少」。假如某天日志暴涨到 2GB,30 天就是 60GB——totalSizeCap=5GB 会兜住这个上限,把最老的归档删掉。生产环境这两个参数必须同时配,否则一次流量尖峰就能把磁盘写满。
微服务里最痛的问题是:一个请求打过 5 个服务、写了 20 行日志,出问题时怎么把它们串起来?答案是 MDC(Mapped Diagnostic Context)——一个绑定在线程上的 key-value 容器,日志 pattern 里用 %X{key} 就能引用。
第一步,用 Filter 在请求入口塞入 traceId:
package com.example.web.filter;import jakarta.servlet.FilterChain;import jakarta.servlet.ServletException;import jakarta.servlet.http.HttpServletRequest;import jakarta.servlet.http.HttpServletResponse;import org.slf4j.MDC;import org.springframework.core.Ordered;import org.springframework.core.annotation.Order;import org.springframework.stereotype.Component;import org.springframework.web.filter.OncePerRequestFilter;import java.io.IOException;import java.util.UUID;@Component@Order(Ordered.HIGHEST_PRECEDENCE)public class TraceIdFilter extends OncePerRequestFilter { public static final String TRACE_ID = "traceId"; @Override protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain chain) throws ServletException, IOException { // 上游网关已透传就沿用,保证全链路同一个 ID String traceId = request.getHeader("X-Trace-Id"); if (traceId == null || traceId.isBlank()) { traceId = UUID.randomUUID().toString().replace("-", "").substring(0, 16); } MDC.put(TRACE_ID, traceId); response.setHeader("X-Trace-Id", traceId); try { chain.doFilter(request, response); } finally { MDC.remove(TRACE_ID); // 必须清理,否则线程复用会串味 } }}Ordered.HIGHEST_PRECEDENCE:最先执行,确保后续所有日志都能带上 traceId- 优先读
X-Trace-Id:让网关或前端生成的 ID 一传到底,全链路可对齐 MDC.put后,pattern 里的%X{traceId}就会自动渲染,业务代码一行都不用改
第二步,pattern 里引用它(也就是第四节配的 [%X{traceId}]),日志立刻变成这样:
2026-10-07 10:12:33.482 INFO [http-nio-8080-exec-3] [9f2c1a7b3e5d8401] c.e.order.OrderService - 创建订单 orderId=10023这两步一个在内核里能按出来。第一格「放与取」,看的就是上面那个 map:MDC 底层是 ThreadLocal<Map<String,String>>,put 写进当前线程自己那份,%X{} 读的也是当前线程那一份:
第二格是那条 pattern:%X{traceId} 为什么有时候打印成 []?因为替换发生在 Encoder 那一格,读的是那一刻所在线程的 map,跟「这条业务从哪来」没有关系:
MDC 底层是 ThreadLocal,新开的线程拿不到父线程的 MDC。如果你的业务用了 @Async 或自定义线程池,日志里的 traceId 会变成空的。解法是给线程池装一个 TaskDecorator,在任务提交时把上下文复制过去:
@EnableAsync@Configurationpublic class AsyncConfig implements AsyncConfigurer { @Override public Executor getAsyncExecutor() { ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor(); executor.setCorePoolSize(8); executor.setMaxPoolSize(16); executor.setQueueCapacity(200); executor.setThreadNamePrefix("async-"); executor.setTaskDecorator(new MdcTaskDecorator()); // 关键:传递 MDC executor.initialize(); return executor; }}class MdcTaskDecorator implements TaskDecorator { @Override public Runnable decorate(Runnable runnable) { Map<String, String> context = MDC.getCopyOfContextMap(); // 提交线程快照 return () -> { try { if (context != null) MDC.setContextMap(context); // 在子线程还原 runnable.run(); } finally { MDC.clear(); // 归还线程前清空,避免污染下一个任务 } }; }}getCopyOfContextMap()在提交任务的线程上抓一份快照setContextMap()在执行任务的线程上还原finally里MDC.clear():线程池的线程会被复用,不清就会把上一个请求的 traceId 带给下一个请求,排查问题时会被彻底带偏
警告:MDC 清理漏掉一次,故障现象极其隐蔽——两个不相关的请求共享同一个 traceId,你会以为是同一笔业务。凡是 MDC.put,必须有一个对应的 finally { MDC.remove(...) },这是铁律。
挂与不挂 TaskDecorator,差别全在这张对照图里。注意左边最后一格——串味比空白更难查,因为日志看起来一切正常:

代码抄得到,顺序抄不到。把这条链摊成一次单步执行,连点下一步,盯线程名从 http-nio-8080-exec-3 变成 async-2 的那一拍,以及第 ④ 拍那个「在谁的线程上抓快照」:
MDC.put("traceId", "9f2c1a7b"); // TraceIdFilter,最先跑的一拍log.info("下单 userId={}", 7); // 这一行打得出 traceIdnotifier.sendAsync(order); // @Async:把活交给线程池Map<String,String> snap = MDC.getCopyOfContextMap(); // 在提交线程上抓快照executor.setTaskDecorator(new MdcTaskDecorator()); // 少这一行,后面全是空括号MDC.setContextMap(snap); task.run(); // 在 async-2 上回放,再执行log.info("短信已发 orderId={}", 10023); // 这行有没有 traceId,取决于第 ⑥ 拍| 线程 | http-nio-8080-exec-3 |
| 这条线程的 MDC | {traceId=9f2c1a7b} |
| 存储本质 | ThreadLocal<Map<String,String>> |
TraceIdFilter.doFilterInternalMDC.put同一条链在内核里跑一遍,切「异步」那一档就能看见 traceId 在第 ⑤ 拍消失:
搬到异步线程只解决了「一个进程内」。请求一旦打到下一个服务,MDC 是 ThreadLocal,天然过不去网络——它必须被塞进 HTTP 头,由对端的 Filter 再放回对端的 MDC。工业做法是 W3C 的 traceparent 头:
@Componentpublic class TraceFeignInterceptor implements RequestInterceptor { @Override public void apply(RequestTemplate template) { String traceId = MDC.get("traceId"); if (traceId != null) { template.header("traceparent", "00-" + traceId + "-" + spanId() + "-01"); } }}- 出站:拦截器从当前线程的 MDC 取值写进 header,所以第 7.1 节那套搬运是前提
- 入站:下游的
TraceIdFilter优先复用 header 里的 ID,没有才自己生成——这就是第七节那段request.getHeader("X-Trace-Id")的用意 - 两端格式要一致:
traceparent的字段顺序是版本-traceId-spanId-flags,自己拼的字段名对不上,链路系统只会把它当两个孤立请求
下面这条动画走完「同一个 ID 怎么跨过两次网络跳」,注意第 ④ 帧那个空括号:

真正上线时不必手写这一套——micrometer-tracing-bridge-brave 加 spring-boot-starter-actuator 就能让 Spring Boot 3 自动生成 traceId、自动放进 MDC 键 traceId/spanId,并自动透传 traceparent。本节手写它,是因为只有手动走过一遍,才知道框架替你做完了哪几拍。
前七节的日志对人友好,对机器不友好——ELK 采集时要写一堆正则才能提取字段。更工程化的做法是直接输出 JSON,一行一条,每条自带字段:
<dependency> <groupId>net.logstash.logback</groupId> <artifactId>logstash-logback-encoder</artifactId> <version>7.4</version></dependency><appender name="JSON_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${LOG_HOME}/${APP_NAME}-json.log</file> <encoder class="net.logstash.logback.encoder.LogstashEncoder"> <includeMdcKeyName>traceId</includeMdcKeyName> <!-- 把 MDC 里的 traceId 一并输出 --> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>${LOG_HOME}/${APP_NAME}-json.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern> <maxFileSize>100MB</maxFileSize> <maxHistory>15</maxHistory> </rollingPolicy></appender>输出就是一行标准 JSON:
{"@timestamp":"2026-10-07T10:12:33.482Z","level":"ERROR","logger_name":"com.example.order.OrderService","thread_name":"http-nio-8080-exec-3","traceId":"9f2c1a7b3e5d8401","message":"创建订单失败 orderId=10023","stack_trace":"java.lang.RuntimeException: 库存不足..."}@timestamp、level、logger_name等字段由 encoder 自动补全,无需手写includeMdcKeyName把 traceId 提成独立字段,ELK 里可以直接按它filter- 生产建议:控制台仍用人类可读格式,文件用 JSON——人看终端,机器读文件
| # | 规约 | 为什么 | 正确做法 |
|---|---|---|---|
| 1 | 禁止 System.out.println | 绕过日志框架,没有级别和格式 | 一律用 log.info(...) |
| 2 | 禁止 e.printStackTrace() | 打到 stderr,无时间戳无 traceId | log.error("msg", e) |
| 3 | 异常必须打完整堆栈 | 只有 message 等于没有线索 | 异常对象作为最后一个参数 |
| 4 | 禁止打印敏感信息 | 密码/token/身份证会进日志平台 | 脱敏后打,或只打 hash |
| 5 | 禁止在循环里打 INFO | 10 万次循环就是 10 万行日志 | 汇总成一条:「处理 N 条,失败 M 条」 |
| 6 | 用占位符,禁拼接 | 拼接在级别判定前就执行了 | log.debug("id={}", id) |
| 7 | 日志要可检索 | 无法定位的日志等于噪声 | 带上业务主键:orderId、userId |
| 8 | ERROR 要克制 | 全打 ERROR 会让告警失效 | 只有需人介入才 ERROR |
| 9 | 别用日志当流程控制 | 靠日志判断逻辑是脆弱设计 | 逻辑归逻辑,日志归日志 |
| 10 | 路径与级别外部化 | 硬编码无法适配环境 | 交给 yml / 配置中心 |
这十条里,第 1~3 条是红线——它们直接决定「出了问题能不能查」。其余是效率与规范问题,可以逐步治理,但红线一次都不能破。
AsyncAppender 默认策略是:当队列快满(剩余 20%)时,主动丢弃 TRACE/DEBUG 级别的事件,这叫 discardingThreshold。如果你既配了 neverBlock=true(队列满时不阻塞业务线程),又把 queueSize 设得很小,流量尖峰时就会丢日志——而丢的往往正是你最需要的那些。
异步日志丢日志的根本原因,是「不想让日志拖慢业务」和「一条都不能少」这两个目标天然冲突。要吞吐就把 queueSize 调大(如 4096)并接受极端情况下丢低级别;要零丢失就 neverBlock=false + discardingThreshold=0,代价是队列满时业务线程会被阻塞。没有两全,只有取舍。
这条取舍只有一个数字可以拖,拖一遍比读三遍管用。queueSize 从 64 拖到 8192,看丢的是谁、卡的是谁:
- 512~1024 对多数服务正好:能吞下秒级的写盘抖动
- 队列长度决定的是「能容忍多久的落盘延迟」,不是「会不会丢」
- 这时候还丢,说明磁盘或下游采集端真的跟不上,调队列没用
- 配套:includeCallerData 别打开,它会为每条事件抓调用栈
下面这段代码是事故常客:
// 反例:一次导入 5 万条数据,每条打一行 INFO,日志文件瞬间 500MB+for (Order order : orders) { log.info("正在处理订单 {}", order.getId()); importService.handle(order);}改成汇总:
int failed = 0;for (Order order : orders) { try { importService.handle(order); } catch (Exception e) { failed++; log.warn("单条导入失败 orderId={}", order.getId(), e); }}log.info("批量导入完成 total={}, failed={}", orders.size(), failed);- 单条成功不打日志,只打失败与汇总
- 这样一次导入只产生「失败数 + 1 条」日志,量级从 5 万降到个位数
log.debug("resp={}", hugeResponse) 看起来无害,但如果 hugeResponse.toString() 要递归序列化几千个字段,每次调用都在做重活。更糟的是有人习惯在 toString 里拼全量数据,一次日志能吃掉几十毫秒。
日志对象优先打「主键 + 关键字段」,不要图省事直接 log.debug("obj={}", obj) 打整个聚合根。真要看全量,也应该放进 if (log.isTraceEnabled()) 里,并且用专门的序列化手段,而不是靠 toString。
日志和 Bean 生命周期其实有个天然的连接点:如果要在「对象被创建」时打一条日志,应该挂在生命周期八个阶段的哪一步?下面这个演示把 Bean 从实例化到销毁的全过程跑一遍,边看边想这个问题。
- 想记录「谁被创建了」,最合适的是初始化后置(
BeanPostProcessor#postProcessAfterInitialization),此时依赖已注入、代理已就绪 - 想记录「资源被释放」,挂在销毁回调(
@PreDestroy) - 直接写在构造器里往往太早——依赖还没注入,日志内容不完整
前面把结论讲完了,这一节把「为什么是这个结论」跑出来。第〇节那张流水线图(业务调用 → 门面 → 绑定 → Filter → Layout → Appender → 落地)就是下面这个实验的主线:
级别过滤发生在格式化之前,第二节那条要点值得现场验证一次:
异步和滚动放在最后一起看,因为它们决定的是「事件放行之后」的命运:
- 绑定发生在启动早期,所以 classpath 里有多个绑定时会立刻告警(第十七节第一行)
- 级别过滤由 Logger 完成,
Filter由 Appender 完成——两者不是一回事,配错了会出现「级别明明开了却不打印」 - Layout/Encoder 是唯一能看到 MDC 的地方,
%X{key}在这里被替换 - AsyncAppender 改变的是「谁去做 I/O」,不改变「要不要输出这条日志」
- 滚动策略只在写满或到期时触发,
totalSizeCap才是真正的磁盘保险丝
日志这套东西有三个「不在链路里却决定链路行为」的外围机制,各用一个实验收尾。
第一个:你的 logging.level.* 到底怎么进到 Logback 里的?答案是走 Spring 的属性体系,因此优先级和 Profile 完全服从那一套规则:
第二个:第四节的在线热改级别,背后是谁在做这件事?Actuator 暴露了一个可写的端点,它直接调 Logback 的 API 改 Logger 对象:
第三个:第七节说 MDC 会在异步线程丢失,第十节说异步 Appender 会丢日志。这两个「异步」其实是同一类问题的两个方向——一个丢上下文,一个丢事件:
实验按完了,换成命令行自己敲。这台控制台连着浏览器里的同一个内核,回显全部由内核算出来——logs 直接看此刻打出来的日志长什么样,再逐条 lab:
logs 之后紧接着敲 lab logtrace async,两次输出并排看——同一段业务代码,前者那对括号里有值、后者是空的,差别只在执行线程。这就是第七.1 节整段话的三十秒版本。
新手最想知道的不是「有哪些级别」,而是「我这么配,屏幕上到底会跳出什么」。这个沙盘固定 root: INFO,只切换那个额外开 DEBUG 的包名,同屏对比输出行数与内容:
10:12:33.482 INFO c.e.o.OrderController - 下单请求 userId=710:12:33.490 DEBUG c.e.o.OrderService - 校验库存 sku=A1 need=2 stock=510:12:33.498 DEBUG c.e.o.PriceCalculator - 原价=99.0 券=10.0 应付=89.010:12:33.510 INFO c.e.o.OrderService - 订单创建成功 orderId=10023# 只有 order 包变吵,user/pay 包纹丝不动总行数:4 行/请求
这里的行数与体积是示意,但规律是真的——开 DEBUG 的成本按「请求数 × 每请求行数」放大。同一个包在你手上是 4 行,在 QPS 200 的接口上就是每秒 800 行。这也是为什么第四节的 Actuator 方案强调「用完立刻改回去」。
先来一道热身题,直接对应第一节那个翻车现场:
再来一道综合题,把第二节的级别继承、第四节的配置来源和第五节那个 logback.xml 陷阱串起来:
| 报错原文(片段) | 真实原因 | 30 秒自救 | 深挖看第几篇 |
|---|---|---|---|
Classpath collision detected: ... both import ... org.slf4j.impl.StaticLoggerBinder | classpath 上有两个以上绑定(例如既有 logback-classic 又有 log4j-slf4j-impl),SLF4J 只能挑一个,于是报警并随机选 | mvn dependency:tree -Dincludes=org.slf4j,ch.qos.logback,org.apache.logging.log4j 找出来,用 <exclusions> 只留一套 | 本篇第三节 |
Logging system failed to initialize using configuration from 'null' / Could not initialize Logback logging from class path resource [logback-spring.xml] | XML 本身语法错、appender 类名写错,或你在 logback.xml 里用了 <springProfile>(那个文件读得太早,不认识 Spring 标签) | 看 caused by 第一行指出的是哪个元素;确认文件名是 logback-spring.xml;临时把文件改名让它回落默认配置以确认是它的问题 | 本篇第五节 |
| 应用起来了但一行日志都没有,或者只有 banner | 级别被压住了:logging.level.root=ERROR,或某个第三方包把 root 改了;也可能是 logback.xml 抢先加载 | curl localhost:8080/actuator/loggers/ROOT 看 effectiveLevel;再看启动日志里有没有 Defaulting Log4J/Logback to ... | 本篇第二、四节 |
日志里 [traceId] 一直是空的 [] | 异步执行(@Async、线程池、CompletableFuture)在新线程上跑,新线程没有父线程的 MDC | 给线程池装 TaskDecorator(第七.1 节),并在 finally 里 MDC.clear() | 本篇第七节 |
| 流量尖峰后发现 ERROR 之外的日志整段消失 | AsyncAppender 的 discardingThreshold 默认会在队列剩 20% 时丢弃 TRACE/DEBUG;配了 neverBlock=true 时队列满还会直接丢 | 要零丢失就 discardingThreshold=0 + neverBlock=false 并接受阻塞;要吞吐就加大 queueSize | 本篇第十.1 节 |
日志文件里中文变成 ??? 或乱码 | encoder 没显式声明字符集,于是沿用 JVM 的 file.encoding;写入端与查看端(编辑器、tail、日志平台)编码不一致时必乱 | <encoder><charset>UTF-8</charset></encoder> 显式写上;必要时启动加 -Dfile.encoding=UTF-8,并统一查看端编码 | 本篇第五节 |
改了 logback-spring.xml 没生效 | 要么改的是 target/classes 下的副本,要么 scan="true" 没开且没重启 | 改源文件并重新编译;或在 <configuration scan="true" scanPeriod="60 seconds"> 上等待一分钟 | 本篇第五节 |
java.lang.IllegalStateException: Logback configuration error detected: ... Failed to parse mapping (Spring Boot 3.x) | logstash-logback-encoder 版本与 Logback 主版本不匹配 | 对齐版本(Boot 3.x 用 encoder 7.4+);mvn dependency:tree 确认没有两个 logback-classic | 本篇第八节 |
这张表里最容易被忽略的一行是「日志一行都没有」。九成不是框架坏了,而是有人在你看不见的地方放了另一个配置文件。第一件事永远是查 /actuator/loggers/ROOT 的实际生效级别,第二件事是搜 classpath 上有没有多个 logback*.xml。
「另一个配置文件」这件事,最典型的现场就是下面这段——它一行异常都没有,却把整个生产环境的级别决定权抹掉了。先别看解析,点出你认为的凶手行:
同事把项目里的 logback-spring.xml 重命名成 logback.xml,理由是「IDEA 提示我这个模板叫这个名字」。启动照常成功,只是 prod 环境的 INFO 好像从来没生效过。
目标:搭出一个「开发看彩色控制台、生产落 JSON 文件、并且带 traceId」的最小可用配置。
第一步,依赖只要默认的(spring-boot-starter-web 已带入 SLF4J + Logback),额外加结构化输出:
<dependency> <groupId>net.logstash.logback</groupId> <artifactId>logstash-logback-encoder</artifactId> <version>7.4</version></dependency>第二步,src/main/resources/logback-spring.xml:
<?xml version="1.0" encoding="UTF-8"?><configuration scan="true" scanPeriod="60 seconds"> <property name="LOG_HOME" value="./logs"/> <property name="PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] [%X{traceId}] %logger{36} - %msg%n"/> <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender"> <encoder> <pattern>%d{HH:mm:ss.SSS} %highlight(%-5level) [%X{traceId}] %cyan(%logger{36}) - %msg%n</pattern> <charset>UTF-8</charset> </encoder> </appender> <appender name="JSON_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender"> <file>${LOG_HOME}/bee-json.log</file> <encoder class="net.logstash.logback.encoder.LogstashEncoder"> <includeMdcKeyName>traceId</includeMdcKeyName> </encoder> <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy"> <fileNamePattern>${LOG_HOME}/bee-json.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern> <maxFileSize>50MB</maxFileSize> <maxHistory>7</maxHistory> <totalSizeCap>1GB</totalSizeCap> </rollingPolicy> </appender> <springProfile name="dev"> <root level="INFO"><appender-ref ref="CONSOLE"/></root> </springProfile> <springProfile name="prod"> <root level="INFO"> <appender-ref ref="CONSOLE"/> <appender-ref ref="JSON_FILE"/> </root> </springProfile></configuration>第三步,塞入 traceId 的那个 Filter 直接用第七节的 TraceIdFilter,然后在任意 Service 里写一行:
log.info("订单创建成功 orderId={}", order.getId());第四步,命令与预期输出:
$ mvn spring-boot:run -Dspring-boot.run.profiles=dev... Started BeeApplication in 3.42 seconds# 浏览器访问 /orders 后,控制台:10:12:33.510 INFO [9f2c1a7b3e5d8401] c.e.o.OrderService - 订单创建成功 orderId=10023$ ls logs/# dev profile 下没有 bee-json.log —— 因为 JSON_FILE 只挂在 prod 上看到控制台那行带方括号 traceId、且 logs/ 目录为空,就算过关。
- 换成
-Dspring-boot.run.profiles=prod再打一次请求。你会观察到:logs/bee-json.log出现,内容是一行标准 JSON,里面有"traceId":"9f2c1a7b3e5d8401"字段。 - 把
maxFileSize改成1KB,写个循环打 5000 行日志。你会观察到:目录下瞬间冒出bee-json.2026-10-07.0.log.gz、.1.log.gz… 一串分片,这就是%i的含义;再把totalSizeCap改成1MB,你会观察到老分片开始被删除。 - 故意把
<charset>UTF-8</charset>那行删掉,并在 Windows 控制台跑。你会观察到中文位置变成乱码——补回来即恢复。接着把文件名改成logback.xml(去掉-spring)重启,你会观察到启动直接抛Logging system failed to initialize,因为<springProfile>在那个文件里不被认识。
做一个「可运维的日志基线」,要求交付一份能被别人接手排障的配置。验收清单:
- [ ] 三个 profile(dev / staging / prod)用同一份
logback-spring.xml,靠<springProfile>区分,无重复文件 - [ ] 业务包 INFO、SQL 包按需 DEBUG,且第三方框架(Hibernate、Hikari)被压到 WARN 或 INFO
- [ ] 有一条完整的 traceId 链路:入口 Filter 写入 → pattern 输出 → 异步线程通过
TaskDecorator不丢失 → 响应头回传 - [ ] ERROR 单独落到一个文件,且只收 ERROR(
LevelFilter的 onMatch/onMismatch 都用上了) - [ ] 文件同时受
maxFileSize、maxHistory、totalSizeCap三者约束,并能解释「少了 totalSizeCap 会发生什么」 - [ ] 用 Actuator 把一个包临时调到 DEBUG、复现一次问题、再改回 INFO,全程不重启
- [ ] README 里写清:出线上问题时,第一句该执行的
curl命令是什么
我能说出「门面 / 实现 / 桥接包」三者分别对应流水线的哪几格吗?说不出就回到第〇节那张图。
我知道 logback.xml 与 logback-spring.xml 的差别不是名字而是加载时机,因此后者才有 <springProfile> 吗?
我的每条 log.error 都把异常对象放在了最后一个参数,而不是 e.getMessage()?
我的异步线程池装了 TaskDecorator,并且 MDC 的每次 put 都能在同一个方法里找到一个 finally 里的 remove/clear?
我能对 queueSize、discardingThreshold、neverBlock 三个参数的任意组合,说出「丢了什么、堵了谁」?
代码只认插头,插座随便换;级别能热调,MDC 必归还。
这一节请把三件事刻进肌肉记忆——业务代码只依赖 SLF4J 门面,实现交给 Logback;级别是过滤门槛而不是重要性排序,能动态调就别重启;MDC 的 put 必须配一个 finally 里的 remove。日志的价值不在「写了多少」,而在「出问题时能不能在十秒内定位」——把它当成一门可检索的工程能力,而不是随手一行的 println。