Skip to content

WebAsyncManager concurrency issue with SseEmitter when client disconnect [SPR-16058] #20607

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
spring-projects-issues opened this issue Oct 10, 2017 · 5 comments
Closed

WebAsyncManager concurrency issue with SseEmitter when client disconnect [SPR-16058] #20607

spring-projects-issues opened this issue Oct 10, 2017 · 5 comments
Assignees
@rstoyanchev
Labels
in: web Issues in web modules (web, webmvc, webflux, websocket) type: bug A general bug
Milestone
4.3.13

Comments

@spring-projects-issues
Copy link
Collaborator

spring-projects-issues commented Oct 10, 2017 •
edited
Loading

Brian Clozel opened SPR-16058 and commented

This issue has been reported first in Spring Boot with a repro project (amended with a pull request).

This repro project simulates an SSE client connecting to a Spring MVC handler that uses SSEEmitter to stream data to the client. That client randomly disconnects while the server is writing. As expected per the Servlet spec, the server isn't notified of that disconnection and has to write to the socket to see that the client is gone.

This sample project shows that sometimes a given, unique request, is re-dispatched on the Spring MVC controller even if the client sent that only once. This goes like this:

First, the client connects and the request is dispatched (note, with the REQUEST dispatcher):

2017-10-10 18:34:11.736  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] connecting...
2017-10-10 18:34:11.738 DEBUG 5560 --- [o-auto-1-exec-8] o.s.web.servlet.DispatcherServlet        : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/sse/15]
2017-10-10 18:34:11.738 DEBUG 5560 --- [o-auto-1-exec-8] s.w.s.m.m.a.RequestMappingHandlerMapping : Looking up handler method for path /sse/15
2017-10-10 18:34:11.738 DEBUG 5560 --- [o-auto-1-exec-8] s.w.s.m.m.a.RequestMappingHandlerMapping : Returning handler method [public org.springframework.web.servlet.mvc.method.annotation.SseEmitter com.example.demo.SseController.sseEmitter(int,javax.servlet.http.HttpServletRequest)]
2017-10-10 18:34:11.738 DEBUG 5560 --- [o-auto-1-exec-8] o.s.web.servlet.DispatcherServlet        : Last-Modified value for [/sse/15] is: -1
2017-10-10 18:34:11.739  INFO 5560 --- [o-auto-1-exec-8] com.example.demo.SseController           : [SERVER] /sse/15, server call 15, dispatcher REQUEST
2017-10-10 18:34:11.739  INFO 5560 --- [         SSE-15] com.example.demo.SseController           : [SERVER] next: 0
2017-10-10 18:34:11.739 DEBUG 5560 --- [o-auto-1-exec-8] o.s.w.c.request.async.WebAsyncManager    : Concurrent handling starting for GET [/sse/15]
2017-10-10 18:34:11.740 DEBUG 5560 --- [o-auto-1-exec-8] .a.ResponseBodyEmitterReturnValueHandler : Written [data:] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:11.740 DEBUG 5560 --- [o-auto-1-exec-8] .a.ResponseBodyEmitterReturnValueHandler : Written [next: 0] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:11.740 DEBUG 5560 --- [o-auto-1-exec-8] .a.ResponseBodyEmitterReturnValueHandler : Written [

] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:11.740 DEBUG 5560 --- [o-auto-1-exec-8] o.s.web.servlet.DispatcherServlet        : Leaving response open for concurrent processing
2017-10-10 18:34:11.740  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] client receives: next: 0

Then the client disconnects, and other requests are sent and dispatched properly:

Exception in thread "SSE-14" java.lang.IllegalArgumentException: Cannot dispatch without an AsyncContext
	at org.springframework.util.Assert.notNull(Assert.java:134)
	at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.dispatch(StandardServletAsyncWebRequest.java:122)
	at org.springframework.web.context.request.async.WebAsyncManager.setConcurrentResultAndDispatch(WebAsyncManager.java:355)
	at org.springframework.web.context.request.async.WebAsyncManager.access$200(WebAsyncManager.java:59)
	at org.springframework.web.context.request.async.WebAsyncManager$7.handleResult(WebAsyncManager.java:418)
	at org.springframework.web.context.request.async.DeferredResult.setResultInternal(DeferredResult.java:233)
	at org.springframework.web.context.request.async.DeferredResult.setErrorResult(DeferredResult.java:248)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.completeWithError(ResponseBodyEmitterReturnValueHandler.java:225)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.completeWithError(ResponseBodyEmitter.java:204)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:169)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:159)
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:126)
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:107)
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:89)
	at com.example.demo.SseController.lambda$sseEmitter$0(SseController.java:45)
	at java.lang.Thread.run(Thread.java:748)
