技術分享 | SpringBoot 流式輸出時，正常輸出後為何突然報錯？詳情 - java,springboot,tomcat,後端,程序人生 LigaAI 動態日志

項目背景

一個 SpringBoot 項目同時使用了 Tomcat 的過濾器和 Spring 的攔截器，一些線程變量在過濾器中初始化並在攔截器中使用。
該項目需要調用大語言模型進行流式輸出。
項目中，筆者使用 SpringBoot 的 ResponseEntity<StreamingResponseBody> 將流式輸出返回前端。

問題出現

問題出現在上述第 3 點：正常輸出一段內容後，後台突然報錯，而報錯內容由攔截器產生。

筆者仔細查看了報錯日誌，發現只是攔截器的問題：執行時由於某些線程變量不存在而報錯。但是，這些線程變量已經在過濾器中初始化了。

那麼問題來了：為什麼這個接口明明可以正常通過過濾器和攔截器，並開始正常輸出，卻又突然在攔截器中報錯呢？

場景重現

Filter

@Slf4j
@Component
@Order(1)
public class MyFilter implements Filter {

    @Override
    public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
        // 要繼續處理請求，必須添加 filterChain.doFilter()
        log.info("doFilter method is running..., thread: {}, dispatcherType: {}", Thread.currentThread(), servletRequest.getDispatcherType()); 
        filterChain.doFilter(servletRequest,servletResponse);
    } 
}

Interceptor

@Slf4j
public class MyInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response, @NotNull Object handler) throws Exception {
        log.info("preHandle method is running..., thread: {}, dispatcherType: {}", Thread.currentThread(), request.getDispatcherType());
        if (DispatcherType.ASYNC == request.getDispatcherType()) {
            log.info("preHandle dispatcherType={}", request.getDispatcherType());
        }
        return true;
    }
    
    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        log.info("postHandle method is running..., thread: {}", Thread.currentThread());
    }      
    
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        log.info("afterCompletion method is running..., thread: {}", Thread.currentThread());
    } 
}

WebMvcConfigurer

@Configuration
public class WebAppConfigurer implements WebMvcConfigurer {
    
    @Bean
    public MyInterceptor myInterceptor() {
        return new MyInterceptor();
    }
    
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        registry.addInterceptor(myInterceptor()).addPathPatterns("/**");
    }
    
    @Override
    public void configureAsyncSupport(AsyncSupportConfigurer configurer) {
        configurer.setDefaultTimeout(120_000L);
        configurer.registerCallableInterceptors();
        configurer.registerDeferredResultInterceptors();
    
        ThreadPoolTaskExecutor executor = new ThreadPoolTaskExecutor();
        executor.setCorePoolSize(5);
        executor.setMaxPoolSize(10);
        executor.setQueueCapacity(100);
        executor.setThreadNamePrefix("web-async-");
        executor.initialize();
        configurer.setTaskExecutor(executor);
    }
}

Controller

@Slf4j
@RestController
@RequestMapping("/test-stream")
public class TestStreamController {

    @ApiOperation("流式輸出示例")
    @PostMapping(value = "/example", produces = MediaType.TEXT_EVENT_STREAM_VALUE)
    public ResponseEntity<StreamingResponseBody> example() {
        log.info("Stream method is running, thread: {}", Thread.currentThread());
        return  ResponseEntity.status(HttpStatus.OK)
            .contentType(new MediaType(MediaType.TEXT_EVENT_STREAM, StandardCharsets.UTF_8))
            .body(outputStream -> {
                log.info("Internal stream method is running, thread: {}", Thread.currentThread());
                try (outputStream) {
                    String msg = "To be or not to be!";
                    outputStream.write(msg.getBytes(StandardCharsets.UTF_8));
                    outputStream.flush();
                }
            });
    }
}

根據以下運行日誌，我們可以看到攔截器的 preHandle 確實執行了兩次，並且此次調用過程共有 3 個線程（io-14000-exec-1，web-async-1，io-14000-exec-2）參與了工作。

