attributes: add `err(Debug)` meta to use `Debug` impl #1631

ciuncan · 2021-10-10T14:20:29Z

Motivation

This PR attempts to solve #1630 by introducing err_dbg 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_dbg makes expands to tracing::error!(error = ?e) which makes the error! macro to use Debug implementation for e. err and err_dbg are mutually exclusive, adding both will create a compilation error.

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_db similar to err,
Add err_dbg field to InstrumentArgs,
Add parsing for err_dbg arg and check for conflicts with err,
Generate tracing::error!(error = ?e) when err_dbg is true and tracing::error!(error = %e) when err is true,
Interpolate generated err_block into Err branches in both async and sync return positions, if err or err_dbg is true.

Even though I copied one of the tests, I'm not sure if it helps to check the new behavior. I manually tested it using VSCode/rust-analyzer's "Expand macro recursively" facility. But I am open to better test suggestions.

hawkw

Overall, this looks great. I had a few suggestions that we might want to address before merging this.

Also, it would be nice to add to the documentation for #[instrument(err)] to explain how to use Debug instead of Display using the new syntax:

tracing/tracing-attributes/src/lib.rs

Lines 184 to 193 in 9396211

    
           /// 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`: 
        
           /// 
        
           /// ``` 
        
           /// # use tracing_attributes::instrument; 
        
           /// #[instrument(err)] 
        
           /// fn my_function(arg: usize) -> Result<(), std::io::Error> { 
        
           ///     Ok(()) 
        
           /// } 
        
           /// ```

Thanks for working on this!!

hawkw · 2021-10-14T16:34:13Z

tracing-attributes/src/lib.rs

        ))
    })();