2017-10-10 18:34:12.738  INFO 5560 --- [         SSE-14] com.example.demo.SseController           : [SERVER] next: 2
2017-10-10 18:34:12.739 DEBUG 5560 --- [         SSE-14] .a.ResponseBodyEmitterReturnValueHandler : Written [data:] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.740  INFO 5560 --- [         SSE-14] o.apache.coyote.http11.Http11Processor   : An error occurred in processing while on a non-container thread. The connection will be closed immediately

java.io.IOException: Broken pipe
	at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_152-ea]
	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_152-ea]
	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_152-ea]
	at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_152-ea]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_152-ea]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1261) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.http11.Http11OutputBuffer.flushBuffer(Http11OutputBuffer.java:581) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:272) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1510) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:283) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.Response.action(Response.java:173) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297) [na:1.8.0_152-ea]
	at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) [na:1.8.0_152-ea]
	at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) [na:1.8.0_152-ea]
	at org.springframework.util.StreamUtils.copy(StreamUtils.java:119) [spring-core-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:106) [spring-web-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:41) [spring-web-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:227) [spring-web-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal(ResponseBodyEmitterReturnValueHandler.java:207) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send(ResponseBodyEmitterReturnValueHandler.java:200) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:166) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:159) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:126) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:107) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:89) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at com.example.demo.SseController.lambda$sseEmitter$0(SseController.java:45) [classes/:na]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_152-ea]

