Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Race condition in error handling for ClientAbortException within a StreamingResponseBody on Tomcat #33439

Open
fabianlinz opened this issue Aug 28, 2024 · 2 comments
Open

Race condition in error handling for ClientAbortException within a StreamingResponseBody on Tomcat #33439

fabianlinz opened this issue Aug 28, 2024 · 2 comments
Labels
in: web Issues in web modules (web, webmvc, webflux, websocket) status: feedback-provided Feedback has been provided status: waiting-for-triage An issue we've not yet triaged or decided on

Comments

@fabianlinz
Copy link

fabianlinz commented Aug 28, 2024 •
edited
Loading

Affects: 6.1.11, 6.2.0-M7

When a ClientAbortException occurs within a Spring MVC StreamingResponseBody sometimes the error handling is not called with the exception thrown by the StreamingResponseBody, but for the root cause java.io.IOException: Broken pipe. There seems to be a race condition, as this can be provoked reliably when throwing the exception from the StreamingResponseBody is delayed by a few milliseconds (see test in example project). This might be only a problem for Tomcat, but I have not yet checked this.

As the client aborted the connection the error handling will not be able to send anything to the client, but it can still log things or do other internal stuff. In our case this resulted in unexpected error log entries.

There are some issues that look very related (comments mention a race between Tomcat and the application), but they are closed and the issue still exists with Spring 6.2.0-M7 (I did not see something in the documentation or in a linked issue that this is a know issue for the time being; sorry if I missed it)

For the example project the expected behaviour would be that the error handling is called for the exception throws by the StreamingResponseBody:

com.example.streaming.response.body.error.handling.race.condition.StreamingResponseBodyErrorHandlingRaceConditionTest$SomethingWentWrongWhileStreamingException: org.springframework.web.context.request.async.AsyncRequestNotUsableException: ServletOutputStream failed to write: java.io.IOException: Broken pipe
at com.example.streaming.response.body.error.handling.race.condition.StreamingResponseBodyErrorHandlingRaceConditionTest$TestController.lambda$fails$0(StreamingResponseBodyErrorHandlingRaceConditionTest.java:128) ~[test/:na]
at org.springframework.web.servlet.mvc.method.annotation.StreamingResponseBodyReturnValueHandler$StreamingResponseBodyTask.call(StreamingResponseBodyReturnValueHandler.java:110) ~[spring-webmvc-6.2.0-M7.jar:6.2.0-M7]
at org.springframework.web.servlet.mvc.method.annotation.StreamingResponseBodyReturnValueHandler$StreamingResponseBodyTask.call(StreamingResponseBodyReturnValueHandler.java:97) ~[spring-webmvc-6.2.0-M7.jar:6.2.0-M7]
at org.springframework.web.context.request.async.WebAsyncManager.lambda$startCallableProcessing$4(WebAsyncManager.java:368) ~[spring-web-6.2.0-M7.jar:6.2.0-M7]
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[na:na]
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[na:na]
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[na:na]
at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]
Caused by: org.springframework.web.context.request.async.AsyncRequestNotUsableException: ServletOutputStream failed to write: java.io.IOException: Broken pipe
at org.springframework.web.context.request.async.StandardServletAsyncWebRequest$LifecycleHttpServletResponse.handleIOException(StandardServletAsyncWebRequest.java:323) ~[spring-web-6.2.0-M7.jar:6.2.0-M7]
at org.springframework.web.context.request.async.StandardServletAsyncWebRequest$LifecycleServletOutputStream.write(StandardServletAsyncWebRequest.java:381) ~[spring-web-6.2.0-M7.jar:6.2.0-M7]
at java.base/java.io.OutputStream.write(OutputStream.java:124) ~[na:na]
at com.example.streaming.response.body.error.handling.race.condition.StreamingResponseBodyErrorHandlingRaceConditionTest$TestController.lambda$fails$0(StreamingResponseBodyErrorHandlingRaceConditionTest.java:121) ~[test/:na]
... 8 common frames omitted
Caused by: org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:341) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.catalina.connector.OutputBuffer.appendByteArray(OutputBuffer.java:746) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:667) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:376) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:354) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:103) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.springframework.web.context.request.async.StandardServletAsyncWebRequest$LifecycleServletOutputStream.write(StandardServletAsyncWebRequest.java:378) ~[spring-web-6.2.0-M7.jar:6.2.0-M7]
... 10 common frames omitted
Caused by: java.io.IOException: Broken pipe
at java.base/sun.nio.ch.SocketDispatcher.write0(Native Method) ~[na:na]
at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:62) ~[na:na]
at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:137) ~[na:na]
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:102) ~[na:na]
at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:58) ~[na:na]
at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:542) ~[na:na]
at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:122) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1378) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:764) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:589) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:533) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:548) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.coyote.http11.filters.ChunkedOutputFilter.doWrite(ChunkedOutputFilter.java:111) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:193) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.coyote.Response.doWrite(Response.java:633) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:329) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
... 16 common frames omitted

Unexpected is that the error handling is called for the root cause

java.io.IOException: Broken pipe
	at java.base/sun.nio.ch.SocketDispatcher.write0(Native Method) ~[na:na]
	at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:62) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:137) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:102) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:58) ~[na:na]
	at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:542) ~[na:na]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:122) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1378) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:764) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:589) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:533) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:548) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.http11.filters.ChunkedOutputFilter.doWrite(ChunkedOutputFilter.java:111) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:193) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.Response.doWrite(Response.java:633) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:329) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
