Implement slog

Cargo.toml

@@ -8,6 +8,9 @@ ethereum-types = ""
 rand = "0.3"
 bytes = ""
 blake2 = "^0.7.1"
+slog = "^2.2.3"
+slog-term = "^2.4.0"
+slog-async = "^2.3.0"
 crypto-mac = "^0.6.2"
 bls = { git = "https://github.com/sigp/bls" }
 rlp = { git = "https://github.com/paritytech/parity-common" }

src/lib.rs

@@ -1,2 +1,5 @@
+#[macro_use]
+extern crate slog;
+
 pub mod state;
 pub mod utils;

src/state/transition/attestors.rs

@@ -1,6 +1,7 @@
 use super::validator_record::ValidatorRecord;
 use super::utils::types::Bitfield;
 use super::utils::bls::{ AggregateSignature, PublicKey };
+use super::utils::logging::Logger;
 use super::crystallized_state::CrystallizedState;
 use super::active_state::ActiveState;
 use super::config::Config;
@@ -25,7 +26,8 @@ pub fn get_attesters_and_proposer(
     cry_state: &CrystallizedState,
     act_state: &ActiveState,
     skip_count: &u64,
-    config: &Config)
+    config: &Config,
+    log:&Logger)
     -> (Vec<usize>, usize)
 {
     let active_validator_count = cry_state.num_active_validators(); 
@@ -89,6 +91,7 @@ pub fn process_attestations(
 #[cfg(test)]
 mod tests {
     use super::*;
+    use super::super::utils::logging::test_logger;
     
     #[test]
     fn test_process_recent_attesters() {
@@ -135,7 +138,8 @@ mod tests {
             &cry_state,
             &act_state,
             &0,
-            &Config::standard());
+            &Config::standard(),
+            &test_logger());
         assert_eq!(attestors, [0, 9, 7, 6, 4, 1, 8, 5, 2]);
         assert_eq!(proposer, 3);
     }
@@ -150,7 +154,8 @@ mod tests {
             &cry_state,
             &act_state,
             &0,
-            &Config::standard());
+            &Config::standard(),
+            &test_logger());
     }
 
     #[test]

src/state/transition/deposits.rs

@@ -1,9 +1,11 @@
 use super::crystallized_state::CrystallizedState;
 use super::utils::types::{ Bitfield, U256 };
+use super::utils::logging::Logger;
 
 pub fn process_ffg_deposits(
     cry_state: &CrystallizedState,
-    ffg_vote_bitfield: &Bitfield)
+    ffg_vote_bitfield: &Bitfield,
+    log: &Logger)
     -> (Vec<i64>, u64, U256, bool, bool)
 {
     let active_validators: usize = cry_state.num_active_validators();
@@ -34,6 +36,11 @@ pub fn process_ffg_deposits(
             should_finalize = true;
         }
     }
+    
+    info!(log, "counted ffg votes";
+            "total_vote_count" => total_vote_count, 
+            "total_vote_deposits" => total_vote_deposits.low_u64());
+
     (deltas, total_vote_count, total_vote_deposits, should_justify, should_finalize)
 }
 
