-
Notifications
You must be signed in to change notification settings - Fork 688
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
attributes: implement #[instrument(ret)]
#1716
Conversation
## 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 } ```
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Parsing looks great 👍 But you should look into making sure that the block
only occurs once in output token stream or else that expression will run twice (if there were side effecting code, they would take effect twice).
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Thank you for working on this, this looks like a great start!
As @ciuncan pointed out, it's important to make sure we're not duplicating the input function's body (#block
) in the generated code --- this could result in the function being evaluated twice, which is potentially inefficient and, when the function's return value is non-deterministic or the function has side effects, could result in some very surprising bugs. So, we ought to fix that.
Also, before we merge this branch, we should also add documentation on using the ret
argument to the docs for instrument
. At a minimum, we can add examples similar to the existing ones for #[instrument(err)]
:
tracing/tracing-attributes/src/lib.rs
Lines 179 to 200 in b439705
/// If the function returns a `Result<T, E>` and `E` implements `std::fmt::Display`, you can add | |
/// `err` or `err(Display)` to emit error events when the function returns `Err`: | |
/// | |
/// ``` | |
/// # use tracing_attributes::instrument; | |
/// #[instrument(err)] | |
/// fn my_function(arg: usize) -> Result<(), std::io::Error> { | |
/// Ok(()) | |
/// } | |
/// ``` | |
/// | |
/// 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(()) | |
/// } | |
/// ``` |
It might also be nice to add a new documentation section on recording return values that summarizes both ret
and err
, as well as providing examples...but if you don't have the time to add that now, we can always do it in a follow-up branch.
I had some additional suggestions as well --- please let me know if you have any questions!
tracing-attributes/src/expand.rs
Outdated
Some(FormatMode::Display) => Some(quote!(tracing::trace!(return = %#block))), | ||
Some(FormatMode::Debug) => Some(quote!(tracing::trace!(return = ?#block))), |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
huh, i'm actually quite surprised that these macro invocations work --- return
is a Rust keyword, rather than an identifier, and the macros only accept an identifier or quoted string literal in the field name position. i would have epected that we would have to quote these, like
Some(FormatMode::Display) => Some(quote!(tracing::trace!(return = %#block))), | |
Some(FormatMode::Debug) => Some(quote!(tracing::trace!(return = ?#block))), | |
Some(FormatMode::Display) => Some(quote!(tracing::trace!("return" = %#block))), | |
Some(FormatMode::Debug) => Some(quote!(tracing::trace!("return" = ?#block))), |
if this actually does work, it's fine, but i'm kind of confused about why it works...
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
actually evaluating the block inside of the tracing macro (return = #block
) means the block will only be evaluated if the TRACE
level is enabled...which seems quite wrong, as it means the execution of the function might depend on the tracing filtering configuration. instead, we should always evaluate the block outside of the macro, binding the result to a variable, and then emit the event with that value.
in the case where the err
attribute is also enabled, that would mean moving the return event into the Ok
match arm, and recording the value inside the Ok
. when err
is not enabled, it would look more like:
Some(FormatMode::Display) => Some(quote!(tracing::trace!(return = %#block))), | |
Some(FormatMode::Debug) => Some(quote!(tracing::trace!(return = ?#block))), | |
quote!( | |
let ret = #block; | |
tracing::trace!(return = %ret))), | |
ret | |
) |
or similar.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
also, I'm not sure if I like that we'll always emit the return event at the TRACE
level. right now, there's no way to change the level of the return value event, so users could write code like
#[instrument(level = "info", ret(Debug))]
fn do_something(a: A) -> B {
// ...
}
enable the INFO
level, and be surprised when the span is enabled but the return value event is not emitted. instead, I think the best thing to do might be to emit the return value event at the same level as the span generated by instrument
. that seems like a reasonable default behavior to me.
it's certainly possible that people might want to emit the return value event at a different level, but i think that should be done by allowing users to explicitly set the level for the return event. i wouldn't implement that now, though, as it requires some extra work --- instead, I'd make a note of that as a potential follow-up if there's a need for it.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
actually evaluating the block inside of the tracing macro (return = #block) means the block will only be evaluated if the TRACE level is enabled...which seems quite wrong, as it means the execution of the function might depend on the tracing filtering configuration. instead, we should always evaluate the block outside of the macro, binding the result to a variable, and then emit the event with that value.
I guess this is fixed by f7cd4c4.
enable the INFO level, and be surprised when the span is enabled but the return value event is not emitted. instead, I think the best thing to do might be to emit the return value event at the same level as the span generated by instrument. that seems like a reasonable default behavior to me.
That sounds really good to me. This looks achievable by using Addressed by 16e8bf1.InstrumentArgs::level()
.
@@ -356,4 +361,5 @@ mod kw { | |||
syn::custom_keyword!(target); | |||
syn::custom_keyword!(name); | |||
syn::custom_keyword!(err); | |||
syn::custom_keyword!(ret); |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
personally, my preference would be to use return
rather than ret
, for consistency with the return
keyword --- the abbreviation feels like it would just make things more confusing for the user. I'm open to being convinced otherwise, though, if most folks think that saving three letters here is really important...
also, the field name is return
rather than ret
, so it's a little surprising that they are different.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
hmm, that's a good point; I hadn't considered that...
Now that `ret` displays `Result::Ok` but not `Result`, there are some case that `ret(Debug)` is not necessary any longer.
} | ||
let content; | ||
let _ = syn::parenthesized!(content in input); | ||
let maybe_mode: Option<Ident> = content.parse()?; | ||
maybe_mode.map_or(Ok(ErrorMode::default()), |ident| { | ||
maybe_mode.map_or(Ok(FormatMode::default()), |ident| { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I don't think Display
should be the default for return values, personally. Most return values will likely not implement Display
--- Display
was the default for errors simply because most errors implement the std::error::Error
trait, which requires them to be Display
. If we're always going to format return values, we should probably default to using Debug
, and make Display
be the one that the user opts in to.
With that said, I think we may actually want to change so that the default behavior is to record the return value as a tracing
primitive value if it's one of the primitive Value
types, and fall back to Display
if it's not. We can look at the function signature's return type, and we already have code for determining whether a type is a primitive Value
:
tracing/tracing-attributes/src/expand.rs
Lines 345 to 398 in f513f4a
impl RecordType { | |
/// Array of primitive types which should be recorded as [RecordType::Value]. | |
const TYPES_FOR_VALUE: &'static [&'static str] = &[ | |
"bool", | |
"str", | |
"u8", | |
"i8", | |
"u16", | |
"i16", | |
"u32", | |
"i32", | |
"u64", | |
"i64", | |
"f32", | |
"f64", | |
"usize", | |
"isize", | |
"NonZeroU8", | |
"NonZeroI8", | |
"NonZeroU16", | |
"NonZeroI16", | |
"NonZeroU32", | |
"NonZeroI32", | |
"NonZeroU64", | |
"NonZeroI64", | |
"NonZeroUsize", | |
"NonZeroIsize", | |
"Wrapping", | |
]; | |
/// Parse `RecordType` from [syn::Type] by looking up | |
/// the [RecordType::TYPES_FOR_VALUE] array. | |
fn parse_from_ty(ty: &syn::Type) -> Self { | |
match ty { | |
syn::Type::Path(syn::TypePath { path, .. }) | |
if path | |
.segments | |
.iter() | |
.last() | |
.map(|path_segment| { | |
let ident = path_segment.ident.to_string(); | |
Self::TYPES_FOR_VALUE.iter().any(|&t| t == ident) | |
}) | |
.unwrap_or(false) => | |
{ | |
RecordType::Value | |
} | |
syn::Type::Reference(syn::TypeReference { elem, .. }) => { | |
RecordType::parse_from_ty(&*elem) | |
} | |
_ => RecordType::Debug, | |
} | |
} | |
} |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Because we are special-casing Result<T, E>
s, in order to do fallback'ing we need to extract T
from the Result
of syn::Type
being returned, which I can find the way to do it. Therefore I'd go with the former change.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Hmm, that's fair; I think it should be possible to find Result
s and get the type parameter using syn
, but it might be fairly complex. We can always add that in a future change.
minor fix on documentation Co-authored-by: Eliza Weisman <eliza@buoyant.io>
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
a few minor things, but once they're addressed, I think this should be good!
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
Co-authored-by: Eliza Weisman <eliza@buoyant.io>
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Okay, this looks great --- thanks for working on this!
* 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 <eliza@buoyant.io>
* 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 <eliza@buoyant.io>
* 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 <eliza@buoyant.io>
* 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 <eliza@buoyant.io>
* 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 <eliza@buoyant.io>
# 0.1.19 (February 3, 2022) This release introduces a new `#[instrument(ret)]` argument to emit an event with the return value of an instrumented function. ### Added - `#[instrument(ret)]` to record the return value of a function ([#1716]) - added `err(Debug)` argument to cause `#[instrument(err)]` to record errors with `Debug` rather than `Display ([#1631]) ### Fixed - incorrect code generation for functions returning async blocks ([#1866]) - incorrect diagnostics when using `rust-analyzer` ([#1634]) Thanks to @Swatinem, @hkmatsumoto, @cynecx, and @ciuncan for contributing to this release! [#1716]: #1716 [#1631]: #1631 [#1634]: #1634 [#1866]: #1866
# 0.1.19 (February 3, 2022) This release introduces a new `#[instrument(ret)]` argument to emit an event with the return value of an instrumented function. ### Added - `#[instrument(ret)]` to record the return value of a function ([#1716]) - added `err(Debug)` argument to cause `#[instrument(err)]` to record errors with `Debug` rather than `Display ([#1631]) ### Fixed - incorrect code generation for functions returning async blocks ([#1866]) - incorrect diagnostics when using `rust-analyzer` ([#1634]) Thanks to @Swatinem, @hkmatsumoto, @cynecx, and @ciuncan for contributing to this release! [#1716]: #1716 [#1631]: #1631 [#1634]: #1634 [#1866]: #1866
# 0.1.19 (February 3, 2022) This release introduces a new `#[instrument(ret)]` argument to emit an event with the return value of an instrumented function. ### Added - `#[instrument(ret)]` to record the return value of a function ([tokio-rs#1716]) - added `err(Debug)` argument to cause `#[instrument(err)]` to record errors with `Debug` rather than `Display ([tokio-rs#1631]) ### Fixed - incorrect code generation for functions returning async blocks ([tokio-rs#1866]) - incorrect diagnostics when using `rust-analyzer` ([tokio-rs#1634]) Thanks to @Swatinem, @hkmatsumoto, @cynecx, and @ciuncan for contributing to this release! [tokio-rs#1716]: tokio-rs#1716 [tokio-rs#1631]: tokio-rs#1631 [tokio-rs#1634]: tokio-rs#1634 [tokio-rs#1866]: tokio-rs#1866
Motivation
Currently, users have to explicitly call logging functions at the end of
functions if they wanted to record values being returned. For example,
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.
Closes #1281.