本节目标：让
libraryd的日志实现、级别、输出格式都可预测，读日志时能稳定拿到时间、线程、logger、requestId与traceId。
适用版本：JDK 25（Temurin 25.0.5）、SLF4J 2.0.20、Logback 1.6.6。
承接的问题
第 11 章结束时，libraryd 已经能在后台扫描逾期借阅，但日志仍然不可靠。最典型的一次排查是这样的：服务启动后，控制台前半段是
[main] INFO io.javalin.Javalin - Starting Javalin ...
后半段又变成
2026-10-21T14:00:03.412+08:00 INFO [main] com.zaxxer.hikari.HikariDataSource requestId= traceId= - libraryd-pool - Starting...
同一份日志里出现两种格式，前者没有时间戳、没有 requestId，后者有。继续查会发现三个独立问题：
- 类路径上同时存在
slf4j-simple和logback-classic，SLF4J 只选了一个 provider。 LIBRARYD_LOG_LEVEL=DEBUG改了，但某些包仍然是 INFO，因为包级 logger 覆盖了根级别。- 某条异常只打印了
failed: connection refused，没有堆栈，因为代码把异常拼进了消息字符串。
这三个问题分别对应 SLF4J 的绑定机制、Logback 的级别继承、以及日志调用的写法。本节把它们拆开，每一部分都给 libraryd 的真实配置与输出。
核心机制一：SLF4J 是门面，Logback 是绑定
业务代码只应该依赖 org.slf4j.Logger 和 LoggerFactory，不出现 ch.qos.logback 的类型。这样换实现时不用改代码。libraryd 的各个模块通过父 POM 引入 slf4j-api，只有 libraryd-app 引入 logback-classic：
<dependency>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-api</artifactId>
</dependency>
<dependency>
<groupId>ch.qos.logback</groupId>
<artifactId>logback-classic</artifactId>
</dependency>
slf4j-api 只定义接口，运行期通过 ServiceLoader 找 provider。类路径上有多个 provider 时，SLF4J 2.x 会打印警告并只选一个。把 slf4j-simple 和 logback-classic 放在一起，本机输出：
SLF4J(W): Class path contains multiple SLF4J providers.
SLF4J(W): Found provider [org.slf4j.simple.SimpleServiceProvider@34a245ab]
SLF4J(W): Found provider [ch.qos.logback.classic.spi.LogbackServiceProvider@7cc355be]
SLF4J(W): See https://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J(I): Actual provider is of type [org.slf4j.simple.SimpleServiceProvider@34a245ab]
[main] INFO LogLevelDemo - borrow accepted isbn=9787111213826 member=m-001
注意最后一行：实际生效的是 slf4j-simple，所以 logback.xml 里的时间戳、requestId、traceId 全都没有出现。Javalin 7.2.4 会传递依赖 slf4j-simple，libraryd-web 必须显式排除它：
<dependency>
<groupId>io.javalin</groupId>
<artifactId>javalin</artifactId>
<exclusions>
<exclusion>
<groupId>org.slf4j</groupId>
<artifactId>slf4j-simple</artifactId>
</exclusion>
</exclusions>
</dependency>
排除之后，类路径上只剩 Logback 一个 provider。这个问题的隐蔽之处在于服务并不会启动失败，只是日志格式和配置悄悄失效；如果不在启动时检查，往往要等到线上排查才发现。
核心机制二：级别继承与有效级别
SLF4J 有五个常用级别：TRACE、DEBUG、INFO、WARN、ERROR。Logger 按名字组成树，com.plume.library.web.LibraryApi 的父 logger 是 com.plume.library.web，再往上是 com.plume.library，最后是 ROOT。一个 logger 没有显式级别时，继承最近的祖先级别，这就是有效级别。
libraryd 的 logback.xml 这样设置：
<configuration>
<property name="LOG_LEVEL" value="${LIBRARYD_LOG_LEVEL:-INFO}"/>
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %-5level [%thread] %logger{36} requestId=%X{requestId:-} traceId=%X{traceId:-} - %msg%n</pattern>
</encoder>
</appender>
<logger name="org.eclipse.jetty" level="WARN"/>
<logger name="com.zaxxer.hikari" level="INFO"/>
<logger name="io.opentelemetry" level="INFO"/>
<root level="${LOG_LEVEL}">
<appender-ref ref="CONSOLE"/>
</root>
</configuration>
${LIBRARYD_LOG_LEVEL:-INFO} 表示优先读环境变量，没有就用 INFO。三个包级 logger 是降噪用的：Jetty 的 DEBUG 非常吵，Hikari 的连接生命周期只需要 INFO，OpenTelemetry 的 SDK 内部日志也只需要 INFO。
用同一个配置文件分别以 INFO、DEBUG、WARN 运行一段日志代码，本机输出：
=== INFO
2026-10-27T18:04:26.430+08:00 INFO [main] LogLevelDemo requestId=demo-req-001 traceId=4bf92f3577b34da6a3ce929d0e0e4736 - borrow accepted isbn=9787111213826 member=m-001
2026-10-27T18:04:26.432+08:00 WARN [main] LogLevelDemo requestId=demo-req-001 traceId=4bf92f3577b34da6a3ce929d0e0e4736 - loan limit approaching member=m-001 active=4
=== DEBUG
2026-10-27T18:04:27.033+08:00 DEBUG [main] LogLevelDemo requestId=demo-req-001 traceId=4bf92f3577b34da6a3ce929d0e0e4736 - debug detail
2026-10-27T18:04:27.034+08:00 INFO [main] LogLevelDemo requestId=demo-req-001 traceId=4bf92f3577b34da6a3ce929d0e0e4736 - borrow accepted isbn=9787111213826 member=m-001
2026-10-27T18:04:27.035+08:00 WARN [main] LogLevelDemo requestId=demo-req-001 traceId=4bf92f3577b34da6a3ce929d0e0e4736 - loan limit approaching member=m-001 active=4
=== WARN
2026-10-27T18:04:27.608+08:00 WARN [main] LogLevelDemo requestId=demo-req-001 traceId=4bf92f3577b34da6a3ce929d0e0e4736 - loan limit approaching member=m-001 active=4
INFO 级别下 DEBUG 不输出，DEBUG 级别下 TRACE 仍然不输出，WARN 级别下 INFO 也不输出。级别是「不低于阈值」的意思，不是只输出某一个级别。
libraryd 还在 AppMain 里做了一次运行期设置：
public static void main(String[] args) {
AppConfig config = AppConfig.fromEnvironment();
applyLogLevel(config.logLevel());
Logger log = LoggerFactory.getLogger(AppMain.class);
// ... 启动 LibraryApplication
}
private static void applyLogLevel(String level) {
if (LoggerFactory.getILoggerFactory() instanceof LoggerContext context) {
context.getLogger(Logger.ROOT_LOGGER_NAME).setLevel(Level.toLevel(level, Level.INFO));
}
}
这段代码的意义是：即使 logback.xml 被替换或环境变量格式不标准，根级别也会被归一化。Level.toLevel(level, Level.INFO) 在遇到无法识别的值时回退到 INFO。代价是级别设置出现在两个地方，读代码时要同时看配置文件和 AppMain。如果只改 logback.xml 而没注意 AppMain，可能以为改了级别但运行期又被覆盖。
核心机制三：Appender 与 encoder
Appender 决定日志去哪里，encoder 决定一行长什么样。libraryd 只用了一个 ConsoleAppender，把日志写到标准输出，由容器负责收集。这是十二要素应用常见的做法：进程不关心文件路径，也不做日志轮转。
pattern 里每个字段都有明确用途：
| 字段 | 含义 | libraryd 里的作用 |
|---|---|---|
%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} | 带时区的 ISO-8601 时间 | 和数据库 timestamptz、调用方日志对齐 |
%-5level | 左对齐级别，宽度 5 | 列对齐，便于 rg |
[%thread] | 线程名 | 区分 Jetty 线程、扫描线程、启动线程 |
%logger{36} | 缩写后的 logger 名 | 保留包名尾部，控制行宽 |
%X{requestId:-} | MDC 字段，缺失时为空 | 串联一次 HTTP 请求 |
%X{traceId:-} | MDC 字段，缺失时为空 | 串联跨服务调用 |
%msg%n | 消息与换行 | 正文 |
%logger{36} 会缩写包名。libraryd 启动日志里能看到 c.p.l.persistence.DatabaseMigrator，而不是完整的 com.plume.library.persistence.DatabaseMigrator。缩写规则是保留类名和尽量多的包名尾部，总长度不超过 36 个字符。
MDC 占位符的默认值也值得注意。用 %X{requestId} 时，字段不存在会输出空字符串；用 %X{requestId:-none} 会输出 none。本机对比：
plain=[] default=[none] msg=no mdc
plain=[req-1] default=[req-1] msg=with mdc
libraryd 选择 :- 后面留空，因为日志消费端更希望看到「字段存在但值为空」，而不是一个看起来像真实值的 none。如果希望缺失时显式标记，可以改成 %X{requestId:-missing}。
Appender 还有一个容易忽略的规则：additivity。一个 logger 默认会把事件继续传给父 logger。如果给 com.plume.library 配了 CONSOLE，根 logger 也配了 CONSOLE，同一条日志会打印两次。要单独控制时写：
<logger name="com.plume.library" level="DEBUG" additivity="false">
<appender-ref ref="CONSOLE"/>
</logger>
additivity="false" 表示到此为止，不再上传给根 logger。libraryd 没有使用这个配置，因为所有业务 logger 都继承根 appender，只有需要单独输出到文件或单独降噪时才需要。
核心机制四：参数化日志与异常
SLF4J 的 {} 占位符不只是语法糖。它在级别未开启时不会把参数转成字符串，能省掉一次 toString()。libraryd 的日志统一写成：
log.info("borrow accepted isbn={} member={}", isbn, memberId);
不要写成字符串拼接：
log.info("borrow accepted isbn=" + isbn + " member=" + memberId);
后者的拼接在调用 log.info 之前就发生了，即使 INFO 被关闭也照样付出成本。更危险的是异常日志。本机运行三种写法：
2026-10-27T18:04:44.953+08:00 INFO [main] PlaceholderDemo requestId= traceId= - borrow 9787111213826 for m-001
2026-10-27T18:04:44.954+08:00 INFO [main] PlaceholderDemo requestId= traceId= - borrow 9787111213826 for m-001
2026-10-27T18:04:44.954+08:00 INFO [main] PlaceholderDemo requestId= traceId= - borrow 9787111213826 for m-001
2026-10-27T18:04:44.954+08:00 ERROR [main] PlaceholderDemo requestId= traceId= - borrow failed
java.lang.IllegalStateException: db connection refused
at PlaceholderDemo.main(PlaceholderDemo.java:14)
2026-10-27T18:04:44.955+08:00 ERROR [main] PlaceholderDemo requestId= traceId= - borrow failed {}
java.lang.IllegalStateException: db connection refused
at PlaceholderDemo.main(PlaceholderDemo.java:14)
第三行 borrow {} for {} 传了三个参数，多出来的 "unused-arg" 被忽略，日志里看不出问题。最后一行 log.error("borrow failed {}", failure) 把异常当成普通参数，占位符没有被替换，输出成 borrow failed {}，但堆栈仍然打印了，因为 SLF4J 会把最后一个 Throwable 当作异常。正确写法是消息里不写占位符：
log.error("borrow failed isbn={}", isbn, failure);
这样消息带业务字段，异常单独作为最后一个参数，堆栈完整保留。libraryd 的 LibraryApi.handleUnexpected 就是这种写法：
log.error("unhandled request failure requestId={}",
RequestContext.requestId(context), exception);
当参数本身很贵时，可以用 isDebugEnabled() 保护：
if (log.isDebugEnabled()) {
log.debug("search plan={}", explainPlan(query));
}
或者用 SLF4J 2 的流式 API：
log.atDebug()
.addArgument(() -> explainPlan(query))
.log("search plan={}");
流式 API 的参数是 Supplier，级别未开启时不会求值。libraryd 目前的日志参数都是字符串和数字，没有用到这个写法，但排查慢查询时可以派上用场。
在 libraryd 里落地：两份配置
libraryd 最终保留两份 Logback 配置：
libraryd-app/src/main/resources/logback.xml：控制台文本，开发与生产默认使用。libraryd-app/src/main/resources/logback-json.xml：JSON 输出，12.2 节展开。
文本配置就是本节前面给出的那一份。JSON 配置通过 -Dlogback.configurationFile=/path/to/logback-json.xml 或资源覆盖来启用。两份配置共享同一个 LIBRARYD_LOG_LEVEL 属性和同样的包级降噪规则，区别只在 encoder。
启动时，AppMain 先读 AppConfig，再设置根级别，最后启动应用：
2026-10-27T18:03:48.462+08:00 INFO [main] com.zaxxer.hikari.HikariDataSource requestId= traceId= - libraryd-pool - Starting...
2026-10-27T18:03:48.695+08:00 INFO [main] com.zaxxer.hikari.HikariDataSource requestId= traceId= - libraryd-pool - Start completed.
2026-10-27T18:03:50.035+08:00 INFO [main] io.javalin.Javalin requestId= traceId= - Javalin started in 214ms \o/
2026-10-27T18:03:50.041+08:00 INFO [main] com.plume.library.OverdueScanner requestId= traceId= - overdue scanner scheduled every 60s
2026-10-27T18:03:50.041+08:00 INFO [main] c.plume.library.LibraryApplication requestId= traceId= - libraryd started on port 18080 (db=jdbc:postgresql://127.0.0.1:15432/libraryd, poolSize=10)
启动阶段的日志 requestId 和 traceId 都是空的，因为它们不属于某次 HTTP 请求。这是正常的：MDC 只在请求进入后由 RequestContext.begin 和 TracingMiddleware.start 写入。12.2 节会把这条链路补全。
生产环境建议保持根级别 INFO，把 DEBUG 留给按需打开的包，例如临时排查 JDBC 时设置 com.plume.library.persistence=DEBUG。不要把根级别长期开到 DEBUG：一次借阅请求会打印 SQL、连接池、Jackson 和 Jetty 的大量细节，日志量和磁盘成本都会上去。
常见错误与边界
错误一：类路径上有多个 SLF4J provider。 本机的警告原文已经在前面给出。表现是日志格式突然变成 [main] INFO ...，logback.xml 完全不生效。排查命令是 mvn dependency:tree -Dincludes=org.slf4j，确认只有 slf4j-api 和 logback-classic，没有 slf4j-simple、slf4j-jdk14、log4j-slf4j-impl。
错误二：没有 logback.xml。 Logback 会使用默认配置，根级别是 DEBUG，pattern 是 %d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n。本机输出：
18:13:03.515 [main] DEBUG LogLevelDemo -- debug detail
18:13:03.516 [main] INFO LogLevelDemo -- borrow accepted isbn=9787111213826 member=m-001
18:13:03.517 [main] WARN LogLevelDemo -- loan limit approaching member=m-001 active=4
默认配置没有 requestId、traceId，也没有时间戳日期。判断方法是在启动日志里找 --- 或 --，看到它就说明自定义配置没有加载。
错误三：只打印 e.getMessage()。 log.error("failed: " + e.getMessage()) 会丢掉异常类型和堆栈，只剩一行文本。连接池超时、SQL 状态码、根因链都不见了。统一写成 log.error("failed isbn={}", isbn, e)。
错误四：logger 取错类。 在静态工具类里写 LoggerFactory.getLogger(getClass())，如果方法是静态的，getClass() 不能直接用；在父类里写死 logger，子类日志会全部记到父类名下。统一用 LoggerFactory.getLogger(当前类.class)，或者用 MethodHandles.lookup().lookupClass()。
错误五：级别在两处设置。 logback.xml 的 <root level="${LOG_LEVEL}"> 和 AppMain.applyLogLevel 都会设置根级别。正常启动时后者覆盖前者，结果一致；但如果你只改了配置文件、又在测试里绕过了 AppMain，行为就会不同。排查时先确认当前进程到底走了哪条路径。
边界：异步 Appender 会丢日志。 Logback 的 AsyncAppender 把日志放进队列，由单独线程写出。本机用 1024 的队列跑 1000 条 INFO，进程退出时只写出了 339 条，说明关闭阶段没有排空。审计日志、借还记录不能只依赖异步 Appender；要么同步写，要么在关闭时显式停止 Logback 并等待队列排空。
小结
- SLF4J 只是门面，运行期由唯一 provider 决定实现；Javalin 传递的
slf4j-simple必须在libraryd-web排除。 - 级别按 logger 树继承，包级 logger 可以覆盖根级别；
LIBRARYD_LOG_LEVEL控制根级别，AppMain会再做一次归一化。 - Appender 决定去向，encoder 决定格式；
%X{key:-}是 MDC 字段的默认值写法。 - 参数化日志用
{}，异常作为最后一个参数传入，不要拼接e.getMessage()。 libraryd的文本配置包含时间、线程、logger、requestId、traceId和消息，启动阶段这两个 MDC 字段为空是正常的。- 多 provider、缺配置、logger 取错类、级别两处设置，是这类问题最常见的四个入口。
文本日志适合人读，不适合按字段检索。下一节把同一批事件输出成 JSON，并用 MDC 把 requestId、traceId 变成可查询的顶层字段。
阅读导航：上一节：11.3 任务幂等：重复执行不出错 · 下一节：12.2 结构化日志：JSON、MDC 与请求上下文 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。