Skip to content

Commit

Permalink
subscriber: impl Filter for EnvFilter (#1983)
Browse files Browse the repository at this point in the history 
## Motivation

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

## Solution

Implement the `Filter` trait for `EnvFilter`. PR #1973 adds additiional
methods to the `Filter` trait, which are necessary for `EnvFilter` to
implement dynamic span filtering. Now that those methods are added, we
can provide a `Filter` impl for `EnvFilter`.

In addition, we changed the globally-scoped `thread_local!` macro to use
a `ThreadLocal` struct as a field, so that multiple `EnvFilter`s used as
per-layer filters don't share a single span scope.

Fixes #1868
Follow-up on #1973

Co-authored-by: Eliza Weisman <[email protected]>
  • Loading branch information
@tfreiberg-fastly @hawkw
tfreiberg-fastly and hawkw authored Mar 25, 2022
1 parent df9666b commit ed7b60a
Show file tree
Hide file tree
Showing 6 changed files with 1,029 additions and 229 deletions.
2 changes: 1 addition & 1 deletion tracing-subscriber/Cargo.toml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -27,7 +27,7 @@ rust-version = "1.49.0"
default = ["smallvec", "fmt", "ansi", "tracing-log", "std"]
alloc = []
std = ["alloc", "tracing-core/std"]
env-filter = ["matchers", "regex", "lazy_static", "tracing", "std"]
env-filter = ["matchers", "regex", "lazy_static", "tracing", "std", "thread_local"]
fmt = ["registry", "std"]
ansi = ["fmt", "ansi_term"]
registry = ["sharded-slab", "thread_local", "std"]
Expand Down
219 changes: 178 additions & 41 deletions tracing-subscriber/src/filter/env/mod.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -10,11 +10,12 @@ mod field;

use crate::{
filter::LevelFilter,
layer::{Context, Layer},
layer::{self, Context, Layer},
sync::RwLock,
};
use directive::ParseError;
use std::{cell::RefCell, collections::HashMap, env, error::Error, fmt, str::FromStr};
use thread_local::ThreadLocal;
use tracing_core::{
callsite,
field::Field,
Expand All @@ -26,6 +27,16 @@ use tracing_core::{
/// A [`Layer`] which filters spans and events based on a set of filter
/// directives.
///
/// `EnvFilter` implements both the [`Layer`](#impl-Layer<S>) and [`Filter`] traits, so it may
/// be used for both [global filtering][global] and [per-layer filtering][plf],
/// respectively. See [the documentation on filtering with `Layer`s][filtering]
/// for details.
///
/// The [`Targets`] type implements a similar form of filtering, but without the
/// ability to dynamically enable events based on the current span context, and
/// without filtering on field values. When these features are not required,
/// [`Targets`] provides a lighter-weight alternative to [`EnvFilter`].
///
/// # Directives
///
/// A filter consists of one or more comma-separated directives which match on [`Span`]s and [`Event`]s.
Expand Down Expand Up @@ -72,7 +83,7 @@ use tracing_core::{
/// - A dash in a target will only appear when being specified explicitly:
/// `tracing::info!(target: "target-name", ...);`
///
/// ## Examples
/// ## Example Syntax
///
/// - `tokio::net=info` will enable all spans or events that:
/// - have the `tokio::net` target,
Expand All @@ -89,10 +100,54 @@ use tracing_core::{
/// - which has a field named `name` with value `bob`,
/// - at _any_ level.
///
/// The [`Targets`] type implements a similar form of filtering, but without the
/// ability to dynamically enable events based on the current span context, and
/// without filtering on field values. When these features are not required,
/// [`Targets`] provides a lighter-weight alternative to [`EnvFilter`].
/// # Examples
///
/// Parsing an `EnvFilter` from the [default environment
/// variable](EnvFilter::from_default_env) (`RUST_LOG`):
///
/// ```
/// use tracing_subscriber::{EnvFilter, fmt, prelude::*};
///
/// tracing_subscriber::registry()
/// .with(fmt::layer())
/// .with(EnvFilter::from_default_env())
/// .init();
/// ```
///
/// Parsing an `EnvFilter` [from a user-provided environment
/// variable](EnvFilter::from_env):
///
/// ```
/// use tracing_subscriber::{EnvFilter, fmt, prelude::*};
///
/// tracing_subscriber::registry()
/// .with(fmt::layer())
/// .with(EnvFilter::from_env("MYAPP_LOG"))
/// .init();
/// ```
///
/// Using `EnvFilter` as a [per-layer filter][plf] to filter only a single
/// [`Layer`]:
///
/// ```
/// use tracing_subscriber::{EnvFilter, fmt, prelude::*};
///
/// // Parse an `EnvFilter` configuration from the `RUST_LOG`
/// // environment variable.
/// let filter = EnvFilter::from_default_env();
///
/// // Apply the filter to this layer *only*.
/// let filtered_layer = fmt::layer().with_filter(filter);
///
/// // Some other layer, whose output we don't want to filter.
/// let unfiltered_layer = // ...
/// # fmt::layer();
///
/// tracing_subscriber::registry()
/// .with(filtered_layer)
/// .with(unfiltered_layer)
/// .init();
/// ```
///
/// [`Span`]: tracing_core::span
/// [fields]: tracing_core::Field
Expand All @@ -101,6 +156,10 @@ use tracing_core::{
/// [`Metadata`]: tracing_core::Metadata
/// [`Targets`]: crate::filter::Targets
/// [`env_logger`]: https://crates.io/crates/env_logger
/// [`Filter`]: #impl-Filter<S>
/// [global]: crate::layer#global-filtering
/// [plf]: crate::layer#per-layer-filtering
/// [filtering]: crate::layer#filtering-with-layers
#[cfg_attr(docsrs, doc(cfg(all(feature = "env-filter", feature = "std"))))]
#[derive(Debug)]
pub struct EnvFilter {
Expand All @@ -109,10 +168,7 @@ pub struct EnvFilter {
has_dynamics: bool,
by_id: RwLock<HashMap<span::Id, directive::SpanMatcher>>,
by_cs: RwLock<HashMap<callsite::Identifier, directive::CallsiteMatcher>>,
}

thread_local! {
static SCOPE: RefCell<Vec<LevelFilter>> = RefCell::new(Vec::new());
scope: ThreadLocal<RefCell<Vec<LevelFilter>>>,
}

type FieldMap<T> = HashMap<Field, T>;
Expand Down Expand Up @@ -350,6 +406,10 @@ impl EnvFilter {
has_dynamics,
by_id: RwLock::new(HashMap::new()),
by_cs: RwLock::new(HashMap::new()),
// TODO(eliza): maybe worth allocating capacity for `num_cpus`
// threads or something (assuming we're running in Tokio)? or
// `num_cpus * 2` or something?
scope: ThreadLocal::new(),
}
}

Expand All @@ -365,9 +425,7 @@ impl EnvFilter {
Interest::never()
}
}
}

impl<S: Subscriber> Layer<S> for EnvFilter {
fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
if self.has_dynamics && metadata.is_span() {
// If this metadata describes a span, first, check if there is a
Expand All @@ -388,20 +446,7 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
}
}

fn max_level_hint(&self) -> Option<LevelFilter> {
if self.dynamics.has_value_filters() {
// If we perform any filtering on span field *values*, we will
// enable *all* spans, because their field values are not known
// until recording.
return Some(LevelFilter::TRACE);
}
std::cmp::max(
self.statics.max_level.into(),
self.dynamics.max_level.into(),
)
}

fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
fn enabled(&self, metadata: &Metadata<'_>) -> bool {
let level = metadata.level();

// is it possible for a dynamic filter directive to enable this event?
Expand All @@ -421,14 +466,15 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
}
}

let enabled_by_scope = SCOPE.with(|scope| {
for filter in scope.borrow().iter() {
let enabled_by_scope = {
let scope = self.scope.get_or_default().borrow();
for filter in &*scope {
if filter >= level {
return true;
}
}
false
});
};
if enabled_by_scope {
return true;
}
Expand All @@ -444,36 +490,43 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
false
}

fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) {
fn max_level_hint(&self) -> Option<LevelFilter> {
if self.dynamics.has_value_filters() {
// If we perform any filtering on span field *values*, we will
// enable *all* spans, because their field values are not known
// until recording.
return Some(LevelFilter::TRACE);
}
std::cmp::max(
self.statics.max_level.into(),
self.dynamics.max_level.into(),
)
}

fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id) {
let by_cs = try_lock!(self.by_cs.read());
if let Some(cs) = by_cs.get(&attrs.metadata().callsite()) {
let span = cs.to_span_match(attrs);
try_lock!(self.by_id.write()).insert(id.clone(), span);
}
}

fn on_record(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, S>) {
if let Some(span) = try_lock!(self.by_id.read()).get(id) {
span.record_update(values);
}
}

fn on_enter(&self, id: &span::Id, _: Context<'_, S>) {
fn on_enter(&self, id: &span::Id) {
// XXX: This is where _we_ could push IDs to the stack instead, and use
// that to allow changing the filter while a span is already entered.
// But that might be much less efficient...
if let Some(span) = try_lock!(self.by_id.read()).get(id) {
SCOPE.with(|scope| scope.borrow_mut().push(span.level()));
self.scope.get_or_default().borrow_mut().push(span.level());
}
}

fn on_exit(&self, id: &span::Id, _: Context<'_, S>) {
fn on_exit(&self, id: &span::Id) {
if self.cares_about_span(id) {
SCOPE.with(|scope| scope.borrow_mut().pop());
self.scope.get_or_default().borrow_mut().pop();
}
}

fn on_close(&self, id: span::Id, _: Context<'_, S>) {
fn on_close(&self, id: span::Id) {
// If we don't need to acquire a write lock, avoid doing so.
if !self.cares_about_span(&id) {
return;
Expand All @@ -484,6 +537,90 @@ impl<S: Subscriber> Layer<S> for EnvFilter {
}
}

impl<S: Subscriber> Layer<S> for EnvFilter {
#[inline]
fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest {
EnvFilter::register_callsite(self, metadata)
}

#[inline]
fn max_level_hint(&self) -> Option<LevelFilter> {
EnvFilter::max_level_hint(self)
}

#[inline]
fn enabled(&self, metadata: &Metadata<'_>, _: Context<'_, S>) -> bool {
self.enabled(metadata)
}

#[inline]
fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) {
self.on_new_span(attrs, id)
}

fn on_record(&self, id: &span::Id, values: &span::Record<'_>, _: Context<'_, S>) {
if let Some(span) = try_lock!(self.by_id.read()).get(id) {
span.record_update(values);
}
}

#[inline]
fn on_enter(&self, id: &span::Id, _: Context<'_, S>) {
self.on_enter(id);
}

#[inline]
fn on_exit(&self, id: &span::Id, _: Context<'_, S>) {
self.on_exit(id);
}

#[inline]
fn on_close(&self, id: span::Id, _: Context<'_, S>) {
self.on_close(id);
}
}

feature! {
#![all(feature = "registry", feature = "std")]

impl<S> layer::Filter<S> for EnvFilter {
#[inline]
fn enabled(&self, meta: &Metadata<'_>, _: &Context<'_, S>) -> bool {
self.enabled(meta)
}

#[inline]
fn callsite_enabled(&self, meta: &'static Metadata<'static>) -> Interest {
self.register_callsite(meta)
}

#[inline]
fn max_level_hint(&self) -> Option<LevelFilter> {
EnvFilter::max_level_hint(self)
}

#[inline]
fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, _: Context<'_, S>) {
self.on_new_span(attrs, id)
}

#[inline]
fn on_enter(&self, id: &span::Id, _: Context<'_, S>) {
self.on_enter(id);
}

#[inline]
fn on_exit(&self, id: &span::Id, _: Context<'_, S>) {
self.on_exit(id);
}

#[inline]
fn on_close(&self, id: span::Id, _: Context<'_, S>) {
self.on_close(id);
}
}
}

impl FromStr for EnvFilter {
type Err = directive::ParseError;

Expand Down
Loading

0 comments on commit ed7b60a

Please sign in to comment.