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

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
+log = "0.4"
 structopt = "0.3"
 wabt = "0.9.1"
 wasmer-clif-backend = { path = "lib/clif-backend", optional = true }
@@ -78,8 +81,8 @@ 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 = ["wasmer-runtime-core/debug", "fern", "log/max_level_debug", "log/release_max_level_debug"]
+trace = ["wasmer-runtime-core/trace", "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

Makefile

@@ -258,7 +258,7 @@ check: check-bench
 
 # 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/emscripten/Cargo.toml

@@ -13,6 +13,7 @@ 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" }
 

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/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/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`

lib/wasi/src/syscalls/mod.rs

@@ -21,7 +21,7 @@ use std::borrow::Borrow;
 use std::cell::Cell;
 use std::convert::{Infallible, TryInto};
 use std::io::{self, Read, Seek, Write};
-use wasmer_runtime_core::{debug, memory::Memory, vm::Ctx};
+use wasmer_runtime_core::{memory::Memory, vm::Ctx};
 
 #[cfg(any(target_os = "linux", target_os = "macos"))]
 pub use unix::*;

src/bin/wasmer.rs

@@ -8,6 +8,8 @@
     unreachable_patterns
 )]
 extern crate structopt;
+#[macro_use]
+extern crate log;
 
 use std::collections::HashMap;
 use std::env;
@@ -37,7 +39,6 @@ use wasmer_runtime_core::tiering::{run_tiering, InteractiveShellContext, ShellEx
 use wasmer_runtime_core::{
     self,
     backend::{Compiler, CompilerConfig, Features, MemoryBoundCheckMode},
-    debug,
     loader::{Instance as LoadedInstance, LocalLoader},
     Module,
 };
@@ -247,6 +248,11 @@ struct Run {
     #[structopt(long = "enable-experimental-io-devices", hidden = true)]
     enable_experimental_io_devices: bool,
 
+    /// Enable debug output
+    #[cfg(feature = "debug")]
+    #[structopt(long = "debug", short = "d")]
+    debug: bool,
+
     /// Application arguments
     #[structopt(name = "--", multiple = true)]
     args: Vec<String>,
@@ -978,6 +984,12 @@ fn get_backend(backend: Backend, path: &PathBuf) -> Backend {
 
 fn run(options: &mut Run) {
     options.backend = get_backend(options.backend, &options.path);
+    #[cfg(feature = "debug")]
+    {
+        if options.debug {
+            logging::set_up_logging().expect("failed to set up logging");
+        }
+    }
     match execute_wasm(options) {
         Ok(()) => {}
         Err(message) => {

src/lib.rs

@@ -10,11 +10,13 @@
 #![doc(html_favicon_url = "https://wasmer.io/static/icons/favicon.ico")]
 #![doc(html_logo_url = "https://avatars3.githubusercontent.com/u/44205449?s=200&v=4")]
 
-#[macro_use]
 extern crate wasmer_runtime_core;
-// extern crate wasmer_emscripten;
+#[macro_use]
+extern crate log;
 
 #[macro_use]
 pub mod update;
 pub mod utils;
 pub mod webassembly;
+#[cfg(feature = "debug")]
+pub mod logging;