一个请求为什么出现两次拦截日志

接口只被客户端调用一次,拦截器却记录了两次 preHandle,两条日志还来自不同线程。直接按日志条数计算请求量,会把一次异步请求计成两次;直接把第二次处理认定为重试,又会错判业务是否执行了两遍。Servlet 的一次 HTTP 交换可以包含多个分派,分派次数、控制器调用次数与业务调用次数需要分别计数。

Spring MVC 的主要入口是 DispatcherServlet,但它不拥有完整的 HTTP 生命周期。Tomcat 先接收并解析请求,选择 Servlet 和 Filter 链;进入 DispatcherServlet 后,才由 MVC 选择处理器、解析参数、调用控制器并处理返回值。服务方法上的 Spring AOP 还要等调用真正经过代理对象时才进入。这三个扩展点重叠,却没有相同的覆盖范围。

实验固定 Spring Framework 6.2.11,源码提交 4c134254642d88e058aa004bdaf44168e1be7bb2,JDK 21 与嵌入式 Tomcat 10.1.46。完整程序是下载工程 mvc-lab/src/main/java/blog/spring/mvc/MvcLab.java,本篇执行参数为 25。客户端使用 JDK HttpClient,通过随机回环端口发出真实请求,不使用 MockMvc 代替容器分派。

一次交换中的同步、异步与错误分派

先区分容器链与 MVC 链

Filter 属于 Servlet 容器。注册时既要指定 URL 映射,也要指定适用的 DispatcherType。本实验用原生 Filter,把 REQUEST、ASYNC、ERROR 等类型明确注册;它的进入日志记录分派类型、URI 与线程名。因此第二次分派确实会再次进入这个 Filter。不能把该结果直接推广到任意 OncePerRequestFilter 子类,后者还有自身的跳过策略。

HandlerInterceptor 属于 MVC 的 HandlerExecutionChain。找到处理器后才得到相应的拦截器链,preHandle 在 HandlerAdapter 调用处理器之前执行。若返回 false,当前分派不会继续调用控制器;成功进入的拦截器才参与后续完成回调。拦截器可以看到 MVC 处理器信息,Filter 通常尚未处在已经选定控制器的阶段。

服务代理位于更深的 Java 调用链。实验里的 Greeting Bean 通过 ProxyFactory 创建 JDK 代理,控制器调用它的 say() 时记录 aop-enter 和 aop-exit。只有实际调用该 Bean 才产生这两条日志。Filter 可以提前响应,控制器也可以完全不调用 Greeting;这些 HTTP 交换都不在这个服务切面的覆盖范围内。

GET /hello 的记录顺序如下。日志原件还包含线程名,以下省略重复字段以便观察嵌套关系。

1
2
3
4
5
6
7
8
9
filter REQUEST /hello
pre REQUEST /hello context=true
handler
aop-enter
aop-exit
post REQUEST
complete REQUEST
filter-exit REQUEST
HTTP GET /hello status=200 body=hello

这组观察支持一个具体结论:当前配置下,正常同步请求先经过 Filter,再经过 MVC 拦截器,控制器调用服务代理后得到结果,最后退出各层。它没有证明所有 Filter 都包围所有 AOP,也没有证明所有异常都会到达服务切面。安全检查应放在能覆盖目标操作的边界,不能只因某次日志出现得早就推断覆盖完整。

doDispatch 的决定分支

固定版本的 DispatcherServlet.doDispatch() 先进行 multipart 检查,取得 HandlerExecutionChain,选择支持该处理器的 HandlerAdapter。经过条件请求检查和拦截器 preHandle 后,调用 ha.handle()。这里传入的是处理器描述,具体注解方法的调用逻辑主要在 RequestMappingHandlerAdapter 中。

HandlerAdapter 返回之后,doDispatch 立即检查 WebAsyncManager.isConcurrentHandlingStarted()。若已经开始异步处理,当前分派直接返回,不执行正常同步路径的 postHandle。finally 分支改为触发 afterConcurrentHandlingStarted;未进入异步时才继续模型视图、异常解析与同步完成路径。固定版本 doDispatch

所以判断回调缺失时,先查看异步状态。异步请求的第一次分派没有 postHandle、afterCompletion,并不自动意味着容器漏调了回调。请求资源的清理也不能全部放进第一次分派的 afterCompletion。若某资源只属于当前线程,应在异步释放该线程时清理;若属于整个异步交换,则需要使用对应的完成回调。

