beefy: Add LOG_TARGET constant (#13222)

* LOG_TARGET const
* fmt
This commit is contained in:
Alejandro Martinez Andres
2023-01-24 15:55:42 +01:00
committed by GitHub
parent 14a4eed2aa
commit b9854171c0
10 changed files with 153 additions and 102 deletions
+3 -3
View File
@@ -18,7 +18,7 @@
//! Schema for BEEFY state persisted in the aux-db. //! Schema for BEEFY state persisted in the aux-db.
use crate::worker::PersistedState; use crate::{worker::PersistedState, LOG_TARGET};
use codec::{Decode, Encode}; use codec::{Decode, Encode};
use log::{info, trace}; use log::{info, trace};
use sc_client_api::{backend::AuxStore, Backend}; use sc_client_api::{backend::AuxStore, Backend};
@@ -31,7 +31,7 @@ const WORKER_STATE: &[u8] = b"beefy_voter_state";
const CURRENT_VERSION: u32 = 1; const CURRENT_VERSION: u32 = 1;
pub(crate) fn write_current_version<B: AuxStore>(backend: &B) -> ClientResult<()> { pub(crate) fn write_current_version<B: AuxStore>(backend: &B) -> ClientResult<()> {
info!(target: "beefy", "🥩 write aux schema version {:?}", CURRENT_VERSION); info!(target: LOG_TARGET, "🥩 write aux schema version {:?}", CURRENT_VERSION);
AuxStore::insert_aux(backend, &[(VERSION_KEY, CURRENT_VERSION.encode().as_slice())], &[]) AuxStore::insert_aux(backend, &[(VERSION_KEY, CURRENT_VERSION.encode().as_slice())], &[])
} }
@@ -40,7 +40,7 @@ pub(crate) fn write_voter_state<Block: BlockT, B: AuxStore>(
backend: &B, backend: &B,
state: &PersistedState<Block>, state: &PersistedState<Block>,
) -> ClientResult<()> { ) -> ClientResult<()> {
trace!(target: "beefy", "🥩 persisting {:?}", state); trace!(target: LOG_TARGET, "🥩 persisting {:?}", state);
backend.insert_aux(&[(WORKER_STATE, state.encode().as_slice())], &[]) backend.insert_aux(&[(WORKER_STATE, state.encode().as_slice())], &[])
} }
@@ -28,7 +28,7 @@ use log::{debug, trace};
use parking_lot::{Mutex, RwLock}; use parking_lot::{Mutex, RwLock};
use wasm_timer::Instant; use wasm_timer::Instant;
use crate::{communication::peers::KnownPeers, keystore::BeefyKeystore}; use crate::{communication::peers::KnownPeers, keystore::BeefyKeystore, LOG_TARGET};
use beefy_primitives::{ use beefy_primitives::{
crypto::{Public, Signature}, crypto::{Public, Signature},
VoteMessage, VoteMessage,
@@ -122,7 +122,7 @@ where
/// ///
/// Noting round will start a live `round`. /// Noting round will start a live `round`.
pub(crate) fn note_round(&self, round: NumberFor<B>) { pub(crate) fn note_round(&self, round: NumberFor<B>) {
debug!(target: "beefy", "🥩 About to note gossip round #{}", round); debug!(target: LOG_TARGET, "🥩 About to note gossip round #{}", round);
self.known_votes.write().insert(round); self.known_votes.write().insert(round);
} }
@@ -130,7 +130,7 @@ where
/// ///
/// This can be called once round is complete so we stop gossiping for it. /// This can be called once round is complete so we stop gossiping for it.
pub(crate) fn conclude_round(&self, round: NumberFor<B>) { pub(crate) fn conclude_round(&self, round: NumberFor<B>) {
debug!(target: "beefy", "🥩 About to drop gossip round #{}", round); debug!(target: LOG_TARGET, "🥩 About to drop gossip round #{}", round);
self.known_votes.write().conclude(round); self.known_votes.write().conclude(round);
} }
} }
@@ -174,7 +174,10 @@ where
return ValidationResult::ProcessAndKeep(self.topic) return ValidationResult::ProcessAndKeep(self.topic)
} else { } else {
// TODO: report peer // TODO: report peer
debug!(target: "beefy", "🥩 Bad signature on message: {:?}, from: {:?}", msg, sender); debug!(
target: LOG_TARGET,
"🥩 Bad signature on message: {:?}, from: {:?}", msg, sender
);
} }
} }
@@ -192,7 +195,7 @@ where
let round = msg.commitment.block_number; let round = msg.commitment.block_number;
let expired = !known_votes.is_live(&round); let expired = !known_votes.is_live(&round);
trace!(target: "beefy", "🥩 Message for round #{} expired: {}", round, expired); trace!(target: LOG_TARGET, "🥩 Message for round #{} expired: {}", round, expired);
expired expired
}) })
@@ -226,7 +229,7 @@ where
let round = msg.commitment.block_number; let round = msg.commitment.block_number;
let allowed = known_votes.is_live(&round); let allowed = known_votes.is_live(&round);
trace!(target: "beefy", "🥩 Message for round #{} allowed: {}", round, allowed); trace!(target: LOG_TARGET, "🥩 Message for round #{} allowed: {}", round, allowed);
allowed allowed
}) })
@@ -30,7 +30,7 @@ use sp_runtime::traits::Block;
use std::{marker::PhantomData, sync::Arc}; use std::{marker::PhantomData, sync::Arc};
use crate::communication::request_response::{ use crate::communication::request_response::{
on_demand_justifications_protocol_config, Error, JustificationRequest, on_demand_justifications_protocol_config, Error, JustificationRequest, BEEFY_SYNC_LOG_TARGET,
}; };
/// A request coming in, including a sender for sending responses. /// A request coming in, including a sender for sending responses.
@@ -174,21 +174,21 @@ where
/// Run [`BeefyJustifsRequestHandler`]. /// Run [`BeefyJustifsRequestHandler`].
pub async fn run(mut self) { pub async fn run(mut self) {
trace!(target: "beefy::sync", "🥩 Running BeefyJustifsRequestHandler"); trace!(target: BEEFY_SYNC_LOG_TARGET, "🥩 Running BeefyJustifsRequestHandler");
while let Ok(request) = self.request_receiver.recv(|| vec![]).await { while let Ok(request) = self.request_receiver.recv(|| vec![]).await {
let peer = request.peer; let peer = request.peer;
match self.handle_request(request) { match self.handle_request(request) {
Ok(()) => { Ok(()) => {
debug!( debug!(
target: "beefy::sync", target: BEEFY_SYNC_LOG_TARGET,
"🥩 Handled BEEFY justification request from {:?}.", peer "🥩 Handled BEEFY justification request from {:?}.", peer
) )
}, },
Err(e) => { Err(e) => {
// TODO (issue #12293): apply reputation changes here based on error type. // TODO (issue #12293): apply reputation changes here based on error type.
debug!( debug!(
target: "beefy::sync", target: BEEFY_SYNC_LOG_TARGET,
"🥩 Failed to handle BEEFY justification request from {:?}: {}", peer, e, "🥩 Failed to handle BEEFY justification request from {:?}: {}", peer, e,
) )
}, },
@@ -40,6 +40,8 @@ const JUSTIF_CHANNEL_SIZE: usize = 10;
const MAX_RESPONSE_SIZE: u64 = 1024 * 1024; const MAX_RESPONSE_SIZE: u64 = 1024 * 1024;
const JUSTIF_REQUEST_TIMEOUT: Duration = Duration::from_secs(3); const JUSTIF_REQUEST_TIMEOUT: Duration = Duration::from_secs(3);
const BEEFY_SYNC_LOG_TARGET: &str = "beefy::sync";
/// Get the configuration for the BEEFY justifications Request/response protocol. /// Get the configuration for the BEEFY justifications Request/response protocol.
/// ///
/// Returns a receiver for messages received on this protocol and the requested /// Returns a receiver for messages received on this protocol and the requested
@@ -32,7 +32,7 @@ use sp_runtime::traits::{Block, NumberFor};
use std::{collections::VecDeque, result::Result, sync::Arc}; use std::{collections::VecDeque, result::Result, sync::Arc};
use crate::{ use crate::{
communication::request_response::{Error, JustificationRequest}, communication::request_response::{Error, JustificationRequest, BEEFY_SYNC_LOG_TARGET},
justification::{decode_and_verify_finality_proof, BeefyVersionedFinalityProof}, justification::{decode_and_verify_finality_proof, BeefyVersionedFinalityProof},
KnownPeers, KnownPeers,
}; };
@@ -96,10 +96,8 @@ impl<B: Block> OnDemandJustificationsEngine<B> {
fn request_from_peer(&mut self, peer: PeerId, req_info: RequestInfo<B>) { fn request_from_peer(&mut self, peer: PeerId, req_info: RequestInfo<B>) {
debug!( debug!(
target: "beefy::sync", target: BEEFY_SYNC_LOG_TARGET,
"🥩 requesting justif #{:?} from peer {:?}", "🥩 requesting justif #{:?} from peer {:?}", req_info.block, peer,
req_info.block,
peer,
); );
let payload = JustificationRequest::<B> { begin: req_info.block }.encode(); let payload = JustificationRequest::<B> { begin: req_info.block }.encode();
@@ -132,7 +130,10 @@ impl<B: Block> OnDemandJustificationsEngine<B> {
if let Some(peer) = self.try_next_peer() { if let Some(peer) = self.try_next_peer() {
self.request_from_peer(peer, RequestInfo { block, active_set }); self.request_from_peer(peer, RequestInfo { block, active_set });
} else { } else {
debug!(target: "beefy::sync", "🥩 no good peers to request justif #{:?} from", block); debug!(
target: BEEFY_SYNC_LOG_TARGET,
"🥩 no good peers to request justif #{:?} from", block
);
} }
} }
@@ -141,8 +142,8 @@ impl<B: Block> OnDemandJustificationsEngine<B> {
match &self.state { match &self.state {
State::AwaitingResponse(_, req_info, _) if req_info.block <= block => { State::AwaitingResponse(_, req_info, _) if req_info.block <= block => {
debug!( debug!(
target: "beefy::sync", "🥩 cancel pending request for justification #{:?}", target: BEEFY_SYNC_LOG_TARGET,
req_info.block "🥩 cancel pending request for justification #{:?}", req_info.block
); );
self.state = State::Idle; self.state = State::Idle;
}, },
@@ -159,17 +160,21 @@ impl<B: Block> OnDemandJustificationsEngine<B> {
response response
.map_err(|e| { .map_err(|e| {
debug!( debug!(
target: "beefy::sync", target: BEEFY_SYNC_LOG_TARGET,
"🥩 for on demand justification #{:?}, peer {:?} hung up: {:?}", "🥩 for on demand justification #{:?}, peer {:?} hung up: {:?}",
req_info.block, peer, e req_info.block,
peer,
e
); );
Error::InvalidResponse Error::InvalidResponse
})? })?
.map_err(|e| { .map_err(|e| {
debug!( debug!(
target: "beefy::sync", target: BEEFY_SYNC_LOG_TARGET,
"🥩 for on demand justification #{:?}, peer {:?} error: {:?}", "🥩 for on demand justification #{:?}, peer {:?} error: {:?}",
req_info.block, peer, e req_info.block,
peer,
e
); );
Error::InvalidResponse Error::InvalidResponse
}) })
@@ -181,7 +186,7 @@ impl<B: Block> OnDemandJustificationsEngine<B> {
) )
.map_err(|e| { .map_err(|e| {
debug!( debug!(
target: "beefy::sync", target: BEEFY_SYNC_LOG_TARGET,
"🥩 for on demand justification #{:?}, peer {:?} responded with invalid proof: {:?}", "🥩 for on demand justification #{:?}, peer {:?} responded with invalid proof: {:?}",
req_info.block, peer, e req_info.block, peer, e
); );
@@ -213,14 +218,16 @@ impl<B: Block> OnDemandJustificationsEngine<B> {
if let Some(peer) = self.try_next_peer() { if let Some(peer) = self.try_next_peer() {
self.request_from_peer(peer, req_info); self.request_from_peer(peer, req_info);
} else { } else {
warn!(target: "beefy::sync", "🥩 ran out of peers to request justif #{:?} from", block); warn!(
target: BEEFY_SYNC_LOG_TARGET,
"🥩 ran out of peers to request justif #{:?} from", block
);
} }
}) })
.map(|proof| { .map(|proof| {
debug!( debug!(
target: "beefy::sync", target: BEEFY_SYNC_LOG_TARGET,
"🥩 received valid on-demand justif #{:?} from {:?}", "🥩 received valid on-demand justif #{:?} from {:?}", block, peer
block, peer
); );
proof proof
}) })
+8 -3
View File
@@ -35,6 +35,7 @@ use sc_consensus::{BlockCheckParams, BlockImport, BlockImportParams, ImportResul
use crate::{ use crate::{
communication::notification::BeefyVersionedFinalityProofSender, communication::notification::BeefyVersionedFinalityProofSender,
justification::{decode_and_verify_finality_proof, BeefyVersionedFinalityProof}, justification::{decode_and_verify_finality_proof, BeefyVersionedFinalityProof},
LOG_TARGET,
}; };
/// A block-import handler for BEEFY. /// A block-import handler for BEEFY.
@@ -138,16 +139,20 @@ where
(Some(encoded), ImportResult::Imported(_)) => { (Some(encoded), ImportResult::Imported(_)) => {
if let Ok(proof) = self.decode_and_verify(&encoded, number, hash) { if let Ok(proof) = self.decode_and_verify(&encoded, number, hash) {
// The proof is valid and the block is imported and final, we can import. // The proof is valid and the block is imported and final, we can import.
debug!(target: "beefy", "🥩 import justif {:?} for block number {:?}.", proof, number); debug!(
target: LOG_TARGET,
"🥩 import justif {:?} for block number {:?}.", proof, number
);
// Send the justification to the BEEFY voter for processing. // Send the justification to the BEEFY voter for processing.
self.justification_sender self.justification_sender
.notify(|| Ok::<_, ()>(proof)) .notify(|| Ok::<_, ()>(proof))
.expect("forwards closure result; the closure always returns Ok; qed."); .expect("forwards closure result; the closure always returns Ok; qed.");
} else { } else {
debug!( debug!(
target: "beefy", target: LOG_TARGET,
"🥩 error decoding justification: {:?} for imported block {:?}", "🥩 error decoding justification: {:?} for imported block {:?}",
encoded, number, encoded,
number,
); );
} }
}, },
+7 -2
View File
@@ -28,7 +28,7 @@ use beefy_primitives::{
BeefyAuthorityId, KEY_TYPE, BeefyAuthorityId, KEY_TYPE,
}; };
use crate::error; use crate::{error, LOG_TARGET};
/// A BEEFY specific keystore implemented as a `Newtype`. This is basically a /// A BEEFY specific keystore implemented as a `Newtype`. This is basically a
/// wrapper around [`sp_keystore::SyncCryptoStore`] and allows to customize /// wrapper around [`sp_keystore::SyncCryptoStore`] and allows to customize
@@ -53,7 +53,12 @@ impl BeefyKeystore {
.collect(); .collect();
if public.len() > 1 { if public.len() > 1 {
warn!(target: "beefy", "🥩 Multiple private keys found for: {:?} ({})", public, public.len()); warn!(
target: LOG_TARGET,
"🥩 Multiple private keys found for: {:?} ({})",
public,
public.len()
);
} }
public.get(0).cloned() public.get(0).cloned()
+20 -13
View File
@@ -75,6 +75,8 @@ pub use communication::beefy_protocol_name::{
#[cfg(test)] #[cfg(test)]
mod tests; mod tests;
const LOG_TARGET: &str = "beefy";
/// A convenience BEEFY client trait that defines all the type bounds a BEEFY client /// A convenience BEEFY client trait that defines all the type bounds a BEEFY client
/// has to satisfy. Ideally that should actually be a trait alias. Unfortunately as /// has to satisfy. Ideally that should actually be a trait alias. Unfortunately as
/// of today, Rust does not allow a type alias to be used as a trait bound. Tracking /// of today, Rust does not allow a type alias to be used as a trait bound. Tracking
@@ -252,11 +254,11 @@ where
prometheus_registry.as_ref().map(metrics::Metrics::register).and_then( prometheus_registry.as_ref().map(metrics::Metrics::register).and_then(
|result| match result { |result| match result {
Ok(metrics) => { Ok(metrics) => {
debug!(target: "beefy", "🥩 Registered metrics"); debug!(target: LOG_TARGET, "🥩 Registered metrics");
Some(metrics) Some(metrics)
}, },
Err(err) => { Err(err) => {
debug!(target: "beefy", "🥩 Failed to register metrics: {:?}", err); debug!(target: LOG_TARGET, "🥩 Failed to register metrics: {:?}", err);
None None
}, },
}, },
@@ -276,7 +278,7 @@ where
}) { }) {
Ok(state) => state, Ok(state) => state,
Err(e) => { Err(e) => {
error!(target: "beefy", "Error: {:?}. Terminating.", e); error!(target: LOG_TARGET, "Error: {:?}. Terminating.", e);
return return
}, },
}; };
@@ -321,7 +323,7 @@ where
state.set_best_grandpa(best_grandpa); state.set_best_grandpa(best_grandpa);
// Overwrite persisted data with newly provided `min_block_delta`. // Overwrite persisted data with newly provided `min_block_delta`.
state.set_min_block_delta(min_block_delta); state.set_min_block_delta(min_block_delta);
info!(target: "beefy", "🥩 Loading BEEFY voter state from db: {:?}.", state); info!(target: LOG_TARGET, "🥩 Loading BEEFY voter state from db: {:?}.", state);
Ok(state) Ok(state)
} else { } else {
initialize_voter_state(backend, runtime, best_grandpa, min_block_delta) initialize_voter_state(backend, runtime, best_grandpa, min_block_delta)
@@ -357,7 +359,7 @@ where
.map(|justifs| justifs.get(BEEFY_ENGINE_ID).is_some()) .map(|justifs| justifs.get(BEEFY_ENGINE_ID).is_some())
{ {
info!( info!(
target: "beefy", target: LOG_TARGET,
"🥩 Initialize BEEFY voter at last BEEFY finalized block: {:?}.", "🥩 Initialize BEEFY voter at last BEEFY finalized block: {:?}.",
*header.number() *header.number()
); );
@@ -382,10 +384,11 @@ where
let genesis_set = expect_validator_set(runtime, BlockId::hash(header.hash())) let genesis_set = expect_validator_set(runtime, BlockId::hash(header.hash()))
.and_then(genesis_set_sanity_check)?; .and_then(genesis_set_sanity_check)?;
info!( info!(
target: "beefy", target: LOG_TARGET,
"🥩 Loading BEEFY voter state from genesis on what appears to be first startup. \ "🥩 Loading BEEFY voter state from genesis on what appears to be first startup. \
Starting voting rounds at block {:?}, genesis validator set {:?}.", Starting voting rounds at block {:?}, genesis validator set {:?}.",
genesis_num, genesis_set, genesis_num,
genesis_set,
); );
sessions.push_front(Rounds::new(genesis_num, genesis_set)); sessions.push_front(Rounds::new(genesis_num, genesis_set));
@@ -394,7 +397,11 @@ where
} }
if let Some(active) = worker::find_authorities_change::<B>(&header) { if let Some(active) = worker::find_authorities_change::<B>(&header) {
info!(target: "beefy", "🥩 Marking block {:?} as BEEFY Mandatory.", *header.number()); info!(
target: LOG_TARGET,
"🥩 Marking block {:?} as BEEFY Mandatory.",
*header.number()
);
sessions.push_front(Rounds::new(*header.number(), active)); sessions.push_front(Rounds::new(*header.number(), active));
} }
@@ -407,7 +414,7 @@ where
.flatten() .flatten()
.ok_or_else(|| { .ok_or_else(|| {
let msg = format!("{}. Could not initialize BEEFY voter.", parent_hash); let msg = format!("{}. Could not initialize BEEFY voter.", parent_hash);
error!(target: "beefy", "🥩 {}", msg); error!(target: LOG_TARGET, "🥩 {}", msg);
ClientError::Consensus(sp_consensus::Error::StateUnavailable(msg)) ClientError::Consensus(sp_consensus::Error::StateUnavailable(msg))
})?; })?;
@@ -432,7 +439,7 @@ where
R: ProvideRuntimeApi<B>, R: ProvideRuntimeApi<B>,
R::Api: BeefyApi<B>, R::Api: BeefyApi<B>,
{ {
info!(target: "beefy", "🥩 BEEFY gadget waiting for BEEFY pallet to become available..."); info!(target: LOG_TARGET, "🥩 BEEFY gadget waiting for BEEFY pallet to become available...");
loop { loop {
futures::select! { futures::select! {
notif = finality.next() => { notif = finality.next() => {
@@ -444,7 +451,7 @@ where
if let Some(active) = runtime.runtime_api().validator_set(&at).ok().flatten() { if let Some(active) = runtime.runtime_api().validator_set(&at).ok().flatten() {
// Beefy pallet available, return best grandpa at the time. // Beefy pallet available, return best grandpa at the time.
info!( info!(
target: "beefy", "🥩 BEEFY pallet available: block {:?} validator set {:?}", target: LOG_TARGET, "🥩 BEEFY pallet available: block {:?} validator set {:?}",
notif.header.number(), active notif.header.number(), active
); );
return Ok(notif.header) return Ok(notif.header)
@@ -456,7 +463,7 @@ where
} }
} }
let err_msg = "🥩 Gossip engine has unexpectedly terminated.".into(); let err_msg = "🥩 Gossip engine has unexpectedly terminated.".into();
error!(target: "beefy", "{}", err_msg); error!(target: LOG_TARGET, "{}", err_msg);
Err(ClientError::Backend(err_msg)) Err(ClientError::Backend(err_msg))
} }
@@ -466,7 +473,7 @@ fn genesis_set_sanity_check(
if active.id() == GENESIS_AUTHORITY_SET_ID { if active.id() == GENESIS_AUTHORITY_SET_ID {
Ok(active) Ok(active)
} else { } else {
error!(target: "beefy", "🥩 Unexpected ID for genesis validator set {:?}.", active); error!(target: LOG_TARGET, "🥩 Unexpected ID for genesis validator set {:?}.", active);
Err(ClientError::Backend("BEEFY Genesis sanity check failed.".into())) Err(ClientError::Backend("BEEFY Genesis sanity check failed.".into()))
} }
} }
+6 -4
View File
@@ -16,6 +16,8 @@
// You should have received a copy of the GNU General Public License // You should have received a copy of the GNU General Public License
// along with this program. If not, see <https://www.gnu.org/licenses/>. // along with this program. If not, see <https://www.gnu.org/licenses/>.
use crate::LOG_TARGET;
use beefy_primitives::{ use beefy_primitives::{
crypto::{Public, Signature}, crypto::{Public, Signature},
ValidatorSet, ValidatorSetId, ValidatorSet, ValidatorSetId,
@@ -122,11 +124,11 @@ where
) -> bool { ) -> bool {
let num = round.1; let num = round.1;
if num < self.session_start || Some(num) <= self.best_done { if num < self.session_start || Some(num) <= self.best_done {
debug!(target: "beefy", "🥩 received vote for old stale round {:?}, ignoring", num); debug!(target: LOG_TARGET, "🥩 received vote for old stale round {:?}, ignoring", num);
false false
} else if !self.validators().iter().any(|id| vote.0 == *id) { } else if !self.validators().iter().any(|id| vote.0 == *id) {
debug!( debug!(
target: "beefy", target: LOG_TARGET,
"🥩 received vote {:?} from validator that is not in the validator set, ignoring", "🥩 received vote {:?} from validator that is not in the validator set, ignoring",
vote vote
); );
@@ -145,7 +147,7 @@ where
.get(round) .get(round)
.map(|tracker| tracker.is_done(threshold(self.validator_set.len()))) .map(|tracker| tracker.is_done(threshold(self.validator_set.len())))
.unwrap_or(false); .unwrap_or(false);
trace!(target: "beefy", "🥩 Round #{} done: {}", round.1, done); trace!(target: LOG_TARGET, "🥩 Round #{} done: {}", round.1, done);
if done { if done {
let signatures = self.rounds.remove(round)?.votes; let signatures = self.rounds.remove(round)?.votes;
@@ -165,7 +167,7 @@ where
self.rounds.retain(|&(_, number), _| number > round_num); self.rounds.retain(|&(_, number), _| number > round_num);
self.mandatory_done = self.mandatory_done || round_num == self.session_start; self.mandatory_done = self.mandatory_done || round_num == self.session_start;
self.best_done = self.best_done.max(Some(round_num)); self.best_done = self.best_done.max(Some(round_num));
debug!(target: "beefy", "🥩 Concluded round #{}", round_num); debug!(target: LOG_TARGET, "🥩 Concluded round #{}", round_num);
} }
} }
+70 -50
View File
@@ -27,7 +27,7 @@ use crate::{
metric_inc, metric_set, metric_inc, metric_set,
metrics::Metrics, metrics::Metrics,
round::Rounds, round::Rounds,
BeefyVoterLinks, BeefyVoterLinks, LOG_TARGET,
}; };
use beefy_primitives::{ use beefy_primitives::{
crypto::{AuthorityId, Signature}, crypto::{AuthorityId, Signature},
@@ -129,7 +129,7 @@ impl<B: Block> VoterOracle<B> {
min_block_delta: min_block_delta.max(1), min_block_delta: min_block_delta.max(1),
}) })
} else { } else {
error!(target: "beefy", "🥩 Invalid sessions queue: {:?}.", sessions); error!(target: LOG_TARGET, "🥩 Invalid sessions queue: {:?}.", sessions);
None None
} }
} }
@@ -227,7 +227,7 @@ impl<B: Block> VoterOracle<B> {
let rounds = if let Some(r) = self.sessions.front() { let rounds = if let Some(r) = self.sessions.front() {
r r
} else { } else {
debug!(target: "beefy", "🥩 No voting round started"); debug!(target: LOG_TARGET, "🥩 No voting round started");
return None return None
}; };
@@ -235,7 +235,7 @@ impl<B: Block> VoterOracle<B> {
let target = let target =
vote_target(best_grandpa, best_beefy, rounds.session_start(), self.min_block_delta); vote_target(best_grandpa, best_beefy, rounds.session_start(), self.min_block_delta);
trace!( trace!(
target: "beefy", target: LOG_TARGET,
"🥩 best beefy: #{:?}, best finalized: #{:?}, current_vote_target: {:?}", "🥩 best beefy: #{:?}, best finalized: #{:?}, current_vote_target: {:?}",
best_beefy, best_beefy,
best_grandpa, best_grandpa,
@@ -405,7 +405,7 @@ where
if store.intersection(&active).count() == 0 { if store.intersection(&active).count() == 0 {
let msg = "no authority public key found in store".to_string(); let msg = "no authority public key found in store".to_string();
debug!(target: "beefy", "🥩 for block {:?} {}", block, msg); debug!(target: LOG_TARGET, "🥩 for block {:?} {}", block, msg);
Err(Error::Keystore(msg)) Err(Error::Keystore(msg))
} else { } else {
Ok(()) Ok(())
@@ -418,13 +418,14 @@ where
validator_set: ValidatorSet<AuthorityId>, validator_set: ValidatorSet<AuthorityId>,
new_session_start: NumberFor<B>, new_session_start: NumberFor<B>,
) { ) {
debug!(target: "beefy", "🥩 New active validator set: {:?}", validator_set); debug!(target: LOG_TARGET, "🥩 New active validator set: {:?}", validator_set);
// BEEFY should finalize a mandatory block during each session. // BEEFY should finalize a mandatory block during each session.
if let Some(active_session) = self.active_rounds() { if let Some(active_session) = self.active_rounds() {
if !active_session.mandatory_done() { if !active_session.mandatory_done() {
debug!( debug!(
target: "beefy", "🥩 New session {} while active session {} is still lagging.", target: LOG_TARGET,
"🥩 New session {} while active session {} is still lagging.",
validator_set.id(), validator_set.id(),
active_session.validator_set_id(), active_session.validator_set_id(),
); );
@@ -432,7 +433,7 @@ where
} }
} }
if log_enabled!(target: "beefy", log::Level::Debug) { if log_enabled!(target: LOG_TARGET, log::Level::Debug) {
// verify the new validator set - only do it if we're also logging the warning // verify the new validator set - only do it if we're also logging the warning
let _ = self.verify_validator_set(&new_session_start, &validator_set); let _ = self.verify_validator_set(&new_session_start, &validator_set);
} }
@@ -443,14 +444,15 @@ where
.add_session(Rounds::new(new_session_start, validator_set)); .add_session(Rounds::new(new_session_start, validator_set));
metric_set!(self, beefy_validator_set_id, id); metric_set!(self, beefy_validator_set_id, id);
info!( info!(
target: "beefy", target: LOG_TARGET,
"🥩 New Rounds for validator set id: {:?} with session_start {:?}", "🥩 New Rounds for validator set id: {:?} with session_start {:?}",
id, new_session_start id,
new_session_start
); );
} }
fn handle_finality_notification(&mut self, notification: &FinalityNotification<B>) { fn handle_finality_notification(&mut self, notification: &FinalityNotification<B>) {
debug!(target: "beefy", "🥩 Finality notification: {:?}", notification); debug!(target: LOG_TARGET, "🥩 Finality notification: {:?}", notification);
let header = &notification.header; let header = &notification.header;
if *header.number() > self.best_grandpa_block() { if *header.number() > self.best_grandpa_block() {
@@ -491,14 +493,17 @@ where
false, false,
)?, )?,
RoundAction::Enqueue => { RoundAction::Enqueue => {
debug!(target: "beefy", "🥩 Buffer vote for round: {:?}.", block_num); debug!(target: LOG_TARGET, "🥩 Buffer vote for round: {:?}.", block_num);
if self.pending_votes.len() < MAX_BUFFERED_VOTE_ROUNDS { if self.pending_votes.len() < MAX_BUFFERED_VOTE_ROUNDS {
let votes_vec = self.pending_votes.entry(block_num).or_default(); let votes_vec = self.pending_votes.entry(block_num).or_default();
if votes_vec.try_push(vote).is_err() { if votes_vec.try_push(vote).is_err() {
warn!(target: "beefy", "🥩 Buffer vote dropped for round: {:?}", block_num) warn!(
target: LOG_TARGET,
"🥩 Buffer vote dropped for round: {:?}", block_num
)
} }
} else { } else {
warn!(target: "beefy", "🥩 Buffer vote dropped for round: {:?}.", block_num); warn!(target: LOG_TARGET, "🥩 Buffer vote dropped for round: {:?}.", block_num);
} }
}, },
RoundAction::Drop => (), RoundAction::Drop => (),
@@ -520,15 +525,18 @@ where
let best_grandpa = self.best_grandpa_block(); let best_grandpa = self.best_grandpa_block();
match self.voting_oracle().triage_round(block_num, best_grandpa)? { match self.voting_oracle().triage_round(block_num, best_grandpa)? {
RoundAction::Process => { RoundAction::Process => {
debug!(target: "beefy", "🥩 Process justification for round: {:?}.", block_num); debug!(target: LOG_TARGET, "🥩 Process justification for round: {:?}.", block_num);
self.finalize(justification)? self.finalize(justification)?
}, },
RoundAction::Enqueue => { RoundAction::Enqueue => {
debug!(target: "beefy", "🥩 Buffer justification for round: {:?}.", block_num); debug!(target: LOG_TARGET, "🥩 Buffer justification for round: {:?}.", block_num);
if self.pending_justifications.len() < MAX_BUFFERED_JUSTIFICATIONS { if self.pending_justifications.len() < MAX_BUFFERED_JUSTIFICATIONS {
self.pending_justifications.entry(block_num).or_insert(justification); self.pending_justifications.entry(block_num).or_insert(justification);
} else { } else {
warn!(target: "beefy", "🥩 Buffer justification dropped for round: {:?}.", block_num); warn!(
target: LOG_TARGET,
"🥩 Buffer justification dropped for round: {:?}.", block_num
);
} }
}, },
RoundAction::Drop => (), RoundAction::Drop => (),
@@ -566,7 +574,10 @@ where
metric_set!(self, beefy_round_concluded, block_num); metric_set!(self, beefy_round_concluded, block_num);
info!(target: "beefy", "🥩 Round #{} concluded, finality_proof: {:?}.", round.1, finality_proof); info!(
target: LOG_TARGET,
"🥩 Round #{} concluded, finality_proof: {:?}.", round.1, finality_proof
);
// We created the `finality_proof` and know to be valid. // We created the `finality_proof` and know to be valid.
// New state is persisted after finalization. // New state is persisted after finalization.
@@ -627,7 +638,10 @@ where
self.backend self.backend
.append_justification(hash, (BEEFY_ENGINE_ID, finality_proof.encode())) .append_justification(hash, (BEEFY_ENGINE_ID, finality_proof.encode()))
}) { }) {
error!(target: "beefy", "🥩 Error {:?} on appending justification: {:?}", e, finality_proof); error!(
target: LOG_TARGET,
"🥩 Error {:?} on appending justification: {:?}", e, finality_proof
);
} }
self.links self.links
@@ -635,7 +649,7 @@ where
.notify(|| Ok::<_, ()>(finality_proof)) .notify(|| Ok::<_, ()>(finality_proof))
.expect("forwards closure result; the closure always returns Ok; qed."); .expect("forwards closure result; the closure always returns Ok; qed.");
} else { } else {
debug!(target: "beefy", "🥩 Can't set best beefy to older: {}", block_num); debug!(target: LOG_TARGET, "🥩 Can't set best beefy to older: {}", block_num);
} }
Ok(()) Ok(())
} }
@@ -666,9 +680,9 @@ where
if !self.pending_justifications.is_empty() { if !self.pending_justifications.is_empty() {
let justifs_to_handle = to_process_for(&mut self.pending_justifications, interval, _ph); let justifs_to_handle = to_process_for(&mut self.pending_justifications, interval, _ph);
for (num, justification) in justifs_to_handle.into_iter() { for (num, justification) in justifs_to_handle.into_iter() {
debug!(target: "beefy", "🥩 Handle buffered justification for: {:?}.", num); debug!(target: LOG_TARGET, "🥩 Handle buffered justification for: {:?}.", num);
if let Err(err) = self.finalize(justification) { if let Err(err) = self.finalize(justification) {
error!(target: "beefy", "🥩 Error finalizing block: {}", err); error!(target: LOG_TARGET, "🥩 Error finalizing block: {}", err);
} }
} }
// Possibly new interval after processing justifications. // Possibly new interval after processing justifications.
@@ -679,14 +693,14 @@ where
if !self.pending_votes.is_empty() { if !self.pending_votes.is_empty() {
let votes_to_handle = to_process_for(&mut self.pending_votes, interval, _ph); let votes_to_handle = to_process_for(&mut self.pending_votes, interval, _ph);
for (num, votes) in votes_to_handle.into_iter() { for (num, votes) in votes_to_handle.into_iter() {
debug!(target: "beefy", "🥩 Handle buffered votes for: {:?}.", num); debug!(target: LOG_TARGET, "🥩 Handle buffered votes for: {:?}.", num);
for v in votes.into_iter() { for v in votes.into_iter() {
if let Err(err) = self.handle_vote( if let Err(err) = self.handle_vote(
(v.commitment.payload, v.commitment.block_number), (v.commitment.payload, v.commitment.block_number),
(v.id, v.signature), (v.id, v.signature),
false, false,
) { ) {
error!(target: "beefy", "🥩 Error handling buffered vote: {}", err); error!(target: LOG_TARGET, "🥩 Error handling buffered vote: {}", err);
}; };
} }
} }
@@ -711,7 +725,7 @@ where
/// ///
/// Also handle this self vote by calling `self.handle_vote()` for it. /// Also handle this self vote by calling `self.handle_vote()` for it.
fn do_vote(&mut self, target_number: NumberFor<B>) -> Result<(), Error> { fn do_vote(&mut self, target_number: NumberFor<B>) -> Result<(), Error> {
debug!(target: "beefy", "🥩 Try voting on {}", target_number); debug!(target: LOG_TARGET, "🥩 Try voting on {}", target_number);
// Most of the time we get here, `target` is actually `best_grandpa`, // Most of the time we get here, `target` is actually `best_grandpa`,
// avoid getting header from backend in that case. // avoid getting header from backend in that case.
@@ -743,7 +757,7 @@ where
let payload = if let Some(hash) = self.payload_provider.payload(&target_header) { let payload = if let Some(hash) = self.payload_provider.payload(&target_header) {
hash hash
} else { } else {
warn!(target: "beefy", "🥩 No MMR root digest found for: {:?}", target_hash); warn!(target: LOG_TARGET, "🥩 No MMR root digest found for: {:?}", target_hash);
return Ok(()) return Ok(())
}; };
@@ -753,16 +767,22 @@ where
.active_rounds_mut() .active_rounds_mut()
.ok_or(Error::UninitSession)?; .ok_or(Error::UninitSession)?;
if !rounds.should_self_vote(&(payload.clone(), target_number)) { if !rounds.should_self_vote(&(payload.clone(), target_number)) {
debug!(target: "beefy", "🥩 Don't double vote for block number: {:?}", target_number); debug!(
target: LOG_TARGET,
"🥩 Don't double vote for block number: {:?}", target_number
);
return Ok(()) return Ok(())
} }
let (validators, validator_set_id) = (rounds.validators(), rounds.validator_set_id()); let (validators, validator_set_id) = (rounds.validators(), rounds.validator_set_id());
let authority_id = if let Some(id) = self.key_store.authority_id(validators) { let authority_id = if let Some(id) = self.key_store.authority_id(validators) {
debug!(target: "beefy", "🥩 Local authority id: {:?}", id); debug!(target: LOG_TARGET, "🥩 Local authority id: {:?}", id);
id id
} else { } else {
debug!(target: "beefy", "🥩 Missing validator id - can't vote for: {:?}", target_hash); debug!(
target: LOG_TARGET,
"🥩 Missing validator id - can't vote for: {:?}", target_hash
);
return Ok(()) return Ok(())
}; };
@@ -772,13 +792,13 @@ where
let signature = match self.key_store.sign(&authority_id, &encoded_commitment) { let signature = match self.key_store.sign(&authority_id, &encoded_commitment) {
Ok(sig) => sig, Ok(sig) => sig,
Err(err) => { Err(err) => {
warn!(target: "beefy", "🥩 Error signing commitment: {:?}", err); warn!(target: LOG_TARGET, "🥩 Error signing commitment: {:?}", err);
return Ok(()) return Ok(())
}, },
}; };
trace!( trace!(
target: "beefy", target: LOG_TARGET,
"🥩 Produced signature using {:?}, is_valid: {:?}", "🥩 Produced signature using {:?}, is_valid: {:?}",
authority_id, authority_id,
BeefyKeystore::verify(&authority_id, &signature, &encoded_commitment) BeefyKeystore::verify(&authority_id, &signature, &encoded_commitment)
@@ -790,14 +810,14 @@ where
metric_inc!(self, beefy_votes_sent); metric_inc!(self, beefy_votes_sent);
debug!(target: "beefy", "🥩 Sent vote message: {:?}", message); debug!(target: LOG_TARGET, "🥩 Sent vote message: {:?}", message);
if let Err(err) = self.handle_vote( if let Err(err) = self.handle_vote(
(message.commitment.payload, message.commitment.block_number), (message.commitment.payload, message.commitment.block_number),
(message.id, message.signature), (message.id, message.signature),
true, true,
) { ) {
error!(target: "beefy", "🥩 Error handling self vote: {}", err); error!(target: LOG_TARGET, "🥩 Error handling self vote: {}", err);
} }
self.gossip_engine.gossip_message(topic::<B>(), encoded_message, false); self.gossip_engine.gossip_message(topic::<B>(), encoded_message, false);
@@ -808,14 +828,14 @@ where
fn process_new_state(&mut self) { fn process_new_state(&mut self) {
// Handle pending justifications and/or votes for now GRANDPA finalized blocks. // Handle pending justifications and/or votes for now GRANDPA finalized blocks.
if let Err(err) = self.try_pending_justif_and_votes() { if let Err(err) = self.try_pending_justif_and_votes() {
debug!(target: "beefy", "🥩 {}", err); debug!(target: LOG_TARGET, "🥩 {}", err);
} }
// Don't bother voting or requesting justifications during major sync. // Don't bother voting or requesting justifications during major sync.
if !self.network.is_major_syncing() { if !self.network.is_major_syncing() {
// There were external events, 'state' is changed, author a vote if needed/possible. // There were external events, 'state' is changed, author a vote if needed/possible.
if let Err(err) = self.try_to_vote() { if let Err(err) = self.try_to_vote() {
debug!(target: "beefy", "🥩 {}", err); debug!(target: LOG_TARGET, "🥩 {}", err);
} }
// If the current target is a mandatory block, // If the current target is a mandatory block,
// make sure there's also an on-demand justification request out for it. // make sure there's also an on-demand justification request out for it.
@@ -835,13 +855,17 @@ where
mut block_import_justif: Fuse<NotificationReceiver<BeefyVersionedFinalityProof<B>>>, mut block_import_justif: Fuse<NotificationReceiver<BeefyVersionedFinalityProof<B>>>,
mut finality_notifications: Fuse<FinalityNotifications<B>>, mut finality_notifications: Fuse<FinalityNotifications<B>>,
) { ) {
info!(target: "beefy", "🥩 run BEEFY worker, best grandpa: #{:?}.", self.best_grandpa_block()); info!(
target: LOG_TARGET,
"🥩 run BEEFY worker, best grandpa: #{:?}.",
self.best_grandpa_block()
);
let mut votes = Box::pin( let mut votes = Box::pin(
self.gossip_engine self.gossip_engine
.messages_for(topic::<B>()) .messages_for(topic::<B>())
.filter_map(|notification| async move { .filter_map(|notification| async move {
trace!(target: "beefy", "🥩 Got vote message: {:?}", notification); trace!(target: LOG_TARGET, "🥩 Got vote message: {:?}", notification);
VoteMessage::<NumberFor<B>, AuthorityId, Signature>::decode( VoteMessage::<NumberFor<B>, AuthorityId, Signature>::decode(
&mut &notification.message[..], &mut &notification.message[..],
@@ -863,7 +887,7 @@ where
// Use `select_biased!` to prioritize order below. // Use `select_biased!` to prioritize order below.
// Make sure to pump gossip engine. // Make sure to pump gossip engine.
_ = gossip_engine => { _ = gossip_engine => {
error!(target: "beefy", "🥩 Gossip engine has terminated, closing worker."); error!(target: LOG_TARGET, "🥩 Gossip engine has terminated, closing worker.");
return; return;
}, },
// Process finality notifications first since these drive the voter. // Process finality notifications first since these drive the voter.
@@ -871,7 +895,7 @@ where
if let Some(notification) = notification { if let Some(notification) = notification {
self.handle_finality_notification(&notification); self.handle_finality_notification(&notification);
} else { } else {
error!(target: "beefy", "🥩 Finality stream terminated, closing worker."); error!(target: LOG_TARGET, "🥩 Finality stream terminated, closing worker.");
return; return;
} }
}, },
@@ -879,7 +903,7 @@ where
justif = self.on_demand_justifications.next().fuse() => { justif = self.on_demand_justifications.next().fuse() => {
if let Some(justif) = justif { if let Some(justif) = justif {
if let Err(err) = self.triage_incoming_justif(justif) { if let Err(err) = self.triage_incoming_justif(justif) {
debug!(target: "beefy", "🥩 {}", err); debug!(target: LOG_TARGET, "🥩 {}", err);
} }
} }
}, },
@@ -888,10 +912,10 @@ where
// Block import justifications have already been verified to be valid // Block import justifications have already been verified to be valid
// by `BeefyBlockImport`. // by `BeefyBlockImport`.
if let Err(err) = self.triage_incoming_justif(justif) { if let Err(err) = self.triage_incoming_justif(justif) {
debug!(target: "beefy", "🥩 {}", err); debug!(target: LOG_TARGET, "🥩 {}", err);
} }
} else { } else {
error!(target: "beefy", "🥩 Block import stream terminated, closing worker."); error!(target: LOG_TARGET, "🥩 Block import stream terminated, closing worker.");
return; return;
} }
}, },
@@ -900,10 +924,10 @@ where
if let Some(vote) = vote { if let Some(vote) = vote {
// Votes have already been verified to be valid by the gossip validator. // Votes have already been verified to be valid by the gossip validator.
if let Err(err) = self.triage_incoming_vote(vote) { if let Err(err) = self.triage_incoming_vote(vote) {
debug!(target: "beefy", "🥩 {}", err); debug!(target: LOG_TARGET, "🥩 {}", err);
} }
} else { } else {
error!(target: "beefy", "🥩 Votes gossiping stream terminated, closing worker."); error!(target: LOG_TARGET, "🥩 Votes gossiping stream terminated, closing worker.");
return; return;
} }
}, },
@@ -937,18 +961,14 @@ where
// if the mandatory block (session_start) does not have a beefy justification yet, // if the mandatory block (session_start) does not have a beefy justification yet,
// we vote on it // we vote on it
let target = if best_beefy < session_start { let target = if best_beefy < session_start {
debug!( debug!(target: LOG_TARGET, "🥩 vote target - mandatory block: #{:?}", session_start,);
target: "beefy",
"🥩 vote target - mandatory block: #{:?}",
session_start,
);
session_start session_start
} else { } else {
let diff = best_grandpa.saturating_sub(best_beefy) + 1u32.into(); let diff = best_grandpa.saturating_sub(best_beefy) + 1u32.into();
let diff = diff.saturated_into::<u32>() / 2; let diff = diff.saturated_into::<u32>() / 2;
let target = best_beefy + min_delta.max(diff.next_power_of_two()).into(); let target = best_beefy + min_delta.max(diff.next_power_of_two()).into();
trace!( trace!(
target: "beefy", target: LOG_TARGET,
"🥩 vote target - diff: {:?}, next_power_of_two: {:?}, target block: #{:?}", "🥩 vote target - diff: {:?}, next_power_of_two: {:?}, target block: #{:?}",
diff, diff,
diff.next_power_of_two(), diff.next_power_of_two(),