appender-tracing: Include trace ID and span ID in logs when nested in tracing crate's spans (#2438)

Co-authored-by: Zhongyang Wu <zhongyang.wu@outlook.com>
Co-authored-by: Lalit Kumar Bhasin <lalit_fin@yahoo.com>
Co-authored-by: Cijo Thomas <cijo.thomas@gmail.com>
Co-authored-by: Cijo Thomas <cithomas@microsoft.com>

Author: 4 people

Cargo.toml

@@ -8,6 +8,9 @@ members = [
     "stress",
 ]
 resolver = "2"
+# Avoid applying patch to force use of workspace members for this
+# not actively maintained crate
+exclude = ["opentelemetry-prometheus"]
 
 [profile.bench]
 # https://doc.rust-lang.org/cargo/reference/profiles.html#bench
@@ -50,3 +53,9 @@ tracing = { version = ">=0.1.40", default-features = false }
 tracing-core = { version = ">=0.1.33", default-features = false } 
 tracing-subscriber = { version = "0.3", default-features = false }
 url = { version = "2.5", default-features = false }
+
+# Aviod use of crates.io version of these crates through the tracing-opentelemetry dependencies
+[patch.crates-io]
+opentelemetry = { path = "opentelemetry" }
+opentelemetry_sdk = { path = "opentelemetry-sdk" }
+opentelemetry-stdout = { path = "opentelemetry-stdout" }

opentelemetry-appender-tracing/CHANGELOG.md

@@ -3,6 +3,7 @@
 ## vNext
 
 - Bump msrv to 1.75.0.
+- New experimental feature to use trace\_id & span\_id from spans created through the [tracing](https://crates.io/crates/tracing) crate (experimental_use_tracing_span_context) [#2438](https://github.com/open-telemetry/opentelemetry-rust/pull/2438)
 
 
 ## 0.27.0

opentelemetry-appender-tracing/Cargo.toml

@@ -17,6 +17,7 @@ tracing = { workspace = true, features = ["std"]}
 tracing-core = { workspace = true }
 tracing-log = { version = "0.2", optional = true }
 tracing-subscriber = { workspace = true, features = ["registry", "std"] }
+tracing-opentelemetry = { version = "0.28", optional = true }
 
 [dev-dependencies]
 log = { workspace = true }
@@ -33,6 +34,7 @@ pprof = { version = "0.14", features = ["flamegraph", "criterion"] }
 [features]
 experimental_metadata_attributes = ["dep:tracing-log"]
 spec_unstable_logs_enabled = ["opentelemetry/spec_unstable_logs_enabled"]
+experimental_use_tracing_span_context = ["tracing-opentelemetry"]
 
 
 [[bench]]

opentelemetry-appender-tracing/src/layer.rs

@@ -8,7 +8,7 @@ use tracing_core::Level;
 use tracing_core::Metadata;
 #[cfg(feature = "experimental_metadata_attributes")]
 use tracing_log::NormalizeEvent;
-use tracing_subscriber::Layer;
+use tracing_subscriber::{registry::LookupSpan, Layer};
 
 const INSTRUMENTATION_LIBRARY_NAME: &str = "opentelemetry-appender-tracing";
 
@@ -149,7 +149,7 @@ where
 
 impl<S, P, L> Layer<S> for OpenTelemetryTracingBridge<P, L>
 where
-    S: tracing::Subscriber,
+    S: tracing::Subscriber + for<'a> LookupSpan<'a>,
     P: LoggerProvider<Logger = L> + Send + Sync + 'static,
     L: Logger + Send + Sync + 'static,
 {
@@ -180,6 +180,26 @@ where
         // Visit fields.
         event.record(&mut visitor);
 
+        #[cfg(feature = "experimental_use_tracing_span_context")]
+        if let Some(span) = _ctx.event_span(event) {
+            use tracing_opentelemetry::OtelData;
+            let opt_span_id = span
+                .extensions()
+                .get::<OtelData>()
+                .and_then(|otd| otd.builder.span_id);
+
+            let opt_trace_id = span.scope().last().and_then(|root_span| {
+                root_span
+                    .extensions()
+                    .get::<OtelData>()
+                    .and_then(|otd| otd.builder.trace_id)
+            });
+
+            if let Some((trace_id, span_id)) = opt_trace_id.zip(opt_span_id) {
+                log_record.set_trace_context(trace_id, span_id, None);
+            }
+        }
+
         //emit record
         self.logger.emit(log_record);
     }
@@ -495,6 +515,67 @@ mod tests {
         }
     }
 
