日志框架与日志规范

S3-026必学进阶约 60 分钟JDK 21企业开发基础 · Spring Boot

1. 本节定位

《Spring Boot 配置管理与多环境》管"配置怎么给"，本节管**"运行信息怎么记"**。

日志是线上系统的"黑匣子"：出问题时，你能依靠的只有它——因为生产环境你既不能调试，也不能复现。

本节要解决的核心问题只有一个：

用户说"我下单报错了"，你怎么在几万行日志里找到那一次请求？

答案就是 traceId——《参数校验与全局异常处理》已经在错误响应里给了它，本节讲怎么让它出现在日志里。

2. 学习目标

完成本节后，你应该能够：

说出 SLF4J 与 Logback 的分工，以及为什么业务代码只用 SLF4J 的 API；
说出五个日志级别各自的判断标准（不是背定义，是知道"什么情况用哪个"）；
用 MDC 给一次请求的所有日志打上 traceId，并说出"不清理会怎样"；
说出日志格式里六个字段各自的用途；
说出哪些内容绝对不能打进日志；
说出日志滚动策略的三个参数及不配置的后果；
说出"占位符"相对"字符串拼接"的性能收益。

3. 前置知识检查

知道 Spring Boot 的配置外置与 profile 吗？（《Spring Boot 配置管理与多环境》）
知道统一错误响应里的 traceId 吗？（《参数校验与全局异常处理》的 5.6 节）

4. 为什么需要这个知识

先看"用 System.out.println 打日志"的五个问题：

java

System.out.println("用户下单：" + userId);        // ✗

#	问题	后果
1	没有级别	生产环境无法"只留重要的"——要么全输出（淹没）、要么删代码 ✗
2	没有时间戳	无法判断"什么时候发生的"
3	没有来源	不知道是哪个类打的
4	输出目标写死	只能到控制台，无法落盘、无法采集到日志系统 ✗
5	不能动态调整	想临时看细一点？改代码、重新部署 ✗

第 5 条最要命：线上排查问题时，"能不能临时把某个包的日志调成 DEBUG"往往决定了排查速度 ✓

用日志框架，改一行配置就能做到：

yaml

logging:
  level:
    cn.kb.learn.web.service: debug        # 临时打开，排查完改回去

5. 核心概念

5.1 SLF4J + Logback：门面与实现

text

你的代码  →  org.slf4j.Logger（门面 / 接口）
                    ↓
              Logback（实现，Spring Boot 默认）
                    ↓
         控制台 / 文件 / 日志采集系统

角色	是什么	为什么这样分
SLF4J	日志门面（一套接口）	业务代码只依赖它——换实现不用改代码 ✓
Logback	日志实现	Spring Boot 的默认选择（Log4j2 也常用）

所以取 logger 的写法是固定的：

java

private static final Logger log = LoggerFactory.getLogger(LoggingLessonRunner.class);

注意 static final：logger 是线程安全且可复用的，每个类一个就够了 ✓

⚠️ 一条实践规则：

绝不要在业务代码里 import ch.qos.logback.* 或 org.apache.logging.log4j.* ✗
只用 org.slf4j.* ✓——否则换日志实现时要改所有文件。

Spring Boot 的 starter 已经自带：spring-boot-starter-logging（含 SLF4J + Logback）✓ 不需要额外加依赖 ✓

5.2 五个级别与选择标准

从低到高：TRACE < DEBUG < INFO < WARN < ERROR

级别是有"开关"的：配置成 INFO 时，TRACE 和 DEBUG 都不会输出 ✓

本节实测：在 dev（DEBUG 级别）下输出五条日志，结果只看到四条：

text

15:10:25.774 DEBUG [main] [] cn.kb.learn.web.LoggingLessonRunner - debug：开发时看流程，例如「进入方法 X，参数 Y」
15:10:25.777 INFO  [main] [] cn.kb.learn.web.LoggingLessonRunner - info：关键业务节点，生产要保留（下单成功、定时任务开始/结束）
15:10:25.778 WARN  [main] [] cn.kb.learn.web.LoggingLessonRunner - warn：可恢复的异常（重试成功、降级生效）
15:10:25.779 ERROR [main] [] cn.kb.learn.web.LoggingLessonRunner - error：需要人介入的错误

trace 那一行不见了——因为 logger 级别是 DEBUG，TRACE 被过滤掉了 ✓

这条"没输出的日志"本身就是最好的演示：级别不是"标签"，它是真的会拦住输出 ✓

选择标准（不是背定义）：

级别	什么时候用	典型例子	生产环境
`TRACE`	只在本地排查时临时用	循环内每一步的值	绝不开启 ✗
`DEBUG`	开发时看流程	"进入方法，参数是..."	默认关，可按包临时打开 ✓
`INFO`	关键业务节点	下单成功、定时任务开始与结束、启动完成	保留 ✓
`WARN`	可恢复但需要留意	重试成功、降级返回缓存、参数被截断	保留并监控 ✓
`ERROR`	需要人介入	数据库连不上、外部接口持续失败、未预期异常	保留并告警 ✓

三个最容易用错的：

错误用法	问题	正确做法
用 `INFO` 打循环里的每一条	日志量爆炸、磁盘写满	降级到 `DEBUG`，或汇总成一条（"处理了 1000 条，失败 3 条"）
用 `ERROR` 打"用户输错了密码"	大量 ERROR 淹没真问题、告警疲劳 ✗	这是业务正常流程，用 `INFO` 或 `WARN`
用 `WARN` 打异常但继续跑	⚠️ 要看情况：能自动恢复的用 WARN，不能的用 ERROR	判断标准："需不需要人去看？"

一条实用规则：

ERROR 的数量应该与"告警次数"大致相当。
如果你们的 ERROR 日志每天几万条却没人看，说明级别用错了——告警会被淹没，真正的问题反而漏掉 ✗

5.3 日志格式：六个字段

