feat(server): slog request log + log dropped Lidarr ping errors
Two debuggability gaps surfaced by the /api/admin route shadowing investigation: 1. handleTestLidarrConnection swallowed client.Ping's error — only the bucket code (lidarr_unreachable) reached the response, the underlying *net.DNSError / *net.OpError / TLS error never reached the logs. Operators couldn't tell a typo'd hostname from a wrong port from a refused TLS handshake. Now logged at Warn (expected-when-misconfigured) with the base_url for diagnostic context. The api_key is never logged. 2. The chi router had no access-log middleware — every 4xx/5xx was silent, making it impossible to tell whether a request even reached the server. chi's middleware.Logger writes to the standard log package not slog, so a small slog wrapper handles it instead. /healthz is skipped (the compose healthcheck hits it every 5s; would be ~17k log lines/day of noise). Severity is keyed off response status: 5xx -> Error, 4xx -> Warn, else Info — so 4xx/5xx surface even when the operator's logger level is set above Info. Tests cover both the severity routing and the /healthz skip. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -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)
|
||||
}
|
||||
}
|
||||
}
|
||||
Reference in New Issue
Block a user