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

refactor(log): replace stdlib log with the application JSON logger

Browse Source 
Every log.Printf/Fatalf becomes a structured slog call through
internal/log: request handlers use the request-scoped logger
(applog.FromContext, carrying request_id), startup failures exit via a
fatal() helper that still emits JSON, and the seedsample/dumpschema CLIs
bootstrap the same JSON logger. Stale client_test expectations aligned
with the refactored wrapper-call logging (message casing, result attr,
ERROR level).

Co-Authored-By: Claude Fable 5 <noreply@anthropic.com>
This commit is contained in:
Kriss Vila
2026-08-04 16:33:26 +02:00
parent 042579a396
commit 431315bac3
13 changed files with 72 additions and 50 deletions
Download Patch File Download Diff File Expand all files Collapse all files

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

@@ -3,10 +3,10 @@ package api
import (
"context"
"encoding/json"
"log"
"net/http"
"geniusrun/backend/internal/garmin"
applog "geniusrun/backend/internal/log"
)
// detailFillBatchSize bounds how many activities' details/splits are fetched
@@ -45,7 +45,7 @@ func (s *Server) recordAuthResult(ctx context.Context, userID int64, res garmin.
if res.Status == garmin.AuthSuccess {
if err := s.DB.MarkGarminConnected(ctx, userID); err != nil {
log.Printf("api: mark garmin connected for user %d: %v", userID, err)
applog.FromContext(ctx).Error("mark garmin connected", "user_id", userID, "error", err)
}
}
}

9
backend/internal/api/server.go
View File

