Logging improvements

anchor/client/src/lib.rs

@@ -693,7 +693,7 @@ async fn init_from_beacon_node<E: EthSpec>(
                     .filter_map(|(_, e)| e.request_failure())
                     .any(|e| e.status() == Some(eth2::StatusCode::NOT_FOUND))
                 {
-                    info!("Waiting for genesis",);
+                    info!("Waiting for genesis");
                 } else {
                     error!(
                         error = ?errors.0,

anchor/common/qbft/Cargo.toml

@@ -12,6 +12,7 @@ arbitrary = { workspace = true, optional = true }
 derive_more = { workspace = true }
 ethereum_ssz = { workspace = true }
 ethereum_ssz_derive = { workspace = true }
+hex = { workspace = true }
 indexmap = { workspace = true }
 sha2 = { workspace = true }
 ssv_types = { workspace = true }

anchor/common/qbft/src/lib.rs

@@ -274,13 +274,20 @@ where
         let data = match D::from_ssz_bytes(wrapped_msg.signed_message.full_data()) {
             Ok(data) => data,
             _ => {
-                warn!(in = ?self.config.operator_id(), "Invalid data");
+                error!(
+                    msg = %wrapped_msg,
+                    "Invalid full data received",
+                );
+                debug!(
+                    full_data = hex::encode(wrapped_msg.signed_message.full_data()),
+                    "Raw invalid full data",
+                );
                 return None;
             }
         };
 
         if !data.validate() {
-            warn!(in = ?self.config.operator_id(), "Data failed validation");
+            warn!("Data failed validation");
             return None;
         }
 
@@ -338,13 +345,13 @@ where
 
     // Handles the beginning of a round.
     fn start_round(&mut self) {
-        debug!(self=?self.config.operator_id(), round = *self.current_round, "Starting new round");
-
         // We are waiting for consensus on a round change, do not start the round yet
         if matches!(self.state, InstanceState::SentRoundChange) {
             return;
         }
 
+        debug!(round = *self.current_round, "Starting new round");
+
         // Initialise the instance state for the round
         self.state = InstanceState::AwaitingProposal;
 
@@ -358,7 +365,7 @@ where
                 .justify_round_change_quorum()
                 .unwrap_or_else(|| self.valid_start_data.clone());
 
-            debug!(operator_id = ?self.config.operator_id(), hash = ?valid_data.hash, data = ?valid_data.data, "Current leader proposing data");
+            debug!(hash = ?valid_data.hash, data = ?valid_data.data, "Current leader proposing data");
 
             // Send the initial proposal and then the following prepare
             self.send_proposal(valid_data.hash, valid_data.data.expect("Start data exists"));
@@ -403,28 +410,28 @@ where
     ) {
         // Make sure that we are actually waiting for a proposal
         if !matches!(self.state, InstanceState::AwaitingProposal) {
-            debug!(from=?operator_id, self=?self.config.operator_id(), ?self.state, "PROPOSE message while in invalid state");
+            debug!(from=?operator_id, ?self.state, "PROPOSE message while in invalid state");
             return;
         }
 
         // If we are passed the first round, make sure that the justifications actually justify the
         // received proposal
         if round > Round::default() && !self.validate_justifications(&wrapped_msg) {
-            warn!(from = ?operator_id, self=?self.config.operator_id(), "Justification verifiction failed");
+            warn!(from = ?operator_id, "Justification verifiction failed");
             return;
         }
 
         // Fulldata is included in propose messages
         let data = match valid_data.data {
             Some(data) => data,
             None => {
-                warn!(from = ?operator_id, self=?self.config.operator_id(), "Proposal should contain data");
+                warn!(from = ?operator_id, "Proposal should contain data");
                 return;
             }
         };
         self.data.insert(valid_data.hash, data);
 
-        debug!(from = ?operator_id, in = ?self.config.operator_id(), state = ?self.state, "PROPOSE received");
+        debug!(from = ?operator_id, state = ?self.state, "PROPOSE received");
 
         // Store the received propse message
         if !self
@@ -437,7 +444,7 @@ where
 
         // Make sure we have not already accepted another proposal for this round.
         if self.proposal_accepted_for_current_round {
-            warn!(from = ?operator_id, self=?self.config.operator_id(), "Proposal has already been accepted for this round");
+            warn!(from = ?operator_id, "Proposal has already been accepted for this round");
             return;
         }
 
@@ -447,7 +454,7 @@ where
         self.state = InstanceState::Prepare {
             proposal_root: valid_data.hash,
         };
-        debug!(in = ?self.config.operator_id(), state = ?self.state, "State updated to PREPARE");
+        debug!(state = ?self.state, "State updated to PREPARE");
 
         // Create and send prepare message
         self.send_prepare(wrapped_msg.qbft_message.root);
@@ -588,17 +595,17 @@ where
             wrapped_msg.qbft_message.qbft_message_type,
             QbftMessageType::Prepare,
         )) {
-            warn!(from=?operator_id, self=?self.config.operator_id(), "Expected a PREPARE message");
+            warn!(from=?operator_id, "Expected a PREPARE message");
             return;
         }
 
         // Make sure that we have accepted a proposal for this round
         if !self.proposal_accepted_for_current_round {
-            warn!(from=?operator_id, ?self.state, self=?self.config.operator_id(), "Have not accepted Proposal for current round yet");
+            debug!(from=?operator_id, ?self.state, "Have not accepted Proposal for current round yet");
             return;
         }
 
-        debug!(from = ?operator_id, self = ?self.config.operator_id(), state = ?self.state, "PREPARE received");
+        debug!(from = ?operator_id, state = ?self.state, "PREPARE received");
 
         // Store the prepare message
         if !self
@@ -614,7 +621,7 @@ where
             let proposal_root = match self.state {
                 InstanceState::Prepare { proposal_root } => proposal_root,
                 _ => {
-                    warn!(from=?operator_id, ?self.state, "Not in PREPARE state");
+                    debug!(from=?operator_id, ?self.state, "Not in PREPARE state");
                     return;
                 }
             };
@@ -630,7 +637,7 @@ where
 
             // Move the state forward since we have a prepare quorum
             self.state = InstanceState::Commit { proposal_root };
-            debug!(in = ?self.config.operator_id(), state = ?self.state, "Reached a PREPARE consensus. State updated to COMMIT");
+            debug!(state = ?self.state, "Reached a PREPARE consensus. State updated to COMMIT");
 
             // Record that we have come to a consensus on this value
             self.past_consensus.insert(round, hash);
@@ -667,17 +674,17 @@ where
             wrapped_msg.qbft_message.qbft_message_type,
             QbftMessageType::Commit,
         )) {
-            warn!(from=?operator_id, self=?self.config.operator_id(), "Expected a COMMIT message");
+            warn!(from=?operator_id, "Expected a COMMIT message");
             return;
         }
 
         // Make sure that we have accepted a proposal for this round
         if !self.proposal_accepted_for_current_round {
-            warn!(from=?operator_id, ?self.state, self=?self.config.operator_id(), "Have not accepted Proposal for current round yet");
+            warn!(from=?operator_id, ?self.state, "Have not accepted Proposal for current round yet");
             return;
         }
 
