Spring Boot:拦截器 preHandle 运行 在流端点上两次

SpringBoot: Interceptor's preHandle run twice on streaming endpoint

我想使用拦截器来管理与服务器的当前活动连接数。除了通常的 JSON 端点外,我的 API 还提供流字节的端点。我实现了一个会话管理器,它跟踪会话计数、一个限制性拦截器和几个 API 端点。下面是一些示例代码。

通常的 JSON 端点与拦截器 运行 很好。然而,流端点实际上调用拦截器的 preHandle 方法两次,但 afterCompletion 只调用一次。对 preHandle 的第二次调用发生在第一次调用的响应计算完成之后。当我从拦截器中删除会话管理器时,此行为不再发生。

最小工作示例:

配置:

@Configuration
@RequiredArgsConstructor
public class AppConfig implements WebMvcConfigurer {
    private final Interceptor interceptor;

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(this.interceptor).addPathPatterns("/numbers", "/numbers/*");
    }
}

拦截器:

@Component
@RequiredArgsConstructor
@Slf4j
public class Interceptor implements HandlerInterceptor {
    private final SessionManager sessionManager;

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        log.info("Pre-handle {}", this.hashCode());
        return this.sessionManager.accept();
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception e) {
        log.info("After completion {}", this.hashCode());
        this.sessionManager.leave();
    }
}

会话管理员:

@Component
@Slf4j
public class SessionManager {
    private static final int MAX_SESSION_COUNT = 1;
    private final AtomicInteger sessionCount = new AtomicInteger(0);

    public synchronized boolean accept() {
        int sessionCount = this.sessionCount.get();
        if (sessionCount >= MAX_SESSION_COUNT) {
            log.error("Upper session limit hit! Currently active sessions: {}, maximum allowed active sessions: {}", sessionCount, MAX_SESSION_COUNT);
            return false;
        }
        sessionCount = this.sessionCount.incrementAndGet();
        log.debug("Accept new session. Currently active sessions: {}, maximum allowed active sessions: {}", sessionCount, MAX_SESSION_COUNT);
        return true;
    }

    public void leave() {
        int sessionCount = this.sessionCount.decrementAndGet();
        log.debug("Decrement session count to {}", sessionCount);
    }
}

控制器:

@RestController
@RequestMapping("/numbers")
@Slf4j
public class Controller {
    private final Random random = new Random();

    @PostMapping("")
    public ResponseEntity<List<Integer>> number() {
        log.info("Generate numbers");
        List<Integer> bytes = IntStream.range(0, 1_000)
                .map(ignored -> this.random.nextInt(255))
                .boxed()
                .collect(Collectors.toList());
        return ResponseEntity.ok(bytes);
    }

    @PostMapping("/stream")
    public ResponseEntity<StreamingResponseBody> numberStream() {
        log.info("Generate stream start");
        StreamingResponseBody responseBody = outputStream -> {
            for (int i = 0; i < 1_000_000; i++) {
                outputStream.write(this.random.nextInt(255));
            }
        };
        return ResponseEntity.ok()
                .contentType(MediaType.APPLICATION_OCTET_STREAM)
                .body(responseBody);
    }
}

我找到了 a similar topic on Whosebug,但是那里给出的建议对我来说不起作用。从我的拦截器中删除 @Component 并在 addInterceptors 方法中手动实例化拦截器和会话管理器时,行为不会改变。

日志(最大会话数 = 2):

  .   ____          _            __ _ _
 /\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v2.6.1)

