From fedeb4cab75399e4672b77efe6a067a7bd148ddf Mon Sep 17 00:00:00 2001 From: Yuri Shkuro Date: Thu, 9 Feb 2023 00:28:04 -0500 Subject: [PATCH] =?UTF-8?q?Restore=20baggage=20support=20in=20HotROD=20?= =?UTF-8?q?=F0=9F=9A=97=20(#4225)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Which problem is this PR solving? - The baggage propagation was broken in HotROD after #4187 - This restores the baggage support by providing a few integration points with OTEL - [ ] This change will not work until OTEL Baggage & Bridge bugs are fixed: https://github.com/open-telemetry/opentelemetry-go/issues/3685 ## Short description of the changes - [`index.html`] The webapp used to send baggage via `jaeger-baggage` header, this is now changed to W3C `baggage` header - [`mux.go`] The Jaeger SDK was able to accept `jaeger-baggage` header even for requests without am active trace. OTEL Bridge does not support that, so we use OTEL's Baggage propagator to manually extract the baggage into Context, and once the Bridge creates a Span, we copy OTEL baggage from Context into the Span. - All other changes are cosmetic / logging related --------- Signed-off-by: Yuri Shkuro --- examples/hotrod/cmd/customer.go | 1 - examples/hotrod/cmd/driver.go | 1 - examples/hotrod/cmd/frontend.go | 1 - examples/hotrod/cmd/root.go | 24 ++++++-- examples/hotrod/cmd/route.go | 1 - examples/hotrod/pkg/log/factory.go | 2 +- examples/hotrod/pkg/log/logger.go | 20 ++++--- examples/hotrod/pkg/log/spanlogger.go | 5 ++ examples/hotrod/pkg/tracing/init.go | 10 +++- examples/hotrod/pkg/tracing/mux.go | 56 ++++++++++++++++--- examples/hotrod/services/customer/client.go | 1 - examples/hotrod/services/customer/server.go | 2 +- examples/hotrod/services/driver/server.go | 8 +-- examples/hotrod/services/frontend/server.go | 2 +- .../services/frontend/web_assets/index.html | 2 +- examples/hotrod/services/route/server.go | 2 +- 16 files changed, 99 insertions(+), 39 deletions(-) diff --git a/examples/hotrod/cmd/customer.go b/examples/hotrod/cmd/customer.go index 56f77bfec44..9952b2ce57a 100644 --- a/examples/hotrod/cmd/customer.go +++ b/examples/hotrod/cmd/customer.go @@ -46,5 +46,4 @@ var customerCmd = &cobra.Command{ func init() { RootCmd.AddCommand(customerCmd) - } diff --git a/examples/hotrod/cmd/driver.go b/examples/hotrod/cmd/driver.go index ac1bf5ae65a..5ff98d85560 100644 --- a/examples/hotrod/cmd/driver.go +++ b/examples/hotrod/cmd/driver.go @@ -46,5 +46,4 @@ var driverCmd = &cobra.Command{ func init() { RootCmd.AddCommand(driverCmd) - } diff --git a/examples/hotrod/cmd/frontend.go b/examples/hotrod/cmd/frontend.go index edf44501f64..e1eedc65c14 100644 --- a/examples/hotrod/cmd/frontend.go +++ b/examples/hotrod/cmd/frontend.go @@ -56,5 +56,4 @@ var options frontend.ConfigOptions func init() { RootCmd.AddCommand(frontendCmd) - } diff --git a/examples/hotrod/cmd/root.go b/examples/hotrod/cmd/root.go index c76fc785812..e3be64446e7 100644 --- a/examples/hotrod/cmd/root.go +++ b/examples/hotrod/cmd/root.go @@ -36,6 +36,7 @@ var ( logger *zap.Logger metricsFactory metrics.Factory otelExporter string // jaeger, otlp, stdout + verbose bool fixDBConnDelay time.Duration fixDBConnDisableMutex bool @@ -84,17 +85,28 @@ func init() { RootCmd.PersistentFlags().StringVarP(&basepath, "basepath", "b", "", `Basepath for frontend service(default "/")`) RootCmd.PersistentFlags().StringVarP(&jaegerUI, "jaeger-ui", "j", "http://localhost:16686", "Address of Jaeger UI to create [find trace] links") - rand.Seed(int64(time.Now().Nanosecond())) - logger, _ = zap.NewDevelopment( - zap.AddStacktrace(zapcore.FatalLevel), - zap.AddCallerSkip(1), - ) - jaegerclientenv2otel.MapJaegerToOtelEnvVars(logger) + RootCmd.PersistentFlags().BoolVarP(&verbose, "verbose", "v", false, "Enables debug logging") + cobra.OnInitialize(onInitialize) } // onInitialize is called before the command is executed. func onInitialize() { + rand.Seed(int64(time.Now().Nanosecond())) + + zapOptions := []zap.Option{ + zap.AddStacktrace(zapcore.FatalLevel), + zap.AddCallerSkip(1), + } + if !verbose { + zapOptions = append(zapOptions, + zap.IncreaseLevel(zap.LevelEnablerFunc(func(l zapcore.Level) bool { return l != zapcore.DebugLevel })), + ) + } + logger, _ = zap.NewDevelopment(zapOptions...) + + jaegerclientenv2otel.MapJaegerToOtelEnvVars(logger) + switch metricsBackend { case "expvar": metricsFactory = expvar.NewFactory(10) // 10 buckets for histograms diff --git a/examples/hotrod/cmd/route.go b/examples/hotrod/cmd/route.go index ce54159f17c..191bd96c556 100644 --- a/examples/hotrod/cmd/route.go +++ b/examples/hotrod/cmd/route.go @@ -46,5 +46,4 @@ var routeCmd = &cobra.Command{ func init() { RootCmd.AddCommand(routeCmd) - } diff --git a/examples/hotrod/pkg/log/factory.go b/examples/hotrod/pkg/log/factory.go index 2c85af90c5e..32ae2d818fb 100644 --- a/examples/hotrod/pkg/log/factory.go +++ b/examples/hotrod/pkg/log/factory.go @@ -37,7 +37,7 @@ func NewFactory(logger *zap.Logger) Factory { // Bg creates a context-unaware logger. func (b Factory) Bg() Logger { - return logger(b) + return wrapper(b) } // For returns a context-aware Logger. If the context diff --git a/examples/hotrod/pkg/log/logger.go b/examples/hotrod/pkg/log/logger.go index 933bdb3d2dd..b81c18a0d30 100644 --- a/examples/hotrod/pkg/log/logger.go +++ b/examples/hotrod/pkg/log/logger.go @@ -22,33 +22,39 @@ import ( // Logger is a simplified abstraction of the zap.Logger type Logger interface { + Debug(msg string, fields ...zapcore.Field) Info(msg string, fields ...zapcore.Field) Error(msg string, fields ...zapcore.Field) Fatal(msg string, fields ...zapcore.Field) With(fields ...zapcore.Field) Logger } -// logger delegates all calls to the underlying zap.Logger -type logger struct { +// wrapper delegates all calls to the underlying zap.Logger +type wrapper struct { logger *zap.Logger } +// Debug logs an debug msg with fields +func (l wrapper) Debug(msg string, fields ...zapcore.Field) { + l.logger.Debug(msg, fields...) +} + // Info logs an info msg with fields -func (l logger) Info(msg string, fields ...zapcore.Field) { +func (l wrapper) Info(msg string, fields ...zapcore.Field) { l.logger.Info(msg, fields...) } // Error logs an error msg with fields -func (l logger) Error(msg string, fields ...zapcore.Field) { +func (l wrapper) Error(msg string, fields ...zapcore.Field) { l.logger.Error(msg, fields...) } // Fatal logs a fatal error msg with fields -func (l logger) Fatal(msg string, fields ...zapcore.Field) { +func (l wrapper) Fatal(msg string, fields ...zapcore.Field) { l.logger.Fatal(msg, fields...) } // With creates a child logger, and optionally adds some context fields to that logger. -func (l logger) With(fields ...zapcore.Field) Logger { - return logger{logger: l.logger.With(fields...)} +func (l wrapper) With(fields ...zapcore.Field) Logger { + return wrapper{logger: l.logger.With(fields...)} } diff --git a/examples/hotrod/pkg/log/spanlogger.go b/examples/hotrod/pkg/log/spanlogger.go index a5ab6f7de82..dd143d19dbd 100644 --- a/examples/hotrod/pkg/log/spanlogger.go +++ b/examples/hotrod/pkg/log/spanlogger.go @@ -31,6 +31,11 @@ type spanLogger struct { spanFields []zapcore.Field } +func (sl spanLogger) Debug(msg string, fields ...zapcore.Field) { + sl.logToSpan("Debug", msg, fields...) + sl.logger.Debug(msg, append(sl.spanFields, fields...)...) +} + func (sl spanLogger) Info(msg string, fields ...zapcore.Field) { sl.logToSpan("info", msg, fields...) sl.logger.Info(msg, append(sl.spanFields, fields...)...) diff --git a/examples/hotrod/pkg/tracing/init.go b/examples/hotrod/pkg/tracing/init.go index eb201e9d6d1..b21b0b06865 100644 --- a/examples/hotrod/pkg/tracing/init.go +++ b/examples/hotrod/pkg/tracing/init.go @@ -44,14 +44,18 @@ var once sync.Once // to return an OpenTracing-compatible tracer. func Init(serviceName string, exporterType string, metricsFactory metrics.Factory, logger log.Factory) opentracing.Tracer { once.Do(func() { - otel.SetTextMapPropagator(propagation.TraceContext{}) + otel.SetTextMapPropagator( + propagation.NewCompositeTextMapPropagator( + propagation.TraceContext{}, + propagation.Baggage{}, + )) }) exp, err := createOtelExporter(exporterType) if err != nil { logger.Bg().Fatal("cannot create exporter", zap.String("exporterType", exporterType), zap.Error(err)) } - logger.Bg().Info("using " + exporterType + " trace exporter") + logger.Bg().Debug("using " + exporterType + " trace exporter") rpcmetricsObserver := rpcmetrics.NewObserver(metricsFactory, rpcmetrics.DefaultNameNormalizer) @@ -64,7 +68,7 @@ func Init(serviceName string, exporterType string, metricsFactory metrics.Factor )), ) otTracer, _ := otbridge.NewTracerPair(tp.Tracer("")) - logger.Bg().Info("created OTEL->OT brige", zap.String("service-name", serviceName)) + logger.Bg().Debug("created OTEL->OT brige", zap.String("service-name", serviceName)) return otTracer } diff --git a/examples/hotrod/pkg/tracing/mux.go b/examples/hotrod/pkg/tracing/mux.go index 260010a6b25..a9102f2ccb4 100644 --- a/examples/hotrod/pkg/tracing/mux.go +++ b/examples/hotrod/pkg/tracing/mux.go @@ -20,34 +20,72 @@ import ( "github.com/opentracing-contrib/go-stdlib/nethttp" "github.com/opentracing/opentracing-go" + "go.opentelemetry.io/otel/baggage" + "go.opentelemetry.io/otel/propagation" + "go.uber.org/zap" + + "github.com/jaegertracing/jaeger/examples/hotrod/pkg/log" ) // NewServeMux creates a new TracedServeMux. -func NewServeMux(tracer opentracing.Tracer) *TracedServeMux { +func NewServeMux(copyBaggage bool, tracer opentracing.Tracer, logger log.Factory) *TracedServeMux { return &TracedServeMux{ - mux: http.NewServeMux(), - tracer: tracer, + mux: http.NewServeMux(), + copyBaggage: copyBaggage, + tracer: tracer, + logger: logger, } } // TracedServeMux is a wrapper around http.ServeMux that instruments handlers for tracing. type TracedServeMux struct { - mux *http.ServeMux - tracer opentracing.Tracer + mux *http.ServeMux + copyBaggage bool + tracer opentracing.Tracer + logger log.Factory } -// Handle implements http.ServeMux#Handle +// Handle implements http.ServeMux#Handle, which is used to register new handler. func (tm *TracedServeMux) Handle(pattern string, handler http.Handler) { + tm.logger.Bg().Debug("registering traced handler", zap.String("endpoint", pattern)) + middleware := nethttp.Middleware( tm.tracer, handler, nethttp.OperationNameFunc(func(r *http.Request) string { return "HTTP " + r.Method + " " + pattern - })) - tm.mux.Handle(pattern, middleware) + }), + // Jaeger SDK was able to accept `jaeger-baggage` header even for requests without am active trace. + // OTEL Bridge does not support that, so we use Baggage propagator to manually extract the baggage + // into Context (in otelBaggageExtractor handler below), and once the Bridge creates a Span, + // we use this SpanObserver to copy OTEL baggage from Context into the Span. + nethttp.MWSpanObserver(func(span opentracing.Span, r *http.Request) { + if !tm.copyBaggage { + return + } + bag := baggage.FromContext(r.Context()) + for _, m := range bag.Members() { + if b := span.BaggageItem(m.Key()); b == "" { + span.SetBaggageItem(m.Key(), m.Value()) + } + } + }), + ) + tm.mux.Handle(pattern, otelBaggageExtractor(middleware)) } -// ServeHTTP implements http.ServeMux#ServeHTTP +// ServeHTTP implements http.ServeMux#ServeHTTP. func (tm *TracedServeMux) ServeHTTP(w http.ResponseWriter, r *http.Request) { tm.mux.ServeHTTP(w, r) } + +// Used with nethttp.MWSpanObserver above. +func otelBaggageExtractor(next http.Handler) http.Handler { + propagator := propagation.Baggage{} + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + carrier := propagation.HeaderCarrier(r.Header) + ctx := propagator.Extract(r.Context(), carrier) + r = r.WithContext(ctx) + next.ServeHTTP(w, r) + }) +} diff --git a/examples/hotrod/services/customer/client.go b/examples/hotrod/services/customer/client.go index 5d971a64f93..f9595289c44 100644 --- a/examples/hotrod/services/customer/client.go +++ b/examples/hotrod/services/customer/client.go @@ -54,7 +54,6 @@ func (c *Client) Get(ctx context.Context, customerID string) (*Customer, error) c.logger.For(ctx).Info("Getting customer", zap.String("customer_id", customerID)) url := fmt.Sprintf("http://"+c.hostPort+"/customer?customer=%s", customerID) - fmt.Println(url) var customer Customer if err := c.client.GetJSON(ctx, "/customer", url, &customer); err != nil { return nil, err diff --git a/examples/hotrod/services/customer/server.go b/examples/hotrod/services/customer/server.go index f35a15c36a6..7cbe0e6da4c 100644 --- a/examples/hotrod/services/customer/server.go +++ b/examples/hotrod/services/customer/server.go @@ -57,7 +57,7 @@ func (s *Server) Run() error { } func (s *Server) createServeMux() http.Handler { - mux := tracing.NewServeMux(s.tracer) + mux := tracing.NewServeMux(false, s.tracer, s.logger) mux.Handle("/customer", http.HandlerFunc(s.customer)) return mux } diff --git a/examples/hotrod/services/driver/server.go b/examples/hotrod/services/driver/server.go index da630555df8..e1d1aa3975b 100644 --- a/examples/hotrod/services/driver/server.go +++ b/examples/hotrod/services/driver/server.go @@ -43,10 +43,10 @@ var _ DriverServiceServer = (*Server)(nil) // NewServer creates a new driver.Server func NewServer(hostPort string, otelExporter string, metricsFactory metrics.Factory, logger log.Factory) *Server { tracer := tracing.Init("driver", otelExporter, metricsFactory, logger) - server := grpc.NewServer(grpc.UnaryInterceptor( - otgrpc.OpenTracingServerInterceptor(tracer)), - grpc.StreamInterceptor( - otgrpc.OpenTracingStreamServerInterceptor(tracer))) + server := grpc.NewServer( + grpc.UnaryInterceptor(otgrpc.OpenTracingServerInterceptor(tracer)), + grpc.StreamInterceptor(otgrpc.OpenTracingStreamServerInterceptor(tracer)), + ) return &Server{ hostPort: hostPort, tracer: tracer, diff --git a/examples/hotrod/services/frontend/server.go b/examples/hotrod/services/frontend/server.go index e47a5615db4..d4d028f1fc4 100644 --- a/examples/hotrod/services/frontend/server.go +++ b/examples/hotrod/services/frontend/server.go @@ -76,7 +76,7 @@ func (s *Server) Run() error { } func (s *Server) createServeMux() http.Handler { - mux := tracing.NewServeMux(s.tracer) + mux := tracing.NewServeMux(true, s.tracer, s.logger) p := path.Join("/", s.basepath) mux.Handle(p, http.StripPrefix(p, http.FileServer(s.assetFS))) mux.Handle(path.Join(p, "/dispatch"), http.HandlerFunc(s.dispatch)) diff --git a/examples/hotrod/services/frontend/web_assets/index.html b/examples/hotrod/services/frontend/web_assets/index.html index d8bf28b85d8..e55b015fa9a 100644 --- a/examples/hotrod/services/frontend/web_assets/index.html +++ b/examples/hotrod/services/frontend/web_assets/index.html @@ -69,7 +69,7 @@

🚗 Rides On Demand 🚗

var freshCar = $($("#hotrod-log").prepend('
Dispatching a car...[req: '+requestID+']
').children()[0]); var customer = evt.target.dataset.customer; var headers = { - 'jaeger-baggage': 'session=' + clientUUID + ', request=' + requestID + 'baggage': 'session=' + clientUUID + ', request=' + requestID }; console.log(headers); var before = Date.now(); diff --git a/examples/hotrod/services/route/server.go b/examples/hotrod/services/route/server.go index 389f2470dc0..b93662b84f0 100644 --- a/examples/hotrod/services/route/server.go +++ b/examples/hotrod/services/route/server.go @@ -59,7 +59,7 @@ func (s *Server) Run() error { } func (s *Server) createServeMux() http.Handler { - mux := tracing.NewServeMux(s.tracer) + mux := tracing.NewServeMux(false, s.tracer, s.logger) mux.Handle("/route", http.HandlerFunc(s.route)) mux.Handle("/debug/vars", expvar.Handler()) // expvar mux.Handle("/metrics", promhttp.Handler()) // Prometheus