AsyncRequestTimeoutException pollutes log

[dilbertside]

Hi,

Thank you for this admin console.

I'm running SBA with a docker composition with 2 SB client.
All instances are running SBA 1.4.3 and SB 1.4.1.RELEASE, and I get the following stacktrace when I browse to http://localhost:8080 and go to details.

How to reproduce:

git pull https://github.com/dilbertside/compose-spring-boot-admin.git
cd compose-spring-boot-admin
docker network create monitor
docker-compose up

Question is: did anyone get this error already? My humble guess it is coming from the SSE emitter.
It does happen also while activating Basic Authentication in my project.

2016-11-05 07:29:14.580  WARN 1 --- [nio-8080-exec-2] .w.s.m.s.DefaultHandlerExceptionResolver : Handling of [org.springframework.web.context.request.async.AsyncRequestTimeoutException] resulted in Exception

java.lang.IllegalStateException: Cannot call sendError() after the response has been committed
	at org.apache.catalina.connector.ResponseFacade.sendError(ResponseFacade.java:472) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.servlet.mvc.support.DefaultHandlerExceptionResolver.handleAsyncRequestTimeoutException(DefaultHandlerExceptionResolver.java:501) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.mvc.support.DefaultHandlerExceptionResolver.doResolveException(DefaultHandlerExceptionResolver.java:164) ~[spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.handler.AbstractHandlerExceptionResolver.resolveException(AbstractHandlerExceptionResolver.java:136) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.handler.HandlerExceptionResolverComposite.resolveException(HandlerExceptionResolverComposite.java:74) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.processHandlerException(DispatcherServlet.java:1193) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.processDispatchResult(DispatcherServlet.java:1030) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:980) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:622) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) [spring-webmvc-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:107) [spring-boot-actuator-1.4.1.RELEASE.jar:1.4.1.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) [spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:726) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationDispatcher.doDispatch(ApplicationDispatcher.java:647) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.ApplicationDispatcher.dispatch(ApplicationDispatcher.java:613) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.AsyncContextImpl$AsyncRunnable.run(AsyncContextImpl.java:555) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.AsyncContextImpl.doInternalDispatch(AsyncContextImpl.java:345) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:196) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:108) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:238) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:228) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_102]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_102]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_102]

2016-11-05 07:29:14.588 ERROR 1 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet dispatcherServlet threw exception

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

2016-11-05 07:29:14.589 ERROR 1 --- [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 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) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.context.request.async.DeferredResultInterceptorChain.triggerAfterTimeout(DeferredResultInterceptorChain.java:75) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.context.request.async.WebAsyncManager$5.run(WebAsyncManager.java:392) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.onTimeout(StandardServletAsyncWebRequest.java:143) ~[spring-web-4.3.3.RELEASE.jar:4.3.3.RELEASE]
	at org.apache.catalina.core.AsyncListenerWrapper.fireOnTimeout(AsyncListenerWrapper.java:44) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.core.AsyncContextImpl.timeout(AsyncContextImpl.java:131) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:157) ~[tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:228) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_102]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_102]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.5.jar:8.5.5]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_102]

[joshiste]

duplicate of #236

[dilbertside]

Well! when I had a look at https://jira.spring.io/browse/SPR-14444 it says
Fix Version/s: 4.2.8, 4.3.2, 5.0 M1

SBA pull Spring Framework 4.3.3.RELEASE and Tomcat 8.5.5, it is definitely not a bug coming from SBA, but I think a work-around is also welcome.
For the pleasure of the watchers, I propose a workaround in the already above mentioned project.

That would be great if any one could give me the best timeout setting to remove this annoying exception.

Thank you.

[dilbertside]

After longer testing, increasing the timeout was just reducing the error frequency
the request which is giving the error is unsurprisingly:
javax.naming.ServiceUnavailableException: request: uri=/api/journal?stream;client=172.20.0.1;headers={host=[localhost:8080], user-agent=[Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:49.0) Gecko/20100101 Firefox/49.0], accept=[text/event-stream], accept-language=[en-US,en;q=0.5], accept-encoding=[gzip, deflate], referer=[http://localhost:8080/], dnt=[1], connection=[keep-alive], pragma=[no-cache], cache-control=[no-cache]}

In another program, which doesn't use AngularJS but pure JQuery $.ajax and ResponseBodyEmitter, I got the error removed.
Use case was different but I wonder if that could be any help.

[dilbertside]

duplicate was #286 and not #236
workaround of setting property spring.mvc.async.request-timeout=-1 did stop the noise.
Apologies for the duplicate.

[joshiste]

oops sorry for pointing out the wrong issue

[joshiste]

I'll add a handler for the AsyncRequestTimeoutException so that no error get's logged.