diff --git a/backend/cmd/dumpschema/main.go b/backend/cmd/dumpschema/main.go index 6afca97..9059fa1 100644 --- a/backend/cmd/dumpschema/main.go +++ b/backend/cmd/dumpschema/main.go @@ -93,12 +93,12 @@ func main() { outPath := "../docs/DATABASE.md" must(os.WriteFile(outPath, []byte(b.String()), 0644)) - slog.Info("wrote schema doc", "path", outPath) + applog.App("main", "main").Info("wrote schema doc", "path", outPath) } func must(err error) { if err != nil { - slog.Error("dumpschema", "error", err) + applog.App("main", "must").Error("dumpschema failed", "error", err) os.Exit(1) } } diff --git a/backend/cmd/geniusrund/main.go b/backend/cmd/geniusrund/main.go index 79e5efd..a17b616 100644 --- a/backend/cmd/geniusrund/main.go +++ b/backend/cmd/geniusrund/main.go @@ -24,14 +24,14 @@ import ( // 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) + applog.App("main", "fatal").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)) + slog.SetDefault(applog.NewLogger("warn", os.Stdout)) envCfg, err := config.LoadEnv() if err != nil { @@ -103,17 +103,17 @@ func main() { httpServer := &http.Server{Addr: envCfg.BackendAddr, Handler: server.Router()} go func() { - slog.Info("geniusrund listening", "addr", envCfg.BackendAddr) + applog.App("main", "main").Info("geniusrund listening", "addr", envCfg.BackendAddr) if err := httpServer.ListenAndServe(); err != nil && err != http.ErrServerClosed { fatal("http server", err) } }() <-ctx.Done() - slog.Info("shutting down") + applog.App("main", "main").Info("shutting down") shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) defer cancel() if err := httpServer.Shutdown(shutdownCtx); err != nil { - slog.Error("http server shutdown", "error", err) + applog.App("main", "main").Error("http server shutdown", "error", err) } } diff --git a/backend/cmd/seedsample/main.go b/backend/cmd/seedsample/main.go index 044d91b..5c0d6cb 100644 --- a/backend/cmd/seedsample/main.go +++ b/backend/cmd/seedsample/main.go @@ -243,7 +243,7 @@ func must(err error) { // 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) + applog.App("main", "fatal").Error(msg, "error", err) os.Exit(1) } @@ -255,7 +255,7 @@ func mustFindKindID(ctx context.Context, db *store.DB, userID int64, name string return k.ID } } - slog.Error("no workout kind with that name for the seeded user (did ProvisionUser seed the taxonomy?)", "kind", name) + applog.App("main", "mustFindKindID").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/api_test.go b/backend/internal/api/api_test.go index 68185b4..7112441 100644 --- a/backend/internal/api/api_test.go +++ b/backend/internal/api/api_test.go @@ -1146,10 +1146,11 @@ func TestSessionCallback_MintsSessionCookieCarryingIDToken(t *testing.T) { func TestRequestLoggingMiddleware_LogsMethodPathStatusDuration(t *testing.T) { s, _, _ := newTestServer(t) var buf bytes.Buffer - logger := slog.New(slog.NewJSONHandler(&buf, nil)) + prev := slog.Default() + slog.SetDefault(applog.NewLogger("info", &buf)) + defer slog.SetDefault(prev) req := httptest.NewRequest(http.MethodGet, "/api/health", nil) - req = req.WithContext(applog.WithLogger(req.Context(), logger)) rec := httptest.NewRecorder() s.Router().ServeHTTP(rec, req) @@ -1157,11 +1158,14 @@ func TestRequestLoggingMiddleware_LogsMethodPathStatusDuration(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"] != "HTTP request" { - t.Errorf("msg = %v, want \"http request\"", entry["msg"]) + if entry["type"] != "http" || entry["class"] != "api" || entry["method"] != "loggingMiddleware" { + t.Errorf("schema fields = %v, want type=http class=api method=loggingMiddleware", entry) } - if entry["method"] != "GET" || entry["path"] != "/api/health" { - t.Errorf("method/path = %v/%v, want GET//api/health", entry["method"], entry["path"]) + if _, hasMsg := entry["msg"]; hasMsg { + t.Errorf("expected no msg on the http record, got %v", entry["msg"]) + } + if entry["http_method"] != "GET" || entry["path"] != "/api/health" { + t.Errorf("http_method/path = %v/%v, want GET//api/health", entry["http_method"], entry["path"]) } if entry["status"] != float64(http.StatusOK) { t.Errorf("status = %v, want 200", entry["status"]) @@ -1176,10 +1180,11 @@ func TestRequestLoggingMiddleware_5xxLogsAtWarnLevel(t *testing.T) { db.Close() // force a downstream DB call to fail with a 500 var buf bytes.Buffer - logger := slog.New(slog.NewJSONHandler(&buf, nil)) + prev := slog.Default() + slog.SetDefault(applog.NewLogger("info", &buf)) + defer slog.SetDefault(prev) req := httptest.NewRequest(http.MethodGet, "/api/profile", nil) - req = req.WithContext(applog.WithLogger(req.Context(), logger)) cookie, err := auth.MintSessionCookie(auth.Claims{Sub: "test-user", Name: "Test User", Email: "test@example.com"}, "", testSessionConfig.Secret, testSessionConfig.Duration, testSessionConfig.Secure) if err != nil { t.Fatalf("mint session cookie: %v", err) diff --git a/backend/internal/api/garmin.go b/backend/internal/api/garmin.go index d126f81..d1aadfe 100644 --- a/backend/internal/api/garmin.go +++ b/backend/internal/api/garmin.go @@ -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 { - applog.FromContext(ctx).Error("mark garmin connected", "user_id", userID, "error", err) + applog.App("api.Server", "recordAuthResult").Error("mark garmin connected", "user_id", userID, "error", err) } } } diff --git a/backend/internal/api/server.go b/backend/internal/api/server.go index a05ece1..881c260 100644 --- a/backend/internal/api/server.go +++ b/backend/internal/api/server.go @@ -15,7 +15,6 @@ import ( "path/filepath" "strconv" "sync" - "sync/atomic" "time" "geniusrun/backend/internal/auth" @@ -162,19 +161,12 @@ func (s *Server) handleHealth(w http.ResponseWriter, r *http.Request) { writeJSON(w, http.StatusOK, map[string]string{"status": "ok"}) } -var requestIDCounter atomic.Int64 - -// loggingMiddleware logs one JSON line per HTTP request (method, -// path, status, duration) and attaches a per-request logger (tagged with a -// request_id) to the request context, so any downstream call this request -// triggers -- e.g. a Garmin wrapper round-trip -- logs with the same -// correlating id (see internal/applog, internal/garmin's roundTrip). +// loggingMiddleware logs one type=http JSON line per HTTP request. The +// record's meaning is fully carried by its fields (http_method, path, +// status, duration_ms), so it has no msg; "method" stays reserved for the +// emitting function per the log schema, hence http_method for the verb. func loggingMiddleware(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - id := fmt.Sprintf("req-%d", requestIDCounter.Add(1)) - logger := applog.FromContext(r.Context()).With("request_id", id) - r = r.WithContext(applog.WithLogger(r.Context(), logger)) - ww := middleware.NewWrapResponseWriter(w, r.ProtoMajor) start := time.Now() next.ServeHTTP(ww, r) @@ -183,8 +175,11 @@ func loggingMiddleware(next http.Handler) http.Handler { if ww.Status() >= 500 { level = slog.LevelWarn } - logger.LogAttrs(r.Context(), level, "HTTP request", - slog.String("method", r.Method), + slog.Default().LogAttrs(r.Context(), level, "", + slog.String("type", "http"), + slog.String("class", "api"), + slog.String("method", "loggingMiddleware"), + slog.String("http_method", r.Method), slog.String("path", r.URL.Path), slog.Int("status", ww.Status()), slog.Int64("duration_ms", time.Since(start).Milliseconds()), @@ -261,7 +256,7 @@ func (s *Server) removeUserClient(userID int64) { if ok { if err := client.Close(); err != nil { - slog.Error("close garmin client for deleted user", "user_id", userID, "error", err) + applog.App("api.Server", "removeUserClient").Error("close garmin client for deleted user", "user_id", userID, "error", err) } } if s.ClientConfig.TokenStorePath == "" { @@ -269,7 +264,7 @@ func (s *Server) removeUserClient(userID int64) { } tokenStoreDir := filepath.Join(s.ClientConfig.TokenStorePath, strconv.FormatInt(userID, 10)) if err := os.RemoveAll(tokenStoreDir); err != nil { - slog.Error("remove token store dir for deleted user", "user_id", userID, "error", err) + applog.App("api.Server", "removeUserClient").Error("remove token store dir for deleted user", "user_id", userID, "error", err) } } @@ -316,7 +311,7 @@ func (s *Server) backgroundSync(userID int64, fn func(ctx context.Context) error s.mu.Unlock() }() if err := fn(context.Background()); err != nil { - slog.Error("background sync failed", "user_id", userID, "error", err) + applog.App("api.Server", "backgroundSync").Error("background sync failed", "user_id", userID, "error", err) } }() return true @@ -336,7 +331,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 { - slog.Error("encode response", "error", err) + applog.App("api", "writeJSON").Error("encode response", "error", err) } } diff --git a/backend/internal/api/session.go b/backend/internal/api/session.go index a434fae..b6d8501 100644 --- a/backend/internal/api/session.go +++ b/backend/internal/api/session.go @@ -64,7 +64,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 { - applog.FromContext(r.Context()).Warn("session callback: missing txn cookie", "error", err) + applog.App("api.Server", "handleSessionCallback").Warn("missing txn cookie", "error", err) http.Redirect(w, r, s.SessionConfig.FrontendURL+"/?auth_error=failed", http.StatusFound) return } @@ -72,14 +72,14 @@ func (s *Server) handleSessionCallback(w http.ResponseWriter, r *http.Request) { txn, err := auth.ParseTxnCookie(txnCookie, s.SessionConfig.Secret) if err != nil { - applog.FromContext(r.Context()).Warn("session callback: failed to parse txn cookie", "error", err) + applog.App("api.Server", "handleSessionCallback").Warn("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 { - applog.FromContext(r.Context()).Error("session callback failed (state mismatch, code exchange, or ID-token verification)", "error", err) + applog.App("api.Server", "handleSessionCallback").Error("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 6458fa9..f6a7224 100644 --- a/backend/internal/api/setup.go +++ b/backend/internal/api/setup.go @@ -189,8 +189,16 @@ func (s *Server) handleSetupComplete(w http.ResponseWriter, r *http.Request) { if s.ClientConfig.TokenStorePath != "" { oldDir := setupTokenStoreDir(s.ClientConfig.TokenStorePath, claims.Sub) newDir := filepath.Join(s.ClientConfig.TokenStorePath, strconv.FormatInt(userID, 10)) + // A stale {userID} directory can survive from a previous account + // with the same id -- pre-production the DB file is freely deleted + // and recreated (ids restart at 1) while the token-store root lives + // on, and os.Rename refuses to replace a non-empty directory. The + // just-validated setup session must win, so clear the target first. + if err := os.RemoveAll(newDir); err != nil { + applog.App("api.Server", "handleSetupComplete").Error("remove stale token store dir", "user_id", userID, "error", err) + } if err := os.Rename(oldDir, newDir); err != nil && !os.IsNotExist(err) { - applog.FromContext(r.Context()).Error("rename setup token store dir", "user_id", userID, "error", err) + applog.App("api.Server", "handleSetupComplete").Error("rename setup token store dir", "user_id", userID, "error", err) } } diff --git a/backend/internal/api/setup_test.go b/backend/internal/api/setup_test.go index edf3ff0..3821d69 100644 --- a/backend/internal/api/setup_test.go +++ b/backend/internal/api/setup_test.go @@ -254,3 +254,64 @@ func unmarshalBody(t *testing.T, rec *httptest.ResponseRecorder, v any) { t.Fatalf("unmarshal response body %q: %v", rec.Body.String(), err) } } + +// Regression: os.Rename refuses to replace an existing directory, so a +// stale {userID} token-store dir (left behind when the DB file was +// recreated -- ids restart at 1 -- while the token-store root survived) +// used to make setup completion silently keep the OLD tokens in place. +// The fresh, just-validated session's directory must win. +func TestSetupComplete_ReplacesStaleTokenStoreDir(t *testing.T) { + db, err := store.Open(filepath.Join(t.TempDir(), "setup_stale_dir_test.db")) + if err != nil { + t.Fatalf("store.Open: %v", err) + } + t.Cleanup(func() { db.Close() }) + m := &garmin.MockClient{} + tokenStoreRoot := t.TempDir() + s := NewServer(db, func(garmin.ClientConfig) garmin.Client { return m }, garmin.ClientConfig{TokenStorePath: tokenStoreRoot}, garmin.SyncConfig{}, &authmock.Verifier{}, testSessionConfig) + router := s.Router() + + // The ephemeral setup dir the wrapper would have written tokens into. + setupDir := setupTokenStoreDir(tokenStoreRoot, "test-user") + if err := os.MkdirAll(setupDir, 0o755); err != nil { + t.Fatalf("mkdir setup dir: %v", err) + } + if err := os.WriteFile(filepath.Join(setupDir, "oauth_token"), []byte("fresh"), 0o600); err != nil { + t.Fatalf("write fresh token: %v", err) + } + // A stale dir already occupying the permanent {userID} path (fresh DB + // starts ids at 1). + staleDir := filepath.Join(tokenStoreRoot, "1") + if err := os.MkdirAll(staleDir, 0o755); err != nil { + t.Fatalf("mkdir stale dir: %v", err) + } + if err := os.WriteFile(filepath.Join(staleDir, "oauth_token"), []byte("stale"), 0o600); err != nil { + t.Fatalf("write stale token: %v", err) + } + + rec := doJSON(t, router, http.MethodPost, "/api/setup/garmin/login", map[string]any{ + "garmin_email": "runner@example.com", "garmin_password": "hunter2", + }) + if rec.Code != http.StatusOK { + t.Fatalf("login status = %d, body = %s", rec.Code, rec.Body.String()) + } + rec = doJSON(t, router, http.MethodPost, "/api/setup/complete", map[string]any{"display_name": "Lucie"}) + if rec.Code != http.StatusOK { + t.Fatalf("complete status = %d, body = %s", rec.Code, rec.Body.String()) + } + + u, found, err := db.GetUserBySub(newCtx(), "test-user") + if err != nil || !found { + t.Fatalf("GetUserBySub: found=%v err=%v", found, err) + } + token, err := os.ReadFile(filepath.Join(tokenStoreRoot, itoa(u.ID), "oauth_token")) + if err != nil { + t.Fatalf("read token after complete: %v", err) + } + if string(token) != "fresh" { + t.Fatalf("token content = %q, want the fresh setup session to replace the stale dir", token) + } + if _, err := os.Stat(setupDir); !os.IsNotExist(err) { + t.Errorf("ephemeral setup dir still present after rename: %v", err) + } +} diff --git a/backend/internal/garmin/client.go b/backend/internal/garmin/client.go index ed182bb..2b13a65 100644 --- a/backend/internal/garmin/client.go +++ b/backend/internal/garmin/client.go @@ -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)}, }) diff --git a/backend/internal/garmin/client_test.go b/backend/internal/garmin/client_test.go index 17e616a..e5db9dd 100644 --- a/backend/internal/garmin/client_test.go +++ b/backend/internal/garmin/client_test.go @@ -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) diff --git a/backend/internal/garmin/sync.go b/backend/internal/garmin/sync.go index 3cdd5e8..8891675 100644 --- a/backend/internal/garmin/sync.go +++ b/backend/internal/garmin/sync.go @@ -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)) diff --git a/backend/internal/garmin/wrapper/tests/test_wrapper.py b/backend/internal/garmin/wrapper/tests/test_wrapper.py index b55d2c5..42427d6 100644 --- a/backend/internal/garmin/wrapper/tests/test_wrapper.py +++ b/backend/internal/garmin/wrapper/tests/test_wrapper.py @@ -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} diff --git a/backend/internal/garmin/wrapper/wrapper.py b/backend/internal/garmin/wrapper/wrapper.py index e223c85..7b3d244 100644 --- a/backend/internal/garmin/wrapper/wrapper.py +++ b/backend/internal/garmin/wrapper/wrapper.py @@ -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 { diff --git a/backend/internal/log/log.go b/backend/internal/log/log.go index 4d4b74c..ee33dd5 100644 --- a/backend/internal/log/log.go +++ b/backend/internal/log/log.go @@ -1,12 +1,13 @@ // Package applog provides geniusrun's structured JSON logging: a -// log/slog-based logger writing to stdout, plus context helpers so a -// logger enriched in one layer (e.g. internal/api's HTTP middleware, -// attaching a request_id) is picked up by another (e.g. internal/garmin's -// wrapper-call logging) without either package depending on the other. +// log/slog-based logger writing to stdout, plus the App helper that tags +// records with the mandatory schema fields every geniusrun log line +// carries -- "type" ("app" | "http" | "wrapper"), "class" (Go type with +// its package, or the package/module name for free functions), and +// "method" (the Go or Python function emitting the record). "msg" is +// optional: NewLogger's handler drops it when empty. package applog import ( - "context" "io" "log/slog" "strings" @@ -14,9 +15,28 @@ import ( // NewLogger builds a JSON-handler *slog.Logger writing to w at the given // level ("debug"|"info"|"warn"|"error", case-insensitive; anything else -// defaults to info). +// defaults to info). Empty msg values are omitted from the output -- +// records whose meaning is fully carried by type/class/method and attrs +// (e.g. the HTTP request line) don't need one. func NewLogger(level string, w io.Writer) *slog.Logger { - return slog.New(slog.NewJSONHandler(w, &slog.HandlerOptions{Level: parseLevel(level)})) + return slog.New(slog.NewJSONHandler(w, &slog.HandlerOptions{ + Level: parseLevel(level), + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if len(groups) == 0 && a.Key == slog.MessageKey && a.Value.String() == "" { + return slog.Attr{} + } + return a + }, + })) +} + +// App returns the default logger tagged with the mandatory schema fields +// for an ordinary application record: type=app, plus the emitting class +// and method. The http and wrapper emitters (internal/api's logging +// middleware, internal/garmin's execute/forwardWrapperStderr) tag their +// own type instead. +func App(class, method string) *slog.Logger { + return slog.Default().With("type", "app", "class", class, "method", method) } func parseLevel(level string) slog.Level { @@ -31,21 +51,3 @@ func parseLevel(level string) slog.Level { return slog.LevelInfo } } - -type ctxKey struct{} - -// WithLogger returns a context carrying logger, retrievable via FromContext. -func WithLogger(ctx context.Context, logger *slog.Logger) context.Context { - return context.WithValue(ctx, ctxKey{}, logger) -} - -// FromContext returns the logger stashed by WithLogger, or slog.Default() -// if none was -- callers (e.g. the background incremental-sync loop, or -// tests that don't bother injecting one) always get a working logger, -// never nil. -func FromContext(ctx context.Context) *slog.Logger { - if logger, ok := ctx.Value(ctxKey{}).(*slog.Logger); ok { - return logger - } - return slog.Default() -} diff --git a/backend/internal/log/log_test.go b/backend/internal/log/log_test.go index a80289a..0c21edc 100644 --- a/backend/internal/log/log_test.go +++ b/backend/internal/log/log_test.go @@ -2,7 +2,6 @@ package applog import ( "bytes" - "context" "encoding/json" "log/slog" "strings" @@ -38,17 +37,36 @@ func TestNewLogger_WritesValidJSON(t *testing.T) { } } -func TestWithLogger_FromContext_RoundTrip(t *testing.T) { - logger := slog.New(slog.NewJSONHandler(&bytes.Buffer{}, nil)) - ctx := WithLogger(context.Background(), logger) +func TestNewLogger_OmitsEmptyMsg(t *testing.T) { + var buf bytes.Buffer + logger := NewLogger("info", &buf) + logger.Info("", "type", "http", "status", 200) - if got := FromContext(ctx); got != logger { - t.Errorf("FromContext returned a different logger than what was stashed") + var decoded map[string]any + if err := json.Unmarshal(buf.Bytes(), &decoded); err != nil { + t.Fatalf("output not JSON: %v (%q)", err, buf.String()) + } + if _, present := decoded["msg"]; present { + t.Errorf("empty msg should be omitted, got %+v", decoded) + } + if decoded["type"] != "http" { + t.Errorf("attrs lost alongside dropped msg: %+v", decoded) } } -func TestFromContext_DefaultsWhenNoneSet(t *testing.T) { - if got := FromContext(context.Background()); got == nil { - t.Fatal("FromContext on a bare context returned nil, want slog.Default()") +func TestApp_TagsMandatoryFields(t *testing.T) { + var buf bytes.Buffer + prev := slog.Default() + slog.SetDefault(NewLogger("info", &buf)) + defer slog.SetDefault(prev) + + App("api.Server", "handleThing").Info("did it", "extra", 1) + + var decoded map[string]any + if err := json.Unmarshal(buf.Bytes(), &decoded); err != nil { + t.Fatalf("output not JSON: %v", err) + } + if decoded["type"] != "app" || decoded["class"] != "api.Server" || decoded["method"] != "handleThing" { + t.Errorf("mandatory fields = %+v, want type=app class=api.Server method=handleThing", decoded) } }