From 501d951e5b10609bba481f0b454f37fbacc2bc0c Mon Sep 17 00:00:00 2001 From: Christophe Vila Date: Sun, 26 Jul 2026 14:22:28 +0200 Subject: [PATCH] docs: add design spec for structured JSON logging --- ...26-07-26-structured-json-logging-design.md | 173 ++++++++++++++++++ 1 file changed, 173 insertions(+) create mode 100644 docs/superpowers/specs/2026-07-26-structured-json-logging-design.md diff --git a/docs/superpowers/specs/2026-07-26-structured-json-logging-design.md b/docs/superpowers/specs/2026-07-26-structured-json-logging-design.md new file mode 100644 index 0000000..35dcf33 --- /dev/null +++ b/docs/superpowers/specs/2026-07-26-structured-json-logging-design.md @@ -0,0 +1,173 @@ +# 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 `requestLoggingMiddleware`, 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`.