2026-07-26 14:36:04 +02:00
# 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.
2026-08-04 20:24:05 +02:00
**Architecture:** A new `internal/applog` package wraps `log/slog` with a JSON handler plus context helpers (`WithLogger` /`FromContext` ). `internal/api` gains a `loggingMiddleware` 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 `execute` , the single funnel point all six Garmin calls go through, logging one line per subprocess round-trip.
2026-07-26 14:36:04 +02:00
**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.
2026-08-04 20:24:05 +02:00
- 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 `execute` .
2026-07-26 14:36:04 +02:00
- `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`
2026-08-04 16:04:18 +02:00
- Create: `../../../backend/internal/log/log_test.go`
2026-07-26 14:36:04 +02:00
**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).
2026-08-04 16:04:18 +02:00
- [ ] **Step 3: Create `../../../backend/internal/log/log.go` **
2026-07-26 14:36:04 +02:00
```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:**
2026-08-04 16:04:18 +02:00
- Modify: `../../../backend/internal/config/envconfig.go` (new `LogLevel` field)
- Modify: `../../../backend/internal/config/envconfig_test.go` (new tests)
2026-07-26 14:36:04 +02:00
- Modify: `backend/cmd/geniusrund/main.go` (wire up `slog.SetDefault` )
2026-08-04 16:04:18 +02:00
- Modify: `backend/internal/api/server.go` (`loggingMiddleware` , registered in `Router()` )
2026-07-26 14:36:04 +02:00
- Modify: `backend/internal/api/api_test.go` (new tests)
**Interfaces:**
- Consumes: `applog.NewLogger` , `applog.WithLogger` , `applog.FromContext` (Task 1).
2026-08-04 16:04:18 +02:00
- Produces: `loggingMiddleware` (unexported chi middleware in `internal/api` ), `config.Config.LogLevel string` .
2026-07-26 14:36:04 +02:00
- [ ] **Step 1: Write the failing config tests **
2026-08-04 16:04:18 +02:00
Append to `../../../backend/internal/config/envconfig_test.go` :
2026-07-26 14:36:04 +02:00
```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).
2026-08-04 16:04:18 +02:00
- [ ] **Step 4: Add `LogLevel` to `envconfig.go` **
2026-07-26 14:36:04 +02:00
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
2026-08-04 16:04:18 +02:00
git add backend/internal/config/envconfig.go backend/internal/config/envconfig_test.go backend/cmd/geniusrund/main.go backend/internal/api/server.go backend/internal/api/api_test.go
2026-07-26 14:36:04 +02:00
git commit -m "feat(api): add structured JSON access log with request-id correlation"
```
---
### Task 3: Garmin wrapper call log
**Files:**
2026-08-04 20:24:05 +02:00
- Modify: `backend/internal/garmin/client.go` (`execute` , `ensureStarted` , all six call sites)
- Modify: `backend/internal/garmin/client_test.go` (update 3 direct-`execute` calls, add 2 new tests)
2026-07-26 14:36:04 +02:00
**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).
2026-08-04 20:24:05 +02:00
- [ ] **Step 1: Update the 3 existing direct-`execute` tests and write the 2 new failing tests **
2026-07-26 14:36:04 +02:00
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`
2026-08-04 20:24:05 +02:00
Expected: FAIL — `execute` still takes 2 args, not 3; `applog` import unresolved.
2026-07-26 14:36:04 +02:00
- [ ] **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
}
```
2026-08-04 20:24:05 +02:00
Replace `execute` entirely. From:
2026-07-26 14:36:04 +02:00
```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"
```