本节的格式（logback-spring.xml）：

xml

<pattern>%d{HH:mm:ss.SSS} %-5level [%thread] [%X{traceId:-}] %logger{36} - %msg%n</pattern>

输出：

text

15:10:25.774 DEBUG [main] [] cn.kb.learn.web.LoggingLessonRunner - debug：开发时看流程，例如「进入方法 X，参数 Y」
│            │      │      │  │                              │
│            │      │      │  └─ logger 名（到 36 字符）      └─ 消息
│            │      │      └─ traceId（MDC 里取，没有就空）
│            │      └─ 线程名
│            └─ 级别（左对齐 5 位）
└─ 时间（毫秒精度）

字段	用途	少了它会怎样
时间	定位"什么时候"	无法与外部事件对齐
级别	过滤与告警	无法"只看错误"
线程名	判断并发问题	分不清哪些日志来自同一个请求 ✗
traceId	串起一次请求 ★	几万行日志里找不到那一次 ✗
logger 名	定位代码位置	不知道该去哪个类看
消息	发生了什么	—

两个格式配置的小技巧：

配置	作用
`%-5level`	级别左对齐占 5 位——日志纵向对齐，好读 ✓
`%logger{36}`	logger 名超过 36 字符时缩写中间部分（保留头尾）——避免长包名撑满一行 ✓

5.4 MDC 与 traceId：把一次请求的日志串起来

问题：一个请求会经过 Filter、Controller、Service、DAO，每层都打日志——怎么知道哪些日志属于同一次请求？

MDC（Mapped Diagnostic Context）的机制：

text

MDC 是一个"线程绑定"的 Map：MDC.put("traceId", "abc")
  ↓
日志格式里的 %X{traceId} 会自动从当前线程的 MDC 里取值
  ↓
这一次请求的所有日志（同一个线程）都会自动带上它

实现（一个 Filter 搞定）：

java

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

    public static final String TRACE_ID_KEY = "traceId";

    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
                                    FilterChain filterChain) throws ServletException, IOException {
        String traceId = request.getHeader("X-Trace-Id");              // ① 优先复用上游传的
        if (traceId == null || traceId.isBlank()) {
            traceId = UUID.randomUUID().toString().replace("-", "").substring(0, 16);
        }

        MDC.put(TRACE_ID_KEY, traceId);
        response.setHeader("X-Trace-Id", traceId);                     // ② 回给调用方
        try {
            filterChain.doFilter(request, response);
        } finally {
            MDC.remove(TRACE_ID_KEY);                                  // ③ ★ 必须清理
        }
    }
}

实测：一个 traceId 同时出现在"响应头"和"日志"里 ↓↓

响应头：

text

HTTP/1.1 404
X-Trace-Id: 6034908592b14ae3

日志：

text

15:10:47.011 DEBUG [http-nio-18080-exec-2] [6034908592b14ae3] cn.kb.learn.web.web.TraceIdFilter - 请求进入 GET /api/orders/ORD-999，traceId=6034908592b14ae3

6034908592b14ae3 这个值在两处完全一致 ✓✓

这就是"可排查性"的全部秘密：
用户报出响应体里的 traceId → 你拿它去日志里搜 → 立刻拿到这一次请求的全部上下文。

与《参数校验与全局异常处理》的打通（本项目已改造）：

java

private String currentTraceId() {
    String traceId = MDC.get(TraceIdFilter.TRACE_ID_KEY);         // 优先用 Filter 放进 MDC 的那个
    return traceId != null ? traceId : UUID.randomUUID().toString();
}

改造前后对比：

	改造前	改造后
响应体里的 traceId	每次新生成一个 UUID	与日志里的一致 ✓
用户报 id 后能查到什么	什么也查不到 ✗	整个请求的处理链路 ✓

⚠️ 一条重要的设计提醒：traceId 只在"同一个线程"里有效 ✗

场景	会怎样
`@Async` 的异步方法	MDC 不会自动传递 ✗ 需要手动传或配置 `TaskDecorator`
线程池里执行的任务	同上
`CompletableFuture` 的异步链	同上

处理方式（示意）：

java

public class MdcTaskDecorator implements TaskDecorator {
    @Override
    public Runnable decorate(Runnable runnable) {
        Map<String, String> context = MDC.getCopyOfContextMap();       // 提交任务时抓一份
        return () -> {
            if (context != null) {
                MDC.setContextMap(context);                            // 在子线程里恢复
            }
            try {
                runnable.run();
            } finally {
                MDC.clear();
            }
        };
    }
}

这就是《Spring：AOP 与事务》讲的"事务不跨线程"的同一个道理：线程绑定的东西，跨线程时必须显式传递 ✓

5.5 `MDC.remove` 为什么必须写

这是本节最容易忽略、后果最难查的一点。

Tomcat 处理请求用的是线程池：

text

请求 A → 线程 exec-1 → MDC.put("traceId", "AAA") → 处理完 → 线程归还池子
请求 B → 复用 exec-1 → 如果没清理，MDC 里还是 "AAA" ✗✗

后果：请求 B 的所有日志都带着请求 A 的 traceId ✗

危害	说明
串号	用户 B 报错，你按他给的 traceId 搜，搜到的是用户 A 的日志 ✗
比"没有 traceId"更糟	没有 id 只是查不到；错的 id 会把你引向错误结论 ✗✗
难复现	只在"线程被复用"时出现，本地单请求测试永远正常 ✗

所以 finally 里那一行不能省：

java

try {
    filterChain.doFilter(request, response);
} finally {
    MDC.remove(TRACE_ID_KEY);      // ★ 不管成不成功、有没有异常，都要清
}

更彻底的做法：用 MDC.clear()（如果你放了多个 key，clear 一次全清）✓

5.6 什么该打、什么不该打

先说"绝对不能打"的（这是安全红线）：

