Tomcat: java.lang.IllegalStateException: Calling [asyncError()] is not valid for a request with Async state [MUST_DISPATCH]

[vitalyster]

After upgrading to Spring Boot 2.1.0 the logs are full of these errors. Looks like it was tracked in Spring JIRA before but marked as resolved

[wilkinsona]

Looking at that Framework issue, it was tracked down to a bug in Tomcat. You haven't said which version of Boot you upgraded from, but you may have picked up a new version of Tomcat as part of that upgrade that contains a regression. However, it's impossible to say with any degree of certainty based on so little information.

If you'd like us to spend some more time looking at this, please take the time to provide a minimal sample that reproduces the problem. Given that the previous, similar problem was a bug in Tomcat, I think it's unlikely that this is going to be a Spring Boot bug, but we can route the issue accordingly once we have a sample that reproduces it.

[vitalyster]

@wilkinsona Previous version was 2.0.x and as I understand 2.1 brings major Tomcat (9) update as dependency. Linked Tomcat ticket mention Fixed in 8.0.x for 8.0.0 and 7.0.x for 7.0.51. but not 9, so it may be really their issue. I did start from Spring Boot tracker to indicate issue with recent dependency update and the possible temporary solution may be downgrade back to 8.x. I will try to provide more info/example.

[vitalyster]

Minimal example with Tomcat errors

To see error: open localhost:8080 in browser, hit "refresh"

Switching to Undertow makes log clean

[wilkinsona]

Thanks for the sample. I've reproduced the problem, but I've only been able to do so by killing the client that's connected to the event stream, for example by using curl and CTRL+C. Upon doing so, I see the following in the log:

2018-11-02 11:43:33.016 ERROR 17152 --- [nio-8080-exec-2] o.a.catalina.connector.CoyoteAdapter     : Exception while processing an asynchronous request

java.lang.IllegalStateException: Calling [asyncError()] is not valid for a request with Async state [MUST_DISPATCH]
	at org.apache.coyote.AsyncStateMachine.asyncError(AsyncStateMachine.java:440) ~[tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:494) [tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.coyote.Request.action(Request.java:430) ~[tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.catalina.core.AsyncContextImpl.setErrorState(AsyncContextImpl.java:382) ~[tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:239) ~[tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.coyote.AbstractProcessor.dispatch(AbstractProcessor.java:241) [tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:53) [tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:770) [tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415) [tomcat-embed-core-9.0.12.jar:9.0.12]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.12.jar:9.0.12]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_181]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.12.jar:9.0.12]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]

Using the debugger, I can see that the failure that's triggered an error state to be set is an IO exception due to a broken pipe.

If I downgrade Tomcat to 8.5.34 a failure occurs but it is different and more obviously caused by the broken pipe:

2018-11-02 11:45:41.985 ERROR 17227 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] threw exception

java.io.IOException: Broken pipe
	at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_181]
	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_181]
	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_181]
	at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_181]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_181]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1306) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:726) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:679) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:669) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.flush(Http11OutputBuffer.java:646) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.coyote.http11.filters.ChunkedOutputFilter.flush(ChunkedOutputFilter.java:169) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:252) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1561) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:380) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.coyote.Response.action(Response.java:173) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118) ~[tomcat-embed-core-8.5.34.jar:8.5.34]
	at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297) ~[na:1.8.0_181]
	at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) ~[na:1.8.0_181]
	at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) ~[na:1.8.0_181]
	at org.springframework.util.StreamUtils.copy(StreamUtils.java:124) ~[spring-core-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:106) ~[spring-web-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:43) ~[spring-web-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:227) ~[spring-web-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal(ResponseBodyEmitterReturnValueHandler.java:191) ~[spring-webmvc-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send(ResponseBodyEmitterReturnValueHandler.java:184) ~[spring-webmvc-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:189) ~[spring-webmvc-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:183) ~[spring-webmvc-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:133) ~[spring-webmvc-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at com.demo.DemoServer.lambda$0(DemoServer.java:27) ~[main/:na]
	at java.util.concurrent.CopyOnWriteArrayList.forEach(CopyOnWriteArrayList.java:891) ~[na:1.8.0_181]
	at com.demo.DemoServer.sendSseEvent(DemoServer.java:22) ~[main/:na]
	at com.demo.DemoServer.helloMessage(DemoServer.java:38) ~[main/:na]
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:1.8.0_181]
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:1.8.0_181]
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.8.0_181]
	at java.lang.reflect.Method.invoke(Method.java:498) ~[na:1.8.0_181]
	at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.1.2.RELEASE.jar:5.1.2.RELEASE]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_181]
	at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) ~[na:1.8.0_181]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_181]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) ~[na:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_181]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_181]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_181]

If I downgrade to Spring Boot 2.0.6 (which uses Tomcat 8.5.34) I see the same behaviour as Spring Boot 2.1.0 with Tomcat 8.5.34.

As far as I can tell, the only thing that's changed here is Tomcat's error handling with the exception that are logged by 8.5.x and 9.0.x being different. The fundamental behaviour appears to be the same though.

@vitalyster If you have observed something different to what I have described above, can you please provide detailed instructions that describe exactly how to reproduce it?

[vitalyster]

Yes, I saw the same on Spring Boot 2.0.6, and that error was tracked on Spring JIRA too and I already tried to bump closed ticket but they forbid it :)
But old exception looks handled correctly for me just logged on wrong level, while new exception was not clear understanded for me as the same sseemitter issue until I started to locate problem.

[wilkinsona]

The commit that addressed SPR-16528 changed to log level for async timeout but not for a broken pipe. If you believe there's a further refinement to be made in Framework, I would recommend opening a new Framework issue although there's probably a good reason for why @rstoyanchev only changed one and not the other.

That said, a change in Framework isn't going to help you with Tomcat 9 as it's Tomcat that's logging the error message in that case not Framework. If you'd like to pursue that side of things, I'd recommend opening a Tomcat issue.

I'm going to close this one as none of the changes in behaviour are due to Spring Boot itself and any changes in what's logged and at what level will have to be made in Spring Framework or Tomcat.

[joshiste]

This issue was closed with for: external-project does anyone know if an issue for tomcat was filed and has a reference to it?

[wilkinsona]

The Tomcat issue is 56042.

[joaocarlos86]

I had this issue today, I can confirm that after updating the (embedded) tomcat to version 9.0.29, the error didn't occur anymore.