From 9b7bab1dbb45a338f8ca0a3522f3d11f3dd6731a Mon Sep 17 00:00:00 2001 From: tfreiberg-fastly <98025906+tfreiberg-fastly@users.noreply.github.com> Date: Fri, 25 Mar 2022 18:37:51 +0100 Subject: [PATCH] subscriber: impl `Filter` for `EnvFilter` (#1983) ## Motivation Filtering by span and field requires using `EnvFilter` rather than `Targets`. Per-subscriber filtering requires the `Filter` trait, which `EnvFilter` does not implement. ## Solution Implement the `Filter` trait for `EnvFilter`. PR #1973 adds additiional methods to the `Filter` trait, which are necessary for `EnvFilter` to implement dynamic span filtering. Now that those methods are added, we can provide a `Filter` impl for `EnvFilter`. In addition, we changed the globally-scoped `thread_local!` macro to use a `ThreadLocal` struct as a field, so that multiple `EnvFilter`s used as per-subscriber filters don't share a single span scope. Fixes #1868 Follow-up on #1973 Co-authored-by: Eliza Weisman --- tracing-mock/src/span.rs | 7 + tracing-subscriber/Cargo.toml | 2 +- tracing-subscriber/src/filter/env/mod.rs | 219 ++++++++++--- .../tests/{filter.rs => env_filter/main.rs} | 7 +- .../tests/env_filter/per_subscriber.rs | 305 ++++++++++++++++++ 5 files changed, 497 insertions(+), 43 deletions(-) rename tracing-subscriber/tests/{filter.rs => env_filter/main.rs} (98%) create mode 100644 tracing-subscriber/tests/env_filter/per_subscriber.rs diff --git a/tracing-mock/src/span.rs b/tracing-mock/src/span.rs index 1a19350bc0..2fde98f163 100644 --- a/tracing-mock/src/span.rs +++ b/tracing-mock/src/span.rs @@ -24,6 +24,13 @@ pub fn mock() -> MockSpan { } } +pub fn named(name: I) -> MockSpan +where + I: Into, +{ + mock().named(name) +} + impl MockSpan { pub fn named(self, name: I) -> Self where diff --git a/tracing-subscriber/Cargo.toml b/tracing-subscriber/Cargo.toml index 9b9bb46283..2a134f5989 100644 --- a/tracing-subscriber/Cargo.toml +++ b/tracing-subscriber/Cargo.toml @@ -27,7 +27,7 @@ rust-version = "1.49.0" default = ["smallvec", "fmt", "ansi", "tracing-log", "std"] alloc = [] std = ["alloc", "tracing-core/std"] -env-filter = ["matchers", "regex", "lazy_static", "tracing", "std"] +env-filter = ["matchers", "regex", "lazy_static", "tracing", "std", "thread_local"] fmt = ["registry", "std"] ansi = ["fmt", "ansi_term"] registry = ["sharded-slab", "thread_local", "std"] diff --git a/tracing-subscriber/src/filter/env/mod.rs b/tracing-subscriber/src/filter/env/mod.rs index f2d6fa16b5..08833abe5a 100644 --- a/tracing-subscriber/src/filter/env/mod.rs +++ b/tracing-subscriber/src/filter/env/mod.rs @@ -10,11 +10,12 @@ mod field; use crate::{ filter::LevelFilter, - subscribe::{Context, Subscribe}, + subscribe::{self, Context, Subscribe}, sync::RwLock, }; use directive::ParseError; use std::{cell::RefCell, collections::HashMap, env, error::Error, fmt, str::FromStr}; +use thread_local::ThreadLocal; use tracing_core::{ callsite, collect::{Collect, Interest}, @@ -25,6 +26,16 @@ use tracing_core::{ /// A [`Subscriber`] which filters spans and events based on a set of filter /// directives. /// +/// `EnvFilter` implements both the [`Subscribe`](#impl-Subscribe) and +/// [`Filter`] traits, so it may be used for both [global filtering][global] and +/// [per-subscriber filtering][psf], respectively. See [the documentation on +/// filtering with `Subscriber`s][filtering] for details. +/// +/// The [`Targets`] type implements a similar form of filtering, but without the +/// ability to dynamically enable events based on the current span context, and +/// without filtering on field values. When these features are not required, +/// [`Targets`] provides a lighter-weight alternative to [`EnvFilter`]. +/// /// # Directives /// /// A filter consists of one or more comma-separated directives which match on [`Span`]s and [`Event`]s. @@ -71,7 +82,7 @@ use tracing_core::{ /// - A dash in a target will only appear when being specified explicitly: /// `tracing::info!(target: "target-name", ...);` /// -/// ## Examples +/// ## Example Syntax /// /// - `tokio::net=info` will enable all spans or events that: /// - have the `tokio::net` target, @@ -88,10 +99,54 @@ use tracing_core::{ /// - which has a field named `name` with value `bob`, /// - at _any_ level. /// -/// The [`Targets`] type implements a similar form of filtering, but without the -/// ability to dynamically enable events based on the current span context, and -/// without filtering on field values. When these features are not required, -/// [`Targets`] provides a lighter-weight alternative to [`EnvFilter`]. +/// # Examples +/// +/// Parsing an `EnvFilter` from the [default environment +/// variable](EnvFilter::from_default_env) (`RUST_LOG`): +/// +/// ``` +/// use tracing_subscriber::{EnvFilter, fmt, prelude::*}; +/// +/// tracing_subscriber::registry() +/// .with(fmt::layer()) +/// .with(EnvFilter::from_default_env()) +/// .init(); +/// ``` +/// +/// Parsing an `EnvFilter` [from a user-provided environment +/// variable](EnvFilter::from_env): +/// +/// ``` +/// use tracing_subscriber::{EnvFilter, fmt, prelude::*}; +/// +/// tracing_subscriber::registry() +/// .with(fmt::layer()) +/// .with(EnvFilter::from_env("MYAPP_LOG")) +/// .init(); +/// ``` +/// +/// Using `EnvFilter` as a [per-subscriber filter][psf] to filter only a single +/// [subscriber](crate::subscribe::Subscribe): +/// +/// ``` +/// use tracing_subscriber::{EnvFilter, fmt, prelude::*}; +/// +/// // Parse an `EnvFilter` configuration from the `RUST_LOG` +/// // environment variable. +/// let filter = EnvFilter::from_default_env(); +/// +/// // Apply the filter to this suscriber *only*. +/// let filtered_subscriber = fmt::subscriber().with_filter(filter); +/// +/// // Some other subscriber, whose output we don't want to filter. +/// let unfiltered_subscriber = // ... +/// # fmt::subscriber(); +/// +/// tracing_subscriber::registry() +/// .with(filtered_subscriber) +/// .with(unfiltered_subscriber) +/// .init(); +/// ``` /// /// [`Subscriber`]: Subscribe /// [`env_logger`]: https://docs.rs/env_logger/0.7.1/env_logger/#enabling-logging @@ -101,6 +156,10 @@ use tracing_core::{ /// [`level`]: tracing_core::Level /// [`Metadata`]: tracing_core::Metadata /// [`Targets`]: crate::filter::Targets +/// [`Filter`]: #impl-Filter +/// [global]: crate::subscribe#global-filtering +/// [psf]: crate::subscribe#per-subscriber-filtering +/// [filtering]: crate::subscribe#filtering-with-subscribers #[cfg_attr(docsrs, doc(cfg(all(feature = "env-filter", feature = "std"))))] #[derive(Debug)] pub struct EnvFilter { @@ -109,10 +168,7 @@ pub struct EnvFilter { has_dynamics: bool, by_id: RwLock>, by_cs: RwLock>, -} - -thread_local! { - static SCOPE: RefCell> = RefCell::new(Vec::new()); + scope: ThreadLocal>>, } type FieldMap = HashMap; @@ -347,6 +403,10 @@ impl EnvFilter { has_dynamics, by_id: RwLock::new(HashMap::new()), by_cs: RwLock::new(HashMap::new()), + // TODO(eliza): maybe worth allocating capacity for `num_cpus` + // threads or something (assuming we're running in Tokio)? or + // `num_cpus * 2` or something? + scope: ThreadLocal::new(), } } @@ -362,9 +422,7 @@ impl EnvFilter { Interest::never() } } -} -impl Subscribe for EnvFilter { 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 @@ -385,20 +443,7 @@ impl Subscribe for EnvFilter { } } - 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 - // until recording. - return Some(LevelFilter::TRACE); - } - std::cmp::max( - self.statics.max_level.into(), - self.dynamics.max_level.into(), - ) - } - - fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, C>) -> bool { + fn enabled(&self, metadata: &Metadata<'_>) -> bool { let level = metadata.level(); // is it possible for a dynamic filter directive to enable this event? @@ -418,14 +463,15 @@ impl Subscribe for EnvFilter { } } - let enabled_by_scope = SCOPE.with(|scope| { - for filter in scope.borrow().iter() { + let enabled_by_scope = { + let scope = self.scope.get_or_default().borrow(); + for filter in &*scope { if filter >= level { return true; } } false - }); + }; if enabled_by_scope { return true; } @@ -441,7 +487,20 @@ impl Subscribe for EnvFilter { false } - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, C>) { + 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 + // until recording. + return Some(LevelFilter::TRACE); + } + std::cmp::max( + self.statics.max_level.into(), + self.dynamics.max_level.into(), + ) + } + + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id) { 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); @@ -449,28 +508,22 @@ impl Subscribe for EnvFilter { } } - fn on_record(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, C>) { - if let Some(span) = try_lock!(self.by_id.read()).get(id) { - span.record_update(values); - } - } - - fn on_enter(&self, id: &span::Id, _: Context<'_, C>) { + fn on_enter(&self, id: &span::Id) { // 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... if let Some(span) = try_lock!(self.by_id.read()).get(id) { - SCOPE.with(|scope| scope.borrow_mut().push(span.level())); + self.scope.get_or_default().borrow_mut().push(span.level()); } } - fn on_exit(&self, id: &span::Id, _: Context<'_, C>) { + fn on_exit(&self, id: &span::Id) { if self.cares_about_span(id) { - SCOPE.with(|scope| scope.borrow_mut().pop()); + self.scope.get_or_default().borrow_mut().pop(); } } - fn on_close(&self, id: span::Id, _: Context<'_, C>) { + fn on_close(&self, id: span::Id) { // If we don't need to acquire a write lock, avoid doing so. if !self.cares_about_span(&id) { return; @@ -481,6 +534,90 @@ impl Subscribe for EnvFilter { } } +impl Subscribe for EnvFilter { + #[inline] + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + EnvFilter::register_callsite(self, metadata) + } + + #[inline] + fn max_level_hint(&self) -> Option { + EnvFilter::max_level_hint(self) + } + + #[inline] + fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, C>) -> bool { + self.enabled(metadata) + } + + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, C>) { + self.on_new_span(attrs, id) + } + + fn on_record(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, C>) { + if let Some(span) = try_lock!(self.by_id.read()).get(id) { + span.record_update(values); + } + } + + #[inline] + fn on_enter(&self, id: &span::Id, _: Context<'_, C>) { + self.on_enter(id); + } + + #[inline] + fn on_exit(&self, id: &span::Id, _: Context<'_, C>) { + self.on_exit(id); + } + + #[inline] + fn on_close(&self, id: span::Id, _: Context<'_, C>) { + self.on_close(id); + } +} + +feature! { + #![all(feature = "registry", feature = "std")] + + impl subscribe::Filter for EnvFilter { + #[inline] + fn enabled(&self, meta: &Metadata<'_>, _: &Context<'_, C>) -> bool { + self.enabled(meta) + } + + #[inline] + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + self.register_callsite(meta) + } + + #[inline] + fn max_level_hint(&self) -> Option { + EnvFilter::max_level_hint(self) + } + + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, C>) { + self.on_new_span(attrs, id) + } + + #[inline] + fn on_enter(&self, id: &span::Id, _: Context<'_, C>) { + self.on_enter(id); + } + + #[inline] + fn on_exit(&self, id: &span::Id, _: Context<'_, C>) { + self.on_exit(id); + } + + #[inline] + fn on_close(&self, id: span::Id, _: Context<'_, C>) { + self.on_close(id); + } + } +} + impl FromStr for EnvFilter { type Err = directive::ParseError; diff --git a/tracing-subscriber/tests/filter.rs b/tracing-subscriber/tests/env_filter/main.rs similarity index 98% rename from tracing-subscriber/tests/filter.rs rename to tracing-subscriber/tests/env_filter/main.rs index 1d269db95a..3f06594769 100644 --- a/tracing-subscriber/tests/filter.rs +++ b/tracing-subscriber/tests/env_filter/main.rs @@ -1,7 +1,12 @@ #![cfg(feature = "env-filter")] +#[path = "../support.rs"] +mod support; +use self::support::*; + +mod per_subscriber; + use tracing::{self, collect::with_default, Level}; -use tracing_mock::*; use tracing_subscriber::{ filter::{EnvFilter, LevelFilter}, prelude::*, diff --git a/tracing-subscriber/tests/env_filter/per_subscriber.rs b/tracing-subscriber/tests/env_filter/per_subscriber.rs new file mode 100644 index 0000000000..2642151d07 --- /dev/null +++ b/tracing-subscriber/tests/env_filter/per_subscriber.rs @@ -0,0 +1,305 @@ +//! Tests for using `EnvFilter` as a per-subscriber filter (rather than a global +//! `subscriber` filter). +#![cfg(feature = "registry")] +use super::*; + +#[test] +fn level_filter_event() { + let filter: EnvFilter = "info".parse().expect("filter should parse"); + let (subscriber, handle) = subscriber::mock() + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + + let _collect = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + tracing::trace!("this should be disabled"); + tracing::info!("this shouldn't be"); + tracing::debug!(target: "foo", "this should also be disabled"); + tracing::warn!(target: "foo", "this should be enabled"); + tracing::error!("this should be enabled too"); + + handle.assert_finished(); +} + +#[test] +fn same_name_spans() { + let filter: EnvFilter = "[foo{bar}]=trace,[foo{baz}]=trace" + .parse() + .expect("filter should parse"); + let (subscriber, handle) = subscriber::mock() + .new_span( + span::mock() + .named("foo") + .at_level(Level::TRACE) + .with_field(field::mock("bar")), + ) + .new_span( + span::mock() + .named("foo") + .at_level(Level::TRACE) + .with_field(field::mock("baz")), + ) + .done() + .run_with_handle(); + + let _collect = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + tracing::trace_span!("foo", bar = 1); + tracing::trace_span!("foo", baz = 1); + + handle.assert_finished(); +} + +#[test] +fn level_filter_event_with_target() { + let filter: EnvFilter = "info,stuff=debug".parse().expect("filter should parse"); + let (subscriber, handle) = subscriber::mock() + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::DEBUG).with_target("stuff")) + .event(event::mock().at_level(Level::WARN).with_target("stuff")) + .event(event::mock().at_level(Level::ERROR)) + .event(event::mock().at_level(Level::ERROR).with_target("stuff")) + .done() + .run_with_handle(); + + let _collect = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + tracing::trace!("this should be disabled"); + tracing::info!("this shouldn't be"); + tracing::debug!(target: "stuff", "this should be enabled"); + tracing::debug!("but this shouldn't"); + tracing::trace!(target: "stuff", "and neither should this"); + tracing::warn!(target: "stuff", "this should be enabled"); + tracing::error!("this should be enabled too"); + tracing::error!(target: "stuff", "this should be enabled also"); + + handle.assert_finished(); +} + +#[test] +fn level_filter_event_with_target_and_span() { + let filter: EnvFilter = "stuff[cool_span]=debug" + .parse() + .expect("filter should parse"); + + let cool_span = span::named("cool_span"); + let (subscriber, handle) = subscriber::mock() + .enter(cool_span.clone()) + .event( + event::mock() + .at_level(Level::DEBUG) + .in_scope(vec![cool_span.clone()]), + ) + .exit(cool_span) + .done() + .run_with_handle(); + + let _collect = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + { + let _span = tracing::info_span!(target: "stuff", "cool_span").entered(); + tracing::debug!("this should be enabled"); + } + + tracing::debug!("should also be disabled"); + + { + let _span = tracing::info_span!("uncool_span").entered(); + tracing::debug!("this should be disabled"); + } + + handle.assert_finished(); +} + +#[test] +fn not_order_dependent() { + // this test reproduces tokio-rs/tracing#623 + + let filter: EnvFilter = "stuff=debug,info".parse().expect("filter should parse"); + let (subscriber, finished) = subscriber::mock() + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::DEBUG).with_target("stuff")) + .event(event::mock().at_level(Level::WARN).with_target("stuff")) + .event(event::mock().at_level(Level::ERROR)) + .event(event::mock().at_level(Level::ERROR).with_target("stuff")) + .done() + .run_with_handle(); + + let _collect = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + tracing::trace!("this should be disabled"); + tracing::info!("this shouldn't be"); + tracing::debug!(target: "stuff", "this should be enabled"); + tracing::debug!("but this shouldn't"); + tracing::trace!(target: "stuff", "and neither should this"); + tracing::warn!(target: "stuff", "this should be enabled"); + tracing::error!("this should be enabled too"); + tracing::error!(target: "stuff", "this should be enabled also"); + + finished.assert_finished(); +} + +#[test] +fn add_directive_enables_event() { + // this test reproduces tokio-rs/tracing#591 + + // by default, use info level + let mut filter = EnvFilter::new(LevelFilter::INFO.to_string()); + + // overwrite with a more specific directive + filter = filter.add_directive("hello=trace".parse().expect("directive should parse")); + + let (subscriber, finished) = subscriber::mock() + .event(event::mock().at_level(Level::INFO).with_target("hello")) + .event(event::mock().at_level(Level::TRACE).with_target("hello")) + .done() + .run_with_handle(); + + let _collect = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + tracing::info!(target: "hello", "hello info"); + tracing::trace!(target: "hello", "hello trace"); + + finished.assert_finished(); +} + +#[test] +fn span_name_filter_is_dynamic() { + let filter: EnvFilter = "info,[cool_span]=debug" + .parse() + .expect("filter should parse"); + let cool_span = span::named("cool_span"); + let uncool_span = span::named("uncool_span"); + let (subscriber, finished) = subscriber::mock() + .event(event::mock().at_level(Level::INFO)) + .enter(cool_span.clone()) + .event( + event::mock() + .at_level(Level::DEBUG) + .in_scope(vec![cool_span.clone()]), + ) + .enter(uncool_span.clone()) + .event( + event::mock() + .at_level(Level::WARN) + .in_scope(vec![uncool_span.clone()]), + ) + .event( + event::mock() + .at_level(Level::DEBUG) + .in_scope(vec![uncool_span.clone()]), + ) + .exit(uncool_span.clone()) + .exit(cool_span) + .enter(uncool_span.clone()) + .event( + event::mock() + .at_level(Level::WARN) + .in_scope(vec![uncool_span.clone()]), + ) + .event( + event::mock() + .at_level(Level::ERROR) + .in_scope(vec![uncool_span.clone()]), + ) + .exit(uncool_span) + .done() + .run_with_handle(); + + let _collect = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + tracing::trace!("this should be disabled"); + tracing::info!("this shouldn't be"); + let cool_span = tracing::info_span!("cool_span"); + let uncool_span = tracing::info_span!("uncool_span"); + + { + let _enter = cool_span.enter(); + tracing::debug!("i'm a cool event"); + tracing::trace!("i'm cool, but not cool enough"); + let _enter2 = uncool_span.enter(); + tracing::warn!("warning: extremely cool!"); + tracing::debug!("i'm still cool"); + } + + { + let _enter = uncool_span.enter(); + tracing::warn!("warning: not that cool"); + tracing::trace!("im not cool enough"); + tracing::error!("uncool error"); + } + + finished.assert_finished(); +} + +#[test] +fn multiple_dynamic_filters() { + // Test that multiple dynamic (span) filters only apply to the layers + // they're attached to. + let (layer1, handle1) = { + let span = span::named("span1"); + let filter: EnvFilter = "[span1]=debug".parse().expect("filter 1 should parse"); + let (subscriber, handle) = subscriber::named("layer1") + .enter(span.clone()) + .event( + event::mock() + .at_level(Level::DEBUG) + .in_scope(vec![span.clone()]), + ) + .exit(span) + .done() + .run_with_handle(); + (subscriber.with_filter(filter), handle) + }; + + let (layer2, handle2) = { + let span = span::named("span2"); + let filter: EnvFilter = "[span2]=info".parse().expect("filter 2 should parse"); + let (subscriber, handle) = subscriber::named("layer2") + .enter(span.clone()) + .event( + event::mock() + .at_level(Level::INFO) + .in_scope(vec![span.clone()]), + ) + .exit(span) + .done() + .run_with_handle(); + (subscriber.with_filter(filter), handle) + }; + + let _collect = tracing_subscriber::registry() + .with(layer1) + .with(layer2) + .set_default(); + + tracing::info_span!("span1").in_scope(|| { + tracing::debug!("hello from span 1"); + tracing::trace!("not enabled"); + }); + + tracing::info_span!("span2").in_scope(|| { + tracing::info!("hello from span 2"); + tracing::debug!("not enabled"); + }); + + handle1.assert_finished(); + handle2.assert_finished(); +}