Repository: bytecodealliance/wasmtime
Pull request #1796 (2020-05-31 02:07:38)

wiggle: switch logging to use `tracing` crate
Wiggle generated code now emits code that uses `tracing` for logging.

We use `tracing` by default at Fastly, so I'd like to use it in wiggle and wasi-common without adapters if possible. Tracing has a couple of advantages over `log` that make it well suited here:

* The concept of spans, which are natural to use in wiggle-generated functions where we want to log the arguments of a function, then later when an inner func returns we want to log the return values. the argument values and return value s are part of the same span, which means the backend can automatically correlate them, rather than have to associate them by searching on some common part of the text

* (stable) support for structured fields (in log this is noted as unstable and called kv support), which also naturally matches to the names of arguments / return values we already have in witx, and keeps that structure around longer so that it can be e.g. encoded in json by the backend that sends it to some logging endpoint that understands json

* tracing statements that are disabled (marked as uninteresting, essentially) by the backend are very low overhead - its one atomic load to determine whether a hook is disabled.


<!--

Please ensure that the following steps are all taken care of before submitting
the PR.

- [ ] This has been discussed in issue #..., or if not, please tell us why
  here.
- [ ] A short description of what this does, why it is needed; if the
  description becomes long, the matter should probably be discussed in an issue
  first.
- [ ] This PR contains test cases, if meaningful.
- [ ] A reviewer from the core maintainer team has been assigned for this PR.
  If you don't know who could review this, please indicate so. The list of
  suggested reviewers on the right can help you.

