package chimw
import (
"context"
"log/slog"
"net/http"
"time"
chimiddleware "github.com/go-chi/chi/v5/middleware"
"sourcecraft.dev/bigbes/sr-ht-ecore/middleware"
)
// defaultLogMessage is the message of the request record. It is a constant
// rather than a formatted sentence because everything that varies is an
// attribute: a structured record whose message changed per request would make
// the one field a log pipeline groups by useless.
const defaultLogMessage = "request"
// SlogFormatter is chi's middleware.LogFormatter emitting slog records instead
// of chi's own line.
//
// chi's Logger writes through a package-level stdlib log.Logger to *stdout*, in
// a colourised human format, with no fields. On this instance that is the
// highest-volume line a service emits and the only one that is not structured
// and not on stderr: an operator who greps the journal for a request id finds
// every panic and every audit line of the daemon, and none of its requests.
// Replacing it is the entire point of this type.
//
// It is a LogFormatter rather than a middleware of our own because chi already
// owns the parts that are tedious to get right — wrapping the ResponseWriter so
// that status and byte count are observable at all, and writing the entry from a
// defer so that a request that panics is still logged. What was missing was
// somewhere to send the result.
//
// The zero value works: records go to slog.Default(), under the message
// "request", for every request. Use it as
//
// r.Use(chimw.RequestLogger(chimw.SlogFormatter{}))
type SlogFormatter struct {
// Logger is where records go. Nil means slog.Default(), read at write time,
// so a service that calls slog.SetDefault after building its router still
// gets its own handler — this is middleware.RecoverPanics's rule, for the
// reason given in the package doc.
Logger *slog.Logger
// Message overrides the record's message. Empty means "request".
Message string
// Skip decides which requests produce no line. Nil logs everything.
//
// The decision is the caller's and not this package's, deliberately. The
// noise worth dropping is a probe hitting /healthz every second — but
// "/healthz" is this instance's spelling, a service may also be polled at
// /metrics, at a badge a README embeds, or at a static prefix, and which of
// those is noise depends on what the operator is looking for that week. A
// list baked in here would silently drop the one line somebody debugging
// the probe needs, in a package they would have to read the source of to
// find out why. SkipPaths covers the common case in one call.
//
// It is evaluated once per request, before the handler runs, and it
// silences only the request line: a panic on a skipped path is still
// reported, because a probe path that panics is not noise.
Skip func(r *http.Request) bool
}
// RequestLogger is the middleware for a formatter: chi's RequestLogger with this
// package's formatter already in it, so that a service need not import chi's
// middleware package to install one.
//
// It goes outermost, ahead of middleware.RecoverPanics — see the package doc for
// why — and after chi's RequestID and RealIP, which must have run before the
// entry is built for the record to carry an id and for RemoteAddr to be the
// viewer's.
func RequestLogger(f SlogFormatter) func(http.Handler) http.Handler {
return chimiddleware.RequestLogger(f)
}
// SkipPaths builds a Skip predicate matching a fixed set of exact paths, which
// is what a probe endpoint is. It matches on the path alone: a query string
// cannot turn /healthz into something worth a line.
func SkipPaths(paths ...string) func(r *http.Request) bool {
set := make(map[string]struct{}, len(paths))
for _, p := range paths {
set[p] = struct{}{}
}
return func(r *http.Request) bool {
_, ok := set[r.URL.Path]
return ok
}
}
// NewLogEntry captures what is known before the handler runs. It implements
// chi's middleware.LogFormatter.
func (f SlogFormatter) NewLogEntry(r *http.Request) chimiddleware.LogEntry {
ctx := r.Context()
return &logEntry{
formatter: f,
ctx: ctx,
method: r.Method,
path: r.URL.Path,
requestID: chimiddleware.GetReqID(ctx),
quiet: f.Skip != nil && f.Skip(r),
}
}
// logEntry is one request's record, filled in when the response is done.
//
// The request itself is not held on to. What is logged is copied out here, at
// the top of the chain, where r.Method is still the method that arrived and the
// path has not been rewritten by anything mounted below; keeping the *http.Request
// would mean logging whatever the last middleware to rewrite it decided.
type logEntry struct {
formatter SlogFormatter
ctx context.Context
method string
path string
requestID string
quiet bool
}
// Write emits the request line. chi calls it from a defer, so it runs for a
// handler that returned normally, one that panicked, and one whose client hung
// up halfway.
//
// The attributes are the five that answer "what happened to this request" —
// method, path, status, bytes, duration — plus the request id when chi's
// RequestID middleware is installed above this one, which is the field that ties
// the line to the panic report and to whatever the handler logged in between.
//
// path is r.URL.Path and deliberately not RequestURI: the query string of these
// services carries search terms a viewer typed and, on the pages that come back
// from an OAuth round trip, parameters nobody wants written to disk twice. The
// route pattern is not logged either — it is available from the route context by
// the time this runs, but it is derivable from the path by anyone reading, and
// the path is the thing an operator has in front of them when a report comes in.
//
// The header is ignored. It is the response's, it is large, and the two fields
// of it worth having (status and length) are already arguments.
func (e *logEntry) Write(status, bytes int, _ http.Header, elapsed time.Duration, _ any) {
if e.quiet {
return
}
status = e.reportedStatus(status)
attrs := make([]slog.Attr, 0, 6)
attrs = append(attrs,
slog.String("method", e.method),
slog.String("path", e.path),
slog.Int("status", status),
slog.Int("bytes", bytes),
slog.Duration("duration", elapsed),
)
if e.requestID != "" {
attrs = append(attrs, slog.String("request_id", e.requestID))
}
e.logger().LogAttrs(e.ctx, levelFor(status), e.message(), attrs...)
}
// Panic is what chi's Recoverer reports through when a log entry is in context;
// without it that report is printed to stdout as a pretty-coloured stack, which
// is the same escape from the log this type exists to close.
//
// It does not double up with middleware.RecoverPanics. That one recovers the
// panic and renders a page, so the only panics still travelling when Recoverer
// looks are the ones it re-raises deliberately — http.ErrAbortHandler, which
// chi's Recoverer re-panics without calling this method.
//
// Skip does not silence it. A request nobody wanted a line for is still a
// request whose panic somebody needs.
func (e *logEntry) Panic(v any, stack []byte) {
attrs := make([]slog.Attr, 0, 5)
attrs = append(attrs,
slog.String("method", e.method),
slog.String("path", e.path),
slog.Any("panic", v),
slog.String("stack", string(stack)),
)
if e.requestID != "" {
attrs = append(attrs, slog.String("request_id", e.requestID))
}
e.logger().LogAttrs(e.ctx, slog.LevelError, "panic serving a request", attrs...)
}
// reportedStatus turns chi's "nothing was written" into the status the client
// actually saw.
//
// chi's wrapped writer reports 0 when no WriteHeader and no Write ever happened.
// Two things produce that. A handler that returned without touching the writer,
// which net/http answers with an empty 200 — so 200 is what the client got, and
// logging a 0 would send an operator looking for a bug in a redirect that worked.
// And a handler that gave up because the caller was already gone, which is what a
// cancelled request context means here: no status line was sent because there was
// nobody left to send it to.
//
// That second case is reported as middleware.StatusClientClosedRequest — nginx's
// 499, the code the log pipelines in front of this instance already read as "the
// client hung up". It is deliberately not any 5xx, which is what levelFor turns
// into an Error record and what the alert rate is written against: a viewer who
// navigated away mid-render and a CI job that pressed ^C must not page anybody.
// That reasoning is the constant's own (middleware.StatusClientClosedRequest);
// this is the place it gets applied to the highest-volume line the service emits.
//
// A handler that answered 499 itself — the donors' status mapping does, on both
// surfaces — needs no help from here: 499 is below 500, so it is already an Info
// record, which is the whole reason that number was picked over 500.
func (e *logEntry) reportedStatus(status int) int {
if status != 0 {
return status
}
if e.ctx.Err() != nil {
return middleware.StatusClientClosedRequest
}
return http.StatusOK
}
// levelFor picks the level of a request line from its status.
//
// Everything is Info except a 5xx, which is Error. A request line is not a
// finding — it is the record that something was served — so the default is the
// level a service's ordinary progress is logged at, and a deployment that
// dropped it to Warn would be trading away the only per-request evidence it has.
//
// A 5xx is promoted because it is the one status the service is confessing to:
// nothing the viewer typed produces it, and the record is worth its own line in
// an operator's filter without them having to know the field name for status.
// 4xx stays at Info on purpose. A 404 is a crawler, a stale bookmark or somebody
// mistyping a repository name, a 403 is the visibility rules working, and
// promoting either would hand a stranger with a URL bar the ability to set the
// warning rate of the instance.
//
// Nothing here special-cases 499: it is below 500 and lands at Info by the same
// rule as a 404, which is what makes it the right code for a client that hung up.
func levelFor(status int) slog.Level {
if status >= http.StatusInternalServerError {
return slog.LevelError
}
return slog.LevelInfo
}
func (e *logEntry) logger() *slog.Logger {
if e.formatter.Logger != nil {
return e.formatter.Logger
}
return slog.Default()
}
func (e *logEntry) message() string {
if e.formatter.Message != "" {
return e.formatter.Message
}
return defaultLogMessage
}