不能打	为什么
密码、密钥、Token	日志系统往往比数据库更容易被更多人访问 ✗
身份证号、银行卡号、完整手机号	合规问题（个人信息保护）
完整的请求体（含用户隐私字段）	同上
堆内存里的对象 dump	体积巨大且可能含敏感数据

本项目的做法（《Spring Boot 配置管理与多环境》的 5.4 节）：

java

System.out.println("数据库密码（演示不落盘） = " + mask(environment.getProperty("DB_PASSWORD")));

private String mask(String value) {
    return value == null || value.isBlank() ? "（未设置）" : "***已设置（长度 " + value.length() + "）***";
}

输出：

text

数据库密码（演示不落盘） = （未设置）

需要确认"配没配上"时，打印"有没有值"就够了，不需要打印值本身。

再说"该打什么"（四条判断标准）：

场景	打不打	怎么打
关键业务节点	✅	`下单成功 orderNo=ORD-1 amount=39800`——含关键标识
异常	✅	必须带上异常对象（打完整堆栈），见 9.2 节
耗时	✅	外部调用与慢查询的耗时（便于发现性能退化）
状态变化	✅	订单状态流转、任务开始/结束
循环体内部	❌	或降级为 DEBUG + 汇总
"我进来了"这种无信息量的	❌	没有可分析的内容

一条自检问题：

"这条日志，在我排查问题时能用上吗？"
不能 → 别打。 日志的价值在信噪比，不在数量。

5.7 滚动与磁盘保护

不配滚动的后果：日志文件无限增长 → 磁盘写满 → 服务全线崩溃 ✗

（这不是假设：磁盘满了以后，数据库也会写不进去，故障面会迅速扩大 ✗）

本节的配置：

xml

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>target/logs/app.log</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>target/logs/app.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
        <maxFileSize>10MB</maxFileSize>          <!-- 单个文件上限 -->
        <maxHistory>7</maxHistory>                <!-- 保留 7 天 -->
        <totalSizeCap>200MB</totalSizeCap>        <!-- 总量上限，超出后删最旧的 -->
    </rollingPolicy>
    <!-- encoder 省略 -->
</appender>

三个参数的配合关系：

参数	作用	不设的后果
`maxFileSize`	单文件多大后切新文件	一个文件几个 GB，打不开也搜不动 ✗
`maxHistory`	保留多少天	磁盘被历史日志占满 ✗
`totalSizeCap`	所有日志的总上限	`maxHistory` 只管天数，不管总量——高峰期一天可能产生几十 GB ✗

⚠️ 一个容易踩的点：maxHistory 和 totalSizeCap 要一起用 ✓

maxHistory 只是"时间维度的上限"，它保证不了磁盘占用 ✗ 例如"保留 7 天"但日流量 50GB → 350GB ✗

totalSizeCap 才是"空间维度的硬上限" ✓

两条额外的实践：

实践	说明
日志目录别放在系统盘	写满系统盘会连累整个机器
给日志目录挂监控	"剩余空间 < 20%" 就该告警（《进程与端口排查》会讲排查）

5.8 占位符：不只是"好看"

两种写法：

java

log.info("占位符（推荐）：用户 {} 创建了订单 {}，金额 {} 分", "u-1", "ORD-1", 39_800);
log.info("字符串拼接（不推荐）：用户 " + "u-1" + " 创建了订单 " + "ORD-1" + "，金额 " + 39_800 + " 分　← 即使级别不开也会白拼字符串");

实测两条都能输出，但性能不同：

写法	级别不开时（如生产是 INFO，这条是 DEBUG）
占位符	参数根本没被用，只做一次级别判断就返回 ✓
字符串拼接	字符串已经拼好了，然后被丢掉 ✗

所以占位符的价值是"惰性求值" ✓ 在高频日志（循环、热点方法）里差别明显。

另一个原因：占位符把"模板"和"参数"分开，日志采集系统更容易做结构化解析 ✓

6. 递进示例

6.1 最小示例：一条日志

java

private static final Logger log = LoggerFactory.getLogger(MyService.class);

log.info("订单创建成功 orderNo={} amount={}", orderNo, amount);

6.2 业务示例：traceId 贯穿

见第 7 节。

6.3 反例：循环里打 INFO

java

for (Order order : orders) {
    log.info("处理订单：" + order);          // ✗ 一万个订单一万行日志
    process(order);
}

修复：

java

log.info("开始处理订单，总数={}", orders.size());
int failed = 0;
for (Order order : orders) {
    log.debug("处理订单 {}", order.getOrderNo());       // 细节降到 DEBUG
    if (!process(order)) {
        failed++;
    }
}
log.info("订单处理完成，成功={} 失败={}", orders.size() - failed, failed);   // 汇总一条

对比：

	循环里打 INFO	汇总 + 细节降级
日志量	与数据量成正比 ✗	恒定 ✓
生产可用性	一次批处理写满磁盘 ✗	正常 ✓
排查能力	有细节但找不到重点 ✗	默认看汇总，需要时临时开 DEBUG ✓

7. 完整可运行代码

文件清单（labs/spring-boot-web/）：

text

src/main/resources/logback-spring.xml              日志配置（含按 profile 切换）
src/main/java/cn/kb/learn/web/
├── web/TraceIdFilter.java                         MDC 注入与清理
├── LoggingLessonRunner.java                       级别、占位符、MDC 演示
└── exception/GlobalExceptionHandler.java          改造为从 MDC 取 traceId

日志配置的核心片段：

xml

<property name="PATTERN"
          value="%d{HH:mm:ss.SSS} %-5level [%thread] [%X{traceId:-}] %logger{36} - %msg%n"/>

<!-- 按环境切换：生产收敛、其他环境详细 -->
<springProfile name="prod">
    <logger name="cn.kb.learn.web" level="INFO"/>
    <root level="WARN">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</springProfile>

<springProfile name="!prod">
    <logger name="cn.kb.learn.web" level="DEBUG"/>
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</springProfile>

