cross-project bug: async_trait and tracing::instrument are incompatible

[inanna-malick]

The combination of macros results in the instrument macro thinking the instrumented function is not in fact async and generating the wrong code.

see full writeup here, cross-posting b/c someone on the tonic/tracing/etc discord suggested it. Thanks for providing this crate!

[davidbarsky]

@dtolnay I wanted to check: how would you suggest resolving this? Since the #[tracing::instrument] macro is "lower" in the hierarchy of expanded macro, I expect that the fix would need to be in tracing. I'm thinking that the #[tracing::instrument] macro should attempt to match on the 'async_trait lifetime and generate code accordingly, but that feels a bit fragile.

[dtolnay]

I think this would be the most reliable pattern to identify: https://github.com/dtolnay/async-trait/blob/1.0.15/src/expand.rs#L402-L403

So if you find a function whose body consists of:

async fn f<...>(...) {...}
Box::pin(f::<...>(...))

then treat the instrument macro as if it had been applied to the inner function not the outer one.

[davidbarsky]

I'll probably start with that.

I wonder if this can/should be generalized. For instance, async-trait can leave behind some sort of marker struct so that other macros can recognize that some code been expanded by async-trait, but I suspect that Box::pin at the end will be sufficient.

[nightmared]

This should be fixed now by the merge request above. Thanks @dtolnay for outlining the pattern to look for to identify async_trait, I followed your suggestion and it works great !

[dtolnay]

Wow, thanks @nightmared. Would you be able to follow up with a PR in async-trait to add a test with #[instrument] so that we avoid inadvertently breaking it?

[nightmared]

You want to add a reverse test ? I'm not sure we can use the mock tests inside tracing outside of the crate. Otherwise we could do something like https://github.com/tokio-rs/tracing/blob/369b0c5e1d770f26c5e98a3e9f8fd9d4c6dfde8c/tracing-attributes/tests/async_fn.rs#L69-L152.

I will think about it in upcoming days

--
Edit: indeed tracing::support is not exposed publicly :/ I will need to think to find a "compact" way to test for this behavior.

[hawkw]

Edit: indeed tracing::support is not exposed publicly :/ I will need to think to find a "compact" way to test for this behavior.

There has been some discussion about publishing the test-support code as its own crate (see tokio-rs/tracing#539). If we were to do that, it could be pretty easy for async-trait to have its own version of the test?

[dtolnay]

But is there no way to test this in a setup that is representative of how downstream crates use async_trait + tracing? I don't know anything about tracing but I feel like we shouldn't need to depend on internal test-support code for this.

[hawkw]

@dtolnay The best way to test that everything works correctly is to write an implementation of the tracing::Subscriber trait that asserts that an expected sequence of events (creating a span, entering the span, exiting the span, and so on) occur in the expected order. This is all the tracing test support code does: it provides a builder pattern style API for constructing a Subscriber that makes these assertions. It's definitely possible to write such a test without it, it just requires writing a bit more code.

It would also be possible to test this using a Subscriber implementation that's actually used in the wild (such as tracing-subscriber::fmt) and then making assertions about its output. This would be akin to testing that something happened by constructing a log logger and asserting that it logs a particular record. I wouldn't suggest this, since it's likely much more brittle: changes in how traces are displayed, which are unrelated to the actual behavior we want to test, could break the test.

[dtolnay]

Thanks for the explanation and links!

I'd be fine having a small tracing::Subscriber impl dedicated to this one test. For an async trait method containing one event, all we care about in this crate is that the event happens before the exit (as opposed to before @nightmared's fix, where the exit would happen as soon as the BoxFuture was created). A struct with a Cell<bool>, or even a static with an AtomicBool, would be enough for our purposes.

[hawkw]

Yup, I think that's probably fine. We might also want to assert that if the future is polled, the span is re-entered as expected, and exited when the poll returns. This could definitely be done with a handwritten test subscriber — the test support code is mostly useful in the context of tracing itself, where we need to have a very large number of tests that make similar assertions. :)

[nightmared]

I hacked together a prototype at nightmared@b544a1b. Would something similar be okay ?

[dtolnay]

Something like that looks reasonable to me.