WebFlux SSE controller does not detect disconnected client [SPR-15306]

[spring-projects-issues]

Sergei Egorov opened SPR-15306 and commented

Spring SSE implementation doesn't cancel the subscription when the client disconnects but waits until the next failed emission.

It leads to a huge number of open subscriptions when notification rarely happens (i.e. Stocks SSE endpoint with a non-frequently changing stock value).

Reference URL contains a Gist with Groovy app demonstrating an issue.
Start an app, use "curl -v localhost:8080", "CTRL-C". The app will continue to log because "distinctUntilChanged()" doesn't trigger anything, but the subscription is not canceled�.

Critical because if subscription is not lightweight (i.e. polling, or distributed event listening, pub/sub) server's performance quickly goes down and can be DoS'ed by hitting SSE endpoint

---

Affects: 5.0 M5

Reference URL: https://gist.github.com/bsideup/c69cd2395996adb246639eef43098343

Issue Links:

• [docs] Document the need for periodic writes on a streaming response [SPR-16494] #21037 [docs] Document the need for periodic writes on a streaming response
• Disconnected client exception logging should differentiate remote service exceptions too [SPR-17341] #21875 Disconnected client exception logging should differentiate remote service exceptions too

[spring-projects-issues]

Rossen Stoyanchev commented

I haven't confirmed but I suspect the issue is due to a limitation in the Servlet async API (SERVLET_SPEC-44). To confirm you can try switching to any of the supported non-Servlet runtimes like Reactor Netty, RxNetty, or Undertow.

It may be possible to address this specifically when running on Tomcat (I will follow up on that). Beyond that I just raised the question on the Servlet 4 mailing list to see if there is any chance of this being addressed.

[spring-projects-issues]

Sergei Egorov commented

I tried Reactor Netty, but it didn't help

[spring-projects-issues]

Rossen Stoyanchev commented

Are you sure you had Tomcat successfully swapped out for Reactor Netty?

At present Boot 2 snapshots default to Reactor Netty. I started from start.spring.io and used curl from the command line. After Ctrl+C from curl, the cancel signal appeared immediately:

2017-03-06 13:22:54.942  INFO 27746 --- [        timer-1] bug                                      : | onSubscribe([Fuseable] FluxJust.WeakScalarSubscription)
2017-03-06 13:22:54.943  INFO 27746 --- [        timer-1] bug                                      : | request(31)
2017-03-06 13:22:54.943  INFO 27746 --- [        timer-1] bug                                      : | onNext(1)
2017-03-06 13:22:54.944  INFO 27746 --- [        timer-1] bug                                      : | request(1)
2017-03-06 13:22:54.944  INFO 27746 --- [        timer-1] bug                                      : | onComplete()
2017-03-06 13:22:55.946  INFO 27746 --- [        timer-1] bug                                      : | onSubscribe([Fuseable] FluxJust.WeakScalarSubscription)
2017-03-06 13:22:55.947  INFO 27746 --- [        timer-1] bug                                      : | request(31)
2017-03-06 13:22:55.948  INFO 27746 --- [        timer-1] bug                                      : | onNext(1)
2017-03-06 13:22:55.949  INFO 27746 --- [        timer-1] bug                                      : | request(1)
2017-03-06 13:22:55.949  INFO 27746 --- [        timer-1] bug                                      : | onComplete()
2017-03-06 13:22:56.644  INFO 27746 --- [-server-epoll-6] bug                                      : | cancel()

Then I switched to Tomcat and got the issue you described. It kept logging until it timed out (no cancel signal):

2017-03-06 13:16:09.193  INFO 27353 --- [        timer-1] bug                                      : | onSubscribe([Fuseable] FluxJust.WeakScalarSubscription)
2017-03-06 13:16:09.193  INFO 27353 --- [        timer-1] bug                                      : | request(1)
2017-03-06 13:16:09.193  INFO 27353 --- [        timer-1] bug                                      : | onNext(1)
2017-03-06 13:16:09.193  INFO 27353 --- [        timer-1] bug                                      : | request(1)
2017-03-06 13:16:09.193  INFO 27353 --- [        timer-1] bug                                      : | onComplete()
2017-03-06 13:16:10.194  INFO 27353 --- [        timer-1] bug                                      : | onSubscribe([Fuseable] FluxJust.WeakScalarSubscription)
2017-03-06 13:16:10.194  INFO 27353 --- [        timer-1] bug                                      : | request(1)
2017-03-06 13:16:10.194  INFO 27353 --- [        timer-1] bug                                      : | onNext(1)
2017-03-06 13:16:10.194  INFO 27353 --- [        timer-1] bug                                      : | request(1)
2017-03-06 13:16:10.194  INFO 27353 --- [        timer-1] bug                                      : | onComplete()
2017-03-06 13:16:10.227 ERROR 27353 --- [nio-8080-exec-2] etServerHttpRequest$RequestBodyPublisher : COMPLETED onError: java.lang.IllegalStateException: Async operation timeout.