⚠️ 注意用的是 logback-spring.xml（不是 logback.xml）——只有前者支持 <springProfile> ✓

运行命令：

powershell

cd labs
./mvnw -pl spring-boot-web package -DskipTests
java "-Dstdout.encoding=UTF-8" -jar spring-boot-web/target/spring-boot-web.jar --spring.profiles.active=dev

预期输出（节选真实结果）：

text

===== S3-026 日志框架与日志规范 =====
当前 logger 的级别由 logback-spring.xml 与 profile 共同决定：

15:10:25.774 DEBUG [main] [] cn.kb.learn.web.LoggingLessonRunner - debug：开发时看流程，例如「进入方法 X，参数 Y」
15:10:25.777 INFO  [main] [] cn.kb.learn.web.LoggingLessonRunner - info：关键业务节点，生产要保留（下单成功、定时任务开始/结束）
15:10:25.778 WARN  [main] [] cn.kb.learn.web.LoggingLessonRunner - warn：可恢复的异常（重试成功、降级生效）
15:10:25.779 ERROR [main] [] cn.kb.learn.web.LoggingLessonRunner - error：需要人介入的错误

写法对比：
15:10:25.786 INFO  [main] [] cn.kb.learn.web.LoggingLessonRunner - 占位符（推荐）：用户 u-1 创建了订单 ORD-1，金额 39800 分

MDC traceId 演示（同一个请求内的日志会带同一个 id）：
15:10:25.791 INFO  [main] [demo-trace-0001] cn.kb.learn.web.LoggingLessonRunner - 手工放进 MDC 的这条日志带了 traceId

紧接着发一个请求，用同一份日志验证"traceId 贯穿"：

powershell

curl.exe -s -D - -o NUL "http://localhost:18080/api/orders/ORD-999"

响应头：

text

HTTP/1.1 404
X-Trace-Id: 6034908592b14ae3

日志里对应的那一行（traceId 完全一致）：

text

15:10:47.011 DEBUG [http-nio-18080-exec-2] [6034908592b14ae3] cn.kb.learn.web.web.TraceIdFilter - 请求进入 GET /api/orders/ORD-999，traceId=6034908592b14ae3

三处值得盯住的输出：

输出	说明了什么
`trace` 那一行没有出现	级别真的会拦住输出（DEBUG 配置下 TRACE 被过滤）
其他五行的 `[]` 是空的，MDC 那行是 `[demo-trace-0001]`	MDC 里没值时占位为空，有值是原样输出 ✓
`[6034908592b14ae3]` 同时出现在响应头与日志	可排查性：用户报的 id 能直接搜到日志 ★

8. Debug 观察点

在 TraceIdFilter.doFilterInternal 的第一行打断点：观察 MDC.get("traceId") 在进入时是 null（上一个请求已清理）——这是"清理生效"的证据；
把 finally 里的 MDC.remove 注释掉，连发两个请求——观察第二个请求的日志带着第一个请求的 traceId ✗（串号现场）；
在 Environment.getProperty("logging.level.cn.kb.learn.web") 处断点：确认级别是配置与 profile 共同决定的；
把日志格式里的 %X{traceId:-} 改成 %X{traceId}：观察 MDC 没值时输出什么（提示：会输出一个字面量 traceId，反而更乱 ✗）；
把 %thread 去掉：观察日志仍然能打，但排查并发问题时少了关键信息 ✗。

9. 常见错误

错误 1：`e.printStackTrace()`

java

try {
    doSomething();
} catch (Exception e) {
    e.printStackTrace();             // ✗
}

三个问题：

问题	说明
输出到 `System.err`	不经过日志框架——级别控制、格式、落盘、采集全都绕过 ✗
格式不可控	没有时间戳、没有 traceId，在日志系统里混成一团 ✗
生产环境可能被丢弃	某些容器的 stderr 处理策略会把它的顺序打乱

修复：

java

log.error("处理订单失败 orderNo={}", orderNo, e);         // ✓ 异常作为最后一个参数

错误 2：`log.error(e.getMessage())` —— 丢掉堆栈

java

catch (Exception e) {
    log.error("处理失败：" + e.getMessage());        // ✗ 只有一行消息，没有堆栈
}

后果：看不到"在哪里抛的、经过了哪些调用" ✗ 排查靠猜。

三种写法的差别：

写法	输出
`log.error(e.getMessage())`	只有消息 ✗
`log.error("处理失败", e)`	消息 + 完整堆栈 ✓ 推荐
`log.error("处理失败 {}", e.toString())`	只有 `类名: 消息`，没有堆栈 ✗

判断方法：问自己"出问题时，这行日志能让我定位到代码行吗？" ✓

错误 3：`log.info("用户信息：" + user.toString())`

两个问题：

问题	说明
可能含敏感字段（密码、手机号）	安全与合规风险 ✗（5.6 节）
`toString()` 可能是个坑	如果它内部又查了数据库（懒加载），打日志会触发额外查询 ✗

修复：只打关键标识 + 必要字段：

java

log.info("用户注册成功 userId={} source={}", user.getId(), user.getSource());

错误 4：`MDC` 不清理

见 5.5 节。串号比没有更糟 ✗

错误 5：用了 `logback.xml` 而不是 `logback-spring.xml`

text

logback.xml          → Logback 直接加载，<springProfile> 不生效 ✗
logback-spring.xml   → 由 Spring Boot 加载，支持 <springProfile> 与 <springProperty> ✓

症状：按 profile 的日志配置完全不生效，但也不报错 ✗

错误 6：日志占满了磁盘

见 5.7 节。只配 maxHistory 不配 totalSizeCap 是典型疏忽 ✗

排查方向：服务突然全线异常 → 检查磁盘（df -h）→ 发现日志目录写满 ✓

错误 7：生产环境开了 DEBUG

yaml

logging:
  level:
    root: debug                # ✗ 全量 DEBUG

