Skip to content

Commit

Permalink
fix: Fix Logger scope in Tracing Appender (#2735)
Browse files Browse the repository at this point in the history
  • Loading branch information
cijothomas authored Mar 4, 2025
1 parent 5a77fb2 commit f15a337
Show file tree
Hide file tree
Showing 3 changed files with 96 additions and 14 deletions.
13 changes: 13 additions & 0 deletions docs/design/logs.md
Original file line number Diff line number Diff line change
Expand Up @@ -296,6 +296,19 @@ convey that decision back to logger, allowing appender to avoid even the cost of
creating a `LogRecord` in the first place if there is no listener. This check is
done for each log emission, and can react dynamically to changes in interest, by
enabling/disabling ETW/user-event listener.
5. `tracing` has a notion of "target", which is expected to be mapped to OTel's
concept of Instrumentation Scope for Logs, when `OpenTelemetry-Tracing-Appender`
bridges `tracing` to OpenTelemetry. Since scopes are tied to Loggers, a naive
approach would require creating a separate logger for each unique target. This
would necessitate an RWLock-protected HashMap lookup, introducing contention and
reducing throughput. To avoid this, `OpenTelemetry-Tracing-Appender` instead
stores the target directly in the LogRecord as a top-level field, ensuring fast
access in the hot path. Components processing the LogRecord can retrieve the
target via LogRecord.target(), treating it as the scope. The OTLP Exporter
already handles this automatically, so end-users will see “target” reflected in
the Instrumentation Scope. An alternative design would be to use thread-local
HashMaps - but it can cause increased memory usage, as there can be 100s of
unique targets. (because `tracing` defaults to using module path as target).

### Perf test - benchmarks

Expand Down
7 changes: 7 additions & 0 deletions opentelemetry-appender-tracing/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,13 @@ simple string, but require format arguments as in the below example.
error!(name: "my-event-name", target: "my-system", event_id = 20, user_name = "otel", user_email = "[email protected]", "This is an example message with format arguments {} and {}", "foo", "bar");
```

Fixes [2658](https://github.com/open-telemetry/opentelemetry-rust/issues/2658)
InstrumentationScope(Logger) used by the appender now uses an empty ("") named
Logger. Previously, a Logger with name and version of the crate was used.
Receivers (processors, exporters) are expected to use `LogRecord.target()` as
scope name. This is already done in OTLP Exporters, so this change should be
transparent to most users.

## 0.28.1

Released 2025-Feb-12
Expand Down
90 changes: 76 additions & 14 deletions opentelemetry-appender-tracing/src/layer.rs
Original file line number Diff line number Diff line change
@@ -1,17 +1,14 @@
use opentelemetry::{
logs::{AnyValue, LogRecord, Logger, LoggerProvider, Severity},
InstrumentationScope, Key,
Key,
};
use std::borrow::Cow;
use tracing_core::Level;
#[cfg(feature = "experimental_metadata_attributes")]
use tracing_core::Metadata;
#[cfg(feature = "experimental_metadata_attributes")]
use tracing_log::NormalizeEvent;
use tracing_subscriber::{registry::LookupSpan, Layer};

const INSTRUMENTATION_LIBRARY_NAME: &str = "opentelemetry-appender-tracing";

/// Visitor to record the fields from the event record.
struct EventVisitor<'a, LR: LogRecord> {
log_record: &'a mut LR,
Expand Down Expand Up @@ -135,12 +132,13 @@ where
L: Logger + Send + Sync,
{
pub fn new(provider: &P) -> Self {
let scope = InstrumentationScope::builder(INSTRUMENTATION_LIBRARY_NAME)
.with_version(Cow::Borrowed(env!("CARGO_PKG_VERSION")))
.build();

OpenTelemetryTracingBridge {
logger: provider.logger_with_scope(scope),
// Using empty scope name.
// The name/version of this library itself can be added
// as a Scope attribute, once a semantic convention is
// defined for the same.
// See https://github.com/open-telemetry/semantic-conventions/issues/1550
logger: provider.logger(""),
_phantom: Default::default(),
}
}
Expand Down Expand Up @@ -349,8 +347,18 @@ mod tests {
.expect("Atleast one log is expected to be present.");

// Validate common fields
assert_eq!(log.instrumentation.name(), "opentelemetry-appender-tracing");
assert_eq!(log.instrumentation.name(), "");
assert_eq!(log.record.severity_number(), Some(Severity::Error));
// Validate target
assert_eq!(
log.record.target().expect("target is expected").to_string(),
"my-system"
);
// Validate event name
assert_eq!(
log.record.event_name().expect("event_name is expected"),
"my-event-name"
);

// Validate trace context is none.
assert!(log.record.trace_context().is_none());
Expand Down Expand Up @@ -399,6 +407,39 @@ mod tests {
assert!(attributes_key.contains(&Key::new("code.lineno")));
assert!(!attributes_key.contains(&Key::new("log.target")));
}

// Test when target, eventname are not explicitly provided
exporter.reset();
error!(
event_id = 20,
user_name = "otel",
user_email = "[email protected]"
);
assert!(logger_provider.force_flush().is_ok());

// Assert TODO: move to helper methods
let exported_logs = exporter
.get_emitted_logs()
.expect("Logs are expected to be exported.");
assert_eq!(exported_logs.len(), 1);
let log = exported_logs
.first()
.expect("Atleast one log is expected to be present.");

// Validate target - tracing defaults to module path
assert_eq!(
log.record.target().expect("target is expected").to_string(),
"opentelemetry_appender_tracing::layer::tests"
);
// Validate event name - tracing defaults to event followed source & line number
// Assert is doing "contains" check to avoid tests failing when line number changes.
// and also account for the fact that the module path is different on different platforms.
// Ex.: The path will be different on a Windows and Linux machine.
assert!(log
.record
.event_name()
.expect("event_name is expected")
.contains("event opentelemetry-appender-tracing"),);
}

#[test]
Expand Down Expand Up @@ -443,8 +484,18 @@ mod tests {
.expect("Atleast one log is expected to be present.");

// validate common fields.
assert_eq!(log.instrumentation.name(), "opentelemetry-appender-tracing");
assert_eq!(log.instrumentation.name(), "");
assert_eq!(log.record.severity_number(), Some(Severity::Error));
// Validate target
assert_eq!(
log.record.target().expect("target is expected").to_string(),
"my-system"
);
// Validate event name
assert_eq!(
log.record.event_name().expect("event_name is expected"),
"my-event-name"
);

// validate trace context.
assert!(log.record.trace_context().is_some());
Expand Down Expand Up @@ -584,7 +635,7 @@ mod tests {
drop(tracing_log::LogTracer::init());

// Act
log::error!(target: "my-system", "log from log crate");
log::error!("log from log crate");
assert!(logger_provider.force_flush().is_ok());

// Assert TODO: move to helper methods
Expand All @@ -597,8 +648,19 @@ mod tests {
.expect("Atleast one log is expected to be present.");

// Validate common fields
assert_eq!(log.instrumentation.name(), "opentelemetry-appender-tracing");
assert_eq!(log.instrumentation.name(), "");
assert_eq!(log.record.severity_number(), Some(Severity::Error));
// Target and EventName from Log crate are "log" and "log event" respectively.
// Validate target
assert_eq!(
log.record.target().expect("target is expected").to_string(),
"log"
);
// Validate event name
assert_eq!(
log.record.event_name().expect("event_name is expected"),
"log event"
);

// Validate trace context is none.
assert!(log.record.trace_context().is_none());
Expand Down Expand Up @@ -676,7 +738,7 @@ mod tests {
.expect("Atleast one log is expected to be present.");

// validate common fields.
assert_eq!(log.instrumentation.name(), "opentelemetry-appender-tracing");
assert_eq!(log.instrumentation.name(), "");
assert_eq!(log.record.severity_number(), Some(Severity::Error));

// validate trace context.
Expand Down

0 comments on commit f15a337

Please sign in to comment.