bvandeusen
5b36d79ff9
Closes the disagreement left open by #2453: requestlog.go logged raw r.RemoteAddr while the Active-sessions surface resolved through the operator's configured proxy depth. Behind a proxy — the normal deployment for anything public — every access-log line carried the same useless proxy address, and the two surfaces contradicted each other about who connected. Logs and UI disagreeing is worse than either being wrong alone, because it costs you trust in both. `remote` now holds auth.ClientIP(r, hops). The attribute KEY is deliberately unchanged so existing log greps keep working; only its accuracy improved. Wiring note. The access log covers /healthz and the SPA, so it's registered before the pool-bearing branch that used to build the settings service. Rather than close over a variable reassigned later — which works, but leaves a mutable-after-registration seam and an awkward question about races — I hoisted netsettings.New above the router entirely. It already handles a nil pool by returning a default-valued service, so no branch is needed and the accessor stays a plain method value. Applied the lesson from the last three CI failures BEFORE pushing this time: a bare-identifier grep for `requestLog(` found three call sites in requestlog_test.go that a qualified pattern could never have matched, since the function is package-private and its tests are in-package. Also swept netsettings.New and ClientIP the same way. Tests: the behaviour change gets its own table — nil accessor and depth 0 log the socket peer, depth 1 through a PUBLIC-addressed proxy logs the client (the exact case the old heuristic got wrong forever), depth 2 reaches through a CDN. Added `remote` to the required-keys assertion so the attribute can't quietly disappear.
71 lines
2.4 KiB
Go
71 lines
2.4 KiB
Go
package server
|
|
|
|
import (
|
|
"log/slog"
|
|
"net/http"
|
|
"time"
|
|
|
|
"github.com/go-chi/chi/v5/middleware"
|
|
|
|
"git.fabledsword.com/bvandeusen/minstrel/internal/auth"
|
|
)
|
|
|
|
// requestLog is an slog-based access log middleware. chi ships
|
|
// middleware.Logger but it writes to the standard library's log package,
|
|
// not slog, so output ordering and formatting drift from the rest of the
|
|
// server's logs. We use a thin wrapper instead.
|
|
//
|
|
// The /healthz path is skipped because the docker-compose healthcheck
|
|
// hits it every 5s and would otherwise drown real signals (~17k lines/day).
|
|
//
|
|
// Severity is keyed off the response status so 4xx/5xx surface even when
|
|
// the operator's logger level is set above Info.
|
|
//
|
|
// The `remote` attribute holds the address resolved through the operator's
|
|
// configured reverse-proxy depth, NOT the raw socket peer (#2453). Behind a
|
|
// proxy — the normal deployment for anything public — the socket peer is the
|
|
// proxy, so every line would have carried the same useless address, and the
|
|
// access log would have disagreed with the Active-sessions surface about who
|
|
// connected. The attribute key is unchanged so existing log greps keep
|
|
// working; only its accuracy improved.
|
|
//
|
|
// trustedHops is a func because this middleware is constructed at boot while
|
|
// the value is operator-editable at runtime, and — since Router() registers
|
|
// this before it builds the settings service — because it lets the accessor
|
|
// be wired before the thing it reads exists. auth.ClientIP tolerates a depth
|
|
// of 0, which is what a nil service reports.
|
|
func requestLog(logger *slog.Logger, trustedHops func() int) func(http.Handler) http.Handler {
|
|
return func(next http.Handler) http.Handler {
|
|
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
|
|
if r.URL.Path == "/healthz" {
|
|
next.ServeHTTP(w, r)
|
|
return
|
|
}
|
|
start := time.Now()
|
|
ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor)
|
|
next.ServeHTTP(ww, r)
|
|
status := ww.Status()
|
|
hops := 0
|
|
if trustedHops != nil {
|
|
hops = trustedHops()
|
|
}
|
|
attrs := []any{
|
|
"method", r.Method,
|
|
"path", r.URL.Path,
|
|
"status", status,
|
|
"duration_ms", time.Since(start).Milliseconds(),
|
|
"request_id", middleware.GetReqID(r.Context()),
|
|
"remote", auth.ClientIP(r, hops),
|
|
}
|
|
switch {
|
|
case status >= 500:
|
|
logger.Error("http", attrs...)
|
|
case status >= 400:
|
|
logger.Warn("http", attrs...)
|
|
default:
|
|
logger.Info("http", attrs...)
|
|
}
|
|
})
|
|
}
|
|
}
|