package app import ( "bytes" "errors" "log/slog" "net/http" "net/http/httptest" "strings" "testing" "github.com/gin-gonic/gin" "galo/internal/httpx" ) func captureLog(t *testing.T, level slog.Level) *bytes.Buffer { t.Helper() buf := &bytes.Buffer{} prev := slog.Default() slog.SetDefault(slog.New(slog.NewTextHandler(buf, &slog.HandlerOptions{Level: level}))) t.Cleanup(func() { slog.SetDefault(prev) }) return buf } func observabilityEngine() *gin.Engine { gin.SetMode(gin.TestMode) r := gin.New() r.Use(requestIDMiddleware(), accessLogMiddleware()) ok := func(c *gin.Context) { c.Status(http.StatusOK) } r.GET("/api/albums", ok) r.GET("/api/health", ok) r.GET("/api/objects/*key", ok) r.GET("/api/sse/albums/:id", ok) r.GET("/browse/:id", ok) return r } func TestRequestID(t *testing.T) { r := observabilityEngine() t.Run("provided id is reused and echoed", func(t *testing.T) { req := httptest.NewRequest(http.MethodGet, "/api/albums", nil) req.Header.Set("X-Request-ID", "req-abc-123") w := httptest.NewRecorder() r.ServeHTTP(w, req) if got := w.Header().Get("X-Request-ID"); got != "req-abc-123" { t.Fatalf("X-Request-ID = %q, want req-abc-123", got) } }) t.Run("generated when absent", func(t *testing.T) { req := httptest.NewRequest(http.MethodGet, "/api/albums", nil) w := httptest.NewRecorder() r.ServeHTTP(w, req) if got := w.Header().Get("X-Request-ID"); got == "" { t.Fatal("X-Request-ID is empty, want generated value") } }) t.Run("invalid id replaced", func(t *testing.T) { req := httptest.NewRequest(http.MethodGet, "/api/albums", nil) req.Header.Set("X-Request-ID", "bad id\nwith spaces") w := httptest.NewRecorder() r.ServeHTTP(w, req) if got := w.Header().Get("X-Request-ID"); got == "bad id\nwith spaces" || got == "" { t.Fatalf("X-Request-ID = %q, want a freshly generated value", got) } }) } func TestAccessLog(t *testing.T) { t.Run("written at debug, without query", func(t *testing.T) { buf := captureLog(t, slog.LevelDebug) req := httptest.NewRequest(http.MethodGet, "/api/albums?token=SUPERSECRET", nil) w := httptest.NewRecorder() observabilityEngine().ServeHTTP(w, req) out := buf.String() for _, want := range []string{"http request", "route=/api/albums", "request_id="} { if !strings.Contains(out, want) { t.Fatalf("log missing %q:\n%s", want, out) } } if strings.Contains(out, "SUPERSECRET") || strings.Contains(out, "token=") { t.Fatalf("query string leaked into log:\n%s", out) } }) t.Run("silent at info", func(t *testing.T) { buf := captureLog(t, slog.LevelInfo) req := httptest.NewRequest(http.MethodGet, "/api/albums", nil) w := httptest.NewRecorder() observabilityEngine().ServeHTTP(w, req) if strings.Contains(buf.String(), "http request") { t.Fatalf("access line written at info:\n%s", buf.String()) } }) } func errorEngine() *gin.Engine { gin.SetMode(gin.TestMode) r := gin.New() r.Use(requestIDMiddleware(), accessLogMiddleware()) r.GET("/api/boom", func(c *gin.Context) { httpx.RespondError(c, errors.New("boom")) }) r.GET("/api/bad", func(c *gin.Context) { httpx.RespondError(c, httpx.BadRequest("bad", "bad request")) }) r.GET("/api/fail", func(c *gin.Context) { httpx.RespondError(c, httpx.Internal("internal exploded")) }) return r } func do(r *gin.Engine, target string, body string) { req := httptest.NewRequest(http.MethodGet, target, strings.NewReader(body)) w := httptest.NewRecorder() r.ServeHTTP(w, req) } func TestErrorLogging(t *testing.T) { t.Run("internal error at error level with cause", func(t *testing.T) { buf := captureLog(t, slog.LevelDebug) do(errorEngine(), "/api/boom", "") out := buf.String() if !strings.Contains(out, "level=ERROR") || !strings.Contains(out, "request error") || !strings.Contains(out, "error=boom") || !strings.Contains(out, "request_id=") { t.Fatalf("internal error log wrong:\n%s", out) } }) t.Run("expected 4xx at debug", func(t *testing.T) { buf := captureLog(t, slog.LevelDebug) do(errorEngine(), "/api/bad", "") out := buf.String() if !strings.Contains(out, "level=DEBUG") || !strings.Contains(out, "request error") { t.Fatalf("4xx should log at debug:\n%s", out) } }) t.Run("app error 5xx at error", func(t *testing.T) { buf := captureLog(t, slog.LevelDebug) do(errorEngine(), "/api/fail", "") out := buf.String() if !strings.Contains(out, "level=ERROR") || !strings.Contains(out, "internal exploded") { t.Fatalf("5xx app error should log at error:\n%s", out) } }) t.Run("4xx hidden at info", func(t *testing.T) { buf := captureLog(t, slog.LevelInfo) do(errorEngine(), "/api/bad", "") if strings.Contains(buf.String(), "request error") { t.Fatalf("expected 4xx must be silent at info:\n%s", buf.String()) } }) } func TestLogPrivacy(t *testing.T) { buf := captureLog(t, slog.LevelDebug) do(errorEngine(), "/api/boom?token=SUPERSECRETTOKEN", "TOPSECRETBODY") out := buf.String() if strings.Contains(out, "SUPERSECRETTOKEN") || strings.Contains(out, "token=") { t.Fatalf("query leaked into log:\n%s", out) } if strings.Contains(out, "TOPSECRETBODY") { t.Fatalf("body leaked into log:\n%s", out) } } func TestAccessLogFiltering(t *testing.T) { buf := captureLog(t, slog.LevelDebug) r := observabilityEngine() for _, target := range []string{"/api/health", "/api/objects/abc/thumb.webp", "/api/sse/albums/a1", "/browse/42"} { w := httptest.NewRecorder() r.ServeHTTP(w, httptest.NewRequest(http.MethodGet, target, nil)) } out := buf.String() if strings.Contains(out, "route=/api/health") { t.Fatalf("/api/health must never be access-logged:\n%s", out) } for _, want := range []string{"route=/api/objects/*key", "route=/api/sse/albums/:id", "route=/browse/:id"} { if !strings.Contains(out, want) { t.Fatalf("expected %q logged at debug:\n%s", want, out) } } }