Skip to content

Commit

Permalink
attributes: add err(Debug) meta to use Debug impl (#1631)
Browse files Browse the repository at this point in the history
## Motivation

This PR attempts to solve #1630 by introducing `err(Debug)` meta to
`intrument` attribute macro. As `err` meta causes the error (`e`)
returned by instrumented function to be passed to `tracing::error!(error
= %e)` i.e. makes it use the `Display` implementation of `e`, the newly
added `err(Debug)` makes expands to `tracing::error!(error = ?e)` which
makes the `error!` macro to use `Debug` implementation for `e`. `err`
and `err(Debug)` are mutually exclusive, adding both will create a
compilation error.

`err(Display)` is also supported to specify `Display` explicitly.

As tried to describe, for some types implementing `Error` it might be
more suitable to use `Debug` implementation as in the case of
`eyre::Result`. This frees us to manually go over the error chain and
print them all, so that `instrument` attribute macro would do it for us.

## Solution

- Added a custom keyword `err(Debug)` similar to `err`,
- Add `err(Debug)` field to `InstrumentArgs`,
- Add parsing for `err(Debug)` arg and check for conflicts with `err`,
- Generate `tracing::error!(error = ?e)` when `err(Debug)` is `true` and
  `tracing::error!(error = %e)` when `err(Display)` or `err` is `true`,
- Interpolate generated `err_block` into `Err` branches in both async
  and sync return positions, if `err` or `err(Debug)` is `true`.
  • Loading branch information
ciuncan authored and hawkw committed Oct 22, 2021
1 parent a22f6f8 commit 41771ac
Show file tree
Hide file tree
Showing 2 changed files with 114 additions and 15 deletions.
79 changes: 64 additions & 15 deletions tracing-attributes/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -374,7 +374,7 @@ use syn::{
/// ```
///
/// If the function returns a `Result<T, E>` and `E` implements `std::fmt::Display`, you can add
/// `err` to emit error events when the function returns `Err`:
/// `err` or `err(Display)` to emit error events when the function returns `Err`:
///
/// ```
/// # use tracing_attributes::instrument;
Expand All @@ -384,6 +384,18 @@ use syn::{
/// }
/// ```
///
/// By default, error values will be recorded using their `std::fmt::Display` implementations.
/// If an error implements `std::fmt::Debug`, it can be recorded using its `Debug` implementation
/// instead, by writing `err(Debug)`:
///
/// ```
/// # use tracing_attributes::instrument;
/// #[instrument(err(Debug))]
/// fn my_function(arg: usize) -> Result<(), std::io::Error> {
/// Ok(())
/// }
/// ```
///
/// `async fn`s may also be instrumented:
///
/// ```
Expand Down Expand Up @@ -591,8 +603,6 @@ fn gen_block(
instrumented_function_name: &str,
self_type: Option<&syn::TypePath>,
) -> proc_macro2::TokenStream {
let err = args.err;

// generate the span's name
let span_name = args
// did the user override the span's name?
Expand Down Expand Up @@ -705,29 +715,34 @@ fn gen_block(
))
})();

let err_event = match args.err_mode {
Some(ErrorMode::Display) => Some(quote!(tracing::error!(error = %e))),
Some(ErrorMode::Debug) => Some(quote!(tracing::error!(error = ?e))),
_ => None,
};

// Generate the instrumented function body.
// If the function is an `async fn`, this will wrap it in an async block,
// which is `instrument`ed using `tracing-futures`. Otherwise, this will
// enter the span and then perform the rest of the body.
// If `err` is in args, instrument any resulting `Err`s.
if async_context {
let mk_fut = if err {
quote_spanned!(block.span()=>
let mk_fut = match err_event {
Some(err_event) => quote_spanned!(block.span()=>
async move {
match async move { #block }.await {
#[allow(clippy::unit_arg)]
Ok(x) => Ok(x),
Err(e) => {
tracing::error!(error = %e);
#err_event;
Err(e)
}
}
}
)
} else {
quote_spanned!(block.span()=>
),
None => quote_spanned!(block.span()=>
async move { #block }
)
),
};

return quote!(
Expand Down Expand Up @@ -764,15 +779,15 @@ fn gen_block(
}
);

if err {
if let Some(err_event) = err_event {
return quote_spanned!(block.span()=>
#span
#[allow(clippy::redundant_closure_call)]
match (move || #block)() {
#[allow(clippy::unit_arg)]
Ok(x) => Ok(x),
Err(e) => {
tracing::error!(error = %e);
#err_event;
Err(e)
}
}
Expand Down Expand Up @@ -802,7 +817,7 @@ struct InstrumentArgs {
skips: HashSet<Ident>,
skip_all: bool,
fields: Option<Fields>,
err: bool,
err_mode: Option<ErrorMode>,
/// Errors describing any unrecognized parse inputs that we skipped.
parse_warnings: Vec<syn::Error>,
}
Expand Down Expand Up @@ -939,8 +954,9 @@ impl Parse for InstrumentArgs {
}
args.fields = Some(input.parse()?);
} else if lookahead.peek(kw::err) {
let _ = input.parse::<kw::err>()?;
args.err = true;
let _ = input.parse::<kw::err>();
let mode = ErrorMode::parse(input)?;
args.err_mode = Some(mode);
} else if lookahead.peek(Token![,]) {
let _ = input.parse::<Token![,]>()?;
} else {
Expand Down Expand Up @@ -998,6 +1014,39 @@ impl Parse for Skips {
}
}

#[derive(Debug, Hash, PartialEq, Eq)]
enum ErrorMode {
Display,
Debug,
}

impl Default for ErrorMode {
fn default() -> Self {
ErrorMode::Display
}
}

impl Parse for ErrorMode {
fn parse(input: ParseStream<'_>) -> syn::Result<Self> {
if !input.peek(syn::token::Paren) {
return Ok(ErrorMode::default());
}
let content;
let _ = syn::parenthesized!(content in input);
let maybe_mode: Option<Ident> = content.parse()?;
maybe_mode.map_or(Ok(ErrorMode::default()), |ident| {
match ident.to_string().as_str() {
"Debug" => Ok(ErrorMode::Debug),
"Display" => Ok(ErrorMode::Display),
_ => Err(syn::Error::new(
ident.span(),
"unknown error mode, must be Debug or Display",
)),
}
})
}
}

#[derive(Debug)]
struct Fields(Punctuated<Field, Token![,]>);

Expand Down
50 changes: 50 additions & 0 deletions tracing-attributes/tests/err.rs
Original file line number Diff line number Diff line change
Expand Up @@ -153,3 +153,53 @@ fn impl_trait_return_type() {

handle.assert_finished();
}

#[instrument(err(Debug))]
fn err_dbg() -> Result<u8, TryFromIntError> {
u8::try_from(1234)
}

#[test]
fn test_err_dbg() {
let span = span::mock().named("err_dbg");
let (collector, handle) = collector::mock()
.new_span(span.clone())
.enter(span.clone())
.event(
event::mock().at_level(Level::ERROR).with_fields(
field::mock("error")
// use the actual error value that will be emitted, so
// that this test doesn't break if the standard library
// changes the `fmt::Debug` output from the error type
// in the future.
.with_value(&tracing::field::debug(u8::try_from(1234).unwrap_err())),
),
)
.exit(span.clone())
.drop_span(span)
.done()
.run_with_handle();
with_default(collector, || err_dbg().ok());
handle.assert_finished();
}

#[test]
fn test_err_display_default() {
let span = span::mock().named("err");
let (collector, handle) = collector::mock()
.new_span(span.clone())
.enter(span.clone())
.event(
event::mock().at_level(Level::ERROR).with_fields(
field::mock("error")
// by default, errors will be emitted with their display values
.with_value(&tracing::field::display(u8::try_from(1234).unwrap_err())),
),
)
.exit(span.clone())
.drop_span(span)
.done()
.run_with_handle();
with_default(collector, || err().ok());
handle.assert_finished();
}

0 comments on commit 41771ac

Please sign in to comment.