ClientAbortException from StreamingResponseBody can cause infinite loop of dispatches #32042
Description
Spring Boot 3.2.0
Java 17.0.8.1
Client aborting a StreamingResponseBody download in combination with an ExceptionHandler can cause an infinite loop of these exceptions (once every second):
java.lang.NullPointerException: Cannot invoke "org.apache.catalina.core.AsyncContextImpl.timeout()" because "asyncConImpl" is null at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:135) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:243) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:896) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1744) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na] There seems to be some sort of race condition as this doesn't happen if you "wait" briefly after catching the ClientAbortException.
What should happen (or actually happens when we wait)
ClientAbortException -> "clean up ot the request" -> request ends
What actually happens (when we don't wait) is something like this:
ClientAbortException -> "clean up" starts -> ExceptionHandler get's called which forwards to the original URL again -> new request comes in -> "clean up" ends (=> asyncConImpl is set to null) -> request never ends -> timeout -> NPEs
Why is the ExceptionHandler called at all? Does this make sense when we use a StreamingResponseBody and encounter a ClientAbortEexception?
Steps to reproduce:
- start the application (see code below)
- call http://localhost:8080/download?wait=false
- abort the download in the browser
- wait 20 seconds (= spring.mvc.async.request-timeout) an watch the logs (see below)
- (if you call http://localhost:8080/download?wait=true this does not happen)
Code:
package com.example.coyote; import org.apache.catalina.connector.ClientAbortException; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.boot.SpringApplication; import org.springframework.boot.autoconfigure.SpringBootApplication; import org.springframework.context.annotation.Configuration; import org.springframework.http.HttpHeaders; import org.springframework.http.ResponseEntity; import org.springframework.web.bind.annotation.*; import org.springframework.web.servlet.mvc.method.annotation.StreamingResponseBody; import java.nio.charset.StandardCharsets; @SpringBootApplication @RestController @RestControllerAdvice @Configuration public class CoyoteApplication { private static final Logger LOG = LoggerFactory.getLogger(CoyoteApplication.class); public static void main(String[] args) { SpringApplication.run(CoyoteApplication.class, args); } @GetMapping(value = "/download") public ResponseEntity<StreamingResponseBody> download(@RequestParam(value = "wait", defaultValue = "false") boolean wait) { LOG.info("wait: {}", wait); var data = "test".getBytes(StandardCharsets.UTF_8); var times = 10; StreamingResponseBody responseBody = outputStream -> { LOG.info("start download"); try { for (int i = 0; i < times; i++) { outputStream.write(data); outputStream.flush(); waitMillis(1000); } } catch (Exception e) { // this might already take too long to reproduce the behavior (see comment below) LOG.error("error"); // if we rethrow the exception fast enough, the exception handler is called, // and we end up in a very strange state // (just wait 20 seconds - spring.mvc.async.request-timeout - to see it in the logs) // note: if not happening, remove the error log from above, as it might already take too much time if (!wait) { throw e; } // if we wait, the exception handler is not called and everything is fine var before = Thread.currentThread().isInterrupted() ? "interrupted" : "running"; waitMillis(100); var after = Thread.currentThread().isInterrupted() ? "interrupted" : "running"; LOG.info("waited: {} -> {}", before, after); throw e; } LOG.info("finish download"); }; return ResponseEntity.ok() .header(HttpHeaders.CONTENT_DISPOSITION, "attachment; filename=file.txt") .header(HttpHeaders.CONTENT_LENGTH, String.valueOf(data.length * times)) .header(HttpHeaders.CONTENT_TYPE, "plain/txt") .body(responseBody); } @ExceptionHandler({ClientAbortException.class}) public void handleClientAbortException() { LOG.info("CLIENT ABORT"); } private static void waitMillis(long millis) { long now = System.currentTimeMillis(); while (System.currentTimeMillis() - now < millis) ; } }application.properties:
spring.mvc.async.request-timeout=20000ms pom.xml
<?xml version="1.0" encoding="UTF-8"?> <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd"> <modelVersion>4.0.0</modelVersion> <parent> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-parent</artifactId> <version>3.2.0</version> <relativePath/> <!-- lookup parent from repository --> </parent> <groupId>com.example</groupId> <artifactId>coyote</artifactId> <version>0.0.1-SNAPSHOT</version> <name>coyote</name> <description>Demo project for Spring Boot</description> <properties> <java.version>17</java.version> </properties> <dependencies> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-web</artifactId> </dependency> <dependency> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-starter-test</artifactId> <scope>test</scope> </dependency> </dependencies> <build> <plugins> <plugin> <groupId>org.springframework.boot</groupId> <artifactId>spring-boot-maven-plugin</artifactId> <configuration> <image> <builder>paketobuildpacks/builder-jammy-base:latest</builder> </image> </configuration> </plugin> </plugins> </build> </project>Logs when not waiting:
2024-01-02T10:37:32.455+01:00 INFO 12788 --- [nio-8080-exec-1] com.example.coyote.CoyoteApplication : wait: false 2024-01-02T10:37:32.469+01:00 INFO 12788 --- [ task-1] com.example.coyote.CoyoteApplication : start download 2024-01-02T10:37:36.471+01:00 ERROR 12788 --- [ task-1] com.example.coyote.CoyoteApplication : error 2024-01-02T10:37:36.481+01:00 INFO 12788 --- [nio-8080-exec-2] com.example.coyote.CoyoteApplication : CLIENT ABORT 2024-01-02T10:37:36.484+01:00 INFO 12788 --- [nio-8080-exec-2] com.example.coyote.CoyoteApplication : wait: false 2024-01-02T10:37:36.485+01:00 INFO 12788 --- [ task-2] com.example.coyote.CoyoteApplication : start download 2024-01-02T10:37:36.485+01:00 ERROR 12788 --- [ task-2] com.example.coyote.CoyoteApplication : error 2024-01-02T10:37:57.090+01:00 ERROR 12788 --- [nio-8080-exec-3] o.a.catalina.connector.CoyoteAdapter : Exception while processing an asynchronous request java.lang.NullPointerException: Cannot invoke "org.apache.catalina.core.AsyncContextImpl.timeout()" because "asyncConImpl" is null at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:135) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:243) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:896) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1744) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na] 2024-01-02T10:37:58.100+01:00 ERROR 12788 --- [nio-8080-exec-4] o.a.catalina.connector.CoyoteAdapter : Exception while processing an asynchronous request java.lang.NullPointerException: Cannot invoke "org.apache.catalina.core.AsyncContextImpl.timeout()" because "asyncConImpl" is null at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:135) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:243) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:57) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:896) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1744) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-10.1.16.jar:10.1.16] at java.base/java.lang.Thread.run(Thread.java:833) ~[na:na] 2024-01-02T10:37:59.094+01:00 ERROR 12788 --- [nio-8080-exec-5] o.a.catalina.connector.CoyoteAdapter : Exception while processing an asynchronous request ... Logs when waiting:
2024-01-02T10:41:04.131+01:00 INFO 7688 --- [nio-8080-exec-1] com.example.coyote.CoyoteApplication : wait: true 2024-01-02T10:41:04.145+01:00 INFO 7688 --- [ task-1] com.example.coyote.CoyoteApplication : start download 2024-01-02T10:41:08.146+01:00 ERROR 7688 --- [ task-1] com.example.coyote.CoyoteApplication : error 2024-01-02T10:41:08.247+01:00 INFO 7688 --- [ task-1] com.example.coyote.CoyoteApplication : waited: running -> interrupted (Issue originally posted here spring-projects/spring-boot#38950)