improve readability and tests

tracing-attributes/src/lib.rs

@@ -169,7 +169,9 @@ use syn::{
 /// }
 /// ```
 ///
-/// It also works with async-trait (and hopefully most of the libraries that does similar things):
+/// 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:
 ///
 /// ```
 /// # use tracing::instrument;
@@ -201,7 +203,9 @@ pub fn instrument(args: TokenStream, item: TokenStream) -> TokenStream {
 
     // check for async_trait-like patterns in the block and wrap the internal function with Instrument
     // instead of wrapping the async_trait generated wrapper
-    if let Some(internal_fun_name) = is_async_trait(&input.block, input.sig.asyncness.is_some()) {
+    if let Some(internal_fun_name) =
+        get_async_trait_name(&input.block, input.sig.asyncness.is_some())
+    {
         // let's rewrite some statements !
         let mut stmts: Vec<Stmt> = input.block.stmts.to_vec();
         for stmt in &mut stmts {
@@ -296,6 +300,7 @@ fn gen_body(
             .collect();
 
         // TODO: allow the user to rename fields at will (all the machinery should be here)
+
         // Little dance with new (user-exposed) names and old (internal) names of identifiers.
         // That way, you can do the following even though async_trait rewrite "self" as "_self":
         // ```
@@ -664,10 +669,18 @@ fn instrument_err(args: &[NestedMeta]) -> bool {
     })
 }
 
-// terrible machinery to make async_trait-like cases works
-// (following the approach suggested in
+// Get the name of the inner function we need to hook, if the function was generated by async-trait.
+// When we are given a function generated by async-trait, that function in only a "temporary"
+// function that returns a pinned future, and it is that pinned function that needs to be
+// instrumened, otherwise we will only collect information on the moment the future was "built",
+// and not it trues span of execution.
+// So we inspect the block of the function to find if we can find the pattern
+// `async fn foo<...>(...) {...}; Box::pin(foo<...>(...))` and return the name `foo` if that
+// is the case. Our caller will then be able to use that information to instrument the proper
+// function.
+// (this follows 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> {
+fn get_async_trait_name(block: &Block, block_is_async: bool) -> Option<String> {
     // are we in an async context ? If yes, this isn't a async_trait-like pattern
     if block_is_async {
         return None;
@@ -703,15 +716,15 @@ fn is_async_trait(block: &Block, block_is_async: bool) -> Option<String> {
     {
         if let Expr::Path(path) = outside_func.as_ref() {
             // is it a call to `Box::pin()` ?
-            if "Box::pin"
-                == path
-                    .path
-                    .segments
-                    .iter()
-                    .map(|x| x.ident.to_string())
-                    .collect::<Vec<String>>()
-                    .join("::")
-            {
+            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("::");
+                }
+            }
+
+            if "Box::pin" == merged_path {
                 // does it takes at least an argument ? (if it doesn't, it's not gonna compile anyway,
                 // but that's no reason to (try to) perform an out of bounds access)
                 if outside_args.is_empty() {

tracing-attributes/tests/async_fn.rs

@@ -14,16 +14,6 @@ async fn test_async_fn(polls: usize) -> Result<(), ()> {
     future.await
 }
 
-#[instrument]
-async fn test_async_fns_nested() {
-    test_async_fns_nested_other().await
-}
-
-#[instrument]
-async fn test_async_fns_nested_other() {
-    tracing::trace!(nested = true);
-}
-
 #[test]
 fn async_fn_only_enters_for_polls() {
     let (subscriber, handle) = subscriber::mock()
@@ -44,6 +34,16 @@ fn async_fn_only_enters_for_polls() {
 
 #[test]
 fn async_fn_nested() {
+    #[instrument]
+    async fn test_async_fns_nested() {
+        test_async_fns_nested_other().await
+    }
+
+    #[instrument]
+    async fn test_async_fns_nested_other() {
+        tracing::trace!(nested = true);
+    }
+
     let span = span::mock().named("test_async_fns_nested");
     let span2 = span::mock().named("test_async_fns_nested_other");
     let (subscriber, handle) = subscriber::mock()
@@ -69,42 +69,71 @@ fn async_fn_nested() {
 #[test]
 fn async_fn_with_async_trait() {
     use async_trait::async_trait;
+
+    // test the correctness of the metadata obtained by #[instrument]
+    // (function name, functions parameters) when async-trait is used
     #[async_trait]
     pub trait TestA {
         async fn foo(&mut self, v: usize);
     }
 
+    // test nesting of async fns with aync-trait
     #[async_trait]
     pub trait TestB {
         async fn bar(&self);
     }
 
+    // test skip(self) with async-await
+    #[async_trait]
+    pub trait TestC {
+        async fn baz(&self);
+    }
+
     #[derive(Debug)]
     struct TestImpl(usize);
 
     #[async_trait]
     impl TestA for TestImpl {
         #[instrument]
         async fn foo(&mut self, v: usize) {
+            self.baz().await;
             self.0 = v;
             self.bar().await
         }
     }
 
     #[async_trait]
     impl TestB for TestImpl {
-        #[instrument(skip(self))]
+        #[instrument]
         async fn bar(&self) {
             tracing::trace!(val = self.0);
         }
     }
 
+    #[async_trait]
+    impl TestC for TestImpl {
+        #[instrument(skip(self))]
+        async fn baz(&self) {
+            tracing::trace!(val = self.0);
+        }
+    }
+
     let span = span::mock().named("foo");
     let span2 = span::mock().named("bar");
+    let span3 = span::mock().named("baz");
     let (subscriber, handle) = subscriber::mock()
-        .new_span(span.clone())
+        .new_span(
+            span.clone()
+                .with_field(field::mock("self"))
+                .with_field(field::mock("v")),
+        )
         .enter(span.clone())
-        .new_span(span2.clone())
+        .new_span(span3.clone())
+        .enter(span3.clone())
+        .event(event::mock().with_fields(field::mock("val").with_value(&2u64)))
+        .exit(span3.clone())
+        .drop_span(span3)
+        .new_span(span2.clone().with_field(field::mock("self")))
         .enter(span2.clone())
         .event(event::mock().with_fields(field::mock("val").with_value(&5u64)))
         .exit(span2.clone())