From 45b5aac486dc487096c088e4759ad207ba576bf5 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] 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..ec24e7ceb8 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::Subscriber::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::Subscriber::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 1fb57296c7..c5432439b5 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,