Aborting a StreamingResponseBody download can cause an infinite loop

[straubp]

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

[straubp]

Hello, I'm not sure if this is the right project for this issue? Can anyone help me here? Thanks.

[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.

[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?

[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.
=> spring-projects/spring-framework#32042