Refine handling of disconnected client error in ExceptionHandlerExceptionResolver

[rstoyanchev]

#26181 minimized logging of "disconnected client" errors while writing error responses. However, it allowed the handling the original exception to continue, which is with we do generally for errors from the invocation of @ExceptionHandler methods. However, in this case the error implies the exception was matched to a handler and resolved, but response writing failed, and therefore it makes sense to mark it as handled.

[stefanharke]

Thanks for addressing this enhancement @rstoyanchev .

I am having a similar issue regarding ClientAbortExceptions but I am not quite sure if the proposed ExceptionHandlerExceptionResolver will solve the issue. I would really appreciate if you can give your estimate on it.

I am using a RestController providing a GetMapping returning a SseEmitter.
After being requested by a client the emitter sends repeatedly small events to the client from a scheduled function. The emitter's send() method is guarded by a try-catch block handling any IOException.

Up to spring-framework 6.1.3 (spring-boot 3.2.2) this worked fine. Upgrading to spring-framwork 6.1.4 (spring-boot 3.2.3) adds additional error logging to the stack originating from the container as reported in #26181 .

[rstoyanchev]

@stefanharke is the stacktrace the same? In particular this, showing an I/O error from an @ExceptionHandler:

...
at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:227) ~[spring-web-5.3.1.jar:5.3.1]
at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:280) ~[spring-webmvc-5.3.1.jar:5.3.1]
at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.handleReturnValue(RequestResponseBodyMethodProcessor.java:181) ~[spring-webmvc-5.3.1.jar:5.3.1]
at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:78) ~[spring-web-5.3.1.jar:5.3.1]
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:124) ~[spring-webmvc-5.3.1.jar:5.3.1]
at org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver.doResolveHandlerMethodException(ExceptionHandlerExceptionResolver.java:421) ~[spring-webmvc-5.3.1.jar:5.3.1]
	

Your scenario sounds more like the same exception but while writing SSE. I'm not sure how you handle the exception, but in cases like these with a network issue, the Servlet container also calls AsyncListener#onError in parallel, which we do handle. This is why we don't try to complete the request if the response fails. There is a note on ResponseBodyEmitter#send about that.

Coincidentally, for 6.1.5 in #32340 there is a significant set of related improvements. I suggest you give 6.1.5-SNAPSHOT a try and let us know if it helps. You could comment under #32340, which seems more relevant for your issue. If necessary, provide a stack trace and relevant logging. This would be very helpful and timely!

[stefanharke]

@rstoyanchev thanks a lot for your very fast response.

The good things first. It looks like, that 6.1.5 will fix the issue. Thanks for pointing me into this direction.

I don't receive any additional errors after handling the exception using 6.1.5-SNAPSHOT. The stacktrace slightly differs. But I expect that this is related to SSE on the one hand. On the other hand I start sending from a scheduled task which will handle such exceptions with TaskUtils$LoggingErrorHandler on ERROR if not handled programmatically.

For the sake of completeness I will add an example of the current log.
But I don't see any reason for further action waiting for 6.1.5 becoming released.

2024-03-06T12:42:38.536+01:00 ERROR 4867 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] threw exception

java.io.IOException: Broken pipe
	at java.base/sun.nio.ch.FileDispatcherImpl.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:132) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:97) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:53) ~[na:na]
	at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:532) ~[na:na]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:118) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1381) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:764) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:728) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:712) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.flush(Http11OutputBuffer.java:566) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.coyote.http11.filters.ChunkedOutputFilter.flush(ChunkedOutputFilter.java:157) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:220) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1245) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:400) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.coyote.Response.action(Response.java:208) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:301) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:267) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:120) ~[tomcat-embed-core-10.1.19.jar:10.1.19]
	at java.base/java.io.FilterOutputStream.flush(FilterOutputStream.java:153) ~[na:na]
	at com.fasterxml.jackson.core.json.UTF8JsonGenerator.flush(UTF8JsonGenerator.java:1200) ~[jackson-core-2.15.4.jar:2.15.4]
	at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:1063) ~[jackson-databind-2.15.4.jar:2.15.4]
	at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:483) ~[spring-web-6.1.4.jar:6.1.4]
	at org.springframework.http.converter.AbstractGenericHttpMessageConverter.writeInternal(AbstractGenericHttpMessageConverter.java:123) ~[spring-web-6.1.4.jar:6.1.4]
	at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:236) ~[spring-web-6.1.4.jar:6.1.4]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal(ResponseBodyEmitterReturnValueHandler.java:221) ~[spring-webmvc-6.1.4.jar:6.1.4]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send(ResponseBodyEmitterReturnValueHandler.java:212) ~[spring-webmvc-6.1.4.jar:6.1.4]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:234) ~[spring-webmvc-6.1.4.jar:6.1.4]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:225) ~[spring-webmvc-6.1.4.jar:6.1.4]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:135) ~[spring-webmvc-6.1.4.jar:6.1.4]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:118) ~[spring-webmvc-6.1.4.jar:6.1.4]
	at com.example.sseissue.SseApplication.sendHeartbeat(SseApplication.java:55) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[na:na]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.runInternal(ScheduledMethodRunnable.java:130) ~[spring-context-6.1.4.jar:6.1.4]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.lambda$run$2(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.4.jar:6.1.4]
	at io.micrometer.observation.Observation.observe(Observation.java:499) ~[micrometer-observation-1.12.3.jar:1.12.3]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:124) ~[spring-context-6.1.4.jar:6.1.4]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.1.4.jar:6.1.4]
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:539) ~[na:na]
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305) ~[na:na]
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) ~[na:na]
	at java.base/java.lang.Thread.run(Thread.java:842) ~[na:na]

[rstoyanchev]

That's very good to know, and thank you for taking the time to confirm.