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 <noreply@anthropic.com>
This commit is contained in:
2026-08-04 19:59:48 +02:00
parent 6effb79097
commit 10cdc4176a
14 changed files with 91 additions and 47 deletions

View File

@@ -93,12 +93,12 @@ func main() {
outPath := "../docs/DATABASE.md" outPath := "../docs/DATABASE.md"
must(os.WriteFile(outPath, []byte(b.String()), 0644)) 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) { func must(err error) {
if err != nil { if err != nil {
applog.App("main", "must").Error("dumpschema failed", "error", err) applog.App().Error("dumpschema failed", "error", err)
os.Exit(1) os.Exit(1)
} }
} }

View File

@@ -24,7 +24,7 @@ import (
// structured replacement for log.Fatalf, so even startup failures come // structured replacement for log.Fatalf, so even startup failures come
// out as JSON lines. // out as JSON lines.
func fatal(msg string, err error) { func fatal(msg string, err error) {
applog.App("main", "fatal").Error(msg, "error", err) applog.App().Error(msg, "error", err)
os.Exit(1) os.Exit(1)
} }
@@ -103,17 +103,17 @@ func main() {
httpServer := &http.Server{Addr: envCfg.BackendAddr, Handler: server.Router()} httpServer := &http.Server{Addr: envCfg.BackendAddr, Handler: server.Router()}
go func() { 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 { if err := httpServer.ListenAndServe(); err != nil && err != http.ErrServerClosed {
fatal("http server", err) fatal("http server", err)
} }
}() }()
<-ctx.Done() <-ctx.Done()
applog.App("main", "main").Info("shutting down") applog.App().Info("shutting down")
shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second) shutdownCtx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
defer cancel() defer cancel()
if err := httpServer.Shutdown(shutdownCtx); err != nil { 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)
} }
} }

View File

@@ -243,7 +243,7 @@ func must(err error) {
// fatal logs through the application JSON logger and exits -- the // fatal logs through the application JSON logger and exits -- the
// structured replacement for log.Fatal. // structured replacement for log.Fatal.
func fatal(msg string, err error) { func fatal(msg string, err error) {
applog.App("main", "fatal").Error(msg, "error", err) applog.App().Error(msg, "error", err)
os.Exit(1) os.Exit(1)
} }
@@ -255,7 +255,7 @@ func mustFindKindID(ctx context.Context, db *store.DB, userID int64, name string
return k.ID 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) os.Exit(1)
return 0 return 0
} }

View File

@@ -1158,8 +1158,8 @@ func TestRequestLoggingMiddleware_LogsMethodPathStatusDuration(t *testing.T) {
if err := json.Unmarshal(buf.Bytes(), &entry); err != nil { if err := json.Unmarshal(buf.Bytes(), &entry); err != nil {
t.Fatalf("log output is not valid JSON: %v (%q)", err, buf.String()) t.Fatalf("log output is not valid JSON: %v (%q)", err, buf.String())
} }
if entry["type"] != "http" || entry["class"] != "api" || entry["method"] != "loggingMiddleware" { if entry["type"] != "http" || entry["package"] != "api" || entry["file"] != "server.go" || entry["method"] != "loggingMiddleware" {
t.Errorf("schema fields = %v, want type=http class=api method=loggingMiddleware", entry) t.Errorf("schema fields = %v, want type=http package=api file=server.go method=loggingMiddleware", entry)
} }
if _, hasMsg := entry["msg"]; hasMsg { if _, hasMsg := entry["msg"]; hasMsg {
t.Errorf("expected no msg on the http record, got %v", entry["msg"]) t.Errorf("expected no msg on the http record, got %v", entry["msg"])

View File

@@ -45,7 +45,7 @@ func (s *Server) recordAuthResult(ctx context.Context, userID int64, res garmin.
if res.Status == garmin.AuthSuccess { if res.Status == garmin.AuthSuccess {
if err := s.DB.MarkGarminConnected(ctx, userID); err != nil { 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)
} }
} }
} }

View File

@@ -177,7 +177,8 @@ func loggingMiddleware(next http.Handler) http.Handler {
} }
slog.Default().LogAttrs(r.Context(), level, "", slog.Default().LogAttrs(r.Context(), level, "",
slog.String("type", "http"), slog.String("type", "http"),
slog.String("class", "api"), slog.String("package", "api"),
slog.String("file", "server.go"),
slog.String("method", "loggingMiddleware"), slog.String("method", "loggingMiddleware"),
slog.String("http_method", r.Method), slog.String("http_method", r.Method),
slog.String("path", r.URL.Path), slog.String("path", r.URL.Path),
@@ -256,7 +257,7 @@ func (s *Server) removeUserClient(userID int64) {
if ok { if ok {
if err := client.Close(); err != nil { 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 == "" { if s.ClientConfig.TokenStorePath == "" {
@@ -264,7 +265,7 @@ func (s *Server) removeUserClient(userID int64) {
} }
tokenStoreDir := filepath.Join(s.ClientConfig.TokenStorePath, strconv.FormatInt(userID, 10)) tokenStoreDir := filepath.Join(s.ClientConfig.TokenStorePath, strconv.FormatInt(userID, 10))
if err := os.RemoveAll(tokenStoreDir); err != nil { 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() s.mu.Unlock()
}() }()
if err := fn(context.Background()); err != nil { 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 return true
@@ -331,7 +332,7 @@ func writeJSON(w http.ResponseWriter, status int, v any) {
w.Header().Set("Content-Type", "application/json") w.Header().Set("Content-Type", "application/json")
w.WriteHeader(status) w.WriteHeader(status)
if err := json.NewEncoder(w).Encode(v); err != nil { 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)
} }
} }

View File

@@ -64,7 +64,7 @@ func (s *Server) handleSessionLogin(w http.ResponseWriter, r *http.Request) {
func (s *Server) handleSessionCallback(w http.ResponseWriter, r *http.Request) { func (s *Server) handleSessionCallback(w http.ResponseWriter, r *http.Request) {
txnCookie, err := r.Cookie(auth.TxnCookieName) txnCookie, err := r.Cookie(auth.TxnCookieName)
if err != nil { 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) http.Redirect(w, r, s.SessionConfig.FrontendURL+"/?auth_error=failed", http.StatusFound)
return return
} }
@@ -72,14 +72,14 @@ func (s *Server) handleSessionCallback(w http.ResponseWriter, r *http.Request) {
txn, err := auth.ParseTxnCookie(txnCookie, s.SessionConfig.Secret) txn, err := auth.ParseTxnCookie(txnCookie, s.SessionConfig.Secret)
if err != nil { 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) http.Redirect(w, r, s.SessionConfig.FrontendURL+"/?auth_error=failed", http.StatusFound)
return return
} }
result, err := s.Auth.HandleCallback(r.Context(), txn, r.URL.Query()) result, err := s.Auth.HandleCallback(r.Context(), txn, r.URL.Query())
if err != nil { 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) http.Redirect(w, r, s.SessionConfig.FrontendURL+"/?auth_error=failed", http.StatusFound)
return return
} }

View File

@@ -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 // on, and os.Rename refuses to replace a non-empty directory. The
// just-validated setup session must win, so clear the target first. // just-validated setup session must win, so clear the target first.
if err := os.RemoveAll(newDir); err != nil { 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) { 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)
} }
} }

View File

@@ -227,7 +227,9 @@ func (c *subprocessClient) execute(ctx context.Context, cmd string, params any)
defer func() { defer func() {
attrs := []slog.Attr{ attrs := []slog.Attr{
slog.String("type", "wrapper"), 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("method", "execute"),
slog.String("cmd", cmd), slog.String("cmd", cmd),
slog.Any("params", params), slog.Any("params", params),
@@ -384,17 +386,18 @@ func forwardWrapperStderr(r io.Reader) {
line := scanner.Text() line := scanner.Text()
var entry map[string]any var entry map[string]any
if err := json.Unmarshal([]byte(line), &entry); err != nil || entry["msg"] == nil { 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 continue
} }
msg, _ := entry["msg"].(string) msg, _ := entry["msg"].(string)
levelName, _ := entry["level"].(string) levelName, _ := entry["level"].(string)
delete(entry, "msg") delete(entry, "msg")
delete(entry, "level") 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). // (wrapper.py's _log stamps the emitting function).
attrs := make([]slog.Attr, 0, len(entry)+2) 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 { for k, v := range entry {
attrs = append(attrs, slog.Any(k, v)) attrs = append(attrs, slog.Any(k, v))
} }

View File

@@ -448,8 +448,8 @@ func TestSubprocessClient_RoundTrip_LogsCallWithResultPreview(t *testing.T) {
if err := json.Unmarshal(buf.Bytes(), &entry); err != nil { if err := json.Unmarshal(buf.Bytes(), &entry); err != nil {
t.Fatalf("log output is not valid JSON: %v (%q)", err, buf.String()) t.Fatalf("log output is not valid JSON: %v (%q)", err, buf.String())
} }
if entry["type"] != "wrapper" || entry["class"] != "garmin.subprocessClient" || entry["method"] != "execute" { 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 class=garmin.subprocessClient method=execute", entry) t.Errorf("schema fields = %v, want type=wrapper package=garmin file=client.go class=subprocessClient method=execute", entry)
} }
if _, hasMsg := entry["msg"]; hasMsg { if _, hasMsg := entry["msg"]; hasMsg {
t.Errorf("expected no msg on the wrapper-call record, got %v", entry["msg"]) 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" { if first["level"] != "WARN" || first["msg"] != "startup tokenstore login failed" {
t.Errorf("first = %v, want the wrapper's level and msg preserved", first) t.Errorf("first = %v, want the wrapper's level and msg preserved", first)
} }
if first["error"] != "boom" || first["type"] != "wrapper" || first["class"] != "wrapper" { if first["error"] != "boom" || first["type"] != "wrapper" || first["file"] != "wrapper.py" {
t.Errorf("first = %v, want error attr preserved and type=wrapper class=wrapper", first) t.Errorf("first = %v, want error attr preserved and type=wrapper file=wrapper.py", first)
} }
var second map[string]any var second map[string]any

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 // after being linked to this activity) will never succeed on
// retry -- mark it so ActivitiesMissingWorkout stops // retry -- mark it so ActivitiesMissingWorkout stops
// surfacing it, instead of retrying forever. // 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 { 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) return fmt.Errorf("mark activity %d workout not found: %w", a.GarminActivityID, serr)
} }
} else { } 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)) s.setProgress(PhaseWorkouts, i+1, len(pending))

