Errors are silently discarded if tracing event gets converted to a message and in breadcrumbs

[thomaseizinger]

Environment

• Version 0.34.0

Steps to Reproduce

1. Create an event-filter that maps WARN logs to Sentry events: https://github.com/firezone/firezone/blob/51d92265f4163967c0045f67495954515da15c62/rust/logging/src/lib.rs#L102-L115
2. Attach errors as &dyn std::error::Error in a WARN log as advised in the documentation: https://github.com/firezone/firezone/blob/51d92265f4163967c0045f67495954515da15c62/rust/gateway/src/eventloop.rs#L80

Expected Result

To receive a Sentry event that contains the error.

Actual Result

A Sentry event that only contains the log message but not the error:

---

I've been digging through the source code here and the problem is that when a tracing event gets converted to a Sentry event, all fields apart from what is prefixed with tags. gets silently dropped:

sentry-rust/sentry-tracing/src/converters.rs

Lines 212 to 230 in a1481d4

	/// Creates an [`Event`] from a given [`tracing_core::Event`]
	pub fn event_from_event<'context, S>(
	event: &tracing_core::Event,
	ctx: impl Into<Option<Context<'context, S>>>,
	) -> Event<'static>
	where
	S: Subscriber + for<'a> LookupSpan<'a>,
	{
	let (message, mut visitor) = extract_event_data_with_context(event, ctx.into());
	Event {
	logger: Some(event.metadata().target().to_owned()),
	level: convert_tracing_level(event.metadata().level()),
	message,
	tags: tags_from_event(&mut visitor.json_values),
	contexts: contexts_from_event(event, visitor.json_values),
	..Default::default()
	}
	}

This is pretty confusing because the documentation clearly states:

To track error structs, assign a reference to error trait object as field in one of the logging macros. By convention, it is recommended to use the ERROR level and assign it to a field called error, although the integration will also work with all other levels and field names.

What is perhaps missing here is a foot-note that it will work with all levels as long as you configure an event filter that converts the event to a sentry exception! However, instead of fixing the documentation here, I think the proper fix is to actually make this work the way the documentation states and attach the exception to the message, even if the log level is not ERROR.

[thomaseizinger]

However, instead of fixing the documentation here, I think the proper fix is to actually make this work the way the documentation states and attach the exception to the message, even if the log level is not ERROR.

I tried to fix this but realised that this essentially just makes "messages" and "exceptions" the same?

[thomaseizinger]

However, instead of fixing the documentation here, I think the proper fix is to actually make this work the way the documentation states and attach the exception to the message, even if the log level is not ERROR.

I tried to fix this but realised that this essentially just makes "messages" and "exceptions" the same?

The other issue here is that the field does not become a context because it is recorded in the FieldVisitor as an exceptions and therefore not grouped with the other fields.

[DoumanAsh]

I think everything is geared towards errors being treated as exceptions hence non-exception events are treated as informational
I usually use empty span fields to record error information and keep context via https://docs.rs/sentry-tracing/0.34.0/sentry_tracing/struct.SentryLayer.html#method.enable_span_attributes

[thomaseizinger]

This is also a problem for breadcrumbs. There, any recorded "errors" on the way are also discarded because only the json_values are captured, see

sentry-rust/sentry-tracing/src/converters.rs

Lines 142 to 153 in a1481d4

	/// Creates a [`Breadcrumb`] from a given [`tracing_core::Event`]
	pub fn breadcrumb_from_event(event: &tracing_core::Event) -> Breadcrumb {
	let (message, visitor) = extract_event_data(event);
	Breadcrumb {
	category: Some(event.metadata().target().to_owned()),
	ty: "log".into(),
	level: convert_tracing_level(event.metadata().level()),
	message,
	data: visitor.json_values,
	..Default::default()
	}
	}

.

The real foot-gun here is that this basically makes it really dangerous to apply a blanket rule of "we will just record all errors as Error within tracing". Arguably, that is what applications should do in order to preserve as much type-information as possible for as long as possible. Sentry discourages that because it will silently drop all of them unless they get reported as exceptions to Sentry.

[DoumanAsh]

You do not necessary need to record everything in error
As I mentioned you can use span's fields (initially initialized with tracing::field::Emtpy) and the fill it on demand

[thomaseizinger]

You do not necessary need to record everything in error

Why wouldn't I though? This is like saying: "You know need to pass fields to tracing, just format everything as a string". Yeah I can do that, but what is the point of using a library that supported structured logging then? I would like to record errors as std::error::Error and Sentry should walk through the source chain and display all of them.

[DoumanAsh]

I believe you're not listening to me
What I mean is that if you do not want to aggregate everything tracing::error! you can do it as follows:

#[tracing::insturment(fields(extr_error = tracing::field::Empy))]
fn my_work() {
   tracing::Span::current().record("extr_error", "whatever I want");
   tracing::error!("my error");
}

This is just suggestion if you want to make current layer work for you better
But otherwise you can continue with issue

[thomaseizinger]

Unless I am missing something, this doesn't solve the issue though, does it? I haven't tried it but from reading the code, the following should happen:

1. Errors set on the span are recorded as debug because SpanFieldVisitor doesn't override the default implementation of record_error.
2. Additional fields recorded in the span later ignore all std::error::Errors:

   sentry-rust/sentry-tracing/src/layer.rs

   Lines 270 to 272 in a1481d4

   	for (key, value) in data.json_values {
   	span.set_data(&key, value);
   	}

if you do not want to aggregate everything tracing::error!

What I want to do is record information in a tracing-idiomatic way without having to implement workarounds because sentry-tracing decides to silently drop certain fields.

[DoumanAsh]

This will work under assumption you use https://docs.rs/sentry-tracing/0.34.0/sentry_tracing/struct.SentryLayer.html#method.enable_span_attributes because it should attach span fields associated with the event (but not to breadcrumb)

But yes, it is not ideal that event doesn't record all non tag fields