diff --git a/internal/server/requestlog.go b/internal/server/requestlog.go index 27fc6a2f..fe597149 100644 --- a/internal/server/requestlog.go +++ b/internal/server/requestlog.go @@ -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: diff --git a/internal/server/requestlog_test.go b/internal/server/requestlog_test.go index bff1c155..b5b552c5 100644 --- a/internal/server/requestlog_test.go +++ b/internal/server/requestlog_test.go @@ -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) + } + }) + } +} diff --git a/internal/server/server.go b/internal/server/server.go index e46c0ee6..d0dede52 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -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