后果：日志量放大 10~100 倍、磁盘迅速写满、正常的 ERROR 被淹没 ✗

正确做法：只对排查的那个包临时开：

yaml

logging:
  level:
    cn.kb.learn.web.service: debug       # ✓ 精确到包

更稳的做法：用 actuator 的 loggers 端点在线调整（不用重启、改完立刻生效、重启后自动恢复）✓

10. 动手实验

目标：把级别、MDC、滚动三件事亲手验一遍。

步骤：

运行第 7 节的命令，核对三处关键输出（特别是 trace 那行的缺失）；
验证 MDC 串号：注释掉 MDC.remove，连发两个请求（curl 两次），在日志里对比两个 traceId——观察第二个是否复用了第一个的 id；
恢复后验证清理：再连发两次，确认两个 traceId 不同 ✓；
验证级别过滤：把 logback-spring.xml 里 cn.kb.learn.web 的级别改成 INFO，重启——观察 debug 与 trace 都不输出；
验证 totalSizeCap：把 maxFileSize 改成 1KB、totalSizeCap 改成 5KB，重启并多发几个请求——观察 target/logs/ 下文件的数量与总量被限制住；
验证 traceId 复用上游的：

powershell

curl.exe -s -D - -o NUL -H "X-Trace-Id: my-custom-trace-001" "http://localhost:18080/api/orders/ORD-999"
# 观察响应头回传的 X-Trace-Id 是不是 my-custom-trace-001，日志里是不是也是它

验收方式：能说出第 2 步串号的原因、第 6 步"为什么上游传的 id 优先"。

扩展任务：把 traceId 打通到 @Async：

加一个 @Async 的方法（需要 @EnableAsync），在里面打一条日志；
先观察：日志里的 traceId 是空的（MDC 没传过去）✗
再修：按 5.4 节实现 TaskDecorator，把它配到 ThreadPoolTaskExecutor 上；
验证：异步方法里的日志带上了与主线程相同的 traceId ✓

11. 练习题

基础题

判断：log.debug(...) 在级别配置为 INFO 时，参数字符串仍然会被拼接。（对 / 错，分"占位符写法"与"字符串拼接写法"分别回答）
填空：MDC 是 ______ 绑定的；过滤器里清理 MDC 必须放在 ______ 块中。
简答：为什么 log.error(e.getMessage()) 是不好的写法？

代码阅读题

java

@GetMapping("/{id}")
public UserResponse find(@PathVariable Long id) {
    log.info("查询用户：" + id);
    User user = userService.findById(id);
    if (user == null) {
        log.error("用户不存在：" + id);            // ← 这里
        throw new ResourceNotFoundException("用户", String.valueOf(id));
    }
    log.info("查到用户：" + user.toString());      // ← 这里
    return toResponse(user);
}

这段代码里的日志有几个问题？分别是什么？
其中哪一个问题在"生产环境告警"上会造成最直接的后果？

编程题

为一个"订单导出"任务写完整的日志方案：
- 需求：导出 10 万条订单到 CSV，包含"查数据、写文件、压缩、上传"四个阶段；
- 要求：
  - 每个阶段打开始与结束日志（含耗时）；
  - 不要在循环里打 INFO（10 万条会淹没日志）；
  - 失败时打完整堆栈（并保留"已处理多少条"的上下文）；
  - 用 traceId（或任务 ID）把同一个任务的日志串起来（提示：定时任务没有 HTTP 请求，需要自己 MDC.put）；
  - 结束后打一条汇总日志（成功数、失败数、耗时、文件大小）；
- 写完后回答："为什么定时任务也要有 traceId / taskId？"

综合任务

设计一套"日志规范与可观测性方案"：
- 背景：系统上线后，平均一次线上问题排查要 2 小时，主要卡在"找不到相关日志"；
- 要求：
  - 写一份至少 8 条的日志规范（覆盖：级别选择、格式字段、敏感信息、循环日志、异常堆栈、traceId、日志保留策略）；
  - 设计"一次请求的可观测链路"：从用户报错到你定位到代码行，中间需要哪些信息？（画出信息流）
  - 说明"结构化日志"（JSON 格式）相比纯文本日志的优势；
  - 说明"日志、指标、链路追踪"三者的分工（提示：日志回答"发生了什么"，指标回答"现在多快/多频繁"，链路追踪回答"慢在哪一段"）；
- 额外要求：估算一下"如果每个日志级别用错一档，磁盘与排查时间会差多少倍"，并说明你的取舍。

分级提示

提示 1（方向）：第 1 题要分两种写法——占位符是惰性的，拼接不是。

提示 2（关键点）：第 4 题里"用户不存在"该用什么级别？

提示 3（接近答案）：第 6 题的"定时任务 traceId"——没有 HTTP 请求，没人帮你注入 MDC，得自己在任务开始时 put、结束时 remove。

12. 参考答案

基础题

分两种情况：

写法	级别为 INFO 时
`log.debug("x={}", x)`	✅ 不拼接——参数根本没被用到（惰性求值）
`log.debug("x=" + x)`	❌ 已经拼接完了，然后被丢掉 ✗

这就是 5.8 节的结论：占位符的收益在"级别不开时"最大 ✓

一个容易忽略的例外：如果参数本身是"昂贵计算"，两种写法都会执行：

java

log.debug("结果={}", expensiveComputation());      // ⚠️ expensiveComputation() 也会被调用！

修复：加级别判断：

java

if (log.isDebugEnabled()) {
    log.debug("结果={}", expensiveComputation());
}

判断标准：参数是"取个字段"就不用判断；是"查库/计算"就要包 isDebugEnabled ✓

线程；finally。

为什么必须是 finally：请求处理抛异常时也要清理 ✗ 否则出错的请求会把 traceId 留给下一个正常请求——恰恰在最需要正确 traceId 的时候串了号 ✗✗

因为丢掉了堆栈信息 ✗

