本节目标：让
libraryd的每条日志都带可检索的requestId与traceId，并能用 JSON 字段而不是正则从日志里还原一次请求的完整路径。
适用版本：JDK 25（Temurin 25.0.5）、SLF4J 2.0.20、Logback 1.6.6、logstash-logback-encoder 9.0。
承接的问题
12.1 节的文本日志人能读，机器不好读。一次借阅请求会产生多条日志：
2026-10-27T18:03:58.412+08:00 INFO [JettyServerThreadPool-46] com.plume.library.web.HttpMetrics requestId=90be800e-aa87-4948-963c-ba19e5f1c153 traceId=11111111111111111111111111111111 - http_request method=POST path=/api/loans status=201 duration_ms=18 requestId=90be800e-aa87-4948-963c-ba19e5f1c153
同一次请求里如果还有 Hikari 的慢连接、Redis 的降级、业务层的 WARN，它们分散在不同行。用 rg 按 requestId=90be... 能找到，但要做「按状态码统计耗时」「按 traceId 关联下游服务」「把异常堆栈单独提取」就很别扭。文本格式把字段压进了一行字符串，消费端只能靠正则。
结构化日志把每个字段变成 JSON 的键。同一行可以写成：
{"@timestamp":"2026-10-27T18:04:16.73474+08:00","@version":"1","message":"http_request method=GET path=/api/books/9787111213826 status=200 duration_ms=21 requestId=json-demo-1","logger_name":"com.plume.library.web.HttpMetrics","thread_name":"JettyServerThreadPool-41","level":"INFO","level_value":20000,"requestId":"json-demo-1","traceId":"602afe5c17b93cbbd7377544135869dd","service":"libraryd"}
消费端可以直接按 requestId、level、logger_name 建索引，不需要解析消息正文。代价是日志体积变大，且字段设计一旦混乱，JSON 也救不了排查。本节先解决字段从哪里来，再解决哪些字段该进来。
核心机制一：MDC 是线程绑定的上下文
SLF4J 的 MDC（Mapped Diagnostic Context）是一个 ThreadLocal<Map<String, String>>。调用 MDC.put("requestId", id) 只影响当前线程，随后同一线程上的日志都能通过 %X{requestId} 或 JSON encoder 拿到这个值。
libraryd 在请求进入时写入：
package com.plume.library.web;
import io.javalin.http.Context;
import java.util.UUID;
import org.slf4j.MDC;
public final class RequestContext {
public static final String HEADER = "X-Request-Id";
public static final String ATTRIBUTE = "libraryd.requestId";
private static final String START_NANOS = "libraryd.startNanos";
public static String begin(Context context) {
String requestId = context.header(HEADER);
if (requestId == null || requestId.isBlank()) {
requestId = UUID.randomUUID().toString();
}
context.attribute(ATTRIBUTE, requestId);
context.attribute(START_NANOS, System.nanoTime());
context.header(HEADER, requestId);
MDC.put("requestId", requestId);
return requestId;
}
public static String requestId(Context context) {
return context.attribute(ATTRIBUTE);
}
public static long elapsedNanos(Context context) {
Long start = context.attribute(START_NANOS);
return start == null ? 0L : System.nanoTime() - start;
}
public static void clear(Context context) {
MDC.remove("requestId");
MDC.remove("traceId");
}
}
三个动作要一起看：
- 客户端带了
X-Request-Id就沿用，没带就生成 UUID。这样调用方可以把请求 ID 带进自己的日志。 - 同一个值写进 Javalin 的
Context属性和响应头，后续 handler 与错误响应都能拿到。 - 写进 MDC，当前线程后续的日志自动带上。
MDC 是线程绑定的，这一点在池化线程上会变成泄漏。下面这段代码在单线程池里提交四个任务，第一个任务写入 requestId 但没有清理：
pool.submit(() -> {
MDC.put("requestId", "req-A");
log.info("first task handled");
}).get();
pool.submit(() -> log.info("second task handled")).get();
本机输出：
2026-10-27T18:04:37.816+08:00 INFO [pool-1-thread-1] MdcLeakDemo requestId=req-A traceId= - first task handled
2026-10-27T18:04:37.818+08:00 INFO [pool-1-thread-1] MdcLeakDemo requestId=req-A traceId= - second task handled
第二个任务已经不属于 req-A，但日志仍然带着它。正确做法是在 finally 里清理：
pool.submit(() -> {
MDC.put("requestId", "req-C");
try {
log.info("third task handled");
} finally {
MDC.clear();
}
}).get();
清理之后，第四个任务的日志变回 requestId=。libraryd 的 RequestContext.clear 放在 Javalin 的 after 处理器里，并且用 finally 包住，确保异常路径也会执行。
核心机制二：LogstashEncoder 与 JSON 字段
Logback 只负责输出，JSON 编码交给 net.logstash.logback:logstash-logback-encoder。libraryd 的 logback-json.xml 是：
<configuration>
<property name="LOG_LEVEL" value="${LIBRARYD_LOG_LEVEL:-INFO}"/>
<appender name="JSON" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="net.logstash.logback.encoder.LogstashEncoder">
<includeMdcKeyName>requestId</includeMdcKeyName>
<includeMdcKeyName>traceId</includeMdcKeyName>
<customFields>{"service":"libraryd"}</customFields>
</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="JSON"/>
</root>
</configuration>
LogstashEncoder 会自动写出一组标准字段：
| 字段 | 来源 | 示例 |
|---|---|---|
@timestamp | 事件时间 | 2026-10-27T18:04:16.73474+08:00 |
@version | encoder 版本 | 1 |
message | 格式化后的消息 | http_request method=GET ... |
logger_name | logger 名 | com.plume.library.web.HttpMetrics |
thread_name | 线程名 | JettyServerThreadPool-41 |
level | 级别文本 | INFO |
level_value | 级别数值 | 20000 |
stack_trace | 异常堆栈，仅有异常时出现 | java.lang.IllegalStateException: ... |
requestId | MDC | json-demo-1 |
traceId | MDC | 602afe5c17b93cbbd7377544135869dd |
service | customFields | libraryd |
includeMdcKeyName 是白名单。指定之后，只有列出的 MDC 键会进入 JSON。本机额外放了一个 memberId 做对比：
{"@timestamp":"2026-10-27T18:13:18.789735+08:00","@version":"1","message":"mdc filter demo","logger_name":"JsonMdcFilterDemo","thread_name":"main","level":"INFO","level_value":20000,"requestId":"req-1","traceId":"4bf92f3577b34da6a3ce929d0e0e4736","service":"libraryd"}
memberId 没有出现。这个白名单很重要：MDC 里的键一旦被随意写入，JSON 顶层字段会跟着膨胀；更糟的是会员 ID、邮箱、令牌如果进了 MDC，就会被所有日志复制。12.3 节会专门处理脱敏。
异常在 JSON 里是独立的 stack_trace 字段，不在 message 里。本机输出：
{"@timestamp":"2026-10-27T18:04:56.399945+08:00","@version":"1","message":"book fetch failed isbn=9787111213826","logger_name":"JsonLogDemo","thread_name":"main","level":"ERROR","level_value":40000,"stack_trace":"java.lang.IllegalStateException: connection reset\n\tat JsonLogDemo.main(JsonLogDemo.java:13)\n","requestId":"req-json-1","traceId":"4bf92f3577b34da6a3ce929d0e0e4736","service":"libraryd"}
消费端可以把 stack_trace 单独存字段，也可以按 level=ERROR 聚合，不需要在消息文本里找 Exception。
核心机制三：requestId 与 traceId 的生命周期
libraryd 在 LibraryApi.create 里注册了两个全局处理器：
config.routes.before(this::before);
config.routes.after(this::after);
before 的顺序是：
private void before(Context context) {
RequestContext.begin(context);
tracing.start(context);
}
RequestContext.begin 先写 requestId，TracingMiddleware.start 再写 traceId。后者从 traceparent 提取父上下文，创建 SERVER span，然后把 span 的 trace id 放进 MDC：
Span span = tracer.spanBuilder(context.method().name() + " " + context.path())
.setParent(parent)
.setSpanKind(SpanKind.SERVER)
.startSpan();
span.setAttribute("http.request.method", context.method().name());
span.setAttribute("url.path", context.path());
span.setAttribute("request.id", RequestContext.requestId(context));
context.attribute(SPAN_ATTRIBUTE, span);
MDC.put("traceId", span.getSpanContext().getTraceId());
after 的顺序相反：
private void after(Context context) {
try {
httpMetrics.record(context, RequestContext.elapsedNanos(context));
} finally {
tracing.finish(context);
RequestContext.clear(context);
}
}
httpMetrics.record 会打一条访问日志，此时 MDC 还在，所以日志里有 requestId 和 traceId。随后 tracing.finish 设置响应状态、注入 traceparent 响应头、结束 span；最后 RequestContext.clear 移除两个 MDC 键。顺序不能反：如果先清 MDC 再打访问日志，日志里就只剩空字段。
实际应用里一次请求的文本日志长这样：
2026-10-27T18:15:47.771+08:00 INFO [JettyServerThreadPool-46] com.plume.library.web.HttpMetrics requestId=missing-1 traceId=c0bf76787883276d917859ba8f0df6f6 - http_request method=GET path=/api/books/does-not-exist status=404 duration_ms=10 requestId=missing-1
JSON 模式下的同一条请求：
{"@timestamp":"2026-10-27T18:04:16.73474+08:00","@version":"1","message":"http_request method=GET path=/api/books/9787111213826 status=200 duration_ms=21 requestId=json-demo-1","logger_name":"com.plume.library.web.HttpMetrics","thread_name":"JettyServerThreadPool-41","level":"INFO","level_value":20000,"requestId":"json-demo-1","traceId":"602afe5c17b93cbbd7377544135869dd","service":"libraryd"}
请求头里的 X-Request-Id 也会出现在响应里。本机发送 X-Request-Id: demo-req-001 创建图书，响应头是：
HTTP/1.1 201 Created
X-Request-Id: demo-req-001
Location: /api/books/9787111213826
traceparent: 00-39fd656118a7a167f26f3440ce3ff0b8-8cdea47bad56a785-03
调用方拿响应头里的值去日志平台查，就能对上服务端的每一条记录。错误响应也一样。404 的 Problem Details 里带 requestId：
{"type":"https://plumphp.com/problems/book-not-found","title":"Not Found","status":404,"detail":"book not found: does-not-exist","code":"E_BOOK_NOT_FOUND","requestId":"missing-1","errors":{}}
requestId 和 traceId 的职责不同：requestId 标识一次 HTTP 请求，客户端可以自带；traceId 标识一条跨服务调用链，由追踪 SDK 生成或从上游传入。一次请求通常只有一个 requestId，但可能有多个 span；所有 span 共享同一个 traceId。
核心机制四：结构化参数与字段选择
MDC 适合放「整个请求期间都成立」的字段，比如 requestId、traceId、租户 ID。单条日志独有的业务字段更适合用 StructuredArguments。logstash-logback-encoder 提供 kv()：
import static net.logstash.logback.argument.StructuredArguments.kv;
log.info("book fetched {}", kv("isbn", "9787111213826"), kv("cache", "hit"));
log.warn("loan overdue {}", kv("loanId", 42L), kv("overdueDays", 3));
本机 JSON 输出：
{"@timestamp":"2026-10-27T18:14:24.609775+08:00","@version":"1","message":"book fetched isbn=9787111213826","logger_name":"StructuredArgsDemo","thread_name":"main","level":"INFO","level_value":20000,"requestId":"req-1","isbn":"9787111213826","cache":"hit","service":"libraryd"}
{"@timestamp":"2026-10-27T18:14:24.620662+08:00","@version":"1","message":"loan overdue loanId=42","logger_name":"StructuredArgsDemo","thread_name":"main","level":"WARN","level_value":30000,"requestId":"req-1","loanId":42,"overdueDays":3,"service":"libraryd"}
isbn、cache、loanId、overdueDays 都成了顶层字段，message 仍然保留人类可读的文本。loanId 是数字类型，JSON 里没有引号；如果消费端按字符串建索引，需要提前约定类型。
字段选择的原则是「查询用什么，就放什么」：
- 按请求聚合：
requestId、traceId，放 MDC。 - 按业务实体过滤：
isbn、memberId、loanId，用kv()。 - 按结果分类：
cache=hit/miss、status=200/404，用kv()或指标 tag。 - 排查细节：SQL、参数、堆栈，放 DEBUG 或异常字段，不要塞进 MDC。
不要把高基数字段放进 MDC。ISBN 有几十万种，放进 MDC 后每条日志都复制一遍，字段膨胀且没有聚合价值；它属于单条事件的参数。
在 libraryd 里落地：一次借阅的完整日志
把上面的部分串起来，用真实请求走一遍。启动 libraryd，带 X-Request-Id: demo-req-001 和 traceparent 发起借阅：
curl -s -i -X POST http://127.0.0.1:8080/api/loans \
-H 'Content-Type: application/json' \
-H 'X-Request-Id: demo-req-001' \
-H 'traceparent: 00-11111111111111111111111111111111-2222222222222222-01' \
-d '{"isbn":"9787111213826","memberId":"m-001"}'
本机响应：
HTTP/1.1 201 Created
X-Request-Id: demo-req-001
Location: /api/loans/1
traceparent: 00-11111111111111111111111111111111-205062f2c0ea07de-01
服务端访问日志：
2026-10-27T18:03:58.xxx+08:00 INFO [JettyServerThreadPool-41] com.plume.library.web.HttpMetrics requestId=demo-req-001 traceId=11111111111111111111111111111111 - http_request method=POST path=/api/loans status=201 duration_ms=18 requestId=demo-req-001
这条日志里能确认四件事：
- 客户端自带的
requestId被沿用，没有生成新的 UUID。 traceId保留了上游的 32 位十六进制值，没有换新的。- 响应头回写了
traceparent，下游可以继续串联。 - 访问日志只记录方法、路径、状态、耗时，没有把请求体整段打出来。
如果借阅失败，LibraryApi.handleLibraryException 会按错误码的严重级别决定日志级别：严重度 3 及以上记 WARN，DB_UNAVAILABLE 和 INTERNAL 记 ERROR，其余（例如 404）只靠访问日志。这样 404 不会把日志刷成 WARN，真正的故障仍然有堆栈。
要在日志平台里还原一次请求，按 requestId 过滤即可：
requestId="demo-req-001"
如果一次请求跨了多个服务，按 traceId 过滤：
traceId="11111111111111111111111111111111"
常见错误与边界
错误一：MDC 写入后不清理。 前面的 MdcLeakDemo 已经演示：池化线程复用时会带着上一个请求的 requestId。清理必须放在 finally，不能只放在成功路径。libraryd 把 RequestContext.clear 放在 after 的 finally 里，即使访问日志或 tracing 抛异常也会执行。
错误二：把 MDC 带到别的线程。 MDC 默认不是 InheritableThreadLocal，提交到线程池的任务看不到父线程的值。本机对比：
2026-10-27T18:11:16.631+08:00 INFO [pool-1-thread-1] MdcPropagationDemo requestId= traceId= - without propagation
2026-10-27T18:11:16.633+08:00 INFO [pool-1-thread-1] MdcPropagationDemo requestId=req-parent traceId= - with propagation
正确写法是先抓取快照，再在任务里设置：
Map<String, String> captured = MDC.getCopyOfContextMap();
executor.submit(() -> {
if (captured != null) {
MDC.setContextMap(captured);
}
try {
log.info("async task");
} finally {
MDC.clear();
}
});
如果使用虚拟线程，每个虚拟线程仍然是独立的 ThreadLocal，规则不变；不要假设它会自动继承。
错误三：MDC.clear() 清掉了别人的字段。 clear() 会清空整个 map。如果同一个线程上还承载了其他上下文（例如测试框架、批处理任务），应该用 MDC.remove("requestId") 精确移除。libraryd 用的是 remove，因为只写入了这两个键。
错误四：JSON 里出现重复字段。 message 里已经拼了 requestId=...，MDC 又输出一个 requestId 顶层字段，消费端会看到两份。HttpMetrics 目前的消息文本确实带了 requestId，这是为了兼容只读文本日志的场景；如果日志平台按顶层字段查询，消息里的副本可以去掉。两处保留时，要明确哪一个是权威字段。
错误五：异常只写进 message。 把 e.toString() 拼进消息会丢掉堆栈，JSON 里也没有 stack_trace。统一把异常作为最后一个参数，让 encoder 生成独立字段。
边界：日志采样与 traceId。 如果对 INFO 日志采样，未采样的请求可能只剩指标没有日志；排查时不能假设每个 traceId 都有完整日志。13.2 节会把 trace 与日志的关系讲清楚。采样策略要保证 ERROR 和 WARN 不被采样掉。
边界：同步输出阻塞请求线程。 ConsoleAppender 默认同步写标准输出。容器把标准输出接到管道时，如果下游消费慢，写日志会阻塞 Jetty 线程。高吞吐场景需要异步 Appender 或 sidecar 收集，但异步会带来丢日志风险，12.1 节已经量过。选择哪种方式取决于日志是否参与审计。
小结
- MDC 是线程绑定的 map，
requestId与traceId在请求进入时写入，在after的finally中清理。 RequestContext.begin复用客户端X-Request-Id，否则生成 UUID，并同时写入响应头。TracingMiddleware.start从traceparent提取父上下文，创建 SERVER span，把 trace id 放进 MDC。LogstashEncoder输出标准字段，includeMdcKeyName是白名单，customFields适合放service这类固定字段。StructuredArguments.kv()把单条事件的业务字段变成 JSON 顶层字段，MDC 只放请求级上下文。- 线程池任务不会自动继承 MDC，要用
getCopyOfContextMap和setContextMap显式传递。 - 文本消息与 JSON 字段可能重复，消费端要约定哪个是权威来源。
字段齐了之后，下一个问题是字段里能放什么。会员 ID、邮箱、令牌一旦进日志，就会跟着所有副本扩散。下一节处理脱敏、采样与日志成本。
阅读导航：上一节：12.1 SLF4J 与 Logback：级别、Appender 与配置 · 下一节：12.3 日志规范：脱敏、采样与成本 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。