2024-05-06 07:35:27.362  INFO 209108 --- [io-14000-exec-1] o.a.c.c.C.[.[localhost].[/java-study]    : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-05-06 07:35:27.362  INFO 209108 --- [io-14000-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2024-05-06 07:35:27.365  INFO 209108 --- [io-14000-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 3 ms
2024-05-06 07:35:27.402  INFO 209108 --- [io-14000-exec-1] com.peng.java.study.web.config.MyFilter  : doFilter method is running..., thread: Thread[http-nio-14000-exec-1,5,main], dispatcherType: REQUEST
2024-05-06 07:35:28.107  INFO 209108 --- [io-14000-exec-1] c.p.java.study.web.config.MyInterceptor  : preHandle method is running..., thread: Thread[http-nio-14000-exec-1,5,main], dispatcherType: REQUEST
2024-05-06 07:35:28.121  INFO 209108 --- [io-14000-exec-1] c.p.j.s.w.r.test.TestStreamController    : Stream method is running, thread: Thread[http-nio-14000-exec-1,5,main]
2024-05-06 07:35:28.152  INFO 209108 --- [    web-async-1] c.p.j.s.w.r.test.TestStreamController    : Internal stream method is running, thread: Thread[web-async-1,5,main]
2024-05-06 07:35:28.167  INFO 209108 --- [io-14000-exec-2] c.p.java.study.web.config.MyInterceptor  : preHandle method is running..., thread: Thread[http-nio-14000-exec-2,5,main], dispatcherType: ASYNC
2024-05-06 07:35:28.167  INFO 209108 --- [io-14000-exec-2] c.p.java.study.web.config.MyInterceptor  : preHandle dispatcherType=ASYNC
2024-05-06 07:35:28.174  INFO 209108 --- [io-14000-exec-2] c.p.java.study.web.config.MyInterceptor  : postHandle method is running..., thread: Thread[http-nio-14000-exec-2,5,main]
2024-05-06 07:35:28.183  INFO 209108 --- [io-14000-exec-2] c.p.java.study.web.config.MyInterceptor  : afterCompletion method is running..., thread: Thread[http-nio-14000-exec-2,5,main]

問題分析

1. 方法調用流程的差異

眾所周知，SpringBoot 的普通輸出接口調用流程圖如圖 1 所示。

圖 1 | SpringBoot 普通輸出調用流程圖
（圖1-SpringBoot 普通輸出調用流程圖）

結合日誌，我們可以簡單畫出流式輸出接口對應的流程圖（圖 2）。

圖 2 | SpringBoot 流式輸出調用流程圖
（圖2-SpringBoot 流式輸出調用流程圖）

2. 線程的差異

普通接口的執行時序圖如圖 3 所示。

圖 3 | 普通接口的時序圖
（圖3-普通接口的時序圖）

而流式接口的時序圖如圖 4 所示。

圖 4 | 流式接口的調用時序圖
（圖4-流式接口的調用時序圖）

解決問題

通過分析，對流式輸出的情況提出兩種解決方案：

將過濾器中的部分業務邏輯遷移到攔截器中。
根據條件，跳過第二次的攔截器 preHandle 方法。

筆者選擇了第二個方案，實現代碼如下。

@Slf4j
public class MyInterceptor implements HandlerInterceptor {
    
    @Override
    public boolean preHandle(@NotNull HttpServletRequest request, @NotNull HttpServletResponse response, @NotNull Object handler) throws Exception {
        log.info("preHandle method is running..., thread: {}, dispatcherType: {}", Thread.currentThread(), request.getDispatcherType());
        // 如果是異步請求，則跳過
        if (DispatcherType.ASYNC == request.getDispatcherType()) {
            log.info("preHandle dispatcherType={}", request.getDispatcherType());
            return true;
        }
        return true;
    }
    
    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        log.info("postHandle method is running..., thread: {}", Thread.currentThread());     
    }
    
    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        log.info("afterCompletion method is running..., thread: {}", Thread.currentThread());
    } 
}

需要注意，請求線程和回調線程都需考慮清理線程變量，不然會導致內存泄漏。

瞭解更多技術乾貨、研發管理實踐等分享，請關注 LigaAI。

邀您體驗 LigaAI-智能研發協作平台，開啓 AI 驅動的智能研發協作！