@@ -9,7 +9,6 @@ import (
"encoding/json"
"fmt"
applog "geniusrun/backend/internal/log"
"log"
"log/slog"
"net/http"
"os"
@@ -262,7 +261,7 @@ func (s *Server) removeUserClient(userID int64) {
if ok {
if err := client.Close(); err != nil {
log.Printf("api: close garmin client for deleted user %d: %v", userID, err)
slog.Error("close garmin client for deleted user", "user_id", userID, "error", err)
}
}
if s.ClientConfig.TokenStorePath == "" {
@@ -270,7 +269,7 @@ func (s *Server) removeUserClient(userID int64) {
}
tokenStoreDir := filepath.Join(s.ClientConfig.TokenStorePath, strconv.FormatInt(userID, 10))
if err := os.RemoveAll(tokenStoreDir); err != nil {
log.Printf("api: remove token store dir for deleted user %d: %v", userID, err)
slog.Error("remove token store dir for deleted user", "user_id", userID, "error", err)
}
}
@@ -317,7 +316,7 @@ func (s *Server) backgroundSync(userID int64, fn func(ctx context.Context) error
s.mu.Unlock()
}()
if err := fn(context.Background()); err != nil {
log.Printf("api: background sync error (user %d): %v", userID, err)
slog.Error("background sync failed", "user_id", userID, "error", err)
}
}()
return true
@@ -337,7 +336,7 @@ func writeJSON(w http.ResponseWriter, status int, v any) {
w.Header().Set("Content-Type", "application/json")
w.WriteHeader(status)
if err := json.NewEncoder(w).Encode(v); err != nil {
log.Printf("api: encode response: %v", err)
slog.Error("encode response", "error", err)
}
}

9
backend/internal/api/session.go
View File

@@ -1,10 +1,11 @@
package api
import (
"log"
"net/http"
"time"
applog "geniusrun/backend/internal/log"
"geniusrun/backend/internal/auth"
)
@@ -57,7 +58,7 @@ func (s *Server) handleSessionLogin(w http.ResponseWriter, r *http.Request) {
func (s *Server) handleSessionCallback(w http.ResponseWriter, r *http.Request) {
txnCookie, err := r.Cookie(auth.TxnCookieName)
if err != nil {
log.Printf("session callback: missing txn cookie: %v", err)
applog.FromContext(r.Context()).Warn("session callback: missing txn cookie", "error", err)
http.Redirect(w, r, s.SessionConfig.FrontendURL+"/?auth_error=failed", http.StatusFound)
return
}
@@ -65,14 +66,14 @@ func (s *Server) handleSessionCallback(w http.ResponseWriter, r *http.Request) {
txn, err := auth.ParseTxnCookie(txnCookie, s.SessionConfig.Secret)
if err != nil {
log.Printf("session callback: failed to parse txn cookie: %v", err)
applog.FromContext(r.Context()).Warn("session callback: failed to parse txn cookie", "error", err)
http.Redirect(w, r, s.SessionConfig.FrontendURL+"/?auth_error=failed", http.StatusFound)
return
}
result, err := s.Auth.HandleCallback(r.Context(), txn, r.URL.Query())
if err != nil {
log.Printf("session callback: HandleCallback failed (state mismatch, code exchange, or ID-token verification): %v", err)
applog.FromContext(r.Context()).Error("session callback failed (state mismatch, code exchange, or ID-token verification)", "error", err)
http.Redirect(w, r, s.SessionConfig.FrontendURL+"/?auth_error=failed", http.StatusFound)
return
}

4
backend/internal/api/setup.go
View File

@@ -2,7 +2,6 @@ package api
import (
"encoding/json"
"log"
"net/http"
"os"
"path/filepath"
@@ -11,6 +10,7 @@ import (
"geniusrun/backend/internal/auth"
"geniusrun/backend/internal/garmin"
applog "geniusrun/backend/internal/log"
)
// setupSessionIdleTimeout bounds how long an onboarding Garmin session
@@ -196,7 +196,7 @@ func (s *Server) handleSetupComplete(w http.ResponseWriter, r *http.Request) {
oldDir := setupTokenStoreDir(s.ClientConfig.TokenStorePath, claims.Sub)
newDir := filepath.Join(s.ClientConfig.TokenStorePath, strconv.FormatInt(userID, 10))
if err := os.Rename(oldDir, newDir); err != nil && !os.IsNotExist(err) {
log.Printf("api: rename setup token store dir for user %d: %v", userID, err)
applog.FromContext(r.Context()).Error("rename setup token store dir", "user_id", userID, "error", err)
}
}

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

@@ -205,15 +205,12 @@ func (c *subprocessClient) ensureStarted(ctx context.Context) error {
c.started = true
c.nextID = 0
applog.FromContext(ctx).Info("garmin wrapper spawning",
"python_path", pythonPath,
)
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. Logs exactly one "garmin wrapper call" line
// 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
@@ -228,13 +225,13 @@ func (c *subprocessClient) roundTrip(ctx context.Context, cmdName string, params
}
level := slog.LevelInfo
if result != nil {
attrs = append(attrs, slog.String("result_preview", truncate(string(result), 500)))
attrs = append(attrs, slog.String("result", truncate(string(result), 500)))
}
if err != nil {
level = slog.LevelWarn
level = slog.LevelError
attrs = append(attrs, slog.String("error", err.Error()))
}
applog.FromContext(ctx).LogAttrs(context.Background(), level, "garmin wrapper call", attrs...)
applog.FromContext(ctx).LogAttrs(context.Background(), level, "Garmin wrapper call", attrs...)
}()
c.nextID++

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

@@ -447,22 +447,22 @@ 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["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)
preview, _ := entry["result"].(string)
if !strings.Contains(preview, "mfa_required") {
t.Errorf("result_preview = %q, want it to contain mfa_required", preview)
t.Errorf("result = %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) {
func TestSubprocessClient_RoundTrip_LogsFailedCallAtErrorLevel(t *testing.T) {
c := newFakeWrapperClient(t, func(cmd string, params json.RawMessage) wireResponsePayload {
return fakeError("boom")
})
@@ -479,8 +479,8 @@ func TestSubprocessClient_RoundTrip_LogsErrorAtWarnLevel(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["level"] != "WARN" {
t.Errorf("level = %v, want WARN for a failed call", entry["level"])
if entry["level"] != "ERROR" {
t.Errorf("level = %v, want ERROR 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)

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

@@ -9,11 +9,11 @@ import (
"encoding/json"
"errors"
"fmt"
"log"
"sync"
"time"
"geniusrun/backend/internal/classify"
applog "geniusrun/backend/internal/log"
"geniusrun/backend/internal/store"
)
@@ -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.
log.Printf("sync: workout for activity %d not found on Garmin, marking as such (will not retry): %v", a.GarminActivityID, err)
applog.FromContext(ctx).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 {
log.Printf("sync: fill workout for activity %d failed, will retry next sync: %v", a.GarminActivityID, err)
applog.FromContext(ctx).Warn("fill workout failed, will retry next sync", "garmin_activity_id", a.GarminActivityID, "error", err)
}
}
s.setProgress(PhaseWorkouts, i+1, len(pending))

0
backend/internal/store/profile.go → backend/internal/store/profiles.go
View File

0
backend/internal/store/profile_test.go → backend/internal/store/profiles_test.go
View File

4
backend/internal/store/users.go
View File

@@ -56,14 +56,14 @@ var defaultWorkoutKindSeeds = []WorkoutKind{
// default workout kinds (with their paired workout_type_paces rows), and an
// initial sync_state row -- all in one transaction, so a partially
// provisioned user is never observable.
func (db *DB) ProvisionUser(ctx context.Context, oidcSub, displayName string) (int64, error) {
func (db *DB) ProvisionUser(ctx context.Context, oidcSub, name string) (int64, error) {
tx, err := db.BeginTx(ctx, nil)
if err != nil {
return 0, fmt.Errorf("begin provision user tx: %w", err)
}
defer tx.Rollback()
res, err := tx.ExecContext(ctx, `INSERT INTO users (oidc_sub, name) VALUES (?, ?)`, oidcSub, displayName)
res, err := tx.ExecContext(ctx, `INSERT INTO users (oidc_sub, name) VALUES (?, ?)`, oidcSub, name)
if err != nil {
return 0, fmt.Errorf("create user %q: %w", oidcSub, err)
}