#[instrument] incorrect for fn() -> impl Future and async move block

[Swatinem]

Bug Report

Version

0.1.29

Description

I have recently experimented with various lazy/non-lazy fn() -> impl Future code, as there are subtle differences that can break other code.
For me details, I have written a blog about Non-Lazy Futures Considered Harmful with a tracing specific example.

Playing around a bit more, I found out that #[instrument] also does the wrong thing in certain situations.

#[tracing::instrument]
async fn fully_async() {
    tracing::info!("log happens on *poll*");
}

#[tracing::instrument]
fn lazy() -> impl Future<Output = ()> {
    async move {
        tracing::info!("log happens on *poll*");
    }
}

#[tracing::instrument]
fn not_lazy() -> impl Future<Output = ()> {
    tracing::info!("log happens on *call*");
    std::future::ready(())
}

#[tracing::instrument]
fn hybrid() -> impl Future<Output = ()> {
    tracing::info!("log happens on *call*");
    async move {
        tracing::info!("log happens on *poll*");
    }
}

#[tracing::instrument]
async fn instrumented_parent() {
    fully_async().await;
    lazy().await;
    not_lazy().await;
    hybrid().await;
}

This leads to the following output:

2022-01-26T16:46:01.815430Z  INFO instrumented_parent:fully_async: lazy_futures: log happens on *poll*
2022-01-26T16:46:01.815738Z  INFO instrumented_parent: lazy_futures: log happens on *poll*
2022-01-26T16:46:01.815993Z  INFO instrumented_parent:not_lazy: lazy_futures: log happens on *call*
2022-01-26T16:46:01.816261Z  INFO instrumented_parent:hybrid: lazy_futures: log happens on *call*
2022-01-26T16:46:01.816497Z  INFO instrumented_parent: lazy_futures: log happens on *poll*

It seems that the async move blocks in both the lazy and hybrid functions are not being correctly instrumented.

I can take a look at this in more detail and work towards a fix.

[Swatinem]

The expanded output looks like this:

fn lazy() -> impl Future<Output = ()> {
    {}

    #[allow(clippy::suspicious_else_formatting)]
    {
        let __tracing_attr_span;
        let __tracing_attr_guard;
        if tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
            && tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
        {
            __tracing_attr_span = {
                use ::tracing::__macro_support::Callsite as _;
                static CALLSITE: ::tracing::__macro_support::MacroCallsite = {
                    use ::tracing::__macro_support::MacroCallsite;
                    static META: ::tracing::Metadata<'static> = {
                        ::tracing_core::metadata::Metadata::new(
                            "lazy",
                            "lazy_futures",
                            tracing::Level::INFO,
                            Some("playground\\lazy-futures\\src\\main.rs"),
                            Some(10u32),
                            Some("lazy_futures"),
                            ::tracing_core::field::FieldSet::new(
                                &[],
                                ::tracing_core::callsite::Identifier(&CALLSITE),
                            ),
                            ::tracing::metadata::Kind::SPAN,
                        )
                    };
                    MacroCallsite::new(&META)
                };
                let mut interest = ::tracing::subscriber::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, &{ meta.fields().value_set(&[]) })
                } else {
                    let span = CALLSITE.disabled_span();
                    {};
                    span
                }
            };
            __tracing_attr_guard = __tracing_attr_span.enter();
        }

        #[warn(clippy::suspicious_else_formatting)]
        {
            async move {
                {
                    // log happens on *poll*
                };
            }
        }
    }
}
fn hybrid() -> impl Future<Output = ()> {
    {}

    #[allow(clippy::suspicious_else_formatting)]
    {
        let __tracing_attr_span;
        let __tracing_attr_guard;
        if tracing::Level::INFO <= ::tracing::level_filters::STATIC_MAX_LEVEL
            && tracing::Level::INFO <= ::tracing::level_filters::LevelFilter::current()
        {
            __tracing_attr_span = {
                use ::tracing::__macro_support::Callsite as _;
                static CALLSITE: ::tracing::__macro_support::MacroCallsite = {
                    use ::tracing::__macro_support::MacroCallsite;
                    static META: ::tracing::Metadata<'static> = {
                        ::tracing_core::metadata::Metadata::new(
                            "hybrid",
                            "lazy_futures",
                            tracing::Level::INFO,
                            Some("playground\\lazy-futures\\src\\main.rs"),
                            Some(23u32),
                            Some("lazy_futures"),
                            ::tracing_core::field::FieldSet::new(
                                &[],
                                ::tracing_core::callsite::Identifier(&CALLSITE),
                            ),
                            ::tracing::metadata::Kind::SPAN,
                        )
                    };
                    MacroCallsite::new(&META)
                };
                let mut interest = ::tracing::subscriber::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, &{ meta.fields().value_set(&[]) })
                } else {
                    let span = CALLSITE.disabled_span();
                    {};
                    span
                }
            };
            __tracing_attr_guard = __tracing_attr_span.enter();
        }

        #[warn(clippy::suspicious_else_formatting)]
        {
            {
                // log happens on *call*
            };
            async move {
                {
                    // log happens on *poll*
                };
            }
        }
    }
}

[hawkw]

Hmm, yeah, this codegen is not great. It would be nice to be able to enter the span for both any code that happens in the function body before the async block, and instrument the returned future in the async block.

Thanks for working on this!

[jplatte]

Was this fixed by #1866? I was just looking for some clues on whether tracing::instrument does the right thing for "hybrid" functions that return impl Future and emit events both inside and outside the async move {} block.

[Swatinem]

I don’t think I have fully solved this, unless someone else has done so in the meantime.

[jplatte]

I just came across another interesting case: A function returning impl Future as part of a compound type, in my case a function that returns (impl Future, Subscriber<PayloadProgress>) for uploading things.

I think for more complex cases like that, maybe it's not worth it to attempt to instrument the returned future(s)? The return type could even be a custom generic type containing a future, where it might not be possible, or is at least impossible to know how to, instrument that.

Anyways, I'll just use Span::current() + .instrument() to handle this.