2017-10-10 18:34:12.741 DEBUG 5560 --- [         SSE-14] o.s.w.c.request.async.WebAsyncManager    : Concurrent result value [org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe] - dispatching request to resume processing
2017-10-10 18:34:12.743  INFO 5560 --- [         SSE-15] com.example.demo.SseController           : [SERVER] next: 1
2017-10-10 18:34:12.745 DEBUG 5560 --- [         SSE-15] .a.ResponseBodyEmitterReturnValueHandler : Written [data:] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.745 DEBUG 5560 --- [         SSE-15] .a.ResponseBodyEmitterReturnValueHandler : Written [next: 1] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.746 DEBUG 5560 --- [         SSE-15] .a.ResponseBodyEmitterReturnValueHandler : Written [

] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.747  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] client receives: next: 1
2017-10-10 18:34:12.747  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] client closes connection
2017-10-10 18:34:12.747  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] connecting...
2017-10-10 18:34:12.750 DEBUG 5560 --- [-auto-1-exec-10] o.s.web.servlet.DispatcherServlet        : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/sse/16]
2017-10-10 18:34:12.750 DEBUG 5560 --- [-auto-1-exec-10] s.w.s.m.m.a.RequestMappingHandlerMapping : Looking up handler method for path /sse/16
2017-10-10 18:34:12.750 DEBUG 5560 --- [-auto-1-exec-10] s.w.s.m.m.a.RequestMappingHandlerMapping : Returning handler method [public org.springframework.web.servlet.mvc.method.annotation.SseEmitter com.example.demo.SseController.sseEmitter(int,javax.servlet.http.HttpServletRequest)]
2017-10-10 18:34:12.751 DEBUG 5560 --- [-auto-1-exec-10] o.s.web.servlet.DispatcherServlet        : Last-Modified value for [/sse/16] is: -1
2017-10-10 18:34:12.751  INFO 5560 --- [-auto-1-exec-10] com.example.demo.SseController           : [SERVER] /sse/16, server call 16, dispatcher REQUEST
2017-10-10 18:34:12.751  INFO 5560 --- [         SSE-16] com.example.demo.SseController           : [SERVER] next: 0
2017-10-10 18:34:12.751 DEBUG 5560 --- [-auto-1-exec-10] o.s.w.c.request.async.WebAsyncManager    : Concurrent handling starting for GET [/sse/16]
2017-10-10 18:34:12.752 DEBUG 5560 --- [-auto-1-exec-10] .a.ResponseBodyEmitterReturnValueHandler : Written [data:] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.752 DEBUG 5560 --- [-auto-1-exec-10] .a.ResponseBodyEmitterReturnValueHandler : Written [next: 0] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.752 DEBUG 5560 --- [-auto-1-exec-10] .a.ResponseBodyEmitterReturnValueHandler : Written [

] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.752 DEBUG 5560 --- [-auto-1-exec-10] o.s.web.servlet.DispatcherServlet        : Leaving response open for concurrent processing
2017-10-10 18:34:12.752  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] client receives: next: 0
2017-10-10 18:34:12.752  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] client closes connection
2017-10-10 18:34:12.752  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] connecting...
2017-10-10 18:34:12.754 DEBUG 5560 --- [o-auto-1-exec-1] o.s.web.servlet.DispatcherServlet        : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/sse/17]
2017-10-10 18:34:12.755 DEBUG 5560 --- [o-auto-1-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Looking up handler method for path /sse/17
2017-10-10 18:34:12.756 DEBUG 5560 --- [o-auto-1-exec-1] s.w.s.m.m.a.RequestMappingHandlerMapping : Returning handler method [public org.springframework.web.servlet.mvc.method.annotation.SseEmitter com.example.demo.SseController.sseEmitter(int,javax.servlet.http.HttpServletRequest)]
2017-10-10 18:34:12.757 DEBUG 5560 --- [o-auto-1-exec-1] o.s.web.servlet.DispatcherServlet        : Last-Modified value for [/sse/17] is: -1
2017-10-10 18:34:12.758  INFO 5560 --- [o-auto-1-exec-1] com.example.demo.SseController           : [SERVER] /sse/17, server call 17, dispatcher REQUEST
2017-10-10 18:34:12.759  INFO 5560 --- [         SSE-17] com.example.demo.SseController           : [SERVER] next: 0
2017-10-10 18:34:12.760 DEBUG 5560 --- [o-auto-1-exec-1] o.s.w.c.request.async.WebAsyncManager    : Concurrent handling starting for GET [/sse/17]
2017-10-10 18:34:12.761 DEBUG 5560 --- [o-auto-1-exec-1] .a.ResponseBodyEmitterReturnValueHandler : Written [data:] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.762 DEBUG 5560 --- [o-auto-1-exec-1] .a.ResponseBodyEmitterReturnValueHandler : Written [next: 0] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.762 DEBUG 5560 --- [o-auto-1-exec-1] .a.ResponseBodyEmitterReturnValueHandler : Written [

] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:12.763 DEBUG 5560 --- [o-auto-1-exec-1] o.s.web.servlet.DispatcherServlet        : Leaving response open for concurrent processing
2017-10-10 18:34:12.763  INFO 5560 --- [           main] com.example.demo.SseTest                 : [CLIENT] client receives: next: 0
2017-10-10 18:34:13.748  INFO 5560 --- [         SSE-15] com.example.demo.SseController           : [SERVER] next: 2
2017-10-10 18:34:13.748 DEBUG 5560 --- [         SSE-15] .a.ResponseBodyEmitterReturnValueHandler : Written [data:] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:13.749  INFO 5560 --- [         SSE-15] o.apache.coyote.http11.Http11Processor   : An error occurred in processing while on a non-container thread. The connection will be closed immediately

java.io.IOException: Broken pipe
	at sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:1.8.0_152-ea]
	at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47) ~[na:1.8.0_152-ea]
	at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93) ~[na:1.8.0_152-ea]
	at sun.nio.ch.IOUtil.write(IOUtil.java:65) ~[na:1.8.0_152-ea]
	at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471) ~[na:1.8.0_152-ea]
	at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1261) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.SocketWrapperBase.flushBlocking(SocketWrapperBase.java:607) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.tomcat.util.net.SocketWrapperBase.flush(SocketWrapperBase.java:597) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.http11.Http11OutputBuffer.flushBuffer(Http11OutputBuffer.java:581) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.http11.Http11OutputBuffer.flush(Http11OutputBuffer.java:272) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.http11.Http11Processor.flush(Http11Processor.java:1510) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:283) ~[tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.coyote.Response.action(Response.java:173) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.catalina.connector.OutputBuffer.doFlush(OutputBuffer.java:317) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.catalina.connector.OutputBuffer.flush(OutputBuffer.java:284) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at org.apache.catalina.connector.CoyoteOutputStream.flush(CoyoteOutputStream.java:118) [tomcat-embed-core-8.5.20.jar:8.5.20]
	at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297) [na:1.8.0_152-ea]
	at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141) [na:1.8.0_152-ea]
	at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229) [na:1.8.0_152-ea]
	at org.springframework.util.StreamUtils.copy(StreamUtils.java:119) [spring-core-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:106) [spring-web-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.http.converter.StringHttpMessageConverter.writeInternal(StringHttpMessageConverter.java:41) [spring-web-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.http.converter.AbstractHttpMessageConverter.write(AbstractHttpMessageConverter.java:227) [spring-web-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.sendInternal(ResponseBodyEmitterReturnValueHandler.java:207) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.send(ResponseBodyEmitterReturnValueHandler.java:200) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:166) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:159) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:126) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:107) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:89) [spring-webmvc-4.3.11.RELEASE.jar:4.3.11.RELEASE]
	at com.example.demo.SseController.lambda$sseEmitter$0(SseController.java:45) [classes/:na]
	at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_152-ea]

