/* This Source Code Form is subject to the terms of the Mozilla Public
* License, v. 2.0. If a copy of the MPL was not distributed with this
* file, You can obtain one at
http://mozilla.org/MPL/2.0/. */
//! 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.sys.mjs] 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.sys.mjs]:
https://searchfox.org/mozilla-central/source/toolkit/modules/Log.sys.mjs
//! [`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 icu_segmenter::GraphemeClusterSegmenter;
use std::fmt;
use std::io;
use std::io::Write;
use std::str;
use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering};
use mozprofile::preferences::Pref;
static LOG_TRUNCATE: AtomicBool = AtomicBool::new(true);
static MAX_LOG_LEVEL: AtomicUsize = AtomicUsize::new(0);
const MAX_STRING_LENGTH: usize = 250;
const LOGGED_TARGETS: &[&str] = &[
"geckodriver",
"mozdevice",
"mozprofile",
"mozrunner",
"mozversion",
"webdriver",
];
/// Logger levels from [Log.sys.mjs].
///
/// [Log.sys.mjs]:
https://searchfox.org/mozilla-central/source/toolkit/modules/Log.sys.mjs
#[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,
}
impl From<usize> 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 Level {
fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
use self::Level::*;
let s = match *self {
Fatal => "FATAL",
Error => "ERROR",
Warn => "WARN",
Info => "INFO",
Config => "CONFIG",
Debug => "DEBUG",
Trace => "TRACE",
};
write!(f, "{}", s)
}
}
impl str::FromStr for Level {
type Err = ();
fn from_str(s: &str) -> Result<Level, ()> {
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(()),
}
}
}
impl From<Level> for log::Level {
fn from(level: Level) -> log::Level {
use self::Level::*;
match level {
Fatal | Error => log::Level::Error,
Warn => log::Level::Warn,
Info => log::Level::Info,
Config | Debug => log::Level::Debug,
Trace => log::Level::Trace,
}
}
}
impl From<Level> for Pref {
fn from(level: Level) -> Pref {
use self::Level::*;
Pref::new(match level {
Fatal => "Fatal",
Error => "Error",
Warn => "Warn",
Info => "Info",
Config => "Config",
Debug => "Debug",
Trace => "Trace",
})
}
}
impl From<log::Level> 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,
}
}
}
struct Logger;
impl log::Log for Logger {
fn enabled(&self, meta: &log::Metadata) -> bool {
LOGGED_TARGETS.iter().any(|&x| meta.target().starts_with(x))
&& meta.level() <= log::max_level()
}
fn log(&self, record: &log::Record) {
if self.enabled(record.metadata()) {
if let Some((s1, s2)) = truncate_message(record.args()) {
println!(
"{}\t{}\t{}\t{} ... {}",
format_ts(chrono::Local::now()),
record.target(),
record.level(),
s1,
s2
);
} else {
println!(
"{}\t{}\t{}\t{}",
format_ts(chrono::Local::now()),
record.target(),
record.level(),
record.args()
)
}
}
}
fn flush(&self) {
io::stdout().flush().unwrap();
}
}
/// Initialises the logging subsystem with the default log level.
pub fn init(truncate: bool) -> Result<(), log::SetLoggerError> {
init_with_level(Level::Info, truncate)
}
/// Initialises the logging subsystem.
pub fn init_with_level(level: Level, truncate: bool) -> Result<(), log::SetLoggerError> {
let logger = Logger {};
set_max_level(level);
set_truncate(truncate);
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())
}
/// Sets the global maximum log level.
pub fn set_truncate(truncate: bool) {
LOG_TRUNCATE.store(truncate, Ordering::SeqCst);
}
/// Returns the truncation flag.
pub fn truncate() -> bool {
LOG_TRUNCATE.load(Ordering::Relaxed)
}
/// Produces a 13-digit Unix Epoch timestamp similar to Gecko.
fn format_ts(ts: chrono::DateTime<chrono::Local>) -> String {
format!("{}{:03}", ts.timestamp(), ts.timestamp_subsec_millis())
}
/// Truncate a log message if it's too long
fn truncate_message(args: &fmt::Arguments) -> Option<(String, String)> {
// Don't truncate the message if requested.
if !truncate() {
return None;
}
let message = format!("{}", args);
if message.is_empty() || message.len() < MAX_STRING_LENGTH {
return None;
}
let chars = GraphemeClusterSegmenter::new()
.segment_str(&message)
.collect::<Vec<_>>()
.windows(2)
.map(|i| &message[i[0]..i[1]])
.collect::<Vec<&str>>();
if chars.len() > MAX_STRING_LENGTH {
let middle: usize = MAX_STRING_LENGTH / 2;
let s1 = chars[0..middle].concat();
let s2 = chars[chars.len() - middle..].concat();
Some((s1, s2))
} else {
None
}
}
#[cfg(test)]
mod tests {
use super::*;
use std::str::FromStr;
use std::sync::Mutex;
use mozprofile::preferences::{Pref, PrefValue};
lazy_static! {
static ref LEVEL_MUTEX: Mutex<()> = Mutex::new(());
}
#[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_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::<log::Level>::into(Level::Fatal), log::Level::Error);
assert_eq!(Into::<log::Level>::into(Level::Error), log::Level::Error);
assert_eq!(Into::<log::Level>::into(Level::Warn), log::Level::Warn);
assert_eq!(Into::<log::Level>::into(Level::Info), log::Level::Info);
assert_eq!(Into::<log::Level>::into(Level::Config), log::Level::Debug);
assert_eq!(Into::<log::Level>::into(Level::Debug), log::Level::Debug);
assert_eq!(Into::<log::Level>::into(Level::Trace), log::Level::Trace);
}
#[test]
fn test_level_into_pref() {
let tests = [
(Level::Fatal, "Fatal"),
(Level::Error, "Error"),
(Level::Warn, "Warn"),
(Level::Info, "Info"),
(Level::Config, "Config"),
(Level::Debug, "Debug"),
(Level::Trace, "Trace"),
];
for &(lvl, s) in tests.iter() {
let expected = Pref {
value: PrefValue::String(s.to_string()),
sticky: false,
};
assert_eq!(Into::<Pref>::into(lvl), expected);
}
}
#[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() {
let _guard = LEVEL_MUTEX.lock();
set_max_level(Level::Info);
assert_eq!(max_level(), Level::Info);
}
#[test]
fn test_set_max_level() {
let _guard = LEVEL_MUTEX.lock();
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() {
let _guard = LEVEL_MUTEX.lock();
init_with_level(Level::Debug, false).unwrap();
assert_eq!(max_level(), Level::Debug);
assert!(init_with_level(Level::Warn, false).is_err());
}
#[test]
fn test_format_ts() {
let ts = chrono::Local::now();
let s = format_ts(ts);
assert_eq!(s.len(), 13);
}
#[test]
fn test_truncate() {
let short_message = (0..MAX_STRING_LENGTH).map(|_| "x").collect::<String>();
// A message up to MAX_STRING_LENGTH is not truncated
assert_eq!(truncate_message(&format_args!("{}", short_message)), None);
let long_message = (0..MAX_STRING_LENGTH + 1).map(|_| "x").collect::<String>();
let part = (0..MAX_STRING_LENGTH / 2).map(|_| "x").collect::<String>();
// A message longer than MAX_STRING_LENGTH is not truncated if requested
set_truncate(false);
assert_eq!(truncate_message(&format_args!("{}", long_message)), None);
// A message longer than MAX_STRING_LENGTH is truncated if requested
set_truncate(true);
assert_eq!(
truncate_message(&format_args!("{}", long_message)),
Some((part.to_owned(), part))
);
}
}
