diff --git a/Cargo.toml b/Cargo.toml index 3a8f3120..f43fa8e5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -4,6 +4,7 @@ members = [ "tracing", "tracing-core", "tracing-attributes", + "tracing-error", "tracing-futures", "tracing-tower", "tracing-log", diff --git a/examples/Cargo.toml b/examples/Cargo.toml index aa8ea73c..fcc830ba 100644 --- a/examples/Cargo.toml +++ b/examples/Cargo.toml @@ -17,6 +17,7 @@ tower-h2 = { git = "https://github.com/tower-rs/tower-h2.git", optional = true } # tracing crates tracing = "0.1" tracing-core = "0.1" +tracing-error = { path = "../tracing-error" } tracing-tower = { version = "0.1.0", path = "../tracing-tower" } tracing-subscriber = { version = "0.2.0-alpha.1", path = "../tracing-subscriber", features = ["json", "chrono"] } tracing-futures = { version = "0.2.1", path = "../tracing-futures", features = ["futures-01"] } diff --git a/examples/examples/custom_error.rs b/examples/examples/custom_error.rs new file mode 100644 index 00000000..071c087c --- /dev/null +++ b/examples/examples/custom_error.rs @@ -0,0 +1,59 @@ +//! This example demonstrates using the `tracing-error` crate's `SpanTrace` type +//! to attach a trace context to a custom error type. +#![deny(rust_2018_idioms)] +use std::error::Error; +use std::fmt; +use tracing_error::{ErrorLayer, SpanTrace}; +use tracing_subscriber::{fmt::Layer as FmtLayer, prelude::*, registry::Registry}; +#[derive(Debug)] +struct FooError { + message: &'static str, + // This struct captures the current `tracing` span context when it is + // constructed. Later, when we display this error, we will format this + // captured span trace. + context: SpanTrace, +} + +impl FooError { + fn new(message: &'static str) -> Self { + Self { + message, + context: SpanTrace::capture(), + } + } +} + +impl Error for FooError {} + +impl fmt::Display for FooError { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + f.pad(self.message)?; + write!(f, "\n{}", self.context) + } +} + +#[tracing::instrument] +fn do_something(foo: &str) -> Result<&'static str, impl Error + Send + Sync + 'static> { + do_another_thing(42, false) +} + +#[tracing::instrument] +fn do_another_thing( + answer: usize, + will_succeed: bool, +) -> Result<&'static str, impl Error + Send + Sync + 'static> { + Err(FooError::new("something broke, lol")) +} + +#[tracing::instrument] +fn main() { + let subscriber = Registry::default() + .with(FmtLayer::default()) + // The `ErrorLayer` subscriber layer enables the use of `SpanTrace`. + .with(ErrorLayer::default()); + tracing::subscriber::set_global_default(subscriber).expect("Could not set global default"); + match do_something("hello world") { + Ok(result) => println!("did something successfully: {}", result), + Err(e) => eprintln!("error: {}", e), + }; +} diff --git a/tracing-error/Cargo.toml b/tracing-error/Cargo.toml index 33e043b4..ef72701d 100644 --- a/tracing-error/Cargo.toml +++ b/tracing-error/Cargo.toml @@ -7,3 +7,5 @@ edition = "2018" # See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html [dependencies] +tracing-subscriber = { path = "../tracing-subscriber", features = ["registry", "fmt"]} +tracing = "0.1" diff --git a/tracing-error/src/backtrace.rs b/tracing-error/src/backtrace.rs new file mode 100644 index 00000000..2dce88d6 --- /dev/null +++ b/tracing-error/src/backtrace.rs @@ -0,0 +1,171 @@ +use crate::layer::WithContext; +use std::fmt; +use tracing::{Metadata, Span}; + +/// A captured trace of [`tracing`] spans. +/// +/// This type can be thought of as a relative of +/// [`std::backtrace::Backtrace`][`Backtrace`]. +/// However, rather than capturing the current call stack when it is +/// constructed, a `SpanTrace` instead captures the current [span] and its +/// [parents]. +/// +/// In many cases, span traces may be as useful as stack backtraces useful in +/// pinpointing where an error occurred and why, if not moreso: +/// +/// * A span trace captures only the user-defined, human-readable `tracing` +/// spans, rather than _every_ frame in the call stack, often cutting out a +/// lot of noise. +/// * Span traces include the [fields] recorded by each span in the trace, as +/// well as their names and source code location, so different invocations of +/// a function can be distinguished, +/// * In asynchronous code, backtraces for errors that occur in [futures] often +/// consist not of the stack frames that _spawned_ a future, but the stack +/// frames of the executor that is responsible for running that future. This +/// means that if an `async fn` calls another `async fn` which generates an +/// error, the calling async function will not appear in the stack trace (and +/// often, the callee won't either!). On the other hand, when the +/// [`tracing-futures`] crate is used to instrument async code, the span trace +/// will represent the logical application context a future was running in, +/// rather than the stack trace of the executor that was polling a future when +/// an error occurred. +/// +/// Finally, unlike stack [`Backtrace`]s, capturing a `SpanTrace` is fairly +/// lightweight, and the resulting struct is not large. The `SpanTrace` struct +/// is formatted lazily; instead, it simply stores a copy of the current span, +/// and allows visiting the spans in that span's trace tree by calling the +/// [`with_spans` method][`with_spans`]. +/// +/// # Formatting +/// +/// The `SpanTrace` type implements `fmt::Display`, formatting the span trace +/// similarly to how Rust formats panics. For example: +/// +/// ```text +/// span backtrace: +/// 0: custom_error::do_another_thing +/// with answer=42 will_succeed=false +/// at examples/examples/custom_error.rs:42 +/// 1: custom_error::do_something +/// with foo="hello world" +/// at examples/examples/custom_error.rs:37 +/// ``` +/// +/// Additionally, if custom formatting is desired, the [`with_spans`] method can +/// be used to visit each span in the trace, formatting them in order. +/// +/// [`tracing`]: https://docs.rs/tracing +/// [`Backtrace`]: https://doc.rust-lang.org/std/backtrace/struct.Backtrace.html +/// [span]: https://docs.rs/tracing/latest/tracing/span/index.html +/// [parents]: https://docs.rs/tracing/latest/tracing/span/index.html#span-relationships +/// [fields]: https://docs.rs/tracing/latest/tracing/field/index.html +/// [futures]: https://doc.rust-lang.org/std/future/trait.Future.html +/// [`tracing-futures`]: https://docs.rs/tracing-futures/ +/// [`with_spans`] method: #method.with_spans.html +#[derive(Clone)] +pub struct SpanTrace { + span: Span, +} + +// === impl SpanTrace === + +impl SpanTrace { + /// Capture the current span trace. + /// + /// # Examples + /// ```rust + /// use tracing_error::SpanTrace; + /// + /// pub struct MyError { + /// span_trace: SpanTrace, + /// // ... + /// } + /// + /// # fn some_error_condition() -> bool { true } + /// + /// #[tracing::instrument] + /// pub fn my_function(arg: &str) -> Result<(), MyError> { + /// if some_error_condition() { + /// return Err(MyError { + /// span_trace: SpanTrace::capture(), + /// // ... + /// }); + /// } + /// + /// // ... + /// # Ok(()) + /// } + /// ``` + pub fn capture() -> Self { + SpanTrace { + span: Span::current(), + } + } + + /// Apply a function to all captured spans in the trace until it returns + /// `false`. + /// + /// This will call the provided function with a reference to the + /// [`Metadata`] and a formatted representation of the [fields] of each span + /// captured in the trace, starting with the span that was current when the + /// trace was captured. The function may return `true` or `false` to + /// indicate whether to continue iterating over spans; if it returns + /// `false`, no additional spans will be visited. + /// + /// [fields]: https://docs.rs/tracing/latest/tracing/field/index.html + /// [`Metadata`]: https://docs.rs/tracing/latest/tracing/struct.Metadata.html + pub fn with_spans(&self, f: impl FnMut(&'static Metadata<'static>, &str) -> bool) { + self.span.with_subscriber(|(id, s)| { + if let Some(getcx) = s.downcast_ref::() { + getcx.with_context(s, id, f); + } + }); + } +} + +macro_rules! try_bool { + ($e:expr, $dest:ident) => {{ + let ret = $e.unwrap_or_else(|e| $dest = Err(e)); + + if $dest.is_err() { + return false; + } + + ret + }}; +} + +impl fmt::Display for SpanTrace { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut err = Ok(()); + let mut span = 0; + + writeln!(f, "span backtrace:")?; + self.with_spans(|metadata, fields| { + try_bool!( + writeln!(f, "{:>4}: {}::{}", span, metadata.target(), metadata.name()), + err + ); + if !fields.is_empty() { + try_bool!(writeln!(f, " with {}", fields), err); + } + if let Some((file, line)) = metadata + .file() + .and_then(|file| metadata.line().map(|line| (file, line))) + { + try_bool!(writeln!(f, " at {}:{}", file, line), err); + } + + span += 1; + true + }); + + err + } +} + +impl fmt::Debug for SpanTrace { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + fmt::Display::fmt(self, f) + } +} diff --git a/tracing-error/src/layer.rs b/tracing-error/src/layer.rs new file mode 100644 index 00000000..ac7e153b --- /dev/null +++ b/tracing-error/src/layer.rs @@ -0,0 +1,124 @@ +use std::any::TypeId; +use std::marker::PhantomData; +use tracing::{span, Dispatch, Metadata, Subscriber}; +use tracing_subscriber::fmt::format::{DefaultFields, FormatFields}; +use tracing_subscriber::{ + fmt::FormattedFields, + layer::{self, Layer}, + registry::LookupSpan, +}; + +/// A subscriber [`Layer`] that enables capturing [`SpanTrace`]s. +/// +/// Optionally, this type may be constructed with a [field formatter] to use +/// when formatting the fields of each span in a trace. When no formatter is +/// provided, the [default format] is used instead. +/// +/// [`Layer`]: https://docs.rs/tracing-subscriber/0.2.0-alpha.5/tracing_subscriber/layer/trait.Layer.html +/// [`SpanTrace`]: ../struct.SpanTrace.html +/// [field formatter]: https://docs.rs/tracing-subscriber/0.2.0-alpha.5/tracing_subscriber/fmt/trait.FormatFields.html +/// [default format]: https://docs.rs/tracing-subscriber/0.2.0-alpha.5/tracing_subscriber/fmt/format/struct.DefaultFields.html +pub struct ErrorLayer { + format: F, + + get_context: WithContext, + _subscriber: PhantomData, +} + +// this function "remembers" the types of the subscriber and the formatter, +// so that we can downcast to something aware of them without knowing those +// types at the callsite. +pub(crate) struct WithContext( + fn(&Dispatch, &span::Id, f: &mut dyn FnMut(&'static Metadata<'static>, &str) -> bool), +); + +impl Layer for ErrorLayer +where + S: Subscriber + for<'span> LookupSpan<'span>, + F: for<'writer> FormatFields<'writer> + 'static, +{ + /// Notifies this layer that a new span was constructed with the given + /// `Attributes` and `Id`. + fn new_span(&self, attrs: &span::Attributes<'_>, id: &span::Id, ctx: layer::Context<'_, S>) { + let span = ctx.span(id).expect("span must already exist!"); + if span.extensions().get::>().is_some() { + return; + } + let mut fields = String::new(); + if self.format.format_fields(&mut fields, attrs).is_ok() { + span.extensions_mut() + .insert(FormattedFields::::new(fields)); + } + } + + unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> { + match id { + id if id == TypeId::of::() => Some(self as *const _ as *const ()), + id if id == TypeId::of::() => { + Some(&self.get_context as *const _ as *const ()) + } + _ => None, + } + } +} + +impl ErrorLayer +where + F: for<'writer> FormatFields<'writer> + 'static, + S: Subscriber + for<'span> LookupSpan<'span>, +{ + /// Returns a new `ErrorLayer` with the provided [field formatter]. + /// + /// [field formatter]: https://docs.rs/tracing-subscriber/0.2.0-alpha.5/tracing_subscriber/fmt/trait.FormatFields.html + pub fn new(format: F) -> Self { + Self { + format, + get_context: WithContext(Self::get_context), + _subscriber: PhantomData, + } + } + + fn get_context( + dispatch: &Dispatch, + id: &span::Id, + f: &mut dyn FnMut(&'static Metadata<'static>, &str) -> bool, + ) { + let subscriber = dispatch + .downcast_ref::() + .expect("subscriber should downcast to expected type; this is a bug!"); + let span = subscriber + .span(id) + .expect("registry should have a span for the current ID"); + let parents = span.parents(); + for span in std::iter::once(span).chain(parents) { + let cont = if let Some(fields) = span.extensions().get::>() { + f(span.metadata(), fields.fields.as_str()) + } else { + f(span.metadata(), "") + }; + if !cont { + break; + } + } + } +} + +impl WithContext { + pub(crate) fn with_context<'a>( + &self, + dispatch: &'a Dispatch, + id: &span::Id, + mut f: impl FnMut(&'static Metadata<'static>, &str) -> bool, + ) { + (self.0)(dispatch, id, &mut f) + } +} + +impl Default for ErrorLayer +where + S: Subscriber + for<'span> LookupSpan<'span>, +{ + fn default() -> Self { + Self::new(DefaultFields::default()) + } +} diff --git a/tracing-error/src/lib.rs b/tracing-error/src/lib.rs new file mode 100644 index 00000000..b92006de --- /dev/null +++ b/tracing-error/src/lib.rs @@ -0,0 +1,18 @@ +//! Utilities for enriching error handling with [`tracing`] diagnostic +//! information. +//! +//! [`tracing`] is a framework for instrumenting Rust programs to collect +//! scoped, structured, and async-aware diagnostics. This crate provides +//! integrations between [`tracing`] instrumentation and Rust error handling, +//! allowing error types to capture the current [`tracing`] span context when +//! they are constructed, format those contexts when they are displayed, and +//! automatically generate [`tracing`] events when errors occur. +//! +//! **Note**: This crate is currently experimental. +//! +//! [`tracing`]: https://docs.rs/tracing +mod backtrace; +mod layer; + +pub use self::backtrace::SpanTrace; +pub use self::layer::ErrorLayer;