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

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

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 = [

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:

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" }

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"]

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;

lib/llvm-backend/Cargo.toml

@@ -46,5 +46,4 @@ rustc_version = "0.2"
 wabt = "0.9.1"
 
 [features]
-debug = ["wasmer-runtime-core/debug"]
 test = []

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"]

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"]

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

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"]

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" }

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::*,

lib/wasi/src/lib.rs

@@ -22,6 +22,8 @@
 
 #[cfg(target = "windows")]
 extern crate winapi;
+#[macro_use]
+extern crate log;
 
 #[macro_use]
 mod macros;

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;
             }
         }

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;

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)]

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`