diff --git a/.env.example b/.env.example index 44465e8..70b85fd 100644 --- a/.env.example +++ b/.env.example @@ -46,3 +46,8 @@ SSE_CLIENT_BUFFER=64 WORKER_INTERVAL=5s WORKER_BATCH=10 WORKER_PENDING_TTL=10m + +# Logging. LOG_LEVEL=debug adds per-request access logs and expected 4xx errors. +# LOG_FORMAT selects the output encoding. +LOG_LEVEL=info +LOG_FORMAT=json diff --git a/README.md b/README.md index 3ce1ffb..69599a3 100644 --- a/README.md +++ b/README.md @@ -68,6 +68,17 @@ cp .env.example .env | `WORKER_INTERVAL` | `5s` | Период проверки воркером очереди задач | | `WORKER_BATCH` | `10` | Размер батча обрабатываемых задач | | `WORKER_PENDING_TTL` | `10m` | TTL задачи в статусе `pending` до повторной попытки | +| **Логирование** | | | +| `LOG_LEVEL` | `info` | Уровень логов: `debug`, `info`, `warn`, `error` | +| `LOG_FORMAT` | `json` | Формат логов: `json` или `text` | + +На уровне `debug` сервер пишет по строке на каждый HTTP-запрос (метод, маршрут, +статус, длительность, пользователь, `request_id`) и логирует ожидаемые отказы 4xx. +Внутренние ошибки (неожиданные и 5xx) логируются на уровне `error` с исходной причиной +и `request_id`; сам `request_id` возвращается клиенту в заголовке ответа +`X-Request-ID`. Маршрут `/api/health` в access-логи не попадает, а `/api/objects/*` и +`/api/sse/*` — только на уровне `debug`. Query-строка, заголовок `Authorization` и тела +запросов в логи не пишутся. Слои данных выбираются параметрами (по умолчанию — локальный режим): diff --git a/backend/cmd/server/main.go b/backend/cmd/server/main.go index efedea3..9ff84a2 100644 --- a/backend/cmd/server/main.go +++ b/backend/cmd/server/main.go @@ -18,6 +18,7 @@ import ( "galo/internal/auth" "galo/internal/config" "galo/internal/db" + "galo/internal/logging" "galo/internal/settings" "galo/internal/sse" "galo/internal/storage" @@ -31,16 +32,25 @@ func main() { loadDotEnv(".env") loadDotEnv("../.env") - logger := slog.New(slog.NewJSONHandler(os.Stdout, &slog.HandlerOptions{Level: slog.LevelInfo})) - slog.SetDefault(logger) - slog.Info("starting galo", "version", version) - cfg, err := config.Load() if err != nil { slog.Error("config error", "error", err) os.Exit(1) } + level, err := logging.ParseLevel(cfg.Log.Level) + if err != nil { + slog.Error("invalid log level", "error", err) + os.Exit(1) + } + handler, err := logging.NewHandler(cfg.Log.Format, level) + if err != nil { + slog.Error("invalid log format", "error", err) + os.Exit(1) + } + slog.SetDefault(slog.New(handler)) + slog.Info("starting galo", "version", version) + switch cfg.Database.Backend { case "sqlite": slog.Info("metadata backend", "backend", "sqlite", "path", cfg.Database.SQLitePath) diff --git a/backend/internal/app/app.go b/backend/internal/app/app.go index 3379c4d..ac9ba51 100644 --- a/backend/internal/app/app.go +++ b/backend/internal/app/app.go @@ -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) diff --git a/backend/internal/app/observability.go b/backend/internal/app/observability.go new file mode 100644 index 0000000..c0c06c6 --- /dev/null +++ b/backend/internal/app/observability.go @@ -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())), + ) + } +} diff --git a/backend/internal/app/observability_test.go b/backend/internal/app/observability_test.go new file mode 100644 index 0000000..a49f7a8 --- /dev/null +++ b/backend/internal/app/observability_test.go @@ -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) + } + } +} diff --git a/backend/internal/config/config.go b/backend/internal/config/config.go index ca15eb9..be4b1db 100644 --- a/backend/internal/config/config.go +++ b/backend/internal/config/config.go @@ -5,6 +5,8 @@ import ( "os" "strconv" "time" + + "galo/internal/logging" ) type Postgres struct { @@ -63,6 +65,11 @@ type Database struct { SQLitePath string } +type Log struct { + Level string + Format string +} + type Config struct { Postgres Postgres S3 S3 @@ -72,6 +79,7 @@ type Config struct { Server Server SSE SSE Worker Worker + Log Log } func Load() (*Config, error) { @@ -125,6 +133,15 @@ func Load() (*Config, error) { return nil, fmt.Errorf("invalid WORKER_PENDING_TTL: %w", err) } + logLevel := getEnv("LOG_LEVEL", "info") + if _, err := logging.ParseLevel(logLevel); err != nil { + return nil, err + } + logFormat := getEnv("LOG_FORMAT", "json") + if _, err := logging.ParseFormat(logFormat); err != nil { + return nil, err + } + cfg := &Config{ Postgres: Postgres{ Host: getEnv("PG_HOST", "pg.localnet"), @@ -169,6 +186,10 @@ func Load() (*Config, error) { Batch: workerBatch, PendingTTL: workerPendingTTL, }, + Log: Log{ + Level: logLevel, + Format: logFormat, + }, } switch cfg.Database.Backend { diff --git a/backend/internal/config/config_test.go b/backend/internal/config/config_test.go index 398d66d..2de56c3 100644 --- a/backend/internal/config/config_test.go +++ b/backend/internal/config/config_test.go @@ -132,3 +132,47 @@ func TestLoadDatabaseBackend(t *testing.T) { } }) } + +func TestLoadLog(t *testing.T) { + t.Run("defaults", func(t *testing.T) { + setRequiredEnv(t) + t.Setenv("LOG_LEVEL", "") + t.Setenv("LOG_FORMAT", "") + cfg, err := Load() + if err != nil { + t.Fatalf("load: %v", err) + } + if cfg.Log.Level != "info" || cfg.Log.Format != "json" { + t.Fatalf("log = %+v, want info/json", cfg.Log) + } + }) + + t.Run("custom values", func(t *testing.T) { + setRequiredEnv(t) + t.Setenv("LOG_LEVEL", "debug") + t.Setenv("LOG_FORMAT", "text") + cfg, err := Load() + if err != nil { + t.Fatalf("load: %v", err) + } + if cfg.Log.Level != "debug" || cfg.Log.Format != "text" { + t.Fatalf("log = %+v, want debug/text", cfg.Log) + } + }) + + t.Run("invalid level", func(t *testing.T) { + setRequiredEnv(t) + t.Setenv("LOG_LEVEL", "trace") + if _, err := Load(); err == nil { + t.Fatal("expected error for invalid LOG_LEVEL") + } + }) + + t.Run("invalid format", func(t *testing.T) { + setRequiredEnv(t) + t.Setenv("LOG_FORMAT", "xml") + if _, err := Load(); err == nil { + t.Fatal("expected error for invalid LOG_FORMAT") + } + }) +} diff --git a/backend/internal/httpx/httpx.go b/backend/internal/httpx/httpx.go index 42e5253..53899a3 100644 --- a/backend/internal/httpx/httpx.go +++ b/backend/internal/httpx/httpx.go @@ -53,6 +53,7 @@ func Internal(message string) *AppError { } func Abort(c *gin.Context, err error) { + _ = c.Error(err) var appErr *AppError if errors.As(err, &appErr) { c.AbortWithStatusJSON(appErr.Status, ErrorResponse{ErrorBody{appErr.Code, appErr.Message}}) @@ -62,6 +63,7 @@ func Abort(c *gin.Context, err error) { } func RespondError(c *gin.Context, err error) { + _ = c.Error(err) var appErr *AppError if errors.As(err, &appErr) { c.JSON(appErr.Status, ErrorResponse{ErrorBody{appErr.Code, appErr.Message}}) diff --git a/backend/internal/httpx/httpx_test.go b/backend/internal/httpx/httpx_test.go new file mode 100644 index 0000000..ebbc478 --- /dev/null +++ b/backend/internal/httpx/httpx_test.go @@ -0,0 +1,68 @@ +package httpx + +import ( + "errors" + "net/http" + "net/http/httptest" + "testing" + + "github.com/gin-gonic/gin" +) + +func runHandler(t *testing.T, handler gin.HandlerFunc) (*gin.Context, *httptest.ResponseRecorder) { + t.Helper() + gin.SetMode(gin.TestMode) + w := httptest.NewRecorder() + c, _ := gin.CreateTestContext(w) + c.Request = httptest.NewRequest(http.MethodGet, "/", nil) + handler(c) + return c, w +} + +func TestRespondErrorRegistersInternalError(t *testing.T) { + c, w := runHandler(t, func(c *gin.Context) { + RespondError(c, errors.New("boom")) + }) + if len(c.Errors) != 1 { + t.Fatalf("c.Errors = %d, want 1", len(c.Errors)) + } + if w.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want 500", w.Code) + } + if body := w.Body.String(); body != `{"error":{"code":"internal_error","message":"internal server error"}}` { + t.Fatalf("body = %s", body) + } +} + +func TestRespondErrorRegistersAppError(t *testing.T) { + c, w := runHandler(t, func(c *gin.Context) { + RespondError(c, NotFound("photo_not_found", "photo not found")) + }) + if len(c.Errors) != 1 { + t.Fatalf("c.Errors = %d, want 1", len(c.Errors)) + } + if w.Code != http.StatusNotFound { + t.Fatalf("status = %d, want 404", w.Code) + } +} + +func TestAbortRegistersInternalError(t *testing.T) { + c, w := runHandler(t, func(c *gin.Context) { + Abort(c, errors.New("kaboom")) + }) + if len(c.Errors) != 1 { + t.Fatalf("c.Errors = %d, want 1", len(c.Errors)) + } + if w.Code != http.StatusInternalServerError { + t.Fatalf("status = %d, want 500", w.Code) + } +} + +// Ensure the package-level recovery of AppError still works for logging levels. +func TestInternalIsAppError500(t *testing.T) { + err := Internal("oops") + var appErr *AppError + if !errors.As(err, &appErr) || appErr.Status != http.StatusInternalServerError { + t.Fatalf("Internal() = %#v", err) + } +} diff --git a/backend/internal/logging/logging.go b/backend/internal/logging/logging.go new file mode 100644 index 0000000..aa90be0 --- /dev/null +++ b/backend/internal/logging/logging.go @@ -0,0 +1,95 @@ +// Package logging configures the process-wide structured logger from +// environment-driven settings. +package logging + +import ( + "context" + "crypto/rand" + "encoding/hex" + "fmt" + "log/slog" + "os" + "strings" +) + +// ParseLevel maps a textual level name to a slog.Level. +func ParseLevel(name string) (slog.Level, error) { + switch strings.ToLower(strings.TrimSpace(name)) { + case "debug": + return slog.LevelDebug, nil + case "info": + return slog.LevelInfo, nil + case "warn", "warning": + return slog.LevelWarn, nil + case "error": + return slog.LevelError, nil + default: + return 0, fmt.Errorf("invalid log level %q (want debug, info, warn or error)", name) + } +} + +// ParseFormat normalizes a format name. An empty name defaults to JSON. +func ParseFormat(name string) (string, error) { + switch strings.ToLower(strings.TrimSpace(name)) { + case "", "json": + return "json", nil + case "text": + return "text", nil + default: + return "", fmt.Errorf("invalid log format %q (want json or text)", name) + } +} + +// NewHandler builds a slog handler writing to stdout in the requested format. +// An empty format defaults to JSON. +func NewHandler(format string, level slog.Level) (slog.Handler, error) { + f, err := ParseFormat(format) + if err != nil { + return nil, err + } + opts := &slog.HandlerOptions{Level: level} + if f == "text" { + return slog.NewTextHandler(os.Stdout, opts), nil + } + return slog.NewJSONHandler(os.Stdout, opts), nil +} + +type requestIDKey struct{} + +// WithRequestID stores a request identifier in the context. +func WithRequestID(ctx context.Context, id string) context.Context { + return context.WithValue(ctx, requestIDKey{}, id) +} + +// RequestID returns the request identifier stored in the context, or "". +func RequestID(ctx context.Context) string { + if id, ok := ctx.Value(requestIDKey{}).(string); ok { + return id + } + return "" +} + +// NewRequestID returns a fresh random request identifier. +func NewRequestID() string { + var b [16]byte + if _, err := rand.Read(b[:]); err != nil { + return "unknown" + } + return hex.EncodeToString(b[:]) +} + +// ValidRequestID reports whether an incoming identifier is safe to reuse. +func ValidRequestID(id string) bool { + if id == "" || len(id) > 128 { + return false + } + for _, r := range id { + switch { + case r >= 'a' && r <= 'z', r >= 'A' && r <= 'Z', r >= '0' && r <= '9': + case r == '-', r == '_', r == '.': + default: + return false + } + } + return true +} diff --git a/backend/internal/logging/logging_test.go b/backend/internal/logging/logging_test.go new file mode 100644 index 0000000..e3f1e64 --- /dev/null +++ b/backend/internal/logging/logging_test.go @@ -0,0 +1,95 @@ +package logging + +import ( + "log/slog" + "strings" + "testing" +) + +func TestParseLevel(t *testing.T) { + cases := []struct { + in string + want slog.Level + ok bool + }{ + {"debug", slog.LevelDebug, true}, + {"DEBUG", slog.LevelDebug, true}, + {" info ", slog.LevelInfo, true}, + {"warn", slog.LevelWarn, true}, + {"warning", slog.LevelWarn, true}, + {"error", slog.LevelError, true}, + {"trace", 0, false}, + {"", 0, false}, + } + for _, c := range cases { + got, err := ParseLevel(c.in) + if c.ok && err != nil { + t.Errorf("ParseLevel(%q) unexpected error: %v", c.in, err) + } + if !c.ok && err == nil { + t.Errorf("ParseLevel(%q) expected error, got %v", c.in, got) + } + if c.ok && got != c.want { + t.Errorf("ParseLevel(%q) = %v, want %v", c.in, got, c.want) + } + } +} + +func TestParseFormat(t *testing.T) { + cases := []struct { + in string + want string + ok bool + }{ + {"", "json", true}, + {"json", "json", true}, + {"TEXT", "text", true}, + {" text ", "text", true}, + {"xml", "", false}, + } + for _, c := range cases { + got, err := ParseFormat(c.in) + if c.ok && err != nil { + t.Errorf("ParseFormat(%q) unexpected error: %v", c.in, err) + } + if !c.ok && err == nil { + t.Errorf("ParseFormat(%q) expected error, got %q", c.in, got) + } + if c.ok && got != c.want { + t.Errorf("ParseFormat(%q) = %q, want %q", c.in, got, c.want) + } + } +} + +func TestRequestIDHelpers(t *testing.T) { + if !ValidRequestID("req-abc_123.4") { + t.Error("ValidRequestID(valid) = false") + } + for _, bad := range []string{"", "has space", "has\nnewline", "semi;colon", strings.Repeat("a", 129)} { + if ValidRequestID(bad) { + t.Errorf("ValidRequestID(%q) = true, want false", bad) + } + } + id := NewRequestID() + if id == "" || !ValidRequestID(id) { + t.Fatalf("NewRequestID() = %q, want a valid non-empty id", id) + } + if NewRequestID() == id { + t.Fatal("NewRequestID() returned the same value twice") + } +} + +func TestNewHandler(t *testing.T) { + for _, format := range []string{"", "json", "JSON", "text"} { + h, err := NewHandler(format, slog.LevelInfo) + if err != nil { + t.Errorf("NewHandler(%q) unexpected error: %v", format, err) + } + if h == nil { + t.Errorf("NewHandler(%q) returned nil handler", format) + } + } + if _, err := NewHandler("xml", slog.LevelInfo); err == nil { + t.Error("NewHandler(\"xml\") expected error, got nil") + } +} diff --git a/openspec/changes/archive/2026-10-11-add-observability-logging/.openspec.yaml b/openspec/changes/archive/2026-10-11-add-observability-logging/.openspec.yaml new file mode 100644 index 0000000..a369219 --- /dev/null +++ b/openspec/changes/archive/2026-10-11-add-observability-logging/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-10-11 diff --git a/openspec/changes/archive/2026-10-11-add-observability-logging/design.md b/openspec/changes/archive/2026-10-11-add-observability-logging/design.md new file mode 100644 index 0000000..e9181f6 --- /dev/null +++ b/openspec/changes/archive/2026-10-11-add-observability-logging/design.md @@ -0,0 +1,112 @@ +# Design + +## Context + +См. `proposal.md` — Why. Текущее состояние, важное для подхода: + +- Логирование инициализируется в `backend/cmd/server/main.go:34` жёстко + (`slog.NewJSONHandler(os.Stdout, LevelInfo)`), без чтения конфига. +- Роутер — `gin.New()` + `gin.Recovery()` (`internal/app/app.go:94`); access-логов, + `request_id` и middleware корреляции нет. Есть только `auth.Middleware` на группе `/api` + (`app.go:122`). +- `httpx.RespondError`/`Abort` (`internal/httpx/httpx.go:55-71`) для не-`AppError` + отвечают generic `500` и не логируют причину. +- `slog` уже используется точечно (`internal/db/db.go`, `internal/photos/worker.go`), + версия Go 1.26, `gin v1.12`. + +## Goals / Non-Goals + +**Goals:** +- Управляемые уровень и формат логов без изменения кода. +- Один след на запрос: `request_id` во всех строках, порождённых этим запросом. +- Видимость причины внутренних ошибок в логах. +- Отсутствие утечки секретов (токены, пароли, query, тела, подписанные URL). + +**Non-Goals:** +- Доменные (операционные) логи в сервисах (`album.created`, `photo.uploaded`) — слой C, + не входит. +- Метрики, трейсинг, экспорт во внешние системы. +- Изменение CLI-команд (`migrate`, `reconcile`, `backfill-exif`). +- Изменение формата ответов API. + +## Decisions + +### D1. Конфигурация уровня и формата +Новые env `LOG_LEVEL` (`debug|info|warn|error`, default `info`) и `LOG_FORMAT` +(`json|text`, default `json`). Значения валидируются в `config.Load`; недопустимое +значение — ошибка старта. `main.go` строит handler из конфига. + +- Альтернатива: булев `GALO_DEBUG` — отклонено, слишком грубо (нет warn/error отдельно) + и не даёт формат. +- Новый пакет `internal/logging` инкапсулирует разбор уровня и сборку handler + (`NewHandler(format, level)`), чтобы не размазывать `slog`-детали по `config` и `main`. + +### D2. Идентификатор запроса +Middleware (B) берёт `X-Request-ID` из входящего запроса, если он корректной формы +(ограничение длины и допустимые символы), иначе генерирует новый. `request_id`: +- кладётся в `context.Context` запроса (`logging.WithRequestID`); +- возвращается клиенту в заголовке ответа `X-Request-ID`. + +Так связка «запрос клиента ↔ строка в логе» работает без доступа к внутреннему состоянию. + +- Альтернатива: не принимать клиентский id и всегда генерировать — проще, но теряет + сквозную корреляцию с внешним прокси. Выбрано «принять валидный, иначе сгенерировать». + +### D3. Логирование внутренних ошибок +`httpx.RespondError`/`Abort` перестают молча выдавать `500`: для ошибки, не являющейся +`*AppError`, они вызывают `c.Error(err)` (gin накапливает, не пишет ответ). Middleware (B) +после `c.Next()` записывает все собранные ошибки на уровне `error` с причиной и `request_id`. + +- Классификация: `*AppError` со статусом `< 500` → `debug`; `*AppError` со статусом `>= 500` + и любая не-`AppError` → `error`. +- Альтернатива: логировать прямо в `httpx` через `slog.ErrorContext` — меньше правок, но + два независимых места логирования и дублирование `request_id`. Выбрана централизация в + middleware. +- `log/slog` не имеет контекстных атрибутов «из коробки»; `request_id` подставляется + явно из `logging.RequestID(ctx)`. + +### D4. Access-лог +Один middleware в `app.Router()` до групп маршрутов; после `c.Next()` пишет строку +уровня `debug`: `method`, `route` (`c.FullPath()`, **без query**), `status`, `latency`, +`bytes`, `client_ip`, `user_id` (`auth.UserID`, если установлен), `request_id`. + +- `user_id` доступен, т.к. middleware оборачивает `auth.Middleware` и читает контекст + после завершения цепочки. + +### D5. Уровни (сводно) + +| Событие | Уровень | +|---|---| +| Старт, бэкенды, миграции, storage ready (как сейчас) | info | +| Причина внутренней ошибки (не-`AppError`, 5xx) | error | +| Access-строка запроса | debug | +| Отказ 4xx (`AppError < 500`) | debug | + +### D6. Фильтрация и приватность +- `/api/health` — всегда исключён из access-лога. +- `/api/objects/*` и `/api/sse/*` — access-логи только на `debug` (объём/долгие соединения). +- Никогда не логируются: query-строка целиком (там `?token=` для SSE), подписанные URL, + заголовок `Authorization`, тела запросов, пароли. + +## Risks / Trade-offs + +- [Рост объёма на `debug` от `/api/objects/*` и SSE] -> фильтры из D6; на `info` + объём не растёт (access/4xx — `debug`). +- [Спуфинг `X-Request-ID` клиентом] -> принимаем только валидную форму с ограничением + длины; иначе генерируем. +- [Ложная latency для SSE (весь срок соединения)] -> SSE-строки только на `debug`; + поле трактуется как длительность соединения. +- [Утечка секретов через логи] -> D6 запрещает query/body/Authorization; явные поля — только + route и метаданные. +- [Двойной ответ при `c.Error`] -> `c.Error` только регистрирует ошибку, ответ уже + отправлен `httpx`; middleware лишь читает `c.Errors`. + +## Migration Plan + +Изменение кода и конфигурации, без миграции данных. При отсутствии новых env поведение +соответствует `LOG_LEVEL=info`, `LOG_FORMAT=json` — обычные логи почти не меняются. Для +диагностики выставить `LOG_LEVEL=debug`. Откат — вернуть прежний жёсткий handler. + +## Open Questions + +Нет. diff --git a/openspec/changes/archive/2026-10-11-add-observability-logging/proposal.md b/openspec/changes/archive/2026-10-11-add-observability-logging/proposal.md new file mode 100644 index 0000000..7975673 --- /dev/null +++ b/openspec/changes/archive/2026-10-11-add-observability-logging/proposal.md @@ -0,0 +1,40 @@ +# Proposal + +## Why + +Диагностика инцидентов идёт вслепую: логов операций нет ни на каком уровне, +access-логов нет, а внутренние ошибки (не-`AppError`) отдаются клиенту как +generic `500` и **нигде не логируются** — таких мест 82. Уровень логов зашит +(`slog.LevelInfo`, `main.go:34`), переключателя нет. Нужны управляемая детализация, +след каждого запроса и регистрация причин внутренних ошибок. + +## What Changes + +- Конфигурация логирования: `LOG_LEVEL` (`debug|info|warn|error`, по умолчанию `info`) + и `LOG_FORMAT` (`json|text`, по умолчанию `json`); `main.go` строит `slog`-handler + из конфига вместо жёсткого `LevelInfo`. +- Gin-middleware: `request_id` (из заголовка `X-Request-ID` либо сгенерированный) + кладётся в контекст запроса; access-лог уровня `debug` с полями method, route, + status, latency, bytes, client_ip, user_id, request_id. +- Регистрация внутренних ошибок: не-`AppError` из `httpx.RespondError`/`Abort` + становятся регистрируемыми и пишутся на уровне `error` с `request_id` и причиной; + отказы 4xx — на уровне `debug`. +- Приватность: не логируются query-строка (`?token=`), подписанные URL и тела + запросов; `/api/health` исключён всегда, `/api/objects/*` и `/api/sse/*` — только `debug`. +- CLI-команды (`migrate`, `reconcile`, `backfill-exif`) не меняются. + +## Capabilities + +### New Capabilities +- `observability`: конфигурируемое структурированное логирование сервера — уровень и формат вывода, access-лог запросов с корреляцией и регистрация причин внутренних ошибок. + +### Modified Capabilities + + +## Impact + +- `backend/internal/config` (секция `Log` + env), `backend/cmd/server/main.go` (сборка handler из конфига). +- `backend/internal/app` (middleware логирования), `backend/internal/httpx` (регистрация внутренних ошибок). +- `.env.example`, `README.md`. +- API, схема БД и хранилище не меняются. При дефолтном `LOG_LEVEL=info` объём обычных + логов почти не растёт: access-строки и 4xx остаются на уровне `debug`. diff --git a/openspec/changes/archive/2026-10-11-add-observability-logging/specs/observability/spec.md b/openspec/changes/archive/2026-10-11-add-observability-logging/specs/observability/spec.md new file mode 100644 index 0000000..12c37f8 --- /dev/null +++ b/openspec/changes/archive/2026-10-11-add-observability-logging/specs/observability/spec.md @@ -0,0 +1,102 @@ +# Spec Delta + +## Purpose + +Конфигурируемое структурированное логирование сервера: уровень и формат вывода, +access-лог запросов с корреляцией по идентификатору и регистрация причин внутренних +ошибок. + +## ADDED Requirements + +### Requirement: Уровень и формат логов +Сервер SHALL настраивать уровень и формат логирования из переменных окружения `LOG_LEVEL` +(`debug|info|warn|error`) и `LOG_FORMAT` (`json|text`) со значениями по умолчанию `info` +и `json` соответственно. + +#### Scenario: Подробный режим +- **WHEN** задан `LOG_LEVEL=debug` +- **THEN** выводятся подробные строки, включая access-строки и отказы 4xx + +#### Scenario: Некорректное значение +- **WHEN** `LOG_LEVEL` или `LOG_FORMAT` содержит недопустимое значение +- **THEN** сервер не стартует и сообщает явную ошибку конфигурации + +#### Scenario: Текстовый формат +- **WHEN** задан `LOG_FORMAT=text` +- **THEN** логи выводятся в текстовом формате + +### Requirement: Идентификатор запроса +Сервер SHALL присваивать каждому HTTP-запросу идентификатор: принимать валидный +`X-Request-ID` либо генерировать новый, SHALL включать его во все логи этого запроса и +SHALL возвращать его в заголовке ответа `X-Request-ID`. + +#### Scenario: Идентификатор передан клиентом +- **WHEN** запрос содержит валидный заголовок `X-Request-ID` +- **THEN** это значение используется как идентификатор запроса + +#### Scenario: Идентификатор сгенерирован +- **WHEN** заголовок `X-Request-ID` отсутствует или невалиден +- **THEN** сервер генерирует новый идентификатор + +#### Scenario: Эхо в ответе +- **WHEN** запрос обработан +- **THEN** ответ содержит заголовок `X-Request-ID` с использованным значением + +### Requirement: Access-лог запроса +На уровне `debug` сервер SHALL писать одну строку на завершённый HTTP-запрос с методом, +шаблоном маршрута (без query-строки), статусом, длительностью, объёмом ответа, клиентским +IP, идентификатором пользователя (если аутентифицирован) и идентификатором запроса. + +#### Scenario: Режим debug +- **WHEN** задан `LOG_LEVEL=debug` +- **THEN** после обработки запроса появляется access-строка + +#### Scenario: Обычный режим +- **WHEN** задан `LOG_LEVEL=info` +- **THEN** access-строки не пишутся + +#### Scenario: Без query-строки +- **WHEN** запрос содержит query-параметры +- **THEN** query-параметры в access-строку не попадают + +### Requirement: Регистрация внутренних ошибок +Сервер SHALL логировать причину внутренних ошибок: ошибки, не являющиеся ожидаемыми +`AppError`, SHALL писаться на уровне `error` с исходной причиной и идентификатором +запроса; ожидаемые отказы со статусом ниже 500 SHALL писаться на уровне `debug`, а +со статусом 500 и выше — на уровне `error`. + +#### Scenario: Внутренняя ошибка +- **WHEN** обработка запроса завершается неожиданной ошибкой +- **THEN** её причина логируется на уровне `error` вместе с идентификатором запроса + +#### Scenario: Ожидаемый отказ +- **WHEN** запрос отклонён ожидаемой ошибкой со статусом 4xx +- **THEN** на уровне `info` причина не логируется, а на уровне `debug` — логируется + +#### Scenario: Клиентское сообщение не подменяет причину +- **WHEN** клиент получает обобщённый ответ о внутренней ошибке +- **THEN** в логе сохраняется исходная причина + +### Requirement: Фильтрация access-логов +Сервер SHALL всегда исключать маршрут `/api/health` из access-логов и SHALL писать +access-логи для маршрутов `/api/objects/*` и `/api/sse/*` только на уровне `debug`. + +#### Scenario: Health исключён +- **WHEN** запрошен `/api/health` +- **THEN** access-строка не пишется даже на уровне `debug` + +#### Scenario: Объекты и SSE +- **WHEN** запрошен `/api/objects/*` или `/api/sse/*` и задан `LOG_LEVEL=debug` +- **THEN** access-строка пишется + +### Requirement: Приватность логов +Сервер SHALL не записывать в логи query-строку запроса, заголовок `Authorization`, тела +запросов, пароли и подписанные URL. + +#### Scenario: Токен в query +- **WHEN** авторизация передана через query-параметр `token` +- **THEN** его значение не попадает в логи + +#### Scenario: Тело запроса не логируется +- **WHEN** запрос содержит тело (JSON или multipart) +- **THEN** содержимое тела не попадает в логи diff --git a/openspec/changes/archive/2026-10-11-add-observability-logging/tasks.md b/openspec/changes/archive/2026-10-11-add-observability-logging/tasks.md new file mode 100644 index 0000000..b5d74ac --- /dev/null +++ b/openspec/changes/archive/2026-10-11-add-observability-logging/tasks.md @@ -0,0 +1,24 @@ +# Tasks + +## 1. Конфигурация логирования (A) + +- [x] 1.1 Добавить пакет `backend/internal/logging` с разбором уровня (`ParseLevel`) и сборкой handler (`NewHandler(format, level)`); проверка — `go test ./internal/logging` покрывает разбор `debug|info|warn|error`, `json|text` и ошибки. +- [x] 1.2 Добавить секцию `Log` в `config.Config` и чтение `LOG_LEVEL`/`LOG_FORMAT` с валидацией; проверка — `go test ./internal/config` покрывает значения по умолчанию и отказ на недопустимом значении. +- [x] 1.3 Строить `slog`-handler в `cmd/server/main.go` из `cfg.Log` вместо жёсткого `LevelInfo`; проверка — запуск с `LOG_LEVEL=debug`/`LOG_FORMAT=text` меняет вывод, а недопустимый `LOG_LEVEL` завершает старт явной ошибкой. +- [x] 1.4 Описать `LOG_LEVEL`/`LOG_FORMAT` в `.env.example` и `README.md`; проверка — задокументированный запуск с `LOG_LEVEL=debug` выводит подробные строки. + +## 2. Идентификатор запроса и access-лог (B) + +- [x] 2.1 Middleware в `app.Router()`: `request_id` из валидного `X-Request-ID` либо сгенерированный, запись в контекст запроса и заголовок ответа `X-Request-ID`; проверка — тест: переданный id сохраняется и возвращается, отсутствующий генерируется. +- [x] 2.2 Access-строка уровня `debug` (method, route `c.FullPath()`, status, latency, bytes, client_ip, user_id, request_id) без query; проверка — тест: на `debug` строка пишется, на `info` нет, query-параметры не попадают. +- [x] 2.3 Фильтрация access-логов: `/api/health` исключён всегда, `/api/objects/*` и `/api/sse/*` — только `debug`; проверка — тест на наборе маршрутов и уровне. + +## 3. Регистрация внутренних ошибок (D) + +- [x] 3.1 В `httpx.RespondError`/`Abort` регистрировать не-`AppError` через `c.Error(err)`; проверка — тест: неизвестная ошибка попадает в `c.Errors`, ответ остаётся обобщённым `500`. +- [x] 3.2 Логировать собранные ошибки в middleware: не-`AppError` и `AppError` со статусом `>=500` — уровень `error` с причиной и request_id, `AppError <500` — уровень `debug`; проверка — тест с буфером лога на обе ветки. +- [x] 3.3 Гарантировать приватность: не логировать query-строку, `Authorization` и тела запросов; проверка — тест с `?token=...` и телом убеждается, что значения не встречаются в буфере лога. + +## 4. Интеграционная проверка + +- [x] 4.1 Прогнать локальный инстанс с `LOG_LEVEL=debug`, выполнить несколько запросов (включая аутентифицированный и `/api/health`) и убедиться: access-строки есть, `X-Request-ID` возвращается в ответе, `/api/health` не логируется, секреты в логах отсутствуют. diff --git a/openspec/specs/observability/spec.md b/openspec/specs/observability/spec.md new file mode 100644 index 0000000..ba697d5 --- /dev/null +++ b/openspec/specs/observability/spec.md @@ -0,0 +1,102 @@ +# observability Specification + +## Purpose + +Конфигурируемое структурированное логирование сервера: уровень и формат вывода, +access-лог запросов с корреляцией по идентификатору и регистрация причин внутренних +ошибок. + +## Requirements + +### Requirement: Уровень и формат логов +Сервер SHALL настраивать уровень и формат логирования из переменных окружения `LOG_LEVEL` +(`debug|info|warn|error`) и `LOG_FORMAT` (`json|text`) со значениями по умолчанию `info` +и `json` соответственно. + +#### Scenario: Подробный режим +- **WHEN** задан `LOG_LEVEL=debug` +- **THEN** выводятся подробные строки, включая access-строки и отказы 4xx + +#### Scenario: Некорректное значение +- **WHEN** `LOG_LEVEL` или `LOG_FORMAT` содержит недопустимое значение +- **THEN** сервер не стартует и сообщает явную ошибку конфигурации + +#### Scenario: Текстовый формат +- **WHEN** задан `LOG_FORMAT=text` +- **THEN** логи выводятся в текстовом формате + +### Requirement: Идентификатор запроса +Сервер SHALL присваивать каждому HTTP-запросу идентификатор: принимать валидный +`X-Request-ID` либо генерировать новый, SHALL включать его во все логи этого запроса и +SHALL возвращать его в заголовке ответа `X-Request-ID`. + +#### Scenario: Идентификатор передан клиентом +- **WHEN** запрос содержит валидный заголовок `X-Request-ID` +- **THEN** это значение используется как идентификатор запроса + +#### Scenario: Идентификатор сгенерирован +- **WHEN** заголовок `X-Request-ID` отсутствует или невалиден +- **THEN** сервер генерирует новый идентификатор + +#### Scenario: Эхо в ответе +- **WHEN** запрос обработан +- **THEN** ответ содержит заголовок `X-Request-ID` с использованным значением + +### Requirement: Access-лог запроса +На уровне `debug` сервер SHALL писать одну строку на завершённый HTTP-запрос с методом, +шаблоном маршрута (без query-строки), статусом, длительностью, объёмом ответа, клиентским +IP, идентификатором пользователя (если аутентифицирован) и идентификатором запроса. + +#### Scenario: Режим debug +- **WHEN** задан `LOG_LEVEL=debug` +- **THEN** после обработки запроса появляется access-строка + +#### Scenario: Обычный режим +- **WHEN** задан `LOG_LEVEL=info` +- **THEN** access-строки не пишутся + +#### Scenario: Без query-строки +- **WHEN** запрос содержит query-параметры +- **THEN** query-параметры в access-строку не попадают + +### Requirement: Регистрация внутренних ошибок +Сервер SHALL логировать причину внутренних ошибок: ошибки, не являющиеся ожидаемыми +`AppError`, SHALL писаться на уровне `error` с исходной причиной и идентификатором +запроса; ожидаемые отказы со статусом ниже 500 SHALL писаться на уровне `debug`, а +со статусом 500 и выше — на уровне `error`. + +#### Scenario: Внутренняя ошибка +- **WHEN** обработка запроса завершается неожиданной ошибкой +- **THEN** её причина логируется на уровне `error` вместе с идентификатором запроса + +#### Scenario: Ожидаемый отказ +- **WHEN** запрос отклонён ожидаемой ошибкой со статусом 4xx +- **THEN** на уровне `info` причина не логируется, а на уровне `debug` — логируется + +#### Scenario: Клиентское сообщение не подменяет причину +- **WHEN** клиент получает обобщённый ответ о внутренней ошибке +- **THEN** в логе сохраняется исходная причина + +### Requirement: Фильтрация access-логов +Сервер SHALL всегда исключать маршрут `/api/health` из access-логов и SHALL писать +access-логи для маршрутов `/api/objects/*` и `/api/sse/*` только на уровне `debug`. + +#### Scenario: Health исключён +- **WHEN** запрошен `/api/health` +- **THEN** access-строка не пишется даже на уровне `debug` + +#### Scenario: Объекты и SSE +- **WHEN** запрошен `/api/objects/*` или `/api/sse/*` и задан `LOG_LEVEL=debug` +- **THEN** access-строка пишется + +### Requirement: Приватность логов +Сервер SHALL не записывать в логи query-строку запроса, заголовок `Authorization`, тела +запросов, пароли и подписанные URL. + +#### Scenario: Токен в query +- **WHEN** авторизация передана через query-параметр `token` +- **THEN** его значение не попадает в логи + +#### Scenario: Тело запроса не логируется +- **WHEN** запрос содержит тело (JSON или multipart) +- **THEN** содержимое тела не попадает в логи