... 16 common frames omitted
@spring-projects-issues spring-projects-issues added the status: waiting-for-triage An issue we've not yet triaged or decided on label Aug 28, 2024
@bclozel bclozel added the in: web Issues in web modules (web, webmvc, webflux, websocket) label Aug 28, 2024
@rstoyanchev
Copy link
Contributor

Indeed, when a connection is lost while writing, there is an inherent race between the Servlet container initiating error handling (to complete request handling and release resources), as well as the application trying to do the same because of the IOException it got while from writing. There was plenty of work done in the issues you found to ensure only one of these goes through because if the Servlet container error handling goes through first, the request and response objects get recycled, and if application error sneaks through as well, it may end up operating on the recycled request and response that are now by then used for a different request.

There is not much we can do to ensure which goes first, and we cannot ensure that one is preferred over the other. Once we exit the Servlet container onError notification, it assumes the error is handled. We cannot hold it up indefinitely either, and there is no guarantee the application will propagate the IOException (wrapped or not) or handle it and exit normally without further action.

In summary, you will need to be prepared to handle the root cause, which can also occur for non-streaming scenarios. We have the DisconnectedClientHelper class that may be of help in recognizing such exceptions without introducing a dependency on a Servlet container class.

@rstoyanchev rstoyanchev added the status: waiting-for-feedback We need additional information before we can continue label Sep 6, 2024
@mvitz
Copy link

mvitz commented Sep 10, 2024 •
edited
Loading

@rstoyanchev we encountered something similar, and I wonder if this is related to this issue. If that's not the case sorry for interrupting this issue.

We use the SseEmitter and the code can be simplified to:

@GetMapping("/sse")
public SseEmitter sse() {
    final var sse = new SseEmitter();
    Runnable r = () -> {
        try {
            for (int i = 0; i < 5; i++) {
                TimeUnit.SECONDS.sleep(5);
                sse.send(SseEmitter.event().name("ping").data(i));
            }
            sse.complete();
        } catch (Exception e) {
        }
    };
    new Thread(r).start();
    return sse;
}

Although we swallow the exception within the running thread when refreshing the page within the browser that connects to this SSE resource, the following error is logged (within Tomcat):

2024-09-10T22:20:07.632+02:00 ERROR 21670 --- [nio-8080-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception

java.io.IOException: Broken pipe
	at java.base/sun.nio.ch.SocketDispatcher.write0(Native Method) ~[na:na]
	at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:62) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:137) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:102) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:58) ~[na:na]
	at java.base/sun.nio.ch.SocketChannelImpl.implWrite(SocketChannelImpl.java:566) ~[na:na]
	at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:618) ~[na:na]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:122) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1378) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:764) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:728) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:712) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.flush(Http11OutputBuffer.java:574) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.http11.filters.ChunkedOutputFilter.flush(ChunkedOutputFilter.java:156) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:216) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1252) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:408) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.coyote.Response.action(Response.java:208) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:299) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:265) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:136) ~[tomcat-embed-core-10.1.28.jar:10.1.28]
	at org.springframework.web.context.request.async.StandardServletAsyncWebRequest$LifecycleServletOutputStream.flush(StandardServletAsyncWebRequest.java:389) ~[spring-web-6.1.12.jar:6.1.12]
	at java.base/java.io.FilterOutputStream.flush(FilterOutputStream.java:155) ~[na:na]
	at com.fasterxml.jackson.core.json.UTF8JsonGenerator.flush(UTF8JsonGenerator.java:1207) ~[jackson-core-2.17.2.jar:2.17.2]
	at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:1063) ~[jackson-databind-2.17.2.jar:2.17.2]
	at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:483) ~[spring-web-6.1.12.jar:6.1.12]
	at org.springframework.http.converter.AbstractGenericHttpMessageConverter.writeInternal(AbstractGenericHttpMessageConverter.java:123) ~[spring-web-6.1.12.jar:6.1.12]
	at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:235) ~[spring-web-6.1.12.jar:6.1.12]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal(ResponseBodyEmitterReturnValueHandler.java:221) ~[spring-webmvc-6.1.12.jar:6.1.12]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send(ResponseBodyEmitterReturnValueHandler.java:212) ~[spring-webmvc-6.1.12.jar:6.1.12]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:223) ~[spring-webmvc-6.1.12.jar:6.1.12]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:214) ~[spring-webmvc-6.1.12.jar:6.1.12]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:135) ~[spring-webmvc-6.1.12.jar:6.1.12]
	at com.innoq.spring.sse.brokenpipe.RootController.lambda$sse$0(RootController.java:36) ~[classes/:na]
	at java.base/java.lang.Thread.run(Thread.java:1575) ~[na:na]

I assume the only and required way to suppress this is by adding something like:

@ExceptionHandler(IOException.class)
void handle(IOException e) {
    new DisconnectedClientHelper(RootController.class.getName()).checkAndLogClientDisconnectedException(e);
}

Right?

If that's not related to this problem, is there any chance of making this a bit more user-friendly or at least adding it to the documentation?

@spring-projects-issues spring-projects-issues added status: feedback-provided Feedback has been provided and removed status: waiting-for-feedback We need additional information before we can continue labels Sep 10, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
in: web Issues in web modules (web, webmvc, webflux, websocket) status: feedback-provided Feedback has been provided status: waiting-for-triage An issue we've not yet triaged or decided on
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@bclozel @rstoyanchev @mvitz @fabianlinz @spring-projects-issues