Please ensure all communication adheres to the [code of
conduct](https://github.com/bytecodealliance/wasmtime/blob/master/CODE_OF_CONDUCT.md).
-->


pchickey: Currently a very sketchy WIP. I made an example inside test-helpers (because it was most convenient to reuse the test-helpers HostMemory and WasiCtx) that demonstrates that tracing integration works at all, but I'm not sure where the best place to stick that in the long run is. In order to provide an example we have to take on `tracing` and `tracing_subscriber` as a `dev-dependency`, which are not especially heavyweight.
github-actions[bot]: #### Subscribe to Label Action

cc @kubkon

<details>
This issue or pull request has been labeled: "wasi"

Thus the following users have been cc'd because of the following labels:

* kubkon: wasi

To subscribe or unsubscribe from this label, edit the <code>.github/subscribe-to-label.json</code> configuration file.

[Learn more.](https://github.com/bytecodealliance/subscribe-to-label-action)
</details>
kubkon: This looks interesting, thanks Pat! I haven’t looked over the code properly yet, however, one observation about removing `log` altogether is that this will probably force every user of `libwasmtime` to rely on `tracing` crate which i don’t think is a good idea. I think if I was a developer making use of the library, I’d rather have the choice or at the very least expect `log` support by default which seems to be the “industry” standard.
alexcrichton: This seems reasonable to me to add as a feature, but I'm also hesitant about deleting `log`. It looks like `tracing` is a pretty hefty dependency, and I'm not sure all users of `wasmtime` will want to take that on.

> (stable) support for structured fields

FWIW this seems like a good reason to poke upstream about the support here, I know it's been in limbo for awhile but upstream may have thoughts about stabilizing.

> tracing statements that are disabled (marked as uninteresting, essentially) by the backend are very low overhead - its one atomic load to determine whether a hook is disabled.

I know this is also true for `log`, so I don't think there should be any speed difference.
pchickey: Cool, thanks for the input and the context. I'll move forward with this patch which will make the logging choice an either/or `log`/`tracing`. I'm not going to pull on the thread of structured fields in `log` for lack of time to do so, but I'd welcome any help with that.
pchickey: I thought about this more and got some feedback from @hawkw and @fitzgen -
* taking a dep on `tracing` implies `tracing-core` and `tracing-attributes`, which in turn pull in `lazy_static`, `cfg-if`, and the standard proc macro crates (proc-macro2, syn, quote). `wasi-common` already has all of those deps transitively, so, this is not so heavyweight. `tracing-subscriber` is the heavyweight crate, just like the backend crates in the `log` ecosystem.
* when the `log` feature is enabled for `tracing`, the `log` system is used as the backend for the `tracing` macros. This allows the existing users who just want `log` in their system to use wasi-common just as they did before. Since the `tracing` dep isn't very heavy, this seems preferable than having a switch throughout wiggle codegen to emit one kind of log or another
* If we want to completely disable any code footprint from `tracing` or `log`, Wiggle can emit macros that point to `wiggle::tracing_impl::(macro)`, and use a feature flag in `wiggle/src/tracing_impl.rs` to substitute between `pub use tracing::*` and a module that defines no-op versions of each macro. This is suitable for use cases that are very sensitive about vendoring in additional deps, or where the code size of always-runtime-disabled macros is an issue.
pchickey: Unfortunately, we can't switch between the `tracing` macros and no-op versions, while keeping that api re-exported inside a module scope like `wiggle::tracing` (and its a fairly big API, so i think we really need to), without defining a whole other `tracing_noop` crate, because much of the API is in terms of `macro_rules` which can only be exported at the top level of a crate. So, Rust visibility rules got us here.

At some point, the cranelift project will need to implement a `tracing_noop` crate in order to turn off `tracing` deps for use inside spidermonkey. Until then, we'll do a mandatory dep on `tracing`, with just a feature to set it in `log` mode.
pchickey: The failures in `wasi-common` are due to a fixed bug in `tracing` that will be part of the 0.1.15 release, which will happen shortly since we need it to merge this.
hawkw: > The failures in `wasi-common` are due to a fixed bug in `tracing` that will be part of the 0.1.15 release, which will happen shortly since we need it to merge this.

Hot off the presses: https://crates.io/crates/tracing/0.1.15

Sorry for any inconvenience! :)

Patch:
diff --git a/Cargo.lock b/Cargo.lock
index a357573ab..ec84f1d5a 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -252,6 +252,17 @@ version = "0.1.10"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "4785bdd1c96b2a846b2bd7cc02e86b6b3dbf14e7e53446c4f54c92a361040822"
 
+[[package]]
+name = "chrono"
+version = "0.4.11"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "80094f509cf8b5ae86a4966a39b3ff66cd7e2a3e594accec3743ff3fabeab5b2"
+dependencies = [
+ "num-integer",
+ "num-traits",
+ "time",
+]
+
 [[package]]
 name = "clap"
 version = "2.33.1"
@@ -1138,6 +1149,15 @@ dependencies = [
  "libc",
 ]
 
+[[package]]
+name = "matchers"
+version = "0.0.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f099785f7595cc4b4553a174ce30dd7589ef93391ff414dbb67f62392b9e0ce1"
+dependencies = [
+ "regex-automata",
+]
+
 [[package]]
 name = "maybe-uninit"
 version = "2.0.0"
@@ -1175,6 +1195,16 @@ version = "0.2.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "0debeb9fcf88823ea64d64e4a815ab1643f33127d995978e099942ce38f25238"
 
+[[package]]
+name = "num-integer"
+version = "0.1.42"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3f6ea62e9d81a77cd3ee9a2a5b9b609447857f3d358704331e4ef39eb247fcba"
+dependencies = [
+ "autocfg 1.0.0",
+ "num-traits",
+]
+
 [[package]]
 name = "num-traits"
 version = "0.2.11"
@@ -1669,6 +1699,16 @@ dependencies = [
  "thread_local",
 ]
 
+[[package]]
+name = "regex-automata"
+version = "0.1.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ae1ded71d66a4a97f5e961fd0cb25a5f366a42a41570d16a763a69c092c26ae4"
+dependencies = [
+ "byteorder",
+ "regex-syntax",
+]
+
 [[package]]
 name = "regex-syntax"
 version = "0.6.18"
@@ -1847,6 +1887,15 @@ dependencies = [
  "opaque-debug",
 ]
 
+[[package]]
+name = "sharded-slab"
+version = "0.0.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "06d5a3f5166fb5b42a5439f2eee8b9de149e235961e3eb21c5808fc3ea17ff3e"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "smallvec"
 version = "1.4.0"
@@ -2038,6 +2087,16 @@ dependencies = [
  "lazy_static",
 ]
 
+[[package]]
+name = "time"
+version = "0.1.43"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "ca8a50ef2360fbd1eeb0ecd46795a87a19024eb4b53c5dc916ca1fd95fe62438"
+dependencies = [
+ "libc",
+ "winapi",
+]
+
 [[package]]
 name = "toml"
 version = "0.5.6"
@@ -2047,6 +2106,79 @@ dependencies = [
  "serde",
 ]
 
+[[package]]
+name = "tracing"
+version = "0.1.15"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a41f40ed0e162c911ac6fcb53ecdc8134c46905fdbbae8c50add462a538b495f"
+dependencies = [
+ "cfg-if",
+ "log",
+ "tracing-attributes",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-attributes"
+version = "0.1.8"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "99bbad0de3fd923c9c3232ead88510b783e5a4d16a6154adffa3d53308de984c"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
+[[package]]
+name = "tracing-core"
+version = "0.1.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0aa83a9a47081cd522c09c81b31aec2c9273424976f922ad61c053b58350b715"
+dependencies = [
+ "lazy_static",
+]
+
+[[package]]
+name = "tracing-log"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5e0f8c7178e13481ff6765bd169b33e8d554c5d2bbede5e32c356194be02b9b9"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-serde"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b6ccba2f8f16e0ed268fc765d9b7ff22e965e7185d32f8f1ec8294fe17d86e79"
+dependencies = [
+ "serde",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.2.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1d53c40489aa69c9aed21ff483f26886ca8403df33bdc2d2f87c60c1617826d2"
+dependencies = [
+ "ansi_term",
+ "chrono",
+ "lazy_static",
+ "matchers",
+ "regex",
+ "serde",
+ "serde_json",
+ "sharded-slab",
+ "smallvec",
+ "tracing-core",
+ "tracing-log",
+ "tracing-serde",
+]
+
 [[package]]
 name = "traitobject"
 version = "0.1.0"
@@ -2492,6 +2624,7 @@ version = "0.17.0"
 dependencies = [
  "proptest",
  "thiserror",
+ "tracing",
  "wiggle-macro",
  "wiggle-test",
  "witx",
@@ -2524,7 +2657,11 @@ dependencies = [
 name = "wiggle-test"
 version = "0.17.0"
 dependencies = [
+ "env_logger",
  "proptest",
+ "thiserror",
+ "tracing",
+ "tracing-subscriber",
  "wiggle",
 ]
 
diff --git a/crates/wasi-common/Cargo.toml b/crates/wasi-common/Cargo.toml
index c24127a33..9a8f46db3 100644
--- a/crates/wasi-common/Cargo.toml
+++ b/crates/wasi-common/Cargo.toml
@@ -41,10 +41,10 @@ maintenance = { status = "actively-developed" }
 
 [features]
 default = ["trace_log"]
-# This feature enables `log::trace` calls in syscalls shims, in effect
-# emulating something like `strace`. This feature is an opt-out and hence
-# enabled by default.
-trace_log = []
+# This feature enables the `tracing` logs in the calls to target the `log`
+# ecosystem of backends (e.g. `env_logger`. Disable this if you want to use
+# `tracing-subscriber`.
+trace_log = [ "wiggle/tracing_log" ]
 # Need to make the wiggle_metadata feature available to consumers of this
 # crate if they want the snapshots to have metadata available.
 wiggle_metadata = ["wiggle/wiggle_metadata"]
diff --git a/crates/wiggle/Cargo.toml b/crates/wiggle/Cargo.toml
index c6f6adb42..55a4ceabb 100644
--- a/crates/wiggle/Cargo.toml
+++ b/crates/wiggle/Cargo.toml
@@ -14,6 +14,7 @@ include = ["src/**/*", "LICENSE"]
 thiserror = "1"
 witx = { path = "../wasi-common/WASI/tools/witx", version = "0.8.5", optional = true }
 wiggle-macro = { path = "macro", version = "0.17.0" }
+tracing = "0.1.15"
 
 [badges]
 maintenance = { status = "actively-developed" }
@@ -23,13 +24,16 @@ wiggle-test = { path = "test-helpers" }
 proptest = "0.9"
 
 [features]
-# These features have no effect on the users of this crate. They are only
-# necessary for testing.
 # The wiggle proc-macro emits some code (inside `pub mod metadata`) guarded
 # by the `wiggle_metadata` feature flag. We use this feature flag so that
 # users of wiggle are not forced to take a direct dependency on the `witx`
 # crate unless they want it.
 wiggle_metadata = ['witx', "wiggle-macro/wiggle_metadata"]
-# In order to test that the contents of this metadata module meet
-# expectations, we must have this feature enabled for the crate by default.
-default = ["wiggle_metadata"]
+
+# The `tracing` crate can use the `log` ecosystem of backends with this
+# non-default feature. We don't need to provide this by default, but its
+# useful for users that don't want to use `tracing-subscriber` to get
+# the logs out of wiggle-generated libraries.
+tracing_log = [ "tracing/log" ]
+
+default = ["wiggle_metadata" ]
diff --git a/crates/wiggle/generate/src/config.rs b/crates/wiggle/generate/src/config.rs
index 6eecf28c9..22ff88aa2 100644
--- a/crates/wiggle/generate/src/config.rs
+++ b/crates/wiggle/generate/src/config.rs
@@ -27,23 +27,35 @@ pub enum ConfigField {
     Error(ErrorConf),
 }
 
-impl ConfigField {
-    pub fn parse_pair(ident: &str, value: ParseStream, err_loc: Span) -> Result<Self> {
-        match ident {
-            "witx" => Ok(ConfigField::Witx(WitxConf::Paths(value.parse()?))),
-            "witx_literal" => Ok(ConfigField::Witx(WitxConf::Literal(value.parse()?))),
-            "ctx" => Ok(ConfigField::Ctx(value.parse()?)),
-            "errors" => Ok(ConfigField::Error(value.parse()?)),
-            _ => Err(Error::new(err_loc, "expected `witx`, `ctx`, or `errors`")),
-        }
-    }
+mod kw {
+    syn::custom_keyword!(witx);
+    syn::custom_keyword!(witx_literal);
+    syn::custom_keyword!(ctx);
+    syn::custom_keyword!(errors);
 }
 
 impl Parse for ConfigField {
     fn parse(input: ParseStream) -> Result<Self> {
-        let id: Ident = input.parse()?;
-        let _colon: Token![:] = input.parse()?;
-        Self::parse_pair(id.to_string().as_ref(), input, id.span())
+        let lookahead = input.lookahead1();
+        if lookahead.peek(kw::witx) {
+            input.parse::<kw::witx>()?;
+            input.parse::<Token![:]>()?;
+            Ok(ConfigField::Witx(WitxConf::Paths(input.parse()?)))
+        } else if lookahead.peek(kw::witx_literal) {
+            input.parse::<kw::witx_literal>()?;
+            input.parse::<Token![:]>()?;
+            Ok(ConfigField::Witx(WitxConf::Literal(input.parse()?)))
+        } else if lookahead.peek(kw::ctx) {
+            input.parse::<kw::ctx>()?;
+            input.parse::<Token![:]>()?;
+            Ok(ConfigField::Ctx(input.parse()?))
+        } else if lookahead.peek(kw::errors) {
+            input.parse::<kw::errors>()?;
+            input.parse::<Token![:]>()?;
+            Ok(ConfigField::Error(input.parse()?))
+        } else {
+            Err(lookahead.error())
+        }
     }
 }
 
diff --git a/crates/wiggle/generate/src/error_transform.rs b/crates/wiggle/generate/src/error_transform.rs
index 80cb56f92..3598e221d 100644
--- a/crates/wiggle/generate/src/error_transform.rs
+++ b/crates/wiggle/generate/src/error_transform.rs
@@ -11,6 +11,9 @@ pub struct ErrorTransform {
 }
 
 impl ErrorTransform {
+    pub fn empty() -> Self {
+        Self { m: Vec::new() }
+    }
     pub fn new(conf: &ErrorConf, doc: &Document) -> Result<Self, Error> {
         let mut richtype_identifiers = HashMap::new();
         let m = conf.iter().map(|(ident, field)|
diff --git a/crates/wiggle/generate/src/funcs.rs b/crates/wiggle/generate/src/funcs.rs
index 2c8cf2b35..0baa8cd39 100644
--- a/crates/wiggle/generate/src/funcs.rs
+++ b/crates/wiggle/generate/src/funcs.rs
@@ -5,11 +5,12 @@ use crate::error_transform::ErrorTransform;
 use crate::lifetimes::anon_lifetime;
 use crate::module_trait::passed_by_reference;
 use crate::names::Names;
+use crate::types::WiggleType;
 
 pub fn define_func(
     names: &Names,
+    module: &witx::Module,
     func: &witx::InterfaceFunc,
-    trait_name: TokenStream,
     errxform: &ErrorTransform,
 ) -> TokenStream {
     let funcname = func.name.as_str();
@@ -49,19 +50,20 @@ pub fn define_func(
     let ret_err = coretype
         .ret
         .map(|ret| {
-            let name = ret.param.name.as_str();
+            let name = names.func_param(&ret.param.name);
             let conversion = if let Some(user_err) = errxform.for_abi_error(&ret.param.tref) {
                 let method = names.user_error_conversion_method(&user_err);
-                quote!(#abi_ret::from(UserErrorConversion::#method(ctx, e)))
+                quote!(UserErrorConversion::#method(ctx, e))
             } else {
-                quote!(#abi_ret::from(e))
+                quote!(e)
             };
             quote! {
-                #[cfg(feature = "trace_log")]
-                {
-                    log::trace!("     | {}={:?}", #name, e);
-                }
-                return #conversion;
+                let e = #conversion;
+                #rt::tracing::event!(
+                    #rt::tracing::Level::TRACE,
+                    #name = #rt::tracing::field::debug(&e),
+                );
+                return #abi_ret::from(e);
             }
         })
         .unwrap_or_else(|| quote!(()));
@@ -76,7 +78,7 @@ pub fn define_func(
             let err_method = names.guest_error_conversion_method(&tref);
             quote! {
                 let e = #rt::GuestError::InFunc { funcname: #funcname, location: #location, err: Box::new(e.into()) };
-                let err: #err_typename = GuestErrorConversion::#err_method(ctx, e); // XXX replace with conversion method on trait!
+                let err: #err_typename = GuestErrorConversion::#err_method(ctx, e);
                 return #abi_ret::from(err);
             }
         } else {
@@ -99,6 +101,23 @@ pub fn define_func(
         }
     });
 
+    let log_marshalled_args = if func.params.len() > 0 {
+        let rt = names.runtime_mod();
+        let args = func.params.iter().map(|param| {
+            let name = names.func_param(&param.name);
+            if param.impls_display() {
+                quote!( #name = #rt::tracing::field::display(&#name) )
+            } else {
+                quote!( #name = #rt::tracing::field::debug(&#name) )
+            }
+        });
+        quote! {
+            #rt::tracing::event!(#rt::tracing::Level::TRACE, #(#args),*);
+        }
+    } else {
+        quote!()
+    };
+
     let (trait_rets, trait_bindings) = if func.results.len() < 2 {
         (quote!({}), quote!(_))
     } else {
@@ -109,29 +128,16 @@ pub fn define_func(
             .map(|result| names.func_param(&result.name))
             .collect();
         let bindings = quote!((#(#trait_rets),*));
-        let names: Vec<_> = func
-            .results
-            .iter()
-            .skip(1)
-            .map(|result| {
-                let name = names.func_param(&result.name);
-                let fmt = match &*result.tref.type_() {
-                    witx::Type::Builtin(_)
-                    | witx::Type::Enum(_)
-                    | witx::Type::Flags(_)
-                    | witx::Type::Handle(_)
-                    | witx::Type::Int(_) => "{}",
-                    _ => "{:?}",
-                };
-                format!("{}={}", name.to_string(), fmt)
-            })
-            .collect();
-        let trace_fmt = format!("     | result=({})", names.join(","));
-        let rets = quote! {
-            #[cfg(feature = "trace_log")]
-            {
-                log::trace!(#trace_fmt, #(#trait_rets),*);
+        let trace_rets = func.results.iter().skip(1).map(|result| {
+            let name = names.func_param(&result.name);
+            if result.tref.impls_display() {
+                quote!(#name = #rt::tracing::field::display(&#name))
+            } else {
+                quote!(#name = #rt::tracing::field::debug(&#name))
             }
+        });
+        let rets = quote! {
+            #rt::tracing::event!(#rt::tracing::Level::TRACE, #(#trace_rets),*);
             (#(#trait_rets),*)
         };
         (rets, bindings)
@@ -151,37 +157,32 @@ pub fn define_func(
         let err_typename = names.type_ref(&err_type, anon_lifetime());
         quote! {
             let success:#err_typename = #rt::GuestErrorType::success();
-            #[cfg(feature = "trace_log")]
-            {
-                log::trace!("     | errno={}", success);
-            }
+            #rt::tracing::event!(
+                #rt::tracing::Level::TRACE,
+                success=#rt::tracing::field::display(&success)
+            );
             #abi_ret::from(success)
         }
     } else {
         quote!()
     };
 
-    let (placeholders, args): (Vec<_>, Vec<_>) = func
-        .params
-        .iter()
-        .map(|param| {
-            let name = names.func_param(&param.name);
-            let fmt = if passed_by_reference(&*param.tref.type_()) {
-                "{:?}"
-            } else {
-                "{}"
-            };
-            (format!("{}={}", name.to_string(), fmt), quote!(#name))
-        })
-        .unzip();
-    let trace_fmt = format!("{}({})", ident.to_string(), placeholders.join(","));
+    let trait_name = names.trait_name(&module.name);
+    let mod_name = &module.name.as_str();
+    let func_name = &func.name.as_str();
+
     quote!(pub fn #ident(#abi_args) -> #abi_ret {
+        let _span = #rt::tracing::span!(
+            #rt::tracing::Level::TRACE,
+            "wiggle abi",
+            module = #mod_name,
+            function = #func_name
+        );
+        let _enter = _span.enter();
+
         #(#marshal_args)*
         #(#marshal_rets_pre)*
-        #[cfg(feature = "trace_log")]
-        {
-            log::trace!(#trace_fmt, #(#args),*);
-        }
+        #log_marshalled_args
         let #trait_bindings  = match #trait_name::#ident(ctx, #(#trait_args),*) {
             Ok(#trait_bindings) => { #trait_rets },
             Err(e) => { #ret_err },
diff --git a/crates/wiggle/generate/src/lib.rs b/crates/wiggle/generate/src/lib.rs
index bd6d5d9e4..f1913163c 100644
--- a/crates/wiggle/generate/src/lib.rs
+++ b/crates/wiggle/generate/src/lib.rs
@@ -49,10 +49,9 @@ pub fn generate(doc: &witx::Document, names: &Names, errs: &ErrorTransform) -> T
     };
     let modules = doc.modules().map(|module| {
         let modname = names.module(&module.name);
-        let trait_name = names.trait_name(&module.name);
         let fs = module
             .funcs()
-            .map(|f| define_func(&names, &f, quote!(#trait_name), &errs));
+            .map(|f| define_func(&names, &module, &f, &errs));
         let modtrait = define_module_trait(&names, &module, &errs);
         let ctx_type = names.ctx_type();
         quote!(
diff --git a/crates/wiggle/generate/src/types/enum.rs b/crates/wiggle/generate/src/types/enum.rs
index a3a009604..cef56065e 100644
--- a/crates/wiggle/generate/src/types/enum.rs
+++ b/crates/wiggle/generate/src/types/enum.rs
@@ -112,3 +112,9 @@ pub(super) fn define_enum(names: &Names, name: &witx::Id, e: &witx::EnumDatatype
         }
     }
 }
+
+impl super::WiggleType for witx::EnumDatatype {
+    fn impls_display(&self) -> bool {
+        true
+    }
+}
diff --git a/crates/wiggle/generate/src/types/flags.rs b/crates/wiggle/generate/src/types/flags.rs
index 7759e7e6a..f87261abc 100644
--- a/crates/wiggle/generate/src/types/flags.rs
+++ b/crates/wiggle/generate/src/types/flags.rs
@@ -180,3 +180,9 @@ pub(super) fn define_flags(names: &Names, name: &witx::Id, f: &witx::FlagsDataty
 
     }
 }
+
+impl super::WiggleType for witx::FlagsDatatype {
+    fn impls_display(&self) -> bool {
+        true
+    }
+}
diff --git a/crates/wiggle/generate/src/types/handle.rs b/crates/wiggle/generate/src/types/handle.rs
index c28b77d88..310c9e7d6 100644
--- a/crates/wiggle/generate/src/types/handle.rs
+++ b/crates/wiggle/generate/src/types/handle.rs
@@ -82,3 +82,9 @@ pub(super) fn define_handle(
 
     }
 }
+
+impl super::WiggleType for witx::HandleDatatype {
+    fn impls_display(&self) -> bool {
+        true
+    }
+}
diff --git a/crates/wiggle/generate/src/types/int.rs b/crates/wiggle/generate/src/types/int.rs
index 43e699768..d916b65b7 100644
--- a/crates/wiggle/generate/src/types/int.rs
+++ b/crates/wiggle/generate/src/types/int.rs
@@ -92,3 +92,9 @@ pub(super) fn define_int(names: &Names, name: &witx::Id, i: &witx::IntDatatype)
 
     }
 }
+
+impl super::WiggleType for witx::IntDatatype {
+    fn impls_display(&self) -> bool {
+        true
+    }
+}
diff --git a/crates/wiggle/generate/src/types/mod.rs b/crates/wiggle/generate/src/types/mod.rs
index 19b8aa948..6ed29af94 100644
--- a/crates/wiggle/generate/src/types/mod.rs
+++ b/crates/wiggle/generate/src/types/mod.rs
@@ -91,3 +91,56 @@ fn atom_token(atom: witx::AtomType) -> TokenStream {
         witx::AtomType::F64 => quote!(f64),
     }
 }
+
+pub trait WiggleType {
+    fn impls_display(&self) -> bool;
+}
+
+impl WiggleType for witx::TypeRef {
+    fn impls_display(&self) -> bool {
+        match self {
+            witx::TypeRef::Name(alias_to) => (&*alias_to).impls_display(),
+            witx::TypeRef::Value(v) => (&*v).impls_display(),
+        }
+    }
+}
+
+impl WiggleType for witx::NamedType {
+    fn impls_display(&self) -> bool {
+        self.tref.impls_display()
+    }
+}
+
+impl WiggleType for witx::Type {
+    fn impls_display(&self) -> bool {
+        match self {
+            witx::Type::Enum(x) => x.impls_display(),
+            witx::Type::Int(x) => x.impls_display(),
+            witx::Type::Flags(x) => x.impls_display(),
+            witx::Type::Struct(x) => x.impls_display(),
+            witx::Type::Union(x) => x.impls_display(),
+            witx::Type::Handle(x) => x.impls_display(),
+            witx::Type::Builtin(x) => x.impls_display(),
+            witx::Type::Pointer { .. }
+            | witx::Type::ConstPointer { .. }
+            | witx::Type::Array { .. } => false,
+        }
+    }
+}
+
+impl WiggleType for witx::BuiltinType {
+    fn impls_display(&self) -> bool {
+        true
+    }
+}
+
+impl WiggleType for witx::InterfaceFuncParam {
+    fn impls_display(&self) -> bool {
+        match &*self.tref.type_() {
+            witx::Type::Struct { .. }
+            | witx::Type::Union { .. }
+            | witx::Type::Builtin(witx::BuiltinType::String { .. }) => false,
+            _ => self.tref.impls_display(),
+        }
+    }
+}
diff --git a/crates/wiggle/generate/src/types/struct.rs b/crates/wiggle/generate/src/types/struct.rs
index 47cd32d1e..5b3a02590 100644
--- a/crates/wiggle/generate/src/types/struct.rs
+++ b/crates/wiggle/generate/src/types/struct.rs
@@ -133,3 +133,9 @@ pub(super) fn define_struct(
         #transparent
     }
 }
+
+impl super::WiggleType for witx::StructDatatype {
+    fn impls_display(&self) -> bool {
+        false
+    }
+}
diff --git a/crates/wiggle/generate/src/types/union.rs b/crates/wiggle/generate/src/types/union.rs
index 0c357756e..ecc3253f3 100644
--- a/crates/wiggle/generate/src/types/union.rs
+++ b/crates/wiggle/generate/src/types/union.rs
@@ -108,3 +108,9 @@ pub(super) fn define_union(names: &Names, name: &witx::Id, u: &witx::UnionDataty
         }
     }
 }
+
+impl super::WiggleType for witx::UnionDatatype {
+    fn impls_display(&self) -> bool {
+        false
+    }
+}
diff --git a/crates/wiggle/src/lib.rs b/crates/wiggle/src/lib.rs
index 000080ad8..cbc92f266 100644
--- a/crates/wiggle/src/lib.rs
+++ b/crates/wiggle/src/lib.rs
@@ -16,6 +16,8 @@ mod error;
 mod guest_type;
 mod region;
 
+pub extern crate tracing;
+
 pub use borrow::BorrowChecker;
 use borrow::BorrowHandle;
 pub use error::GuestError;


Test patch:
diff --git a/crates/wiggle/test-helpers/Cargo.toml b/crates/wiggle/test-helpers/Cargo.toml
index da548e395..0df67f862 100644
--- a/crates/wiggle/test-helpers/Cargo.toml
+++ b/crates/wiggle/test-helpers/Cargo.toml
@@ -12,7 +12,14 @@ include = ["src/**/*", "LICENSE"]
 
 [dependencies]
 proptest = "0.9"
-wiggle = { path = ".." }
+wiggle = { path = "..", features = ["tracing_log"] }
+
+[dev-dependencies]
+thiserror = "1.0"
+tracing = "0.1.14"
+tracing-subscriber = "0.2.4"
+env_logger = "0.7"
+
 
 [badges]
 maintenance = { status = "actively-developed" }
diff --git a/crates/wiggle/test-helpers/examples/tracing.rs b/crates/wiggle/test-helpers/examples/tracing.rs
new file mode 100644
index 000000000..5b7eeb818
--- /dev/null
+++ b/crates/wiggle/test-helpers/examples/tracing.rs
@@ -0,0 +1,123 @@
+use wiggle_test::{impl_errno, HostMemory, WasiCtx};
+
+/// The `errors` argument to the wiggle gives us a hook to map a rich error
+/// type like this one (typical of wiggle use cases in wasi-common and beyond)
+/// down to the flat error enums that witx can specify.
+#[derive(Debug, thiserror::Error)]
+pub enum RichError {
+    #[error("Invalid argument: {0}")]
+    InvalidArg(String),
+    #[error("Won't cross picket line: {0}")]
+    PicketLine(String),
+}
+
+// Define an errno with variants corresponding to RichError. Use it in a
+// trivial function.
+wiggle::from_witx!({
+witx_literal: "
+(typename $errno (enum u8 $ok $invalid_arg $picket_line))
+(typename $s (struct (field $f1 (@witx usize)) (field $f2 (@witx pointer u8))))
+(typename $t (struct (field $f1 u32) (field $f2 f32)))
+(module $one_error_conversion
+  (@interface func (export \"foo\")
+     (param $strike u32)
+     (param $s $s)
+     (result $err $errno)
+     (result $t $t)))
+    ",
+    ctx: WasiCtx,
+    errors: { errno => RichError },
+});
+
+// The impl of GuestErrorConversion works just like in every other test where
+// we have a single error type with witx `$errno` with the success called `$ok`
+impl_errno!(types::Errno, types::GuestErrorConversion);
+
+/// When the `errors` mapping in witx is non-empty, we need to impl the
+/// types::UserErrorConversion trait that wiggle generates from that mapping.
+impl<'a> types::UserErrorConversion for WasiCtx<'a> {
+    fn errno_from_rich_error(&self, e: RichError) -> types::Errno {
+        wiggle::tracing::debug!(
+            rich_error = wiggle::tracing::field::debug(&e),
+            "error conversion"
+        );
+        // WasiCtx can collect a Vec<String> log so we can test this. We're
+        // logging the Display impl that `thiserror::Error` provides us.
+        self.log.borrow_mut().push(e.to_string());
+        // Then do the trivial mapping down to the flat enum.
+        match e {
+            RichError::InvalidArg { .. } => types::Errno::InvalidArg,
+            RichError::PicketLine { .. } => types::Errno::PicketLine,
+        }
+    }
+}
+
+impl<'a> one_error_conversion::OneErrorConversion for WasiCtx<'a> {
+    fn foo(&self, strike: u32, _s: &types::S) -> Result<types::T, RichError> {
+        // We use the argument to this function to exercise all of the
+        // possible error cases we could hit here
+        match strike {
+            0 => Ok(types::T {
+                f1: 123,
+                f2: 456.78,
+            }),
+            1 => Err(RichError::PicketLine(format!("I'm not a scab"))),
+            _ => Err(RichError::InvalidArg(format!("out-of-bounds: {}", strike))),
+        }
+    }
+}
+
+fn main() {
+    if std::env::var("RUST_LOG").is_err() {
+        // with no RUST_LOG env variable: use the tracing subscriber.
+        let subscriber = tracing_subscriber::fmt()
+            // all spans/events with a level equal to or higher than TRACE (e.g, trace, debug, info, warn, etc.)
+            // will be written to stdout.
+            .with_max_level(tracing::Level::TRACE)
+            // builds the subscriber.
+            .finish();
+        tracing::subscriber::set_global_default(subscriber).expect("set global tracing subscriber");
+    } else {
+        // with RUST_LOG set: use the env_logger backend to tracing.
+        env_logger::init();
+    }
+
+    let ctx = WasiCtx::new();
+    let host_memory = HostMemory::new();
+
+    // Exercise each of the branches in `foo`.
+    // Start with the success case:
+    let r0 = one_error_conversion::foo(&ctx, &host_memory, 0, 0, 8);
+    assert_eq!(
+        r0,
+        i32::from(types::Errno::Ok),
+        "Expected return value for strike=0"
+    );
+    assert!(ctx.log.borrow().is_empty(), "No error log for strike=0");
+
+    // First error case:
+    let r1 = one_error_conversion::foo(&ctx, &host_memory, 1, 0, 8);
+    assert_eq!(
+        r1,
+        i32::from(types::Errno::PicketLine),
+        "Expected return value for strike=1"
+    );
+    assert_eq!(
+        ctx.log.borrow_mut().pop().expect("one log entry"),
+        "Won't cross picket line: I'm not a scab",
+        "Expected log entry for strike=1",
+    );
+
+    // Second error case:
+    let r2 = one_error_conversion::foo(&ctx, &host_memory, 2, 0, 8);
+    assert_eq!(
+        r2,
+        i32::from(types::Errno::InvalidArg),
+        "Expected return value for strike=2"
+    );
+    assert_eq!(
+        ctx.log.borrow_mut().pop().expect("one log entry"),
+        "Invalid argument: out-of-bounds: 2",
+        "Expected log entry for strike=2",
+    );
+}