Uploaded image for project: 'Spring Framework'
  1. Spring Framework
  2. SPR-16058

WebAsyncManager concurrency issue with SseEmitter when client disconnect

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Complete
    • Affects Version/s: 4.3.11
    • Fix Version/s: 4.3.13
    • Component/s: Web
    • Labels:
      None

      Description

      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();
              }
      

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                rstoya05-aop Rossen Stoyanchev
                Reporter:
                bclozel Brian Clozel
                Last updater:
                Spring Issuemaster
              • Votes:
                1 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Days since last comment:
                  26 weeks, 4 days ago