Poor SseEmitter handling of timeouts [SPR-13497]

[spring-projects-issues]

Konrad Garus opened SPR-13497 and commented

Whenever Tomcat async request times out, an error appears in the log and unexpected JSON message is emitted in response. For example, it happens with embedded Tomcat that arrives with Boot, where asyncTimeout appears to be 30 seconds.

To reproduce, create a Spring Boot app with embedded Tomcat. Just spring-boot-starter-web, version 1.3.0.M5. Let the main class look like:

@SpringBootApplication
@Controller
public class Application {
    private static final Logger log = LoggerFactory.getLogger(Application.class);

    @RequestMapping(path = "/api/events", method = RequestMethod.GET)
    public SseEmitter getEvents() throws Exception {
        SseEmitter emitter = new SseEmitter();
        ScheduledExecutorService pingThread = Executors.newScheduledThreadPool(1);
        emitter.onCompletion(() -> {
            log.info("Complete");
            pingThread.shutdown();
        });
        emitter.onTimeout(() -> {
            log.info("Timeout");
        });
        pingThread.scheduleAtFixedRate(() -> {
            try {
                emitter.send(SseEmitter.event().data("Hello").name("ping"));
            } catch (Exception e) {
                log.error("Unable to emit", e);
                throw new RuntimeException(e);
            }
        } , 1000, 1000, TimeUnit.MILLISECONDS);
        return emitter;
    }

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

Run the app.

Get the event stream, and observe:

$ 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 15:51:58 GMT
< 
data:Hello
event:ping

data:Hello
event:ping

1. ... repeated 30 times ...

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

Note the JSON at the very bottom.

In addition, when it happens the server log prints:

2015-09-24 17:53:18.601  WARN 9056 --- [io-8080-exec-10] .w.s.m.s.DefaultHandlerExceptionResolver : Handler execution resulted in exception: Could not find acceptable representation

---

Affects: 4.2.1

Issue Links:

• 18076 SseEmitter should ignore calls to send after timeout

[spring-projects-issues]

Konrad Garus commented

It may be related to Spring Boot, see also https://github.com/spring-projects/spring-boot/issues/4021.

[spring-projects-issues]

Rossen Stoyanchev commented

Between the improvement planned for #18076, the Tomcat bug, and the suggested Boot improvement I think we are covered.