Files
wasmtime/crates/wiggle/generate/src/funcs.rs
Michael Gattozzi 58bf9b7bba 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
2021-08-20 11:20:38 -05:00

410 lines
15 KiB
Rust

use crate::codegen_settings::CodegenSettings;
use crate::lifetimes::anon_lifetime;
use crate::module_trait::passed_by_reference;
use crate::names::Names;
use crate::types::WiggleType;
use proc_macro2::{Ident, Span, TokenStream};
use quote::quote;
use std::mem;
use witx::Instruction;
pub fn define_func(
names: &Names,
module: &witx::Module,
func: &witx::InterfaceFunc,
settings: &CodegenSettings,
) -> TokenStream {
let (ts, _bounds) = _define_func(names, module, func, settings);
ts
}
pub fn func_bounds(
names: &Names,
module: &witx::Module,
func: &witx::InterfaceFunc,
settings: &CodegenSettings,
) -> Vec<Ident> {
let (_ts, bounds) = _define_func(names, module, func, settings);
bounds
}
fn _define_func(
names: &Names,
module: &witx::Module,
func: &witx::InterfaceFunc,
settings: &CodegenSettings,
) -> (TokenStream, Vec<Ident>) {
let rt = names.runtime_mod();
let ident = names.func(&func.name);
let (wasm_params, wasm_results) = func.wasm_signature();
let param_names = (0..wasm_params.len())
.map(|i| Ident::new(&format!("arg{}", i), Span::call_site()))
.collect::<Vec<_>>();
let abi_params = wasm_params.iter().zip(&param_names).map(|(arg, name)| {
let wasm = names.wasm_type(*arg);
quote!(#name : #wasm)
});
let abi_ret = match wasm_results.len() {
0 => quote!(()),
1 => {
let ty = names.wasm_type(wasm_results[0]);
quote!(#ty)
}
_ => unimplemented!(),
};
let mut body = TokenStream::new();
let mut bounds = vec![names.trait_name(&module.name)];
func.call_interface(
&module.name,
&mut Rust {
src: &mut body,
params: &param_names,
block_storage: Vec::new(),
blocks: Vec::new(),
rt: &rt,
names,
module,
funcname: func.name.as_str(),
settings,
bounds: &mut bounds,
},
);
let mod_name = &module.name.as_str();
let func_name = &func.name.as_str();
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<Output = Result<#abi_ret, #rt::Trap>> + 'a {
use std::convert::TryFrom as _;
use #rt::tracing::Instrument as _;
#mk_span
async move {
#body
}.instrument(_span)
}
),
bounds,
)
}
}
struct Rust<'a> {
src: &'a mut TokenStream,
params: &'a [Ident],
block_storage: Vec<TokenStream>,
blocks: Vec<TokenStream>,
rt: &'a TokenStream,
names: &'a Names,
module: &'a witx::Module,
funcname: &'a str,
settings: &'a CodegenSettings,
bounds: &'a mut Vec<Ident>,
}
impl Rust<'_> {
fn bound(&mut self, i: Ident) {
if !self.bounds.contains(&i) {
self.bounds.push(i);
}
}
}
impl witx::Bindgen for Rust<'_> {
type Operand = TokenStream;
fn push_block(&mut self) {
let prev = mem::replace(self.src, TokenStream::new());
self.block_storage.push(prev);
}
fn finish_block(&mut self, operand: Option<TokenStream>) {
let to_restore = self.block_storage.pop().unwrap();
let src = mem::replace(self.src, to_restore);
match operand {
None => self.blocks.push(src),
Some(s) => {
if src.is_empty() {
self.blocks.push(s);
} else {
self.blocks.push(quote!({ #src; #s }));
}
}
}
}
// This is only used for `call_wasm` at this time.
fn allocate_space(&mut self, _: usize, _: &witx::NamedType) {
unimplemented!()
}
fn emit(
&mut self,
inst: &Instruction<'_>,
operands: &mut Vec<TokenStream>,
results: &mut Vec<TokenStream>,
) {
let rt = self.rt;
let wrap_err = |location: &str| {
let modulename = self.module.name.as_str();
let funcname = self.funcname;
quote! {
|e| {
#rt::GuestError::InFunc {
modulename: #modulename,
funcname: #funcname,
location: #location,
err: Box::new(#rt::GuestError::from(e)),
}
}
}
};
let mut try_from = |ty: TokenStream| {
let val = operands.pop().unwrap();
let wrap_err = wrap_err(&format!("convert {}", ty));
results.push(quote!(#ty::try_from(#val).map_err(#wrap_err)?));
};
match inst {
Instruction::GetArg { nth } => {
let param = &self.params[*nth];
results.push(quote!(#param));
}
Instruction::PointerFromI32 { ty } | Instruction::ConstPointerFromI32 { ty } => {
let val = operands.pop().unwrap();
let pointee_type = self.names.type_ref(ty, anon_lifetime());
results.push(quote! {
#rt::GuestPtr::<#pointee_type>::new(memory, #val as u32)
});
}
Instruction::ListFromPointerLength { ty } => {
let ptr = &operands[0];
let len = &operands[1];
let ty = match &**ty.type_() {
witx::Type::Builtin(witx::BuiltinType::Char) => quote!(str),
_ => {
let ty = self.names.type_ref(ty, anon_lifetime());
quote!([#ty])
}
};
results.push(quote! {
#rt::GuestPtr::<#ty>::new(memory, (#ptr as u32, #len as u32));
})
}
Instruction::CallInterface { func, .. } => {
// Use the `tracing` crate to log all arguments that are going
// out, and afterwards we call the function with those bindings.
let mut args = Vec::new();
for (i, param) in func.params.iter().enumerate() {
let name = self.names.func_param(&param.name);
let val = &operands[i];
self.src.extend(quote!(let #name = #val;));
if passed_by_reference(param.tref.type_()) {
args.push(quote!(&#name));
} else {
args.push(quote!(#name));
}
}
if func.params.len() > 0 {
let args = func
.params
.iter()
.map(|param| {
let name = self.names.func_param(&param.name);
if param.impls_display() {
quote!( #name = #rt::tracing::field::display(&#name) )
} else {
quote!( #name = #rt::tracing::field::debug(&#name) )
}
})
.collect::<Vec<_>>();
self.src.extend(quote! {
#rt::tracing::event!(#rt::tracing::Level::TRACE, #(#args),*);
});
}
let trait_name = self.names.trait_name(&self.module.name);
let ident = self.names.func(&func.name);
if self.settings.get_async(&self.module, &func).is_sync() {
self.src.extend(quote! {
let ret = #trait_name::#ident(ctx, #(#args),*);
})
} else {
self.src.extend(quote! {
let ret = #trait_name::#ident(ctx, #(#args),*).await;
})
};
self.src.extend(quote! {
#rt::tracing::event!(
#rt::tracing::Level::TRACE,
result = #rt::tracing::field::debug(&ret),
);
});
if func.results.len() > 0 {
results.push(quote!(ret));
} else if func.noreturn {
self.src.extend(quote!(return Err(ret);));
}
}
// Lowering an enum is typically simple but if we have an error
// transformation registered for this enum then what we're actually
// doing is lowering from a user-defined error type to the error
// enum, and *then* we lower to an i32.
Instruction::EnumLower { ty } => {
let val = operands.pop().unwrap();
let val = match self.settings.errors.for_name(ty) {
Some(custom) => {
let method = self.names.user_error_conversion_method(&custom);
self.bound(quote::format_ident!("UserErrorConversion"));
quote!(UserErrorConversion::#method(ctx, #val)?)
}
None => val,
};
results.push(quote!(#val as i32));
}
Instruction::ResultLower { err: err_ty, .. } => {
let err = self.blocks.pop().unwrap();
let ok = self.blocks.pop().unwrap();
let val = operands.pop().unwrap();
let err_typename = self.names.type_ref(err_ty.unwrap(), anon_lifetime());
results.push(quote! {
match #val {
Ok(e) => { #ok; <#err_typename as #rt::GuestErrorType>::success() as i32 }
Err(e) => { #err }
}
});
}
Instruction::VariantPayload => results.push(quote!(e)),
Instruction::Return { amt: 0 } => {
self.src.extend(quote!(return Ok(())));
}
Instruction::Return { amt: 1 } => {
let val = operands.pop().unwrap();
self.src.extend(quote!(return Ok(#val)));
}
Instruction::Return { .. } => unimplemented!(),
Instruction::TupleLower { amt } => {
let names = (0..*amt)
.map(|i| Ident::new(&format!("t{}", i), Span::call_site()))
.collect::<Vec<_>>();
let val = operands.pop().unwrap();
self.src.extend(quote!( let (#(#names,)*) = #val;));
results.extend(names.iter().map(|i| quote!(#i)));
}
Instruction::Store { ty } => {
let ptr = operands.pop().unwrap();
let val = operands.pop().unwrap();
let wrap_err = wrap_err(&format!("write {}", ty.name.as_str()));
let pointee_type = self.names.type_(&ty.name);
self.src.extend(quote! {
#rt::GuestPtr::<#pointee_type>::new(memory, #ptr as u32)
.write(#val)
.map_err(#wrap_err)?;
});
}
Instruction::Load { ty } => {
let ptr = operands.pop().unwrap();
let wrap_err = wrap_err(&format!("read {}", ty.name.as_str()));
let pointee_type = self.names.type_(&ty.name);
results.push(quote! {
#rt::GuestPtr::<#pointee_type>::new(memory, #ptr as u32)
.read()
.map_err(#wrap_err)?
});
}
Instruction::HandleFromI32 { ty } => {
let val = operands.pop().unwrap();
let ty = self.names.type_(&ty.name);
results.push(quote!(#ty::from(#val)));
}
// Smaller-than-32 numerical conversions are done with `TryFrom` to
// ensure we're not losing bits.
Instruction::U8FromI32 => try_from(quote!(u8)),
Instruction::S8FromI32 => try_from(quote!(i8)),
Instruction::Char8FromI32 => try_from(quote!(u8)),
Instruction::U16FromI32 => try_from(quote!(u16)),
Instruction::S16FromI32 => try_from(quote!(i16)),
// Conversions with matching bit-widths but different signededness
// use `as` since we're basically just reinterpreting the bits.
Instruction::U32FromI32 | Instruction::UsizeFromI32 => {
let val = operands.pop().unwrap();
results.push(quote!(#val as u32));
}
Instruction::U64FromI64 => {
let val = operands.pop().unwrap();
results.push(quote!(#val as u64));
}
// Conversions to enums/bitflags use `TryFrom` to ensure that the
// values are valid coming in.
Instruction::EnumLift { ty }
| Instruction::BitflagsFromI64 { ty }
| Instruction::BitflagsFromI32 { ty } => {
let ty = self.names.type_(&ty.name);
try_from(quote!(#ty))
}
// No conversions necessary for these, the native wasm type matches
// our own representation.
Instruction::If32FromF32
| Instruction::If64FromF64
| Instruction::S32FromI32
| Instruction::S64FromI64 => results.push(operands.pop().unwrap()),
// There's a number of other instructions we could implement but
// they're not exercised by WASI at this time. As necessary we can
// add code to implement them.
other => panic!("no implementation for {:?}", other),
}
}
}