From fdc441f4cba766c646906e2b378962e9535d898f Mon Sep 17 00:00:00 2001 From: Andreas Tolfsen Date: Thu, 8 Feb 2018 21:07:29 +0000 Subject: [PATCH] Bug 1436830 - Roll own log::Log implementation in geckodriver. r=rillian,jgraham This provides a custom implementaiton of log::Log for geckodriver, effectively making slog redundant in central. slog is, for our purposes, an unnecessarily complicated crate to depend on. With Rust 1.24 transitioning to stable soon, we need to prepare code and crates in central for this change. geckodriver only uses slog for the single purpose of changing the log level at runtime, and it would be less work to roll our own logger implementation than it would be to grok the slog API changes. MozReview-Commit-ID: 2wyS8e6s2mr --- testing/geckodriver/Cargo.lock | 101 ++----- testing/geckodriver/Cargo.toml | 6 +- testing/geckodriver/src/capabilities.rs | 32 +-- testing/geckodriver/src/logging.rs | 350 ++++++++++++++++-------- testing/geckodriver/src/main.rs | 21 +- testing/geckodriver/src/marionette.rs | 24 +- 6 files changed, 290 insertions(+), 244 deletions(-) diff --git a/testing/geckodriver/Cargo.lock b/testing/geckodriver/Cargo.lock index f4eed0ad3a2a..fcede98befd2 100644 --- a/testing/geckodriver/Cargo.lock +++ b/testing/geckodriver/Cargo.lock @@ -62,6 +62,11 @@ name = "cc" version = "1.0.3" source = "registry+https://github.com/rust-lang/crates.io-index" +[[package]] +name = "cfg-if" +version = "0.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" + [[package]] name = "chrono" version = "0.2.25" @@ -91,11 +96,6 @@ dependencies = [ "time 0.1.38 (registry+https://github.com/rust-lang/crates.io-index)", ] -[[package]] -name = "crossbeam" -version = "0.2.10" -source = "registry+https://github.com/rust-lang/crates.io-index" - [[package]] name = "flate2" version = "0.2.20" @@ -129,16 +129,12 @@ dependencies = [ "clap 2.29.0 (registry+https://github.com/rust-lang/crates.io-index)", "hyper 0.10.13 (registry+https://github.com/rust-lang/crates.io-index)", "lazy_static 0.1.16 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", + "log 0.4.1 (registry+https://github.com/rust-lang/crates.io-index)", "mozprofile 0.3.0", "mozrunner 0.5.0", "mozversion 0.1.2", "regex 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)", "rustc-serialize 0.3.24 (registry+https://github.com/rust-lang/crates.io-index)", - "slog 1.6.0 (registry+https://github.com/rust-lang/crates.io-index)", - "slog-atomic 0.4.3 (registry+https://github.com/rust-lang/crates.io-index)", - "slog-stdlog 1.1.0 (registry+https://github.com/rust-lang/crates.io-index)", - "slog-stream 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)", "uuid 0.1.18 (registry+https://github.com/rust-lang/crates.io-index)", "webdriver 0.33.0", "zip 0.1.19 (registry+https://github.com/rust-lang/crates.io-index)", @@ -177,16 +173,6 @@ dependencies = [ "unicode-normalization 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)", ] -[[package]] -name = "isatty" -version = "0.1.5" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "kernel32-sys 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)", - "libc 0.2.33 (registry+https://github.com/rust-lang/crates.io-index)", - "winapi 0.2.8 (registry+https://github.com/rust-lang/crates.io-index)", -] - [[package]] name = "kernel32-sys" version = "0.1.4" @@ -239,6 +225,14 @@ name = "log" version = "0.3.8" source = "registry+https://github.com/rust-lang/crates.io-index" +[[package]] +name = "log" +version = "0.4.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +dependencies = [ + "cfg-if 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)", +] + [[package]] name = "matches" version = "0.1.6" @@ -416,63 +410,6 @@ name = "semver-parser" version = "0.7.0" source = "registry+https://github.com/rust-lang/crates.io-index" -[[package]] -name = "slog" -version = "1.6.0" -source = "registry+https://github.com/rust-lang/crates.io-index" - -[[package]] -name = "slog-atomic" -version = "0.4.3" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "crossbeam 0.2.10 (registry+https://github.com/rust-lang/crates.io-index)", - "slog 1.6.0 (registry+https://github.com/rust-lang/crates.io-index)", -] - -[[package]] -name = "slog-extra" -version = "0.1.2" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "slog 1.6.0 (registry+https://github.com/rust-lang/crates.io-index)", - "thread_local 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)", -] - -[[package]] -name = "slog-stdlog" -version = "1.1.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "crossbeam 0.2.10 (registry+https://github.com/rust-lang/crates.io-index)", - "lazy_static 0.2.11 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", - "slog 1.6.0 (registry+https://github.com/rust-lang/crates.io-index)", - "slog-term 1.5.0 (registry+https://github.com/rust-lang/crates.io-index)", -] - -[[package]] -name = "slog-stream" -version = "1.2.1" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "slog 1.6.0 (registry+https://github.com/rust-lang/crates.io-index)", - "slog-extra 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)", - "thread_local 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)", -] - -[[package]] -name = "slog-term" -version = "1.5.0" -source = "registry+https://github.com/rust-lang/crates.io-index" -dependencies = [ - "chrono 0.2.25 (registry+https://github.com/rust-lang/crates.io-index)", - "isatty 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)", - "slog 1.6.0 (registry+https://github.com/rust-lang/crates.io-index)", - "slog-stream 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)", - "thread_local 0.3.4 (registry+https://github.com/rust-lang/crates.io-index)", -] - [[package]] name = "strsim" version = "0.6.0" @@ -660,17 +597,16 @@ dependencies = [ "checksum bzip2 0.3.2 (registry+https://github.com/rust-lang/crates.io-index)" = "c3eafc42c44e0d827de6b1c131175098fe7fb53b8ce8a47e65cb3ea94688be24" "checksum bzip2-sys 0.1.6 (registry+https://github.com/rust-lang/crates.io-index)" = "2c5162604199bbb17690ede847eaa6120a3f33d5ab4dcc8e7c25b16d849ae79b" "checksum cc 1.0.3 (registry+https://github.com/rust-lang/crates.io-index)" = "a9b13a57efd6b30ecd6598ebdb302cca617930b5470647570468a65d12ef9719" +"checksum cfg-if 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "d4c819a1287eb618df47cc647173c5c4c66ba19d888a6e50d605672aed3140de" "checksum chrono 0.2.25 (registry+https://github.com/rust-lang/crates.io-index)" = "9213f7cd7c27e95c2b57c49f0e69b1ea65b27138da84a170133fd21b07659c00" "checksum clap 2.29.0 (registry+https://github.com/rust-lang/crates.io-index)" = "110d43e343eb29f4f51c1db31beb879d546db27998577e5715270a54bcf41d3f" "checksum cookie 0.10.1 (registry+https://github.com/rust-lang/crates.io-index)" = "746858cae4eae40fff37e1998320068df317bc247dc91a67c6cfa053afdc2abb" -"checksum crossbeam 0.2.10 (registry+https://github.com/rust-lang/crates.io-index)" = "0c5ea215664ca264da8a9d9c3be80d2eaf30923c259d03e870388eb927508f97" "checksum flate2 0.2.20 (registry+https://github.com/rust-lang/crates.io-index)" = "e6234dd4468ae5d1e2dbb06fe2b058696fdc50a339c68a393aefbf00bc81e423" "checksum fuchsia-zircon 0.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "f6c0581a4e363262e52b87f59ee2afe3415361c6ec35e665924eb08afe8ff159" "checksum fuchsia-zircon-sys 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "43f3795b4bae048dc6123a6b972cadde2e676f9ded08aef6bb77f5f157684a82" "checksum httparse 1.2.3 (registry+https://github.com/rust-lang/crates.io-index)" = "af2f2dd97457e8fb1ae7c5a420db346af389926e36f43768b96f101546b04a07" "checksum hyper 0.10.13 (registry+https://github.com/rust-lang/crates.io-index)" = "368cb56b2740ebf4230520e2b90ebb0461e69034d85d1945febd9b3971426db2" "checksum idna 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)" = "014b298351066f1512874135335d62a789ffe78a9974f94b43ed5621951eaf7d" -"checksum isatty 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)" = "00c9301a947a2eaee7ce2556b80285dcc89558d07088962e6e8b9c25730f9dc6" "checksum kernel32-sys 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)" = "e014dab1082fd9d80ea1fa6fcb261b47ed3eb511612a14198bb507701add083e" "checksum kernel32-sys 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)" = "7507624b29483431c0ba2d82aece8ca6cdba9382bff4ddd0f7490560c056098d" "checksum ktmw32-sys 0.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "7f9313a869ff779ae08dd990b75a92dc06aa16d771f41305f7286649cd39a0ee" @@ -679,6 +615,7 @@ dependencies = [ "checksum lazy_static 0.2.11 (registry+https://github.com/rust-lang/crates.io-index)" = "76f033c7ad61445c5b347c7382dd1237847eb1bce590fe50365dcb33d546be73" "checksum libc 0.2.33 (registry+https://github.com/rust-lang/crates.io-index)" = "5ba3df4dcb460b9dfbd070d41c94c19209620c191b0340b929ce748a2bcd42d2" "checksum log 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)" = "880f77541efa6e5cc74e76910c9884d9859683118839d6a1dc3b11e63512565b" +"checksum log 0.4.1 (registry+https://github.com/rust-lang/crates.io-index)" = "89f010e843f2b1a31dbd316b3b8d443758bc634bed37aabade59c686d644e0a2" "checksum matches 0.1.6 (registry+https://github.com/rust-lang/crates.io-index)" = "100aabe6b8ff4e4a7e32c1c13523379802df0772b82466207ac25b013f193376" "checksum memchr 1.0.2 (registry+https://github.com/rust-lang/crates.io-index)" = "148fab2e51b4f1cfc66da2a7c32981d1d3c083a803978268bb11fe4b86925e7a" "checksum mime 0.2.6 (registry+https://github.com/rust-lang/crates.io-index)" = "ba626b8a6de5da682e1caa06bdb42a335aee5a84db8e5046a3e8ab17ba0a3ae0" @@ -700,12 +637,6 @@ dependencies = [ "checksum safemem 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)" = "e27a8b19b835f7aea908818e871f5cc3a5a186550c30773be987e155e8163d8f" "checksum semver 0.6.0 (registry+https://github.com/rust-lang/crates.io-index)" = "7a3186ec9e65071a2095434b1f5bb24838d4e8e130f584c790f6033c79943537" "checksum semver-parser 0.7.0 (registry+https://github.com/rust-lang/crates.io-index)" = "388a1df253eca08550bef6c72392cfe7c30914bf41df5269b68cbd6ff8f570a3" -"checksum slog 1.6.0 (registry+https://github.com/rust-lang/crates.io-index)" = "5b965551440d867da261b10d50871ae608537c56fbeb872a296b12add733acf1" -"checksum slog-atomic 0.4.3 (registry+https://github.com/rust-lang/crates.io-index)" = "d6f5a4e4908d6818fe553b6126ba5377801556ab885c65ebf960b722a6778864" -"checksum slog-extra 0.1.2 (registry+https://github.com/rust-lang/crates.io-index)" = "511581f4dd1dc90e4eca99b60be8a692d9c975e8757558aa774f16007d27492a" -"checksum slog-stdlog 1.1.0 (registry+https://github.com/rust-lang/crates.io-index)" = "56cc08f40c45e0ab41dcfde0a19a22c5b7176d3827fc7d078450ebfdc080a37c" -"checksum slog-stream 1.2.1 (registry+https://github.com/rust-lang/crates.io-index)" = "3fac4af71007ddb7338f771e059a46051f18d1454d8ac556f234a0573e719daa" -"checksum slog-term 1.5.0 (registry+https://github.com/rust-lang/crates.io-index)" = "cb53c0bae0745898fd5a7b75b1c389507333470ac4c645ae431890c0f828b6ca" "checksum strsim 0.6.0 (registry+https://github.com/rust-lang/crates.io-index)" = "b4d15c810519a91cf877e7e36e63fe068815c678181439f2f29e2562147c3694" "checksum tempdir 0.3.5 (registry+https://github.com/rust-lang/crates.io-index)" = "87974a6f5c1dfb344d733055601650059a3363de2a6104819293baff662132d6" "checksum term_size 0.3.0 (registry+https://github.com/rust-lang/crates.io-index)" = "e2b6b55df3198cc93372e85dd2ed817f0e38ce8cc0f22eb32391bfad9c4bf209" diff --git a/testing/geckodriver/Cargo.toml b/testing/geckodriver/Cargo.toml index c3e74d733f14..4edfd6da57b5 100644 --- a/testing/geckodriver/Cargo.toml +++ b/testing/geckodriver/Cargo.toml @@ -14,16 +14,12 @@ chrono = "^0.2" clap = { version = "^2.19", default-features = false, features = ["suggestions", "wrap_help"] } hyper = "0.10" lazy_static = "0.1" -log = "0.3" +log = { version = "0.4", features = ["std"] } mozprofile = { path = "../mozbase/rust/mozprofile" } mozrunner = { path = "../mozbase/rust/mozrunner" } mozversion = { path = "../mozbase/rust/mozversion" } regex = "0.2" rustc-serialize = "0.3" -slog = "1" -slog-atomic = "0.4" -slog-stdlog = "1" -slog-stream = "1" uuid = "0.1.18" webdriver = { path = "../webdriver" } zip = "0.1" diff --git a/testing/geckodriver/src/capabilities.rs b/testing/geckodriver/src/capabilities.rs index 9a925dea60df..c5adfcecaf9f 100644 --- a/testing/geckodriver/src/capabilities.rs +++ b/testing/geckodriver/src/capabilities.rs @@ -1,4 +1,4 @@ -use logging::LogLevel; +use logging::Level; use marionette::LogOptions; use mozprofile::preferences::Pref; use mozprofile::profile::Profile; @@ -200,11 +200,10 @@ impl<'a> BrowserCapabilities for FirefoxCapabilities<'a> { let level = try_opt!(log_value.as_string(), ErrorStatus::InvalidArgument, "log level is not a string"); - if LogLevel::from_str(level).is_err() { + if Level::from_str(level).is_err() { return Err(WebDriverError::new( ErrorStatus::InvalidArgument, - format!("{} is not a valid log level", - level))) + format!("Not a valid log level: {}", level))) } } x => return Err(WebDriverError::new( @@ -342,25 +341,26 @@ impl FirefoxOptions { fn load_log(options: &Capabilities) -> WebDriverResult { if let Some(json) = options.get("log") { - let log = try!(json.as_object() - .ok_or(WebDriverError::new(ErrorStatus::InvalidArgument, - "Log section is not an object"))); + let log = json.as_object().ok_or(WebDriverError::new( + ErrorStatus::InvalidArgument, + "Log section is not an object", + ))?; let level = match log.get("level") { Some(json) => { - let s = try!(json.as_string() - .ok_or(WebDriverError::new(ErrorStatus::InvalidArgument, - "Log level is not a string"))); - Some(try!(LogLevel::from_str(s) - .ok() - .ok_or(WebDriverError::new(ErrorStatus::InvalidArgument, - "Log level is unknown")))) + let s = json.as_string().ok_or(WebDriverError::new( + ErrorStatus::InvalidArgument, + "Log level is not a string", + ))?; + Some(Level::from_str(s).ok().ok_or(WebDriverError::new( + ErrorStatus::InvalidArgument, + "Log level is unknown", + ))?) } None => None, }; - Ok(LogOptions { level: level }) - + Ok(LogOptions { level }) } else { Ok(Default::default()) } diff --git a/testing/geckodriver/src/logging.rs b/testing/geckodriver/src/logging.rs index a1c99a7b0930..4b3ad8c57953 100644 --- a/testing/geckodriver/src/logging.rs +++ b/testing/geckodriver/src/logging.rs @@ -1,158 +1,290 @@ +//! Gecko-esque logger implementation for the [`log`] crate. +//! +//! The [`log`] crate provides a single logging API that abstracts over the +//! actual logging implementation. This module uses the logging API +//! to provide a log implementation that shares many aesthetical traits with +//! [Log.jsm] from Gecko. +//! +//! Using the [`error!`], [`warn!`], [`info!`], [`debug!`], and +//! [`trace!`] macros from `log` will output a timestamp field, followed by the +//! log level, and then the message. The fields are separated by a tab +//! character, making the output suitable for further text processing with +//! `awk(1)`. +//! +//! This module shares the same API as `log`, except it provides additional +//! entry functions [`init`] and [`init_with_level`] and additional log levels +//! `Level::Fatal` and `Level::Config`. Converting these into the +//! [`log::Level`] is lossy so that `Level::Fatal` becomes `log::Level::Error` +//! and `Level::Config` becomes `log::Level::Debug`. +//! +//! [`log`]: https://docs.rs/log/newest/log/ +//! [Log.jsm]: https://developer.mozilla.org/en/docs/Mozilla/JavaScript_code_modules/Log.jsm +//! [`error!`]: https://docs.rs/log/newest/log/macro.error.html +//! [`warn!`]: https://docs.rs/log/newest/log/macro.warn.html +//! [`info!`]: https://docs.rs/log/newest/log/macro.info.html +//! [`debug!`]: https://docs.rs/log/newest/log/macro.debug.html +//! [`trace!`]: https://docs.rs/log/newest/log/macro.trace.html +//! [`init`]: fn.init.html +//! [`init_with_level`]: fn.init_with_level.html + +use chrono; +use log; use std::fmt; use std::io; -use std::str::FromStr; -use std::sync::atomic::AtomicBool; -use std::sync::atomic::Ordering::SeqCst; +use std::io::Write; +use std::str; +use std::sync::atomic::{ATOMIC_USIZE_INIT, AtomicUsize, Ordering}; -use chrono::{DateTime, Local}; -use slog; -use slog::DrainExt; -use slog_atomic::{AtomicSwitch, AtomicSwitchCtrl}; -use slog_stream::{stream, Format, Streamer}; -use slog::Level as SlogLevel; -use slog::{LevelFilter, Logger}; -use slog::{OwnedKeyValueList, Record}; -use slog_stdlog; +static MAX_LOG_LEVEL: AtomicUsize = ATOMIC_USIZE_INIT; -lazy_static! { - static ref ATOMIC_DRAIN: AtomicSwitchCtrl = AtomicSwitch::new( - slog::Discard.map_err(|_| io::Error::new(io::ErrorKind::Other, "should not happen")) - ).ctrl(); - static ref FIRST_RUN: AtomicBool = AtomicBool::new(true); +/// Logger levels from [Log.jsm]. +/// +/// [Log.jsm]: +/// https://developer.mozilla.org/en/docs/Mozilla/JavaScript_code_modules/Log. +/// jsm +#[repr(usize)] +#[derive(Clone, Copy, Eq, Debug, Hash, PartialEq)] +pub enum Level { + Fatal = 70, + Error = 60, + Warn = 50, + Info = 40, + Config = 30, + Debug = 20, + Trace = 10, } -static DEFAULT_LEVEL: &'static LogLevel = &LogLevel::Info; - -/// Logger levels from [Log.jsm] -/// (https://developer.mozilla.org/en/docs/Mozilla/JavaScript_code_modules/Log.jsm). -#[derive(Debug, Clone)] -pub enum LogLevel { - Fatal, - Error, - Warn, - Info, - Config, - Debug, - Trace, +impl From for Level { + fn from(n: usize) -> Level { + use self::Level::*; + match n { + 70 => Fatal, + 60 => Error, + 50 => Warn, + 40 => Info, + 30 => Config, + 20 => Debug, + 10 => Trace, + _ => Info, + } + } } -impl fmt::Display for LogLevel { +impl fmt::Display for Level { fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result { + use self::Level::*; let s = match *self { - LogLevel::Fatal => "FATAL", - LogLevel::Error => "ERROR", - LogLevel::Warn => "WARN", - LogLevel::Info => "INFO", - LogLevel::Config => "CONFIG", - LogLevel::Debug => "DEBUG", - LogLevel::Trace => "TRACE", + Fatal => "FATAL", + Error => "ERROR", + Warn => "WARN", + Info => "INFO", + Config => "CONFIG", + Debug => "DEBUG", + Trace => "TRACE", }; write!(f, "{}", s) } } -impl FromStr for LogLevel { +impl str::FromStr for Level { type Err = (); - fn from_str(s: &str) -> Result { - match s { - "fatal" => Ok(LogLevel::Fatal), - "error" => Ok(LogLevel::Error), - "warn" => Ok(LogLevel::Warn), - "info" => Ok(LogLevel::Info), - "config" => Ok(LogLevel::Config), - "debug" => Ok(LogLevel::Debug), - "trace" => Ok(LogLevel::Trace), + fn from_str(s: &str) -> Result { + use self::Level::*; + match s.to_lowercase().as_ref() { + "fatal" => Ok(Fatal), + "error" => Ok(Error), + "warn" => Ok(Warn), + "info" => Ok(Info), + "config" => Ok(Config), + "debug" => Ok(Debug), + "trace" => Ok(Trace), _ => Err(()), } } } -trait ToSlogLevel { - fn to_slog(&self) -> SlogLevel; -} - -impl ToSlogLevel for LogLevel { - fn to_slog(&self) -> SlogLevel { - match *self { - LogLevel::Fatal => SlogLevel::Critical, - LogLevel::Error => SlogLevel::Error, - LogLevel::Warn => SlogLevel::Warning, - LogLevel::Info => SlogLevel::Info, - LogLevel::Config | LogLevel::Debug => SlogLevel::Debug, - LogLevel::Trace => SlogLevel::Trace, +impl Into for Level { + fn into(self) -> log::Level { + use self::Level::*; + match self { + Fatal | Error => log::Level::Error, + Warn => log::Level::Warn, + Info => log::Level::Info, + Config | Debug => log::Level::Debug, + Trace => log::Level::Trace, } } } -trait ToGeckoLevel { - fn to_gecko(&self) -> LogLevel; -} - -impl ToGeckoLevel for SlogLevel { - fn to_gecko(&self) -> LogLevel { - match *self { - SlogLevel::Critical => LogLevel::Fatal, - SlogLevel::Error => LogLevel::Error, - SlogLevel::Warning => LogLevel::Warn, - SlogLevel::Info => LogLevel::Info, - SlogLevel::Debug => LogLevel::Debug, - SlogLevel::Trace => LogLevel::Trace, +impl From for Level { + fn from(log_level: log::Level) -> Level { + use log::Level::*; + match log_level { + Error => Level::Error, + Warn => Level::Warn, + Info => Level::Info, + Debug => Level::Debug, + Trace => Level::Trace, } } } -/// Initialise logger if it has not been already. The provided `level` -/// filters out log records below this granularity. -pub fn init(level: &Option) { - let effective_level = level.as_ref().unwrap_or(DEFAULT_LEVEL); +struct Logger; - let drain = filtered_gecko_log(&effective_level); - ATOMIC_DRAIN.set(drain); - - let first_run = FIRST_RUN.load(SeqCst); - FIRST_RUN.store(false, SeqCst); - if first_run { - let log = Logger::root(ATOMIC_DRAIN.drain().fuse(), o!()); - slog_stdlog::set_logger(log.clone()).unwrap(); +impl log::Log for Logger { + fn enabled(&self, meta: &log::Metadata) -> bool { + meta.level() <= log::max_level() } -} -fn filtered_gecko_log(level: &LogLevel) -> LevelFilter> { - let io = stream(io::stderr(), GeckoFormat {}); - slog::level_filter(level.to_slog(), io) -} - -struct GeckoFormat; - -impl Format for GeckoFormat { - fn format(&self, io: &mut io::Write, record: &Record, _: &OwnedKeyValueList) -> io::Result<()> { - // TODO(ato): Quite sure this is the wrong way to filter records with slog, - // but I do not comprehend how slog works. - let module = record.module(); - if module.starts_with("geckodriver") || module.starts_with("webdriver") || - module.starts_with("mozrunner") { - let ts = format_ts(Local::now()); - let level = record.level().to_gecko(); - let _ = try!(write!(io, "{}\t{}\t{}\t{}\n", ts, module, level, record.msg())); + fn log(&self, record: &log::Record) { + if self.enabled(record.metadata()) { + let ts = format_ts(chrono::Local::now()); + println!( + "{}\t{}\t{}\t{}", + ts, + record.target(), + record.level(), + record.args() + ); } - Ok(()) } + + fn flush(&self) { + io::stdout().flush().unwrap(); + } +} + +/// Initialises the logging subsystem with the default log level. +pub fn init() -> Result<(), log::SetLoggerError> { + init_with_level(Level::Info) +} + +/// Initialises the logging subsystem. +pub fn init_with_level(level: Level) -> Result<(), log::SetLoggerError> { + let logger = Logger {}; + set_max_level(level); + log::set_boxed_logger(Box::new(logger))?; + Ok(()) +} + +/// Returns the current maximum log level. +pub fn max_level() -> Level { + MAX_LOG_LEVEL.load(Ordering::Relaxed).into() +} + +/// Sets the global maximum log level. +pub fn set_max_level(level: Level) { + MAX_LOG_LEVEL.store(level as usize, Ordering::SeqCst); + + let slevel: log::Level = level.into(); + log::set_max_level(slevel.to_level_filter()) } /// Produces a 13-digit Unix Epoch timestamp similar to Gecko. -fn format_ts(ts: DateTime) -> String { +fn format_ts(ts: chrono::DateTime) -> String { format!("{}{:03}", ts.timestamp(), ts.timestamp_subsec_millis()) } #[cfg(test)] mod tests { - use chrono::Local; - use super::format_ts; + use super::{Level, format_ts, init, init_with_level, max_level, set_max_level}; + use chrono; + use log; + use std::str::FromStr; + + #[test] + fn test_level_repr() { + assert_eq!(Level::Fatal as usize, 70); + assert_eq!(Level::Error as usize, 60); + assert_eq!(Level::Warn as usize, 50); + assert_eq!(Level::Info as usize, 40); + assert_eq!(Level::Config as usize, 30); + assert_eq!(Level::Debug as usize, 20); + assert_eq!(Level::Trace as usize, 10); + } + + #[test] + fn test_level_eq() { + assert_eq!(Level::Fatal, Level::Fatal); + assert_eq!(Level::Error, Level::Error); + assert_eq!(Level::Warn, Level::Warn); + assert_eq!(Level::Info, Level::Info); + assert_eq!(Level::Config, Level::Config); + assert_eq!(Level::Debug, Level::Debug); + assert_eq!(Level::Trace, Level::Trace); + } + + #[test] + fn test_level_from_log() { + assert_eq!(Level::from(log::Level::Error), Level::Error); + assert_eq!(Level::from(log::Level::Warn), Level::Warn); + assert_eq!(Level::from(log::Level::Info), Level::Info); + assert_eq!(Level::from(log::Level::Debug), Level::Debug); + assert_eq!(Level::from(log::Level::Trace), Level::Trace); + } + + #[test] + fn test_level_into_log() { + assert_eq!(Into::::into(Level::Fatal), log::Level::Error); + assert_eq!(Into::::into(Level::Error), log::Level::Error); + assert_eq!(Into::::into(Level::Warn), log::Level::Warn); + assert_eq!(Into::::into(Level::Info), log::Level::Info); + assert_eq!(Into::::into(Level::Config), log::Level::Debug); + assert_eq!(Into::::into(Level::Debug), log::Level::Debug); + assert_eq!(Into::::into(Level::Trace), log::Level::Trace); + } + + #[test] + fn test_level_from_str() { + assert_eq!(Level::from_str("fatal"), Ok(Level::Fatal)); + assert_eq!(Level::from_str("error"), Ok(Level::Error)); + assert_eq!(Level::from_str("warn"), Ok(Level::Warn)); + assert_eq!(Level::from_str("info"), Ok(Level::Info)); + assert_eq!(Level::from_str("config"), Ok(Level::Config)); + assert_eq!(Level::from_str("debug"), Ok(Level::Debug)); + assert_eq!(Level::from_str("trace"), Ok(Level::Trace)); + + assert_eq!(Level::from_str("INFO"), Ok(Level::Info)); + + assert!(Level::from_str("foo").is_err()); + } + + #[test] + fn test_level_to_str() { + assert_eq!(Level::Fatal.to_string(), "FATAL"); + assert_eq!(Level::Error.to_string(), "ERROR"); + assert_eq!(Level::Warn.to_string(), "WARN"); + assert_eq!(Level::Info.to_string(), "INFO"); + assert_eq!(Level::Config.to_string(), "CONFIG"); + assert_eq!(Level::Debug.to_string(), "DEBUG"); + assert_eq!(Level::Trace.to_string(), "TRACE"); + } + + #[test] + fn test_max_level() { + set_max_level(Level::Info); + assert_eq!(max_level(), Level::Info); + } + + #[test] + fn test_set_max_level() { + set_max_level(Level::Error); + assert_eq!(max_level(), Level::Error); + set_max_level(Level::Fatal); + assert_eq!(max_level(), Level::Fatal); + } + + #[test] + fn test_init_with_level() { + init_with_level(Level::Debug).unwrap(); + assert_eq!(max_level(), Level::Debug); + assert!(init_with_level(Level::Warn).is_err()); + } #[test] fn test_format_ts() { - let ts = Local::now(); + let ts = chrono::Local::now(); let s = format_ts(ts); assert_eq!(s.len(), 13); } diff --git a/testing/geckodriver/src/main.rs b/testing/geckodriver/src/main.rs index 3c645fb356df..18df569cf761 100644 --- a/testing/geckodriver/src/main.rs +++ b/testing/geckodriver/src/main.rs @@ -9,11 +9,6 @@ extern crate mozrunner; extern crate mozversion; extern crate regex; extern crate rustc_serialize; -#[macro_use] -extern crate slog; -extern crate slog_atomic; -extern crate slog_stdlog; -extern crate slog_stream; extern crate uuid; extern crate zip; extern crate webdriver; @@ -43,7 +38,6 @@ mod prefs; mod marionette; mod capabilities; -use logging::LogLevel; use marionette::{MarionetteHandler, MarionetteSettings, extension_routes}; include!(concat!(env!("OUT_DIR"), "/build-info.rs")); @@ -180,22 +174,25 @@ fn run() -> ProgramResult { }; let log_level = if matches.is_present("log_level") { - LogLevel::from_str(matches.value_of("log_level").unwrap()).ok() + logging::Level::from_str(matches.value_of("log_level").unwrap()).ok() } else { match matches.occurrences_of("verbosity") { - 0 => Some(LogLevel::Info), - 1 => Some(LogLevel::Debug), - _ => Some(LogLevel::Trace), + 0 => Some(logging::Level::Info), + 1 => Some(logging::Level::Debug), + _ => Some(logging::Level::Trace), } }; - logging::init(&log_level); + if let Some(ref level) = log_level { + logging::init_with_level(level.clone()).unwrap(); + } else { + logging::init().unwrap(); + } info!("geckodriver {}", BuildInfo); let settings = MarionetteSettings { port: marionette_port, binary, - log_level, connect_existing: matches.is_present("connect_existing"), jsdebugger: matches.is_present("jsdebugger"), }; diff --git a/testing/geckodriver/src/marionette.rs b/testing/geckodriver/src/marionette.rs index 7d9c2b33d719..13cd45d51d55 100644 --- a/testing/geckodriver/src/marionette.rs +++ b/testing/geckodriver/src/marionette.rs @@ -1,6 +1,4 @@ use hyper::method::Method; -use logging; -use logging::LogLevel; use mozprofile::preferences::Pref; use mozprofile::profile::Profile; use mozrunner::runner::{FirefoxRunner, FirefoxProcess, Runner, RunnerProcess}; @@ -53,6 +51,7 @@ use webdriver::server::{WebDriverHandler, Session}; use webdriver::httpapi::{WebDriverExtensionRoute}; use capabilities::{FirefoxCapabilities, FirefoxOptions}; +use logging; use prefs; const DEFAULT_HOST: &'static str = "localhost"; @@ -373,7 +372,7 @@ impl ToMarionette for AddonUninstallParameters { #[derive(Default)] pub struct LogOptions { - pub level: Option, + pub level: Option, } #[derive(Default)] @@ -385,27 +384,20 @@ pub struct MarionetteSettings { /// Brings up the Browser Toolbox when starting Firefox, /// letting you debug internals. pub jsdebugger: bool, - - /// Optionally increase Marionette's verbosity by providing a log - /// level. The Gecko default is LogLevel::Info for optimised - /// builds and LogLevel::Debug for debug builds. - pub log_level: Option, } pub struct MarionetteHandler { connection: Mutex>, settings: MarionetteSettings, browser: Option, - current_log_level: Option, } impl MarionetteHandler { pub fn new(settings: MarionetteSettings) -> MarionetteHandler { MarionetteHandler { connection: Mutex::new(None), - settings: settings, + settings, browser: None, - current_log_level: None, } } @@ -427,8 +419,9 @@ impl MarionetteHandler { (options, capabilities) }; - self.current_log_level = options.log.level.clone().or(self.settings.log_level.clone()); - logging::init(&self.current_log_level); + if let Some(l) = options.log.level { + logging::set_max_level(l); + } let port = self.settings.port.unwrap_or(try!(get_free_port())); if !self.settings.connect_existing { @@ -463,7 +456,6 @@ impl MarionetteHandler { format!("Failed to set preferences: {}", e)) })?; - let mut runner = FirefoxRunner::new(&binary, profile); // https://developer.mozilla.org/docs/Environment_variables_affecting_crash_reporting @@ -515,9 +507,7 @@ impl MarionetteHandler { prefs.insert("marionette.debugging.clicktostart", Pref::new(true)); } - if let Some(ref level) = self.current_log_level { - prefs.insert("marionette.log.level", Pref::new(level.to_string())); - }; + prefs.insert("marionette.log.level", Pref::new(logging::max_level().to_string())); prefs.insert("marionette.port", Pref::new(port as i64)); prefs.write().map_err(|_| WebDriverError::new(ErrorStatus::UnknownError,