subscriber: impl Filter for EnvFilter (tokio-rs#1983)

Filtering by span and field requires using `EnvFilter` rather than
`Targets`. Per-layer filtering requires the `Filter` trait, which
`EnvFilter` does not implement.

Implement the `Filter` trait for `EnvFilter`. PR tokio-rs#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-layer filters don't share a single span scope.

Fixes tokio-rs#1868
Follow-up on tokio-rs#1973

Co-authored-by: Eliza Weisman <[email protected]>

Author: 2 people

tracing-subscriber/src/filter/env/mod.rs

@@ -586,8 +586,35 @@ impl EnvFilter {
             return;
         }
 
-        let mut spans = try_lock!(self.by_id.write());
-        spans.remove(&id);
+        #[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<'_, S>) {
+            self.on_new_span(attrs, id)
+        }
+
+        #[inline]
+        fn on_enter(&self, id: &span::Id, _: Context<'_, S>) {
+            self.on_enter(id);
+        }
+
+        #[inline]
+        fn on_exit(&self, id: &span::Id, _: Context<'_, S>) {
+            self.on_exit(id);
+        }
+
+        #[inline]
+        fn on_close(&self, id: span::Id, _: Context<'_, S>) {
+            self.on_close(id);
+        }
     }
 
     /// Informs the filter that the span with the provided `id` recorded the

tracing-subscriber/tests/env_filter/per_layer.rs

@@ -0,0 +1,305 @@
+//! Tests for using `EnvFilter` as a per-layer filter (rather than a global
+//! `Layer` filter).
+#![cfg(feature = "registry")]
+use super::*;
+
+#[test]
+fn level_filter_event() {
+    let filter: EnvFilter = "info".parse().expect("filter should parse");
+    let (layer, handle) = layer::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 _subscriber = tracing_subscriber::registry()
+        .with(layer.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 (layer, handle) = layer::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 _subscriber = tracing_subscriber::registry()
+        .with(layer.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 (layer, handle) = layer::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 _subscriber = tracing_subscriber::registry()
+        .with(layer.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 (layer, handle) = layer::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 _subscriber = tracing_subscriber::registry()
+        .with(layer.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 (layer, finished) = layer::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 _subscriber = tracing_subscriber::registry()
+        .with(layer.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 (layer, finished) = layer::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 _subscriber = tracing_subscriber::registry()
+        .with(layer.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 (layer, finished) = layer::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 _subscriber = tracing_subscriber::registry()
+        .with(layer.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 (layer, handle) = layer::named("layer1")
+            .enter(span.clone())
+            .event(
+                event::mock()
+                    .at_level(Level::DEBUG)
+                    .in_scope(vec![span.clone()]),
+            )
+            .exit(span)
+            .done()
+            .run_with_handle();
+        (layer.with_filter(filter), handle)
+    };
+
+    let (layer2, handle2) = {
+        let span = span::named("span2");
+        let filter: EnvFilter = "[span2]=info".parse().expect("filter 2 should parse");
+        let (layer, handle) = layer::named("layer2")
+            .enter(span.clone())
+            .event(
+                event::mock()
+                    .at_level(Level::INFO)
+                    .in_scope(vec![span.clone()]),
+            )
+            .exit(span)
+            .done()
+            .run_with_handle();
+        (layer.with_filter(filter), handle)
+    };
+
+    let _subscriber = 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();
+}

tracing/tests/support/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