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. tokio-rs/valuable#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 <eliza@buoyant.io>
Co-authored-by: David Barsky <me@davidbarsky.com>

Author: 3 people

tracing-subscriber/src/fmt/fmt_subscriber.rs

@@ -68,6 +68,7 @@ pub struct Subscriber<C, N = format::DefaultFields, E = format::Format, W = fn()
     fmt_event: E,
     fmt_span: format::FmtSpanConfig,
     is_ansi: bool,
+    log_internal_errors: bool,
     _inner: PhantomData<fn(C)>,
 }
 
@@ -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<C, N, E, W> Subscriber<C, N, E, W> {
             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<C, N, E, W> Subscriber<C, N, E, W> {
             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<C, N, E, W> Subscriber<C, N, E, W> {
         }
     }
 
+    /// 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<C, N, E, W> Subscriber<C, N, E, W> {
             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<C, N, E, W> Subscriber<C, N, E, W> {
             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<C, N, E, W> Subscriber<C, N, E, W> {
             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<C> Default for Subscriber<C> {
             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();

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<N, format::Format<L, T>, 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,