信息	有堆栈	只有 message
异常类型	✅	有时能猜出来
异常消息	✅	✅
抛出位置（哪一行）	✅	❌
调用链	✅	❌
根因（`Caused by`）	✅	❌

一个真实的场景：

java

log.error(e.getMessage());        // 输出：Connection reset

排查者看到这一行能做什么？几乎不能 ✗ —— 不知道是哪个连接、在哪一行、被谁调用。

正确写法：

java

log.error("调用支付服务失败 orderNo={} amount={}", orderNo, amount, e);      // ✓ 上下文 + 堆栈

注意参数顺序：异常对象必须是最后一个参数（SLF4J 的约定）✓

代码阅读题（第 4、5 题）

第 4 题：四个问题。

#	问题	正确做法
1	`log.info("查询用户：" + id)` 用了拼接（不致命，但不是好习惯）	`log.info("查询用户 id={}", id)`
2	`log.error("用户不存在：" + id)` 级别错了 ★	"用户不存在"是业务正常流程（用户输错 id 很正常），不是系统错误 ✗
3	`log.info("查到用户：" + user.toString())` 可能泄露敏感信息 ★	只打关键字段（`userId`、`username`），不打整个对象
4	缺少"上下文一致性"：两条日志没有共同的 traceId（如果类里没有 MDC，或者这个接口经过 Filter 则其实有）	依赖 `TraceIdFilter` 注入（本项目已有）✓

第 5 题：第 2 个问题（log.error 用于业务正常流程）在告警上后果最直接。

连锁反应：

text

用户输错 id（很常见的操作）
  → log.error
  → 告警系统按"ERROR 数量 > 阈值"触发
  → 凌晨三点告警电话
  → 工程师爬起来发现是"用户输错了 id"
  → 第二天把告警阈值调高 / 屏蔽这个告警
  → ✗✗ 真的故障来了，也不会告警了

这就是"告警疲劳"的完整链条 ✓

正确的级别选择：

情况	级别	理由
用户查了一个不存在的 id	`INFO`（或 `WARN`）	业务正常流程，不需要人介入
列表接口返回空	不打，或 `DEBUG`	完全正常
参数格式错误（422）	`WARN`	客户端的问题，值得留意但不用告警
数据库连不上	`ERROR`	需要人介入 ✓
外部接口持续失败	`ERROR`	需要人介入 ✓
未预期异常（500）	`ERROR`	需要人介入 ✓

判断标准（本节的 5.2 节）：

"这条日志出现时，需不需要有人半夜爬起来？"
需要 → ERROR；不需要 → 降级。

顺带支持这个判断：HTTP 4xx 是客户端的问题，5xx 才是服务端的问题 ✓ ——日志级别应该与这个语义对齐 ✓

编程题（第 6 题）

java

package cn.kb.learn.data;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

import java.nio.file.Path;
import java.util.UUID;

/** 订单导出：定时任务如何打日志（任务级 traceId + 阶段耗时 + 汇总） */
public class OrderExportTask {
    private static final Logger log = LoggerFactory.getLogger(OrderExportTask.class);
    private static final int BATCH_SIZE = 2000;

    public ExportResult export(long sinceEpochMillis, Path targetDir) {
        // 定时任务没有 HTTP 请求，没人帮我们注入 MDC —— 自己来
        String taskId = "export-" + UUID.randomUUID().toString().replace("-", "").substring(0, 12);
        MDC.put("traceId", taskId);
        long started = System.currentTimeMillis();
        try {
            log.info("导出任务开始 since={} targetDir={}", sinceEpochMillis, targetDir);

            long t0 = System.currentTimeMillis();
            long total = countOrders(sinceEpochMillis);
            log.info("阶段 1/4 统计完成 total={} 耗时={}ms", total, System.currentTimeMillis() - t0);

            t0 = System.currentTimeMillis();
            Path csv = writeCsv(sinceEpochMillis, targetDir, total);
            log.info("阶段 2/4 写文件完成 file={} 耗时={}ms", csv.getFileName(), System.currentTimeMillis() - t0);

            t0 = System.currentTimeMillis();
            Path gz = compress(csv);
            log.info("阶段 3/4 压缩完成 file={} 耗时={}ms", gz.getFileName(), System.currentTimeMillis() - t0);

            t0 = System.currentTimeMillis();
            upload(gz);
            log.info("阶段 4/4 上传完成 耗时={}ms", System.currentTimeMillis() - t0);

            long totalCost = System.currentTimeMillis() - started;
            log.info("导出任务成功 total={} 总耗时={}ms", total, totalCost);
            return new ExportResult(total, 0, totalCost, sizeOf(gz));
        } catch (Exception e) {
            // 关键：带上"已经处理到哪一步"的上下文 + 完整堆栈
            long totalCost = System.currentTimeMillis() - started;
            log.error("导出任务失败 taskId={} 已耗时={}ms", taskId, totalCost, e);
            throw new IllegalStateException("导出失败", e);
        } finally {
            MDC.remove("traceId");                 // ★ 定时任务线程也会被复用（调度线程池）
        }
    }

    /** 分批次打 DEBUG，避免 10 万行 INFO */
    private Path writeCsv(long since, Path dir, long total) {
        long processed = 0;
        for (long offset = 0; offset < total; offset += BATCH_SIZE) {
            // ... 查一批、写一批
            processed += BATCH_SIZE;
            if (log.isDebugEnabled()) {
                log.debug("导出进度 {}/{}", Math.min(processed, total), total);      // 细节降到 DEBUG
            }
        }
        return dir.resolve("orders.csv");
    }

    // 其余方法（countOrders / compress / upload / sizeOf）省略
    private long countOrders(long since) { return 100_000; }
    private Path compress(Path csv) { return csv; }
    private void upload(Path gz) { }
    private long sizeOf(Path path) { return 0; }
    private Path writeCsvStub() { return null; }

