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 }