java.lang.IllegalStateException: Async operation timeout.
	at org.springframework.http.server.reactive.ServletServerHttpRequest$RequestAsyncListener.onTimeout(ServletServerHttpRequest.java:219) ~[spring-web-5.0.0.BUILD-20170306.165527-754.jar:5.0.0.BUILD-SNAPSHOT]
	at org.apache.catalina.core.AsyncListenerWrapper.fireOnTimeout(AsyncListenerWrapper.java:44) [tomcat-embed-core-8.5.11.jar:8.5.11]
	at org.apache.catalina.core.AsyncContextImpl.timeout(AsyncContextImpl.java:131) [tomcat-embed-core-8.5.11.jar:8.5.11]
	at org.apache.catalina.connector.CoyoteAdapter.asyncDispatch(CoyoteAdapter.java:157) [tomcat-embed-core-8.5.11.jar:8.5.11]

[spring-projects-issues]

Sergei Egorov commented

   ReactiveWebServerConfiguration.ReactorNettyAutoConfiguration matched:
...
   ReactiveWebServerConfiguration.TomcatAutoConfiguration:
      Did not match:
         - @ConditionalOnClass did not find required class 'org.apache.catalina.startup.Tomcat' (OnClassCondition)

I run the same script I linked, after full cache cleanup to ensure that I'm using the latest Snapshot.

However, I see logs after I pressed "Ctrl-C", and no "cancel" event at all

[spring-projects-issues]

Rossen Stoyanchev commented

Hm, very strange. I'm not sure why but I see different behavior. Can you do gradle --dependency:tree to confirm the actual tree of dependencies? Also perhaps take a stacktrace at runtime to see what's processing the request. There is no reason for this not work on Netty.

[spring-projects-issues]

Sergei Egorov commented

I wasn't using Gradle, but just groovy bug.groovy.

I'll try fresh demo project from start.spring.io now

[spring-projects-issues]

Sergei Egorov commented

Reproduced.

https://github.com/bsideup/SPR-15306

[spring-projects-issues]

Sergei Egorov commented

https://github.com/bsideup/SPR-15306/blob/master/src/test/java/com/example/DemoApplicationTests.java

wrote a test. Nobody can argue with a test :D

[spring-projects-issues]

Rossen Stoyanchev commented

Not questioning what you're seeing. Just trying to figure out why the difference.

I still see expected behavior from the server side if I use curl. The test you provided with the WebClient (and StepVerifier) however does demonstrate what you described. At this point I suspect it's related to the WebClient or our Reactory Netty client connector not seeing or not processing the cancel.

[spring-projects-issues]

Rossen Stoyanchev commented

There is at least one issue to be fixed on the Reactor Netty side reactor/reactor-netty#57.

Beyond there may be more work left . On my machine (Linux) Netty is using native epolling and doesn't have trouble detecting the connection closing from the sever side. When epolling is turned off however, it seems to wait for the next write which in this case never comes.

[spring-projects-issues]

Sergei Egorov commented

Cool! I use Mac so it explains why we're getting different results. Thanks for the explanation!

[spring-projects-issues]

Rossen Stoyanchev commented

There were a couple of fixes in reactor-netty 0.6.2 that address this issue. I've confirmed with both epoll and nio loop. If you could please give it a try. Just change the reactor-netty version to 0.6.2.RELEASE.

[spring-projects-issues]

Rossen Stoyanchev commented

Resolving for now since this should work with Reactor Netty 0.6.2. It would be great to get a confirmation from your side. Thanks for the report.

[trajano]

I seem to be seeing this issue on my set up. In my case I am hooked up to a docker daemon wrapped in a socat to forward TCP to unix socket.

My relevant dependencies are

• org.springframework.boot:spring-boot-starter-reactor-netty:2.1.3.RELEASE
• io.projectreactor.netty:reactor-netty:0.8.5.RELEASE

[rstoyanchev]

You've see the first paragraph here?

[trajano]

@rstoyanchev so you're making the assumption that one has control of the server side which some of us do not have access to do so. As such this is not really resolved.

[rstoyanchev]

What you mean by "control of the server side", control of the actual server (runtime) and/or the application that runs (e.g. controllers)? If the controller are part of your application, then the point is that you should be writing an empty SSE periodically. If you don't have control of neither, then it's the concern of whoever does have control.