kriss/geniusrun
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

refactor(log): unified schema — mandatory type/class/method, request_id removed

Browse Source 
Every log record now carries type ('http' for the request middleware
line, 'wrapper' for garmin execute() calls and forwarded wrapper.py
stderr, 'app' for everything else), class (Go type with package, or the
package/module for free functions), and method (the emitting Go/Python
function -- wrapper.py stamps it automatically, so its msg prefixes are
gone). msg is optional and omitted when empty; the redundant messages
('HTTP request', 'wrapper call', 'garmin wrapper stderr') are dropped,
the HTTP verb moves to http_method, source=garmin-wrapper is replaced by
type=wrapper, and the request_id middleware plumbing (applog
WithLogger/FromContext) is removed. applog.App(class, method) is the
tagging helper for app records.

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Kriss Vila
2026-08-04 19:45:30 +02:00
parent 78c494affb
commit 6effb79097
16 changed files with 267 additions and 152 deletions
Download Patch File Download Diff File Expand all files Collapse all files

71
backend/internal/garmin/client.go
View File

@@ -17,8 +17,6 @@ import (
"strconv"
"sync"
"time"
"geniusrun/backend/internal/log"
)
//go:embed wrapper/wrapper.py
@@ -149,14 +147,14 @@ func (c *subprocessClient) ensureStarted(ctx context.Context) error {
if c.scriptPath == "" {
f, err := os.CreateTemp("", "geniusrun-garmin-wrapper-*.py")
if err != nil {
return fmt.Errorf("write embedded wrapper script: %w", err)
return fmt.Errorf("write wrapper script: %w", err)
}
if _, err := f.WriteString(wrapperScript); err != nil {
f.Close()
return fmt.Errorf("write embedded wrapper script: %w", err)
return fmt.Errorf("write wrapper script: %w", err)
}
if err := f.Close(); err != nil {
return fmt.Errorf("write embedded wrapper script: %w", err)
return fmt.Errorf("write wrapper script: %w", err)
}
c.scriptPath = f.Name()
}
@@ -189,7 +187,7 @@ func (c *subprocessClient) ensureStarted(ctx context.Context) error {
}
if err := cmd.Start(); err != nil {
return fmt.Errorf("spawn garmin wrapper subprocess: %w", err)
return fmt.Errorf("spawn wrapper subprocess: %w", err)
}
// wrapper.py logs auth/rate-limit diagnostics to stderr as JSON lines
// (see its _log helper); forwardWrapperStderr re-emits them through the
@@ -216,19 +214,22 @@ func (c *subprocessClient) ensureStarted(ctx context.Context) error {
return nil
}
// roundTrip sends one request and returns its result payload, or an error
// execute 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) {
// called ensureStarted. Logs exactly one type=wrapper line regardless of
// outcome (the record's meaning is carried by its fields, no msg) --
// 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) execute(ctx context.Context, cmd string, params any) (result json.RawMessage, err error) {
start := time.Now()
var errorType, traceback string // Python-side failure detail, set from the error response
defer func() {
attrs := []slog.Attr{
slog.String("cmd", cmdName),
slog.String("type", "wrapper"),
slog.String("class", "garmin.subprocessClient"),
slog.String("method", "execute"),
slog.String("cmd", cmd),
slog.Any("params", params),
slog.Int64("duration_ms", time.Since(start).Milliseconds()),
}
@@ -246,41 +247,41 @@ func (c *subprocessClient) roundTrip(ctx context.Context, cmdName string, params
attrs = append(attrs, slog.String("traceback", traceback))
}
}
applog.FromContext(ctx).LogAttrs(context.Background(), level, "Garmin wrapper call", attrs...)
slog.Default().LogAttrs(ctx, level, "", 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)
if err = c.enc.Encode(wireRequest{ID: id, Cmd: cmd, Params: params}); err != nil {
err = fmt.Errorf("write %s request: %w", cmd, err)
return nil, err
}
if !c.scanner.Scan() {
if serr := c.scanner.Err(); serr != nil {
err = fmt.Errorf("read %s response: %w", cmdName, serr)
err = fmt.Errorf("read %s response: %w", cmd, serr)
} else {
err = fmt.Errorf("read %s response: subprocess closed its output", cmdName)
err = fmt.Errorf("read %s response: subprocess closed its output", cmd)
}
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)
err = fmt.Errorf("parse %s response: %w", cmd, uerr)
return nil, err
}
if resp.ID != id {
err = 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", cmd, resp.ID, id)
return nil, err
}
if resp.Error != "" {
errorType, traceback = resp.ErrorType, resp.Traceback
if resp.NotFound {
err = fmt.Errorf("%s: %s: %w", cmdName, resp.Error, ErrNotFound)
err = fmt.Errorf("%s: %s: %w", cmd, resp.Error, ErrNotFound)
} else {
err = fmt.Errorf("%s: %s", cmdName, resp.Error)
err = fmt.Errorf("%s: %s", cmd, resp.Error)
}
return nil, err
}
@@ -295,7 +296,7 @@ func (c *subprocessClient) Authenticate(ctx context.Context) (AuthResult, error)
if err := c.ensureStarted(ctx); err != nil {
return AuthResult{}, err
}
raw, err := c.roundTrip(ctx, "authenticate", nil)
raw, err := c.execute(ctx, "authenticate", nil)
if err != nil {
return AuthResult{}, err
}
@@ -313,7 +314,7 @@ func (c *subprocessClient) CompleteMFA(ctx context.Context, code string) (AuthRe
if err := c.ensureStarted(ctx); err != nil {
return AuthResult{}, err
}
raw, err := c.roundTrip(ctx, "complete_mfa", map[string]any{"code": code})
raw, err := c.execute(ctx, "complete_mfa", map[string]any{"code": code})
if err != nil {
return AuthResult{}, err
}
@@ -374,7 +375,7 @@ func (c *subprocessClient) close() error {
// the corresponding level with their attrs preserved. Anything that isn't
// such a line (a Python startup crash before _log exists, a chatty
// third-party library printing directly) is wrapped as a warn-level
// "garmin wrapper stderr" record rather than passed through raw, so the
// type=wrapper record carrying the raw "line" rather than passed through, so the
// backend's combined output is JSON no matter what the subprocess does.
func forwardWrapperStderr(r io.Reader) {
scanner := bufio.NewScanner(r)
@@ -383,19 +384,21 @@ func forwardWrapperStderr(r io.Reader) {
line := scanner.Text()
var entry map[string]any
if err := json.Unmarshal([]byte(line), &entry); err != nil || entry["msg"] == nil {
slog.Warn("garmin wrapper stderr", "line", line)
slog.Warn("", "type", "wrapper", "class", "garmin", "method", "forwardWrapperStderr", "line", line)
continue
}
msg, _ := entry["msg"].(string)
levelName, _ := entry["level"].(string)
delete(entry, "msg")
delete(entry, "level")
attrs := make([]slog.Attr, 0, len(entry)+1)
attrs = append(attrs, slog.String("source", "garmin-wrapper"))
// class is the Python module; method arrives in the entry itself
// (wrapper.py's _log stamps the emitting function).
attrs := make([]slog.Attr, 0, len(entry)+2)
attrs = append(attrs, slog.String("type", "wrapper"), slog.String("class", "wrapper"))
for k, v := range entry {
attrs = append(attrs, slog.Any(k, v))
}
slog.LogAttrs(context.Background(), wrapperLogLevel(levelName), msg, attrs...)
slog.Default().LogAttrs(context.Background(), wrapperLogLevel(levelName), msg, attrs...)
}
}
@@ -436,7 +439,7 @@ func (c *subprocessClient) GetActivities(ctx context.Context, startDate, endDate
if err := c.ensureStarted(ctx); err != nil {
return nil, err
}
raw, err := c.roundTrip(ctx, "call", callParams{
raw, err := c.execute(ctx, "call", callParams{
Method: "get_activities_by_date",
Args: map[string]any{"startdate": startDate, "enddate": endDate},
})
@@ -471,7 +474,7 @@ func (c *subprocessClient) GetActivitySplits(ctx context.Context, activityID int
if err := c.ensureStarted(ctx); err != nil {
return ActivitySplits{}, err
}
raw, err := c.roundTrip(ctx, "call", callParams{
raw, err := c.execute(ctx, "call", callParams{
Method: "get_activity_splits",
Args: map[string]any{"activity_id": strconv.FormatInt(activityID, 10)},
})
@@ -506,7 +509,7 @@ func (c *subprocessClient) GetActivityDetails(ctx context.Context, activityID in
if err := c.ensureStarted(ctx); err != nil {
return ActivityDetails{}, err
}
raw, err := c.roundTrip(ctx, "call", callParams{
raw, err := c.execute(ctx, "call", callParams{
Method: "get_activity_details",
Args: map[string]any{"activity_id": strconv.FormatInt(activityID, 10)},
})
@@ -529,7 +532,7 @@ func (c *subprocessClient) GetWorkoutByID(ctx context.Context, workoutID int64)
if err := c.ensureStarted(ctx); err != nil {
return Workout{}, err
}
raw, err := c.roundTrip(ctx, "call", callParams{
raw, err := c.execute(ctx, "call", callParams{
Method: "get_workout_by_id",
Args: map[string]any{"workout_id": strconv.FormatInt(workoutID, 10)},
})

44
backend/internal/garmin/client_test.go
View File

@@ -101,7 +101,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(context.Background(), "authenticate", nil)
_, err := c.execute(context.Background(), "authenticate", nil)
if err == nil || !strings.Contains(err.Error(), "id mismatch") {
t.Fatalf("roundTrip error = %v, want an id mismatch error", err)
}
@@ -123,7 +123,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(context.Background(), "authenticate", nil)
_, err := c.execute(context.Background(), "authenticate", nil)
if err == nil || !strings.Contains(err.Error(), "closed") {
t.Fatalf("roundTrip error = %v, want a subprocess-closed error", err)
}
@@ -134,7 +134,7 @@ func TestSubprocessClient_RoundTrip_WrapperErrorPropagates(t *testing.T) {
return fakeError("boom")
})
_, err := c.roundTrip(context.Background(), "authenticate", nil)
_, err := c.execute(context.Background(), "authenticate", nil)
if err == nil || !strings.Contains(err.Error(), "boom") {
t.Fatalf("roundTrip error = %v, want it to mention %q", err, "boom")
}
@@ -145,7 +145,7 @@ func TestSubprocessClient_RoundTrip_NotFoundWrapsErrNotFound(t *testing.T) {
return fakeNotFoundError("API Error 404")
})
_, err := c.roundTrip(context.Background(), "call", nil)
_, err := c.execute(context.Background(), "call", nil)
if !errors.Is(err, ErrNotFound) {
t.Fatalf("roundTrip error = %v, want errors.Is(err, ErrNotFound)", err)
}
@@ -159,7 +159,7 @@ func TestSubprocessClient_RoundTrip_OrdinaryErrorDoesNotWrapErrNotFound(t *testi
return fakeError("boom")
})
_, err := c.roundTrip(context.Background(), "call", nil)
_, err := c.execute(context.Background(), "call", nil)
if errors.Is(err, ErrNotFound) {
t.Fatalf("roundTrip error = %v, want errors.Is(err, ErrNotFound) to be false", err)
}
@@ -436,10 +436,11 @@ func TestSubprocessClient_RoundTrip_LogsCallWithResultPreview(t *testing.T) {
})
var buf bytes.Buffer
logger := slog.New(slog.NewJSONHandler(&buf, nil))
ctx := applog.WithLogger(context.Background(), logger)
prev := slog.Default()
slog.SetDefault(applog.NewLogger("info", &buf))
defer slog.SetDefault(prev)
if _, err := c.Authenticate(ctx); err != nil {
if _, err := c.Authenticate(context.Background()); err != nil {
t.Fatalf("Authenticate: %v", err)
}
@@ -447,8 +448,11 @@ func TestSubprocessClient_RoundTrip_LogsCallWithResultPreview(t *testing.T) {
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["type"] != "wrapper" || entry["class"] != "garmin.subprocessClient" || entry["method"] != "execute" {
t.Errorf("schema fields = %v, want type=wrapper class=garmin.subprocessClient method=execute", entry)
}
if _, hasMsg := entry["msg"]; hasMsg {
t.Errorf("expected no msg on the wrapper-call record, got %v", entry["msg"])
}
if entry["cmd"] != "authenticate" {
t.Errorf("cmd = %v, want authenticate", entry["cmd"])
@@ -468,10 +472,11 @@ func TestSubprocessClient_RoundTrip_LogsFailedCallAtErrorLevel(t *testing.T) {
})
var buf bytes.Buffer
logger := slog.New(slog.NewJSONHandler(&buf, nil))
ctx := applog.WithLogger(context.Background(), logger)
prev := slog.Default()
slog.SetDefault(applog.NewLogger("info", &buf))
defer slog.SetDefault(prev)
if _, err := c.Authenticate(ctx); err == nil {
if _, err := c.Authenticate(context.Background()); err == nil {
t.Fatal("expected Authenticate to return an error")
}
@@ -490,7 +495,7 @@ func TestSubprocessClient_RoundTrip_LogsFailedCallAtErrorLevel(t *testing.T) {
func TestForwardWrapperStderr_ReemitsJSONAndWrapsFreeText(t *testing.T) {
var buf bytes.Buffer
prev := slog.Default()
slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})))
slog.SetDefault(applog.NewLogger("debug", &buf))
defer slog.SetDefault(prev)
stderr := strings.NewReader(
@@ -511,16 +516,19 @@ func TestForwardWrapperStderr_ReemitsJSONAndWrapsFreeText(t *testing.T) {
if first["level"] != "WARN" || first["msg"] != "startup tokenstore login failed" {
t.Errorf("first = %v, want the wrapper's level and msg preserved", first)
}
if first["error"] != "boom" || first["source"] != "garmin-wrapper" {
t.Errorf("first = %v, want error attr preserved and source=garmin-wrapper", first)
if first["error"] != "boom" || first["type"] != "wrapper" || first["class"] != "wrapper" {
t.Errorf("first = %v, want error attr preserved and type=wrapper class=wrapper", first)
}
var second map[string]any
if err := json.Unmarshal([]byte(lines[1]), &second); err != nil {
t.Fatalf("second line not JSON: %v", err)
}
if second["msg"] != "garmin wrapper stderr" || second["level"] != "WARN" {
t.Errorf("second = %v, want free text wrapped as a warn record", second)
if _, hasMsg := second["msg"]; hasMsg {
t.Errorf("second = %v, want no msg on a wrapped free-text record", second)
}
if second["type"] != "wrapper" || second["level"] != "WARN" {
t.Errorf("second = %v, want free text wrapped as a warn type=wrapper record", second)
}
if line, _ := second["line"].(string); !strings.Contains(line, "Traceback") {
t.Errorf("second line attr = %q, want the raw text preserved", line)

4
backend/internal/garmin/sync.go
View File

@@ -368,12 +368,12 @@ func (s *Sync) fillPendingWorkouts(ctx context.Context, limit int) error {
// after being linked to this activity) will never succeed on
// retry -- mark it so ActivitiesMissingWorkout stops
// surfacing it, instead of retrying forever.
applog.FromContext(ctx).Warn("workout not found on Garmin, marking as such (will not retry)", "garmin_activity_id", a.GarminActivityID, "error", err)
applog.App("garmin.Sync", "fillPendingWorkouts").Warn("workout not found on Garmin, marking as such (will not retry)", "garmin_activity_id", a.GarminActivityID, "error", err)
if serr := s.db.SetActivityWorkoutNotFound(ctx, s.userID, a.ID); serr != nil {
return fmt.Errorf("mark activity %d workout not found: %w", a.GarminActivityID, serr)
}
} else {
applog.FromContext(ctx).Warn("fill workout failed, will retry next sync", "garmin_activity_id", a.GarminActivityID, "error", err)
applog.App("garmin.Sync", "fillPendingWorkouts").Warn("fill workout failed, will retry next sync", "garmin_activity_id", a.GarminActivityID, "error", err)
}
}
s.setProgress(PhaseWorkouts, i+1, len(pending))

13
backend/internal/garmin/wrapper/tests/test_wrapper.py
View File

@@ -1,3 +1,4 @@
import json
import os
import time
import queue
@@ -351,3 +352,15 @@ def test_startup_login_late_success_never_overrides_explicit_auth_flow():
release.set()
time.sleep(0.2) # give the thread ample time to (wrongly) flip it
assert wrapper._auth_state == "mfa_pending"
def test_log_stamps_emitting_method(capsys):
"""Every wrapper log line carries the emitting function as "method" --
the Go side forwards it into the unified log schema."""
def some_emitter():
wrapper._log("info", "hello", extra=1)
some_emitter()
entry = json.loads(capsys.readouterr().err.strip())
assert entry == {"level": "info", "msg": "hello", "method": "some_emitter", "extra": 1}

50
backend/internal/garmin/wrapper/wrapper.py
View File

@@ -29,16 +29,18 @@ def _log(level, msg, **attrs):
stderr line by line and re-emits these through the Go application
logger, so the backend's combined output stays a single JSON stream --
never print free text to stderr or stdout from this process (stdout is
reserved for the request/response protocol)."""
entry = {"level": level, "msg": msg}
reserved for the request/response protocol). The emitting function is
stamped as "method" automatically; the Go side adds the rest of the
log schema (type=wrapper, class=wrapper)."""
entry = {"level": level, "msg": msg, "method": sys._getframe(1).f_code.co_name}
entry.update(attrs)
print(json.dumps(entry), file=sys.stderr, flush=True)
def _prompt_mfa():
_log("debug", "prompt_mfa(): invoked")
_log("debug", "invoked")
code = _mfa_input_queue.get(timeout=300)
_log("debug", "prompt_mfa(): returning MFA code", code_length=len(code))
_log("debug", "returning MFA code", code_length=len(code))
return code
@@ -88,12 +90,12 @@ def _startup_login():
_client = Garmin(email, password)
result_queue = queue.Queue() # private to this call, never shared with authenticate/complete_mfa
def _do_login():
def _do_startup_login():
global _auth_state
_log("debug", "startup_login(): background thread starting _client.login()", tokenstore=TOKENSTORE)
_log("debug", "background thread starting _client.login()", tokenstore=TOKENSTORE)
try:
_client.login(tokenstore=TOKENSTORE)
_log("debug", "startup_login(): _client.login() returned successfully")
_log("debug", "_client.login() returned successfully")
result_queue.put(("success", None))
# A success arriving after the 10s timeout below would land in
# an abandoned queue -- flip the state here too, so later calls
@@ -105,30 +107,30 @@ def _startup_login():
except Exception as exc:
_log(
"error",
"startup_login(): _client.login() failed",
"_client.login() failed",
error=str(exc),
error_type=type(exc).__name__,
traceback=traceback.format_exc(),
)
result_queue.put(("error", str(exc)))
threading.Thread(target=_do_login, daemon=True).start()
threading.Thread(target=_do_startup_login, daemon=True).start()
try:
status, err = result_queue.get(timeout=10)
_log("debug", "startup_login(): got result within 10s timeout", status=status)
_log("debug", "got result within 10s timeout", status=status)
if status == "success":
_auth_state = "authenticated"
else:
_log("error", "startup_login(): login failed", error=err)
_log("error", "login failed", error=err)
_auth_state = "unauthenticated"
except queue.Empty:
# No assignment here: the state is already "unauthenticated", and
# writing it again could clobber a success the background thread
# records right around the timeout boundary (see _do_login).
# records right around the timeout boundary (see _do_startup_login).
_log(
"warn",
"startup_login(): hit the 10s timeout but still running in the "
"hit the 10s timeout but still running in the "
"background and will update auth state if it eventually succeeds",
)
@@ -149,16 +151,16 @@ def _handle_authenticate(_params):
"message": "GARMIN_EMAIL and GARMIN_PASSWORD environment variables are required.",
}
def _do_login():
_log("debug", "handle_authenticate(): background thread starting _client.login()", tokenstore=TOKENSTORE)
def _do_authenticate_login():
_log("debug", "background thread starting _client.login()", tokenstore=TOKENSTORE)
try:
_client.login(tokenstore=TOKENSTORE)
_log("debug", "handle_authenticate(): _client.login() returned successfully")
_log("debug", "_client.login() returned successfully")
_login_result_queue.put(("success", None))
except Exception as exc:
_log(
"error",
"handle_authenticate(): _client.login() failed",
"_client.login() failed",
error=str(exc),
error_type=type(exc).__name__,
traceback=traceback.format_exc(),
@@ -167,21 +169,21 @@ def _handle_authenticate(_params):
_client = Garmin(email, password)
_client.prompt_mfa = _prompt_mfa
threading.Thread(target=_do_login, daemon=True).start()
threading.Thread(target=_do_authenticate_login, daemon=True).start()
try:
status, err = _login_result_queue.get(timeout=10)
_log("debug", "handle_authenticate(): got result within 10s timeout", status=status)
_log("debug", "got result within 10s timeout", status=status)
if status == "success":
_auth_state = "authenticated"
return {"status": "success", "message": "Authenticated successfully."}
else:
_log("error", "handle_authenticate(): login failed", error=err)
_log("error", "login failed", error=err)
return {"status": "failed", "message": f"Authentication failed: {err}"}
except queue.Empty:
_log(
"warn",
"handle_authenticate(): hit the 10s timeout with no result yet, reporting mfa_required",
"hit the 10s timeout with no result yet, reporting mfa_required",
)
_auth_state = "mfa_pending"
return {
@@ -197,12 +199,12 @@ def _handle_complete_mfa(params):
return {"status": "failed", "message": "No MFA in progress. Call authenticate first."}
code = params["code"]
_log("debug", "handle_complete_mfa(): received a code, pushing to mfa queue", code_length=len(code))
_log("debug", "received a code, pushing to mfa queue", code_length=len(code))
_mfa_input_queue.put(code)
try:
status, err = _login_result_queue.get(timeout=30)
_log("debug", "handle_complete_mfa(): got result", status=status, error=err)
_log("debug", "got result", status=status, error=err)
if status == "success":
_auth_state = "authenticated"
return {"status": "success", "message": "MFA accepted. Authenticated successfully."}
@@ -210,7 +212,7 @@ def _handle_complete_mfa(params):
except queue.Empty:
_log(
"error",
"handle_complete_mfa(): hit the 30s timeout with no result yet, reporting unauthenticated",
"hit the 30s timeout with no result yet, reporting unauthenticated",
)
_auth_state = "unauthenticated"
return {