subscriber: fix filter selection regressions (#624)

## Motivation

Recent changes to `tracing-subscriber` (#580 and #583) introduced some
regressions in filter directive selection. In particular, directive
selection appears to depend on the _order_ in which directives were
specified in a env filter string, or on the order in which they were
added using `add_directive`, rather than on specificity. 

This regression is due to the change that switched the storage of filter
directives in `DirectiveSet`s from a `BTreeSet` to a `Vec`. Previously,
the `DirectiveSet::add` and `DirectiveSet::extend` methods both relied
on the inherent ordering of `BTreeSet`s. After changing to a `Vec`, the
`DirectiveSet::add` method was changed to use a binary search to find
the correct position for each directive, and use `Vec::insert` to add
the directive at that position. This is correct behavior. However, the
`Extend` (and therefore also `FromIterator`) implementations _did not
use_ `add_directive` --- instead, they simply called `extend` on the
underlying data structure. This was fine previously, when we could rely
on the sorted nature of `BTreeSet`s, but now, it means that when a
directive set is created from an iterator (such as when parsing a string
with multiple filter directives!), the ordering of the directive set is
based on the iterator's ordering, rather than sorted.

We didn't catch this bug because all of our tests happen to put the
least specific directive first. When the change to using a `Vec` broke
all the existing tests, I was able to "fix" them simply by adding a
`.rev()` call to the iterator, based on the incorrect assumption that we
were always using the sorted insertion order, and that the test failures
were simply due to the binary search inserting in the opposite order as
`BTreeSet`. Adding the `.rev()` call caused issue #591, where a
`DirectiveSet` built by calls to `add_directive` (which _does_ obey the
correct sorting) was not selecting the right filters, since we were
reversing the ordering and picking the least specific directive first.

## Solution

I've changed the `DirectiveSet::extend` method to call `self.add` for
each directive in the iterator. Now, they are inserted at the correct
position. I've also removed the call to `.rev()` so that we iterate 
over the correctly sorted `DirectiveSet` in most-specific-first order.

I've added new tests to reproduce both issue #591 and issue #623, and
confirmed that they both fail prior to this change.

Fixes #591
Fixes #623

Signed-off-by: Eliza Weisman <eliza@buoyant.io>

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

@@ -406,14 +406,19 @@ impl<T: Match + Ord> DirectiveSet<T> {
  self.directives
  .iter()
  .filter(move |d| d.cares_about(metadata))
- .rev()
  }
 
  pub(crate) fn add(&mut self, directive: T) {
+ // does this directive enable a more verbose level than the current
+ // max? if so, update the max level.
  let level = directive.level();
  if *level > self.max_level {
  self.max_level = level.clone();
  }
+ // insert the directive into the vec of directives, ordered by
+ // specificity (length of target + number of field filters). this
+ // ensures that, when finding a directive to match a span or event, we
+ // search the directive set in most specific first order.
  match self.directives.binary_search(&directive) {
  Ok(i) => self.directives[i] = directive,
  Err(i) => self.directives.insert(i, directive),
@@ -431,14 +436,9 @@ impl<T: Match + Ord> FromIterator<T> for DirectiveSet<T> {
 
 impl<T: Match + Ord> Extend<T> for DirectiveSet<T> {
  fn extend<I: IntoIterator<Item = T>>(&mut self, iter: I) {
- let max_level = &mut self.max_level;
- let ds = iter.into_iter().inspect(|d| {
- let level = d.level();
- if *level > *max_level {
- *max_level = level.clone();
- }
- });
- self.directives.extend(ds);
+ for directive in iter.into_iter() {
+ self.add(directive);
+ }
  }
 }
 

tracing-subscriber/tests/filter.rs

@@ -1,7 +1,10 @@
 mod support;
 use self::support::*;
 use tracing::{self, subscriber::with_default, Level};
-use tracing_subscriber::{filter::EnvFilter, prelude::*};
+use tracing_subscriber::{
+ filter::{EnvFilter, LevelFilter},
+ prelude::*,
+};
 
 #[test]
 fn level_filter_event() {
@@ -81,6 +84,60 @@ fn level_filter_event_with_target() {
  finished.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 subscriber = subscriber.with(filter);
+
+ with_default(subscriber, || {
+ 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 subscriber = subscriber.with(filter);
+
+ with_default(subscriber, || {
+ 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"