Skip to content

feat(tracing): Improve structure for tracing errors #585

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 5 commits into from
May 25, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
3 changes: 3 additions & 0 deletions sentry-backtrace/src/trim.rs
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,8 @@ const WELL_KNOWN_SYS_MODULES: &[&str] = &[
// these are well-known library frames
"anyhow::",
"log::",
"tokio::",
"tracing_core::",
];

const WELL_KNOWN_BORDER_FRAMES: &[&str] = &[
Expand All @@ -24,6 +26,7 @@ const WELL_KNOWN_BORDER_FRAMES: &[&str] = &[
// well-known library frames
"anyhow::",
"<sentry_log::Logger as log::Log>::log",
"tracing_core::",
];

/// A helper function to trim a stacktrace.
Expand Down
5 changes: 5 additions & 0 deletions sentry-tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -12,10 +12,15 @@ Sentry integration for tracing and tracing-subscriber crates.
edition = "2021"
rust-version = "1.66"

[features]
default = []
backtrace = ["dep:sentry-backtrace"]

[dependencies]
sentry-core = { version = "0.31.2", path = "../sentry-core", features = ["client"] }
tracing-core = "0.1"
tracing-subscriber = { version = "0.3.1", default-features = false, features = ["std"] }
sentry-backtrace = { version = "0.31.2", path = "../sentry-backtrace", optional = true }

[dev-dependencies]
log = "0.4"
Expand Down
98 changes: 88 additions & 10 deletions sentry-tracing/src/converters.rs
Original file line number Diff line number Diff line change
@@ -1,7 +1,7 @@
use std::collections::BTreeMap;
use std::error::Error;

use sentry_core::protocol::{Event, Exception, Value};
use sentry_core::protocol::{Event, Exception, Mechanism, Thread, Value};
use sentry_core::{event_from_error, Breadcrumb, Level};
use tracing_core::field::{Field, Visit};
use tracing_core::{span, Subscriber};
Expand All @@ -18,6 +18,16 @@ fn convert_tracing_level(level: &tracing_core::Level) -> Level {
}
}

fn level_to_exception_type(level: &tracing_core::Level) -> &'static str {
match *level {
tracing_core::Level::TRACE => "tracing::trace!",
tracing_core::Level::DEBUG => "tracing::debug!",
tracing_core::Level::INFO => "tracing::info!",
tracing_core::Level::WARN => "tracing::warn!",
tracing_core::Level::ERROR => "tracing::error!",
}
}

/// Extracts the message and metadata from an event
fn extract_event_data(event: &tracing_core::Event) -> (Option<String>, FieldVisitor) {
// Find message of the event, if any
Expand Down Expand Up @@ -106,9 +116,32 @@ pub fn breadcrumb_from_event(event: &tracing_core::Event) -> Breadcrumb {
}
}

fn tags_from_event(fields: &mut BTreeMap<String, Value>) -> BTreeMap<String, String> {
let mut tags = BTreeMap::new();

fields.retain(|key, value| {
let Some(key) = key.strip_prefix("tags.") else { return true };
let string = match value {
Value::Bool(b) => b.to_string(),
Value::Number(n) => n.to_string(),
Value::String(s) => std::mem::take(s),
// remove null entries since empty tags are not allowed
Value::Null => return false,
// keep entries that cannot be represented as simple string
Value::Array(_) | Value::Object(_) => return true,
};

tags.insert(key.to_owned(), string);

false
});

tags
}

