From 13a525dbe4b3bba965b585db198f1ecd347455d9 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Wed, 23 Mar 2022 12:30:52 -0700 Subject: [PATCH] subscriber: implement per-subscriber filtering (#1523) ## Motivation Currently, filtering with `Subscribe`s is always _global_. If a `Subscribe` performs filtering, it will disable a span or event for _all_ subscribers that compose the current subscriber. In some cases, however, it is often desirable for individual subscribers to see different spans or events than the rest of the `Subscribe` stack. Issues in other projects, such as tokio-rs/console#64 and tokio-rs/console#76, linkerd/linkerd2-proxy#601, influxdata/influxdb_iox#1012 and influxdata/influxdb_iox#1681, jackwaudby/spaghetti#86, etc; as well as `tracing` feature requests like #302, #597, and #1348, all indicate that there is significant demand for the ability to add filters to individual `Subscribe`s. Unfortunately, doing this nicely is somewhat complicated. Although a naive implementation that simply skips events/spans in `Subscribe::on_event` and `Subscribe::new_span` based on some filter is relatively simple, this wouldn't really be an ideal solution, for a number of reasons. A proper per-subscriber filtering implementation would satisfy the following _desiderata_: * If a per-subscriber filter disables a span, it shouldn't be present _for the subscriber that filter is attached to_ when iterating over span contexts (such as `Context::event_scope`, `SpanRef::scope`, etc), or when looking up a span's parents. * When _all_ per-subscriber filters disable a span or event, it should be completely disabled, rather than simply skipped by those particular subscribers. This means that per-subscriber filters should participate in `enabled`, as well as being able to skip spans and events in `new_span` and `on_event`. * Per-subscriber filters shouldn't interfere with non-filtered `Subscribe`s. If a subscriber contains subscribers without any filters, as well as subscribers with per-subscriber filters, the non-filtered `Subscribe`s should behave exactly as they would without any per-subscriber filters present. * Similarly, per-subscriber filters shouldn't interfere with global filtering. If a `Subscribe` in a stack is performing global filtering (e.g. the current filtering behavior), per-subscriber filters should also be effected by the global filter. * Per-subscriber filters _should_ be able to participate in `Interest` caching, _but only when doing so doesn't interfere with non-per-subscriber-filtered subscribers_. * Per-subscriber filters should be _tree-shaped_. If a `Subscriber` consists of multiple subscribers that have been `Subscribeed` together to form new `Subscribe`s, and some of the `Subscribeed` subscribers have per-subscriber filters, those per-subscriber filters should effect all subscribers in that subtree. Similarly, if `Subscribe`s in a per-subscriber filtered subtree have their _own_ per-subscriber filters, those subscribers should be effected by the union of their own filters and any per-subscriber filters that wrap them at higher levels in the tree. Meeting all these requirements means that implementing per-subscriber filtering correctly is somewhat more complex than simply skipping events and spans in a `Subscribe`'s `on_event` and `new_span` callbacks. ## Solution This branch has a basic working implementation of per-subscriber filtering for `tracing-subscriber` v0.2. It should be possible to add this in a point release without a breaking change --- in particular, the new per-subscriber filtering feature _doesn't_ interfere with the global filtering behavior that subscribers currently have when not using the new per-subscriber filtering APIs, so existing configurations should all behave exactly as they do now. ### Implementation The new per-subscriber filtering API consists of a `Filter` trait that defines a filtering strategy and a `Filtered` type that combines a `Filter` with a `Subscribe`. When `enabled` is called on a `Filtered` subscriber, it checks the metadata against the `Filter` and stores whether that filter enabled the span/event in a thread-local cell. If every per-subscriber filter disables a span/event, and there are no non-per-subscriber-filtered subscribers in use, the `Registry`'s `enabled` will return `false`. Otherwise, when the span/event is recorded, each `Filtered` subscriber's `on_event` and `new_span` method checks with the `Registry` to see whether _it_ enabled or disabled that span/event, and skips passing it to the wrapped subscriber if it was disabled. When a span is recorded, the `Registry` which filters disabled it, so that they can skip it when looking up spans in other callbacks. A new `on_subscriber` method was added to the `Subscribe` trait, which allows running a callback when adding a `Subscribe` to a `Subscriber`. This allows mutating both the `Subscribe` and the `Subscriber`, since they are both passed by value when subscribering a `Subscribe` onto a `Subscriber`, and a new `register_filter` method was added to `LookupSpan`, which returns a `FilterId` type. When a `Filtered` subscriber is added to a subscriber that implements `LookupSpan`, it calls `register_filter` in its `on_subscriber` hook to generate a unique ID for its filter. `FilterId` can be used to look up whether a span or event was enabled by the `Filtered` subscriber. Internally, the filter results are stored in a simple bitset to reduce the performance overhead of adding per-subscriber filtering as much as possible. The `FilterId` type is actually a bitmask that's used to set the bit corresponding to a `Filtered` subscriber in that bitmap when it disables a span or event, and check whether the bit is set when querying if a span or event was disabled. Setting a bit in the bitset and testing whether its set is extremely efficient --- it's just a couple of bitwise ops. Additionally, the "filter map" that tracks which filters disabled a span or event is just a single `u64` --- we don't need to allocate a costly `HashSet` or similar every time we want to filter an event. This *does* mean that we are limited to 64 unique filters per `Registry`...however, I would be _very_ surprised if anyone _ever_ builds a subscriber with 64 subscribers, let alone 64 separate per-subscriber filters. Additionally, the `Context` and `SpanRef` types now also potentially carry `FilterId`s, so that they can filter span lookups and span traversals for `Filtered` subscribers. When `Filtered` subscribers are nested using the `Subscribeed`, the `Context` _combines_ the filter ID of the inner and outer subscribers so that spans can be skipped if they were disabled by either. Finally, an implementation of the `Filter` trait was added for `LevelFilter`, and new `FilterFn` and `DynFilterFn` structs were added to produce a `Filter` implementation from a function pointer or closure. ### Notes Some other miscellaneous factors to consider when reviewing this change include: * I did a bit of unrelated refactoring in the `subscriber` module. Since we were adding more code to the `Subscribe` module (the `Filter` trait), the `subscriber.rs` file got significantly longer and was becoming somewhat hard to navigate. Therefore, I split out the `Context` and `Subscribeed` types into their own files. Most of the code in those files is the same as it was before, although some of it was changed in order to support per-subscriber filtering. Apologies in advance to reviewers for this... * In order to test this change, I added some new test-support code in `tracing-subscriber`. The `tracing` test support code provides a `Subscriber` implementation that can be configured to expect a particular set of spans and events, and assert that they occurred as expected. In order to test per-subscriber filtering, I added a new `Subscribe` implementation that does the same thing, but implements `Subscribe` rather than `Subscriber`. This allows testing per-subscriber filter behavior in the same way we test global filter behavior. Reviewers should feel free to just skim the test the test support changes, or skip reviewing them entirely. ## Future Work There is a bunch of additional stuff we can do once this change lands. In order to limit the size of this PR, I didn't make these changes yet, but once this merges, we will want to consider some important follow up changes: * [ ] Currently, _only_ `tracing-subscriber`'s `Registry` is capable of serving as a root subscriber for per-subscriber filters. This is in order to avoid stabilizing a lot of the per-subscriber filtering design as public API without taking the time to ensure there are no serious issues. In the future, we will want to add new APIs to allow users to implement their own root `Subscriber`s that can host subscribers with per-subscriber filtering. * [ ] The `EnvFilter` type doesn't implement the `Filter` trait and thus cannot currently be used as a per-subscriber filter. We should add an implementation of `Filter` for `EnvFilter`. * [ ] The new `FilterFn` and `DynFilterFn` types could conceivably _also_ be used as global filters. We could consider adding `Subscribe` implementations to allow them to be used for global filtering. * [ ] We could consider adding new `Filter` implementations for performing common filtering predicates. For example, "only enable spans/events with a particular target or a set of targets", "only enable spans", "only enable events", etc. Then, we could add a combinator API to combine these predicates to build new filters. * [ ] It would be nice if the `Interest` system could be used to cache the result of multiple individual per-subscriber filter evaluations, so that we don't need to always use `enabled` when there are several per-subscriber filters that disagree on whether or not they want a given span/event. There are a lot of unused bits in `Interest` that could potentially be used for this purpose. However, this would require new API changes in `tracing-core`, and is therefore out of scope for this PR. Closes #302 Closes #597 Closes #1348 Signed-off-by: Eliza Weisman --- tracing-mock/src/collector.rs | 197 +-- tracing-mock/src/event.rs | 81 +- tracing-mock/src/field.rs | 48 +- tracing-mock/src/lib.rs | 72 +- tracing-mock/src/metadata.rs | 18 +- tracing-mock/src/span.rs | 86 +- tracing-subscriber/src/filter/mod.rs | 54 +- .../src/filter/subscriber_filters.rs | 1452 ++++++++++++++++ tracing-subscriber/src/lib.rs | 42 +- tracing-subscriber/src/registry/mod.rs | 166 +- tracing-subscriber/src/registry/sharded.rs | 47 +- tracing-subscriber/src/registry/stack.rs | 14 +- tracing-subscriber/src/reload.rs | 4 + tracing-subscriber/src/subscribe.rs | 1468 ----------------- tracing-subscriber/src/subscribe/context.rs | 499 ++++++ tracing-subscriber/src/subscribe/layered.rs | 465 ++++++ tracing-subscriber/src/subscribe/mod.rs | 1197 ++++++++++++++ tracing-subscriber/src/subscribe/tests.rs | 328 ++++ ...d_layer_filters_dont_break_other_layers.rs | 123 ++ ...d_layer_filters_dont_break_other_layers.rs | 133 ++ .../layer_filter_interests_are_cached.rs | 69 + .../tests/layer_filters/combinators.rs | 42 + .../tests/layer_filters/filter_scopes.rs | 131 ++ .../tests/layer_filters/main.rs | 185 +++ .../tests/layer_filters/trees.rs | 146 ++ .../multiple_layer_filter_interests_cached.rs | 131 ++ tracing-subscriber/tests/support.rs | 407 +++++ ...d_layer_filters_dont_break_other_layers.rs | 123 ++ tracing-subscriber/tests/utils.rs | 2 +- tracing/tests/event.rs | 16 +- tracing/tests/support/mod.rs | 84 + 31 files changed, 6155 insertions(+), 1675 deletions(-) create mode 100644 tracing-subscriber/src/filter/subscriber_filters.rs delete mode 100644 tracing-subscriber/src/subscribe.rs create mode 100644 tracing-subscriber/src/subscribe/context.rs create mode 100644 tracing-subscriber/src/subscribe/layered.rs create mode 100644 tracing-subscriber/src/subscribe/mod.rs create mode 100644 tracing-subscriber/src/subscribe/tests.rs create mode 100644 tracing-subscriber/tests/cached_layer_filters_dont_break_other_layers.rs create mode 100644 tracing-subscriber/tests/hinted_layer_filters_dont_break_other_layers.rs create mode 100644 tracing-subscriber/tests/layer_filter_interests_are_cached.rs create mode 100644 tracing-subscriber/tests/layer_filters/combinators.rs create mode 100644 tracing-subscriber/tests/layer_filters/filter_scopes.rs create mode 100644 tracing-subscriber/tests/layer_filters/main.rs create mode 100644 tracing-subscriber/tests/layer_filters/trees.rs create mode 100644 tracing-subscriber/tests/multiple_layer_filter_interests_cached.rs create mode 100644 tracing-subscriber/tests/support.rs create mode 100644 tracing-subscriber/tests/unhinted_layer_filters_dont_break_other_layers.rs create mode 100644 tracing/tests/support/mod.rs diff --git a/tracing-mock/src/collector.rs b/tracing-mock/src/collector.rs index c1536648dd..48c8bb49dc 100644 --- a/tracing-mock/src/collector.rs +++ b/tracing-mock/src/collector.rs @@ -3,7 +3,6 @@ use super::{ event::MockEvent, field as mock_field, span::{MockSpan, NewSpan}, - Parent, }; use std::{ collections::{HashMap, VecDeque}, @@ -22,7 +21,7 @@ use tracing::{ }; #[derive(Debug, Eq, PartialEq)] -enum Expect { +pub enum Expect { Event(MockEvent), Enter(MockSpan), Exit(MockSpan), @@ -221,7 +220,8 @@ where if let Some(name) = expected_span.name() { assert_eq!(name, span.name); } - let mut checker = expected_values.checker(format!("span {}: ", span.name)); + let context = format!("span {}: ", span.name); + let mut checker = expected_values.checker(&context, &self.name); values.record(&mut checker); checker.finish(); } @@ -234,69 +234,18 @@ where match self.expected.lock().unwrap().pop_front() { None => {} Some(Expect::Event(mut expected)) => { - let spans = self.spans.lock().unwrap(); - expected.check(event); - match expected.parent { - Some(Parent::ExplicitRoot) => { - assert!( - event.is_root(), - "[{}] expected {:?} to be an explicit root event", - self.name, - name - ); - } - Some(Parent::Explicit(expected_parent)) => { - let actual_parent = - event.parent().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have explicit parent {:?}", - self.name, - name, - expected_parent, - ); - } - Some(Parent::ContextualRoot) => { - assert!( - event.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - assert!( - self.current.lock().unwrap().last().is_none(), - "[{}] expected {:?} to be a root, but we were inside a span", - self.name, - name - ); - } - Some(Parent::Contextual(expected_parent)) => { - assert!( - event.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - let stack = self.current.lock().unwrap(); - let actual_parent = - stack.last().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have contextual parent {:?}", - self.name, - name, - expected_parent, - ); - } - None => {} - } + let get_parent_name = || { + let stack = self.current.lock().unwrap(); + let spans = self.spans.lock().unwrap(); + event + .parent() + .and_then(|id| spans.get(id)) + .or_else(|| stack.last().and_then(|id| spans.get(id))) + .map(|s| s.name.to_string()) + }; + expected.check(event, get_parent_name, &self.name); } - Some(ex) => ex.bad( - &self.name, - format_args!("[{}] observed event {:?}", self.name, event), - ), + Some(ex) => ex.bad(&self.name, format_args!("observed event {:#?}", event)), } } @@ -320,70 +269,14 @@ where let mut spans = self.spans.lock().unwrap(); if was_expected { if let Expect::NewSpan(mut expected) = expected.pop_front().unwrap() { - let name = meta.name(); - expected - .span - .metadata - .check(meta, format_args!("span `{}`", name)); - let mut checker = expected.fields.checker(name.to_string()); - span.record(&mut checker); - checker.finish(); - match expected.parent { - Some(Parent::ExplicitRoot) => { - assert!( - span.is_root(), - "[{}] expected {:?} to be an explicit root span", - self.name, - name - ); - } - Some(Parent::Explicit(expected_parent)) => { - let actual_parent = - span.parent().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have explicit parent {:?}", - self.name, - name, - expected_parent, - ); - } - Some(Parent::ContextualRoot) => { - assert!( - span.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - assert!( - self.current.lock().unwrap().last().is_none(), - "[{}] expected {:?} to be a root, but we were inside a span", - self.name, - name - ); - } - Some(Parent::Contextual(expected_parent)) => { - assert!( - span.is_contextual(), - "[{}] expected {:?} to have a contextual parent", - self.name, - name - ); - let stack = self.current.lock().unwrap(); - let actual_parent = - stack.last().and_then(|id| spans.get(id)).map(|s| s.name); - assert_eq!( - Some(expected_parent.as_ref()), - actual_parent, - "[{}] expected {:?} to have contextual parent {:?}", - self.name, - name, - expected_parent, - ); - } - None => {} - } + let get_parent_name = || { + let stack = self.current.lock().unwrap(); + span.parent() + .and_then(|id| spans.get(id)) + .or_else(|| stack.last().and_then(|id| spans.get(id))) + .map(|s| s.name.to_string()) + }; + expected.check(span, get_parent_name, &self.name); } } spans.insert( @@ -537,11 +430,15 @@ where } impl MockHandle { + pub fn new(expected: Arc>>, name: String) -> Self { + Self(expected, name) + } + pub fn assert_finished(&self) { if let Ok(ref expected) = self.0.lock() { assert!( !expected.iter().any(|thing| thing != &Expect::Nothing), - "[{}] more notifications expected: {:?}", + "\n[{}] more notifications expected: {:#?}", self.1, **expected ); @@ -550,26 +447,44 @@ impl MockHandle { } impl Expect { - fn bad(&self, name: impl AsRef, what: fmt::Arguments<'_>) { + pub fn bad(&self, name: impl AsRef, what: fmt::Arguments<'_>) { let name = name.as_ref(); match self { - Expect::Event(e) => panic!("[{}] expected event {}, but {} instead", name, e, what,), - Expect::Enter(e) => panic!("[{}] expected to enter {} but {} instead", name, e, what,), - Expect::Exit(e) => panic!("[{}] expected to exit {} but {} instead", name, e, what,), + Expect::Event(e) => panic!( + "\n[{}] expected event {}\n[{}] but instead {}", + name, e, name, what, + ), + Expect::Enter(e) => panic!( + "\n[{}] expected to enter {}\n[{}] but instead {}", + name, e, name, what, + ), + Expect::Exit(e) => panic!( + "\n[{}] expected to exit {}\n[{}] but instead {}", + name, e, name, what, + ), Expect::CloneSpan(e) => { - panic!("[{}] expected to clone {} but {} instead", name, e, what,) + panic!( + "\n[{}] expected to clone {}\n[{}] but instead {}", + name, e, name, what, + ) } Expect::DropSpan(e) => { - panic!("[{}] expected to drop {} but {} instead", name, e, what,) + panic!( + "\n[{}] expected to drop {}\n[{}] but instead {}", + name, e, name, what, + ) } Expect::Visit(e, fields) => panic!( - "[{}] expected {} to record {} but {} instead", - name, e, fields, what, + "\n[{}] expected {} to record {}\n[{}] but instead {}", + name, e, fields, name, what, + ), + Expect::NewSpan(e) => panic!( + "\n[{}] expected {}\n[{}] but instead {}", + name, e, name, what ), - Expect::NewSpan(e) => panic!("[{}] expected {} but {} instead", name, e, what), Expect::Nothing => panic!( - "[{}] expected nothing else to happen, but {} instead", - name, what, + "\n[{}] expected nothing else to happen\n[{}] but {} instead", + name, name, what, ), } } diff --git a/tracing-mock/src/event.rs b/tracing-mock/src/event.rs index 8ce36a25bc..d16f276678 100644 --- a/tracing-mock/src/event.rs +++ b/tracing-mock/src/event.rs @@ -1,5 +1,5 @@ #![allow(missing_docs)] -use super::{field, metadata, Parent}; +use super::{field, metadata, span, Parent}; use std::fmt; @@ -7,10 +7,11 @@ use std::fmt; /// /// This is intended for use with the mock subscriber API in the /// `subscriber` module. -#[derive(Debug, Default, Eq, PartialEq)] +#[derive(Default, Eq, PartialEq)] pub struct MockEvent { pub fields: Option, pub(crate) parent: Option, + in_spans: Vec, metadata: metadata::Expect, } @@ -20,6 +21,10 @@ pub fn mock() -> MockEvent { } } +pub fn msg(message: impl fmt::Display) -> MockEvent { + mock().with_fields(field::msg(message)) +} + impl MockEvent { pub fn named(self, name: I) -> Self where @@ -78,17 +83,49 @@ impl MockEvent { } } - pub(crate) fn check(&mut self, event: &tracing::Event<'_>) { + pub fn check( + &mut self, + event: &tracing::Event<'_>, + get_parent_name: impl FnOnce() -> Option, + collector_name: &str, + ) { let meta = event.metadata(); let name = meta.name(); self.metadata - .check(meta, format_args!("event \"{}\"", name)); - assert!(meta.is_event(), "expected {}, but got {:?}", self, event); + .check(meta, format_args!("event \"{}\"", name), collector_name); + assert!( + meta.is_event(), + "[{}] expected {}, but got {:?}", + collector_name, + self, + event + ); if let Some(ref mut expected_fields) = self.fields { - let mut checker = expected_fields.checker(name.to_string()); + let mut checker = expected_fields.checker(name, collector_name); event.record(&mut checker); checker.finish(); } + + if let Some(ref expected_parent) = self.parent { + let actual_parent = get_parent_name(); + expected_parent.check_parent_name( + actual_parent.as_deref(), + event.parent().cloned(), + event.metadata().name(), + collector_name, + ) + } + } + + pub fn in_scope(self, spans: impl IntoIterator) -> Self { + Self { + in_spans: spans.into_iter().collect(), + ..self + } + } + + pub fn scope_mut(&mut self) -> &mut [span::MockSpan] { + &mut self.in_spans[..] } } @@ -97,3 +134,35 @@ impl fmt::Display for MockEvent { write!(f, "an event{}", self.metadata) } } + +impl fmt::Debug for MockEvent { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("MockEvent"); + + if let Some(ref name) = self.metadata.name { + s.field("name", name); + } + + if let Some(ref target) = self.metadata.target { + s.field("target", target); + } + + if let Some(ref level) = self.metadata.level { + s.field("level", &format_args!("{:?}", level)); + } + + if let Some(ref fields) = self.fields { + s.field("fields", fields); + } + + if let Some(ref parent) = self.parent { + s.field("parent", &format_args!("{:?}", parent)); + } + + if !self.in_spans.is_empty() { + s.field("in_spans", &self.in_spans); + } + + s.finish() + } +} diff --git a/tracing-mock/src/field.rs b/tracing-mock/src/field.rs index 0e7799fa26..45a17bfa29 100644 --- a/tracing-mock/src/field.rs +++ b/tracing-mock/src/field.rs @@ -65,6 +65,13 @@ where } } +pub fn msg(message: impl fmt::Display) -> MockField { + MockField { + name: "message".to_string(), + value: MockValue::Debug(message.to_string()), + } +} + impl MockField { /// Expect a field with the given name and value. pub fn with_value(self, value: &dyn Value) -> Self { @@ -113,13 +120,14 @@ impl Expect { Self { only: true, ..self } } - fn compare_or_panic(&mut self, name: &str, value: &dyn Value, ctx: &str) { + fn compare_or_panic(&mut self, name: &str, value: &dyn Value, ctx: &str, collector_name: &str) { let value = value.into(); match self.fields.remove(name) { Some(MockValue::Any) => {} Some(expected) => assert!( expected == value, - "\nexpected `{}` to contain:\n\t`{}{}`\nbut got:\n\t`{}{}`", + "\n[{}] expected `{}` to contain:\n\t`{}{}`\nbut got:\n\t`{}{}`", + collector_name, ctx, name, expected, @@ -127,15 +135,19 @@ impl Expect { value ), None if self.only => panic!( - "\nexpected `{}` to contain only:\n\t`{}`\nbut got:\n\t`{}{}`", - ctx, self, name, value + "[{}]expected `{}` to contain only:\n\t`{}`\nbut got:\n\t`{}{}`", + collector_name, ctx, self, name, value ), _ => {} } } - pub fn checker(&mut self, ctx: String) -> CheckVisitor<'_> { - CheckVisitor { expect: self, ctx } + pub fn checker<'a>(&'a mut self, ctx: &'a str, collector_name: &'a str) -> CheckVisitor<'a> { + CheckVisitor { + expect: self, + ctx, + collector_name, + } } pub fn is_empty(&self) -> bool { @@ -159,38 +171,43 @@ impl fmt::Display for MockValue { pub struct CheckVisitor<'a> { expect: &'a mut Expect, - ctx: String, + ctx: &'a str, + collector_name: &'a str, } impl<'a> Visit for CheckVisitor<'a> { fn record_f64(&mut self, field: &Field, value: f64) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_i64(&mut self, field: &Field, value: i64) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_u64(&mut self, field: &Field, value: u64) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_bool(&mut self, field: &Field, value: bool) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_str(&mut self, field: &Field, value: &str) { self.expect - .compare_or_panic(field.name(), &value, &self.ctx[..]) + .compare_or_panic(field.name(), &value, self.ctx, self.collector_name) } fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) { - self.expect - .compare_or_panic(field.name(), &field::debug(value), &self.ctx) + self.expect.compare_or_panic( + field.name(), + &field::debug(value), + self.ctx, + self.collector_name, + ) } } @@ -198,7 +215,8 @@ impl<'a> CheckVisitor<'a> { pub fn finish(self) { assert!( self.expect.fields.is_empty(), - "{}missing {}", + "[{}] {}missing {}", + self.collector_name, self.expect, self.ctx ); diff --git a/tracing-mock/src/lib.rs b/tracing-mock/src/lib.rs index f860f3b9a9..eefc409ea0 100644 --- a/tracing-mock/src/lib.rs +++ b/tracing-mock/src/lib.rs @@ -10,7 +10,7 @@ mod metadata; pub mod span; #[derive(Debug, Eq, PartialEq)] -pub(crate) enum Parent { +pub enum Parent { ContextualRoot, Contextual(String), ExplicitRoot, @@ -23,6 +23,76 @@ pub struct PollN { polls: usize, } +impl Parent { + pub fn check_parent_name( + &self, + parent_name: Option<&str>, + provided_parent: Option, + ctx: impl std::fmt::Display, + collector_name: &str, + ) { + match self { + Parent::ExplicitRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to be an explicit root, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + } + Parent::Explicit(expected_parent) => { + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have explicit parent {}, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + expected_parent, + provided_parent, + parent_name, + ); + } + Parent::ContextualRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to have a contextual parent, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert!( + parent_name.is_none(), + "[{}] expected {} to be contextual a root, but we were inside span {:?}", + collector_name, + ctx, + parent_name, + ); + } + Parent::Contextual(expected_parent) => { + assert!(provided_parent.is_none(), + "[{}] expected {} to have a contextual parent\nbut its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have contextual parent {:?}, but got {:?}", + collector_name, + ctx, + expected_parent, + parent_name, + ); + } + } + } +} + impl std::future::Future for PollN where T: Unpin, diff --git a/tracing-mock/src/metadata.rs b/tracing-mock/src/metadata.rs index f648c46141..6655e32caf 100644 --- a/tracing-mock/src/metadata.rs +++ b/tracing-mock/src/metadata.rs @@ -1,5 +1,5 @@ use std::fmt; -use tracing::Metadata; +use tracing_core::Metadata; #[derive(Clone, Debug, Eq, PartialEq, Default)] pub struct Expect { @@ -9,12 +9,18 @@ pub struct Expect { } impl Expect { - pub(crate) fn check(&self, actual: &Metadata<'_>, ctx: fmt::Arguments<'_>) { + pub(crate) fn check( + &self, + actual: &Metadata<'_>, + ctx: fmt::Arguments<'_>, + collector_name: &str, + ) { if let Some(ref expected_name) = self.name { let name = actual.name(); assert!( expected_name == name, - "expected {} to be named `{}`, but got one named `{}`", + "\n[{}] expected {} to be named `{}`, but got one named `{}`", + collector_name, ctx, expected_name, name @@ -25,7 +31,8 @@ impl Expect { let level = actual.level(); assert!( expected_level == level, - "expected {} to be at level `{:?}`, but it was at level `{:?}` instead", + "\n[{}] expected {} to be at level `{:?}`, but it was at level `{:?}` instead", + collector_name, ctx, expected_level, level, @@ -36,7 +43,8 @@ impl Expect { let target = actual.target(); assert!( expected_target == target, - "expected {} to have target `{}`, but it had target `{}` instead", + "\n[{}] expected {} to have target `{}`, but it had target `{}` instead", + collector_name, ctx, expected_target, target, diff --git a/tracing-mock/src/span.rs b/tracing-mock/src/span.rs index 5b9ce7df23..1a19350bc0 100644 --- a/tracing-mock/src/span.rs +++ b/tracing-mock/src/span.rs @@ -6,12 +6,12 @@ use std::fmt; /// /// This is intended for use with the mock subscriber API in the /// `subscriber` module. -#[derive(Clone, Debug, Default, Eq, PartialEq)] +#[derive(Clone, Default, Eq, PartialEq)] pub struct MockSpan { pub(crate) metadata: metadata::Expect, } -#[derive(Debug, Default, Eq, PartialEq)] +#[derive(Default, Eq, PartialEq)] pub struct NewSpan { pub(crate) span: MockSpan, pub(crate) fields: field::Expect, @@ -86,6 +86,14 @@ impl MockSpan { self.metadata.name.as_ref().map(String::as_ref) } + pub fn level(&self) -> Option { + self.metadata.level + } + + pub fn target(&self) -> Option<&str> { + self.metadata.target.as_deref() + } + pub fn with_field(self, fields: I) -> NewSpan where I: Into, @@ -98,6 +106,26 @@ impl MockSpan { } } +impl fmt::Debug for MockSpan { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("MockSpan"); + + if let Some(name) = self.name() { + s.field("name", &name); + } + + if let Some(level) = self.level() { + s.field("level", &format_args!("{:?}", level)); + } + + if let Some(target) = self.target() { + s.field("target", &target); + } + + s.finish() + } +} + impl fmt::Display for MockSpan { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { if self.metadata.name.is_some() { @@ -149,6 +177,32 @@ impl NewSpan { ..self } } + + pub fn check( + &mut self, + span: &tracing_core::span::Attributes<'_>, + get_parent_name: impl FnOnce() -> Option, + collector_name: &str, + ) { + let meta = span.metadata(); + let name = meta.name(); + self.span + .metadata + .check(meta, format_args!("span `{}`", name), collector_name); + let mut checker = self.fields.checker(name, collector_name); + span.record(&mut checker); + checker.finish(); + + if let Some(expected_parent) = self.parent.as_ref() { + let actual_parent = get_parent_name(); + expected_parent.check_parent_name( + actual_parent.as_deref(), + span.parent().cloned(), + format_args!("span `{}`", name), + collector_name, + ) + } + } } impl fmt::Display for NewSpan { @@ -160,3 +214,31 @@ impl fmt::Display for NewSpan { Ok(()) } } + +impl fmt::Debug for NewSpan { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("NewSpan"); + + if let Some(name) = self.span.name() { + s.field("name", &name); + } + + if let Some(level) = self.span.level() { + s.field("level", &format_args!("{:?}", level)); + } + + if let Some(target) = self.span.target() { + s.field("target", &target); + } + + if let Some(ref parent) = self.parent { + s.field("parent", &format_args!("{:?}", parent)); + } + + if !self.fields.is_empty() { + s.field("fields", &self.fields); + } + + s.finish() + } +} diff --git a/tracing-subscriber/src/filter/mod.rs b/tracing-subscriber/src/filter/mod.rs index 9d63ff3f4d..c7f839a1d0 100644 --- a/tracing-subscriber/src/filter/mod.rs +++ b/tracing-subscriber/src/filter/mod.rs @@ -1,13 +1,53 @@ -//! [`Subscriber`]s that control which spans and events are enabled by the wrapped -//! subscriber. +//! [Subscribers](crate::subscribe) that control which spans and events are +//! enabled by the wrapped collector. //! -//! [`Subscriber`]: crate::fmt::Subscriber +//! This module contains a number of types that provide implementations of +//! various strategies for filtering which spans and events are enabled. For +//! details on filtering spans and events using [`Subscribe`] implementations, +//! see the [`subscribe` module documentation]. +//! +//! [`subscribe` module documentation]: crate::subscribe#filtering-with-subscribers +//! [`Subscribe`]: crate::subscribe +#[cfg(feature = "env-filter")] +mod env; mod level; +#[cfg(feature = "registry")] +mod subscriber_filters; + +#[cfg(not(feature = "registry"))] +pub(crate) use self::has_plf_stubs::*; +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub use self::subscriber_filters::*; pub use self::level::{LevelFilter, ParseError as LevelParseError}; -feature! { - #![all(feature = "env-filter", feature = "std")] - mod env; - pub use self::env::*; +#[cfg(feature = "env-filter")] +#[cfg_attr(docsrs, doc(cfg(feature = "env-filter")))] +pub use self::env::*; + +/// Stub implementations of the per-layer-fitler detection functions for when the +/// `registry` feature is disabled. +#[cfg(not(feature = "registry"))] +mod has_plf_stubs { + pub(crate) fn is_plf_downcast_marker(_: std::any::TypeId) -> bool { + false + } + + /// Does a type implementing `Collect` contain any per-layer filters? + pub(crate) fn collector_has_plf(_: &C) -> bool + where + C: tracing_core::Collect, + { + false + } + + /// Does a type implementing `Layer` contain any per-layer filters? + pub(crate) fn subscriber_has_plf(_: &S) -> bool + where + S: crate::Subscribe, + C: tracing_core::Collect, + { + false + } } diff --git a/tracing-subscriber/src/filter/subscriber_filters.rs b/tracing-subscriber/src/filter/subscriber_filters.rs new file mode 100644 index 0000000000..356d0709a6 --- /dev/null +++ b/tracing-subscriber/src/filter/subscriber_filters.rs @@ -0,0 +1,1452 @@ +//! ## Per-Subscriber Filtering +//! +//! Per-subscriber filters permit individual `Subscribe`s to have their own filter +//! configurations without interfering with other `Subscribe`s. +//! +//! This module is not public; the public APIs defined in this module are +//! re-exported in the top-level `filter` module. Therefore, this documentation +//! primarily concerns the internal implementation details. For the user-facing +//! public API documentation, see the individual public types in this module, as +//! well as the, see the `Subscribe` trait documentation's [per-subscriber filtering +//! section]][1]. +//! +//! ## How does per-subscriber filtering work? +//! +//! As described in the API documentation, the [`Filter`] trait defines a +//! filtering strategy for a per-subscriber filter. We expect there will be a variety +//! of implementations of [`Filter`], both in `tracing-subscriber` and in user +//! code. +//! +//! To actually *use* a [`Filter`] implementation, it is combined with a +//! [`Subscribe`] by the [`Filtered`] struct defined in this module. [`Filtered`] +//! implements [`Subscribe`] by calling into the wrapped [`Subscribe`], or not, based on +//! the filtering strategy. While there will be a variety of types that implement +//! [`Filter`], all actual *uses* of per-subscriber filtering will occur through the +//! [`Filtered`] struct. Therefore, most of the implementation details live +//! there. +//! +//! [1]: crate::subscribe#per-subscriber-filtering +//! [`Filter`]: crate::subscribe::Filter +use crate::{ + filter::LevelFilter, + registry, + subscribe::{self, Context, Subscribe}, +}; +use std::{ + any::{type_name, TypeId}, + cell::{Cell, RefCell}, + fmt, + marker::PhantomData, + ptr::NonNull, + sync::Arc, + thread_local, +}; +use tracing_core::{ + collect::{Collect, Interest}, + span, Event, Metadata, +}; + +/// A [`Subscribe`] that wraps an inner [`Subscribe`] and adds a [`Filter`] which +/// controls what spans and events are enabled for that subscriber. +/// +/// This is returned by the [`Subscribe::with_filter`] method. See the +/// [documentation on per-subscriber filtering][plf] for details. +/// +/// [`Filter`]: crate::subscribe::Filter +/// [plf]: crate::subscribe#per-subscriber-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Clone)] +pub struct Filtered { + filter: F, + subscriber: S, + id: MagicPlfDowncastMarker, + _s: PhantomData, +} + +/// A per-subscriber [`Filter`] implemented by a closure or function pointer that +/// determines whether a given span or event is enabled _dynamically_, +/// potentially based on the current [span context]. +/// +/// See the [documentation on per-subscriber filtering][plf] for details. +/// +/// [span context]: crate::subscribe::Context +/// [`Filter`]: crate::subscribe::Filter +/// [plf]: crate::subscribe#per-subscriber-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub struct DynFilterFn< + C, + // TODO(eliza): should these just be boxed functions? + F = fn(&Metadata<'_>, &Context<'_, C>) -> bool, + R = fn(&'static Metadata<'static>) -> Interest, +> { + enabled: F, + register_callsite: Option, + max_level_hint: Option, + _s: PhantomData, +} + +/// A per-subscriber [`Filter`] implemented by a closure or function pointer that +/// determines whether a given span or event is enabled, based on its +/// [`Metadata`]. +/// +/// See the [documentation on per-subscriber filtering][plf] for details. +/// +/// [`Metadata`]: tracing_core::Metadata +/// [`Filter`]: crate::subscribe::Filter +/// [plf]: crate::subscribe#per-subscriber-filtering +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Clone)] +pub struct FilterFn) -> bool> { + enabled: F, + max_level_hint: Option, +} + +/// Uniquely identifies an individual [`Filter`] instance in the context of +/// a [collector]. +/// +/// When adding a [`Filtered`] [`Subscribe`] to a [collector], the [collector]] +/// generates a `FilterId` for that [`Filtered`] subscriber. The [`Filtered`] subscriber +/// will then use the generated ID to query whether a particular span was +/// previously enabled by that subscriber's [`Filter`]. +/// +/// **Note**: Currently, the [`Registry`] type provided by this crate is the +/// **only** [`Collect`][collector] implementation capable of participating in per-subscriber +/// filtering. Therefore, the `FilterId` type cannot currently be constructed by +/// code outside of `tracing-subscriber`. In the future, new APIs will be added to `tracing-subscriber` to +/// allow non-Registry [collector]s to also participate in per-subscriber +/// filtering. When those APIs are added, subscribers will be responsible +/// for generating and assigning `FilterId`s. +/// +/// [`Filter`]: crate::subscribe::Filter +/// [collector]: tracing_core::Collect +/// [`Subscribe`]: crate::subscribe::Subscribe +/// [`Registry`]: crate::registry::Registry +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +#[derive(Copy, Clone)] +pub struct FilterId(u64); + +/// A bitmap tracking which [`FilterId`]s have enabled a given span or +/// event. +/// +/// This is currently a private type that's used exclusively by the +/// [`Registry`]. However, in the future, this may become a public API, in order +/// to allow user subscribers to host [`Filter`]s. +/// +/// [`Registry`]: crate::Registry +/// [`Filter`]: crate::subscribe::Filter +#[derive(Default, Copy, Clone, Eq, PartialEq)] +pub(crate) struct FilterMap { + bits: u64, +} + +/// The current state of `enabled` calls to per-subscriber filters on this +/// thread. +/// +/// When `Filtered::enabled` is called, the filter will set the bit +/// corresponding to its ID if the filter will disable the event/span being +/// filtered. When the event or span is recorded, the per-subscriber filter will +/// check its bit to determine if it disabled that event or span, and skip +/// forwarding the event or span to the inner subscriber if the bit is set. Once +/// a span or event has been skipped by a per-subscriber filter, it unsets its +/// bit, so that the `FilterMap` has been cleared for the next set of +/// `enabled` calls. +/// +/// FilterState is also read by the `Registry`, for two reasons: +/// +/// 1. When filtering a span, the Registry must store the `FilterMap` +/// generated by `Filtered::enabled` calls for that span as part of the +/// span's per-span data. This allows `Filtered` subscribers to determine +/// whether they had previously disabled a given span, and avoid showing it +/// to the wrapped subscriber if it was disabled. +/// +/// This allows `Filtered` subscribers to also filter out the spans they +/// disable from span traversals (such as iterating over parents, etc). +/// 2. If all the bits are set, then every per-subscriber filter has decided it +/// doesn't want to enable that span or event. In that case, the +/// `Registry`'s `enabled` method will return `false`, so that +/// recording a span or event can be skipped entirely. +#[derive(Debug)] +pub(crate) struct FilterState { + enabled: Cell, + // TODO(eliza): `Interest`s should _probably_ be `Copy`. The only reason + // they're not is our Obsessive Commitment to Forwards-Compatibility. If + // this changes in tracing-core`, we can make this a `Cell` rather than + // `RefCell`... + interest: RefCell>, + + #[cfg(debug_assertions)] + counters: DebugCounters, +} + +/// Extra counters added to `FilterState` used only to make debug assertions. +#[cfg(debug_assertions)] +#[derive(Debug, Default)] +struct DebugCounters { + /// How many per-subscriber filters have participated in the current `enabled` + /// call? + in_filter_pass: Cell, + + /// How many per-subscriber filters have participated in the current `register_callsite` + /// call? + in_interest_pass: Cell, +} + +thread_local! { + pub(crate) static FILTERING: FilterState = FilterState::new(); +} + +// === impl Filter === +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +impl subscribe::Filter for LevelFilter { + fn enabled(&self, meta: &Metadata<'_>, _: &Context<'_, C>) -> bool { + meta.level() <= self + } + + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + if meta.level() <= self { + Interest::always() + } else { + Interest::never() + } + } + + fn max_level_hint(&self) -> Option { + Some(*self) + } +} + +impl subscribe::Filter for Arc + Send + Sync + 'static> { + #[inline] + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, C>) -> bool { + (**self).enabled(meta, cx) + } + + #[inline] + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + (**self).callsite_enabled(meta) + } + + #[inline] + fn max_level_hint(&self) -> Option { + (**self).max_level_hint() + } +} + +impl subscribe::Filter for Box + Send + Sync + 'static> { + #[inline] + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, C>) -> bool { + (**self).enabled(meta, cx) + } + + #[inline] + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + (**self).callsite_enabled(meta) + } + + #[inline] + fn max_level_hint(&self) -> Option { + (**self).max_level_hint() + } +} + +// === impl Filtered === + +impl Filtered { + /// Wraps the provided [`Subscribe`] so that it is filtered by the given + /// [`Filter`]. + /// + /// This is equivalent to calling the [`Subscribe::with_filter`] method. + /// + /// See the [documentation on per-subscriber filtering][plf] for details. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [plf]: crate::subscribe#per-subscriber-filtering + pub fn new(subscriber: S, filter: F) -> Self { + Self { + subscriber, + filter, + id: MagicPlfDowncastMarker(FilterId::disabled()), + _s: PhantomData, + } + } + + #[inline(always)] + fn id(&self) -> FilterId { + self.id.0 + } + + fn did_enable(&self, f: impl FnOnce()) { + FILTERING.with(|filtering| filtering.did_enable(self.id(), f)) + } +} + +impl Subscribe for Filtered +where + C: Collect + for<'span> registry::LookupSpan<'span> + 'static, + F: subscribe::Filter + 'static, + S: Subscribe, +{ + fn on_subscribe(&mut self, collector: &mut C) { + self.id = MagicPlfDowncastMarker(collector.register_filter()); + self.subscriber.on_subscribe(collector); + } + + // TODO(eliza): can we figure out a nice way to make the `Filtered` subscriber + // not call `is_enabled_for` in hooks that the inner subscriber doesn't actually + // have real implementations of? probably not... + // + // it would be cool if there was some wild rust reflection way of checking + // if a trait impl has the default impl of a trait method or not, but that's + // almsot certainly impossible...right? + + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + let interest = self.filter.callsite_enabled(metadata); + + // If the filter didn't disable the callsite, allow the inner subscriber to + // register it — since `register_callsite` is also used for purposes + // such as reserving/caching per-callsite data, we want the inner subscriber + // to be able to perform any other registration steps. However, we'll + // ignore its `Interest`. + if !interest.is_never() { + self.subscriber.register_callsite(metadata); + } + + // Add our `Interest` to the current sum of per-subscriber filter `Interest`s + // for this callsite. + FILTERING.with(|filtering| filtering.add_interest(interest)); + + // don't short circuit! if the stack consists entirely of `Subscribe`s with + // per-subscriber filters, the `Registry` will return the actual `Interest` + // value that's the sum of all the `register_callsite` calls to those + // per-subscriber filters. if we returned an actual `never` interest here, a + // `Subscribeed` subscriber would short-circuit and not allow any `Filtered` + // subscribers below us if _they_ are interested in the callsite. + Interest::always() + } + + fn enabled(&self, metadata: &Metadata<'_>, cx: Context<'_, C>) -> bool { + let cx = cx.with_filter(self.id()); + let enabled = self.filter.enabled(metadata, &cx); + FILTERING.with(|filtering| filtering.set(self.id(), enabled)); + + if enabled { + // If the filter enabled this metadata, ask the wrapped subscriber if + // _it_ wants it --- it might have a global filter. + self.subscriber.enabled(metadata, cx) + } else { + // Otherwise, return `true`. The _per-subscriber_ filter disabled this + // metadata, but returning `false` in `Subscribe::enabled` will + // short-circuit and globally disable the span or event. This is + // *not* what we want for per-subscriber filters, as other subscribers may + // still want this event. Returning `true` here means we'll continue + // asking the next subscriber in the stack. + // + // Once all per-subscriber filters have been evaluated, the `Registry` + // at the root of the stack will return `false` from its `enabled` + // method if *every* per-subscriber filter disabled this metadata. + // Otherwise, the individual per-subscriber filters will skip the next + // `new_span` or `on_event` call for their subscriber if *they* disabled + // the span or event, but it was not globally disabled. + true + } + } + + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, cx: Context<'_, C>) { + self.did_enable(|| { + self.subscriber + .on_new_span(attrs, id, cx.with_filter(self.id())); + }) + } + + #[doc(hidden)] + fn max_level_hint(&self) -> Option { + self.filter.max_level_hint() + } + + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(span, self.id()) { + self.subscriber.on_record(span, values, cx) + } + } + + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, cx: Context<'_, C>) { + // only call `on_follows_from` if both spans are enabled by us + if cx.is_enabled_for(span, self.id()) && cx.is_enabled_for(follows, self.id()) { + self.subscriber + .on_follows_from(span, follows, cx.with_filter(self.id())) + } + } + + fn on_event(&self, event: &Event<'_>, cx: Context<'_, C>) { + self.did_enable(|| { + self.subscriber.on_event(event, cx.with_filter(self.id())); + }) + } + + fn on_enter(&self, id: &span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(id, self.id()) { + self.subscriber.on_enter(id, cx) + } + } + + fn on_exit(&self, id: &span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(id, self.id()) { + self.subscriber.on_exit(id, cx) + } + } + + fn on_close(&self, id: span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(&id, self.id()) { + self.subscriber.on_close(id, cx) + } + } + + // XXX(eliza): the existence of this method still makes me sad... + fn on_id_change(&self, old: &span::Id, new: &span::Id, cx: Context<'_, C>) { + if let Some(cx) = cx.if_enabled_for(old, self.id()) { + self.subscriber.on_id_change(old, new, cx) + } + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + match id { + id if id == TypeId::of::() => Some(NonNull::from(self).cast()), + id if id == TypeId::of::() => Some(NonNull::from(&self.subscriber).cast()), + id if id == TypeId::of::() => Some(NonNull::from(&self.filter).cast()), + id if id == TypeId::of::() => { + Some(NonNull::from(&self.id).cast()) + } + _ => None, + } + } +} + +impl fmt::Debug for Filtered +where + F: fmt::Debug, + L: fmt::Debug, +{ + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("Filtered") + .field("filter", &self.filter) + .field("subscriber", &self.subscriber) + .field("id", &self.id) + .finish() + } +} + +// === impl FilterFn === + +/// Constructs a [`FilterFn`], which implements the [`Filter`] trait, from +/// a function or closure that returns `true` if a span or event should be enabled. +/// +/// This is equivalent to calling [`FilterFn::new`]. +/// +/// See the [documentation on per-subscriber filtering][plf] for details on using +/// [`Filter`]s. +/// +/// [`Filter`]: crate::subscribe::Filter +/// [plf]: crate::subscribe#per-subscriber-filtering +/// +/// # Examples +/// +/// ``` +/// use tracing_subscriber::{ +/// subscribe::{Subscribe, CollectExt}, +/// filter, +/// util::SubscriberInitExt, +/// }; +/// +/// let my_filter = filter::filter_fn(|metadata| { +/// // Only enable spans or events with the target "interesting_things" +/// metadata.target() == "interesting_things" +/// }); +/// +/// let my_subscriber = tracing_subscriber::fmt::subscriber(); +/// +/// tracing_subscriber::registry() +/// .with(my_subscriber.with_filter(my_filter)) +/// .init(); +/// +/// // This event will not be enabled. +/// tracing::warn!("something important but uninteresting happened!"); +/// +/// // This event will be enabled. +/// tracing::debug!(target: "interesting_things", "an interesting minor detail..."); +/// ``` +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub fn filter_fn(f: F) -> FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + FilterFn::new(f) +} + +/// Constructs a [`DynFilterFn`], which implements the [`Filter`] trait, from +/// a function or closure that returns `true` if a span or event should be +/// enabled within a particular [span context][`Context`]. +/// +/// This is equivalent to calling [`DynFilterFn::new`]. +/// +/// Unlike [`filter_fn`], this function takes a closure or function pointer +/// taking the [`Metadata`] for a span or event *and* the current [`Context`]. +/// This means that a [`DynFilterFn`] can choose whether to enable spans or +/// events based on information about the _current_ span (or its parents). +/// +/// If this is *not* necessary, use [`filter_fn`] instead. +/// +/// See the [documentation on per-subscriber filtering][plf] for details on using +/// [`Filter`]s. +/// +/// # Examples +/// +/// ``` +/// use tracing_subscriber::{ +/// subscribe::{Subscribe, CollectExt}, +/// filter, +/// util::SubscriberInitExt, +/// }; +/// +/// // Only enable spans or events within a span named "interesting_span". +/// let my_filter = filter::dynamic_filter_fn(|metadata, cx| { +/// // If this *is* "interesting_span", make sure to enable it. +/// if metadata.is_span() && metadata.name() == "interesting_span" { +/// return true; +/// } +/// +/// // Otherwise, are we in an interesting span? +/// if let Some(current_span) = cx.lookup_current() { +/// return current_span.name() == "interesting_span"; +/// } +/// +/// false +/// }); +/// +/// let my_subscriber = tracing_subscriber::fmt::subscriber(); +/// +/// tracing_subscriber::registry() +/// .with(my_subscriber.with_filter(my_filter)) +/// .init(); +/// +/// // This event will not be enabled. +/// tracing::info!("something happened"); +/// +/// tracing::info_span!("interesting_span").in_scope(|| { +/// // This event will be enabled. +/// tracing::debug!("something else happened"); +/// }); +/// ``` +/// +/// [`Filter`]: crate::subscribe::Filter +/// [plf]: crate::subscribe#per-subscriber-filtering +/// [`Context`]: crate::subscribe::Context +/// [`Metadata`]: tracing_core::Metadata +#[cfg_attr(docsrs, doc(cfg(feature = "registry")))] +pub fn dynamic_filter_fn(f: F) -> DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + DynFilterFn::new(f) +} + +impl FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + /// Constructs a [`Filter`] from a function or closure that returns `true` + /// if a span or event should be enabled, based on its [`Metadata`]. + /// + /// If determining whether a span or event should be enabled also requires + /// information about the current span context, use [`DynFilterFn`] instead. + /// + /// See the [documentation on per-subscriber filtering][plf] for details on using + /// [`Filter`]s. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [plf]: crate::subscribe#per-subscriber-filtering + /// [`Metadata`]: tracing_core::Metadata + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::FilterFn, + /// util::SubscriberInitExt, + /// }; + /// + /// let my_filter = FilterFn::new(|metadata| { + /// // Only enable spans or events with the target "interesting_things" + /// metadata.target() == "interesting_things" + /// }); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// + /// // This event will not be enabled. + /// tracing::warn!("something important but uninteresting happened!"); + /// + /// // This event will be enabled. + /// tracing::debug!(target: "interesting_things", "an interesting minor detail..."); + /// ``` + pub fn new(enabled: F) -> Self { + Self { + enabled, + max_level_hint: None, + } + } + + /// Sets the highest verbosity [`Level`] the filter function will enable. + /// + /// The value passed to this method will be returned by this `FilterFn`'s + /// [`Filter::max_level_hint`] method. + /// + /// If the provided function will not enable all levels, it is recommended + /// to call this method to configure it with the most verbose level it will + /// enable. + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::{filter_fn, LevelFilter}, + /// util::SubscriberInitExt, + /// }; + /// use tracing_core::Level; + /// + /// let my_filter = filter_fn(|metadata| { + /// // Only enable spans or events with targets starting with `my_crate` + /// // and levels at or below `INFO`. + /// metadata.level() <= &Level::INFO && metadata.target().starts_with("my_crate") + /// }) + /// // Since the filter closure will only enable the `INFO` level and + /// // below, set the max level hint + /// .with_max_level_hint(LevelFilter::INFO); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [`Level`]: tracing_core::Level + /// [`Filter::max_level_hint`]: crate::subscribe::Filter::max_level_hint + pub fn with_max_level_hint(self, max_level_hint: impl Into) -> Self { + Self { + max_level_hint: Some(max_level_hint.into()), + ..self + } + } + + fn is_below_max_level(&self, metadata: &Metadata<'_>) -> bool { + self.max_level_hint + .as_ref() + .map(|hint| metadata.level() <= hint) + .unwrap_or(true) + } +} + +impl subscribe::Filter for FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + fn enabled(&self, metadata: &Metadata<'_>, _: &Context<'_, S>) -> bool { + let enabled = (self.enabled)(metadata); + debug_assert!( + !enabled || self.is_below_max_level(metadata), + "FilterFn<{}> claimed it would only enable {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + + enabled + } + + fn callsite_enabled(&self, metadata: &'static Metadata<'static>) -> Interest { + // Because `self.enabled` takes a `Metadata` only (and no `Context` + // parameter), we can reasonably assume its results are cachable, and + // just return `Interest::always`/`Interest::never`. + if (self.enabled)(metadata) { + debug_assert!( + self.is_below_max_level(metadata), + "FilterFn<{}> claimed it was only interested in {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + return Interest::always(); + } + + Interest::never() + } + + fn max_level_hint(&self) -> Option { + self.max_level_hint + } +} + +impl From for FilterFn +where + F: Fn(&Metadata<'_>) -> bool, +{ + fn from(enabled: F) -> Self { + Self::new(enabled) + } +} + +impl fmt::Debug for FilterFn { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("FilterFn") + .field("enabled", &format_args!("{}", type_name::())) + .field("max_level_hint", &self.max_level_hint) + .finish() + } +} + +// === impl DynFilterFn == + +impl DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + /// Constructs a [`Filter`] from a function or closure that returns `true` + /// if a span or event should be enabled in the current [span + /// context][`Context`]. + /// + /// Unlike [`FilterFn`], a `DynFilterFn` is constructed from a closure or + /// function pointer that takes both the [`Metadata`] for a span or event + /// *and* the current [`Context`]. This means that a [`DynFilterFn`] can + /// choose whether to enable spans or events based on information about the + /// _current_ span (or its parents). + /// + /// If this is *not* necessary, use [`FilterFn`] instead. + /// + /// See the [documentation on per-subscriber filtering][plf] for details on using + /// [`Filter`]s. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [plf]: crate::subscribe#per-subscriber-filtering + /// [`Context`]: crate::subscribe::Context + /// [`Metadata`]: tracing_core::Metadata + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::DynFilterFn, + /// util::SubscriberInitExt, + /// }; + /// + /// // Only enable spans or events within a span named "interesting_span". + /// let my_filter = DynFilterFn::new(|metadata, cx| { + /// // If this *is* "interesting_span", make sure to enable it. + /// if metadata.is_span() && metadata.name() == "interesting_span" { + /// return true; + /// } + /// + /// // Otherwise, are we in an interesting span? + /// if let Some(current_span) = cx.lookup_current() { + /// return current_span.name() == "interesting_span"; + /// } + /// + /// false + /// }); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// + /// // This event will not be enabled. + /// tracing::info!("something happened"); + /// + /// tracing::info_span!("interesting_span").in_scope(|| { + /// // This event will be enabled. + /// tracing::debug!("something else happened"); + /// }); + /// ``` + pub fn new(enabled: F) -> Self { + Self { + enabled, + register_callsite: None, + max_level_hint: None, + _s: PhantomData, + } + } +} + +impl DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + /// Sets the highest verbosity [`Level`] the filter function will enable. + /// + /// The value passed to this method will be returned by this `DynFilterFn`'s + /// [`Filter::max_level_hint`] method. + /// + /// If the provided function will not enable all levels, it is recommended + /// to call this method to configure it with the most verbose level it will + /// enable. + /// + /// # Examples + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::{DynFilterFn, LevelFilter}, + /// util::SubscriberInitExt, + /// }; + /// use tracing_core::Level; + /// + /// // Only enable spans or events with levels at or below `INFO`, if + /// // we are inside a span called "interesting_span". + /// let my_filter = DynFilterFn::new(|metadata, cx| { + /// // If the level is greater than INFO, disable it. + /// if metadata.level() > &Level::INFO { + /// return false; + /// } + /// + /// // If any span in the current scope is named "interesting_span", + /// // enable this span or event. + /// for span in cx.lookup_current().iter().flat_map(|span| span.scope()) { + /// if span.name() == "interesting_span" { + /// return true; + /// } + /// } + /// + /// // Otherwise, disable it. + /// false + /// }) + /// // Since the filter closure will only enable the `INFO` level and + /// // below, set the max level hint + /// .with_max_level_hint(LevelFilter::INFO); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [`Level`]: tracing_core::Level + /// [`Filter::max_level_hint`]: crate::subscribe::Filter::max_level_hint + pub fn with_max_level_hint(self, max_level_hint: impl Into) -> Self { + Self { + max_level_hint: Some(max_level_hint.into()), + ..self + } + } + + /// Adds a function for filtering callsites to this filter. + /// + /// When this filter's [`Filter::callsite_enabled`][cse] method is called, + /// the provided function will be used rather than the default. + /// + /// By default, `DynFilterFn` assumes that, because the filter _may_ depend + /// dynamically on the current [span context], its result should never be + /// cached. However, some filtering strategies may require dynamic information + /// from the current span context in *some* cases, but are able to make + /// static filtering decisions from [`Metadata`] alone in others. + /// + /// For example, consider the filter given in the example for + /// [`DynFilterFn::new`]. That filter enables all spans named + /// "interesting_span", and any events and spans that occur inside of an + /// interesting span. Since the span's name is part of its static + /// [`Metadata`], the "interesting_span" can be enabled in + /// [`callsite_enabled`][cse]: + /// + /// ``` + /// use tracing_subscriber::{ + /// subscribe::{Subscribe, CollectExt}, + /// filter::DynFilterFn, + /// util::SubscriberInitExt, + /// }; + /// use tracing_core::collect::Interest; + /// + /// // Only enable spans or events within a span named "interesting_span". + /// let my_filter = DynFilterFn::new(|metadata, cx| { + /// // If this *is* "interesting_span", make sure to enable it. + /// if metadata.is_span() && metadata.name() == "interesting_span" { + /// return true; + /// } + /// + /// // Otherwise, are we in an interesting span? + /// if let Some(current_span) = cx.lookup_current() { + /// return current_span.name() == "interesting_span"; + /// } + /// + /// false + /// }).with_callsite_filter(|metadata| { + /// // If this is an "interesting_span", we know we will always + /// // enable it. + /// if metadata.is_span() && metadata.name() == "interesting_span" { + /// return Interest::always(); + /// } + /// + /// // Otherwise, it depends on whether or not we're in an interesting + /// // span. You'll have to ask us again for each span/event! + /// Interest::sometimes() + /// }); + /// + /// let my_subscriber = tracing_subscriber::fmt::subscriber(); + /// + /// tracing_subscriber::registry() + /// .with(my_subscriber.with_filter(my_filter)) + /// .init(); + /// ``` + /// + /// [cse]: crate::subscribe::Filter::callsite_enabled + /// [`enabled`]: crate::subscribe::Filter::enabled + /// [`Metadata`]: tracing_core::Metadata + /// [span context]: crate::subscribe::Context + pub fn with_callsite_filter(self, callsite_enabled: R2) -> DynFilterFn + where + R2: Fn(&'static Metadata<'static>) -> Interest, + { + let register_callsite = Some(callsite_enabled); + let DynFilterFn { + enabled, + max_level_hint, + _s, + .. + } = self; + DynFilterFn { + enabled, + register_callsite, + max_level_hint, + _s, + } + } + + fn default_callsite_enabled(&self, metadata: &Metadata<'_>) -> Interest { + // If it's below the configured max level, assume that `enabled` will + // never enable it... + if !is_below_max_level(&self.max_level_hint, metadata) { + debug_assert!( + !(self.enabled)(metadata, &Context::none()), + "DynFilterFn<{}> claimed it would only enable {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + return Interest::never(); + } + + // Otherwise, since this `enabled` function is dynamic and depends on + // the current context, we don't know whether this span or event will be + // enabled or not. Ask again every time it's recorded! + Interest::sometimes() + } +} + +impl subscribe::Filter for DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, + R: Fn(&'static Metadata<'static>) -> Interest, +{ + fn enabled(&self, metadata: &Metadata<'_>, cx: &Context<'_, S>) -> bool { + let enabled = (self.enabled)(metadata, cx); + debug_assert!( + !enabled || is_below_max_level(&self.max_level_hint, metadata), + "DynFilterFn<{}> claimed it would only enable {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + + enabled + } + + fn callsite_enabled(&self, metadata: &'static Metadata<'static>) -> Interest { + let interest = self + .register_callsite + .as_ref() + .map(|callsite_enabled| callsite_enabled(metadata)) + .unwrap_or_else(|| self.default_callsite_enabled(metadata)); + debug_assert!( + interest.is_never() || is_below_max_level(&self.max_level_hint, metadata), + "DynFilterFn<{}, {}> claimed it was only interested in {:?} and below, \ + but it enabled metadata with the {:?} level\nmetadata={:#?}", + type_name::(), + type_name::(), + self.max_level_hint.unwrap(), + metadata.level(), + metadata, + ); + + interest + } + + fn max_level_hint(&self) -> Option { + self.max_level_hint + } +} + +impl fmt::Debug for DynFilterFn { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("DynFilterFn"); + s.field("enabled", &format_args!("{}", type_name::())); + if self.register_callsite.is_some() { + s.field( + "register_callsite", + &format_args!("Some({})", type_name::()), + ); + } else { + s.field("register_callsite", &format_args!("None")); + } + + s.field("max_level_hint", &self.max_level_hint).finish() + } +} + +impl Clone for DynFilterFn +where + F: Clone, + R: Clone, +{ + fn clone(&self) -> Self { + Self { + enabled: self.enabled.clone(), + register_callsite: self.register_callsite.clone(), + max_level_hint: self.max_level_hint, + _s: PhantomData, + } + } +} + +impl From for DynFilterFn +where + F: Fn(&Metadata<'_>, &Context<'_, S>) -> bool, +{ + fn from(f: F) -> Self { + Self::new(f) + } +} + +// === impl FilterId === + +impl FilterId { + const fn disabled() -> Self { + Self(u64::MAX) + } + + /// Returns a `FilterId` that will consider _all_ spans enabled. + pub(crate) const fn none() -> Self { + Self(0) + } + + pub(crate) fn new(id: u8) -> Self { + assert!(id < 64, "filter IDs may not be greater than 64"); + Self(1 << id as usize) + } + + /// Combines two `FilterId`s, returning a new `FilterId` that will match a + /// [`FilterMap`] where the span was disabled by _either_ this `FilterId` + /// *or* the combined `FilterId`. + /// + /// This method is called by [`Context`]s when adding the `FilterId` of a + /// [`Filtered`] subscriber to the context. + /// + /// This is necessary for cases where we have a tree of nested [`Filtered`] + /// subscribers, like this: + /// + /// ```text + /// Filtered { + /// filter1, + /// Subscribeed { + /// subscriber1, + /// Filtered { + /// filter2, + /// subscriber2, + /// }, + /// } + /// ``` + /// + /// We want `subscriber2` to be affected by both `filter1` _and_ `filter2`. + /// Without combining `FilterId`s, this works fine when filtering + /// `on_event`/`new_span`, because the outer `Filtered` subscriber (`filter1`) + /// won't call the inner subscriber's `on_event` or `new_span` callbacks if it + /// disabled the event/span. + /// + /// However, it _doesn't_ work when filtering span lookups and traversals + /// (e.g. `scope`). This is because the [`Context`] passed to `subscriber2` + /// would set its filter ID to the filter ID of `filter2`, and would skip + /// spans that were disabled by `filter2`. However, what if a span was + /// disabled by `filter1`? We wouldn't see it in `new_span`, but we _would_ + /// see it in lookups and traversals...which we don't want. + /// + /// When a [`Filtered`] subscriber adds its ID to a [`Context`], it _combines_ it + /// with any previous filter ID that the context had, rather than replacing + /// it. That way, `subscriber2`'s context will check if a span was disabled by + /// `filter1` _or_ `filter2`. The way we do this, instead of representing + /// `FilterId`s as a number number that we shift a 1 over by to get a mask, + /// we just store the actual mask,so we can combine them with a bitwise-OR. + /// + /// For example, if we consider the following case (pretending that the + /// masks are 8 bits instead of 64 just so i don't have to write out a bunch + /// of extra zeroes): + /// + /// - `filter1` has the filter id 1 (`0b0000_0001`) + /// - `filter2` has the filter id 2 (`0b0000_0010`) + /// + /// A span that gets disabled by filter 1 would have the [`FilterMap`] with + /// bits `0b0000_0001`. + /// + /// If the `FilterId` was internally represented as `(bits to shift + 1), + /// when `subscriber2`'s [`Context`] checked if it enabled the span, it would + /// make the mask `0b0000_0010` (`1 << 1`). That bit would not be set in the + /// [`FilterMap`], so it would see that it _didn't_ disable the span. Which + /// is *true*, it just doesn't reflect the tree-like shape of the actual + /// subscriber. + /// + /// By having the IDs be masks instead of shifts, though, when the + /// [`Filtered`] with `filter2` gets the [`Context`] with `filter1`'s filter ID, + /// instead of replacing it, it ors them together: + /// + /// ```ignore + /// 0b0000_0001 | 0b0000_0010 == 0b0000_0011; + /// ``` + /// + /// We then test if the span was disabled by seeing if _any_ bits in the + /// mask are `1`: + /// + /// ```ignore + /// filtermap & mask != 0; + /// 0b0000_0001 & 0b0000_0011 != 0; + /// 0b0000_0001 != 0; + /// true; + /// ``` + /// + /// [`Context`]: crate::subscribe::Context + pub(crate) fn and(self, FilterId(other): Self) -> Self { + // If this mask is disabled, just return the other --- otherwise, we + // would always see that every span is disabled. + if self.0 == Self::disabled().0 { + return Self(other); + } + + Self(self.0 | other) + } +} + +impl fmt::Debug for FilterId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + // don't print a giant set of the numbers 0..63 if the filter ID is disabled. + if self.0 == Self::disabled().0 { + return f + .debug_tuple("FilterId") + .field(&format_args!("DISABLED")) + .finish(); + } + + if f.alternate() { + f.debug_struct("FilterId") + .field("ids", &format_args!("{:?}", FmtBitset(self.0))) + .field("bits", &format_args!("{:b}", self.0)) + .finish() + } else { + f.debug_tuple("FilterId").field(&FmtBitset(self.0)).finish() + } + } +} + +impl fmt::Binary for FilterId { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_tuple("FilterId") + .field(&format_args!("{:b}", self.0)) + .finish() + } +} + +// === impl FilterMap === + +impl FilterMap { + pub(crate) fn set(self, FilterId(mask): FilterId, enabled: bool) -> Self { + if mask == u64::MAX { + return self; + } + + if enabled { + Self { + bits: self.bits & (!mask), + } + } else { + Self { + bits: self.bits | mask, + } + } + } + + #[inline] + pub(crate) fn is_enabled(self, FilterId(mask): FilterId) -> bool { + self.bits & mask == 0 + } + + #[inline] + pub(crate) fn any_enabled(self) -> bool { + self.bits != u64::MAX + } +} + +impl fmt::Debug for FilterMap { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let alt = f.alternate(); + let mut s = f.debug_struct("FilterMap"); + s.field("disabled_by", &format_args!("{:?}", &FmtBitset(self.bits))); + + if alt { + s.field("bits", &format_args!("{:b}", self.bits)); + } + + s.finish() + } +} + +impl fmt::Binary for FilterMap { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.debug_struct("FilterMap") + .field("bits", &format_args!("{:b}", self.bits)) + .finish() + } +} + +// === impl FilterState === + +impl FilterState { + fn new() -> Self { + Self { + enabled: Cell::new(FilterMap::default()), + interest: RefCell::new(None), + + #[cfg(debug_assertions)] + counters: DebugCounters::default(), + } + } + + fn set(&self, filter: FilterId, enabled: bool) { + #[cfg(debug_assertions)] + { + let in_current_pass = self.counters.in_filter_pass.get(); + if in_current_pass == 0 { + debug_assert_eq!(self.enabled.get(), FilterMap::default()); + } + self.counters.in_filter_pass.set(in_current_pass + 1); + debug_assert_eq!( + self.counters.in_interest_pass.get(), + 0, + "if we are in or starting a filter pass, we must not be in an interest pass." + ) + } + + self.enabled.set(self.enabled.get().set(filter, enabled)) + } + + fn add_interest(&self, interest: Interest) { + let mut curr_interest = self.interest.borrow_mut(); + + #[cfg(debug_assertions)] + { + let in_current_pass = self.counters.in_interest_pass.get(); + if in_current_pass == 0 { + debug_assert!(curr_interest.is_none()); + } + self.counters.in_interest_pass.set(in_current_pass + 1); + } + + if let Some(curr_interest) = curr_interest.as_mut() { + if (curr_interest.is_always() && !interest.is_always()) + || (curr_interest.is_never() && !interest.is_never()) + { + *curr_interest = Interest::sometimes(); + } + // If the two interests are the same, do nothing. If the current + // interest is `sometimes`, stay sometimes. + } else { + *curr_interest = Some(interest); + } + } + + pub(crate) fn event_enabled() -> bool { + FILTERING + .try_with(|this| { + let enabled = this.enabled.get().any_enabled(); + #[cfg(debug_assertions)] + { + if this.counters.in_filter_pass.get() == 0 { + debug_assert_eq!(this.enabled.get(), FilterMap::default()); + } + + // Nothing enabled this event, we won't tick back down the + // counter in `did_enable`. Reset it. + if !enabled { + this.counters.in_filter_pass.set(0); + } + } + enabled + }) + .unwrap_or(true) + } + + /// Executes a closure if the filter with the provided ID did not disable + /// the current span/event. + /// + /// This is used to implement the `on_event` and `new_span` methods for + /// `Filtered`. + fn did_enable(&self, filter: FilterId, f: impl FnOnce()) { + let map = self.enabled.get(); + if map.is_enabled(filter) { + // If the filter didn't disable the current span/event, run the + // callback. + f(); + } else { + // Otherwise, if this filter _did_ disable the span or event + // currently being processed, clear its bit from this thread's + // `FilterState`. The bit has already been "consumed" by skipping + // this callback, and we need to ensure that the `FilterMap` for + // this thread is reset when the *next* `enabled` call occurs. + self.enabled.set(map.set(filter, true)); + } + #[cfg(debug_assertions)] + { + let in_current_pass = self.counters.in_filter_pass.get(); + if in_current_pass <= 1 { + debug_assert_eq!(self.enabled.get(), FilterMap::default()); + } + self.counters + .in_filter_pass + .set(in_current_pass.saturating_sub(1)); + debug_assert_eq!( + self.counters.in_interest_pass.get(), + 0, + "if we are in a filter pass, we must not be in an interest pass." + ) + } + } + + pub(crate) fn take_interest() -> Option { + FILTERING + .try_with(|filtering| { + #[cfg(debug_assertions)] + { + if filtering.counters.in_interest_pass.get() == 0 { + debug_assert!(filtering.interest.try_borrow().ok()?.is_none()); + } + filtering.counters.in_interest_pass.set(0); + } + filtering.interest.try_borrow_mut().ok()?.take() + }) + .ok()? + } + + pub(crate) fn filter_map(&self) -> FilterMap { + let map = self.enabled.get(); + #[cfg(debug_assertions)] + if self.counters.in_filter_pass.get() == 0 { + debug_assert_eq!(map, FilterMap::default()); + } + + map + } +} +/// This is a horrible and bad abuse of the downcasting system to expose +/// *internally* whether a subscriber has per-subscriber filtering, within +/// `tracing-subscriber`, without exposing a public API for it. +/// +/// If a `Subscribe` has per-subscriber filtering, it will downcast to a +/// `MagicPlfDowncastMarker`. Since subscribers which contain other subscribers permit +/// downcasting to recurse to their children, this will do the Right Thing with +/// subscribers like Reload, Option, etc. +/// +/// Why is this a wrapper around the `FilterId`, you may ask? Because +/// downcasting works by returning a pointer, and we don't want to risk +/// introducing UB by constructing pointers that _don't_ point to a valid +/// instance of the type they claim to be. In this case, we don't _intend_ for +/// this pointer to be dereferenced, so it would actually be fine to return one +/// that isn't a valid pointer...but we can't guarantee that the caller won't +/// (accidentally) dereference it, so it's better to be safe than sorry. We +/// could, alternatively, add an additional field to the type that's used only +/// for returning pointers to as as part of the evil downcasting hack, but I +/// thought it was nicer to just add a `repr(transparent)` wrapper to the +/// existing `FilterId` field, since it won't make the struct any bigger. +/// +/// Don't worry, this isn't on the test. :) +#[derive(Clone, Copy)] +#[repr(transparent)] +struct MagicPlfDowncastMarker(FilterId); +impl fmt::Debug for MagicPlfDowncastMarker { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + // Just pretend that `MagicPlfDowncastMarker` doesn't exist for + // `fmt::Debug` purposes...if no one *sees* it in their `Debug` output, + // they don't have to know I thought this code would be a good idea. + fmt::Debug::fmt(&self.0, f) + } +} + +pub(crate) fn is_plf_downcast_marker(type_id: TypeId) -> bool { + type_id == TypeId::of::() +} + +/// Does a type implementing `Collect` contain any per-subscriber filters? +pub(crate) fn collector_has_plf(collector: &C) -> bool +where + C: Collect, +{ + (collector as &dyn Collect).is::() +} + +/// Does a type implementing `Subscriber` contain any per-subscriber filters? +pub(crate) fn subscriber_has_plf(subscriber: &S) -> bool +where + S: Subscribe, + C: Collect, +{ + unsafe { + // Safety: we're not actually *doing* anything with this pointer --- we + // only care about the `Option`, which we're turning into a `bool`. So + // even if the subscriber decides to be evil and give us some kind of invalid + // pointer, we don't ever dereference it, so this is always safe. + subscriber.downcast_raw(TypeId::of::()) + } + .is_some() +} + +struct FmtBitset(u64); + +impl fmt::Debug for FmtBitset { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut set = f.debug_set(); + for bit in 0..64 { + // if the `bit`-th bit is set, add it to the debug set + if self.0 & (1 << bit) != 0 { + set.entry(&bit); + } + } + set.finish() + } +} + +fn is_below_max_level(hint: &Option, metadata: &Metadata<'_>) -> bool { + hint.as_ref() + .map(|hint| metadata.level() <= hint) + .unwrap_or(true) +} diff --git a/tracing-subscriber/src/lib.rs b/tracing-subscriber/src/lib.rs index 34b17d4e53..e26609a183 100644 --- a/tracing-subscriber/src/lib.rs +++ b/tracing-subscriber/src/lib.rs @@ -14,9 +14,34 @@ //! //! [msrv]: #supported-rust-versions //! -//! ## Included Subscribers -//! -//! The following `Collector`s are provided for application authors: +//! ## Subscribers and Filters +//! +//! The most important component of the `tracing-subscriber` API is the +//! [`Subscribe`] trait, which provides a composable abstraction for building +//! [collector]s. Like the [`Collect`] trait, [`Subscribe`] defines a +//! particular behavior for collecting trace data. Unlike [`Collect`], +//! which implements a *complete* strategy for how trace data is collected, +//! [`Subscribe`] provide *modular* implementations of specific behaviors. +//! Therefore, they can be [composed together] to form a [collector] which is +//! capable of recording traces in a variety of ways. See the [`subscribe` module's +//! documentation][subscribe] for details on using [subscribers]. +//! +//! In addition, the [`Filter`] trait defines an interface for filtering what +//! spans and events are recorded by a particular subscriber. This allows different +//! [`Subscribe`] implementationss to handle separate subsets of the trace data +//! emitted by a program. See the [documentation on per-subscriber +//! filtering][plf] for more information on using [`Filter`]s. +//! +//! [`Subscribe`]: crate::subscribe::Subscribe +//! [composed together]: crate::subscribe#composing-subscribers +//! [subscribe]: crate::subscribe +//! [subscribers]: crate::subscribe +//! [`Filter`]: crate::subscribe::Filter +//! [plf]: crate::subscribe#per-subscriber-filtering +//! +//! ## Included Collectors +//! +//! The following [ollectors] are provided for application authors: //! //! - [`fmt`] - Formats and logs tracing data (requires the `fmt` feature flag) //! @@ -95,6 +120,7 @@ //! [`fmt`]: mod@fmt //! [`registry`]: mod@registry //! [`Collect`]: tracing_core::collect::Collect +//! [collector]: tracing_core::collect::Collect //! [`EnvFilter`]: filter::EnvFilter //! [`tracing-log`]: https://crates.io/crates/tracing-log //! [`smallvec`]: https://crates.io/crates/smallvec @@ -109,7 +135,15 @@ html_favicon_url = "https://raw.githubusercontent.com/tokio-rs/tracing/master/assets/favicon.ico", issue_tracker_base_url = "https://github.com/tokio-rs/tracing/issues/" )] -#![cfg_attr(docsrs, feature(doc_cfg))] +#![cfg_attr( + docsrs, + // Allows displaying cfgs/feature flags in the documentation. + feature(doc_cfg), + // Allows adding traits to RustDoc's list of "notable traits" + feature(doc_notable_trait), + // Fail the docs build if any intra-docs links are broken + deny(rustdoc::broken_intra_doc_links), +)] #![warn( missing_debug_implementations, missing_docs, diff --git a/tracing-subscriber/src/registry/mod.rs b/tracing-subscriber/src/registry/mod.rs index 334cd0b792..26df85856d 100644 --- a/tracing-subscriber/src/registry/mod.rs +++ b/tracing-subscriber/src/registry/mod.rs @@ -60,6 +60,8 @@ //! [lookup]: crate::subscribe::Context::span() use core::fmt::Debug; +#[cfg(feature = "registry")] +use crate::filter::FilterId; use tracing_core::{field::FieldSet, span::Id, Metadata}; feature! { @@ -126,8 +128,34 @@ pub trait LookupSpan<'a> { Some(SpanRef { registry: self, data, + #[cfg(feature = "registry")] + filter: FilterId::none(), }) } + + /// Registers a [`Filter`] for [per-subscriber filtering] with this + /// [collector]. + /// + /// The [`Filter`] can then use the returned [`FilterId`] to + /// [check if it previously enabled a span][check]. + /// + /// # Panics + /// + /// If this collector does not support [per-subscriber filtering]. + /// + /// [`Filter`]: crate::subscribe::Filter + /// [per-subscriber filtering]: crate::subscribe#per-subscriber-filtering + /// [collector]: tracing_core::Collect + /// [`FilterId`]: crate::filter::FilterId + /// [check]: SpanData::is_enabled_for + #[cfg(feature = "registry")] + #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] + fn register_filter(&mut self) -> FilterId { + panic!( + "{} does not currently support filters", + std::any::type_name::() + ) + } } /// A stored representation of data associated with a span. @@ -156,6 +184,23 @@ pub trait SpanData<'a> { #[cfg(feature = "std")] #[cfg_attr(docsrs, doc(cfg(feature = "std")))] fn extensions_mut(&self) -> ExtensionsMut<'_>; + + /// Returns `true` if this span is enabled for the [per-subscriber filter][plf] + /// corresponding to the provided [`FilterId`]. + /// + /// ## Default Implementation + /// + /// By default, this method assumes that the [`LookupSpan`] implementation + /// does not support [per-subscriber filtering][plf], and always returns `true`. + /// + /// [plf]: crate::subscribe#per-subscriber-filtering + /// [`FilterId`]: crate::filter::FilterId + #[cfg(feature = "registry")] + #[cfg_attr(docsrs, doc(cfg(feature = "registry")))] + fn is_enabled_for(&self, filter: FilterId) -> bool { + let _ = filter; + true + } } /// A reference to [span data] and the associated [registry]. @@ -170,6 +215,9 @@ pub trait SpanData<'a> { pub struct SpanRef<'a, R: LookupSpan<'a>> { registry: &'a R, data: R::Data, + + #[cfg(feature = "registry")] + filter: FilterId, } /// An iterator over the parents of a span, ordered from leaf to root. @@ -179,10 +227,18 @@ pub struct SpanRef<'a, R: LookupSpan<'a>> { pub struct Scope<'a, R> { registry: &'a R, next: Option, + + #[cfg(feature = "registry")] + filter: FilterId, } feature! { - #![feature = "std"] + #![any(feature = "alloc", feature = "std")] + + #[cfg(not(feature = "smallvec"))] + use alloc::vec::{self, Vec}; + + use core::{fmt,iter}; /// An iterator over the parents of a span, ordered from root to leaf. /// @@ -192,9 +248,9 @@ feature! { R: LookupSpan<'a>, { #[cfg(feature = "smallvec")] - spans: std::iter::Rev>>, + spans: iter::Rev>>, #[cfg(not(feature = "smallvec"))] - spans: std::iter::Rev>>, + spans: iter::Rev>>, } #[cfg(feature = "smallvec")] @@ -243,11 +299,11 @@ feature! { } } - impl<'a, R> Debug for ScopeFromRoot<'a, R> + impl<'a, R> fmt::Debug for ScopeFromRoot<'a, R> where R: LookupSpan<'a>, { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { f.pad("ScopeFromRoot { .. }") } } @@ -260,9 +316,25 @@ where type Item = SpanRef<'a, R>; fn next(&mut self) -> Option { - let curr = self.registry.span(self.next.as_ref()?)?; - self.next = curr.parent_id().cloned(); - Some(curr) + loop { + let curr = self.registry.span(self.next.as_ref()?)?; + + #[cfg(feature = "registry")] + let curr = curr.with_filter(self.filter); + self.next = curr.data.parent().cloned(); + + // If the `Scope` is filtered, check if the current span is enabled + // by the selected filter ID. + + #[cfg(feature = "registry")] + if !curr.is_enabled_for(self.filter) { + // The current span in the chain is disabled for this + // filter. Try its parent. + continue; + } + + return Some(curr); + } } } @@ -294,15 +366,69 @@ where /// Returns the ID of this span's parent, or `None` if this span is the root /// of its trace tree. + #[deprecated( + note = "this method cannot properly support per-subscriber filtering, and may \ + return the `Id` of a disabled span if per-subscriber filtering is in \ + use. use `.parent().map(SpanRef::id)` instead.", + since = "0.2.21" + )] pub fn parent_id(&self) -> Option<&Id> { + // XXX(eliza): this doesn't work with PLF because the ID is potentially + // borrowed from a parent we got from the registry, rather than from + // `self`, so we can't return a borrowed parent. so, right now, we just + // return the actual parent ID, and ignore PLF. which is not great. + // + // i think if we want this to play nice with PLF, we should just change + // it to return the `Id` by value instead of `&Id` (which we ought to do + // anyway since an `Id` is just a word) but that's a breaking change. + // alternatively, we could deprecate this method since it can't support + // PLF in its current form (which is what we would want to do if we want + // to release PLF in a minor version)... + + // let mut id = self.data.parent()?; + // loop { + // // Is this parent enabled by our filter? + // if self + // .filter + // .map(|filter| self.registry.is_enabled_for(id, filter)) + // .unwrap_or(true) + // { + // return Some(id); + // } + // id = self.registry.span_data(id)?.parent()?; + // } self.data.parent() } /// Returns a `SpanRef` describing this span's parent, or `None` if this /// span is the root of its trace tree. + pub fn parent(&self) -> Option { let id = self.data.parent()?; let data = self.registry.span_data(id)?; + + #[cfg(feature = "registry")] + { + // move these into mut bindings if the registry feature is enabled, + // since they may be mutated in the loop. + let mut data = data; + loop { + // Is this parent enabled by our filter? + if data.is_enabled_for(self.filter) { + return Some(Self { + registry: self.registry, + filter: self.filter, + data, + }); + } + + // It's not enabled. If the disabled span has a parent, try that! + let id = data.parent()?; + data = self.registry.span_data(id)?; + } + } + + #[cfg(not(feature = "registry"))] Some(Self { registry: self.registry, data, @@ -380,6 +506,9 @@ where Scope { registry: self.registry, next: Some(self.id()), + + #[cfg(feature = "registry")] + filter: self.filter, } } @@ -402,6 +531,27 @@ where pub fn extensions_mut(&self) -> ExtensionsMut<'_> { self.data.extensions_mut() } + + #[cfg(feature = "registry")] + pub(crate) fn try_with_filter(self, filter: FilterId) -> Option { + if self.is_enabled_for(filter) { + return Some(self.with_filter(filter)); + } + + None + } + + #[inline] + #[cfg(feature = "registry")] + pub(crate) fn is_enabled_for(&self, filter: FilterId) -> bool { + self.data.is_enabled_for(filter) + } + + #[inline] + #[cfg(feature = "registry")] + fn with_filter(self, filter: FilterId) -> Self { + Self { filter, ..self } + } } #[cfg(all(test, feature = "registry", feature = "std"))] diff --git a/tracing-subscriber/src/registry/sharded.rs b/tracing-subscriber/src/registry/sharded.rs index b6ee290e12..736082234c 100644 --- a/tracing-subscriber/src/registry/sharded.rs +++ b/tracing-subscriber/src/registry/sharded.rs @@ -3,6 +3,7 @@ use thread_local::ThreadLocal; use super::stack::SpanStack; use crate::{ + filter::{FilterId, FilterMap, FilterState}, registry::{ extensions::{Extensions, ExtensionsInner, ExtensionsMut}, LookupSpan, SpanData, @@ -10,7 +11,7 @@ use crate::{ sync::RwLock, }; use std::{ - cell::{Cell, RefCell}, + cell::{self, Cell, RefCell}, sync::atomic::{fence, AtomicUsize, Ordering}, }; use tracing_core::{ @@ -90,6 +91,7 @@ use tracing_core::{ pub struct Registry { spans: Pool, current_spans: ThreadLocal>, + next_filter_id: u8, } /// Span data stored in a [`Registry`]. @@ -115,6 +117,7 @@ pub struct Data<'a> { /// implementations for this type are load-bearing. #[derive(Debug)] struct DataInner { + filter_map: FilterMap, metadata: &'static Metadata<'static>, parent: Option, ref_count: AtomicUsize, @@ -130,6 +133,7 @@ impl Default for Registry { Self { spans: Pool::new(), current_spans: ThreadLocal::new(), + next_filter_id: 0, } } } @@ -191,6 +195,14 @@ impl Registry { is_closing: false, } } + + pub(crate) fn has_per_layer_filters(&self) -> bool { + self.next_filter_id > 0 + } + + pub(crate) fn span_stack(&self) -> cell::Ref<'_, SpanStack> { + self.current_spans.get_or_default().borrow() + } } thread_local! { @@ -203,10 +215,17 @@ thread_local! { impl Collect for Registry { fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { + if self.has_per_layer_filters() { + return FilterState::take_interest().unwrap_or_else(Interest::always); + } + Interest::always() } fn enabled(&self, _: &Metadata<'_>) -> bool { + if self.has_per_layer_filters() { + return FilterState::event_enabled(); + } true } @@ -229,6 +248,14 @@ impl Collect for Registry { .create_with(|data| { data.metadata = attrs.metadata(); data.parent = parent; + data.filter_map = crate::filter::FILTERING.with(|filtering| filtering.filter_map()); + #[cfg(debug_assertions)] + { + if data.filter_map != FilterMap::default() { + debug_assert!(self.has_per_layer_filters()); + } + } + let refs = data.ref_count.get_mut(); debug_assert_eq!(*refs, 0); *refs = 1; @@ -331,6 +358,12 @@ impl<'a> LookupSpan<'a> for Registry { let inner = self.get(id)?; Some(Data { inner }) } + + fn register_filter(&mut self) -> FilterId { + let id = FilterId::new(self.next_filter_id); + self.next_filter_id += 1; + id + } } // === impl CloseGuard === @@ -388,6 +421,11 @@ impl<'a> SpanData<'a> for Data<'a> { fn extensions_mut(&self) -> ExtensionsMut<'_> { ExtensionsMut::new(self.inner.extensions.write().expect("Mutex poisoned")) } + + #[inline] + fn is_enabled_for(&self, filter: FilterId) -> bool { + self.inner.filter_map.is_enabled(filter) + } } // === impl DataInner === @@ -428,6 +466,7 @@ impl Default for DataInner { }; Self { + filter_map: FilterMap::default(), metadata: &NULL_METADATA, parent: None, ref_count: AtomicUsize::new(0), @@ -471,6 +510,8 @@ impl Clear for DataInner { l.into_inner() }) .clear(); + + self.filter_map = FilterMap::default(); } } @@ -489,6 +530,10 @@ mod tests { Collect, }; + #[derive(Debug)] + struct DoesNothing; + impl Subscribe for DoesNothing {} + struct AssertionSubscriber; impl Subscribe for AssertionSubscriber where diff --git a/tracing-subscriber/src/registry/stack.rs b/tracing-subscriber/src/registry/stack.rs index b0b372c13f..4a3f7e59d8 100644 --- a/tracing-subscriber/src/registry/stack.rs +++ b/tracing-subscriber/src/registry/stack.rs @@ -17,14 +17,14 @@ pub(crate) struct SpanStack { impl SpanStack { #[inline] - pub(crate) fn push(&mut self, id: Id) -> bool { + pub(super) fn push(&mut self, id: Id) -> bool { let duplicate = self.stack.iter().any(|i| i.id == id); self.stack.push(ContextId { id, duplicate }); !duplicate } #[inline] - pub(crate) fn pop(&mut self, expected_id: &Id) -> bool { + pub(super) fn pop(&mut self, expected_id: &Id) -> bool { if let Some((idx, _)) = self .stack .iter() @@ -39,12 +39,16 @@ impl SpanStack { } #[inline] - pub(crate) fn current(&self) -> Option<&Id> { + pub(crate) fn iter(&self) -> impl Iterator { self.stack .iter() .rev() - .find(|context_id| !context_id.duplicate) - .map(|context_id| &context_id.id) + .filter_map(|ContextId { id, duplicate }| if !*duplicate { Some(id) } else { None }) + } + + #[inline] + pub(crate) fn current(&self) -> Option<&Id> { + self.iter().next() } } diff --git a/tracing-subscriber/src/reload.rs b/tracing-subscriber/src/reload.rs index d245731d54..5827165667 100644 --- a/tracing-subscriber/src/reload.rs +++ b/tracing-subscriber/src/reload.rs @@ -58,6 +58,10 @@ where S: crate::Subscribe + 'static, C: Collect, { + fn on_subscribe(&mut self, collector: &mut C) { + try_lock!(self.inner.write(), else return).on_subscribe(collector); + } + #[inline] fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { try_lock!(self.inner.read(), else return Interest::sometimes()).register_callsite(metadata) diff --git a/tracing-subscriber/src/subscribe.rs b/tracing-subscriber/src/subscribe.rs deleted file mode 100644 index 85d96d42c5..0000000000 --- a/tracing-subscriber/src/subscribe.rs +++ /dev/null @@ -1,1468 +0,0 @@ -//! A composable abstraction for building [collector]s. -//! -//! [collector]: tracing_core::Collect -use tracing_core::{ - collect::{Collect, Interest}, - metadata::Metadata, - span, Event, LevelFilter, -}; - -#[cfg(all(feature = "std", feature = "registry"))] -use crate::registry::Registry; -use crate::registry::{self, LookupSpan, SpanRef}; -use core::{any::TypeId, cmp, marker::PhantomData, ptr::NonNull}; - -feature! { - #![feature = "alloc"] - use alloc::boxed::Box; - use core::ops::Deref; -} - -/// A composable handler for `tracing` events. -/// -/// The [`Collect`] trait in `tracing-core` represents the _complete_ set of -/// functionality required to consume `tracing` instrumentation. This means that -/// a single [collector] instance is a self-contained implementation of a -/// complete strategy for collecting traces; but it _also_ means that the -/// `Collect` trait cannot easily be composed with other `Collect`s. -/// -/// In particular, collectors are responsible for generating [span IDs] and -/// assigning them to spans. Since these IDs must uniquely identify a span -/// within the context of the current trace, this means that there may only be -/// a single [collector] for a given thread at any point in time — -/// otherwise, there would be no authoritative source of span IDs. -/// -/// [collector]: tracing_core::Collect -/// -/// On the other hand, the majority of the [`Collect`] trait's functionality -/// is composable: any number of collectors may _observe_ events, span entry -/// and exit, and so on, provided that there is a single authoritative source of -/// span IDs. The `Subscribe` trait represents this composable subset of the -/// [`Collect`]'s behavior; it can _observe_ events and spans, but does not -/// assign IDs. -/// -/// ## Composing Subscribers -/// -/// Since `Subscribe` does not implement a complete strategy for collecting -/// traces, it must be composed with a `Collect` in order to be used. The -/// `Subscribe` trait is generic over a type parameter (called `C` in the trait -/// definition), representing the types of `Collect` they can be composed -/// with. Thus, a subscriber may be implemented that will only compose with a -/// particular `Collect` implementation, or additional trait bounds may be -/// added to constrain what types implementing `Collect` a subscriber can wrap. -/// -/// Subscribers may be added to a `Collect` by using the [`CollectExt::with`] -/// method, which is provided by `tracing-subscriber`'s [prelude]. This method -/// returns a [`Layered`] struct that implements `Collect` by composing the -/// subscriber with the collector. -/// -/// For example: -/// ```rust -/// use tracing_subscriber::Subscribe; -/// use tracing_subscriber::subscribe::CollectExt; -/// use tracing::Collect; -/// use tracing_core::span::Current; -/// -/// pub struct MySubscriber { -/// // ... -/// } -/// -/// impl Subscribe for MySubscriber { -/// // ... -/// } -/// -/// pub struct MyCollector { -/// // ... -/// } -/// -/// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; -/// impl Collect for MyCollector { -/// // ... -/// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } -/// # fn record(&self, _: &Id, _: &Record) {} -/// # fn event(&self, _: &Event) {} -/// # fn record_follows_from(&self, _: &Id, _: &Id) {} -/// # fn enabled(&self, _: &Metadata) -> bool { false } -/// # fn enter(&self, _: &Id) {} -/// # fn exit(&self, _: &Id) {} -/// # fn current_span(&self) -> Current { Current::unknown() } -/// } -/// # impl MySubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyCollector { -/// # fn new() -> Self { Self { }} -/// # } -/// -/// let collector = MyCollector::new() -/// .with(MySubscriber::new()); -/// -/// tracing::collect::set_global_default(collector); -/// ``` -/// -/// Multiple `Subscriber`s may be composed in the same manner: -/// ```rust -/// # use tracing_subscriber::Subscribe; -/// # use tracing_subscriber::subscribe::CollectExt; -/// # use tracing::Collect; -/// # use tracing_core::span::Current; -/// pub struct MyOtherSubscriber { -/// // ... -/// } -/// -/// impl Subscribe for MyOtherSubscriber { -/// // ... -/// } -/// -/// pub struct MyThirdSubscriber { -/// // ... -/// } -/// -/// impl Subscribe for MyThirdSubscriber { -/// // ... -/// } -/// # pub struct MySubscriber {} -/// # impl Subscribe for MySubscriber {} -/// # pub struct MyCollector { } -/// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; -/// # impl Collect for MyCollector { -/// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } -/// # fn record(&self, _: &Id, _: &Record) {} -/// # fn event(&self, _: &Event) {} -/// # fn record_follows_from(&self, _: &Id, _: &Id) {} -/// # fn enabled(&self, _: &Metadata) -> bool { false } -/// # fn enter(&self, _: &Id) {} -/// # fn exit(&self, _: &Id) {} -/// # fn current_span(&self) -> Current { Current::unknown() } -/// } -/// # impl MySubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyOtherSubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyThirdSubscriber { -/// # fn new() -> Self { Self {} } -/// # } -/// # impl MyCollector { -/// # fn new() -> Self { Self { }} -/// # } -/// -/// let collector = MyCollector::new() -/// .with(MySubscriber::new()) -/// .with(MyOtherSubscriber::new()) -/// .with(MyThirdSubscriber::new()); -/// -/// tracing::collect::set_global_default(collector); -/// ``` -/// -/// The [`Subscribe::with_collector` method][with-col] constructs the `Layered` -/// type from a `Subscribe` and `Collect`, and is called by -/// [`CollectExt::with`]. In general, it is more idiomatic to use -/// `CollectExt::with`, and treat `Subscribe::with_collector` as an -/// implementation detail, as `with_collector` calls must be nested, leading to -/// less clear code for the reader. However, subscribers which wish to perform -/// additional behavior when composed with a subscriber may provide their own -/// implementations of `SubscriberExt::with`. -/// -/// [prelude]: super::prelude -/// [with-col]: Subscribe::with_collector() -/// -/// ## Recording Traces -/// -/// The `Subscribe` trait defines a set of methods for consuming notifications from -/// tracing instrumentation, which are generally equivalent to the similarly -/// named methods on [`Collect`]. Unlike [`Collect`], the methods on -/// `Subscribe` are additionally passed a [`Context`] type, which exposes additional -/// information provided by the wrapped collector (such as [the current span]) -/// to the subscriber. -/// -/// ## Filtering with Subscribers -/// -/// As well as strategies for handling trace events, the `Subscriber` trait may also -/// be used to represent composable _filters_. This allows the determination of -/// what spans and events should be recorded to be decoupled from _how_ they are -/// recorded: a filtering subscriber can be applied to other subscribers or -/// collectors. A `Subscriber` that implements a filtering strategy should override the -/// [`register_callsite`] and/or [`enabled`] methods. It may also choose to implement -/// methods such as [`on_enter`], if it wishes to filter trace events based on -/// the current span context. -/// -/// Note that the [`Subscribe::register_callsite`] and [`Subscribe::enabled`] methods -/// determine whether a span or event is enabled *globally*. Thus, they should -/// **not** be used to indicate whether an individual subscriber wishes to record a -/// particular span or event. Instead, if a subscriber is only interested in a subset -/// of trace data, but does *not* wish to disable other spans and events for the -/// rest of the subscriber stack should ignore those spans and events in its -/// notification methods. -/// -/// The filtering methods on a stack of subscribers are evaluated in a top-down -/// order, starting with the outermost `Subscribe` and ending with the wrapped -/// [`Collect`]. If any subscriber returns `false` from its [`enabled`] method, or -/// [`Interest::never()`] from its [`register_callsite`] method, filter -/// evaluation will short-circuit and the span or event will be disabled. -/// -/// [`Collect`]: tracing_core::collect::Collect -/// [span IDs]: tracing_core::span::Id -/// [the current span]: Context::current_span() -/// [`register_callsite`]: Subscribe::register_callsite() -/// [`enabled`]: Subscribe::enabled() -/// [`on_enter`]: Subscribe::on_enter() -pub trait Subscribe -where - C: Collect, - Self: 'static, -{ - /// Registers a new callsite with this subscriber, returning whether or not - /// the subscriber is interested in being notified about the callsite, similarly - /// to [`Collect::register_callsite`]. - /// - /// By default, this returns [`Interest::always()`] if [`self.enabled`] returns - /// true, or [`Interest::never()`] if it returns false. - /// - ///
- /// 
-    ///
-    /// **Note**: This method (and [`Subscribe::enabled`]) determine whether a span or event is
-    /// globally enabled, *not* whether the individual subscriber will be notified about that
-    /// span or event.  This is intended to be used by subscribers that implement filtering for
-    /// the entire stack. Subscribers which do not wish to be notified about certain spans or
-    /// events but do not wish to globally disable them should ignore those spans or events in
-    /// their [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
-    /// and other notification methods.
-    ///
-    ///
- /// - /// See [the trait-level documentation] for more information on filtering - /// with `Subscriber`s. - /// - /// Subscribers may also implement this method to perform any behaviour that - /// should be run once per callsite. If the subscriber wishes to use - /// `register_callsite` for per-callsite behaviour, but does not want to - /// globally enable or disable those callsites, it should always return - /// [`Interest::always()`]. - /// - /// [`Interest`]: tracing_core::Interest - /// [`Collect::register_callsite`]: tracing_core::Collect::register_callsite() - /// [`self.enabled`]: Subscribe::enabled() - /// [the trait-level documentation]: #filtering-with-subscribers - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - if self.enabled(metadata, Context::none()) { - Interest::always() - } else { - Interest::never() - } - } - - /// Returns `true` if this subscriber is interested in a span or event with the - /// given `metadata` in the current [`Context`], similarly to - /// [`Collect::enabled`]. - /// - /// By default, this always returns `true`, allowing the wrapped collector - /// to choose to disable the span. - /// - ///
- /// 
-    ///
-    /// **Note**: This method (and [`register_callsite`][Self::register_callsite])
-    /// determine whether a span or event is
-    /// globally enabled, *not* whether the individual subscriber will be
-    /// notified about that span or event. This is intended to be used
-    /// by layers that implement filtering for the entire stack. Layers which do
-    /// not wish to be notified about certain spans or events but do not wish to
-    /// globally disable them should ignore those spans or events in their
-    /// [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
-    /// and other notification methods.
-    ///
-    ///
- /// - /// - /// See [the trait-level documentation] for more information on filtering - /// with `Subscriber`s. - /// - /// [`Interest`]: tracing_core::Interest - /// [the trait-level documentation]: #filtering-with-subscribers - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - let _ = (metadata, ctx); - true - } - - /// Notifies this subscriber that a new span was constructed with the given - /// `Attributes` and `Id`. - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - let _ = (attrs, id, ctx); - } - - // TODO(eliza): do we want this to be a public API? If we end up moving - // filtering subscribers to a separate trait, we may no longer want `Subscriber`s to - // be able to participate in max level hinting... - #[doc(hidden)] - fn max_level_hint(&self) -> Option { - None - } - - /// Notifies this subscriber that a span with the given `Id` recorded the given - /// `values`. - // Note: it's unclear to me why we'd need the current span in `record` (the - // only thing the `Context` type currently provides), but passing it in anyway - // seems like a good future-proofing measure as it may grow other methods later... - fn on_record(&self, _span: &span::Id, _values: &span::Record<'_>, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that a span with the ID `span` recorded that it - /// follows from the span with the ID `follows`. - // Note: it's unclear to me why we'd need the current span in `record` (the - // only thing the `Context` type currently provides), but passing it in anyway - // seems like a good future-proofing measure as it may grow other methods later... - fn on_follows_from(&self, _span: &span::Id, _follows: &span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that an event has occurred. - fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that a span with the given ID was entered. - fn on_enter(&self, _id: &span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that the span with the given ID was exited. - fn on_exit(&self, _id: &span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that the span with the given ID has been closed. - fn on_close(&self, _id: span::Id, _ctx: Context<'_, C>) {} - - /// Notifies this subscriber that a span ID has been cloned, and that the - /// subscriber returned a different ID. - fn on_id_change(&self, _old: &span::Id, _new: &span::Id, _ctx: Context<'_, C>) {} - - /// Composes this subscriber around the given collector, returning a `Layered` - /// struct implementing `Subscribe`. - /// - /// The returned subscriber will call the methods on this subscriber and then - /// those of the new subscriber, before calling the methods on the collector - /// it wraps. For example: - /// - /// ```rust - /// # use tracing_subscriber::subscribe::Subscribe; - /// # use tracing_core::Collect; - /// # use tracing_core::span::Current; - /// pub struct FooSubscriber { - /// // ... - /// } - /// - /// pub struct BarSubscriber { - /// // ... - /// } - /// - /// pub struct MyCollector { - /// // ... - /// } - /// - /// impl Subscribe for FooSubscriber { - /// // ... - /// } - /// - /// impl Subscribe for BarSubscriber { - /// // ... - /// } - /// - /// # impl FooSubscriber { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl BarSubscriber { - /// # fn new() -> Self { Self { }} - /// # } - /// # impl MyCollector { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; - /// # impl tracing_core::Collect for MyCollector { - /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } - /// # fn record(&self, _: &Id, _: &Record) {} - /// # fn event(&self, _: &Event) {} - /// # fn record_follows_from(&self, _: &Id, _: &Id) {} - /// # fn enabled(&self, _: &Metadata) -> bool { false } - /// # fn enter(&self, _: &Id) {} - /// # fn exit(&self, _: &Id) {} - /// # fn current_span(&self) -> Current { Current::unknown() } - /// # } - /// let collector = FooSubscriber::new() - /// .and_then(BarSubscriber::new()) - /// .with_collector(MyCollector::new()); - /// ``` - /// - /// Multiple subscribers may be composed in this manner: - /// - /// ```rust - /// # use tracing_subscriber::subscribe::Subscribe; - /// # use tracing_core::{Collect, span::Current}; - /// # pub struct FooSubscriber {} - /// # pub struct BarSubscriber {} - /// # pub struct MyCollector {} - /// # impl Subscribe for FooSubscriber {} - /// # impl Subscribe for BarSubscriber {} - /// # impl FooSubscriber { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl BarSubscriber { - /// # fn new() -> Self { Self { }} - /// # } - /// # impl MyCollector { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; - /// # impl tracing_core::Collect for MyCollector { - /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } - /// # fn record(&self, _: &Id, _: &Record) {} - /// # fn event(&self, _: &Event) {} - /// # fn record_follows_from(&self, _: &Id, _: &Id) {} - /// # fn enabled(&self, _: &Metadata) -> bool { false } - /// # fn enter(&self, _: &Id) {} - /// # fn exit(&self, _: &Id) {} - /// # fn current_span(&self) -> Current { Current::unknown() } - /// # } - /// pub struct BazSubscriber { - /// // ... - /// } - /// - /// impl Subscribe for BazSubscriber { - /// // ... - /// } - /// # impl BazSubscriber { fn new() -> Self { BazSubscriber {} } } - /// - /// let collector = FooSubscriber::new() - /// .and_then(BarSubscriber::new()) - /// .and_then(BazSubscriber::new()) - /// .with_collector(MyCollector::new()); - /// ``` - fn and_then(self, subscriber: S) -> Layered - where - S: Subscribe, - Self: Sized, - { - Layered { - subscriber, - inner: self, - _s: PhantomData, - } - } - - /// Composes this subscriber with the given collector, returning a - /// `Layered` struct that implements [`Collect`]. - /// - /// The returned `Layered` subscriber will call the methods on this subscriber - /// and then those of the wrapped collector. - /// - /// For example: - /// ```rust - /// # use tracing_subscriber::subscribe::Subscribe; - /// # use tracing_core::Collect; - /// # use tracing_core::span::Current; - /// pub struct FooSubscriber { - /// // ... - /// } - /// - /// pub struct MyCollector { - /// // ... - /// } - /// - /// impl Subscribe for FooSubscriber { - /// // ... - /// } - /// - /// # impl FooSubscriber { - /// # fn new() -> Self { Self {} } - /// # } - /// # impl MyCollector { - /// # fn new() -> Self { Self { }} - /// # } - /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata}; - /// # impl tracing_core::Collect for MyCollector { - /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(0) } - /// # fn record(&self, _: &Id, _: &Record) {} - /// # fn event(&self, _: &tracing_core::Event) {} - /// # fn record_follows_from(&self, _: &Id, _: &Id) {} - /// # fn enabled(&self, _: &Metadata) -> bool { false } - /// # fn enter(&self, _: &Id) {} - /// # fn exit(&self, _: &Id) {} - /// # fn current_span(&self) -> Current { Current::unknown() } - /// # } - /// let collector = FooSubscriber::new() - /// .with_collector(MyCollector::new()); - ///``` - /// - /// [`Collect`]: tracing_core::Collect - fn with_collector(self, inner: C) -> Layered - where - Self: Sized, - { - Layered { - subscriber: self, - inner, - _s: PhantomData, - } - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - Some(NonNull::from(self).cast()) - } else { - None - } - } -} - -/// Extension trait adding a `with(Subscriber)` combinator to `Collect`. -pub trait CollectExt: Collect + crate::sealed::Sealed { - /// Wraps `self` with the provided `subscriber`. - fn with(self, subscriber: S) -> Layered - where - S: Subscribe, - Self: Sized, - { - subscriber.with_collector(self) - } -} - -/// Represents information about the current context provided to [subscriber]s by the -/// wrapped [collector]. -/// -/// To access [stored data] keyed by a span ID, implementors of the `Subscribe` -/// trait should ensure that the `Collect` type parameter is *also* bound by the -/// [`LookupSpan`]: -/// -/// ```rust -/// use tracing::Collect; -/// use tracing_subscriber::{Subscribe, registry::LookupSpan}; -/// -/// pub struct MyCollector; -/// -/// impl Subscribe for MyCollector -/// where -/// C: Collect + for<'a> LookupSpan<'a>, -/// { -/// // ... -/// } -/// ``` -/// -/// [subscriber]: Subscribe -/// [collector]: tracing_core::Collect -/// [stored data]: super::registry::SpanRef -#[derive(Debug)] -pub struct Context<'a, C> { - collector: Option<&'a C>, -} - -/// A [collector] composed of a collector wrapped by one or more -/// [subscriber]s. -/// -/// [subscriber]: super::subscribe::Subscribe -/// [collector]: tracing_core::Collect -#[derive(Clone, Debug)] -pub struct Layered { - subscriber: S, - inner: I, - _s: PhantomData, -} - -/// A Subscriber that does nothing. -#[derive(Clone, Debug, Default)] -pub struct Identity { - _p: (), -} - -// === impl Layered === - -impl Collect for Layered -where - S: Subscribe, - C: Collect, -{ - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - let outer = self.subscriber.register_callsite(metadata); - if outer.is_never() { - // if the outer subscriber has disabled the callsite, return now so that - // the collector doesn't get its hopes up. - return outer; - } - - // The intention behind calling `inner.register_callsite()` before the if statement - // is to ensure that the inner subscriber is informed that the callsite exists - // regardless of the outer subscriber's filtering decision. - let inner = self.inner.register_callsite(metadata); - if outer.is_sometimes() { - // if this interest is "sometimes", return "sometimes" to ensure that - // filters are reevaluated. - outer - } else { - // otherwise, allow the inner subscriber or collector to weigh in. - inner - } - } - - fn enabled(&self, metadata: &Metadata<'_>) -> bool { - if self.subscriber.enabled(metadata, self.ctx()) { - // if the outer subscriber enables the callsite metadata, ask the collector. - self.inner.enabled(metadata) - } else { - // otherwise, the callsite is disabled by the subscriber - false - } - } - - fn max_level_hint(&self) -> Option { - cmp::max( - self.subscriber.max_level_hint(), - self.inner.max_level_hint(), - ) - } - - fn new_span(&self, span: &span::Attributes<'_>) -> span::Id { - let id = self.inner.new_span(span); - self.subscriber.on_new_span(span, &id, self.ctx()); - id - } - - fn record(&self, span: &span::Id, values: &span::Record<'_>) { - self.inner.record(span, values); - self.subscriber.on_record(span, values, self.ctx()); - } - - fn record_follows_from(&self, span: &span::Id, follows: &span::Id) { - self.inner.record_follows_from(span, follows); - self.subscriber.on_follows_from(span, follows, self.ctx()); - } - - fn event(&self, event: &Event<'_>) { - self.inner.event(event); - self.subscriber.on_event(event, self.ctx()); - } - - fn enter(&self, span: &span::Id) { - self.inner.enter(span); - self.subscriber.on_enter(span, self.ctx()); - } - - fn exit(&self, span: &span::Id) { - self.inner.exit(span); - self.subscriber.on_exit(span, self.ctx()); - } - - fn clone_span(&self, old: &span::Id) -> span::Id { - let new = self.inner.clone_span(old); - if &new != old { - self.subscriber.on_id_change(old, &new, self.ctx()) - }; - new - } - - #[inline] - fn drop_span(&self, id: span::Id) { - self.try_close(id); - } - - fn try_close(&self, id: span::Id) -> bool { - #[cfg(all(feature = "registry", feature = "std"))] - let subscriber = &self.inner as &dyn Collect; - #[cfg(all(feature = "registry", feature = "std"))] - let mut guard = subscriber - .downcast_ref::() - .map(|registry| registry.start_close(id.clone())); - if self.inner.try_close(id.clone()) { - // If we have a registry's close guard, indicate that the span is - // closing. - #[cfg(all(feature = "registry", feature = "std"))] - { - if let Some(g) = guard.as_mut() { - g.is_closing() - }; - } - - self.subscriber.on_close(id, self.ctx()); - true - } else { - false - } - } - - #[inline] - fn current_span(&self) -> span::Current { - self.inner.current_span() - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - return Some(NonNull::from(self).cast()); - } - self.subscriber - .downcast_raw(id) - .or_else(|| self.inner.downcast_raw(id)) - } -} - -impl Subscribe for Layered -where - A: Subscribe, - B: Subscribe, - C: Collect, -{ - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - let outer = self.subscriber.register_callsite(metadata); - if outer.is_never() { - // if the outer subscriber has disabled the callsite, return now so that - // inner subscribers don't get their hopes up. - return outer; - } - - // The intention behind calling `inner.register_callsite()` before the if statement - // is to ensure that the inner subscriber is informed that the callsite exists - // regardless of the outer subscriber's filtering decision. - let inner = self.inner.register_callsite(metadata); - if outer.is_sometimes() { - // if this interest is "sometimes", return "sometimes" to ensure that - // filters are reevaluated. - outer - } else { - // otherwise, allow the inner subscriber or collector to weigh in. - inner - } - } - - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - if self.subscriber.enabled(metadata, ctx.clone()) { - // if the outer subscriber enables the callsite metadata, ask the inner subscriber. - self.inner.enabled(metadata, ctx) - } else { - // otherwise, the callsite is disabled by this subscriber - false - } - } - - #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - self.inner.on_new_span(attrs, id, ctx.clone()); - self.subscriber.on_new_span(attrs, id, ctx); - } - - #[inline] - fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { - self.inner.on_record(span, values, ctx.clone()); - self.subscriber.on_record(span, values, ctx); - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { - self.inner.on_follows_from(span, follows, ctx.clone()); - self.subscriber.on_follows_from(span, follows, ctx); - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { - self.inner.on_event(event, ctx.clone()); - self.subscriber.on_event(event, ctx); - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { - self.inner.on_enter(id, ctx.clone()); - self.subscriber.on_enter(id, ctx); - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { - self.inner.on_exit(id, ctx.clone()); - self.subscriber.on_exit(id, ctx); - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { - self.inner.on_close(id.clone(), ctx.clone()); - self.subscriber.on_close(id, ctx); - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { - self.inner.on_id_change(old, new, ctx.clone()); - self.subscriber.on_id_change(old, new, ctx); - } - - #[doc(hidden)] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - return Some(NonNull::from(self).cast()); - } - self.subscriber - .downcast_raw(id) - .or_else(|| self.inner.downcast_raw(id)) - } -} - -impl Subscribe for Option -where - S: Subscribe, - C: Collect, -{ - #[inline] - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - match self { - Some(ref inner) => inner.register_callsite(metadata), - None => Interest::always(), - } - } - - #[inline] - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - match self { - Some(ref inner) => inner.enabled(metadata, ctx), - None => true, - } - } - - #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_new_span(attrs, id, ctx) - } - } - - #[inline] - fn max_level_hint(&self) -> Option { - match self { - Some(ref inner) => inner.max_level_hint(), - None => None, - } - } - - #[inline] - fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_record(span, values, ctx); - } - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_follows_from(span, follows, ctx); - } - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_event(event, ctx); - } - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_enter(id, ctx); - } - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_exit(id, ctx); - } - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_close(id, ctx); - } - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { - if let Some(ref inner) = self { - inner.on_id_change(old, new, ctx) - } - } - - #[doc(hidden)] - #[inline] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - if id == TypeId::of::() { - Some(NonNull::from(self).cast()) - } else { - self.as_ref().and_then(|inner| inner.downcast_raw(id)) - } - } -} - -feature! { - #![any(feature = "std", feature = "alloc")] - - macro_rules! subscriber_impl_body { - () => { - #[inline] - fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { - self.deref().on_new_span(attrs, id, ctx) - } - - #[inline] - fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { - self.deref().register_callsite(metadata) - } - - #[inline] - fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { - self.deref().enabled(metadata, ctx) - } - - #[inline] - fn max_level_hint(&self) -> Option { - self.deref().max_level_hint() - } - - #[inline] - fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { - self.deref().on_record(span, values, ctx) - } - - #[inline] - fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { - self.deref().on_follows_from(span, follows, ctx) - } - - #[inline] - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { - self.deref().on_event(event, ctx) - } - - #[inline] - fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { - self.deref().on_enter(id, ctx) - } - - #[inline] - fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { - self.deref().on_exit(id, ctx) - } - - #[inline] - fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { - self.deref().on_close(id, ctx) - } - - #[inline] - fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { - self.deref().on_id_change(old, new, ctx) - } - - #[doc(hidden)] - #[inline] - unsafe fn downcast_raw(&self, id: TypeId) -> Option> { - self.deref().downcast_raw(id) - } - }; - } - - impl Subscribe for Box - where - S: Subscribe, - C: Collect, - { - subscriber_impl_body! {} - } - - impl Subscribe for Box + Send + Sync> - where - C: Collect, - { - subscriber_impl_body! {} - } -} - -impl<'a, S, C> LookupSpan<'a> for Layered -where - C: Collect + LookupSpan<'a>, -{ - type Data = C::Data; - - fn span_data(&'a self, id: &span::Id) -> Option { - self.inner.span_data(id) - } -} - -impl Layered -where - C: Collect, -{ - fn ctx(&self) -> Context<'_, C> { - Context { - collector: Some(&self.inner), - } - } -} - -// impl Layered { -// // TODO(eliza): is there a compelling use-case for this being public? -// pub(crate) fn into_inner(self) -> S { -// self.inner -// } -// } - -// === impl CollectExt === - -impl crate::sealed::Sealed for C {} -impl CollectExt for C {} - -// === impl Context === - -impl<'a, C> Context<'a, C> -where - C: Collect, -{ - /// Returns the wrapped subscriber's view of the current span. - #[inline] - pub fn current_span(&self) -> span::Current { - self.collector - .map(Collect::current_span) - // TODO: this would be more correct as "unknown", so perhaps - // `tracing-core` should make `Current::unknown()` public? - .unwrap_or_else(span::Current::none) - } - - /// Returns whether the wrapped subscriber would enable the current span. - #[inline] - pub fn enabled(&self, metadata: &Metadata<'_>) -> bool { - self.collector - .map(|collector| collector.enabled(metadata)) - // If this context is `None`, we are registering a callsite, so - // return `true` so that the subscriber does not incorrectly assume that - // the inner collector has disabled this metadata. - // TODO(eliza): would it be more correct for this to return an `Option`? - .unwrap_or(true) - } - - /// Records the provided `event` with the wrapped collector. - /// - /// # Notes - /// - /// - The collector is free to expect that the event's callsite has been - /// [registered][register], and may panic or fail to observe the event if this is - /// not the case. The `tracing` crate's macros ensure that all events are - /// registered, but if the event is constructed through other means, the - /// user is responsible for ensuring that [`register_callsite`][register] - /// has been called prior to calling this method. - /// - This does _not_ call [`enabled`] on the inner collector. If the - /// caller wishes to apply the wrapped collector's filter before choosing - /// whether to record the event, it may first call [`Context::enabled`] to - /// check whether the event would be enabled. This allows `Collectors`s to - /// elide constructing the event if it would not be recorded. - /// - /// [register]: tracing_core::collect::Collect::register_callsite() - /// [`enabled`]: tracing_core::collect::Collect::enabled() - /// [`Context::enabled`]: ::enabled() - #[inline] - pub fn event(&self, event: &Event<'_>) { - if let Some(collector) = self.collector { - collector.event(event); - } - } - - /// Returns a [`SpanRef`] for the parent span of the given [`Event`], if - /// it has a parent. - /// - /// If the event has an explicitly overridden parent, this method returns - /// a reference to that span. If the event's parent is the current span, - /// this returns a reference to the current span, if there is one. If this - /// returns `None`, then either the event's parent was explicitly set to - /// `None`, or the event's parent was defined contextually, but no span - /// is currently entered. - /// - /// Compared to [`Context::current_span`] and [`Context::lookup_current`], - /// this respects overrides provided by the [`Event`]. - /// - /// Compared to [`Event::parent`], this automatically falls back to the contextual - /// span, if required. - /// - /// ```rust - /// use tracing::{Collect, Event}; - /// use tracing_subscriber::{ - /// subscribe::{Context, Subscribe}, - /// prelude::*, - /// registry::LookupSpan, - /// }; - /// - /// struct PrintingSubscriber; - /// impl Subscribe for PrintingSubscriber - /// where - /// C: Collect + for<'lookup> LookupSpan<'lookup>, - /// { - /// fn on_event(&self, event: &Event, ctx: Context) { - /// let span = ctx.event_span(event); - /// println!("Event in span: {:?}", span.map(|s| s.name())); - /// } - /// } - /// - /// tracing::collect::with_default(tracing_subscriber::registry().with(PrintingSubscriber), || { - /// tracing::info!("no span"); - /// // Prints: Event in span: None - /// - /// let span = tracing::info_span!("span"); - /// tracing::info!(parent: &span, "explicitly specified"); - /// // Prints: Event in span: Some("span") - /// - /// let _guard = span.enter(); - /// tracing::info!("contextual span"); - /// // Prints: Event in span: Some("span") - /// }); - /// ``` - /// - ///
- /// 
-    /// Note: This requires the wrapped subscriber to implement the
-    /// LookupSpan trait.
-    /// See the documentation on Context's
-    /// declaration for details.
-    ///
- #[inline] - pub fn event_span(&self, event: &Event<'_>) -> Option> - where - C: for<'lookup> LookupSpan<'lookup>, - { - if event.is_root() { - None - } else if event.is_contextual() { - self.lookup_current() - } else { - event.parent().and_then(|id| self.span(id)) - } - } - - /// Returns metadata for the span with the given `id`, if it exists. - /// - /// If this returns `None`, then no span exists for that ID (either it has - /// closed or the ID is invalid). - #[inline] - pub fn metadata(&self, id: &span::Id) -> Option<&'static Metadata<'static>> - where - C: for<'lookup> LookupSpan<'lookup>, - { - let span = self.collector.as_ref()?.span(id)?; - Some(span.metadata()) - } - - /// Returns [stored data] for the span with the given `id`, if it exists. - /// - /// If this returns `None`, then no span exists for that ID (either it has - /// closed or the ID is invalid). - /// - ///
- /// 
-    ///
-    /// **Note**: This requires the wrapped collector to implement the [`LookupSpan`] trait.
-    /// See the documentation on [`Context`]'s declaration for details.
-    ///
-    ///
- /// - /// [stored data]: super::registry::SpanRef - #[inline] - pub fn span(&self, id: &span::Id) -> Option> - where - C: for<'lookup> LookupSpan<'lookup>, - { - self.collector.as_ref()?.span(id) - } - - /// Returns `true` if an active span exists for the given `Id`. - /// - ///
- /// 
-    ///
-    /// **Note**: This requires the wrapped subscriber to implement the [`LookupSpan`] trait.
-    /// See the documentation on [`Context`]'s declaration for details.
-    ///
-    ///
- #[inline] - pub fn exists(&self, id: &span::Id) -> bool - where - C: for<'lookup> LookupSpan<'lookup>, - { - self.collector.as_ref().and_then(|s| s.span(id)).is_some() - } - - /// Returns [stored data] for the span that the wrapped collector considers - /// to be the current. - /// - /// If this returns `None`, then we are not currently within a span. - /// - ///
- /// 
-    ///
-    /// **Note**: This requires the wrapped subscriber to implement the [`LookupSpan`] trait.
-    /// See the documentation on [`Context`]'s declaration for details.
-    ///
-    ///
- /// - /// [stored data]: super::registry::SpanRef - #[inline] - pub fn lookup_current(&self) -> Option> - where - C: for<'lookup> LookupSpan<'lookup>, - { - let collector = self.collector.as_ref()?; - let current = collector.current_span(); - let id = current.id()?; - let span = collector.span(id); - debug_assert!( - span.is_some(), - "the subscriber should have data for the current span ({:?})!", - id, - ); - span - } - - /// Returns an iterator over the [stored data] for all the spans in the - /// current context, starting with the specified span and ending with the - /// root of the trace tree and ending with the current span. - /// - ///
- ///
ⓘNote
- ///
- ///
- /// 
-    /// Note: Compared to scope this
-    /// returns the spans in reverse order (from leaf to root). Use
-    /// Scope::from_root
-    /// in case root-to-leaf ordering is desired.
-    ///
- /// - ///
- /// 
-    /// Note: This requires the wrapped subscriber to implement the
-    /// LookupSpan trait.
-    /// See the documentation on Context's
-    /// declaration for details.
-    ///
- /// - /// [stored data]: ../registry/struct.SpanRef.html - pub fn span_scope(&self, id: &span::Id) -> Option> - where - C: for<'lookup> registry::LookupSpan<'lookup>, - { - Some(self.span(id)?.scope()) - } - - /// Returns an iterator over the [stored data] for all the spans in the - /// current context, starting with the parent span of the specified event, - /// and ending with the root of the trace tree and ending with the current span. - /// - ///
- /// 
-    /// Note: Compared to scope this
-    /// returns the spans in reverse order (from leaf to root). Use
-    /// Scope::from_root
-    /// in case root-to-leaf ordering is desired.
-    ///
- /// - ///
- /// 
-    /// Note: This requires the wrapped subscriber to implement the
-    /// LookupSpan trait.
-    /// See the documentation on Context's
-    /// declaration for details.
-    ///
- /// - /// [stored data]: ../registry/struct.SpanRef.html - pub fn event_scope(&self, event: &Event<'_>) -> Option> - where - C: for<'lookup> registry::LookupSpan<'lookup>, - { - Some(self.event_span(event)?.scope()) - } -} - -impl<'a, C> Context<'a, C> { - pub(crate) fn none() -> Self { - Self { collector: None } - } -} - -impl<'a, C> Clone for Context<'a, C> { - #[inline] - fn clone(&self) -> Self { - let collector = self.collector.as_ref().copied(); - Context { collector } - } -} - -// === impl Identity === -// -impl Subscribe for Identity {} - -impl Identity { - /// Returns a new `Identity` subscriber. - pub fn new() -> Self { - Self { _p: () } - } -} - -#[cfg(test)] -pub(crate) mod tests { - use super::*; - - pub(crate) struct NopCollector; - - impl Collect for NopCollector { - fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { - Interest::never() - } - - fn enabled(&self, _: &Metadata<'_>) -> bool { - false - } - - fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { - span::Id::from_u64(1) - } - - fn record(&self, _: &span::Id, _: &span::Record<'_>) {} - fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} - fn event(&self, _: &Event<'_>) {} - fn enter(&self, _: &span::Id) {} - fn exit(&self, _: &span::Id) {} - fn current_span(&self) -> span::Current { - span::Current::unknown() - } - } - - struct NopSubscriber; - impl Subscribe for NopSubscriber {} - - #[allow(dead_code)] - struct NopSubscriber2; - impl Subscribe for NopSubscriber2 {} - - /// A subscriber that holds a string. - /// - /// Used to test that pointers returned by downcasting are actually valid. - struct StringSubscriber(&'static str); - impl Subscribe for StringSubscriber {} - - struct StringSubscriber2(&'static str); - impl Subscribe for StringSubscriber2 {} - - struct StringSubscriber3(&'static str); - impl Subscribe for StringSubscriber3 {} - - pub(crate) struct StringCollector(&'static str); - - impl Collect for StringCollector { - fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { - Interest::never() - } - - fn enabled(&self, _: &Metadata<'_>) -> bool { - false - } - - fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { - span::Id::from_u64(1) - } - - fn record(&self, _: &span::Id, _: &span::Record<'_>) {} - fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} - fn event(&self, _: &Event<'_>) {} - fn enter(&self, _: &span::Id) {} - fn exit(&self, _: &span::Id) {} - fn current_span(&self) -> span::Current { - span::Current::unknown() - } - } - - fn assert_collector(_s: impl Collect) {} - - #[test] - fn subscriber_is_collector() { - let s = NopSubscriber.with_collector(NopCollector); - assert_collector(s) - } - - #[test] - fn two_subscribers_are_collector() { - let s = NopSubscriber - .and_then(NopSubscriber) - .with_collector(NopCollector); - assert_collector(s) - } - - #[test] - fn three_subscribers_are_collector() { - let s = NopSubscriber - .and_then(NopSubscriber) - .and_then(NopSubscriber) - .with_collector(NopCollector); - assert_collector(s) - } - - #[test] - fn downcasts_to_collector() { - let s = NopSubscriber - .and_then(NopSubscriber) - .and_then(NopSubscriber) - .with_collector(StringCollector("collector")); - let collector = - ::downcast_ref::(&s).expect("collector should downcast"); - assert_eq!(collector.0, "collector"); - } - - #[test] - fn downcasts_to_subscriber() { - let s = StringSubscriber("subscriber_1") - .and_then(StringSubscriber2("subscriber_2")) - .and_then(StringSubscriber3("subscriber_3")) - .with_collector(NopCollector); - let subscriber = ::downcast_ref::(&s) - .expect("subscriber 2 should downcast"); - assert_eq!(subscriber.0, "subscriber_1"); - let subscriber = ::downcast_ref::(&s) - .expect("subscriber 2 should downcast"); - assert_eq!(subscriber.0, "subscriber_2"); - let subscriber = ::downcast_ref::(&s) - .expect("subscriber 3 should downcast"); - assert_eq!(subscriber.0, "subscriber_3"); - } - - #[test] - #[cfg(all(feature = "registry", feature = "std"))] - fn context_event_span() { - use std::sync::{Arc, Mutex}; - let last_event_span = Arc::new(Mutex::new(None)); - - struct RecordingSubscriber { - last_event_span: Arc>>, - } - - impl Subscribe for RecordingSubscriber - where - S: Collect + for<'lookup> LookupSpan<'lookup>, - { - fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { - let span = ctx.event_span(event); - *self.last_event_span.lock().unwrap() = span.map(|s| s.name()); - } - } - - tracing::collect::with_default( - crate::registry().with(RecordingSubscriber { - last_event_span: last_event_span.clone(), - }), - || { - tracing::info!("no span"); - assert_eq!(*last_event_span.lock().unwrap(), None); - - let parent = tracing::info_span!("explicit"); - tracing::info!(parent: &parent, "explicit span"); - assert_eq!(*last_event_span.lock().unwrap(), Some("explicit")); - - let _guard = tracing::info_span!("contextual").entered(); - tracing::info!("contextual span"); - assert_eq!(*last_event_span.lock().unwrap(), Some("contextual")); - }, - ); - } -} diff --git a/tracing-subscriber/src/subscribe/context.rs b/tracing-subscriber/src/subscribe/context.rs new file mode 100644 index 0000000000..6690645280 --- /dev/null +++ b/tracing-subscriber/src/subscribe/context.rs @@ -0,0 +1,499 @@ +use tracing_core::{collect::Collect, metadata::Metadata, span, Event}; + +use crate::registry::{self, LookupSpan, SpanRef}; +#[cfg(feature = "registry")] +use crate::{filter::FilterId, registry::Registry}; +/// Represents information about the current context provided to [`Layer`]s by the +/// wrapped [`Subscriber`]. +/// +/// To access [stored data] keyed by a span ID, implementors of the `Layer` +/// trait should ensure that the `Subscriber` type parameter is *also* bound by the +/// [`LookupSpan`]: +/// +/// ```rust +/// use tracing::Collect; +/// use tracing_subscriber::{Subscribe, registry::LookupSpan}; +/// +/// pub struct MySubscriber; +/// +/// impl Subscribe for MySubscriber +/// where +/// C: Collect + for<'a> LookupSpan<'a>, +/// { +/// // ... +/// } +/// ``` +/// +/// [`Layer`]: ../layer/trait.Layer.html +/// [`Subscriber`]: https://docs.rs/tracing-core/latest/tracing_core/trait.Subscriber.html +/// [stored data]: ../registry/struct.SpanRef.html +/// [`LookupSpan`]: "../registry/trait.LookupSpan.html +#[derive(Debug)] +pub struct Context<'a, S> { + subscriber: Option<&'a S>, + /// The bitmask of all [`Filtered`] layers that currently apply in this + /// context. If there is only a single [`Filtered`] wrapping the layer that + /// produced this context, then this is that filter's ID. Otherwise, if we + /// are in a nested tree with multiple filters, this is produced by + /// [`and`]-ing together the [`FilterId`]s of each of the filters that wrap + /// the current layer. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [`FilterId`]: crate::filter::FilterId + /// [`and`]: crate::filter::FilterId::and + #[cfg(feature = "registry")] + filter: FilterId, +} + +/// An iterator over the [stored data] for all the spans in the +/// current context, starting the root of the trace tree and ending with +/// the current span. +/// +/// This is returned by [`Context::scope`]. +/// +/// [stored data]: ../registry/struct.SpanRef.html +/// [`Context::scope`]: struct.Context.html#method.scope +#[deprecated(note = "renamed to crate::registry::ScopeFromRoot", since = "0.2.19")] +#[derive(Debug)] +pub struct Scope<'a, L>(std::iter::Flatten>>) +where + L: LookupSpan<'a>; + +#[allow(deprecated)] +impl<'a, L> Iterator for Scope<'a, L> +where + L: LookupSpan<'a>, +{ + type Item = SpanRef<'a, L>; + + fn next(&mut self) -> Option { + self.0.next() + } +} + +// === impl Context === + +impl<'a, C> Context<'a, C> +where + C: Collect, +{ + pub(super) fn new(subscriber: &'a C) -> Self { + Self { + subscriber: Some(subscriber), + + #[cfg(feature = "registry")] + filter: FilterId::none(), + } + } + + /// Returns the wrapped subscriber's view of the current span. + #[inline] + pub fn current_span(&self) -> span::Current { + self.subscriber + .map(Collect::current_span) + // TODO: this would be more correct as "unknown", so perhaps + // `tracing-core` should make `Current::unknown()` public? + .unwrap_or_else(span::Current::none) + } + + /// Returns whether the wrapped subscriber would enable the current span. + #[inline] + pub fn enabled(&self, metadata: &Metadata<'_>) -> bool { + self.subscriber + .map(|subscriber| subscriber.enabled(metadata)) + // If this context is `None`, we are registering a callsite, so + // return `true` so that the layer does not incorrectly assume that + // the inner subscriber has disabled this metadata. + // TODO(eliza): would it be more correct for this to return an `Option`? + .unwrap_or(true) + } + + /// Records the provided `event` with the wrapped subscriber. + /// + /// # Notes + /// + /// - The subscriber is free to expect that the event's callsite has been + /// [registered][register], and may panic or fail to observe the event if this is + /// not the case. The `tracing` crate's macros ensure that all events are + /// registered, but if the event is constructed through other means, the + /// user is responsible for ensuring that [`register_callsite`][register] + /// has been called prior to calling this method. + /// - This does _not_ call [`enabled`] on the inner subscriber. If the + /// caller wishes to apply the wrapped subscriber's filter before choosing + /// whether to record the event, it may first call [`Context::enabled`] to + /// check whether the event would be enabled. This allows `Layer`s to + /// elide constructing the event if it would not be recorded. + /// + /// [register]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/trait.Subscriber.html#method.register_callsite + /// [`enabled`]: https://docs.rs/tracing-core/latest/tracing_core/subscriber/trait.Subscriber.html#method.enabled + /// [`Context::enabled`]: #method.enabled + #[inline] + pub fn event(&self, event: &Event<'_>) { + if let Some(subscriber) = self.subscriber { + subscriber.event(event); + } + } + + /// Returns a [`SpanRef`] for the parent span of the given [`Event`], if + /// it has a parent. + /// + /// If the event has an explicitly overridden parent, this method returns + /// a reference to that span. If the event's parent is the current span, + /// this returns a reference to the current span, if there is one. If this + /// returns `None`, then either the event's parent was explicitly set to + /// `None`, or the event's parent was defined contextually, but no span + /// is currently entered. + /// + /// Compared to [`Context::current_span`] and [`Context::lookup_current`], + /// this respects overrides provided by the [`Event`]. + /// + /// Compared to [`Event::parent`], this automatically falls back to the contextual + /// span, if required. + /// + /// ```rust + /// use tracing::{Event, Collect}; + /// use tracing_subscriber::{ + /// subscribe::{Context, Subscribe}, + /// prelude::*, + /// registry::LookupSpan, + /// }; + /// + /// struct PrintingSubscriber; + /// impl Subscribe for PrintingSubscriber + /// where + /// C: Collect + for<'lookup> LookupSpan<'lookup>, + /// { + /// fn on_event(&self, event: &Event, ctx: Context) { + /// let span = ctx.event_span(event); + /// println!("Event in span: {:?}", span.map(|s| s.name())); + /// } + /// } + /// + /// tracing::collect::with_default(tracing_subscriber::registry().with(PrintingSubscriber), || { + /// tracing::info!("no span"); + /// // Prints: Event in span: None + /// + /// let span = tracing::info_span!("span"); + /// tracing::info!(parent: &span, "explicitly specified"); + /// // Prints: Event in span: Some("span") + /// + /// let _guard = span.enter(); + /// tracing::info!("contextual span"); + /// // Prints: Event in span: Some("span") + /// }); + /// ``` + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ #[inline] + pub fn event_span(&self, event: &Event<'_>) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + if event.is_root() { + None + } else if event.is_contextual() { + self.lookup_current() + } else { + // TODO(eliza): this should handle parent IDs + event.parent().and_then(|id| self.span(id)) + } + } + + /// Returns metadata for the span with the given `id`, if it exists. + /// + /// If this returns `None`, then no span exists for that ID (either it has + /// closed or the ID is invalid). + #[inline] + pub fn metadata(&self, id: &span::Id) -> Option<&'static Metadata<'static>> + where + C: for<'lookup> LookupSpan<'lookup>, + { + let span = self.span(id)?; + Some(span.metadata()) + } + + /// Returns [stored data] for the span with the given `id`, if it exists. + /// + /// If this returns `None`, then no span exists for that ID (either it has + /// closed or the ID is invalid). + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + #[inline] + pub fn span(&self, id: &span::Id) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + let span = self.subscriber.as_ref()?.span(id)?; + + #[cfg(feature = "registry")] + return span.try_with_filter(self.filter); + + #[cfg(not(feature = "registry"))] + Some(span) + } + + /// Returns `true` if an active span exists for the given `Id`. + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ #[inline] + pub fn exists(&self, id: &span::Id) -> bool + where + C: for<'lookup> LookupSpan<'lookup>, + { + self.subscriber.as_ref().and_then(|s| s.span(id)).is_some() + } + + /// Returns [stored data] for the span that the wrapped subscriber considers + /// to be the current. + /// + /// If this returns `None`, then we are not currently within a span. + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + #[inline] + pub fn lookup_current(&self) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + let subscriber = *self.subscriber.as_ref()?; + let current = subscriber.current_span(); + let id = current.id()?; + let span = subscriber.span(id); + debug_assert!( + span.is_some(), + "the subscriber should have data for the current span ({:?})!", + id, + ); + + // If we found a span, and our per-layer filter enables it, return that + // span! + #[cfg(feature = "registry")] + if let Some(span) = span?.try_with_filter(self.filter) { + Some(span) + } else { + // Otherwise, the span at the *top* of the stack is disabled by + // per-layer filtering, but there may be additional spans in the stack. + // + // Currently, `LookupSpan` doesn't have a nice way of exposing access to + // the whole span stack. However, if we can downcast the innermost + // subscriber to a a `Registry`, we can iterate over its current span + // stack. + // + // TODO(eliza): when https://github.com/tokio-rs/tracing/issues/1459 is + // implemented, change this to use that instead... + self.lookup_current_filtered(subscriber) + } + + #[cfg(not(feature = "registry"))] + span + } + + /// Slow path for when the current span is disabled by PLF and we have a + /// registry. + // This is called by `lookup_current` in the case that per-layer filtering + // is in use. `lookup_current` is allowed to be inlined, but this method is + // factored out to prevent the loop and (potentially-recursive) subscriber + // downcasting from being inlined if `lookup_current` is inlined. + #[inline(never)] + #[cfg(feature = "registry")] + fn lookup_current_filtered<'lookup>( + &self, + subscriber: &'lookup C, + ) -> Option> + where + C: LookupSpan<'lookup>, + { + let registry = (subscriber as &dyn Collect).downcast_ref::()?; + registry + .span_stack() + .iter() + .find_map(|id| subscriber.span(id)?.try_with_filter(self.filter)) + } + + /// Returns an iterator over the [stored data] for all the spans in the + /// current context, starting the root of the trace tree and ending with + /// the current span. + /// + /// If this iterator is empty, then there are no spans in the current context. + /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + #[deprecated( + note = "equivalent to `self.current_span().id().and_then(|id| self.span_scope(id).from_root())` but consider passing an explicit ID instead of relying on the contextual span", + since = "0.2.19" + )] + #[allow(deprecated)] + pub fn scope(&self) -> Scope<'_, C> + where + C: for<'lookup> LookupSpan<'lookup>, + { + Scope( + self.lookup_current() + .as_ref() + .map(registry::SpanRef::scope) + .map(registry::Scope::from_root) + .into_iter() + .flatten(), + ) + } + + /// Returns an iterator over the [stored data] for all the spans in the + /// current context, starting with the specified span and ending with the + /// root of the trace tree and ending with the current span. + /// + ///
+ ///
ⓘNote
+ ///
+ ///
+ /// 
+    /// Note: Compared to scope this
+    /// returns the spans in reverse order (from leaf to root). Use
+    /// Scope::from_root
+    /// in case root-to-leaf ordering is desired.
+    ///
+ /// + ///
+ ///
ⓘNote
+ ///
+ ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + pub fn span_scope(&self, id: &span::Id) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + Some(self.span(id)?.scope()) + } + + /// Returns an iterator over the [stored data] for all the spans in the + /// current context, starting with the parent span of the specified event, + /// and ending with the root of the trace tree and ending with the current span. + /// + ///
+ /// 
+    /// Note: Compared to scope this
+    /// returns the spans in reverse order (from leaf to root). Use
+    /// Scope::from_root
+    /// in case root-to-leaf ordering is desired.
+    ///
+ /// + ///
+ /// 
+    /// Note: This requires the wrapped subscriber to implement the
+    /// LookupSpan trait.
+    /// See the documentation on Context's
+    /// declaration for details.
+    ///
+ /// + /// [stored data]: ../registry/struct.SpanRef.html + pub fn event_scope(&self, event: &Event<'_>) -> Option> + where + C: for<'lookup> LookupSpan<'lookup>, + { + Some(self.event_span(event)?.scope()) + } + + #[cfg(feature = "registry")] + pub(crate) fn with_filter(self, filter: FilterId) -> Self { + // If we already have our own `FilterId`, combine it with the provided + // one. That way, the new `FilterId` will consider a span to be disabled + // if it was disabled by the given `FilterId` *or* any `FilterId`s for + // layers "above" us in the stack. + // + // See the doc comment for `FilterId::and` for details. + let filter = self.filter.and(filter); + Self { filter, ..self } + } + + #[cfg(feature = "registry")] + pub(crate) fn is_enabled_for(&self, span: &span::Id, filter: FilterId) -> bool + where + C: for<'lookup> LookupSpan<'lookup>, + { + self.is_enabled_inner(span, filter).unwrap_or(false) + } + + #[cfg(feature = "registry")] + pub(crate) fn if_enabled_for(self, span: &span::Id, filter: FilterId) -> Option + where + C: for<'lookup> LookupSpan<'lookup>, + { + if self.is_enabled_inner(span, filter)? { + Some(self.with_filter(filter)) + } else { + None + } + } + + #[cfg(feature = "registry")] + fn is_enabled_inner(&self, span: &span::Id, filter: FilterId) -> Option + where + C: for<'lookup> LookupSpan<'lookup>, + { + Some(self.span(span)?.is_enabled_for(filter)) + } +} + +impl<'a, S> Context<'a, S> { + pub(crate) fn none() -> Self { + Self { + subscriber: None, + + #[cfg(feature = "registry")] + filter: FilterId::none(), + } + } +} + +impl<'a, S> Clone for Context<'a, S> { + #[inline] + fn clone(&self) -> Self { + let subscriber = self.subscriber.as_ref().copied(); + Context { + subscriber, + + #[cfg(feature = "registry")] + filter: self.filter, + } + } +} diff --git a/tracing-subscriber/src/subscribe/layered.rs b/tracing-subscriber/src/subscribe/layered.rs new file mode 100644 index 0000000000..8241f0d64c --- /dev/null +++ b/tracing-subscriber/src/subscribe/layered.rs @@ -0,0 +1,465 @@ +use tracing_core::{ + collect::{Collect, Interest}, + metadata::Metadata, + span, Event, LevelFilter, +}; + +use crate::{ + filter, + registry::LookupSpan, + subscribe::{Context, Subscribe}, +}; +#[cfg(feature = "registry")] +use crate::{filter::FilterId, registry::Registry}; +use std::{any::TypeId, fmt, marker::PhantomData, ptr::NonNull}; + +/// A [collector] composed of a [collector] wrapped by one or more +/// [subscriber]s. +/// +/// [subscriber]: crate::Subscribe +/// [collector]: tracing_core::Collect +#[derive(Clone)] +pub struct Layered { + /// The subscriber. + subscriber: S, + + /// The inner value that `self.subscriber` was subscribered onto. + /// + /// If this is also a `Subscribe`, then this `Layered` will implement `Subscribe`. + /// If this is a `Collect`, then this `Layered` will implement + /// `Collect` instead. + inner: I, + + // These booleans are used to determine how to combine `Interest`s and max + // level hints when per-subscriber filters are in use. + /// Is `self.inner` a `Registry`? + /// + /// If so, when combining `Interest`s, we want to "bubble up" its + /// `Interest`. + inner_is_registry: bool, + + /// Does `self.subscriber` have per-subscriber filters? + /// + /// This will be true if: + /// - `self.inner` is a `Filtered`. + /// - `self.inner` is a tree of `Layered`s where _all_ arms of those + /// `Layered`s have per-subscriber filters. + /// + /// Otherwise, if it's a `Layered` with one per-subscriber filter in one branch, + /// but a non-per-subscriber-filtered subscriber in the other branch, this will be + /// _false_, because the `Layered` is already handling the combining of + /// per-subscriber filter `Interest`s and max level hints with its non-filtered + /// `Subscribe`. + has_subscriber_filter: bool, + + /// Does `self.inner` have per-subscriber filters? + /// + /// This is determined according to the same rules as + /// `has_subscriber_filter` above. + inner_has_subscriber_filter: bool, + _s: PhantomData, +} + +// === impl Layered === + +impl Collect for Layered +where + S: Subscribe, + C: Collect, +{ + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.pick_interest(self.subscriber.register_callsite(metadata), || { + self.inner.register_callsite(metadata) + }) + } + + fn enabled(&self, metadata: &Metadata<'_>) -> bool { + if self.subscriber.enabled(metadata, self.ctx()) { + // if the outer subscriber enables the callsite metadata, ask the collector. + self.inner.enabled(metadata) + } else { + // otherwise, the callsite is disabled by the collector + false + } + } + + fn max_level_hint(&self) -> Option { + self.pick_level_hint( + self.subscriber.max_level_hint(), + self.inner.max_level_hint(), + ) + } + + fn new_span(&self, span: &span::Attributes<'_>) -> span::Id { + let id = self.inner.new_span(span); + self.subscriber.on_new_span(span, &id, self.ctx()); + id + } + + fn record(&self, span: &span::Id, values: &span::Record<'_>) { + self.inner.record(span, values); + self.subscriber.on_record(span, values, self.ctx()); + } + + fn record_follows_from(&self, span: &span::Id, follows: &span::Id) { + self.inner.record_follows_from(span, follows); + self.subscriber.on_follows_from(span, follows, self.ctx()); + } + + fn event(&self, event: &Event<'_>) { + self.inner.event(event); + self.subscriber.on_event(event, self.ctx()); + } + + fn enter(&self, span: &span::Id) { + self.inner.enter(span); + self.subscriber.on_enter(span, self.ctx()); + } + + fn exit(&self, span: &span::Id) { + self.inner.exit(span); + self.subscriber.on_exit(span, self.ctx()); + } + + fn clone_span(&self, old: &span::Id) -> span::Id { + let new = self.inner.clone_span(old); + if &new != old { + self.subscriber.on_id_change(old, &new, self.ctx()) + }; + new + } + + #[inline] + fn drop_span(&self, id: span::Id) { + self.try_close(id); + } + + fn try_close(&self, id: span::Id) -> bool { + #[cfg(feature = "registry")] + let subscriber = &self.inner as &dyn Collect; + #[cfg(feature = "registry")] + let mut guard = subscriber + .downcast_ref::() + .map(|registry| registry.start_close(id.clone())); + if self.inner.try_close(id.clone()) { + // If we have a registry's close guard, indicate that the span is + // closing. + #[cfg(feature = "registry")] + { + if let Some(g) = guard.as_mut() { + g.is_closing() + }; + } + + self.subscriber.on_close(id, self.ctx()); + true + } else { + false + } + } + + #[inline] + fn current_span(&self) -> span::Current { + self.inner.current_span() + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + // Unlike the implementation of `Subscribe` for `Layered`, we don't have to + // handle the "magic PLF downcast marker" here. If a `Layered` + // implements `Collect`, we already know that the `inner` branch is + // going to contain something that doesn't have per-subscriber filters (the + // actual root `Collect`). Thus, a `Layered` that implements + // `Collect` will always be propagating the root subscriber's + // `Interest`/level hint, even if it includes a `Subscribe` that has + // per-subscriber filters, because it will only ever contain subscribers where + // _one_ child has per-subscriber filters. + // + // The complex per-subscriber filter detection logic is only relevant to + // *trees* of subscribers, which involve the `Subscribe` implementation for + // `Layered`, not *lists* of subscribers, where every `Layered` implements + // `Collect`. Of course, a linked list can be thought of as a + // degenerate tree...but luckily, we are able to make a type-level + // distinction between individual `Layered`s that are definitely + // list-shaped (their inner child implements `Collect`), and + // `Layered`s that might be tree-shaped (the inner child is also a + // `Subscribe`). + + // If downcasting to `Self`, return a pointer to `self`. + if id == TypeId::of::() { + return Some(NonNull::from(self).cast()); + } + + self.subscriber + .downcast_raw(id) + .or_else(|| self.inner.downcast_raw(id)) + } +} + +impl Subscribe for Layered +where + A: Subscribe, + B: Subscribe, + C: Collect, +{ + fn on_subscribe(&mut self, collect: &mut C) { + self.subscriber.on_subscribe(collect); + self.inner.on_subscribe(collect); + } + + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.pick_interest(self.subscriber.register_callsite(metadata), || { + self.inner.register_callsite(metadata) + }) + } + + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + if self.subscriber.enabled(metadata, ctx.clone()) { + // if the outer subscriber enables the callsite metadata, ask the inner subscriber. + self.inner.enabled(metadata, ctx) + } else { + // otherwise, the callsite is disabled by this subscriber + false + } + } + + fn max_level_hint(&self) -> Option { + self.pick_level_hint( + self.subscriber.max_level_hint(), + self.inner.max_level_hint(), + ) + } + + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + self.inner.on_new_span(attrs, id, ctx.clone()); + self.subscriber.on_new_span(attrs, id, ctx); + } + + #[inline] + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { + self.inner.on_record(span, values, ctx.clone()); + self.subscriber.on_record(span, values, ctx); + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { + self.inner.on_follows_from(span, follows, ctx.clone()); + self.subscriber.on_follows_from(span, follows, ctx); + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + self.inner.on_event(event, ctx.clone()); + self.subscriber.on_event(event, ctx); + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { + self.inner.on_enter(id, ctx.clone()); + self.subscriber.on_enter(id, ctx); + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { + self.inner.on_exit(id, ctx.clone()); + self.subscriber.on_exit(id, ctx); + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { + self.inner.on_close(id.clone(), ctx.clone()); + self.subscriber.on_close(id, ctx); + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { + self.inner.on_id_change(old, new, ctx.clone()); + self.subscriber.on_id_change(old, new, ctx); + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + match id { + // If downcasting to `Self`, return a pointer to `self`. + id if id == TypeId::of::() => Some(NonNull::from(self).cast()), + + // Oh, we're looking for per-subscriber filters! + // + // This should only happen if we are inside of another `Layered`, + // and it's trying to determine how it should combine `Interest`s + // and max level hints. + // + // In that case, this `Layered` should be considered to be + // "per-subscriber filtered" if *both* the outer subscriber and the inner + // subscriber/subscriber have per-subscriber filters. Otherwise, this `Layered + // should *not* be considered per-subscriber filtered (even if one or the + // other has per subscriber filters). If only one `Subscribe` is per-subscriber + // filtered, *this* `Layered` will handle aggregating the `Interest` + // and level hints on behalf of its children, returning the + // aggregate (which is the value from the &non-per-subscriber-filtered* + // child). + // + // Yes, this rule *is* slightly counter-intuitive, but it's + // necessary due to a weird edge case that can occur when two + // `Layered`s where one side is per-subscriber filtered and the other + // isn't are `Layered` together to form a tree. If we didn't have + // this rule, we would actually end up *ignoring* `Interest`s from + // the non-per-subscriber-filtered subscribers, since both branches would + // claim to have PLF. + // + // If you don't understand this...that's fine, just don't mess with + // it. :) + id if filter::is_plf_downcast_marker(id) => self + .subscriber + .downcast_raw(id) + .and(self.inner.downcast_raw(id)), + + // Otherwise, try to downcast both branches normally... + _ => self + .subscriber + .downcast_raw(id) + .or_else(|| self.inner.downcast_raw(id)), + } + } +} + +impl<'a, S, C> LookupSpan<'a> for Layered +where + C: Collect + LookupSpan<'a>, +{ + type Data = C::Data; + + fn span_data(&'a self, id: &span::Id) -> Option { + self.inner.span_data(id) + } + + #[cfg(feature = "registry")] + fn register_filter(&mut self) -> FilterId { + self.inner.register_filter() + } +} + +impl Layered +where + C: Collect, +{ + fn ctx(&self) -> Context<'_, C> { + Context::new(&self.inner) + } +} + +impl Layered +where + A: Subscribe, + C: Collect, +{ + pub(super) fn new(subscriber: A, inner: B, inner_has_subscriber_filter: bool) -> Self { + #[cfg(feature = "registry")] + let inner_is_registry = TypeId::of::() == TypeId::of::(); + #[cfg(not(feature = "registry"))] + let inner_is_registry = false; + + let inner_has_subscriber_filter = inner_has_subscriber_filter || inner_is_registry; + let has_subscriber_filter = filter::subscriber_has_plf(&subscriber); + Self { + subscriber, + inner, + has_subscriber_filter, + inner_has_subscriber_filter, + inner_is_registry, + _s: PhantomData, + } + } + + fn pick_interest(&self, outer: Interest, inner: impl FnOnce() -> Interest) -> Interest { + if self.has_subscriber_filter { + return inner(); + } + + // If the outer subscriber has disabled the callsite, return now so that + // the inner subscriber/subscriber doesn't get its hopes up. + if outer.is_never() { + return outer; + } + + // The `inner` closure will call `inner.register_callsite()`. We do this + // before the `if` statement to ensure that the inner subscriber is + // informed that the callsite exists regardless of the outer subscriber's + // filtering decision. + let inner = inner(); + if outer.is_sometimes() { + // if this interest is "sometimes", return "sometimes" to ensure that + // filters are reevaluated. + return outer; + } + + // If there is a per-subscriber filter in the `inner` stack, and it returns + // `never`, change the interest to `sometimes`, because the `outer` + // subscriber didn't return `never`. This means that _some_ subscriber still wants + // to see that callsite, even though the inner stack's per-subscriber filter + // didn't want it. Therefore, returning `sometimes` will ensure + // `enabled` is called so that the per-subscriber filter can skip that + // span/event, while the `outer` subscriber still gets to see it. + if inner.is_never() && self.inner_has_subscriber_filter { + return Interest::sometimes(); + } + + // otherwise, allow the inner subscriber or collector to weigh in. + inner + } + + fn pick_level_hint( + &self, + outer_hint: Option, + inner_hint: Option, + ) -> Option { + use std::cmp::max; + + if self.inner_is_registry { + return outer_hint; + } + + if self.has_subscriber_filter && self.inner_has_subscriber_filter { + return Some(max(outer_hint?, inner_hint?)); + } + + if self.has_subscriber_filter && inner_hint.is_none() { + return None; + } + + if self.inner_has_subscriber_filter && outer_hint.is_none() { + return None; + } + + max(outer_hint, inner_hint) + } +} + +impl fmt::Debug for Layered +where + A: fmt::Debug, + B: fmt::Debug, +{ + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + #[cfg(feature = "registry")] + let alt = f.alternate(); + let mut s = f.debug_struct("Layered"); + // These additional fields are more verbose and usually only necessary + // for internal debugging purposes, so only print them if alternate mode + // is enabled. + #[cfg(feature = "registry")] + if alt { + s.field("inner_is_registry", &self.inner_is_registry) + .field("has_subscriber_filter", &self.has_subscriber_filter) + .field( + "inner_has_subscriber_filter", + &self.inner_has_subscriber_filter, + ); + } + + s.field("subscriber", &self.subscriber) + .field("inner", &self.inner) + .finish() + } +} diff --git a/tracing-subscriber/src/subscribe/mod.rs b/tracing-subscriber/src/subscribe/mod.rs new file mode 100644 index 0000000000..c7676e3e89 --- /dev/null +++ b/tracing-subscriber/src/subscribe/mod.rs @@ -0,0 +1,1197 @@ +//! The [`Subscribe`] trait, a composable abstraction for building [collector]s. +//! +//! The [`Collect`] trait in `tracing-core` represents the _complete_ set of +//! functionality required to consume `tracing` instrumentation. This means that +//! a single `Collect` instance is a self-contained implementation of a +//! complete strategy for collecting traces; but it _also_ means that the +//! `Collect` trait cannot easily be composed with other collectors. +//! +//! In particular, [collector]s are responsible for generating [span IDs] and +//! assigning them to spans. Since these IDs must uniquely identify a span +//! within the context of the current trace, this means that there may only be +//! a single collector for a given thread at any point in time — +//! otherwise, there would be no authoritative source of span IDs. +//! +//! On the other hand, the majority of the [`Collect`] trait's functionality +//! is composable: any number of subscribers may _observe_ events, span entry +//! and exit, and so on, provided that there is a single authoritative source of +//! span IDs. The [`Subscribe`] trait represents this composable subset of the +//! [`Collect`] behavior; it can _observe_ events and spans, but does not +//! assign IDs. +//! +//! ## Composing Subscribers +//! +//! Since a [subscriber] does not implement a complete strategy for collecting +//! traces, it must be composed with a [collector] in order to be used. The +//! [`Subscribe`] trait is generic over a type parameter (called `C` in the trait +//! definition), representing the types of `Collect` they can be composed +//! with. Thus, a subscriber may be implemented that will only compose with a +//! particular `Collect` implementation, or additional trait bounds may be +//! added to constrain what types implementing `Collect` a subscriber can wrap. +//! +//! Subscribers may be added to a collector by using the [`CollectExt::with`] +//! method, which is provided by `tracing-subscriber`'s [prelude]. This method +//! returns a [`Layered`] struct that implements [`Collect`] by composing the +//! `Subscribe` with the collector. +//! +//! For example: +//! ```rust +//! use tracing_subscriber::Subscribe; +//! use tracing_subscriber::prelude::*; +//! use tracing::Collect; +//! +//! pub struct MySubscriber { +//! // ... +//! } +//! +//! impl Subscribe for MySubscriber { +//! // ... +//! } +//! +//! pub struct MyCollector { +//! // ... +//! } +//! +//! # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; +//! impl Collect for MyCollector { +//! // ... +//! # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } +//! # fn record(&self, _: &Id, _: &Record) {} +//! # fn event(&self, _: &Event) {} +//! # fn record_follows_from(&self, _: &Id, _: &Id) {} +//! # fn enabled(&self, _: &Metadata) -> bool { false } +//! # fn enter(&self, _: &Id) {} +//! # fn exit(&self, _: &Id) {} +//! # fn current_span(&self) -> tracing_core::span::Current { tracing_core::span::Current::none() } +//! } +//! # impl MySubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyCollector { +//! # fn new() -> Self { Self { }} +//! # } +//! +//! let collector = MyCollector::new() +//! .with(MySubscriber::new()); +//! +//! tracing::collect::set_global_default(collector); +//! ``` +//! +//! Multiple subscriber may be composed in the same manner: +//! ```rust +//! # use tracing_subscriber::{Subscribe, subscribe::CollectExt}; +//! # use tracing::Collect; +//! pub struct MyOtherSubscriber { +//! // ... +//! } +//! +//! impl Subscribe for MyOtherSubscriber { +//! // ... +//! } +//! +//! pub struct MyThirdSubscriber { +//! // ... +//! } +//! +//! impl Subscribe for MyThirdSubscriber { +//! // ... +//! } +//! # pub struct MySubscriber {} +//! # impl Subscribe for MySubscriber {} +//! # pub struct MyCollector { } +//! # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; +//! # impl Collect for MyCollector { +//! # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } +//! # fn record(&self, _: &Id, _: &Record) {} +//! # fn event(&self, _: &Event) {} +//! # fn record_follows_from(&self, _: &Id, _: &Id) {} +//! # fn enabled(&self, _: &Metadata) -> bool { false } +//! # fn current_span(&self) -> tracing_core::span::Current { tracing_core::span::Current::none() } +//! # fn enter(&self, _: &Id) {} +//! # fn exit(&self, _: &Id) {} +//! } +//! # impl MySubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyOtherSubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyThirdSubscriber { +//! # fn new() -> Self { Self {} } +//! # } +//! # impl MyCollector { +//! # fn new() -> Self { Self { }} +//! # } +//! +//! let collect = MyCollector::new() +//! .with(MySubscriber::new()) +//! .with(MyOtherSubscriber::new()) +//! .with(MyThirdSubscriber::new()); +//! +//! tracing::collect::set_global_default(collect); +//! ``` +//! +//! The [`Subscribe::with_collector`] constructs the [`Layered`] type from a +//! [`Subscribe`] and [`Collect`], and is called by [`CollectExt::with`]. In +//! general, it is more idiomatic to use [`CollectExt::with`], and treat +//! [`Subscribe::with_collector`] as an implementation detail, as `with_collector` +//! calls must be nested, leading to less clear code for the reader. +//! +//! [prelude]: crate::prelude +//! +//! ## Recording Traces +//! +//! The [`Subscribe`] trait defines a set of methods for consuming notifications from +//! tracing instrumentation, which are generally equivalent to the similarly +//! named methods on [`Collect`]. Unlike [`Collect`], the methods on +//! `Subscribe` are additionally passed a [`Context`] type, which exposes additional +//! information provided by the wrapped subscriber (such as [the current span]) +//! to the subscriber. +//! +//! ## Filtering with `Subscribers`s +//! +//! As well as strategies for handling trace events, the `Subscribe` trait may also +//! be used to represent composable _filters_. This allows the determination of +//! what spans and events should be recorded to be decoupled from _how_ they are +//! recorded: a filtering subscriber can be applied to other subscribers or +//! subscribers. `Subscribe`s can be used to implement _global filtering_, where a +//! `Subscribe` provides a filtering strategy for the entire subscriber. +//! Additionally, individual recording `Subscribe`s or sets of `Subscribe`s may be +//! combined with _per-subscriber filters_ that control what spans and events are +//! recorded by those subscribers. +//! +//! ### Global Filtering +//! +//! A `Subscribe` that implements a filtering strategy should override the +//! [`register_callsite`] and/or [`enabled`] methods. It may also choose to implement +//! methods such as [`on_enter`], if it wishes to filter trace events based on +//! the current span context. +//! +//! Note that the [`Subscribe::register_callsite`] and [`Subscribe::enabled`] methods +//! determine whether a span or event is enabled *globally*. Thus, they should +//! **not** be used to indicate whether an individual subscriber wishes to record a +//! particular span or event. Instead, if a subscriber is only interested in a subset +//! of trace data, but does *not* wish to disable other spans and events for the +//! rest of the subscriber stack should ignore those spans and events in its +//! notification methods. +//! +//! The filtering methods on a stack of `Subscribe`s are evaluated in a top-down +//! order, starting with the outermost `Subscribe` and ending with the wrapped +//! [`Collect`]. If any subscriber returns `false` from its [`enabled`] method, or +//! [`Interest::never()`] from its [`register_callsite`] method, filter +//! evaluation will short-circuit and the span or event will be disabled. +//! +//! ### Per-Subscriber Filtering +//! +//! **Note**: per-subscriber filtering APIs currently require the [`"registry"` crate +//! feature flag][feat] to be enabled. +//! +//! Sometimes, it may be desirable for one `Subscribe` to record a particular subset +//! of spans and events, while a different subset of spans and events are +//! recorded by other `Subscribe`s. For example: +//! +//! - A subscriber that records metrics may wish to observe only events including +//! particular tracked values, while a logging subscriber ignores those events. +//! - If recording a distributed trace is expensive, it might be desirable to +//! only send spans with `INFO` and lower verbosity to the distributed tracing +//! system, while logging more verbose spans to a file. +//! - Spans and events with a particular target might be recorded differently +//! from others, such as by generating an HTTP access log from a span that +//! tracks the lifetime of an HTTP request. +//! +//! The [`Filter`] trait is used to control what spans and events are +//! observed by an individual `Subscribe`, while still allowing other `Subscribe`s to +//! potentially record them. The [`Subscribe::with_filter`] method combines a +//! `Subscribe` with a [`Filter`], returning a [`Filtered`] subscriber. +//! +//! This crate's [`filter`] module provides a number of types which implement +//! the [`Filter`] trait, such as [`LevelFilter`], [`Targets`], and +//! [`FilterFn`]. These [`Filter`]s provide ready-made implementations of +//! common forms of filtering. For custom filtering policies, the [`FilterFn`] +//! and [`DynFilterFn`] types allow implementing a [`Filter`] with a closure or +//! function pointer. In addition, when more control is required, the [`Filter`] +//! trait may also be implemented for user-defined types. +//! +//!
+//! 
+//!     Warning: Currently, the 
+//!     Registry type defined in this crate is the only root
+//!     Collect capable of supporting Layers with
+//!     per-subscriber filters. In the future, new APIs will be added to allow other
+//!     root Collects to support per-subscriber filters.
+//!
+//! +//! For example, to generate an HTTP access log based on spans with +//! the `http_access` target, while logging other spans and events to +//! standard out, a [`Filter`] can be added to the access log subscriber: +//! +//! ``` +//! use tracing_subscriber::{filter, prelude::*}; +//! +//! // Generates an HTTP access log. +//! let access_log = // ... +//! # filter::LevelFilter::INFO; +//! +//! // Add a filter to the access log subscriber so that it only observes +//! // spans and events with the `http_access` target. +//! let access_log = access_log.with_filter(filter::filter_fn(|metadata| { +//! // Returns `true` if and only if the span or event's target is +//! // "http_access". +//! metadata.target() == "http_access" +//! })); +//! +//! // A gteneral-purpose logging subscriber. +//! let fmt_subscriber = tracing_subscriber::fmt::subscriber(); +//! +//! // Build a subscriber that combines the access log and stdout log +//! // subscribers. +//! tracing_subscriber::registry() +//! .with(fmt_subscriber) +//! .with(access_log) +//! .init(); +//! ``` +//! +//! Multiple subscribers can have their own, separate per-subscriber filters. A span or +//! event will be recorded if it is enabled by _any_ per-subscriber filter, but it +//! will be skipped by the subscribers whose filters did not enable it. Building on +//! the previous example: +//! +//! ``` +//! use tracing_subscriber::{filter::{filter_fn, LevelFilter}, prelude::*}; +//! +//! let access_log = // ... +//! # LevelFilter::INFO; +//! let fmt_subscriber = tracing_subscriber::fmt::subscriber(); +//! +//! tracing_subscriber::registry() +//! // Add the filter for the "http_access" target to the access +//! // log subscriber, like before. +//! .with(access_log.with_filter(filter_fn(|metadata| { +//! metadata.target() == "http_access" +//! }))) +//! // Add a filter for spans and events with the INFO level +//! // and below to the logging subscriber. +//! .with(fmt_subscriber.with_filter(LevelFilter::INFO)) +//! .init(); +//! +//! // Neither subscriber will observe this event +//! tracing::debug!(does_anyone_care = false, "a tree fell in the forest"); +//! +//! // This event will be observed by the logging subscriber, but not +//! // by the access log subscriber. +//! tracing::warn!(dose_roentgen = %3.8, "not great, but not terrible"); +//! +//! // This event will be observed only by the access log subscriber. +//! tracing::trace!(target: "http_access", "HTTP request started"); +//! +//! // Both subscribers will observe this event. +//! tracing::error!(target: "http_access", "HTTP request failed with a very bad error!"); +//! ``` +//! +//! A per-subscriber filter can be applied to multiple [`Subscribe`]s at a time, by +//! combining them into a [`Layered`] subscriber using [`Subscribe::and_then`], and then +//! calling [`Subscribe::with_filter`] on the resulting [`Layered`] subscriber. +//! +//! Consider the following: +//! - `subscriber_a` and `subscriber_b`, which should only receive spans and events at +//! the [`INFO`] [level] and above. +//! - A third subscriber, `subscriber_c`, which should receive spans and events at +//! the [`DEBUG`] [level] as well. +//! The subscribers and filters would be composed thusly: +//! +//! ``` +//! use tracing_subscriber::{filter::LevelFilter, prelude::*}; +//! +//! let subscriber_a = // ... +//! # LevelFilter::INFO; +//! let subscriber_b = // ... +//! # LevelFilter::INFO; +//! let subscriber_c = // ... +//! # LevelFilter::INFO; +//! +//! let info_subscribers = subscriber_a +//! // Combine `subscriber_a` and `subscriber_b` into a `Layered` subscriber: +//! .and_then(subscriber_b) +//! // ...and then add an `INFO` `LevelFilter` to that subscriber: +//! .with_filter(LevelFilter::INFO); +//! +//! tracing_subscriber::registry() +//! // Add `subscriber_c` with a `DEBUG` filter. +//! .with(subscriber_c.with_filter(LevelFilter::DEBUG)) +//! .with(info_subscribers) +//! .init(); +//!``` +//! +//! If a [`Filtered`] [`Subscribe`] is combined with another [`Subscribe`] +//! [`Subscribe::and_then`], and a filter is added to the [`Layered`] subscriber, that +//! subscriber will be filtered by *both* the inner filter and the outer filter. +//! Only spans and events that are enabled by *both* filters will be +//! observed by that subscriber. This can be used to implement complex filtering +//! trees. +//! +//! As an example, consider the following constraints: +//! - Suppose that a particular [target] is used to indicate events that +//! should be counted as part of a metrics system, which should be only +//! observed by a subscriber that collects metrics. +//! - A log of high-priority events ([`INFO`] and above) should be logged +//! to stdout, while more verbose events should be logged to a debugging log file. +//! - Metrics-focused events should *not* be included in either log output. +//! +//! In that case, it is possible to apply a filter to both logging subscribers to +//! exclude the metrics events, while additionally adding a [`LevelFilter`] +//! to the stdout log: +//! +//! ``` +//! # // wrap this in a function so we don't actually create `debug.log` when +//! # // running the doctests.. +//! # fn docs() -> Result<(), Box> { +//! use tracing_subscriber::{filter, prelude::*}; +//! use std::{fs::File, sync::Arc}; +//! +//! // A subscriber that logs events to stdout using the human-readable "pretty" +//! // format. +//! let stdout_log = tracing_subscriber::fmt::subscriber() +//! .pretty(); +//! +//! // A subscriber that logs events to a file. +//! let file = File::create("debug.log")?; +//! let debug_log = tracing_subscriber::fmt::subscriber() +//! .with_writer(file); +//! +//! // A subscriber that collects metrics using specific events. +//! let metrics_subscriber = /* ... */ filter::LevelFilter::INFO; +//! +//! tracing_subscriber::registry() +//! .with( +//! stdout_log +//! // Add an `INFO` filter to the stdout logging subscriber +//! .with_filter(filter::LevelFilter::INFO) +//! // Combine the filtered `stdout_log` subscriber with the +//! // `debug_log` subscriber, producing a new `Layered` subscriber. +//! .and_then(debug_log) +//! // Add a filter to *both* subscribers that rejects spans and +//! // events whose targets start with `metrics`. +//! .with_filter(filter::filter_fn(|metadata| { +//! !metadata.target().starts_with("metrics") +//! })) +//! ) +//! .with( +//! // Add a filter to the metrics label that *only* enables +//! // events whose targets start with `metrics`. +//! metrics_subscriber.with_filter(filter::filter_fn(|metadata| { +//! metadata.target().starts_with("metrics") +//! })) +//! ) +//! .init(); +//! +//! // This event will *only* be recorded by the metrics subscriber. +//! tracing::info!(target: "metrics::cool_stuff_count", value = 42); +//! +//! // This event will only be seen by the debug log file subscriber: +//! tracing::debug!("this is a message, and part of a system of messages"); +//! +//! // This event will be seen by both the stdout log subscriber *and* +//! // the debug log file subscriber, but not by the metrics subscriber. +//! tracing::warn!("the message is a warning about danger!"); +//! # Ok(()) } +//! ``` +//! +//! [subscriber]: Subscribe +//! [`Collect`]:tracing_core::Collect +//! [collector]: tracing_core::Collect +//! [span IDs]: https://docs.rs/tracing-core/latest/tracing_core/span/struct.Id.html +//! [the current span]: Context::current_span +//! [`register_callsite`]: Subscribe::register_callsite +//! [`enabled`]: Subscribe::enabled +//! [`on_enter`]: Subscribe::on_enter +//! [`Subscribe::register_callsite`]: Subscribe::register_callsite +//! [`Subscribe::enabled`]: Subscribe::enabled +//! [`Interest::never()`]: tracing_core::collect::Interest::never +//! [`Filtered`]: crate::filter::Filtered +//! [`filter`]: crate::filter +//! [`Targets`]: crate::filter::Targets +//! [`FilterFn`]: crate::filter::FilterFn +//! [`DynFilterFn`]: crate::filter::DynFilterFn +//! [level]: tracing_core::Level +//! [`INFO`]: tracing_core::Level::INFO +//! [`DEBUG`]: tracing_core::Level::DEBUG +//! [target]: tracing_core::Metadata::target +//! [`LevelFilter`]: crate::filter::LevelFilter +//! [feat]: crate#feature-flags +use crate::filter; +use std::{any::TypeId, ops::Deref, ptr::NonNull, sync::Arc}; +use tracing_core::{ + collect::{Collect, Interest}, + metadata::Metadata, + span, Event, LevelFilter, +}; + +mod context; +mod layered; +pub use self::{context::*, layered::*}; + +// The `tests` module is `pub(crate)` because it contains test utilities used by +// other modules. +#[cfg(test)] +pub(crate) mod tests; + +/// A composable handler for `tracing` events. +/// +/// A type that implements `Subscribe` &mdash a "subscriber" — provides a +/// particular behavior for recording or collecting traces that can +/// be composed together with other subscribers to build a [collector]. See the +/// [module-level documentation](crate::subscribe) for details. +/// +/// [collector]: tracing_core::Collect +pub trait Subscribe +where + C: Collect, + Self: 'static, +{ + /// Performs late initialization when attaching a subscriber to a + /// [collector]. + /// + /// This is a callback that is called when the `Subscribe` is added to a + /// [`Collect`] (e.g. in [`Subscribe::with_collector`] and + /// [`CollectExt::with`]). Since this can only occur before the + /// [`Collect`] has been set as the default, both the subscriber and + /// [`Collect`] are passed to this method _mutably_. This gives the + /// subscribe the opportunity to set any of its own fields with values + /// recieved by method calls on the [`Collect`]. + /// + /// For example, [`Filtered`] subscribers implement `on_subscribe` to call the + /// [`Collect`]'s [`register_filter`] method, and store the returned + /// [`FilterId`] as a field. + /// + /// **Note** In most cases, subscriber implementations will not need to + /// implement this method. However, in cases where a type implementing + /// subscriber wraps one or more other types that implement `Subscribe`, like the + /// [`Layered`] and [`Filtered`] types in this crate, that type MUST ensure + /// that the inner `Subscribe` instance's' `on_subscribe` methods are + /// called. Otherwise, unctionality that relies on `on_subscribe`, such as + /// [per-subscriber filtering], may not work correctly. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [`register_filter`]: crate::registry::LookupSpan::register_filter + /// [per-subscribe filtering]: #per-subscriber-filtering + /// [`FilterId`]: crate::filter::FilterId + fn on_subscribe(&mut self, collector: &mut C) { + let _ = collector; + } + + /// Registers a new callsite with this subscriber, returning whether or not + /// the subscriber is interested in being notified about the callsite, similarly + /// to [`Collect::register_callsite`]. + /// + /// By default, this returns [`Interest::always()`] if [`self.enabled`] returns + /// true, or [`Interest::never()`] if it returns false. + /// + ///
+ /// 
+    ///
+    /// **Note**: This method (and [`Subscribe::enabled`]) determine whether a span or event is
+    /// globally enabled, *not* whether the individual subscriber will be notified about that
+    /// span or event.  This is intended to be used by subscribers that implement filtering for
+    /// the entire stack. Subscribers which do not wish to be notified about certain spans or
+    /// events but do not wish to globally disable them should ignore those spans or events in
+    /// their [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
+    /// and other notification methods.
+    ///
+    ///
+ /// + /// See [the trait-level documentation] for more information on filtering + /// with subscribers. + /// + /// Subscribers may also implement this method to perform any behaviour that + /// should be run once per callsite. If the subscriber wishes to use + /// `register_callsite` for per-callsite behaviour, but does not want to + /// globally enable or disable those callsites, it should always return + /// [`Interest::always()`]. + /// + /// [`Interest`]: tracing_core::collect::Interest + /// [`Collect::register_callsite`]: tracing_core::Collect::register_callsite() + /// [`self.enabled`]: Subscribe::enabled() + /// [the trait-level documentation]: #filtering-with-subscribers + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + if self.enabled(metadata, Context::none()) { + Interest::always() + } else { + Interest::never() + } + } + + /// Returns `true` if this subscriber is interested in a span or event with the + /// given `metadata` in the current [`Context`], similarly to + /// [`Collect::enabled`]. + /// + /// By default, this always returns `true`, allowing the wrapped collector + /// to choose to disable the span. + /// + ///
+ /// 
+    ///
+    /// **Note**: This method (and [`register_callsite`][Self::register_callsite])
+    /// determine whether a span or event is
+    /// globally enabled, *not* whether the individual subscriber will be
+    /// notified about that span or event. This is intended to be used
+    /// by subscribers that implement filtering for the entire stack. Layers which do
+    /// not wish to be notified about certain spans or events but do not wish to
+    /// globally disable them should ignore those spans or events in their
+    /// [on_event][Self::on_event], [on_enter][Self::on_enter], [on_exit][Self::on_exit],
+    /// and other notification methods.
+    ///
+    ///
+ /// + /// + /// See [the trait-level documentation] for more information on filtering + /// with subscribers. + /// + /// [`Interest`]: tracing_core::Interest + /// [the trait-level documentation]: #filtering-with-subscribers + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + let _ = (metadata, ctx); + true + } + + /// Notifies this subscriber that a new span was constructed with the given + /// `Attributes` and `Id`. + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + let _ = (attrs, id, ctx); + } + + // TODO(eliza): do we want this to be a public API? If we end up moving + // filtering subscribers to a separate trait, we may no longer want subscribers to + // be able to participate in max level hinting... + #[doc(hidden)] + fn max_level_hint(&self) -> Option { + None + } + + /// Notifies this subscriber that a span with the given `Id` recorded the given + /// `values`. + // Note: it's unclear to me why we'd need the current span in `record` (the + // only thing the `Context` type currently provides), but passing it in anyway + // seems like a good future-proofing measure as it may grow other methods later... + fn on_record(&self, _span: &span::Id, _values: &span::Record<'_>, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that a span with the ID `span` recorded that it + /// follows from the span with the ID `follows`. + // Note: it's unclear to me why we'd need the current span in `record` (the + // only thing the `Context` type currently provides), but passing it in anyway + // seems like a good future-proofing measure as it may grow other methods later... + fn on_follows_from(&self, _span: &span::Id, _follows: &span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that an event has occurred. + fn on_event(&self, _event: &Event<'_>, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that a span with the given ID was entered. + fn on_enter(&self, _id: &span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that the span with the given ID was exited. + fn on_exit(&self, _id: &span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that the span with the given ID has been closed. + fn on_close(&self, _id: span::Id, _ctx: Context<'_, C>) {} + + /// Notifies this subscriber that a span ID has been cloned, and that the + /// subscriber returned a different ID. + fn on_id_change(&self, _old: &span::Id, _new: &span::Id, _ctx: Context<'_, C>) {} + + /// Composes this subscriber around the given collector, returning a `Layered` + /// struct implementing `Subscribe`. + /// + /// The returned subscriber will call the methods on this subscriber and then + /// those of the new subscriber, before calling the methods on the collector + /// it wraps. For example: + /// + /// ```rust + /// # use tracing_subscriber::subscribe::Subscribe; + /// # use tracing_core::Collect; + /// # use tracing_core::span::Current; + /// pub struct FooSubscriber { + /// // ... + /// } + /// + /// pub struct BarSubscriber { + /// // ... + /// } + /// + /// pub struct MyCollector { + /// // ... + /// } + /// + /// impl Subscribe for FooSubscriber { + /// // ... + /// } + /// + /// impl Subscribe for BarSubscriber { + /// // ... + /// } + /// + /// # impl FooSubscriber { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl BarSubscriber { + /// # fn new() -> Self { Self { }} + /// # } + /// # impl MyCollector { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; + /// # impl tracing_core::Collect for MyCollector { + /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } + /// # fn record(&self, _: &Id, _: &Record) {} + /// # fn event(&self, _: &Event) {} + /// # fn record_follows_from(&self, _: &Id, _: &Id) {} + /// # fn enabled(&self, _: &Metadata) -> bool { false } + /// # fn enter(&self, _: &Id) {} + /// # fn exit(&self, _: &Id) {} + /// # fn current_span(&self) -> Current { Current::unknown() } + /// # } + /// let collector = FooSubscriber::new() + /// .and_then(BarSubscriber::new()) + /// .with_collector(MyCollector::new()); + /// ``` + /// + /// Multiple subscribers may be composed in this manner: + /// + /// ```rust + /// # use tracing_subscriber::subscribe::Subscribe; + /// # use tracing_core::{Collect, span::Current}; + /// # pub struct FooSubscriber {} + /// # pub struct BarSubscriber {} + /// # pub struct MyCollector {} + /// # impl Subscribe for FooSubscriber {} + /// # impl Subscribe for BarSubscriber {} + /// # impl FooSubscriber { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl BarSubscriber { + /// # fn new() -> Self { Self { }} + /// # } + /// # impl MyCollector { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata, Event}; + /// # impl tracing_core::Collect for MyCollector { + /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(1) } + /// # fn record(&self, _: &Id, _: &Record) {} + /// # fn event(&self, _: &Event) {} + /// # fn record_follows_from(&self, _: &Id, _: &Id) {} + /// # fn enabled(&self, _: &Metadata) -> bool { false } + /// # fn enter(&self, _: &Id) {} + /// # fn exit(&self, _: &Id) {} + /// # fn current_span(&self) -> Current { Current::unknown() } + /// # } + /// pub struct BazSubscriber { + /// // ... + /// } + /// + /// impl Subscribe for BazSubscriber { + /// // ... + /// } + /// # impl BazSubscriber { fn new() -> Self { BazSubscriber {} } } + /// + /// let collector = FooSubscriber::new() + /// .and_then(BarSubscriber::new()) + /// .and_then(BazSubscriber::new()) + /// .with_collector(MyCollector::new()); + /// ``` + fn and_then(self, subscriber: S) -> Layered + where + S: Subscribe, + Self: Sized, + { + let inner_has_subscriber_filter = filter::subscriber_has_plf(&self); + Layered::new(subscriber, self, inner_has_subscriber_filter) + } + + /// Composes this subscriber with the given collector, returning a + /// `Layered` struct that implements [`Collect`]. + /// + /// The returned `Layered` subscriber will call the methods on this subscriber + /// and then those of the wrapped collector. + /// + /// For example: + /// ```rust + /// # use tracing_subscriber::subscribe::Subscribe; + /// # use tracing_core::Collect; + /// # use tracing_core::span::Current; + /// pub struct FooSubscriber { + /// // ... + /// } + /// + /// pub struct MyCollector { + /// // ... + /// } + /// + /// impl Subscribe for FooSubscriber { + /// // ... + /// } + /// + /// # impl FooSubscriber { + /// # fn new() -> Self { Self {} } + /// # } + /// # impl MyCollector { + /// # fn new() -> Self { Self { }} + /// # } + /// # use tracing_core::{span::{Id, Attributes, Record}, Metadata}; + /// # impl tracing_core::Collect for MyCollector { + /// # fn new_span(&self, _: &Attributes) -> Id { Id::from_u64(0) } + /// # fn record(&self, _: &Id, _: &Record) {} + /// # fn event(&self, _: &tracing_core::Event) {} + /// # fn record_follows_from(&self, _: &Id, _: &Id) {} + /// # fn enabled(&self, _: &Metadata) -> bool { false } + /// # fn enter(&self, _: &Id) {} + /// # fn exit(&self, _: &Id) {} + /// # fn current_span(&self) -> Current { Current::unknown() } + /// # } + /// let collector = FooSubscriber::new() + /// .with_collector(MyCollector::new()); + ///``` + /// + /// [`Collect`]: tracing_core::Collect + fn with_collector(mut self, mut inner: C) -> Layered + where + Self: Sized, + { + let inner_has_subscriber_filter = filter::collector_has_plf(&inner); + self.on_subscribe(&mut inner); + Layered::new(self, inner, inner_has_subscriber_filter) + } + + /// Combines `self` with a [`Filter`], returning a [`Filtered`] subscriber. + /// + /// The [`Filter`] will control which spans and events are enabled for + /// this subscriber. See [the trait-level documentation][plf] for details on + /// per-subscriber filtering. + /// + /// [`Filtered`]: crate::filter::Filtered + /// [plf]: #per-subscriber-filtering + #[cfg(all(feature = "registry", feature = "std"))] + #[cfg_attr(docsrs, doc(cfg(all(feature = "registry", feature = "std"))))] + fn with_filter(self, filter: F) -> filter::Filtered + where + Self: Sized, + F: Filter, + { + filter::Filtered::new(self, filter) + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + if id == TypeId::of::() { + Some(NonNull::from(self).cast()) + } else { + None + } + } +} + +/// A per-[`Subscribe`] filter that determines whether a span or event is enabled +/// for an individual subscriber. +#[cfg(feature = "registry")] +#[cfg_attr(docsrs, doc(cfg(feature = "registry"), notable_trait))] +pub trait Filter { + /// Returns `true` if this subscriber is interested in a span or event with the + /// given [`Metadata`] in the current [`Context`], similarly to + /// [`Collect::enabled`]. + /// + /// If this returns `false`, the span or event will be disabled _for the + /// wrapped [`Subscribe`]_. Unlike [`Subscribe::enabled`], the span or event will + /// still be recorded if any _other_ subscribers choose to enable it. However, + /// the subscriber [filtered] by this filter will skip recording that span or + /// event. + /// + /// If all subscribers indicate that they do not wish to see this span or event, + /// it will be disabled. + /// + /// [`metadata`]: tracing_core::Metadata + /// [`Collect::enabled`]: tracing_core::Collect::enabled + /// [filtered]: crate::filter::Filtered + fn enabled(&self, meta: &Metadata<'_>, cx: &Context<'_, S>) -> bool; + + /// Returns an [`Interest`] indicating whether this subscriber will [always], + /// [sometimes], or [never] be interested in the given [`Metadata`]. + /// + /// When a given callsite will [always] or [never] be enabled, the results + /// of evaluating the filter may be cached for improved performance. + /// Therefore, if a filter is capable of determining that it will always or + /// never enable a particular callsite, providing an implementation of this + /// function is recommended. + /// + ///
+ /// 
+    /// Note: If a Filter will perform
+    /// dynamic filtering that depends on the current context in which
+    /// a span or event was observered (e.g. only enabling an event when it
+    /// occurs within a particular span), it must return
+    /// Interest::sometimes() from this method. If it returns
+    /// Interest::always() or Interest::never(), the
+    /// enabled method may not be called when a particular instance
+    /// of that span or event is recorded.
+    ///
+ ///
+ /// + /// This method is broadly similar to [`Collect::register_callsite`]; + /// however, since the returned value represents only the interest of + /// *this* subscriber, the resulting behavior is somewhat different. + /// + /// If a [`Collect`] returns [`Interest::always()`][always] or + /// [`Interest::never()`][never] for a given [`Metadata`], its [`enabled`] + /// method is then *guaranteed* to never be called for that callsite. On the + /// other hand, when a `Filter` returns [`Interest::always()`][always] or + /// [`Interest::never()`][never] for a callsite, _other_ [`Subscribe`]s may have + /// differing interests in that callsite. If this is the case, the callsite + /// will recieve [`Interest::sometimes()`][sometimes], and the [`enabled`] + /// method will still be called for that callsite when it records a span or + /// event. + /// + /// Returning [`Interest::always()`][always] or [`Interest::never()`][never] from + /// `Filter::callsite_enabled` will permanently enable or disable a + /// callsite (without requiring subsequent calls to [`enabled`]) if and only + /// if the following is true: + /// + /// - all [`Subscribe`]s that comprise the subscriber include `Filter`s + /// (this includes a tree of [`Layered`] subscribers that share the same + /// `Filter`) + /// - all those `Filter`s return the same [`Interest`]. + /// + /// For example, if a [`Collect`] consists of two [`Filtered`] subscribers, + /// and both of those subscribers return [`Interest::never()`][never], that + /// callsite *will* never be enabled, and the [`enabled`] methods of those + /// [`Filter`]s will not be called. + /// + /// ## Default Implementation + /// + /// The default implementation of this method assumes that the + /// `Filter`'s [`enabled`] method _may_ perform dynamic filtering, and + /// returns [`Interest::sometimes()`][sometimes], to ensure that [`enabled`] + /// is called to determine whether a particular _instance_ of the callsite + /// is enabled in the current context. If this is *not* the case, and the + /// `Filter`'s [`enabled`] method will always return the same result + /// for a particular [`Metadata`], this method can be overridden as + /// follows: + /// + /// ``` + /// use tracing_subscriber::subscribe; + /// use tracing_core::{Metadata, collect::Interest}; + /// + /// struct MyFilter { + /// // ... + /// } + /// + /// impl MyFilter { + /// // The actual logic for determining whether a `Metadata` is enabled + /// // must be factored out from the `enabled` method, so that it can be + /// // called without a `Context` (which is not provided to the + /// // `callsite_enabled` method). + /// fn is_enabled(&self, metadata: &Metadata<'_>) -> bool { + /// // ... + /// # drop(metadata); true + /// } + /// } + /// + /// impl subscribe::Filter for MyFilter { + /// fn enabled(&self, metadata: &Metadata<'_>, _: &subscribe::Context<'_, C>) -> bool { + /// // Even though we are implementing `callsite_enabled`, we must still provide a + /// // working implementation of `enabled`, as returning `Interest::always()` or + /// // `Interest::never()` will *allow* caching, but will not *guarantee* it. + /// // Other filters may still return `Interest::sometimes()`, so we may be + /// // asked again in `enabled`. + /// self.is_enabled(metadata) + /// } + /// + /// fn callsite_enabled(&self, metadata: &'static Metadata<'static>) -> Interest { + /// // The result of `self.enabled(metadata, ...)` will always be + /// // the same for any given `Metadata`, so we can convert it into + /// // an `Interest`: + /// if self.is_enabled(metadata) { + /// Interest::always() + /// } else { + /// Interest::never() + /// } + /// } + /// } + /// ``` + /// + /// [`Metadata`]: tracing_core::Metadata + /// [`Interest`]: tracing_core::Interest + /// [always]: tracing_core::Interest::always + /// [sometimes]: tracing_core::Interest::sometimes + /// [never]: tracing_core::Interest::never + /// [`Collect::register_callsite`]: tracing_core::Collect::register_callsite + /// [`Collect`]: tracing_core::Collect + /// [`enabled`]: Filter::enabled + /// [`Filtered`]: crate::filter::Filtered + fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest { + let _ = meta; + Interest::sometimes() + } + + /// Returns an optional hint of the highest [verbosity level][level] that + /// this `Filter` will enable. + /// + /// If this method returns a [`LevelFilter`], it will be used as a hint to + /// determine the most verbose level that will be enabled. This will allow + /// spans and events which are more verbose than that level to be skipped + /// more efficiently. An implementation of this method is optional, but + /// strongly encouraged. + /// + /// If the maximum level the `Filter` will enable can change over the + /// course of its lifetime, it is free to return a different value from + /// multiple invocations of this method. However, note that changes in the + /// maximum level will **only** be reflected after the callsite [`Interest`] + /// cache is rebuilt, by calling the + /// [`tracing_core::callsite::rebuild_interest_cache`][rebuild] function. + /// Therefore, if the `Filter will change the value returned by this + /// method, it is responsible for ensuring that + /// [`rebuild_interest_cache`][rebuild] is called after the value of the max + /// level changes. + /// + /// ## Default Implementation + /// + /// By default, this method returns `None`, indicating that the maximum + /// level is unknown. + /// + /// [level]: tracing_core::metadata::Level + /// [`LevelFilter`]: crate::filter::LevelFilter + /// [`Interest`]: tracing_core::collect::Interest + /// [rebuild]: tracing_core::callsite::rebuild_interest_cache + fn max_level_hint(&self) -> Option { + None + } +} + +/// Extension trait adding a `with(Subscribe)` combinator to types implementing +/// [`Collect`]. +pub trait CollectExt: Collect + crate::sealed::Sealed { + /// Wraps `self` with the provided `subscriber`. + fn with(self, subscriber: S) -> Layered + where + S: Subscribe, + Self: Sized, + { + subscriber.with_collector(self) + } +} +/// A subscriber that does nothing. +#[derive(Clone, Debug, Default)] +pub struct Identity { + _p: (), +} + +// === impl Subscribe === + +impl Subscribe for Option +where + S: Subscribe, + C: Collect, +{ + fn on_subscribe(&mut self, collector: &mut C) { + if let Some(ref mut subscriber) = self { + subscriber.on_subscribe(collector) + } + } + + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_new_span(attrs, id, ctx) + } + } + + #[inline] + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + match self { + Some(ref inner) => inner.register_callsite(metadata), + None => Interest::always(), + } + } + + #[inline] + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + match self { + Some(ref inner) => inner.enabled(metadata, ctx), + None => true, + } + } + + #[inline] + fn max_level_hint(&self) -> Option { + match self { + Some(ref inner) => inner.max_level_hint(), + None => None, + } + } + + #[inline] + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_record(span, values, ctx); + } + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_follows_from(span, follows, ctx); + } + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_event(event, ctx); + } + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_enter(id, ctx); + } + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_exit(id, ctx); + } + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_close(id, ctx); + } + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { + if let Some(ref inner) = self { + inner.on_id_change(old, new, ctx) + } + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + if id == TypeId::of::() { + Some(NonNull::from(self).cast()) + } else { + self.as_ref().and_then(|inner| inner.downcast_raw(id)) + } + } +} + +macro_rules! subscriber_impl_body { + () => { + #[inline] + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, C>) { + self.deref().on_new_span(attrs, id, ctx) + } + + #[inline] + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + self.deref().register_callsite(metadata) + } + + #[inline] + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, C>) -> bool { + self.deref().enabled(metadata, ctx) + } + + #[inline] + fn max_level_hint(&self) -> Option { + self.deref().max_level_hint() + } + + #[inline] + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, C>) { + self.deref().on_record(span, values, ctx) + } + + #[inline] + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, C>) { + self.deref().on_follows_from(span, follows, ctx) + } + + #[inline] + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + self.deref().on_event(event, ctx) + } + + #[inline] + fn on_enter(&self, id: &span::Id, ctx: Context<'_, C>) { + self.deref().on_enter(id, ctx) + } + + #[inline] + fn on_exit(&self, id: &span::Id, ctx: Context<'_, C>) { + self.deref().on_exit(id, ctx) + } + + #[inline] + fn on_close(&self, id: span::Id, ctx: Context<'_, C>) { + self.deref().on_close(id, ctx) + } + + #[inline] + fn on_id_change(&self, old: &span::Id, new: &span::Id, ctx: Context<'_, C>) { + self.deref().on_id_change(old, new, ctx) + } + + #[doc(hidden)] + #[inline] + unsafe fn downcast_raw(&self, id: TypeId) -> Option> { + self.deref().downcast_raw(id) + } + }; +} + +impl Subscribe for Arc +where + S: Subscribe, + C: Collect, +{ + subscriber_impl_body! {} +} + +impl Subscribe for Arc> +where + C: Collect, +{ + subscriber_impl_body! {} +} + +impl Subscribe for Box +where + S: Subscribe, + C: Collect, +{ + subscriber_impl_body! {} +} + +impl Subscribe for Box> +where + C: Collect, +{ + subscriber_impl_body! {} +} + +// === impl CollectExt === + +impl crate::sealed::Sealed for C {} +impl CollectExt for C {} + +// === impl Identity === + +impl Subscribe for Identity {} + +impl Identity { + /// Returns a new `Identity` subscriber. + pub fn new() -> Self { + Self { _p: () } + } +} diff --git a/tracing-subscriber/src/subscribe/tests.rs b/tracing-subscriber/src/subscribe/tests.rs new file mode 100644 index 0000000000..1a1ebcbbf9 --- /dev/null +++ b/tracing-subscriber/src/subscribe/tests.rs @@ -0,0 +1,328 @@ +use super::*; + +pub(crate) struct NopCollector; + +impl Collect for NopCollector { + fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { + Interest::never() + } + + fn enabled(&self, _: &Metadata<'_>) -> bool { + false + } + + fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { + span::Id::from_u64(1) + } + + fn record(&self, _: &span::Id, _: &span::Record<'_>) {} + fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} + fn event(&self, _: &Event<'_>) {} + fn enter(&self, _: &span::Id) {} + fn exit(&self, _: &span::Id) {} + fn current_span(&self) -> span::Current { + span::Current::unknown() + } +} + +#[derive(Debug)] +pub(crate) struct NopSubscriber; +impl Subscribe for NopSubscriber {} + +#[allow(dead_code)] +struct NopSubscriber2; +impl Subscribe for NopSubscriber2 {} + +/// A layer that holds a string. +/// +/// Used to test that pointers returned by downcasting are actually valid. +struct StringSubscriber(String); +impl Subscribe for StringSubscriber {} +struct StringSubscriber2(String); +impl Subscribe for StringSubscriber2 {} + +struct StringSubscriber3(String); +impl Subscribe for StringSubscriber3 {} + +pub(crate) struct StringCollector(String); + +impl Collect for StringCollector { + fn register_callsite(&self, _: &'static Metadata<'static>) -> Interest { + Interest::never() + } + + fn enabled(&self, _: &Metadata<'_>) -> bool { + false + } + + fn new_span(&self, _: &span::Attributes<'_>) -> span::Id { + span::Id::from_u64(1) + } + + fn record(&self, _: &span::Id, _: &span::Record<'_>) {} + fn record_follows_from(&self, _: &span::Id, _: &span::Id) {} + fn event(&self, _: &Event<'_>) {} + fn enter(&self, _: &span::Id) {} + fn exit(&self, _: &span::Id) {} + + fn current_span(&self) -> span::Current { + todo!() + } +} + +fn assert_collector(_s: impl Collect) {} + +#[test] +fn layer_is_subscriber() { + let s = NopSubscriber.with_collector(NopCollector); + assert_collector(s) +} + +#[test] +fn two_layers_are_subscriber() { + let s = NopSubscriber + .and_then(NopSubscriber) + .with_collector(NopCollector); + assert_collector(s) +} + +#[test] +fn three_layers_are_subscriber() { + let s = NopSubscriber + .and_then(NopSubscriber) + .and_then(NopSubscriber) + .with_collector(NopCollector); + assert_collector(s) +} + +#[test] +fn downcasts_to_subscriber() { + let s = NopSubscriber + .and_then(NopSubscriber) + .and_then(NopSubscriber) + .with_collector(StringCollector("subscriber".into())); + let subscriber = + ::downcast_ref::(&s).expect("collector should downcast"); + assert_eq!(&subscriber.0, "subscriber"); +} + +#[test] +fn downcasts_to_layer() { + let s = StringSubscriber("layer_1".into()) + .and_then(StringSubscriber2("layer_2".into())) + .and_then(StringSubscriber3("layer_3".into())) + .with_collector(NopCollector); + let layer = + ::downcast_ref::(&s).expect("subscriber 1 should downcast"); + assert_eq!(&layer.0, "layer_1"); + let layer = + ::downcast_ref::(&s).expect("subscriber 2 should downcast"); + assert_eq!(&layer.0, "layer_2"); + let layer = + ::downcast_ref::(&s).expect("subscriber 3 should downcast"); + assert_eq!(&layer.0, "layer_3"); +} + +#[cfg(feature = "registry")] +mod registry_tests { + use super::*; + use crate::registry::LookupSpan; + + #[test] + fn context_event_span() { + use std::sync::{Arc, Mutex}; + let last_event_span = Arc::new(Mutex::new(None)); + + struct RecordingSubscriber { + last_event_span: Arc>>, + } + + impl Subscribe for RecordingSubscriber + where + C: Collect + for<'lookup> LookupSpan<'lookup>, + { + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, C>) { + let span = ctx.event_span(event); + *self.last_event_span.lock().unwrap() = span.map(|s| s.name()); + } + } + + tracing::collect::with_default( + crate::registry().with(RecordingSubscriber { + last_event_span: last_event_span.clone(), + }), + || { + tracing::info!("no span"); + assert_eq!(*last_event_span.lock().unwrap(), None); + + let parent = tracing::info_span!("explicit"); + tracing::info!(parent: &parent, "explicit span"); + assert_eq!(*last_event_span.lock().unwrap(), Some("explicit")); + + let _guard = tracing::info_span!("contextual").entered(); + tracing::info!("contextual span"); + assert_eq!(*last_event_span.lock().unwrap(), Some("contextual")); + }, + ); + } + + /// Tests for how max-level hints are calculated when combining layers + /// with and without per-layer filtering. + mod max_level_hints { + + use super::*; + use crate::filter::*; + + #[test] + fn mixed_with_unfiltered() { + let subscriber = crate::registry() + .with(NopSubscriber) + .with(NopSubscriber.with_filter(LevelFilter::INFO)); + assert_eq!(subscriber.max_level_hint(), None); + } + + #[test] + fn mixed_with_unfiltered_layered() { + let subscriber = crate::registry().with(NopSubscriber).with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber.with_filter(LevelFilter::TRACE)), + ); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn mixed_interleaved() { + let subscriber = crate::registry() + .with(NopSubscriber) + .with(NopSubscriber.with_filter(LevelFilter::INFO)) + .with(NopSubscriber) + .with(NopSubscriber.with_filter(LevelFilter::INFO)); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn mixed_layered() { + let subscriber = crate::registry() + .with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber), + ) + .with(NopSubscriber.and_then(NopSubscriber.with_filter(LevelFilter::INFO))); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn plf_only_unhinted() { + let subscriber = crate::registry() + .with(NopSubscriber.with_filter(LevelFilter::INFO)) + .with(NopSubscriber.with_filter(filter_fn(|_| true))); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn plf_only_unhinted_nested_outer() { + // if a nested tree of per-layer filters has an _outer_ filter with + // no max level hint, it should return `None`. + let subscriber = crate::registry() + .with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber.with_filter(LevelFilter::WARN)), + ) + .with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(LevelFilter::DEBUG)), + ); + assert_eq!(dbg!(subscriber).max_level_hint(), None); + } + + #[test] + fn plf_only_unhinted_nested_inner() { + // If a nested tree of per-layer filters has an _inner_ filter with + // no max-level hint, but the _outer_ filter has a max level hint, + // it should pick the outer hint. This is because the outer filter + // will disable the spans/events before they make it to the inner + // filter. + let subscriber = dbg!(crate::registry().with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::INFO), + )); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn unhinted_nested_inner() { + let subscriber = dbg!(crate::registry() + .with( + NopSubscriber + .and_then(NopSubscriber) + .with_filter(LevelFilter::INFO) + ) + .with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::WARN), + )); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn unhinted_nested_inner_mixed() { + let subscriber = dbg!(crate::registry() + .with( + NopSubscriber + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::INFO) + ) + .with( + NopSubscriber + .with_filter(filter_fn(|_| true)) + .and_then(NopSubscriber.with_filter(filter_fn(|_| true))) + .with_filter(LevelFilter::WARN), + )); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::INFO)); + } + + #[test] + fn plf_only_picks_max() { + let subscriber = crate::registry() + .with(NopSubscriber.with_filter(LevelFilter::WARN)) + .with(NopSubscriber.with_filter(LevelFilter::DEBUG)); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::DEBUG)); + } + + #[test] + fn many_plf_only_picks_max() { + let subscriber = crate::registry() + .with(NopSubscriber.with_filter(LevelFilter::WARN)) + .with(NopSubscriber.with_filter(LevelFilter::DEBUG)) + .with(NopSubscriber.with_filter(LevelFilter::INFO)) + .with(NopSubscriber.with_filter(LevelFilter::ERROR)); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::DEBUG)); + } + + #[test] + fn nested_plf_only_picks_max() { + let subscriber = crate::registry() + .with( + NopSubscriber.with_filter(LevelFilter::INFO).and_then( + NopSubscriber + .with_filter(LevelFilter::WARN) + .and_then(NopSubscriber.with_filter(LevelFilter::DEBUG)), + ), + ) + .with( + NopSubscriber + .with_filter(LevelFilter::INFO) + .and_then(NopSubscriber.with_filter(LevelFilter::ERROR)), + ); + assert_eq!(dbg!(subscriber).max_level_hint(), Some(LevelFilter::DEBUG)); + } + } +} diff --git a/tracing-subscriber/tests/cached_layer_filters_dont_break_other_layers.rs b/tracing-subscriber/tests/cached_layer_filters_dont_break_other_layers.rs new file mode 100644 index 0000000000..0a2b05e5c8 --- /dev/null +++ b/tracing-subscriber/tests/cached_layer_filters_dont_break_other_layers.rs @@ -0,0 +1,123 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::Level; +use tracing_subscriber::{filter::LevelFilter, prelude::*}; + +#[test] +fn subscriber_filters() { + let (unfiltered, unfiltered_handle) = unfiltered("unfiltered"); + let (filtered, filtered_handle) = filtered("filtered"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered.with_filter(filter())) + .set_default(); + + events(); + + unfiltered_handle.assert_finished(); + filtered_handle.assert_finished(); +} + +#[test] +fn subscribered_subscriber_filters() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let unfiltered = unfiltered1.and_then(unfiltered2); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + let filtered = filtered1 + .with_filter(filter()) + .and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn out_of_order() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered1) + .with(filtered1.with_filter(filter())) + .with(unfiltered2) + .with(filtered2.with_filter(filter())) + .set_default(); + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn mixed_subscribered() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let subscribered1 = filtered1.with_filter(filter()).and_then(unfiltered1); + let subscribered2 = unfiltered2.and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(subscribered1) + .with(subscribered2) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); +} + +fn filter() -> LevelFilter { + LevelFilter::INFO +} + +fn unfiltered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .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() +} + +fn filtered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .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() +} diff --git a/tracing-subscriber/tests/hinted_layer_filters_dont_break_other_layers.rs b/tracing-subscriber/tests/hinted_layer_filters_dont_break_other_layers.rs new file mode 100644 index 0000000000..96fb87162f --- /dev/null +++ b/tracing-subscriber/tests/hinted_layer_filters_dont_break_other_layers.rs @@ -0,0 +1,133 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::{Collect, Level, Metadata}; +use tracing_subscriber::{filter::DynFilterFn, prelude::*, subscribe::Context}; + +#[test] +fn subscriber_filters() { + let (unfiltered, unfiltered_handle) = unfiltered("unfiltered"); + let (filtered, filtered_handle) = filtered("filtered"); + + let subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered.with_filter(filter())); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered_handle.assert_finished(); + filtered_handle.assert_finished(); +} + +#[test] +fn subscribered_subscriber_filters() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let unfiltered = unfiltered1.and_then(unfiltered2); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + let filtered = filtered1 + .with_filter(filter()) + .and_then(filtered2.with_filter(filter())); + + let subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn out_of_order() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let subscriber = tracing_subscriber::registry() + .with(unfiltered1) + .with(filtered1.with_filter(filter())) + .with(unfiltered2) + .with(filtered2.with_filter(filter())); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn mixed_subscribered() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let subscribered1 = filtered1.with_filter(filter()).and_then(unfiltered1); + let subscribered2 = unfiltered2.and_then(filtered2.with_filter(filter())); + + let subscriber = tracing_subscriber::registry() + .with(subscribered1) + .with(subscribered2); + assert_eq!(subscriber.max_level_hint(), None); + let _subscriber = subscriber.set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); +} + +fn filter() -> DynFilterFn { + DynFilterFn::new( + (|metadata: &Metadata<'_>, _: &tracing_subscriber::subscribe::Context<'_, S>| { + metadata.level() <= &Level::INFO + }) as fn(&Metadata<'_>, &Context<'_, S>) -> bool, + ) + .with_max_level_hint(Level::INFO) +} + +fn unfiltered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .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() +} + +fn filtered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .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() +} diff --git a/tracing-subscriber/tests/layer_filter_interests_are_cached.rs b/tracing-subscriber/tests/layer_filter_interests_are_cached.rs new file mode 100644 index 0000000000..647d170b1e --- /dev/null +++ b/tracing-subscriber/tests/layer_filter_interests_are_cached.rs @@ -0,0 +1,69 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; + +use std::{ + collections::HashMap, + sync::{Arc, Mutex}, +}; +use tracing::{Collect, Level}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn subscriber_filter_interests_are_cached() { + let seen = Arc::new(Mutex::new(HashMap::new())); + let seen2 = seen.clone(); + let filter = filter::filter_fn(move |meta| { + *seen + .lock() + .unwrap() + .entry(meta.callsite()) + .or_insert(0usize) += 1; + meta.level() == &Level::INFO + }); + + let (expect, handle) = subscriber::mock() + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let subscriber = tracing_subscriber::registry().with(expect.with_filter(filter)); + assert!(subscriber.max_level_hint().is_none()); + + let _subscriber = subscriber.set_default(); + + fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + } + + events(); + { + let lock = seen2.lock().unwrap(); + for (callsite, &count) in lock.iter() { + assert_eq!( + count, 1, + "callsite {:?} should have been seen 1 time (after first set of events)", + callsite + ); + } + } + + events(); + { + let lock = seen2.lock().unwrap(); + for (callsite, &count) in lock.iter() { + assert_eq!( + count, 1, + "callsite {:?} should have been seen 1 time (after second set of events)", + callsite + ); + } + } + + handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/layer_filters/combinators.rs b/tracing-subscriber/tests/layer_filters/combinators.rs new file mode 100644 index 0000000000..7cc84d8465 --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/combinators.rs @@ -0,0 +1,42 @@ +use super::*; +use tracing_subscriber::{ + filter::{filter_fn, FilterExt, LevelFilter}, + prelude::*, +}; + +#[test] +fn and() { + let (subscriber, handle) = subscriber::mock() + .event( + event::msg("a very interesting event") + .at_level(tracing::Level::INFO) + .with_target("interesting_target"), + ) + .done() + .run_with_handle(); + + // Enables spans and events with targets starting with `interesting_target`: + let target_filter = filter::filter_fn(|meta| meta.target().starts_with("interesting_target")); + + // Enables spans and events with levels `INFO` and below: + let level_filter = LevelFilter::INFO; + + // Combine the two filters together, returning a filter that only enables + // spans and events that *both* filters will enable: + let filter = target_filter.and(level_filter); + + let _subscriber = tracing_subscriber::registry() + .with(subscriber.with_filter(filter)) + .set_default(); + + // This event will *not* be enabled: + tracing::info!("an event with an uninteresting target"); + + // This event *will* be enabled: + tracing::info!(target: "interesting_target", "a very interesting event"); + + // This event will *not* be enabled: + tracing::debug!(target: "interesting_target", "interesting debug event..."); + + handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/layer_filters/filter_scopes.rs b/tracing-subscriber/tests/layer_filters/filter_scopes.rs new file mode 100644 index 0000000000..710d267b86 --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/filter_scopes.rs @@ -0,0 +1,131 @@ +use super::*; + +#[test] +fn filters_span_scopes() { + let (debug_subscriber, debug_handle) = subscriber::named("debug") + .enter(span::mock().at_level(Level::DEBUG)) + .enter(span::mock().at_level(Level::INFO)) + .enter(span::mock().at_level(Level::WARN)) + .enter(span::mock().at_level(Level::ERROR)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().at_level(Level::ERROR), + span::mock().at_level(Level::WARN), + span::mock().at_level(Level::INFO), + span::mock().at_level(Level::DEBUG), + ])) + .exit(span::mock().at_level(Level::ERROR)) + .exit(span::mock().at_level(Level::WARN)) + .exit(span::mock().at_level(Level::INFO)) + .exit(span::mock().at_level(Level::DEBUG)) + .done() + .run_with_handle(); + let (info_subscriber, info_handle) = subscriber::named("info") + .enter(span::mock().at_level(Level::INFO)) + .enter(span::mock().at_level(Level::WARN)) + .enter(span::mock().at_level(Level::ERROR)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().at_level(Level::ERROR), + span::mock().at_level(Level::WARN), + span::mock().at_level(Level::INFO), + ])) + .exit(span::mock().at_level(Level::ERROR)) + .exit(span::mock().at_level(Level::WARN)) + .exit(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + let (warn_subscriber, warn_handle) = subscriber::named("warn") + .enter(span::mock().at_level(Level::WARN)) + .enter(span::mock().at_level(Level::ERROR)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().at_level(Level::ERROR), + span::mock().at_level(Level::WARN), + ])) + .exit(span::mock().at_level(Level::ERROR)) + .exit(span::mock().at_level(Level::WARN)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(debug_subscriber.with_filter(LevelFilter::DEBUG)) + .with(info_subscriber.with_filter(LevelFilter::INFO)) + .with(warn_subscriber.with_filter(LevelFilter::WARN)) + .set_default(); + + { + let _trace = tracing::trace_span!("my_span").entered(); + let _debug = tracing::debug_span!("my_span").entered(); + let _info = tracing::info_span!("my_span").entered(); + let _warn = tracing::warn_span!("my_span").entered(); + let _error = tracing::error_span!("my_span").entered(); + tracing::error!("hello world"); + } + + debug_handle.assert_finished(); + info_handle.assert_finished(); + warn_handle.assert_finished(); +} + +#[test] +fn filters_interleaved_span_scopes() { + fn target_subscriber(target: &'static str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(format!("target_{}", target)) + .enter(span::mock().with_target(target)) + .enter(span::mock().with_target(target)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().with_target(target), + span::mock().with_target(target), + ])) + .event( + event::msg("hello to my target") + .in_scope(vec![ + span::mock().with_target(target), + span::mock().with_target(target), + ]) + .with_target(target), + ) + .exit(span::mock().with_target(target)) + .exit(span::mock().with_target(target)) + .done() + .run_with_handle() + } + + let (a_subscriber, a_handle) = target_subscriber("a"); + let (b_subscriber, b_handle) = target_subscriber("b"); + let (all_subscriber, all_handle) = subscriber::named("all") + .enter(span::mock().with_target("b")) + .enter(span::mock().with_target("a")) + .event(event::msg("hello world").in_scope(vec![ + span::mock().with_target("a"), + span::mock().with_target("b"), + ])) + .exit(span::mock().with_target("a")) + .exit(span::mock().with_target("b")) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(all_subscriber.with_filter(LevelFilter::INFO)) + .with(a_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "a" || target == module_path!() + }))) + .with(b_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "b" || target == module_path!() + }))) + .set_default(); + + { + let _a1 = tracing::trace_span!(target: "a", "a/trace").entered(); + let _b1 = tracing::info_span!(target: "b", "b/info").entered(); + let _a2 = tracing::info_span!(target: "a", "a/info").entered(); + let _b2 = tracing::trace_span!(target: "b", "b/trace").entered(); + tracing::info!("hello world"); + tracing::debug!(target: "a", "hello to my target"); + tracing::debug!(target: "b", "hello to my target"); + } + + a_handle.assert_finished(); + b_handle.assert_finished(); + all_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/layer_filters/main.rs b/tracing-subscriber/tests/layer_filters/main.rs new file mode 100644 index 0000000000..a61b8ff97e --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/main.rs @@ -0,0 +1,185 @@ +#![cfg(feature = "registry")] +#[path = "../support.rs"] +mod support; +use self::support::*; +mod filter_scopes; +mod trees; + +use tracing::{level_filters::LevelFilter, Level}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn basic_subscriber_filters() { + let (trace_subscriber, trace_handle) = subscriber::named("trace") + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (debug_subscriber, debug_handle) = subscriber::named("debug") + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (info_subscriber, info_handle) = subscriber::named("info") + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(trace_subscriber.with_filter(LevelFilter::TRACE)) + .with(debug_subscriber.with_filter(LevelFilter::DEBUG)) + .with(info_subscriber.with_filter(LevelFilter::INFO)) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + + trace_handle.assert_finished(); + debug_handle.assert_finished(); + info_handle.assert_finished(); +} + +#[test] +fn basic_subscriber_filters_spans() { + let (trace_subscriber, trace_handle) = subscriber::named("trace") + .new_span(span::mock().at_level(Level::TRACE)) + .new_span(span::mock().at_level(Level::DEBUG)) + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (debug_subscriber, debug_handle) = subscriber::named("debug") + .new_span(span::mock().at_level(Level::DEBUG)) + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let (info_subscriber, info_handle) = subscriber::named("info") + .new_span(span::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(trace_subscriber.with_filter(LevelFilter::TRACE)) + .with(debug_subscriber.with_filter(LevelFilter::DEBUG)) + .with(info_subscriber.with_filter(LevelFilter::INFO)) + .set_default(); + + tracing::trace_span!("hello trace"); + tracing::debug_span!("hello debug"); + tracing::info_span!("hello info"); + + trace_handle.assert_finished(); + debug_handle.assert_finished(); + info_handle.assert_finished(); +} + +#[test] +fn global_filters_subscribers_still_work() { + let (expect, handle) = subscriber::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(expect) + .with(LevelFilter::INFO) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + + handle.assert_finished(); +} + +#[test] +fn global_filter_interests_are_cached() { + let (expect, handle) = subscriber::mock() + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(expect.with_filter(filter::filter_fn(|meta| { + assert!( + meta.level() <= &Level::INFO, + "enabled should not be called for callsites disabled by the global filter" + ); + meta.level() <= &Level::WARN + }))) + .with(LevelFilter::INFO) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + + handle.assert_finished(); +} + +#[test] +fn global_filters_affect_subscriber_filters() { + let (expect, handle) = subscriber::named("debug") + .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(expect.with_filter(LevelFilter::DEBUG)) + .with(LevelFilter::INFO) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + + handle.assert_finished(); +} + +#[test] +fn filter_fn() { + let (all, all_handle) = subscriber::named("all_targets") + .event(event::msg("hello foo")) + .event(event::msg("hello bar")) + .done() + .run_with_handle(); + + let (foo, foo_handle) = subscriber::named("foo_target") + .event(event::msg("hello foo")) + .done() + .run_with_handle(); + + let (bar, bar_handle) = subscriber::named("bar_target") + .event(event::msg("hello bar")) + .done() + .run_with_handle(); + + let _subscriber = tracing_subscriber::registry() + .with(all) + .with(foo.with_filter(filter::filter_fn(|meta| meta.target().starts_with("foo")))) + .with(bar.with_filter(filter::filter_fn(|meta| meta.target().starts_with("bar")))) + .set_default(); + + tracing::trace!(target: "foo", "hello foo"); + tracing::trace!(target: "bar", "hello bar"); + + foo_handle.assert_finished(); + bar_handle.assert_finished(); + all_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/layer_filters/trees.rs b/tracing-subscriber/tests/layer_filters/trees.rs new file mode 100644 index 0000000000..3332045e1a --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/trees.rs @@ -0,0 +1,146 @@ +use super::*; + +#[test] +fn basic_trees() { + let (with_target, with_target_handle) = subscriber::named("info_with_target") + .event(event::mock().at_level(Level::INFO).with_target("my_target")) + .done() + .run_with_handle(); + + let (info, info_handle) = subscriber::named("info") + .event( + event::mock() + .at_level(Level::INFO) + .with_target(module_path!()), + ) + .event(event::mock().at_level(Level::INFO).with_target("my_target")) + .done() + .run_with_handle(); + + let (all, all_handle) = subscriber::named("all") + .event( + event::mock() + .at_level(Level::INFO) + .with_target(module_path!()), + ) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::INFO).with_target("my_target")) + .event( + event::mock() + .at_level(Level::TRACE) + .with_target("my_target"), + ) + .done() + .run_with_handle(); + + let info_tree = info + .and_then( + with_target.with_filter(filter::filter_fn(|meta| dbg!(meta.target()) == "my_target")), + ) + .with_filter(LevelFilter::INFO); + + let subscriber = tracing_subscriber::registry().with(info_tree).with(all); + let _guard = dbg!(subscriber).set_default(); + + tracing::info!("hello world"); + tracing::trace!("hello trace"); + tracing::info!(target: "my_target", "hi to my target"); + tracing::trace!(target: "my_target", "hi to my target at trace"); + + all_handle.assert_finished(); + info_handle.assert_finished(); + with_target_handle.assert_finished(); +} + +#[test] +fn filter_span_scopes() { + fn target_subscriber(target: &'static str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(format!("target_{}", target)) + .enter(span::mock().with_target(target).at_level(Level::INFO)) + .event( + event::msg("hello world") + .in_scope(vec![span::mock().with_target(target).at_level(Level::INFO)]), + ) + .exit(span::mock().with_target(target).at_level(Level::INFO)) + .done() + .run_with_handle() + } + + let (a_subscriber, a_handle) = target_subscriber("a"); + let (b_subscriber, b_handle) = target_subscriber("b"); + let (info_subscriber, info_handle) = subscriber::named("info") + .enter(span::mock().with_target("b").at_level(Level::INFO)) + .enter(span::mock().with_target("a").at_level(Level::INFO)) + .event(event::msg("hello world").in_scope(vec![ + span::mock().with_target("a").at_level(Level::INFO), + span::mock().with_target("b").at_level(Level::INFO), + ])) + .exit(span::mock().with_target("a").at_level(Level::INFO)) + .exit(span::mock().with_target("b").at_level(Level::INFO)) + .done() + .run_with_handle(); + + let full_scope = vec![ + span::mock().with_target("b").at_level(Level::TRACE), + span::mock().with_target("a").at_level(Level::INFO), + span::mock().with_target("b").at_level(Level::INFO), + span::mock().with_target("a").at_level(Level::TRACE), + ]; + let (all_subscriber, all_handle) = subscriber::named("all") + .enter(span::mock().with_target("a").at_level(Level::TRACE)) + .enter(span::mock().with_target("b").at_level(Level::INFO)) + .enter(span::mock().with_target("a").at_level(Level::INFO)) + .enter(span::mock().with_target("b").at_level(Level::TRACE)) + .event(event::msg("hello world").in_scope(full_scope.clone())) + .event( + event::msg("hello to my target") + .with_target("a") + .in_scope(full_scope.clone()), + ) + .event( + event::msg("hello to my target") + .with_target("b") + .in_scope(full_scope), + ) + .exit(span::mock().with_target("b").at_level(Level::TRACE)) + .exit(span::mock().with_target("a").at_level(Level::INFO)) + .exit(span::mock().with_target("b").at_level(Level::INFO)) + .exit(span::mock().with_target("a").at_level(Level::TRACE)) + .done() + .run_with_handle(); + + let a_subscriber = a_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "a" || target == module_path!() + })); + + let b_subscriber = b_subscriber.with_filter(filter::filter_fn(|meta| { + let target = meta.target(); + target == "b" || target == module_path!() + })); + + let info_tree = info_subscriber + .and_then(a_subscriber) + .and_then(b_subscriber) + .with_filter(LevelFilter::INFO); + + let subscriber = tracing_subscriber::registry() + .with(info_tree) + .with(all_subscriber); + let _guard = dbg!(subscriber).set_default(); + + { + let _a1 = tracing::trace_span!(target: "a", "a/trace").entered(); + let _b1 = tracing::info_span!(target: "b", "b/info").entered(); + let _a2 = tracing::info_span!(target: "a", "a/info").entered(); + let _b2 = tracing::trace_span!(target: "b", "b/trace").entered(); + tracing::info!("hello world"); + tracing::debug!(target: "a", "hello to my target"); + tracing::debug!(target: "b", "hello to my target"); + } + + all_handle.assert_finished(); + info_handle.assert_finished(); + a_handle.assert_finished(); + b_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/multiple_layer_filter_interests_cached.rs b/tracing-subscriber/tests/multiple_layer_filter_interests_cached.rs new file mode 100644 index 0000000000..8088fbb8d6 --- /dev/null +++ b/tracing-subscriber/tests/multiple_layer_filter_interests_cached.rs @@ -0,0 +1,131 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; + +use std::{ + collections::HashMap, + sync::{Arc, Mutex}, +}; +use tracing::{Collect, Level}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn multiple_subscriber_filter_interests_are_cached() { + // This subscriber will return Interest::always for INFO and lower. + let seen_info = Arc::new(Mutex::new(HashMap::new())); + let seen_info2 = seen_info.clone(); + let filter = filter::filter_fn(move |meta| { + *seen_info + .lock() + .unwrap() + .entry(*meta.level()) + .or_insert(0usize) += 1; + meta.level() <= &Level::INFO + }); + let seen_info = seen_info2; + + let (info_subscriber, info_handle) = subscriber::named("info") + .event(event::mock().at_level(Level::INFO)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .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 info_subscriber = info_subscriber.with_filter(filter); + + // This subscriber will return Interest::always for WARN and lower. + let seen_warn = Arc::new(Mutex::new(HashMap::new())); + let seen_warn2 = seen_warn.clone(); + let filter = filter::filter_fn(move |meta| { + *seen_warn + .lock() + .unwrap() + .entry(*meta.level()) + .or_insert(0usize) += 1; + meta.level() <= &Level::WARN + }); + let seen_warn = seen_warn2; + + let (warn_subscriber, warn_handle) = subscriber::named("warn") + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .event(event::mock().at_level(Level::WARN)) + .event(event::mock().at_level(Level::ERROR)) + .done() + .run_with_handle(); + let warn_subscriber = warn_subscriber.with_filter(filter); + + let subscriber = tracing_subscriber::registry() + .with(warn_subscriber) + .with(info_subscriber); + assert!(subscriber.max_level_hint().is_none()); + + let _subscriber = subscriber.set_default(); + + fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); + } + + events(); + { + let lock = seen_info.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the INFO subscriber (after first set of events)", + level + ); + } + + let lock = seen_warn.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the WARN subscriber (after first set of events)", + level + ); + } + } + + events(); + { + let lock = seen_info.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the INFO subscriber (after second set of events)", + level + ); + } + + let lock = seen_warn.lock().unwrap(); + for (&level, &count) in lock.iter() { + if level == Level::INFO { + continue; + } + assert_eq!( + count, 1, + "level {:?} should have been seen 1 time by the WARN subscriber (after second set of events)", + level + ); + } + } + + info_handle.assert_finished(); + warn_handle.assert_finished(); +} diff --git a/tracing-subscriber/tests/support.rs b/tracing-subscriber/tests/support.rs new file mode 100644 index 0000000000..fab742b68c --- /dev/null +++ b/tracing-subscriber/tests/support.rs @@ -0,0 +1,407 @@ +#![allow(missing_docs, dead_code)] +pub use tracing_mock::{collector, event, field, span}; + +use self::{ + collector::{Expect, MockHandle}, + event::MockEvent, + span::{MockSpan, NewSpan}, +}; +use tracing_core::{ + span::{Attributes, Id, Record}, + Collect, Event, +}; +use tracing_subscriber::{ + registry::{LookupSpan, SpanRef}, + subscribe::{Context, Subscribe}, +}; + +use std::{ + collections::VecDeque, + fmt, + sync::{Arc, Mutex}, +}; + +pub mod subscriber { + use super::ExpectSubscriberBuilder; + + pub fn mock() -> ExpectSubscriberBuilder { + ExpectSubscriberBuilder { + expected: Default::default(), + name: std::thread::current() + .name() + .map(String::from) + .unwrap_or_default(), + } + } + + pub fn named(name: impl std::fmt::Display) -> ExpectSubscriberBuilder { + mock().named(name) + } +} + +pub struct ExpectSubscriberBuilder { + expected: VecDeque, + name: String, +} + +pub struct ExpectSubscriber { + expected: Arc>>, + current: Mutex>, + name: String, +} + +impl ExpectSubscriberBuilder { + /// Overrides the name printed by the mock subscriber's debugging output. + /// + /// The debugging output is displayed if the test panics, or if the test is + /// run with `--nocapture`. + /// + /// By default, the mock subscriber's name is the name of the test + /// (*technically*, the name of the thread where it was created, which is + /// the name of the test unless tests are run with `--test-threads=1`). + /// When a test has only one mock subscriber, this is sufficient. However, + /// some tests may include multiple subscribers, in order to test + /// interactions between multiple subscribers. In that case, it can be + /// helpful to give each subscriber a separate name to distinguish where the + /// debugging output comes from. + pub fn named(mut self, name: impl fmt::Display) -> Self { + use std::fmt::Write; + if !self.name.is_empty() { + write!(&mut self.name, "::{}", name).unwrap(); + } else { + self.name = name.to_string(); + } + self + } + + pub fn enter(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::Enter(span)); + self + } + + pub fn event(mut self, event: MockEvent) -> Self { + self.expected.push_back(Expect::Event(event)); + self + } + + pub fn exit(mut self, span: MockSpan) -> Self { + self.expected.push_back(Expect::Exit(span)); + self + } + + pub fn done(mut self) -> Self { + self.expected.push_back(Expect::Nothing); + self + } + + pub fn record(mut self, span: MockSpan, fields: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::Visit(span, fields.into())); + self + } + + pub fn new_span(mut self, new_span: I) -> Self + where + I: Into, + { + self.expected.push_back(Expect::NewSpan(new_span.into())); + self + } + + pub fn run(self) -> ExpectSubscriber { + ExpectSubscriber { + expected: Arc::new(Mutex::new(self.expected)), + name: self.name, + current: Mutex::new(Vec::new()), + } + } + + pub fn run_with_handle(self) -> (ExpectSubscriber, MockHandle) { + let expected = Arc::new(Mutex::new(self.expected)); + let handle = MockHandle::new(expected.clone(), self.name.clone()); + let subscriber = ExpectSubscriber { + expected, + name: self.name, + current: Mutex::new(Vec::new()), + }; + (subscriber, handle) + } +} + +impl ExpectSubscriber { + fn check_span_ref<'spans, S>( + &self, + expected: &MockSpan, + actual: &SpanRef<'spans, S>, + what_happened: impl fmt::Display, + ) where + S: LookupSpan<'spans>, + { + if let Some(exp_name) = expected.name() { + assert_eq!( + actual.name(), + exp_name, + "\n[{}] expected {} a span named {:?}\n\ + [{}] but it was named {:?} instead (span {} {:?})", + self.name, + what_happened, + exp_name, + self.name, + actual.name(), + actual.name(), + actual.id() + ); + } + + if let Some(exp_level) = expected.level() { + let actual_level = actual.metadata().level(); + assert_eq!( + actual_level, + &exp_level, + "\n[{}] expected {} a span at {:?}\n\ + [{}] but it was at {:?} instead (span {} {:?})", + self.name, + what_happened, + exp_level, + self.name, + actual_level, + actual.name(), + actual.id(), + ); + } + + if let Some(exp_target) = expected.target() { + let actual_target = actual.metadata().target(); + assert_eq!( + actual_target, + exp_target, + "\n[{}] expected {} a span with target {:?}\n\ + [{}] but it had the target {:?} instead (span {} {:?})", + self.name, + what_happened, + exp_target, + self.name, + actual_target, + actual.name(), + actual.id(), + ); + } + } +} + +impl Subscribe for ExpectSubscriber +where + C: Collect + for<'a> LookupSpan<'a>, +{ + fn register_callsite( + &self, + metadata: &'static tracing::Metadata<'static>, + ) -> tracing_core::Interest { + println!("[{}] register_callsite {:#?}", self.name, metadata); + tracing_core::Interest::always() + } + + fn on_record(&self, _: &Id, _: &Record<'_>, _: Context<'_, C>) { + unimplemented!( + "so far, we don't have any tests that need an `on_record` \ + implementation.\nif you just wrote one that does, feel free to \ + implement it!" + ); + } + + fn on_event(&self, event: &Event<'_>, cx: Context<'_, C>) { + let name = event.metadata().name(); + println!( + "[{}] event: {}; level: {}; target: {}", + self.name, + name, + event.metadata().level(), + event.metadata().target(), + ); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Event(mut expected)) => { + let get_parent_name = || cx.event_span(event).map(|span| span.name().to_string()); + expected.check(event, get_parent_name, &self.name); + let mut current_scope = cx.event_scope(event).into_iter().flatten(); + let expected_scope = expected.scope_mut(); + let mut i = 0; + for (expected, actual) in expected_scope.iter_mut().zip(&mut current_scope) { + println!( + "[{}] event_scope[{}] actual={} ({:?}); expected={}", + self.name, + i, + actual.name(), + actual.id(), + expected + ); + self.check_span_ref( + expected, + &actual, + format_args!("the {}th span in the event's scope to be", i), + ); + i += 1; + } + let remaining_expected = &expected_scope[i..]; + assert!( + remaining_expected.is_empty(), + "\n[{}] did not observe all expected spans in event scope!\n[{}] missing: {:#?}", + self.name, + self.name, + remaining_expected, + ); + assert!( + current_scope.next().is_none(), + "\n[{}] did not expect all spans in the actual event scope!", + self.name, + ); + } + Some(ex) => ex.bad(&self.name, format_args!("observed event {:#?}", event)), + } + } + + fn on_follows_from(&self, _span: &Id, _follows: &Id, _: Context<'_, C>) { + // TODO: it should be possible to expect spans to follow from other spans + } + + fn on_new_span(&self, span: &Attributes<'_>, id: &Id, cx: Context<'_, C>) { + let meta = span.metadata(); + println!( + "[{}] new_span: name={:?}; target={:?}; id={:?};", + self.name, + meta.name(), + meta.target(), + id + ); + let mut expected = self.expected.lock().unwrap(); + let was_expected = matches!(expected.front(), Some(Expect::NewSpan(_))); + if was_expected { + if let Expect::NewSpan(mut expected) = expected.pop_front().unwrap() { + let get_parent_name = || { + span.parent() + .and_then(|id| cx.span(id)) + .or_else(|| cx.lookup_current()) + .map(|span| span.name().to_string()) + }; + expected.check(span, get_parent_name, &self.name); + } + } + } + + fn on_enter(&self, id: &Id, cx: Context<'_, C>) { + let span = cx + .span(id) + .unwrap_or_else(|| panic!("[{}] no span for ID {:?}", self.name, id)); + println!("[{}] enter: {}; id={:?};", self.name, span.name(), id); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Enter(ref expected_span)) => { + self.check_span_ref(expected_span, &span, "to enter"); + } + Some(ex) => ex.bad(&self.name, format_args!("entered span {:?}", span.name())), + } + self.current.lock().unwrap().push(id.clone()); + } + + fn on_exit(&self, id: &Id, cx: Context<'_, C>) { + if std::thread::panicking() { + // `exit()` can be called in `drop` impls, so we must guard against + // double panics. + println!("[{}] exit {:?} while panicking", self.name, id); + return; + } + let span = cx + .span(id) + .unwrap_or_else(|| panic!("[{}] no span for ID {:?}", self.name, id)); + println!("[{}] exit: {}; id={:?};", self.name, span.name(), id); + match self.expected.lock().unwrap().pop_front() { + None => {} + Some(Expect::Exit(ref expected_span)) => { + self.check_span_ref(expected_span, &span, "to exit"); + let curr = self.current.lock().unwrap().pop(); + assert_eq!( + Some(id), + curr.as_ref(), + "[{}] exited span {:?}, but the current span was {:?}", + self.name, + span.name(), + curr.as_ref().and_then(|id| cx.span(id)).map(|s| s.name()) + ); + } + Some(ex) => ex.bad(&self.name, format_args!("exited span {:?}", span.name())), + }; + } + + fn on_close(&self, id: Id, cx: Context<'_, C>) { + if std::thread::panicking() { + // `try_close` can be called in `drop` impls, so we must guard against + // double panics. + println!("[{}] close {:?} while panicking", self.name, id); + return; + } + let span = cx.span(&id); + let name = span.as_ref().map(|span| { + println!("[{}] close_span: {}; id={:?};", self.name, span.name(), id,); + span.name() + }); + if name.is_none() { + println!("[{}] drop_span: id={:?}", self.name, id); + } + if let Ok(mut expected) = self.expected.try_lock() { + let was_expected = match expected.front() { + Some(Expect::DropSpan(ref expected_span)) => { + // Don't assert if this function was called while panicking, + // as failing the assertion can cause a double panic. + if !::std::thread::panicking() { + if let Some(ref span) = span { + self.check_span_ref(expected_span, span, "to close"); + } + } + true + } + Some(Expect::Event(_)) => { + if !::std::thread::panicking() { + panic!( + "[{}] expected an event, but dropped span {} (id={:?}) instead", + self.name, + name.unwrap_or(""), + id + ); + } + true + } + _ => false, + }; + if was_expected { + expected.pop_front(); + } + } + } + + fn on_id_change(&self, _old: &Id, _new: &Id, _ctx: Context<'_, C>) { + panic!("well-behaved subscribers should never do this to us, lol"); + } +} + +impl fmt::Debug for ExpectSubscriber { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut s = f.debug_struct("ExpectSubscriber"); + s.field("name", &self.name); + + if let Ok(expected) = self.expected.try_lock() { + s.field("expected", &expected); + } else { + s.field("expected", &format_args!("")); + } + + if let Ok(current) = self.current.try_lock() { + s.field("current", &format_args!("{:?}", ¤t)); + } else { + s.field("current", &format_args!("")); + } + + s.finish() + } +} diff --git a/tracing-subscriber/tests/unhinted_layer_filters_dont_break_other_layers.rs b/tracing-subscriber/tests/unhinted_layer_filters_dont_break_other_layers.rs new file mode 100644 index 0000000000..3cf6e721ba --- /dev/null +++ b/tracing-subscriber/tests/unhinted_layer_filters_dont_break_other_layers.rs @@ -0,0 +1,123 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; +use tracing::Level; +use tracing_subscriber::{filter::DynFilterFn, prelude::*}; + +#[test] +fn subscriber_filters() { + let (unfiltered, unfiltered_handle) = unfiltered("unfiltered"); + let (filtered, filtered_handle) = filtered("filtered"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered.with_filter(filter())) + .set_default(); + + events(); + + unfiltered_handle.assert_finished(); + filtered_handle.assert_finished(); +} + +#[test] +fn subscribered_subscriber_filters() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let unfiltered = unfiltered1.and_then(unfiltered2); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + let filtered = filtered1 + .with_filter(filter()) + .and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered) + .with(filtered) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn out_of_order() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let _subscriber = tracing_subscriber::registry() + .with(unfiltered1) + .with(filtered1.with_filter(filter())) + .with(unfiltered2) + .with(filtered2.with_filter(filter())) + .set_default(); + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +#[test] +fn mixed_subscribered() { + let (unfiltered1, unfiltered1_handle) = unfiltered("unfiltered_1"); + let (unfiltered2, unfiltered2_handle) = unfiltered("unfiltered_2"); + let (filtered1, filtered1_handle) = filtered("filtered_1"); + let (filtered2, filtered2_handle) = filtered("filtered_2"); + + let subscribered1 = filtered1.with_filter(filter()).and_then(unfiltered1); + let subscribered2 = unfiltered2.and_then(filtered2.with_filter(filter())); + + let _subscriber = tracing_subscriber::registry() + .with(subscribered1) + .with(subscribered2) + .set_default(); + + events(); + + unfiltered1_handle.assert_finished(); + unfiltered2_handle.assert_finished(); + filtered1_handle.assert_finished(); + filtered2_handle.assert_finished(); +} + +fn events() { + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!("hello info"); + tracing::warn!("hello warn"); + tracing::error!("hello error"); +} + +fn filter() -> DynFilterFn { + DynFilterFn::new(|metadata, _| metadata.level() <= &Level::INFO) +} + +fn unfiltered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .event(event::mock().at_level(Level::TRACE)) + .event(event::mock().at_level(Level::DEBUG)) + .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() +} + +fn filtered(name: &str) -> (ExpectSubscriber, collector::MockHandle) { + subscriber::named(name) + .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() +} diff --git a/tracing-subscriber/tests/utils.rs b/tracing-subscriber/tests/utils.rs index 34e9bb6eae..b0f175b1bc 100644 --- a/tracing-subscriber/tests/utils.rs +++ b/tracing-subscriber/tests/utils.rs @@ -31,7 +31,7 @@ fn builders_are_init_ext() { #[test] #[cfg(all(feature = "fmt", feature = "env-filter"))] -fn layered_is_init_ext() { +fn subscribered_is_init_ext() { tracing_subscriber::registry() .with(tracing_subscriber::fmt::subscriber()) .with(tracing_subscriber::EnvFilter::new("foo=info")) diff --git a/tracing/tests/event.rs b/tracing/tests/event.rs index eeba3a00cf..3db6c68cfd 100644 --- a/tracing/tests/event.rs +++ b/tracing/tests/event.rs @@ -81,12 +81,10 @@ fn message_without_delims() { field::mock("answer") .with_value(&42) .and(field::mock("question").with_value(&"life, the universe, and everything")) - .and( - field::mock("message").with_value(&tracing::field::debug(format_args!( - "hello from my event! tricky? {:?}!", - true - ))), - ) + .and(field::msg(format_args!( + "hello from my event! tricky? {:?}!", + true + ))) .only(), ), ) @@ -110,11 +108,7 @@ fn string_message_without_delims() { field::mock("answer") .with_value(&42) .and(field::mock("question").with_value(&"life, the universe, and everything")) - .and( - field::mock("message").with_value(&tracing::field::debug(format_args!( - "hello from my event" - ))), - ) + .and(field::msg(format_args!("hello from my event"))) .only(), ), ) diff --git a/tracing/tests/support/mod.rs b/tracing/tests/support/mod.rs new file mode 100644 index 0000000000..cdfbfa0606 --- /dev/null +++ b/tracing/tests/support/mod.rs @@ -0,0 +1,84 @@ +#![allow(dead_code)] +pub mod collector; +pub mod event; +pub mod field; +mod metadata; +pub mod span; + +#[derive(Debug, Eq, PartialEq)] +pub(in crate::support) enum Parent { + ContextualRoot, + Contextual(String), + ExplicitRoot, + Explicit(String), +} + +impl Parent { + pub(in crate::support) fn check_parent_name( + &self, + parent_name: Option<&str>, + provided_parent: Option, + ctx: impl std::fmt::Display, + collector_name: &str, + ) { + match self { + Parent::ExplicitRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to be an explicit root, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + } + Parent::Explicit(expected_parent) => { + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have explicit parent {}, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + expected_parent, + provided_parent, + parent_name, + ); + } + Parent::ContextualRoot => { + assert!( + provided_parent.is_none(), + "[{}] expected {} to have a contextual parent, but its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert!( + parent_name.is_none(), + "[{}] expected {} to be contextual a root, but we were inside span {:?}", + collector_name, + ctx, + parent_name, + ); + } + Parent::Contextual(expected_parent) => { + assert!(provided_parent.is_none(), + "[{}] expected {} to have a contextual parent\nbut its parent was actually {:?} (name: {:?})", + collector_name, + ctx, + provided_parent, + parent_name, + ); + assert_eq!( + Some(expected_parent.as_ref()), + parent_name, + "[{}] expected {} to have contextual parent {:?}, but got {:?}", + collector_name, + ctx, + expected_parent, + parent_name, + ); + } + } + } +}