Add more logging for validator duties

validator_client/src/block_service.rs

@@ -3,7 +3,7 @@ use environment::RuntimeContext;
 use exit_future::Signal;
 use futures::{stream, Future, IntoFuture, Stream};
 use remote_beacon_node::{PublishStatus, RemoteBeaconNode};
-use slog::{crit, info};
+use slog::{crit, error, info, trace};
 use slot_clock::SlotClock;
 use std::ops::Deref;
 use std::sync::Arc;
@@ -159,17 +159,34 @@ impl<T: SlotClock + 'static, E: EthSpec> BlockService<T, E> {
     /// Attempt to produce a block for any block producers in the `ValidatorStore`.
     fn do_update(self) -> impl Future<Item = (), Error = ()> {
         let service = self.clone();
-        let log = self.context.log.clone();
+        let log_1 = self.context.log.clone();
+        let log_2 = self.context.log.clone();
 
         self.slot_clock
             .now()
             .ok_or_else(move || {
-                crit!(log, "Duties manager failed to read slot clock");
+                crit!(log_1, "Duties manager failed to read slot clock");
             })
             .into_future()
             .and_then(move |slot| {
                 let iter = service.duties_service.block_producers(slot).into_iter();
 
+                if iter.len() == 0 {
+                    trace!(
+                        log_2,
+                        "No local block proposers for this slot";
+                        "slot" => slot.as_u64()
+                    )
+                } else if iter.len() > 1 {
+                    error!(
+                        log_2,
+                        "Multiple block proposers for this slot";
+                        "action" => "producing blocks for all proposers",
+                        "num_proposers" => iter.len(),
+                        "slot" => slot.as_u64(),
+                    )
+                }
+
                 stream::unfold(iter, move |mut block_producers| {
                     let log_1 = service.context.log.clone();
                     let log_2 = service.context.log.clone();

validator_client/src/duties_service.rs

@@ -23,8 +23,10 @@ type BaseHashMap = HashMap<PublicKey, HashMap<Epoch, ValidatorDuty>>;
 
 /// The outcome of inserting some `ValidatorDuty` into the `DutiesStore`.
 enum InsertOutcome {
-    /// The duties were previously unknown and have been stored.
-    New,
+    /// These are the first duties received for this validator.
+    NewValidator,
+    /// The duties for this given epoch were previously unknown and have been stored.
+    NewEpoch,
     /// The duties were identical to some already in the store.
     Identical,
     /// There were duties for this validator and epoch in the store that were different to the ones
@@ -107,7 +109,7 @@ impl DutiesStore {
             } else {
                 validator_map.insert(epoch, duties);
 
-                InsertOutcome::New
+                InsertOutcome::NewEpoch
             }
         } else {
             let validator_pubkey = duties.validator_pubkey.clone();
@@ -117,7 +119,7 @@ impl DutiesStore {
 
             store.insert(validator_pubkey, validator_map);
 
-            InsertOutcome::New
+            InsertOutcome::NewValidator
         }
     }
 
@@ -354,14 +356,30 @@ impl<T: SlotClock + 'static, E: EthSpec> DutiesService<T, E> {
             .map(move |all_duties| (epoch, all_duties))
             .map_err(move |e| format!("Failed to get duties for epoch {}: {:?}", epoch, e))
             .map(move |(epoch, all_duties)| {
-                let mut new = 0;
+                let log = service_2.context.log.clone();
+
+                let mut new_validator = 0;
+                let mut new_epoch = 0;
                 let mut identical = 0;
                 let mut replaced = 0;
                 let mut invalid = 0;
 
                 all_duties.into_iter().for_each(|duties| {
-                    match service_2.store.insert(epoch, duties, E::slots_per_epoch()) {
-                        InsertOutcome::New => new += 1,
+                    match service_2
+                        .store
+                        .insert(epoch, duties.clone(), E::slots_per_epoch())
+                    {
+                        InsertOutcome::NewValidator => {
+                            info!(
+                                log,
+                                "First duty assignment for validator";
+                                "proposal_slot" => format!("{:?}", &duties.block_proposal_slot),
+                                "attestation_slot" => format!("{:?}", &duties.attestation_slot),
+                                "validator" => format!("{:?}", &duties.validator_pubkey)
+                            );
+                            new_validator += 1
+                        }
+                        InsertOutcome::NewEpoch => new_epoch += 1,
                         InsertOutcome::Identical => identical += 1,
                         InsertOutcome::Replaced => replaced += 1,
                         InsertOutcome::Invalid => invalid += 1,
@@ -370,7 +388,7 @@ impl<T: SlotClock + 'static, E: EthSpec> DutiesService<T, E> {
 
                 if invalid > 0 {
                     error!(
-                        service_2.context.log,
+                        log,
                         "Received invalid duties from beacon node";
                         "bad_duty_count" => invalid,
                         "info" => "Duties are from wrong epoch."
@@ -378,17 +396,18 @@ impl<T: SlotClock + 'static, E: EthSpec> DutiesService<T, E> {
                 }
 
                 trace!(
-                    service_2.context.log,
+                    log,
                     "Performed duties update";
-                    "replaced_duties" => replaced,
-                    "identical_duties" => identical,
-                    "new_duties" => new,
+                    "identical" => identical,
+                    "new_epoch" => new_epoch,
+                    "new_validator" => new_validator,
+                    "replaced" => replaced,
                     "epoch" => format!("{}", epoch)
                 );
 
                 if replaced > 0 {
                     warn!(
-                        service_2.context.log,
+                        log,
                         "Duties changed during routine update";
                         "info" => "Chain re-org likely occurred."
                     )