Repository: caddyserver/caddy (language: go)

Issue:
Include `http.request.uuid` field in access logs?
I have a reverse proxy setup and I'm trying to 'link' access logs to upstream server events. What I've got so far is the following Caddy file:

```nginx
localhost {
	reverse_proxy {
		to https://localhost:5000
		header_up X-Request-Id "{http.request.uuid}"
		transport http {
			tls
			tls_insecure_skip_verify
			read_buffer 8192
		}
	}
	log {
		level info
		# somehow include an additional field {..., requestId: "{http.request.uuid}"} in the log?
	}
}
```

The HTTP server at `https://localhost:5000` can read the incoming `X-Request-Id` header just fine. But how can I  write the same request ID to the access log to link them together (for deeper analysis in case of upstream server errors)?

Perhaps someone knows a work-around for this issue?


Discussion / hints:
We don't actually generate the UUID until the placeholder is used, however, so if we add it to the logs, it would always be generated. (Not that that's bad... it just brings us ever closer to that meteor strike. ... jk)

The access logs are designed to show the requests as the client sent them, but I suppose it would make sense to add that UUID if we have it. Since the log line is deferred to after the request, maybe we can add it. I'll play with this in a bit.
We do add `traceID` as per OpenTracing when tracing is enabled, so there is precedent:

https://github.com/caddyserver/caddy/blob/master/modules/caddyhttp/tracing/tracer.go#L90-L92
A workaround I found is to copy the header sent by Caddy at the upstream as a response header (it shows up in Caddy's logs at `request.resp_headers`), but then there's no point in getting the ID from Caddy since it has to go through the upstream server and back, so might as well just generate it there.

This does make the request ID also visible to the client but IMO that's often not an issue and could even be useful for error reports if exposed to the user.

Fix patch:
diff --git a/caddyconfig/httpcaddyfile/shorthands.go b/caddyconfig/httpcaddyfile/shorthands.go
index 102bc36d627..75795ae61ee 100644
--- a/caddyconfig/httpcaddyfile/shorthands.go
+++ b/caddyconfig/httpcaddyfile/shorthands.go
@@ -64,6 +64,7 @@ func placeholderShorthands() []string {
 		"{remote_port}", "{http.request.remote.port}",
 		"{scheme}", "{http.request.scheme}",
 		"{uri}", "{http.request.uri}",
+		"{uuid}", "{http.request.uuid}",
 		"{tls_cipher}", "{http.request.tls.cipher_suite}",
 		"{tls_version}", "{http.request.tls.version}",
 		"{tls_client_fingerprint}", "{http.request.tls.client.fingerprint}",
diff --git a/modules/caddyhttp/logging.go b/modules/caddyhttp/logging.go
index 8ecc49a63db..728befd2bc2 100644
--- a/modules/caddyhttp/logging.go
+++ b/modules/caddyhttp/logging.go
@@ -151,6 +151,18 @@ func (e *ExtraLogFields) Add(field zap.Field) {
 	e.fields = append(e.fields, field)
 }
 
+// Set sets a field in the list of extra fields to log.
+// If the field already exists, it is replaced.
+func (e *ExtraLogFields) Set(field zap.Field) {
+	for i := range e.fields {
+		if e.fields[i].Key == field.Key {
+			e.fields[i] = field
+			return
+		}
+	}
+	e.fields = append(e.fields, field)
+}
+
 const (
 	// Variable name used to indicate that this request
 	// should be omitted from the access logs
diff --git a/modules/caddyhttp/replacer.go b/modules/caddyhttp/replacer.go
index f6b042ce5d6..ef5084e3a40 100644
--- a/modules/caddyhttp/replacer.go
+++ b/modules/caddyhttp/replacer.go
@@ -40,6 +40,7 @@ import (
 	"time"
 
 	"github.com/google/uuid"
+	"go.uber.org/zap"
 
 	"github.com/caddyserver/caddy/v2"
 	"github.com/caddyserver/caddy/v2/modules/caddytls"
@@ -157,9 +158,17 @@ func addHTTPVarsToReplacer(repl *caddy.Replacer, req *http.Request, w http.Respo
 			case "http.request.duration_ms":
 				start := GetVar(req.Context(), "start_time").(time.Time)
 				return time.Since(start).Seconds() * 1e3, true // multiply seconds to preserve decimal (see #4666)
+
 			case "http.request.uuid":
+				// fetch the UUID for this request
 				id := GetVar(req.Context(), "uuid").(*requestID)
+
+				// set it to this request's access log
+				extra := req.Context().Value(ExtraLogFieldsCtxKey).(*ExtraLogFields)
+				extra.Set(zap.String("uuid", id.String()))
+
 				return id.String(), true
+
 			case "http.request.body":
 				if req.Body == nil {
 					return "", true


Test patch: