diff --git a/logctx/handler.go b/logctx/handler.go new file mode 100644 index 0000000..2ad15d6 --- /dev/null +++ b/logctx/handler.go @@ -0,0 +1,108 @@ +package logctx + +import ( + "context" + "log/slog" + "os" +) + +// Field-name constants — never inline these strings in tests or callers. +// The schema is part of our log contract and grep-ability across services +// requires that every Go file uses the same identifiers. +const ( + FieldService = "service" + FieldCommitID = "commit_id" + FieldTraceID = "trace_id" + FieldTID = "tid" + FieldTeamID = "team_id" +) + +// commitID returns the build's git SHA. Track 1 of the observability rollout +// adds a real `instant.dev/common/buildinfo` package whose GitSHA var is set +// via `-ldflags -X`. Until that package merges, we fall back to the +// COMMIT_ID env var (set by the Dockerfile / k8s deployment) so this package +// does not block on track 1. The sentinel "dev" matches the buildinfo +// package's planned default so log readers see a single consistent value +// across both implementations. +func commitID() string { + if v := os.Getenv("COMMIT_ID"); v != "" { + return v + } + return "dev" +} + +// Handler wraps an underlying slog.Handler and injects the five mandatory +// observability fields onto every record: +// +// service — constant supplied at construction time ("api" / "worker" / "provisioner") +// commit_id — git SHA of the running binary (compile-time or env) +// trace_id — pulled from ctx via TraceIDFromContext +// tid — pulled from ctx via TIDFromContext +// team_id — pulled from ctx via TeamIDFromContext +// +// Missing ctx fields are emitted as empty strings — never dropped — so log +// schema is stable across every line. A nil ctx is treated identically to +// context.Background; the handler MUST NOT panic on a nil ctx. +type Handler struct { + base slog.Handler + service string + commitID string +} + +// NewHandler wraps base so that every record emitted through the wrapper +// carries the five mandatory observability fields. The returned handler is +// safe for concurrent use to the same degree base is. +// +// service is the binary name ("api", "worker", "provisioner") and is emitted +// on every record. base is any slog.Handler — typically slog.NewJSONHandler +// over stdout with AddSource=true. +func NewHandler(service string, base slog.Handler) slog.Handler { + return &Handler{ + base: base, + service: service, + commitID: commitID(), + } +} + +// Enabled forwards to the wrapped handler unchanged. Wrapping must not change +// which records get emitted — that decision belongs to the base handler's +// configured level. +func (h *Handler) Enabled(ctx context.Context, level slog.Level) bool { + return h.base.Enabled(ctx, level) +} + +// Handle annotates the record with the five mandatory fields and forwards. +// A nil ctx is tolerated — getters return empty strings rather than panic. +func (h *Handler) Handle(ctx context.Context, r slog.Record) error { + // AddAttrs mutates the record in place; the standard library reserves + // the right to do this exactly once per Record value, which is fine + // here because every record reaches the wrapper at most once. + r.AddAttrs( + slog.String(FieldService, h.service), + slog.String(FieldCommitID, h.commitID), + slog.String(FieldTraceID, TraceIDFromContext(ctx)), + slog.String(FieldTID, TIDFromContext(ctx)), + slog.String(FieldTeamID, TeamIDFromContext(ctx)), + ) + return h.base.Handle(ctx, r) +} + +// WithAttrs returns a new wrapper around base.WithAttrs(attrs). The injected +// service / commit_id stay attached to the new wrapper so child loggers +// (built via slog.Logger.With) still carry the mandatory fields. +func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { + return &Handler{ + base: h.base.WithAttrs(attrs), + service: h.service, + commitID: h.commitID, + } +} + +// WithGroup returns a new wrapper around base.WithGroup(name). +func (h *Handler) WithGroup(name string) slog.Handler { + return &Handler{ + base: h.base.WithGroup(name), + service: h.service, + commitID: h.commitID, + } +} diff --git a/logctx/handler_test.go b/logctx/handler_test.go new file mode 100644 index 0000000..4a3b744 --- /dev/null +++ b/logctx/handler_test.go @@ -0,0 +1,161 @@ +package logctx + +import ( + "bytes" + "context" + "encoding/json" + "log/slog" + "strings" + "testing" + "time" +) + +// newTestHandler builds a logctx Handler over a fresh JSON handler writing to +// the returned buffer. Tests inspect the buffer after each emit. Level is set +// to Debug so nothing is filtered unless the test explicitly disables it. +func newTestHandler(t *testing.T, service string) (*bytes.Buffer, slog.Handler) { + t.Helper() + buf := &bytes.Buffer{} + base := slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}) + return buf, NewHandler(service, base) +} + +// decode reads the buffer as a single JSON-line slog record and returns the +// parsed map. Fails the test on bad JSON or empty input. +func decode(t *testing.T, buf *bytes.Buffer) map[string]any { + t.Helper() + raw := strings.TrimSpace(buf.String()) + if raw == "" { + t.Fatal("no log line emitted") + } + out := map[string]any{} + if err := json.Unmarshal([]byte(raw), &out); err != nil { + t.Fatalf("malformed log JSON %q: %v", raw, err) + } + return out +} + +// newRecord constructs a slog.Record at INFO with a fixed message. Tests +// never need the source frame in this package. +func newRecord(msg string) slog.Record { + return slog.NewRecord(time.Now(), slog.LevelInfo, msg, 0) +} + +// Test 1: with a bare context (no setters called) the handler emits service, +// commit_id, and empty values for the three ctx-sourced fields. +func TestHandler_NoCtx(t *testing.T) { + buf, h := newTestHandler(t, "api") + if err := h.Handle(context.Background(), newRecord("hello")); err != nil { + t.Fatalf("Handle: %v", err) + } + + rec := decode(t, buf) + if rec[FieldService] != "api" { + t.Errorf("service = %v, want api", rec[FieldService]) + } + // commit_id default is "dev" (see commitID()). + if rec[FieldCommitID] != "dev" { + t.Errorf("commit_id = %v, want dev", rec[FieldCommitID]) + } + for _, f := range []string{FieldTraceID, FieldTID, FieldTeamID} { + if got, ok := rec[f]; !ok || got != "" { + t.Errorf("%s = %v present=%v, want empty string present=true", f, got, ok) + } + } +} + +// Test 2: WithTraceID propagates through Handle. +func TestHandler_WithTraceID(t *testing.T) { + buf, h := newTestHandler(t, "api") + ctx := WithTraceID(context.Background(), "abc") + if err := h.Handle(ctx, newRecord("hello")); err != nil { + t.Fatalf("Handle: %v", err) + } + rec := decode(t, buf) + if rec[FieldTraceID] != "abc" { + t.Errorf("trace_id = %v, want abc", rec[FieldTraceID]) + } + // Sibling ctx fields untouched stay empty. + if rec[FieldTID] != "" || rec[FieldTeamID] != "" { + t.Errorf("sibling fields not empty: tid=%v team_id=%v", rec[FieldTID], rec[FieldTeamID]) + } +} + +// Test 3: all three setters compose; all three values reach the record. +func TestHandler_WithAll(t *testing.T) { + buf, h := newTestHandler(t, "worker") + ctx := context.Background() + ctx = WithTraceID(ctx, "trace-xyz") + ctx = WithTID(ctx, "tid-77") + ctx = WithTeamID(ctx, "team-42") + if err := h.Handle(ctx, newRecord("hello")); err != nil { + t.Fatalf("Handle: %v", err) + } + rec := decode(t, buf) + if rec[FieldService] != "worker" { + t.Errorf("service = %v, want worker", rec[FieldService]) + } + if rec[FieldTraceID] != "trace-xyz" { + t.Errorf("trace_id = %v, want trace-xyz", rec[FieldTraceID]) + } + if rec[FieldTID] != "tid-77" { + t.Errorf("tid = %v, want tid-77", rec[FieldTID]) + } + if rec[FieldTeamID] != "team-42" { + t.Errorf("team_id = %v, want team-42", rec[FieldTeamID]) + } +} + +// Test 4: nil ctx must NOT panic. The defensive nil checks in keys.go and +// handler.go are load-bearing — slog will hand us a nil ctx from +// (*Logger).Log when callers pass nil. +func TestHandler_NilCtx(t *testing.T) { + buf, h := newTestHandler(t, "api") + defer func() { + if r := recover(); r != nil { + t.Fatalf("Handle(nil ctx) panicked: %v", r) + } + }() + // Pass an explicitly nil context. The handler must treat it as empty. + if err := h.Handle(nil, newRecord("hello")); err != nil { + t.Fatalf("Handle: %v", err) + } + rec := decode(t, buf) + if rec[FieldTraceID] != "" || rec[FieldTID] != "" || rec[FieldTeamID] != "" { + t.Errorf("nil ctx produced non-empty fields: %v", rec) + } +} + +// disabledHandler is a stub base handler that always reports Enabled=false. +// Tests use it to verify the wrapper does not override the base's filtering. +type disabledHandler struct{ slog.Handler } + +func (disabledHandler) Enabled(context.Context, slog.Level) bool { return false } + +// Test 5: when the base handler says Enabled=false, the wrapper says false +// too. The wrapper must never widen the set of emitted records. +func TestHandler_EnabledPassthrough(t *testing.T) { + base := disabledHandler{Handler: slog.NewJSONHandler(&bytes.Buffer{}, nil)} + h := NewHandler("api", base) + if h.Enabled(context.Background(), slog.LevelError) { + t.Error("wrapper widened Enabled — base said false, wrapper said true") + } +} + +// Bonus: WithAttrs / WithGroup preserve the injected service+commit_id on +// the returned child handler. Belt-and-braces guard against regressions +// where someone refactors the struct and forgets to copy the fields. +func TestHandler_WithAttrsPreservesService(t *testing.T) { + buf, h := newTestHandler(t, "provisioner") + child := h.WithAttrs([]slog.Attr{slog.String("extra", "v")}) + if err := child.Handle(context.Background(), newRecord("hi")); err != nil { + t.Fatalf("Handle: %v", err) + } + rec := decode(t, buf) + if rec[FieldService] != "provisioner" { + t.Errorf("WithAttrs dropped service: %v", rec[FieldService]) + } + if rec["extra"] != "v" { + t.Errorf("WithAttrs dropped extra attr") + } +} diff --git a/logctx/keys.go b/logctx/keys.go new file mode 100644 index 0000000..550d33c --- /dev/null +++ b/logctx/keys.go @@ -0,0 +1,87 @@ +// Package logctx provides a slog.Handler wrapper that auto-injects mandatory +// observability fields (service, commit_id, trace_id, tid, team_id) onto every +// log record by reading them from a context.Context. +// +// Setters and getters on this file are the only sanctioned way to put those +// fields onto a context; the handler in handler.go is the only sanctioned way +// to read them off again when emitting a record. +package logctx + +import "context" + +// Unexported context keys — these prevent collisions with other packages that +// might want to store strings on a context under the same name. Each type is +// a distinct empty struct so equality is identity, not value-based. +type ( + traceIDCtxKey struct{} + tidCtxKey struct{} + teamIDCtxKey struct{} +) + +// WithTraceID returns a copy of ctx carrying the supplied trace_id. The trace +// id is the W3C TraceContext trace ID when an OpenTelemetry span is in flight, +// falling back to the upstream request_id for non-span paths. Passing an empty +// string is permitted and behaves like no annotation — the handler will emit +// an empty trace_id field. +func WithTraceID(ctx context.Context, v string) context.Context { + if ctx == nil { + ctx = context.Background() + } + return context.WithValue(ctx, traceIDCtxKey{}, v) +} + +// TraceIDFromContext extracts the trace_id previously stored by WithTraceID. +// Returns an empty string when ctx is nil or carries no trace id — callers +// should NEVER panic on a missing field. +func TraceIDFromContext(ctx context.Context) string { + if ctx == nil { + return "" + } + if v, ok := ctx.Value(traceIDCtxKey{}).(string); ok { + return v + } + return "" +} + +// WithTID returns a copy of ctx carrying the supplied tid (River job task ID +// for worker jobs; empty for non-job code paths). +func WithTID(ctx context.Context, v string) context.Context { + if ctx == nil { + ctx = context.Background() + } + return context.WithValue(ctx, tidCtxKey{}, v) +} + +// TIDFromContext extracts the tid previously stored by WithTID. Returns an +// empty string when absent or when ctx is nil. +func TIDFromContext(ctx context.Context) string { + if ctx == nil { + return "" + } + if v, ok := ctx.Value(tidCtxKey{}).(string); ok { + return v + } + return "" +} + +// WithTeamID returns a copy of ctx carrying the supplied team_id (the JWT +// team_id claim, propagated from the auth middleware). +func WithTeamID(ctx context.Context, v string) context.Context { + if ctx == nil { + ctx = context.Background() + } + return context.WithValue(ctx, teamIDCtxKey{}, v) +} + +// TeamIDFromContext extracts the team_id previously stored by WithTeamID. +// Returns an empty string when absent (unauthenticated request) or when ctx +// is nil. +func TeamIDFromContext(ctx context.Context) string { + if ctx == nil { + return "" + } + if v, ok := ctx.Value(teamIDCtxKey{}).(string); ok { + return v + } + return "" +}