From e353102e32e83589086c46f7f96f230bd1ee969d Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Fri, 20 Jul 2018 17:47:10 +1000 Subject: [PATCH] Implement slog --- Cargo.toml | 3 +++ src/lib.rs | 3 +++ src/state/transition/attestors.rs | 11 +++++++--- src/state/transition/deposits.rs | 19 ++++++++++++---- src/state/transition/epoch.rs | 28 +++++++++++++++++++++--- src/state/transition/mod.rs | 16 +++++++++++--- src/state/transition/new_active_state.rs | 11 ++++++++-- src/state/transition/validators.rs | 19 ++++++++++++---- src/utils/logging.rs | 23 +++++++++++++++++++ src/utils/mod.rs | 1 + 10 files changed, 115 insertions(+), 19 deletions(-) create mode 100644 src/utils/logging.rs diff --git a/Cargo.toml b/Cargo.toml index 8d664b6f43..51aea03f39 100644 --- a/Cargo.toml +++ b/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" } diff --git a/src/lib.rs b/src/lib.rs index 63c76f0c82..bec82a2b62 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -1,2 +1,5 @@ +#[macro_use] +extern crate slog; + pub mod state; pub mod utils; diff --git a/src/state/transition/attestors.rs b/src/state/transition/attestors.rs index e5acf43673..71bd56353b 100644 --- a/src/state/transition/attestors.rs +++ b/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) { 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] diff --git a/src/state/transition/deposits.rs b/src/state/transition/deposits.rs index 95f8b95ae9..fee2176157 100644 --- a/src/state/transition/deposits.rs +++ b/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, 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]); diff --git a/src/state/transition/epoch.rs b/src/state/transition/epoch.rs index 5d4c227968..271b3f7fdc 100644 --- a/src/state/transition/epoch.rs +++ b/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 = @@ -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::() + recent_proposers_deltas.iter().sum::(); + 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) } diff --git a/src/state/transition/mod.rs b/src/state/transition/mod.rs index 3979ecb295..51fce8fae0 100644 --- a/src/state/transition/mod.rs +++ b/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) } diff --git a/src/state/transition/new_active_state.rs b/src/state/transition/new_active_state.rs index 612de2822c..eb24e7e571 100644 --- a/src/state/transition/new_active_state.rs +++ b/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( diff --git a/src/state/transition/validators.rs b/src/state/transition/validators.rs index 79c728acaa..aaa916ee2d 100644 --- a/src/state/transition/validators.rs +++ b/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, - config: &Config) + config: &Config, + log: &Logger) -> (Vec, Vec, Vec) { let mut new_active_validators: Vec = vec![]; let mut new_exited_validators: Vec = 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 \ diff --git a/src/utils/logging.rs b/src/utils/logging.rs new file mode 100644 index 0000000000..67b27bf2c0 --- /dev/null +++ b/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!()) +} diff --git a/src/utils/mod.rs b/src/utils/mod.rs index 683e80d0a2..bae40ad228 100644 --- a/src/utils/mod.rs +++ b/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;