subscriber: if error occurs when formatting event, write error to Writer

[bryangarza]

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.

Testing

Added unit tests in fmt_layer.rs.

I also tested using @jaskij's repo: https://github.com/jaskij/valuable-serde-bug-reproduction.

diff --git a/not_working/Cargo.toml b/not_working/Cargo.toml
index 8907c81..9459e33 100644
--- a/not_working/Cargo.toml
+++ b/not_working/Cargo.toml
@@ -11,5 +11,5 @@ serde_json = "1.0.79"
 valuable = "0.1.0"
 valuable-derive = "0.1.0"
 valuable-serde = "0.1.0"
-tracing = "0.1.31"
-tracing-subscriber = { version = "0.3.9", features = ["json", "valuable"] }
+tracing = { path = "../../tracing/tracing" }
+tracing-subscriber = { path = "../../tracing/tracing-subscriber", features = ["json", "valuable"] }

% cargo run --bin tracing
    Finished dev [unoptimized + debuginfo] target(s) in 1.41s
     Running `/local/home/garzbrya/code/rs/valuable-serde-bug-reproduction/target/debug/tracing`
Unable to format the following event. Name: event not_working/src/bin/tracing.rs:17; Fields: Iter { idxs: 0..1, fields: FieldSet { names: ["test"], callsite: Identifier(0x55ba2bde4008) } }

I tried adding a Span, which then panics (when debug_assertions=true):

    Finished dev [unoptimized + debuginfo] target(s) in 1.61s
     Running `/local/home/garzbrya/code/rs/valuable-serde-bug-reproduction/target/debug/tracing`
thread 'main' panicked at 'internal error: entered unreachable code: `valuable::Valuable` implementations should always serialize successfully, but an error occurred: asdf FOO', /local/home/garzbrya/code/rs/tracing/tracing-subscriber/src/fmt/format/json.rs:484:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

I think the Span case should be good enough (without addressing it in this PR)? I think anyone testing their code will hit the panic, because non-release builds do have debug_assertions=true by default.

Open Questions

Should I add a method to SubscriberBuilder to be able to enable/disable this behavior? If so, what should be the default, on or off?

Something like:

tracing_subscriber::fmt()
    .with_writer(std::io::stdout)
    .with_silence_errors(true) // This line
    .json()
    .init();

Edit: I did update the builder, in my second commit.

[jaskij]

I looked again at my code (albeit a quick look on mobile), and there's only info!, which is an event (exactly the same as the one you added), not a span.

[bryangarza]

Oh, yeah you're right. Will retest..

[hawkw]

This seems like a fine solution!

One thought, though, is that it would be really nice to be able to expose any actual error message as well. However, doing that would be a bit more complex. For all the text-based formatters, the error generated would just be a fmt::Error, which doesn't have any interesting information attached to it. On the other hand, when using the JSON formatter, we get a potentially more useful serde serialization error...which, unfortunately, is currently always just discarded and replaced with fmt::Error, discarding any information about the error:

tracing/tracing-subscriber/src/fmt/format/json.rs

Line 327 in 22b5873

visit().map_err(|_| fmt::Error)?;

We could potentially print that error information if we changed the approach so that it's the FormatEvent implementations that are responsible for printing the error instead. However, this would mean that any arbitrary user-provided FormatEvent implementations would have to remember to add that themselves, while in your approach, tracing-subscriber would always ensure that the error is printed. So, there's a tradeoff there that's worth thinking about.

A third solution is to change the FormatEvent trait to allow it to return any arbitrary error type, rather than hard-coding fmt::Error. This would permit the JSON formatter to return serialization errors directly. However, this would be a breaking API change, so we'd have to save that for tracing-subscriber 0.4...

[hawkw]

Some other things:

• It would be nice to have some kind of test for this in tracing-subscriber itself, rather than just in the @jaskij's reproduction. We could probably test this with just a type that has a manual fmt::Debug implementation that just always returns fmt::Error --- that way, we wouldn't need to rely on valuable to test the way tracing-subscriber::fmt handles errors...
• I think the builder option is probably a good idea? I would probably enable errors by default, I think.

[bryangarza]

Yeah @jaskij so if I test with a span, and debug_assertions=true, we get panic

diff --git a/not_working/src/bin/tracing.rs b/not_working/src/bin/tracing.rs
index 76a1799..7861533 100644
--- a/not_working/src/bin/tracing.rs
+++ b/not_working/src/bin/tracing.rs
@@ -2,7 +2,7 @@
 mod valuable_anyhow;

 use anyhow::anyhow;
-use tracing::info;
+use tracing::{info, info_span};
 use valuable::Valuable;
 use valuable_anyhow::ValuableAnyhow;

@@ -14,5 +14,6 @@ fn main() {

     let err = anyhow!("asdf FOO");
     let va = ValuableAnyhow::from(err);
-    info!(test=va.as_value());
+    // info!(test=va.as_value());
+    info_span!("foo", test=va.as_value());
 }

thread 'main' panicked at 'internal error: entered unreachable code: `valuable::Valuable` implementations should always serialize successfully, but an error occurred: asdf FOO', /local/home/garzbrya/code/rs/tracing/tracing-subscriber/src/fmt/format/json.rs:484:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Not sure if that is good enough for the Span case, since everyone is probably building with debug_assertions=true during development (enabled by default in non-release builds)

[bryangarza]

@hawkw Regarding your comment about being able to actually see the original error (since we are just losing it due to fmt::Error), I do think that changing the return type to allow any arbitrary error type could be the best overall solution, because we can then take that error and use it from within tracing-subscriber itself, like we are doing in this PR. And then someone that is writing a FormatEvent impl doesn't have to deal with the error themselves.

Since that's a breaking change, one thing we could do in the meantime (maybe) would be to print the error directly for now:

 visit().map_err(|e| {
    // we can also add event.name here etc I think
    eprintln("Unable to serialize to JSON due to: {:?}", e);
    fmt::Error
})?; 

[bryangarza]

I amended the original commit (wanted to correct the commit message)

[bryangarza]

@hawkw created #2103 to track breaking change to FormatEvent, if we wanna do that separately.

[bryangarza]

Ready for a second review :)

[davidbarsky]

I don't think that we should make this a toggle; this should probably be on by-default. It's not a breaking change, and if people are encountered this issue in the wild, I'd rather have subscriber break their log ingestion system loudly.

[hawkw]

I don't think that we should make this a toggle; this should probably be on by-default. It's not a breaking change, and if people are encountered this issue in the wild, I'd rather have subscriber break their log ingestion system loudly.

I think it should definitely be possible to turn it off, but I'm fine with making it default to on.

[davidbarsky]

I think it should definitely be possible to turn it off, but I'm fine with making it default to on.

Fair enough! In that case, the builder option should probably be renamed to something more descriptive. maybe .with_internal_error_logging, but I can see that being too wordy.

[bryangarza]

I think it should definitely be possible to turn it off, but I'm fine with making it default to on.

Fair enough! In that case, the builder option should probably be renamed to something more descriptive. maybe .with_internal_error_logging, but I can see that being too wordy.

I renamed to silence_internal_errors now 👍

[bryangarza]

Renamed to log_internal_errors as per our Discord convo in #tracing-dev

All feedback up to this point has been addressed :)