Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
Merged
Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
17 commits
Select commit Hold shift + click to select a range
fb2af02
appender-tracing: Include trace ID and span ID in logs when nested in…
dylanahsmith Dec 13, 2024
d08b480
appender-tracing: Make tracing-opentelemetry integration optional
dylanahsmith Dec 17, 2024
69b467a
Merge branch 'main' into appender-tracing-fix-trace-context
TommyCpp Dec 17, 2024
c6e1141
Make the new feature experimental
dylanahsmith Dec 17, 2024
12cf399
appender-tracing: Remove undesired dependency on opentelemetry_sdk
dylanahsmith Dec 17, 2024
750df51
s/experimental-use-tracing-span-context/experimental_use_tracing_span…
dylanahsmith Dec 18, 2024
319bed7
Merge branch 'main' into appender-tracing-fix-trace-context
lalitb Dec 19, 2024
3146dfb
Merge branch 'main' into appender-tracing-fix-trace-context
lalitb Jan 12, 2025
f7f2e16
Merge branch 'main' into appender-tracing-fix-trace-context
lalitb Jan 21, 2025
80741cd
Remove opentelemetry-prometheus as a workspace member
dylanahsmith Jan 22, 2025
3aa5bdf
Merge branch 'main' into appender-tracing-fix-trace-context
cijothomas Jan 23, 2025
d0b94ce
Merge branch 'main' into appender-tracing-fix-trace-context
lalitb Jan 23, 2025
a53f3fc
Link tracing crate in new changelog entry
dylanahsmith Jan 24, 2025
99580f8
Merge branch 'main' into appender-tracing-fix-trace-context
dylanahsmith Jan 24, 2025
50b549a
Add a comment for the [patch.crates-io] Cargo.toml section
dylanahsmith Jan 24, 2025
260df21
Merge branch 'main' into appender-tracing-fix-trace-context
cijothomas Jan 24, 2025
bd23f55
Merge branch 'main' into appender-tracing-fix-trace-context
cijothomas Jan 25, 2025
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
5 changes: 5 additions & 0 deletions Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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]
dylanahsmith marked this conversation as resolved.
Show resolved Hide resolved
opentelemetry = { path = "opentelemetry" }
opentelemetry_sdk = { path = "opentelemetry-sdk" }
opentelemetry-stdout = { path = "opentelemetry-stdout" }
cijothomas marked this conversation as resolved.
Show resolved Hide resolved
1 change: 1 addition & 0 deletions opentelemetry-appender-tracing/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 4 additions & 0 deletions opentelemetry-appender-tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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"] }
dylanahsmith marked this conversation as resolved.
Show resolved Hide resolved
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 }
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Will there be a conflict if the application uses version 0.29 of tracing-opentelemetry, while the appender depends on version 0.28 as specified in this configuration?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

tracing-opentelemetry v0.29 hasn't been released, but I think I see what you are getting at.

tracing-opentelemetry v0.28 (latest release) depends on opentelemetry v0.27, so won't be compatible with opentelemetry v0.28 when it is released. It looks like typically all the opentelemetry crates would be bumped together so there is a version of all these crates that are compatible with each other. However, this means the point at which opentelemetry-appender-tracing v0.28 would be released there wouldn't be a compatible version of tracing-opentelemetry without coordination with that external crate.

Given that this is an experimental feature, I'm guessing it doesn't make sense to wait for tracing-opentelemetry v0.29 to be released before releasing opentelemetry-appender-tracing.

Removing the version constraint would probably work in practice with these unstable versions given that the constraint on opentelemetry crates should ensure the correct version is used. Although, potentially tracing-opentelemetry could introduce a breaking change that is incompatible with opentelemetry-appender-tracing ithout changing the opentelemetry v0.x version that it depends on, which I think would result in the incompatible version of tracing-opentelemetry to be chosen to use by cargo when a compatible version does exist.

I think the simplest thing to do for now (while things are unstable) when releasing a new v0.x version of opentelemetry crates would be to just optimistically bump the version of this optional tracing-opentelemetry dependency to its next v0.y version. E.g. when releasing opentelemetry v0.28.0, depend on tracing-opentelemetry v0.29, so that it can be made compatible with opentelemetry-appender-tracing without any further changes to opentelemetry-appender-tracing. If tracing-opentelemetry v0.29.0 isn't compatible, then v0.28.1 can be released of opentelemetry-appender-tracing could be released fixing this feature. However, it also won't result in an incompatible v0.30 version of tracing-opentelemetry being used when v0.29 is already working with this feature.

Functionally, you could think of a release of a new v0.x version of opentelemetry crates (including opentelemetry-appender-tracing) as removing this feature, then automatically reintroducing the new feature when the next v0.y version of tracing-opentelemetry is made. This could be done manually, which would allow for extra testing after the v0.y release of tracing-opentelemetry is made, but it just seems like it introduces unnecessary work and complicates the opentelemetry-appender-tracing release process.

Once things stabilize, this could be coordinated more carefully between opentelemetry-appender-tracing & tracing-opentelemetry using RC releases, such that the new major version of opentelemetry-appender-tracing is made compatible with a RC version of tracing-opentelemetry.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @dylanahsmith. I agree that optimistically bumping the version of tracing-opentelemetry to the next v0.y (e.g., v0.29 when releasing opentelemetry v0.28) seems like a practical approach for now, given the experimental nature of the feature. If compatibility issues arise, a quick patch release can address them.


[dev-dependencies]
log = { workspace = true }
Expand All @@ -32,8 +34,10 @@ tokio = { workspace = true, features = ["full"]}
pprof = { version = "0.13", features = ["flamegraph", "criterion"] }

[features]
default = ["tracing"]
experimental_metadata_attributes = ["dep:tracing-log"]
spec_unstable_logs_enabled = ["opentelemetry/spec_unstable_logs_enabled"]
tracing = ["tracing-opentelemetry"]


[[bench]]
Expand Down
85 changes: 83 additions & 2 deletions opentelemetry-appender-tracing/src/layer.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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";

Expand Down Expand Up @@ -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,
{
Expand Down Expand Up @@ -180,6 +180,26 @@ where
// Visit fields.
event.record(&mut visitor);

#[cfg(feature = "tracing")]
dylanahsmith marked this conversation as resolved.
Show resolved Hide resolved
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| {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it really necessary to look for the root span to get the trace_id here? Shouldn't the current span have the trace_id set as well?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Typically the current span won't have the span id explicitly set on it, so it won't actually store the trace id itself, instead it will be inherited when the span is built for sending.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I suppose going straight to the root span wouldn't support an explicitly set trace id on a non-root span. Is there a non-contrived example of when this might be done that I should add a test for and support? Or should this just be left as a limitation to avoid extra code and runtime overhead?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I looked at the listener code and yeah, it's only root spans that get the trace_id set in the builder. Someone would have to manually override that and set a trace_id on the builder to get that behavior.

Still, I think that we should pull out the trace_id from the builder and use that if it's available, or fall back to the root one.

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);
}
Expand Down Expand Up @@ -491,6 +511,67 @@ mod tests {
}
}

#[cfg(feature = "tracing")]
#[test]
fn tracing_appender_inside_tracing_crate_context() {
use opentelemetry_sdk::testing::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
Expand Down
Loading