From 0f51e691e0b6d3316b5f258200167ab838cd8c6d Mon Sep 17 00:00:00 2001 From: elliedavidson <118024407+elliedavidson@users.noreply.github.com> Date: Thu, 10 Aug 2023 13:12:39 -0400 Subject: [PATCH 1/2] Reduce logging more --- src/lib.rs | 2 +- src/traits/election/static_committee.rs | 4 +- src/traits/networking/web_server_network.rs | 17 +++----- task-impls/src/consensus.rs | 48 ++++++++++----------- task-impls/src/da.rs | 18 ++++---- task-impls/src/view_sync.rs | 18 ++++---- task/src/event_stream.rs | 2 +- types/src/certificate.rs | 4 +- web_server/src/lib.rs | 11 ++--- 9 files changed, 61 insertions(+), 63 deletions(-) diff --git a/src/lib.rs b/src/lib.rs index ea0ac2b7dc..d491930543 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -197,7 +197,7 @@ impl> SystemContext, metrics: Box, ) -> Result> { - info!("Creating a new hotshot"); + debug!("Creating a new hotshot"); let consensus_metrics = Arc::new(ConsensusMetrics::new( &*metrics.subgroup("consensus".to_string()), diff --git a/src/traits/election/static_committee.rs b/src/traits/election/static_committee.rs index 3f19477479..b964e1eb4f 100644 --- a/src/traits/election/static_committee.rs +++ b/src/traits/election/static_committee.rs @@ -14,7 +14,7 @@ use jf_primitives::signatures::BLSSignatureScheme; use serde::{Deserialize, Serialize}; use std::marker::PhantomData; use std::num::NonZeroU64; -use tracing::info; +use tracing::debug; /// Dummy implementation of [`Membership`] @@ -154,7 +154,7 @@ where fn create_election(keys: Vec, config: TYPES::ElectionConfigType) -> Self { let mut committee_nodes = keys.clone(); committee_nodes.truncate(config.num_nodes.try_into().unwrap()); - info!("Election Membership Size: {}", config.num_nodes); + debug!("Election Membership Size: {}", config.num_nodes); Self { nodes: keys, committee_nodes, diff --git a/src/traits/networking/web_server_network.rs b/src/traits/networking/web_server_network.rs index 552a2c74e3..fe001b4554 100644 --- a/src/traits/networking/web_server_network.rs +++ b/src/traits/networking/web_server_network.rs @@ -53,7 +53,7 @@ use std::{ time::Duration, }; use surf_disco::error::ClientError; -use tracing::{debug, error, info, warn}; +use tracing::{debug, error, info}; /// Represents the communication channel abstraction for the web server #[derive(Clone, Debug)] pub struct WebCommChannel< @@ -182,7 +182,7 @@ impl { - // warn!( - // "Received proposal from web server for view {} {}", - // view_number, self.is_da - // ); + // Only pushing the first proposal since we will soon only be allowing 1 proposal per view self.broadcast_poll_queue .write() @@ -266,7 +263,7 @@ impl { - warn!( + debug!( "Received DAC from web server for view {} {}", view_number, self.is_da ); @@ -335,7 +332,7 @@ impl { if view_number == event_view { - warn!("Shutting down polling task for view {}", event_view); + debug!("Shutting down polling task for view {}", event_view); return Ok(()); } } @@ -346,7 +343,7 @@ impl { - warn!("QCFormed! {:?}", qc.view_number); + debug!("QCFormed! {:?}", qc.view_number); state .event_stream .publish(SequencingHotShotEvent::QCFormed(qc.clone())) @@ -384,7 +384,7 @@ where ); if let GeneralConsensusMessage::Vote(vote) = message { - warn!( + debug!( "Sending vote to next quorum leader {:?}", vote.current_view() ); @@ -464,7 +464,7 @@ where // TODO ED Only publish event in vote if able if let GeneralConsensusMessage::Vote(vote) = message { - warn!( + debug!( "Sending vote to next quorum leader {:?}", vote.current_view() ); @@ -476,13 +476,13 @@ where } } } - warn!( + debug!( "Couldn't find DAC cert in certs, meaning we haven't received it yet for view {:?}", *proposal.get_view_number(), ); return false; } - warn!( + debug!( "Could not vote because we don't have a proposal yet for view {}", *self.cur_view ); @@ -494,7 +494,7 @@ where async fn update_view(&mut self, new_view: ViewNumber) -> bool { if *self.cur_view < *new_view { - warn!( + debug!( "Updating view from {} to {} in consensus task", *self.cur_view, *new_view ); @@ -522,7 +522,7 @@ where .await; if self.quorum_exchange.is_leader(self.cur_view + 1) { - warn!("Polling for quorum votes for view {}", *self.cur_view); + debug!("Polling for quorum votes for view {}", *self.cur_view); self.quorum_exchange .network() .inject_consensus_info(ConsensusIntentEvent::PollForVotes(*self.cur_view)) @@ -856,7 +856,7 @@ where .outstanding_transactions_memory_size .update(-(i64::try_from(included_txn_size).unwrap_or(i64::MAX))); - warn!("about to publish decide"); + debug!("about to publish decide"); let decide_sent = self.output_event_stream.publish(Event { view_number: consensus.last_decided_view, event: EventType::Decide { @@ -917,7 +917,7 @@ where self.update_view(new_view).await; if let GeneralConsensusMessage::Vote(vote) = message { - info!("Sending vote to next leader {:?}", vote); + debug!("Sending vote to next leader {:?}", vote); // warn!("Vote is {:?}", vote.current_view()); // self.event_stream @@ -928,7 +928,7 @@ where } } SequencingHotShotEvent::QuorumVoteRecv(vote) => { - warn!("Received quroum vote: {:?}", vote.current_view()); + debug!("Received quroum vote: {:?}", vote.current_view()); if !self.quorum_exchange.is_leader(vote.current_view() + 1) { error!( @@ -1010,7 +1010,7 @@ where let _task = async_spawn(async move { VoteCollectionTypes::build(builder).launch().await; }); - warn!("Starting vote handle for view {:?}", vote.current_view); + debug!("Starting vote handle for view {:?}", vote.current_view); } else if let Some((_, _, stream_id)) = self.vote_collector { self.event_stream .direct_message( @@ -1026,7 +1026,7 @@ where } } SequencingHotShotEvent::QCFormed(qc) => { - warn!("QC Formed event happened!"); + debug!("QC Formed event happened!"); let mut consensus = self.consensus.write().await; consensus.high_qc = qc.clone(); @@ -1058,7 +1058,7 @@ where // warn!("Handle qc formed event!"); // TODO ED Why isn't cur view correct here? // // So we don't create a QC on the first view unless we are the leader - warn!( + debug!( "Attempting to publish proposal after forming a QC for view {}", *qc.view_number ); @@ -1068,7 +1068,7 @@ where } } SequencingHotShotEvent::DACRecv(cert) => { - warn!("DAC Recved for view ! {}", *cert.view_number); + debug!("DAC Recved for view ! {}", *cert.view_number); let view = cert.view_number; self.certs.insert(view, cert); @@ -1084,7 +1084,7 @@ where } SequencingHotShotEvent::ViewChange(new_view) => { - warn!("View Change event for view {}", *new_view); + debug!("View Change event for view {}", *new_view); let old_view_number = self.cur_view; @@ -1144,7 +1144,7 @@ where let mut next_parent_hash = original_parent_hash; if !reached_decided { - warn!("not reached decide fro view {:?}", self.cur_view); + debug!("not reached decide fro view {:?}", self.cur_view); while let Some(next_parent_leaf) = consensus.saved_leaves.get(&next_parent_hash) { if next_parent_leaf.view_number <= consensus.last_decided_view { @@ -1153,7 +1153,7 @@ where next_parent_hash = next_parent_leaf.parent_commitment; } // TODO do some sort of sanity check on the view number that it matches decided - warn!("updated saved leaves"); + debug!("updated saved leaves"); } let block_commitment = self.block.commit(); @@ -1186,8 +1186,8 @@ where data: proposal, signature, }; - // warn!("Sending proposal for view {:?} \n {:?}", self.cur_view, message.clone()); - warn!("Sending proposal for view {:?}", message.data.clone()); + // debug!("Sending proposal for view {:?} \n {:?}", self.cur_view, message.clone()); + debug!("Sending proposal for view {:?}", message.data.clone()); self.event_stream .publish(SequencingHotShotEvent::QuorumProposalSend( @@ -1210,7 +1210,7 @@ where } SequencingHotShotEvent::SendDABlockData(block) => { // ED TODO Should make sure this is actually the most recent block - // warn!("Updating self . block!"); + // debug!("Updating self . block!"); self.block = block; } _ => {} @@ -1267,20 +1267,20 @@ where // Walk back until we find a decide if !reached_decided { - warn!("not reached decide fro view {:?}", self.cur_view); + debug!("not reached decide fro view {:?}", self.cur_view); while let Some(next_parent_leaf) = consensus.saved_leaves.get(&next_parent_hash) { if next_parent_leaf.view_number <= consensus.last_decided_view { break; } next_parent_hash = next_parent_leaf.parent_commitment; } - warn!("updated saved leaves"); + debug!("updated saved leaves"); // TODO do some sort of sanity check on the view number that it matches decided } let block_commitment = self.block.commit(); if block_commitment == TYPES::BlockType::new().commit() { - warn!("Block is generic block! {:?}", self.cur_view); + debug!("Block is generic block! {:?}", self.cur_view); } // warn!( // "leaf commitment of new qc: {:?}", diff --git a/task-impls/src/da.rs b/task-impls/src/da.rs index d0b65c1047..2e410e81ac 100644 --- a/task-impls/src/da.rs +++ b/task-impls/src/da.rs @@ -150,12 +150,12 @@ where { match event { SequencingHotShotEvent::DAVoteRecv(vote) => { - warn!("DA vote recv, collection task {:?}", vote.current_view); + debug!("DA vote recv, collection task {:?}", vote.current_view); // panic!("Vote handle received DA vote for view {}", *vote.current_view); // For the case where we receive votes after we've made a certificate if state.accumulator.is_right() { - warn!("DA accumulator finished view: {:?}", state.cur_view); + debug!("DA accumulator finished view: {:?}", state.cur_view); return (None, state); } @@ -172,11 +172,11 @@ where ) { Left(acc) => { state.accumulator = Either::Left(acc); - // warn!("Not enough DA votes! "); + // debug!("Not enough DA votes! "); return (None, state); } Right(dac) => { - warn!("Sending DAC! {:?}", dac.view_number); + debug!("Sending DAC! {:?}", dac.view_number); state .event_stream .publish(SequencingHotShotEvent::DACSend( @@ -260,7 +260,7 @@ where return None; } SequencingHotShotEvent::DAProposalRecv(proposal, sender) => { - warn!( + debug!( "DA proposal received for view: {:?}", proposal.data.get_view_number() ); @@ -312,7 +312,7 @@ where // self.cur_view = view; if let CommitteeConsensusMessage::DAVote(vote) = message { - warn!("Sending vote to the DA leader {:?}", vote.current_view); + debug!("Sending vote to the DA leader {:?}", vote.current_view); self.event_stream .publish(SequencingHotShotEvent::DAVoteSend(vote)) .await; @@ -432,7 +432,7 @@ where .contains(self.committee_exchange.public_key()); if is_da { - warn!("Polling for DA proposals for view {}", *self.cur_view + 1); + debug!("Polling for DA proposals for view {}", *self.cur_view + 1); self.committee_exchange .network() .inject_consensus_info(ConsensusIntentEvent::PollForProposal( @@ -441,7 +441,7 @@ where .await; } if self.committee_exchange.is_leader(self.cur_view + 3) { - warn!("Polling for transactions for view {}", *self.cur_view + 3); + debug!("Polling for transactions for view {}", *self.cur_view + 3); self.committee_exchange .network() .inject_consensus_info(ConsensusIntentEvent::PollForTransactions( @@ -519,7 +519,7 @@ where // Upon entering a new view we want to send a DA Proposal for the next view -> Is it always the case that this is cur_view + 1? view_number: self.cur_view + 1, }; - warn!("Sending DA proposal for view {:?}", data.view_number); + debug!("Sending DA proposal for view {:?}", data.view_number); // let message = SequencingMessage::(Right( // CommitteeConsensusMessage::DAProposal(Proposal { data, signature }), diff --git a/task-impls/src/view_sync.rs b/task-impls/src/view_sync.rs index d79caa52cf..3f39a6c594 100644 --- a/task-impls/src/view_sync.rs +++ b/task-impls/src/view_sync.rs @@ -42,7 +42,7 @@ use snafu::Snafu; use std::collections::HashMap; use std::sync::Arc; use std::time::Duration; -use tracing::{debug, error, instrument, warn}; +use tracing::{debug, error, instrument}; #[derive(PartialEq, PartialOrd, Clone, Debug, Eq, Hash)] pub enum ViewSyncPhase { @@ -267,7 +267,7 @@ where // This certificate is old, we can throw it away // If next view = cert round, then that means we should already have a task running for it if self.current_view > certificate_internal.round { - warn!("Already in a higher view than the view sync message"); + debug!("Already in a higher view than the view sync message"); return; } @@ -360,7 +360,7 @@ where .is_leader(vote_internal.round + vote_internal.relay) { // This will occur because everyone is pulling down votes for now, will fix soon ED - warn!("View sync vote sent to wrong leader"); + debug!("View sync vote sent to wrong leader"); return; } @@ -419,7 +419,7 @@ where SequencingHotShotEvent::ViewChange(new_view) => { // TODO ED Don't call new twice if self.current_view < TYPES::Time::new(*new_view) { - warn!( + debug!( "Change from view {} to view {} in view sync task", *self.current_view, *new_view ); @@ -600,7 +600,7 @@ where // Ignore certificate if it is for an older round if certificate_internal.round < self.next_view { - warn!("We're already in a higher round"); + debug!("We're already in a higher round"); return (None, self); } @@ -780,7 +780,7 @@ where ); if let GeneralConsensusMessage::ViewSyncVote(vote) = message { - warn!( + debug!( "Sending precommit vote to start protocol for next view = {}", *vote.round() ); @@ -928,7 +928,7 @@ where } }; - warn!( + debug!( "Recved vote for next view {}, and relay {}, and phase {:?}", *vote_internal.round, vote_internal.relay, phase ); @@ -938,7 +938,7 @@ where .exchange .is_leader(vote_internal.round + vote_internal.relay) { - warn!("We are not the correct relay"); + debug!("We are not the correct relay"); return (None, self); } @@ -948,7 +948,7 @@ where } .commit(); - warn!( + debug!( "Accumulating view sync vote {} relay {}", *vote_internal.round, vote_internal.relay ); diff --git a/task/src/event_stream.rs b/task/src/event_stream.rs index e434ed7d3e..b1b668cb88 100644 --- a/task/src/event_stream.rs +++ b/task/src/event_stream.rs @@ -136,7 +136,7 @@ impl EventStream for ChannelStream { } } None => { - tracing::info!("Requested stream id not found"); + tracing::debug!("Requested stream id not found"); } } } diff --git a/types/src/certificate.rs b/types/src/certificate.rs index 8f17374a15..a8be431b39 100644 --- a/types/src/certificate.rs +++ b/types/src/certificate.rs @@ -17,7 +17,7 @@ use hotshot_utils::bincode::bincode_opts; use serde::{Deserialize, Serialize}; use std::fmt::{self, Display, Formatter}; use std::{collections::BTreeMap, fmt::Debug, ops::Deref}; -use tracing::warn; +use tracing::debug; /// A `DACertificate` is a threshold signature that some data is available. /// It is signed by the members of the DA committee, not the entire network. It is used @@ -160,7 +160,7 @@ impl> signatures, is_genesis: false, }; - warn!("QC commitment when formed is {:?}", qc.leaf_commitment); + debug!("QC commitment when formed is {:?}", qc.leaf_commitment); qc } diff --git a/web_server/src/lib.rs b/web_server/src/lib.rs index 4479831355..9df3559ec8 100644 --- a/web_server/src/lib.rs +++ b/web_server/src/lib.rs @@ -21,6 +21,7 @@ use tide_disco::Api; use tide_disco::App; use tide_disco::StatusCode; use tracing::info; +use tracing::debug; type State = RwLock>; type Error = ServerError; @@ -252,7 +253,7 @@ impl WebServerDataSource for WebServerState { } if !txns_to_return.is_empty() { - info!("Returning this many txs {}", txns_to_return.len()); + debug!("Returning this many txs {}", txns_to_return.len()); Ok(Some((index, txns_to_return))) } else { Err(ServerError { @@ -328,7 +329,7 @@ impl WebServerDataSource for WebServerState { } /// Stores a received proposal in the `WebServerState` fn post_proposal(&mut self, view_number: u64, mut proposal: Vec) -> Result<(), Error> { - info!("Received proposal for view {}", view_number); + debug!("Received proposal for view {}", view_number); // Only keep proposal history for MAX_VIEWS number of view if self.proposals.len() >= MAX_VIEWS { @@ -376,7 +377,7 @@ impl WebServerDataSource for WebServerState { /// Stores a received DA certificate in the `WebServerState` fn post_da_certificate(&mut self, view_number: u64, mut cert: Vec) -> Result<(), Error> { - info!("Received DA Certificate for view {}", view_number); + debug!("Received DA Certificate for view {}", view_number); // Only keep proposal history for MAX_VIEWS number of view if self.da_certificates.len() >= MAX_VIEWS { @@ -401,7 +402,7 @@ impl WebServerDataSource for WebServerState { self.transactions.insert(self.num_txns, txn); self.num_txns += 1; - info!( + debug!( "Received transaction! Number of transactions received is: {}", self.num_txns ); @@ -452,7 +453,7 @@ impl WebServerDataSource for WebServerState { view_number: u64, mut proposal: Vec, ) -> Result<(), Error> { - info!("Received proposal for view {}", view_number); + debug!("Received proposal for view {}", view_number); // Only keep proposal history for MAX_VIEWS number of views if self.proposals.len() >= MAX_VIEWS { From c2e6e07b3da8647ed665fe5e48878944d17deeeb Mon Sep 17 00:00:00 2001 From: elliedavidson <118024407+elliedavidson@users.noreply.github.com> Date: Thu, 10 Aug 2023 13:19:03 -0400 Subject: [PATCH 2/2] lints --- src/traits/networking/web_server_network.rs | 1 - web_server/src/lib.rs | 2 +- 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/src/traits/networking/web_server_network.rs b/src/traits/networking/web_server_network.rs index fe001b4554..1fe36bad9b 100644 --- a/src/traits/networking/web_server_network.rs +++ b/src/traits/networking/web_server_network.rs @@ -232,7 +232,6 @@ impl { - // Only pushing the first proposal since we will soon only be allowing 1 proposal per view self.broadcast_poll_queue .write() diff --git a/web_server/src/lib.rs b/web_server/src/lib.rs index 9df3559ec8..42e5333e36 100644 --- a/web_server/src/lib.rs +++ b/web_server/src/lib.rs @@ -20,8 +20,8 @@ use tide_disco::method::WriteState; use tide_disco::Api; use tide_disco::App; use tide_disco::StatusCode; -use tracing::info; use tracing::debug; +use tracing::info; type State = RwLock>; type Error = ServerError;