opentelemetry: Backport update to otel v0.11.x (#1161)

examples/Cargo.toml

@@ -52,5 +52,5 @@ inferno = "0.10.0"
 tempdir = "0.3.7"
 
 # opentelemetry example
-opentelemetry = { version = "0.10", default-features = false, features = ["trace"] }
-opentelemetry-jaeger = "0.9"
+opentelemetry = { version = "0.11", default-features = false, features = ["trace"] }
+opentelemetry-jaeger = "0.10"

examples/examples/opentelemetry-remote-context.rs

@@ -1,4 +1,4 @@
-use opentelemetry::sdk::propagation::B3Propagator;
+use opentelemetry::sdk::propagation::TraceContextPropagator;
 use opentelemetry::{global, Context};
 use std::collections::HashMap;
 use tracing::span;
@@ -15,16 +15,16 @@ fn make_request(_cx: Context) {
 fn build_example_carrier() -> HashMap<String, String> {
     let mut carrier = HashMap::new();
     carrier.insert(
-        "X-B3".to_string(),
-        "4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-1".to_string(),
+        "traceparent".to_string(),
+        "00-0af7651916cd43dd8448eb211c80319c-b7ad6b7169203331-01".to_string(),
     );
 
     carrier
 }
 
 fn main() {
     // Set a format for propagating context. This MUST be provided, as the default is a no-op.
-    global::set_text_map_propagator(B3Propagator::new());
+    global::set_text_map_propagator(TraceContextPropagator::new());
     let subscriber = Registry::default().with(tracing_opentelemetry::layer());
 
     tracing::subscriber::with_default(subscriber, || {
@@ -37,7 +37,7 @@ fn main() {
         let app_root = span!(tracing::Level::INFO, "app_start");
 
         // Assign parent trace from external context
-        app_root.set_parent(&parent_context);
+        app_root.set_parent(parent_context);
 
         // To include tracing context in client requests from _this_ app,
         // use `context` to extract the current OpenTelemetry context.

tracing-opentelemetry/Cargo.toml

@@ -22,11 +22,12 @@ edition = "2018"
 default = ["tracing-log"]
 
 [dependencies]
-opentelemetry = { version = "0.10", default-features = false, features = ["trace"] }
+opentelemetry = { version = "0.11", default-features = false, features = ["trace"] }
 tracing = { path = "../tracing", version = "0.1" }
 tracing-core = { path = "../tracing-core", version = "0.1" }
 tracing-subscriber = { path = "../tracing-subscriber", version = "0.2", default-features = false, features = ["registry"] }
 tracing-log = { path = "../tracing-log", version = "0.1", default-features = false, optional = true }
 
 [dev-dependencies]
-opentelemetry-jaeger = "0.9"
+async-trait = "0.1"
+opentelemetry-jaeger = "0.10"

tracing-opentelemetry/src/layer.rs

@@ -3,7 +3,7 @@ use opentelemetry::{trace as otel, trace::TraceContextExt, Context as OtelContex
 use std::any::TypeId;
 use std::fmt;
 use std::marker;
-use std::time::SystemTime;
+use std::time::{Instant, SystemTime};
 use tracing_core::span::{self, Attributes, Id, Record};
 use tracing_core::{field, Event, Subscriber};
 #[cfg(feature = "tracing-log")]
@@ -22,7 +22,7 @@ static SPAN_KIND_FIELD: &str = "otel.kind";
 /// [tracing]: https://github.com/tokio-rs/tracing
 pub struct OpenTelemetryLayer<S, T> {
     tracer: T,
-
+    tracked_inactivity: bool,
     get_context: WithContext,
     _registry: marker::PhantomData<S>,
 }
@@ -268,6 +268,7 @@ where
     pub fn new(tracer: T) -> Self {
         OpenTelemetryLayer {
             tracer,
+            tracked_inactivity: true,
             get_context: WithContext(Self::get_context),
             _registry: marker::PhantomData,
         }
@@ -304,41 +305,51 @@ where
     {
         OpenTelemetryLayer {
             tracer,
+            tracked_inactivity: self.tracked_inactivity,
             get_context: WithContext(OpenTelemetryLayer::<S, Tracer>::get_context),
             _registry: self._registry,
         }
     }
 
-    /// Retrieve the parent OpenTelemetry [`SpanContext`] from the current
-    /// tracing [`span`] through the [`Registry`]. This [`SpanContext`]
-    /// links spans to their parent for proper hierarchical visualization.
+    /// Sets whether or not spans metadata should include the _busy time_
+    /// (total time for which it was entered), and _idle time_ (total time
+    /// the span existed but was not entered).
+    pub fn with_tracked_inactivity(self, tracked_inactivity: bool) -> Self {
+        Self {
+            tracked_inactivity,
+            ..self
+        }
+    }
+
+    /// Retrieve the parent OpenTelemetry [`Context`] from the current tracing
+    /// [`span`] through the [`Registry`]. This [`Context`] links spans to their
+    /// parent for proper hierarchical visualization.
     ///
-    /// [`SpanContext`]: opentelemetry::trace::SpanContext
+    /// [`Context`]: opentelemetry::Context
     /// [`span`]: tracing::Span
     /// [`Registry`]: tracing_subscriber::Registry
-    fn parent_span_context(
-        &self,
-        attrs: &Attributes<'_>,
-        ctx: &Context<'_, S>,
-    ) -> Option<otel::SpanContext> {
+    fn parent_context(&self, attrs: &Attributes<'_>, ctx: &Context<'_, S>) -> OtelContext {
         // If a span is specified, it _should_ exist in the underlying `Registry`.
         if let Some(parent) = attrs.parent() {
             let span = ctx.span(parent).expect("Span not found, this is a bug");
             let mut extensions = span.extensions_mut();
             extensions
                 .get_mut::<otel::SpanBuilder>()
-                .map(|builder| self.tracer.sampled_span_context(builder))
+                .map(|builder| self.tracer.sampled_context(builder))
+                .unwrap_or_default()
         // Else if the span is inferred from context, look up any available current span.
         } else if attrs.is_contextual() {
-            ctx.lookup_current().and_then(|span| {
-                let mut extensions = span.extensions_mut();
-                extensions
-                    .get_mut::<otel::SpanBuilder>()
-                    .map(|builder| self.tracer.sampled_span_context(builder))
-            })
+            ctx.lookup_current()
+                .and_then(|span| {
+                    let mut extensions = span.extensions_mut();
+                    extensions
+                        .get_mut::<otel::SpanBuilder>()
+                        .map(|builder| self.tracer.sampled_context(builder))
+                })
+                .unwrap_or_else(OtelContext::current)
         // Explicit root spans should have no parent context.
         } else {
-            None
+            OtelContext::new()
         }
     }
 
@@ -377,6 +388,10 @@ where
         let span = ctx.span(id).expect("Span not found, this is a bug");
         let mut extensions = span.extensions_mut();
 
+        if self.tracked_inactivity && extensions.get_mut::<Timings>().is_none() {
+            extensions.insert(Timings::new());
+        }
+
         let mut builder = self
             .tracer
             .span_builder(attrs.metadata().name())
@@ -385,23 +400,50 @@ where
             .with_span_id(self.tracer.new_span_id());
 
         // Set optional parent span context from attrs
-        builder.parent_context = self.parent_span_context(attrs, &ctx);
-
-        // Ensure trace id exists so children are matched properly.
-        if builder.parent_context.is_none() {
-            let cx = OtelContext::current();
-            let existing_otel_span_context = cx.span().span_context();
-            if existing_otel_span_context.is_valid() {
-                builder.trace_id = Some(existing_otel_span_context.trace_id());
-            } else {
-                builder.trace_id = Some(self.tracer.new_trace_id());
-            }
+        builder.parent_context = Some(self.parent_context(attrs, &ctx));
+
+        // Ensure trace id exists so spans are associated with the proper trace.
+        //
+        // Parent contexts are in 4 possible states, first two require a new
+        // trace ids, second two have existing trace ids:
+        //   * Empty - explicit new tracing root span, needs new id
+        //   * A parent context containing no active or remote span, needs new id
+        //   * A parent context containing an active span, defer to that span's trace
+        //   * A parent context containing a remote span context, defer to remote trace
+        let needs_trace_id = builder.parent_context.as_ref().map_or(true, |cx| {
+            !cx.has_active_span() && cx.remote_span_context().is_none()
+        });
+
+        if needs_trace_id {
+            builder.trace_id = Some(self.tracer.new_trace_id());
         }
 
         attrs.record(&mut SpanAttributeVisitor(&mut builder));
         extensions.insert(builder);
     }
 
+    fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) {
+        let span = ctx.span(id).expect("Span not found, this is a bug");
+        let mut extensions = span.extensions_mut();
+
+        if let Some(timings) = extensions.get_mut::<Timings>() {
+            let now = Instant::now();
+            timings.idle += (now - timings.last).as_nanos() as u64;
+            timings.last = now;
+        }
+    }
+
+    fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) {
+        let span = ctx.span(id).expect("Span not found, this is a bug");
+        let mut extensions = span.extensions_mut();
+
+        if let Some(timings) = extensions.get_mut::<Timings>() {
+            let now = Instant::now();
+            timings.busy += (now - timings.last).as_nanos() as u64;
+            timings.last = now;
+        }
+    }
+
     /// Record OpenTelemetry [`attributes`] for the given values.
     ///
     /// [`attributes`]: opentelemetry::trace::SpanBuilder::attributes
@@ -428,7 +470,12 @@ where
             .get_mut::<otel::SpanBuilder>()
             .expect("Missing SpanBuilder span extensions");
 
-        let follows_context = self.tracer.sampled_span_context(follows_builder);
+        let follows_context = self
+            .tracer
+            .sampled_context(follows_builder)
+            .span()
+            .span_context()
+            .clone();
         let follows_link = otel::Link::new(follows_context, Vec::new());
         if let Some(ref mut links) = builder.links {
             links.push(follows_link);
@@ -487,7 +534,20 @@ where
     fn on_close(&self, id: span::Id, ctx: Context<'_, S>) {
         let span = ctx.span(&id).expect("Span not found, this is a bug");
         let mut extensions = span.extensions_mut();
-        if let Some(builder) = extensions.remove::<otel::SpanBuilder>() {
+        if let Some(mut builder) = extensions.remove::<otel::SpanBuilder>() {
+            // Append busy/idle timings when enabled.
+            if let Some(timings) = extensions.get_mut::<Timings>() {
+                let mut timings_attributes = vec![
+                    KeyValue::new("busy_ns", timings.busy.to_string()),
+                    KeyValue::new("idle_ns", timings.idle.to_string()),
+                ];
+
+                match builder.attributes {
+                    Some(ref mut attributes) => attributes.append(&mut timings_attributes),
+                    None => builder.attributes = Some(timings_attributes),
+                }
+            }
+
             // Assign end time, build and start span, drop span to export
             builder.with_end_time(SystemTime::now()).start(&self.tracer);
         }
@@ -506,6 +566,22 @@ where
     }
 }
 
+struct Timings {
+    idle: u64,
+    busy: u64,
+    last: Instant,
+}
+
+impl Timings {
+    fn new() -> Self {
+        Self {
+            idle: 0,
+            busy: 0,
+            last: Instant::now(),
+        }
+    }
+}
+
 #[cfg(test)]
 mod tests {
     use super::*;
@@ -520,21 +596,21 @@ mod tests {
         fn invalid(&self) -> Self::Span {
             otel::NoopSpan::new()
         }
-        fn start_from_context(&self, _name: &str, _context: &OtelContext) -> Self::Span {
+        fn start_with_context(&self, _name: &str, _context: OtelContext) -> Self::Span {
             self.invalid()
         }
         fn span_builder(&self, name: &str) -> otel::SpanBuilder {
             otel::SpanBuilder::from_name(name.to_string())
         }
-        fn build_with_context(&self, builder: otel::SpanBuilder, _cx: &OtelContext) -> Self::Span {
+        fn build(&self, builder: otel::SpanBuilder) -> Self::Span {
             *self.0.lock().unwrap() = Some(builder);
             self.invalid()
         }
     }
 
     impl PreSampledTracer for TestTracer {
-        fn sampled_span_context(&self, _builder: &mut otel::SpanBuilder) -> otel::SpanContext {
-            otel::SpanContext::empty_context()
+        fn sampled_context(&self, _builder: &mut otel::SpanBuilder) -> OtelContext {
+            OtelContext::new()
         }
         fn new_trace_id(&self) -> otel::TraceId {
             otel::TraceId::invalid()
@@ -605,7 +681,18 @@ mod tests {
             tracing::debug_span!("request", otel.kind = "Server");
         });
 
-        let recorded_trace_id = tracer.0.lock().unwrap().as_ref().unwrap().trace_id;
-        assert_eq!(recorded_trace_id, Some(trace_id))
+        let recorded_trace_id = tracer
+            .0
+            .lock()
+            .unwrap()
+            .as_ref()
+            .unwrap()
+            .parent_context
+            .as_ref()
+            .unwrap()
+            .span()
+            .span_context()
+            .trace_id();
+        assert_eq!(recorded_trace_id, trace_id)
     }
 }

tracing-opentelemetry/src/lib.rs

@@ -51,7 +51,7 @@
 //! ## Examples
 //!
 //! ```
-//! use opentelemetry::exporter::trace::stdout;
+//! use opentelemetry::sdk::export::trace::stdout;
 //! use tracing::{error, span};
 //! use tracing_subscriber::layer::SubscriberExt;
 //! use tracing_subscriber::Registry;