Backport 9262 to release-25.0.0 (#9270)

* wit-bindgen: Don't trace values containing lists by default. (#9262)

* wit-bindgen: Don't trace values containing lists by default.

`list` values in Wit interfaces can represent things like HTTP bodies
which can be very large. To enable tracing without spamming logfiles
with all this data, put printing of values containing `list`s behind
a separate `verbose_tracing` option.

This is a coarse-grained approach; but it seems like a pretty good
default for tracing, and enabling full tracing when one needs it is
straightforward.

In the future, we may want to refine the option by implementing
the `Valuable` trait and using `tracing::field::valuable`, which
could allow us to do things like print non-`list` fields of records
that otherwise contain `list`s.

* Use `option_type_contains_lists` more.

* Hook up `verbose_tracing` to the macro.

* Update expected outputs for tests.

* Add release notes

---------

Co-authored-by: Dan Gohman <dev@sunfishcode.online>

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.

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<TrappableError>),
  Ownership(Ownership),
@@ -288,6 +291,10 @@ impl Parse for Opt {
  input.parse::<kw::tracing>()?;
  input.parse::<Token![:]>()?;
  Ok(Opt::Tracing(input.parse::<syn::LitBool>()?.value))
+ } else if l.peek(kw::verbose_tracing) {
+ input.parse::<kw::verbose_tracing>()?;
+ input.parse::<Token![:]>()?;
+ Ok(Opt::VerboseTracing(input.parse::<syn::LitBool>()?.value))
  } else if l.peek(Token![async]) {
  let span = input.parse::<Token![async]>()?.span;
  input.parse::<Token![:]>()?;

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
  }

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,))
  }

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,))
  }

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,))
  }

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`.

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::<Vec<String>>();
  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<Type>, 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.