ds-galo/backend/internal/app/observability_test.go

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)
		}
	}
}