From c9e089a2b246cebb193fd4300e564abd9fead147 Mon Sep 17 00:00:00 2001 From: Christophe Vila Date: Sun, 26 Jul 2026 14:33:20 +0200 Subject: [PATCH] feat(garmin): log every wrapper subprocess call as structured JSON --- backend/internal/garmin/client.go | 88 ++++++++++++++++++-------- backend/internal/garmin/client_test.go | 67 +++++++++++++++++++- 2 files changed, 127 insertions(+), 28 deletions(-) diff --git a/backend/internal/garmin/client.go b/backend/internal/garmin/client.go index 1f370d4..2885a16 100644 --- a/backend/internal/garmin/client.go +++ b/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. -func (c *subprocessClient) roundTrip(cmdName string, params any) (json.RawMessage, error) { +// 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 { - return nil, fmt.Errorf("write %s request: %w", cmdName, err) + 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 err := c.scanner.Err(); err != nil { - return nil, fmt.Errorf("read %s response: %w", cmdName, err) + 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, 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 { - return nil, fmt.Errorf("parse %s response: %w", cmdName, err) + 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 { - 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)}, }) diff --git a/backend/internal/garmin/client_test.go b/backend/internal/garmin/client_test.go index 3d8e328..9bf09d9 100644 --- a/backend/internal/garmin/client_test.go +++ b/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) + } +}