docs: add design spec for structured JSON logging
This commit is contained in:
@@ -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`.
|
||||
Reference in New Issue
Block a user