From 1d4b1cccfd1ea147d8e91bb005c0e9cf0861fdd5 Mon Sep 17 00:00:00 2001 From: Christophe Vila Date: Sun, 26 Jul 2026 14:30:39 +0200 Subject: [PATCH] feat(api): add structured JSON access log with request-id correlation --- backend/cmd/geniusrund/main.go | 4 ++ backend/internal/api/api_test.go | 59 ++++++++++++++++++++++++++ backend/internal/api/server.go | 35 +++++++++++++++ backend/internal/config/config.go | 3 ++ backend/internal/config/config_test.go | 26 ++++++++++++ 5 files changed, 127 insertions(+) diff --git a/backend/cmd/geniusrund/main.go b/backend/cmd/geniusrund/main.go index bc1baa2..f5ef198 100644 --- a/backend/cmd/geniusrund/main.go +++ b/backend/cmd/geniusrund/main.go @@ -6,12 +6,15 @@ package main import ( "context" "log" + "log/slog" "net/http" + "os" "os/signal" "syscall" "time" "geniusrun/backend/internal/api" + "geniusrun/backend/internal/applog" "geniusrun/backend/internal/auth" "geniusrun/backend/internal/config" "geniusrun/backend/internal/garmin" @@ -24,6 +27,7 @@ func main() { if err != nil { log.Fatalf("config: %v", err) } + slog.SetDefault(applog.NewLogger(cfg.LogLevel, os.Stdout)) db, err := store.Open(cfg.DBPath) if err != nil { diff --git a/backend/internal/api/api_test.go b/backend/internal/api/api_test.go index a6db7f3..a4ded69 100644 --- a/backend/internal/api/api_test.go +++ b/backend/internal/api/api_test.go @@ -5,6 +5,7 @@ import ( "context" "encoding/json" "fmt" + "log/slog" "net/http" "net/http/httptest" "net/url" @@ -14,6 +15,7 @@ import ( "testing" "time" + "geniusrun/backend/internal/applog" "geniusrun/backend/internal/auth" authmock "geniusrun/backend/internal/auth/mock" "geniusrun/backend/internal/garmin" @@ -1132,3 +1134,60 @@ func TestSessionCallback_MintsSessionCookieCarryingIDToken(t *testing.T) { t.Errorf("claims.IDToken = %q, want %q", claims.IDToken, "raw-id-token-jwt") } } + +func TestRequestLoggingMiddleware_LogsMethodPathStatusDuration(t *testing.T) { + s, _, _ := newTestServer(t) + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + + req := httptest.NewRequest(http.MethodGet, "/api/health", nil) + req = req.WithContext(applog.WithLogger(req.Context(), logger)) + rec := httptest.NewRecorder() + s.Router().ServeHTTP(rec, req) + + var entry map[string]any + if err := json.Unmarshal(buf.Bytes(), &entry); err != nil { + t.Fatalf("log output is not valid JSON: %v (%q)", err, buf.String()) + } + if entry["msg"] != "http request" { + t.Errorf("msg = %v, want \"http request\"", entry["msg"]) + } + if entry["method"] != "GET" || entry["path"] != "/api/health" { + t.Errorf("method/path = %v/%v, want GET//api/health", entry["method"], entry["path"]) + } + if entry["status"] != float64(http.StatusOK) { + t.Errorf("status = %v, want 200", entry["status"]) + } + if _, ok := entry["duration_ms"]; !ok { + t.Error("expected a duration_ms field") + } +} + +func TestRequestLoggingMiddleware_5xxLogsAtWarnLevel(t *testing.T) { + s, db, _ := newTestServer(t) + db.Close() // force a downstream DB call to fail with a 500 + + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + + req := httptest.NewRequest(http.MethodGet, "/api/profile", nil) + req = req.WithContext(applog.WithLogger(req.Context(), logger)) + cookie, err := auth.MintSessionCookie(auth.Claims{Sub: "test-user", Name: "Test User", Email: "test@example.com"}, testSessionConfig.Secret, testSessionConfig.Duration, testSessionConfig.Secure) + if err != nil { + t.Fatalf("mint session cookie: %v", err) + } + req.AddCookie(cookie) + rec := httptest.NewRecorder() + s.Router().ServeHTTP(rec, req) + + if rec.Code != http.StatusInternalServerError { + t.Fatalf("expected the request itself to 500 after closing the DB, got %d", rec.Code) + } + var entry map[string]any + if err := json.Unmarshal(buf.Bytes(), &entry); err != nil { + t.Fatalf("log output is not valid JSON: %v (%q)", err, buf.String()) + } + if entry["level"] != "WARN" { + t.Errorf("level = %v, want WARN for a 5xx response", entry["level"]) + } +} diff --git a/backend/internal/api/server.go b/backend/internal/api/server.go index ee18af2..9ce2401 100644 --- a/backend/internal/api/server.go +++ b/backend/internal/api/server.go @@ -9,15 +9,19 @@ import ( "encoding/json" "fmt" "log" + "log/slog" "net/http" "os" "path/filepath" "strconv" "sync" + "sync/atomic" "time" "github.com/go-chi/chi/v5" + "github.com/go-chi/chi/v5/middleware" + "geniusrun/backend/internal/applog" "geniusrun/backend/internal/auth" "geniusrun/backend/internal/garmin" "geniusrun/backend/internal/store" @@ -285,9 +289,40 @@ func (s *Server) RunIncrementalSyncForAllUsers(ctx context.Context) { } } +var requestIDCounter atomic.Int64 + +// requestLoggingMiddleware logs one JSON line per HTTP request (method, +// path, status, duration) and attaches a per-request logger (tagged with a +// request_id) to the request context, so any downstream call this request +// triggers -- e.g. a Garmin wrapper round-trip -- logs with the same +// correlating id (see internal/applog, internal/garmin's roundTrip). +func requestLoggingMiddleware(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + id := fmt.Sprintf("req-%d", requestIDCounter.Add(1)) + logger := applog.FromContext(r.Context()).With("request_id", id) + r = r.WithContext(applog.WithLogger(r.Context(), logger)) + + ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) + start := time.Now() + next.ServeHTTP(ww, r) + + level := slog.LevelInfo + if ww.Status() >= 500 { + level = slog.LevelWarn + } + logger.LogAttrs(r.Context(), level, "http request", + slog.String("method", r.Method), + slog.String("path", r.URL.Path), + slog.Int("status", ww.Status()), + slog.Int64("duration_ms", time.Since(start).Milliseconds()), + ) + }) +} + // Router builds the HTTP routes. func (s *Server) Router() http.Handler { r := chi.NewRouter() + r.Use(requestLoggingMiddleware) r.Use(corsMiddleware) r.Route("/api", func(r chi.Router) { r.Get("/health", s.handleHealth) diff --git a/backend/internal/config/config.go b/backend/internal/config/config.go index 90ec0b0..37d95eb 100644 --- a/backend/internal/config/config.go +++ b/backend/internal/config/config.go @@ -37,6 +37,8 @@ type Config struct { MinConfidence float64 IncrementalSyncEvery time.Duration + // LogLevel controls internal/applog's JSON logger ("debug"|"info"|"warn"|"error"). + LogLevel string // OIDC login gate (Keycloak). BackendURL is this app's own externally // reachable origin (e.g. "https://geniusrun.example.com") -- it derives @@ -75,6 +77,7 @@ func Load() (Config, error) { GarminTokenStoreRoot: os.Getenv("GARMIN_TOKENSTORE"), MinConfidence: getEnvFloat("GENIUSRUN_MIN_CONFIDENCE", 0.6), IncrementalSyncEvery: getEnvDuration("GENIUSRUN_INCREMENTAL_SYNC_EVERY", 6*time.Hour), + LogLevel: getEnvDefault("GENIUSRUN_LOG_LEVEL", "info"), BackendURL: strings.TrimRight(os.Getenv("GENIUSRUN_BACKEND_URL"), "/"), OIDCIssuerURL: os.Getenv("GENIUSRUN_OIDC_ISSUER_URL"), OIDCClientID: os.Getenv("GENIUSRUN_OIDC_CLIENT_ID"), diff --git a/backend/internal/config/config_test.go b/backend/internal/config/config_test.go index ec09c9d..2508924 100644 --- a/backend/internal/config/config_test.go +++ b/backend/internal/config/config_test.go @@ -108,6 +108,32 @@ func TestLoad_GarminTokenStoreRootExplicitOverridesDefault(t *testing.T) { } } +func TestLoad_LogLevelDefaultsToInfo(t *testing.T) { + setRequiredEnv(t) + t.Setenv("GENIUSRUN_LOG_LEVEL", "") + + cfg, err := Load() + if err != nil { + t.Fatalf("Load: %v", err) + } + if cfg.LogLevel != "info" { + t.Errorf("LogLevel = %q, want default %q", cfg.LogLevel, "info") + } +} + +func TestLoad_LogLevelExplicitOverridesDefault(t *testing.T) { + setRequiredEnv(t) + t.Setenv("GENIUSRUN_LOG_LEVEL", "debug") + + cfg, err := Load() + if err != nil { + t.Fatalf("Load: %v", err) + } + if cfg.LogLevel != "debug" { + t.Errorf("LogLevel = %q, want debug", cfg.LogLevel) + } +} + func TestLoad_GarminPythonPathDefaultsToPython3(t *testing.T) { setRequiredEnv(t) t.Setenv("GARMIN_WRAPPER_PYTHON", "")