2021-12-10 14:21:25.999  INFO 17112 --- [           main] c.e.untitled2.Untitled2Application       : Starting Untitled2Application using Java 1.8.0_312 on HOSTNAME with PID 17112 (D:\IntelliJProjects\untitled2\target\classes started by USERNAME in D:\IntelliJProjects\untitled2)
2021-12-10 14:21:26.001  INFO 17112 --- [           main] c.e.untitled2.Untitled2Application       : No active profile set, falling back to default profiles: default
2021-12-10 14:21:26.626  INFO 17112 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2021-12-10 14:21:26.632  INFO 17112 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2021-12-10 14:21:26.632  INFO 17112 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.55]
2021-12-10 14:21:26.701  INFO 17112 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2021-12-10 14:21:26.701  INFO 17112 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 669 ms
2021-12-10 14:21:26.907  INFO 17112 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2021-12-10 14:21:26.913  INFO 17112 --- [           main] c.e.untitled2.Untitled2Application       : Started Untitled2Application in 1.197 seconds (JVM running for 1.84)
#### Call /numbers
2021-12-10 14:21:49.494  INFO 17112 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2021-12-10 14:21:49.494  INFO 17112 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2021-12-10 14:21:49.494  INFO 17112 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 0 ms
2021-12-10 14:21:49.502  INFO 17112 --- [nio-8080-exec-1] com.example.untitled2.Interceptor        : Interceptor 1184674729 pre-handles request 1068123396: POST /numbers
2021-12-10 14:21:49.503  INFO 17112 --- [nio-8080-exec-1] com.example.untitled2.SessionManager     : Accept new session. Currently active sessions: 1, maximum allowed active sessions: 2
2021-12-10 14:21:49.508  INFO 17112 --- [nio-8080-exec-1] com.example.untitled2.Controller         : Generate numbers
2021-12-10 14:21:49.536  INFO 17112 --- [nio-8080-exec-1] com.example.untitled2.Interceptor        : After completion 1184674729
2021-12-10 14:21:49.536  INFO 17112 --- [nio-8080-exec-1] com.example.untitled2.SessionManager     : Decrement session count to 0
#### Call /numbers again
2021-12-10 14:21:57.054  INFO 17112 --- [nio-8080-exec-3] com.example.untitled2.Interceptor        : Interceptor 1184674729 pre-handles request 1068123396: POST /numbers
2021-12-10 14:21:57.054  INFO 17112 --- [nio-8080-exec-3] com.example.untitled2.SessionManager     : Accept new session. Currently active sessions: 1, maximum allowed active sessions: 2
2021-12-10 14:21:57.054  INFO 17112 --- [nio-8080-exec-3] com.example.untitled2.Controller         : Generate numbers
2021-12-10 14:21:57.055  INFO 17112 --- [nio-8080-exec-3] com.example.untitled2.Interceptor        : After completion 1184674729
2021-12-10 14:21:57.055  INFO 17112 --- [nio-8080-exec-3] com.example.untitled2.SessionManager     : Decrement session count to 0
#### Call /numbers/stream
2021-12-10 14:22:06.375  INFO 17112 --- [nio-8080-exec-4] com.example.untitled2.Interceptor        : Interceptor 1184674729 pre-handles request 1068123396: POST /numbers/stream
2021-12-10 14:22:06.376  INFO 17112 --- [nio-8080-exec-4] com.example.untitled2.SessionManager     : Accept new session. Currently active sessions: 1, maximum allowed active sessions: 2
2021-12-10 14:22:06.376  INFO 17112 --- [nio-8080-exec-4] com.example.untitled2.Controller         : Generate stream start
2021-12-10 14:22:06.414  INFO 17112 --- [nio-8080-exec-5] com.example.untitled2.Interceptor        : Interceptor 1184674729 pre-handles request 317286159: POST /numbers/stream
2021-12-10 14:22:06.414  INFO 17112 --- [nio-8080-exec-5] com.example.untitled2.SessionManager     : Accept new session. Currently active sessions: 2, maximum allowed active sessions: 2
2021-12-10 14:22:06.416  INFO 17112 --- [nio-8080-exec-5] com.example.untitled2.Interceptor        : After completion 1184674729
2021-12-10 14:22:06.416  INFO 17112 --- [nio-8080-exec-5] com.example.untitled2.SessionManager     : Decrement session count to 1
#### Call /numbers/stream again
2021-12-10 14:22:17.857  INFO 17112 --- [nio-8080-exec-6] com.example.untitled2.Interceptor        : Interceptor 1184674729 pre-handles request 1068123396: POST /numbers/stream
2021-12-10 14:22:17.857  INFO 17112 --- [nio-8080-exec-6] com.example.untitled2.SessionManager     : Accept new session. Currently active sessions: 2, maximum allowed active sessions: 2
2021-12-10 14:22:17.857  INFO 17112 --- [nio-8080-exec-6] com.example.untitled2.Controller         : Generate stream start
2021-12-10 14:22:17.889  INFO 17112 --- [nio-8080-exec-7] com.example.untitled2.Interceptor        : Interceptor 1184674729 pre-handles request 1473864520: POST /numbers/stream
2021-12-10 14:22:17.889 ERROR 17112 --- [nio-8080-exec-7] com.example.untitled2.SessionManager     : Upper session limit hit! Currently active sessions: 2, maximum allowed active sessions: 2
#### Call /numbers/stream again
2021-12-10 14:22:26.443  INFO 17112 --- [nio-8080-exec-8] com.example.untitled2.Interceptor        : Interceptor 1184674729 pre-handles request 1068123396: POST /numbers/stream
2021-12-10 14:22:26.443 ERROR 17112 --- [nio-8080-exec-8] com.example.untitled2.SessionManager     : Upper session limit hit! Currently active sessions: 2, maximum allowed active sessions: 2

