From 5262b9ea7db4728c946f25c89c91e8a14513e9c4 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Thu, 7 Apr 2022 17:08:42 -0700 Subject: [PATCH 1/7] chore: fix Rust 1.60 warnings (#2056) ## Motivation The Rust 1.60 release introduced a few new lints that trigger on the `tracing` codebase. In particular, `clippy` added some new lints for method naming, and the `unreachable_pub` lint now seems to be triggered incorrectly by `pub use foo as _` re-exports. ## Solution This branch fixes the lints. Signed-off-by: Eliza Weisman --- tracing-error/src/lib.rs | 3 +++ tracing-subscriber/src/filter/env/builder.rs | 4 ++++ tracing-subscriber/src/layer/layered.rs | 2 +- tracing-subscriber/src/registry/sharded.rs | 2 +- 4 files changed, 9 insertions(+), 2 deletions(-) diff --git a/tracing-error/src/lib.rs b/tracing-error/src/lib.rs index d88f850a6d..a54543c333 100644 --- a/tracing-error/src/lib.rs +++ b/tracing-error/src/lib.rs @@ -232,5 +232,8 @@ pub mod prelude { //! extension traits. These traits allow attaching `SpanTrace`s to errors and //! subsequently retrieving them from `dyn Error` trait objects. + // apparently `as _` reexpoorts now generate `unreachable_pub` linting? which + // seems wrong to me... + #![allow(unreachable_pub)] pub use crate::{ExtractSpanTrace as _, InstrumentError as _, InstrumentResult as _}; } diff --git a/tracing-subscriber/src/filter/env/builder.rs b/tracing-subscriber/src/filter/env/builder.rs index 128b1868e8..d950b1e419 100644 --- a/tracing-subscriber/src/filter/env/builder.rs +++ b/tracing-subscriber/src/filter/env/builder.rs @@ -184,6 +184,10 @@ impl Builder { } // TODO(eliza): consider making this a public API? + // Clippy doesn't love this naming, because it suggests that `from_` methods + // should not take a `Self`...but in this case, it's the `EnvFilter` that is + // being constructed "from" the directives, rather than the builder itself. + #[allow(clippy::wrong_self_convention)] pub(super) fn from_directives( &self, directives: impl IntoIterator, diff --git a/tracing-subscriber/src/layer/layered.rs b/tracing-subscriber/src/layer/layered.rs index c690764add..5e81239a71 100644 --- a/tracing-subscriber/src/layer/layered.rs +++ b/tracing-subscriber/src/layer/layered.rs @@ -152,7 +152,7 @@ where #[cfg(all(feature = "registry", feature = "std"))] { if let Some(g) = guard.as_mut() { - g.is_closing() + g.set_closing() }; } diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index a6311cb718..c714409ef7 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -380,7 +380,7 @@ impl<'a> LookupSpan<'a> for Registry { // === impl CloseGuard === impl<'a> CloseGuard<'a> { - pub(crate) fn is_closing(&mut self) { + pub(crate) fn set_closing(&mut self) { self.is_closing = true; } } From 6f8f56d4bd8b0da1819d6362c658e2d64920869f Mon Sep 17 00:00:00 2001 From: Ma_124 Date: Fri, 8 Apr 2022 02:27:55 +0200 Subject: [PATCH 2/7] subscriber: fix empty string handling in `EnvFilter::builder().parse` (#2052) ## Motivation See issue #2046. When using calling [`Builder::parse`] or [`Builder::parse_lossy`] with an empty string an error is produced. This happens for example when `EnvFilter::from_default_env()` is called, but the `RUST_LOG` variable is unset. This regression was introduced by #2035. ## Solution Filter any empty directives. This allows the whole string to be empty, as well as leading and trailing commas. A unit test was added for [`Builder::parse`], but not [`Builder::parse_lossy`] because it (per definition) doesn't produce any side effects visible from tests when erroring. Fixes #2046 [`Builder::parse`]: https://github.com/tokio-rs/tracing/blob/cade7e311848227348c9b3062e4a33db827a0390/tracing-subscriber/src/filter/env/builder.rs#L151= [`Builder::parse_lossy`]: https://github.com/tokio-rs/tracing/blob/cade7e311848227348c9b3062e4a33db827a0390/tracing-subscriber/src/filter/env/builder.rs#L135= --- tracing-subscriber/src/filter/env/builder.rs | 22 +++++++++++--------- tracing-subscriber/src/filter/env/mod.rs | 8 +++++++ 2 files changed, 20 insertions(+), 10 deletions(-) diff --git a/tracing-subscriber/src/filter/env/builder.rs b/tracing-subscriber/src/filter/env/builder.rs index d950b1e419..36b5205431 100644 --- a/tracing-subscriber/src/filter/env/builder.rs +++ b/tracing-subscriber/src/filter/env/builder.rs @@ -133,16 +133,17 @@ impl Builder { /// Returns a new [`EnvFilter`] from the directives in the given string, /// *ignoring* any that are invalid. pub fn parse_lossy>(&self, dirs: S) -> EnvFilter { - let directives = - dirs.as_ref() - .split(',') - .filter_map(|s| match Directive::parse(s, self.regex) { - Ok(d) => Some(d), - Err(err) => { - eprintln!("ignoring `{}`: {}", s, err); - None - } - }); + let directives = dirs + .as_ref() + .split(',') + .filter(|s| !s.is_empty()) + .filter_map(|s| match Directive::parse(s, self.regex) { + Ok(d) => Some(d), + Err(err) => { + eprintln!("ignoring `{}`: {}", s, err); + None + } + }); self.from_directives(directives) } @@ -155,6 +156,7 @@ impl Builder { } let directives = dirs .split(',') + .filter(|s| !s.is_empty()) .map(|s| Directive::parse(s, self.regex)) .collect::, _>>()?; Ok(self.from_directives(directives)) diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index e59ba012e4..c75fd8e119 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -920,4 +920,12 @@ mod tests { [span2{bar=2 baz=false}],crate2[{quux=\"quuux\"}]=debug", ); } + + #[test] + fn parse_empty_string() { + // There is no corresponding test for [`Builder::parse_lossy`] as failed + // parsing does not produce any observable side effects. If this test fails + // check that [`Builder::parse_lossy`] is behaving correctly as well. + assert!(EnvFilter::builder().parse("").is_ok()); + } } From cd8d613b73fc27909f8bfad01361870d481831a9 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 8 Apr 2022 10:05:48 -0700 Subject: [PATCH 3/7] subscriber: add inherent impls for `EnvFilter` methods (#2057) ## Motivation Currently, there is a potential namespace resolution issue when calling `EnvFilter` methods that have the same name in the `Filter` and `Layer` traits (such as `enabled` and `max_level_hint`). When both `Filter` and `Layer` are in scope, the method resolution is ambiguous. See https://github.com/tokio-rs/tracing/pull/1983#issuecomment-1088984580 ## Solution This commit solves the problem by making the inherent method versions of these methods public. When the traits are in scope, name resolution will always select the inherent method prefer`entially, preventing the name clash. Signed-off-by: Eliza Weisman --- tracing-subscriber/src/filter/env/mod.rs | 161 ++++++++++++-------- tracing-subscriber/tests/env_filter/main.rs | 9 ++ 2 files changed, 109 insertions(+), 61 deletions(-) diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index c75fd8e119..e0758ffe41 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -11,7 +11,7 @@ mod field; use crate::{ filter::LevelFilter, - layer::{self, Context, Layer}, + layer::{Context, Layer}, sync::RwLock, }; use directive::ParseError; @@ -228,6 +228,8 @@ impl EnvFilter { /// [`EnvFilter::try_from_default_env`]: #method.try_from_default_env pub const DEFAULT_ENV: &'static str = "RUST_LOG"; + // === constructors, etc === + /// Returns a [builder] that can be used to configure a new [`EnvFilter`] /// instance. /// @@ -460,44 +462,19 @@ impl EnvFilter { self } - fn cares_about_span(&self, span: &span::Id) -> bool { - let spans = try_lock!(self.by_id.read(), else return false); - spans.contains_key(span) - } + // === filtering methods === - fn base_interest(&self) -> Interest { - if self.has_dynamics { - Interest::sometimes() - } else { - Interest::never() - } - } - - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - if self.has_dynamics && metadata.is_span() { - // If this metadata describes a span, first, check if there is a - // dynamic filter that should be constructed for it. If so, it - // should always be enabled, since it influences filtering. - if let Some(matcher) = self.dynamics.matcher(metadata) { - let mut by_cs = try_lock!(self.by_cs.write(), else return self.base_interest()); - by_cs.insert(metadata.callsite(), matcher); - return Interest::always(); - } - } - - // Otherwise, check if any of our static filters enable this metadata. - if self.statics.enabled(metadata) { - Interest::always() - } else { - self.base_interest() - } - } - - fn enabled(&self, metadata: &Metadata<'_>) -> bool { + /// Returns `true` if this `EnvFilter` would enable the provided `metadata` + /// in the current context. + /// + /// This is equivalent to calling the [`Layer::enabled`] or + /// [`Filter::enabled`] methods on `EnvFilter`'s implementations of those + /// traits, but it does not require the trait to be in scope. + pub fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool { let level = metadata.level(); // is it possible for a dynamic filter directive to enable this event? - // if not, we can avoid the thread local access + iterating over the + // if not, we can avoid the thread loca'l access + iterating over the // spans in the current scope. if self.has_dynamics && self.dynamics.max_level >= *level { if metadata.is_span() { @@ -537,7 +514,15 @@ impl EnvFilter { false } - fn max_level_hint(&self) -> Option { + /// Returns an optional hint of the highest [verbosity level][level] that + /// this `EnvFilter` will enable. + /// + /// This is equivalent to calling the [`Layer::max_level_hint`] or + /// [`Filter::max_level_hint`] methods on `EnvFilter`'s implementations of those + /// traits, but it does not require the trait to be in scope. + /// + /// [level]: tracing_core::metadata::Level + pub fn max_level_hint(&self) -> Option { if self.dynamics.has_value_filters() { // If we perform any filtering on span field *values*, we will // enable *all* spans, because their field values are not known @@ -550,7 +535,12 @@ impl EnvFilter { ) } - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id) { + /// Informs the filter that a new span was created. + /// + /// This is equivalent to calling the [`Layer::on_new_span`] or + /// [`Filter::on_new_span`] methods on `EnvFilter`'s implementations of those + /// traits, but it does not require the trait to be in scope. + pub fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) { let by_cs = try_lock!(self.by_cs.read()); if let Some(cs) = by_cs.get(&attrs.metadata().callsite()) { let span = cs.to_span_match(attrs); @@ -558,7 +548,12 @@ impl EnvFilter { } } - fn on_enter(&self, id: &span::Id) { + /// Informs the filter that the span with the provided `id` was entered. + /// + /// This is equivalent to calling the [`Layer::on_enter`] or + /// [`Filter::on_enter`] methods on `EnvFilter`'s implementations of those + /// traits, but it does not require the trait to be in scope. + pub fn on_enter(&self, id: &span::Id, _: Context<'_, S>) { // XXX: This is where _we_ could push IDs to the stack instead, and use // that to allow changing the filter while a span is already entered. // But that might be much less efficient... @@ -567,13 +562,23 @@ impl EnvFilter { } } - fn on_exit(&self, id: &span::Id) { + /// Informs the filter that the span with the provided `id` was exited. + /// + /// This is equivalent to calling the [`Layer::on_exit`] or + /// [`Filter::on_exit`] methods on `EnvFilter`'s implementations of those + /// traits, but it does not require the trait to be in scope. + pub fn on_exit(&self, id: &span::Id, _: Context<'_, S>) { if self.cares_about_span(id) { self.scope.get_or_default().borrow_mut().pop(); } } - fn on_close(&self, id: span::Id) { + /// Informs the filter that the span with the provided `id` was closed. + /// + /// This is equivalent to calling the [`Layer::on_close`] or + /// [`Filter::on_close`] methods on `EnvFilter`'s implementations of those + /// traits, but it does not require the trait to be in scope. + pub fn on_close(&self, id: span::Id, _: Context<'_, S>) { // If we don't need to acquire a write lock, avoid doing so. if !self.cares_about_span(&id) { return; @@ -582,6 +587,39 @@ impl EnvFilter { let mut spans = try_lock!(self.by_id.write()); spans.remove(&id); } + + fn cares_about_span(&self, span: &span::Id) -> bool { + let spans = try_lock!(self.by_id.read(), else return false); + spans.contains_key(span) + } + + fn base_interest(&self) -> Interest { + if self.has_dynamics { + Interest::sometimes() + } else { + Interest::never() + } + } + + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + if self.has_dynamics && metadata.is_span() { + // If this metadata describes a span, first, check if there is a + // dynamic filter that should be constructed for it. If so, it + // should always be enabled, since it influences filtering. + if let Some(matcher) = self.dynamics.matcher(metadata) { + let mut by_cs = try_lock!(self.by_cs.write(), else return self.base_interest()); + by_cs.insert(metadata.callsite(), matcher); + return Interest::always(); + } + } + + // Otherwise, check if any of our static filters enable this metadata. + if self.statics.enabled(metadata) { + Interest::always() + } else { + self.base_interest() + } + } } impl Layer for EnvFilter { @@ -596,13 +634,13 @@ impl Layer for EnvFilter { } #[inline] - fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool { - self.enabled(metadata) + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool { + self.enabled(metadata, ctx) } #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) { - self.on_new_span(attrs, id) + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + self.on_new_span(attrs, id, ctx) } fn on_record(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, S>) { @@ -612,28 +650,29 @@ impl Layer for EnvFilter { } #[inline] - fn on_enter(&self, id: &span::Id, _: Context<'_, S>) { - self.on_enter(id); + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + self.on_enter(id, ctx); } #[inline] - fn on_exit(&self, id: &span::Id, _: Context<'_, S>) { - self.on_exit(id); + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + self.on_exit(id, ctx); } #[inline] - fn on_close(&self, id: span::Id, _: Context<'_, S>) { - self.on_close(id); + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + self.on_close(id, ctx); } } feature! { #![all(feature = "registry", feature = "std")] + use crate::layer::Filter; - impl layer::Filter for EnvFilter { + impl Filter for EnvFilter { #[inline] - fn enabled(&self, meta: &Metadata<'_>, _: &Context<'_, S>) -> bool { - self.enabled(meta) + fn enabled(&self, meta: &Metadata<'_>, ctx: &Context<'_, S>) -> bool { + self.enabled(meta, ctx.clone()) } #[inline] @@ -647,23 +686,23 @@ feature! { } #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) { - self.on_new_span(attrs, id) + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + self.on_new_span(attrs, id, ctx) } #[inline] - fn on_enter(&self, id: &span::Id, _: Context<'_, S>) { - self.on_enter(id); + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + self.on_enter(id, ctx); } #[inline] - fn on_exit(&self, id: &span::Id, _: Context<'_, S>) { - self.on_exit(id); + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + self.on_exit(id, ctx); } #[inline] - fn on_close(&self, id: span::Id, _: Context<'_, S>) { - self.on_close(id); + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + self.on_close(id, ctx); } } } diff --git a/tracing-subscriber/tests/env_filter/main.rs b/tracing-subscriber/tests/env_filter/main.rs index 05e983e1af..3c3d4868be 100644 --- a/tracing-subscriber/tests/env_filter/main.rs +++ b/tracing-subscriber/tests/env_filter/main.rs @@ -230,6 +230,15 @@ fn span_name_filter_is_dynamic() { finished.assert_finished(); } +#[test] +fn method_name_resolution() { + #[allow(unused_imports)] + use tracing_subscriber::layer::{Filter, Layer}; + + let filter = EnvFilter::new("hello_world=info"); + filter.max_level_hint(); +} + // contains the same tests as the first half of this file // but using EnvFilter as a `Filter`, not as a `Layer` mod per_layer_filter { From bd6c611e7e5964c3f6eb7120b0fb127425cb21ab Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 8 Apr 2022 10:32:39 -0700 Subject: [PATCH 4/7] subscriber: add missing `Filter::on_record` for to `EnvFilter` (#2058) Depends on #2057 ## Motivation Currently, `EnvFilter`'s `Layer` implementation provides a `Layer::on_record` method, but its `Filter` implementation is missing the corresponding `Filter::on_record` implementation. This means that when using `EnvFilter` as a per-layer filter, recording span fields after the spans were created will not update the filter state. ## Solution This commit factors out the `on_record` implementation for `Layer` into an inherent method, and adds a new `Filter::on_record` method that calls it as well. Signed-off-by: Eliza Weisman --- tracing-subscriber/src/filter/env/mod.rs | 24 ++++++++++++++++++++---- 1 file changed, 20 insertions(+), 4 deletions(-) diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index e0758ffe41..50270c50d7 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -588,6 +588,18 @@ impl EnvFilter { spans.remove(&id); } + /// Informs the filter that the span with the provided `id` recorded the + /// provided field `values`. + /// + /// This is equivalent to calling the [`Layer::on_record`] or + /// [`Filter::on_record`] methods on `EnvFilter`'s implementations of those + /// traits, but it does not require the trait to be in scope + pub fn on_record(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, S>) { + if let Some(span) = try_lock!(self.by_id.read()).get(id) { + span.record_update(values); + } + } + fn cares_about_span(&self, span: &span::Id) -> bool { let spans = try_lock!(self.by_id.read(), else return false); spans.contains_key(span) @@ -643,10 +655,9 @@ impl Layer for EnvFilter { self.on_new_span(attrs, id, ctx) } - fn on_record(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, S>) { - if let Some(span) = try_lock!(self.by_id.read()).get(id) { - span.record_update(values); - } + #[inline] + fn on_record(&self, id: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { + self.on_record(id, values, ctx); } #[inline] @@ -690,6 +701,11 @@ feature! { self.on_new_span(attrs, id, ctx) } + #[inline] + fn on_record(&self, id: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { + self.on_record(id, values, ctx); + } + #[inline] fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { self.on_enter(id, ctx); From 4eed50aafb1621221c4287250c58b5c6d7c0bca9 Mon Sep 17 00:00:00 2001 From: Wiktor Sikora Date: Fri, 8 Apr 2022 19:57:36 +0200 Subject: [PATCH 5/7] journald: remove span field prefixes; add separate fields for span data (#1968) ## Motivation Currently, `tracing-journald` prefixes event fields with the number of parent spans, if present, in order to namespace field values. This turned out to be unnecessary as journald preserves values for duplicated field names. ## Solution This branch removes event field prefixes and emits parent span names and their field/value pairs as additional key/value pairs. --- tracing-journald/src/lib.rs | 74 ++++++++--------- tracing-journald/tests/journal.rs | 131 +++++++++++++++++++++++++++++- 2 files changed, 163 insertions(+), 42 deletions(-) diff --git a/tracing-journald/src/lib.rs b/tracing-journald/src/lib.rs index ac1265999d..2680869750 100644 --- a/tracing-journald/src/lib.rs +++ b/tracing-journald/src/lib.rs @@ -69,12 +69,11 @@ mod socket; /// - `DEBUG` => Informational (6) /// - `TRACE` => Debug (7) /// -/// Note that the naming scheme differs slightly for the latter half. -/// /// The standard journald `CODE_LINE` and `CODE_FILE` fields are automatically emitted. A `TARGET` -/// field is emitted containing the event's target. Enclosing spans are numbered counting up from -/// the root, and their fields and metadata are included in fields prefixed by `Sn_` where `n` is -/// that number. +/// field is emitted containing the event's target. +/// +/// For events recorded inside spans, an additional `SPAN_NAME` field is emitted with the name of +/// each of the event's parent spans. /// /// User-defined fields other than the event `message` field have a prefix applied by default to /// prevent collision with standard fields. @@ -215,16 +214,13 @@ where let span = ctx.span(id).expect("unknown span"); let mut buf = Vec::with_capacity(256); - let depth = span.scope().skip(1).count(); - - writeln!(buf, "S{}_NAME", depth).unwrap(); + writeln!(buf, "SPAN_NAME").unwrap(); put_value(&mut buf, span.name().as_bytes()); - put_metadata(&mut buf, span.metadata(), Some(depth)); + put_metadata(&mut buf, span.metadata(), Some("SPAN_")); attrs.record(&mut SpanVisitor { buf: &mut buf, - depth, - prefix: self.field_prefix.as_ref().map(|x| &x[..]), + field_prefix: self.field_prefix.as_deref(), }); span.extensions_mut().insert(SpanFields(buf)); @@ -232,13 +228,11 @@ where fn on_record(&self, id: &Id, values: &Record, ctx: Context) { let span = ctx.span(id).expect("unknown span"); - let depth = span.scope().skip(1).count(); let mut exts = span.extensions_mut(); let buf = &mut exts.get_mut::().expect("missing fields").0; values.record(&mut SpanVisitor { buf, - depth, - prefix: self.field_prefix.as_ref().map(|x| &x[..]), + field_prefix: self.field_prefix.as_deref(), }); } @@ -257,6 +251,7 @@ where } // Record event fields + put_priority(&mut buf, event.metadata()); put_metadata(&mut buf, event.metadata(), None); put_field_length_encoded(&mut buf, "SYSLOG_IDENTIFIER", |buf| { write!(buf, "{}", self.syslog_identifier).unwrap() @@ -264,7 +259,7 @@ where event.record(&mut EventVisitor::new( &mut buf, - self.field_prefix.as_ref().map(|x| &x[..]), + self.field_prefix.as_deref(), )); // At this point we can't handle the error anymore so just ignore it. @@ -276,17 +271,15 @@ struct SpanFields(Vec); struct SpanVisitor<'a> { buf: &'a mut Vec, - depth: usize, - prefix: Option<&'a str>, + field_prefix: Option<&'a str>, } impl SpanVisitor<'_> { fn put_span_prefix(&mut self) { - write!(self.buf, "S{}", self.depth).unwrap(); - if let Some(prefix) = self.prefix { + if let Some(prefix) = self.field_prefix { self.buf.extend_from_slice(prefix.as_bytes()); + self.buf.push(b'_'); } - self.buf.push(b'_'); } } @@ -345,33 +338,34 @@ impl Visit for EventVisitor<'_> { } } -fn put_metadata(buf: &mut Vec, meta: &Metadata, span: Option) { - if span.is_none() { - put_field_wellformed( - buf, - "PRIORITY", - match *meta.level() { - Level::ERROR => b"3", - Level::WARN => b"4", - Level::INFO => b"5", - Level::DEBUG => b"6", - Level::TRACE => b"7", - }, - ); - } - if let Some(n) = span { - write!(buf, "S{}_", n).unwrap(); +fn put_priority(buf: &mut Vec, meta: &Metadata) { + put_field_wellformed( + buf, + "PRIORITY", + match *meta.level() { + Level::ERROR => b"3", + Level::WARN => b"4", + Level::INFO => b"5", + Level::DEBUG => b"6", + Level::TRACE => b"7", + }, + ); +} + +fn put_metadata(buf: &mut Vec, meta: &Metadata, prefix: Option<&str>) { + if let Some(prefix) = prefix { + write!(buf, "{}", prefix).unwrap(); } put_field_wellformed(buf, "TARGET", meta.target().as_bytes()); if let Some(file) = meta.file() { - if let Some(n) = span { - write!(buf, "S{}_", n).unwrap(); + if let Some(prefix) = prefix { + write!(buf, "{}", prefix).unwrap(); } put_field_wellformed(buf, "CODE_FILE", file.as_bytes()); } if let Some(line) = meta.line() { - if let Some(n) = span { - write!(buf, "S{}_", n).unwrap(); + if let Some(prefix) = prefix { + write!(buf, "{}", prefix).unwrap(); } // Text format is safe as a line number can't possibly contain anything funny writeln!(buf, "CODE_LINE={}", line).unwrap(); diff --git a/tracing-journald/tests/journal.rs b/tracing-journald/tests/journal.rs index 25c1412e5d..c2e07cc9ca 100644 --- a/tracing-journald/tests/journal.rs +++ b/tracing-journald/tests/journal.rs @@ -5,7 +5,8 @@ use std::process::Command; use std::time::Duration; use serde::Deserialize; -use tracing::{debug, error, info, warn}; + +use tracing::{debug, error, info, info_span, warn}; use tracing_journald::Layer; use tracing_subscriber::layer::SubscriberExt; use tracing_subscriber::Registry; @@ -16,9 +17,13 @@ fn journalctl_version() -> std::io::Result { } fn with_journald(f: impl FnOnce()) { + with_journald_layer(Layer::new().unwrap().with_field_prefix(None), f) +} + +fn with_journald_layer(layer: Layer, f: impl FnOnce()) { match journalctl_version() { Ok(_) => { - let sub = Registry::default().with(Layer::new().unwrap().with_field_prefix(None)); + let sub = Registry::default().with(layer); tracing::subscriber::with_default(sub, f); } Err(error) => eprintln!( @@ -32,15 +37,35 @@ fn with_journald(f: impl FnOnce()) { #[serde(untagged)] enum Field { Text(String), + Array(Vec), Binary(Vec), } +impl Field { + fn as_array(&self) -> Option<&[String]> { + match self { + Field::Text(_) => None, + Field::Binary(_) => None, + Field::Array(v) => Some(v), + } + } + + fn as_text(&self) -> Option<&str> { + match self { + Field::Text(v) => Some(v.as_str()), + Field::Binary(_) => None, + Field::Array(_) => None, + } + } +} + // Convenience impls to compare fields against strings and bytes with assert_eq! impl PartialEq<&str> for Field { fn eq(&self, other: &&str) -> bool { match self { Field::Text(s) => s == other, Field::Binary(_) => false, + Field::Array(_) => false, } } } @@ -50,6 +75,17 @@ impl PartialEq<[u8]> for Field { match self { Field::Text(s) => s.as_bytes() == other, Field::Binary(data) => data == other, + Field::Array(_) => false, + } + } +} + +impl PartialEq> for Field { + fn eq(&self, other: &Vec<&str>) -> bool { + match self { + Field::Text(_) => false, + Field::Binary(_) => false, + Field::Array(data) => data == other, } } } @@ -182,3 +218,94 @@ fn large_message() { assert_eq!(message["PRIORITY"], "6"); }); } + +#[test] +fn simple_metadata() { + let sub = Layer::new() + .unwrap() + .with_field_prefix(None) + .with_syslog_identifier("test_ident".to_string()); + with_journald_layer(sub, || { + info!(test.name = "simple_metadata", "Hello World"); + + let message = retry_read_one_line_from_journal("simple_metadata"); + assert_eq!(message["MESSAGE"], "Hello World"); + assert_eq!(message["PRIORITY"], "5"); + assert_eq!(message["TARGET"], "journal"); + assert_eq!(message["SYSLOG_IDENTIFIER"], "test_ident"); + assert!(message["CODE_FILE"].as_text().is_some()); + assert!(message["CODE_LINE"].as_text().is_some()); + }); +} + +#[test] +fn span_metadata() { + with_journald(|| { + let s1 = info_span!("span1", span_field1 = "foo1"); + let _g1 = s1.enter(); + + info!(test.name = "span_metadata", "Hello World"); + + let message = retry_read_one_line_from_journal("span_metadata"); + assert_eq!(message["MESSAGE"], "Hello World"); + assert_eq!(message["PRIORITY"], "5"); + assert_eq!(message["TARGET"], "journal"); + + assert_eq!(message["SPAN_FIELD1"].as_text(), Some("foo1")); + assert_eq!(message["SPAN_NAME"].as_text(), Some("span1")); + + assert!(message["CODE_FILE"].as_text().is_some()); + assert!(message["CODE_LINE"].as_text().is_some()); + + assert!(message["SPAN_CODE_FILE"].as_text().is_some()); + assert!(message["SPAN_CODE_LINE"].as_text().is_some()); + }); +} + +#[test] +fn multiple_spans_metadata() { + with_journald(|| { + let s1 = info_span!("span1", span_field1 = "foo1"); + let _g1 = s1.enter(); + let s2 = info_span!("span2", span_field1 = "foo2"); + let _g2 = s2.enter(); + + info!(test.name = "multiple_spans_metadata", "Hello World"); + + let message = retry_read_one_line_from_journal("multiple_spans_metadata"); + assert_eq!(message["MESSAGE"], "Hello World"); + assert_eq!(message["PRIORITY"], "5"); + assert_eq!(message["TARGET"], "journal"); + + assert_eq!(message["SPAN_FIELD1"], vec!["foo1", "foo2"]); + assert_eq!(message["SPAN_NAME"], vec!["span1", "span2"]); + + assert!(message["CODE_FILE"].as_text().is_some()); + assert!(message["CODE_LINE"].as_text().is_some()); + + assert!(message.contains_key("SPAN_CODE_FILE")); + assert_eq!(message["SPAN_CODE_LINE"].as_array().unwrap().len(), 2); + }); +} + +#[test] +fn spans_field_collision() { + with_journald(|| { + let s1 = info_span!("span1", span_field = "foo1"); + let _g1 = s1.enter(); + let s2 = info_span!("span2", span_field = "foo2"); + let _g2 = s2.enter(); + + info!( + test.name = "spans_field_collision", + span_field = "foo3", + "Hello World" + ); + + let message = retry_read_one_line_from_journal("spans_field_collision"); + assert_eq!(message["MESSAGE"], "Hello World"); + assert_eq!(message["SPAN_NAME"], vec!["span1", "span2"]); + + assert_eq!(message["SPAN_FIELD"], vec!["foo1", "foo2", "foo3"]); + }); +} From 14cc4de5cd7946f6ddd12951851c76780784e5c2 Mon Sep 17 00:00:00 2001 From: John-John Tedro Date: Fri, 8 Apr 2022 23:27:49 +0200 Subject: [PATCH 6/7] chore(ci): add a minimal-versions check (#2015) This adds a minimal-versions check to the tracing project. Adapted from `tokio-rs/tokio`. Adding this avoids breaking downstream dependencies from accidentally under-constraining minimal versions of dependencies when they depend on tracing. I've currently just introduced the check. I will try to and do encourage others to add patches to fix this where possible since it can be a fair bit of work to chase down a version of all dependencies that passes minimal-versions and is msrv. I've also seen some really odd windows-specific issues (which are not being tested for here). This is currently only testing `tracing`, `tracing-core`, and `tracing-subscriber`. Packages such as `tracing-futures` are proving to be a bit harder to deal with due to having features which enable very old dependencies. Steps to test the build minimal versions locally: ```sh cargo install cargo-hack rustup default nightly cargo hack --remove-dev-deps --workspace cargo update -Z minimal-versions cargo hack check --all-features --ignore-private ``` CC: tokio-rs/tokio#4513 --- .github/workflows/CI.yml | 29 +++++++++++++++++++++++++++++ tracing-core/Cargo.toml | 2 +- 2 files changed, 30 insertions(+), 1 deletion(-) diff --git a/.github/workflows/CI.yml b/.github/workflows/CI.yml index b8edff6b0d..7b91a9d934 100644 --- a/.github/workflows/CI.yml +++ b/.github/workflows/CI.yml @@ -222,3 +222,32 @@ jobs: with: token: ${{ secrets.GITHUB_TOKEN }} args: --all --examples --tests --benches -- -D warnings + + minimal-versions: + # Check for minimal-versions errors where a dependency is too + # underconstrained to build on the minimal supported version of all + # dependencies in the dependency graph. + name: minimal-versions + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v2 + - uses: actions-rs/toolchain@v1 + with: + toolchain: nightly + profile: minimal + override: true + - name: Install cargo-hack + run: | + curl -LsSf https://github.com/taiki-e/cargo-hack/releases/latest/download/cargo-hack-x86_64-unknown-linux-gnu.tar.gz | tar xzf - -C ~/.cargo/bin + - name: "check --all-features -Z minimal-versions" + run: | + # Remove dev-dependencies from Cargo.toml to prevent the next `cargo update` + # from determining minimal versions based on dev-dependencies. + cargo hack --remove-dev-deps --workspace + # Update Cargo.lock to minimal version dependencies. + cargo update -Z minimal-versions + cargo hack check \ + --package tracing \ + --package tracing-core \ + --package tracing-subscriber \ + --all-features --ignore-private diff --git a/tracing-core/Cargo.toml b/tracing-core/Cargo.toml index aa8006068b..c05cf3f8bf 100644 --- a/tracing-core/Cargo.toml +++ b/tracing-core/Cargo.toml @@ -34,7 +34,7 @@ std = ["lazy_static"] maintenance = { status = "actively-developed" } [dependencies] -lazy_static = { version = "1", optional = true } +lazy_static = { version = "1.0.2", optional = true } [target.'cfg(tracing_unstable)'.dependencies] valuable = { version = "0.1.0", optional = true, default_features = false } From b6874b88f7e633f76df1ac459f9a74d0f1c946be Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 8 Apr 2022 15:56:39 -0700 Subject: [PATCH 7/7] tracing: fix issues compiling for WASM/other <=32-bit platforms (#2060) This changes the "unregistered" interest state from `0xDEADFACED` to`0xDEAD`, which should fit in a `usize` even on 16-bit platforms. The actual value of this thing doesn't matter at all, it just has to be "not 0, 1, or 2", and it's good for it to be something weird to make it more obvious in the event of stuff going wrong. This should fix a warning being emitted when building for wasm (and other <=32-bit platforms) because the previous literal would be truncated. Also, the `wasm_bindgen_test` macro apparently messes with the `macros_redefined_core` tests, so skip them on wasm. --- tracing/src/lib.rs | 2 +- tracing/tests/macros_redefined_core.rs | 3 --- 2 files changed, 1 insertion(+), 4 deletions(-) diff --git a/tracing/src/lib.rs b/tracing/src/lib.rs index 6a919d7bfb..33e33aa600 100644 --- a/tracing/src/lib.rs +++ b/tracing/src/lib.rs @@ -1005,7 +1005,7 @@ pub mod __macro_support { /// without warning. pub const fn new(meta: &'static Metadata<'static>) -> Self { Self { - interest: AtomicUsize::new(0xDEADFACED), + interest: AtomicUsize::new(0xDEAD), meta, registration: Once::new(), } diff --git a/tracing/tests/macros_redefined_core.rs b/tracing/tests/macros_redefined_core.rs index 5932c06553..d830dcdb02 100644 --- a/tracing/tests/macros_redefined_core.rs +++ b/tracing/tests/macros_redefined_core.rs @@ -2,19 +2,16 @@ extern crate self as core; use tracing::{enabled, event, span, Level}; -#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] #[test] fn span() { span!(Level::DEBUG, "foo"); } -#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] #[test] fn event() { event!(Level::DEBUG, "foo"); } -#[cfg_attr(target_arch = "wasm32", wasm_bindgen_test::wasm_bindgen_test)] #[test] fn enabled() { enabled!(Level::DEBUG);