server/requestlog: request logging unconditionally consumes entire body

[zombiezen]

Offending lines:

go-cloud/server/requestlog/requestlog.go

Lines 84 to 88 in 012388a

	if rcc.err == nil && rcc.r != nil && !w2.hijacked {
	// If the handler hasn't encountered an error in the Body (like EOF),
	// then consume the rest of the Body to provide an accurate rcc.n.
	io.Copy(ioutil.Discard, rcc)
	}

For servers that take in large requests, especially those that rely on HTTP 100 Continue to bail early, this can cause a request to be stalled for much longer than necessary to reject a request.

[vangent]

Looks like this was done on purpose...?

go-cloud/server/requestlog/requestlog.go

Line 55 in 012388a

// ServeHTTP will always consume the request body up to the first error,

also refers to this behavior.

Based on the comments, the tradeoff is incorrect request size being logged?

[zombiezen]

It was the intent I had when writing the requestlog package, but I think the intent was misguided. This behavior causes a client to be able to DoS a server because there is no upper bound on how many bytes are consumed from the client. The wrapped handler can't even reject the request because this middleware will wait to write the error status code until after the request body has been consumed.

For context, *http.Server has an upper bound of ~200K that it will read past the end of what the Handler reads: https://github.com/golang/go/blob/go1.15/src/net/http/transfer.go#L975

I think the behavior should be (in order of preference):

1. If the request sends a Content-Length header, use that. RFC 7230 specifies that receiving less bytes is an error and net/http.Server will never read more than Content-Length if set: https://github.com/golang/go/blob/go1.15/src/net/http/transfer.go#L555
2. If the handler consumes the entire request body (i.e. Request.Body returns an io.EOF error), then use the number of bytes read from the body as the length.
3. If the wrapped handler has called Read on the body, read up to a fixed amount of bytes (probably up to the same limit as in net/http) to try to find io.EOF. If it encounters an error, use the number of bytes read from the body as the length. I feel okay in doing this because in worst case, this would hit the read timeout.
4. Otherwise, the handler did not expect a request body. Don't read any bytes, since this could trigger an HTTP 100 Continue. Use 0 as the length.

I believe this represents the best compromise between giving an accurate request body size, not creating a DoS vector, and not altering the behavior of a handler that uses HTTP 100 Continue. WDYT?

P.S. I am motivated to send a PR to fix this, as this affects a service I'm building. As a workaround, we can disable request logging, but I'd prefer not to.

[vangent]

SGTM. A minor alternative change would be to drop #3 by always using the # of bytes read by the handler (as in #2) if it ready any. This seems easier to document/understand to me, and it's not like "try to read some more" makes it more accurate.