2017-10-10 18:34:13.749 DEBUG 5560 --- [         SSE-15] o.s.w.c.request.async.WebAsyncManager    : Concurrent result value [org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe] - dispatching request to resume processing
2017-10-10 18:34:13.749  INFO 5560 --- [         SSE-15] com.example.demo.SseController           : IOException

Right after that, the first request is re-dispatched and re-routed to the Spring MVC Controller handler, this time with the ASYNC dispatcher:

2017-10-10 18:34:13.752 DEBUG 5560 --- [o-auto-1-exec-2] o.s.web.servlet.DispatcherServlet        : DispatcherServlet with name 'dispatcherServlet' processing GET request for [/sse/15]
2017-10-10 18:34:13.752 DEBUG 5560 --- [o-auto-1-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Looking up handler method for path /sse/15
2017-10-10 18:34:13.753 DEBUG 5560 --- [o-auto-1-exec-2] s.w.s.m.m.a.RequestMappingHandlerMapping : Returning handler method [public org.springframework.web.servlet.mvc.method.annotation.SseEmitter com.example.demo.SseController.sseEmitter(int,javax.servlet.http.HttpServletRequest)]
2017-10-10 18:34:13.753 DEBUG 5560 --- [o-auto-1-exec-2] o.s.web.servlet.DispatcherServlet        : Last-Modified value for [/sse/15] is: -1
2017-10-10 18:34:13.753  INFO 5560 --- [         SSE-16] com.example.demo.SseController           : [SERVER] next: 1
2017-10-10 18:34:13.753  INFO 5560 --- [o-auto-1-exec-2] com.example.demo.SseController           : [SERVER] /sse/15, server call 18, dispatcher ASYNC
2017-10-10 18:34:13.753 DEBUG 5560 --- [         SSE-16] .a.ResponseBodyEmitterReturnValueHandler : Written [data:] using [org.springframework.http.converter.StringHttpMessageConverter@7db534f2]
2017-10-10 18:34:13.753 DEBUG 5560 --- [o-auto-1-exec-2] .m.m.a.ExceptionHandlerExceptionResolver : Resolving exception from handler [public org.springframework.web.servlet.mvc.method.annotation.SseEmitter com.example.demo.SseController.sseEmitter(int,javax.servlet.http.HttpServletRequest)]: java.lang.IllegalStateException: Server call 18; client call 15; dispatcher: ASYNC
2017-10-10 18:34:13.754  INFO 5560 --- [         SSE-16] o.apache.coyote.http11.Http11Processor   : An error occurred in processing while on a non-container thread. The connection will be closed immediately

This duplicate request should not be routed since an async result (disconnect error) should already have been received at that point.

Note that the logs show other errors, that might be unrelated. It seems we're calling an async dispatch even though the underlying state machine forbids it.

DEBUG 2683 --- [         SSE-10] o.s.w.c.request.async.WebAsyncManager    : Concurrent result value [org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe] - dispatching request to resume processing
Exception in thread "SSE-10" java.lang.IllegalStateException: Calling [asyncDispatch()] is not valid for a request with Async state [MUST_COMPLETE]
	at org.apache.coyote.AsyncStateMachine.doDispatch(AsyncStateMachine.java:379)
	at org.apache.coyote.AsyncStateMachine.asyncDispatch(AsyncStateMachine.java:347)
	at org.apache.coyote.AbstractProcessor.action(AbstractProcessor.java:387)
	at org.apache.coyote.Request.action(Request.java:431)
	at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:208)
	at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:176)
	at org.apache.catalina.core.AsyncContextImpl.dispatch(AsyncContextImpl.java:170)
	at org.springframework.web.context.request.async.StandardServletAsyncWebRequest.dispatch(StandardServletAsyncWebRequest.java:123)
	at org.springframework.web.context.request.async.WebAsyncManager.setConcurrentResultAndDispatch(WebAsyncManager.java:355)
	at org.springframework.web.context.request.async.WebAsyncManager.access$200(WebAsyncManager.java:59)
	at org.springframework.web.context.request.async.WebAsyncManager$7.handleResult(WebAsyncManager.java:418)
	at org.springframework.web.context.request.async.DeferredResult.setResultInternal(DeferredResult.java:233)
	at org.springframework.web.context.request.async.DeferredResult.setErrorResult(DeferredResult.java:248)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitterReturnValueHandler$HttpMessageConvertingHandler.completeWithError(ResponseBodyEmitterReturnValueHandler.java:225)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.completeWithError(ResponseBodyEmitter.java:204)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.sendInternal(ResponseBodyEmitter.java:169)
	at org.springframework.web.servlet.mvc.method.annotation.ResponseBodyEmitter.send(ResponseBodyEmitter.java:159)
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:126)
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:107)
	at org.springframework.web.servlet.mvc.method.annotation.SseEmitter.send(SseEmitter.java:89)
	at com.example.demo.SseController.lambda$sseEmitter$0(SseController.java:45)
	at java.lang.Thread.run(Thread.java:748)

