Poor SseEmitter handling of timeouts

[konrad-garus]

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

# ... 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

[konrad-garus]

I'll move this bug to spring-framework.

[philwebb]

@konrad-garus Actually I wouldn't be surprised if something in Spring Boot is complicating things. The JSON looks like it's from DefaultErrorAttributes and is probably returned from our BasicErrorController.

[konrad-garus]

Related: https://jira.spring.io/browse/SPR-13497 https://jira.spring.io/browse/SPR-13498

[rstoyanchev]

Investigating...

[rstoyanchev]

Several things going on..

The Servlet API has a timeout notification for async requests. In Spring MVC you can register timeout logic in SseEmitter#onTimeout (per request) or also globally via WebAsyncConfigurer#configureAsyncSupport. By default on timeout Spring MVC sets the response to 503 if response is not committed. However with HTTP streaming in Spring Framework 4.2, the response is likely committed so no timeout handling from the Spring MVC side.

In the absence of any concrete timeout logic, Tomcat turns the timeout into an ERROR dispatch which is then picked up by Boot's "/error" mapping and the default ErrorController is responsible for the JSON at the end. Tomcat actually does this with an "include" since the response is committed, and that allows Boot to append to the response.

So my suggestion for Spring Boot is to check if the response is already committed and avoid writing anything in BasicErrorController. I'd argue in such situations you can't make any assumptions about what the response is and what status, headers, and content have been written so far, so it shouldn't be altered further.

It gets stranger from there as shown in https://jira.spring.io/browse/SPR-13498. If the client connects again the "old" response suddenly starts writing to the "new" request. That I believe is a Tomcat bug and I confirmed that Jetty doesn't behave like that. I've created a bug in Tomcat https://bz.apache.org/bugzilla/show_bug.cgi?id=58457. This is not related to Spring Boot but I mention it for completeness.

[nnanda2016]

Is this fixed? We are planning to SSE using spring boot for one of our important use cases.

[rstoyanchev]

It is quite possible that due the fix for https://jira.spring.io/browse/SPR-14669 in 4.3.3 this may no longer be an issue. We no longer set the response to 503 in the timeout handler but instead do an ASYNC dispatch back into the container with an AsyncTimeoutException. So even though we still can't set the response to 503 when the ASYNC dispatch completes, so does the async request.

[bclozel]

Confirmed, this works fine now.