core: change Interest-combining to play nicer with multiple subscri…

…bers (#920)

## Motivation

Currently, when multiple subscribers are in use, the way that `Interest`
values are combined results in surprising behavior. 

If _any_ subscriber returns `Interest::always` for a callsite, that
interest currently takes priority over any other `Interest`s. This means
that if two threads have separate subscribers, one of which enables a
callsite `always`, and the other `never`, _both_ subscribers will always
record that callsite, without the option to disable it. This is not
quite right. Instead, we should check whether the current subscriber
will enable that callsite in this case.

## Solution

This branch changes the rules for combining `Interest`s so that `always`
is only returned if _both_ `Interest`s are `always`. If only _one_ is
`always`, the combined interest is now `sometimes`, instead. This means
that when multiple subscribers exist, `enabled` will always be called on
the _current_ subscriber, except when _all_ subscribers have indicated
that they are `always` or `never` interested in a callsite.

I've added tests that reproduce the issues with leaky filters.

Fixing this revealed an additional issue where `tracing-subscriber`'s
`EnvFilter` assumes that `enabled` is only called for events, and never
for spans, because it always returns either `always` or `never` from
`register_callsite` for spans. Therefore, the dynamic span matching
directives that might enable a span were never checked in `enabled`.
However, under the new interest-combining rules, `enabled` *may* still
be called even if a subscriber returns an `always` or `never` interest,
if *another* subscriber exists that returned an incompatible interest.
This PR fixes that, as well.

Depends on #919 

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

tracing-core/src/callsite.rs

@@ -28,13 +28,21 @@ impl Registry {
     fn rebuild_callsite_interest(&self, callsite: &'static dyn Callsite) {
         let meta = callsite.metadata();
 
-        let mut interest = Interest::never();
-
-        for registrar in &self.dispatchers {
-            if let Some(sub_interest) = registrar.try_register(meta) {
-                interest = interest.and(sub_interest);
-            }
-        }
+        // Iterate over the subscribers in the registry, and — if they are
+        // active — register the callsite with them.
+        let mut interests = self
+            .dispatchers
+            .iter()
+            .filter_map(|registrar| registrar.try_register(meta));
+
+        // Use the first subscriber's `Interest` as the base value.
+        let interest = if let Some(interest) = interests.next() {
+            // Combine all remaining `Interest`s.
+            interests.fold(interest, Interest::and)
+        } else {
+            // If nobody was interested in this thing, just return `never`.
+            Interest::never()
+        };
 
         callsite.set_interest(interest)
     }

tracing-core/src/subscriber.rs

@@ -556,24 +556,15 @@ impl Interest {
 
     /// Returns the common interest between these two Interests.
     ///
-    /// The common interest is defined as the least restrictive, so if one
-    /// interest is `never` and the other is `always` the common interest is
-    /// `always`.
+    /// If both interests are the same, this propagates that interest.
+    /// Otherwise, if they differ, the result must always be
+    /// `Interest::sometimes` --- if the two subscribers differ in opinion, we
+    /// will have to ask the current subscriber what it thinks, no matter what.
     pub(crate) fn and(self, rhs: Interest) -> Self {
-        match rhs.0 {
-            // If the added interest is `never()`, don't change anything —
-            // either a different subscriber added a higher interest, which we
-            // want to preserve, or the interest is 0 anyway (as it's
-            // initialized to 0).
-            InterestKind::Never => self,
-            // If the interest is `sometimes()`, that overwrites a `never()`
-            // interest, but doesn't downgrade an `always()` interest.
-            InterestKind::Sometimes if self.0 == InterestKind::Never => rhs,
-            // If the interest is `always()`, we overwrite the current interest,
-            // as always() is the highest interest level and should take
-            // precedent.
-            InterestKind::Always => rhs,
-            _ => self,
+        if self.0 == rhs.0 {
+            self
+        } else {
+            Interest::sometimes()
         }
     }
 }

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

@@ -297,6 +297,19 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
         // if not, we can avoid the thread local access + iterating over the
         // spans in the current scope.
         if self.has_dynamics && self.dynamics.max_level >= *level {
+            if metadata.is_span() {
+                // If the metadata is a span, see if we care about its callsite.
+                let enabled_by_cs = self
+                    .by_cs
+                    .read()
+                    .ok()
+                    .map(|by_cs| by_cs.contains_key(&metadata.callsite()))
+                    .unwrap_or(false);
+                if enabled_by_cs {
+                    return true;
+                }
+            }
+
             let enabled_by_scope = SCOPE.with(|scope| {
                 for filter in scope.borrow().iter() {
                     if filter >= level {
@@ -314,9 +327,6 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
         if self.statics.max_level >= *level {
             // Otherwise, fall back to checking if the callsite is
             // statically enabled.
-            // TODO(eliza): we *might* want to check this only if the `log`
-            // feature is enabled, since if this is a `tracing` event with a
-            // real callsite, it would already have been statically enabled...
             return self.statics.enabled(metadata);
         }
 

tracing/tests/filters_dont_leak.rs

@@ -0,0 +1,80 @@
+#![cfg(feature = "std")]
+
+mod support;
+use self::support::*;
+
+#[test]
+fn spans_dont_leak() {
+    fn do_span() {
+        let span = tracing::debug_span!("alice");
+        let _e = span.enter();
+    }
+
+    let (subscriber, handle) = subscriber::mock()
+        .named("spans/subscriber1")
+        .with_filter(|_| false)
+        .done()
+        .run_with_handle();
+
+    let _guard = tracing::subscriber::set_default(subscriber);
+
+    do_span();
+
+    let alice = span::mock().named("alice");
+    let (subscriber2, handle2) = subscriber::mock()
+        .named("spans/subscriber2")
+        .with_filter(|_| true)
+        .new_span(alice.clone())
+        .enter(alice.clone())
+        .exit(alice.clone())
+        .drop_span(alice)
+        .done()
+        .run_with_handle();
+
+    tracing::subscriber::with_default(subscriber2, || {
+        println!("--- subscriber 2 is default ---");
+        do_span()
+    });
+
+    println!("--- subscriber 1 is default ---");
+    do_span();
+
+    handle.assert_finished();
+    handle2.assert_finished();
+}
+
+#[test]
+fn events_dont_leak() {
+    fn do_event() {
+        tracing::debug!("alice");
+    }
+
+    let (subscriber, handle) = subscriber::mock()
+        .named("events/subscriber1")
+        .with_filter(|_| false)
+        .done()
+        .run_with_handle();
+
+    let _guard = tracing::subscriber::set_default(subscriber);
+
+    do_event();
+
+    let (subscriber2, handle2) = subscriber::mock()
+        .named("events/subscriber2")
+        .with_filter(|_| true)
+        .event(event::mock())
+        .done()
+        .run_with_handle();
+
+    tracing::subscriber::with_default(subscriber2, || {
+        println!("--- subscriber 2 is default ---");
+        do_event()
+    });
+
+    println!("--- subscriber 1 is default ---");
+
+    do_event();
+
+    handle.assert_finished();
+    handle2.assert_finished();
+}