Tracing spans in code generated by wasmtime-wit-bindgen are entered incorrectly for async functions #9210
Description
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.