Add special handling of disconnected client errors in ExceptionHandlerExceptionResolver

[vy]

Using Spring Boot 2.4.0 and Web MVC, when a client closes the connection before the server completes the response transmission, regular request handlers (e.g., @GetMapping) don't log any failures regarding the raised ClientAbortException by Tomcat. Whereas, in the case of a @ExceptionHandler, a ClientAbortException is logged. I think, the very same ClientAbortException needs to be suppressed, as is the case in regular request handlers.

Consider the following simple application:

@SpringBootApplication
public class MainApplication {

    public static void main(String[] args) {
        SpringApplication.run(MainApplication.class, args);
    }

    @RestController
    public static class MainController {

        private static final String RESPONSE_PAYLOAD;
        static {
            StringBuilder stringBuilder = new StringBuilder();
            for (int i = 0; i < 1_000_000; i++) {
                stringBuilder.append("foo bar baz ").append(i);
            }
            RESPONSE_PAYLOAD = stringBuilder.toString();
        }

        private static final class CustomError extends RuntimeException {}

        @GetMapping("/collapse")
        public String collapse() {
            throw new CustomError();
        }

        @ExceptionHandler(CustomError.class)
        public String handleException() {
            return RESPONSE_PAYLOAD;
        }

        @GetMapping("/work")
        public String work() {
            return RESPONSE_PAYLOAD;
        }

    }

}

Note that both handlers (i.e., request and exception) return back the very same payload.

Below I use toxiproxy to simulate the premature connection reset:

# Start the toxiproxy server.
$ toxiproxy-server
INFO[0000] API HTTP server starting                      host=localhost port=8474 version=2.1.4
...

# Create a new proxy to simulate the premature connection reset.
$ toxiproxy-cli create connectionreset -l localhost:18080 -u localhost:8080
Created new proxy connectionreset

# Configure `connectionreset` proxy to only allow a single byte in downstream. 
$ toxiproxy-cli toxic add connectionreset -t limit_data -a bytes=1
Added downstream limit_data toxic 'limit_data_downstream' on proxy 'connectionreset'

If I query http://localhost:18080/work, nothing gets logged to the server console. Whereas, querying http://localhost:18080/collapse causes the following failure in the server:

2020-11-26 11:12:54.440  WARN 10935 --- [nio-8080-exec-2] .m.m.a.ExceptionHandlerExceptionResolver : Failure in @ExceptionHandler com.vlkan.spring.MainApplication$MainController#handleException()

org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
	at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:351) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.OutputBuffer.appendByteArray(OutputBuffer.java:746) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:675) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:386) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:364) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:96) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at java.base/sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:233) ~[na:na]
	at java.base/sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:303) ~[na:na]
	at java.base/sun.nio.cs.StreamEncoder.implWrite(StreamEncoder.java:281) ~[na:na]
	at java.base/sun.nio.cs.StreamEncoder.write(StreamEncoder.java:125) ~[na:na]
	at java.base/sun.nio.cs.StreamEncoder.write(StreamEncoder.java:135) ~[na:na]
	at java.base/java.io.OutputStreamWriter.write(OutputStreamWriter.java:229) ~[na:na]
	at java.base/java.io.Writer.write(Writer.java:249) ~[na:na]
	at org.springframework.util.StreamUtils.copy(StreamUtils.java:147) ~[spring-core-5.3.1.jar:5.3.1]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:126) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:44) ~[spring-web-5.3.1.jar:5.3.1]
	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]
	at org.springframework.web.servlet.handler.AbstractHandlerMethodExceptionResolver.doResolveException(AbstractHandlerMethodExceptionResolver.java:75) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver.resolveException(AbstractHandlerExceptionResolver.java:141) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.handler.HandlerExceptionResolverComposite.resolveException(HandlerExceptionResolverComposite.java:80) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.DispatcherServlet.processHandlerException(DispatcherServlet.java:1321) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1132) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1078) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:961) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:626) ~[tomcat-embed-core-9.0.39.jar:4.0.FR]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:733) ~[tomcat-embed-core-9.0.39.jar:4.0.FR]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.1.jar:5.3.1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.1.jar:5.3.1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.1.jar:5.3.1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na]
