*: clean up the usage of slog

Cargo.toml

@@ -24,7 +24,6 @@ prost-codec = ["raft-proto/prost-codec"]
 
 # Make sure to synchronize updates with Harness.
 [dependencies]
-log = "0.4"
 protobuf = "2"
 slog = "2.2"
 quick-error = "1.2.2"
@@ -35,15 +34,12 @@ rand = "0.6.5"
 hashbrown = "0.5"
 fail = { version = "0.3", optional = true }
 getset = "0.0.7"
-slog-stdlog = "4"
-slog-envlogger = "2.1.0"
-# We don't actually use this crate, but by pinning to 0.5.1 it forces Cargo to
-# avoid 0.5.2 and thus pulling in a transitive dep with a security vulnerability.
-term = "=0.5.1"
 
 [dev-dependencies]
 criterion = ">0.2.4"
 regex = "1.1"
+slog-stdlog = "4"
+slog-envlogger = "2.1.0"
 slog-async = "2.3.0"
 slog-term = "2.4.0"
 

benches/benches.rs

@@ -1,13 +1,45 @@
 #![allow(dead_code)] // Due to criterion we need this to avoid warnings.
 #![cfg_attr(feature = "cargo-clippy", allow(clippy::let_and_return))] // Benches often artificially return values. Allow it.
 
+#[macro_use]
+extern crate slog;
+
 use criterion::Criterion;
 use std::time::Duration;
 
 mod suites;
 
 pub const DEFAULT_RAFT_SETS: [(usize, usize); 4] = [(0, 0), (3, 1), (5, 2), (7, 3)];
 
