From 0852ab3282b8204ab16aec3da8195350b6ad9a51 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Tue, 29 Mar 2022 16:54:52 -0700 Subject: [PATCH] subscriber: add `Layer` impl for `Vec` (#2027) Depends on #2028 ## Motivation In many cases, it is desirable to have a variable number of `Layer`s at runtime (such as when reading a logging configuration from a config file). The current approach, where types implementing `Layer` are composed at the type level into `Layered` layers, doesn't work well when the number of layers varies at runtime. ## Solution To solve this, this branch adds a `Layer` implementation for `Vec where L: Layer`. This allows variable-length lists of layers to be added to a subscriber. Although the impl for `Vec` requires all the layers to be the same type, it can also be used in onjunction with `Box + ...>` trait objects to implement a variable-length list of layers of multiple types. I also wrote a bunch of docs examples. ## Notes Alternatively, we could have a separate type defined in `tracing-subscriber` for a variable-length list of type-erased `Layer`s. This would have one primary usability benefit, which is that we could have a `push` operation that takes an `impl Layer` and boxes it automatically. However, I thought the approach used here is nicer, since it's based on composing together existing primitives such as `Vec` and `Box`, rather than adding a whole new API. Additionally, it allows avoiding the additional `Box`ing in the case where the list consists of layers that are all the same type. Closes #1708 Signed-off-by: Eliza Weisman --- tracing-subscriber/src/layer/mod.rs | 221 +++++++++++++++++- .../tests/layer_filters/main.rs | 3 +- tracing-subscriber/tests/layer_filters/vec.rs | 113 +++++++++ .../vec_subscriber_filter_interests_cached.rs | 117 ++++++++++ 4 files changed, 451 insertions(+), 3 deletions(-) create mode 100644 tracing-subscriber/tests/layer_filters/vec.rs create mode 100644 tracing-subscriber/tests/vec_subscriber_filter_interests_cached.rs diff --git a/tracing-subscriber/src/layer/mod.rs b/tracing-subscriber/src/layer/mod.rs index 3b1cb3bda0..fc4a34841b 100644 --- a/tracing-subscriber/src/layer/mod.rs +++ b/tracing-subscriber/src/layer/mod.rs @@ -215,11 +215,11 @@ //! ``` //! //! If a [`Layer`] may be one of several different types, note that [`Box + Send + Sync>` implements `Layer`][box-impl]. +//! Layer + Send + Sync>` implements `Layer`][box-impl]. //! This may be used to erase the type of a [`Layer`]. //! //! For example, a function that configures a [`Layer`] to log to one of -//! several outputs might return a `Box + Send + Sync + 'static>`: +//! several outputs might return a `Box + Send + Sync + 'static>`: //! ``` //! use tracing_subscriber::{ //! Layer, @@ -267,6 +267,107 @@ //! The [`Layer::boxed`] method is provided to make boxing a `Layer` //! more convenient, but [`Box::new`] may be used as well. //! +//! When the number of `Layer`s varies at runtime, note that a +//! [`Vec where L: `Layer`` also implements `Layer`][vec-impl]. This +//! can be used to add a variable number of `Layer`s to a `Subscriber`: +//! +//! ``` +//! use tracing_subscriber::{Layer, prelude::*}; +//! struct MyLayer { +//! // ... +//! } +//! # impl MyLayer { fn new() -> Self { Self {} }} +//! +//! impl Layer for MyLayer { +//! // ... +//! } +//! +//! /// Returns how many layers we need +//! fn how_many_layers() -> usize { +//! // ... +//! # 3 +//! } +//! +//! // Create a variable-length `Vec` of layers +//! let mut layers = Vec::new(); +//! for _ in 0..how_many_layers() { +//! layers.push(MyLayer::new()); +//! } +//! +//! tracing_subscriber::registry() +//! .with(layers) +//! .init(); +//! ``` +//! +//! If a variable number of `Layer` is needed and those `Layer`s have +//! different types, a `Vec` of [boxed `Layer` trait objects][box-impl] may +//! be used. For example: +//! +//! ``` +//! use tracing_subscriber::{filter::LevelFilter, Layer, prelude::*}; +//! use std::fs::File; +//! # fn main() -> Result<(), Box> { +//! struct Config { +//! enable_log_file: bool, +//! enable_stdout: bool, +//! enable_stderr: bool, +//! // ... +//! } +//! # impl Config { +//! # fn from_config_file()-> Result> { +//! # // don't enable the log file so that the example doesn't actually create it +//! # Ok(Self { enable_log_file: false, enable_stdout: true, enable_stderr: true }) +//! # } +//! # } +//! +//! let cfg = Config::from_config_file()?; +//! +//! // Based on our dynamically loaded config file, create any number of layers: +//! let mut layers = Vec::new(); +//! +//! if cfg.enable_log_file { +//! let file = File::create("myapp.log")?; +//! let layer = tracing_subscriber::fmt::layer() +//! .with_thread_names(true) +//! .with_target(true) +//! .json() +//! .with_writer(file) +//! // Box the layer as a type-erased trait object, so that it can +//! // be pushed to the `Vec`. +//! .boxed(); +//! layers.push(layer); +//! } +//! +//! if cfg.enable_stdout { +//! let layer = tracing_subscriber::fmt::layer() +//! .pretty() +//! .with_filter(LevelFilter::INFO) +//! // Box the layer as a type-erased trait object, so that it can +//! // be pushed to the `Vec`. +//! .boxed(); +//! layers.push(layer); +//! } +//! +//! if cfg.enable_stdout { +//! let layer = tracing_subscriber::fmt::layer() +//! .with_target(false) +//! .with_filter(LevelFilter::WARN) +//! // Box the layer as a type-erased trait object, so that it can +//! // be pushed to the `Vec`. +//! .boxed(); +//! layers.push(layer); +//! } +//! +//! tracing_subscriber::registry() +//! .with(layers) +//! .init(); +//!# Ok(()) } +//! ``` +//! +//! Finally, if the number of layers _changes_ at runtime, a `Vec` of +//! subscribers can be used alongside the [`reload`](crate::reload) module to +//! add or remove subscribers dynamically at runtime. +//! //! [option-impl]: Layer#impl-Layer-for-Option //! [box-impl]: Layer#impl-Layer%3CS%3E-for-Box%3Cdyn%20Layer%3CS%3E%20+%20Send%20+%20Sync%3E //! [prelude]: crate::prelude @@ -1060,6 +1161,8 @@ where feature! { #![all(feature = "registry", feature = "std")] + use alloc::vec::Vec; + /// A per-[`Layer`] filter that determines whether a span or event is enabled /// for an individual layer. /// @@ -1491,6 +1594,120 @@ feature! { { layer_impl_body! {} } + + + + impl Layer for Vec + where + L: Layer, + S: Subscriber, + { + + fn on_layer(&mut self, subscriber: &mut S) { + for l in self { + l.on_layer(subscriber); + } + } + + fn register_callsite(&self, metadata: &'static Metadata<'static>) -> Interest { + // Return highest level of interest. + let mut interest = Interest::never(); + for l in self { + let new_interest = l.register_callsite(metadata); + if (interest.is_sometimes() && new_interest.is_always()) + || (interest.is_never() && !new_interest.is_never()) + { + interest = new_interest; + } + } + + interest + } + + fn enabled(&self, metadata: &Metadata<'_>, ctx: Context<'_, S>) -> bool { + self.iter().all(|l| l.enabled(metadata, ctx.clone())) + } + + fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { + for l in self { + l.on_new_span(attrs, id, ctx.clone()); + } + } + + fn max_level_hint(&self) -> Option { + let mut max_level = LevelFilter::ERROR; + for l in self { + // NOTE(eliza): this is slightly subtle: if *any* layer + // returns `None`, we have to return `None`, assuming there is + // no max level hint, since that particular layer cannot + // provide a hint. + let hint = l.max_level_hint()?; + max_level = core::cmp::max(hint, max_level); + } + Some(max_level) + } + + fn on_record(&self, span: &span::Id, values: &span::Record<'_>, ctx: Context<'_, S>) { + for l in self { + l.on_record(span, values, ctx.clone()) + } + } + + fn on_follows_from(&self, span: &span::Id, follows: &span::Id, ctx: Context<'_, S>) { + for l in self { + l.on_follows_from(span, follows, ctx.clone()); + } + } + + fn on_event(&self, event: &Event<'_>, ctx: Context<'_, S>) { + for l in self { + l.on_event(event, ctx.clone()); + } + } + + fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { + for l in self { + l.on_enter(id, ctx.clone()); + } + } + + fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { + for l in self { + l.on_exit(id, ctx.clone()); + } + } + + fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { + for l in self { + l.on_close(id.clone(), ctx.clone()); + } + } + + #[doc(hidden)] + unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { + // If downcasting to `Self`, return a pointer to `self`. + if id == TypeId::of::() { + return Some(self as *const _ as *const ()); + } + + // Someone is looking for per-layer filters. But, this `Vec` + // might contain layers with per-layer filters *and* + // layers without filters. It should only be treated as a + // per-layer-filtered layer if *all* its layers have + // per-layer filters. + // XXX(eliza): it's a bummer we have to do this linear search every + // time. It would be nice if this could be cached, but that would + // require replacing the `Vec` impl with an impl for a newtype... + if filter::is_plf_downcast_marker(id) && self.iter().any(|s| s.downcast_raw(id).is_none()) { + return None; + } + + // Otherwise, return the first child of `self` that downcaasts to + // the selected type, if any. + // XXX(eliza): hope this is reasonable lol + self.iter().find_map(|l| l.downcast_raw(id)) + } + } } // === impl SubscriberExt === diff --git a/tracing-subscriber/tests/layer_filters/main.rs b/tracing-subscriber/tests/layer_filters/main.rs index 2359584d72..0233f063b9 100644 --- a/tracing-subscriber/tests/layer_filters/main.rs +++ b/tracing-subscriber/tests/layer_filters/main.rs @@ -7,9 +7,10 @@ mod downcast_raw; mod filter_scopes; mod targets; mod trees; +mod vec; use tracing::{level_filters::LevelFilter, Level}; -use tracing_subscriber::{filter, prelude::*}; +use tracing_subscriber::{filter, prelude::*, Layer}; #[test] fn basic_layer_filters() { diff --git a/tracing-subscriber/tests/layer_filters/vec.rs b/tracing-subscriber/tests/layer_filters/vec.rs new file mode 100644 index 0000000000..77675a5f94 --- /dev/null +++ b/tracing-subscriber/tests/layer_filters/vec.rs @@ -0,0 +1,113 @@ +use super::*; +use tracing::Subscriber; + +#[test] +fn with_filters_unboxed() { + let (trace_layer, trace_handle) = layer::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 trace_layer = trace_layer.with_filter(LevelFilter::TRACE); + + let (debug_layer, debug_handle) = layer::named("debug") + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + let debug_layer = debug_layer.with_filter(LevelFilter::DEBUG); + + let (info_layer, info_handle) = layer::named("info") + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + let info_layer = info_layer.with_filter(LevelFilter::INFO); + + let _subscriber = tracing_subscriber::registry() + .with(vec![trace_layer, debug_layer, info_layer]) + .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 with_filters_boxed() { + let (unfiltered_layer, unfiltered_handle) = layer::named("unfiltered") + .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 unfiltered_layer = unfiltered_layer.boxed(); + + let (debug_layer, debug_handle) = layer::named("debug") + .event(event::mock().at_level(Level::DEBUG)) + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + let debug_layer = debug_layer.with_filter(LevelFilter::DEBUG).boxed(); + + let (target_layer, target_handle) = layer::named("target") + .event(event::mock().at_level(Level::INFO)) + .done() + .run_with_handle(); + let target_layer = target_layer + .with_filter(filter::filter_fn(|meta| meta.target() == "my_target")) + .boxed(); + + let _subscriber = tracing_subscriber::registry() + .with(vec![unfiltered_layer, debug_layer, target_layer]) + .set_default(); + + tracing::trace!("hello trace"); + tracing::debug!("hello debug"); + tracing::info!(target: "my_target", "hello my target"); + + unfiltered_handle.assert_finished(); + debug_handle.assert_finished(); + target_handle.assert_finished(); +} + +#[test] +fn mixed_max_level_hint() { + let unfiltered = layer::named("unfiltered").run().boxed(); + let info = layer::named("info") + .run() + .with_filter(LevelFilter::INFO) + .boxed(); + let debug = layer::named("debug") + .run() + .with_filter(LevelFilter::DEBUG) + .boxed(); + + let subscriber = tracing_subscriber::registry().with(vec![unfiltered, info, debug]); + + assert_eq!(subscriber.max_level_hint(), None); +} + +#[test] +fn all_filtered_max_level_hint() { + let warn = layer::named("warn") + .run() + .with_filter(LevelFilter::WARN) + .boxed(); + let info = layer::named("info") + .run() + .with_filter(LevelFilter::INFO) + .boxed(); + let debug = layer::named("debug") + .run() + .with_filter(LevelFilter::DEBUG) + .boxed(); + + let subscriber = tracing_subscriber::registry().with(vec![warn, info, debug]); + + assert_eq!(subscriber.max_level_hint(), Some(LevelFilter::DEBUG)); +} diff --git a/tracing-subscriber/tests/vec_subscriber_filter_interests_cached.rs b/tracing-subscriber/tests/vec_subscriber_filter_interests_cached.rs new file mode 100644 index 0000000000..10467cb7d6 --- /dev/null +++ b/tracing-subscriber/tests/vec_subscriber_filter_interests_cached.rs @@ -0,0 +1,117 @@ +#![cfg(feature = "registry")] +mod support; +use self::support::*; + +use std::{ + collections::HashMap, + sync::{Arc, Mutex}, +}; +use tracing::{Level, Subscriber}; +use tracing_subscriber::{filter, prelude::*}; + +#[test] +fn vec_layer_filter_interests_are_cached() { + let mk_filtered = |level: Level, subscriber: ExpectLayer| { + let seen = Arc::new(Mutex::new(HashMap::new())); + let filter = filter::filter_fn({ + let seen = seen.clone(); + move |meta| { + *seen.lock().unwrap().entry(*meta.level()).or_insert(0usize) += 1; + meta.level() <= &level + } + }); + (subscriber.with_filter(filter).boxed(), seen) + }; + + // This layer will return Interest::always for INFO and lower. + let (info_layer, info_handle) = layer::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_layer, seen_info) = mk_filtered(Level::INFO, info_layer); + + // This layer will return Interest::always for WARN and lower. + let (warn_layer, warn_handle) = layer::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_layer, seen_warn) = mk_filtered(Level::WARN, warn_layer); + + let subscriber = tracing_subscriber::registry().with(vec![warn_layer, info_layer]); + 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(); +}