@@ -41,12 +48,14 @@ pub fn process_ffg_deposits(
 mod tests {
     use super::*;
     use super::super::utils::types::{ Address, Sha256Digest };
+    use super::super::utils::logging::test_logger;
     use super::super::super::validator_record::ValidatorRecord;
     use super::super::
         utils::test_helpers::get_dangerous_test_keypair;
 
     #[test]
     fn test_deposit_processing_scenario_1() {
+        let log = test_logger();
         let mut cry_state = CrystallizedState::zero();
         let mut bitfield = Bitfield::new();
         let mut total_deposits = U256::zero();
@@ -75,7 +84,7 @@ mod tests {
 
         let (deltas, total_vote_count, total_vote_deposits,
              should_justify, should_finalize) = process_ffg_deposits(
-                 &cry_state, &bitfield);
+                 &cry_state, &bitfield, &log);
 
         assert_eq!(deltas, [6; 10]);
         assert_eq!(total_vote_count, 10);
@@ -86,6 +95,7 @@ mod tests {
     
     #[test]
     fn test_deposit_processing_scenario_2() {
+        let log = test_logger();
         let mut cry_state = CrystallizedState::zero();
         let bitfield = Bitfield::new();
         let individual_deposit = U256::from(0);
@@ -111,7 +121,7 @@ mod tests {
 
         let (deltas, total_vote_count, total_vote_deposits,
              should_justify, should_finalize) = process_ffg_deposits(
-                 &cry_state, &bitfield);
+                 &cry_state, &bitfield, &log);
 
         assert_eq!(deltas, [-6; 10]);
         assert_eq!(total_vote_count, 0);
@@ -122,6 +132,7 @@ mod tests {
 
     #[test]
     fn test_deposit_processing_scenario_3() {
+        let log = test_logger();
         let mut cry_state = CrystallizedState::zero();
         let mut bitfield = Bitfield::new();
         let mut total_deposits = U256::zero();
@@ -153,7 +164,7 @@ mod tests {
 
         let (deltas, total_vote_count, total_vote_deposits,
              should_justify, should_finalize) = process_ffg_deposits(
-                 &cry_state, &bitfield);
+                 &cry_state, &bitfield, &log);
 
         assert_eq!(deltas[0..5].to_vec(), [6;5]);
         assert_eq!(deltas[5..10].to_vec(), [-6;5]);

src/state/transition/epoch.rs

@@ -2,6 +2,7 @@ use super::active_state::ActiveState;
 use super::crystallized_state::CrystallizedState;
 use super::validator_record::ValidatorRecord;
 use super::utils::types::{ Bitfield, U256, Sha256Digest };
+use super::utils::logging::Logger;
 use super::config::Config;
 
 use super::deposits::process_ffg_deposits;
@@ -14,7 +15,8 @@ use super::shuffling::get_shuffling;
 pub fn initialize_new_epoch(
     cry_state: &CrystallizedState,
     act_state: &ActiveState,
-    config: &Config) 
+    config: &Config,
+    log: &Logger) 
     -> (CrystallizedState, ActiveState)
 {
     let mut new_validator_records: Vec<ValidatorRecord> = 
@@ -25,7 +27,12 @@ pub fn initialize_new_epoch(
     let (ffg_deltas, _, _,
          should_justify, should_finalize) = process_ffg_deposits (
              &cry_state,
-             &ffg_voter_bitfield);
+             &ffg_voter_bitfield,
+             &log);
+
+    info!(log, "processed ffg deposits";
+            "should_justify" => should_justify, 
+            "should_finalize" => should_finalize);
 
     let (crosslink_notaries_deltas, new_crosslinks) = 
         process_crosslinks(
@@ -33,6 +40,9 @@ pub fn initialize_new_epoch(
             &act_state.partial_crosslinks,
             &config);
 
+    info!(log, "processed crosslinks";
+            "new_crosslinks_count" => new_crosslinks.len());
+
     let recent_attesters_deltas = process_recent_attesters(
         &cry_state,
         &act_state.recent_attesters,
@@ -62,6 +72,9 @@ pub fn initialize_new_epoch(
         recent_attesters_deltas.iter().sum::<i64>() +
         recent_proposers_deltas.iter().sum::<i64>();
 
+    info!(log, "processed validator deltas";
+            "new_total_deposits" => deposit_sum);
+
     let total_deposits: U256 = match deposit_sum > 0 {
         true => U256::from(deposit_sum as u64),
         false => U256::zero()
@@ -83,7 +96,8 @@ pub fn initialize_new_epoch(
         true => get_incremented_validator_sets(
             &cry_state,
             &new_validator_records,
-            &config),
+            &config,
+            &log),
         false => (cry_state.queued_validators.to_vec(), 
                   cry_state.active_validators.to_vec(),
                   cry_state.exited_validators.to_vec())
@@ -111,6 +125,11 @@ pub fn initialize_new_epoch(
         total_deposits
     };
 
+    info!(log, "created new crystallized state";
+            "epoch" => new_cry_state.current_epoch,
+            "last_justified_epoch" => new_cry_state.last_justified_epoch,
+            "last_finalized_epoch" => new_cry_state.last_finalized_epoch);
+
     let new_act_state = ActiveState {
         height: act_state.height,
         randao: act_state.randao,
@@ -121,6 +140,9 @@ pub fn initialize_new_epoch(
         recent_proposers: vec![]
     };
 
+    info!(log, "created new active state";
+            "height" => new_act_state.height);
+
     (new_cry_state, new_act_state)
 }
 

src/state/transition/mod.rs

@@ -30,13 +30,15 @@ use super::crystallized_state::CrystallizedState;
 use super::active_state::ActiveState;
 use super::transition::epoch::initialize_new_epoch;
 use super::transition::new_active_state::compute_new_active_state;
+use super::utils::logging::Logger;
 
 pub fn compute_state_transition (
     parent_cry_state: &CrystallizedState,
     parent_act_state: &ActiveState,
     parent_block: &Block,
     block: &Block,
-    config: &Config) 
+    config: &Config,
+    log: &Logger) 
     -> (CrystallizedState, ActiveState)
 {
     let is_new_epoch =  parent_act_state.height % 
@@ -47,15 +49,23 @@ pub fn compute_state_transition (
         true => initialize_new_epoch(
             &parent_cry_state,
             &parent_act_state,
-            &config)
+            &config,
+            &log)
     };
+    
+    if is_new_epoch {
+        info!(log, "initialized new epoch";
+              "epoch" => cry_state.current_epoch);
+    }
+
 
     act_state = compute_new_active_state(
         &cry_state,
         &act_state,
         &parent_block,
         &block,
-        &config);
+        &config,
+        &log);
 
     (cry_state, act_state)
 }

src/state/transition/new_active_state.rs

@@ -5,6 +5,7 @@ use super::crystallized_state::CrystallizedState;
 use super::recent_proposer_record::RecentPropserRecord;
 use super::block::Block;
 use super::utils::types::Sha256Digest;
+use super::utils::logging::Logger;
 use super::config::Config;
 use super::rlp;
 
@@ -19,14 +20,20 @@ pub fn compute_new_active_state(
     act_state: &ActiveState,
     parent_block: &Block,
     block: &Block,
-    config: &Config)
+    config: &Config,
+    log: &Logger)
     -> ActiveState
 {
     let (attestation_indicies, proposer) = get_attesters_and_proposer(
         &cry_state,
         &act_state,
         &block.skip_count,
-        &config);
+        &config,
+        &log);
+    
+    info!(log, "calculated attesters and proposers";
+          "attesters_count" => attestation_indicies.len(),
+          "proposer_index" => proposer);
 
     let parent_block_rlp = rlp::encode(parent_block);
     let attesters_option = process_attestations(

src/state/transition/validators.rs

@@ -2,23 +2,27 @@ use std::cmp::min;
 
 use super::crystallized_state::CrystallizedState;
 use super::validator_record::ValidatorRecord;
+use super::utils::logging::Logger;
 use super::config::Config;
 
 pub fn get_incremented_validator_sets(
     cry_state: &CrystallizedState,
     active_validators: &Vec<ValidatorRecord>,
-    config: &Config)
+    config: &Config,
+    log: &Logger)
     -> (Vec<ValidatorRecord>, Vec<ValidatorRecord>, Vec<ValidatorRecord>)
 {
     let mut new_active_validators: Vec<ValidatorRecord> = vec![];
     let mut new_exited_validators: Vec<ValidatorRecord> 
         = cry_state.exited_validators.clone();
     let next_dynasty = cry_state.dynasty + 1;
+    let mut ejection_count = 0;
 
     for v in active_validators {
         if (v.balance <= config.eject_balance) | 
             (v.switch_dynasty == next_dynasty) {
             new_exited_validators.push(v.clone());
+            ejection_count += 1;
         } 
         else {
             new_active_validators.push(v.clone());
@@ -39,6 +43,11 @@ pub fn get_incremented_validator_sets(
     let new_queued_validators = cry_state.
         queued_validators[first_ineligable..cry_state.queued_validators.len()]
             .to_vec();
+
+    info!(log, "updated validator sets";
+          "inducted_count" => induction_count,
+          "ejected_count" => ejection_count);
+
     (new_queued_validators, new_active_validators, new_exited_validators)
 }
 
@@ -46,7 +55,7 @@ pub fn get_incremented_validator_sets(
 mod tests {
     use super::*;
     use super::super::utils::types::U256;
-    // use super::super::shuffling::get_shuffling;
+    use super::super::utils::logging::test_logger;
     
     fn test_setup() -> (CrystallizedState, Config) {
         let mut cry_state = CrystallizedState::zero();
@@ -98,7 +107,8 @@ mod tests {
         let (nq, na, nx) = get_incremented_validator_sets(
             &cry_state,
             &a,
-            &config);
+            &config,
+            &test_logger());
 
         let inducted = validator_count / 30 + 1;
         assert!(inducted > 0);
@@ -155,7 +165,8 @@ mod tests {
         let (nq, na, nx) = get_incremented_validator_sets(
             &cry_state,
             &a,
-            &config);
+            &config,
+            &test_logger());
 
         let inducted = validator_count / 30 + 1;
         assert!(inducted > eligable_queued, "this test requires more inductable \

src/utils/logging.rs

@@ -0,0 +1,23 @@
+extern crate slog;
+extern crate slog_term;
+extern crate slog_async;
+
+use slog::*;
+pub use slog::Logger;
+
+pub fn test_logger() -> slog::Logger {
+    let plain = slog_term::PlainSyncDecorator::new(slog_term::TestStdoutWriter);
+    let logger = Logger::root(
+        slog_term::FullFormat::new(plain)
+        .build().fuse(), o!()
+    );
+    logger
+}
+
+pub fn get_logger() -> slog::Logger {
+    let decorator = slog_term::TermDecorator::new().build();
+    let drain = slog_term::CompactFormat::new(decorator).build().fuse();
+    let drain = slog_async::Async::new(drain).build().fuse();
+
+    slog::Logger::root(drain, o!())
+}

src/utils/mod.rs

@@ -9,3 +9,4 @@ pub mod types;
 pub mod bls;
 pub mod test_helpers;
 pub mod boolean_bitfield;
+pub mod logging;