Caused by: 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:47) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:113) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:79) ~[na:na]
	at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:50) ~[na:na]
	at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:466) ~[na:na]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:138) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:152) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1253) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:764) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:584) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:528) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:546) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(IdentityOutputFilter.java:73) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.Response.doWrite(Response.java:601) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:339) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	... 66 common frames omitted

2020-11-26 11:12:54.443 ERROR 10935 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is com.vlkan.spring.MainApplication$MainController$CustomError] with root cause

com.vlkan.spring.MainApplication$MainController$CustomError: null
	at com.vlkan.spring.MainApplication$MainController.collapse(MainApplication.java:34) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[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:567) ~[na:na]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:807) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1061) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:961) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:626) ~[tomcat-embed-core-9.0.39.jar:4.0.FR]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.1.jar:5.3.1]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:733) ~[tomcat-embed-core-9.0.39.jar:4.0.FR]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.1.jar:5.3.1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.1.jar:5.3.1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.1.jar:5.3.1]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.1.jar:5.3.1]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.39.jar:9.0.39]
	at java.base/java.lang.Thread.run(Thread.java:835) ~[na:na]

[philwebb]

Thanks for the bug report. I think this is something that the Spring Framework team will need to consider. I'll transfer the issue for them to review.

[rstoyanchev]

Thanks for the sample.

At the point of handling the controller method return value, the exception is allowed to propagate as it may be handled for example by an @ExceptionHandler and logged. The DispatcherServlet does log a single line at DEBUG for unhandled exceptions but even there it's possible the exception may be handled later through Servlet container level error mappings like the Spring Boot ErrorController for example.

It's a little different at the point of @ExceptionHandler where the exception handling itself fails to resolve the exception but even there we only log at DEBUG level unless a warnLogger is explicitly configured.

Furthermore, many times the exact opposite behavior is frequently requested, i.e. not to log I/O exceptions for clients that have gone away, especially for long running connections. We have a couple of places in the code (SockJS and WebFlux) where ClientAbortException and other similar server-specific exceptions are filtered out.

You can add an @ExceptionHandler and use that to log as needed. This could be declared globally in an @ControllerAdvice.

[vy]

Thanks for your prompt response @rstoyanchev, appreciated.

You can add an @ExceptionHandler and use that to log as needed.

I could not follow you on how to handle the exception thrown while Spring tries to transmit the response of a successfully completed exception handler method call. I have added the following simple exception handler to the snippet I shared above:

@ExceptionHandler(ClientAbortException.class)
void handleClientAbortException() {}

And you might guess that I still get the very same stack trace in the logs. Given the exception is not thrown by the code I have in my controller, but Spring itself, I am clueless about how to suppress it. Do I miss your point here? Would you mind elaborating on how can I "add an @ExceptionHandler and use that to log as needed", please?

[rstoyanchev]

@ExceptionHandler doesn't only catch errors from controller logic. It also catches errors from the subsequent handling which in this case is having the String written to the response body.

I'm not sure why you are not able to capture it. All I did was literally to add the @ExceptionHandler to your sample:

@RestController
public static class MainController {

	private static final String RESPONSE_PAYLOAD;
	static {
		StringBuilder stringBuilder = new StringBuilder();
		for (int i = 0; i < 1_000_000; i++) {
			stringBuilder.append("foo bar baz ").append(i);
		}
		RESPONSE_PAYLOAD = stringBuilder.toString();
	}

	// ...

	@ExceptionHandler
	public void handleException(IOException ex) {
		System.out.println("IOException: " + ex);
	}

	// ...
}

I wrote it slightly differently but all other variations work too:

