Stream: git-wasmtime

Topic: wasmtime / issue #9210 Tracing spans in code generated by...

Wasmtime GitHub notifications bot (Sep 06 2024 at 22:19):

swlynch99 opened issue #9210:

TLDR: The generated code creates a span and enters it by calling span.enter(). This works fine for sync functions but for async functions it results in the span still being entered even if the inner function has yielded. The end result is that the trace span will be shown on other unrelated tokio tasks that happen to run on the same thread at the same time.

Now, in more detail. If we have a component::bindgen! call like this

wasmtime::component::bindgen!({
    world: "imports",
    inline: "
package test:example@1.0.0;

interface test {
  my-func: func();
}

world imports {
  import test;
}
",

    tracing: true,
    async: true,
    include_generated_code_from_file: true
});

Then the generated code in add_to_linker_get_host will look something like this

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

Note that it holds the _enter guard across an await point. This is wrong, since the span remains entered even when the resulting future is suspended.

The correct thing to do here is to use tracing's Instrument trait, which takes care of entering/exiting the span when the future is polled.

Wasmtime GitHub notifications bot (Sep 06 2024 at 22:20):

swlynch99 edited issue #9210:

TLDR: The generated code creates a span and enters it by calling span.enter(). This works fine for sync functions but for async functions it results in the span still being entered even if the inner function has yielded. The end result is that the trace span will be shown on other unrelated tokio tasks that happen to run on the same thread at the same time.

Now, in more detail. If we have a component::bindgen! call like this

wasmtime::component::bindgen!({
    world: "imports",
    inline: "
package test:example@1.0.0;

interface test {
  my-func: func();
}

world imports {
  import test;
}
",

    tracing: true,
    async: true,
    include_generated_code_from_file: true
});

Then the generated code in add_to_linker_get_host will look something like this

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

Note that it holds the _enter guard across an await point. This is wrong, since the span remains entered even when the resulting future is suspended.

The correct thing to do here is to use tracing's Instrument trait which takes care of entering/exiting the span when the future is polled.

Wasmtime GitHub notifications bot (Sep 09 2024 at 16:49):

pchickey commented on issue #9210:

Thanks for the report. This is my bad, I didn't understand that aspect of how tracing spans interact with async. Would you like to submit a fix?

Wasmtime GitHub notifications bot (Sep 09 2024 at 21:00):

swlynch99 commented on issue #9210:

I've submitted a fix over in #9217

Wasmtime GitHub notifications bot (Sep 10 2024 at 00:38):

pchickey closed issue #9210:

TLDR: The generated code creates a span and enters it by calling span.enter(). This works fine for sync functions but for async functions it results in the span still being entered even if the inner function has yielded. The end result is that the trace span will be shown on other unrelated tokio tasks that happen to run on the same thread at the same time.

Now, in more detail. If we have a component::bindgen! call like this

wasmtime::component::bindgen!({
    world: "imports",
    inline: "
package test:example@1.0.0;

interface test {
  my-func: func();
}

world imports {
  import test;
}
",

    tracing: true,
    async: true,
    include_generated_code_from_file: true
});

Then the generated code in add_to_linker_get_host will look something like this

inst.func_wrap_async(
    "my-func",
    move |mut caller: wasmtime::StoreContextMut<'_, T>, (): ()| {
        wasmtime::component::__internal::Box::new(async move {
            let span = tracing::span!(
                tracing::Level::TRACE,
                "wit-bindgen import",
                module = "test",
                function = "my-func",
            );
            let _enter = span.enter();
            tracing::event!(tracing::Level::TRACE, "call");
            let host = &mut host_getter(caller.data_mut());
            let r = Host::my_func(host).await;
            tracing::event!(
                tracing::Level::TRACE,
                result = tracing::field::debug(&r),
                "return"
            );
            Ok(r)
        })
    },
)?;

Note that it holds the _enter guard across an await point. This is wrong, since the span remains entered even when the resulting future is suspended.

The correct thing to do here is to use tracing's Instrument trait which takes care of entering/exiting the span when the future is polled.

Last updated: Oct 23 2024 at 20:03 UTC