Skip to content

Commit

Permalink
subscriber: if error occurs when formatting event, write error to Wri…
Browse files Browse the repository at this point in the history 
…ter (#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>
  • Loading branch information
@bryangarza @hawkw @davidbarsky
3 people committed Aug 24, 2022
1 parent 0afab2f commit fd712ac
Show file tree
Hide file tree
Showing 2 changed files with 136 additions and 1 deletion.
115 changes: 114 additions & 1 deletion tracing-subscriber/src/fmt/fmt_subscriber.rs
View file
Expand Up @@ -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)>,
}

Expand Down Expand Up @@ -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,
}
}
Expand Down Expand Up @@ -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,
}
}
Expand Down Expand Up @@ -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,
}
Expand Down Expand Up @@ -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,
}
Expand All @@ -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::Layer` 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.
Expand Down Expand Up @@ -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,
}
Expand Down Expand Up @@ -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,
}
}
Expand All @@ -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,
}
}
Expand Down Expand Up @@ -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,
}
}
Expand All @@ -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,
}
}
Expand Down Expand Up @@ -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,
}
}
Expand Down Expand Up @@ -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,
}
}
Expand Down Expand Up @@ -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,
}
}
Expand All @@ -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,
}
}
Expand Down Expand Up @@ -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
);
}
}

Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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();
Expand Down
22 changes: 22 additions & 0 deletions tracing-subscriber/src/fmt/mod.rs
View file
Expand Up @@ -463,6 +463,7 @@ impl Default for CollectorBuilder {
filter: Collector::DEFAULT_MAX_LEVEL,
inner: Default::default(),
}
.log_internal_errors(true)
}
}

Expand Down Expand Up @@ -619,6 +620,27 @@ where
}
}

/// Sets whether to write errors from [`FormatEvent`] to the writer.
/// Defaults to true.
///
/// By default, `fmt::Layer` 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,
Expand Down

0 comments on commit fd712ac

Please sign in to comment.