SseEmitter should ignore calls to send after timeout [SPR-13498]

spring-projects-issues commented 9 years ago

Konrad Garus opened SPR-13498 and commented

Let's say I have a misbehaving handler that keeps using SseEmitter even though it's closed/timed out:

@RequestMapping(path = "/api/events", method = RequestMethod.GET)
public SseEmitter getEvents() throws Exception {
    SseEmitter emitter = new SseEmitter();
    Executors.newScheduledThreadPool(1).scheduleAtFixedRate(() -> {
        try {
            emitter.send(SseEmitter.event().data("Thread writing: " + Thread.currentThread()).name("ping"));
        } catch (Exception e) {
        }
    } , 1000, 1000, TimeUnit.MILLISECONDS);
    return emitter;
}

When I get the event stream for the first time, it looks like you would expect, except for the JSON at the very bottom (see #18075):

$ curl -v http://localhost:8080/api/events
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /api/events HTTP/1.1
> User-Agent: curl/7.38.0
> Host: localhost:8080
> Accept: */*
> 
< HTTP/1.1 200 OK
* Server Apache-Coyote/1.1 is not blacklisted
< Server: Apache-Coyote/1.1
< Content-Type: text/event-stream;charset=UTF-8
< Transfer-Encoding: chunked
< Date: Thu, 24 Sep 2015 16:03:35 GMT
< 
data:Thread writing: Thread[pool-1-thread-1,5,main]
event:ping

data:Thread writing: Thread[pool-1-thread-1,5,main]
event:ping

1. ... repeats until timeout ...

* Connection #0 to host localhost left intact
{"timestamp":1443110621518,"status":200,"error":"OK","message":"No message available","path":"/api/events"}

Now, have a look at what happens on reconnect:

$ curl -v http://localhost:8080/api/events
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET /api/events HTTP/1.1
> User-Agent: curl/7.38.0
> Host: localhost:8080
> Accept: */*
> 
data:data:data:data:data:
5
data:
2e
Thread writing: Thread[pool-1-thread-1,5,main]
d

event:ping

5
data:
2e
Thread writing: Thread[pool-2-thread-1,5,main]
d

event:ping

5
data:
2e
Thread writing: Thread[pool-1-thread-1,5,main]
d

event:ping

5
data:
2e
Thread writing: Thread[pool-2-thread-1,5,main]
d

event:ping

We can see both threads writing to the same connection, even though the first emitter was supposedly closed!

What's even more interesting, it's not limited to that endpoint or SSE streams. Here's what happens when I try to load a static resource:

$ curl -v http://localhost:8080
* Rebuilt URL to: http://localhost:8080/
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET / HTTP/1.1
> User-Agent: curl/7.38.0
> Host: localhost:8080
> Accept: */*
> 
data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:data:<!DOCTYPE HTML>
<html>
<head></head>
<body>Whatever</body>
</html>

0

Note the "data:data:data:..." on top.

Yes, the code leading to this bug is broken. It's just a made-up example though. I suspect in the real life such issues are still possible with clean-looking code.

I think this should be addressed by preventing use of a closed SseEmitter. If you try to send an event to one, you get an exception immediately and it doesn't even try to touch the underlying connection. Logically something like:

public class SseEmitter {
    public void send(Object event) {
        if(closed) { throw new IllegalStateException("Emitter closed"); }
        connection.send(event);
    }
}

Affects: 4.2.1

Issue Links:

18075 Poor SseEmitter handling of timeouts

spring-projects-issues commented 9 years ago

Konrad Garus commented

Looks like manually calling SseEmitter.complete is enough to prevent the stray thread from writing:

emitter.onCompletion(emitter::complete);

It seems like something that the library should do by itself.

spring-projects-issues commented 9 years ago

Rossen Stoyanchev commented

The Servlet API provides callbacks on timeout and Spring MVC exposes them too, e.g.:

emitter.onTimeout(() -> {
    emitter.complete();
});

You can also register timeout logic globally. An example with the MVC namespace but the same can be done through the MVC Java config (i.e.WebMvcConfigurer) too.

To the best of my knowledge you shouldn't have to handle timeouts for the response to be closed. I believe the above behavior where a new request is established and the old response starts writing to it is a Tomcat bug which I've reported https://bz.apache.org/bugzilla/show_bug.cgi?id=58457. Switching to Jetty also shows it's Tomcat specific behavior.

That said we could make some improvements on our side as you suggested. We already have a completed flag in ResponseBodyEmitter (the base class for SseEmitter) and could set it after timeout. I'll have a look at that.

As for the JSON at the end after the timeout, I've suggested an improvement for Boot's default ErrorController to not write if the response is committed. My comments there.

spring-projects-issues commented 9 years ago

Rossen Stoyanchev commented

Repro project https://github.com/spring-projects/spring-framework-issues/tree/master/SPR-13498.

spring-projects-issues commented 9 years ago

Rossen Stoyanchev commented

I've added hooks to detect timeout/completion and set the complete flag. The above code now works as expected even ahead of any potential Tomcat fixes.

spring-projects / spring-framework

SseEmitter should ignore calls to send after timeout [SPR-13498] #18076

18075 Poor SseEmitter handling of timeouts