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 <[email protected]>
tokio-rs · Mar 29, 2022 · d0a73e2 · d0a73e2
1 parent 7e4724d
commit d0a73e2
Show file tree

Hide file tree

Showing 5 changed files with 497 additions and 43 deletions.
diff --git a/tracing-mock/src/span.rs b/tracing-mock/src/span.rs
@@ -24,6 +24,13 @@ pub fn mock() -> MockSpan {
     }
 }
 
+pub fn named<I>(name: I) -> MockSpan
+where
+    I: Into<String>,
+{
+    mock().named(name)
+}
+
 impl MockSpan {
     pub fn named<I>(self, name: I) -> Self
     where

diff --git 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
@@ -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<C>) 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::subscriber())
+///     .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::subscriber())
+///     .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 subscriber *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<C>
+/// [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<HashMap<span::Id, directive::SpanMatcher>>,
     by_cs: RwLock<HashMap<callsite::Identifier, directive::CallsiteMatcher>>,
-}
-
-thread_local! {
-    static SCOPE: RefCell<Vec<LevelFilter>> = RefCell::new(Vec::new());
+    scope: ThreadLocal<RefCell<Vec<LevelFilter>>>,
 }
 
 type FieldMap<T> = HashMap<Field, T>;
@@ -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<C: Collect> Subscribe<C> 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<C: Collect> Subscribe<C> for EnvFilter {
         }
     }
 
-    fn max_level_hint(&self) -> Option<LevelFilter> {
-        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<C: Collect> Subscribe<C> 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,36 +487,43 @@ impl<C: Collect> Subscribe<C> for EnvFilter {
         false
     }
 
-    fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, C>) {
+    fn max_level_hint(&self) -> Option<LevelFilter> {
+        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);
             try_lock!(self.by_id.write()).insert(id.clone(), span);
         }
     }
 
-    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<C: Collect> Subscribe<C> for EnvFilter {
     }
 }
 
+impl<C: Collect> Subscribe<C> for EnvFilter {
+    #[inline]
+    fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
+        EnvFilter::register_callsite(self, metadata)
+    }
+
+    #[inline]
+    fn max_level_hint(&self) -> Option<LevelFilter> {
+        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<C> subscribe::Filter<C> 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<LevelFilter> {
+            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 → tracing-subscriber/tests/env_filter/main.rs b/tracing-subscriber/tests/filter.rs → 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::*,