diff --git a/backend/cmd/dumpschema/main.go b/backend/cmd/dumpschema/main.go index 0a1a0ab..6afca97 100644 --- a/backend/cmd/dumpschema/main.go +++ b/backend/cmd/dumpschema/main.go @@ -10,11 +10,12 @@ package main import ( "fmt" - "log" + "log/slog" "os" "path/filepath" "strings" + applog "geniusrun/backend/internal/log" "geniusrun/backend/internal/store" ) @@ -26,6 +27,7 @@ type schemaEntry struct { } func main() { + slog.SetDefault(applog.NewLogger("info", os.Stdout)) tmpDir, err := os.MkdirTemp("", "geniusrun-dumpschema") must(err) defer os.RemoveAll(tmpDir) @@ -91,11 +93,12 @@ func main() { outPath := "../docs/DATABASE.md" must(os.WriteFile(outPath, []byte(b.String()), 0644)) - log.Printf("wrote %s", outPath) + slog.Info("wrote schema doc", "path", outPath) } func must(err error) { if err != nil { - log.Fatal(err) + slog.Error("dumpschema", "error", err) + os.Exit(1) } } diff --git a/backend/cmd/geniusrund/main.go b/backend/cmd/geniusrund/main.go index 271a60e..a043762 100644 --- a/backend/cmd/geniusrund/main.go +++ b/backend/cmd/geniusrund/main.go @@ -5,7 +5,6 @@ package main import ( "context" - "log" "log/slog" "net/http" "os" @@ -17,30 +16,42 @@ import ( "geniusrun/backend/internal/auth" "geniusrun/backend/internal/config" "geniusrun/backend/internal/garmin" - "geniusrun/backend/internal/log" + applog "geniusrun/backend/internal/log" "geniusrun/backend/internal/store" ) +// fatal logs through the application JSON logger and exits -- the +// structured replacement for log.Fatalf, so even startup failures come +// out as JSON lines. +func fatal(msg string, err error) { + slog.Error(msg, "error", err) + os.Exit(1) +} + func main() { + // Bootstrap logger at info so failures loading the env config itself + // (which carries the real log level) are still emitted as JSON. + slog.SetDefault(applog.NewLogger("info", os.Stdout)) + envCfg, err := config.LoadEnv() if err != nil { - log.Fatalf("config: %v", err) + fatal("load env config", err) } slog.SetDefault(applog.NewLogger(envCfg.LogLevel, os.Stdout)) db, err := store.Open(envCfg.DBPath) if err != nil { - log.Fatalf("open database: %v", err) + fatal("open database", err) } defer db.Close() overrides, err := db.ConfigValues(context.Background()) if err != nil { - log.Fatalf("app config: %v", err) + fatal("read app config overrides", err) } appCfg, err := config.LoadApp(overrides) if err != nil { - log.Fatalf("app config: %v", err) + fatal("load app config", err) } authVerifier, err := auth.NewOIDCVerifier(context.Background(), auth.OIDCConfig{ @@ -51,7 +62,7 @@ func main() { RequiredRole: envCfg.OIDCRequiredRole, }) if err != nil { - log.Fatalf("oidc: %v", err) + fatal("oidc verifier setup", err) } server := api.NewServer( @@ -80,17 +91,17 @@ func main() { httpServer := &http.Server{Addr: envCfg.BackendAddr, Handler: server.Router()} go func() { - log.Printf("geniusrund listening on %s", envCfg.BackendAddr) + slog.Info("geniusrund listening", "addr", envCfg.BackendAddr) if err := httpServer.ListenAndServe(); err != nil && err != http.ErrServerClosed { - log.Fatalf("http server: %v", err) + fatal("http server", err) } }() <-ctx.Done() - log.Println("shutting down...") + slog.Info("shutting down") shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) defer cancel() if err := httpServer.Shutdown(shutdownCtx); err != nil { - log.Printf("http server shutdown: %v", err) + slog.Error("http server shutdown", "error", err) } } diff --git a/backend/cmd/seedsample/main.go b/backend/cmd/seedsample/main.go index e0f1bb2..044d91b 100644 --- a/backend/cmd/seedsample/main.go +++ b/backend/cmd/seedsample/main.go @@ -9,22 +9,25 @@ import ( "context" "flag" "fmt" - "log" + "log/slog" + "os" "time" "geniusrun/backend/internal/classify" "geniusrun/backend/internal/garmin" + applog "geniusrun/backend/internal/log" "geniusrun/backend/internal/store" ) func main() { + slog.SetDefault(applog.NewLogger("info", os.Stdout)) dbPath := flag.String("db", "geniusrun_sample.db", "path to the SQLite database to seed") flag.Parse() ctx := context.Background() db, err := store.Open(*dbPath) if err != nil { - log.Fatalf("open db: %v", err) + fatal("open db", err) } defer db.Close() @@ -233,10 +236,17 @@ func seedIntervalLapsAndSamples(ctx context.Context, db *store.DB, userID, activ func must(err error) { if err != nil { - log.Fatal(err) + fatal("seedsample", err) } } +// fatal logs through the application JSON logger and exits -- the +// structured replacement for log.Fatal. +func fatal(msg string, err error) { + slog.Error(msg, "error", err) + os.Exit(1) +} + func mustFindKindID(ctx context.Context, db *store.DB, userID int64, name string) int64 { kinds, err := db.ListWorkoutKinds(ctx, userID, false) must(err) @@ -245,6 +255,7 @@ func mustFindKindID(ctx context.Context, db *store.DB, userID int64, name string return k.ID } } - log.Fatalf("seedsample: no workout kind named %q found for the seeded user (did ProvisionUser seed the taxonomy?)", name) + slog.Error("no workout kind with that name for the seeded user (did ProvisionUser seed the taxonomy?)", "kind", name) + os.Exit(1) return 0 } diff --git a/backend/internal/api/garmin.go b/backend/internal/api/garmin.go index 64f42e9..d126f81 100644 --- a/backend/internal/api/garmin.go +++ b/backend/internal/api/garmin.go @@ -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) } } } diff --git a/backend/internal/api/server.go b/backend/internal/api/server.go index 5f894c0..a05ece1 100644 --- a/backend/internal/api/server.go +++ b/backend/internal/api/server.go @@ -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) } } diff --git a/backend/internal/api/session.go b/backend/internal/api/session.go index 11d1ce7..4b0e24c 100644 --- a/backend/internal/api/session.go +++ b/backend/internal/api/session.go @@ -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 } diff --git a/backend/internal/api/setup.go b/backend/internal/api/setup.go index c7d724b..464b176 100644 --- a/backend/internal/api/setup.go +++ b/backend/internal/api/setup.go @@ -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) } } diff --git a/backend/internal/garmin/client.go b/backend/internal/garmin/client.go index 08c2862..d7dedbb 100644 --- a/backend/internal/garmin/client.go +++ b/backend/internal/garmin/client.go @@ -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++ diff --git a/backend/internal/garmin/client_test.go b/backend/internal/garmin/client_test.go index 34113c3..d4c8086 100644 --- a/backend/internal/garmin/client_test.go +++ b/backend/internal/garmin/client_test.go @@ -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) diff --git a/backend/internal/garmin/sync.go b/backend/internal/garmin/sync.go index 33344af..3cdd5e8 100644 --- a/backend/internal/garmin/sync.go +++ b/backend/internal/garmin/sync.go @@ -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)) diff --git a/backend/internal/store/profile.go b/backend/internal/store/profiles.go similarity index 100% rename from backend/internal/store/profile.go rename to backend/internal/store/profiles.go diff --git a/backend/internal/store/profile_test.go b/backend/internal/store/profiles_test.go similarity index 100% rename from backend/internal/store/profile_test.go rename to backend/internal/store/profiles_test.go diff --git a/backend/internal/store/users.go b/backend/internal/store/users.go index 250eae8..aeaed9a 100644 --- a/backend/internal/store/users.go +++ b/backend/internal/store/users.go @@ -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) }