From 1ca3e26190863edb40e465cc3a41522fb29c89a2 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Mon, 13 Sep 2021 09:28:38 -0700 Subject: [PATCH] feat(subscriber): use per-layer filtering Currently, the `console_subscriber::build()` and `console_subscriber::init()` functions configure an `EnvFilter` that enables the `tokio` and `runtime` targets, plus any targets configured by `RUST_LOG`. This means that the `tokio` spans used by the console will always be enabled at the `TRACE` level for all layers. This includes the `fmt` layer we previously added in `init`. Since this resulted in the `fmt` layer logs being cluttered with a bunch of `tokio=trace` spans and events even when only high-level application logs are enabled by `RUST_LOG`, we removed the `fmt` layer in PR #64. However, tokio-rs/tracing#1523 was recently merged and [released][1], adding support for [per-layer filtering][2] to `tracing-subscriber`. We can now use the per-layer filtering API to selectively enable the `tokio`/`runtime` spans and events at the `TRACE` level _only_ for the `TasksLayer`, and add a filter to the `fmt` layer based on `RUST_LOG`. This allows us to put back the `fmt` layer in `console_subscriber::init`. Closes #76 --- Cargo.lock | 8 ++-- console-subscriber/Cargo.toml | 2 +- console-subscriber/examples/app.rs | 8 +++- console-subscriber/src/init.rs | 59 ++++++++++++++++++++++++------ 4 files changed, 60 insertions(+), 17 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 8f88f72a4..0fe12ec8c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1501,9 +1501,9 @@ dependencies = [ [[package]] name = "tracing-core" -version = "0.1.18" +version = "0.1.20" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "a9ff14f98b1a4b289c6248a023c1c2fa1491062964e9fed67ab29c4e4da4a052" +checksum = "46125608c26121c81b0c6d693eab5a420e416da7e43c426d2e8f7df8da8a3acf" dependencies = [ "lazy_static", ] @@ -1561,9 +1561,9 @@ dependencies = [ [[package]] name = "tracing-subscriber" -version = "0.2.20" +version = "0.2.21" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "b9cbe87a2fa7e35900ce5de20220a582a9483a7063811defce79d7cbd59d4cfe" +checksum = "f7d29c0f56bcd17117430bc60fd10624b419ab8a3b5c358796a31e9a37a83a65" dependencies = [ "ansi_term", "chrono", diff --git a/console-subscriber/Cargo.toml b/console-subscriber/Cargo.toml index 1691c89ef..76187b709 100644 --- a/console-subscriber/Cargo.toml +++ b/console-subscriber/Cargo.toml @@ -18,7 +18,7 @@ console-api = { path = "../console-api", features = ["transport"]} tonic = { version = "0.5", features = ["transport"] } tracing-core = "0.1.18" tracing = "0.1.26" -tracing-subscriber = { version = "0.2.19", default-features = false, features = ["fmt", "registry", "env-filter"] } +tracing-subscriber = { version = "0.2.21", default-features = false, features = ["fmt", "registry"] } futures = { version = "0.3", default-features = false } hdrhistogram = { version = "7.3.0", default-features = false, features = ["serialization"] } serde = { version = "1", features = ["derive"] } diff --git a/console-subscriber/examples/app.rs b/console-subscriber/examples/app.rs index 6ad00d4ff..065778f62 100644 --- a/console-subscriber/examples/app.rs +++ b/console-subscriber/examples/app.rs @@ -65,15 +65,21 @@ async fn main() -> Result<(), Box> { async fn spawn_tasks(min: u64, max: u64) { loop { for i in min..max { + tracing::trace!(i, "spawning wait task"); tokio::task::Builder::new().name("wait").spawn(wait(i)); - tokio::time::sleep(Duration::from_secs(max) - Duration::from_secs(i)).await; + + let sleep = Duration::from_secs(max) - Duration::from_secs(i); + tracing::trace!(?sleep, "sleeping..."); + tokio::time::sleep(sleep).await; } } } #[tracing::instrument] async fn wait(seconds: u64) { + tracing::debug!("waiting..."); tokio::time::sleep(Duration::from_secs(seconds)).await; + tracing::trace!("done!"); } #[tracing::instrument] diff --git a/console-subscriber/src/init.rs b/console-subscriber/src/init.rs index 12848578f..d80145092 100644 --- a/console-subscriber/src/init.rs +++ b/console-subscriber/src/init.rs @@ -1,20 +1,34 @@ use crate::TasksLayer; use std::thread; use tokio::runtime; -use tracing_subscriber::{layer::Layered, prelude::*, EnvFilter, Registry}; +use tracing_subscriber::{ + filter::{Filtered, LevelFilter, Targets}, + layer::Layered, + prelude::*, + Registry, +}; -type ConsoleSubscriberLayer = Layered>; +type ConsoleSubscriberLayer = Layered, Registry>; -/// Starts the console subscriber server on its own thread. +/// Initializes the console [tracing `Subscriber`][sub] and starts the console +/// subscriber [`Server`] on its own background thread. /// /// This function represents the easiest way to get started using /// tokio-console. /// +/// In addition to the [`TasksLayer`], which collects instrumentation data +/// consumed by the console, the default [`Subscriber`][sub] initialized by this +/// function also includes a [`tracing_subscriber::fmt`] layer, which logs +/// tracing spans and events to stdout. Which spans and events are logged will +/// be determined by the `RUST_LOG` environment variable. +/// /// **Note**: this function sets the [default `tracing` subscriber][default] /// for your application. If you need to add additional layers to this /// subscriber, see [`build`]. /// /// [default]: https://docs.rs/tracing/latest/tracing/dispatcher/index.html#setting-the-default-subscriber +/// [sub]: https://docs.rs/tracing/latest/tracing/trait.Subscriber.html +/// [`tracing_subscriber::fmt`]: https://docs.rs/tracing-subscriber/latest/tracing-subscriber/fmt/index.html /// /// ## Configuration /// @@ -28,7 +42,7 @@ type ConsoleSubscriberLayer = Layered>; /// | `TOKIO_CONSOLE_BIND` | A HOST:PORT description, such as `localhost:1234` | `127.0.0.1:6669` | /// | `TOKIO_CONSOLE_PUBLISH_INTERVAL_MS` | The number of milliseconds to wait between sending updates to the console | 1000ms (1s) | /// | `TOKIO_CONSOLE_RECORD_PATH` | The file path to save a recording | None | -/// | `RUST_LOG` | Configure the tracing filter. See [`EnvFilter`] for further information | `tokio=trace` | +/// | `RUST_LOG` | Configures what events are logged events. See [`Targets`] for details. | "error" | /// /// ## Further customization /// @@ -42,8 +56,22 @@ type ConsoleSubscriberLayer = Layered>; /// // .with(..potential additional layer..) /// .init(); /// ``` +/// +/// [`Targets`]: https://docs.rs/tracing-subscriber/latest/tracing-subscriber/filter/struct.Targets.html pub fn init() { - build().init() + let fmt_filter = std::env::var("RUST_LOG") + .ok() + .and_then(|rust_log| match rust_log.parse::() { + Ok(targets) => Some(targets), + Err(e) => { + eprintln!("failed to parse `RUST_LOG={:?}`: {}", rust_log, e); + None + } + }) + .unwrap_or_else(|| Targets::default().with_default(LevelFilter::ERROR)); + build() + .with(tracing_subscriber::fmt::layer().with_filter(fmt_filter)) + .init() } /// Returns a new `tracing` [subscriber] configured with a [`TasksLayer`] @@ -53,7 +81,7 @@ pub fn init() { /// additional [`Layer`]s to be added. /// /// [subscriber]: https://docs.rs/tracing/latest/tracing/subscriber/trait.Subscriber.html -/// [filter]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.EnvFilter.html +/// [filter]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/filter/struct.Targets.html /// [`Layer`]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/layer/trait.Layer.html /// /// ## Configuration @@ -63,6 +91,12 @@ pub fn init() { /// /// ## Differences from `init` /// +/// Unlike [`console_subscriber::init`], this function does *not* add a +/// [`tracing_subscriber::fmt`] layer to the configured `Subscriber`. This means +/// that this function will not log spans and events based on the value of the +/// `RUST_LOG` environment variable. Instead, a user-provided [`fmt::Layer`] can +/// be added in order to customize the log format. +/// /// You must call [`.init()`] on the final subscriber in order to [set the /// subscriber as the default][set_default]. /// @@ -76,16 +110,19 @@ pub fn init() { /// .init(); /// ``` /// [`.init()`]: https://docs.rs/tracing-subscriber/latest/tracing_subscriber/util/trait.SubscriberInitExt.html -/// [set_default]: https://docs.rs/tracing/latest/tracing/subscriber/fn.set_default.html +/// [default]: https://docs.rs/tracing/latest/tracing/dispatcher/index.html#setting-the-default-subscriber +/// [sub]: https://docs.rs/tracing/latest/tracing/trait.Subscriber.html +/// [`tracing_subscriber::fmt`]: https://docs.rs/tracing-subscriber/latest/tracing-subscriber/fmt/index.html +/// [`fmt::Layer`]: https://docs.rs/tracing-subscriber/latest/tracing-subscriber/fmt/struct.Layer.html #[must_use = "build() without init() will not set the default tracing subscriber"] pub fn build() -> ConsoleSubscriberLayer { let (layer, server) = TasksLayer::builder().with_default_env().build(); - let filter = EnvFilter::from_default_env() - .add_directive("tokio=trace".parse().unwrap()) - .add_directive("runtime=trace".parse().unwrap()); + let filter = Targets::new() + .with_target("tokio", LevelFilter::TRACE) + .with_target("runtime", LevelFilter::TRACE); - let console_subscriber = tracing_subscriber::registry().with(filter).with(layer); + let console_subscriber = tracing_subscriber::registry().with(layer.with_filter(filter)); thread::Builder::new() .name("console_subscriber".into())