From 9ba999141b5ca5adaf45893992f4889629f77a9d Mon Sep 17 00:00:00 2001
From: Matt Holt <mholt@users.noreply.github.com>
Date: Sat, 18 May 2024 14:48:42 -0600
Subject: [PATCH] caddyhttp: Trace individual middleware handlers (#6313)
* caddyhttp: Trace individual middleware handlers
* Fix typo
---
caddyconfig/httpcaddyfile/serveroptions.go | 46 ++++++----------------
modules/caddyhttp/app.go | 3 ++
modules/caddyhttp/logging.go | 11 ++++++
modules/caddyhttp/routes.go | 6 ++-
modules/caddyhttp/server.go | 10 +++++
5 files changed, 41 insertions(+), 35 deletions(-)
diff --git a/caddyconfig/httpcaddyfile/serveroptions.go b/caddyconfig/httpcaddyfile/serveroptions.go
index 18f14996c..4246cd7dc 100644
--- a/caddyconfig/httpcaddyfile/serveroptions.go
+++ b/caddyconfig/httpcaddyfile/serveroptions.go
@@ -50,6 +50,7 @@ type serverOptions struct {
ClientIPHeaders []string
ShouldLogCredentials bool
Metrics *caddyhttp.Metrics
+ Trace bool // TODO: EXPERIMENTAL
}
func unmarshalCaddyfileServerOptions(d *caddyfile.Dispenser) (any, error) {
@@ -246,39 +247,11 @@ func unmarshalCaddyfileServerOptions(d *caddyfile.Dispenser) (any, error) {
}
serverOpts.Metrics = new(caddyhttp.Metrics)
- // TODO: DEPRECATED. (August 2022)
- case "protocol":
- caddy.Log().Named("caddyfile").Warn("DEPRECATED: protocol sub-option will be removed soon")
-
- for nesting := d.Nesting(); d.NextBlock(nesting); {
- switch d.Val() {
- case "allow_h2c":
- caddy.Log().Named("caddyfile").Warn("DEPRECATED: allow_h2c will be removed soon; use protocols option instead")
-
- if d.NextArg() {
- return nil, d.ArgErr()
- }
- if sliceContains(serverOpts.Protocols, "h2c") {
- return nil, d.Errf("protocol h2c already specified")
- }
- serverOpts.Protocols = append(serverOpts.Protocols, "h2c")
-
- case "strict_sni_host":
- caddy.Log().Named("caddyfile").Warn("DEPRECATED: protocol > strict_sni_host in this position will be removed soon; move up to the servers block instead")
-
- if d.NextArg() && d.Val() != "insecure_off" && d.Val() != "on" {
- return nil, d.Errf("strict_sni_host only supports 'on' or 'insecure_off', got '%s'", d.Val())
- }
- boolVal := true
- if d.Val() == "insecure_off" {
- boolVal = false
- }
- serverOpts.StrictSNIHost = &boolVal
-
- default:
- return nil, d.Errf("unrecognized protocol option '%s'", d.Val())
- }
+ case "trace":
+ if d.NextArg() {
+ return nil, d.ArgErr()
}
+ serverOpts.Trace = true
default:
return nil, d.Errf("unrecognized servers option '%s'", d.Val())
@@ -351,10 +324,17 @@ func applyServerOptions(
server.Metrics = opts.Metrics
if opts.ShouldLogCredentials {
if server.Logs == nil {
- server.Logs = &caddyhttp.ServerLogConfig{}
+ server.Logs = new(caddyhttp.ServerLogConfig)
}
server.Logs.ShouldLogCredentials = opts.ShouldLogCredentials
}
+ if opts.Trace {
+ // TODO: THIS IS EXPERIMENTAL (MAY 2024)
+ if server.Logs == nil {
+ server.Logs = new(caddyhttp.ServerLogConfig)
+ }
+ server.Logs.Trace = opts.Trace
+ }
if opts.Name != "" {
nameReplacements[key] = opts.Name
diff --git a/modules/caddyhttp/app.go b/modules/caddyhttp/app.go
index 4df8689a5..5dbecf9b2 100644
--- a/modules/caddyhttp/app.go
+++ b/modules/caddyhttp/app.go
@@ -198,6 +198,9 @@ func (app *App) Provision(ctx caddy.Context) error {
// only enable access logs if configured
if srv.Logs != nil {
srv.accessLogger = app.logger.Named("log.access")
+ if srv.Logs.Trace {
+ srv.traceLogger = app.logger.Named("log.trace")
+ }
}
// the Go standard library does not let us serve only HTTP/2 using
diff --git a/modules/caddyhttp/logging.go b/modules/caddyhttp/logging.go
index 1fab1e8e8..823763e91 100644
--- a/modules/caddyhttp/logging.go
+++ b/modules/caddyhttp/logging.go
@@ -65,6 +65,17 @@ type ServerLogConfig struct {
// and this includes some request and response headers, i.e `Cookie`,
// `Set-Cookie`, `Authorization`, and `Proxy-Authorization`.
ShouldLogCredentials bool `json:"should_log_credentials,omitempty"`
+
+ // Log each individual handler that is invoked.
+ // Requires that the log emit at DEBUG level.
+ //
+ // NOTE: This may log the configuration of your
+ // HTTP handler modules; do not enable this in
+ // insecure contexts when there is sensitive
+ // data in the configuration.
+ //
+ // EXPERIMENTAL: Subject to change or removal.
+ Trace bool `json:"trace,omitempty"`
}
// wrapLogger wraps logger in one or more logger named
diff --git a/modules/caddyhttp/routes.go b/modules/caddyhttp/routes.go
index 9db4f2520..6f2371495 100644
--- a/modules/caddyhttp/routes.go
+++ b/modules/caddyhttp/routes.go
@@ -326,8 +326,10 @@ func wrapMiddleware(_ caddy.Context, mh MiddlewareHandler, metrics *Metrics) Mid
nextCopy := next
return HandlerFunc(func(w http.ResponseWriter, r *http.Request) error {
- // TODO: This is where request tracing could be implemented
- // TODO: see what the std lib gives us in terms of stack tracing too
+ // EXPERIMENTAL: Trace each module that gets invoked
+ if server, ok := r.Context().Value(ServerCtxKey).(*Server); ok && server != nil {
+ server.logTrace(handlerToUse)
+ }
return handlerToUse.ServeHTTP(w, r, nextCopy)
})
}
diff --git a/modules/caddyhttp/server.go b/modules/caddyhttp/server.go
index 1d621456d..96a819b40 100644
--- a/modules/caddyhttp/server.go
+++ b/modules/caddyhttp/server.go
@@ -234,6 +234,7 @@ type Server struct {
logger *zap.Logger
accessLogger *zap.Logger
errorLogger *zap.Logger
+ traceLogger *zap.Logger
ctx caddy.Context
server *http.Server
@@ -738,6 +739,15 @@ func (s *Server) shouldLogRequest(r *http.Request) bool {
return !s.Logs.SkipUnmappedHosts
}
+// logTrace will log that this middleware handler is being invoked.
+// It emits at DEBUG level.
+func (s *Server) logTrace(mh MiddlewareHandler) {
+ if s.Logs == nil || !s.Logs.Trace {
+ return
+ }
+ s.traceLogger.Debug(caddy.GetModuleName(mh), zap.Any("module", mh))
+}
+
// logRequest logs the request to access logs, unless skipped.
func (s *Server) logRequest(
accLog *zap.Logger, r *http.Request, wrec ResponseRecorder, duration *time.Duration,