Merge #1147

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/[email protected]/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/[email protected]/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 <[email protected]>
wasmerio · Jan 14, 2020 · d350613 · d350613
2 parents a8ed5b9 + 39025d0
commit d350613
Show file tree

Hide file tree

Showing 25 changed files with 176 additions and 83 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -2,6 +2,7 @@
 
 ## **[Unreleased]**
 
+- [#1147](https://github.com/wasmerio/wasmer/pull/1147) Remove `log` and `trace` macros from `wasmer-runtime-core`, remove `debug` and `trace` features from `wasmer-*` crates, use the `log` crate for logging and use `fern` in the Wasmer CLI binary to output log messages.  Colorized output will be enabled automatically if printing to a terminal, to force colorization on or off, set the `WASMER_COLOR` environment variable to `true` or `false`.
 - [#1128](https://github.com/wasmerio/wasmer/pull/1128) Fix a crash when a host function is missing and the `allow_missing_functions` flag is enabled
 - [#1099](https://github.com/wasmerio/wasmer/pull/1099) Remove `backend::Backend` from `wasmer_runtime_core`
 - [#1097](https://github.com/wasmerio/wasmer/pull/1097) Move inline breakpoint outside of runtime backend

diff --git a/Cargo.lock b/Cargo.lock
diff --git a/Cargo.toml b/Cargo.toml
@@ -20,8 +20,11 @@ include = [
 ]
 
 [dependencies]
+atty = "0.2"
 byteorder = "1.3"
 errno = "0.2"
+fern = { version = "0.5", features = ["colored"], optional = true }
+log = "0.4"
 structopt = "0.3"
 wabt = "0.9.1"
 wasmer-clif-backend = { path = "lib/clif-backend", optional = true }
@@ -78,10 +81,9 @@ typetag = "0.1" # used by the plugin example
 [features]
 default = ["fast-tests", "wasi", "backend-cranelift"]
 "loader-kernel" = ["wasmer-kernel-loader"]
-debug = ["wasmer-runtime-core/debug"]
-trace = ["wasmer-runtime-core/trace"]
+debug = ["fern", "log/max_level_debug", "log/release_max_level_debug"]
+trace = ["fern", "log/max_level_trace", "log/release_max_level_trace"]
 docs = ["wasmer-runtime/docs"]
-extra-debug = ["wasmer-clif-backend/debug", "wasmer-runtime-core/debug"]
 # This feature will allow cargo test to run much faster
 fast-tests = []
 backend-cranelift = [

diff --git a/Makefile b/Makefile
@@ -231,34 +231,34 @@ check: check-bench
 	cargo check --release --manifest-path lib/runtime/Cargo.toml
 
 	$(RUNTIME_CHECK) \
-		--features=cranelift,cache,debug,llvm,singlepass,default-backend-singlepass
+		--features=cranelift,cache,llvm,singlepass,default-backend-singlepass
 	$(RUNTIME_CHECK) --release \
 		--features=cranelift,cache,llvm,singlepass,default-backend-singlepass
 	$(RUNTIME_CHECK) \
-		--features=cranelift,cache,debug,llvm,singlepass,default-backend-cranelift
+		--features=cranelift,cache,llvm,singlepass,default-backend-cranelift
 	$(RUNTIME_CHECK) --release \
 		--features=cranelift,cache,llvm,singlepass,default-backend-cranelift
 	$(RUNTIME_CHECK) \
-		--features=cranelift,cache,debug,llvm,singlepass,default-backend-llvm
+		--features=cranelift,cache,llvm,singlepass,default-backend-llvm
 	$(RUNTIME_CHECK) --release \
 		--features=cranelift,cache,llvm,singlepass,default-backend-llvm
 	$(RUNTIME_CHECK) \
-		--features=singlepass,default-backend-singlepass,debug
+		--features=singlepass,default-backend-singlepass
 	$(RUNTIME_CHECK) --release \
 		--features=singlepass,default-backend-singlepass
 	$(RUNTIME_CHECK) \
-		--features=cranelift,default-backend-cranelift,debug
+		--features=cranelift,default-backend-cranelift
 	$(RUNTIME_CHECK) --release \
 		--features=cranelift,default-backend-cranelift
 	$(RUNTIME_CHECK) \
-		--features=llvm,default-backend-llvm,debug
+		--features=llvm,default-backend-llvm
 	$(RUNTIME_CHECK) --release \
 		--features=llvm,default-backend-llvm
-		--features=default-backend-singlepass,singlepass,cranelift,llvm,cache,debug,deterministic-execution
+		--features=default-backend-singlepass,singlepass,cranelift,llvm,cache,deterministic-execution
 
 # Release
 release:
-	cargo build --release --features backend-singlepass,backend-cranelift,backend-llvm,loader-kernel,experimental-io-devices
+	cargo build --release --features backend-singlepass,backend-cranelift,backend-llvm,loader-kernel,experimental-io-devices,log/release_max_level_off
 
 # Only one backend (cranelift)
 release-clif:

diff --git a/lib/clif-backend/Cargo.toml b/lib/clif-backend/Cargo.toml
@@ -37,7 +37,4 @@ version = "0.0.7"
 
 [target.'cfg(windows)'.dependencies]
 winapi = { version = "0.3", features = ["errhandlingapi", "minwindef", "minwinbase", "winnt"] }
-wasmer-win-exception-handler = { path = "../win-exception-handler", version = "0.12.0" }
-
-[features]
-debug = ["wasmer-runtime-core/debug"]
+wasmer-win-exception-handler = { path = "../win-exception-handler", version = "0.12.0" }
diff --git a/lib/emscripten/Cargo.toml b/lib/emscripten/Cargo.toml
@@ -13,11 +13,9 @@ edition = "2018"
 byteorder = "1.3"
 lazy_static = "1.4"
 libc = "0.2.60"
+log = "0.4"
 time = "0.1"
 wasmer-runtime-core = { path = "../runtime-core", version = "0.12.0" }
 
 [target.'cfg(windows)'.dependencies]
 getrandom = "0.1"
-
-[features]
-debug = ["wasmer-runtime-core/debug"]
diff --git a/lib/emscripten/src/lib.rs b/lib/emscripten/src/lib.rs
@@ -12,6 +12,8 @@
 
 #[macro_use]
 extern crate wasmer_runtime_core;
+#[macro_use]
+extern crate log;
 
 use lazy_static::lazy_static;
 use std::cell::UnsafeCell;

diff --git a/lib/llvm-backend/Cargo.toml b/lib/llvm-backend/Cargo.toml
@@ -46,5 +46,4 @@ rustc_version = "0.2"
 wabt = "0.9.1"
 
 [features]
-debug = ["wasmer-runtime-core/debug"]
 test = []
diff --git a/lib/runtime-c-api/Cargo.toml b/lib/runtime-c-api/Cargo.toml
@@ -39,7 +39,6 @@ optional = true
 
 [features]
 default = ["cranelift-backend", "wasi"]
-debug = ["wasmer-runtime/debug"]
 singlepass-backend = ["wasmer-runtime/singlepass", "wasmer-runtime/default-backend-singlepass"]
 cranelift-backend = ["wasmer-runtime/cranelift", "wasmer-runtime/default-backend-cranelift"]
 llvm-backend = ["wasmer-runtime/llvm", "wasmer-runtime/default-backend-llvm"]

diff --git a/lib/runtime-core/Cargo.toml b/lib/runtime-core/Cargo.toml
@@ -50,7 +50,5 @@ rustc_version = "0.2"
 cc = "1.0"
 
 [features]
-debug = []
-trace = ["debug"]
 managed = []
 deterministic-execution = ["wasmparser/deterministic"]
diff --git a/lib/runtime-core/src/macros.rs b/lib/runtime-core/src/macros.rs
@@ -1,49 +1,3 @@
-/// Prints a log message with args, similar to println, when the debug feature is enabled.
-/// If the debug feature is disabled, arguments are not evaluated or printed.
-#[macro_export]
-#[cfg(feature = "debug")]
-macro_rules! debug {
-    ($fmt:expr) => (println!(concat!("[{}] wasmer-runtime(:{}) ", $fmt), {
-       let time = ::std::time::SystemTime::now().duration_since(::std::time::UNIX_EPOCH).expect("Can't get time");
-       format!("{}.{:03}", time.as_secs(), time.subsec_millis())
-    }, line!()));
-    ($fmt:expr, $($arg:tt)*) => (println!(concat!("[{}] wasmer-runtime(:{}) ", $fmt, "\n"), {
-       let time = ::std::time::SystemTime::now().duration_since(::std::time::UNIX_EPOCH).expect("Can't get time");
-       format!("{}.{:03}", time.as_secs(), time.subsec_millis())
-    }, line!(), $($arg)*));
-}
-
-/// Prints a log message with args, similar to println, when the debug feature is enabled.
-/// If the debug feature is disabled, arguments are not evaluated or printed.
-#[macro_export]
-#[cfg(not(feature = "debug"))]
-macro_rules! debug {
-    ($fmt:expr) => {};
-    ($fmt:expr, $($arg:tt)*) => {};
-}
-
-/// Prints a log message with args, similar to println, when the trace feature is enabled.
-/// If the trace feature is disabled, arguments are not evaluated or printed.
-#[macro_export]
-#[cfg(feature = "trace")]
-macro_rules! trace {
-    ($fmt:expr) => {
-        debug!($fmt)
-    };
-    ($fmt:expr, $($arg:tt)*) => {
-        debug!($fmt, $($arg)*);
-    }
-}
-
-/// Prints a log message with args, similar to println, when the trace feature is enabled.
-/// If the trace feature is disabled, arguments are not evaluated or printed.
-#[macro_export]
-#[cfg(not(feature = "trace"))]
-macro_rules! trace {
-    ($fmt:expr) => {};
-    ($fmt:expr, $($arg:tt)*) => {};
-}
-
 /// Helper macro to create a new `Func` object using the provided function pointer.
 ///
 /// # Usage

diff --git a/lib/runtime/Cargo.toml b/lib/runtime/Cargo.toml
@@ -46,7 +46,6 @@ default = ["cranelift", "default-backend-cranelift"]
 docs = []
 cranelift = ["wasmer-clif-backend"]
 cache = ["cranelift"]
-debug = ["wasmer-clif-backend/debug", "wasmer-runtime-core/debug"]
 llvm = ["wasmer-llvm-backend"]
 singlepass = ["wasmer-singlepass-backend"]
 default-backend-singlepass = ["singlepass"]

diff --git a/lib/wasi-experimental-io-devices/Cargo.toml b/lib/wasi-experimental-io-devices/Cargo.toml
@@ -12,6 +12,7 @@ license = "MIT"
 maintenance = { status = "experimental" }
 
 [dependencies]
+log = "0.4"
 minifb = "0.13"
 wasmer-wasi = { version = "0.12.0", path = "../wasi" }
 wasmer-runtime-core = { version = "0.12.0", path = "../runtime-core" }

diff --git a/lib/wasi-experimental-io-devices/src/lib.rs b/lib/wasi-experimental-io-devices/src/lib.rs
@@ -1,8 +1,10 @@
+#[macro_use]
+extern crate log;
+
 use serde::{Deserialize, Serialize};
 use std::collections::{BTreeSet, VecDeque};
 use std::convert::TryInto;
 use std::io::{Read, Seek, SeekFrom, Write};
-use wasmer_runtime_core::debug;
 use wasmer_wasi::{
     state::{Fd, WasiFile, WasiFs, WasiFsError, ALL_RIGHTS, VIRTUAL_ROOT_FD},
     types::*,

diff --git a/lib/wasi/src/lib.rs b/lib/wasi/src/lib.rs
@@ -22,6 +22,8 @@
 
 #[cfg(target = "windows")]
 extern crate winapi;
+#[macro_use]
+extern crate log;
 
 #[macro_use]
 mod macros;

diff --git a/lib/wasi/src/macros.rs b/lib/wasi/src/macros.rs
@@ -3,11 +3,11 @@ macro_rules! wasi_try {
         let res: Result<_, crate::syscalls::types::__wasi_errno_t> = $expr;
         match res {
             Ok(val) => {
-                wasmer_runtime_core::trace!("wasi::wasi_try::val: {:?}", val);
+                trace!("wasi::wasi_try::val: {:?}", val);
                 val
             }
             Err(err) => {
-                wasmer_runtime_core::trace!("wasi::wasi_try::err: {:?}", err);
+                trace!("wasi::wasi_try::err: {:?}", err);
                 return err;
             }
         }

diff --git a/lib/wasi/src/state/mod.rs b/lib/wasi/src/state/mod.rs
@@ -31,7 +31,7 @@ use std::{
     path::{Path, PathBuf},
     time::SystemTime,
 };
-use wasmer_runtime_core::{debug, vm::Ctx};
+use wasmer_runtime_core::vm::Ctx;
 
 /// the fd value of the virtual root
 pub const VIRTUAL_ROOT_FD: __wasi_fd_t = 3;

diff --git a/lib/wasi/src/state/types.rs b/lib/wasi/src/state/types.rs
@@ -9,7 +9,6 @@ use std::{
     path::PathBuf,
     time::SystemTime,
 };
-use wasmer_runtime_core::debug;
 
 /// Error type for external users
 #[derive(Copy, Clone, Debug, PartialEq, Eq)]

diff --git a/lib/wasi/src/syscalls/legacy/snapshot0.rs b/lib/wasi/src/syscalls/legacy/snapshot0.rs
@@ -1,7 +1,7 @@
 use crate::ptr::{Array, WasmPtr};
 use crate::syscalls;
 use crate::syscalls::types::{self, snapshot0};
-use wasmer_runtime_core::{debug, vm::Ctx};
+use wasmer_runtime_core::vm::Ctx;
 
 /// Wrapper around `syscalls::fd_filestat_get` with extra logic to handle the size
 /// difference of `wasi_filestat_t`