Repository: bytecodealliance/wasmtime
Pull request #7239 (2023-10-13 20:53:44)

wasmtime-cli: add tracing output on `WASMTIME_LOG`
We use `log` and `tracing` messages in many parts of the wasmtime project to provide debug output. This PR installs `tracing-subscriber` in the wasmtime-cli `fn main()`. It is configured to read the `WASMTIME_LOG` env variable, output to stderr, and use ansi coloring when std::io::stderr().is_terminal().

<details>
<pre>
[phickey@pch-tower:src/wasmtime]% WASMTIME_LOG=wasmtime_wasi=trace cargo run -- --wasm component-model cli_hello_stdout.component.wasm
   Compiling wasmtime-cli v15.0.0 (/home/phickey/src/wasmtime)
    Finished dev [unoptimized + debuginfo] target(s) in 1.27s
     Running `target/debug/wasmtime --wasm component-model cli_hello_stdout.component.wasm`
2023-10-13T20:49:45.513742Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="terminal-stdin" function="get-terminal-stdin"}: wasmtime_wasi::preview2::bindings::wasi::cli::terminal_stdin: call
2023-10-13T20:49:45.513811Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="terminal-stdin" function="get-terminal-stdin"}: wasmtime_wasi::preview2::bindings::wasi::cli::terminal_stdin: return result=Ok(Some(Resource { rep: 3, state: "own (not in table)" }))
2023-10-13T20:49:45.513943Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="terminal-stdout" function="get-terminal-stdout"}: wasmtime_wasi::preview2::bindings::wasi::cli::terminal_stdout: call
2023-10-13T20:49:45.513972Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="terminal-stdout" function="get-terminal-stdout"}: wasmtime_wasi::preview2::bindings::wasi::cli::terminal_stdout: return result=Ok(Some(Resource { rep: 4, state: "own (not in table)" }))
2023-10-13T20:49:45.514052Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="terminal-stderr" function="get-terminal-stderr"}: wasmtime_wasi::preview2::bindings::wasi::cli::terminal_stderr: call
2023-10-13T20:49:45.514081Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="terminal-stderr" function="get-terminal-stderr"}: wasmtime_wasi::preview2::bindings::wasi::cli::terminal_stderr: return result=Ok(Some(Resource { rep: 5, state: "own (not in table)" }))
2023-10-13T20:49:45.514182Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="stdin" function="get-stdin"}: wasmtime_wasi::preview2::bindings::wasi::cli::stdin: call
2023-10-13T20:49:45.514214Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="stdin" function="get-stdin"}: wasmtime_wasi::preview2::bindings::wasi::cli::stdin: return result=Ok(Resource { rep: 6, state: "own (not in table)" })
2023-10-13T20:49:45.514289Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="stdout" function="get-stdout"}: wasmtime_wasi::preview2::bindings::wasi::cli::stdout: call
2023-10-13T20:49:45.514511Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="stdout" function="get-stdout"}: wasmtime_wasi::preview2::bindings::wasi::cli::stdout: return result=Ok(Resource { rep: 7, state: "own (not in table)" })
2023-10-13T20:49:45.514595Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="stderr" function="get-stderr"}: wasmtime_wasi::preview2::bindings::wasi::cli::stderr: call
2023-10-13T20:49:45.514635Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="stderr" function="get-stderr"}: wasmtime_wasi::preview2::bindings::wasi::cli::stderr: return result=Ok(Resource { rep: 8, state: "own (not in table)" })
2023-10-13T20:49:45.514696Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="preopens" function="get-directories"}: wasmtime_wasi::preview2::bindings::wasi::filesystem::preopens: call
2023-10-13T20:49:45.514726Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="preopens" function="get-directories"}: wasmtime_wasi::preview2::bindings::wasi::filesystem::preopens: return result=Ok([])
2023-10-13T20:49:45.514846Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::bindings::sync_io::_internal::wasi::io::streams: call self_=Resource { rep: 7, state: "borrow" } contents=[104, 101, 108, 108, 111, 44, 32, 119, 111, 114, 108, 100, 10]
2023-10-13T20:49:45.515027Z DEBUG wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::write_stream: worker writing: b"hello, world\n"
hello, world
2023-10-13T20:49:45.515316Z DEBUG wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::write_stream: worker marking flush complete
2023-10-13T20:49:45.515371Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::bindings::sync_io::_internal::wasi::io::streams: return result=Ok(())
2023-10-13T20:49:45.515460Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::bindings::sync_io::_internal::wasi::io::streams: call self_=Resource { rep: 8, state: "borrow" } contents=[104, 101, 108, 108, 111, 44, 32, 119, 111, 114, 108, 100, 10]
2023-10-13T20:49:45.515534Z DEBUG wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::write_stream: worker writing: b"hello, world\n"
hello, world
2023-10-13T20:49:45.515655Z DEBUG wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::write_stream: worker marking flush complete
2023-10-13T20:49:45.515701Z TRACE wit-bindgen export{module="wasi:cli/run" function="run"}:wit-bindgen import{module="streams" function="[method]output-stream.blocking-write-and-flush"}: wasmtime_wasi::preview2::bindings::sync_io::_internal::wasi::io::streams: return result=Ok(())