fn contexts_from_event(
event: &tracing_core::Event,
event_tags: BTreeMap<String, Value>,
fields: BTreeMap<String, Value>,
) -> BTreeMap<String, sentry_core::protocol::Context> {
let event_meta = event.metadata();
let mut location_map = BTreeMap::new();
Expand All @@ -123,10 +156,10 @@ fn contexts_from_event(
}

let mut context = BTreeMap::new();
if !event_tags.is_empty() {
if !fields.is_empty() {
context.insert(
"Rust Tracing Tags".to_string(),
sentry_core::protocol::Context::Other(event_tags),
"Rust Tracing Fields".to_string(),
sentry_core::protocol::Context::Other(fields),
);
}
if !location_map.is_empty() {
Expand All @@ -143,12 +176,13 @@ pub fn event_from_event<S>(event: &tracing_core::Event, _ctx: Context<S>) -> Eve
where
S: Subscriber + for<'a> LookupSpan<'a>,
{
let (message, visitor) = extract_event_data(event);
let (message, mut visitor) = extract_event_data(event);

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()
}
Expand All @@ -159,17 +193,61 @@ pub fn exception_from_event<S>(event: &tracing_core::Event, _ctx: Context<S>) ->
where
S: Subscriber + for<'a> LookupSpan<'a>,
{
// TODO: Exception records in Sentry need a valid type, value and full stack trace to support
// Exception records in Sentry need a valid type, value and full stack trace to support
// proper grouping and issue metadata generation. tracing_core::Record does not contain sufficient
// information for this. However, it may contain a serialized error which we can parse to emit
// an exception record.
let (message, visitor) = extract_event_data(event);
let (mut message, visitor) = extract_event_data(event);
let FieldVisitor {
mut exceptions,
mut json_values,
} = visitor;

// If there are both a message and an exception, then add the message as synthetic wrapper
// around the exception to support proper grouping. If configured, also add the current stack
// trace to this exception directly, since it points to the place where the exception is
// captured.
if !exceptions.is_empty() && message.is_some() {
#[allow(unused_mut)]
let mut thread = Thread::default();

#[cfg(feature = "backtrace")]
if let Some(client) = sentry_core::Hub::current().client() {
if client.options().attach_stacktrace {
thread = sentry_backtrace::current_thread(true);
Comment on lines +216 to +217
Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These two changes I'm not happy with. In order to attach the stack trace, I need to depend on sentry_backtrace and also grab the client to check its options.

The backtrace integration could detect this case (attach_stacktrace enabled + top-level exception is synthetic) and write there. Would that be a better alternative? It composes better, but I'm not sure if we're happy with these semantics.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I believe its a fair thing to do. However turning on attach_stacktrace is a rather hard hammer, and may have high overhead if you just want to log random messages, and not necessarily errors.

As I said in another comment. Another alternative would be to add the "Rust Tracing Location" as it is now as the stack trace here. That is definitely better than it being hidden somewhere in a random context.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I was thinking about adding the tracing location, too. However, it doesn't have enough information to create even a single stack frame that is eligible for grouping, most notably because of the missing function name.

We could also pass this as an option to the tracing integration and pass it down to the converter function, so you can control this separately. At least in Relay, we've enabled stack traces for everything (they are just added for error messages anyway, otherwise we're not tracking stuff in Sentry), so the behavior is intended. This is a good consideration for what attach_stacktraces is actually supposed to mean; and I think in this specific case (we have an exception entry) it's seems exactly as intended.

}
}

let exception = Exception {
ty: level_to_exception_type(event.metadata().level()).to_owned(),
value: message.take(),
module: event.metadata().module_path().map(str::to_owned),
stacktrace: thread.stacktrace,
raw_stacktrace: thread.raw_stacktrace,
thread_id: thread.id,
mechanism: Some(Mechanism {
synthetic: Some(true),
..Mechanism::default()
}),
};

exceptions.push(exception);
}

if let Some(exception) = exceptions.last_mut() {
exception
.mechanism
.get_or_insert_with(Mechanism::default)
.ty = "tracing".to_owned();
}

Event {
logger: Some(event.metadata().target().to_owned()),
level: convert_tracing_level(event.metadata().level()),
message,
exception: visitor.exceptions.into(),
contexts: contexts_from_event(event, visitor.json_values),
exception: exceptions.into(),
tags: tags_from_event(&mut json_values),
contexts: contexts_from_event(event, json_values),
..Default::default()
}
}
2 changes: 1 addition & 1 deletion sentry/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@ rustdoc-args = ["--cfg", "doc_cfg"]
default = ["backtrace", "contexts", "debug-images", "panic", "transport"]

# default integrations
backtrace = ["sentry-backtrace"]
backtrace = ["sentry-backtrace", "sentry-tracing?/backtrace"]
contexts = ["sentry-contexts"]
panic = ["sentry-panic"]
# other integrations
Expand Down
4 changes: 2 additions & 2 deletions sentry/tests/test_tracing.rs
Original file line number Diff line number Diff line change
Expand Up @@ -45,7 +45,7 @@ fn test_tracing() {
event.breadcrumbs[0].message,
Some("Hello Tracing World!".into())
);
match event.contexts.get("Rust Tracing Tags").unwrap() {
match event.contexts.get("Rust Tracing Fields").unwrap() {
Context::Other(tags) => {
let value = Value::String("tagvalue".to_string());
assert_eq!(*tags.get("tagname").unwrap(), value);
Expand Down Expand Up @@ -84,7 +84,7 @@ fn test_tracing() {
event.exception[0].value,
Some("invalid digit found in string".into())
);
match event.contexts.get("Rust Tracing Tags").unwrap() {
match event.contexts.get("Rust Tracing Fields").unwrap() {
Context::Other(tags) => {
let value = Value::String("tagvalue".to_string());
assert_eq!(*tags.get("tagname").unwrap(), value);
Expand Down