Repository: caddyserver/caddy (language: go)

Issue:
Feature request: Log request size
This may of course be a naive request, given streaming may make it more difficult than is obvious. I'd love to be able to log size (in bytes, like the response size) of incoming requests, and I don't see that in the access log JSON object.

e.g.
1) Client POSTS to /foo/bar with a few fields (say, 1600 bytes total).
2) "size": 1600 is included in the "request" key of the access log JSON object.

The motivation for this is to simplify debugging when I believe a client is sending a body that doesn't match its Content-Length header, so we can rule out our beloved reverse proxy causing the issue :)

Thanks!


Discussion / hints:
Based on my read (and my results in testing), that's the response size.


On Tue, Dec 28, 2021 at 8:58 AM Conor Evans ***@***.***>
wrote:

> I had a look at this -- is this feature not already in place?
> https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/server.go#L196
> .
>
> caddy run
>
> 2021/12/28 17:04:42.213 ←[34mINFO←[0m   using adjacent Caddyfile
>
> ...
>
> 2021/12/28 17:04:42.242 ←[34mINFO←[0m   serving initial configuration
>
> 2021/12/28 17:04:50.598 ←[34mINFO←[0m   http.log.access.log0    handled request {"request": {"remote_ip": "::1", "remote_port": "54405", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:2015", "uri": "/", "headers": {"User-Agent": ["curl/7.55.1"], "Accept": ["*/*"]}}, "user_id": "", "duration": 0.0007042, "size": 13, "status": 200, "resp_headers": {"Server": ["Caddy"], "Content-Type": []}}
>
> Is shouldLogRequest() false in your context?
> https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/server.go#L473
>
> —
> Reply to this email directly, view it on GitHub
> <https://github.com/caddyserver/caddy/issues/4494#issuecomment-1002197209>,
> or unsubscribe
> <https://github.com/notifications/unsubscribe-auth/AAC2L57WSPRUYXYCBBSQLWTUTHUE5ANCNFSM5KTR256A>
> .
> Triage notifications on the go with GitHub Mobile for iOS
> <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675>
> or Android
> <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.
>
> You are receiving this because you authored the thread.Message ID:
> ***@***.***>
>

You're right that streaming makes it trickier.

We might be able to wrap the request reader to count the amount of bytes read and store the total in the request context.

That would mean that the request size might be zero if the request body is ignored or not read, depending on how the request is handled.

Here's an example of how it would look: https://stackoverflow.com/a/53402924
yep @obrienmd realized that a moment too late 😅 (I removed my comment)

Wrapping the request's body's reader with something that counts is probably the way to go about it. Similar to how we set the request body here: https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/requestbody/requestbody.go.
Hello,

I'm sorry to bump this ticket, but is there a recommended workaround while this feature gets written? 

The logs currently do expose a "size" and "res_headers.content-length" keys but, in my tests, both of them do always return the same values, which is the response size and not the request size.

The Prometheus metrics do expose a [caddy_http_request_size_bytes](https://caddyserver.com/docs/metrics#caddy-http-request-size-bytes), so it is somehow possible to get that information, but I would prefer not to manage a Prometheus instance. And pushing that metric to another metrics system (like Cloudwatch) do not help since it's an histogram metric and is not really usable elsewhere than Prometheus/Grafana, as far as I can tell (and, finally, those metrics are "server wide" while having the request size printed in the logs would allow a finer granularity).

Is there already a plugin that could help with that?

I can ask that question on the forum if it would be more suited.

cc @mholt @francislavoie
@simon-lejeune The prometheus metric is taking an "educated guess" at the request size by trusting the Content-Length and adding an approximate count of bytes based on headers. Is an estimation good enough for you? Even if the Content-Length header set by the client is an outright lie?

FWIW, the logs already do write the request's Content-Length header... can you use that?
@mholt thank you a lot for the quick answer.

I indeed somehow missed the "request.content-length" key, sorry about that. I think I can work with that while caddy implements a more trustable equivalent of nginx's `$request_length`, thank you.

On that topic, do you think it's doable in a Caddy plugin? By mixing the current Prometheus [educated guess implementation](https://github.com/caddyserver/caddy/blob/d35f618b10e9f530b068f42d1dcecb9e70b6ae0a/modules/caddyhttp/metrics.go#L156) with `io.Copy` on the request's body and finally adding the sum of all of that in a new key in default json logger? This implementation would have a performance cost obviously (especially versus your idea [here](https://github.com/caddyserver/caddy/issues/4494#issuecomment-1002231228)), but maybe could work as a stop gap while Caddy bundles that option, and is also an interesting exercice.
@simon-lejeune Absolutely can be done in a plugin, as all of Caddy's features are plugins too :)

It won't be able to change Caddy's access logs, but you can emit your own log from the plugin!
@mholt great, thank you for those insights
Can I work on this issue?
Yep! PRs welcome.

Fix patch:
diff --git a/modules/caddyhttp/server.go b/modules/caddyhttp/server.go
index eb618067ff4..82fdbe5eb1d 100644
--- a/modules/caddyhttp/server.go
+++ b/modules/caddyhttp/server.go
@@ -19,6 +19,7 @@ import (
 	"crypto/tls"
 	"encoding/json"
 	"fmt"
+	"io"
 	"net"
 	"net/http"
 	"net/netip"
@@ -259,6 +260,14 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		wrec := NewResponseRecorder(w, nil, nil)
 		w = wrec
 
+		// wrap the request body in a LengthReader
+		// so we can track the number of bytes read from it
+		var bodyReader *lengthReader
+		if r.Body != nil {
+			bodyReader = &lengthReader{Source: r.Body}
+			r.Body = bodyReader
+		}
+
 		// capture the original version of the request
 		accLog := s.accessLogger.With(loggableReq)
 
@@ -285,7 +294,13 @@ func (s *Server) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 
 			userID, _ := repl.GetString("http.auth.user.id")
 
+			reqBodyLength := 0
+			if bodyReader != nil {
+				reqBodyLength = bodyReader.Length
+			}
+
 			log("handled request",
+				zap.Int("bytes_read", reqBodyLength),
 				zap.String("user_id", userID),
 				zap.Duration("duration", duration),
 				zap.Int("size", wrec.Size()),
@@ -826,6 +841,23 @@ func cloneURL(from, to *url.URL) {
 	}
 }
 
+// lengthReader is an io.ReadCloser that keeps track of the
+// number of bytes read from the request body.
+type lengthReader struct {
+	Source io.ReadCloser
+	Length int
+}
+
+func (r *lengthReader) Read(b []byte) (int, error) {
+	n, err := r.Source.Read(b)
+	r.Length += n
+	return n, err
+}
+
+func (r *lengthReader) Close() error {
+	return r.Source.Close()
+}
+
 // Context keys for HTTP request context values.
 const (
 	// For referencing the server instance


Test patch: