opentelemetry_appender_tracing/
layer.rs

1use opentelemetry::{
2    logs::{AnyValue, LogRecord, Logger, LoggerProvider, Severity},
3    Key,
4};
5use tracing_core::Level;
6#[cfg(feature = "experimental_metadata_attributes")]
7use tracing_core::Metadata;
8#[cfg(feature = "experimental_metadata_attributes")]
9use tracing_log::NormalizeEvent;
10use tracing_subscriber::{registry::LookupSpan, Layer};
11
12/// Visitor to record the fields from the event record.
13struct EventVisitor<'a, LR: LogRecord> {
14    log_record: &'a mut LR,
15}
16
17/// Logs from the log crate have duplicated attributes that we removed here.
18#[cfg(feature = "experimental_metadata_attributes")]
19fn is_duplicated_metadata(field: &'static str) -> bool {
20    field
21        .strip_prefix("log.")
22        .map(|remainder| matches!(remainder, "file" | "line" | "module_path" | "target"))
23        .unwrap_or(false)
24}
25
26#[cfg(feature = "experimental_metadata_attributes")]
27fn get_filename(filepath: &str) -> &str {
28    if let Some((_, filename)) = filepath.rsplit_once('/') {
29        return filename;
30    }
31    if let Some((_, filename)) = filepath.rsplit_once('\\') {
32        return filename;
33    }
34    filepath
35}
36
37impl<'a, LR: LogRecord> EventVisitor<'a, LR> {
38    fn new(log_record: &'a mut LR) -> Self {
39        EventVisitor { log_record }
40    }
41
42    #[cfg(feature = "experimental_metadata_attributes")]
43    fn visit_experimental_metadata(&mut self, meta: &Metadata) {
44        if let Some(module_path) = meta.module_path() {
45            self.log_record.add_attribute(
46                Key::new("code.namespace"),
47                AnyValue::from(module_path.to_owned()),
48            );
49        }
50
51        if let Some(filepath) = meta.file() {
52            self.log_record.add_attribute(
53                Key::new("code.filepath"),
54                AnyValue::from(filepath.to_owned()),
55            );
56            self.log_record.add_attribute(
57                Key::new("code.filename"),
58                AnyValue::from(get_filename(filepath).to_owned()),
59            );
60        }
61
62        if let Some(line) = meta.line() {
63            self.log_record
64                .add_attribute(Key::new("code.lineno"), AnyValue::from(line));
65        }
66    }
67}
68
69impl<LR: LogRecord> tracing::field::Visit for EventVisitor<'_, LR> {
70    fn record_debug(&mut self, field: &tracing::field::Field, value: &dyn std::fmt::Debug) {
71        #[cfg(feature = "experimental_metadata_attributes")]
72        if is_duplicated_metadata(field.name()) {
73            return;
74        }
75        if field.name() == "message" {
76            self.log_record.set_body(format!("{value:?}").into());
77        } else {
78            self.log_record
79                .add_attribute(Key::new(field.name()), AnyValue::from(format!("{value:?}")));
80        }
81    }
82
83    fn record_error(
84        &mut self,
85        _field: &tracing_core::Field,
86        value: &(dyn std::error::Error + 'static),
87    ) {
88        self.log_record.add_attribute(
89            Key::new("exception.message"),
90            AnyValue::from(value.to_string()),
91        );
92        // No ability to get exception.stacktrace or exception.type from the error today.
93    }
94
95    fn record_bytes(&mut self, field: &tracing_core::Field, value: &[u8]) {
96        self.log_record
97            .add_attribute(Key::new(field.name()), AnyValue::from(value));
98    }
99
100    fn record_str(&mut self, field: &tracing_core::Field, value: &str) {
101        #[cfg(feature = "experimental_metadata_attributes")]
102        if is_duplicated_metadata(field.name()) {
103            return;
104        }
105        //TODO: Fix heap allocation. Check if lifetime of &str can be used
106        // to optimize sync exporter scenario.
107        if field.name() == "message" {
108            self.log_record.set_body(AnyValue::from(value.to_owned()));
109        } else {
110            self.log_record
111                .add_attribute(Key::new(field.name()), AnyValue::from(value.to_owned()));
112        }
113    }
114
115    fn record_bool(&mut self, field: &tracing_core::Field, value: bool) {
116        self.log_record
117            .add_attribute(Key::new(field.name()), AnyValue::from(value));
118    }
119
120    fn record_f64(&mut self, field: &tracing::field::Field, value: f64) {
121        self.log_record
122            .add_attribute(Key::new(field.name()), AnyValue::from(value));
123    }
124
125    fn record_i64(&mut self, field: &tracing::field::Field, value: i64) {
126        #[cfg(feature = "experimental_metadata_attributes")]
127        if is_duplicated_metadata(field.name()) {
128            return;
129        }
130        self.log_record
131            .add_attribute(Key::new(field.name()), AnyValue::from(value));
132    }
133
134    // TODO: We might need to do similar for record_i128,record_u128 too
135    // to avoid stringification, unless needed.
136    fn record_u64(&mut self, field: &tracing::field::Field, value: u64) {
137        #[cfg(feature = "experimental_metadata_attributes")]
138        if is_duplicated_metadata(field.name()) {
139            return;
140        }
141        if let Ok(signed) = i64::try_from(value) {
142            self.log_record
143                .add_attribute(Key::new(field.name()), AnyValue::from(signed));
144        } else {
145            self.log_record
146                .add_attribute(Key::new(field.name()), AnyValue::from(format!("{value:?}")));
147        }
148    }
149
150    fn record_i128(&mut self, field: &tracing::field::Field, value: i128) {
151        #[cfg(feature = "experimental_metadata_attributes")]
152        if is_duplicated_metadata(field.name()) {
153            return;
154        }
155        if let Ok(signed) = i64::try_from(value) {
156            self.log_record
157                .add_attribute(Key::new(field.name()), AnyValue::from(signed));
158        } else {
159            self.log_record
160                .add_attribute(Key::new(field.name()), AnyValue::from(format!("{value:?}")));
161        }
162    }
163
164    fn record_u128(&mut self, field: &tracing::field::Field, value: u128) {
165        #[cfg(feature = "experimental_metadata_attributes")]
166        if is_duplicated_metadata(field.name()) {
167            return;
168        }
169        if let Ok(signed) = i64::try_from(value) {
170            self.log_record
171                .add_attribute(Key::new(field.name()), AnyValue::from(signed));
172        } else {
173            self.log_record
174                .add_attribute(Key::new(field.name()), AnyValue::from(format!("{value:?}")));
175        }
176    }
177
178    // TODO: Remaining field types from AnyValue : Bytes, ListAny, Boolean
179}
180
181pub struct OpenTelemetryTracingBridge<P, L>
182where
183    P: LoggerProvider<Logger = L> + Send + Sync,
184    L: Logger + Send + Sync,
185{
186    logger: L,
187    _phantom: std::marker::PhantomData<P>, // P is not used.
188}
189
190impl<P, L> OpenTelemetryTracingBridge<P, L>
191where
192    P: LoggerProvider<Logger = L> + Send + Sync,
193    L: Logger + Send + Sync,
194{
195    pub fn new(provider: &P) -> Self {
196        OpenTelemetryTracingBridge {
197            // Using empty scope name.
198            // The name/version of this library itself can be added
199            // as a Scope attribute, once a semantic convention is
200            // defined for the same.
201            // See https://github.com/open-telemetry/semantic-conventions/issues/1550
202            logger: provider.logger(""),
203            _phantom: Default::default(),
204        }
205    }
206}
207
208impl<S, P, L> Layer<S> for OpenTelemetryTracingBridge<P, L>
209where
210    S: tracing::Subscriber + for<'a> LookupSpan<'a>,
211    P: LoggerProvider<Logger = L> + Send + Sync + 'static,
212    L: Logger + Send + Sync + 'static,
213{
214    fn on_event(
215        &self,
216        event: &tracing::Event<'_>,
217        _ctx: tracing_subscriber::layer::Context<'_, S>,
218    ) {
219        let metadata = event.metadata();
220        let severity = severity_of_level(metadata.level());
221        let target = metadata.target();
222        let name = metadata.name();
223        #[cfg(feature = "spec_unstable_logs_enabled")]
224        if !self.logger.event_enabled(severity, target, Some(name)) {
225            // TODO: See if we need internal logs or track the count.
226            return;
227        }
228
229        #[cfg(feature = "experimental_metadata_attributes")]
230        let normalized_meta = event.normalized_metadata();
231
232        #[cfg(feature = "experimental_metadata_attributes")]
233        let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
234
235        let mut log_record = self.logger.create_log_record();
236
237        log_record.set_target(target);
238        log_record.set_event_name(name);
239        log_record.set_severity_number(severity);
240        log_record.set_severity_text(metadata.level().as_str());
241        let mut visitor = EventVisitor::new(&mut log_record);
242        #[cfg(feature = "experimental_metadata_attributes")]
243        visitor.visit_experimental_metadata(meta);
244        // Visit fields.
245        event.record(&mut visitor);
246
247        #[cfg(feature = "experimental_use_tracing_span_context")]
248        if let Some(span) = _ctx.event_span(event) {
249            use tracing_opentelemetry::OtelData;
250            if let Some(otd) = span.extensions().get::<OtelData>() {
251                if let Some(span_id) = otd.span_id() {
252                    // Try the trace_id of the current span first;
253                    // If it is not already established (still in the Builder state), try finding the root span.
254                    let opt_trace_id = otd.trace_id().or_else(|| {
255                        span.scope().last().and_then(|root_span| {
256                            root_span
257                                .extensions()
258                                .get::<OtelData>()
259                                .and_then(|root_otd| root_otd.trace_id())
260                        })
261                    });
262                    if let Some(trace_id) = opt_trace_id {
263                        // Unable to reliably obtain TraceFlags (old implementation also passed None)
264                        log_record.set_trace_context(trace_id, span_id, None);
265                    }
266                }
267            }
268        }
269
270        //emit record
271        self.logger.emit(log_record);
272    }
273}
274
275const fn severity_of_level(level: &Level) -> Severity {
276    match *level {
277        Level::TRACE => Severity::Trace,
278        Level::DEBUG => Severity::Debug,
279        Level::INFO => Severity::Info,
280        Level::WARN => Severity::Warn,
281        Level::ERROR => Severity::Error,
282    }
283}
284
285#[cfg(test)]
286mod tests {
287    use crate::layer;
288    use opentelemetry::logs::Severity;
289    use opentelemetry::trace::TracerProvider;
290    use opentelemetry::trace::{TraceContextExt, TraceFlags, Tracer};
291    use opentelemetry::InstrumentationScope;
292    use opentelemetry::{logs::AnyValue, Key};
293    use opentelemetry_sdk::error::{OTelSdkError, OTelSdkResult};
294    use opentelemetry_sdk::logs::{InMemoryLogExporter, LogProcessor};
295    use opentelemetry_sdk::logs::{SdkLogRecord, SdkLoggerProvider};
296    use opentelemetry_sdk::trace::{Sampler, SdkTracerProvider};
297    use tracing::error;
298    use tracing_subscriber::prelude::__tracing_subscriber_SubscriberExt;
299    use tracing_subscriber::Layer;
300
301    pub fn attributes_contains(log_record: &SdkLogRecord, key: &Key, value: &AnyValue) -> bool {
302        log_record
303            .attributes_iter()
304            .any(|(k, v)| k == key && v == value)
305    }
306
307    #[allow(impl_trait_overcaptures)] // can only be fixed with Rust 1.82+
308    fn create_tracing_subscriber(logger_provider: &SdkLoggerProvider) -> impl tracing::Subscriber {
309        let level_filter = tracing_subscriber::filter::LevelFilter::WARN; // Capture WARN and ERROR levels
310        let layer =
311            layer::OpenTelemetryTracingBridge::new(logger_provider).with_filter(level_filter); // No filter based on target, only based on log level
312
313        tracing_subscriber::registry().with(layer)
314    }
315
316    // cargo test --features=testing
317    #[test]
318    fn tracing_appender_standalone() {
319        // Arrange
320        let exporter: InMemoryLogExporter = InMemoryLogExporter::default();
321        let logger_provider = SdkLoggerProvider::builder()
322            .with_simple_exporter(exporter.clone())
323            .build();
324
325        let subscriber = create_tracing_subscriber(&logger_provider);
326
327        // avoiding setting tracing subscriber as global as that does not
328        // play well with unit tests.
329        let _guard = tracing::subscriber::set_default(subscriber);
330
331        // Act
332        let small_u64value: u64 = 42;
333        let big_u64value: u64 = u64::MAX;
334        let small_usizevalue: usize = 42;
335        let big_usizevalue: usize = usize::MAX;
336        let small_u128value: u128 = 42;
337        let big_u128value: u128 = u128::MAX;
338        let small_i128value: i128 = 42;
339        let big_i128value: i128 = i128::MAX;
340        error!(name: "my-event-name", target: "my-system", event_id = 20, bytes = &b"abc"[..], error = &OTelSdkError::AlreadyShutdown as &dyn std::error::Error, small_u64value, big_u64value, small_usizevalue, big_usizevalue, small_u128value, big_u128value, small_i128value, big_i128value, user_name = "otel", user_email = "otel@opentelemetry.io");
341        assert!(logger_provider.force_flush().is_ok());
342
343        // Assert TODO: move to helper methods
344        let exported_logs = exporter
345            .get_emitted_logs()
346            .expect("Logs are expected to be exported.");
347        assert_eq!(exported_logs.len(), 1);
348        let log = exported_logs
349            .first()
350            .expect("Atleast one log is expected to be present.");
351
352        // Validate common fields
353        assert_eq!(log.instrumentation.name(), "");
354        assert_eq!(log.record.severity_number(), Some(Severity::Error));
355        // Validate target
356        assert_eq!(
357            log.record.target().expect("target is expected").to_string(),
358            "my-system"
359        );
360        // Validate event name
361        assert_eq!(
362            log.record.event_name().expect("event_name is expected"),
363            "my-event-name"
364        );
365
366        // Validate trace context is none.
367        assert!(log.record.trace_context().is_none());
368
369        // Validate attributes
370        #[cfg(not(feature = "experimental_metadata_attributes"))]
371        assert_eq!(log.record.attributes_iter().count(), 13);
372        #[cfg(feature = "experimental_metadata_attributes")]
373        assert_eq!(log.record.attributes_iter().count(), 17);
374        assert!(attributes_contains(
375            &log.record,
376            &Key::new("event_id"),
377            &AnyValue::Int(20)
378        ));
379        assert!(attributes_contains(
380            &log.record,
381            &Key::new("user_name"),
382            &AnyValue::String("otel".into())
383        ));
384        assert!(attributes_contains(
385            &log.record,
386            &Key::new("user_email"),
387            &AnyValue::String("otel@opentelemetry.io".into())
388        ));
389        assert!(attributes_contains(
390            &log.record,
391            &Key::new("exception.message"),
392            &AnyValue::String(OTelSdkError::AlreadyShutdown.to_string().into())
393        ));
394        assert!(attributes_contains(
395            &log.record,
396            &Key::new("small_u64value"),
397            &AnyValue::Int(42.into())
398        ));
399        assert!(attributes_contains(
400            &log.record,
401            &Key::new("big_u64value"),
402            &AnyValue::String(format!("{}", u64::MAX).into())
403        ));
404        assert!(attributes_contains(
405            &log.record,
406            &Key::new("small_usizevalue"),
407            &AnyValue::Int(42.into())
408        ));
409        assert!(attributes_contains(
410            &log.record,
411            &Key::new("big_usizevalue"),
412            &AnyValue::String(format!("{}", u64::MAX).into())
413        ));
414        assert!(attributes_contains(
415            &log.record,
416            &Key::new("small_u128value"),
417            &AnyValue::Int(42.into())
418        ));
419        assert!(attributes_contains(
420            &log.record,
421            &Key::new("big_u128value"),
422            &AnyValue::String(format!("{}", u128::MAX).into())
423        ));
424        assert!(attributes_contains(
425            &log.record,
426            &Key::new("small_i128value"),
427            &AnyValue::Int(42.into())
428        ));
429        assert!(attributes_contains(
430            &log.record,
431            &Key::new("big_i128value"),
432            &AnyValue::String(format!("{}", i128::MAX).into())
433        ));
434        assert!(attributes_contains(
435            &log.record,
436            &Key::new("bytes"),
437            &AnyValue::Bytes(Box::new(b"abc".to_vec()))
438        ));
439        #[cfg(feature = "experimental_metadata_attributes")]
440        {
441            assert!(attributes_contains(
442                &log.record,
443                &Key::new("code.filename"),
444                &AnyValue::String("layer.rs".into())
445            ));
446            assert!(attributes_contains(
447                &log.record,
448                &Key::new("code.namespace"),
449                &AnyValue::String("opentelemetry_appender_tracing::layer::tests".into())
450            ));
451            // The other 3 experimental_metadata_attributes are too unstable to check their value.
452            // Ex.: The path will be different on a Windows and Linux machine.
453            // Ex.: The line can change easily if someone makes changes in this source file.
454            let attributes_key: Vec<Key> = log
455                .record
456                .attributes_iter()
457                .map(|(key, _)| key.clone())
458                .collect();
459            assert!(attributes_key.contains(&Key::new("code.filepath")));
460            assert!(attributes_key.contains(&Key::new("code.lineno")));
461            assert!(!attributes_key.contains(&Key::new("log.target")));
462        }
463
464        // Test when target, eventname are not explicitly provided
465        exporter.reset();
466        error!(
467            event_id = 20,
468            user_name = "otel",
469            user_email = "otel@opentelemetry.io"
470        );
471        assert!(logger_provider.force_flush().is_ok());
472
473        // Assert TODO: move to helper methods
474        let exported_logs = exporter
475            .get_emitted_logs()
476            .expect("Logs are expected to be exported.");
477        assert_eq!(exported_logs.len(), 1);
478        let log = exported_logs
479            .first()
480            .expect("Atleast one log is expected to be present.");
481
482        // Validate target - tracing defaults to module path
483        assert_eq!(
484            log.record.target().expect("target is expected").to_string(),
485            "opentelemetry_appender_tracing::layer::tests"
486        );
487        // Validate event name - tracing defaults to event followed source & line number
488        // Assert is doing "contains" check to avoid tests failing when line number changes.
489        // and also account for the fact that the module path is different on different platforms.
490        // Ex.: The path will be different on a Windows and Linux machine.
491        assert!(log
492            .record
493            .event_name()
494            .expect("event_name is expected")
495            .contains("event opentelemetry-appender-tracing"),);
496    }
497
498    #[test]
499    fn tracing_appender_inside_tracing_context() {
500        // Arrange
501        let exporter: InMemoryLogExporter = InMemoryLogExporter::default();
502        let logger_provider = SdkLoggerProvider::builder()
503            .with_simple_exporter(exporter.clone())
504            .build();
505
506        let subscriber = create_tracing_subscriber(&logger_provider);
507
508        // avoiding setting tracing subscriber as global as that does not
509        // play well with unit tests.
510        let _guard = tracing::subscriber::set_default(subscriber);
511
512        // setup tracing as well.
513        let tracer_provider = SdkTracerProvider::builder()
514            .with_sampler(Sampler::AlwaysOn)
515            .build();
516        let tracer = tracer_provider.tracer("test-tracer");
517
518        // Act
519        let (trace_id_expected, span_id_expected) = tracer.in_span("test-span", |cx| {
520            let trace_id = cx.span().span_context().trace_id();
521            let span_id = cx.span().span_context().span_id();
522
523            // logging is done inside span context.
524            error!(name: "my-event-name", target: "my-system", event_id = 20, user_name = "otel", user_email = "otel@opentelemetry.io");
525            (trace_id, span_id)
526        });
527
528        assert!(logger_provider.force_flush().is_ok());
529
530        // Assert TODO: move to helper methods
531        let exported_logs = exporter
532            .get_emitted_logs()
533            .expect("Logs are expected to be exported.");
534        assert_eq!(exported_logs.len(), 1);
535        let log = exported_logs
536            .first()
537            .expect("Atleast one log is expected to be present.");
538
539        // validate common fields.
540        assert_eq!(log.instrumentation.name(), "");
541        assert_eq!(log.record.severity_number(), Some(Severity::Error));
542        // Validate target
543        assert_eq!(
544            log.record.target().expect("target is expected").to_string(),
545            "my-system"
546        );
547        // Validate event name
548        assert_eq!(
549            log.record.event_name().expect("event_name is expected"),
550            "my-event-name"
551        );
552
553        // validate trace context.
554        assert!(log.record.trace_context().is_some());
555        assert_eq!(
556            log.record.trace_context().unwrap().trace_id,
557            trace_id_expected
558        );
559        assert_eq!(
560            log.record.trace_context().unwrap().span_id,
561            span_id_expected
562        );
563        assert_eq!(
564            log.record.trace_context().unwrap().trace_flags.unwrap(),
565            TraceFlags::SAMPLED
566        );
567
568        // validate attributes.
569        #[cfg(not(feature = "experimental_metadata_attributes"))]
570        assert_eq!(log.record.attributes_iter().count(), 3);
571        #[cfg(feature = "experimental_metadata_attributes")]
572        assert_eq!(log.record.attributes_iter().count(), 7);
573        assert!(attributes_contains(
574            &log.record,
575            &Key::new("event_id"),
576            &AnyValue::Int(20.into())
577        ));
578        assert!(attributes_contains(
579            &log.record,
580            &Key::new("user_name"),
581            &AnyValue::String("otel".into())
582        ));
583        assert!(attributes_contains(
584            &log.record,
585            &Key::new("user_email"),
586            &AnyValue::String("otel@opentelemetry.io".into())
587        ));
588        #[cfg(feature = "experimental_metadata_attributes")]
589        {
590            assert!(attributes_contains(
591                &log.record,
592                &Key::new("code.filename"),
593                &AnyValue::String("layer.rs".into())
594            ));
595            assert!(attributes_contains(
596                &log.record,
597                &Key::new("code.namespace"),
598                &AnyValue::String("opentelemetry_appender_tracing::layer::tests".into())
599            ));
600            // The other 3 experimental_metadata_attributes are too unstable to check their value.
601            // Ex.: The path will be different on a Windows and Linux machine.
602            // Ex.: The line can change easily if someone makes changes in this source file.
603            let attributes_key: Vec<Key> = log
604                .record
605                .attributes_iter()
606                .map(|(key, _)| key.clone())
607                .collect();
608            assert!(attributes_key.contains(&Key::new("code.filepath")));
609            assert!(attributes_key.contains(&Key::new("code.lineno")));
610            assert!(!attributes_key.contains(&Key::new("log.target")));
611        }
612    }
613
614    #[cfg(feature = "experimental_use_tracing_span_context")]
615    #[test]
616    fn tracing_appender_inside_tracing_crate_context() {
617        use opentelemetry::{trace::SpanContext, Context, SpanId, TraceId};
618        use opentelemetry_sdk::trace::InMemorySpanExporterBuilder;
619        use tracing_opentelemetry::OpenTelemetrySpanExt;
620
621        // Arrange
622        let exporter: InMemoryLogExporter = InMemoryLogExporter::default();
623        let logger_provider = SdkLoggerProvider::builder()
624            .with_simple_exporter(exporter.clone())
625            .build();
626
627        // setup tracing layer to compare trace/span IDs against
628        let span_exporter = InMemorySpanExporterBuilder::new().build();
629        let tracer_provider = SdkTracerProvider::builder()
630            .with_simple_exporter(span_exporter.clone())
631            .build();
632        let tracer = tracer_provider.tracer("test-tracer");
633
634        let level_filter = tracing_subscriber::filter::LevelFilter::ERROR;
635        let log_layer =
636            layer::OpenTelemetryTracingBridge::new(&logger_provider).with_filter(level_filter);
637
638        let subscriber = tracing_subscriber::registry()
639            .with(log_layer)
640            .with(tracing_opentelemetry::layer().with_tracer(tracer));
641
642        // Avoiding global subscriber.init() as that does not play well with unit tests.
643        let _guard = tracing::subscriber::set_default(subscriber);
644
645        // Act
646        tracing::error_span!("outer-span").in_scope(|| {
647            error!("first-event");
648
649            tracing::error_span!("inner-span").in_scope(|| {
650                error!("second-event");
651            });
652        });
653
654        assert!(logger_provider.force_flush().is_ok());
655
656        let logs = exporter.get_emitted_logs().expect("No emitted logs");
657        assert_eq!(logs.len(), 2, "Expected 2 logs, got: {logs:?}");
658
659        let spans = span_exporter.get_finished_spans().unwrap();
660        assert_eq!(spans.len(), 2);
661
662        let trace_id = spans[0].span_context.trace_id();
663        assert_eq!(trace_id, spans[1].span_context.trace_id());
664        let inner_span_id = spans[0].span_context.span_id();
665        let outer_span_id = spans[1].span_context.span_id();
666        assert_eq!(outer_span_id, spans[0].parent_span_id);
667
668        let trace_ctx0 = logs[0].record.trace_context().unwrap();
669        let trace_ctx1 = logs[1].record.trace_context().unwrap();
670
671        assert_eq!(trace_ctx0.trace_id, trace_id);
672        assert_eq!(trace_ctx1.trace_id, trace_id);
673        assert_eq!(trace_ctx0.span_id, outer_span_id);
674        assert_eq!(trace_ctx1.span_id, inner_span_id);
675
676        // Set context from remote.
677        let remote_trace_id = TraceId::from(233);
678        let remote_span_id = SpanId::from(2333);
679        let remote_span_context = SpanContext::new(
680            remote_trace_id,
681            remote_span_id,
682            TraceFlags::SAMPLED,
683            true,
684            Default::default(),
685        );
686
687        // Act again.
688        {
689            let parent_context = Context::current().with_remote_span_context(remote_span_context);
690            let outer_span = tracing::error_span!("outer-span");
691            let _ = outer_span.set_parent(parent_context);
692
693            outer_span.in_scope(|| {
694                error!("first-event");
695
696                let inner_span = tracing::error_span!("inner-span");
697                inner_span.in_scope(|| {
698                    error!("second-event");
699                });
700            });
701        }
702
703        assert!(logger_provider.force_flush().is_ok());
704
705        let logs = exporter.get_emitted_logs().expect("No emitted logs");
706        assert_eq!(logs.len(), 4, "Expected 4 logs, got: {logs:?}");
707        let logs = &logs[2..];
708
709        let spans = span_exporter.get_finished_spans().unwrap();
710        assert_eq!(spans.len(), 4);
711        let spans = &spans[2..];
712
713        let trace_id = spans[0].span_context.trace_id();
714        assert_eq!(trace_id, remote_trace_id);
715        assert_eq!(trace_id, spans[1].span_context.trace_id());
716        let inner_span_id = spans[0].span_context.span_id();
717        let outer_span_id = spans[1].span_context.span_id();
718        assert_eq!(outer_span_id, spans[0].parent_span_id);
719
720        let trace_ctx0 = logs[0].record.trace_context().unwrap();
721        let trace_ctx1 = logs[1].record.trace_context().unwrap();
722
723        assert_eq!(trace_ctx0.trace_id, trace_id);
724        assert_eq!(trace_ctx1.trace_id, trace_id);
725        assert_eq!(trace_ctx0.span_id, outer_span_id);
726        assert_eq!(trace_ctx1.span_id, inner_span_id);
727    }
728
729    #[test]
730    fn tracing_appender_standalone_with_tracing_log() {
731        // Arrange
732        let exporter: InMemoryLogExporter = InMemoryLogExporter::default();
733        let logger_provider = SdkLoggerProvider::builder()
734            .with_simple_exporter(exporter.clone())
735            .build();
736
737        let subscriber = create_tracing_subscriber(&logger_provider);
738
739        // avoiding setting tracing subscriber as global as that does not
740        // play well with unit tests.
741        let _guard = tracing::subscriber::set_default(subscriber);
742        drop(tracing_log::LogTracer::init());
743
744        // Act
745        log::error!("log from log crate");
746        assert!(logger_provider.force_flush().is_ok());
747
748        // Assert TODO: move to helper methods
749        let exported_logs = exporter
750            .get_emitted_logs()
751            .expect("Logs are expected to be exported.");
752        assert_eq!(exported_logs.len(), 1);
753        let log = exported_logs
754            .first()
755            .expect("Atleast one log is expected to be present.");
756
757        // Validate common fields
758        assert_eq!(log.instrumentation.name(), "");
759        assert_eq!(log.record.severity_number(), Some(Severity::Error));
760        // Target and EventName from Log crate are "log" and "log event" respectively.
761        // Validate target
762        assert_eq!(
763            log.record.target().expect("target is expected").to_string(),
764            "log"
765        );
766        // Validate event name
767        assert_eq!(
768            log.record.event_name().expect("event_name is expected"),
769            "log event"
770        );
771
772        // Validate trace context is none.
773        assert!(log.record.trace_context().is_none());
774
775        // Attributes can be polluted when we don't use this feature.
776        #[cfg(feature = "experimental_metadata_attributes")]
777        assert_eq!(log.record.attributes_iter().count(), 4);
778
779        #[cfg(feature = "experimental_metadata_attributes")]
780        {
781            assert!(attributes_contains(
782                &log.record,
783                &Key::new("code.filename"),
784                &AnyValue::String("layer.rs".into())
785            ));
786            assert!(attributes_contains(
787                &log.record,
788                &Key::new("code.namespace"),
789                &AnyValue::String("opentelemetry_appender_tracing::layer::tests".into())
790            ));
791            // The other 3 experimental_metadata_attributes are too unstable to check their value.
792            // Ex.: The path will be different on a Windows and Linux machine.
793            // Ex.: The line can change easily if someone makes changes in this source file.
794            let attributes_key: Vec<Key> = log
795                .record
796                .attributes_iter()
797                .map(|(key, _)| key.clone())
798                .collect();
799            assert!(attributes_key.contains(&Key::new("code.filepath")));
800            assert!(attributes_key.contains(&Key::new("code.lineno")));
801            assert!(!attributes_key.contains(&Key::new("log.target")));
802        }
803    }
804
805    #[test]
806    fn tracing_appender_inside_tracing_context_with_tracing_log() {
807        // Arrange
808        let exporter: InMemoryLogExporter = InMemoryLogExporter::default();
809        let logger_provider = SdkLoggerProvider::builder()
810            .with_simple_exporter(exporter.clone())
811            .build();
812
813        let subscriber = create_tracing_subscriber(&logger_provider);
814
815        // avoiding setting tracing subscriber as global as that does not
816        // play well with unit tests.
817        let _guard = tracing::subscriber::set_default(subscriber);
818        drop(tracing_log::LogTracer::init());
819
820        // setup tracing as well.
821        let tracer_provider = SdkTracerProvider::builder()
822            .with_sampler(Sampler::AlwaysOn)
823            .build();
824        let tracer = tracer_provider.tracer("test-tracer");
825
826        // Act
827        let (trace_id_expected, span_id_expected) = tracer.in_span("test-span", |cx| {
828            let trace_id = cx.span().span_context().trace_id();
829            let span_id = cx.span().span_context().span_id();
830
831            // logging is done inside span context.
832            log::error!(target: "my-system", "log from log crate");
833            (trace_id, span_id)
834        });
835
836        assert!(logger_provider.force_flush().is_ok());
837
838        // Assert TODO: move to helper methods
839        let exported_logs = exporter
840            .get_emitted_logs()
841            .expect("Logs are expected to be exported.");
842        assert_eq!(exported_logs.len(), 1);
843        let log = exported_logs
844            .first()
845            .expect("Atleast one log is expected to be present.");
846
847        // validate common fields.
848        assert_eq!(log.instrumentation.name(), "");
849        assert_eq!(log.record.severity_number(), Some(Severity::Error));
850
851        // validate trace context.
852        assert!(log.record.trace_context().is_some());
853        assert_eq!(
854            log.record.trace_context().unwrap().trace_id,
855            trace_id_expected
856        );
857        assert_eq!(
858            log.record.trace_context().unwrap().span_id,
859            span_id_expected
860        );
861        assert_eq!(
862            log.record.trace_context().unwrap().trace_flags.unwrap(),
863            TraceFlags::SAMPLED
864        );
865
866        for attribute in log.record.attributes_iter() {
867            println!("key: {:?}, value: {:?}", attribute.0, attribute.1);
868        }
869
870        // Attributes can be polluted when we don't use this feature.
871        #[cfg(feature = "experimental_metadata_attributes")]
872        assert_eq!(log.record.attributes_iter().count(), 4);
873
874        #[cfg(feature = "experimental_metadata_attributes")]
875        {
876            assert!(attributes_contains(
877                &log.record,
878                &Key::new("code.filename"),
879                &AnyValue::String("layer.rs".into())
880            ));
881            assert!(attributes_contains(
882                &log.record,
883                &Key::new("code.namespace"),
884                &AnyValue::String("opentelemetry_appender_tracing::layer::tests".into())
885            ));
886            // The other 3 experimental_metadata_attributes are too unstable to check their value.
887            // Ex.: The path will be different on a Windows and Linux machine.
888            // Ex.: The line can change easily if someone makes changes in this source file.
889            let attributes_key: Vec<Key> = log
890                .record
891                .attributes_iter()
892                .map(|(key, _)| key.clone())
893                .collect();
894            assert!(attributes_key.contains(&Key::new("code.filepath")));
895            assert!(attributes_key.contains(&Key::new("code.lineno")));
896            assert!(!attributes_key.contains(&Key::new("log.target")));
897        }
898    }
899
900    #[derive(Debug)]
901    struct LogProcessorWithIsEnabled {
902        severity_level: Severity,
903        name: String,
904        target: String,
905    }
906
907    impl LogProcessorWithIsEnabled {
908        fn new(severity_level: Severity, name: String, target: String) -> Self {
909            LogProcessorWithIsEnabled {
910                severity_level,
911                name,
912                target,
913            }
914        }
915    }
916
917    impl LogProcessor for LogProcessorWithIsEnabled {
918        fn emit(&self, _record: &mut SdkLogRecord, _scope: &InstrumentationScope) {
919            // no-op
920        }
921
922        #[cfg(feature = "spec_unstable_logs_enabled")]
923        fn event_enabled(&self, level: Severity, target: &str, name: Option<&str>) -> bool {
924            // assert that passed in arguments are same as the ones set in the test.
925            assert_eq!(self.severity_level, level);
926            assert_eq!(self.target, target);
927            assert_eq!(
928                self.name,
929                name.expect("name is expected from tracing appender")
930            );
931            true
932        }
933
934        fn force_flush(&self) -> OTelSdkResult {
935            Ok(())
936        }
937    }
938
939    #[cfg(feature = "spec_unstable_logs_enabled")]
940    #[test]
941    fn is_enabled() {
942        // Arrange
943        let logger_provider = SdkLoggerProvider::builder()
944            .with_log_processor(LogProcessorWithIsEnabled::new(
945                Severity::Error,
946                "my-event-name".to_string(),
947                "my-system".to_string(),
948            ))
949            .build();
950
951        let subscriber = create_tracing_subscriber(&logger_provider);
952
953        // avoiding setting tracing subscriber as global as that does not
954        // play well with unit tests.
955        let _guard = tracing::subscriber::set_default(subscriber);
956
957        // Name, Target and Severity are expected to be passed to the IsEnabled check
958        // The validation is done in the LogProcessorWithIsEnabled struct.
959        error!(name: "my-event-name", target: "my-system", event_id = 20, user_name = "otel", user_email = "otel@opentelemetry.io");
960    }
961}
opentelemetry_appender_tracing/layer.rs

opentelemetry_appender_tracing/
layer.rs
