From 7346e2eadd2e3e66826f2b7f7a543d288132a3a8 Mon Sep 17 00:00:00 2001 From: Christophe Vila Date: Sun, 26 Jul 2026 14:36:04 +0200 Subject: [PATCH] docs: add implementation plan for structured JSON logging --- .../2026-07-26-structured-json-logging.md | 961 ++++++++++++++++++ 1 file changed, 961 insertions(+) create mode 100644 docs/superpowers/plans/2026-07-26-structured-json-logging.md diff --git a/docs/superpowers/plans/2026-07-26-structured-json-logging.md b/docs/superpowers/plans/2026-07-26-structured-json-logging.md new file mode 100644 index 0000000..25c8403 --- /dev/null +++ b/docs/superpowers/plans/2026-07-26-structured-json-logging.md @@ -0,0 +1,961 @@ +# Structured JSON Logging Implementation Plan + +> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. + +**Goal:** Emit structured JSON logs on stdout for (1) every HTTP API request and (2) every Garmin wrapper subprocess call, correlated by a per-request id — without touching any existing `log.Printf` call site. + +**Architecture:** A new `internal/applog` package wraps `log/slog` with a JSON handler plus context helpers (`WithLogger`/`FromContext`). `internal/api` gains a `requestLoggingMiddleware` that logs one line per HTTP request and stashes a request-id-tagged logger into the request context. `internal/garmin`'s `client.go` reads that same logger back out of context (via the `ctx` every `Client` method already receives) inside `roundTrip`, the single funnel point all six Garmin calls go through, logging one line per subprocess round-trip. + +**Tech Stack:** Go stdlib `log/slog` (no new dependency), `github.com/go-chi/chi/v5/middleware` (already-available subpackage of the existing chi dependency). + +## Global Constraints + +- Existing `log.Printf`/`log.Fatalf` call sites are untouched — they keep going to stderr, unstructured, exactly as today. +- Garmin credentials must never be logged. Confirmed safe: `authenticate`/`complete_mfa`/`call` wire params never carry email/password (only env vars at subprocess spawn do) — logging `params` in full is safe everywhere in `roundTrip`. +- `gofmt -l .` must report nothing; `go vet ./...` and `go build ./...` must pass. + +--- + +### Task 1: `internal/applog` — JSON logger + context helpers + +**Files:** +- Create: `backend/internal/applog/applog.go` +- Create: `backend/internal/applog/applog_test.go` + +**Interfaces:** +- Produces: `func NewLogger(level string, w io.Writer) *slog.Logger`, `func WithLogger(ctx context.Context, logger *slog.Logger) context.Context`, `func FromContext(ctx context.Context) *slog.Logger` (never nil — falls back to `slog.Default()`). + +- [ ] **Step 1: Write the failing tests** + +Create `backend/internal/applog/applog_test.go`: + +```go +package applog + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "strings" + "testing" +) + +func TestNewLogger_FiltersBelowConfiguredLevel(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger("warn", &buf) + + logger.Info("should be dropped") + if buf.Len() != 0 { + t.Fatalf("expected no output for an Info message under a warn-level logger, got %q", buf.String()) + } + + logger.Warn("should appear") + if !strings.Contains(buf.String(), "should appear") { + t.Fatalf("expected the Warn message in output, got %q", buf.String()) + } +} + +func TestNewLogger_WritesValidJSON(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger("info", &buf) + logger.Info("hello", "key", "value") + + var decoded map[string]any + if err := json.Unmarshal(buf.Bytes(), &decoded); err != nil { + t.Fatalf("output is not valid JSON: %v (%q)", err, buf.String()) + } + if decoded["msg"] != "hello" || decoded["key"] != "value" { + t.Errorf("decoded = %+v, want msg=hello key=value", decoded) + } +} + +func TestWithLogger_FromContext_RoundTrip(t *testing.T) { + logger := slog.New(slog.NewJSONHandler(&bytes.Buffer{}, nil)) + ctx := WithLogger(context.Background(), logger) + + if got := FromContext(ctx); got != logger { + t.Errorf("FromContext returned a different logger than what was stashed") + } +} + +func TestFromContext_DefaultsWhenNoneSet(t *testing.T) { + if got := FromContext(context.Background()); got == nil { + t.Fatal("FromContext on a bare context returned nil, want slog.Default()") + } +} +``` + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `cd backend && go test ./internal/applog/... -v` +Expected: FAIL — package `internal/applog` doesn't exist yet (build failure). + +- [ ] **Step 3: Create `backend/internal/applog/applog.go`** + +```go +// Package applog provides geniusrun's structured JSON logging: a +// log/slog-based logger writing to stdout, plus context helpers so a +// logger enriched in one layer (e.g. internal/api's HTTP middleware, +// attaching a request_id) is picked up by another (e.g. internal/garmin's +// wrapper-call logging) without either package depending on the other. +package applog + +import ( + "context" + "io" + "log/slog" + "strings" +) + +// NewLogger builds a JSON-handler *slog.Logger writing to w at the given +// level ("debug"|"info"|"warn"|"error", case-insensitive; anything else +// defaults to info). +func NewLogger(level string, w io.Writer) *slog.Logger { + return slog.New(slog.NewJSONHandler(w, &slog.HandlerOptions{Level: parseLevel(level)})) +} + +func parseLevel(level string) slog.Level { + switch strings.ToLower(level) { + case "debug": + return slog.LevelDebug + case "warn": + return slog.LevelWarn + case "error": + return slog.LevelError + default: + return slog.LevelInfo + } +} + +type ctxKey struct{} + +// WithLogger returns a context carrying logger, retrievable via FromContext. +func WithLogger(ctx context.Context, logger *slog.Logger) context.Context { + return context.WithValue(ctx, ctxKey{}, logger) +} + +// FromContext returns the logger stashed by WithLogger, or slog.Default() +// if none was -- callers (e.g. the background incremental-sync loop, or +// tests that don't bother injecting one) always get a working logger, +// never nil. +func FromContext(ctx context.Context) *slog.Logger { + if logger, ok := ctx.Value(ctxKey{}).(*slog.Logger); ok { + return logger + } + return slog.Default() +} +``` + +- [ ] **Step 4: Run tests to verify they pass** + +Run: `cd backend && go test ./internal/applog/... -v` +Expected: PASS. + +- [ ] **Step 5: Commit** + +```bash +git add backend/internal/applog +git commit -m "feat(applog): add JSON logger and context helpers" +``` + +--- + +### Task 2: HTTP access log middleware + +**Files:** +- Modify: `backend/internal/config/config.go` (new `LogLevel` field) +- Modify: `backend/internal/config/config_test.go` (new tests) +- Modify: `backend/cmd/geniusrund/main.go` (wire up `slog.SetDefault`) +- Modify: `backend/internal/api/server.go` (`requestLoggingMiddleware`, registered in `Router()`) +- Modify: `backend/internal/api/api_test.go` (new tests) + +**Interfaces:** +- Consumes: `applog.NewLogger`, `applog.WithLogger`, `applog.FromContext` (Task 1). +- Produces: `requestLoggingMiddleware` (unexported chi middleware in `internal/api`), `config.Config.LogLevel string`. + +- [ ] **Step 1: Write the failing config tests** + +Append to `backend/internal/config/config_test.go`: + +```go +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) + } +} +``` + +- [ ] **Step 2: Write the failing API tests** + +Add `"log/slog"` to `backend/internal/api/api_test.go`'s stdlib import group, and `"geniusrun/backend/internal/applog"` to its internal import group. + +Append to `backend/internal/api/api_test.go`: + +```go +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"]) + } +} +``` + +- [ ] **Step 3: Run tests to verify they fail** + +Run: `cd backend && go test ./internal/config/... ./internal/api/... -run 'TestLoad_LogLevel|TestRequestLoggingMiddleware' -v` +Expected: FAIL — `LogLevel` field doesn't exist on `Config`; `applog` import unresolved; no log output produced (middleware doesn't exist). + +- [ ] **Step 4: Add `LogLevel` to `config.go`** + +Change: + +```go + MinConfidence float64 + IncrementalSyncEvery time.Duration +``` + +to: + +```go + MinConfidence float64 + IncrementalSyncEvery time.Duration + // LogLevel controls internal/applog's JSON logger ("debug"|"info"|"warn"|"error"). + LogLevel string +``` + +Change: + +```go + IncrementalSyncEvery: getEnvDuration("GENIUSRUN_INCREMENTAL_SYNC_EVERY", 6*time.Hour), +``` + +to: + +```go + IncrementalSyncEvery: getEnvDuration("GENIUSRUN_INCREMENTAL_SYNC_EVERY", 6*time.Hour), + LogLevel: getEnvDefault("GENIUSRUN_LOG_LEVEL", "info"), +``` + +- [ ] **Step 5: Add the middleware to `server.go`** + +Change the import block: + +```go +import ( + "context" + "crypto/sha256" + "encoding/hex" + "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" + appsync "geniusrun/backend/internal/sync" +) +``` + +Insert this above `// Router builds the HTTP routes.`: + +```go +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()), + ) + }) +} +``` + +Change `Router()`'s opening lines: + +```go +func (s *Server) Router() http.Handler { + r := chi.NewRouter() + r.Use(corsMiddleware) +``` + +to: + +```go +func (s *Server) Router() http.Handler { + r := chi.NewRouter() + r.Use(requestLoggingMiddleware) + r.Use(corsMiddleware) +``` + +- [ ] **Step 6: Wire `slog.SetDefault` into `main.go`** + +Change the import block: + +```go +import ( + "context" + "log" + "net/http" + "os/signal" + "syscall" + "time" + + "geniusrun/backend/internal/api" + "geniusrun/backend/internal/auth" + "geniusrun/backend/internal/config" + "geniusrun/backend/internal/garmin" + "geniusrun/backend/internal/store" + appsync "geniusrun/backend/internal/sync" +) +``` + +to: + +```go +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" + "geniusrun/backend/internal/store" + appsync "geniusrun/backend/internal/sync" +) +``` + +Change: + +```go + cfg, err := config.Load() + if err != nil { + log.Fatalf("config: %v", err) + } + + db, err := store.Open(cfg.DBPath) +``` + +to: + +```go + cfg, err := config.Load() + if err != nil { + log.Fatalf("config: %v", err) + } + slog.SetDefault(applog.NewLogger(cfg.LogLevel, os.Stdout)) + + db, err := store.Open(cfg.DBPath) +``` + +- [ ] **Step 7: Run tests to verify they pass** + +Run: `cd backend && go test ./internal/config/... ./internal/api/... -run 'TestLoad_LogLevel|TestRequestLoggingMiddleware' -v` +Expected: PASS. + +- [ ] **Step 8: Run the full backend test suite** + +Run: `cd backend && go build ./... && go vet ./... && gofmt -l . && go test ./...` +Expected: `gofmt -l .` empty; everything passes. + +- [ ] **Step 9: Commit** + +```bash +git add backend/internal/config/config.go backend/internal/config/config_test.go backend/cmd/geniusrund/main.go backend/internal/api/server.go backend/internal/api/api_test.go +git commit -m "feat(api): add structured JSON access log with request-id correlation" +``` + +--- + +### Task 3: Garmin wrapper call log + +**Files:** +- Modify: `backend/internal/garmin/client.go` (`roundTrip`, `ensureStarted`, all six call sites) +- Modify: `backend/internal/garmin/client_test.go` (update 3 direct-`roundTrip` calls, add 2 new tests) + +**Interfaces:** +- Consumes: `applog.FromContext` (Task 1). +- Produces: `func (c *subprocessClient) roundTrip(ctx context.Context, cmdName string, params any) (result json.RawMessage, err error)` (signature change — `ctx` added as first param), `func (c *subprocessClient) ensureStarted(ctx context.Context) error` (signature change — `ctx` added). + +- [ ] **Step 1: Update the 3 existing direct-`roundTrip` tests and write the 2 new failing tests** + +In `backend/internal/garmin/client_test.go`, add `"bytes"` and `"log/slog"` to the stdlib import block, and add `"geniusrun/backend/internal/applog"` as a new import group. + +Change (in `TestSubprocessClient_RoundTrip_DetectsIDMismatch`): + +```go + _, err := c.roundTrip("authenticate", nil) +``` + +to: + +```go + _, err := c.roundTrip(context.Background(), "authenticate", nil) +``` + +Change (in `TestSubprocessClient_RoundTrip_SubprocessClosedIsError`): + +```go + _, err := c.roundTrip("authenticate", nil) +``` + +to: + +```go + _, err := c.roundTrip(context.Background(), "authenticate", nil) +``` + +Change (in `TestSubprocessClient_RoundTrip_WrapperErrorPropagates`): + +```go + _, err := c.roundTrip("authenticate", nil) +``` + +to: + +```go + _, err := c.roundTrip(context.Background(), "authenticate", nil) +``` + +Append two new tests: + +```go +func TestSubprocessClient_RoundTrip_LogsCallWithResultPreview(t *testing.T) { + c := newFakeWrapperClient(t, func(cmd string, params json.RawMessage) wireResponsePayload { + return fakeResult(authResultWire{Status: "mfa_required", Message: "MFA required."}) + }) + + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + ctx := applog.WithLogger(context.Background(), logger) + + if _, err := c.Authenticate(ctx); err != nil { + t.Fatalf("Authenticate: %v", err) + } + + 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"] != "garmin wrapper call" { + t.Errorf("msg = %v, want \"garmin wrapper call\"", entry["msg"]) + } + if entry["cmd"] != "authenticate" { + t.Errorf("cmd = %v, want authenticate", entry["cmd"]) + } + preview, _ := entry["result_preview"].(string) + if !strings.Contains(preview, "mfa_required") { + t.Errorf("result_preview = %q, want it to contain mfa_required", preview) + } + if _, hasError := entry["error"]; hasError { + t.Errorf("expected no error field on a successful call, got %v", entry["error"]) + } +} + +func TestSubprocessClient_RoundTrip_LogsErrorAtWarnLevel(t *testing.T) { + c := newFakeWrapperClient(t, func(cmd string, params json.RawMessage) wireResponsePayload { + return fakeError("boom") + }) + + var buf bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&buf, nil)) + ctx := applog.WithLogger(context.Background(), logger) + + if _, err := c.Authenticate(ctx); err == nil { + t.Fatal("expected Authenticate to return an error") + } + + 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 failed call", entry["level"]) + } + if errMsg, _ := entry["error"].(string); !strings.Contains(errMsg, "boom") { + t.Errorf("error field = %q, want it to mention \"boom\"", errMsg) + } +} +``` + +- [ ] **Step 2: Run tests to verify they fail** + +Run: `cd backend && go test ./internal/garmin/... -run 'TestSubprocessClient_RoundTrip' -v` +Expected: FAIL — `roundTrip` still takes 2 args, not 3; `applog` import unresolved. + +- [ ] **Step 3: Update `client.go`** + +Change the import block: + +```go +import ( + "bufio" + "context" + _ "embed" + "encoding/json" + "fmt" + "io" + "os" + "os/exec" + "strconv" + "sync" +) +``` + +to: + +```go +import ( + "bufio" + "context" + _ "embed" + "encoding/json" + "fmt" + "io" + "log/slog" + "os" + "os/exec" + "strconv" + "sync" + "time" + + "geniusrun/backend/internal/applog" +) +``` + +Change `ensureStarted`'s signature and add the spawn log. From: + +```go +// ensureStarted spawns the wrapper subprocess if it isn't already running. +// Callers must hold c.mu. +func (c *subprocessClient) ensureStarted() error { + if c.started { + return nil + } +``` + +to: + +```go +// ensureStarted spawns the wrapper subprocess if it isn't already running. +// Callers must hold c.mu. +func (c *subprocessClient) ensureStarted(ctx context.Context) error { + if c.started { + return nil + } +``` + +And change its ending, from: + +```go + c.cmd = cmd + c.stdin = stdin + c.enc = json.NewEncoder(stdin) + scanner := bufio.NewScanner(stdout) + scanner.Buffer(make([]byte, 0, 64*1024), maxWrapperLineBytes) + c.scanner = scanner + c.started = true + c.nextID = 0 + return nil +} +``` + +to: + +```go + c.cmd = cmd + c.stdin = stdin + c.enc = json.NewEncoder(stdin) + scanner := bufio.NewScanner(stdout) + scanner.Buffer(make([]byte, 0, 64*1024), maxWrapperLineBytes) + c.scanner = scanner + c.started = true + c.nextID = 0 + + applog.FromContext(ctx).Info("garmin wrapper spawning", + "python_path", pythonPath, + "token_store_configured", c.cfg.TokenStorePath != "", + ) + return nil +} +``` + +Replace `roundTrip` entirely. From: + +```go +// roundTrip sends one request and returns its result payload, or an error +// if the wrapper reported one. Callers must hold c.mu and have already +// called ensureStarted. +func (c *subprocessClient) roundTrip(cmdName string, params any) (json.RawMessage, error) { + c.nextID++ + id := c.nextID + + if err := c.enc.Encode(wireRequest{ID: id, Cmd: cmdName, Params: params}); err != nil { + return nil, fmt.Errorf("write %s request: %w", cmdName, err) + } + + if !c.scanner.Scan() { + if err := c.scanner.Err(); err != nil { + return nil, fmt.Errorf("read %s response: %w", cmdName, err) + } + return nil, fmt.Errorf("read %s response: subprocess closed its output", cmdName) + } + + var resp wireResponse + if err := json.Unmarshal(c.scanner.Bytes(), &resp); err != nil { + return nil, fmt.Errorf("parse %s response: %w", cmdName, err) + } + if resp.ID != id { + return nil, fmt.Errorf("%s response id mismatch: got %d, want %d", cmdName, resp.ID, id) + } + if resp.Error != "" { + return nil, fmt.Errorf("%s: %s", cmdName, resp.Error) + } + return resp.Result, nil +} +``` + +to: + +```go +// roundTrip sends one request and returns its result payload, or an error +// if the wrapper reported one. Callers must hold c.mu and have already +// called ensureStarted. Logs exactly one "garmin wrapper call" line +// regardless of outcome (see internal/applog) -- cmd/params are always +// safe to log in full here: Garmin credentials only ever reach the +// subprocess via env vars at spawn time (see ensureStarted), never through +// these wire params. +func (c *subprocessClient) roundTrip(ctx context.Context, cmdName string, params any) (result json.RawMessage, err error) { + start := time.Now() + defer func() { + attrs := []slog.Attr{ + slog.String("cmd", cmdName), + slog.Any("params", params), + slog.Int64("duration_ms", time.Since(start).Milliseconds()), + } + level := slog.LevelInfo + if result != nil { + attrs = append(attrs, slog.String("result_preview", truncate(string(result), 500))) + } + if err != nil { + level = slog.LevelWarn + attrs = append(attrs, slog.String("error", err.Error())) + } + applog.FromContext(ctx).LogAttrs(context.Background(), level, "garmin wrapper call", attrs...) + }() + + c.nextID++ + id := c.nextID + + if err = c.enc.Encode(wireRequest{ID: id, Cmd: cmdName, Params: params}); err != nil { + err = fmt.Errorf("write %s request: %w", cmdName, err) + return nil, err + } + + if !c.scanner.Scan() { + if serr := c.scanner.Err(); serr != nil { + err = fmt.Errorf("read %s response: %w", cmdName, serr) + } else { + err = fmt.Errorf("read %s response: subprocess closed its output", cmdName) + } + return nil, err + } + + var resp wireResponse + if uerr := json.Unmarshal(c.scanner.Bytes(), &resp); uerr != nil { + err = fmt.Errorf("parse %s response: %w", cmdName, uerr) + return nil, err + } + if resp.ID != id { + err = fmt.Errorf("%s response id mismatch: got %d, want %d", cmdName, resp.ID, id) + return nil, err + } + if resp.Error != "" { + err = fmt.Errorf("%s: %s", cmdName, resp.Error) + return nil, err + } + result = resp.Result + return result, nil +} +``` + +Update the six call sites. In `Authenticate`: + +```go + if err := c.ensureStarted(); err != nil { + return AuthResult{}, err + } + raw, err := c.roundTrip("authenticate", nil) +``` + +to: + +```go + if err := c.ensureStarted(ctx); err != nil { + return AuthResult{}, err + } + raw, err := c.roundTrip(ctx, "authenticate", nil) +``` + +In `CompleteMFA`: + +```go + if err := c.ensureStarted(); err != nil { + return AuthResult{}, err + } + raw, err := c.roundTrip("complete_mfa", map[string]any{"code": code}) +``` + +to: + +```go + if err := c.ensureStarted(ctx); err != nil { + return AuthResult{}, err + } + raw, err := c.roundTrip(ctx, "complete_mfa", map[string]any{"code": code}) +``` + +In `GetActivities`: + +```go + if err := c.ensureStarted(); err != nil { + return nil, err + } + raw, err := c.roundTrip("call", callParams{ + Method: "get_activities_by_date", + Args: map[string]any{"startdate": startDate, "enddate": endDate}, + }) +``` + +to: + +```go + if err := c.ensureStarted(ctx); err != nil { + return nil, err + } + raw, err := c.roundTrip(ctx, "call", callParams{ + Method: "get_activities_by_date", + Args: map[string]any{"startdate": startDate, "enddate": endDate}, + }) +``` + +In `GetActivitySplits`: + +```go + if err := c.ensureStarted(); err != nil { + return ActivitySplits{}, err + } + raw, err := c.roundTrip("call", callParams{ + Method: "get_activity_splits", + Args: map[string]any{"activity_id": strconv.FormatInt(activityID, 10)}, + }) +``` + +to: + +```go + if err := c.ensureStarted(ctx); err != nil { + return ActivitySplits{}, err + } + raw, err := c.roundTrip(ctx, "call", callParams{ + Method: "get_activity_splits", + Args: map[string]any{"activity_id": strconv.FormatInt(activityID, 10)}, + }) +``` + +In `GetActivityDetails`: + +```go + if err := c.ensureStarted(); err != nil { + return ActivityDetails{}, err + } + raw, err := c.roundTrip("call", callParams{ + Method: "get_activity_details", + Args: map[string]any{"activity_id": strconv.FormatInt(activityID, 10)}, + }) +``` + +to: + +```go + if err := c.ensureStarted(ctx); err != nil { + return ActivityDetails{}, err + } + raw, err := c.roundTrip(ctx, "call", callParams{ + Method: "get_activity_details", + Args: map[string]any{"activity_id": strconv.FormatInt(activityID, 10)}, + }) +``` + +In `GetWorkoutByID`: + +```go + if err := c.ensureStarted(); err != nil { + return Workout{}, err + } + raw, err := c.roundTrip("call", callParams{ + Method: "get_workout_by_id", + Args: map[string]any{"workout_id": strconv.FormatInt(workoutID, 10)}, + }) +``` + +to: + +```go + if err := c.ensureStarted(ctx); err != nil { + return Workout{}, err + } + raw, err := c.roundTrip(ctx, "call", callParams{ + Method: "get_workout_by_id", + Args: map[string]any{"workout_id": strconv.FormatInt(workoutID, 10)}, + }) +``` + +- [ ] **Step 4: Run tests to verify they pass** + +Run: `cd backend && go test ./internal/garmin/... -v` +Expected: PASS (all existing tests still pass with the new `ctx` param threaded through; the 2 new logging tests pass). + +- [ ] **Step 5: Run the full backend test suite** + +Run: `cd backend && go build ./... && go vet ./... && gofmt -l . && go test ./...` +Expected: `gofmt -l .` empty; everything passes. + +- [ ] **Step 6: Commit** + +```bash +git add backend/internal/garmin/client.go backend/internal/garmin/client_test.go +git commit -m "feat(garmin): log every wrapper subprocess call as structured JSON" +``` + +--- + +### Task 4: Final verification + +**Files:** none (verification only) + +- [ ] **Step 1: Full backend check** + +Run: `cd backend && gofmt -l . && go vet ./... && go build ./... && go test ./...` +Expected: `gofmt -l .` empty; everything else passes. + +- [ ] **Step 2: Manual smoke check** + +Run the real server briefly (`cd backend && ./start.sh`, or `go run ./cmd/geniusrund` with the required env vars set) and confirm stdout shows JSON lines for at least a health-check request (`curl localhost:8080/api/health`) — one `"msg":"http request"` line with a `request_id`. This doesn't require a real Garmin account; it only confirms the JSON handler is actually wired to stdout in the real binary (as opposed to only passing in tests). + +- [ ] **Step 3: Commit (if anything drifted)** + +```bash +git add -A +git commit -m "fix: address final verification findings" +```