feat(api): add structured JSON access log with request-id correlation

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"])
+	}
+}

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)