bvandeusen/minstrel
1
0
Fork 0
Code Issues 1 Pull Requests Actions Packages Projects Releases 46 Wiki Activity

fix(server): access log reports the real client, not the proxy — #2453
test-go / test (push) Successful in 1m3s
Details
test-go / integration (push) Successful in 5m9s
Details

Browse Source 
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.
This commit is contained in:
bvandeusen
2026-08-05 13:02:36 -04:00
parent 11538095be
commit 5b36d79ff9
3 changed files with 102 additions and 15 deletions
Download Patch File Download Diff File Expand all files Collapse all files
internal/server/requestlog.go
+22 -2
View File
@@ -6,6 +6,8 @@ import (
"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
@@ -18,7 +20,21 @@ import (
//
// Severity is keyed off the response status so 4xx/5xx surface even when
// the operator's logger level is set above Info.
func requestLog(logger *slog.Logger) func(http.Handler) http.Handler {
//
// 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" {
@@ -29,13 +45,17 @@ func requestLog(logger *slog.Logger) func(http.Handler) http.Handler {
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", r.RemoteAddr,
"remote", auth.ClientIP(r, hops),
}
switch {
case status >= 500:
internal/server/requestlog_test.go
+67 -4
View File
@@ -53,7 +53,7 @@ func TestRequestLog_StatusToSeverity(t *testing.T) {
for _, tc := range cases {
t.Run(tc.name, func(t *testing.T) {
logger, records := newCaptureLogger()
h := requestLog(logger)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
h := requestLog(logger, nil)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(tc.status)
}))
req := httptest.NewRequest(http.MethodGet, "/something", nil)
@@ -75,7 +75,7 @@ func TestRequestLog_StatusToSeverity(t *testing.T) {
func TestRequestLog_SkipsHealthz(t *testing.T) {
logger, records := newCaptureLogger()
h := requestLog(logger)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
h := requestLog(logger, nil)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusOK)
}))
req := httptest.NewRequest(http.MethodGet, "/healthz", nil)
@@ -92,7 +92,7 @@ func TestRequestLog_AttributesPresent(t *testing.T) {
// formatter (catches WithAttrs/WithGroup integration regressions).
var buf bytes.Buffer
logger := slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}))
h := requestLog(logger)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
h := requestLog(logger, nil)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusOK)
}))
req := httptest.NewRequest(http.MethodPost, "/api/something", strings.NewReader(""))
@@ -102,9 +102,72 @@ func TestRequestLog_AttributesPresent(t *testing.T) {
if err := json.Unmarshal(buf.Bytes(), &got); err != nil {
t.Fatalf("decode log line: %v\nraw: %s", err, buf.String())
}
for _, key := range []string{"method", "path", "status", "duration_ms"} {
for _, key := range []string{"method", "path", "status", "duration_ms", "remote"} {
if _, ok := got[key]; !ok {
t.Errorf("expected key %q in log entry, got %v", key, got)
}
}
}
// The point of routing #2453 through the access log: behind a proxy, `remote`
// must be the client rather than the proxy, and must agree with what the
// Active-sessions surface records for the same request. Logs and UI
// disagreeing about who connected is worse than either being wrong alone.
func TestRequestLog_RemoteHonoursTrustedProxyDepth(t *testing.T) {
cases := []struct {
name string
hops func() int
remoteAddr string
forwarded string
want string
}{
{
name: "nil accessor falls back to the socket peer",
hops: nil,
remoteAddr: "203.0.113.200:40000",
forwarded: "198.51.100.7",
want: "203.0.113.200",
},
{
name: "depth 0 ignores a forwarded header",
hops: func() int { return 0 },
remoteAddr: "203.0.113.200:40000",
forwarded: "198.51.100.7",
want: "203.0.113.200",
},
{
// The case that motivated the change: proxy on a PUBLIC address,
// which the pre-#2453 heuristic logged as the proxy forever.
name: "depth 1 through a public-addressed proxy logs the client",
hops: func() int { return 1 },
remoteAddr: "203.0.113.200:40000",
forwarded: "198.51.100.7",
want: "198.51.100.7",
},
{
name: "depth 2 reaches through a cdn to the client",
hops: func() int { return 2 },
remoteAddr: "172.18.0.1:40000",
forwarded: "198.51.100.7, 203.0.113.50",
want: "198.51.100.7",
},
}
for _, tc := range cases {
t.Run(tc.name, func(t *testing.T) {
logger, records := newCaptureLogger()
h := requestLog(logger, tc.hops)(http.HandlerFunc(
func(w http.ResponseWriter, _ *http.Request) { w.WriteHeader(http.StatusOK) }))
req := httptest.NewRequest(http.MethodGet, "/api/something", nil)
req.RemoteAddr = tc.remoteAddr
req.Header.Set("X-Forwarded-For", tc.forwarded)
h.ServeHTTP(httptest.NewRecorder(), req)
if len(*records) != 1 {
t.Fatalf("len(records) = %d, want 1", len(*records))
}
if got := (*records)[0].Attrs["remote"]; got != tc.want {
t.Errorf("remote = %v, want %q", got, tc.want)
}
})
}
}
internal/server/server.go
+13 -9
View File
@@ -113,8 +113,20 @@ func New(logger *slog.Logger, pool *pgxpool.Pool, scanner ScanTrigger, subCfg su
func (s *Server) Router() http.Handler {
r := chi.NewRouter()
// Built before the router because the access log needs it, and the access
// log covers /healthz and the SPA — which exist whether or not there's a
// pool. netsettings.New handles a nil pool by returning a default-valued
// service, so this needs no branch and no later reassignment; hoisting it
// here keeps the accessor a plain method value instead of a closure over
// a variable mutated after the middleware is already registered.
netSettings, nsErr := netsettings.New(context.Background(), s.Pool, s.Logger)
if nsErr != nil {
s.Logger.Error("server: netsettings boot failed, using default hops", "err", nsErr)
}
r.Use(middleware.RequestID)
r.Use(requestLog(s.Logger))
r.Use(requestLog(s.Logger, netSettings.Hops))
r.Use(middleware.Recoverer)
r.Get("/healthz", s.handleHealthz)
@@ -165,14 +177,6 @@ func (s *Server) Router() http.Handler {
s.Logger.Error("server: recsettings boot failed", "err", err)
}
}
// Cached trusted-proxy depth (#2453). Constructed here rather than in
// main.go because nothing else needs it at boot, and New always hands
// back a usable service — a DB hiccup degrades to the default rather
// than breaking the authenticated request path that reads it.
netSettings, err := netsettings.New(context.Background(), s.Pool, s.Logger)
if err != nil {
s.Logger.Error("server: netsettings boot failed, using default hops", "err", err)
}
api.Mount(r, s.Pool, s.Logger, writer, s.RecommendationCfg, recSettings, lidarrCfg, lidarrReqs, lidarrQuar, tracksSvc, playlistsSvc, s.CoverEnricher, s.CoverSettings, s.TagSettings, s.LibraryScanner, s.ScanCfg, s.DataDir, smtpSender, bus, s.PlaylistScheduler, s.StreamSecret, netSettings)
// /api/admin/scan is the only admin route owned by the server package
// (it needs the Scanner). Register it as a single inline-middleware