SSE: Terminating chunk not sent using tomcat >= 8.0.35 [SPR-14444]

[spring-projects-issues]

Johannes Edmeier opened SPR-14444 and commented

Since tomcat version 8.0.35 chrome complains about an net::ERR_INCOMPLETE_CHUNKED_ENCODING error. When you have a look in tcpdump you can see that the terminating chunk with size zero is missing and the tcp connection gets closed. Also a exception is thrown on the server side (for the next polling request?).

A tcp dump for wireshark is attached.

2016-07-08 18:40:00.918 ERROR 7382 --- [nio-8080-exec-6] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet dispatcherServlet threw exception

java.lang.IllegalStateException: Can't set AsyncWebRequest with concurrent handling in progress
        at org.springframework.util.Assert.state(Assert.java:392)
        at org.springframework.web.context.request.async.WebAsyncManager.setAsyncWebRequest(WebAsyncManager.java:108)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:818)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:743)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:961)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:895)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:967)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:858)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:622)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:843)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:101)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
        at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:720)
        at org.apache.catalina.core.ApplicationDispatcher.doInclude(ApplicationDispatcher.java:584)
        at org.apache.catalina.core.ApplicationDispatcher.include(ApplicationDispatcher.java:523)
        at org.apache.catalina.core.StandardHostValve.custom(StandardHostValve.java:436)
        at org.apache.catalina.core.StandardHostValve.status(StandardHostValve.java:301)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:178)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
        at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:388)
        at org.apache.coyote.http11.AbstractHttp11Processor.asyncDispatch(AbstractHttp11Processor.java:1719)
        at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:652)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1520)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1476)
        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.7

Attachments:

• error.dump.pcap (1.45 kB)

Backported to: 4.2.8

0 votes, 5 watchers

[spring-projects-issues]

Johannes Edmeier commented

p.s. moving back to tomcat 8.0.33 fixes the issue...

[spring-projects-issues]

Rossen Stoyanchev commented

According to the stack trace, isAsyncStarted returns "true" at a point where we don't expect it to be, i.e. before the request is handled. This is probably not an issue on our side and the fact that changing the Tomcat version makes a difference points in the same direction.

Can you provide some more details? What does the controller method look like? Is this happening on the initial request to the controller method, or after a few events? Or if you have a small repro project...

[spring-projects-issues]

Johannes Edmeier commented

What does the controller method look like?
Here is the code for the controller: https://github.com/codecentric/spring-boot-admin/blob/master/spring-boot-admin-server/src/main/java/de/codecentric/boot/admin/journal/web/JournalController.java

Is this happening on the initial request to the controller method, or after a few events?
In fact no events are written to the stream at all and the exception occurs after the first request has ended (without the terminating chunk) and the browser makes a subsequent request.

This is probably not an issue on our side and the fact that changing the Tomcat version makes a difference points in the same direction.
That's also my guess but in fact I really just didn't know what write in a bug report for Tomcat - in 8.0.34 there are several changes regarding the AsyncListener may be you can track it down to one of them:

https://tomcat.apache.org/tomcat-8.0-doc/changelog.html

Fix: 59213: Async dispatches should be based off a wrapped request. (remm)
Fix: Ensure that javax.servlet.ServletRequest and javax.servlet.ServletResponse provided during javax.servlet.AsyncListener registration are made available via javax.servlet.AsyncEvent.getSuppliedRequest and javax.servlet.AsyncEvent.getSuppliedResponse (violetagg)
Fix: 59219: Ensure AsyncListener.onError() is called if an Exception is thrown during async processing. (markt)
Fix: 59220: Ensure that AsyncListener.onComplete() is called if the async request times out and the response is already committed. (markt)

[spring-projects-issues]

Rossen Stoyanchev commented

I've created basic repro project https://github.com/spring-projects/spring-framework-issues/tree/master/SPR-14444 to demonstrate the issue. When the async request times out, an error dispatch is issued to Boot's error controller, and that's when the failure occurs. According to the Servlet spec asyncStarted should be false after the request that called startAsync exits but it doesn't mention error dispatches explicitly. I've sent an email to the Tomcat dev list to probe if this is expected. Also for what it's worth Jetty doesn't have this issue.

[spring-projects-issues]

Juergen Hoeller commented

Can we be more defensive, i.e. not throw an IllegalStateException but rather silently accept an unexpected asyncStarted state there?

[spring-projects-issues]

Rossen Stoyanchev commented

Yes in fact we will have to be. There is no interest in changing the behavior on Tomcat's side, see http://markmail.org/thread/54jris7yp74pneox.

[spring-projects-issues]

Juergen Hoeller commented

Rossen Stoyanchev, does your recent commit sufficiently address the issue already? Is it good enough to simply remove that assertion?

[spring-projects-issues]

Rossen Stoyanchev commented

I've removed the assertion. Johannes Edmeier, there is now a 4.2.8.BUILD-SNAPSHOT, if you could please give that a try.

[spring-projects-issues]

Rossen Stoyanchev commented

Juergen Hoeller yes I think it is good enough to remove the assertion. We are simply getting out of the way. In any case we don't know how the application wants to handle the error dispatch. If the thread simply exits without any further handling, then the async request should complete automatically.

I did try with a sample application the above scenario and SSE polling continues without any errors in the logs.

[spring-projects-issues]

Juergen Hoeller commented

OK, let's optimistically mark this issue as resolved then.

[spring-projects-issues]

Johannes Edmeier commented

I gave 4.2.8-BUILD-SNAPSHOT and 4.3.2-BUILD-SNAPSHOT a try. Both looking good. The errors in the browser and the exception on the server doesn't occur anymore. Good Job! Thank you.

[spring-projects-issues]

dilbert side commented

I guess the issue is not working yet with version Spring Framework 4.3.3.RELEASE and Tomcat 8.5.5, or we face a border-line situation with docker.

In an example project I tweaked

---

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

---

if you remove the class override configureAsyncSupport(AsyncSupportConfigurer configurer) added in dilbertside/compose-spring-boot-admin@861a0de
you get the stacktrace described in codecentric/spring-boot-admin#317 which the maintainer of this application believe it is linked to this issue.

Raising the timeout value and handleTimeout in registerDeferredResultInterceptors doesn't show the exception any-more.
I believe my patch is not much more than cosmetic.

If you think my report is not related to this issue, I can file a new issue report.

Thank you.

[spring-projects-issues]

dilbert side commented

It looks like the above related issue is instead addressed by #19305 and codecentric/spring-boot-admin#286
Previous comment is de facto void.