caddyhttp: Trace individual middleware handlers (#6313)

* caddyhttp: Trace individual middleware handlers

* Fix typo

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

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

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

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)
 		})
 	}

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,