日志显示 preHandle 被调用了两次,而 afterCompletion 只被调用了一次。

来自document

Note: Will only be called if this interceptor's preHandle method has successfully completed and returned true!

afterCompletion()方法只有在preHandle()方法returnstrue时才会被调用。在您的情况下,您正在增加会话计数并返回 false。

如果您想始终调用 sessionManager.leave();(无论 preHandle() returns 是什么),请使用 postHandle() 而不是 afterCompletion()

因此,为了解决您遇到的问题,我们需要从 Servlet 环境支持的调度类型开始,尤其是作为 Servlet 3.0 规范的一部分添加的 ASYNC 调度类型。简而言之,添加了 ASYNC 调度类型以支持长 运行 / 重请求,这些请求在过去会阻止 servlet 容器处理其他请求,因为处理程序线程被阻塞等待 heavy/long-running要完成的任务。所以聪明的人决定可以在并行线程中执行长 运行 和繁重的作业,并且可以将主工作线程释放到池中,以便可以处理新的小请求。

让我们回到您的问题: 因此,有两个端点,一个是 returning JSON 或一个可以由处理程序线程处理的简单对象,另一个是 return 是 StreamingResponseBody。对于第一个,没有定义特殊处理,因此 Spring 将请求作为普通请求处理,只生成一个有效负载,然后 return 将其返回给客户端。对于第二个 spring 有一个名为 StreamingResponseBodyReturnValueHandler 的自定义响应处理程序,它基本上创建请求的异步版本(处理所有属性但更改调度类型)并通过将执行推送到新线程WebAsyncManager.

那么为什么 preHandle() 调用了两次?那是因为一旦它作为基于 REQUEST 调度的第一次执行的一部分被调用并且就在预句柄 Spring 开始处理请求并理解它应该在 ASYNC 模式下处理因为 return 类型是一个流(基本上没有大小的东西),所以请求的副本被制作它再次在新线程中执行。因此,如果您查看 preHandle(),您会注意到它是从不同的线程调用的,具有相同的请求数据,但请求时的调度类型不同。

更多信息在这里:

Github Issue

Code

那你能做什么? 你的 Interceptor 应该有点聪明,不要盲目地调用 sessionManager.accept(); 而是检查请求是否已经被处理过。

所以非常虚拟的版本看起来像这样

@Component
@RequiredArgsConstructor
@Slf4j
public class Interceptor implements HandlerInterceptor {
    private final SessionManager sessionManager;

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        log.info("Pre-handle {}", this.hashCode());
        if(BooleanUtils.isTrue(request.getAttribute("accepted")) || DispatcherType.ASYNC == request.getDispatcherType()){
            return true;
        }
        boolean accepted = this.sessionManager.accept();
        if (accepted){
            request.setAttribute("accepted", true);
        }
        return accepted;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception e) {
        log.info("After completion {}", this.hashCode());
        this.sessionManager.leave();
    }
}