geniusrun/docs/superpowers/plans/2026-07-26-structured-json-logging.md

# 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 `loggingMiddleware` 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 `execute`, 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 `execute`.
- `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/log/log_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/log/log.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/envconfig.go` (new `LogLevel` field)
- Modify: `../../../backend/internal/config/envconfig_test.go` (new tests)
- Modify: `backend/cmd/geniusrund/main.go` (wire up `slog.SetDefault`)
- Modify: `backend/internal/api/server.go` (`loggingMiddleware`, registered in `Router()`)
- Modify: `backend/internal/api/api_test.go` (new tests)

**Interfaces:**
- Consumes: `applog.NewLogger`, `applog.WithLogger`, `applog.FromContext` (Task 1).
- Produces: `loggingMiddleware` (unexported chi middleware in `internal/api`), `config.Config.LogLevel string`.

- [ ] **Step 1: Write the failing config tests**

Append to `../../../backend/internal/config/envconfig_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 `envconfig.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/envconfig.go backend/internal/config/envconfig_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` (`execute`, `ensureStarted`, all six call sites)
- Modify: `backend/internal/garmin/client_test.go` (update 3 direct-`execute` 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-`execute` 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 — `execute` 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 `execute` 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"
```