-        debug!(from = ?operator_id, in = ?self.config.operator_id(), state = ?self.state, "COMMIT received");
+        debug!(from = ?operator_id, state = ?self.state, "COMMIT received");
 
         // Store the received commit message
         if !self
@@ -707,7 +714,7 @@ where
             let commit_quorum = self.commit_container.get_quorum_of_messages(round);
             let aggregated_commit = self.aggregate_commit_messages(commit_quorum);
             if aggregated_commit.is_some() {
-                debug!(in = ?self.config.operator_id(), state = ?self.state, "Reached a COMMIT consensus. Success!");
+                debug!(state = ?self.state, "Reached a COMMIT consensus. Success!");
                 self.aggregated_commit = aggregated_commit;
                 self.state = InstanceState::Complete;
                 self.completed = Some(Completed::Success(hash));
@@ -763,7 +770,7 @@ where
             return;
         }
 
-        debug!(from = ?operator_id, in = ?self.config.operator_id(), state = ?self.state, "ROUNDCHANGE received");
+        debug!(from = ?operator_id, state = ?self.state, "ROUNDCHANGE received");
 
         // Store the round changed message
         if !self
@@ -780,11 +787,7 @@ where
             if matches!(self.state, InstanceState::SentRoundChange) {
                 // If we have reached a quorum for this round and have already sent a round change,
                 // advance to that round.
-                debug!(
-                    operator_id = ?self.config.operator_id(),
-                    round = *round,
-                    "Round change quorum reached"
-                );
+                debug!(round = *round, "Round change quorum reached");
 
                 // We have reached consensus on a round change, we can start a new round now
                 self.state = InstanceState::RoundChangeConsensus;
@@ -824,7 +827,7 @@ where
 
     // End the current round and move to the next one, if possible.
     pub fn end_round(&mut self) {
-        debug!(self=?self.config.operator_id(), round = *self.current_round, "Incrementing round");
+        debug!(round = *self.current_round, "Incrementing round");
         let Some(next_round) = self.current_round.next() else {
             self.state = InstanceState::Complete;
             self.completed = Some(Completed::TimedOut);

anchor/common/qbft/src/qbft_types.rs

@@ -1,5 +1,9 @@
 //! A collection of types used by the QBFT modules
-use std::{cmp::Eq, fmt::Debug, hash::Hash};
+use std::{
+    cmp::Eq,
+    fmt::{Debug, Display, Formatter},
+    hash::Hash,
+};
 
 use derive_more::{Deref, From};
 use indexmap::IndexSet;
@@ -50,6 +54,19 @@ pub struct WrappedQbftMessage {
     pub qbft_message: QbftMessage,
 }
 
+// This impl is meant for displaying messages in debug logs, where we usually do not need to know,
+// e.g., the exact byte values of signatures. The `Debug` impl remains fully featured for tracing
+// logs or other special cases.
+impl Display for WrappedQbftMessage {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        let mut f = f.debug_struct("WrappedQbftMessage");
+        f.field("operator_ids", self.signed_message.operator_ids())
+            .field("full_data", &!self.signed_message.full_data().is_empty());
+        self.qbft_message.format_fields(&mut f);
+        f.finish()
+    }
+}
+
 // Wrapped qbft message is a wrapper around both an unsigned ssv message, and the underlying qbft
 // message.
 #[derive(Debug, Clone)]

anchor/common/qbft/src/tests.rs

@@ -15,6 +15,7 @@ use ssv_types::{
     message::{RSA_SIGNATURE_SIZE, SignedSSVMessage},
 };
 use ssz_derive::{Decode, Encode};
+use tracing::debug_span;
 use tracing_subscriber::filter::EnvFilter;
 use types::Hash256;
 
@@ -166,12 +167,14 @@ impl<D: QbftData<Hash = Hash256>, S: FnMut(UnsignedWrappedQbftMessage)> TestQBFT
 
             // Only receive messages for active instances
             for id in self.active_instances.iter() {
+                let span = debug_span!("receive", self = ?id);
+
                 // We do not make sure that id != sender since we want to loop back and receive our
                 // own messages
                 let instance = self.instances.get_mut(id).expect("Instance exists");
 
                 let wrapped = convert_unsigned_to_signed(msg.clone(), sender);
-                instance.receive(wrapped);
+                span.in_scope(|| instance.receive(wrapped));
             }
         }
     }

