Default async timeout handling results in Logged Exception for Tomcat 8.5.x [SPR-14739]

[spring-projects-issues]

Johannes Edmeier opened SPR-14739 and commented

When the response has been already committed and the request timeouts afterwards there is an AsyncRequestTimeoutException logged on Tomcat 8.5.x.
When the response hasn't been committed no error is logged.

I guess this is due to the change in #19233.
Is the logged exception expected behaviour?

2016-09-21 21:27:02.101 ERROR 18717 --- [nio-8080-exec-5] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.web.context.request.async.AsyncRequestTimeoutException] with root cause

org.springframework.web.context.request.async.AsyncRequestTimeoutException: null
        at org.springframework.web.context.request.async.TimeoutDeferredResultProcessingInterceptor.handleTimeout(TimeoutDeferredResultProcessingInterceptor.java:42)
        at org.springframework.web.context.request.async.DeferredResultInterceptorChain.triggerAfterTimeout(DeferredResultInterceptorChain.java:75)
        at org.springframework.web.context.request.async.WebAsyncManager$5.run(WebAsyncManager.java:392)
        at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.onTimeout(StandardServletAsyncWebRequest.java:143)
        at org.apache.catalina.core.AsyncListenerWrapper.fireOnTimeout(AsyncListenerWrapper.java:44)
        at org.apache.catalina.core.AsyncContextImpl.timeout(AsyncContextImpl.java:131)
        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:157)
        at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:228)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:745)

---

Affects: 4.2.8, 4.3.3

Issue Links:

• Default async request timeout handling does not work with Jetty 9.x [SPR-14669] #19233 Default async request timeout handling does not work with Jetty 9.x

Referenced from: commits spring-attic/spring-framework-issues@d44d40c

Backported to: 4.2.9

[spring-projects-issues]

Rossen Stoyanchev commented

Is there a way you can describe how to reproduce the condition? Or perhaps provide more logging that shows the processing before and after the timeout?

[spring-projects-issues]

Johannes Edmeier commented

I've put up a very small sample:
https://github.com/joshiste/spring-framework-issues/tree/master/SPR-14739

[spring-projects-issues]

Rossen Stoyanchev commented

Okay thanks for that. So in an SSE scenario where at least one event has been sent, followed by a timeout.

A log message at that point isn't so out of place since the request timed out and the timeout wasn't handled (e.g. through a listener) and we can no longer change the response status to notify the client. However we can reduce the noise and handle the AsyncTimeoutException by logging a minimal debug message if the response is already committed.