Add and update logs

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<AttestationDutyMap> = 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<usize> {
+        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),

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();

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.");
 

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

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)

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<Vec<(Vec<usize>, 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![];