feat(subscriber): use per-layer filtering (#140)

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`.

Now, if we run the example app (which uses `init`) with a `RUST_LOG`
value that enables only the app's logs, we get nice output:

![image](https://user-images.githubusercontent.com/2796466/133124582-608c2b72-db2f-4588-bb75-585312ac8d66.png)

However, we can also enable the `console-subscriber` crate's internal
logging:

![image](https://user-images.githubusercontent.com/2796466/133124746-7df10f14-cf8c-40ef-96f3-5046039a8577.png)

And, we can still enable `tokio=trace` ourselves, if we actually _want_
to see all the task spans and waker events:

![image](https://user-images.githubusercontent.com/2796466/133124851-3e4af25a-06a4-4912-9950-bfbab6dba4c7.png)

I also added some `trace!` and `debug!` macros in `examples/app.rs` to
demo that `console_subscriber::init()` also enables logging.

Closes #76

Author: hawkw

Cargo.lock

@@ -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"] }

console-subscriber/Cargo.toml

@@ -65,15 +65,21 @@ async fn main() -> Result<(), Box<dyn std::error::Error + Send + Sync>> {
 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]

console-subscriber/examples/app.rs

@@ -1,20 +1,35 @@
 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<TasksLayer, Layered<EnvFilter, Registry>>;
+type ConsoleSubscriberLayer = Layered<Filtered<TasksLayer, Targets, Registry>, 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
+/// [`Server`]: crate::Server
 ///
 /// ## Configuration
 ///
@@ -28,7 +43,7 @@ type ConsoleSubscriberLayer = Layered<TasksLayer, Layered<EnvFilter, Registry>>;
 /// | `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,29 +57,53 @@ type ConsoleSubscriberLayer = Layered<TasksLayer, Layered<EnvFilter, Registry>>;
 /// //  .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::<Targets>() {
+            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`]
 /// and a [filter] that enables the spans and events required by the console.
 ///
+/// This function spawns the console subscriber's [`Server`] in its own Tokio
+/// runtime in a background thread.
+///
 /// Unlike [`init`], this function does not set the default subscriber, allowing
 /// 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
+/// [`Server`]: crate::Server
 ///
 /// ## Configuration
 ///
 /// `console_subscriber::build` supports all of the environmental
-/// configuration described at [`console_subscriber::init`][init]
+/// configuration described at [`console_subscriber::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].
+/// subscriber as the default][default].
 ///
 /// ## Examples
 ///
@@ -76,16 +115,20 @@ 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
+/// [`console_subscriber::init`]: crate::init()
 #[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())