Update logging to use `log`, add command line flag to toggle it #1147

MarkMcCaskey · 2020-01-14T20:41:05Z

This PR:

ports our logging to the log crate which is the de-facto standard way to do logging in Rust (it defines a trait which logging backends can implement (we can also implement our own at a later date using these traits)). Another benefit of using the standard logging utilities is that we can now allow users of our libraries to filter and display log messages from Wasmer in a more natural way.
adds a command line flag to enable/disable logging
updates the debug and trace features to pass the correct static toggles to the log crate; judging by the log documentation these features need to only be set once
copies and slightly modifies our fern configuration from wapm
updates the makefile so that make release compiles out all log statements
TODO: update CI to not print with color (may not be necessary actually)

Review

Add a short description of the the change to the CHANGELOG.md file

Here's some example output:

[1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::inodes
[1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::preopen_dirs
[1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::mapped_dirs
[1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::end
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_prestat_get: fd=3
[1579035881.810 DEBUG wasmer_wasi::state] in prestat_fd Fd { rights: 536870911, rights_inheriting: 536870911, flags: 0, offset: 0, open_flags: 1, inode: Index { index: 3, generation: 0 } }
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_prestat_dir_name: fd=3, path_len=2
[1579035881.810 DEBUG wasmer_wasi::syscalls] => result: "/"
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_fdstat_get: fd=3, buf_ptr=1048536
[1579035881.810 DEBUG wasmer_wasi::state] fdstat: Fd { rights: 536870911, rights_inheriting: 536870911, flags: 0, offset: 0, open_flags: 1, inode: Index { index: 3, generation: 0 } }
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_prestat_get: fd=4
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::environ_sizes_get
[1579035881.810 DEBUG wasmer_wasi::syscalls] env_var_count: 0, env_buf_size: 0
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::args_sizes_get
[1579035881.810 DEBUG wasmer_wasi::syscalls] => argc=3, argv_buf_size=92
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::args_get
[1579035881.810 DEBUG wasmer_wasi::syscalls] => args:
                   0: /Users/mark/.wasmer/globals/wapm_packages/mark/rust-example@0.1.11/wasi-example.wasm
                   1: -e
                   2: HQ+
[1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::args_sizes_get
[1579035881.811 DEBUG wasmer_wasi::syscalls] => argc=3, argv_buf_size=92
[1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::args_get
[1579035881.811 DEBUG wasmer_wasi::syscalls] => args:
                   0: /Users/mark/.wasmer/globals/wapm_packages/mark/rust-example@0.1.11/wasi-example.wasm
                   1: -e
                   2: HQ+
[1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::random_get buf_len: 16
[1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::fd_write: fd=1
Hello, world!

[1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::fd_write: fd=1
HQ+

MarkMcCaskey · 2020-01-14T20:41:17Z

bors try

MarkMcCaskey · 2020-01-14T20:42:51Z

bors try-

MarkMcCaskey · 2020-01-14T20:42:56Z

bors try

MarkMcCaskey · 2020-01-14T21:00:30Z

bors try-

MarkMcCaskey · 2020-01-14T21:00:35Z

bors try

nlewycky · 2020-01-14T21:03:13Z

Cargo.toml

@@ -22,6 +22,9 @@ include = [
 [dependencies]
 byteorder = "1.3"
 errno = "0.2"
+fern = { version = "0.5", features = ["colored"], optional = true }
+# statically turn off logging for wasmer by default, fetaures override this


Suggested change

# statically turn off logging for wasmer by default, fetaures override this

# statically turn off logging for wasmer by default, features override this

I deleted this comment because it's no longer true!

nlewycky · 2020-01-14T21:13:22Z

src/utils.rs

+pub fn wasmer_should_print_color() -> bool {
+    std::env::var("WASMER_DISABLE_COLOR")
+        .map(|_| false)
+        .unwrap_or(true)


.unwrap_or(stdout_isatty()) from the isatty crate?

Which also implies that it shouldn't be WASMER_DISABLE_COLOR because we might also want to forcibly enable color when isatty is false. Perhaps WASMER_COLORS which may be true or false.

nlewycky · 2020-01-14T21:16:48Z

src/bin/wasmer.rs

@@ -247,6 +248,11 @@ struct Run {
    #[structopt(long = "enable-experimental-io-devices", hidden = true)]
    enable_experimental_io_devices: bool,

+    /// Enable debug output


Is there a canonical naming for the logging flags? I would expect that --debug would map precisely to enabling debug!() and above. Something like --log-level=... which corresponds to the enum in Log::LevelFilter, defaulting to Off given that we conditionally initialize logging?

Or maybe we should set it to Error or Warn and always initialize logging? I like that even more.

Yeah, so currently I'm using Cargo features for this!

bors · 2020-01-14T21:41:15Z

try

Build failed

wasmerio.wasmer

MarkMcCaskey · 2020-01-14T21:53:38Z

bors r+

1147: Update logging to use `log`, add command line flag to toggle it r=MarkMcCaskey a=MarkMcCaskey This PR: - ports our logging to the [`log`](https://crates.io/crates/log) crate which is the de-facto standard way to do logging in Rust (it defines a trait which logging backends can implement (we can also implement our own at a later date using these traits)). Another benefit of using the standard logging utilities is that we can now allow users of our libraries to filter and display log messages from Wasmer in a more natural way. - adds a command line flag to enable/disable logging - updates the `debug` and `trace` features to pass the correct static toggles to the `log` crate; judging by the `log` documentation these features need to only be set once - copies and slightly modifies our `fern` configuration from wapm - updates the makefile so that `make release` compiles out all log statements - TODO: update CI to not print with color (may not be necessary actually) # Review - [x] Add a short description of the the change to the CHANGELOG.md file Here's some example output: ``` [1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::inodes [1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::preopen_dirs [1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::mapped_dirs [1579035881.809 DEBUG wasmer_wasi::state] wasi::fs::end [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_prestat_get: fd=3 [1579035881.810 DEBUG wasmer_wasi::state] in prestat_fd Fd { rights: 536870911, rights_inheriting: 536870911, flags: 0, offset: 0, open_flags: 1, inode: Index { index: 3, generation: 0 } } [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_prestat_dir_name: fd=3, path_len=2 [1579035881.810 DEBUG wasmer_wasi::syscalls] => result: "/" [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_fdstat_get: fd=3, buf_ptr=1048536 [1579035881.810 DEBUG wasmer_wasi::state] fdstat: Fd { rights: 536870911, rights_inheriting: 536870911, flags: 0, offset: 0, open_flags: 1, inode: Index { index: 3, generation: 0 } } [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::fd_prestat_get: fd=4 [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::environ_sizes_get [1579035881.810 DEBUG wasmer_wasi::syscalls] env_var_count: 0, env_buf_size: 0 [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::args_sizes_get [1579035881.810 DEBUG wasmer_wasi::syscalls] => argc=3, argv_buf_size=92 [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::args_get [1579035881.810 DEBUG wasmer_wasi::syscalls] => args: 0: /Users/mark/.wasmer/globals/wapm_packages/mark/rust-example@0.1.11/wasi-example.wasm 1: -e 2: HQ+ [1579035881.810 DEBUG wasmer_wasi::syscalls] wasi::args_sizes_get [1579035881.811 DEBUG wasmer_wasi::syscalls] => argc=3, argv_buf_size=92 [1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::args_get [1579035881.811 DEBUG wasmer_wasi::syscalls] => args: 0: /Users/mark/.wasmer/globals/wapm_packages/mark/rust-example@0.1.11/wasi-example.wasm 1: -e 2: HQ+ [1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::random_get buf_len: 16 [1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::fd_write: fd=1 Hello, world! [1579035881.811 DEBUG wasmer_wasi::syscalls] wasi::fd_write: fd=1 HQ+ ``` Co-authored-by: Mark McCaskey <mark@wasmer.io>

bors · 2020-01-14T22:13:17Z

Build succeeded

continuous-integration/travis-ci/push
wasmerio.wasmer

MarkMcCaskey added 🎉 enhancement New feature! 📦 lib-deprecated About the deprecated crates 📦 lib-cli About wasmer-cli labels Jan 14, 2020

MarkMcCaskey requested review from bjfish, Hywan and syrusakbary as code owners January 14, 2020 20:41

bors bot added a commit that referenced this pull request Jan 14, 2020

Try #1147:

2fe73f1

Update logging to use log, add command line flag to toggle it

12f7416

MarkMcCaskey force-pushed the feature/standardized-logging branch from a56d859 to 12f7416 Compare January 14, 2020 20:42

bors bot added a commit that referenced this pull request Jan 14, 2020

Try #1147:

3914407

MarkMcCaskey requested review from losfair and nlewycky as code owners January 14, 2020 20:53

MarkMcCaskey force-pushed the feature/standardized-logging branch from c03f2f1 to 397343e Compare January 14, 2020 21:00

bors bot added a commit that referenced this pull request Jan 14, 2020

Try #1147:

89e1008

Remove vestigial debug features from various crates

286e5db

MarkMcCaskey force-pushed the feature/standardized-logging branch from 397343e to 286e5db Compare January 14, 2020 21:03

nlewycky reviewed Jan 14, 2020

View reviewed changes

Check if printing to a terminal for color output

39025d0

nlewycky approved these changes Jan 14, 2020

View reviewed changes

bors bot merged commit 39025d0 into master Jan 14, 2020

bors bot deleted the feature/standardized-logging branch January 14, 2020 22:13

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Update logging to use `log`, add command line flag to toggle it #1147

Update logging to use `log`, add command line flag to toggle it #1147

MarkMcCaskey commented Jan 14, 2020 •

edited

Loading

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

nlewycky Jan 14, 2020

MarkMcCaskey Jan 14, 2020

nlewycky Jan 14, 2020

nlewycky Jan 14, 2020

MarkMcCaskey Jan 14, 2020

bors bot commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

bors bot commented Jan 14, 2020

	# statically turn off logging for wasmer by default, fetaures override this
	# statically turn off logging for wasmer by default, features override this

Update logging to use log, add command line flag to toggle it #1147

Update logging to use log, add command line flag to toggle it #1147

Conversation

MarkMcCaskey commented Jan 14, 2020 • edited Loading

Review

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

MarkMcCaskey commented Jan 14, 2020

nlewycky Jan 14, 2020

Choose a reason for hiding this comment

MarkMcCaskey Jan 14, 2020

Choose a reason for hiding this comment

nlewycky Jan 14, 2020

Choose a reason for hiding this comment

nlewycky Jan 14, 2020

Choose a reason for hiding this comment

MarkMcCaskey Jan 14, 2020

Choose a reason for hiding this comment

bors bot commented Jan 14, 2020

try

Build failed

MarkMcCaskey commented Jan 14, 2020

bors bot commented Jan 14, 2020

Build succeeded

Update logging to use `log`, add command line flag to toggle it #1147

Update logging to use `log`, add command line flag to toggle it #1147

MarkMcCaskey commented Jan 14, 2020 •

edited

Loading