From 805eb51bc9f5ab7d193c9f7b3f382526fd5dbf62 Mon Sep 17 00:00:00 2001 From: Eliza Weisman Date: Fri, 14 May 2021 15:55:48 -0700 Subject: [PATCH] subscriber: add `MakeWriter::make_writer_for` (#1141) This backports PR #1141 from `master`. subscriber: add `MakeWriter::make_writer_for` ## Motivation In some cases, it might be desirable to configure the writer used for writing out trace data based on the metadata of the span or event being written. For example, we might want to send different levels to different outputs, write logs from different targets to separate files, or wrap formatted output in ANSI color codes based on levels. Currently, it's not possible for the `MakeWriter` trait to model this kind of behavior --- it has one method, `make_writer`, which is completely unaware of *where* the data being written came from. In particular, this came up in PR #1137, when discussing a proposal that writing to syslog could be implemented as a `MakeWriter` implementation rather than as a `Subscribe` implementation, so that all the formatting logic from `tracing_subscriber::fmt` could be reused. See [here][1] for details. ## Solution This branch adds a new `make_writer_for` method to `MakeWriter`, taking a `Metadata`. Implementations can opt in to metadata-specific behavior by implementing this method. The method has a default implementation that just calls `self.make_writer()` and ignores the metadata, so it's only necessary to implement this when per-metadata behavior is required. This isn't a breaking change to existing implementations. There are a couple downsides to this approach: it's possible for callers to skip the metadata-specific behavior by calling `make_writer` rather than `make_writer_for`, and the impls for closures can't easily provide metadata-specific behavior. Since the upcoming release is going to be a breaking change anyway, we may want to just make the breaking change of having `MakeWriter::make_writer` _always_ take a `Metadata`, which solves these problems. However, that can't be backported to v0.1.x as easily. Additionally, that would mean that functions like `io::stdout` no longer implement `MakeWriter`; they would have to be wrapped in a wrapper type or closure that ignores metadata. [1]: https://github.com/tokio-rs/tracing/pull/1137#discussion_r542728604 Signed-off-by: Eliza Weisman --- tracing-subscriber/src/fmt/fmt_layer.rs | 71 ++++++++- tracing-subscriber/src/fmt/mod.rs | 5 + tracing-subscriber/src/fmt/writer.rs | 192 ++++++++++++++++++++++-- 3 files changed, 252 insertions(+), 16 deletions(-) diff --git a/tracing-subscriber/src/fmt/fmt_layer.rs b/tracing-subscriber/src/fmt/fmt_layer.rs index ab1806d4dd..12dfd8af00 100644 --- a/tracing-subscriber/src/fmt/fmt_layer.rs +++ b/tracing-subscriber/src/fmt/fmt_layer.rs @@ -740,7 +740,7 @@ where let ctx = self.make_ctx(ctx); if self.fmt_event.format_event(&ctx, &mut buf, event).is_ok() { - let mut writer = self.make_writer.make_writer(); + let mut writer = self.make_writer.make_writer_for(event.metadata()); let _ = io::Write::write_all(&mut writer, buf.as_bytes()); } @@ -913,11 +913,12 @@ impl Timings { #[cfg(test)] mod test { + use super::*; use crate::fmt::{ self, format::{self, test::MockTime, Format}, layer::Layer as _, - test::MockWriter, + test::{MockMakeWriter, MockWriter}, time, }; use crate::Registry; @@ -1110,4 +1111,70 @@ mod test { actual.as_str() ); } + + #[test] + fn make_writer_based_on_meta() { + lazy_static! { + static ref BUF1: Mutex> = Mutex::new(vec![]); + static ref BUF2: Mutex> = Mutex::new(vec![]); + } + struct MakeByTarget<'a> { + make_writer1: MockMakeWriter<'a>, + make_writer2: MockMakeWriter<'a>, + } + + impl<'a> MakeWriter for MakeByTarget<'a> { + type Writer = MockWriter<'a>; + + fn make_writer(&self) -> Self::Writer { + self.make_writer1.make_writer() + } + + fn make_writer_for(&self, meta: &Metadata<'_>) -> Self::Writer { + if meta.target() == "writer2" { + return self.make_writer2.make_writer(); + } + self.make_writer() + } + } + + let make_writer1 = MockMakeWriter::new(&BUF1); + let make_writer2 = MockMakeWriter::new(&BUF2); + + let make_writer = MakeByTarget { + make_writer1: make_writer1.clone(), + make_writer2: make_writer2.clone(), + }; + + let subscriber = crate::fmt::Subscriber::builder() + .with_writer(make_writer) + .with_level(false) + .with_target(false) + .with_ansi(false) + .with_timer(MockTime) + .with_span_events(FmtSpan::CLOSE) + .finish(); + + with_default(subscriber, || { + let span1 = tracing::info_span!("writer1_span", x = 42); + let _e = span1.enter(); + tracing::info!(target: "writer2", "hello writer2!"); + let span2 = tracing::info_span!(target: "writer2", "writer2_span"); + let _e = span2.enter(); + tracing::warn!(target: "writer1", "hello writer1!"); + }); + + let actual = sanitize_timings(make_writer1.get_string()); + assert_eq!( + "fake time writer1_span{x=42}:writer2_span: hello writer1!\n\ + fake time writer1_span{x=42}: close timing timing\n", + actual.as_str() + ); + let actual = sanitize_timings(make_writer2.get_string()); + assert_eq!( + "fake time writer1_span{x=42}: hello writer2!\n\ + fake time writer1_span{x=42}:writer2_span: close timing timing\n", + actual.as_str() + ); + } } diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index db6f2629e6..1bc8ef6fd2 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -1189,6 +1189,11 @@ mod test { pub(crate) fn buf(&self) -> MutexGuard<'a, Vec> { self.buf.lock().unwrap() } + + pub(crate) fn get_string(&self) -> String { + String::from_utf8(self.buf.lock().unwrap().clone()) + .expect("subscriber must write valid UTF-8") + } } impl<'a> MakeWriter for MockMakeWriter<'a> { diff --git a/tracing-subscriber/src/fmt/writer.rs b/tracing-subscriber/src/fmt/writer.rs index d437e5f5dc..ed7c45e4a2 100644 --- a/tracing-subscriber/src/fmt/writer.rs +++ b/tracing-subscriber/src/fmt/writer.rs @@ -1,9 +1,11 @@ //! Abstractions for creating [`io::Write`] instances. //! //! [`io::Write`]: https://doc.rust-lang.org/std/io/trait.Write.html - -use io::Write; -use std::{fmt::Debug, io}; +use std::{ + fmt::Debug, + io::{self, Write}, +}; +use tracing_core::Metadata; /// A type that can create [`io::Write`] instances. /// @@ -13,12 +15,75 @@ use std::{fmt::Debug, io}; /// This trait is already implemented for function pointers and immutably-borrowing closures that /// return an instance of [`io::Write`], such as [`io::stdout`] and [`io::stderr`]. /// -/// [`io::Write`]: https://doc.rust-lang.org/std/io/trait.Write.html -/// [`fmt::Subscriber`]: ../../fmt/struct.Subscriber.html -/// [`fmt::Layer`]: ../../fmt/struct.Layer.html -/// [`Event`]: https://docs.rs/tracing-core/0.1.5/tracing_core/event/struct.Event.html -/// [`io::stdout`]: https://doc.rust-lang.org/std/io/fn.stdout.html -/// [`io::stderr`]: https://doc.rust-lang.org/std/io/fn.stderr.html +/// The [`MakeWriter::make_writer_for`] method takes [`Metadata`] describing a +/// span or event and returns a writer. `MakeWriter`s can optionally provide +/// implementations of this method with behaviors that differ based on the span +/// or event being written. For example, events at different [levels] might be +/// written to different output streams, or data from different [targets] might +/// be written to separate log files. When the `MakeWriter` has no custom +/// behavior based on metadata, the default implementation of `make_writer_for` +/// simply calls `self.make_writer()`, ignoring the metadata. Therefore, when +/// metadata _is_ available, callers should prefer to call `make_writer_for`, +/// passing in that metadata, so that the `MakeWriter` implementation can choose +/// the appropriate behavior. +/// +/// # Examples +/// +/// The simplest usage is to pass in a named function that returns a writer. For +/// example, to log all events to stderr, we could write: +/// ``` +/// let subscriber = tracing_subscriber::fmt() +/// .with_writer(std::io::stderr) +/// .finish(); +/// # drop(subscriber); +/// ``` +/// +/// Any function that returns a writer can be used: +/// +/// ``` +/// fn make_my_great_writer() -> impl std::io::Write { +/// // ... +/// # std::io::stdout() +/// } +/// +/// let subscriber = tracing_subscriber::fmt() +/// .with_writer(make_my_great_writer) +/// .finish(); +/// # drop(subscriber); +/// ``` +/// +/// A closure can be used to introduce arbitrary logic into how the writer is +/// created. Consider the (admittedly rather silly) example of sending every 5th +/// event to stderr, and all other events to stdout: +/// +/// ``` +/// use std::io; +/// use std::sync::atomic::{AtomicUsize, Ordering::Relaxed}; +/// +/// let n = AtomicUsize::new(0); +/// let subscriber = tracing_subscriber::fmt() +/// .with_writer(move || -> Box { +/// if n.fetch_add(1, Relaxed) % 5 == 0 { +/// Box::new(io::stderr()) +/// } else { +/// Box::new(io::stdout()) +/// } +/// }) +/// .finish(); +/// # drop(subscriber); +/// ``` +/// +/// [`io::Write`]: std::io::Write +/// [`fmt::Collector`]: super::super::fmt::Collector +/// [`fmt::Subscriber`]: super::super::fmt::Subscriber +/// [`Event`]: tracing_core::event::Event +/// [`io::stdout`]: std::io::stdout() +/// [`io::stderr`]: std::io::stderr() +/// [mutex]: std::sync::Mutex +/// [`MakeWriter::make_writer_for`]: MakeWriter::make_writer_for +/// [`Metadata`]: tracing_core::Metadata +/// [levels]: tracing_core::Level +/// [targets]: tracing_core::Metadata::target pub trait MakeWriter { /// The concrete [`io::Write`] implementation returned by [`make_writer`]. /// @@ -36,11 +101,100 @@ pub trait MakeWriter { /// [`MakeWriter`] to improve performance. /// /// [`Writer`]: #associatedtype.Writer - /// [`fmt::Layer`]: ../../fmt/struct.Layer.html - /// [`fmt::Subscriber`]: ../../fmt/struct.Subscriber.html - /// [`io::Write`]: https://doc.rust-lang.org/std/io/trait.Write.html - /// [`MakeWriter`]: trait.MakeWriter.html + /// [`fmt::Layer`]: crate::fmt::Layer + /// [`fmt::Subscriber`]: crate::fmt::Subscriber + /// [`io::Write`]: std::io::Write fn make_writer(&self) -> Self::Writer; + + /// Returns a [`Writer`] for writing data from the span or event described + /// by the provided [`Metadata`]. + /// + /// By default, this calls [`self.make_writer()`][make_writer], ignoring + /// the provided metadata, but implementations can override this to provide + /// metadata-specific behaviors. + /// + /// This method allows `MakeWriter` implementations to implement different + /// behaviors based on the span or event being written. The `MakeWriter` + /// type might return different writers based on the provided metadata, or + /// might write some values to the writer before or after providing it to + /// the caller. + /// + /// For example, we might want to write data from spans and events at the + /// [`ERROR`] and [`WARN`] levels to `stderr`, and data from spans or events + /// at lower levels to stdout: + /// + /// ``` + /// use std::io::{self, Stdout, Stderr}; + /// use tracing_subscriber::fmt::writer::MakeWriter; + /// use tracing_core::{Metadata, Level}; + /// + /// pub struct MyMakeWriter {} + /// + /// /// A lock on either stdout or stderr, depending on the verbosity level + /// /// of the event being written. + /// pub enum Stdio { + /// Stdout(Stdout), + /// Stderr(Stderr), + /// } + /// + /// impl io::Write for Stdio { + /// fn write(&mut self, buf: &[u8]) -> io::Result { + /// match self { + /// Stdio::Stdout(io) => io.write(buf), + /// Stdio::Stderr(io) => io.write(buf), + /// } + /// } + /// + /// fn write_all(&mut self, buf: &[u8]) -> io::Result<()> { + /// // ... + /// # match self { + /// # Stdio::Stdout(io) => io.write_all(buf), + /// # Stdio::Stderr(io) => io.write_all(buf), + /// # } + /// } + /// + /// fn flush(&mut self) -> io::Result<()> { + /// // ... + /// # match self { + /// # Stdio::Stdout(io) => io.flush(), + /// # Stdio::Stderr(io) => io.flush(), + /// # } + /// } + /// } + /// + /// impl MakeWriter for MyMakeWriter { + /// type Writer = Stdio; + /// + /// fn make_writer(&self) -> Self::Writer { + /// // We must have an implementation of `make_writer` that makes + /// // a "default" writer without any configuring metadata. Let's + /// // just return stdout in that case. + /// Stdio::Stdout(io::stdout()) + /// } + /// + /// fn make_writer_for(&self, meta: &Metadata<'_>) -> Self::Writer { + /// // Here's where we can implement our special behavior. We'll + /// // check if the metadata's verbosity level is WARN or ERROR, + /// // and return stderr in that case. + /// if meta.level() <= &Level::WARN { + /// return Stdio::Stderr(io::stderr()); + /// } + /// + /// // Otherwise, we'll return stdout. + /// Stdio::Stdout(io::stdout()) + /// } + /// } + /// ``` + /// + /// [`Writer`]: MakeWriter::Writer + /// [`Metadata`]: tracing_core::Metadata + /// [make_writer]: MakeWriter::make_writer + /// [`WARN`]: tracing_core::Level::WARN + /// [`ERROR`]: tracing_core::Level::ERROR + fn make_writer_for(&self, meta: &Metadata<'_>) -> Self::Writer { + let _ = meta; + self.make_writer() + } } impl MakeWriter for F @@ -162,6 +316,10 @@ impl MakeWriter for BoxMakeWriter { fn make_writer(&self) -> Self::Writer { self.inner.make_writer() } + + fn make_writer_for(&self, meta: &Metadata<'_>) -> Self::Writer { + self.inner.make_writer_for(meta) + } } struct Boxed(M); @@ -174,7 +332,13 @@ where type Writer = Box; fn make_writer(&self) -> Self::Writer { - Box::new(self.0.make_writer()) + let w = self.0.make_writer(); + Box::new(w) + } + + fn make_writer_for(&self, meta: &Metadata<'_>) -> Self::Writer { + let w = self.0.make_writer_for(meta); + Box::new(w) } }