From 12f7416a85bbcc1e926730bdfd15bc4e18b2c886 Mon Sep 17 00:00:00 2001 From: Mark McCaskey Date: Tue, 14 Jan 2020 12:35:54 -0800 Subject: [PATCH] Update logging to use `log`, add command line flag to toggle it --- Cargo.lock | 68 ++++++++++++++++++++++- Cargo.toml | 7 ++- Makefile | 2 +- lib/emscripten/Cargo.toml | 1 + lib/emscripten/src/lib.rs | 2 + lib/runtime-core/src/macros.rs | 46 --------------- lib/wasi/src/lib.rs | 2 + lib/wasi/src/macros.rs | 4 +- lib/wasi/src/state/mod.rs | 2 +- lib/wasi/src/state/types.rs | 1 - lib/wasi/src/syscalls/legacy/snapshot0.rs | 2 +- lib/wasi/src/syscalls/mod.rs | 2 +- src/bin/wasmer.rs | 14 ++++- src/lib.rs | 6 +- src/logging.rs | 55 ++++++++++++++++++ src/utils.rs | 7 +++ 16 files changed, 160 insertions(+), 61 deletions(-) create mode 100644 src/logging.rs diff --git a/Cargo.lock b/Cargo.lock index 1282e76f35d..063b85e4105 100644 --- a/Cargo.lock +++ b/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", diff --git a/Cargo.toml b/Cargo.toml index 6dd5334291d..3c0e06e81c3 100644 --- a/Cargo.toml +++ b/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 diff --git a/Makefile b/Makefile index 272a473127d..01bcf1481bc 100644 --- a/Makefile +++ b/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: diff --git a/lib/emscripten/Cargo.toml b/lib/emscripten/Cargo.toml index 371f90fea81..d921ed42fb7 100644 --- a/lib/emscripten/Cargo.toml +++ b/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" } diff --git a/lib/emscripten/src/lib.rs b/lib/emscripten/src/lib.rs index 289835ff955..c4981b3050e 100644 --- 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/runtime-core/src/macros.rs b/lib/runtime-core/src/macros.rs index 2aa68aa2dbe..8251a4133c2 100644 --- 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/wasi/src/lib.rs b/lib/wasi/src/lib.rs index 4c54f5102a1..c1f0dd11460 100644 --- 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 index e0e144a626f..53986bef463 100644 --- 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 index babadbf17d9..403a577f8ff 100644 --- 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 index 5eb55c670f2..b98b1d9ed7d 100644 --- 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 index 67566a50c7d..38a1811146b 100644 --- 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` diff --git a/lib/wasi/src/syscalls/mod.rs b/lib/wasi/src/syscalls/mod.rs index ccd2a4ec064..5a243c5d56f 100644 --- a/lib/wasi/src/syscalls/mod.rs +++ b/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::*; diff --git a/src/bin/wasmer.rs b/src/bin/wasmer.rs index 339b0a1bbac..5a77e3336fd 100644 --- a/src/bin/wasmer.rs +++ b/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, @@ -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) => { diff --git a/src/lib.rs b/src/lib.rs index f4d0e03bb31..72a758a182c 100644 --- a/src/lib.rs +++ b/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; diff --git a/src/logging.rs b/src/logging.rs new file mode 100644 index 00000000000..e9f8dbb6a02 --- /dev/null +++ b/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(()) +} diff --git a/src/utils.rs b/src/utils.rs index 1feec86b28a..da498956b7f 100644 --- a/src/utils.rs +++ b/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) +}