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

# Structured JSON logging (API calls + Garmin wrapper calls)

Status: approved, not yet implemented.

## Problem

Motivated by a real debugging need: after implementing the deferred-commit
onboarding wizard, a login attempt reported `mfa_required` but no MFA code
ever arrived by email. There is currently no visibility into what actually
happened between geniusrun and the Garmin wrapper subprocess beyond raw,
unstructured stderr output.

**Likely root cause of that specific incident** (found while surveying the
code for this design, worth recording even though this task doesn't fix
it): `internal/garmin/pyscript/wrapper.py`'s `authenticate` handler blocks
on a 10-second queue read and, on timeout, unconditionally returns
`{"status": "mfa_required"}` -- regardless of whether `garminconnect` ever
actually called `prompt_mfa()`. A login that's merely slow (Garmin/Cloudflare
rate-limiting, already a documented trap in this codebase) looks identical
to a real MFA challenge. The only current way to tell them apart is a raw
stderr line (`"garminconnect invoked prompt_mfa()..."`, only emitted when
MFA is real) that's easy to miss. This design doesn't change that timeout
logic -- it makes the distinction visible in structured logs instead of
buried in stderr, which is the requested first step.

The user asked, specifically: JSON logs on stdout (for an existing
observability stack), for now covering only two things -- calls made to
geniusrun's own APIs, and calls made to external components (the Python
wrapper subprocess).

## Design

### Scope

- Two new log categories: an HTTP access log (one line per API request) and
  a Garmin-wrapper call log (one line per subprocess round-trip).
- Existing ad-hoc `log.Printf` calls throughout the codebase are **not**
  touched or migrated -- they keep going to stderr, unstructured, exactly as
  today. This is deliberate, matching "for now" -- a wholesale migration is
  a separate, later concern.
- `log/slog` (stdlib, available with no new dependency given this repo's Go
  version) with a JSON handler writing to stdout -- a separate stream from
  the existing stderr output, matching "JSON logs on stdout" literally.

### New package: `internal/applog`

```go
package applog

// NewLogger builds a JSON-handler *slog.Logger writing to w at the given
// level ("debug"|"info"|"warn"|"error", case-insensitive, defaulting to
// info for anything unrecognized).
func NewLogger(level string, w io.Writer) *slog.Logger

// WithLogger/FromContext thread a *slog.Logger through request-scoped
// context.Context, so a logger enriched with (e.g.) a request_id in one
// layer is picked up by another (e.g. internal/garmin, downstream of
// internal/api) without either package depending on the other.
// FromContext never returns nil -- it falls back to slog.Default() so
// callers with no request context (the background incremental-sync loop,
// tests that don't bother injecting one) still get a working logger.
func WithLogger(ctx context.Context, logger *slog.Logger) context.Context
func FromContext(ctx context.Context) *slog.Logger
```

`internal/config`: new `LogLevel string` field, `getEnvDefault("GENIUSRUN_LOG_LEVEL", "info")`,
same pattern as every other optional config value.

`cmd/geniusrund/main.go`: once at startup,
```go
slog.SetDefault(applog.NewLogger(cfg.LogLevel, os.Stdout))
```
No other wiring needed -- every consumer reads via `applog.FromContext`,
which falls back to this default.

### HTTP access log (`internal/api`)

A new `loggingMiddleware`, registered as the **first** `r.Use(...)`
in `Router()` (ahead of `corsMiddleware`), so it wraps every request
including unauthenticated ones (login redirect, health check) and OPTIONS
preflights:

- Generates a per-request id from an in-process monotonic counter (e.g.
  `req-42`) -- simple, no new randomness dependency, resets on restart
  (acceptable; log aggregation timestamps disambiguate across restarts).
- Builds `logger := applog.FromContext(r.Context()).With("request_id", id)`
  and re-stashes it via `r = r.WithContext(applog.WithLogger(...))` *before*
  calling `next.ServeHTTP` -- this is what lets every downstream layer
  (including a Garmin wrapper call the handler triggers) log with the same
  `request_id`.
- Wraps the `http.ResponseWriter` with chi's own
  `middleware.NewWrapResponseWriter` (already available -- `go-chi/chi/v5`
  is already a dependency, this is just a different subpackage of it, no
  new module) to capture the status code.
- After `next.ServeHTTP` returns, logs one line:
  `msg: "http request"`, fields `request_id`, `method`, `path` (`r.URL.Path`
  only, deliberately excluding the query string, to stay conservative about
  anything unexpected ending up in a log line), `status`, `duration_ms`.
  Level `Info`, or `Warn` if `status >= 500`.

### Garmin wrapper call log (`internal/garmin`)

`client.go`'s `roundTrip` is the single funnel point every one of the six
`Client` methods already goes through (confirmed while surveying: none of
them ever put Garmin credentials in the wire `params` -- email/password
only ever reach the subprocess via env vars at spawn time, so logging
`params` in full, for every command, is safe). Change its signature to
`roundTrip(ctx context.Context, cmdName string, params any) (result json.RawMessage, err error)`
(named returns), and wrap the whole body in a single `defer` that logs
exactly once regardless of which branch returned:

```go
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...)
}()
```

Reusing the existing `truncate()` helper for `result_preview` (500 chars) is
what keeps this safe for the huge per-second-telemetry responses
(`get_activity_details` can run to several MB, per `maxWrapperLineBytes`)
while still showing tiny auth results (`{"status":"mfa_required",...}`) in
full -- exactly the detail needed for the motivating incident.

All six `Client` methods pass their own `ctx` through to `roundTrip`
(currently they call it without one). `ensureStarted` also gains a `ctx
context.Context` param and logs one `Info` line on actual spawn
(`python_path`, whether a token store is configured) -- spawning the
subprocess is itself a call to the external component.

### Out of scope

- Migrating existing `log.Printf` call sites to `slog`/JSON.
- Fixing `wrapper.py`'s 10-second MFA-timeout ambiguity itself (see
  Problem section) -- this design only makes the distinction visible.
- Logging request/response bodies for HTTP calls, or full (non-preview)
  Garmin call results.
- `user_id` on the HTTP access log line (would need threading it out of
  `resolveUser`'s context back to the outermost middleware, a bigger change
  than "for now" calls for) -- `request_id` correlation covers the
  motivating need (one login attempt <-> its Garmin calls) without it.

## Testing

- `internal/applog`: level filtering (a below-threshold message doesn't
  appear in the output writer); `WithLogger`/`FromContext` round-trip
  (same logger comes back out); `FromContext` on a bare `context.Background()`
  returns a non-nil logger.
- `internal/garmin`: reuse the existing in-process fake-wrapper harness
  (`newFakeWrapperClient`) -- inject a captor logger via
  `applog.WithLogger`, call `Authenticate`/`CompleteMFA`, assert the emitted
  JSON line's `cmd`/`duration_ms`/`result_preview` fields, and that a
  wrapper-reported error surfaces at `Warn` with an `error` field. Update
  the three existing tests that call `roundTrip` directly
  (`TestSubprocessClient_RoundTrip_DetectsIDMismatch`,
  `_SubprocessClosedIsError`, `_WrapperErrorPropagates`) to pass
  `context.Background()` as the new first argument.
- `internal/api`: one focused test building a request with a pre-seeded
  context logger (writing to a `bytes.Buffer`), confirming the access-log
  line's fields, and that a handler returning a 5xx bumps the log level to
  `Warn`.