appender-tracing: Include trace ID and span ID in logs when nested in…

… spans

Cargo.toml

@@ -51,3 +51,8 @@ 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 }
+
+[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.
+- Include trace_id & span_id when logging from inside a tracing span
 
 
 ## 0.27.0

opentelemetry-appender-tracing/Cargo.toml

@@ -13,10 +13,12 @@ rust-version = "1.75.0"
 [dependencies]
 log = { workspace = true, optional = true }
 opentelemetry = { version = "0.27", path = "../opentelemetry", features = ["logs"] }
+opentelemetry_sdk = { version = "0.27", path = "../opentelemetry-sdk", features = ["logs"]  }
 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" }
 
 [dev-dependencies]
 log = { workspace = true }

opentelemetry-appender-tracing/src/layer.rs

@@ -8,7 +8,8 @@ use tracing_core::Level;
 use tracing_core::Metadata;
 #[cfg(feature = "experimental_metadata_attributes")]
 use tracing_log::NormalizeEvent;
-use tracing_subscriber::Layer;
+use tracing_opentelemetry::OtelData;
+use tracing_subscriber::{registry::LookupSpan, Layer};
 
 const INSTRUMENTATION_LIBRARY_NAME: &str = "opentelemetry-appender-tracing";
 
@@ -149,15 +150,11 @@ 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,
 {
-    fn on_event(
-        &self,
-        event: &tracing::Event<'_>,
-        _ctx: tracing_subscriber::layer::Context<'_, S>,
-    ) {
+    fn on_event(&self, event: &tracing::Event<'_>, ctx: tracing_subscriber::layer::Context<'_, S>) {
         #[cfg(feature = "experimental_metadata_attributes")]
         let normalized_meta = event.normalized_metadata();
 
@@ -180,6 +177,24 @@ where
         // Visit fields.
         event.record(&mut visitor);
 
+        if let Some(span) = ctx.event_span(event) {
+            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);
     }
@@ -217,6 +232,7 @@ mod tests {
     use opentelemetry_sdk::export::logs::{LogBatch, LogExporter};
     use opentelemetry_sdk::logs::{LogRecord, LogResult, LoggerProvider};
     use opentelemetry_sdk::testing::logs::InMemoryLogExporter;
+    use opentelemetry_sdk::testing::trace::InMemorySpanExporterBuilder;
     use opentelemetry_sdk::trace::{Sampler, TracerProvider};
     use tracing::{error, warn};
     use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt;
@@ -491,6 +507,64 @@ mod tests {
         }
     }
 
+    #[test]
+    fn tracing_appender_inside_tracing_crate_context() {
+        // 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