View File

@@ -31,7 +31,7 @@ def _log(level, msg, **attrs):
never print free text to stderr or stdout from this process (stdout is never print free text to stderr or stdout from this process (stdout is
reserved for the request/response protocol). The emitting function is reserved for the request/response protocol). The emitting function is
stamped as "method" automatically; the Go side adds the rest of the 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 = {"level": level, "msg": msg, "method": sys._getframe(1).f_code.co_name}
entry.update(attrs) entry.update(attrs)
print(json.dumps(entry), file=sys.stderr, flush=True) print(json.dumps(entry), file=sys.stderr, flush=True)

View File

@@ -1,15 +1,18 @@
// Package applog provides geniusrun's structured JSON logging: a // Package applog provides geniusrun's structured JSON logging: a
// log/slog-based logger writing to stdout, plus the App helper that tags // log/slog-based logger writing to stdout, plus the App helper that tags
// records with the mandatory schema fields every geniusrun log line // records with the schema fields every geniusrun log line carries --
// carries -- "type" ("app" | "http" | "wrapper"), "class" (Go type with // "type" ("app" | "http" | "wrapper"), "package" (Go package; absent on
// its package, or the package/module name for free functions), and // Python-emitted lines), "file" (Go/Python source file basename), "class"
// "method" (the Go or Python function emitting the record). "msg" is // (Go receiver type or Python class, omitted when there is none), and
// optional: NewLogger's handler drops it when empty. // "method" (the emitting Go/Python function). "msg" is optional:
// NewLogger's handler drops it when empty.
package applog package applog
import ( import (
"io" "io"
"log/slog" "log/slog"
"path/filepath"
"runtime"
"strings" "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 // App returns the default logger tagged with the schema fields for an
// for an ordinary application record: type=app, plus the emitting class // ordinary application record (type=app), deriving the emitting location
// and method. The http and wrapper emitters (internal/api's logging // from the caller via the runtime: package, file, class (the receiver
// middleware, internal/garmin's execute/forwardWrapperStderr) tag their // type, omitted for free functions), method. Derivation instead of
// own type instead. // hand-typed strings means the labels can never drift from the code. The
func App(class, method string) *slog.Logger { // http and wrapper emitters (internal/api's logging middleware,
return slog.Default().With("type", "app", "class", class, "method", method) // 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 { func parseLevel(level string) slog.Level {

View File

@@ -60,13 +60,19 @@ func TestApp_TagsMandatoryFields(t *testing.T) {
slog.SetDefault(NewLogger("info", &buf)) slog.SetDefault(NewLogger("info", &buf))
defer slog.SetDefault(prev) defer slog.SetDefault(prev)
App("api.Server", "handleThing").Info("did it", "extra", 1) App().Info("did it", "extra", 1)
var decoded map[string]any var decoded map[string]any
if err := json.Unmarshal(buf.Bytes(), &decoded); err != nil { if err := json.Unmarshal(buf.Bytes(), &decoded); err != nil {
t.Fatalf("output not JSON: %v", err) t.Fatalf("output not JSON: %v", err)
} }
if decoded["type"] != "app" || decoded["class"] != "api.Server" || decoded["method"] != "handleThing" { if decoded["type"] != "app" || decoded["package"] != "log" || decoded["file"] != "log_test.go" {
t.Errorf("mandatory fields = %+v, want type=app class=api.Server method=handleThing", decoded) 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"])
} }
} }