From 58bf9b7bba041ee19a6d47a318e99fa35a7966ed Mon Sep 17 00:00:00 2001 From: Michael Gattozzi Date: Fri, 20 Aug 2021 12:20:38 -0400 Subject: [PATCH] Fix wiggle code generation for correct span usage (#3220) * Fix wiggle code generation for correct span usage Up to this point when using wiggle to generate functions we could end up with two types of functions an async or sync one with this proc macro ``` #[allow(unreachable_code)] // deals with warnings in noreturn functions pub #asyncness fn #ident( ctx: &mut (impl #(#bounds)+*), memory: &dyn #rt::GuestMemory, #(#abi_params),* ) -> Result<#abi_ret, #rt::Trap> { use std::convert::TryFrom as _; let _span = #rt::tracing::span!( #rt::tracing::Level::TRACE, "wiggle abi", module = #mod_name, function = #func_name ); let _enter = _span.enter(); #body } ``` Now this might seem fine, we just create a span and enter it and run the body code and we get async versions as well. However, this is where the source of our problem lies. The impetus for this fix was seeing multiple request IDs output in the logs for a single function call of a generated function. Something was clearly happening that shouldn't have been. If we take a look at the tracing docs here we can see why the above code will not work in asynchronous code. https://docs.rs/tracing/0.1.26/tracing/span/struct.Span.html#in-asynchronous-code > Warning: in asynchronous code that uses async/await syntax, > Span::enter should be used very carefully or avoided entirely. > Holding the drop guard returned by Span::enter across .await points > will result in incorrect traces. The above documentation provides some more information, but what could happen is that the `#body` itself could contain code that would await and mess up the tracing that occurred and causing output that would be completely nonsensical. The code itself should work fine in the synchronous case though and in cases where await was not called again inside the body as the future would poll to completion as if it was a synchronous function. The solution then is to use the newer `Instrument` trait which can make sure that the span will be entered on every poll of the future. In order to make sure that we have the same behavior as before we generate synchronous functions and the ones that were async instead return a future that uses the instrument trait. This way we can guarantee that the span is created in synchronous code before being passed into a future. This does change the function signature, but the functionality itself is exactly as before and so we should see no actual difference in how it's used by others. We also just to be safe call the synchronous version's body with `in_scope` now as per the docs recommendation even though it's more intended for calling sync code inside async functions. Functionally it's the same as before with the call to enter. We also bump the version of tracing uses so that wiggle can reexport tracing with the instrument changes. * Move function span generation out of if statement We were duplicating the span creation code in our function generation in wiggle. This commit moves it out into one spot so that we can reuse it in both branches of the async/sync function generation. * Make formatting consistent --- crates/wiggle/Cargo.toml | 2 +- crates/wiggle/generate/src/funcs.rs | 74 +++++++++++++++++---------- crates/wiggle/test-helpers/Cargo.toml | 2 +- 3 files changed, 48 insertions(+), 30 deletions(-) diff --git a/crates/wiggle/Cargo.toml b/crates/wiggle/Cargo.toml index d8ede624a7..a176469669 100644 --- a/crates/wiggle/Cargo.toml +++ b/crates/wiggle/Cargo.toml @@ -14,7 +14,7 @@ include = ["src/**/*", "README.md", "LICENSE"] thiserror = "1" witx = { path = "../wasi-common/WASI/tools/witx", version = "0.9.1", optional = true } wiggle-macro = { path = "macro", version = "0.29.0" } -tracing = "0.1.15" +tracing = "0.1.26" bitflags = "1.2" async-trait = "0.1.42" wasmtime = { path = "../wasmtime", version = "0.29.0", optional = true, default-features = false } diff --git a/crates/wiggle/generate/src/funcs.rs b/crates/wiggle/generate/src/funcs.rs index 31e4a7bc26..693f1fe3e9 100644 --- a/crates/wiggle/generate/src/funcs.rs +++ b/crates/wiggle/generate/src/funcs.rs @@ -73,36 +73,54 @@ fn _define_func( }, ); - let asyncness = if settings.get_async(&module, &func).is_sync() { - quote!() - } else { - quote!(async) - }; let mod_name = &module.name.as_str(); let func_name = &func.name.as_str(); - ( - quote! { - #[allow(unreachable_code)] // deals with warnings in noreturn functions - pub #asyncness fn #ident( - ctx: &mut (impl #(#bounds)+*), - memory: &dyn #rt::GuestMemory, - #(#abi_params),* - ) -> Result<#abi_ret, #rt::Trap> { - use std::convert::TryFrom as _; - - let _span = #rt::tracing::span!( - #rt::tracing::Level::TRACE, - "wiggle abi", - module = #mod_name, - function = #func_name - ); - let _enter = _span.enter(); - - #body - } - }, - bounds, - ) + let mk_span = quote!( + let _span = #rt::tracing::span!( + #rt::tracing::Level::TRACE, + "wiggle abi", + module = #mod_name, + function = #func_name + ); + ); + if settings.get_async(&module, &func).is_sync() { + ( + quote!( + #[allow(unreachable_code)] // deals with warnings in noreturn functions + pub fn #ident( + ctx: &mut (impl #(#bounds)+*), + memory: &dyn #rt::GuestMemory, + #(#abi_params),* + ) -> Result<#abi_ret, #rt::Trap> { + use std::convert::TryFrom as _; + #mk_span + _span.in_scope(|| { + #body + }) + } + ), + bounds, + ) + } else { + ( + quote!( + #[allow(unreachable_code)] // deals with warnings in noreturn functions + pub fn #ident<'a>( + ctx: &'a mut (impl #(#bounds)+*), + memory: &'a dyn #rt::GuestMemory, + #(#abi_params),* + ) -> impl std::future::Future> + 'a { + use std::convert::TryFrom as _; + use #rt::tracing::Instrument as _; + #mk_span + async move { + #body + }.instrument(_span) + } + ), + bounds, + ) + } } struct Rust<'a> { diff --git a/crates/wiggle/test-helpers/Cargo.toml b/crates/wiggle/test-helpers/Cargo.toml index 7944bbe24e..b77fb9333e 100644 --- a/crates/wiggle/test-helpers/Cargo.toml +++ b/crates/wiggle/test-helpers/Cargo.toml @@ -17,7 +17,7 @@ wiggle = { path = "..", features = ["tracing_log"] } [dev-dependencies] thiserror = "1.0" -tracing = "0.1.14" +tracing = "0.1.26" tracing-subscriber = "0.2.4" env_logger = "0.8"