diff --git a/RELEASES.md b/RELEASES.md index 031f32fbcea0..dbd00a6b7115 100644 --- a/RELEASES.md +++ b/RELEASES.md @@ -29,6 +29,12 @@ Unreleased. ### Changed +* The host bindgen macro now accepts a new `verbose_tracing` option, which will + trace the value of `list` arguments. The new behavior of the `tracing` option + is that it does not print `list` values without `verbose_tracing` also being + present. + [#9262](https://github.com/bytecodealliance/wasmtime/pull/9262) + * Wasmtime's support for WASI is now listed with the 0.2.1 version instead of 0.2.0. This is expected to not cause fallout or breakage, but please open an issue if you see any problems. diff --git a/crates/component-macro/src/bindgen.rs b/crates/component-macro/src/bindgen.rs index 9b0a6a1d90ad..f17184dd8941 100644 --- a/crates/component-macro/src/bindgen.rs +++ b/crates/component-macro/src/bindgen.rs @@ -110,6 +110,7 @@ impl Parse for Config { inline = Some(s.value()); } Opt::Tracing(val) => opts.tracing = val, + Opt::VerboseTracing(val) => opts.verbose_tracing = val, Opt::Async(val, span) => { if async_configured { return Err(Error::new(span, "cannot specify second async config")); @@ -232,6 +233,7 @@ mod kw { syn::custom_keyword!(inline); syn::custom_keyword!(path); syn::custom_keyword!(tracing); + syn::custom_keyword!(verbose_tracing); syn::custom_keyword!(trappable_error_type); syn::custom_keyword!(world); syn::custom_keyword!(ownership); @@ -254,6 +256,7 @@ enum Opt { Path(syn::LitStr), Inline(syn::LitStr), Tracing(bool), + VerboseTracing(bool), Async(AsyncConfig, Span), TrappableErrorType(Vec), Ownership(Ownership), @@ -288,6 +291,10 @@ impl Parse for Opt { input.parse::()?; input.parse::()?; Ok(Opt::Tracing(input.parse::()?.value)) + } else if l.peek(kw::verbose_tracing) { + input.parse::()?; + input.parse::()?; + Ok(Opt::VerboseTracing(input.parse::()?.value)) } else if l.peek(Token![async]) { let span = input.parse::()?.span; input.parse::()?; diff --git a/crates/component-macro/tests/codegen.rs b/crates/component-macro/tests/codegen.rs index c7f40829b0be..1d0f0211800d 100644 --- a/crates/component-macro/tests/codegen.rs +++ b/crates/component-macro/tests/codegen.rs @@ -16,6 +16,7 @@ macro_rules! gentest { wasmtime::component::bindgen!({ path: $path, tracing: true, + verbose_tracing: true, ownership: Borrowing { duplicate_if_necessary: true } diff --git a/crates/component-macro/tests/expanded/lists_tracing_async.rs b/crates/component-macro/tests/expanded/lists_tracing_async.rs index 4e69ec9d48bd..4f142b12eb1c 100644 --- a/crates/component-macro/tests/expanded/lists_tracing_async.rs +++ b/crates/component-macro/tests/expanded/lists_tracing_async.rs @@ -527,7 +527,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -556,7 +556,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -585,7 +585,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -614,7 +614,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -643,7 +643,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -672,7 +672,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -701,7 +701,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -730,7 +730,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -759,7 +759,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -788,7 +788,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -817,8 +817,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_u8_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -840,8 +840,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_u16_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -863,8 +863,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_u32_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -886,8 +886,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_u64_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -909,8 +909,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_s8_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -932,8 +932,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_s16_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -955,8 +955,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_s32_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -978,8 +978,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_s64_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1001,8 +1001,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_float32_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1024,8 +1024,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_float64_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1047,14 +1047,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::tuple_list(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1082,7 +1082,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, a = tracing::field::debug(& arg0), + tracing::Level::TRACE, a = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -1111,8 +1111,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::string_list_ret(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1140,14 +1140,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::tuple_string_list(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1175,14 +1175,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::string_list(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1204,14 +1204,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::record_list(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1233,14 +1233,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::record_list_reverse(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1262,14 +1262,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::variant_list(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -1291,14 +1291,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, a = tracing::field::debug(& arg0), + tracing::Level::TRACE, a = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::load_store_everything(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } diff --git a/crates/component-macro/tests/expanded/resources-import_tracing_async.rs b/crates/component-macro/tests/expanded/resources-import_tracing_async.rs index 33d35ed86a2e..3a5f6ed8aea2 100644 --- a/crates/component-macro/tests/expanded/resources-import_tracing_async.rs +++ b/crates/component-macro/tests/expanded/resources-import_tracing_async.rs @@ -1045,7 +1045,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -1080,7 +1080,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, x = tracing::field::debug(& arg0), + tracing::Level::TRACE, x = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -1109,8 +1109,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::list_result(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } diff --git a/crates/component-macro/tests/expanded/simple-lists_tracing_async.rs b/crates/component-macro/tests/expanded/simple-lists_tracing_async.rs index 32cad358dded..69fd96ffeba3 100644 --- a/crates/component-macro/tests/expanded/simple-lists_tracing_async.rs +++ b/crates/component-macro/tests/expanded/simple-lists_tracing_async.rs @@ -255,7 +255,7 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, l = tracing::field::debug(& arg0), + tracing::Level::TRACE, l = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); @@ -284,8 +284,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::simple_list2(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -313,14 +313,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, a = tracing::field::debug(& arg0), b - = tracing::field::debug(& arg1), "call" + tracing::Level::TRACE, a = tracing::field::debug("..."), b = + tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::simple_list3(host, arg0, arg1).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } @@ -348,14 +348,14 @@ pub mod foo { wasmtime::component::__internal::Box::new( async move { tracing::event!( - tracing::Level::TRACE, l = tracing::field::debug(& arg0), + tracing::Level::TRACE, l = tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::simple_list4(host, arg0).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } diff --git a/crates/component-macro/tests/expanded/variants_tracing_async.rs b/crates/component-macro/tests/expanded/variants_tracing_async.rs index 94001b2536ca..792fd5815987 100644 --- a/crates/component-macro/tests/expanded/variants_tracing_async.rs +++ b/crates/component-macro/tests/expanded/variants_tracing_async.rs @@ -868,8 +868,8 @@ pub mod foo { tracing::Level::TRACE, a = tracing::field::debug(& arg0), b = tracing::field::debug(& arg1), c = tracing::field::debug(& arg2), d = tracing::field::debug(& arg3), e = - tracing::field::debug(& arg4), f = tracing::field::debug(& - arg5), "call" + tracing::field::debug(& arg4), f = + tracing::field::debug("..."), "call" ); let host = &mut host_getter(caller.data_mut()); let r = Host::result_arg( @@ -906,8 +906,8 @@ pub mod foo { let host = &mut host_getter(caller.data_mut()); let r = Host::result_result(host).await; tracing::event!( - tracing::Level::TRACE, result = tracing::field::debug(& r), - "return" + tracing::Level::TRACE, result = + tracing::field::debug("..."), "return" ); Ok((r,)) } diff --git a/crates/wasmtime/src/runtime/component/mod.rs b/crates/wasmtime/src/runtime/component/mod.rs index 93f85932021b..eaf4307e35a8 100644 --- a/crates/wasmtime/src/runtime/component/mod.rs +++ b/crates/wasmtime/src/runtime/component/mod.rs @@ -241,11 +241,19 @@ pub(crate) use self::store::ComponentStoreData; /// ", /// /// // Add calls to `tracing::span!` before each import or export is called -/// // to log arguments and return values. +/// // to log most arguments and return values. By default values +/// // containing lists are excluded; enable `verbose_tracing` to include +/// // them. /// // /// // This option defaults to `false`. /// tracing: true, /// +/// // Include all arguments and return values in the tracing output, +/// // including values containing lists, which may be very large. +/// // +/// // This option defaults to `false`. +/// verbose_tracing: false, +/// /// // Imports will be async functions through #[async_trait] and exports /// // are also invoked as async functions. Requires `Config::async_support` /// // to be `true`. diff --git a/crates/wit-bindgen/src/lib.rs b/crates/wit-bindgen/src/lib.rs index 338567ccdc94..8cd6d51439c5 100644 --- a/crates/wit-bindgen/src/lib.rs +++ b/crates/wit-bindgen/src/lib.rs @@ -125,6 +125,10 @@ pub struct Opts { /// Whether or not to emit `tracing` macro calls on function entry/exit. pub tracing: bool, + /// Whether or not `tracing` macro calls should included argument and + /// return values which contain dynamically-sized `list` values. + pub verbose_tracing: bool, + /// Whether or not to use async rust functions and traits. pub async_: AsyncConfig, @@ -2582,9 +2586,9 @@ impl<'a> InterfaceGenerator<'a> { .params .iter() .enumerate() - .map(|(i, (name, _ty))| { + .map(|(i, (name, ty))| { let name = to_rust_ident(&name); - format!("{name} = tracing::field::debug(&arg{i})") + formatting_for_arg(&name, i, *ty, &self.gen.opts, &self.resolve) }) .collect::>(); event_fields.push(format!("\"call\"")); @@ -2629,7 +2633,8 @@ impl<'a> InterfaceGenerator<'a> { if self.gen.opts.tracing { uwrite!( self.src, - "tracing::event!(tracing::Level::TRACE, result = tracing::field::debug(&r), \"return\");" + "tracing::event!(tracing::Level::TRACE, {}, \"return\");", + formatting_for_results(&func.results, &self.gen.opts, &self.resolve) ); } @@ -2955,6 +2960,89 @@ impl<'a> RustGenerator<'a> for InterfaceGenerator<'a> { } } +/// Produce a string for tracing a function argument. +fn formatting_for_arg( + name: &str, + index: usize, + ty: Type, + opts: &Opts, + resolve: &Resolve, +) -> String { + if !opts.verbose_tracing && type_contains_lists(ty, resolve) { + return format!("{name} = tracing::field::debug(\"...\")"); + } + + // Normal tracing. + format!("{name} = tracing::field::debug(&arg{index})") +} + +/// Produce a string for tracing function results. +fn formatting_for_results(results: &Results, opts: &Opts, resolve: &Resolve) -> String { + let contains_lists = match results { + Results::Anon(ty) => type_contains_lists(*ty, resolve), + Results::Named(params) => params + .iter() + .any(|(_, ty)| type_contains_lists(*ty, resolve)), + }; + + if !opts.verbose_tracing && contains_lists { + return format!("result = tracing::field::debug(\"...\")"); + } + + // Normal tracing. + format!("result = tracing::field::debug(&r)") +} + +/// Test whether the given type contains lists. +/// +/// Here, a `string` is not considered a list. +fn type_contains_lists(ty: Type, resolve: &Resolve) -> bool { + match ty { + Type::Id(id) => match &resolve.types[id].kind { + TypeDefKind::Resource + | TypeDefKind::Unknown + | TypeDefKind::Flags(_) + | TypeDefKind::Handle(_) + | TypeDefKind::Enum(_) => false, + TypeDefKind::Option(ty) => type_contains_lists(*ty, resolve), + TypeDefKind::Result(Result_ { ok, err }) => { + option_type_contains_lists(*ok, resolve) + || option_type_contains_lists(*err, resolve) + } + TypeDefKind::Record(record) => record + .fields + .iter() + .any(|field| type_contains_lists(field.ty, resolve)), + TypeDefKind::Tuple(tuple) => tuple + .types + .iter() + .any(|ty| type_contains_lists(*ty, resolve)), + TypeDefKind::Variant(variant) => variant + .cases + .iter() + .any(|case| option_type_contains_lists(case.ty, resolve)), + TypeDefKind::Type(ty) => type_contains_lists(*ty, resolve), + TypeDefKind::Future(ty) => option_type_contains_lists(*ty, resolve), + TypeDefKind::Stream(Stream { element, end }) => { + option_type_contains_lists(*element, resolve) + || option_type_contains_lists(*end, resolve) + } + TypeDefKind::List(_) => true, + }, + + // Technically strings are lists too, but we ignore that here because + // they're usually short. + _ => false, + } +} + +fn option_type_contains_lists(ty: Option, resolve: &Resolve) -> bool { + match ty { + Some(ty) => type_contains_lists(ty, resolve), + None => false, + } +} + /// When an interface `use`s a type from another interface, it creates a new TypeId /// referring to the definition TypeId. Chase this chain of references down to /// a TypeId for type's definition.