[tracing-attributes] Support for using #[instrument] with async-trait #711

nightmared · 2020-05-10T10:25:08Z

Rewrite the block when it looks like there is async_trait involved to wrap the internal async function instead of the
wrapper generated by asyc-trait
Rewrite '_self' as 'self' when using #[instrument] jointly with async-trait
Add somes tests

Motivation

As outlined in #399, right now tracing-futures (or more precisely, the code generated by #[instrument]) is not working well with async-trait. What happens is that async-trait rewrites the trait method as a non-async function, insides of which it pins the async method we want to instrument, and we end up instrumenting the wrapper instead of the async fn.

This will allow people to use traits with (seemingly) async functions along with #[instrument].

Solution

I decided to follow the discussion at dtolnay/async-trait#45 and see if I could make it working. Right now I would describe its state as "works for me, and should work for everyone".

nightmared · 2020-05-10T11:56:51Z

Disclaimer: I have absolutely no idea why the test failed on field_filter_events, especially considering it doesn't appears to use #[instrument], and it's the only piece of code I touched. SO maybe some spurious event ?

Also: I deleted the test field_filter_events in tracing-subscriber/tests/filter.rs as it appears to be a duplicated of field_filter_events in tracing-subscriber/tests/field_filter.rs.

--

Looks like it's #449 ;)

--

