Merge branch 'adjust-logging-levels'

5 files changed, 107 insertions, 50 deletions

diff --git a/mullvad-daemon/Cargo.toml b/mullvad-daemon/Cargo.toml
index 48bd3c59af..6bba73bbd3 100644
--- a/mullvad-daemon/Cargo.toml
+++ b/mullvad-daemon/Cargo.toml
@@ -11,11 +11,11 @@ app_dirs = "1.1"
 chrono = { version = "0.4", features = ["serde"] }
 clap = "2.25"
 error-chain = "0.11"
-fern = "0.4"
+fern = { version = "0.5", features = ["colored"] }
 futures = "0.1"
 serde = { version = "1.0", features = ["derive"] }
 serde_json = "1.0"
-log = "0.3"
+log = "0.4"
 jsonrpc-core = { git = "https://github.com/paritytech/jsonrpc", tag = "v7.1.1" }
 jsonrpc-macros = { git = "https://github.com/paritytech/jsonrpc", tag = "v7.1.1" }
 jsonrpc-pubsub = { git = "https://github.com/paritytech/jsonrpc", tag = "v7.1.1" }
diff --git a/mullvad-daemon/src/cli.rs b/mullvad-daemon/src/cli.rs
index 0550613232..4c0779bf97 100644
--- a/mullvad-daemon/src/cli.rs
+++ b/mullvad-daemon/src/cli.rs
@@ -4,7 +4,7 @@ use log;
 use std::path::PathBuf;
 
 pub struct Config {
-    pub log_level: log::LogLevelFilter,
+    pub log_level: log::LevelFilter,
     pub log_file: Option<PathBuf>,
     pub tunnel_log_file: Option<PathBuf>,
     pub resource_dir: Option<PathBuf>,
@@ -16,9 +16,9 @@ pub fn get_config() -> Config {
     let matches = app.get_matches();
 
     let log_level = match matches.occurrences_of("v") {
-        0 => log::LogLevelFilter::Info,
-        1 => log::LogLevelFilter::Debug,
-        _ => log::LogLevelFilter::Trace,
+        0 => log::LevelFilter::Info,
+        1 => log::LevelFilter::Debug,
+        _ => log::LevelFilter::Trace,
     };
     let log_file = matches.value_of_os("log_file").map(PathBuf::from);
     let tunnel_log_file = matches.value_of_os("tunnel_log_file").map(PathBuf::from);
diff --git a/mullvad-daemon/src/logging.rs b/mullvad-daemon/src/logging.rs
new file mode 100644
index 0000000000..a43b00524a
--- /dev/null
+++ b/mullvad-daemon/src/logging.rs
@@ -0,0 +1,92 @@
+extern crate fern;
+
+use self::fern::colors::{Color, ColoredLevelConfig};
+use chrono;
+use log;
+
+use std::fmt;
+use std::io;
+use std::path::PathBuf;
+
+error_chain! {
+    errors {
+        WriteFileError(path: PathBuf) {
+            description("Unable to open log file for writing")
+            display("Unable to open log file for writing: {}", path.to_string_lossy())
+        }
+    }
+    foreign_links {
+        SetLoggerError(log::SetLoggerError);
+    }
+}
+
+const SILENCED_CRATES: &[&str] = &[
+    "jsonrpc_core",
+    // jsonrpc_core does some logging under the "rpc" target as well.
+    "rpc",
+    "tokio_core",
+    "tokio_proto",
+    "jsonrpc_ws_server",
+    "ws",
+    "mio",
+    "hyper",
+];
+
+const COLORS: ColoredLevelConfig = ColoredLevelConfig {
+    error: Color::Red,
+    warn: Color::Yellow,
+    info: Color::Green,
+    debug: Color::Blue,
+    trace: Color::Black,
+};
+
+pub const DATE_TIME_FORMAT_STR: &str = "%Y-%m-%d %H:%M:%S%.3f";
+
+pub fn init_logger(log_level: log::LevelFilter, log_file: Option<&PathBuf>) -> Result<()> {
+    let mut top_dispatcher = fern::Dispatch::new().level(log_level);
+    for silenced_crate in SILENCED_CRATES {
+        top_dispatcher = top_dispatcher.level_for(*silenced_crate, log::LevelFilter::Warn);
+    }
+
+    let stdout_dispatcher = fern::Dispatch::new()
+        .format(move |out, message, record| format_log_message(out, message, record, true))
+        .chain(io::stdout());
+    top_dispatcher = top_dispatcher.chain(stdout_dispatcher);
+
+    if let Some(ref log_file) = log_file {
+        let f = fern::log_file(log_file)
+            .chain_err(|| ErrorKind::WriteFileError(log_file.to_path_buf()))?;
+        let file_dispatcher = fern::Dispatch::new()
+            .format(|out, message, record| format_log_message(out, message, record, false))
+            .chain(f);
+        top_dispatcher = top_dispatcher.chain(file_dispatcher);
+    }
+    top_dispatcher.apply()?;
+    Ok(())
+}
+
+fn format_log_message(
+    out: fern::FormatCallback,
+    message: &fmt::Arguments,
+    record: &log::Record,
+    color_output: bool,
+) {
+    let timestamp = chrono::Local::now().format(DATE_TIME_FORMAT_STR);
+    if color_output && cfg!(not(windows)) {
+        out.finish(format_args!(
+            "[{}][{}][{}] {}",
+            timestamp,
+            record.target(),
+            COLORS.color(record.level()),
+            message,
+        ))
+    } else {
+        out.finish(format_args!(
+            "[{}][{}][{}] {}",
+            timestamp,
+            record.target(),
+            record.level(),
+            message
+        ))
+    }
+}
diff --git a/mullvad-daemon/src/main.rs b/mullvad-daemon/src/main.rs
index 8bd5ff9826..d6cc7755fc 100644
--- a/mullvad-daemon/src/main.rs
+++ b/mullvad-daemon/src/main.rs
@@ -13,7 +13,6 @@ extern crate chrono;
 extern crate clap;
 #[macro_use]
 extern crate error_chain;
-extern crate fern;
 extern crate futures;
 #[macro_use]
 extern crate log;
@@ -43,6 +42,7 @@ extern crate talpid_types;
 mod account_history;
 mod cli;
 mod geoip;
+mod logging;
 mod management_interface;
 mod relays;
 mod rpc_info;
@@ -119,8 +119,6 @@ static APP_INFO: AppInfo = AppInfo {
     author: "Mullvad",
 };
 
-const DATE_TIME_FORMAT_STR: &str = "%Y-%m-%d %H:%M:%S%.3f";
-
 
 /// All events that can happen in the daemon. Sent from various threads and exposed interfaces.
 pub enum DaemonEvent {
@@ -311,7 +309,7 @@ impl Daemon {
     ) {
         thread::spawn(move || {
             let result = server.wait();
-            debug!("Mullvad management interface shut down");
+            error!("Mullvad management interface shut down");
             let _ = exit_tx.send(DaemonEvent::ManagementInterfaceExited(result));
         });
     }
@@ -764,7 +762,8 @@ quick_main!(run);
 
 fn run() -> Result<()> {
     let config = cli::get_config();
-    init_logger(config.log_level, config.log_file.as_ref())?;
+    logging::init_logger(config.log_level, config.log_file.as_ref())
+        .chain_err(|| "Unable to initialize logger")?;
     log_version();
 
     let resource_dir = config.resource_dir.unwrap_or_else(|| get_resource_dir());
@@ -777,45 +776,11 @@ fn run() -> Result<()> {
 
     daemon.run()?;
 
-    debug!("Mullvad daemon is quitting");
+    info!("Mullvad daemon is quitting");
     thread::sleep(Duration::from_millis(500));
     Ok(())
 }
 
-fn init_logger(log_level: log::LogLevelFilter, log_file: Option<&PathBuf>) -> Result<()> {
-    let silenced_crates = [
-        "jsonrpc_core",
-        "tokio_core",
-        "tokio_proto",
-        "jsonrpc_ws_server",
-        "ws",
-        "mio",
-        "hyper",
-    ];
-    let mut config = fern::Dispatch::new()
-        .format(|out, message, record| {
-            out.finish(format_args!(
-                "[{}][{}][{}] {}",
-                chrono::Local::now().format(DATE_TIME_FORMAT_STR),
-                record.target(),
-                record.level(),
-                message
-            ))
-        })
-        .level(log_level)
-        .chain(std::io::stdout());
-    for silenced_crate in &silenced_crates {
-        config = config.level_for(*silenced_crate, log::LogLevelFilter::Warn);
-    }
-    if let Some(ref log_file) = log_file {
-        let f = fern::log_file(log_file).chain_err(|| "Failed to open log file for writing")?;
-        config = config.chain(f);
-    }
-    config
-        .apply()
-        .chain_err(|| "Failed to bootstrap logging system")
-}
-
 fn log_version() {
     info!(
         "Starting {} - {} {}",
diff --git a/mullvad-daemon/src/relays.rs b/mullvad-daemon/src/relays.rs
index f19feb8edb..3f1a9ab77f 100644
--- a/mullvad-daemon/src/relays.rs
+++ b/mullvad-daemon/src/relays.rs
@@ -54,10 +54,10 @@ impl RelaySelector {
     pub fn new(rpc_handle: HttpHandle, resource_dir: &Path) -> Result<Self> {
         let (last_updated, relay_list) = Self::read_cached_relays(resource_dir)?;
         let (locations, relays) = Self::process_relay_list(relay_list);
-        debug!(
+        info!(
             "Initialized with {} cached relays from {}",
             relays.len(),
-            DateTime::<Local>::from(last_updated).format(::DATE_TIME_FORMAT_STR)
+            DateTime::<Local>::from(last_updated).format(::logging::DATE_TIME_FORMAT_STR)
         );
         Ok(RelaySelector {
             locations,
@@ -243,7 +243,7 @@ impl RelaySelector {
 
     /// Downloads the latest relay list and caches it. This operation is blocking.
     pub fn update(&mut self, timeout: Duration) -> Result<()> {
-        info!("Downloading list of relays");
+        info!("Downloading list of relays...");
         let download_future = self.rpc_client
             .relay_list()
             .map_err(|e| Error::with_chain(e, ErrorKind::DownloadError));
@@ -252,7 +252,7 @@ impl RelaySelector {
             error!("Unable to save relays to cache: {}", e.display_chain());
         }
         let (locations, relays) = Self::process_relay_list(relay_list);
-        debug!("Downloaded relay inventory has {} relays", relays.len());
+        info!("Downloaded relay inventory has {} relays", relays.len());
         self.locations = locations;
         self.relays = relays;
         self.last_updated = SystemTime::now();