From d394efa8d1c55b92282c81f5b33a2c56612efded Mon Sep 17 00:00:00 2001 From: Max Lehuraux <72396955+LehMaxence@users.noreply.github.com> Date: Mon, 23 Aug 2021 17:21:51 -0400 Subject: [PATCH 1/7] opentelemetry: Add extension to link spans (#1516) Repeat of #1480 to merge on master. ## Motivation Discussed in #1121, the opentelemetry specifications allow adding a link to a propagated span and/or a closed span. However, the implemented `on_follows_from` of the `OpenTelemetryLayer` does not allow this. ## Solution The solution follows the same model as the `set_parent` `Span` extension function. A `add_link` function that takes the linked span context was added to the `OpenTelemetrySpanExt`. --- tracing-opentelemetry/src/layer.rs | 22 +++++++++ tracing-opentelemetry/src/span_ext.rs | 71 ++++++++++++++++++++++++++- 2 files changed, 92 insertions(+), 1 deletion(-) diff --git a/tracing-opentelemetry/src/layer.rs b/tracing-opentelemetry/src/layer.rs index 2879c51790..ac67d2fae0 100644 --- a/tracing-opentelemetry/src/layer.rs +++ b/tracing-opentelemetry/src/layer.rs @@ -127,6 +127,21 @@ impl<'a> field::Visit for SpanEventVisitor<'a> { } } + /// Record events on the underlying OpenTelemetry [`Span`] from `f64` values. + /// + /// [`Span`]: opentelemetry::trace::Span + fn record_f64(&mut self, field: &field::Field, value: f64) { + match field.name() { + "message" => self.0.name = value.to_string().into(), + // Skip fields that are actually log metadata that have already been handled + #[cfg(feature = "tracing-log")] + name if name.starts_with("log.") => (), + name => { + self.0.attributes.push(KeyValue::new(name, value)); + } + } + } + /// Record events on the underlying OpenTelemetry [`Span`] from `i64` values. /// /// [`Span`]: opentelemetry::trace::Span @@ -197,6 +212,13 @@ impl<'a> field::Visit for SpanAttributeVisitor<'a> { self.record(KeyValue::new(field.name(), value)); } + /// Set attributes on the underlying OpenTelemetry [`Span`] from `f64` values. + /// + /// [`Span`]: opentelemetry::trace::Span + fn record_f64(&mut self, field: &field::Field, value: f64) { + self.record(KeyValue::new(field.name(), value)); + } + /// Set attributes on the underlying OpenTelemetry [`Span`] from `i64` values. /// /// [`Span`]: opentelemetry::trace::Span diff --git a/tracing-opentelemetry/src/span_ext.rs b/tracing-opentelemetry/src/span_ext.rs index 7140372ccf..800c63335b 100644 --- a/tracing-opentelemetry/src/span_ext.rs +++ b/tracing-opentelemetry/src/span_ext.rs @@ -1,5 +1,5 @@ use crate::layer::WithContext; -use opentelemetry::Context; +use opentelemetry::{trace::SpanContext, Context, KeyValue}; /// Utility functions to allow tracing [`Span`]s to accept and return /// [OpenTelemetry] [`Context`]s. @@ -42,6 +42,50 @@ pub trait OpenTelemetrySpanExt { /// ``` fn set_parent(&self, cx: Context); + /// Associates `self` with a given OpenTelemetry trace, using the provided + /// followed span [`SpanContext`]. + /// + /// [`SpanContext`]: opentelemetry::trace::SpanContext + /// + /// # Examples + /// + /// ```rust + /// use opentelemetry::{propagation::TextMapPropagator, trace::TraceContextExt}; + /// use opentelemetry::sdk::propagation::TraceContextPropagator; + /// use tracing_opentelemetry::OpenTelemetrySpanExt; + /// use std::collections::HashMap; + /// use tracing::Span; + /// + /// // Example carrier, could be a framework header map that impls otel's `Extract`. + /// let mut carrier = HashMap::new(); + /// + /// // Propagator can be swapped with b3 propagator, jaeger propagator, etc. + /// let propagator = TraceContextPropagator::new(); + /// + /// // Extract otel context of linked span via the chosen propagator + /// let linked_span_otel_context = propagator.extract(&carrier); + /// + /// // Extract the linked span context from the otel context + /// let linked_span_context = linked_span_otel_context.span().span_context().clone(); + /// + /// // Generate a tracing span as usual + /// let app_root = tracing::span!(tracing::Level::INFO, "app_start"); + /// + /// // Assign linked trace from external context + /// app_root.add_link(linked_span_context); + /// + /// // Or if the current span has been created elsewhere: + /// let linked_span_context = linked_span_otel_context.span().span_context().clone(); + /// Span::current().add_link(linked_span_context); + /// ``` + fn add_link(&self, cx: SpanContext); + + /// Associates `self` with a given OpenTelemetry trace, using the provided + /// followed span [`SpanContext`] and attributes. + /// + /// [`SpanContext`]: opentelemetry::trace::SpanContext + fn add_link_with_attributes(&self, cx: SpanContext, attributes: Vec); + /// Extracts an OpenTelemetry [`Context`] from `self`. /// /// [`Context`]: opentelemetry::Context @@ -86,6 +130,31 @@ impl OpenTelemetrySpanExt for tracing::Span { }); } + fn add_link(&self, cx: SpanContext) { + self.add_link_with_attributes(cx, Vec::new()) + } + + fn add_link_with_attributes(&self, cx: SpanContext, attributes: Vec) { + if cx.is_valid() { + let mut cx = Some(cx); + let mut att = Some(attributes); + self.with_subscriber(move |(id, collector)| { + if let Some(get_context) = collector.downcast_ref::() { + get_context.with_context(collector, id, move |builder, _tracer| { + if let Some(cx) = cx.take() { + let attr = att.take().unwrap_or_default(); + let follows_link = opentelemetry::trace::Link::new(cx, attr); + builder + .links + .get_or_insert_with(|| Vec::with_capacity(1)) + .push(follows_link); + } + }); + } + }); + } + } + fn context(&self) -> Context { let mut cx = None; self.with_subscriber(|(id, subscriber)| { From c90e5c8c5e62fa6b88de0ca669a75f524a9bedc2 Mon Sep 17 00:00:00 2001 From: Max Burke Date: Tue, 24 Aug 2021 17:27:14 -0700 Subject: [PATCH 2/7] core: add support for visiting floating point values (#1507) ## Motivation Tracing is a really useful framework but a lack of floating point value support for the core visitors means these get coerced unnecessarily to strings. ## Solution This change adds support for floating point (`f64`) visitors. --- tracing-core/src/field.rs | 20 ++++- tracing-serde/src/lib.rs | 12 +++ tracing-subscriber/src/field/debug.rs | 5 ++ tracing-subscriber/src/field/display.rs | 5 ++ tracing-subscriber/src/filter/env/field.rs | 88 +++++++++++++++++++++- tracing-subscriber/src/fmt/format/json.rs | 6 ++ tracing/tests/event.rs | 3 +- tracing/tests/span.rs | 22 ++++++ tracing/tests/support/field.rs | 38 +++++++++- 9 files changed, 192 insertions(+), 7 deletions(-) diff --git a/tracing-core/src/field.rs b/tracing-core/src/field.rs index 22c9365669..14cadb8f64 100644 --- a/tracing-core/src/field.rs +++ b/tracing-core/src/field.rs @@ -16,9 +16,9 @@ //! will contain any fields attached to each event. //! //! `tracing` represents values as either one of a set of Rust primitives -//! (`i64`, `u64`, `bool`, and `&str`) or using a `fmt::Display` or `fmt::Debug` -//! implementation. `Subscriber`s are provided these primitive value types as -//! `dyn Value` trait objects. +//! (`i64`, `u64`, `f64`, `bool`, and `&str`) or using a `fmt::Display` or +//! `fmt::Debug` implementation. `Subscriber`s are provided these primitive +//! value types as `dyn Value` trait objects. //! //! These trait objects can be formatted using `fmt::Debug`, but may also be //! recorded as typed data by calling the [`Value::record`] method on these @@ -184,6 +184,11 @@ pub struct Iter { /// [`Event`]: ../event/struct.Event.html /// [`ValueSet`]: struct.ValueSet.html pub trait Visit { + /// Visit a double-precision floating point value. + fn record_f64(&mut self, field: &Field, value: f64) { + self.record_debug(field, &value) + } + /// Visit a signed 64-bit integer value. fn record_i64(&mut self, field: &Field, value: i64) { self.record_debug(field, &value) @@ -335,6 +340,12 @@ macro_rules! ty_to_nonzero { } macro_rules! impl_one_value { + (f32, $op:expr, $record:ident) => { + impl_one_value!(normal, f32, $op, $record); + }; + (f64, $op:expr, $record:ident) => { + impl_one_value!(normal, f64, $op, $record); + }; (bool, $op:expr, $record:ident) => { impl_one_value!(normal, bool, $op, $record); }; @@ -387,7 +398,8 @@ impl_values! { record_u64(usize, u32, u16, u8 as u64), record_i64(i64), record_i64(isize, i32, i16, i8 as i64), - record_bool(bool) + record_bool(bool), + record_f64(f64, f32 as f64) } impl crate::sealed::Sealed for Wrapping {} diff --git a/tracing-serde/src/lib.rs b/tracing-serde/src/lib.rs index 94b486fbbc..9629480bc1 100644 --- a/tracing-serde/src/lib.rs +++ b/tracing-serde/src/lib.rs @@ -384,6 +384,12 @@ where } } + fn record_f64(&mut self, field: &Field, value: f64) { + if self.state.is_ok() { + self.state = self.serializer.serialize_entry(field.name(), &value) + } + } + fn record_str(&mut self, field: &Field, value: &str) { if self.state.is_ok() { self.state = self.serializer.serialize_entry(field.name(), &value) @@ -430,6 +436,12 @@ where } } + fn record_f64(&mut self, field: &Field, value: f64) { + if self.state.is_ok() { + self.state = self.serializer.serialize_field(field.name(), &value) + } + } + fn record_str(&mut self, field: &Field, value: &str) { if self.state.is_ok() { self.state = self.serializer.serialize_field(field.name(), &value) diff --git a/tracing-subscriber/src/field/debug.rs b/tracing-subscriber/src/field/debug.rs index 1e7512f796..10b9eb274c 100644 --- a/tracing-subscriber/src/field/debug.rs +++ b/tracing-subscriber/src/field/debug.rs @@ -38,6 +38,11 @@ impl Visit for Alt where V: Visit, { + #[inline] + fn record_f64(&mut self, field: &Field, value: f64) { + self.0.record_f64(field, value) + } + #[inline] fn record_i64(&mut self, field: &Field, value: i64) { self.0.record_i64(field, value) diff --git a/tracing-subscriber/src/field/display.rs b/tracing-subscriber/src/field/display.rs index 7e96de39cf..15f66c4b71 100644 --- a/tracing-subscriber/src/field/display.rs +++ b/tracing-subscriber/src/field/display.rs @@ -40,6 +40,11 @@ impl Visit for Messages where V: Visit, { + #[inline] + fn record_f64(&mut self, field: &Field, value: f64) { + self.0.record_f64(field, value) + } + #[inline] fn record_i64(&mut self, field: &Field, value: i64) { self.0.record_i64(field, value) diff --git a/tracing-subscriber/src/filter/env/field.rs b/tracing-subscriber/src/filter/env/field.rs index 994a9406dd..a6b849a8a8 100644 --- a/tracing-subscriber/src/filter/env/field.rs +++ b/tracing-subscriber/src/filter/env/field.rs @@ -36,14 +36,77 @@ pub(crate) struct MatchVisitor<'a> { inner: &'a SpanMatch, } -#[derive(Debug, Clone, PartialOrd, Ord, Eq, PartialEq)] +#[derive(Debug, Clone)] pub(crate) enum ValueMatch { Bool(bool), + F64(f64), U64(u64), I64(i64), + NaN, Pat(Box), } +impl Eq for ValueMatch {} + +impl PartialEq for ValueMatch { + fn eq(&self, other: &Self) -> bool { + use ValueMatch::*; + match (self, other) { + (Bool(a), Bool(b)) => a.eq(b), + (F64(a), F64(b)) => { + debug_assert!(!a.is_nan()); + debug_assert!(!b.is_nan()); + + a.eq(b) + } + (U64(a), U64(b)) => a.eq(b), + (I64(a), I64(b)) => a.eq(b), + (NaN, NaN) => true, + (Pat(a), Pat(b)) => a.eq(b), + _ => false, + } + } +} + +impl Ord for ValueMatch { + fn cmp(&self, other: &Self) -> Ordering { + use ValueMatch::*; + match (self, other) { + (Bool(this), Bool(that)) => this.cmp(that), + (Bool(_), _) => Ordering::Less, + + (F64(this), F64(that)) => this + .partial_cmp(that) + .expect("`ValueMatch::F64` may not contain `NaN` values"), + (F64(_), Bool(_)) => Ordering::Greater, + (F64(_), _) => Ordering::Less, + + (NaN, NaN) => Ordering::Equal, + (NaN, Bool(_)) | (NaN, F64(_)) => Ordering::Greater, + (NaN, _) => Ordering::Less, + + (U64(this), U64(that)) => this.cmp(that), + (U64(_), Bool(_)) | (U64(_), F64(_)) | (U64(_), NaN) => Ordering::Greater, + (U64(_), _) => Ordering::Less, + + (I64(this), I64(that)) => this.cmp(that), + (I64(_), Bool(_)) | (I64(_), F64(_)) | (I64(_), NaN) | (I64(_), U64(_)) => { + Ordering::Greater + } + (I64(_), _) => Ordering::Less, + + (Pat(this), Pat(that)) => this.cmp(that), + (Pat(_), _) => Ordering::Greater, + } + } +} + +impl PartialOrd for ValueMatch { + fn partial_cmp(&self, other: &Self) -> Option { + Some(self.cmp(other)) + } +} + #[derive(Debug, Clone)] pub(crate) struct MatchPattern { pub(crate) matcher: Pattern, @@ -127,6 +190,14 @@ impl PartialOrd for Match { // === impl ValueMatch === +fn value_match_f64(v: f64) -> ValueMatch { + if v.is_nan() { + ValueMatch::NaN + } else { + ValueMatch::F64(v) + } +} + impl FromStr for ValueMatch { type Err = matchers::Error; fn from_str(s: &str) -> Result { @@ -134,6 +205,7 @@ impl FromStr for ValueMatch { .map(ValueMatch::Bool) .or_else(|_| s.parse::().map(ValueMatch::U64)) .or_else(|_| s.parse::().map(ValueMatch::I64)) + .or_else(|_| s.parse::().map(value_match_f64)) .or_else(|_| { s.parse::() .map(|p| ValueMatch::Pat(Box::new(p))) @@ -145,6 +217,8 @@ impl fmt::Display for ValueMatch { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { match self { ValueMatch::Bool(ref inner) => fmt::Display::fmt(inner, f), + ValueMatch::F64(ref inner) => fmt::Display::fmt(inner, f), + ValueMatch::NaN => fmt::Display::fmt(&f64::NAN, f), ValueMatch::I64(ref inner) => fmt::Display::fmt(inner, f), ValueMatch::U64(ref inner) => fmt::Display::fmt(inner, f), ValueMatch::Pat(ref inner) => fmt::Display::fmt(inner, f), @@ -275,6 +349,18 @@ impl SpanMatch { } impl<'a> Visit for MatchVisitor<'a> { + fn record_f64(&mut self, field: &Field, value: f64) { + match self.inner.fields.get(field) { + Some((ValueMatch::NaN, ref matched)) if value.is_nan() => { + matched.store(true, Release); + } + Some((ValueMatch::F64(ref e), ref matched)) if (value - *e).abs() < f64::EPSILON => { + matched.store(true, Release); + } + _ => {} + } + } + fn record_i64(&mut self, field: &Field, value: i64) { use std::convert::TryInto; diff --git a/tracing-subscriber/src/fmt/format/json.rs b/tracing-subscriber/src/fmt/format/json.rs index 8e06db111b..8c4137bb93 100644 --- a/tracing-subscriber/src/fmt/format/json.rs +++ b/tracing-subscriber/src/fmt/format/json.rs @@ -431,6 +431,12 @@ impl<'a> crate::field::VisitOutput for JsonVisitor<'a> { } impl<'a> field::Visit for JsonVisitor<'a> { + /// Visit a double precision floating point value. + fn record_f64(&mut self, field: &Field, value: f64) { + self.values + .insert(field.name(), serde_json::Value::from(value)); + } + /// Visit a signed 64-bit integer value. fn record_i64(&mut self, field: &Field, value: i64) { self.values diff --git a/tracing/tests/event.rs b/tracing/tests/event.rs index d61ef748b8..5d757d821a 100644 --- a/tracing/tests/event.rs +++ b/tracing/tests/event.rs @@ -145,6 +145,7 @@ fn one_with_everything() { ))) .and(field::mock("foo").with_value(&666)) .and(field::mock("bar").with_value(&false)) + .and(field::mock("like_a_butterfly").with_value(&42.0)) .only(), ) .at_level(Level::ERROR) @@ -157,7 +158,7 @@ fn one_with_everything() { event!( target: "whatever", Level::ERROR, - { foo = 666, bar = false }, + { foo = 666, bar = false, like_a_butterfly = 42.0 }, "{:#x} make me one with{what:.>20}", 4_277_009_102u64, what = "everything" ); }); diff --git a/tracing/tests/span.rs b/tracing/tests/span.rs index 406207d9c5..f7991931c5 100644 --- a/tracing/tests/span.rs +++ b/tracing/tests/span.rs @@ -458,6 +458,28 @@ fn move_field_out_of_struct() { handle.assert_finished(); } +#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] +#[test] +fn float_values() { + let (collector, handle) = collector::mock() + .new_span( + span::mock().named("foo").with_field( + field::mock("x") + .with_value(&3.234) + .and(field::mock("y").with_value(&-1.223)) + .only(), + ), + ) + .run_with_handle(); + + with_default(collector, || { + let foo = span!(Level::TRACE, "foo", x = 3.234, y = -1.223); + foo.in_scope(|| {}); + }); + + handle.assert_finished(); +} + // TODO(#1138): determine a new syntax for uninitialized span fields, and // re-enable these. /* diff --git a/tracing/tests/support/field.rs b/tracing/tests/support/field.rs index 25f17d5dc8..0e7799fa26 100644 --- a/tracing/tests/support/field.rs +++ b/tracing/tests/support/field.rs @@ -19,8 +19,9 @@ pub struct MockField { value: MockValue, } -#[derive(Debug, Eq, PartialEq)] +#[derive(Debug)] pub enum MockValue { + F64(f64), I64(i64), U64(u64), Bool(bool), @@ -29,6 +30,31 @@ pub enum MockValue { Any, } +impl Eq for MockValue {} + +impl PartialEq for MockValue { + fn eq(&self, other: &Self) -> bool { + use MockValue::*; + + match (self, other) { + (F64(a), F64(b)) => { + debug_assert!(!a.is_nan()); + debug_assert!(!b.is_nan()); + + a.eq(b) + } + (I64(a), I64(b)) => a.eq(b), + (U64(a), U64(b)) => a.eq(b), + (Bool(a), Bool(b)) => a.eq(b), + (Str(a), Str(b)) => a.eq(b), + (Debug(a), Debug(b)) => a.eq(b), + (Any, _) => true, + (_, Any) => true, + _ => false, + } + } +} + pub fn mock(name: K) -> MockField where String: From, @@ -120,6 +146,7 @@ impl Expect { impl fmt::Display for MockValue { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { match self { + MockValue::F64(v) => write!(f, "f64 = {:?}", v), MockValue::I64(v) => write!(f, "i64 = {:?}", v), MockValue::U64(v) => write!(f, "u64 = {:?}", v), MockValue::Bool(v) => write!(f, "bool = {:?}", v), @@ -136,6 +163,11 @@ pub struct CheckVisitor<'a> { } impl<'a> Visit for CheckVisitor<'a> { + fn record_f64(&mut self, field: &Field, value: f64) { + self.expect + .compare_or_panic(field.name(), &value, &self.ctx[..]) + } + fn record_i64(&mut self, field: &Field, value: i64) { self.expect .compare_or_panic(field.name(), &value, &self.ctx[..]) @@ -180,6 +212,10 @@ impl<'a> From<&'a dyn Value> for MockValue { } impl Visit for MockValueBuilder { + fn record_f64(&mut self, _: &Field, value: f64) { + self.value = Some(MockValue::F64(value)); + } + fn record_i64(&mut self, _: &Field, value: i64) { self.value = Some(MockValue::I64(value)); } From 9cd3c567a483c65b4dd14662c4bc3d76951d6aa8 Mon Sep 17 00:00:00 2001 From: Folyd Date: Fri, 27 Aug 2021 01:11:35 +0800 Subject: [PATCH 3/7] attributes: record `f32` and `f64` as `Value` (#1522) Companion PR with #1507. --- tracing-attributes/src/lib.rs | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index 3e095ca03f..17b13c3b3d 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -1067,7 +1067,7 @@ enum RecordType { impl RecordType { /// Array of primitive types which should be recorded as [RecordType::Value]. - const TYPES_FOR_VALUE: [&'static str; 23] = [ + const TYPES_FOR_VALUE: &'static [&'static str] = &[ "bool", "str", "u8", @@ -1078,6 +1078,8 @@ impl RecordType { "i32", "u64", "i64", + "f32", + "f64", "usize", "isize", "NonZeroU8", From 7657fe080d68c8db10972bdf44211ea11976adb8 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 1 Sep 2021 13:43:34 -0700 Subject: [PATCH 4/7] chore(ci): turn off `fail-fast` for some build matrix jobs (#1530) The default behavior for GitHub Actions `matrix` strategies is to cancel all remaining jobs in a `matrix` job if *any* of them fail. However, this sometimes obscures important information. For example, we have a step that runs tests on stable, beta, and nightly Rust. In this case, it's useful to know whether a failure occurred only on nightly, or if it effects *every* Rust version. Furthermore, our branch protection settings don't require the nightly build to pass in order to merge a PR, because there are sometimes spurious failures due to nightly-specific bugs. We *do* require the stable build to pass. However, because the `matrix` strategy will cancel all jobs in the matrix if any of them fails, this means that we implicitly *do* require the tests to pass on nightly, as if the nightly job fails, it will also cancel the required stable job. This commit updates the github actions config to disable failfast for some build matrices. --- .github/workflows/CI.yml | 3 +++ 1 file changed, 3 insertions(+) diff --git a/.github/workflows/CI.yml b/.github/workflows/CI.yml index a6aee16db4..87a5ff52f4 100644 --- a/.github/workflows/CI.yml +++ b/.github/workflows/CI.yml @@ -85,6 +85,7 @@ jobs: - log-always - std log-always - std + fail-fast: false steps: - uses: actions/checkout@main - uses: actions-rs/toolchain@v1 @@ -128,6 +129,7 @@ jobs: strategy: matrix: rust: [stable, beta, nightly] + fail-fast: false steps: - uses: actions/checkout@main - uses: actions-rs/toolchain@v1 @@ -160,6 +162,7 @@ jobs: - tracing-serde - tracing-subscriber - tracing-tower + fail-fast: false steps: - uses: actions/checkout@main - uses: actions-rs/toolchain@v1 From c5ba3d364f82009efb94b77f313e1cae55eca045 Mon Sep 17 00:00:00 2001 From: David Barsky Date: Sat, 4 Sep 2021 13:48:09 -0400 Subject: [PATCH 5/7] chore: run tracing-subscriber's tests under `--no-default-features` (#1537) ## Motivation When reviewing https://github.com/tokio-rs/tracing/pull/1523, I suggested that the examples use `fmt::Layer` directly to allow readers to copy-and-paste examples into their own code. However, @hawkw pointed out that rustdoc doesn't receive feature flags from Cargo, which means that running tracing-subscriber's tests under `--no-default-features` would fail. ## Solution It turned out that that we're only running `cargo check --no-default-features` for tracing-subscriber. Running `cargo test --no-default-features` resulted in compilation failures, but it seems like nobody noticed. Building on https://github.com/tokio-rs/tracing/pull/1532, this branch argues that running tracing-subscriber's tests under `cargo test --lib --tests --no-default-features` is _probably_ fine if we're able to skip the doctests (which are _not_ aware of Cargo's feature flags). --- .github/workflows/CI.yml | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/.github/workflows/CI.yml b/.github/workflows/CI.yml index 87a5ff52f4..ac50c9855f 100644 --- a/.github/workflows/CI.yml +++ b/.github/workflows/CI.yml @@ -217,6 +217,9 @@ jobs: features-stable: # Feature flag tests that run on stable Rust. + # TODO(david): once tracing's MSRV goes up to Rust 1.51, we should be able to switch to + # using cargo's V2 feature resolver (https://doc.rust-lang.org/cargo/reference/resolver.html#resolver-versions) + # and avoid cd'ing into each crate's directory. needs: check runs-on: ubuntu-latest steps: @@ -234,6 +237,10 @@ jobs: run: (cd tracing-core && cargo test --no-default-features) - name: "Test tracing no-std support" run: (cd tracing && cargo test --no-default-features) + # this skips running doctests under the `--no-default-features` flag, + # as rustdoc isn't aware of cargo's feature flags. + - name: "Test tracing-subscriber with all features disabled" + run: (cd tracing-subscriber && cargo test --lib --tests --no-default-features) style: # Check style. From 151c0628e7a727d1ba7e8b2cdd74173f7dec9e60 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 4 Sep 2021 11:15:58 -0700 Subject: [PATCH 6/7] tracing: add `Span::or_current` to help with efficient propagation (#1538) This adds a new `Span::or_current` method that returns the span it's called on, if that span is enabled, or the current span if that span is not enabled. This should provide a more efficient alternative to writing code like ```rust tokio::spawn( future .instrument(some_span) .in_current_span() ); ``` since it doesn't wrap the future in two different spans which are (potentially) both entered on polls. It's also a little more concise to write, which (hopefully) will encourage people to use it instead of the less efficient alternative. `Span::or_current` may be useful in other cases as well. Signed-off-by: Eliza Weisman --- examples/examples/tower-load.rs | 6 +- tracing/src/instrument.rs | 41 +++++++++- tracing/src/span.rs | 129 ++++++++++++++++++++++++++++++++ 3 files changed, 173 insertions(+), 3 deletions(-) diff --git a/examples/examples/tower-load.rs b/examples/examples/tower-load.rs index 582e6c0909..06bb78c5ce 100644 --- a/examples/examples/tower-load.rs +++ b/examples/examples/tower-load.rs @@ -41,7 +41,9 @@ use std::{ }; use tokio::{time, try_join}; use tower::{Service, ServiceBuilder, ServiceExt}; -use tracing::{self, debug, error, info, span, trace, warn, Instrument as _, Level, Span}; +use tracing::{ + self, debug, error, info, info_span, span, trace, warn, Instrument as _, Level, Span, +}; use tracing_subscriber::{filter::EnvFilter, reload::Handle}; use tracing_tower::{request_span, request_span::make}; @@ -368,7 +370,7 @@ async fn load_gen(addr: SocketAddr) -> Result<(), Err> { .instrument(span) .await } - .instrument(span!(target: "gen", Level::INFO, "generated_request", remote.addr=%addr)); + .instrument(info_span!(target: "gen", "generated_request", remote.addr=%addr).or_current()); tokio::spawn(f); } } diff --git a/tracing/src/instrument.rs b/tracing/src/instrument.rs index 53e10d9059..3525a76c4e 100644 --- a/tracing/src/instrument.rs +++ b/tracing/src/instrument.rs @@ -34,7 +34,46 @@ pub trait Instrument: Sized { /// # } /// ``` /// - /// [entered]: ../struct.Span.html#method.enter + /// The [`Span::or_current`] combinator can be used in combination with + /// `instrument` to ensure that the [current span] is attached to the + /// future if the span passed to `instrument` is [disabled]: + /// + /// ```W + /// use tracing::Instrument; + /// # mod tokio { + /// # pub(super) fn spawn(_: impl std::future::Future) {} + /// # } + /// + /// let my_future = async { + /// // ... + /// }; + /// + /// let outer_span = tracing::info_span!("outer").entered(); + /// + /// // If the "my_future" span is enabled, then the spawned task will + /// // be within both "my_future" *and* "outer", since "outer" is + /// // "my_future"'s parent. However, if "my_future" is disabled, + /// // the spawned task will *not* be in any span. + /// tokio::spawn( + /// my_future + /// .instrument(tracing::debug_span!("my_future")) + /// ); + /// + /// // Using `Span::or_current` ensures the spawned task is instrumented + /// // with the current span, if the new span passed to `instrument` is + /// // not enabled. This means that if the "my_future" span is disabled, + /// // the spawned task will still be instrumented with the "outer" span: + /// # let my_future = async {}; + /// tokio::spawn( + /// my_future + /// .instrument(tracing::debug_span!("my_future").or_current()) + /// ); + /// ``` + /// + /// [entered]: super::Span::enter() + /// [`Span::or_current`]: super::Span::or_current() + /// [current span]: super::Span::current() + /// [disabled]: super::Span::is_disabled() fn instrument(self, span: Span) -> Instrumented { Instrumented { inner: self, span } } diff --git a/tracing/src/span.rs b/tracing/src/span.rs index 51b652610c..8e7fadcf15 100644 --- a/tracing/src/span.rs +++ b/tracing/src/span.rs @@ -900,6 +900,135 @@ impl Span { } } + /// Returns this span, if it was [enabled] by the current [`Subscriber`], or + /// the [current span] (whose lexical distance may be further than expected), + /// if this span [is disabled]. + /// + /// This method can be useful when propagating spans to spawned threads or + /// [async tasks]. Consider the following: + /// + /// ``` + /// let _parent_span = tracing::info_span!("parent").entered(); + /// + /// // ... + /// + /// let child_span = tracing::debug_span!("child"); + /// + /// std::thread::spawn(move || { + /// let _entered = child_span.entered(); + /// + /// tracing::info!("spawned a thread!"); + /// + /// // ... + /// }); + /// ``` + /// + /// If the current [`Subscriber`] enables the [`DEBUG`] level, then both + /// the "parent" and "child" spans will be enabled. Thus, when the "spawaned + /// a thread!" event occurs, it will be inside of the "child" span. Because + /// "parent" is the parent of "child", the event will _also_ be inside of + /// "parent". + /// + /// However, if the [`Subscriber`] only enables the [`INFO`] level, the "child" + /// span will be disabled. When the thread is spawned, the + /// `child_span.entered()` call will do nothing, since "child" is not + /// enabled. In this case, the "spawned a thread!" event occurs outside of + /// *any* span, since the "child" span was responsible for propagating its + /// parent to the spawned thread. + /// + /// If this is not the desired behavior, `Span::or_current` can be used to + /// ensure that the "parent" span is propagated in both cases, either as a + /// parent of "child" _or_ directly. For example: + /// + /// ``` + /// let _parent_span = tracing::info_span!("parent").entered(); + /// + /// // ... + /// + /// // If DEBUG is enabled, then "child" will be enabled, and `or_current` + /// // returns "child". Otherwise, if DEBUG is not enabled, "child" will be + /// // disabled, and `or_current` returns "parent". + /// let child_span = tracing::debug_span!("child").or_current(); + /// + /// std::thread::spawn(move || { + /// let _entered = child_span.entered(); + /// + /// tracing::info!("spawned a thread!"); + /// + /// // ... + /// }); + /// ``` + /// + /// When spawning [asynchronous tasks][async tasks], `Span::or_current` can + /// be used similarly, in combination with [`instrument`]: + /// + /// ``` + /// use tracing::Instrument; + /// # // lol + /// # mod tokio { + /// # pub(super) fn spawn(_: impl std::future::Future) {} + /// # } + /// + /// let _parent_span = tracing::info_span!("parent").entered(); + /// + /// // ... + /// + /// let child_span = tracing::debug_span!("child"); + /// + /// tokio::spawn( + /// async { + /// tracing::info!("spawned a task!"); + /// + /// // ... + /// + /// }.instrument(child_span.or_current()) + /// ); + /// ``` + /// + /// In general, `or_current` should be preferred over nesting an + /// [`instrument`] call inside of an [`in_current_span`] call, as using + /// `or_current` will be more efficient. + /// + /// ``` + /// use tracing::Instrument; + /// # // lol + /// # mod tokio { + /// # pub(super) fn spawn(_: impl std::future::Future) {} + /// # } + /// async fn my_async_fn() { + /// // ... + /// } + /// + /// let _parent_span = tracing::info_span!("parent").entered(); + /// + /// // Do this: + /// tokio::spawn( + /// my_async_fn().instrument(tracing::debug_span!("child").or_current()) + /// ); + /// + /// // ...rather than this: + /// tokio::spawn( + /// my_async_fn() + /// .instrument(tracing::debug_span!("child")) + /// .in_current_span() + /// ); + /// ``` + /// + /// [enabled]: crate::Subscriber::enabled + /// [`Subscriber`]: crate::Subscriber + /// [current span]: Span::current + /// [is disabled]: Span::is_disabled + /// [`INFO`]: crate::Level::INFO + /// [`DEBUG`]: crate::Level::DEBUG + /// [async tasks]: std::task + /// [`instrument`]: crate::instrument::Instrument + pub fn or_current(self) -> Self { + if self.is_disabled() { + return Self::current(); + } + self + } + #[inline] fn do_enter(&self) { if let Some(inner) = self.inner.as_ref() { From ed7f31e317c536af09cae74c3cdd3df5edcb59a4 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Sat, 4 Sep 2021 11:29:14 -0700 Subject: [PATCH 7/7] chore: fix inconsistent terminology I noticed a handful of places where `v0.1.x` refers to `Subscriber`s as "collectors". This probably happened because we backported some commits from master and forgot to change every instance of "collector" back to "subscriber". This commit fixes that. Whoops. Signed-off-by: Eliza Weisman --- examples/examples/fmt-multiple-writers.rs | 2 +- examples/examples/fmt-pretty.rs | 2 +- examples/examples/fmt.rs | 2 +- tracing-opentelemetry/src/span_ext.rs | 6 +++--- tracing-subscriber/src/filter/env/mod.rs | 2 +- tracing-subscriber/src/fmt/mod.rs | 12 ++++++------ tracing/tests/span.rs | 4 ++-- 7 files changed, 15 insertions(+), 15 deletions(-) diff --git a/examples/examples/fmt-multiple-writers.rs b/examples/examples/fmt-multiple-writers.rs index cb05ebee5b..61ea4ac456 100644 --- a/examples/examples/fmt-multiple-writers.rs +++ b/examples/examples/fmt-multiple-writers.rs @@ -17,7 +17,7 @@ fn main() { .with(EnvFilter::from_default_env().add_directive(tracing::Level::TRACE.into())) .with(fmt::Layer::new().with_writer(io::stdout)) .with(fmt::Layer::new().with_writer(non_blocking)); - tracing::subscriber::set_global_default(subscriber).expect("Unable to set a global collector"); + tracing::subscriber::set_global_default(subscriber).expect("Unable to set a global subscriber"); let number_of_yaks = 3; // this creates a new event, outside of any spans. diff --git a/examples/examples/fmt-pretty.rs b/examples/examples/fmt-pretty.rs index 570b5fb71a..37bfaf15d9 100644 --- a/examples/examples/fmt-pretty.rs +++ b/examples/examples/fmt-pretty.rs @@ -8,7 +8,7 @@ fn main() { .with_thread_names(true) // enable everything .with_max_level(tracing::Level::TRACE) - // sets this to be the default, global collector for this application. + // sets this to be the default, global subscriber for this application. .init(); let number_of_yaks = 3; diff --git a/examples/examples/fmt.rs b/examples/examples/fmt.rs index a990821df4..a8b3848188 100644 --- a/examples/examples/fmt.rs +++ b/examples/examples/fmt.rs @@ -6,7 +6,7 @@ fn main() { tracing_subscriber::fmt() // enable everything .with_max_level(tracing::Level::TRACE) - // sets this to be the default, global collector for this application. + // sets this to be the default, global subscriber for this application. .init(); let number_of_yaks = 3; diff --git a/tracing-opentelemetry/src/span_ext.rs b/tracing-opentelemetry/src/span_ext.rs index 800c63335b..66753e4e7e 100644 --- a/tracing-opentelemetry/src/span_ext.rs +++ b/tracing-opentelemetry/src/span_ext.rs @@ -138,9 +138,9 @@ impl OpenTelemetrySpanExt for tracing::Span { if cx.is_valid() { let mut cx = Some(cx); let mut att = Some(attributes); - self.with_subscriber(move |(id, collector)| { - if let Some(get_context) = collector.downcast_ref::() { - get_context.with_context(collector, id, move |builder, _tracer| { + self.with_subscriber(move |(id, subscriber)| { + if let Some(get_context) = subscriber.downcast_ref::() { + get_context.with_context(subscriber, id, move |builder, _tracer| { if let Some(cx) = cx.take() { let attr = att.take().unwrap_or_default(); let follows_link = opentelemetry::trace::Link::new(cx, attr); diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index 42e5bd317a..c1293896c2 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -261,7 +261,7 @@ impl EnvFilter { #[cfg(feature = "ansi_term")] use ansi_term::{Color, Style}; // NOTE: We can't use a configured `MakeWriter` because the EnvFilter - // has no knowledge of any underlying subscriber or collector, which + // has no knowledge of any underlying subscriber or subscriber, which // may or may not use a `MakeWriter`. let warn = |msg: &str| { #[cfg(not(feature = "ansi_term"))] diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index 1bc8ef6fd2..9a759d0d75 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -27,7 +27,7 @@ //! //! ## Filtering Events with Environment Variables //! -//! The default collector installed by `init` enables you to filter events +//! The default subscriber installed by `init` enables you to filter events //! at runtime using environment variables (using the [`EnvFilter`]). //! //! The filter syntax is a superset of the [`env_logger`] syntax. @@ -52,7 +52,7 @@ //! You can create one by calling: //! //! ```rust -//! let collector = tracing_subscriber::fmt() +//! let subscriber = tracing_subscriber::fmt() //! // ... add configuration //! .finish(); //! ``` @@ -336,7 +336,7 @@ pub struct SubscriberBuilder< /// .with_target(false) /// .with_timer(tracing_subscriber::fmt::time::uptime()) /// .with_level(true) -/// // Set the collector as the default. +/// // Set the subscriber as the default. /// .init(); /// ``` /// @@ -347,11 +347,11 @@ pub struct SubscriberBuilder< /// /// fn init_subscriber() -> Result<(), Box> { /// tracing_subscriber::fmt() -/// // Configure the collector to emit logs in JSON format. +/// // Configure the subscriber to emit logs in JSON format. /// .json() -/// // Configure the collector to flatten event fields in the output JSON objects. +/// // Configure the subscriber to flatten event fields in the output JSON objects. /// .flatten_event(true) -/// // Set the collector as the default, returning an error if this fails. +/// // Set the subscriber as the default, returning an error if this fails. /// .try_init()?; /// /// Ok(()) diff --git a/tracing/tests/span.rs b/tracing/tests/span.rs index f7991931c5..c784a96069 100644 --- a/tracing/tests/span.rs +++ b/tracing/tests/span.rs @@ -461,7 +461,7 @@ fn move_field_out_of_struct() { #[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] #[test] fn float_values() { - let (collector, handle) = collector::mock() + let (subscriber, handle) = subscriber::mock() .new_span( span::mock().named("foo").with_field( field::mock("x") @@ -472,7 +472,7 @@ fn float_values() { ) .run_with_handle(); - with_default(collector, || { + with_default(subscriber, || { let foo = span!(Level::TRACE, "foo", x = 3.234, y = -1.223); foo.in_scope(|| {}); });