diff --git a/go.mod b/go.mod index 5733a9909..8ddd8cb08 100644 --- a/go.mod +++ b/go.mod @@ -29,13 +29,17 @@ require ( github.com/spf13/cobra v1.10.2 github.com/spf13/viper v1.21.0 github.com/stretchr/testify v1.11.1 + go.opentelemetry.io/contrib/bridges/otelslog v0.19.0 go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.69.0 go.opentelemetry.io/contrib/instrumentation/runtime v0.69.0 go.opentelemetry.io/otel v1.44.0 + go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.20.0 go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.44.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.44.0 + go.opentelemetry.io/otel/log v0.20.0 go.opentelemetry.io/otel/metric v1.44.0 go.opentelemetry.io/otel/sdk v1.44.0 + go.opentelemetry.io/otel/sdk/log v0.20.0 go.opentelemetry.io/otel/sdk/metric v1.44.0 go.opentelemetry.io/otel/trace v1.44.0 go.uber.org/goleak v1.3.0 diff --git a/go.sum b/go.sum index 33f37fb6a..0f7c9aa37 100644 --- a/go.sum +++ b/go.sum @@ -1596,6 +1596,8 @@ go.opencensus.io v0.24.0/go.mod h1:vNK8G9p7aAivkbmorf4v+7Hgx+Zs0yY+0fOtgBfjQKo= go.opentelemetry.io/auto/sdk v1.1.0/go.mod h1:3wSPjt5PWp2RhlCcmmOial7AvC4DQqZb7a7wCow3W8A= go.opentelemetry.io/auto/sdk v1.2.1 h1:jXsnJ4Lmnqd11kwkBV2LgLoFMZKizbCi5fNZ/ipaZ64= go.opentelemetry.io/auto/sdk v1.2.1/go.mod h1:KRTj+aOaElaLi+wW1kO/DZRXwkF4C5xPbEe3ZiIhN7Y= +go.opentelemetry.io/contrib/bridges/otelslog v0.19.0 h1:5RgvxieNq9tS3ewrV1vnODvbHPfKUIJcYtF9Cvz+6aQ= +go.opentelemetry.io/contrib/bridges/otelslog v0.19.0/go.mod h1:iTBIdNwx/xmUhfgJs6+84S4dIK059811cO1eUBjKcHY= go.opentelemetry.io/contrib/detectors/gcp v1.28.0/go.mod h1:9BIqH22qyHWAiZxQh0whuJygro59z+nbMVuc7ciiGug= go.opentelemetry.io/contrib/detectors/gcp v1.29.0/go.mod h1:GW2aWZNwR2ZxDLdv8OyC2G8zkRoQBuURgV7RPQgcPoU= go.opentelemetry.io/contrib/detectors/gcp v1.31.0/go.mod h1:tzQL6E1l+iV44YFTkcAeNQqzXUiekSYP9jjJjXwEd00= @@ -1658,6 +1660,8 @@ go.opentelemetry.io/otel v1.42.0/go.mod h1:lJNsdRMxCUIWuMlVJWzecSMuNjE7dOYyWlqOX go.opentelemetry.io/otel v1.43.0/go.mod h1:JuG+u74mvjvcm8vj8pI5XiHy1zDeoCS2LB1spIq7Ay0= go.opentelemetry.io/otel v1.44.0 h1:JjwHmHpA4iZ3wBxluu2fbbE7j4kqlE8jXyAyPXH7HqU= go.opentelemetry.io/otel v1.44.0/go.mod h1:BMgjTHL9WPRlRjL2oZCBTL4whCGtXch2H4BhOPIAyYc= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.20.0 h1:rydZ9sxbcFdm/oWrVyfLTjHIygMgv0bEeMd+3B/BvoM= +go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc v0.20.0/go.mod h1:earQ25dooT0Hhspq59DZ8YCC50jWfOlFEeWoxy/P444= go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.44.0 h1:SUplec5dp06reu1zaXmOXdvqH398taqrDXqUl99jxSc= go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc v1.44.0/go.mod h1:ho2g4N+ane+swq5I/VBkKWnRDY4kUINH3FuqyZqX/Ug= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.44.0 h1:4YsVu3B8+3qtWYYrsUYgn0OG78pN0rnNPRGX4SbokQI= @@ -1669,6 +1673,8 @@ go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.29.0/go.mod h1:BLbf7zb go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.35.0/go.mod h1:U2R3XyVPzn0WX7wOIypPuptulsMcPDPs/oiSVOMVnHY= go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.36.0/go.mod h1:dowW6UsM9MKbJq5JTz2AMVp3/5iW5I/TStsk8S+CfHw= go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.42.0/go.mod h1:so9ounLcuoRDu033MW/E0AD4hhUjVqswrMF5FoZlBcw= +go.opentelemetry.io/otel/log v0.20.0 h1:/5i0vuHxCLWUfChWG41K9wkM0jafruPw9NU1/RCJirs= +go.opentelemetry.io/otel/log v0.20.0/go.mod h1:wOcMcjsZpG8x7Bak7IhSi/lg8wscV2C1VdrKCLPlt0E= go.opentelemetry.io/otel/metric v0.20.0/go.mod h1:598I5tYlH1vzBjn+BTuhzTCSb/9debfNp6R3s7Pr1eU= go.opentelemetry.io/otel/metric v1.21.0/go.mod h1:o1p3CA8nNHW8j5yuQLdc1eeqEaPfzug24uvsyIEJRWM= go.opentelemetry.io/otel/metric v1.22.0/go.mod h1:evJGjVpZv0mQ5QBRJoBF64yMuOf4xCWdXjK8pzFvliY= @@ -1716,6 +1722,10 @@ go.opentelemetry.io/otel/sdk v1.42.0/go.mod h1:rGHCAxd9DAph0joO4W6OPwxjNTYWghRWm go.opentelemetry.io/otel/sdk v1.43.0/go.mod h1:P+IkVU3iWukmiit/Yf9AWvpyRDlUeBaRg6Y+C58QHzg= go.opentelemetry.io/otel/sdk v1.44.0 h1:nHYwb9lK+fJPU/dnT6s7W7Z8itMWyqrnVfbheVYrZ58= go.opentelemetry.io/otel/sdk v1.44.0/go.mod h1:Osuydd3Se74nqjAKxid74N5eC+jfEqfTegHRnq58oK0= +go.opentelemetry.io/otel/sdk/log v0.20.0 h1:vM3xI7TQgKPiSghe6urZtAkyFY7SodrSpC83CffDFuY= +go.opentelemetry.io/otel/sdk/log v0.20.0/go.mod h1:Knej2nmsTUzN79T2eeXdRsjjPcoxoq2pUyUHz9TFyyU= +go.opentelemetry.io/otel/sdk/log/logtest v0.20.0 h1:OqdRZ1guyzamK3M6LlRsmGqRrjkHWw6WZOKKli5ELpg= +go.opentelemetry.io/otel/sdk/log/logtest v0.20.0/go.mod h1:PuMIlm7zAt7c3z8zfOI5ox4iT1Z87We+PF6YoINux/M= go.opentelemetry.io/otel/sdk/metric v1.28.0/go.mod h1:cWPjykihLAPvXKi4iZc1dpER3Jdq2Z0YLse3moQUCpg= go.opentelemetry.io/otel/sdk/metric v1.29.0/go.mod h1:6zZLdCl2fkauYoZIOn/soQIDSWFmNSRcICarHfuhNJQ= go.opentelemetry.io/otel/sdk/metric v1.30.0/go.mod h1:waS6P3YqFNzeP01kuo/MBBYqaoBJl7efRQHOaydhy1Y= diff --git a/spinifex/otelsetup/otelsetup.go b/spinifex/otelsetup/otelsetup.go index 978db88de..1df1e097b 100644 --- a/spinifex/otelsetup/otelsetup.go +++ b/spinifex/otelsetup/otelsetup.go @@ -15,12 +15,16 @@ import ( "strings" "time" + "go.opentelemetry.io/contrib/bridges/otelslog" otelruntime "go.opentelemetry.io/contrib/instrumentation/runtime" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/exporters/otlp/otlplog/otlploggrpc" "go.opentelemetry.io/otel/exporters/otlp/otlpmetric/otlpmetricgrpc" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" + loggerglobal "go.opentelemetry.io/otel/log/global" "go.opentelemetry.io/otel/propagation" + sdklog "go.opentelemetry.io/otel/sdk/log" sdkmetric "go.opentelemetry.io/otel/sdk/metric" "go.opentelemetry.io/otel/sdk/resource" sdktrace "go.opentelemetry.io/otel/sdk/trace" @@ -72,6 +76,21 @@ func Init(ctx context.Context, serviceName string) (func(context.Context) error, ) otel.SetMeterProvider(mp) + logExp, err := otlploggrpc.New(ctx) + if err != nil { + shutdownCtx, cancel := context.WithTimeout(context.Background(), shutdownTimeout) + defer cancel() + return nil, errors.Join( + fmt.Errorf("otlp log exporter for %s: %w", serviceName, err), + tp.Shutdown(shutdownCtx), mp.Shutdown(shutdownCtx)) + } + lp := sdklog.NewLoggerProvider( + sdklog.WithResource(res), + sdklog.WithProcessor(sdklog.NewBatchProcessor(logExp)), + ) + loggerglobal.SetLoggerProvider(lp) + addFanoutHandler(otelslog.NewHandler(serviceName, otelslog.WithLoggerProvider(lp))) + if err := otelruntime.Start(); err != nil { slog.Warn("otel runtime metrics disabled", "err", err) } @@ -79,7 +98,7 @@ func Init(ctx context.Context, serviceName string) (func(context.Context) error, shutdown := func(ctx context.Context) error { ctx, cancel := context.WithTimeout(ctx, shutdownTimeout) defer cancel() - return errors.Join(tp.Shutdown(ctx), mp.Shutdown(ctx)) + return errors.Join(tp.Shutdown(ctx), mp.Shutdown(ctx), lp.Shutdown(ctx)) } return shutdown, nil } diff --git a/spinifex/otelsetup/otelsetup_test.go b/spinifex/otelsetup/otelsetup_test.go index 7477d74bc..5f44ef1af 100644 --- a/spinifex/otelsetup/otelsetup_test.go +++ b/spinifex/otelsetup/otelsetup_test.go @@ -5,12 +5,18 @@ import ( "context" "encoding/json" "log/slog" + "sync" "testing" "time" "go.opentelemetry.io/otel" + sdklog "go.opentelemetry.io/otel/sdk/log" "go.opentelemetry.io/otel/trace" "go.opentelemetry.io/otel/trace/noop" + + "go.opentelemetry.io/contrib/bridges/otelslog" + loggerglobal "go.opentelemetry.io/otel/log/global" + lognoop "go.opentelemetry.io/otel/log/noop" ) func TestInitWithoutEndpointIsNoop(t *testing.T) { @@ -161,6 +167,223 @@ func TestSlogHandlerNoSpanNoStamp(t *testing.T) { } } +// TestInitWithoutEndpointInstallsNoLoggerProvider is the prod-safety +// guarantee: with no OTLP endpoint configured, Init must not install a +// LoggerProvider (the global stays whatever was there before) and must not +// touch the process default slog handler. +func TestInitWithoutEndpointInstallsNoLoggerProvider(t *testing.T) { + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "") + t.Setenv("OTEL_EXPORTER_OTLP_TRACES_ENDPOINT", "") + t.Setenv("OTEL_EXPORTER_OTLP_METRICS_ENDPOINT", "") + + prevLP := loggerglobal.GetLoggerProvider() + defer loggerglobal.SetLoggerProvider(prevLP) + sentinelLP := lognoop.NewLoggerProvider() + loggerglobal.SetLoggerProvider(sentinelLP) + + prevHandler := slog.Default().Handler() + defer slog.SetDefault(slog.New(prevHandler)) + sentinelHandler := slog.NewJSONHandler(&bytes.Buffer{}, nil) + slog.SetDefault(slog.New(sentinelHandler)) + + shutdown, err := Init(context.Background(), "test-svc") + if err != nil { + t.Fatalf("Init: %v", err) + } + defer func() { _ = shutdown(context.Background()) }() + + if _, ok := loggerglobal.GetLoggerProvider().(lognoop.LoggerProvider); !ok { + t.Errorf("expected global LoggerProvider to remain the noop sentinel, got %T", loggerglobal.GetLoggerProvider()) + } + if got := slog.Default().Handler(); got != slog.Handler(sentinelHandler) { + t.Errorf("expected default slog handler unchanged, got %T", got) + } +} + +// TestInitWithEndpointInstallsLoggerProvider proves the same gate installs a +// real LoggerProvider and fans the default logger out once an OTLP endpoint +// is configured. +func TestInitWithEndpointInstallsLoggerProvider(t *testing.T) { + t.Setenv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://127.0.0.1:1") + prevLP := loggerglobal.GetLoggerProvider() + defer loggerglobal.SetLoggerProvider(prevLP) + prevTracer := otel.GetTracerProvider() + prevMeter := otel.GetMeterProvider() + defer otel.SetTracerProvider(prevTracer) + defer otel.SetMeterProvider(prevMeter) + prevHandler := slog.Default().Handler() + defer slog.SetDefault(slog.New(prevHandler)) + + shutdown, err := Init(context.Background(), "test-svc") + if err != nil { + t.Fatalf("Init: %v", err) + } + + if _, ok := loggerglobal.GetLoggerProvider().(*sdklog.LoggerProvider); !ok { + t.Errorf("expected a real sdk/log LoggerProvider, got %T", loggerglobal.GetLoggerProvider()) + } + if _, ok := slog.Default().Handler().(*fanoutHandler); !ok { + t.Errorf("expected default slog handler rewrapped as fanoutHandler, got %T", slog.Default().Handler()) + } + + ctx, cancel := context.WithTimeout(context.Background(), 100*time.Millisecond) + defer cancel() + _ = shutdown(ctx) +} + +// recordingLogExporter is a minimal sdk/log.Exporter that records every +// exported record for assertions, used since v0.20.0 ships no built-in +// in-memory test exporter for external consumers. +type recordingLogExporter struct { + mu sync.Mutex + records []sdklog.Record +} + +var _ sdklog.Exporter = (*recordingLogExporter)(nil) + +func (e *recordingLogExporter) Export(_ context.Context, records []sdklog.Record) error { + e.mu.Lock() + defer e.mu.Unlock() + for _, r := range records { + e.records = append(e.records, r.Clone()) + } + return nil +} + +func (e *recordingLogExporter) Shutdown(context.Context) error { return nil } +func (e *recordingLogExporter) ForceFlush(context.Context) error { return nil } + +func (e *recordingLogExporter) snapshot() []sdklog.Record { + e.mu.Lock() + defer e.mu.Unlock() + return append([]sdklog.Record(nil), e.records...) +} + +// TestLogRecordCarriesResourceAndTraceID exercises the exact pipeline Init +// wires (resource -> LoggerProvider -> otelslog bridge) with a recording +// exporter standing in for the OTLP gRPC exporter, proving exported records +// carry the full resource (incl. ci.run_id from OTEL_RESOURCE_ATTRIBUTES) and +// trace_id/span_id from the logging context. +func TestLogRecordCarriesResourceAndTraceID(t *testing.T) { + t.Setenv("OTEL_RESOURCE_ATTRIBUTES", "ci.run_id=TESTRUN") + + res, err := newResource(context.Background(), "test-svc") + if err != nil { + t.Fatalf("newResource: %v", err) + } + + exp := &recordingLogExporter{} + lp := sdklog.NewLoggerProvider( + sdklog.WithResource(res), + sdklog.WithProcessor(sdklog.NewSimpleProcessor(exp)), + ) + defer func() { _ = lp.Shutdown(context.Background()) }() + + bridge := otelslog.NewHandler("test-svc", otelslog.WithLoggerProvider(lp)) + logger := slog.New(bridge) + + sc := trace.NewSpanContext(trace.SpanContextConfig{ + TraceID: trace.TraceID{0x01, 0x02, 0x03, 0x04, 0x05, 0x06, 0x07, 0x08, 0x09, 0x0a, 0x0b, 0x0c, 0x0d, 0x0e, 0x0f, 0x10}, + SpanID: trace.SpanID{0x0a, 0x0b, 0x0c, 0x0d, 0x0e, 0x0f, 0x01, 0x02}, + TraceFlags: trace.FlagsSampled, + }) + ctx := trace.ContextWithSpanContext(context.Background(), sc) + + logger.InfoContext(ctx, "hello from bridge") + + records := exp.snapshot() + if len(records) != 1 { + t.Fatalf("got %d exported records, want 1", len(records)) + } + rec := records[0] + + if rec.TraceID() != sc.TraceID() { + t.Errorf("record TraceID = %s, want %s", rec.TraceID(), sc.TraceID()) + } + if rec.SpanID() != sc.SpanID() { + t.Errorf("record SpanID = %s, want %s", rec.SpanID(), sc.SpanID()) + } + + attrs := map[string]string{} + for _, kv := range rec.Resource().Attributes() { + attrs[string(kv.Key)] = kv.Value.Emit() + } + if attrs["ci.run_id"] != "TESTRUN" { + t.Errorf("resource ci.run_id = %q, want TESTRUN", attrs["ci.run_id"]) + } + if attrs["service.name"] != "test-svc" { + t.Errorf("resource service.name = %q, want test-svc", attrs["service.name"]) + } +} + +// recordingSlogHandler is a bare slog.Handler that records whether Handle +// was called, standing in for the pre-existing stdout/journald handler in +// fan-out tests. +type recordingSlogHandler struct { + mu sync.Mutex + called int +} + +var _ slog.Handler = (*recordingSlogHandler)(nil) + +func (h *recordingSlogHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (h *recordingSlogHandler) Handle(context.Context, slog.Record) error { + h.mu.Lock() + defer h.mu.Unlock() + h.called++ + return nil +} + +func (h *recordingSlogHandler) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h *recordingSlogHandler) WithGroup(string) slog.Handler { return h } + +func (h *recordingSlogHandler) count() int { + h.mu.Lock() + defer h.mu.Unlock() + return h.called +} + +// TestFanoutHandlerWritesToAllHandlers proves the existing stdout/journald +// handler still fires when the OTLP bridge handler is fanned in alongside it. +func TestFanoutHandlerWritesToAllHandlers(t *testing.T) { + stdout := &recordingSlogHandler{} + bridge := &recordingSlogHandler{} + logger := slog.New(newFanoutHandler(stdout, bridge)) + + logger.Info("dual write") + + if stdout.count() != 1 { + t.Errorf("stdout handler called %d times, want 1", stdout.count()) + } + if bridge.count() != 1 { + t.Errorf("bridge handler called %d times, want 1", bridge.count()) + } +} + +// TestAddFanoutHandlerPreservesExistingDefault proves addFanoutHandler +// rewraps rather than replaces whatever default handler was already +// installed (e.g. by SetDefaultJSONLogger before Init runs). +func TestAddFanoutHandlerPreservesExistingDefault(t *testing.T) { + prevHandler := slog.Default().Handler() + defer slog.SetDefault(slog.New(prevHandler)) + + existing := &recordingSlogHandler{} + slog.SetDefault(slog.New(existing)) + + bridge := &recordingSlogHandler{} + addFanoutHandler(bridge) + + slog.Info("after rewrap") + + if existing.count() != 1 { + t.Errorf("pre-existing handler called %d times, want 1", existing.count()) + } + if bridge.count() != 1 { + t.Errorf("bridge handler called %d times, want 1", bridge.count()) + } +} + func TestSlogHandlerPreservesWrapperThroughWithAttrs(t *testing.T) { var buf bytes.Buffer logger := slog.New(NewSlogHandler(slog.NewJSONHandler(&buf, nil))). diff --git a/spinifex/otelsetup/slog.go b/spinifex/otelsetup/slog.go index 924583341..7b2589991 100644 --- a/spinifex/otelsetup/slog.go +++ b/spinifex/otelsetup/slog.go @@ -2,6 +2,7 @@ package otelsetup import ( "context" + "errors" "log/slog" "os" @@ -52,3 +53,60 @@ func (h *traceHandler) WithAttrs(attrs []slog.Attr) slog.Handler { func (h *traceHandler) WithGroup(name string) slog.Handler { return &traceHandler{inner: h.inner.WithGroup(name)} } + +var _ slog.Handler = (*fanoutHandler)(nil) + +// fanoutHandler writes every record to all inner handlers, e.g. so OTLP +// export is additive to the existing stdout/journald handler rather than +// replacing it. +type fanoutHandler struct { + handlers []slog.Handler +} + +// newFanoutHandler returns a handler that fans out to all of handlers. +func newFanoutHandler(handlers ...slog.Handler) slog.Handler { + return &fanoutHandler{handlers: handlers} +} + +func (h *fanoutHandler) Enabled(ctx context.Context, level slog.Level) bool { + for _, inner := range h.handlers { + if inner.Enabled(ctx, level) { + return true + } + } + return false +} + +func (h *fanoutHandler) Handle(ctx context.Context, r slog.Record) error { + var errs error + for _, inner := range h.handlers { + if inner.Enabled(ctx, r.Level) { + errs = errors.Join(errs, inner.Handle(ctx, r.Clone())) + } + } + return errs +} + +func (h *fanoutHandler) WithAttrs(attrs []slog.Attr) slog.Handler { + next := make([]slog.Handler, len(h.handlers)) + for i, inner := range h.handlers { + next[i] = inner.WithAttrs(attrs) + } + return &fanoutHandler{handlers: next} +} + +func (h *fanoutHandler) WithGroup(name string) slog.Handler { + next := make([]slog.Handler, len(h.handlers)) + for i, inner := range h.handlers { + next[i] = inner.WithGroup(name) + } + return &fanoutHandler{handlers: next} +} + +// addFanoutHandler rewraps the process slog default so records also reach +// extra, in addition to whatever handler is already installed (e.g. the +// stdout/journald handler from SetDefaultJSONLogger). Used by Init to bolt +// the OTLP bridge onto an already-configured default logger. +func addFanoutHandler(extra slog.Handler) { + slog.SetDefault(slog.New(newFanoutHandler(slog.Default().Handler(), extra))) +}