diff --git a/sentry-core/src/performance.rs b/sentry-core/src/performance.rs index 09bfe0a0..9db4a66a 100644 --- a/sentry-core/src/performance.rs +++ b/sentry-core/src/performance.rs @@ -112,7 +112,9 @@ impl TransactionContext { ) } TransactionOrSpan::Span(span) => { - (span.span.trace_id, span.span.span_id, Some(span.sampled)) + let sampled = span.sampled; + let span = span.span.lock().unwrap(); + (span.trace_id, span.span_id, Some(sampled)) } }; @@ -158,6 +160,14 @@ impl From for TransactionOrSpan { } impl TransactionOrSpan { + /// Set some extra information to be sent with this Transaction/Span. + pub fn set_data(&self, key: &str, value: protocol::Value) { + match self { + TransactionOrSpan::Transaction(transaction) => transaction.set_data(key, value), + TransactionOrSpan::Span(span) => span.set_data(key, value), + } + } + /// Returns the headers needed for distributed tracing. pub fn iter_headers(&self) -> TraceHeadersIter { match self { @@ -187,11 +197,14 @@ impl TransactionOrSpan { TransactionOrSpan::Transaction(transaction) => { transaction.inner.lock().unwrap().context.clone() } - TransactionOrSpan::Span(span) => protocol::TraceContext { - span_id: span.span.span_id, - trace_id: span.span.trace_id, - ..Default::default() - }, + TransactionOrSpan::Span(span) => { + let span = span.span.lock().unwrap(); + protocol::TraceContext { + span_id: span.span_id, + trace_id: span.trace_id, + ..Default::default() + } + } }; event.contexts.insert("trace".into(), context.into()); } @@ -266,6 +279,14 @@ impl Transaction { } } + /// Set some extra information to be sent with this Transaction. + pub fn set_data(&self, key: &str, value: protocol::Value) { + let mut inner = self.inner.lock().unwrap(); + if let Some(transaction) = inner.transaction.as_mut() { + transaction.data.insert(key.into(), value); + } + } + /// Returns the headers needed for distributed tracing. pub fn iter_headers(&self) -> TraceHeadersIter { let inner = self.inner.lock().unwrap(); @@ -326,7 +347,7 @@ impl Transaction { Span { transaction: Arc::clone(&self.inner), sampled: inner.sampled, - span, + span: Arc::new(Mutex::new(span)), } } } @@ -339,13 +360,22 @@ impl Transaction { pub struct Span { transaction: TransactionArc, sampled: bool, - span: protocol::Span, + span: SpanArc, } +type SpanArc = Arc>; + impl Span { + /// Set some extra information to be sent with this Transaction. + pub fn set_data(&self, key: &str, value: protocol::Value) { + let mut span = self.span.lock().unwrap(); + span.data.insert(key.into(), value); + } + /// Returns the headers needed for distributed tracing. pub fn iter_headers(&self) -> TraceHeadersIter { - let trace = SentryTrace(self.span.trace_id, self.span.span_id, Some(self.sampled)); + let span = self.span.lock().unwrap(); + let trace = SentryTrace(span.trace_id, span.span_id, Some(self.sampled)); TraceHeadersIter { sentry_trace: Some(trace.to_string()), } @@ -355,12 +385,17 @@ impl Span { /// /// This will record the end timestamp and add the span to the transaction /// in which it was started. - pub fn finish(mut self) { - self.span.finish(); + pub fn finish(self) { + let mut span = self.span.lock().unwrap(); + if span.timestamp.is_some() { + // the span was already finished + return; + } + span.finish(); let mut inner = self.transaction.lock().unwrap(); if let Some(transaction) = inner.transaction.as_mut() { if transaction.spans.len() <= MAX_SPANS { - transaction.spans.push(self.span); + transaction.spans.push(span.clone()); } } } @@ -370,9 +405,10 @@ impl Span { /// The span must be explicitly finished via [`Span::finish`]. #[must_use = "a span must be explicitly closed via `finish()`"] pub fn start_child(&self, op: &str, description: &str) -> Span { + let span = self.span.lock().unwrap(); let span = protocol::Span { - trace_id: self.span.trace_id, - parent_span_id: Some(self.span.span_id), + trace_id: span.trace_id, + parent_span_id: Some(span.span_id), op: Some(op.into()), description: if description.is_empty() { None @@ -384,7 +420,7 @@ impl Span { Span { transaction: self.transaction.clone(), sampled: self.sampled, - span, + span: Arc::new(Mutex::new(span)), } } } diff --git a/sentry-tracing/src/converters.rs b/sentry-tracing/src/converters.rs index 954d3341..60a69480 100644 --- a/sentry-tracing/src/converters.rs +++ b/sentry-tracing/src/converters.rs @@ -1,16 +1,12 @@ use std::collections::BTreeMap; -use sentry_core::protocol::{self, Event, TraceContext, Value}; +use sentry_core::protocol::{Event, Value}; use sentry_core::{Breadcrumb, Level}; -use tracing_core::{ - field::{Field, Visit}, - span, Subscriber, -}; +use tracing_core::field::{Field, Visit}; +use tracing_core::{span, Subscriber}; use tracing_subscriber::layer::Context; use tracing_subscriber::registry::LookupSpan; -use crate::Trace; - /// Converts a [`tracing_core::Level`] to a Sentry [`Level`] pub fn convert_tracing_level(level: &tracing_core::Level) -> Level { match level { @@ -94,46 +90,19 @@ pub fn breadcrumb_from_event(event: &tracing_core::Event) -> Breadcrumb { } /// Creates an [`Event`] from a given [`tracing_core::Event`] -pub fn event_from_event(event: &tracing_core::Event, ctx: Context) -> Event<'static> +pub fn event_from_event(event: &tracing_core::Event, _ctx: Context) -> Event<'static> where S: Subscriber + for<'a> LookupSpan<'a>, { let (message, extra) = extract_event_data(event); - let mut result = Event { + Event { logger: Some(event.metadata().target().to_owned()), level: convert_tracing_level(event.metadata().level()), message, extra, ..Default::default() - }; - - let parent = event - .parent() - .and_then(|id| ctx.span(id)) - .or_else(|| ctx.lookup_current()); - - if let Some(parent) = parent { - let extensions = parent.extensions(); - if let Some(trace) = extensions.get::() { - let context = protocol::Context::from(TraceContext { - span_id: trace.span.span_id, - trace_id: trace.span.trace_id, - ..TraceContext::default() - }); - - result.contexts.insert(String::from("trace"), context); - - result.transaction = parent - .parent() - .into_iter() - .flat_map(|span| span.scope()) - .last() - .map(|root| root.name().into()); - } } - - result } /// Creates an exception [`Event`] from a given [`tracing_core::Event`] diff --git a/sentry-tracing/src/layer.rs b/sentry-tracing/src/layer.rs index ee237e20..d37a9a73 100644 --- a/sentry-tracing/src/layer.rs +++ b/sentry-tracing/src/layer.rs @@ -1,18 +1,7 @@ -use std::{ - collections::BTreeMap, - time::{Instant, SystemTime}, -}; - -use sentry_core::{ - protocol::{self, Breadcrumb, TraceContext, TraceId, Transaction, Value}, - types::Uuid, - Envelope, Hub, -}; +use sentry_core::{Breadcrumb, TransactionOrSpan}; use tracing_core::{span, Event, Level, Metadata, Subscriber}; -use tracing_subscriber::{ - layer::{Context, Layer}, - registry::{LookupSpan, SpanRef}, -}; +use tracing_subscriber::layer::{Context, Layer}; +use tracing_subscriber::registry::LookupSpan; use crate::converters::*; @@ -64,109 +53,14 @@ pub fn default_span_filter(metadata: &Metadata) -> bool { ) } -/// The default span mapper. -/// -/// By default, a new empty span is created with the `op` -/// field set to the name of the span, with the `trace_id` -/// copied from the parent span if any -pub fn default_span_mapper( - span: &SpanRef, - parent: Option<&protocol::Span>, - attrs: &span::Attributes, -) -> protocol::Span -where - S: Subscriber + for<'a> LookupSpan<'a>, -{ - let (description, data) = extract_span_data(attrs); - - let trace_id = parent - .map(|parent| parent.trace_id) - .unwrap_or_else(TraceId::default); - - protocol::Span { - trace_id, - op: Some(span.name().into()), - description, - data, - ..protocol::Span::default() - } -} - -/// The default span on_close hook. -/// -/// By default, this sets the end timestamp of the span, -/// and creates `busy` and `idle` data fields from the timing data -pub fn default_span_on_close(span: &mut protocol::Span, timings: Timings) { - span.data - .insert(String::from("busy"), Value::Number(timings.busy.into())); - - span.data - .insert(String::from("idle"), Value::Number(timings.idle.into())); - - span.timestamp = Some(timings.end_time.into()); -} - -/// The default transaction mapper. -/// -/// By default, this creates a transaction from a root span -/// containing all of its children spans -pub fn default_transaction_mapper( - sentry_span: protocol::Span, - tracing_span: &SpanRef, - spans: Vec, - timings: Timings, -) -> Transaction<'static> -where - S: Subscriber + for<'a> LookupSpan<'a>, -{ - let mut contexts = BTreeMap::new(); - - contexts.insert( - String::from("trace"), - protocol::Context::Trace(Box::new(TraceContext { - span_id: sentry_span.span_id, - trace_id: sentry_span.trace_id, - parent_span_id: sentry_span.parent_span_id, - op: sentry_span.op, - description: sentry_span.description, - status: sentry_span.status, - })), - ); - - Transaction { - event_id: Uuid::new_v4(), - name: Some(tracing_span.name().into()), - start_timestamp: timings.start_time.into(), - timestamp: Some(timings.end_time.into()), - spans, - contexts, - ..Transaction::default() - } -} - type EventMapper = Box) -> EventMapping + Send + Sync>; -type SpanMapper = Box< - dyn Fn(&SpanRef, Option<&protocol::Span>, &span::Attributes) -> protocol::Span + Send + Sync, ->; - -type SpanOnClose = Box; - -type TransactionMapper = Box< - dyn Fn(protocol::Span, &SpanRef, Vec, Timings) -> Transaction<'static> - + Send - + Sync, ->; - /// Provides a tracing layer that dispatches events to sentry pub struct SentryLayer { event_filter: Box EventFilter + Send + Sync>, event_mapper: Option>, span_filter: Box bool + Send + Sync>, - span_mapper: SpanMapper, - span_on_close: SpanOnClose, - transaction_mapper: TransactionMapper, } impl SentryLayer { @@ -205,48 +99,6 @@ impl SentryLayer { self.span_filter = Box::new(filter); self } - - /// Sets a custom span mapper function. - /// - /// The mapper is responsible for creating [`protocol::Span`]s from - /// [`tracing::Span`]s. - pub fn span_mapper(mut self, mapper: F) -> Self - where - F: Fn(&SpanRef, Option<&protocol::Span>, &span::Attributes) -> protocol::Span - + Send - + Sync - + 'static, - { - self.span_mapper = Box::new(mapper); - self - } - - /// Sets a custom span `on_close` hook. - /// - /// The hook is called with [`Timings`] information when a [`tracing::Span`] - /// is closed, and can mutate the associated [`protocol::Span`] accordingly. - pub fn span_on_close(mut self, on_close: F) -> Self - where - F: Fn(&mut protocol::Span, Timings) + Send + Sync + 'static, - { - self.span_on_close = Box::new(on_close); - self - } - - /// Sets a custom transaction mapper function. - /// - /// The mapper is responsible for creating [`Transaction`]s from - /// [`tracing::Span`]s. - pub fn transaction_mapper(mut self, mapper: F) -> Self - where - F: Fn(protocol::Span, &SpanRef, Vec, Timings) -> Transaction<'static> - + Send - + Sync - + 'static, - { - self.transaction_mapper = Box::new(mapper); - self - } } impl Default for SentryLayer @@ -259,13 +111,18 @@ where event_mapper: None, span_filter: Box::new(default_span_filter), - span_mapper: Box::new(default_span_mapper), - span_on_close: Box::new(default_span_on_close), - transaction_mapper: Box::new(default_transaction_mapper), } } } +/// Data that is attached to the tracing Spans `extensions`, in order to +/// `finish` the corresponding sentry span `on_close`, and re-set its parent as +/// the *current* span. +struct SentrySpanData { + sentry_span: TransactionOrSpan, + parent_sentry_span: Option, +} + impl Layer for SentryLayer where S: Subscriber + for<'a> LookupSpan<'a>, @@ -290,8 +147,8 @@ where } } - /// When a new Span gets created, run the filter and initialize the trace extension - /// if it passes + /// When a new Span gets created, run the filter and start a new sentry span + /// if it passes, setting it as the *current* sentry span. fn on_new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: Context<'_, S>) { let span = match ctx.span(id) { Some(span) => span, @@ -302,61 +159,29 @@ where return; } - let mut extensions = span.extensions_mut(); - if extensions.get_mut::().is_none() { - for parent in span.parent().into_iter().flat_map(|span| span.scope()) { - let parent = parent.extensions(); - let parent = match parent.get::() { - Some(trace) => trace, - None => continue, - }; + let (description, _data) = extract_span_data(attrs); + let op = span.name(); + let description = description.as_deref().unwrap_or(""); - let span = (self.span_mapper)(&span, Some(&parent.span), attrs); - extensions.insert(Trace::new(span)); - return; + let parent_sentry_span = sentry_core::configure_scope(|s| s.get_span()); + let sentry_span: sentry_core::TransactionOrSpan = match &parent_sentry_span { + Some(parent) => parent.start_child(op, description).into(), + None => { + let ctx = sentry_core::TransactionContext::new(description, op); + sentry_core::start_transaction(ctx).into() } - - let span = (self.span_mapper)(&span, None, attrs); - extensions.insert(Trace::new(span)); - } - } - - /// From the tracing-subscriber implementation of span timings, - /// keep track of when the span was last entered - fn on_enter(&self, id: &span::Id, ctx: Context<'_, S>) { - let span = match ctx.span(id) { - Some(span) => span, - None => return, }; + sentry_core::configure_scope(|scope| scope.set_span(Some(sentry_span.clone()))); let mut extensions = span.extensions_mut(); - if let Some(timings) = extensions.get_mut::() { - let now = Instant::now(); - timings.idle += (now - timings.last).as_nanos() as u64; - timings.last = now; - } - } - - /// From the tracing-subscriber implementation of span timings, - /// keep track of when the span was last exited - fn on_exit(&self, id: &span::Id, ctx: Context<'_, S>) { - let span = match ctx.span(id) { - Some(span) => span, - None => return, - }; - - let mut extensions = span.extensions_mut(); - if let Some(timings) = extensions.get_mut::() { - let now = Instant::now(); - timings.busy += (now - timings.last).as_nanos() as u64; - timings.last = now; - timings.last_sys = SystemTime::now(); - } + extensions.insert(SentrySpanData { + sentry_span, + parent_sentry_span, + }); } - /// When a span gets closed, if it has a trace extension either - /// attach it to a parent span or submit it as a Transaction if - /// it is a root of the span tree + /// When a span gets closed, finish the underlying sentry span, and set back + /// its parent as the *current* sentry span. fn on_close(&self, id: span::Id, ctx: Context<'_, S>) { let span = match ctx.span(&id) { Some(span) => span, @@ -364,53 +189,16 @@ where }; let mut extensions = span.extensions_mut(); - let mut trace = match extensions.remove::() { - Some(trace) => trace, + let SentrySpanData { + sentry_span, + parent_sentry_span, + } = match extensions.remove::() { + Some(data) => data, None => return, }; - // Construct the timing data and call the on_close hook - trace.idle += (Instant::now() - trace.last).as_nanos() as u64; - - let timings = Timings { - start_time: trace.first, - end_time: trace.last_sys, - idle: trace.idle, - busy: trace.busy, - }; - - (self.span_on_close)(&mut trace.span, timings); - - // Traverse the parents of this span to attach to the nearest one - // that has tracing data (spans ignored by the span_filter do not) - for parent in span.parent().into_iter().flat_map(|span| span.scope()) { - let mut extensions = parent.extensions_mut(); - if let Some(parent) = extensions.get_mut::() { - parent.spans.extend(trace.spans); - - trace.span.parent_span_id = Some(parent.span.span_id); - parent.spans.push(trace.span); - return; - } - } - - // If no parent was found, consider this span a - // transaction root and submit it to Sentry - let span = &span; - Hub::with_active(move |hub| { - let client = match hub.client() { - Some(client) => client, - None => return, - }; - - if !client.sample_traces_should_send() { - return; - } - - let transaction = (self.transaction_mapper)(trace.span, span, trace.spans, timings); - let envelope = Envelope::from(transaction); - client.send_envelope(envelope); - }); + sentry_span.finish(); + sentry_core::configure_scope(|scope| scope.set_span(parent_sentry_span)); } /// Implement the writing of extra data to span @@ -420,9 +208,9 @@ where _ => return, }; - let mut extensions_holder = span.extensions_mut(); - let trace = match extensions_holder.get_mut::() { - Some(t) => t, + let mut extensions = span.extensions_mut(); + let span = match extensions.get_mut::() { + Some(t) => &t.sentry_span, _ => return, }; @@ -430,56 +218,7 @@ where values.record(&mut data); for (key, value) in data.0 { - trace.span.data.insert(key, value); - } - } -} - -/// Timing informations for a given Span -#[derive(Clone, Copy, Debug)] -pub struct Timings { - /// The time the span was first entered - pub start_time: SystemTime, - /// The time the span was last entered - pub end_time: SystemTime, - /// The total busy time for this span, in nanoseconds - pub busy: u64, - /// The total idle time for this span, in nanoseconds - pub idle: u64, -} - -/// Private internal state for a Span -/// -/// Every Span that passes the `span_filter` has -/// an instance of this struct attached as an extension. -/// It is used to store transient informations while the -/// Span is being built such as the incomplete protocol::Span -/// as well as finished children Spans. -pub(crate) struct Trace { - pub(crate) span: protocol::Span, - spans: Vec, - - // From the tracing-subscriber implementation of span timings, - // with additional SystemTime informations to reconstruct the UTC - // times needed by Sentry - idle: u64, - busy: u64, - last: Instant, - first: SystemTime, - last_sys: SystemTime, -} - -impl Trace { - fn new(span: protocol::Span) -> Self { - Trace { - span, - spans: Vec::new(), - - idle: 0, - busy: 0, - last: Instant::now(), - first: SystemTime::now(), - last_sys: SystemTime::now(), + span.set_data(&key, value); } } } diff --git a/sentry-types/src/protocol/v7.rs b/sentry-types/src/protocol/v7.rs index d7ce66e5..10ebae9c 100644 --- a/sentry-types/src/protocol/v7.rs +++ b/sentry-types/src/protocol/v7.rs @@ -1830,6 +1830,9 @@ pub struct Transaction<'a> { /// Optional tags to be attached to the event. #[serde(default, skip_serializing_if = "Map::is_empty")] pub tags: Map, + /// Optional extra information to be sent with the event. + #[serde(default, skip_serializing_if = "Map::is_empty")] + pub data: Map, /// SDK metadata #[serde(default, skip_serializing_if = "Option::is_none")] pub sdk: Option>, @@ -1858,6 +1861,7 @@ impl<'a> Default for Transaction<'a> { event_id: event::default_id(), name: Default::default(), tags: Default::default(), + data: Default::default(), release: Default::default(), environment: Default::default(), sdk: Default::default(), @@ -1882,6 +1886,7 @@ impl<'a> Transaction<'a> { event_id: self.event_id, name: self.name, tags: self.tags, + data: self.data, release: self.release.map(|x| Cow::Owned(x.into_owned())), environment: self.environment.map(|x| Cow::Owned(x.into_owned())), sdk: self.sdk.map(|x| Cow::Owned(x.into_owned())), diff --git a/sentry/examples/tracing-demo.rs b/sentry/examples/tracing-demo.rs index bb595f67..74cf9d4d 100644 --- a/sentry/examples/tracing-demo.rs +++ b/sentry/examples/tracing-demo.rs @@ -1,6 +1,10 @@ -use tracing_::{debug, error, info, warn}; +use std::thread; +use std::time::Duration; + +use tracing_ as tracing; use tracing_subscriber::prelude::*; +// cargo run --example tracing-demo fn main() { tracing_subscriber::registry() .with(tracing_subscriber::fmt::layer()) @@ -10,11 +14,42 @@ fn main() { let _sentry = sentry::init(sentry::ClientOptions { release: sentry::release_name!(), + traces_sample_rate: 1.0, + debug: true, ..Default::default() }); - debug!("System is booting"); - info!("System is booting"); - warn!("System is warning"); - error!("Holy shit everything is on fire!"); + tracing::debug!("System is booting"); + tracing::info!("System is booting"); + + main_span1(); + thread::sleep(Duration::from_millis(100)); +} + +#[tracing::instrument] +fn main_span1() { + thread::sleep(Duration::from_millis(50)); + + tracing::warn!("System is warning"); + + thread::spawn(move || { + thread::sleep(Duration::from_millis(50)); + + thread_span1(); + + tracing::error!("Holy shit everything is on fire!"); + }); + thread::sleep(Duration::from_millis(100)); + + main_span2() +} + +#[tracing::instrument] +fn thread_span1() { + thread::sleep(Duration::from_millis(200)); +} + +#[tracing::instrument] +fn main_span2() { + thread::sleep(Duration::from_millis(200)); }