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

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,

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:

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.