@ExceptionHandler
public void handle(ClientAbortException ex) { }

@ExceptionHandler(ClientAbortException.class)
public void handle() { }

@ExceptionHandler(IOException.class)
public void handle() { }

[vy]

@rstoyanchev, please see the following test where testWork() succeeds whereas testCollapse() fails:

import ch.qos.logback.classic.Level;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.read.ListAppender;
import org.apache.catalina.connector.ClientAbortException;
import org.assertj.core.api.Assertions;
import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.boot.test.context.SpringBootTest;
import org.springframework.boot.web.server.LocalServerPort;
import org.springframework.web.bind.annotation.ExceptionHandler;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

import java.io.IOException;
import java.net.HttpURLConnection;
import java.net.URI;

@SpringBootTest(
        webEnvironment = SpringBootTest.WebEnvironment.RANDOM_PORT,
        classes = MainApplicationTest.TestApplication.class)
class MainApplicationTest {

    private static final Logger LOGGER =
            LoggerFactory.getLogger(MainApplicationTest.class);

    @LocalServerPort
    private int port;

    @Test
    void testWork() throws Exception {
        withLogVerification(() -> query("/work"));
    }

    @Test
    void testCollapse() throws Exception {
        withLogVerification(() -> query("/collapse"));
    }

    @FunctionalInterface
    private interface ThrowingRunnable {

        void run() throws Exception;

    }

    private static void withLogVerification(
            ThrowingRunnable body
    ) throws Exception {
        ListAppender<ILoggingEvent> appender = captureLogs();
        body.run();
        verifyLogs(appender);
    }

    private static ListAppender<ILoggingEvent> captureLogs() {
        ListAppender<ILoggingEvent> appender = new ListAppender<>();
        appender.list.clear();
        appender.setContext((LoggerContext) LoggerFactory.getILoggerFactory());
        ch.qos.logback.classic.Logger logger =
                (ch.qos.logback.classic.Logger) LoggerFactory
                        .getLogger(Logger.ROOT_LOGGER_NAME);
        logger.addAppender(appender);
        appender.start();
        return appender;
    }

    private static void verifyLogs(
            ListAppender<ILoggingEvent> appender
    ) throws InterruptedException {
        // It takes a while for Spring to dump the ERROR logs, hence waiting.
        Thread.sleep(1_000);
        Assertions
                .assertThat(appender.list)
                .noneSatisfy(event -> Assertions
                        .assertThat(event
                                .getLevel()
                                .isGreaterOrEqual(Level.ERROR))
                        .isTrue());
    }

    private void query(String path) throws IOException {
        HttpURLConnection urlConnection = (HttpURLConnection) URI
                .create("http://localhost:" + port + path)
                .toURL()
                .openConnection();
        try {
            // Prematurely close the connection.            
            urlConnection.getInputStream().close();
            int responseCode = urlConnection.getResponseCode();
            LOGGER.info("{} -> {}", path, responseCode);
        } finally {
            urlConnection.disconnect();
        }
    }

    @SpringBootApplication
    static class TestApplication {

        @RestController
        static class TestController {

            private static final String RESPONSE_PAYLOAD;

            static {
                StringBuilder stringBuilder = new StringBuilder();
                for (int i = 0; i < 1_000_000; i++) {
                    stringBuilder.append("foo bar baz ").append(i);
                }
                RESPONSE_PAYLOAD = stringBuilder.toString();
            }

            private static final class CustomError extends RuntimeException {}

            @GetMapping("/collapse")
            public String collapse() {
                throw new CustomError();
            }

            @ExceptionHandler(CustomError.class)
            public String handleCustomError() {
                return RESPONSE_PAYLOAD;
            }

            @ExceptionHandler(ClientAbortException.class)
            public void handleClientAbortException() {}

            @GetMapping("/work")
            public String work() {
                return RESPONSE_PAYLOAD;
            }

        }

    }

}