+/// The default logger we fall back to when passed `None` in external facing constructors.
+///
+/// Currently, this is a `log` adaptor behind a `Once` to ensure there is no clobbering.
+fn default_logger() -> slog::Logger {
+    use slog::Drain;
+    use std::sync::{Mutex, Once};
+
+    static LOGGER_INITIALIZED: Once = Once::new();
+    static mut LOGGER: Option<slog::Logger> = None;
+
+    let logger = unsafe {
+        LOGGER_INITIALIZED.call_once(|| {
+            let decorator = slog_term::TermDecorator::new().build();
+            let drain = slog_term::CompactFormat::new(decorator).build();
+            let drain = slog_envlogger::new(drain);
+            LOGGER = Some(slog::Logger::root(Mutex::new(drain).fuse(), o!()));
+        });
+        LOGGER.as_ref().unwrap()
+    };
+    let case = std::thread::current()
+        .name()
+        .unwrap()
+        .split(":")
+        .last()
+        .unwrap()
+        .to_string();
+    logger.new(o!("case" => case))
+}
+
 fn main() {
     let mut c = Criterion::default()
         // Configure defaults before overriding with args.

benches/suites/progress_set.rs

@@ -16,7 +16,7 @@ pub fn bench_progress_set(c: &mut Criterion) {
 }
 
 fn quick_progress_set(voters: usize, learners: usize) -> ProgressSet {
-    let mut set = ProgressSet::with_capacity(voters, learners);
+    let mut set = ProgressSet::with_capacity(voters, learners, crate::default_logger());
     (0..voters).for_each(|id| {
         set.insert_voter(id as u64, Progress::new(0, 10)).ok();
     });
@@ -29,7 +29,7 @@ fn quick_progress_set(voters: usize, learners: usize) -> ProgressSet {
 pub fn bench_progress_set_new(c: &mut Criterion) {
     let bench = |b: &mut Bencher| {
         // No setup.
-        b.iter(|| ProgressSet::new());
+        b.iter(|| ProgressSet::new(crate::default_logger()));
     };
 
     c.bench_function("ProgressSet::new", bench);
@@ -39,7 +39,7 @@ pub fn bench_progress_set_with_capacity(c: &mut Criterion) {
     let bench = |voters, learners| {
         move |b: &mut Bencher| {
             // No setup.
-            b.iter(|| ProgressSet::with_capacity(voters, learners));
+            b.iter(|| ProgressSet::with_capacity(voters, learners, crate::default_logger()));
         }
     };
 

benches/suites/raft.rs

@@ -1,17 +1,17 @@
 use crate::DEFAULT_RAFT_SETS;
-use criterion::{Bencher, Criterion};
+use criterion::Criterion;
 use raft::{storage::MemStorage, Config, Raft};
 
 pub fn bench_raft(c: &mut Criterion) {
     bench_raft_new(c);
     bench_raft_campaign(c);
 }
 
-fn quick_raft(voters: usize, learners: usize) -> Raft<MemStorage> {
+fn quick_raft(voters: usize, learners: usize, logger: &slog::Logger) -> Raft<MemStorage> {
     let id = 1;
     let storage = MemStorage::default();
     let config = Config::new(id);
-    let mut raft = Raft::new(&config, storage).unwrap();
+    let mut raft = Raft::new(&config, storage, logger).unwrap();
     (0..voters).for_each(|id| {
         raft.add_node(id as u64).unwrap();
     });
@@ -22,47 +22,36 @@ fn quick_raft(voters: usize, learners: usize) -> Raft<MemStorage> {
 }
 
 pub fn bench_raft_new(c: &mut Criterion) {
-    let bench = |voters, learners| {
-        move |b: &mut Bencher| {
-            // No setup.
-            b.iter(|| quick_raft(voters, learners));
-        }
-    };
-
     DEFAULT_RAFT_SETS.iter().for_each(|(voters, learners)| {
-        c.bench_function(
-            &format!("Raft::new ({}, {})", voters, learners),
-            bench(*voters, *learners),
-        );
+        c.bench_function(&format!("Raft::new ({}, {})", voters, learners), move |b| {
+            let logger = crate::default_logger();
+            b.iter(|| quick_raft(*voters, *learners, &logger))
+        });
     });
 }
 
 pub fn bench_raft_campaign(c: &mut Criterion) {
-    let bench = |voters, learners, variant| {
-        move |b: &mut Bencher| {
-            b.iter(|| {
-                // TODO: Make raft clone somehow.
-                let mut raft = quick_raft(voters, learners);
-                raft.campaign(variant)
-            })
-        }
-    };
-
     DEFAULT_RAFT_SETS
         .iter()
         .skip(1)
         .for_each(|(voters, learners)| {
             // We don't want to make `raft::raft` public at this point.
-            let msgs = [
+            let msgs = &[
                 "CampaignPreElection",
                 "CampaignElection",
                 "CampaignTransfer",
             ];
             // Skip the first since it's 0,0
-            for msg in &msgs {
+            for msg in msgs {
                 c.bench_function(
                     &format!("Raft::campaign ({}, {}, {})", voters, learners, msg),
-                    bench(*voters, *learners, msg.as_bytes()),
+                    move |b| {
+                        let logger = crate::default_logger();
+                        b.iter(|| {
+                            let mut raft = quick_raft(*voters, *learners, &logger);
+                            raft.campaign(msg.as_bytes());
+                        })
+                    },
                 );
             }
         });

benches/suites/raw_node.rs

@@ -5,17 +5,17 @@ pub fn bench_raw_node(c: &mut Criterion) {
     bench_raw_node_new(c);
 }
 
-fn quick_raw_node() -> RawNode<MemStorage> {
+fn quick_raw_node(logger: &slog::Logger) -> RawNode<MemStorage> {
     let id = 1;
     let storage = MemStorage::default();
     let config = Config::new(id);
-    RawNode::new(&config, storage).unwrap()
+    RawNode::new(&config, storage, logger).unwrap()
 }
 
 pub fn bench_raw_node_new(c: &mut Criterion) {
     let bench = |b: &mut Bencher| {
-        // No setup.
-        b.iter(quick_raw_node);
+        let logger = crate::default_logger();
+        b.iter(|| quick_raw_node(&logger));
     };
 
     c.bench_function("RawNode::new", bench);

examples/five_mem_node/main.rs

@@ -10,6 +10,11 @@
 // distributed under the License is distributed on an "AS IS" BASIS,
 // See the License for the specific language governing permissions and
 // limitations under the License.
+
+#[macro_use]
+extern crate slog;
+
+use slog::Drain;
 use std::collections::{HashMap, VecDeque};
 use std::sync::mpsc::{self, Receiver, Sender, SyncSender, TryRecvError};
 use std::sync::{Arc, Mutex};
@@ -23,6 +28,15 @@ use raft::{prelude::*, StateRole};
 use regex::Regex;
 
 fn main() {
+    let decorator = slog_term::TermDecorator::new().build();
+    let drain = slog_term::FullFormat::new(decorator).build().fuse();
+    let drain = slog_async::Async::new(drain)
+        .chan_size(4096)
+        .overflow_strategy(slog_async::OverflowStrategy::Block)
+        .build()
+        .fuse();
+    let logger = slog::Logger::root(drain, o!());
+
     const NUM_NODES: u32 = 5;
     // Create 5 mailboxes to send/receive messages. Every node holds a `Receiver` to receive
     // messages from others, and uses the respective `Sender` to send messages to others.
@@ -46,7 +60,7 @@ fn main() {
         let mailboxes = (1..6u64).zip(tx_vec.iter().cloned()).collect();
         let mut node = match i {
             // Peer 1 is the leader.
-            0 => Node::create_raft_leader(1, rx, mailboxes),
+            0 => Node::create_raft_leader(1, rx, mailboxes, &logger),
             // Other peers are followers.
             _ => Node::create_raft_follower(rx, mailboxes),
         };
@@ -57,13 +71,14 @@ fn main() {
 
         // Clone the stop receiver
         let rx_stop_clone = Arc::clone(&rx_stop);
+        let logger = logger.clone();
         // Here we spawn the node on a new thread and keep a handle so we can join on them later.
         let handle = thread::spawn(move || loop {
             thread::sleep(Duration::from_millis(10));
             loop {
                 // Step raft messages.
                 match node.my_mailbox.try_recv() {
-                    Ok(msg) => node.step(msg),
+                    Ok(msg) => node.step(msg, &logger),
                     Err(TryRecvError::Empty) => break,
                     Err(TryRecvError::Disconnected) => return,
                 }
@@ -91,7 +106,13 @@ fn main() {
             }
 
             // Handle readies from the raft.
-            on_ready(raft_group, &mut node.kv_pairs, &node.mailboxes, &proposals);
+            on_ready(
+                raft_group,
+                &mut node.kv_pairs,
+                &node.mailboxes,
+                &proposals,
+                &logger,
+            );
 
             // Check control signals from
             if check_signals(&rx_stop_clone) {
@@ -105,7 +126,10 @@ fn main() {
     add_all_followers(proposals.as_ref());
 
     // Put 100 key-value pairs.
-    println!("We get a 5 nodes Raft cluster now, now propose 100 proposals");
+    info!(
+        logger,
+        "We get a 5 nodes Raft cluster now, now propose 100 proposals"
+    );
     (0..100u16)
         .filter(|i| {
             let (proposal, rx) = Proposal::normal(*i, "hello, world".to_owned());
@@ -116,7 +140,7 @@ fn main() {
         })
         .count();
 
-    println!("Propose 100 proposals success!");
+    info!(logger, "Propose 100 proposals success!");
 
     // Send terminate signals
     for _ in 0..NUM_NODES {
@@ -159,13 +183,14 @@ impl Node {
         id: u64,
         my_mailbox: Receiver<Message>,
         mailboxes: HashMap<u64, Sender<Message>>,
+        logger: &slog::Logger,
     ) -> Self {
         let mut cfg = example_config();
         cfg.id = id;
-        cfg.tag = format!("peer_{}", id);
+        let logger = logger.new(o!("tag" => format!("peer_{}", id)));
 
         let storage = MemStorage::new_with_conf_state(ConfState::from((vec![id], vec![])));
-        let raft_group = Some(RawNode::new(&cfg, storage).unwrap());
+        let raft_group = Some(RawNode::new(&cfg, storage, &logger).unwrap());
         Node {
             raft_group,
             my_mailbox,
@@ -188,22 +213,22 @@ impl Node {
     }
 
     // Initialize raft for followers.
-    fn initialize_raft_from_message(&mut self, msg: &Message) {
+    fn initialize_raft_from_message(&mut self, msg: &Message, logger: &slog::Logger) {
         if !is_initial_msg(msg) {
             return;
         }
         let mut cfg = example_config();
         cfg.id = msg.to;
-        cfg.tag = format!("peer_{}", msg.to);
+        let logger = logger.new(o!("tag" => format!("peer_{}", msg.to)));
         let storage = MemStorage::new();
-        self.raft_group = Some(RawNode::new(&cfg, storage).unwrap());
+        self.raft_group = Some(RawNode::new(&cfg, storage, &logger).unwrap());
     }
 
     // Step a raft message, initialize the raft if need.
-    fn step(&mut self, msg: Message) {
+    fn step(&mut self, msg: Message, logger: &slog::Logger) {
         if self.raft_group.is_none() {
             if is_initial_msg(&msg) {
-                self.initialize_raft_from_message(&msg);
+                self.initialize_raft_from_message(&msg, &logger);
             } else {
                 return;
             }
@@ -218,6 +243,7 @@ fn on_ready(
     kv_pairs: &mut HashMap<u16, String>,
     mailboxes: &HashMap<u64, Sender<Message>>,
     proposals: &Mutex<VecDeque<Proposal>>,
+    logger: &slog::Logger,
 ) {
     if !raft_group.has_ready() {
         return;
@@ -230,15 +256,21 @@ fn on_ready(
     // Persistent raft logs. It's necessary because in `RawNode::advance` we stabilize
     // raft logs to the latest position.
     if let Err(e) = store.wl().append(ready.entries()) {
-        eprintln!("persist raft log fail: {:?}, need to retry or panic", e);
+        error!(
+            logger,
+            "persist raft log fail: {:?}, need to retry or panic", e
+        );
         return;
     }
 
     // Apply the snapshot. It's necessary because in `RawNode::advance` we stabilize the snapshot.
     if *ready.snapshot() != Snapshot::default() {
         let s = ready.snapshot().clone();
         if let Err(e) = store.wl().apply_snapshot(s) {
-            eprintln!("apply snapshot fail: {:?}, need to retry or panic", e);
+            error!(
+                logger,
+                "apply snapshot fail: {:?}, need to retry or panic", e
+            );
             return;
         }
     }
@@ -247,7 +279,10 @@ fn on_ready(
     for msg in ready.messages.drain(..) {
         let to = msg.to;
         if mailboxes[&to].send(msg).is_err() {
-            eprintln!("send raft message to {} fail, let Raft retry it", to);
+            error!(
+                logger,
+                "send raft message to {} fail, let Raft retry it", to
+            );
         }
     }