From f880d1e8b86dd114b0be4cd5612573141fcff409 Mon Sep 17 00:00:00 2001 From: Lily Ballard Date: Fri, 28 Jan 2022 09:50:17 -0800 Subject: [PATCH 1/2] subscriber: Add `SubscriberBuilder`/`Layer` accessors (#1871) `SubscriberBuilder`s and `Layer`s configured with custom event/field formatters do not provide any means of accessing or mutating those formatters. Any configuration that needs to be done must be done before setting them on the builder/layer. This is frustrating as it makes it difficult to provide a pre-configured API akin to `tracing_subscriber::fmt()` along with accessors like `.compact()` that modify the formatter. Add accessors `.map_event_format()` and `.map_fmt_fields()` to `SubscriberBuilder` and `Layer` that map the existing formatter through a closure. This allows the closure to modify it or to derive a new formatter from it with a different type. Also add a `.map_writer()` method that does the same thing for the `MakeWriter`, to round out the accessors for the various type parameters. The filter type is currently restricted to just `LevelFilter` or `EnvFilter` and so this does not add a corresponding `.map_filter()`. That can be added later if we add the ability to attach arbitrary filters. Also fix some minor docs issues that were spotted as part of implementing this. Fixes #1756 --- tracing-subscriber/src/fmt/fmt_subscriber.rs | 92 ++++++++++++++++ tracing-subscriber/src/fmt/mod.rs | 107 +++++++++++++++++-- 2 files changed, 193 insertions(+), 6 deletions(-) diff --git a/tracing-subscriber/src/fmt/fmt_subscriber.rs b/tracing-subscriber/src/fmt/fmt_subscriber.rs index fbedbc446b..acd299a8e4 100644 --- a/tracing-subscriber/src/fmt/fmt_subscriber.rs +++ b/tracing-subscriber/src/fmt/fmt_subscriber.rs @@ -120,6 +120,35 @@ where _inner: self._inner, } } + + /// Updates the event formatter by applying a function to the existing event formatter. + /// + /// This sets the event formatter that the subscriber being built will use to record fields. + /// + /// # Examples + /// + /// Updating an event formatter: + /// + /// ```rust + /// let subscriber = tracing_subscriber::fmt::subscriber() + /// .map_event_format(|e| e.compact()); + /// # // this is necessary for type inference. + /// # use tracing_subscriber::Subscribe as _; + /// # let _ = subscriber.with_collector(tracing_subscriber::registry::Registry::default()); + /// ``` + pub fn map_event_format(self, f: impl FnOnce(E) -> E2) -> Subscriber + where + E2: FormatEvent + 'static, + { + Subscriber { + fmt_fields: self.fmt_fields, + fmt_event: f(self.fmt_event), + fmt_span: self.fmt_span, + make_writer: self.make_writer, + is_ansi: self.is_ansi, + _inner: self._inner, + } + } } // This needs to be a separate impl block because they place different bounds on the type parameters. @@ -249,6 +278,39 @@ impl Subscriber { ..self } } + + /// Updates the [`MakeWriter`] by applying a function to the existing [`MakeWriter`]. + /// + /// This sets the [`MakeWriter`] that the subscriber being built will use to write events. + /// + /// # Examples + /// + /// Redirect output to stderr if level is <= WARN: + /// + /// ```rust + /// use tracing::Level; + /// use tracing_subscriber::fmt::{self, writer::MakeWriterExt}; + /// + /// let stderr = std::io::stderr.with_max_level(Level::WARN); + /// let subscriber = fmt::subscriber() + /// .map_writer(move |w| stderr.or_else(w)); + /// # // this is necessary for type inference. + /// # use tracing_subscriber::Subscribe as _; + /// # let _ = subscriber.with_collector(tracing_subscriber::registry::Registry::default()); + /// ``` + pub fn map_writer(self, f: impl FnOnce(W) -> W2) -> Subscriber + where + W2: for<'writer> MakeWriter<'writer> + 'static, + { + Subscriber { + fmt_fields: self.fmt_fields, + fmt_event: self.fmt_event, + fmt_span: self.fmt_span, + is_ansi: self.is_ansi, + make_writer: f(self.make_writer), + _inner: self._inner, + } + } } impl Subscriber, W> @@ -531,6 +593,36 @@ impl Subscriber { _inner: self._inner, } } + + /// Updates the field formatter by applying a function to the existing field formatter. + /// + /// This sets the field formatter that the subscriber being built will use to record fields. + /// + /// # Examples + /// + /// Updating a field formatter: + /// + /// ```rust + /// use tracing_subscriber::field::MakeExt; + /// let subscriber = tracing_subscriber::fmt::subscriber() + /// .map_fmt_fields(|f| f.debug_alt()); + /// # // this is necessary for type inference. + /// # use tracing_subscriber::Subscribe as _; + /// # let _ = subscriber.with_collector(tracing_subscriber::registry::Registry::default()); + /// ``` + pub fn map_fmt_fields(self, f: impl FnOnce(N) -> N2) -> Subscriber + where + N2: for<'writer> FormatFields<'writer> + 'static, + { + Subscriber { + fmt_event: self.fmt_event, + fmt_fields: f(self.fmt_fields), + fmt_span: self.fmt_span, + make_writer: self.make_writer, + is_ansi: self.is_ansi, + _inner: self._inner, + } + } } impl Default for Subscriber { diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index 2230362d0e..2821f57d2b 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -892,8 +892,9 @@ impl CollectorBuilder { /// Sets the maximum [verbosity level] that will be enabled by the /// collector. /// - /// If the max level has already been set, this replaces that configuration - /// with the new maximum level. + /// If the max level has already been set, or a [`EnvFilter`] was added by + /// [`with_env_filter`], this replaces that configuration with the new + /// maximum level. /// /// # Examples /// @@ -915,7 +916,8 @@ impl CollectorBuilder { /// .finish(); /// ``` /// [verbosity level]: tracing_core::Level - /// [`EnvFilter`]: super::filter::EnvFilter + /// [`EnvFilter`]: struct@crate::filter::EnvFilter + /// [`with_env_filter`]: fn@Self::with_env_filter pub fn with_max_level( self, filter: impl Into, @@ -972,8 +974,26 @@ impl CollectorBuilder { } } - /// Sets the function that the collector being built should use to format - /// events that occur. + /// Sets the [event formatter][`FormatEvent`] that the subscriber being built + /// will use to format events that occur. + /// + /// The event formatter may be any type implementing the [`FormatEvent`] + /// trait, which is implemented for all functions taking a [`FmtContext`], a + /// [`Writer`], and an [`Event`]. + /// + /// # Examples + /// + /// Setting a type implementing [`FormatEvent`] as the formatter: + /// + /// ```rust + /// use tracing_subscriber::fmt::format; + /// + /// let subscriber = tracing_subscriber::fmt() + /// .event_format(format().compact()) + /// .finish(); + /// ``` + /// + /// [`Writer`]: struct@self::format::Writer pub fn event_format(self, fmt_event: E2) -> CollectorBuilder where E2: FormatEvent + 'static, @@ -1000,7 +1020,6 @@ impl CollectorBuilder { /// .with_writer(io::stderr) /// .init(); /// ``` - /// pub fn with_writer(self, make_writer: W2) -> CollectorBuilder where W2: for<'writer> MakeWriter<'writer> + 'static, @@ -1041,6 +1060,82 @@ impl CollectorBuilder { inner: self.inner.with_writer(TestWriter::default()), } } + + /// Updates the event formatter by applying a function to the existing event formatter. + /// + /// This sets the event formatter that the collector being built will use to record fields. + /// + /// # Examples + /// + /// Updating an event formatter: + /// + /// ```rust + /// let subscriber = tracing_subscriber::fmt() + /// .map_event_format(|e| e.compact()) + /// .finish(); + /// ``` + pub fn map_event_format(self, f: impl FnOnce(E) -> E2) -> CollectorBuilder + where + E2: FormatEvent + 'static, + N: for<'writer> FormatFields<'writer> + 'static, + W: for<'writer> MakeWriter<'writer> + 'static, + { + CollectorBuilder { + filter: self.filter, + inner: self.inner.map_event_format(f), + } + } + + /// Updates the field formatter by applying a function to the existing field formatter. + /// + /// This sets the field formatter that the subscriber being built will use to record fields. + /// + /// # Examples + /// + /// Updating a field formatter: + /// + /// ```rust + /// use tracing_subscriber::field::MakeExt; + /// let subscriber = tracing_subscriber::fmt() + /// .map_fmt_fields(|f| f.debug_alt()) + /// .finish(); + /// ``` + pub fn map_fmt_fields(self, f: impl FnOnce(N) -> N2) -> CollectorBuilder + where + N2: for<'writer> FormatFields<'writer> + 'static, + { + CollectorBuilder { + filter: self.filter, + inner: self.inner.map_fmt_fields(f), + } + } + + /// Updates the [`MakeWriter`] by applying a function to the existing [`MakeWriter`]. + /// + /// This sets the [`MakeWriter`] that the subscriber being built will use to write events. + /// + /// # Examples + /// + /// Redirect output to stderr if level is <= WARN: + /// + /// ```rust + /// use tracing::Level; + /// use tracing_subscriber::fmt::{self, writer::MakeWriterExt}; + /// + /// let stderr = std::io::stderr.with_max_level(Level::WARN); + /// let collector = tracing_subscriber::fmt() + /// .map_writer(move |w| stderr.or_else(w)) + /// .finish(); + /// ``` + pub fn map_writer(self, f: impl FnOnce(W) -> W2) -> CollectorBuilder + where + W2: for<'writer> MakeWriter<'writer> + 'static, + { + CollectorBuilder { + filter: self.filter, + inner: self.inner.map_writer(f), + } + } } /// Install a global tracing collector that listens for events and From ca3c05b8c3de368e1e15ef30985fbe033d3982af Mon Sep 17 00:00:00 2001 From: Bryan Garza <1396101+bryangarza@users.noreply.github.com> Date: Mon, 25 Jul 2022 09:44:27 -0700 Subject: [PATCH 2/2] subscriber: if error occurs when formatting event, write error to Writer (#2102) Motivation: When `Format_event::format_event(...)` returns an error, we are currently silently dropping that Event. https://github.com/tokio-rs/valuable/issues/88 explains one such case in which this was encountered (due to a bug in valuable-serde). We want to be made aware whenever an Event is dropped. Solution: Write to the Writer with an error message to let the user know that we were unable to format a specific event. If writing to the Writer fails, we fall back to writing to stderr. We are not emitting an actual tracing Event, to avoid the risk of a cycle (the new Event could trigger the same formatting error again). Resolves #1965. Co-authored-by: Eliza Weisman Co-authored-by: David Barsky --- tracing-subscriber/src/fmt/fmt_subscriber.rs | 115 ++++++++++++++++++- tracing-subscriber/src/fmt/mod.rs | 22 ++++ 2 files changed, 136 insertions(+), 1 deletion(-) diff --git a/tracing-subscriber/src/fmt/fmt_subscriber.rs b/tracing-subscriber/src/fmt/fmt_subscriber.rs index acd299a8e4..9887b711ff 100644 --- a/tracing-subscriber/src/fmt/fmt_subscriber.rs +++ b/tracing-subscriber/src/fmt/fmt_subscriber.rs @@ -68,6 +68,7 @@ pub struct Subscriber, } @@ -117,6 +118,7 @@ where fmt_span: self.fmt_span, make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -146,6 +148,7 @@ where fmt_span: self.fmt_span, make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -181,6 +184,7 @@ impl Subscriber { fmt_event: self.fmt_event, fmt_span: self.fmt_span, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, make_writer, _inner: self._inner, } @@ -264,6 +268,7 @@ impl Subscriber { fmt_event: self.fmt_event, fmt_span: self.fmt_span, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, make_writer: TestWriter::default(), _inner: self._inner, } @@ -279,6 +284,24 @@ impl Subscriber { } } + /// Sets whether to write errors from [`FormatEvent`] to the writer. + /// Defaults to true. + /// + /// By default, `fmt::Subscriber` will write any `FormatEvent`-internal errors to + /// the writer. These errors are unlikely and will only occur if there is a + /// bug in the `FormatEvent` implementation or its dependencies. + /// + /// If writing to the writer fails, the error message is printed to stderr + /// as a fallback. + /// + /// [`FormatEvent`]: crate::fmt::FormatEvent + pub fn log_internal_errors(self, log_internal_errors: bool) -> Self { + Self { + log_internal_errors, + ..self + } + } + /// Updates the [`MakeWriter`] by applying a function to the existing [`MakeWriter`]. /// /// This sets the [`MakeWriter`] that the subscriber being built will use to write events. @@ -307,6 +330,7 @@ impl Subscriber { fmt_event: self.fmt_event, fmt_span: self.fmt_span, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, make_writer: f(self.make_writer), _inner: self._inner, } @@ -338,6 +362,7 @@ where fmt_span: self.fmt_span, make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -350,6 +375,7 @@ where fmt_span: self.fmt_span.without_time(), make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -481,6 +507,7 @@ where fmt_span: self.fmt_span, make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -495,6 +522,7 @@ where fmt_span: self.fmt_span, make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -524,6 +552,7 @@ where make_writer: self.make_writer, // always disable ANSI escapes in JSON mode! is_ansi: false, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -590,6 +619,7 @@ impl Subscriber { fmt_span: self.fmt_span, make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -620,6 +650,7 @@ impl Subscriber { fmt_span: self.fmt_span, make_writer: self.make_writer, is_ansi: self.is_ansi, + log_internal_errors: self.log_internal_errors, _inner: self._inner, } } @@ -633,6 +664,7 @@ impl Default for Subscriber { fmt_span: format::FmtSpanConfig::default(), make_writer: io::stdout, is_ansi: cfg!(feature = "ansi"), + log_internal_errors: false, _inner: PhantomData, } } @@ -752,6 +784,11 @@ where { fields.was_ansi = self.is_ansi; extensions.insert(fields); + } else { + eprintln!( + "[tracing-subscriber] Unable to format the following event, ignoring: {:?}", + attrs + ); } } @@ -898,7 +935,20 @@ where .is_ok() { let mut writer = self.make_writer.make_writer_for(event.metadata()); - let _ = io::Write::write_all(&mut writer, buf.as_bytes()); + let res = io::Write::write_all(&mut writer, buf.as_bytes()); + if self.log_internal_errors { + if let Err(e) = res { + eprintln!("[tracing-subscriber] Unable to write an event to the Writer for this Subscriber! Error: {}\n", e); + } + } + } else if self.log_internal_errors { + let err_msg = format!("Unable to format the following event. Name: {}; Fields: {:?}\n", + event.metadata().name(), event.fields()); + let mut writer = self.make_writer.make_writer_for(event.metadata()); + let res = io::Write::write_all(&mut writer, err_msg.as_bytes()); + if let Err(e) = res { + eprintln!("[tracing-subscriber] Unable to write an \"event formatting error\" to the Writer for this Subscriber! Error: {}\n", e); + } } buf.clear(); @@ -1197,6 +1247,69 @@ mod test { re.replace_all(s.as_str(), "timing").to_string() } + #[test] + fn format_error_print_to_stderr() { + struct AlwaysError; + + impl std::fmt::Debug for AlwaysError { + fn fmt(&self, _f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { + Err(std::fmt::Error) + } + } + + let make_writer = MockMakeWriter::default(); + let subscriber = crate::fmt::Collector::builder() + .with_writer(make_writer.clone()) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime) + .finish(); + + with_default(subscriber, || { + tracing::info!(?AlwaysError); + }); + let actual = sanitize_timings(make_writer.get_string()); + + // Only assert the start because the line number and callsite may change. + let expected = concat!( + "Unable to format the following event. Name: event ", + file!(), + ":" + ); + assert!( + actual.as_str().starts_with(expected), + "\nactual = {}\nshould start with expected = {}\n", + actual, + expected + ); + } + + #[test] + fn format_error_ignore_if_log_internal_errors_is_false() { + struct AlwaysError; + + impl std::fmt::Debug for AlwaysError { + fn fmt(&self, _f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { + Err(std::fmt::Error) + } + } + + let make_writer = MockMakeWriter::default(); + let subscriber = crate::fmt::Collector::builder() + .with_writer(make_writer.clone()) + .with_level(false) + .with_ansi(false) + .with_timer(MockTime) + .log_internal_errors(false) + .finish(); + + with_default(subscriber, || { + tracing::info!(?AlwaysError); + }); + let actual = sanitize_timings(make_writer.get_string()); + assert_eq!("", actual.as_str()); + } + #[test] fn synthesize_span_none() { let make_writer = MockMakeWriter::default(); diff --git a/tracing-subscriber/src/fmt/mod.rs b/tracing-subscriber/src/fmt/mod.rs index 2821f57d2b..936ecd6400 100644 --- a/tracing-subscriber/src/fmt/mod.rs +++ b/tracing-subscriber/src/fmt/mod.rs @@ -463,6 +463,7 @@ impl Default for CollectorBuilder { filter: Collector::DEFAULT_MAX_LEVEL, inner: Default::default(), } + .log_internal_errors(true) } } @@ -619,6 +620,27 @@ where } } + /// Sets whether to write errors from [`FormatEvent`] to the writer. + /// Defaults to true. + /// + /// By default, `fmt::Collector` will write any `FormatEvent`-internal errors to + /// the writer. These errors are unlikely and will only occur if there is a + /// bug in the `FormatEvent` implementation or its dependencies. + /// + /// If writing to the writer fails, the error message is printed to stderr + /// as a fallback. + /// + /// [`FormatEvent`]: crate::fmt::FormatEvent + pub fn log_internal_errors( + self, + log_internal_errors: bool, + ) -> CollectorBuilder, F, W> { + CollectorBuilder { + inner: self.inner.log_internal_errors(log_internal_errors), + ..self + } + } + /// Sets whether or not an event's target is displayed. pub fn with_target( self,