feat(garmin): log every wrapper subprocess call as structured JSON

backend/internal/garmin/client.go

@@ -10,10 +10,14 @@ import (
 	"encoding/json"
 	"fmt"
 	"io"
+	"log/slog"
 	"os"
 	"os/exec"
 	"strconv"
 	"sync"
+	"time"
+
+	"geniusrun/backend/internal/applog"
 )
 
 //go:embed pyscript/wrapper.py
@@ -122,7 +126,7 @@ type subprocessClient struct {
 
 // ensureStarted spawns the wrapper subprocess if it isn't already running.
 // Callers must hold c.mu.
-func (c *subprocessClient) ensureStarted() error {
+func (c *subprocessClient) ensureStarted(ctx context.Context) error {
 	if c.started {
 		return nil
 	}
@@ -192,48 +196,82 @@ func (c *subprocessClient) ensureStarted() error {
 	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
 }
 
 // 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.
+// called ensureStarted. Logs exactly one "garmin wrapper call" line
-func (c *subprocessClient) roundTrip(cmdName string, params any) (json.RawMessage, error) {
+// 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 {
+	if err = c.enc.Encode(wireRequest{ID: id, Cmd: cmdName, Params: params}); err != nil {
-		return nil, fmt.Errorf("write %s request: %w", cmdName, err)
+		err = fmt.Errorf("write %s request: %w", cmdName, err)
+		return nil, err
 	}
 
 	if !c.scanner.Scan() {
-		if err := c.scanner.Err(); err != nil {
+		if serr := c.scanner.Err(); serr != nil {
-			return nil, fmt.Errorf("read %s response: %w", cmdName, err)
+			err = fmt.Errorf("read %s response: %w", cmdName, serr)
+		} else {
+			err = fmt.Errorf("read %s response: subprocess closed its output", cmdName)
 		}
-		return nil, fmt.Errorf("read %s response: subprocess closed its output", cmdName)
+		return nil, err
 	}
 
 	var resp wireResponse
-	if err := json.Unmarshal(c.scanner.Bytes(), &resp); err != nil {
+	if uerr := json.Unmarshal(c.scanner.Bytes(), &resp); uerr != nil {
-		return nil, fmt.Errorf("parse %s response: %w", cmdName, err)
+		err = fmt.Errorf("parse %s response: %w", cmdName, uerr)
+		return nil, err
 	}
 	if resp.ID != id {
-		return nil, fmt.Errorf("%s response id mismatch: got %d, want %d", cmdName, resp.ID, id)
+		err = fmt.Errorf("%s response id mismatch: got %d, want %d", cmdName, resp.ID, id)
+		return nil, err
 	}
 	if resp.Error != "" {
-		return nil, fmt.Errorf("%s: %s", cmdName, resp.Error)
+		err = fmt.Errorf("%s: %s", cmdName, resp.Error)
+		return nil, err
 	}
-	return resp.Result, nil
+	result = resp.Result
+	return result, nil
 }
 
 func (c *subprocessClient) Authenticate(ctx context.Context) (AuthResult, error) {
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	if err := c.ensureStarted(); err != nil {
+	if err := c.ensureStarted(ctx); err != nil {
 		return AuthResult{}, err
 	}
-	raw, err := c.roundTrip("authenticate", nil)
+	raw, err := c.roundTrip(ctx, "authenticate", nil)
 	if err != nil {
 		return AuthResult{}, err
 	}
@@ -248,10 +286,10 @@ func (c *subprocessClient) CompleteMFA(ctx context.Context, code string) (AuthRe
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	if err := c.ensureStarted(); err != nil {
+	if err := c.ensureStarted(ctx); err != nil {
 		return AuthResult{}, err
 	}
-	raw, err := c.roundTrip("complete_mfa", map[string]any{"code": code})
+	raw, err := c.roundTrip(ctx, "complete_mfa", map[string]any{"code": code})
 	if err != nil {
 		return AuthResult{}, err
 	}
@@ -325,10 +363,10 @@ func (c *subprocessClient) GetActivities(ctx context.Context, startDate, endDate
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	if err := c.ensureStarted(); err != nil {
+	if err := c.ensureStarted(ctx); err != nil {
 		return nil, err
 	}
-	raw, err := c.roundTrip("call", callParams{
+	raw, err := c.roundTrip(ctx, "call", callParams{
 		Method: "get_activities_by_date",
 		Args:   map[string]any{"startdate": startDate, "enddate": endDate},
 	})
@@ -360,10 +398,10 @@ func (c *subprocessClient) GetActivitySplits(ctx context.Context, activityID int
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	if err := c.ensureStarted(); err != nil {
+	if err := c.ensureStarted(ctx); err != nil {
 		return ActivitySplits{}, err
 	}
-	raw, err := c.roundTrip("call", callParams{
+	raw, err := c.roundTrip(ctx, "call", callParams{
 		Method: "get_activity_splits",
 		Args:   map[string]any{"activity_id": strconv.FormatInt(activityID, 10)},
 	})
@@ -395,10 +433,10 @@ func (c *subprocessClient) GetActivityDetails(ctx context.Context, activityID in
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	if err := c.ensureStarted(); err != nil {
+	if err := c.ensureStarted(ctx); err != nil {
 		return ActivityDetails{}, err
 	}
-	raw, err := c.roundTrip("call", callParams{
+	raw, err := c.roundTrip(ctx, "call", callParams{
 		Method: "get_activity_details",
 		Args:   map[string]any{"activity_id": strconv.FormatInt(activityID, 10)},
 	})
@@ -418,10 +456,10 @@ func (c *subprocessClient) GetWorkoutByID(ctx context.Context, workoutID int64)
 	c.mu.Lock()
 	defer c.mu.Unlock()
 
-	if err := c.ensureStarted(); err != nil {
+	if err := c.ensureStarted(ctx); err != nil {
 		return Workout{}, err
 	}
-	raw, err := c.roundTrip("call", callParams{
+	raw, err := c.roundTrip(ctx, "call", callParams{
 		Method: "get_workout_by_id",
 		Args:   map[string]any{"workout_id": strconv.FormatInt(workoutID, 10)},
 	})

backend/internal/garmin/client_test.go

@@ -2,13 +2,17 @@ package garmin
 
 import (
 	"bufio"
+	"bytes"
 	"context"
 	"encoding/json"
 	"io"
+	"log/slog"
 	"os/exec"
 	"strings"
 	"testing"
 	"time"
+
+	"geniusrun/backend/internal/applog"
 )
 
 // wireResponsePayload is what a fake wrapper handler returns for one
@@ -91,7 +95,7 @@ func TestSubprocessClient_RoundTrip_DetectsIDMismatch(t *testing.T) {
 	scanner.Buffer(make([]byte, 0, 64*1024), maxWrapperLineBytes)
 	c := &subprocessClient{started: true, enc: json.NewEncoder(reqW), scanner: scanner}
 
-	_, err := c.roundTrip("authenticate", nil)
+	_, err := c.roundTrip(context.Background(), "authenticate", nil)
 	if err == nil || !strings.Contains(err.Error(), "id mismatch") {
 		t.Fatalf("roundTrip error = %v, want an id mismatch error", err)
 	}
@@ -113,7 +117,7 @@ func TestSubprocessClient_RoundTrip_SubprocessClosedIsError(t *testing.T) {
 	scanner.Buffer(make([]byte, 0, 64*1024), maxWrapperLineBytes)
 	c := &subprocessClient{started: true, enc: json.NewEncoder(reqW), scanner: scanner}
 
-	_, err := c.roundTrip("authenticate", nil)
+	_, err := c.roundTrip(context.Background(), "authenticate", nil)
 	if err == nil || !strings.Contains(err.Error(), "closed") {
 		t.Fatalf("roundTrip error = %v, want a subprocess-closed error", err)
 	}
@@ -124,7 +128,7 @@ func TestSubprocessClient_RoundTrip_WrapperErrorPropagates(t *testing.T) {
 		return fakeError("boom")
 	})
 
-	_, err := c.roundTrip("authenticate", nil)
+	_, err := c.roundTrip(context.Background(), "authenticate", nil)
 	if err == nil || !strings.Contains(err.Error(), "boom") {
 		t.Fatalf("roundTrip error = %v, want it to mention %q", err, "boom")
 	}
@@ -394,3 +398,60 @@ func TestSubprocessClient_GetWorkoutByID_ParsesSegments(t *testing.T) {
 		t.Fatalf("workout = %+v", workout)
 	}
 }
+
+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)
+	}
+}