Ensure flush after StreamingResponseBody

[jru]

Consider this simple controller:

@RestController
@RequestMapping("/api")
public class DemoController {
    @GetMapping("/demo")
    public StreamingResponseBody demo(@RequestParam(required = false) Boolean flush) {
        String str = "This is the response";

        return os -> {
            IOUtils.copy(new ByteArrayInputStream(str.getBytes()), os);
            if (flush)
                os.flush();
        };
    }
}

When called with the flush=true argument we get the expected response:

$ curl  -vv http://localhost:8080/api/demo?flush=true

*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 8080 (#0)
> GET /api/demo?flush=true HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.63.0
> Accept: */*
>
< HTTP/1.1 200
< Transfer-Encoding: chunked
< Date: Wed, 17 Apr 2019 13:18:26 GMT
<
This is the response* Connection #0 to host localhost left intact

However, when called without, we get a 500:

$ curl  -vv http://localhost:8080/api/demo

*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 8080 (#0)
> GET /api/demo HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.63.0
> Accept: */*
>
< HTTP/1.1 500
< Content-Type: application/json;charset=UTF-8
< Transfer-Encoding: chunked
< Date: Wed, 17 Apr 2019 13:20:07 GMT
< Connection: close
<
{"timestamp":1555507207121,"status":500,"error":"Internal Server Error","message":"No message available","path":"/api/demo"}* Closing connection 0

Affected version: Spring Boot 2.2.0.M2

[sbrannen]

@rstoyanchev, what do you think about adding this.outputStream.flush(); to StreamingResponseBodyReturnValueHandler.StreamingResponseBodyTask.call() before returning null?

[rstoyanchev]

@sbrannen that sounds fine regardless. That said @jru any idea what the actual exception. I can't see why it results in a 500 error?

[lgxbslgx]

@sbrannen @rstoyanchev It may be a exception caused by @RequestParam(required = false) Boolean flush. The default value of flush is null so that the expression if (flush) produces a NullPointerException during the Autoboxing and autounboxing in Java. So I don't think it is a bug in spring-framework.

@jru you can use any of the fellow methods to resolve your problem.

1. Use curl -vv http://localhost:8080/api/demo?flush=false instead of curl -vv http://localhost:8080/api/demo
2. Use boolean flush instead of Boolean flush
3. Use if (flush != null && flush) instead of if (flush)

[jru]

@lgxbslgx I think you are right. My bad! However, when I found this problem in a different application I got a 404 when no data was flushed, so there is still something fishy going on.

Let me try to fix the repro to show that problem!

[jru]

So, after trying for a while I am unable to reproduce outside of the application.. :(

What I did is crank up the logging to DEBUG level and run the endpoint with and without flushing. Here you can see the relevant output for both of them: https://gist.github.com/jru/927a6b18a5f81b9a4e609cb8956651d4

One of the differences I can see is that with flushing, there is an INCLUDE that returns 200:

2019-04-18 13:48:15.565 DEBUG 17980 --- [nio-8081-exec-5] s.w.s.m.m.a.RequestMappingHandlerAdapter : Resume with async result []
2019-04-18 13:48:15.565 DEBUG 17980 --- [nio-8081-exec-5] o.s.w.s.v.ContentNegotiatingViewResolver : View remains unresolved given [text/xml]
2019-04-18 13:48:15.565 DEBUG 17980 --- [nio-8081-exec-5] o.s.w.servlet.view.InternalResourceView  : View name 'api/v1/endpoint', model {}
2019-04-18 13:48:15.565 DEBUG 17980 --- [nio-8081-exec-5] o.s.w.servlet.view.InternalResourceView  : Including [api/v1/endpoint]
2019-04-18 13:48:15.565 DEBUG 17980 --- [nio-8081-exec-5] o.s.web.servlet.DispatcherServlet        : "INCLUDE" dispatch for GET "/api/v1/endpoint?param1=756225&param2=756230", parameters={masked}
2019-04-18 13:48:15.565 DEBUG 17980 --- [nio-8081-exec-5] pertySourcedRequestMappingHandlerMapping : looking up handler for path: /api/v1/endpoint
2019-04-18 13:48:15.565 DEBUG 17980 --- [nio-8081-exec-5] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/", "/"]
2019-04-18 13:48:15.575 DEBUG 17980 --- [nio-8081-exec-5] o.s.w.s.r.ResourceHttpRequestHandler     : Resource not found
2019-04-18 13:48:15.575 DEBUG 17980 --- [nio-8081-exec-5] o.s.web.servlet.DispatcherServlet : Exiting from "INCLUDE" dispatch, status 200

Whereas without, there is a FORWARD that gets a 404 (whatever that means):

2019-04-18 13:33:30.668 DEBUG 16680 --- [nio-8081-exec-2] s.w.s.m.m.a.RequestMappingHandlerAdapter : Resume with async result []
2019-04-18 13:33:30.678 DEBUG 16680 --- [nio-8081-exec-2] o.s.w.s.v.ContentNegotiatingViewResolver : View remains unresolved given [text/xml]
2019-04-18 13:33:30.688 DEBUG 16680 --- [nio-8081-exec-2] o.s.w.servlet.view.InternalResourceView  : View name 'api/v1/endpoint', model {}
2019-04-18 13:33:30.688 DEBUG 16680 --- [nio-8081-exec-2] o.s.w.servlet.view.InternalResourceView  : Forwarding to [api/v1/endpoint]
2019-04-18 13:33:30.688 DEBUG 16680 --- [nio-8081-exec-2] o.s.web.servlet.DispatcherServlet        : "FORWARD" dispatch for GET "/api/v1/endpoint?param1=756225&param2=756230", parameters={masked}
2019-04-18 13:33:30.688 DEBUG 16680 --- [nio-8081-exec-2] pertySourcedRequestMappingHandlerMapping : looking up handler for path: /api/v1/endpoint
2019-04-18 13:33:30.688 DEBUG 16680 --- [nio-8081-exec-2] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler ["classpath:/META-INF/resources/", "classpath:/resources/", "classpath:/static/", "classpath:/public/", "/"]
2019-04-18 13:33:30.688 DEBUG 16680 --- [nio-8081-exec-2] o.s.w.s.r.ResourceHttpRequestHandler     : Resource not found
2019-04-18 13:33:30.688 DEBUG 16680 --- [nio-8081-exec-2] o.s.web.servlet.DispatcherServlet : Exiting from "FORWARD" dispatch, status 404

I hope this can help, and sorry for the mess up with the repro!

If I should edit it to better reflect what the problem is, please let me know.

[sbrannen]

@lgxbslgx, good catch with the null Boolean value! 👍

---

@sbrannen that sounds fine regardless.

@rstoyanchev, shall I go ahead and do that for 5.1.x (and master) and backport it to 5.0.x as well?

[rstoyanchev]

@jru the flush commits the response and the status cannot change after that. Hence the 200.

@sbrannen I've applied the change to 5.1.x. As it is an improvement there is no need to backport to 5.0.x I think.

[bbecker-te]

We see a change in behavior now that we are using spring-web 5.2.3 that might be related to this change. We have a streaming endpoint that returns WebAsyncTask. We do a flush to send back an initial header row (with http200 response). Then if an Exception occurs while processing and streaming back other rows we would like to return 500. We used to return 500, but now we return 200 after the error and when the connection is closed. Could it be related?

[bclozel]

@bbecker-te this change is merely flushing the response once it's been written to it, and it's applied for streaming response bodies.

I'm not sure I understand what you're saying:

• you're doing an initial flush to send the 200 OK status
• then an exception happens while processing the request
• you expect to send an 500 status after that

I don't know if this was working previously, but this goes against the HTTP response contract: once the response is committed the response status might have been written to the network (in this case this is triggered by the manual flush), so there's no way to change it back. Closing the connection is the only course of action at that point.

If I'm missing something here, please create a new issue with a repro project showing the problem. Thanks!

[bbecker-te]

I didn't realized that calling flush on the OutputStreamWriter that wraps the CoyotyOutputStream would have the effect of committing the response. It seems like we can get results streamed over the connection without calling flush for every piece of data, so now I just call flush at the very end. If an error happens before that, then we will get a 500.