Aaaaand there it goes ;)
If you want me to remove the last commit (because it's not really the point of this PR), or if you want me to rebase the above commits, please tell me, I would be happy to.

hawkw · 2020-05-10T17:56:44Z

This is great, thanks for working on it!

Disclaimer: I have absolutely no idea why the test failed on field_filter_events, especially considering it doesn't appears to use #[instrument], and it's the only piece of code I touched. SO maybe some spurious event ?

Also: I deleted the test field_filter_events in tracing-subscriber/tests/filter.rs as it appears to be a duplicated of field_filter_events in tracing-subscriber/tests/field_filter.rs.

--

Looks like it's #449 ;)

Yeah, that's correct, this test occasionally fails spuriously. I hadn't realized there was a duplicate copy of the test --- it was moved to its own module to prevent racy behavior between the test and other tests that might result in this kind of spurious failure. If the version in filter.rs was not deleted, that might explain the spurious failures!

If you don't mind, it would be great to open a separate PR removing the duplicate test, so that it's not part of the squashed commit on master for this PR when we merge it? Thanks!

nightmared · 2020-05-10T18:51:09Z

Wow, did I ran into a race condition with the update of the rust version or is the network "just" flaky ? Guess I will never know: https://github.com/tokio-rs/tracing/runs/661243980

--
It's probably just 'cause I'm a noob with Github Actions, but I didn't know how to trigger the checks again, so I "force pushed" the commit.

…rait * Rewrite the block when it looks like there is async_trait involved to wrap the internal async function instead of the wrapper generated by asyc-trait * Rewrite '_self' as 'self' when using #[instrument] jointly with async-trait * Add somes tests * Remove the mention that async-trait is not supported with tracing

This removes the test `field_filter_events` in `tracing-subscriber/tests/filter.rs` as it appears to be a duplicate of `field_filter_events` in `tracing-subscriber/tests/field_filter.rs` (see discussion at #711 (comment)).

davidbarsky · 2020-05-11T19:02:13Z

tracing-attributes/Cargo.toml



 [dev-dependencies]
 tracing = { path = "../tracing", version = "0.1" }
 tracing-futures = { path = "../tracing-futures", version = "0.2" }
 tokio-test = { version = "0.2.0" }
 tracing-core = { path = "../tracing-core", version = "0.1"}
+# I'm not a huge fan of adding such a dependency only for tests, any idea ?


/md I think taking a dependency is fine. This PR is meant to address a poor interaction between the two crates, so it makes sense to depend on the crate that previously caused a poor interaction.

nightmared · 2020-05-12T14:40:49Z

Any idea on how to improve this ?

hawkw · 2020-05-10T17:57:38Z

tracing-attributes/Cargo.toml

+# I'm not a huge fan of adding such a dependency only for tests, any idea ?
+async-trait = "0.1"


I believe dev dependencies will only be downloaded when running tests, so I don't think this is a huge deal. If it is an issue, we can also move the tests for compatibility with async-trait to a separate crate that is used only for testing.

You're right, "Dev-dependencies are not used when compiling a package for building, but are used for compiling tests, examples, and benchmarks.

These dependencies are not propagated to other packages which depend on this package."

So it's finally not that big of an issue, as you said. Alas, I never took the time to "read" (instead of looking at it when in need) the cargo book and it looks like I'm still learning the basics of cargo sometimes ^^

Great, let's just add the dev dependency, then. Since this isn't an issue, we can remove the comment.

hawkw · 2020-05-12T20:42:10Z

Any idea on how to improve this ?

Sorry, I just haven't gotten the chance to take a close look at the change yet. I'm planning on giving it a more thorough review this afternoon. At a glance, it looks good!

hawkw

This looks good overall — the approach used seems correct. I had some style notes, but didn't see any major issues.

hawkw · 2020-05-12T20:43:25Z

tracing-attributes/src/lib.rs

@@ -168,6 +168,28 @@ use syn::{
 ///     # Ok(())
 /// }
 /// ```
+///
+/// It also works with async-trait (and hopefully most of the libraries that does similar things):


Can we add a link to the async-trait crate here?

hawkw · 2020-05-12T20:46:49Z

tracing-attributes/tests/async_fn.rs

+        .new_span(span.clone())
+        .enter(span.clone())
+        .new_span(span2.clone())


Should we also assert that the spans are created with the correct fields?

hawkw · 2020-05-12T20:48:44Z

tracing-attributes/src/lib.rs

+// terrible machinery to make async_trait-like cases works
+// (following the approach suggested in
+// https://github.com/dtolnay/async-trait/issues/45#issuecomment-571245673)
+fn is_async_trait(block: &Block, block_is_async: bool) -> Option<String> {


Nit, take it or leave it: In general, I try to reserve is_ for functions that return a boolean. This is returning the name of the async-trait-generated inner function, if it exists...

hawkw · 2020-05-12T20:50:00Z

tracing-attributes/src/lib.rs

+                == path
+                    .path
+                    .segments
+                    .iter()
+                    .map(|x| x.ident.to_string())
+                    .collect::<Vec<String>>()
+                    .join("::")


nit: can we maybe move this long expression to a let-binding outside the if condition? this is a little hard to follow IMO.

hawkw · 2020-05-12T20:55:36Z

tracing-attributes/src/lib.rs

+                    .map(|x| x.ident.to_string())
+                    .collect::<Vec<String>>()


I think we could avoid a couple of allocations if we did this by creating a string and used push_str to append the string slices from the path.segments iterator, rather than creating a String from each string slice and collecting them into a Vec. I don't think this is hot enough that this is terribly important though, so it's fine as-is.

tracing-attributes/src/lib.rs

hawkw · 2020-05-12T20:57:11Z

tracing-attributes/src/lib.rs

            .clone()
            .into_iter()
            .flat_map(|param| match param {
                FnArg::Typed(PatType { pat, .. }) => param_names(*pat),
                FnArg::Receiver(_) => Box::new(iter::once(Ident::new("self", param.span()))),
            })
+            // if we are inside a function generated by async-trait, we should take care to rewrite
+            // "_self" as "self" for 'user convenience'


I think the presence of a _self identifier is another likely marker that async-trait is in use...should that be part of our heuristic for detecting async-trait as well?

You're right that we could do that to assert with more certainty that we are facing a aync_trait-like situation (aka: it is more probable that async_trait is in use if you see the the both pattern fn f(...) Box::pin(f(...)) and _self) , but this is not necessarily true will all traits, so its absence cannot rule out the use of async_trait. Consider this for example:

#[async_trait] pub trait Foo { async fn foo(v: usize) -> (); }

This foo method on this trait doesn't take self, so async_trait won't give us a _self parameter for that function either.

In the end, if we want to use this variable renaming to be more precise, maybe we can consider that functions with the fn f(...) Box::pin(f(...)) pattern but with self as an argument are not cases of async_trait, as self should have been rewritten to ``self. But I wonder if there are other crates that exists and that does similar things without renaming self` to `_self` or with a different name, and that we don't want to exclude simply because they don't apply the exact same mechanisms as async_trait.

That's fair, I think the pattern we're detecting is much more reliable.

hawkw · 2020-05-12T23:35:46Z

@nightmared as a heads-up, I'll probably also want to merge PR #672 at some point in the near future. That branch probably conflicts w/ this one, so depending on which one merges first, you might need to make some changes after rebasing.

nightmared · 2020-05-13T05:50:26Z

Thanks for the review, I will probably fix these later today.

hawkw

This looks great. I had a few additional suggestions, but I'm happy with this as-is (although, let's remove the comment about dev-dependencies).

I was going to ask that we try to wrap the comments here more consistently with the existing comments in this file, but it looks like the line wrapping here is already not consistent. We can fix that later.

hawkw · 2020-05-13T17:24:45Z

tracing-attributes/Cargo.toml

+# I'm not a huge fan of adding such a dependency only for tests, any idea ?
+async-trait = "0.1"


Great, let's just add the dev dependency, then. Since this isn't an issue, we can remove the comment.

hawkw · 2020-05-13T17:25:50Z

tracing-attributes/src/lib.rs

+/// It also works with [async-trait](https://crates.io/crates/async-trait) (a crate that allows
+/// async functions on traits, something not currently possible in rust), and hopefully most
+/// libraries that exhibit similar behaviors:


Nitpick: can we wrap these comments consistently with other comments in this file?

hawkw · 2020-05-13T17:27:49Z

tracing-attributes/src/lib.rs

+    // obtain the list of direct internal functions and the last expression of the block
+    for stmt in &block.stmts {
+        if let Stmt::Item(Item::Fn(fun)) = &stmt {
+            // is the function declared as async ? If so, this is a good candidate, let's keep it


nit:

Suggested change

// is the function declared as async ? If so, this is a good candidate, let's keep it

// is the function declared as async? If so, this is a good candidate, let's keep it

hawkw · 2020-05-13T17:28:04Z

tracing-attributes/src/lib.rs

+    })) = last_expr
+    {
+        if let Expr::Path(path) = outside_func.as_ref() {
+            // is it a call to `Box::pin()` ?


nit

Suggested change

// is it a call to `Box::pin()` ?

// is it a call to `Box::pin()`?

hawkw · 2020-05-13T17:29:50Z

tracing-attributes/src/lib.rs

+            let mut merged_path = String::new();
+            for i in 0..path.path.segments.len() {
+                merged_path.push_str(&path.path.segments[i].ident.to_string());
+                if i < path.path.segments.len() - 1 {
+                    merged_path.push_str("::");
+                }
+            }


Take it or leave it: this seems like it could be factored out into a helper function that we could also use here

tracing/tracing-attributes/src/lib.rs

Lines 737 to 743 in 9b07f86

let func_name = inside_path

.path

.segments

.iter()

.map(|x| x.ident.to_string())

.collect::<Vec<String>>()

.join("::");

hawkw · 2020-05-13T17:43:50Z

tracing-attributes/src/lib.rs

+            // is it a call to `Box::pin()` ?
+            let mut merged_path = String::new();
+            for i in 0..path.path.segments.len() {
+                merged_path.push_str(&path.path.segments[i].ident.to_string());


What we're doing here is writing the ident's fmt::Display output to the end of path_str. Using to_string() creates a new String, which allocates memory for a new string that we then immediately throw away. What if we used write! instead, like this:

Suggested change

merged_path.push_str(&path.path.segments[i].ident.to_string());

use std::fmt::Write;

write!(&mut merged_path, "{}", &path.path.segments[i].ident.to_string())

.expect("writing to a String never fails");

hawkw · 2020-05-13T17:44:11Z

tracing-attributes/src/lib.rs

+            }
+
+            if "Box::pin" == merged_path {
+                // does it takes at least an argument ? (if it doesn't, it's not gonna compile anyway,


nnit

Suggested change

// does it takes at least an argument ? (if it doesn't, it's not gonna compile anyway,

// does it takes at least an argument? (if it doesn't, it's not gonna compile anyway,

hawkw · 2020-05-13T17:44:34Z

tracing-attributes/src/lib.rs

+                if outside_args.is_empty() {
+                    return None;
+                }
+                // is the argument to Box::pin a function call itself ?


nit:

Suggested change

// is the argument to Box::pin a function call itself ?

// is the argument to Box::pin a function call itself?

hawkw · 2020-05-13T17:44:56Z

tracing-attributes/src/lib.rs

+                            .map(|x| x.ident.to_string())
+                            .collect::<Vec<String>>()
+                            .join("::");
+                        // is this function directly defined insided the current block ?


nit:

Suggested change

// is this function directly defined insided the current block ?

// is this function directly defined insided the current block?

hawkw · 2020-05-13T17:45:16Z

tracing-attributes/src/lib.rs

+    if let Some(internal_fun_name) =
+        get_async_trait_name(&input.block, input.sig.asyncness.is_some())
+    {
+        // let's rewrite some statements !


nit:

Suggested change

// let's rewrite some statements !

// let's rewrite some statements!

hawkw

Wonderful, this looks great and I'm going to go ahead and merge it.

Thanks so much for working on this, @nightmared, I think you've just made a lot of folks very happy! :)

nightmared · 2020-05-13T20:01:01Z

Happy to, I wanted to try tracing, and I was frustrated to learn that tracing wasn't working on the very project I wanted to test it on, so I figured that I could take a look ;)
Thanks for the reviews and the time you spent on this.

@ilana

0.1.8 (May 13, 2020) Added: - Support for using `#[instrument]` on methods that are part of [`async-trait`] trait implementations (#711) - Optional `#[instrument(err)]` argument to automatically emit an event if an instrumented function returns `Err` (#637) Thanks to @ilana and @nightmared for contributing to this release! [`async-trait`]: https://crates.io/crates/async-trait Signed-off-by: Eliza Weisman <eliza@buoyant.io>

@ilana

0.1.8 (May 13, 2020) Added: - Support for using `#[instrument]` on methods that are part of [`async-trait`] trait implementations (#711) - Optional `#[instrument(err)]` argument to automatically emit an event if an instrumented function returns `Err` (#637) Thanks to @ilana and @nightmared for contributing to this release! [`async-trait`]: https://crates.io/crates/async-trait Signed-off-by: Eliza Weisman <eliza@buoyant.io>

@FintanH

# 0.1.14 (May 14, 2020) ### Added - **log**: When using the [`log`] compatibility feature alongside a `tracing` `Subscriber`, log records for spans now include span IDs (#613) - **attributes**: Support for using `#[instrument]` on methods that are part of [`async-trait`] trait implementations (#711) - **attributes**: Optional `#[instrument(err)]` argument to automatically emit an event if an instrumented function returns `Err` (#637) - Added `#[must_use]` attribute to the guard returned by `subscriber::set_default` (#685) ### Changed - **log**: Made [`log`] records emitted by spans much less noisy when span IDs are not available (#613) ### Fixed - Several typos in the documentation (#656, #710, #715) Thanks to @FintanH, @shepmaster, @inanna-malick, @zekisharif, @bkchr, @majecty, @ilana and @nightmared for contributing to this release! [`async-trait`]: https://crates.io/crates/async-traite! [`log`]: https://crates.io/crates/log

nightmared requested review from hawkw and a team as code owners May 10, 2020 10:25

nightmared mentioned this pull request May 10, 2020

[tracing-subscriber] remove the duplicated test 'field_filter_events' #712

Merged

davidbarsky reviewed May 11, 2020

View reviewed changes

hawkw reviewed May 12, 2020

View reviewed changes

improve readability and tests

9b07f86

hawkw approved these changes May 13, 2020

View reviewed changes

nightmared added 2 commits May 13, 2020 20:27

fixes, part. 2

f54465d

reflow comments

d5f7d72

hawkw approved these changes May 13, 2020

View reviewed changes

hawkw merged commit 369b0c5 into tokio-rs:master May 13, 2020

nightmared deleted the fix-399-async-trait branch May 13, 2020 20:02

hawkw mentioned this pull request May 13, 2020

attributes: prepare to release v0.1.8 #714

Merged

hawkw mentioned this pull request May 14, 2020

tracing: prepare to release 0.1.14 #716

Merged

hawkw mentioned this pull request May 23, 2020

attributes: support arbitrary field expressions #672

Merged

nightmared mentioned this pull request Feb 3, 2021

#[instrument] - Future-proofing async-trait support in tracing-attributes #1219

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[tracing-attributes] Support for using #[instrument] with async-trait #711

[tracing-attributes] Support for using #[instrument] with async-trait #711

nightmared commented May 10, 2020

nightmared commented May 10, 2020 •

edited

Loading

hawkw commented May 10, 2020

nightmared commented May 10, 2020 •

edited

Loading

davidbarsky May 11, 2020

nightmared commented May 12, 2020

hawkw May 10, 2020

nightmared May 13, 2020

hawkw May 13, 2020

hawkw commented May 12, 2020

hawkw left a comment

hawkw May 12, 2020

hawkw May 12, 2020

hawkw May 12, 2020

hawkw May 12, 2020

hawkw May 12, 2020

hawkw May 12, 2020

nightmared May 13, 2020 •

edited

Loading

hawkw May 13, 2020

hawkw commented May 12, 2020

nightmared commented May 13, 2020

hawkw left a comment

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw May 13, 2020

hawkw left a comment

nightmared commented May 13, 2020

		# I'm not a huge fan of adding such a dependency only for tests, any idea ?
		async-trait = "0.1"

	// is the function declared as async ? If so, this is a good candidate, let's keep it
	// is the function declared as async? If so, this is a good candidate, let's keep it

	// is it a call to `Box::pin()` ?
	// is it a call to `Box::pin()`?

	let func_name = inside_path
	.path
	.segments
	.iter()
	.map(\|x\| x.ident.to_string())
	.collect::<Vec<String>>()
	.join("::");

-                merged_path.push_str(&path.path.segments[i].ident.to_string());
+                use std::fmt::Write;
+                write!(&mut merged_path, "{}", &path.path.segments[i].ident.to_string())
+                    .expect("writing to a String never fails");

	// does it takes at least an argument ? (if it doesn't, it's not gonna compile anyway,
	// does it takes at least an argument? (if it doesn't, it's not gonna compile anyway,

	// is the argument to Box::pin a function call itself ?
	// is the argument to Box::pin a function call itself?

	// is this function directly defined insided the current block ?
	// is this function directly defined insided the current block?

	// let's rewrite some statements !
	// let's rewrite some statements!

[tracing-attributes] Support for using #[instrument] with async-trait #711

[tracing-attributes] Support for using #[instrument] with async-trait #711

Conversation

nightmared commented May 10, 2020

Motivation

Solution

nightmared commented May 10, 2020 • edited Loading

hawkw commented May 10, 2020

nightmared commented May 10, 2020 • edited Loading

Choose a reason for hiding this comment

nightmared commented May 12, 2020

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hawkw commented May 12, 2020

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nightmared May 13, 2020 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hawkw commented May 12, 2020

nightmared commented May 13, 2020

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

hawkw left a comment

Choose a reason for hiding this comment

nightmared commented May 13, 2020

nightmared commented May 10, 2020 •

edited

Loading

nightmared commented May 10, 2020 •

edited

Loading

nightmared May 13, 2020 •

edited

Loading