</pre>
</details>


Patch:
diff --git a/Cargo.lock b/Cargo.lock
index e84eb5adf..3b6e0bb5a 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -1827,6 +1827,16 @@ dependencies = [
  "windows-sys",
 ]
 
+[[package]]
+name = "nu-ansi-term"
+version = "0.46.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84"
+dependencies = [
+ "overload",
+ "winapi",
+]
+
 [[package]]
 name = "num-traits"
 version = "0.2.15"
@@ -1938,6 +1948,12 @@ dependencies = [
  "pretty_env_logger 0.4.0",
 ]
 
+[[package]]
+name = "overload"
+version = "0.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39"
+
 [[package]]
 name = "paste"
 version = "1.0.7"
@@ -2824,6 +2840,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77"
 dependencies = [
  "matchers",
+ "nu-ansi-term",
  "once_cell",
  "regex",
  "sharded-slab",
@@ -3376,6 +3393,7 @@ dependencies = [
  "tempfile",
  "test-programs-artifacts",
  "tokio",
+ "tracing-subscriber",
  "walkdir",
  "wasm-encoder",
  "wasmparser",
diff --git a/Cargo.toml b/Cargo.toml
index c029cb08c..ec36b875e 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -39,6 +39,7 @@ wasmtime-runtime = { workspace = true }
 clap = { workspace = true, features = ["color", "suggestions", "derive"] }
 anyhow = { workspace = true }
 target-lexicon = { workspace = true }
+tracing-subscriber = { workspace = true }
 once_cell = { workspace = true }
 listenfd = "1.0.0"
 wat = { workspace = true }
@@ -263,7 +264,7 @@ indexmap = "2.0.0"
 pretty_env_logger = "0.5.0"
 syn = "2.0.25"
 test-log = { version = "0.2", default-features = false, features = ["trace"] }
-tracing-subscriber = { version = "0.3.1", default-features = false, features = ['fmt', 'env-filter'] }
+tracing-subscriber = { version = "0.3.1", default-features = false, features = ['fmt', 'env-filter', 'ansi'] }
 url = "2.3.1"
 
 [features]
diff --git a/src/bin/wasmtime.rs b/src/bin/wasmtime.rs
index 46868b3ac..6e289a74b 100644
--- a/src/bin/wasmtime.rs
+++ b/src/bin/wasmtime.rs
@@ -82,6 +82,16 @@ impl Wasmtime {
 }
 
 fn main() -> Result<()> {
+    use std::io::IsTerminal;
+    use tracing_subscriber::{EnvFilter, FmtSubscriber};
+
+    let mut b = FmtSubscriber::builder()
+        .with_writer(std::io::stderr)
+        .with_env_filter(EnvFilter::from_env("WASMTIME_LOG"));
+    if std::io::stderr().is_terminal() {
+        b = b.with_ansi(true);
+    }
+    b.init();
     Wasmtime::parse().execute()
 }
 
diff --git a/supply-chain/audits.toml b/supply-chain/audits.toml
index 075dd2052..f03ba4690 100644
--- a/supply-chain/audits.toml
+++ b/supply-chain/audits.toml
@@ -1626,6 +1626,12 @@ criteria = "safe-to-deploy"
 version = "0.2.11"
 notes = "build is only looking for environment variables to set cfg. only two minor uses of unsafe,on macos, with ffi bindings to digest primitives and libc atexit. otherwise, this is an abstraction over three very complex systems (schannel, security-framework, and openssl) which may end up having subtle differences, but none of those are apparent from the implementation of this crate"
 
+[[audits.nu-ansi-term]]
+who = "Pat Hickey <phickey@fastly.com>"
+criteria = "safe-to-deploy"
+version = "0.46.0"
+notes = "one use of unsafe to call windows specific api to get console handle."
+
 [[audits.object]]
 who = "Chris Fallin <chris@cfallin.org>"
 criteria = "safe-to-deploy"
@@ -1707,6 +1713,12 @@ who = "Andrew Brown <andrew.brown@intel.com>"
 criteria = "safe-to-deploy"
 delta = "0.4.2 -> 0.5.0"
 
+[[audits.overload]]
+who = "Pat Hickey <phickey@fastly.com>"
+criteria = "safe-to-deploy"
+version = "0.1.1"
+notes = "small crate, only defines macro-rules!, nicely documented as well"
+
 [[audits.peeking_take_while]]
 who = "Nick Fitzgerald <fitzgen@gmail.com>"
 criteria = "safe-to-deploy"
@@ -1904,6 +1916,12 @@ criteria = "safe-to-deploy"
 delta = "0.9.9 -> 0.10.2"
 notes = "This upgrade is mostly a code refactor, as far as I can tell. No new uses of unsafe nor any new ambient capabilities usage."
 
+[[audits.sharded-slab]]
+who = "Pat Hickey <phickey@fastly.com>"
+criteria = "safe-to-deploy"
+version = "0.1.4"
+notes = "I always really enjoy reading eliza's code, she left perfect comments at every use of unsafe."
+
 [[audits.signal-hook-registry]]
 who = "Pat Hickey <phickey@fastly.com>"
 criteria = "safe-to-deploy"
@@ -2017,6 +2035,12 @@ who = "Pat Hickey <phickey@fastly.com>"
 criteria = "safe-to-deploy"
 version = "0.2.11"
 
+[[audits.thread_local]]
+who = "Pat Hickey <phickey@fastly.com>"
+criteria = "safe-to-deploy"
+version = "1.1.4"
+notes = "uses unsafe to implement thread local storage of objects"
+
 [[audits.tinyvec]]
 who = "Alex Crichton <alex@alexcrichton.com>"
 criteria = "safe-to-deploy"
@@ -2096,6 +2120,11 @@ This is a relatively minor set of releases with minor refactorings and bug
 fixes. Nothing fundamental was added in these changes.
 """
 
+[[audits.tracing-subscriber]]
+who = "Pat Hickey <phickey@fastly.com>"
+criteria = "safe-to-deploy"
+version = "0.3.17"
+
 [[audits.tracing-subscriber]]
 who = "Alex Crichton <alex@alexcrichton.com>"
 criteria = "safe-to-run"
diff --git a/supply-chain/config.toml b/supply-chain/config.toml
index e1d1435fb..8a9194695 100644
--- a/supply-chain/config.toml
+++ b/supply-chain/config.toml
@@ -169,9 +169,6 @@ audit-as-crates-io = true
 [policy.wasmtime-wit-bindgen]
 audit-as-crates-io = true
 
-[policy.wasmtime-wmemcheck]
-audit-as-crates-io = true
-
 [policy.wiggle]
 audit-as-crates-io = true
 
@@ -527,10 +524,6 @@ notes = "contains assembly language and object file implementations of crypto pr
 version = "0.3.0"
 criteria = "safe-to-deploy"
 
-[[exemptions.sharded-slab]]
-version = "0.1.4"
-criteria = "safe-to-run"
-
 [[exemptions.shellexpand]]
 version = "2.1.0"
 criteria = "safe-to-deploy"
@@ -579,10 +572,6 @@ criteria = "safe-to-deploy"
 version = "0.1.17"
 criteria = "safe-to-deploy"
 
-[[exemptions.thread_local]]
-version = "1.1.4"
-criteria = "safe-to-run"
-
 [[exemptions.tinytemplate]]
 version = "1.2.1"
 criteria = "safe-to-run"
@@ -608,10 +597,6 @@ criteria = "safe-to-deploy"
 version = "0.1.28"
 criteria = "safe-to-deploy"
 
-[[exemptions.tracing-subscriber]]
-version = "0.3.11"
-criteria = "safe-to-run"
-
 [[exemptions.typenum]]
 version = "1.15.0"
 criteria = "safe-to-deploy"
diff --git a/supply-chain/imports.lock b/supply-chain/imports.lock
index 50f08e466..e80834140 100644
--- a/supply-chain/imports.lock
+++ b/supply-chain/imports.lock
@@ -1010,12 +1010,6 @@ when = "2023-09-20"
 user-id = 73222
 user-login = "wasmtime-publish"
 
-[[publisher.wasmtime-wmemcheck]]
-version = "13.0.0"
-when = "2023-09-20"
-user-id = 73222
-user-login = "wasmtime-publish"
-
 [[publisher.wast]]
 version = "65.0.2"
 when = "2023-09-26"


Test patch:
diff --git a/tests/all/cli_tests.rs b/tests/all/cli_tests.rs
index 997738cdd..a114e2a3e 100644
--- a/tests/all/cli_tests.rs
+++ b/tests/all/cli_tests.rs
@@ -32,7 +32,7 @@ pub fn get_wasmtime_command() -> Result<Command> {
     // If we're running tests with a "runner" then we might be doing something
     // like cross-emulation, so spin up the emulator rather than the tests
     // itself, which may not be natively executable.
-    let cmd = if let Some((_, runner)) = runner {
+    let mut cmd = if let Some((_, runner)) = runner {
         let mut parts = runner.split_whitespace();
         let mut cmd = Command::new(parts.next().unwrap());
         for arg in parts {
@@ -44,6 +44,10 @@ pub fn get_wasmtime_command() -> Result<Command> {
         Command::new(&me)
     };
 
+    if let Ok(val) = std::env::var("WASMTIME_LOG") {
+        cmd.env("WASMTIME_LOG", val);
+    }
+
     Ok(cmd)
 }