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 CientAbortException.
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
Comment From: straubp
Hello, I'm not sure if this is the right project for this issue? Can anyone help me here? Thanks.
Comment From: wilkinsona
Given that the NPE is occurring in Tomcat and the stack is entirely Tomcat code, I doubt that there's anything that can be done about this in Spring Boot and I think that the problem should reported to the Tomcat team in the first instance. Even if there's a bug somewhere (on the Spring side, Spring MVC would be the most likely place), I would expect Tomcat to fail more gracefully than with an NPE. Before reporting a Tomcat issue, you may want to try the latest version of Tomcat to verify that the problem hasn't already been fixed.
Comment From: KazzmanK
I would like to upvote issue, as we are experiencing the same thing. Fix with waiting also helps. Someone will cross-post issue to tomcat team?
Comment From: straubp
Thank you for your reply, Andi. I would cross-post it, but I'm not sure, if it is an issue in Tomcat. To me it seems to be a synchronization issue after the exception occurs.
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
So why is the ExceptionHandler called at all? Does this make sense when we use a StreamingResponseBody and encounter a ClientAbortEexception?
I will cross-post the issue at spring-mvc. => https://github.com/spring-projects/spring-framework/issues/32042