caddyhttp: Trace individual middleware handlers

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,