FrameworkServlet 在请求处理范围内设置并恢复线程相关的请求上下文。本实验在同步和异步重新分派的 preHandle 中都观察到 RequestContextHolder 有值;对应线程却可能不同。上下文可用不等于原线程一直被占用,更不表示任意自行启动的后台线程都能读取同一上下文。FrameworkServlet

ASYNC 分派不会再次执行原控制器

/async 返回 Callable<String>。初次调用控制器后,MVC 启动 Servlet 异步模式,把 Callable 提交给显式配置的 mvc-task- 执行器。当前容器线程随后退出 Filter 和 Servlet 链,HTTP 响应尚未完成。

Callable 返回 async-ok 后,WebAsyncManager 保存并发结果并发起异步分派。第二次请求仍经过 URL 映射,HandlerInterceptor 的 preHandle 再次执行;RequestMappingHandlerAdapter 发现已有并发结果,会将其包装成可处理的返回值,继续执行返回值处理。它不会再次调用创建 Callable 的原控制器方法。适配器的并发结果路径

实验中 handler-async 恰好一次,pre REQUEST 与 pre ASYNC 各一次,客户端最终得到一个 200 响应。业务任务在 mvc-task-1 上执行,初次与后续分派在 Tomcat 线程上执行。具体线程编号不是断言目标:容器有权复用同一线程,也可以使用不同线程。断言依赖的是分派类型和控制器调用次数。

这也解释了为什么拦截器中的计数或副作用要定义计量单位。记录“分派耗时”可以每次 preHandle 都开始一个范围;记录“外部 HTTP 请求量”则必须识别初次 REQUEST,或使用跨分派的关联标识。如果在每次 preHandle 都写一次订单审计,而业务只执行一次,重复审计来自扩展点选择,不一定来自业务重试。

ERROR 分派由容器触发

/filter-error 在 Filter 中执行 sendError(500),不调用 chain.doFilter()。Tomcat 配置了状态码 500 对应的错误页 /container-error,于是以 ERROR 类型重新分派。该错误页由 MVC 控制器返回 JSON,其中 dispatch 为 ERROR。

实际日志里有 filter REQUEST /filter-error,随后有 filter ERROR /container-error 与 pre ERROR。没有 Greeting 的 AOP 日志。第一次分派中的 Filter 失败并没有通过原控制器的调用栈传播到 MVC 异常解析器;能返回错误 JSON,是因为容器另行调度了配置好的错误页。

MVC 内部的异常解析和容器 ERROR 分派是两条不同机制。一个控制器异常若已被 @ExceptionHandler 转成 ResponseEntity,往往在 MVC 内部就完成响应,并不需要容器再次分派 ERROR。反过来,Filter、容器解析阶段甚至 Servlet 初始化阶段的错误,也不能凭一个 ControllerAdvice 保证统一接管。

错误页映射是本例行为的前提。移除该映射,Tomcat 仍可以产生 500,但错误体和分派路径会改变。应用框架可能自动注册错误页;本实验不用 Spring Boot,所有 Servlet、Filter 和错误页注册都保留在 main 中,便于区分容器默认值与框架自动配置。

复现与资源检查

在第 00 篇下载的实验目录中,令 JAVA_HOME 指向 JDK 21,执行:

1
2
./mvnw -f mvc-lab/pom.xml -q compile exec:java \
-Dexec.mainClass=blog.spring.mvc.MvcLab -Dexec.args=25

本章共 12 条断言,包括同步、异步、错误分派及四项关闭检查。evidence/25/local-20261002/run.txt 保存完整请求、线程和回调记录,邻近 manifest 保存源文件 SHA-256 与命令。结束时关闭生产执行器、Spring 上下文和 MVC 执行器,再连接原端口确认已经拒绝连接。只看到 JVM 正常退出,不能替代这些资源终态。

推导题:把 Filter 的映射改成仅 REQUEST,保留控制器的 Callable 返回值,客户端响应是否仍能成功?控制器方法调用几次?预期响应仍完成,控制器调用一次;该 Filter 不再记录 ASYNC,但 MVC 拦截器仍可以在重新分派中执行。异步支持标志也必须继续开启,它与分派类型映射是两个配置。

改动练习:仅改变 filterMap.setDispatcher 的注册类型,重跑 25,保留失败断言并解释每条差异。随后在拦截器日志加入请求属性中的固定关联标识,验证 REQUEST 与 ASYNC 的线程名可以不同,关联标识仍相同。不要用 ThreadLocal 作为跨线程关联标识的唯一保存位置。

完整工程下载见 深入 Spring(00):从手动组装到可验证的容器实验。六章共用独立的 mvc-lab 模块,单章参数决定执行场景;正文中的改动练习未计入已通过断言。

参考资料