caddy: Exceeding `request_body`'s `max_size` causes unexpected rejection behavior

I verified that 3d616e8c6d65e5617f5a918d72fb1514c9c7144e will now return HTTP 413 from Read() if too many bytes are read. I also improved error wrapping generally.

Digging into this a bit deeper again. I tried out my suggested handle_errors approach. It won’t really work, because how MaxBytesReader works is that it will stop reading from the client, and attempt to write a response, then close the connection. Since most clients won’t stop writing their request until they’re done, they’ll never see the response before the connection is closed.

So even if we could change the response code, the client would never see it. Quick google search shows that’s intended and the only way it can actually work to stop receiving data from the client. See https://stackoverflow.com/questions/35173819/request-body-too-large-causing-connection-reset-in-go for example.

This is how I tested it:

Caddyfile:

{
	admin off
	debug
}

:8881 {
	request_body {
		max_size 1kb
	}

	log

	reverse_proxy localhost:8882

	handle_errors {
		respond "{http.error.message}" 413
	}
}

:8882 {
	log
	respond {http.request.body}
}

Send a curl request with a big file, see the result of a closed connection:

$ curl -v --data-binary "@bigfile.txt" http://localhost:8881
* Rebuilt URL to: http://localhost:8881/
*   Trying ::1...
* TCP_NODELAY set
* Connected to localhost (::1) port 8881 (#0)
> POST / HTTP/1.1
> Host: localhost:8881
> User-Agent: curl/7.55.1
> Accept: */*
> Content-Length: 47120384
> Content-Type: application/x-www-form-urlencoded
> Expect: 100-continue
>
< HTTP/1.1 100 Continue
* Send failure: Connection was reset
* Closing connection 0
curl: (55) Send failure: Connection was reset

In Caddy’s logs:

2022/02/04 14:12:42.403 INFO    http.log.access handled request {"request": {"remote_ip": "::1", "remote_port": "50207", "proto": "HTTP/1.1", "method": "POST", "host": "localhost:8881", "uri": "/", "headers": {"User-Agent": ["curl/7.55.1"], "Content-Length": ["47120384"], "Accept": ["*/*"], "Expect": ["100-continue"], "X-Forwarded-For": ["::1"], "Accept-Encoding": ["gzip"], "Content-Type": ["application/x-www-form-urlencoded"], "X-Forwarded-Proto": ["http"]}}, "user_id": "", "duration": 0.011588, "size": 0, "status": 200, "resp_headers": {"Server": ["Caddy"], "Content-Type": []}}
2022/02/04 14:12:42.403 DEBUG   http.handlers.reverse_proxy     upstream roundtrip      {"upstream": "localhost:8882", "duration": 0.0129982, "request": {"remote_ip": "::1", "remote_port": "50206", "proto": "HTTP/1.1", "method": "POST", "host": "localhost:8881", "uri": "/", "headers": {"X-Forwarded-Proto": ["http"], "X-Forwarded-For": ["::1"], "User-Agent": ["curl/7.55.1"], "Accept": ["*/*"], "Content-Length": ["47120384"], "Content-Type": ["application/x-www-form-urlencoded"], "Expect": ["100-continue"]}}, "error": "readfrom tcp [::1]:50207->[::1]:8882: http: request body too large"}
2022/02/04 14:12:42.404 ERROR   http.log.error  readfrom tcp [::1]:50207->[::1]:8882: http: request body too large      {"request": {"remote_ip": "::1", "remote_port": "50206", "proto": "HTTP/1.1", "method": "POST", "host": "localhost:8881", "uri": "/", "headers": {"User-Agent": ["curl/7.55.1"], "Accept": ["*/*"], "Content-Length": ["47120384"], "Content-Type": ["application/x-www-form-urlencoded"], "Expect": ["100-continue"]}}, "duration": 0.0129982, "status": 502, "err_id": "c7i5rsed9", "err_trace": "reverseproxy.statusError (reverseproxy.go:893)"}
2022/02/04 14:12:42.404 ERROR   http.log.access handled request {"request": {"remote_ip": "::1", "remote_port": "50206", "proto": "HTTP/1.1", "method": "POST", "host": "localhost:8881", "uri": "/", "headers": {"User-Agent": ["curl/7.55.1"], "Accept": ["*/*"], "Content-Length": ["47120384"], "Content-Type": ["application/x-www-form-urlencoded"], "Expect": ["100-continue"]}}, "user_id": "", "duration": 0.0129982, "size": 20, "status": 413, "resp_headers": {"Server": ["Caddy"], "Content-Type": []}}

First line is the :8882 server receiving the request (access logs happen after the request is completed, upstream finishes before the proxy does), second line is the :8881 proxy performing the roundtrip (and logging how long it took), third line is the error being logged by the :8881 HTTP server before passing it onto the handle_errors routes, and the last line is the access log from :8881 showing the final request and “response”.

Notice that the last log line does show that Caddy attempts to write status 413 as per handle_errors but the client never sees it.

---

I think all that we can really do is flesh out the docs on https://caddyserver.com/docs/caddyfile/directives/request_body to better explain how it will behave, clarifying that the client connection will be closed if too many bytes are tried to be read from the request.

Ah, sorry, I misunderstood this issue. I do think this could be handled better in the code though too. Maybe we can somehow wrap the returned error from MaxBytesReader with one of our structured errors that adds status code.

@mholt we already do this https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/requestbody/requestbody.go

The code in the v1 branch is a copy of the stdlib, but I don’t think it actually works correctly because res.requestTooLarge() can’t be called outside of stdlib, cause it’s not exported. Pretty sure, anyways.

Digging into the code a bit more, it’s not possible to yoink out the code from stdlib since it uses private/unexported functions to manipulate the HTTP response state.

There is an open issue https://github.com/golang/go/issues/30715 which is relevant here, if it were implemented (which it seems it will be, the proposal was accepted), we could add a check for this specific error to write a specific status code.

So I’ll keep this issue open and mark it as a feature request that requires an upstream change.

In the meantime, I’ll handle the request size limit in the app.

Have you tried my suggestion of handling it with handle_errors? Wouldn’t that be easier?

Would the wrapper enhancement use Content-Length to discern size or a superior approach hopefully?

No, that’s not a reliable way to do it. Clients (bad actors) can lie and send an invalid Content-Length. The right way is to actually prevent reading past a certain limit.

Ah, okay I understand what’s going on then. So since it’s a reader wrapper, basically the thing that invokes reading the request body is what will receive the error. So the reverse_proxy module is what reads the body so that it can copy it to the upstream, but it encounters that error. And I think that reverse_proxy code assumes it’s a problem with the upstream when it gets any kind of error, and writes a 502.

I don’t think we can really do much about this unless we either get the Go stdlib to change the error it emits to something we can do a type assertion on to change the response code, or we re-implement the wrapper in Caddy itself to do that. It’s a really simple wrapper, so we could just do that. 🤷‍♂️

That’s what’s reported in the browser console. I’ll investigate further.

Please do. What’s in Caddy’s logs? Turn on the debug global option to get more details. Turn on the log directive in your site to enable access logging.

Is the expected behavior to return 413?

No, there’s no “expected behaviour”, really. Like I said, there is no specific HTTP status code attached to MaxBytesReader, it just emits an Golang error, which you can then do whatever you like with in handle_errors.

Hmm. Do you have evidence in your logs that that’s the response code it writes? I’m not convinced that Caddy itself sends 502.

Basically, request_body max_size is using Golang’s built-in MaxBytesReader wrapper, which apparently just returns an error errors.New("http: request body too large").

Caddy is not specifically handling this error (and it’s kinda tricky to because it would involve a string comparison to check it, because it’s not a specific error type), so it’ll just trigger Caddy’s default error handling behaviour. You can use handle_errors to customize what you do with it, if you want. You can use the expression matcher to match against the error having that message with the {http.error.message} placeholder. Maybe something like this:

handle_errors {
	@tooLarge expression `{http.error.message} == "http: request body too large"`
	handle @tooLarge {
		respond "Payload too large" 413
	}
}