From 2a4f7ed0ef5bcea2d2e3cf77430f626d56766dfc Mon Sep 17 00:00:00 2001 From: Hirochika Matsumoto Date: Tue, 30 Nov 2021 06:33:43 +0900 Subject: [PATCH] attributes: implement `#[instrument(ret)]` (#1716) * attributes: implement `#[instrument(ret)]` ## Motivation Currently, users have to explicitly call logging functions at the end of functions if they wanted to record values being returned. For example, ```rust fn increment(a: i32) -> i32 { let succ = a + 1; tracing::debug!(?succ); succ } ``` The code above will be significantly simpler if we provide the functionality to record returned values. ## Solution This PR adds the exact feature we're talking here, which enables users to write the code below instead. ```rust #[instrument(ret)] fn increment(a: i32) -> i32 { a + 1 } ``` Co-authored-by: Eliza Weisman --- tracing-attributes/src/attr.rs | 27 ++-- tracing-attributes/src/expand.rs | 101 ++++++++++---- tracing-attributes/src/lib.rs | 40 ++++++ tracing-attributes/tests/ret.rs | 226 +++++++++++++++++++++++++++++++ 4 files changed, 361 insertions(+), 33 deletions(-) create mode 100644 tracing-attributes/tests/ret.rs diff --git a/tracing-attributes/src/attr.rs b/tracing-attributes/src/attr.rs index 617f4bd772..2e2ef1502d 100644 --- a/tracing-attributes/src/attr.rs +++ b/tracing-attributes/src/attr.rs @@ -14,7 +14,8 @@ pub(crate) struct InstrumentArgs { pub(crate) skips: HashSet, pub(crate) skip_all: bool, pub(crate) fields: Option, - pub(crate) err_mode: Option, + pub(crate) err_mode: Option, + pub(crate) ret_mode: Option, /// Errors describing any unrecognized parse inputs that we skipped. parse_warnings: Vec, } @@ -152,8 +153,12 @@ impl Parse for InstrumentArgs { args.fields = Some(input.parse()?); } else if lookahead.peek(kw::err) { let _ = input.parse::(); - let mode = ErrorMode::parse(input)?; + let mode = FormatMode::parse(input)?; args.err_mode = Some(mode); + } else if lookahead.peek(kw::ret) { + let _ = input.parse::()?; + let mode = FormatMode::parse(input)?; + args.ret_mode = Some(mode); } else if lookahead.peek(Token![,]) { let _ = input.parse::()?; } else { @@ -212,29 +217,30 @@ impl Parse for Skips { } #[derive(Clone, Debug, Hash, PartialEq, Eq)] -pub(crate) enum ErrorMode { +pub(crate) enum FormatMode { + Default, Display, Debug, } -impl Default for ErrorMode { +impl Default for FormatMode { fn default() -> Self { - ErrorMode::Display + FormatMode::Default } } -impl Parse for ErrorMode { +impl Parse for FormatMode { fn parse(input: ParseStream<'_>) -> syn::Result { if !input.peek(syn::token::Paren) { - return Ok(ErrorMode::default()); + return Ok(FormatMode::default()); } let content; let _ = syn::parenthesized!(content in input); let maybe_mode: Option = content.parse()?; - maybe_mode.map_or(Ok(ErrorMode::default()), |ident| { + maybe_mode.map_or(Ok(FormatMode::default()), |ident| { match ident.to_string().as_str() { - "Debug" => Ok(ErrorMode::Debug), - "Display" => Ok(ErrorMode::Display), + "Debug" => Ok(FormatMode::Debug), + "Display" => Ok(FormatMode::Display), _ => Err(syn::Error::new( ident.span(), "unknown error mode, must be Debug or Display", @@ -370,4 +376,5 @@ mod kw { syn::custom_keyword!(target); syn::custom_keyword!(name); syn::custom_keyword!(err); + syn::custom_keyword!(ret); } diff --git a/tracing-attributes/src/expand.rs b/tracing-attributes/src/expand.rs index 9f5ccd14de..e9b4f898c6 100644 --- a/tracing-attributes/src/expand.rs +++ b/tracing-attributes/src/expand.rs @@ -9,7 +9,7 @@ use syn::{ }; use crate::{ - attr::{ErrorMode, Field, Fields, InstrumentArgs}, + attr::{Field, Fields, FormatMode, InstrumentArgs}, MaybeItemFnRef, }; @@ -191,8 +191,18 @@ 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))), + Some(FormatMode::Default) | Some(FormatMode::Display) => { + Some(quote!(tracing::error!(error = %e))) + } + Some(FormatMode::Debug) => Some(quote!(tracing::error!(error = ?e))), + _ => None, + }; + + let ret_event = match args.ret_mode { + Some(FormatMode::Display) => Some(quote!(tracing::event!(#level, return = %x))), + Some(FormatMode::Default) | Some(FormatMode::Debug) => { + Some(quote!(tracing::event!(#level, return = ?x))) + } _ => None, }; @@ -201,9 +211,26 @@ fn gen_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 `ret` is in args, instrument any resulting `Ok`s when the function + // returns `Result`s, otherwise instrument any resulting values. if async_context { - let mk_fut = match err_event { - Some(err_event) => quote_spanned!(block.span()=> + let mk_fut = match (err_event, ret_event) { + (Some(err_event), Some(ret_event)) => quote_spanned!(block.span()=> + async move { + match async move { #block }.await { + #[allow(clippy::unit_arg)] + Ok(x) => { + #ret_event; + Ok(x) + }, + Err(e) => { + #err_event; + Err(e) + } + } + } + ), + (Some(err_event), None) => quote_spanned!(block.span()=> async move { match async move { #block }.await { #[allow(clippy::unit_arg)] @@ -215,7 +242,14 @@ fn gen_block( } } ), - None => quote_spanned!(block.span()=> + (None, Some(ret_event)) => quote_spanned!(block.span()=> + async move { + let x = async move { #block }.await; + #ret_event; + x + } + ), + (None, None) => quote_spanned!(block.span()=> async move { #block } ), }; @@ -254,8 +288,23 @@ fn gen_block( } ); - if let Some(err_event) = err_event { - return quote_spanned!(block.span()=> + match (err_event, ret_event) { + (Some(err_event), Some(ret_event)) => quote_spanned! {block.span()=> + #span + #[allow(clippy::redundant_closure_call)] + match (move || #block)() { + #[allow(clippy::unit_arg)] + Ok(x) => { + #ret_event; + Ok(x) + }, + Err(e) => { + #err_event; + Err(e) + } + } + }, + (Some(err_event), None) => quote_spanned!(block.span()=> #span #[allow(clippy::redundant_closure_call)] match (move || #block)() { @@ -266,22 +315,28 @@ fn gen_block( Err(e) } } - ); - } - - quote_spanned!(block.span() => - // Because `quote` produces a stream of tokens _without_ whitespace, the - // `if` and the block will appear directly next to each other. This - // generates a clippy lint about suspicious `if/else` formatting. - // Therefore, suppress the lint inside the generated code... - #[allow(clippy::suspicious_else_formatting)] - { + ), + (None, Some(ret_event)) => quote_spanned!(block.span()=> #span - // ...but turn the lint back on inside the function body. - #[warn(clippy::suspicious_else_formatting)] - #block - } - ) + #[allow(clippy::redundant_closure_call)] + let x = (move || #block)(); + #ret_event; + x + ), + (None, None) => quote_spanned!(block.span() => + // Because `quote` produces a stream of tokens _without_ whitespace, the + // `if` and the block will appear directly next to each other. This + // generates a clippy lint about suspicious `if/else` formatting. + // Therefore, suppress the lint inside the generated code... + #[allow(clippy::suspicious_else_formatting)] + { + #span + // ...but turn the lint back on inside the function body. + #[warn(clippy::suspicious_else_formatting)] + #block + } + ), + } } /// Indicates whether a field should be recorded as `Value` or `Debug`. diff --git a/tracing-attributes/src/lib.rs b/tracing-attributes/src/lib.rs index b07461c22e..a321962ca6 100644 --- a/tracing-attributes/src/lib.rs +++ b/tracing-attributes/src/lib.rs @@ -368,6 +368,35 @@ mod expand; /// } /// ``` /// +/// Adding the `ret` argument to `#[instrument]` will emit an event with the function's +/// return value when the function returns: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(ret)] +/// fn my_function() -> i32 { +/// 42 +/// } +/// ``` +/// The return value event will have the same level as the span generated by `#[instrument]`. +/// By default, this will be `TRACE`, but if the level is overridden, the event will be at the same +/// level. +/// +/// **Note**: if the function returns a `Result`, `ret` will record returned values if and +/// only if the function returns [`Result::Ok`]. +/// +/// By default, returned values will be recorded using their [`std::fmt::Debug`] implementations. +/// If a returned value implements [`std::fmt::Display`], it can be recorded using its `Display` +/// implementation instead, by writing `ret(Display)`: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(ret(Display))] +/// fn my_function() -> i32 { +/// 42 +/// } +/// ``` +/// /// If the function returns a `Result` and `E` implements `std::fmt::Display`, you can add /// `err` or `err(Display)` to emit error events when the function returns `Err`: /// @@ -391,6 +420,17 @@ mod expand; /// } /// ``` /// +/// The `ret` and `err` arguments can be combined in order to record an event if a +/// function returns [`Result::Ok`] or [`Result::Err`]: +/// +/// ``` +/// # use tracing_attributes::instrument; +/// #[instrument(err, ret)] +/// fn my_function(arg: usize) -> Result<(), std::io::Error> { +/// Ok(()) +/// } +/// ``` +/// /// `async fn`s may also be instrumented: /// /// ``` diff --git a/tracing-attributes/tests/ret.rs b/tracing-attributes/tests/ret.rs new file mode 100644 index 0000000000..af23182a61 --- /dev/null +++ b/tracing-attributes/tests/ret.rs @@ -0,0 +1,226 @@ +#[path = "../../tracing-futures/tests/support.rs"] +// we don't use some of the test support functions, but `tracing-futures` does. +#[allow(dead_code)] +mod support; +use support::*; + +use std::convert::TryFrom; +use std::num::TryFromIntError; + +use tracing::{subscriber::with_default, Level}; +use tracing_attributes::instrument; + +#[instrument(ret)] +fn ret() -> i32 { + 42 +} + +#[test] +fn test() { + let span = span::mock().named("ret"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret); + handle.assert_finished(); +} + +#[instrument(level = "warn", ret)] +fn ret_warn() -> i32 { + 42 +} + +#[test] +fn test_warn() { + let span = span::mock().named("ret_warn"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::WARN), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret_warn); + handle.assert_finished(); +} + +#[instrument(ret)] +fn ret_mut(a: &mut i32) -> i32 { + *a *= 2; + tracing::info!(?a); + *a +} + +#[test] +fn test_mut() { + let span = span::mock().named("ret_mut"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("a").with_value(&tracing::field::display(2))) + .at_level(Level::INFO), + ) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(2))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || ret_mut(&mut 1)); + handle.assert_finished(); +} + +#[instrument(ret)] +async fn ret_async() -> i32 { + 42 +} + +#[test] +fn test_async() { + let span = span::mock().named("ret_async"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || block_on_future(async { ret_async().await })); + handle.assert_finished(); +} + +#[instrument(ret)] +fn ret_impl_type() -> impl Copy { + 42 +} + +#[test] +fn test_impl_type() { + let span = span::mock().named("ret_impl_type"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::debug(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret_impl_type); + handle.assert_finished(); +} + +#[instrument(ret(Display))] +fn ret_display() -> i32 { + 42 +} + +#[test] +fn test_dbg() { + let span = span::mock().named("ret_display"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields(field::mock("return").with_value(&tracing::field::display(42))) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, ret_display); + handle.assert_finished(); +} + +#[instrument(err, ret)] +fn ret_and_err() -> Result { + u8::try_from(1234) +} + +#[test] +fn test_ret_and_err() { + let span = span::mock().named("ret_and_err"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields( + field::mock("error") + .with_value(&tracing::field::display(u8::try_from(1234).unwrap_err())) + .only(), + ) + .at_level(Level::ERROR), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || ret_and_err().ok()); + handle.assert_finished(); +} + +#[instrument(err, ret)] +fn ret_and_ok() -> Result { + u8::try_from(123) +} + +#[test] +fn test_ret_and_ok() { + let span = span::mock().named("ret_and_ok"); + let (subscriber, handle) = subscriber::mock() + .new_span(span.clone()) + .enter(span.clone()) + .event( + event::mock() + .with_fields( + field::mock("return") + .with_value(&tracing::field::debug(u8::try_from(123).unwrap())) + .only(), + ) + .at_level(Level::INFO), + ) + .exit(span.clone()) + .drop_span(span) + .done() + .run_with_handle(); + + with_default(subscriber, || ret_and_ok().ok()); + handle.assert_finished(); +}