docs: add implementation plan for structured JSON logging
This commit is contained in:
961
docs/superpowers/plans/2026-07-26-structured-json-logging.md
Normal file
961
docs/superpowers/plans/2026-07-26-structured-json-logging.md
Normal file
@@ -0,0 +1,961 @@
|
||||
# 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 `requestLoggingMiddleware` 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 `roundTrip`, 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 `roundTrip`.
|
||||
- `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/applog/applog_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/applog/applog.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/config.go` (new `LogLevel` field)
|
||||
- Modify: `backend/internal/config/config_test.go` (new tests)
|
||||
- Modify: `backend/cmd/geniusrund/main.go` (wire up `slog.SetDefault`)
|
||||
- Modify: `backend/internal/api/server.go` (`requestLoggingMiddleware`, registered in `Router()`)
|
||||
- Modify: `backend/internal/api/api_test.go` (new tests)
|
||||
|
||||
**Interfaces:**
|
||||
- Consumes: `applog.NewLogger`, `applog.WithLogger`, `applog.FromContext` (Task 1).
|
||||
- Produces: `requestLoggingMiddleware` (unexported chi middleware in `internal/api`), `config.Config.LogLevel string`.
|
||||
|
||||
- [ ] **Step 1: Write the failing config tests**
|
||||
|
||||
Append to `backend/internal/config/config_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 `config.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/config.go backend/internal/config/config_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` (`roundTrip`, `ensureStarted`, all six call sites)
|
||||
- Modify: `backend/internal/garmin/client_test.go` (update 3 direct-`roundTrip` 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-`roundTrip` 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 — `roundTrip` 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 `roundTrip` 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"
|
||||
```
|
||||
Reference in New Issue
Block a user