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

Cargo.lock

@@ -138,6 +138,17 @@ version = "0.1.10"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "4785bdd1c96b2a846b2bd7cc02e86b6b3dbf14e7e53446c4f54c92a361040822"
 
+[[package]]
+name = "chrono"
+version = "0.4.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "31850b4a4d6bae316f7a09e691c944c28299298837edc0a03f755618c23cbc01"
+dependencies = [
+ "num-integer",
+ "num-traits",
+ "time",
+]
+
 [[package]]
 name = "clap"
 version = "2.33.0"
@@ -171,6 +182,17 @@ dependencies = [
  "cc",
 ]
 
+[[package]]
+name = "colored"
+version = "1.9.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "8815e2ab78f3a59928fc32e141fbeece88320a240e43f47b2fd64ea3a88a5b3d"
+dependencies = [
+ "atty",
+ "lazy_static",
+ "winapi",
+]
+
 [[package]]
 name = "constant_time_eq"
 version = "0.1.4"
@@ -438,6 +460,17 @@ dependencies = [
  "libc",
 ]
 
+[[package]]
+name = "fern"
+version = "0.5.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e69ab0d5aca163e388c3a49d284fed6c3d0810700e77c5ae2756a50ec1a4daaa"
+dependencies = [
+ "chrono",
+ "colored",
+ "log",
+]
+
 [[package]]
 name = "fuchsia-cprng"
 version = "0.1.1"
@@ -558,7 +591,7 @@ dependencies = [
  "libc",
  "llvm-sys",
  "once_cell",
- "parking_lot",
+ "parking_lot 0.10.0",
  "regex",
 ]
 
@@ -827,6 +860,17 @@ dependencies = [
  "md5",
 ]
 
+[[package]]
+name = "parking_lot"
+version = "0.9.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f842b1982eb6c2fe34036a4fbfb06dd185a3f5c8edfaacdf7d1ea10b07de6252"
+dependencies = [
+ "lock_api",
+ "parking_lot_core 0.6.2",
+ "rustc_version",
+]
+
 [[package]]
 name = "parking_lot"
 version = "0.10.0"
@@ -834,7 +878,22 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "92e98c49ab0b7ce5b222f2cc9193fc4efe11c6d0bd4f648e374684a6857b1cfc"
 dependencies = [
  "lock_api",
- "parking_lot_core",
+ "parking_lot_core 0.7.0",
+]
+
+[[package]]
+name = "parking_lot_core"
+version = "0.6.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b876b1b9e7ac6e1a74a6da34d25c42e17e8862aa409cbbbdcfc8d86c6f3bc62b"
+dependencies = [
+ "cfg-if",
+ "cloudabi",
+ "libc",
+ "redox_syscall",
+ "rustc_version",
+ "smallvec 0.6.13",
+ "winapi",
 ]
 
 [[package]]
@@ -1618,7 +1677,9 @@ version = "0.12.0"
 dependencies = [
  "byteorder",
  "errno",
+ "fern",
  "glob 0.3.0",
+ "log",
  "rustc_version",
  "serde",
  "structopt",
@@ -1679,6 +1740,7 @@ dependencies = [
  "getrandom",
  "lazy_static",
  "libc",
+ "log",
  "time",
  "wasmer-runtime-core",
 ]
@@ -1800,7 +1862,7 @@ dependencies = [
  "libc",
  "nix",
  "page_size",
- "parking_lot",
+ "parking_lot 0.9.0",
  "rustc_version",
  "serde",
  "serde-bench",

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"]
+debug = ["wasmer-runtime-core/debug", "fern", "log/max_level_debug", "log/release_max_level_debug"]
-trace = ["wasmer-runtime-core/trace"]
+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;
+#[cfg(feature = "debug")]
+pub mod logging;
 pub mod utils;
 pub mod webassembly;

src/logging.rs

@@ -0,0 +1,55 @@
+use crate::utils::wasmer_should_print_color;
+use fern::colors::{Color, ColoredLevelConfig};
+use std::time;
+
+/// Subroutine to instantiate the loggers
+pub fn set_up_logging() -> Result<(), String> {
+    let colors_line = ColoredLevelConfig::new()
+        .error(Color::Red)
+        .warn(Color::Yellow)
+        .trace(Color::BrightBlack);
+    let should_color = wasmer_should_print_color();
+
+    let colors_level = colors_line.info(Color::Green);
+    let dispatch = fern::Dispatch::new()
+        .level(log::LevelFilter::Debug)
+        .chain({
+            let base = if should_color {
+                fern::Dispatch::new().format(move |out, message, record| {
+                    let time = time::SystemTime::now().duration_since(time::UNIX_EPOCH).expect("Can't get time");
+                    out.finish(format_args!(
+                        "{color_line}[{seconds}.{millis} {level} {target}{color_line}]{ansi_close} {message}",
+                        color_line = format_args!(
+                            "\x1B[{}m",
+                            colors_line.get_color(&record.level()).to_fg_str()
+                        ),
+                        seconds = time.as_secs(),
+                        millis = time.subsec_millis(),
+                        level = colors_level.color(record.level()),
+                        target = record.target(),
+                        ansi_close = "\x1B[0m",
+                        message = message,
+                    ));
+                })
+            } else {
+                // default formatter without color
+                fern::Dispatch::new().format(move |out, message, record| {
+                    let time = time::SystemTime::now().duration_since(time::UNIX_EPOCH).expect("Can't get time");
+                    out.finish(format_args!(
+                        "[{seconds}.{millis} {level} {target}] {message}",
+                        seconds = time.as_secs(),
+                        millis = time.subsec_millis(),
+                        level = record.level(),
+                        target = record.target(),
+                        message = message,
+                    ));
+                })
+            };
+
+            base.chain(std::io::stdout())
+        });
+
+    dispatch.apply().map_err(|e| format!("{}", e))?;
+
+    Ok(())
+}

src/utils.rs

@@ -119,3 +119,10 @@ pub fn parse_args(
             )
     }
 }
+
+/// Whether or not Wasmer should print with color
+pub fn wasmer_should_print_color() -> bool {
+    std::env::var("WASMER_DISABLE_COLOR")
+        .map(|_| false)
+        .unwrap_or(true)
+}