    public record ExportResult(long total, long failed, long costMillis, long fileSize) { }
}

这个方案的六个设计点：

#	设计	解决什么
1	任务级 traceId	一次任务的所有日志能串起来（含"失败前处理到哪"）✓
2	`MDC.remove` 在 finally	定时任务线程也会被复用（调度线程池），不清理会串号
3	阶段日志 + 耗时	慢的时候一眼看出卡在哪一段 ✓
4	进度日志降到 DEBUG	10 万条不会写满日志 ✓
5	失败日志带上下文	`taskId` + `已耗时` + 完整堆栈 ✓
6	汇总日志	一眼看到"成功/失败/耗时"，便于建立基线 ✓

"为什么定时任务也要有 traceId / taskId"：

理由	说明
一次任务会产生大量日志	没有 id 就"混在系统日志里"，无法区分是这次跑的还是上次跑的 ✗
排查"为什么慢"需要串起来看	四个阶段的耗时日志靠 id 才能连成一条链路
告警需要可追溯	"导出任务失败"告警发出后，运维要能把这一次的全部日志拉出来 ✓
支持"重跑"的判断	有了 id，能确认"这次成功的任务"与"上次失败的任务"是两次执行

一个真实场景：任务跑了 3 小时没结束（卡住了）——

没有 taskId	有 taskId
看日志：`导出进度 20000/100000`——但这是哪次跑的？现在的进度是多少？ ✗	按 taskId 过滤：看到最后一条是"阶段 2/4 写文件"，卡在写文件阶段 ✓

顺带一条：任务的 traceId 最好用"任务名 + 日期"这种可预测的格式（如 export-20260921），这样运维不用先查日志就知道搜什么 ✓

java

String taskId = "export-" + LocalDate.now();          // 可预测，便于人工搜索

综合任务（第 7 题）

《日志规范（8 条）》

#	规范	反向案例
1	级别与"是否需要人介入"对齐	用 ERROR 记录"用户没登录"→ 告警疲劳 ✗
2	格式必须含六字段（时间、级别、线程、traceId、logger、消息）	少了 traceId → 排查靠猜
3	敏感信息一律不打；必须确认时打掩码	密码进日志 = 安全事故
4	循环里禁止 INFO；细节降 DEBUG，出口打汇总	10 万行日志写满磁盘
5	异常必须带堆栈（异常作为最后一个参数）	`e.getMessage()` → 看不到出错行
6	所有入口都要有 traceId：HTTP 走 Filter、定时任务自己 put、消息消费从消息头取	定时任务日志无法归类
7	滚动必须同时配 `maxFileSize` + `maxHistory` + `totalSizeCap`	只配天数 → 磁盘写满
8	生产只允许按包临时开 DEBUG（优先用 actuator 在线调整）	全局 DEBUG → 服务不可用

"一次请求的可观测链路"（用户报错 → 定位到代码行）：

text

① 用户：看到错误提示（含 traceId）
       ↓ "操作失败，请联系客服（错误编号：6034908592b14ae3）"
② 客服/工单：把 traceId 转给研发
       ↓
③ 研发：在日志系统里搜 `6034908592b14ae3`
       ↓ 得到这一次请求的**全部日志按时间排序**
④ 看日志：找到最下面那条 ERROR（或最后一条 INFO）
       ↓ 里面有 **logger 名（哪个类）+ 异常堆栈（哪一行）+ 业务上下文（订单号）**
⑤ 打开代码：定位到具体那一行
       ↓
⑥ 结合同一 traceId 的**上游日志**（DB 耗时、外部调用耗时）判断根因

每一环需要什么信息：

环节	需要的信息	谁提供
用户报错	traceId 返回给用户	《参数校验与全局异常处理》的统一错误响应 ✓
按 id 搜日志	日志里有 traceId 字段	本节 ✓
知道错在哪	logger 名 + 完整堆栈	9.2 节
知道为什么	业务上下文（orderNo、参数）	5.6 节的"该打什么"
知道慢在哪	各阶段耗时日志	编程题 6

结构化日志（JSON）的优势：

优势	说明
字段可检索	能按 `traceId=xxx AND level=ERROR` 精确查询（纯文本只能模糊搜）✓
便于聚合统计	"最近 1 小时 ERROR 数按类分布"一句话查出来 ✓
解析稳定	纯文本靠正则解析，日志格式一改就崩 ✗
字段可扩展	加一个 `orderNo` 字段不用改解析规则 ✓

代价：人直接看时可读性差 ✓（不过日志系统一般会渲染成表格）

本项目为什么用纯文本：教学场景下"人眼可读"更重要 ✓；生产环境更推荐 JSON + 采集系统（ELK / Loki）✓

日志、指标、链路追踪的分工：

类型	回答什么问题	数据特征	典型工具
日志（Logs）	发生了什么（含上下文与异常）	离散文本、量大	ELK、Loki
指标（Metrics）	现在多快、多频繁、用了多少	数值、可聚合、成本低	Prometheus + Grafana
链路追踪（Traces）	一次请求慢在哪一段	跨服务的调用树	Jaeger、SkyWalking

三者如何配合（一个真实的排查过程）：

text

① 看板（Metrics）：错误率从 0.1% 涨到 5%                ← 指标发现"有事"
② 点进看板（Traces）：某一批请求的 DB 段耗时从 20ms → 2s   ← 追踪定位"慢在哪一段"
③ 搜日志（Logs，按 traceId）：看到 "慢查询 orderNo=..."    ← 日志回答"具体是什么"
④ 定位：某个查询没走索引

一句话总结三者关系：

指标告诉你"出事了"，追踪告诉你"哪里慢"，日志告诉你"为什么"。
三者靠"同一个 traceId"串起来——这也是为什么本节花的力气最大的一件事是让 traceId 贯穿 ✓

"级别用错一档，磁盘与排查时间差多少倍"：