+    let err_block = match args.err_mode {


nit, take it or leave it: not sure if err_block is the best name for this; it's not actually a block, just an expression. maybe

Suggested change

let err_block = match args.err_mode {

let err_event = match args.err_mode {

hawkw · 2021-10-14T16:34:59Z

tracing-attributes/src/lib.rs

+        let mk_fut = match err_block {
+            Some(err_block) => quote_spanned!(block.span()=>


if you apply my naming suggestion from above, we would also need to change this

Suggested change

let mk_fut = match err_block {

Some(err_block) => quote_spanned!(block.span()=>

let mk_fut = match err_block {

Some(err_block) => quote_spanned!(block.span()=>

Suggested change

let mk_fut = match err_block {

Some(err_block) => quote_spanned!(block.span()=>

let mk_fut = match err_event {

Some(err_event) => quote_spanned!(block.span()=>

hawkw · 2021-10-14T16:38:26Z

tracing-attributes/src/lib.rs

                        Ok(x) => Ok(x),
                        Err(e) => {
-                            tracing::error!(error = %e);
+                            #err_block;


...and we'd change this as well

Suggested change

#err_block;

#err_event;

hawkw · 2021-10-14T16:38:54Z

tracing-attributes/src/lib.rs

    );

-    if err {
+    if let Some(err_block) = err_block {


...and we'd change this

Suggested change

if let Some(err_block) = err_block {

if let Some(err_event) = err_event {

hawkw · 2021-10-14T16:39:05Z

tracing-attributes/src/lib.rs

                Ok(x) => Ok(x),
                Err(e) => {
-                    tracing::error!(error = %e);
+                    #err_block;


Suggested change

#err_block;

#err_event;

hawkw · 2021-10-14T16:40:18Z

tracing-attributes/src/lib.rs

+}
+impl Default for ErrorMode {


nit: prefer a line of whitespace between definitions & impl blocks:

Suggested change

}

impl Default for ErrorMode {

}

impl Default for ErrorMode {

hawkw · 2021-10-14T16:53:38Z

tracing-attributes/src/lib.rs

+            let modes: Punctuated<ErrorMode, Token![,]> = content.parse_terminated(ErrorMode::parse)?;
+            let modes = modes.into_iter().collect::<HashSet<_>>();
+            return match modes.len() {
+                0 => Ok(Self(ErrorMode::Display)),
+                1 => Ok(Self(modes.into_iter().next().unwrap())),
+                _ => Err(syn::Error::new(
+                    content.span(),
+                    "at most one of Debug or Display can be given",
+                ))
+            }


I think we can simplify this a bit --- it shouldn't be necessary to use parse_terminated to parse any number of error modes, and then emit an error if we parsed more than one. I think, instead, we can use the Parse impl for Option<T: Parse + Token> in syn.

I believe that should allow us to replace the ErrorModes type entirely. We could move the parenthesized! inside the ErrorMode parser, and just try to parse an Option<ErrorMode> when we find an err` token.

This should hopefully be much simpler!

I might have misunderstood but, I couldn't implement Token trait. It appears to be supposed to parse some punctuation, identifiers, keywords etc. Also it looks like sealed.

I went ahead and utilized Option<Ident> to parse an ErrorMode by its name, I moved most of the parsing including the parenthesis into impl Parse for ErrorMode.

Overall this looks simpler, but let me know if I further can improve it.

hawkw · 2021-10-14T17:12:13Z

tracing-attributes/tests/err.rs

+    let (collector, handle) = collector::mock()
+        .new_span(span.clone())
+        .enter(span.clone())
+        .event(event::mock().at_level(Level::ERROR))


thanks for adding the test! it might be nice to change this line to also expect that the error field is recorded with its Debug implementation (rather than with Display).

we could do that like this:

Suggested change

.event(event::mock().at_level(Level::ERROR))

.event(

event::mock()

.at_level(Level::ERROR)

.with_field(

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())

)

)

but, the other tests don't make assertions about the formatted value of the error, so this isn't strictly necessary --- I just thought it might be nice.

Perfect! Honestly I didn't know what I was doing, and just copied one of the tests. This is what I was looking for. 👍 Will apply.

hawkw

Overall, this looks good to me --- I commented on a couple minor things. However, it does look like CI is failing because rustfmt needs to be run: https://github.com/tokio-rs/tracing/pull/1631/checks?check_run_id=3899421739 (this is actually my fault, since I wrote the suggestion for the test change in the GitHub suggestions UI and didn't run rustfmt on it...). Would you mind running rustfmt on this branch and committing the results?

hawkw · 2021-10-14T21:15:07Z

tracing-attributes/src/lib.rs

+/// The above example will be emitting error events using the `std::fmt::Display` implementation.
+/// If `E` implements `std::fmt::Debug`, you can also make it use that implementation with
+/// `err(Debug)`:


How about changing this to something like:

Suggested change

/// The above example will be emitting error events using the `std::fmt::Display` implementation.

/// If `E` implements `std::fmt::Debug`, you can also make it use that implementation with

/// `err(Debug)`:

/// 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)`:

hawkw · 2021-10-14T21:18:19Z

tracing-attributes/src/lib.rs

+struct ErrorModes(ErrorMode);
+
+impl Parse for ErrorModes {
+
+    fn parse(input: ParseStream<'_>) -> syn::Result<Self> {
+        let _ = input.parse::<kw::err>();
+        let mode = ErrorMode::parse(input)?;
+        Ok(Self(mode))
+    }
+}


I feel like the name ErrorModes is not really accurate for this anymore, since it no longer parses a list of error modes, and now simply parses the err keyword along with the mode. Maybe we should just rename it to

Suggested change

struct ErrorModes(ErrorMode);

impl Parse for ErrorModes {

fn parse(input: ParseStream<'_>) -> syn::Result<Self> {

let _ = input.parse::<kw::err>();

let mode = ErrorMode::parse(input)?;

Ok(Self(mode))

}

}

struct Error(ErrorMode);

impl Parse for Error {

fn parse(input: ParseStream<'_>) -> syn::Result<Self> {

let _ = input.parse::<kw::err>();

let mode = ErrorMode::parse(input)?;

Ok(Self(mode))

}

}

or, we could probably just get rid of this entirely, and move the err keyword into InstrumentArgs, like it was before --- we would just try to parse an ErrorMode if we parsed the err keyword, inside of the Parse impl for InstrumentArgs.

IMO, having a separate type for this is not really necessary any longer, but it's up to you...

That's right, I completely missed this. I think removing Error and doing err parsing into the InstrumentArgs Parse impl. 👍

ciuncan · 2021-10-14T21:36:56Z

Overall, this looks good to me --- I commented on a couple minor things. However, it does look like CI is failing because rustfmt needs to be run: https://github.com/tokio-rs/tracing/pull/1631/checks?check_run_id=3899421739 (this is actually my fault, since I wrote the suggestion for the test change in the GitHub suggestions UI and didn't run rustfmt on it...). Would you mind running rustfmt on this branch and committing the results?

Ah sorry about that, I didn't check style CI step. I was so used to my cargo-husky hooks on our repository, it runs it as pre-commit hook and prevents if there is any diff produced by cargo fmt, I guess I was spoiled by that. 😅

Applied the suggested changes 👍

hawkw

This looks great! Thanks again for working on this --- I'm going to go ahead and merge it when CI finishes!

## 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`.

@Swatinem

# 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

@Swatinem

# 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

@Swatinem

# 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

attributes: add err_dbg meta to use Debug impl

b8d94fe

ciuncan mentioned this pull request Oct 10, 2021

want way to ask #[instrument] to trace the return value #1281

Closed

attributes: switch to err(Debug)

83e030a

hawkw reviewed Oct 14, 2021

View reviewed changes

hawkw and others added 2 commits October 14, 2021 10:14

Merge branch 'master' into master

0bfac9f

attributes: add doc, test, simplify ErrorMode parsing

5768a50

ciuncan requested a review from hawkw October 14, 2021 18:26

hawkw marked this pull request as ready for review October 14, 2021 21:20

hawkw requested review from a team and davidbarsky as code owners October 14, 2021 21:20

hawkw reviewed Oct 14, 2021

View reviewed changes

attributes: remove ErrorModes, improve wording on doc, run fmt

db5a161

ciuncan force-pushed the master branch from a5316c7 to db5a161 Compare October 14, 2021 21:36

hawkw approved these changes Oct 14, 2021

View reviewed changes

hawkw changed the title ~~[WIP] attributes: add err_dbg meta to use Debug impl~~ attributes: add err(Debug) meta to use Debug impl Oct 14, 2021

hawkw merged commit a1868ea into tokio-rs:master Oct 15, 2021

hawkw mentioned this pull request Oct 15, 2021

Add ability to print error Result using err via Debug instead of only Display #1630

Open

hawkw mentioned this pull request Oct 22, 2021

remaining backports for tracing-subscriber 0.3 #1676

Merged

hawkw mentioned this pull request Feb 4, 2022

attributes: prepare to release 0.1.19 #1898

Merged

davidbarsky mentioned this pull request Sep 26, 2023

chore: backport roughly a year's worth of changes #2728

Merged

	/// 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`:
	///
	/// ```
	/// # use tracing_attributes::instrument;
	/// #[instrument(err)]
	/// fn my_function(arg: usize) -> Result<(), std::io::Error> {
	/// Ok(())
	/// }
	/// ```

	let err_block = match args.err_mode {
	let err_event = match args.err_mode {

		let mk_fut = match err_block {
		Some(err_block) => quote_spanned!(block.span()=>

	if let Some(err_block) = err_block {
	if let Some(err_event) = err_event {

-        .event(event::mock().at_level(Level::ERROR))
+        .event(
+            event::mock()
+                .at_level(Level::ERROR)
+                .with_field(
+                    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())
+                )
+        )

attributes: add err(Debug) meta to use Debug impl #1631

attributes: add err(Debug) meta to use Debug impl #1631

Conversation

ciuncan commented Oct 10, 2021

Motivation

Solution

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ciuncan commented Oct 14, 2021

Uh oh!

hawkw left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

attributes: add `err(Debug)` meta to use `Debug` impl #1631

attributes: add `err(Debug)` meta to use `Debug` impl #1631