ServerSentEvents handler called again in case of client closes the connection

[yuryfunikov]

Bug report reopening https://github.com/spring-projects/spring-boot/issues/10332

Using Spring Boot 1.5.7-RELEASE and Spring MVC and having just one application and controller classes:

The full example with test case is here

@SpringBootApplication
public class SpringSseApplication {

    public static void main(String[] args) {
        SpringApplication.run(SpringSseApplication.class, args);
    }
}

@RestController
public class SseController {
private static final Logger logger = LoggerFactory.getLogger(SseController.class);
   @RequestMapping("/sse")
    public SseEmitter sseEmitter2() {
        logger.info("/sse");
        SseEmitter emitter = new SseEmitter();

        new Thread(()->{
            for (int i = 0; i < 1000; i++) {
                try {
                    logger.info("next: {}", i);
                    emitter.send("next: " + i);
                } catch (IOException e) {
                    logger.info("IOException ");
                    break;
                }
                try {
                    Thread.sleep(1000L);
                } catch (InterruptedException e) {
                    logger.info("interrupted...");
                    break;
                }
            }
            emitter.complete();
        }).start();

        return emitter;

    }
}

Controller has request handler that returns SseEmitter object. Then i start the application and SSE data consumer for instance using curl:

curl -i -H "Accept: application/json" http://localhost:8080/sse

In case if SSE data stream is stopped by client (e.g. with ctrl+c) there's a chance (~10%) that sseEmitter() method will be called again and you will see 'next: xxx' messages in server's console (though there's no connection to client anymore) without any errors. I.e. one will see console output like this:

2017-09-18 20:16:05.702  INFO 19416 --- [nio-8081-exec-3] com.example.springsse.SseController      : /sse
2017-09-18 20:16:05.703  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 0
2017-09-18 20:16:06.703  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 1
2017-09-18 20:16:07.707  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 2
2017-09-18 20:16:08.711  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 3
2017-09-18 20:16:09.714  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 4
2017-09-18 20:16:10.718  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 5
2017-09-18 20:16:11.722  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 6
2017-09-18 20:16:12.725  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : next: 7
2017-09-18 20:16:12.727  INFO 19416 --- [      Thread-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: An existing connection was forcibly closed by the remote host
    at sun.nio.ch.SocketDispatcher.write0(Native Method) ~[na:1.8.0_71]
...
    at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_71]

2017-09-18 20:16:12.733  INFO 19416 --- [      Thread-14] com.example.springsse.SseController      : IOException 
2017-09-18 20:16:12.737 ERROR 19416 --- [nio-8081-exec-4] o.a.c.c.C.[Tomcat].[localhost]           : Exception Processing ErrorPage[errorCode=0, location=/error]

org.apache.catalina.connector.ClientAbortException: java.io.IOException: An existing connection was forcibly closed by the remote host
...
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.5.20.jar:8.5.20]

...
2017-09-18 20:16:12.739  INFO 19416 --- [nio-8081-exec-4] com.example.springsse.SseController      : /sse
2017-09-18 20:16:12.740  INFO 19416 --- [      Thread-15] com.example.springsse.SseController      : next: 0
2017-09-18 20:16:13.740  INFO 19416 --- [      Thread-15] com.example.springsse.SseController      : next: 1
2017-09-18 20:16:14.740  INFO 19416 --- [      Thread-15] com.example.springsse.SseController      : next: 2

I wrote a test that calls /sse endpoint again and again up to 40 times and checks that number of calls from the client is the same as number of method calls on the server. If it becomes unequal the test fails.

I still think there's a bug of some kind that results in controller's method called again. It's called again even with POST method being used so i think it's quite critical for all who uses SseEmitter. Can you please re-open the issue.

[philwebb]

I've reopened the original issue.