feat(observability): configurable logging, request ids and error logs

- internal/logging: LOG_LEVEL/LOG_FORMAT parsing and slog handler - request_id middleware (X-Request-ID or generated, echoed) + debug access log - httpx registers errors; middleware logs internal causes with request_id - health excluded, objects/sse debug-only, no query/body/secrets in logs - new observability capability spec; README/.env.example docs
2026-10-11 13:40:11 +03:00
parent a5d0cee0eb
commit 6361e48b20
18 changed files with 998 additions and 5 deletions
@@ -91,7 +91,7 @@ func (s *Server) StartWorker(ctx context.Context) {

 func (s *Server) Router() *gin.Engine {
 	r := gin.New()
-	r.Use(gin.Recovery())
+	r.Use(gin.Recovery(), requestIDMiddleware(), accessLogMiddleware())

 	authHandler := auth.NewHandler(s.auth)
 	albumsHandler := albums.NewHandler(s.albums)
@@ -0,0 +1,77 @@
+package app
+
+import (
+	"errors"
+	"log/slog"
+	"time"
+
+	"github.com/gin-gonic/gin"
+
+	"galo/internal/auth"
+	"galo/internal/httpx"
+	"galo/internal/logging"
+)
+
+const ctxRequestID = "logging.request_id"
+
+// requestIDMiddleware assigns a request identifier, echoes it in the response
+// header and stores it in the request context for downstream logging.
+func requestIDMiddleware() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		id := c.GetHeader("X-Request-ID")
+		if !logging.ValidRequestID(id) {
+			id = logging.NewRequestID()
+		}
+		c.Set(ctxRequestID, id)
+		c.Header("X-Request-ID", id)
+		c.Request = c.Request.WithContext(logging.WithRequestID(c.Request.Context(), id))
+		c.Next()
+	}
+}
+
+// accessLogMiddleware writes one debug-level line per completed request and
+// logs collected errors. The query string, Authorization header and bodies are
+// never logged.
+func accessLogMiddleware() gin.HandlerFunc {
+	return func(c *gin.Context) {
+		start := time.Now()
+		c.Next()
+
+		if route := c.FullPath(); shouldLogAccess(route) {
+			logRequest(c, start, route)
+		}
+		logErrors(c)
+	}
+}
+
+func shouldLogAccess(route string) bool {
+	return route != "" && route != "/api/health"
+}
+
+func logRequest(c *gin.Context, start time.Time, route string) {
+	slog.Default().LogAttrs(c.Request.Context(), slog.LevelDebug, "http request",
+		slog.String("method", c.Request.Method),
+		slog.String("route", route),
+		slog.Int("status", c.Writer.Status()),
+		slog.Duration("latency", time.Since(start)),
+		slog.Int("bytes", c.Writer.Size()),
+		slog.String("client_ip", c.ClientIP()),
+		slog.String("user_id", auth.UserID(c)),
+		slog.String("request_id", logging.RequestID(c.Request.Context())),
+	)
+}
+
+func logErrors(c *gin.Context) {
+	for _, ginErr := range c.Errors {
+		level := slog.LevelError
+		var appErr *httpx.AppError
+		if errors.As(ginErr.Err, &appErr) && appErr.Status < 500 {
+			level = slog.LevelDebug
+		}
+		slog.Default().LogAttrs(c.Request.Context(), level, "request error",
+			slog.String("error", ginErr.Err.Error()),
+			slog.String("route", c.FullPath()),
+			slog.String("request_id", logging.RequestID(c.Request.Context())),
+		)
+	}
+}
@@ -0,0 +1,183 @@
+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)
+		}
+	}
+}