本节目标：让 libraryd 的每个请求都有稳定的请求 ID、一条访问日志和一次耗时统计，并且异常发生时这些信息仍然完整。
适用版本：JDK 25（Temurin 25.0.5）、Javalin 7.2.4、SLF4J 2.0.20、Micrometer 1.17.2。
承接的问题
7.1 节把 12 条路由挂上了，但每个 handler 只关心自己的业务。真正上线后，还有四件事要在所有请求上发生：
- 客户端传了
X-Request-Id就沿用，没传就生成一个；响应头必须带回同一个值。 - 每条日志都要能按请求串起来。只写一个
borrow failed，排查时无法知道是哪个请求、哪个用户、哪次重试。 - 每个请求的耗时、状态码要进指标，否则无法回答「99 分位延迟是多少」。
- 异常发生时，响应要变成统一错误格式，日志要保留请求 ID 和堆栈。
如果把这些逻辑复制进 12 个 handler，会出现三个问题：漏写一个就少一条日志；顺序不一致，有的先记耗时再解析请求；异常路径和成功路径走两套代码，错误响应反而没有请求 ID。
这一节把这些横切关注点收进 before 和 after，让 handler 只做业务。
核心机制一：before/after 是同一请求的两端
Javalin 的 before 在路由 handler 之前执行，after 在请求处理结束后执行。两者都注册在 config.routes 上：
Javalin app = Javalin.create(config -> {
config.routes.before(this::before);
config.routes.after(this::after);
config.routes.get("/api/books", this::listBooks);
});
before 和 after 对所有请求生效，包括没有匹配到路由的请求。本机用一个只有 before/after 的小应用验证：
/ok status=200 before=1 after=1
/nope status=404 before=1 after=1
/nope 没有注册路由，但 before 仍然先执行，after 仍然在 404 响应后执行。这意味着请求 ID 和访问日志可以覆盖 404，不会出现「查不到路由的请求没有日志」的盲区。
执行顺序比「先 before 后 after」更细。用一个抛异常的路由验证：
before path=/boom
exception-handler mdc=rid-order
after status=500 mdc=rid-order
client status=500 body=handled
顺序是：
before执行，写入 MDC。- 路由 handler 抛出异常。
- 匹配到的
exception处理器执行，此时 MDC 还在。 after执行，statusCode()已经是异常处理器设置的 500。- 响应发给客户端。
这个顺序决定了三件事：异常处理器里能拿到请求 ID；after 里记录的状态码是最终状态码；MDC 的清理必须放在 after，不能放在 handler 里。
核心机制二：请求 ID 的生成、回写与 MDC
请求 ID 的逻辑收在一个类里，before 只调用一次：
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";
private RequestContext() {
}
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");
}
}
四个动作各有用途：
context.header(HEADER)读请求头。客户端重试时带同一个 ID，服务端日志就能把两次请求归到一组。- 缺失或空白时生成 UUID。空白也算缺失，避免响应头出现一个空字符串。
context.header(HEADER, requestId)写响应头。Javalin 的header(String, String)是设置响应头，不是读请求头；同名方法靠参数个数区分。MDC.put("requestId", requestId)让同线程里的所有日志自动带上这个字段。Logback 的 pattern 里写%X{requestId:-}就能输出。
START_NANOS 用 System.nanoTime() 而不是 currentTimeMillis()。前者是单调时钟，不受系统时间校准影响；耗时统计不应该因为 NTP 调时而出现负数。
MDC 是线程本地变量。Jetty 的请求线程会被复用，如果只 put 不 remove，下一个请求可能继承上一个请求的 ID。清理放在 after 的 finally 里，保证异常路径也会执行：
private void after(Context context) {
try {
httpMetrics.record(context, RequestContext.elapsedNanos(context));
} finally {
tracing.finish(context);
RequestContext.clear(context);
}
}
这里先记录指标，再结束 trace，最后清理 MDC。顺序不能反：HttpMetrics.record 的日志要用 requestId，tracing.finish 要把 traceId 注入响应头，清理必须最后做。
核心机制三：访问日志与指标只记录一次
访问日志和指标都放在 HttpMetrics，after 只调用一次：
public final class HttpMetrics {
private static final Logger log = LoggerFactory.getLogger(HttpMetrics.class);
private final MeterRegistry registry;
public HttpMetrics(MeterRegistry registry) {
this.registry = Objects.requireNonNull(registry, "registry");
}
public void record(Context context, long elapsedNanos) {
Duration duration = Duration.ofNanos(elapsedNanos);
Timer.builder("libraryd.http.server.requests")
.description("HTTP requests handled by libraryd")
.tag("method", context.method().name())
.tag("status", String.valueOf(context.statusCode()))
.register(registry)
.record(duration);
log.info("http_request method={} path={} status={} duration_ms={} requestId={}",
context.method().name(),
context.path(),
context.statusCode(),
duration.toMillis(),
RequestContext.requestId(context));
}
}
指标只打两个标签：method 和 status。日志里可以写 path，因为日志是逐条文本，基数再大也只是多几行；指标标签不能写原始路径，否则 /api/books/9787111213826、/api/books/9787115428028 会各生成一条时间序列，几千本书就能把 Prometheus 的基数打爆。
本机开启 INFO 级别后，一条真实的访问日志是：
18:13:36.564 INFO com.plume.library.web.HttpMetrics requestId=75457309-0763-4c78-9f57-bee951e30cc1 traceId= - http_request method=POST path=/api/books status=201 duration_ms=17 requestId=75457309-0763-4c78-9f57-bee951e30cc1
requestId 出现了两次：一次来自 MDC 的 pattern，一次来自消息体。这不是冗余，而是为了让日志既能被结构化采集（MDC 字段），又能在纯文本 grep 时直接看到（消息体）。如果日志已经用 JSON encoder，消息体里的 requestId 可以去掉，避免重复字段。
耗时从 before 开始算，包含路由匹配、handler、异常处理和响应序列化。它不包含 TCP 建连和 TLS 握手，那些属于接入层指标。一个请求如果在 before 之前就被 Jetty 拒绝（例如请求头过大），不会进入这个统计，这是已知边界。
核心机制四：异常处理器是中间件的最后一段
异常处理器也注册在 config.routes 上，按异常类型匹配：
config.routes.exception(LibraryException.class, this::handleLibraryException);
config.routes.exception(ValidationFailure.class, this::handleValidationFailure);
config.routes.exception(Exception.class, this::handleUnexpected);
Javalin 选择最具体的处理器。本机用三个处理器验证：同时注册 RuntimeException、IllegalArgumentException 和 Exception，抛 IllegalArgumentException，返回的是 IllegalArgumentException 对应的 400，不是 RuntimeException 的 500，也不是兜底的 Exception。
status=400 body=illegal-argument
Exception.class 的处理器是兜底，必须存在。没有它，未捕获异常会走 Javalin 自己的 500 页面，响应格式和 libraryd 的错误契约不一致，堆栈也可能被写进响应。
三个处理器的分工：
private void handleLibraryException(LibraryException exception, Context context) {
if (exception.errorCode().severity() >= 3) {
log.warn("request rejected requestId={} code={} message={}",
RequestContext.requestId(context), exception.errorCode().code(), exception.getMessage());
} else if (exception.errorCode() == ErrorCode.DB_UNAVAILABLE
|| exception.errorCode() == ErrorCode.INTERNAL) {
log.error("request failed requestId={} code={}",
RequestContext.requestId(context), exception.errorCode().code(), exception);
}
ProblemDetails.write(context, exception.errorCode(), exception.getMessage(), Map.of());
}
private void handleValidationFailure(ValidationFailure exception, Context context) {
log.warn("validation failed requestId={} errors={}",
RequestContext.requestId(context), exception.errors());
ProblemDetails.write(context, ErrorCode.VALIDATION_FAILED,
"request validation failed", exception.errors());
}
private void handleUnexpected(Exception exception, Context context) {
log.error("unhandled request failure requestId={}",
RequestContext.requestId(context), exception);
ProblemDetails.write(context, ErrorCode.INTERNAL, "internal server error", Map.of());
}
日志级别跟着错误性质走：客户端犯错（校验失败、资源冲突）是 WARN，服务端故障（数据库不可用、未捕获异常）是 ERROR。把所有异常都打成 ERROR，告警会被 404 淹没；都打成 WARN，真正的 500 又会被忽略。
处理器本身不能再抛异常。ProblemDetails.write 如果序列化失败，外层没有第二个兜底，Jetty 会返回一个空响应。8.2 节会给它加一个显式的序列化失败分支。
在 libraryd 里落地：装配顺序
把上面的类拼进 LibraryApi.create：
public Javalin create() {
return Javalin.create(config -> {
config.jsonMapper(new JavalinJackson(JsonSupport.objectMapper(), false));
config.http.defaultContentType = "application/json";
config.router.ignoreTrailingSlashes = true;
config.routes.before(this::before);
config.routes.after(this::after);
config.routes.get("/api/books", this::listBooks);
config.routes.get("/api/books/{isbn}", this::getBook);
config.routes.post("/api/books", this::createBook);
config.routes.put("/api/books/{isbn}", this::updateBook);
config.routes.delete("/api/books/{isbn}", this::deleteBook);
config.routes.post("/api/loans", this::borrowBook);
config.routes.get("/api/loans/{id}", this::getLoan);
config.routes.get("/api/members/{id}/loans", this::memberLoans);
config.routes.post("/api/returns", this::returnBook);
config.routes.post("/api/renews", this::renewLoan);
config.routes.get("/health", this::health);
config.routes.get("/metrics", this::metrics);
config.routes.exception(LibraryException.class, this::handleLibraryException);
config.routes.exception(ValidationFailure.class, this::handleValidationFailure);
config.routes.exception(Exception.class, this::handleUnexpected);
});
}
private void before(Context context) {
RequestContext.begin(context);
tracing.start(context);
}
private void after(Context context) {
try {
httpMetrics.record(context, RequestContext.elapsedNanos(context));
} finally {
tracing.finish(context);
RequestContext.clear(context);
}
}
before 里只做两件轻量的事：生成请求 ID、开启 trace。不要在这里查数据库、读 Redis 或做权限校验的重活，否则每个请求都要多付一次延迟，而且 before 抛异常时 after 仍然会执行，指标里会出现一个没有业务处理却带着耗时的请求。
tracing 是 TracingMiddleware，负责从 traceparent 请求头恢复上下文、开 server span、把 trace id 写进 MDC。它的细节在第 13 章展开；本节只需要保证 tracing.start 在 RequestContext.begin 之后，因为 span 上要挂 request.id 属性，tracing.finish 在 RequestContext.clear 之前，因为 trace id 还要写响应头。
/health 和 /metrics 也走同一套 before/after。健康检查被负载均衡器高频调用，访问日志会很多；如果觉得吵，可以在 HttpMetrics.record 里对这两个路径降级为 debug，但不要跳过请求 ID，否则健康检查失败时无法和网关日志对齐。
常见错误与边界
错误一：MDC 只 put 不 remove。 请求线程会被复用，上一个请求的 requestId 会出现在下一个请求的日志里。clear 必须放在 after 的 finally 块，不能放在 handler 末尾。
错误二：在每个 handler 里手动记日志和耗时。 12 个 handler 就有 12 份重复逻辑，异常路径最容易漏。中间件只写一次，成功和失败共享同一条记录路径。
错误三：把原始路径当指标标签。 /api/books/{isbn} 里的 ISBN 是无限集合，每个值都会生成一条时间序列。指标标签只放 method、status 这类低基数字段，路径模板要在路由层归一化后再用。
错误四：无条件信任客户端传来的 X-Request-Id。 攻击者可以传一个超长字符串或带换行的值，污染日志甚至响应头。工程上要限制长度（例如 128 字符）、只允许可见 ASCII，并且在网关层覆盖客户端值。请求 ID 只用于追踪，不能当身份凭证。
错误五：异常处理器里再抛异常。 处理器是最后一道网，抛出去就没人接了。序列化错误响应时要么用不会失败的字符串拼接，要么在 write 内部捕获并退化成最小响应。
边界：after 里响应可能已经提交。 如果 handler 已经写了响应体，after 再改状态码或响应头不会生效，Jetty 会忽略或抛 IllegalStateException。after 只做记录，不要试图修改业务响应。
边界：before 对静态资源和未匹配路由也执行。 如果将来挂静态文件，before 里的数据库健康检查会对每个 CSS 请求都跑一次。横切逻辑要么足够轻，要么按路径前缀跳过。
小结
before/after对所有请求生效，包括未匹配路由；顺序是 before → handler → exception → after。- 请求 ID 优先沿用客户端
X-Request-Id，缺失时生成 UUID，同时写响应头和 MDC。 - MDC 是线程本地变量，必须在
after的finally里清理，否则线程复用会串请求。 - 访问日志和指标只在
HttpMetrics记录一次；指标标签用低基数的method、status，不要用原始路径。 - 异常处理器按最具体类型匹配，
Exception.class兜底必须存在，处理器本身不能再抛异常。 before只做轻量工作，after只做记录，不要在响应提交后修改业务响应。
请求 ID、日志和错误响应都接上后，服务已经能被观测。但进程收到 SIGTERM 时，正在处理的请求会不会被切断，数据库连接会不会来不及归还，还没有答案。下一节看优雅停机与连接管理。
阅读导航：上一节：7.1 Javalin 起步：路由、路径参数与 JSON · 下一节：7.3 优雅停机与连接管理 。
继续阅读
探索更多技术文章
浏览归档，发现更多关于系统设计、工具链和工程实践的内容。