+    #[cfg(feature = "experimental_use_tracing_span_context")]
+    #[test]
+    fn tracing_appender_inside_tracing_crate_context() {
+        use opentelemetry_sdk::trace::InMemorySpanExporterBuilder;
+
+        // Arrange
+        let exporter: InMemoryLogExporter = InMemoryLogExporter::default();
+        let logger_provider = LoggerProvider::builder()
+            .with_simple_exporter(exporter.clone())
+            .build();
+
+        // setup tracing layer to compare trace/span IDs against
+        let span_exporter = InMemorySpanExporterBuilder::new().build();
+        let tracer_provider = TracerProvider::builder()
+            .with_simple_exporter(span_exporter.clone())
+            .build();
+        let tracer = tracer_provider.tracer("test-tracer");
+
+        let level_filter = tracing_subscriber::filter::LevelFilter::INFO;
+        let log_layer =
+            layer::OpenTelemetryTracingBridge::new(&logger_provider).with_filter(level_filter);
+
+        let subscriber = tracing_subscriber::registry()
+            .with(log_layer)
+            .with(tracing_opentelemetry::layer().with_tracer(tracer));
+
+        // Avoiding global subscriber.init() as that does not play well with unit tests.
+        let _guard = tracing::subscriber::set_default(subscriber);
+
+        // Act
+        tracing::info_span!("outer-span").in_scope(|| {
+            error!("first-event");
+
+            tracing::info_span!("inner-span").in_scope(|| {
+                error!("second-event");
+            });
+        });
+
+        logger_provider.force_flush();
+
+        let logs = exporter.get_emitted_logs().expect("No emitted logs");
+        assert_eq!(logs.len(), 2);
+
+        let spans = span_exporter.get_finished_spans().unwrap();
+        assert_eq!(spans.len(), 2);
+
+        let trace_id = spans[0].span_context.trace_id();
+        assert_eq!(trace_id, spans[1].span_context.trace_id());
+        let inner_span_id = spans[0].span_context.span_id();
+        let outer_span_id = spans[1].span_context.span_id();
+        assert_eq!(outer_span_id, spans[0].parent_span_id);
+
+        let trace_ctx0 = logs[0].record.trace_context().unwrap();
+        let trace_ctx1 = logs[1].record.trace_context().unwrap();
+
+        assert_eq!(trace_ctx0.trace_id, trace_id);
+        assert_eq!(trace_ctx1.trace_id, trace_id);
+        assert_eq!(trace_ctx0.span_id, outer_span_id);
+        assert_eq!(trace_ctx1.span_id, inner_span_id);
+    }
+
     #[test]
     fn tracing_appender_standalone_with_tracing_log() {
         // Arrange

opentelemetry-prometheus/Cargo.toml

@@ -20,19 +20,19 @@ all-features = true
 rustdoc-args = ["--cfg", "docsrs"]
 
 [dependencies]
-once_cell = { workspace = true }
+once_cell = { version = "1.13" }
 opentelemetry = { version = "0.27", default-features = false, features = ["metrics"] }
 opentelemetry_sdk = { version = "0.27", default-features = false, features = ["metrics"] }
 prometheus = "0.13"
 protobuf = "2.14"
-tracing = {workspace = true, optional = true} # optional for opentelemetry internal logging
+tracing = {version = ">=0.1.40", default-features = false, optional = true} # optional for opentelemetry internal logging
 
 [dev-dependencies]
 opentelemetry-semantic-conventions = { version = "0.27" }
-http-body-util = { workspace = true }
-hyper = { workspace = true, features = ["full"] }
-hyper-util = { workspace = true, features = ["full"] }
-tokio = { workspace = true, features = ["full"] }
+http-body-util = { version = "0.1" }
+hyper = { version = "1.3", features = ["full"] }
+hyper-util = { version = "0.1", features = ["full"] }
+tokio = { version = "1", features = ["full"] }
 
 [features]
 default = ["internal-logs"]

scripts/test.sh

@@ -13,6 +13,10 @@ cargo test --workspace --all-features --lib
 echo "Running tests for opentelemetry package with --no-default-features"
 cargo test --manifest-path=opentelemetry/Cargo.toml --no-default-features --lib
 
+# Run tests for non-workspace member crate
+echo "Running tests for opentelemetry-prometheus with --all-features"
+(cd opentelemetry-prometheus && cargo test --all-features --lib)
+
 # Run global tracer provider test in single thread
 # //TODO: This tests were not running for a while. Need to find out how to run
 # run them. Using --ignored will run other tests as well, so that cannot be used.