From 10cdc4176a2b881f58024288472ca878bafa0eec Mon Sep 17 00:00:00 2001 From: Christophe Vila Date: Tue, 4 Aug 2026 19:59:48 +0200 Subject: [PATCH] refactor(log): split location into package/file/class/method, auto-derived Per the log schema: 'package' is the Go package (absent on Python-emitted lines), 'file' the Go/Python source basename, 'class' the Go receiver or Python class (omitted when there is none -- free functions no longer masquerade under a package-as-class), 'method' the emitting function. applog.App() now takes no arguments and derives all of it from runtime.Caller, so labels can never drift from the code; the manual http/wrapper emitters and forwarded wrapper.py lines (file= wrapper.py, no package) carry the same fields. Co-Authored-By: Claude Fable 5 --- backend/cmd/dumpschema/main.go | 4 +- backend/cmd/geniusrund/main.go | 8 +-- backend/cmd/seedsample/main.go | 4 +- backend/internal/api/api_test.go | 4 +- backend/internal/api/garmin.go | 2 +- backend/internal/api/server.go | 11 ++-- backend/internal/api/session.go | 6 +-- backend/internal/api/setup.go | 4 +- backend/internal/garmin/client.go | 11 ++-- backend/internal/garmin/client_test.go | 8 +-- backend/internal/garmin/sync.go | 4 +- backend/internal/garmin/wrapper/wrapper.py | 2 +- backend/internal/log/log.go | 58 +++++++++++++++++----- backend/internal/log/log_test.go | 12 +++-- 14 files changed, 91 insertions(+), 47 deletions(-) diff --git a/backend/cmd/dumpschema/main.go b/backend/cmd/dumpschema/main.go index 9059fa1..9638ce1 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)) - applog.App("main", "main").Info("wrote schema doc", "path", outPath) + applog.App().Info("wrote schema doc", "path", outPath) } func must(err error) { if err != nil { - applog.App("main", "must").Error("dumpschema failed", "error", err) + applog.App().Error("dumpschema failed", "error", err) os.Exit(1) } } diff --git a/backend/cmd/geniusrund/main.go b/backend/cmd/geniusrund/main.go index a17b616..ac22a36 100644 --- a/backend/cmd/geniusrund/main.go +++ b/backend/cmd/geniusrund/main.go @@ -24,7 +24,7 @@ import ( // structured replacement for log.Fatalf, so even startup failures come // out as JSON lines. func fatal(msg string, err error) { - applog.App("main", "fatal").Error(msg, "error", err) + applog.App().Error(msg, "error", err) os.Exit(1) } @@ -103,17 +103,17 @@ func main() { httpServer := &http.Server{Addr: envCfg.BackendAddr, Handler: server.Router()} go func() { - applog.App("main", "main").Info("geniusrund listening", "addr", envCfg.BackendAddr) + applog.App().Info("geniusrund listening", "addr", envCfg.BackendAddr) if err := httpServer.ListenAndServe(); err != nil && err != http.ErrServerClosed { fatal("http server", err) } }() <-ctx.Done() - applog.App("main", "main").Info("shutting down") + applog.App().Info("shutting down") shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) defer cancel() if err := httpServer.Shutdown(shutdownCtx); err != nil { - applog.App("main", "main").Error("http server shutdown", "error", err) + applog.App().Error("http server shutdown", "error", err) } } diff --git a/backend/cmd/seedsample/main.go b/backend/cmd/seedsample/main.go index 5c0d6cb..4ca3953 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) { - applog.App("main", "fatal").Error(msg, "error", err) + applog.App().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 } } - applog.App("main", "mustFindKindID").Error("no workout kind with that name for the seeded user (did ProvisionUser seed the taxonomy?)", "kind", name) + applog.App().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 7112441..2dfdc77 100644 --- a/backend/internal/api/api_test.go +++ b/backend/internal/api/api_test.go @@ -1158,8 +1158,8 @@ 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["type"] != "http" || entry["class"] != "api" || entry["method"] != "loggingMiddleware" { - t.Errorf("schema fields = %v, want type=http class=api method=loggingMiddleware", entry) + if entry["type"] != "http" || entry["package"] != "api" || entry["file"] != "server.go" || entry["method"] != "loggingMiddleware" { + t.Errorf("schema fields = %v, want type=http package=api file=server.go method=loggingMiddleware", entry) } if _, hasMsg := entry["msg"]; hasMsg { t.Errorf("expected no msg on the http record, got %v", entry["msg"]) diff --git a/backend/internal/api/garmin.go b/backend/internal/api/garmin.go index d1aadfe..508f276 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.App("api.Server", "recordAuthResult").Error("mark garmin connected", "user_id", userID, "error", err) + applog.App().Error("mark garmin connected", "user_id", userID, "error", err) } } } diff --git a/backend/internal/api/server.go b/backend/internal/api/server.go index 881c260..480e9b6 100644 --- a/backend/internal/api/server.go +++ b/backend/internal/api/server.go @@ -177,7 +177,8 @@ func loggingMiddleware(next http.Handler) http.Handler { } slog.Default().LogAttrs(r.Context(), level, "", slog.String("type", "http"), - slog.String("class", "api"), + slog.String("package", "api"), + slog.String("file", "server.go"), slog.String("method", "loggingMiddleware"), slog.String("http_method", r.Method), slog.String("path", r.URL.Path), @@ -256,7 +257,7 @@ func (s *Server) removeUserClient(userID int64) { if ok { if err := client.Close(); err != nil { - applog.App("api.Server", "removeUserClient").Error("close garmin client for deleted user", "user_id", userID, "error", err) + applog.App().Error("close garmin client for deleted user", "user_id", userID, "error", err) } } if s.ClientConfig.TokenStorePath == "" { @@ -264,7 +265,7 @@ func (s *Server) removeUserClient(userID int64) { } tokenStoreDir := filepath.Join(s.ClientConfig.TokenStorePath, strconv.FormatInt(userID, 10)) if err := os.RemoveAll(tokenStoreDir); err != nil { - applog.App("api.Server", "removeUserClient").Error("remove token store dir for deleted user", "user_id", userID, "error", err) + applog.App().Error("remove token store dir for deleted user", "user_id", userID, "error", err) } } @@ -311,7 +312,7 @@ func (s *Server) backgroundSync(userID int64, fn func(ctx context.Context) error s.mu.Unlock() }() if err := fn(context.Background()); err != nil { - applog.App("api.Server", "backgroundSync").Error("background sync failed", "user_id", userID, "error", err) + applog.App().Error("background sync failed", "user_id", userID, "error", err) } }() return true @@ -331,7 +332,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 { - applog.App("api", "writeJSON").Error("encode response", "error", err) + applog.App().Error("encode response", "error", err) } } diff --git a/backend/internal/api/session.go b/backend/internal/api/session.go index b6d8501..153780c 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.App("api.Server", "handleSessionCallback").Warn("missing txn cookie", "error", err) + applog.App().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.App("api.Server", "handleSessionCallback").Warn("failed to parse txn cookie", "error", err) + applog.App().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.App("api.Server", "handleSessionCallback").Error("callback failed (state mismatch, code exchange, or ID-token verification)", "error", err) + applog.App().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 f6a7224..44e540f 100644 --- a/backend/internal/api/setup.go +++ b/backend/internal/api/setup.go @@ -195,10 +195,10 @@ func (s *Server) handleSetupComplete(w http.ResponseWriter, r *http.Request) { // 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) + applog.App().Error("remove stale token store dir", "user_id", userID, "error", err) } if err := os.Rename(oldDir, newDir); err != nil && !os.IsNotExist(err) { - applog.App("api.Server", "handleSetupComplete").Error("rename setup token store dir", "user_id", userID, "error", err) + applog.App().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 2b13a65..c1e2920 100644 --- a/backend/internal/garmin/client.go +++ b/backend/internal/garmin/client.go @@ -227,7 +227,9 @@ func (c *subprocessClient) execute(ctx context.Context, cmd string, params any) defer func() { attrs := []slog.Attr{ slog.String("type", "wrapper"), - slog.String("class", "garmin.subprocessClient"), + slog.String("package", "garmin"), + slog.String("file", "client.go"), + slog.String("class", "subprocessClient"), slog.String("method", "execute"), slog.String("cmd", cmd), slog.Any("params", params), @@ -384,17 +386,18 @@ 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("", "type", "wrapper", "class", "garmin", "method", "forwardWrapperStderr", "line", line) + slog.Warn("", "type", "wrapper", "package", "garmin", "file", "client.go", "method", "forwardWrapperStderr", "line", line) continue } msg, _ := entry["msg"].(string) levelName, _ := entry["level"].(string) delete(entry, "msg") delete(entry, "level") - // class is the Python module; method arrives in the entry itself + // Python-emitted lines carry no "package" (a Go-only field) and no + // "class" (wrapper.py has none); 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")) + attrs = append(attrs, slog.String("type", "wrapper"), slog.String("file", "wrapper.py")) for k, v := range entry { attrs = append(attrs, slog.Any(k, v)) } diff --git a/backend/internal/garmin/client_test.go b/backend/internal/garmin/client_test.go index e5db9dd..617d814 100644 --- a/backend/internal/garmin/client_test.go +++ b/backend/internal/garmin/client_test.go @@ -448,8 +448,8 @@ 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["type"] != "wrapper" || entry["class"] != "garmin.subprocessClient" || entry["method"] != "execute" { - t.Errorf("schema fields = %v, want type=wrapper class=garmin.subprocessClient method=execute", entry) + if entry["type"] != "wrapper" || entry["package"] != "garmin" || entry["file"] != "client.go" || entry["class"] != "subprocessClient" || entry["method"] != "execute" { + t.Errorf("schema fields = %v, want type=wrapper package=garmin file=client.go class=subprocessClient method=execute", entry) } if _, hasMsg := entry["msg"]; hasMsg { t.Errorf("expected no msg on the wrapper-call record, got %v", entry["msg"]) @@ -516,8 +516,8 @@ 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["type"] != "wrapper" || first["class"] != "wrapper" { - t.Errorf("first = %v, want error attr preserved and type=wrapper class=wrapper", first) + if first["error"] != "boom" || first["type"] != "wrapper" || first["file"] != "wrapper.py" { + t.Errorf("first = %v, want error attr preserved and type=wrapper file=wrapper.py", first) } var second map[string]any diff --git a/backend/internal/garmin/sync.go b/backend/internal/garmin/sync.go index 8891675..a9cf918 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.App("garmin.Sync", "fillPendingWorkouts").Warn("workout not found on Garmin, marking as such (will not retry)", "garmin_activity_id", a.GarminActivityID, "error", err) + applog.App().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.App("garmin.Sync", "fillPendingWorkouts").Warn("fill workout failed, will retry next sync", "garmin_activity_id", a.GarminActivityID, "error", err) + applog.App().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/wrapper.py b/backend/internal/garmin/wrapper/wrapper.py index 7b3d244..8202100 100644 --- a/backend/internal/garmin/wrapper/wrapper.py +++ b/backend/internal/garmin/wrapper/wrapper.py @@ -31,7 +31,7 @@ def _log(level, msg, **attrs): never print free text to stderr or stdout from this process (stdout is 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).""" + log schema (type=wrapper, file=wrapper.py).""" 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) diff --git a/backend/internal/log/log.go b/backend/internal/log/log.go index ee33dd5..dd2843d 100644 --- a/backend/internal/log/log.go +++ b/backend/internal/log/log.go @@ -1,15 +1,18 @@ // Package applog provides geniusrun's structured JSON logging: a // 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. +// records with the schema fields every geniusrun log line carries -- +// "type" ("app" | "http" | "wrapper"), "package" (Go package; absent on +// Python-emitted lines), "file" (Go/Python source file basename), "class" +// (Go receiver type or Python class, omitted when there is none), and +// "method" (the emitting Go/Python function). "msg" is optional: +// NewLogger's handler drops it when empty. package applog import ( "io" "log/slog" + "path/filepath" + "runtime" "strings" ) @@ -30,13 +33,44 @@ func NewLogger(level string, w io.Writer) *slog.Logger { })) } -// 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) +// App returns the default logger tagged with the schema fields for an +// ordinary application record (type=app), deriving the emitting location +// from the caller via the runtime: package, file, class (the receiver +// type, omitted for free functions), method. Derivation instead of +// hand-typed strings means the labels can never drift from the code. The +// http and wrapper emitters (internal/api's logging middleware, +// internal/garmin's execute/forwardWrapperStderr) tag their own type and +// location instead. +func App() *slog.Logger { + pkg, file, class, method := location(1) + logger := slog.Default().With("type", "app", "package", pkg, "file", file) + if class != "" { + logger = logger.With("class", class) + } + return logger.With("method", method) +} + +// location resolves the caller (skip frames above this function's caller) +// into the log schema's package/file/class/method fields. A method's +// runtime name looks like "geniusrun/backend/internal/api.(*Server).X"; +// a free function's like "geniusrun/backend/internal/api.X"; a closure +// gets its parent's name plus ".funcN", kept verbatim in method. +func location(skip int) (pkg, file, class, method string) { + pc, path, _, ok := runtime.Caller(skip + 1) + if !ok { + return "unknown", "unknown", "", "unknown" + } + file = filepath.Base(path) + full := runtime.FuncForPC(pc).Name() + base := full[strings.LastIndex(full, "/")+1:] + pkg, rest, _ := strings.Cut(base, ".") + if strings.HasPrefix(rest, "(*") { + if end := strings.Index(rest, ")."); end != -1 { + class = rest[2:end] + rest = rest[end+2:] + } + } + return pkg, file, class, rest } func parseLevel(level string) slog.Level { diff --git a/backend/internal/log/log_test.go b/backend/internal/log/log_test.go index 0c21edc..c9579fe 100644 --- a/backend/internal/log/log_test.go +++ b/backend/internal/log/log_test.go @@ -60,13 +60,19 @@ func TestApp_TagsMandatoryFields(t *testing.T) { slog.SetDefault(NewLogger("info", &buf)) defer slog.SetDefault(prev) - App("api.Server", "handleThing").Info("did it", "extra", 1) + App().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) + if decoded["type"] != "app" || decoded["package"] != "log" || decoded["file"] != "log_test.go" { + t.Errorf("fields = %+v, want type=app package=log (import-path element) file=log_test.go", decoded) + } + if decoded["method"] != "TestApp_TagsMandatoryFields" { + t.Errorf("method = %v, want the emitting function name", decoded["method"]) + } + if _, hasClass := decoded["class"]; hasClass { + t.Errorf("class should be omitted for a free function, got %v", decoded["class"]) } }