Add basic logging to ruaft and especially tests.

A new sub-crate is created to hold the code so that it could be shared
with the KV server.

Cargo.toml

@@ -19,6 +19,7 @@ crossbeam-utils = "0.8"
 futures-channel = "0.3.15"
 futures-util = "0.3.15"
 labrpc = "0.1.12"
+log = "0.4"
 parking_lot = "0.11.1"
 rand = "0.8"
 serde = "1.0.116"
@@ -29,10 +30,12 @@ tokio = { version = "1.7", features = ["rt-multi-thread", "time", "parking_lot"]
 anyhow = "1.0"
 futures = { version = "0.3.15", features = ["thread-pool"] }
 scopeguard = "1.1.0"
+test_utils = { path = "test_utils" }
 kvraft = { path = "kvraft" }
 
 [workspace]
 members = [
     "kvraft",
     "linearizability",
-]
+    "test_utils",
+]

src/lib.rs

@@ -2,6 +2,7 @@ extern crate bincode;
 extern crate futures_channel;
 extern crate futures_util;
 extern crate labrpc;
+extern crate log;
 extern crate rand;
 #[macro_use]
 extern crate serde_derive;
@@ -259,6 +260,7 @@ where
 
         let _ = self.new_log_entry.clone().unwrap().send(None);
 
+        log::info!("{:?} started new entry at {} {:?}", self.me, index, term);
         Some((term, index))
     }
 

test_utils/Cargo.toml

@@ -0,0 +1,9 @@
+[package]
+name = "test_utils"
+version = "0.1.0"
+edition = "2018"
+
+[dependencies]
+env_logger = "0.8"
+log = "0.4"
+rand = "0.8"

test_utils/src/lib.rs

@@ -0,0 +1,6 @@
+extern crate env_logger;
+extern crate log;
+extern crate rand;
+
+mod logging;
+pub use logging::{init_log, init_log_once, LOG_DIR};

test_utils/src/logging.rs

@@ -0,0 +1,59 @@
+use std::path::PathBuf;
+use std::time::SystemTime;
+
+use rand::Rng;
+use std::sync::Once;
+
+#[macro_export]
+macro_rules! init_test_log {
+    () => {
+        $crate::init_log_once(module_path!())
+    };
+}
+
+static INIT_LOG_ONCE: Once = Once::new();
+static mut LOG_FILE: Option<PathBuf> = None;
+
+pub fn init_log_once(module_path: &str) -> PathBuf {
+    INIT_LOG_ONCE.call_once(|| unsafe {
+        LOG_FILE.replace(
+            init_log(module_path).expect("init_log() should never fail"),
+        );
+    });
+    unsafe { LOG_FILE.clone().expect("The log file should have been set") }
+}
+
+pub const LOG_DIR: &str = "/tmp/ruaft-test-logs/";
+
+pub fn init_log(module_path: &str) -> std::io::Result<PathBuf> {
+    let module = module_path.replace("::config", "");
+    let module_file = module.replace("::", "-");
+    let timestamp = SystemTime::now()
+        .duration_since(SystemTime::UNIX_EPOCH)
+        .map(|d| d.as_secs())
+        .unwrap_or(0);
+    let suffix: String = rand::thread_rng()
+        .sample_iter(&rand::distributions::Alphanumeric)
+        .take(10)
+        .map(char::from)
+        .collect();
+    let log_file_name =
+        format!("{}-{:010}-{}.log", module_file, timestamp, suffix);
+
+    let log_dir = option_env!("LOG_DIR").unwrap_or(LOG_DIR);
+    let mut path = PathBuf::from(log_dir);
+    std::fs::create_dir_all(path.as_path())?;
+
+    path.push(log_file_name);
+    let log_file = std::fs::File::create(path.as_path())?;
+
+    let env = env_logger::Env::default().default_filter_or("info");
+    env_logger::Builder::from_env(env)
+        .target(env_logger::Target::Pipe(Box::new(log_file)))
+        .filter(Some(module.as_str()), log::LevelFilter::Trace)
+        .format_timestamp_millis()
+        .is_test(true)
+        .init();
+
+    Ok(path)
+}

tests/config/mod.rs

@@ -1,4 +1,5 @@
 use std::collections::HashMap;
+use std::path::PathBuf;
 use std::rc::Rc;
 use std::sync::Arc;
 use std::time::Instant;
@@ -30,6 +31,7 @@ pub struct Config {
     server_count: usize,
     state: Mutex<ConfigState>,
     log: Arc<Mutex<LogState>>,
+    log_file_path: PathBuf,
 }
 
 impl Config {
@@ -361,6 +363,7 @@ impl Config {
     pub fn end(&self) {}
 
     pub fn cleanup(&self) {
+        log::trace!("Cleaning up test config ...");
         let mut network = self.network.lock();
         for i in 0..self.server_count {
             network.remove_server(Self::server_name(i));
@@ -372,6 +375,8 @@ impl Config {
                 raft.kill();
             }
         }
+        log::trace!("Cleaning up test config done.");
+        eprintln!("Ruaft log file: {:?}", self.log_file_path.as_os_str());
     }
 }
 
@@ -433,6 +438,9 @@ impl Config {
 }
 
 pub fn make_config(server_count: usize, unreliable: bool) -> Config {
+    // Create a logger first.
+    let log_file_path = test_utils::init_test_log!();
+
     let network = labrpc::Network::run_daemon();
     {
         let mut unlocked_network = network.lock();
@@ -460,6 +468,7 @@ pub fn make_config(server_count: usize, unreliable: bool) -> Config {
         server_count,
         state,
         log,
+        log_file_path,
     };
 
     for i in 0..server_count {