diff --git a/cmd/proxy/actions/app.go b/cmd/proxy/actions/app.go index d86598f8f..ed50d2858 100644 --- a/cmd/proxy/actions/app.go +++ b/cmd/proxy/actions/app.go @@ -72,6 +72,11 @@ func App(logger *log.Logger, conf *config.Config) (http.Handler, func(), error) // RegisterExporter will register an exporter where we will export our traces to. // The error from the RegisterExporter would be nil if the tracer was specified by // the user and the trace exporter was created successfully. + // RegisterPropagator installs W3C TraceContext and B3 propagation so that + // incoming trace headers are extracted for log correlation, regardless of + // whether a trace exporter is configured. + observ.RegisterPropagator() + // RegisterExporter returns the cleanup function that flushes remaining traces // and stops the exporter. The caller is responsible for calling it at shutdown. cleanupTraces := noop diff --git a/go.mod b/go.mod index 7c68444b4..1e1ac6f2b 100644 --- a/go.mod +++ b/go.mod @@ -43,13 +43,13 @@ require ( go.etcd.io/etcd/server/v3 v3.6.10 go.mongodb.org/mongo-driver/v2 v2.7.0 go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.68.0 - go.opentelemetry.io/otel v1.43.0 + go.opentelemetry.io/otel v1.44.0 go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.43.0 go.opentelemetry.io/otel/exporters/prometheus v0.65.0 - go.opentelemetry.io/otel/metric v1.43.0 + go.opentelemetry.io/otel/metric v1.44.0 go.opentelemetry.io/otel/sdk v1.43.0 go.opentelemetry.io/otel/sdk/metric v1.43.0 - go.opentelemetry.io/otel/trace v1.43.0 + go.opentelemetry.io/otel/trace v1.44.0 golang.org/x/mod v0.35.0 golang.org/x/oauth2 v0.36.0 golang.org/x/sync v0.21.0 @@ -158,6 +158,7 @@ require ( go.opentelemetry.io/auto/sdk v1.2.1 // indirect go.opentelemetry.io/contrib/detectors/gcp v1.43.0 // indirect go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.68.0 // indirect + go.opentelemetry.io/contrib/propagators/b3 v1.44.0 // indirect go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0 // indirect go.opentelemetry.io/proto/otlp v1.10.0 // indirect go.uber.org/atomic v1.11.0 // indirect diff --git a/go.sum b/go.sum index 38204538b..c971be0dd 100644 --- a/go.sum +++ b/go.sum @@ -398,8 +398,12 @@ go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.6 go.opentelemetry.io/contrib/instrumentation/google.golang.org/grpc/otelgrpc v0.68.0/go.mod h1:Sje3i3MjSPKTSPvVWCaL8ugBzJwik3u4smCjUeuupqg= go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.68.0 h1:CqXxU8VOmDefoh0+ztfGaymYbhdB/tT3zs79QaZTNGY= go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp v0.68.0/go.mod h1:BuhAPThV8PBHBvg8ZzZ/Ok3idOdhWIodywz2xEcRbJo= +go.opentelemetry.io/contrib/propagators/b3 v1.44.0 h1:1IFH4oFKK8KupzIelCl3u+bkxpGRps1oWRjQI2+TTWs= +go.opentelemetry.io/contrib/propagators/b3 v1.44.0/go.mod h1:JqWFXsc7VDaqIyubFhEd2cPHqsrzqP0Lvn783SUwyro= go.opentelemetry.io/otel v1.43.0 h1:mYIM03dnh5zfN7HautFE4ieIig9amkNANT+xcVxAj9I= 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/otlptrace v1.43.0 h1:88Y4s2C8oTui1LGM6bTWkw0ICGcOLCAI5l6zsD1j20k= go.opentelemetry.io/otel/exporters/otlp/otlptrace v1.43.0/go.mod h1:Vl1/iaggsuRlrHf/hfPJPvVag77kKyvrLeD10kpMl+A= go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc v1.43.0 h1:RAE+JPfvEmvy+0LzyUA25/SGawPwIUbZ6u0Wug54sLc= @@ -410,12 +414,16 @@ go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.43.0 h1:TC+BewnDpeiAmc go.opentelemetry.io/otel/exporters/stdout/stdoutmetric v1.43.0/go.mod h1:J/ZyF4vfPwsSr9xJSPyQ4LqtcTPULFR64KwTikGLe+A= go.opentelemetry.io/otel/metric v1.43.0 h1:d7638QeInOnuwOONPp4JAOGfbCEpYb+K6DVWvdxGzgM= go.opentelemetry.io/otel/metric v1.43.0/go.mod h1:RDnPtIxvqlgO8GRW18W6Z/4P462ldprJtfxHxyKd2PY= +go.opentelemetry.io/otel/metric v1.44.0 h1:1w0gILTcHdr3YI+ixLyjemwrVnsMURbTZFrSYCdDdmc= +go.opentelemetry.io/otel/metric v1.44.0/go.mod h1:8O7hanEPBNgEMmybD3s2VBKcgWOCsA6tzHBPODAiquo= go.opentelemetry.io/otel/sdk v1.43.0 h1:pi5mE86i5rTeLXqoF/hhiBtUNcrAGHLKQdhg4h4V9Dg= go.opentelemetry.io/otel/sdk v1.43.0/go.mod h1:P+IkVU3iWukmiit/Yf9AWvpyRDlUeBaRg6Y+C58QHzg= go.opentelemetry.io/otel/sdk/metric v1.43.0 h1:S88dyqXjJkuBNLeMcVPRFXpRw2fuwdvfCGLEo89fDkw= go.opentelemetry.io/otel/sdk/metric v1.43.0/go.mod h1:C/RJtwSEJ5hzTiUz5pXF1kILHStzb9zFlIEe85bhj6A= go.opentelemetry.io/otel/trace v1.43.0 h1:BkNrHpup+4k4w+ZZ86CZoHHEkohws8AY+WTX09nk+3A= go.opentelemetry.io/otel/trace v1.43.0/go.mod h1:/QJhyVBUUswCphDVxq+8mld+AvhXZLhe+8WVFxiFff0= +go.opentelemetry.io/otel/trace v1.44.0 h1:jxF5CsGYCe74MCRx2X4g7WsY/VBKRqqpNvXlX/6gtIk= +go.opentelemetry.io/otel/trace v1.44.0/go.mod h1:oLl1jrMQAVo6v3GAggN+1VH9VIz9iUSvW53sW1Q8PIE= go.opentelemetry.io/proto/otlp v1.10.0 h1:IQRWgT5srOCYfiWnpqUYz9CVmbO8bFmKcwYxpuCSL2g= go.opentelemetry.io/proto/otlp v1.10.0/go.mod h1:/CV4QoCR/S9yaPj8utp3lvQPoqMtxXdzn7ozvvozVqk= go.uber.org/atomic v1.11.0 h1:ZvwS0R+56ePWxUNi+Atn9dWONBPp/AUETXlHW0DxSjE= diff --git a/pkg/middleware/requestid.go b/pkg/middleware/requestid.go index 9a5289759..c417b0305 100644 --- a/pkg/middleware/requestid.go +++ b/pkg/middleware/requestid.go @@ -1,19 +1,28 @@ package middleware import ( + "context" "net/http" "github.com/gomods/athens/pkg/requestid" "github.com/google/uuid" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/propagation" + "go.opentelemetry.io/otel/trace" ) -// WithRequestID ensures a request id is in the -// request context by either the incoming header -// or creating a new one. +// WithRequestID ensures a request id is in the request context. +// It prefers the trace ID extracted from incoming trace headers +// (traceparent/b3) via the global OTel propagator, then falls back +// to the Athens-Request-ID header, and finally generates a UUID. func WithRequestID(h http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - requestID := r.Header.Get(requestid.HeaderKey) - if requestID == "" { + var requestID string + if sc := extractRemoteSpanContext(r.Context(), r.Header); sc.HasTraceID() { + requestID = sc.TraceID().String() + } else if id := r.Header.Get(requestid.HeaderKey); id != "" { + requestID = id + } else { requestID = uuid.New().String() } ctx := requestid.SetInContext(r.Context(), requestID) @@ -21,3 +30,11 @@ func WithRequestID(h http.Handler) http.Handler { h.ServeHTTP(w, r) }) } + +// extractRemoteSpanContext uses the global OTel propagator to extract +// a span context from the request headers. Returns an empty SpanContext +// if no valid trace headers are present. +func extractRemoteSpanContext(ctx context.Context, headers http.Header) trace.SpanContext { + ctx = otel.GetTextMapPropagator().Extract(ctx, propagation.HeaderCarrier(headers)) + return trace.SpanContextFromContext(ctx) +} diff --git a/pkg/middleware/requestid_test.go b/pkg/middleware/requestid_test.go index 4cbe53bae..bb90f6117 100644 --- a/pkg/middleware/requestid_test.go +++ b/pkg/middleware/requestid_test.go @@ -7,25 +7,123 @@ import ( "github.com/gomods/athens/pkg/requestid" "github.com/google/uuid" + "go.opentelemetry.io/contrib/propagators/b3" + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/propagation" ) +func init() { + // Set up composite propagator for tests (same as production). + otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator( + b3.New(), + propagation.TraceContext{}, + propagation.Baggage{}, + )) +} + func TestWithRequestID(t *testing.T) { var givenRequestID string - h := WithRequestID(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { givenRequestID = requestid.FromContext(r.Context()) - })) - req := httptest.NewRequest("GET", "/", nil) - expectedRequestID := uuid.New().String() - req.Header.Set(requestid.HeaderKey, expectedRequestID) - w := httptest.NewRecorder() - h.ServeHTTP(w, req) - if givenRequestID != expectedRequestID { - t.Fatalf("expected request id to be %q but got %q", expectedRequestID, givenRequestID) - } - req = httptest.NewRequest("GET", "/", nil) - w = httptest.NewRecorder() - h.ServeHTTP(w, req) - if givenRequestID == "" { - t.Fatal("expected a request id to be created when a request id header is empty") - } + }) + + t.Run("uses trace ID from W3C traceparent header", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + req.Header.Set("Traceparent", "00-4bf92f3577b6a814af67ab2d6fc0f4e1-00f067aa0ba902b7-01") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID != "4bf92f3577b6a814af67ab2d6fc0f4e1" { + t.Fatalf("expected trace id %q but got %q", "4bf92f3577b6a814af67ab2d6fc0f4e1", givenRequestID) + } + }) + + t.Run("uses trace ID from B3 multi-header", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + req.Header.Set("X-B3-TraceId", "463ac35c9f6413ad48485a3953bb6124") + req.Header.Set("X-B3-SpanId", "0020000000000001") + req.Header.Set("X-B3-Sampled", "1") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID != "463ac35c9f6413ad48485a3953bb6124" { + t.Fatalf("expected trace id %q but got %q", "463ac35c9f6413ad48485a3953bb6124", givenRequestID) + } + }) + + t.Run("uses trace ID from B3 single header", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + req.Header.Set("B3", "80f198ee56343ba864fe8b2a57d3eff7-e457b5a2e4d86bd1-1") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID != "80f198ee56343ba864fe8b2a57d3eff7" { + t.Fatalf("expected trace id %q but got %q", "80f198ee56343ba864fe8b2a57d3eff7", givenRequestID) + } + }) + + t.Run("W3C takes priority over B3 when both present", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + req.Header.Set("Traceparent", "00-aaaa1111bbbb2222cccc3333dddd4444-00f067aa0ba902b7-01") + req.Header.Set("X-B3-TraceId", "1111222233334444aaaabbbbccccdddd") + req.Header.Set("X-B3-SpanId", "0020000000000001") + req.Header.Set("X-B3-Sampled", "1") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID != "aaaa1111bbbb2222cccc3333dddd4444" { + t.Fatalf("expected W3C trace id %q to win but got %q", "aaaa1111bbbb2222cccc3333dddd4444", givenRequestID) + } + }) + + t.Run("falls back to Athens-Request-ID header when no trace headers", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + req.Header.Set(requestid.HeaderKey, "my-custom-id-123") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID != "my-custom-id-123" { + t.Fatalf("expected %q but got %q", "my-custom-id-123", givenRequestID) + } + }) + + t.Run("generates UUID when no trace headers and no Athens header", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID == "" { + t.Fatal("expected a request id to be generated") + } + if _, err := uuid.Parse(givenRequestID); err != nil { + t.Fatalf("expected a valid UUID but got %q: %v", givenRequestID, err) + } + }) + + t.Run("falls back to UUID on malformed traceparent", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + req.Header.Set("Traceparent", "invalid-traceparent-value") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID == "" { + t.Fatal("expected a request id to be generated") + } + if _, err := uuid.Parse(givenRequestID); err != nil { + t.Fatalf("expected a valid UUID but got %q: %v", givenRequestID, err) + } + }) + + t.Run("falls back to Athens-Request-ID on malformed B3 header", func(t *testing.T) { + h := WithRequestID(handler) + req := httptest.NewRequest("GET", "/", nil) + req.Header.Set("X-B3-TraceId", "not-a-valid-hex-id") + req.Header.Set("X-B3-SpanId", "also-invalid") + req.Header.Set(requestid.HeaderKey, "fallback-id") + w := httptest.NewRecorder() + h.ServeHTTP(w, req) + if givenRequestID != "fallback-id" { + t.Fatalf("expected fallback %q but got %q", "fallback-id", givenRequestID) + } + }) } diff --git a/pkg/observ/observ.go b/pkg/observ/observ.go index 0920c2e4c..a250acd0f 100755 --- a/pkg/observ/observ.go +++ b/pkg/observ/observ.go @@ -6,6 +6,7 @@ import ( "time" "github.com/gomods/athens/pkg/errors" + "go.opentelemetry.io/contrib/propagators/b3" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/exporters/otlp/otlptrace/otlptracegrpc" "go.opentelemetry.io/otel/propagation" @@ -21,6 +22,18 @@ const instrumentationName = "github.com/gomods/athens" // shutdownTimeout bounds how long provider shutdown may block while flushing. const shutdownTimeout = 5 * time.Second +// RegisterPropagator installs the global OTel text map propagator with support +// for W3C TraceContext and Zipkin B3 (single + multiple header). This is +// registered unconditionally so that trace context can be extracted for log +// correlation even when no trace exporter is configured. +func RegisterPropagator() { + otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator( + b3.New(), + propagation.TraceContext{}, + propagation.Baggage{}, + )) +} + // RegisterExporter configures the OpenTelemetry TracerProvider used to export traces. // // Athens exports traces via OTLP. The traceExporter argument acts as a toggle: @@ -79,10 +92,6 @@ func registerOTLPExporter(url, service, env string, samplingFraction float64) (f sdktrace.WithSampler(sampler), ) otel.SetTracerProvider(tp) - otel.SetTextMapPropagator(propagation.NewCompositeTextMapPropagator( - propagation.TraceContext{}, - propagation.Baggage{}, - )) return func() { ctx, cancel := context.WithTimeout(context.Background(), shutdownTimeout)