Query frontend slow log warning: invalid Read on closed Body

[yeya24]

We are seeing a lot of warnings in the Thanos Query frontend slow log http: invalid Read on closed Body. Since it uses Cortex Query frontend as a library, I tested the Cortex one and it has the same problem.

The warning occurs when it logs a POST request. It doesn't affect anything but it is annoying.

level=warn ts=2020-08-31T15:01:31.642718692Z caller=frontend.go:198 org_id=fake traceID=f8ac3a930226002 msg="unable to parse form for request" err="http: invalid Read on closed Body"
level=info ts=2020-08-31T15:01:31.6427589Z caller=frontend.go:206 org_id=fake traceID=f8ac3a930226002 msg="slow query detected" method=POST host= path=/api/v1/query time_taken=1m3.598993508s
level=warn ts=2020-08-31T15:02:16.45874421Z caller=frontend.go:198 org_id=fake traceID=653a2ed25929e383 msg="unable to parse form for request" err="http: invalid Read on closed Body"
level=info ts=2020-08-31T15:02:16.458782837Z caller=frontend.go:206 org_id=fake traceID=653a2ed25929e383 msg="slow query detected" method=POST host= path=/api/v1/query time_taken=44.715073818s
level=warn ts=2020-08-31T15:02:28.766424824Z caller=frontend.go:198 org_id=fake traceID=2382a13b1e6ef89 msg="unable to parse form for request" err="http: invalid Read on closed Body"
level=info ts=2020-08-31T15:02:28.766461552Z caller=frontend.go:206 org_id=fake traceID=2382a13b1e6ef89 msg="slow query detected" method=POST host= path=/api/v1/query time_taken=12.206554463s

[pracucci]

Does it happen when a query request gets canceled?

[yeya24]

@pracucci I think no. The requests are not canceled.

What I found today is:

1. This only happens for a POST request directly going to downstream URL. So query_range API is not affected.

2. The request body is closed during https://github.com/cortexproject/cortex/blob/master/pkg/querier/frontend/frontend.go#L127

[melkorm]

I did a little investigation and perhaps this works like this:

We hit this condition:

cortex/pkg/querier/frontend/frontend.go

Line 187 in 0a33f9d

if err != nil {

and we write to the response later in the code

cortex/pkg/querier/frontend/frontend.go

Line 224 in 012fc0b

func writeError(w http.ResponseWriter, err error) {

but the Go docs say:
https://golang.org/pkg/net/http/#ResponseWriter

    // Write writes the data to the connection as part of an HTTP reply.
    //
    // If WriteHeader has not yet been called, Write calls
    // WriteHeader(http.StatusOK) before writing the data. If the Header
    // does not contain a Content-Type line, Write adds a Content-Type set
    // to the result of passing the initial 512 bytes of written data to
    // DetectContentType. Additionally, if the total size of all written
    // data is under a few KB and there are no Flush calls, the
    // Content-Length header is added automatically.
    //
    // Depending on the HTTP protocol version and the client, calling
    // Write or WriteHeader may prevent future reads on the
    // Request.Body. For HTTP/1.x requests, handlers should read any
    // needed request body data before writing the response. Once the
    // headers have been flushed (due to either an explicit Flusher.Flush
    // call or writing enough data to trigger a flush), the request body
    // may be unavailable. For HTTP/2 requests, the Go HTTP server permits
    // handlers to continue to read the request body while concurrently
    // writing the response. However, such behavior may not be supported
    // by all HTTP/2 clients. Handlers should read before writing if
    // possible to maximize compatibility.
    Write([]byte) (int, error)

and we actually try to read body later on when trying to analyse form data:

cortex/pkg/querier/frontend/frontend.go

Line 210 in 0a33f9d

err = r.ParseForm()

probably one should skip form parsing when we hit request error.

PS. Hope I didn't mix things - I am new to this code 🙈

[yeya24]

@melkorm Thanks for the investigation. But my case seems different. It doesn't have this error

cortex/pkg/querier/frontend/frontend.go

Line 187 in 0a33f9d

if err != nil {

[melkorm]

@yeya24 I just noticed that we write to http.ResponseWriter here

cortex/pkg/querier/frontend/frontend.go

Line 194 in 0a33f9d

w.WriteHeader(resp.StatusCode)

so perhaps we run in a case when we shouldn't read body later on.

Edit:
Overall I think we should report slow requests in the beginning and only later write to http.ResponseWriter which should eliminate this behaviour

Edit 2:
I was able to reproduce this in tests, trying to simplify test to the minimum to see what actually causes it.
As for now my previous findings are extended with what actually causes closed body (flush on ResponseWriter) and to detect it you need larger payload to force Flush. Cooking PR in progress 🧑‍🍳

Edit 3:
Alright it was harder than I thought 😪
For some reason Cortex RoundTripper doesn't always close request body or it is converted to ioutil.NopCloser so form parsing doesn't complain but fails silently and doesn't return any form values.
The issue is visible when setting downstream endpoint as only then Body is actually closed and warning pops up about accessing closed reader.
Overall fix is to read request body, parse form and then assign back the body to the request which allows us to report form values, overall I would think how much logging form values is required as it makes the code more complex.

Anyway, pushing the PR now and see where it goes 😄

PS. Testing downstream scenarios with require.NoError(t, err) gave me huge headaches as it was deadlocking :( Switched to assert for now as I couldn't find why it happens. You can test it setting 201 http code here https://github.com/cortexproject/cortex/blob/v1.3.0/pkg/querier/frontend/frontend_test.go#L154