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) * https://github.com/spring-projects/spring-framework/issues/32042 - ClientAbortException from StreamingResponseBody can cause infinite loop of dispatches * https://github.com/spring-projects/spring-framework/issues/32340 - Better protect against concurrent error handling for async requests * https://github.com/spring-projects/spring-framework/commit/dd5fe6852261db533306328f40e6fbe841946fdb
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
Comment From: rstoyanchev
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.
Comment From: mvitz
@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?