#[instrument] codegen does not work with async_trait async fns

[inanna-malick]

Bug Report

async_trait (as re-exported by tonic) and instrument do not work as expected together. Instrumented async trait fns enter then immediately exit and drop their span, while top-level async functions work as expected.

Minimal reproduction with checked-in expanded macro-generated code at https://github.com/inanna-malick/tracing-async-trait-bug-repro

This is a cross-project bug, let me know if it's best posted elsewhere.

Version

│   │   │   │   └── tracing v0.1.9
│   │   │   │       ├── tracing-attributes v0.1.4
│   │   │   │       └── tracing-core v0.1.7
│   │   │   │   └── tracing v0.1.9 (*)
│   │   │   └── tracing-core v0.1.7 (*)
│   │   │   └── tracing v0.1.9 (*)
│   │   └── tracing v0.1.9 (*)
│   └── tracing v0.1.9 (*)
├── tracing v0.1.9 (*)
├── tracing-attributes v0.1.4 (*)
├── tracing-core v0.1.7 (*)
├── tracing-futures v0.1.0
│   └── tracing v0.1.9 (*)
└── tracing-subscriber v0.1.5
    ├── tracing-core v0.1.7 (*)
    └── tracing-log v0.1.0
        └── tracing-core v0.1.7 (*)
    └── tracing-log v0.1.0 (*)

Platform

Linux pk-thinkpad 4.15.0-54-generic #58-Ubuntu SMP Mon Jun 24 10:55:24 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Crates

tracing-attributes, tracing-futures

Description

code output by #[instrument] macro for async trait functions does not use expected code gen pathway for async trait fns.

for

#[tonic::async_trait]
pub trait Foo
where
    Self: std::marker::Send,
{
    async fn foo(&self) -> ();
}

struct FooImpl;

#[tonic::async_trait]
impl Foo for FooImpl {
    #[instrument]
    async fn foo(&self) {}
}

#[instrument]
async fn top_level() {}

the resulting generated code uses the expected future instrumentation pathway for top_level

    tracing_futures::Instrument::instrument(async move  { { } },
                                            __tracing_attr_span).await

but for the async trait fn foo it generates

    fn foo<'life0, 'async_trait>(&'life0 self)
     ->
         ::core::pin::Pin<Box<dyn ::core::future::Future<Output = ()> +
                              ::core::marker::Send + 'async_trait>> where
     'life0: 'async_trait, Self: 'async_trait {
        let __tracing_attr_span = { omitted };
        let __tracing_attr_guard = __tracing_attr_span.enter();
        {
            #[allow(clippy :: used_underscore_binding)]
            async fn __foo(_self: &FooImpl) { }
            Box::pin(__foo::<>(self))
        }
    }

[xd009642]

I'd be willing to help with this as it's an issue I've came up against. I may need some help though

[nightmared]

I have a "somewhat working" version at https://github.com/nightmared/tracing/tree/fix-399-async-trait
(somewhat because it exposes internal information like __query instead of query). I also updated the reproducer posted by @inanna-malick at https://github.com/nightmared/tracing-async-trait-bug-repro.
My main question right now is "should we provide tests for theses cases in the tracing-attributes crate ?" (as it would add a (dev-)depency towards async-trait, and because it implies I must write tests, and god knows nobody likes writing those pesky little things).
I will keep you posted !

--
Edit: You'd better not take a look at the current version, which is badly broken right now (:/), but I will fix that tomorrow (hopefully).

[nightmared]

All right, so it should be better now, and because async-trait likes to rewrite self as _self, I added a tiny bit of code to expose _self under a field named self (btw, this is almost all the work required to allow users to rename variables with something like #[instrument(rename(variable = "var"))], maybe adding this would be worth it ?).

As for the tests, I haven't dragged myself to do it yet :/