错误	影响倍数	说明
循环里 INFO → 应该是汇总	日志量 × 1000 倍（10 万条 vs 100 条）	磁盘 + 采集成本
全局 DEBUG 而非按包	日志量 × 10~100 倍	淹没关键信息
ERROR 用于业务正常流程	告警量 × 100 倍	告警失效（最严重）
没有 traceId	排查时间 × 10 倍以上	从"搜 id"变成"翻日志"

取舍结论：

日志的成本是"线性"的（磁盘、采集费），收益是"非线性"的（一次故障的定位速度）。
所以宁可多打"有分析价值"的日志，也绝不为了省磁盘而牺牲可排查性 ✓
但"多打"指的是"关键节点 + 上下文"，不是"每个循环都打" ✗ ——这正是前 8 条规范要平衡的。

13. 掌握标准

[ ] 能说出 SLF4J 与 Logback 的分工，且业务代码只用 SLF4J；
[ ] 能说出五个级别的选择标准（判断依据是"要不要人介入"）；
[ ] 会用 MDC + Filter 实现 traceId 贯穿，并知道必须 MDC.remove；
[ ] 知道"响应体 traceId 与日志 traceId 一致"是怎么做到的；
[ ] 能说出日志格式六个字段各自的用途；
[ ] 知道哪些内容绝不能进日志，会打掩码；
[ ] 知道循环里不能打 INFO，要用"细节降级 + 汇总"；
[ ] 会配滚动策略的三个参数（尤其 totalSizeCap）；
[ ] 知道占位符相对拼接的性能收益，以及何时需要 isDebugEnabled；
[ ] 知道 MDC 不跨线程，会用 TaskDecorator 传递。

14. 扩展资源

15. 下一步学习

《接口文档与前后端联调》：把接口"说清楚"，让前端能自助联调。

前置知识

S3-009 Spring Boot 自动配置与项目结构

后续知识

S8-008 搜索与日志技术栈视野

进度只保存在本机浏览器，可随时清除

外部学习资源

面试题库索引

项目与练手索引

工具与软件索引

日志框架与日志规范

1. 本节定位

2. 学习目标

3. 前置知识检查

4. 为什么需要这个知识

5. 核心概念

5.1 SLF4J + Logback：门面与实现

5.2 五个级别与选择标准

5.3 日志格式：六个字段

5.4 MDC 与 traceId：把一次请求的日志串起来

5.5 `MDC.remove` 为什么必须写

5.6 什么该打、什么不该打

5.7 滚动与磁盘保护

5.8 占位符：不只是"好看"

6. 递进示例

6.1 最小示例：一条日志

6.2 业务示例：traceId 贯穿

6.3 反例：循环里打 INFO

7. 完整可运行代码

8. Debug 观察点

9. 常见错误

错误 1：`e.printStackTrace()`

错误 2：`log.error(e.getMessage())` —— 丢掉堆栈

错误 3：`log.info("用户信息：" + user.toString())`

错误 4：`MDC` 不清理

错误 5：用了 `logback.xml` 而不是 `logback-spring.xml`

错误 6：日志占满了磁盘

错误 7：生产环境开了 DEBUG

10. 动手实验

11. 练习题

12. 参考答案

13. 掌握标准

14. 扩展资源

15. 下一步学习

前置知识

后续知识

日志框架与日志规范 ​

1. 本节定位 ​

2. 学习目标 ​

3. 前置知识检查 ​

4. 为什么需要这个知识 ​

5. 核心概念 ​

5.1 SLF4J + Logback：门面与实现 ​

5.2 五个级别与选择标准 ​

5.3 日志格式：六个字段 ​

5.4 MDC 与 traceId：把一次请求的日志串起来 ​

5.5 MDC.remove 为什么必须写 ​

5.6 什么该打、什么不该打 ​

5.7 滚动与磁盘保护 ​

5.8 占位符：不只是"好看" ​

6. 递进示例 ​

6.1 最小示例：一条日志 ​

6.2 业务示例：traceId 贯穿 ​

6.3 反例：循环里打 INFO ​

7. 完整可运行代码 ​

8. Debug 观察点 ​

9. 常见错误 ​

错误 1：e.printStackTrace() ​

错误 2：log.error(e.getMessage()) —— 丢掉堆栈 ​

错误 3：log.info("用户信息：" + user.toString()) ​

错误 4：MDC 不清理 ​

错误 5：用了 logback.xml 而不是 logback-spring.xml ​

错误 6：日志占满了磁盘 ​

错误 7：生产环境开了 DEBUG ​

10. 动手实验 ​

11. 练习题 ​

12. 参考答案 ​

13. 掌握标准 ​

14. 扩展资源 ​

15. 下一步学习 ​

前置知识

后续知识

日志框架与日志规范

1. 本节定位

2. 学习目标

3. 前置知识检查

4. 为什么需要这个知识

5. 核心概念

5.1 SLF4J + Logback：门面与实现

5.2 五个级别与选择标准

5.3 日志格式：六个字段

5.4 MDC 与 traceId：把一次请求的日志串起来

5.5 `MDC.remove` 为什么必须写

5.6 什么该打、什么不该打

5.7 滚动与磁盘保护

5.8 占位符：不只是"好看"

6. 递进示例

6.1 最小示例：一条日志

6.2 业务示例：traceId 贯穿

6.3 反例：循环里打 INFO

7. 完整可运行代码

8. Debug 观察点

9. 常见错误

错误 1：`e.printStackTrace()`

错误 2：`log.error(e.getMessage())` —— 丢掉堆栈

错误 3：`log.info("用户信息：" + user.toString())`

错误 4：`MDC` 不清理

错误 5：用了 `logback.xml` 而不是 `logback-spring.xml`

错误 6：日志占满了磁盘

错误 7：生产环境开了 DEBUG

10. 动手实验

11. 练习题

12. 参考答案

13. 掌握标准

14. 扩展资源

15. 下一步学习