tracing-attributes 0.1.14 causes variables to be out of scope when they're in scope

[jeromegn]

Bug Report

Version

│   │   └── tracing v0.1.25
│   │       ├── tracing-attributes v0.1.14 (proc-macro)
│   │       └── tracing-core v0.1.17
│   ├── tracing v0.1.25 (*)
│   └── tracing v0.1.25 (*)
│   └── tracing v0.1.25 (*)
├── tracing v0.1.25 (*)
├── tracing-core v0.1.17 (*)
├── tracing-futures v0.2.5
│   └── tracing v0.1.25 (*)
├── tracing-log v0.1.2
│   └── tracing-core v0.1.17 (*)
├── tracing-subscriber v0.2.16
│   ├── tracing v0.1.25 (*)
│   ├── tracing-core v0.1.17 (*)
│   ├── tracing-log v0.1.2 (*)
│   └── tracing-serde v0.1.2
│       └── tracing-core v0.1.17 (*)

Platform

Darwin Kernel Version 20.3.0 (AMR64)

Crates

tracing-attributes

Description

Upgrading to tracing-attributes 0.1.14 appears to be placing variables out of scope.

I don't exactly have a minimal reproduction, but here's roughly the code that causes it:

#[instrument(skip(self, req), fields(app_id))]
fn call(&mut self, req: (Req, IpAddr)) -> Self::Future {
    // ...
    let metrics = self.metrics.clone();
    // ...
    Box::pin(async move {
        // ...
        metrics // cannot find value `metrics` in this scope
    })
}

Removing #[instrument(...)] fixes the issue.

[hawkw]

cc @nightmared, it looks like this may have been introduced in #1228?

I'll take a look soon.

[nightmared]

Hmm yes, I can reproduce this:

impl TestImpl {
        #[instrument]
        fn fun(&self) -> Pin<Box<dyn std::future::Future<Output = ()> + Send>> {
            let val = self.clone();
            Box::pin(async move {
                println!("{:?}", val);
            })
        }
    }

yields

    impl TestImpl {
        fn fun(&self) -> Pin<Box<dyn std::future::Future<Output = ()> + Send>> {
            Box::pin(async move {
                let __tracing_attr_span = {
                    use ::tracing::__macro_support::{Callsite as _, Registration};
                    static CALLSITE: ::tracing::__macro_support::MacroCallsite = {
                        use ::tracing::__macro_support::{MacroCallsite, Registration};
                        static META: ::tracing::Metadata<'static> = {
                            ::tracing_core::metadata::Metadata::new(
                                "fun",
                                "async_fn",
                                tracing::Level::INFO,
                                Some("tracing-attributes/tests/async_fn.rs"),
                                Some(220u32),
                                Some("async_fn"),
                                ::tracing_core::field::FieldSet::new(
                                    &["self"],
                                    ::tracing_core::callsite::Identifier(&CALLSITE),
                                ),
                                ::tracing::metadata::Kind::SPAN,
                            )
                        };
                        static REG: Registration = Registration::new(&CALLSITE);
                        MacroCallsite::new(&META, &REG)
                    };
                    let mut interest = ::tracing::collect::Interest::never();
                    if tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
                        && tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
                        && {
                            interest = CALLSITE.interest();
                            !interest.is_never()
                        }
                        && CALLSITE.is_enabled(interest)
                    {
                        let meta = CALLSITE.metadata();
                        ::tracing::Span::new(meta, &{
                            #[allow(unused_imports)]
                            use ::tracing::field::{debug, display, Value};
                            let mut iter = meta.fields().iter();
                            meta.fields().value_set(&[(
                                &iter.next().expect("FieldSet corrupted (this is a bug)"),
                                Some(&tracing::field::debug(&self) as &Value),
                            )])
                        })
                    } else {
                        let span = CALLSITE.disabled_span();
                        {};
                        span
                    }
                };
                tracing::Instrument::instrument(
                    async move {
                        {
                            {
                                ::std::io::_print(::core::fmt::Arguments::new_v1(
                                    &["", "\n"],
                                    &match (&val,) {
                                        (arg0,) => [::core::fmt::ArgumentV1::new(
                                            arg0,
                                            ::core::fmt::Debug::fmt,
                                        )],
                                    },
                                ));
                            };
                        }
                    },
                    __tracing_attr_span,
                )
                .await
            })
        }
    }

I will take a look

[nightmared]

Oh wait, that looks like a stupid one-line mistake I made

[hawkw]

FWIW, I just wrote a test in a branch, I can push that up if you like?

[nightmared]

Yeah, I think I'm going to open a PR with a new test and the code to fix that mistake

[hawkw]

@nightmared please feel free to use the test in this branch if you like: https://github.com/tokio-rs/tracing/tree/eliza/attributes-1296

[hawkw]

In general, it seems like, while we have plenty of tests for instrumenting async fn and async_trait fns, we could use more tests for instrumenting synchronous functions returning Box::pinned futures?

(but, let's focus on solving this specific problem first 🙂)