anchor/common/ssv_types/src/consensus.rs

@@ -1,5 +1,5 @@
 use std::{
-    fmt::{Debug, Formatter},
+    fmt::{Debug, DebugStruct, Display, Formatter},
     hash::Hash,
     ops::Deref,
 };
@@ -49,7 +49,7 @@ pub struct UnsignedSSVMessage {
 }
 
 /// A QBFT specific message
-#[derive(Clone, Encode, Decode)]
+#[derive(Debug, Clone, Encode, Decode)]
 #[cfg_attr(feature = "arbitrary-fuzz", derive(arbitrary::Arbitrary))]
 pub struct QbftMessage {
     pub qbft_message_type: QbftMessageType,
@@ -63,21 +63,27 @@ pub struct QbftMessage {
     pub prepare_justification: Vec<SignedSSVMessage>,      // always without full_data
 }
 
-impl Debug for QbftMessage {
+impl Display for QbftMessage {
     fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
-        f.debug_struct("QbftMessage")
-            .field("qbft_message_type", &self.qbft_message_type)
+        let mut f = f.debug_struct("QbftMessage");
+        self.format_fields(&mut f);
+        f.finish()
+    }
+}
+
+impl QbftMessage {
+    pub fn format_fields(&self, f: &mut DebugStruct<'_, '_>) {
+        f.field("qbft_message_type", &self.qbft_message_type)
             .field("height", &self.height)
             .field("round", &self.round)
-            .field("identifier", &hex::encode(self.identifier.deref()))
+            .field("msg_id", &hex::encode(self.identifier.deref()))
             .field("root", &self.root)
             .field("data_round", &self.data_round)
             .field(
                 "round_change_justification",
-                &self.round_change_justification,
+                &self.round_change_justification.len(),
             )
-            .field("prepare_justification", &self.prepare_justification)
-            .finish()
+            .field("prepare_justification", &self.prepare_justification.len());
     }
 }
 

anchor/common/ssv_types/src/message.rs

@@ -1,6 +1,6 @@
 use std::{
     collections::HashSet,
-    fmt::{Debug, Formatter},
+    fmt::{Debug, Display, Formatter},
 };
 
 use ssz::{Decode, DecodeError, Encode};
@@ -330,6 +330,20 @@ impl<'a> Arbitrary<'a> for SignedSSVMessage {
     }
 }
 