Checking our codebase in WebAsyncManager, it seems we're entering the else condition while the underlying state is changing.

        if (this.asyncWebRequest.isAsyncComplete()) {
            logger.error("Could not complete async processing due to timeout or network error");
        } else {
            if (logger.isDebugEnabled()) {
                logger.debug("Concurrent result value [" + this.concurrentResult + "] - dispatching request to resume processing");
            }

            this.asyncWebRequest.dispatch();
        }

Affects: 4.3.11

Reference URL: spring-projects/spring-boot#10332

Issue Links:

Referenced from: commits 97bc276

1 votes, 5 watchers
@spring-projects-issues
Copy link
Collaborator Author

Yury Funikov commented

hi guys,
any update on this one please? The issue reported a month ago and it's still in 'Waiting for Triage'.

Not sure why it has minor priority since it effectively makes SSE support in Spring useless for production purposes.

@spring-projects-issues
Copy link
Collaborator Author

spring-projects-issues commented Nov 8, 2017 •
edited
Loading

Rossen Stoyanchev commented

This is the same issue as #20173 I believe.

When a write fails, there is a race between us trying to clean up and the Servlet container trying to do the same. We fixed it in 5.0 only because the fix modified lots of classes and some contracts too. The assumption was that it was an improvement and until now I had not seen any side effects such as async dispatch actually getting through with invalid state.

I will investigate a way to address this in 4.3.x.

@spring-projects-issues
Copy link
Collaborator Author

Rossen Stoyanchev commented

I've added a fix to 4.3.x and tested with the sample. However note that you also need to remove the call to completeWithError on SseEmitter in the IOException handling from your own code, i.e. on this line.

Instead the Servlet container initiate the error handling in its own thread, we will then set the exception on the DeferredResult, and you can handle the exception in the resulting async dispatch. I recommend adding an @ExceptionHandler method for IOException either in the same controller or globally via a @ControllerAdvice.

@spring-projects-issues
Copy link
Collaborator Author

Yury Funikov commented

Hi Rossen, it's a great news, thank you!

Could you please share a link to these changes on GitHub?

@spring-projects-issues
Copy link
Collaborator Author

Rossen Stoyanchev commented

The commit is 97bc27. There is 4.3.13.BUILD-SNAPSHOT ready so give it a try.

@spring-projects-issues spring-projects-issues added type: bug A general bug in: web Issues in web modules (web, webmvc, webflux, websocket) labels Jan 11, 2019
@spring-projects-issues spring-projects-issues added this to the 4.3.13 milestone Jan 11, 2019
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@rstoyanchev rstoyanchev

Labels
in: web Issues in web modules (web, webmvc, webflux, websocket) type: bug A general bug
Projects
None yet
Milestone
4.3.13
Development

No branches or pull requests
2 participants
@rstoyanchev @spring-projects-issues