chore(logging): add service logging package — handler chain and access-log sampler (S03 Step 2)

What

Step 2 of the S03 logging foundation: the internal/logging package — the service-owned slog.Handler chain that wraps LabKit v2's base handler.

  • contextFieldHandler attaches the context-derived baseline fields (correlation_id via correlation.ExtractFromContext, trace_id/span_id via oteltrace.SpanFromContext) to every record when present, de-duplicating any key the record already carries (LabKit's access logger stamps correlation_id itself).
  • accessLogSampler applies the access-log volume rules: always forward status >= 400 and duration_s >= slow_threshold; drop fast 2xx/3xx with probability 1 - success_fraction; drop everything when disabled; pass non-"access" records through untouched.
  • NewLogger(base, cfg) wires the chain (sampler → context-field → base) against a local SamplerConfig — no internal/config import, no HTTP wiring. Those land in Step 3.

Plan: docs/plans/2026-06-02-s03-logging.md, Step 2. Spec: docs/specs/S03-observability.md.

This is a chore (no operator-visible surface on its own); the wiring that makes the running service use this chain is the feat in Step 3.

Spec coverage

Step 2 owns AC 2, 3, 4, 5, 6. AC 1/7/8 are owned by Step 1 / Step 3 per the plan's AC-coverage map and are listed here as out-of-scope rows.

Acceptance criteria

# Criterion Tests
AC-1 Base handler JSON on stderr by default Out of scope (Step 3 wiring). Base handler is LabKit-owned; tests here use a buffer-backed JSON base.
AC-2 Context-field handler attaches correlation_id/trace_id/span_id; no-op when absent; no double-stamp TestHandler_CorrelationPresent, TestHandler_TraceSpanPresent, TestHandler_NoneWhenAbsent, TestHandler_NoDoubleStamp, TestHandler_NoBleed
AC-3 Sampler always logs status >= 400 and duration_s >= slow_threshold regardless of fraction TestSampler_ErrorAlwaysLogged, TestSampler_SlowAlwaysLogged
AC-4 success_fraction = 0.0 drops fast 2xx/3xx, keeps errors and slow responses TestSampler_FastSuccessDropped (drop at 0.0); error/slow preservation at 0.0 in TestSampler_ErrorAlwaysLogged, TestSampler_SlowAlwaysLogged (both run at fraction 0.0)
AC-5 access_log.disabled = true emits nothing for 4xx/5xx/fast-2xx/slow-2xx TestSampler_Disabled (table over all four)
AC-6 Wide-event record carries outcome + duration_s; correlation_id/trace_id/span_id by chain TestWideEvent_BaselineFields
AC-7 LogConfig load/validate; omitted block defaults; invalid slow_threshold startup error Out of scope (Step 1 load/defaults; Step 3 applied-before-serving).
AC-8 success_fraction bounds + explicit-0.0 vs unset; level/format in: rejection Out of scope (Step 1, proto + protovalidate + conversion).

Supporting coverage:

  • Sampler no-op for non-"access" records: TestSampler_NonAccessPasses.
  • Fast success logged at fraction 1.0 regardless of the rand draw: TestSampler_FractionOneLogs.
  • Record-clone overflow contract under concurrent fan-out: TestContextHandler_OverflowFanout (regression guard for the lazy Record.Clone() below — fails under go test -race without it).

Error cases

# Condition Tests
E-1 Log pipeline saturated -> success_fraction < 1.0 caps volume TestSampler_FastSuccessDropped exercises the drop path at fraction 0.0.
E-2 access_log.disabled = true -> no records, rules bypassed, errors not preserved TestSampler_Disabled (asserts 4xx/5xx also dropped).
E-3 log.level / log.format omitted or "" Out of scope (Step 1 config conversion).
E-4 log.level / log.format outside in: set Out of scope (Step 1 protovalidate).
E-5 Invalid slow_threshold duration string Out of scope (Step 1 config conversion).

Security considerations

# Concern Tests
S-1 No secrets in logs Wide-event emitters enforce per-event schema; no secret-bearing field exercised. Per-event emitters owned by format specs (out of scope for S03).
S-2 X-Request-ID echo / sanitization LabKit's CorrelationIDMiddleware-owned (S01). Not tested in this MR.

Review fixes folded in

The branch-review pass surfaced three items, all addressed in the final commit:

  • Clone before mutatecontextFieldHandler.Handle takes a lazy record.Clone() before AddAttrs (slog's middleware contract: record copies share an overflow backing array). Lazy so the no-enrichment path stays allocation-free.
  • Kind-guarded sampler readsshouldLog guards its status/duration_s reads with Value.Kind() checks; slog.Value.Int64/Float64 panic on a kind mismatch and the sampler matches on key alone.
  • Overflow-path testTestContextHandler_OverflowFanout exercises the

    5-attr overflow array under a concurrent fan-out; it fails under -race without the clone.

go mod tidy also promotes go.opentelemetry.io/otel/trace from // indirect to a direct require (it is now imported directly by handler.go), keeping the CI go-mod-tidy check green.

Diff size

The diff is test-dominated — +499 test (handler_test.go) vs +213 implementation (handler.go), with a one-line go.mod change. The package is small and the behavior (sampling rules across status/duration/disabled/ non-access combinations, context-field attach/no-op/no-double-stamp, and the concurrency/overflow contracts) is exercised exhaustively, so the test file legitimately outweighs the implementation.

Edited by Suleimi Ahmed

Merge request reports

Loading
Loading