+// This impl is meant for displaying messages in debug logs, where we usually do not need to know,
+// e.g., the exact byte values of signatures. The `Debug` impl remains fully featured for tracing
+// logs or other special cases.
+impl Display for SignedSSVMessage {
+    fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+        f.debug_struct("SignedSSVMessage")
+            .field("signatures", &self.signatures.len())
+            .field("operator_ids", &self.operator_ids)
+            .field("ssv_message", &self.ssv_message)
+            .field("full_data", &!self.full_data.is_empty())
+            .finish()
+    }
+}
+
 impl Debug for SignedSSVMessage {
     fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
         let signatures = self.signatures.iter().map(hex::encode).collect::<Vec<_>>();

anchor/duties_tracker/src/duties_tracker.rs

@@ -9,7 +9,7 @@ use ssv_types::ValidatorIndex;
 use task_executor::TaskExecutor;
 use thiserror::Error;
 use tokio::{sync::watch, time::sleep};
-use tracing::{debug, error, info, trace, warn};
+use tracing::{debug, error, trace, warn};
 use types::{ChainSpec, Epoch, Slot};
 
 use crate::{Duties, DutiesProvider, voluntary_exit_tracker::VoluntaryExitTracker};
@@ -175,7 +175,7 @@ impl<T: SlotClock + 'static> DutiesTracker<T> {
 
         // Insert only validators that have duties
         for duty in duties {
-            info!(
+            debug!(
                 validator_index = duty.validator_index,
                 sync_committee_period, "Validator in sync committee"
             );