Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

wasmtime-cli: add tracing output on WASMTIME_LOG #7239

Merged
merged 3 commits into from
Oct 13, 2023
Merged

Conversation

pchickey
Copy link
Collaborator

@pchickey pchickey commented Oct 13, 2023

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().

[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(())

@pchickey pchickey requested review from a team as code owners October 13, 2023 20:53
@pchickey pchickey requested review from alexcrichton and removed request for a team October 13, 2023 20:53
Copy link
Member

@elliottt elliottt left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nice!

@pchickey pchickey added this pull request to the merge queue Oct 13, 2023
Merged via the queue into main with commit f952ff2 Oct 13, 2023
20 checks passed
@pchickey pchickey deleted the pch/cli_tracing branch October 13, 2023 23:48
alexcrichton added a commit to alexcrichton/wasmtime that referenced this pull request Oct 14, 2023
Some things I noticed from bytecodealliance#7239 which are very much not critical but I
figure might be nice-to-haves:

* Move the logging configuration to the `wasmtime-cli-flags` crate with
  the other logging configuration to keep it in one place.
* Remove `pretty_env_logger` since `tracing-subscriber` probably
  supplants it.
* Don't explicitly inherit env vars in tests since that happens
  automatically with `Command`.
alexcrichton added a commit to alexcrichton/wasmtime that referenced this pull request Oct 16, 2023
Some things I noticed from bytecodealliance#7239 which are very much not critical but I
figure might be nice-to-haves:

* Move the logging configuration to the `wasmtime-cli-flags` crate with
  the other logging configuration to keep it in one place.
* Remove `pretty_env_logger` since `tracing-subscriber` probably
  supplants it.
* Don't explicitly inherit env vars in tests since that happens
  automatically with `Command`.
github-merge-queue bot pushed a commit that referenced this pull request Oct 16, 2023
Some things I noticed from #7239 which are very much not critical but I
figure might be nice-to-haves:

* Move the logging configuration to the `wasmtime-cli-flags` crate with
  the other logging configuration to keep it in one place.
* Remove `pretty_env_logger` since `tracing-subscriber` probably
  supplants it.
* Don't explicitly inherit env vars in tests since that happens
  automatically with `Command`.
cfallin added a commit to cfallin/wasmtime that referenced this pull request Nov 1, 2023
In bytecodealliance#7239 we added a `tracing-log` subscriber that prints logs to stderr
if enabled with an environment variable. It included logic to add ANSI
color sequences when stderr is a terminal, for legibility. Unfortunately
it seems that while this logic *enabled* colors on a terminal, it did
not *disable* colors on a non-terminal; so redirects of stderr to a file
would result in ANSI color sequences being captured in that file.
Specifically, the builder seems not to default to no-color; so rather
than enable-or-nothing, we should explicitly enable or disable always.

Fixes bytecodealliance#7435.
github-merge-queue bot pushed a commit that referenced this pull request Nov 1, 2023
…7436)

In #7239 we added a `tracing-log` subscriber that prints logs to stderr
if enabled with an environment variable. It included logic to add ANSI
color sequences when stderr is a terminal, for legibility. Unfortunately
it seems that while this logic *enabled* colors on a terminal, it did
not *disable* colors on a non-terminal; so redirects of stderr to a file
would result in ANSI color sequences being captured in that file.
Specifically, the builder seems not to default to no-color; so rather
than enable-or-nothing, we should explicitly enable or disable always.

Fixes #7435.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

2 participants