subscriber: increase EnvFilter test coverage

With a view to replacing the env filter parsing in #3243, this change
adds some additional tests to improve our confidence in not breaking
existing behavior. Tests for empty and invalid directives is added, as
well as tests for directives overriding less specific directives.

One of the latter tests (`more_specific_dynamic_filter_less_verbose`)
currently fails, which is a known issue reported in #1388. The test is
in place with `#[should_panic]` and can be reverted to a normal test
when that behavior is fixed.

The documentation on `parse`, `parse_lossy`, `from_env_lossy` and
`try_from_env` has also been made more explicit as to the result of an
empty directive (the default directive is used). This was already
documented on `with_default_directive`.

Author: hds

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

@@ -133,6 +133,11 @@ impl Builder {
 
     /// Returns a new [`EnvFilter`] from the directives in the given string,
     /// *ignoring* any that are invalid.
+    ///
+    /// If `parse_lossy` is called with an empty string, then the
+    /// [default directive] is used instead.
+    ///
+    /// [default directive]: Self::with_default_directive
     pub fn parse_lossy<S: AsRef<str>>(&self, dirs: S) -> EnvFilter {
         let directives = dirs
             .as_ref()
@@ -150,6 +155,11 @@ impl Builder {
 
     /// Returns a new [`EnvFilter`] from the directives in the given string,
     /// or an error if any are invalid.
+    ///
+    /// If `parse` is called with an empty string, then the [default directive]
+    /// is used instead.
+    ///
+    /// [default directive]: Self::with_default_directive
     pub fn parse<S: AsRef<str>>(&self, dirs: S) -> Result<EnvFilter, directive::ParseError> {
         let dirs = dirs.as_ref();
         if dirs.is_empty() {
@@ -165,6 +175,11 @@ impl Builder {
 
     /// Returns a new [`EnvFilter`] from the directives in the configured
     /// environment variable, ignoring any directives that are invalid.
+    ///
+    /// If the environment variable is empty, then the [default directive]
+    /// is used instead.
+    ///
+    /// [default directive]: Self::with_default_directive
     pub fn from_env_lossy(&self) -> EnvFilter {
         let var = env::var(self.env_var_name()).unwrap_or_default();
         self.parse_lossy(var)
@@ -174,6 +189,11 @@ impl Builder {
     /// environment variable. If the environment variable is unset, no directive is added.
     ///
     /// An error is returned if the environment contains invalid directives.
+    ///
+    /// If the environment variable is empty, then the [default directive]
+    /// is used instead.
+    ///
+    /// [default directive]: Self::with_default_directive
     pub fn from_env(&self) -> Result<EnvFilter, FromEnvError> {
         let var = env::var(self.env_var_name()).unwrap_or_default();
         self.parse(var).map_err(Into::into)
@@ -182,6 +202,11 @@ impl Builder {
     /// Returns a new [`EnvFilter`] from the directives in the configured
     /// environment variable, or an error if the environment variable is not set
     /// or contains invalid directives.
+    ///
+    /// If the environment variable is empty, then the [default directive]
+    /// is used instead.
+    ///
+    /// [default directive]: Self::with_default_directive
     pub fn try_from_env(&self) -> Result<EnvFilter, FromEnvError> {
         let var = env::var(self.env_var_name())?;
         self.parse(var).map_err(Into::into)

tracing-subscriber/tests/env_filter/main.rs

@@ -195,3 +195,210 @@ fn method_name_resolution() {
     let filter = EnvFilter::new("hello_world=info");
     filter.max_level_hint();
 }
+
+#[test]
+fn parse_invalid_string() {
+    assert!(EnvFilter::builder().parse(",!").is_err());
+}
+
+#[test]
+fn parse_empty_string_no_default_directive() {
+    let filter = EnvFilter::builder().parse("").expect("filter should parse");
+    let (collector, finished) = collector::mock().only().run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::trace!("this should be disabled");
+        tracing::debug!("this should be disabled");
+        tracing::info!("this should be disabled");
+        tracing::warn!("this should be disabled");
+        tracing::error!("this should be disabled");
+    });
+
+    finished.assert_finished();
+}
+
+#[test]
+fn parse_empty_string_with_default_directive() {
+    let filter = EnvFilter::builder()
+        .with_default_directive(LevelFilter::INFO.into())
+        .parse("")
+        .expect("filter should parse");
+    let (collector, finished) = collector::mock()
+        .event(expect::event().at_level(Level::INFO))
+        .event(expect::event().at_level(Level::WARN))
+        .event(expect::event().at_level(Level::ERROR))
+        .only()
+        .run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::trace!("this should be disabled");
+        tracing::debug!("this should be disabled");
+        tracing::info!("this shouldn't be disabled");
+        tracing::warn!("this shouldn't be disabled");
+        tracing::error!("this shouldn't be disabled");
+    });
+
+    finished.assert_finished();
+}
+
+#[test]
+fn new_invalid_string() {
+    let filter = EnvFilter::new(",!");
+    let (collector, finished) = collector::mock()
+        .event(expect::event().at_level(Level::ERROR))
+        .only()
+        .run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::trace!("this should be disabled");
+        tracing::debug!("this should be disabled");
+        tracing::info!("this should be disabled");
+        tracing::warn!("this should be disabled");
+        tracing::error!("this shouldn't be disabled");
+    });
+
+    finished.assert_finished();
+}
+
+#[test]
+fn new_empty_string() {
+    let filter = EnvFilter::new("");
+    let (collector, finished) = collector::mock()
+        .event(expect::event().at_level(Level::ERROR))
+        .only()
+        .run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::trace!("this should be disabled");
+        tracing::debug!("this should be disabled");
+        tracing::info!("this should be disabled");
+        tracing::warn!("this should be disabled");
+        tracing::error!("this shouldn't be disabled");
+    });
+
+    finished.assert_finished();
+}
+
+#[test]
+fn more_specific_static_filter_more_verbose() {
+    let filter = EnvFilter::new("info,hello=debug");
+    let (collector, finished) = collector::mock()
+        .event(expect::event().at_level(Level::INFO))
+        .event(expect::event().at_level(Level::DEBUG).with_target("hello"))
+        .only()
+        .run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::info!("should be enabled");
+        tracing::debug!("should be disabled");
+        tracing::debug!(target: "hello", "should be enabled");
+    });
+
+    finished.assert_finished();
+}
+
+#[test]
+fn more_specific_static_filter_less_verbose() {
+    let filter = EnvFilter::new("info,hello=warn");
+    let (collector, finished) = collector::mock()
+        .event(expect::event().at_level(Level::INFO))
+        .event(
+            expect::event()
+                .at_level(Level::WARN)
+                .with_target("env_filter"),
+        )
+        .only()
+        .run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::info!("should be enabled");
+        tracing::warn!("should be enabled");
+        tracing::info!(target: "hello", "should be disabled");
+    });
+
+    finished.assert_finished();
+}
+
+#[test]
+fn more_specific_dynamic_filter_more_verbose() {
+    let filter = EnvFilter::new("info,[{hello=4}]=debug");
+    let (collector, finished) = collector::mock()
+        .new_span(expect::span().at_level(Level::INFO))
+        .drop_span("enabled info")
+        .new_span(
+            expect::span()
+                .at_level(Level::DEBUG)
+                .with_fields(expect::field("hello").with_value(&4_u64)),
+        )
+        .drop_span("enabled debug")
+        .event(expect::event().with_fields(expect::msg("marker")))
+        .only()
+        .run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::info_span!("enabled info");
+        tracing::debug_span!("disabled debug");
+        tracing::debug_span!("enabled debug", hello = &4_u64);
+
+        // .only() doesn't work when we don't enter/exit spans
+        tracing::info!("marker");
+    });
+
+    finished.assert_finished();
+}
+
+/// This is a negative test. This functionality should work, but doesn't.
+///
+/// If an improvement to `EnvFilter` fixes this test, then the `#[should_panic]`
+/// can be removed and the test kept as it is. If the test requires some sort of
+/// modification, then care should be taken.
+///
+/// Fixing this test would resolve https://github.com/tokio-rs/tracing/issues/1388
+/// (and probably a few more issues as well).
+#[test]
+#[should_panic(
+    expected = "[more_specific_dynamic_filter_less_verbose] expected a new span \
+    at level `Level(Warn)`,\n[more_specific_dynamic_filter_less_verbose] but \
+    got one at level `Level(Info)` instead."
+)]
+fn more_specific_dynamic_filter_less_verbose() {
+    let filter = EnvFilter::new("info,[{hello=4}]=warn");
+    let (collector, finished) = collector::mock()
+        .new_span(expect::span().at_level(Level::INFO))
+        .drop_span("enabled info")
+        .new_span(
+            expect::span()
+                .at_level(Level::WARN)
+                .with_fields(expect::field("hello").with_value(&100_u64)),
+        )
+        .drop_span("enabled hello=100 warn")
+        .new_span(
+            expect::span()
+                .at_level(Level::WARN)
+                .with_fields(expect::field("hello").with_value(&4_u64)),
+        )
+        .drop_span("enabled hello=4 warn")
+        .event(expect::event().with_fields(expect::msg("marker")))
+        .only()
+        .run_with_handle();
+    let subscriber = collector.with(filter);
+
+    with_default(subscriber, || {
+        tracing::info_span!("enabled info");
+        tracing::warn_span!("enabled hello=100 warn", hello = &100_u64);
+        tracing::info_span!("disabled hello=4 info", hello = &4_u64);
+        tracing::warn_span!("enabled hello=4 warn", hello = &4_u64);
+
+        // .only() doesn't work when we don't enter/exit spans
+        tracing::info!("marker");
+    });
+
+    finished.assert_finished();
+}