diff --git a/CHANGELOG.md b/CHANGELOG.md index fb90e66..197797d 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,12 @@ Gatekeeper is a standalone credential-injecting TLS-intercepting proxy. It trans Gatekeeper is pre-1.0. The configuration schema and credential source interface may change between minor versions. +## v0.17.2 — 2026-07-15 + +### Fixed + +- **Gatekeeper's own OTel diagnostics no longer feed back into the failing OTel log-export pipeline** — `configureLogging` fans every slog record out to `otelslog.NewHandler("gatekeeper")` unconditionally: the bridge's `Enabled` defers entirely to the OTel logger, not the console handler's configured level, so nothing before v0.17.0's DEBUG demotion (and nothing since) kept the bridge from seeing a record just because it was noisy. That meant `logOTelError` ([#47](https://github.com/majorcontext/gatekeeper/pull/47))'s own DEBUG record on a failed export was itself enqueued right back into the OTel log-export pipeline that had just failed: failed export → DEBUG diagnostic → diagnostic fanned out to the bridge → re-enqueued for the next export → that export fails too, now carrying the diagnostic → another diagnostic logged → re-enqueued again, and so on for as long as the collector stays unreachable. Bounded — one record per export attempt, and the batch queue drops on overflow rather than growing without limit — but a genuine feedback loop, not merely repeated independent failures. `gatekeeper.OTelDiagnosticKey` is a new exported marker attribute; `logOTelError` tags its DEBUG record with it, and `configureLogging`'s otelslog bridge handler is now wrapped in a filter that drops any record carrying the marker before forwarding — the console/file handler is unaffected and still logs every record, marked or not, at its configured level. Diagnostics about the OTel pipeline itself are now visible locally but never re-enter the pipeline they're reporting on ([#48](https://github.com/majorcontext/gatekeeper/issues/48)) + ## v0.17.1 — 2026-07-15 ### Fixed diff --git a/cmd/gatekeeper/main.go b/cmd/gatekeeper/main.go index 8167281..38a3725 100644 --- a/cmd/gatekeeper/main.go +++ b/cmd/gatekeeper/main.go @@ -46,8 +46,16 @@ func otelSDKDisabled(getenv func(string) string) bool { // with no backoff between attempts) produced an INFO log line that drowned // the canonical request lines whenever no collector was present. Logging // export errors at DEBUG here keeps them observable without the noise. +// +// The record is tagged with gatekeeper.OTelDiagnosticKey so +// configureLogging's otelslog bridge filter excludes it from the OTel log +// export pipeline. Without that exclusion, a failed OTel log export +// produces this very DEBUG record, which — like any other record — gets +// fanned out to the same OTel log pipeline that just failed; it's queued, +// fails on the next export attempt, produces another diagnostic, and so on +// indefinitely while the collector stays unreachable. func logOTelError(err error) { - slog.Default().Debug("otel error", "error", err) + slog.Default().Debug("otel error", "error", err, gatekeeper.OTelDiagnosticKey, true) } func initOTel(ctx context.Context, getenv func(string) string) (shutdown func(context.Context) error, err error) { diff --git a/cmd/gatekeeper/main_test.go b/cmd/gatekeeper/main_test.go index abd934b..4a949bc 100644 --- a/cmd/gatekeeper/main_test.go +++ b/cmd/gatekeeper/main_test.go @@ -2,9 +2,12 @@ package main import ( "bytes" + "context" "errors" "log/slog" "testing" + + "github.com/majorcontext/gatekeeper" ) // TestOtelSDKDisabled pins the OTEL_SDK_DISABLED semantics: per the @@ -90,3 +93,53 @@ func TestLogOTelError_DemotesToDebug(t *testing.T) { } }) } + +// recordingHandler is a minimal slog.Handler that captures every record +// passed to it, for inspecting the attributes a call site attached. +type recordingHandler struct { + records []slog.Record +} + +func (h *recordingHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (h *recordingHandler) Handle(_ context.Context, r slog.Record) error { + h.records = append(h.records, r) + return nil +} + +func (h *recordingHandler) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h *recordingHandler) WithGroup(string) slog.Handler { return h } + +// TestLogOTelError_MarksAsOTelDiagnostic encodes the fix for #48: gatekeeper.go's +// configureLogging fans every slog record out to the otelslog bridge +// unconditionally, so logOTelError's own DEBUG record on a failed OTel +// export was itself re-enqueued into the same failing OTel log-export +// pipeline — failed export -> DEBUG diagnostic -> re-enqueued -> next +// export fails carrying it -> another diagnostic, indefinitely while the +// collector is unreachable. logOTelError must mark its record with +// gatekeeper.OTelDiagnosticKey so configureLogging's bridge filter can keep +// it out of that pipeline. +func TestLogOTelError_MarksAsOTelDiagnostic(t *testing.T) { + var handler recordingHandler + prev := slog.Default() + t.Cleanup(func() { slog.SetDefault(prev) }) + slog.SetDefault(slog.New(&handler)) + + logOTelError(errors.New(`Post "https://localhost:4318/v1/logs": dial tcp [::1]:4318: connect: connection refused`)) + + if len(handler.records) != 1 { + t.Fatalf("got %d records, want 1", len(handler.records)) + } + + marked := false + handler.records[0].Attrs(func(a slog.Attr) bool { + if a.Key == gatekeeper.OTelDiagnosticKey && a.Value.Kind() == slog.KindBool && a.Value.Bool() { + marked = true + return false + } + return true + }) + if !marked { + t.Errorf("logOTelError record missing %s=true attribute, so configureLogging's bridge filter can't exclude it from the OTel log-export pipeline", gatekeeper.OTelDiagnosticKey) + } +} diff --git a/gatekeeper.go b/gatekeeper.go index 8384404..3af549b 100644 --- a/gatekeeper.go +++ b/gatekeeper.go @@ -79,11 +79,58 @@ func configureLogging(cfg LogConfig) (func(), error) { } else { handler = slog.NewTextHandler(w, opts) } - handler = newMultiHandler(handler, otelslog.NewHandler("gatekeeper")) + handler = newMultiHandler(handler, newOTelDiagnosticFilter(otelslog.NewHandler("gatekeeper"))) slog.SetDefault(slog.New(handler)) return cleanup, nil } +// OTelDiagnosticKey marks a log record as gatekeeper's own diagnostic about +// the OTel pipeline itself — currently, the OTel SDK/export error records +// cmd/gatekeeper's logOTelError logs at DEBUG. configureLogging's otelslog +// bridge handler excludes any record carrying this attribute (see +// newOTelDiagnosticFilter): without the exclusion, a failed OTel log export +// produces a DEBUG diagnostic that is itself fanned out to the same OTel +// log-export pipeline that just failed, so it gets queued, fails on the +// next export attempt, produces another diagnostic, and so on indefinitely +// while a collector is unreachable. The console/file handler still receives +// every record regardless of this marker. +const OTelDiagnosticKey = "otel_diagnostic" + +// otelDiagnosticFilter wraps a slog.Handler — the otelslog bridge — and +// drops any record carrying OTelDiagnosticKey before it reaches the wrapped +// handler, keeping gatekeeper's own OTel diagnostics out of the OTel log +// export pipeline. Records without the marker pass through unchanged. +type otelDiagnosticFilter struct { + slog.Handler +} + +func newOTelDiagnosticFilter(h slog.Handler) slog.Handler { + return &otelDiagnosticFilter{Handler: h} +} + +func (f *otelDiagnosticFilter) Handle(ctx context.Context, record slog.Record) error { + marked := false + record.Attrs(func(a slog.Attr) bool { + if a.Key == OTelDiagnosticKey && a.Value.Kind() == slog.KindBool && a.Value.Bool() { + marked = true + return false + } + return true + }) + if marked { + return nil + } + return f.Handler.Handle(ctx, record) +} + +func (f *otelDiagnosticFilter) WithAttrs(attrs []slog.Attr) slog.Handler { + return &otelDiagnosticFilter{Handler: f.Handler.WithAttrs(attrs)} +} + +func (f *otelDiagnosticFilter) WithGroup(name string) slog.Handler { + return &otelDiagnosticFilter{Handler: f.Handler.WithGroup(name)} +} + // multiHandler fans out log records to multiple slog handlers. type multiHandler struct { handlers []slog.Handler diff --git a/gatekeeper_test.go b/gatekeeper_test.go index b05a3bd..dc149e8 100644 --- a/gatekeeper_test.go +++ b/gatekeeper_test.go @@ -2935,6 +2935,55 @@ func TestMultiHandler_WithGroup(t *testing.T) { } } +// fakeSlogHandler is a minimal slog.Handler that records every record it +// receives, for observing what actually reaches a handler in tests. +type fakeSlogHandler struct { + records []slog.Record +} + +func (f *fakeSlogHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (f *fakeSlogHandler) Handle(_ context.Context, r slog.Record) error { + f.records = append(f.records, r) + return nil +} + +func (f *fakeSlogHandler) WithAttrs([]slog.Attr) slog.Handler { return f } +func (f *fakeSlogHandler) WithGroup(string) slog.Handler { return f } + +// TestOTelDiagnosticFilter_KeepsBridgeOutOfLoop encodes the fix for #48: +// gatekeeper's own OTel diagnostics (logOTelError's DEBUG record on a +// failed export) must never reach the otelslog bridge handler, or the +// diagnostic itself gets enqueued into the same failing OTel log-export +// pipeline — producing another diagnostic on the next failed attempt, and +// so on indefinitely while a collector is unreachable. The console handler +// must still see every record, marked or not. +func TestOTelDiagnosticFilter_KeepsBridgeOutOfLoop(t *testing.T) { + var console, bridge fakeSlogHandler + handler := newMultiHandler(&console, newOTelDiagnosticFilter(&bridge)) + logger := slog.New(handler) + + logger.Debug("otel error", "error", "dial tcp [::1]:4318: connect: connection refused", OTelDiagnosticKey, true) + logger.Info("normal request", "host", "example.com") + // A record carrying the key set to false is not a diagnostic and must + // still reach the bridge — the filter keys off the value, not mere + // presence of the attribute. + logger.Info("opted-in request", "host", "example.com", OTelDiagnosticKey, false) + + if got := len(console.records); got != 3 { + t.Fatalf("console handler received %d records, want 3 (all records)", got) + } + if got := len(bridge.records); got != 2 { + t.Fatalf("bridge handler received %d records, want 2 (only the true-marked diagnostic is filtered out)", got) + } + if got := bridge.records[0].Message; got != "normal request" { + t.Errorf("bridge handler's first surviving record = %q, want %q", got, "normal request") + } + if got := bridge.records[1].Message; got != "opted-in request" { + t.Errorf("bridge handler's second surviving record = %q, want %q (key=false must pass through)", got, "opted-in request") + } +} + func TestHTTPSTokenExchangeOutrankedByStatic(t *testing.T) { // End-to-end wiring check for outranked resolvers: a token-exchange // credential under a wildcard host is outranked by a static credential