caddyhttp: Trace individual middleware handlers

[mholt]

This has been on my mind for years. Just a simple way to see which middleware handlers are being invoked during a request.

Requires DEBUG level logging to be enabled, as well as explicitly opting-in to trace logs. Here is an example global option config along with a sample server in a Caddyfile:

{
	debug
	servers {
		trace
	}
}

:1234 {
	root /asdf
	file_server browse
	encode gzip zstd
	templates
	rewrite /foo /bar
	log
}

Making a simple request using curl -v http://localhost:1234 I get:

2024/05/10 22:32:52.613 DEBUG   http.log.trace  vars    {"module": {"root":"/asdf"}}
2024/05/10 22:32:52.613 DEBUG   http.log.trace  encode  {"module": {"prefer":["gzip","zstd"],"minimum_length":512,"match":{"headers":{"Content-Type":["application/atom+xml*","application/eot*","application/font*","application/geo+json*","application/graphql+json*","application/javascript*","application/json*","application/ld+json*","application/manifest+json*","application/opentype*","application/otf*","application/rss+xml*","application/truetype*","application/ttf*","application/vnd.api+json*","application/vnd.ms-fontobject*","application/wasm*","application/x-httpd-cgi*","application/x-javascript*","application/x-opentype*","application/x-otf*","application/x-perl*","application/x-protobuf*","application/x-ttf*","application/xhtml+xml*","application/xml*","font/*","image/svg+xml*","image/vnd.microsoft.icon*","image/x-icon*","multipart/bag*","multipart/mixed*","text/*"]}}}}
2024/05/10 22:32:52.613 DEBUG   http.log.trace  templates       {"module": {"file_root":"{http.vars.root}","mime_types":["text/html","text/plain","text/markdown"]}}
2024/05/10 22:32:52.613 DEBUG   http.log.trace  file_server     {"module": {"fs":"{http.vars.fs}","root":"{http.vars.root}","hide":["/home/matt/Dev/caddyserver/caddy/cmd/caddy/Caddyfile"],"index_names":["index.html","index.txt"],"browse":{}}}
2024/05/10 22:32:52.613 DEBUG   http.handlers.file_server       sanitized path join     {"site_root": "/asdf", "fs": "", "request_path": "/", "result": "/asdf"}
2024/05/10 22:32:52.613 DEBUG   http.log.error  {id=h9n01tz5n} fileserver.(*FileServer).notFound (staticfiles.go:818): HTTP 404 {"request": {"remote_ip": "::1", "remote_port": "36704", "client_ip": "::1", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:1234", "uri": "/", "headers": {"User-Agent": ["curl/8.7.1"], "Accept": ["*/*"]}}, "duration": 0.000174089, "status": 404, "err_id": "h9n01tz5n", "err_trace": "fileserver.(*FileServer).notFound (staticfiles.go:818)"}
2024/05/10 22:32:52.613 INFO    http.log.access handled request {"request": {"remote_ip": "::1", "remote_port": "36704", "client_ip": "::1", "proto": "HTTP/1.1", "method": "GET", "host": "localhost:1234", "uri": "/", "headers": {"Accept": ["*/*"], "User-Agent": ["curl/8.7.1"]}}, "bytes_read": 0, "user_id": "", "duration": 0.000174089, "size": 0, "status": 404, "resp_headers": {"Server": ["Caddy"]}}

So I can see every middleware it went through. (Notice it didn't go through rewrite because it didn't match.)

This would almost never be used in production, but I would be aware that this will log your middleware configurations which may be sensitive (?) so keep that in mind.