Add more logging around block/attn production

beacon_node/beacon_chain/src/beacon_chain.rs

@@ -9,7 +9,7 @@ use lmd_ghost::LmdGhost;
 use operation_pool::DepositInsertStatus;
 use operation_pool::{OperationPool, PersistedOperationPool};
 use parking_lot::{RwLock, RwLockReadGuard};
-use slog::{error, info, warn, Logger};
+use slog::{error, info, trace, warn, Logger};
 use slot_clock::SlotClock;
 use ssz::Encode;
 use state_processing::per_block_processing::{
@@ -639,6 +639,14 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         metrics::inc_counter(&metrics::ATTESTATION_PRODUCTION_SUCCESSES);
         metrics::stop_timer(timer);
 
+        trace!(
+            self.log,
+            "Produced beacon attestation data";
+            "beacon_block_root" => format!("{}", head_block_root),
+            "shard" => shard,
+            "slot" => state.slot
+        );
+
         Ok(AttestationData {
             beacon_block_root: head_block_root,
             source: state.current_justified_checkpoint.clone(),
@@ -751,7 +759,7 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
             // has a higher slot than the attestation.
             //
             // Permitting this would allow for attesters to vote on _future_ slots.
-            if attestation_slot > state.slot {
+            if state.slot > attestation_slot {
                 Ok(AttestationProcessingOutcome::AttestsToFutureState {
                     state: state.slot,
                     attestation: attestation_slot,
@@ -1270,6 +1278,14 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
         metrics::inc_counter(&metrics::BLOCK_PRODUCTION_SUCCESSES);
         metrics::stop_timer(timer);
 
+        trace!(
+            self.log,
+            "Produced beacon block";
+            "parent" => format!("{}", block.parent_root),
+            "attestations" => block.body.attestations.len(),
+            "slot" => block.slot
+        );
+
         Ok((block, state))
     }
 
@@ -1307,7 +1323,10 @@ impl<T: BeaconChainTypes> BeaconChain<T> {
                 warn!(
                     self.log,
                     "Beacon chain re-org";
+                    "previous_head" => format!("{}", self.head().beacon_block_root),
                     "previous_slot" => previous_slot,
+                    "new_head_parent" => format!("{}", beacon_block.parent_root),
+                    "new_head" => format!("{}", beacon_block_root),
                     "new_slot" => new_slot
                 );
             } else {

validator_client/src/attestation_producer/mod.rs

@@ -50,9 +50,12 @@ impl<'a, B: BeaconNodeAttestation, S: Signer, E: EthSpec> AttestationProducer<'a
     /// Handle outputs and results from attestation production.
     pub fn handle_produce_attestation(&mut self, log: slog::Logger) {
         match self.produce_attestation() {
-            Ok(ValidatorEvent::AttestationProduced(_slot)) => {
+            Ok(ValidatorEvent::AttestationProduced(slot)) => info!(
-                info!(log, "Attestation produced"; "Validator" => format!("{}", self.signer))
+                log,
-            }
+                "Attestation produced";
+                "validator" => format!("{}", self.signer),
+                "slot" => slot,
+            ),
             Err(e) => error!(log, "Attestation production error"; "Error" => format!("{:?}", e)),
             Ok(ValidatorEvent::SignerRejection(_slot)) => {
                 error!(log, "Attestation production error"; "Error" => "Signer could not sign the attestation".to_string())

validator_client/src/block_producer/mod.rs

@@ -59,9 +59,12 @@ impl<'a, B: BeaconNodeBlock, S: Signer, E: EthSpec> BlockProducer<'a, B, S, E> {
     /// Handle outputs and results from block production.
     pub fn handle_produce_block(&mut self, log: slog::Logger) {
         match self.produce_block() {
-            Ok(ValidatorEvent::BlockProduced(_slot)) => {
+            Ok(ValidatorEvent::BlockProduced(slot)) => info!(
-                info!(log, "Block produced"; "Validator" => format!("{}", self.signer))
+                log,
-            }
+                "Block produced";
+                "validator" => format!("{}", self.signer),
+                "slot" => slot,
+            ),
             Err(e) => error!(log, "Block production error"; "Error" => format!("{:?}", e)),
             Ok(ValidatorEvent::SignerRejection(_slot)) => {
                 error!(log, "Block production error"; "Error" => "Signer Could not sign the block".to_string())
@@ -105,12 +108,13 @@ impl<'a, B: BeaconNodeBlock, S: Signer, E: EthSpec> BlockProducer<'a, B, S, E> {
             .produce_beacon_block(self.slot, &randao_reveal)?
         {
             if self.safe_to_produce(&block) {
+                let slot = block.slot;
                 let domain = self
                     .spec
                     .get_domain(epoch, Domain::BeaconProposer, &self.fork);
                 if let Some(block) = self.sign_block(block, domain) {
                     self.beacon_node.publish_beacon_block(block)?;
-                    Ok(ValidatorEvent::BlockProduced(self.slot))
+                    Ok(ValidatorEvent::BlockProduced(slot))
                 } else {
                     Ok(ValidatorEvent::SignerRejection(self.slot))
                 }

validator_client/src/service.rs

@@ -359,7 +359,12 @@ impl<B: BeaconNodeDuties + 'static, S: Signer + 'static, E: EthSpec> Service<B,
                     let log = self.log.clone();
                     let slots_per_epoch = self.slots_per_epoch;
                     std::thread::spawn(move || {
-                        info!(log, "Producing a block"; "Validator"=> format!("{}", signers[signer_index]));
+                        info!(
+                            log,
+                            "Producing a block";
+                            "validator"=> format!("{}", signers[signer_index]),
+                            "slot"=> slot
+                        );
                         let signer = &signers[signer_index];
                         let mut block_producer = BlockProducer {
                             fork,
@@ -376,6 +381,9 @@ impl<B: BeaconNodeDuties + 'static, S: Signer + 'static, E: EthSpec> Service<B,
                 if work_type.attestation_duty.is_some() {
                     // we need to produce an attestation
                     // spawns a thread to produce and sign an attestation
+                    let slot = self
+                        .current_slot
+                        .expect("The current slot must be updated before processing duties");
                     let signers = self.duties_manager.signers.clone(); // this is an arc
                     let fork = self.fork.clone();
                     let spec = self.spec.clone();
@@ -383,7 +391,12 @@ impl<B: BeaconNodeDuties + 'static, S: Signer + 'static, E: EthSpec> Service<B,
                     let log = self.log.clone();
                     let slots_per_epoch = self.slots_per_epoch;
                     std::thread::spawn(move || {
-                        info!(log, "Producing an attestation"; "Validator"=> format!("{}", signers[signer_index]));
+                        info!(
+                            log,
+                            "Producing an attestation";
+                            "validator"=> format!("{}", signers[signer_index]),
+                            "slot"=> slot
+                        );
                         let signer = &signers[signer_index];
                         let mut attestation_producer = AttestationProducer {
                             fork,