diff --git a/internal/api/admin_lidarr.go b/internal/api/admin_lidarr.go index adf080f2..c21af7b0 100644 --- a/internal/api/admin_lidarr.go +++ b/internal/api/admin_lidarr.go @@ -147,6 +147,14 @@ func (h *handlers) handleTestLidarrConnection(w http.ResponseWriter, r *http.Req result, err := client.Ping(r.Context()) if err != nil { errCode := lidarrErrCode(err) + // Warn (not Error): a failed connection test is expected when the + // admin is configuring the integration and may have a typo'd URL + // or wrong key. Without this log line the underlying *net.DNSError + // / *net.OpError / TLS error is invisible to operators — they only + // see the bucket code in the UI. base_url is safe to log; api_key + // must NEVER be logged. + h.logger.Warn("admin: test lidarr ping failed", + "err", err, "base_url", baseURL, "code", errCode) writeJSON(w, http.StatusOK, map[string]any{"ok": false, "error": errCode}) return } diff --git a/internal/server/requestlog.go b/internal/server/requestlog.go new file mode 100644 index 00000000..27fc6a2f --- /dev/null +++ b/internal/server/requestlog.go @@ -0,0 +1,50 @@ +package server + +import ( + "log/slog" + "net/http" + "time" + + "github.com/go-chi/chi/v5/middleware" +) + +// 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. +func requestLog(logger *slog.Logger) 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() + 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, + } + switch { + case status >= 500: + logger.Error("http", attrs...) + case status >= 400: + logger.Warn("http", attrs...) + default: + logger.Info("http", attrs...) + } + }) + } +} diff --git a/internal/server/requestlog_test.go b/internal/server/requestlog_test.go new file mode 100644 index 00000000..bff1c155 --- /dev/null +++ b/internal/server/requestlog_test.go @@ -0,0 +1,110 @@ +package server + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" +) + +// captureLogger is a slog.Handler that records each Record emitted, so +// requestLog tests can assert level + attrs without parsing JSON. +type capturedRecord struct { + Level slog.Level + Msg string + Attrs map[string]any +} + +type captureHandler struct { + records *[]capturedRecord +} + +func (h *captureHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } + +func (h *captureHandler) Handle(_ context.Context, r slog.Record) error { + rec := capturedRecord{Level: r.Level, Msg: r.Message, Attrs: map[string]any{}} + r.Attrs(func(a slog.Attr) bool { rec.Attrs[a.Key] = a.Value.Any(); return true }) + *h.records = append(*h.records, rec) + return nil +} + +func (h *captureHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h } +func (h *captureHandler) WithGroup(_ string) slog.Handler { return h } + +func newCaptureLogger() (*slog.Logger, *[]capturedRecord) { + records := &[]capturedRecord{} + return slog.New(&captureHandler{records: records}), records +} + +func TestRequestLog_StatusToSeverity(t *testing.T) { + cases := []struct { + name string + status int + wantLevel slog.Level + }{ + {"2xx is Info", http.StatusOK, slog.LevelInfo}, + {"4xx is Warn", http.StatusNotFound, slog.LevelWarn}, + {"5xx is Error", http.StatusInternalServerError, slog.LevelError}, + } + 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) { + w.WriteHeader(tc.status) + })) + req := httptest.NewRequest(http.MethodGet, "/something", nil) + h.ServeHTTP(httptest.NewRecorder(), req) + + if len(*records) != 1 { + t.Fatalf("len(records) = %d, want 1", len(*records)) + } + rec := (*records)[0] + if rec.Level != tc.wantLevel { + t.Errorf("level = %v, want %v", rec.Level, tc.wantLevel) + } + if rec.Attrs["status"] != int64(tc.status) { + t.Errorf("status = %v, want %d", rec.Attrs["status"], tc.status) + } + }) + } +} + +func TestRequestLog_SkipsHealthz(t *testing.T) { + logger, records := newCaptureLogger() + h := requestLog(logger)(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusOK) + })) + req := httptest.NewRequest(http.MethodGet, "/healthz", nil) + h.ServeHTTP(httptest.NewRecorder(), req) + + if len(*records) != 0 { + t.Errorf("expected /healthz to be skipped, got %d records", len(*records)) + } +} + +// Sanity that other paths produce a useful structured payload. +func TestRequestLog_AttributesPresent(t *testing.T) { + // Use a real slog text handler buffer so we also exercise the + // 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) { + w.WriteHeader(http.StatusOK) + })) + req := httptest.NewRequest(http.MethodPost, "/api/something", strings.NewReader("")) + h.ServeHTTP(httptest.NewRecorder(), req) + + var got map[string]any + 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"} { + if _, ok := got[key]; !ok { + t.Errorf("expected key %q in log entry, got %v", key, got) + } + } +} diff --git a/internal/server/server.go b/internal/server/server.go index c333aead..0a29ad5c 100644 --- a/internal/server/server.go +++ b/internal/server/server.go @@ -48,6 +48,7 @@ func New(logger *slog.Logger, pool *pgxpool.Pool, scanner ScanTrigger, subCfg su func (s *Server) Router() http.Handler { r := chi.NewRouter() r.Use(middleware.RequestID) + r.Use(requestLog(s.Logger)) r.Use(middleware.Recoverer) r.Get("/healthz", s.handleHealthz)