From b0513b1ec1839826ad64704b5457d47adcc8d257 Mon Sep 17 00:00:00 2001 From: Paul Hauner Date: Sat, 16 Feb 2019 15:08:33 +1100 Subject: [PATCH] Add and update logs --- .../beacon_chain/src/cached_beacon_state.rs | 9 ++-- .../test_harness/src/beacon_chain_harness.rs | 13 ++++- .../beacon_chain/test_harness/tests/chain.rs | 2 +- .../state_processing/src/block_processable.rs | 13 ++--- .../state_processing/src/epoch_processable.rs | 13 +++++ eth2/types/src/beacon_state.rs | 49 ++++++++----------- 6 files changed, 59 insertions(+), 40 deletions(-) diff --git a/beacon_node/beacon_chain/src/cached_beacon_state.rs b/beacon_node/beacon_chain/src/cached_beacon_state.rs index fec1d7c06..e14e9fe99 100644 --- a/beacon_node/beacon_chain/src/cached_beacon_state.rs +++ b/beacon_node/beacon_chain/src/cached_beacon_state.rs @@ -1,4 +1,4 @@ -use log::debug; +use log::{debug, trace}; use std::collections::HashMap; use types::{beacon_state::BeaconStateError, BeaconState, ChainSpec, Epoch, Slot}; @@ -42,7 +42,7 @@ impl CachedBeaconState { let mut attestation_duties: Vec = Vec::with_capacity(3); if CACHE_PREVIOUS { - debug!("CachedBeaconState::from_beacon_state: building previous epoch cache."); + debug!("from_beacon_state: building previous epoch cache."); let cache = build_epoch_cache(&state, previous_epoch, &spec)?; committees.push(cache.committees); attestation_duties.push(cache.attestation_duty_map); @@ -51,7 +51,7 @@ impl CachedBeaconState { attestation_duties.push(HashMap::new()); } if CACHE_CURRENT { - debug!("CachedBeaconState::from_beacon_state: building current epoch cache."); + debug!("from_beacon_state: building current epoch cache."); let cache = build_epoch_cache(&state, current_epoch, &spec)?; committees.push(cache.committees); attestation_duties.push(cache.attestation_duty_map); @@ -60,7 +60,7 @@ impl CachedBeaconState { attestation_duties.push(HashMap::new()); } if CACHE_NEXT { - debug!("CachedBeaconState::from_beacon_state: building next epoch cache."); + debug!("from_beacon_state: building next epoch cache."); let cache = build_epoch_cache(&state, next_epoch, &spec)?; committees.push(cache.committees); attestation_duties.push(cache.attestation_duty_map); @@ -81,6 +81,7 @@ impl CachedBeaconState { } fn slot_to_cache_index(&self, slot: Slot) -> Option { + trace!("slot_to_cache_index: cache lookup"); match slot.epoch(self.spec.epoch_length) { epoch if (epoch == self.previous_epoch) & CACHE_PREVIOUS => Some(0), epoch if (epoch == self.current_epoch) & CACHE_CURRENT => Some(1), diff --git a/beacon_node/beacon_chain/test_harness/src/beacon_chain_harness.rs b/beacon_node/beacon_chain/test_harness/src/beacon_chain_harness.rs index 5ea681ca3..9d61952f0 100644 --- a/beacon_node/beacon_chain/test_harness/src/beacon_chain_harness.rs +++ b/beacon_node/beacon_chain/test_harness/src/beacon_chain_harness.rs @@ -128,7 +128,18 @@ impl BeaconChainHarness { pub fn increment_beacon_chain_slot(&mut self) -> Slot { let slot = self.beacon_chain.present_slot() + 1; - debug!("Incrementing BeaconChain slot to {}.", slot); + let nth_slot = slot + - slot + .epoch(self.spec.epoch_length) + .start_slot(self.spec.epoch_length); + let nth_epoch = slot.epoch(self.spec.epoch_length) - self.spec.genesis_epoch; + debug!( + "Advancing BeaconChain to slot {}, epoch {} (epoch height: {}, slot {} in epoch.).", + slot, + slot.epoch(self.spec.epoch_length), + nth_epoch, + nth_slot + ); self.beacon_chain.slot_clock.set_slot(slot.as_u64()); self.beacon_chain.advance_state(slot).unwrap(); diff --git a/beacon_node/beacon_chain/test_harness/tests/chain.rs b/beacon_node/beacon_chain/test_harness/tests/chain.rs index a57a0161f..b3354784f 100644 --- a/beacon_node/beacon_chain/test_harness/tests/chain.rs +++ b/beacon_node/beacon_chain/test_harness/tests/chain.rs @@ -33,7 +33,7 @@ fn it_can_produce_past_first_epoch_boundary() { for i in 0..blocks { harness.advance_chain_with_block(); - debug!("Produced block {}/{}.", i, blocks); + debug!("Produced block {}/{}.", i + 1, blocks); } let dump = harness.chain_dump().expect("Chain dump failed."); diff --git a/eth2/state_processing/src/block_processable.rs b/eth2/state_processing/src/block_processable.rs index 904d2fac5..539711c69 100644 --- a/eth2/state_processing/src/block_processable.rs +++ b/eth2/state_processing/src/block_processable.rs @@ -1,7 +1,7 @@ use crate::SlotProcessingError; use hashing::hash; use int_to_bytes::int_to_bytes32; -use log::debug; +use log::{debug, trace}; use ssz::{ssz_encode, TreeHash}; use types::{ beacon_state::{AttestationParticipantsError, BeaconStateError}, @@ -219,6 +219,8 @@ fn per_block_processing_signature_optional( Error::MaxAttestationsExceeded ); + debug!("Verifying {} attestations.", block.body.attestations.len()); + for attestation in &block.body.attestations { validate_attestation(&state, attestation, spec)?; @@ -231,11 +233,6 @@ fn per_block_processing_signature_optional( state.latest_attestations.push(pending_attestation); } - debug!( - "{} attestations verified & processed.", - block.body.attestations.len() - ); - /* * Deposits */ @@ -312,6 +309,10 @@ fn validate_attestation_signature_optional( spec: &ChainSpec, verify_signature: bool, ) -> Result<(), AttestationValidationError> { + trace!( + "validate_attestation_signature_optional: attestation epoch: {}", + attestation.data.slot.epoch(spec.epoch_length) + ); ensure!( attestation.data.slot + spec.min_attestation_inclusion_delay <= state.slot, AttestationValidationError::IncludedTooEarly diff --git a/eth2/state_processing/src/epoch_processable.rs b/eth2/state_processing/src/epoch_processable.rs index 658449d6f..80318914c 100644 --- a/eth2/state_processing/src/epoch_processable.rs +++ b/eth2/state_processing/src/epoch_processable.rs @@ -315,6 +315,11 @@ impl EpochProcessable for BeaconState { // for slot in self.slot.saturating_sub(2 * spec.epoch_length)..self.slot { for slot in self.previous_epoch(spec).slot_iter(spec.epoch_length) { + trace!( + "Finding winning root for slot: {} (epoch: {})", + slot, + slot.epoch(spec.epoch_length) + ); let crosslink_committees_at_slot = self.get_crosslink_committees_at_slot(slot, false, spec)?; @@ -539,6 +544,12 @@ impl EpochProcessable for BeaconState { */ self.previous_calculation_epoch = self.current_calculation_epoch; self.previous_epoch_start_shard = self.current_epoch_start_shard; + + debug!( + "setting previous_epoch_seed to : {}", + self.current_epoch_seed + ); + self.previous_epoch_seed = self.current_epoch_seed; let should_update_validator_registy = if self.finalized_epoch @@ -553,6 +564,7 @@ impl EpochProcessable for BeaconState { }; if should_update_validator_registy { + trace!("updating validator registry."); self.update_validator_registry(spec); self.current_calculation_epoch = next_epoch; @@ -561,6 +573,7 @@ impl EpochProcessable for BeaconState { % spec.shard_count; self.current_epoch_seed = self.generate_seed(self.current_calculation_epoch, spec)? } else { + trace!("not updating validator registry."); let epochs_since_last_registry_update = current_epoch - self.validator_registry_update_epoch; if (epochs_since_last_registry_update > 1) diff --git a/eth2/types/src/beacon_state.rs b/eth2/types/src/beacon_state.rs index aa6690705..6a4033d5c 100644 --- a/eth2/types/src/beacon_state.rs +++ b/eth2/types/src/beacon_state.rs @@ -265,7 +265,7 @@ impl BeaconState { } trace!( - "BeaconState::get_shuffling: active_validator_indices.len() == {}", + "get_shuffling: active_validator_indices.len() == {}", active_validator_indices.len() ); @@ -273,8 +273,9 @@ impl BeaconState { self.get_epoch_committee_count(active_validator_indices.len(), spec); trace!( - "BeaconState::get_shuffling: active_validator_indices.len() == {}, committees_per_epoch: {}", - active_validator_indices.len(), committees_per_epoch + "get_shuffling: active_validator_indices.len() == {}, committees_per_epoch: {}", + active_validator_indices.len(), + committees_per_epoch ); let mut shuffled_active_validator_indices = vec![0; active_validator_indices.len()]; @@ -332,7 +333,7 @@ impl BeaconState { let latest_index_root = current_epoch + spec.entry_exit_delay; trace!( - "BeaconState::get_active_index_root: epoch: {}, earliest: {}, latest: {}", + "get_active_index_root: epoch: {}, earliest: {}, latest: {}", epoch, earliest_index_root, latest_index_root @@ -341,7 +342,7 @@ impl BeaconState { if (epoch >= earliest_index_root) & (epoch <= latest_index_root) { Some(self.latest_index_roots[epoch.as_usize() % spec.latest_index_roots_length]) } else { - trace!("BeaconState::get_active_index_root: epoch out of range."); + trace!("get_active_index_root: epoch out of range."); None } } @@ -386,37 +387,28 @@ impl BeaconState { ) -> Result, u64)>, BeaconStateError> { let epoch = slot.epoch(spec.epoch_length); let current_epoch = self.current_epoch(spec); - let previous_epoch = if current_epoch == spec.genesis_epoch { - current_epoch - } else { - current_epoch.saturating_sub(1_u64) - }; + let previous_epoch = self.previous_epoch(spec); let next_epoch = self.next_epoch(spec); - trace!( - "BeaconState::get_crosslink_committees_at_slot: epoch: {}", - epoch - ); - let (committees_per_epoch, seed, shuffling_epoch, shuffling_start_shard) = - if epoch == previous_epoch { - trace!("BeaconState::get_crosslink_committees_at_slot: epoch == previous_epoch"); - ( - self.get_previous_epoch_committee_count(spec), - self.previous_epoch_seed, - self.previous_calculation_epoch, - self.previous_epoch_start_shard, - ) - } else if epoch == current_epoch { - trace!("BeaconState::get_crosslink_committees_at_slot: epoch == current_epoch"); + if epoch == current_epoch { + trace!("get_crosslink_committees_at_slot: current_epoch"); ( self.get_current_epoch_committee_count(spec), self.current_epoch_seed, self.current_calculation_epoch, self.current_epoch_start_shard, ) + } else if epoch == previous_epoch { + trace!("get_crosslink_committees_at_slot: previous_epoch"); + ( + self.get_previous_epoch_committee_count(spec), + self.previous_epoch_seed, + self.previous_calculation_epoch, + self.previous_epoch_start_shard, + ) } else if epoch == next_epoch { - trace!("BeaconState::get_crosslink_committees_at_slot: epoch == next_epoch"); + trace!("get_crosslink_committees_at_slot: next_epoch"); let current_committees_per_epoch = self.get_current_epoch_committee_count(spec); let epochs_since_last_registry_update = current_epoch - self.validator_registry_update_epoch; @@ -454,9 +446,10 @@ impl BeaconState { (shuffling_start_shard + committees_per_slot * offset) % spec.shard_count; trace!( - "BeaconState::get_crosslink_committees_at_slot: committees_per_slot: {}, slot_start_shard: {}", + "get_crosslink_committees_at_slot: committees_per_slot: {}, slot_start_shard: {}, seed: {}", committees_per_slot, - slot_start_shard + slot_start_shard, + seed ); let mut crosslinks_at_slot = vec![];