diff --git a/Cargo.lock b/Cargo.lock index 15a3f87148..66db0b5102 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -2578,9 +2578,11 @@ version = "1.0.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "cb7330aeadfbe296029522e6c40f315320aba36fc43a5b3632f3795348f3bd22" dependencies = [ + "convert_case 0.6.0", "proc-macro2", "quote", "syn 2.0.77", + "unicode-xid", ] [[package]] @@ -2967,7 +2969,7 @@ dependencies = [ "cld", "committable", "contract-bindings", - "derive_more 0.99.18", + "derive_more 1.0.0", "dyn-clone 1.0.17 (registry+https://github.com/rust-lang/crates.io-index)", "ethers", "fluent-asserter", @@ -8798,7 +8800,7 @@ dependencies = [ "contract-bindings", "csv", "derivative", - "derive_more 0.99.18", + "derive_more 1.0.0", "dotenvy", "dyn-clone 1.0.17 (registry+https://github.com/rust-lang/crates.io-index)", "escargot", @@ -8870,7 +8872,7 @@ dependencies = [ "clap", "committable", "contract-bindings", - "derive_more 0.99.18", + "derive_more 1.0.0", "ethers", "futures", "hotshot-contract-adapter", diff --git a/Cargo.toml b/Cargo.toml index a1b3f17bdc..1bb42b0bc5 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -50,7 +50,7 @@ blake3 = "1.5" circular-buffer = "0.1.7" clap = { version = "4.4", features = ["derive", "env", "string"] } cld = "0.5" -derive_more = "0.99.17" +derive_more = { version = "1.0", features = ["full"] } es-version = { git = "https://github.com/EspressoSystems/es-version.git", branch = "main" } dotenvy = "0.15" dyn-clone = "1.0" diff --git a/sequencer/src/api.rs b/sequencer/src/api.rs index 4955d18610..6d91c5a418 100644 --- a/sequencer/src/api.rs +++ b/sequencer/src/api.rs @@ -293,7 +293,7 @@ impl< Ok(tree) } - #[tracing::instrument(skip(self))] + #[tracing::instrument(skip(self, instance))] async fn get_frontier( &self, instance: &NodeState, @@ -383,7 +383,7 @@ impl, V: Versions, P: SequencerPersistence> CatchupD retain_accounts(&state.fee_merkle_tree, accounts.iter().copied()) } - #[tracing::instrument(skip(self))] + #[tracing::instrument(skip(self, _instance))] async fn get_frontier( &self, _instance: &NodeState, diff --git a/sequencer/src/bin/keygen.rs b/sequencer/src/bin/keygen.rs index 79e6c3717d..593cefce21 100644 --- a/sequencer/src/bin/keygen.rs +++ b/sequencer/src/bin/keygen.rs @@ -19,11 +19,11 @@ use tracing::info_span; #[derive(Clone, Copy, Debug, Display, Default, ValueEnum)] enum Scheme { #[default] - #[display(fmt = "all")] + #[display("all")] All, - #[display(fmt = "bls")] + #[display("bls")] Bls, - #[display(fmt = "schnorr")] + #[display("schnorr")] Schnorr, } diff --git a/sequencer/src/bin/utils/keygen.rs b/sequencer/src/bin/utils/keygen.rs index db3d520947..211901d396 100644 --- a/sequencer/src/bin/utils/keygen.rs +++ b/sequencer/src/bin/utils/keygen.rs @@ -18,11 +18,11 @@ use tracing::info_span; #[derive(Clone, Copy, Debug, Display, Default, ValueEnum)] enum Scheme { #[default] - #[display(fmt = "all")] + #[display("all")] All, - #[display(fmt = "bls")] + #[display("bls")] Bls, - #[display(fmt = "schnorr")] + #[display("schnorr")] Schnorr, } diff --git a/sequencer/src/catchup.rs b/sequencer/src/catchup.rs index 7998ce4491..99301a1a45 100644 --- a/sequencer/src/catchup.rs +++ b/sequencer/src/catchup.rs @@ -15,6 +15,7 @@ use hotshot_types::{ data::ViewNumber, network::NetworkConfig, traits::node_implementation::ConsensusTime as _, ValidatorConfig, }; +use itertools::Itertools; use jf_merkle_tree::{prelude::MerkleNode, ForgetableMerkleTreeScheme, MerkleTreeScheme}; use serde::de::DeserializeOwned; use std::collections::HashMap; @@ -141,7 +142,7 @@ impl StateCatchup for StatePeers { let snapshot = match req.send().await { Ok(res) => res, Err(err) => { - tracing::warn!("Error fetching accounts from peer: {err:#}"); + tracing::info!(peer = %client.url, "error fetching accounts from peer: {err:#}"); continue; } }; @@ -149,11 +150,11 @@ impl StateCatchup for StatePeers { // Verify proofs. for account in accounts { let Some((proof, _)) = FeeAccountProof::prove(&snapshot, (*account).into()) else { - tracing::warn!("response from peer missing account {account}"); + tracing::warn!(peer = %client.url, "response from peer missing account {account}"); continue; }; if let Err(err) = proof.verify(&fee_merkle_tree_root) { - tracing::warn!("peer gave invalid proof for account {account}: {err:#}"); + tracing::warn!(peer = %client.url, "peer gave invalid proof for account {account}: {err:#}"); continue; } } @@ -163,7 +164,7 @@ impl StateCatchup for StatePeers { bail!("Could not fetch account from any peer"); } - #[tracing::instrument(skip(self, mt), height = mt.num_leaves())] + #[tracing::instrument(skip(self, _instance, mt))] async fn try_remember_blocks_merkle_tree( &self, _instance: &NodeState, @@ -172,7 +173,7 @@ impl StateCatchup for StatePeers { mt: &mut BlockMerkleTree, ) -> anyhow::Result<()> { for client in self.clients.iter() { - tracing::info!("Fetching frontier from {}", client.url); + tracing::debug!(peer = %client.url, "fetching frontier from peer"); match client .get::(&format!("catchup/{height}/{}/blocks", view.u64())) .send() @@ -180,19 +181,19 @@ impl StateCatchup for StatePeers { { Ok(frontier) => { let Some(elem) = frontier.elem() else { - tracing::warn!("Provided frontier is missing leaf element"); + tracing::warn!(peer = %client.url, "Provided frontier is missing leaf element"); continue; }; match mt.remember(mt.num_leaves() - 1, *elem, &frontier) { Ok(_) => return Ok(()), Err(err) => { - tracing::warn!("Error verifying block proof: {}", err); + tracing::warn!(peer = %client.url, "Error verifying block proof: {err:#}"); continue; } } } Err(err) => { - tracing::warn!("Error fetching blocks from peer: {}", err); + tracing::info!(peer = %client.url, "error fetching blocks from peer: {err:#}"); } } } @@ -233,6 +234,16 @@ impl StateCatchup for StatePeers { fn backoff(&self) -> &BackoffParams { &self.backoff } + + fn name(&self) -> String { + format!( + "StatePeers({})", + self.clients + .iter() + .map(|client| client.url.to_string()) + .join(",") + ) + } } pub(crate) trait CatchupStorage: Sync { @@ -344,7 +355,7 @@ impl SqlStateCatchup { #[async_trait] impl StateCatchup for SqlStateCatchup where - T: CatchupStorage + std::fmt::Debug + Send + Sync, + T: CatchupStorage + Send + Sync, { // TODO: add a test for the account proof validation // issue # 2102 (https://github.com/EspressoSystems/espresso-sequencer/issues/2102) @@ -364,7 +375,7 @@ where .0) } - #[tracing::instrument(skip(self))] + #[tracing::instrument(skip(self, instance, mt))] async fn try_remember_blocks_merkle_tree( &self, instance: &NodeState, @@ -410,6 +421,10 @@ where fn backoff(&self) -> &BackoffParams { &self.backoff } + + fn name(&self) -> String { + "SqlStateCatchup".into() + } } /// Disable catchup entirely. @@ -479,4 +494,8 @@ impl StateCatchup for NullStateCatchup { fn backoff(&self) -> &BackoffParams { &self.backoff } + + fn name(&self) -> String { + "NullStateCatchup".into() + } } diff --git a/sequencer/src/context.rs b/sequencer/src/context.rs index ba726bd43c..2705680e82 100644 --- a/sequencer/src/context.rs +++ b/sequencer/src/context.rs @@ -40,6 +40,7 @@ use hotshot_types::{ PeerConfig, }; use std::time::Duration; +use tracing::{Instrument, Level}; use url::Url; use crate::{ @@ -319,6 +320,17 @@ impl, P: SequencerPersistence, V: Versions> Sequence self.tasks.spawn(name, task); } + /// Spawn a short-lived background task attached to this context. + /// + /// When this context is dropped or [`shut_down`](Self::shut_down), background tasks will be + /// cancelled in the reverse order that they were spawned. + /// + /// The only difference between a short-lived background task and a [long-lived](Self::spawn) + /// one is how urgently logging related to the task is treated. + pub fn spawn_short_lived(&mut self, name: impl Display, task: impl Future + Send + 'static) { + self.tasks.spawn_short_lived(name, task); + } + /// Stop participating in consensus. pub async fn shut_down(&mut self) { tracing::info!("shutting down SequencerContext"); @@ -427,7 +439,7 @@ async fn fetch_proposals( // to the anchor. This allows state replay from the decided state. let parent_view = proposal.data.justify_qc.view_number; let parent_leaf = proposal.data.justify_qc.data.leaf_commit; - tasks.spawn( + tasks.spawn_short_lived( format!("fetch proposal {parent_view:?},{parent_leaf}"), fetch_proposal_chain( consensus.clone(), @@ -473,7 +485,7 @@ async fn fetch_proposal_chain( { Ok(future) => future, Err(err) => { - tracing::warn!(?view, %leaf, "failed to request proposal: {err:#}"); + tracing::info!(?view, %leaf, "failed to request proposal: {err:#}"); sleep(Duration::from_secs(1)).await; continue; } @@ -481,12 +493,12 @@ async fn fetch_proposal_chain( let proposal = match async_timeout(Duration::from_secs(30), future).await { Ok(Ok(proposal)) => proposal, Ok(Err(err)) => { - tracing::warn!("error fetching proposal: {err:#}"); + tracing::info!("error fetching proposal: {err:#}"); sleep(Duration::from_secs(1)).await; continue; } Err(_) => { - tracing::warn!("timed out fetching proposal"); + tracing::info!("timed out fetching proposal"); sleep(Duration::from_secs(1)).await; continue; } @@ -523,7 +535,7 @@ async fn fetch_proposal_chain( consensus .update_saved_leaves(leaf, &handle.hotshot.upgrade_lock) .await; - tracing::info!( + tracing::debug!( ?view, "added view to validated state map view proposal fetcher" ); @@ -550,21 +562,43 @@ async fn load_anchor_view(persistence: &impl SequencerPersistence) -> ViewNumber #[derive(Debug, Default)] pub(crate) struct TaskList(Vec<(String, JoinHandle<()>)>); +macro_rules! spawn_with_log_level { + ($this:expr, $lvl:expr, $name:expr, $task: expr) => { + let name = $name.to_string(); + let task = { + let name = name.clone(); + let span = tracing::span!($lvl, "background task", name); + spawn( + async move { + tracing::event!($lvl, "spawning background task"); + $task.await; + tracing::event!($lvl, "background task exited"); + } + .instrument(span), + ) + }; + $this.0.push((name, task)); + }; +} + impl TaskList { /// Spawn a background task attached to this [`TaskList`]. /// /// When this [`TaskList`] is dropped or [`shut_down`](Self::shut_down), background tasks will /// be cancelled in the reverse order that they were spawned. pub fn spawn(&mut self, name: impl Display, task: impl Future + Send + 'static) { - let name = name.to_string(); - let task = { - let name = name.clone(); - spawn(async move { - task.await; - tracing::info!(name, "background task exited"); - }) - }; - self.0.push((name, task)); + spawn_with_log_level!(self, Level::INFO, name, task); + } + + /// Spawn a short-lived background task attached to this [`TaskList`]. + /// + /// When this [`TaskList`] is dropped or [`shut_down`](Self::shut_down), background tasks will + /// be cancelled in the reverse order that they were spawned. + /// + /// The only difference between a short-lived background task and a [long-lived](Self::spawn) + /// one is how urgently logging related to the task is treated. + pub fn spawn_short_lived(&mut self, name: impl Display, task: impl Future + Send + 'static) { + spawn_with_log_level!(self, Level::DEBUG, name, task); } /// Stop all background tasks. diff --git a/types/src/v0/impls/instance_state.rs b/types/src/v0/impls/instance_state.rs index b8144770e2..b6385e81a4 100644 --- a/types/src/v0/impls/instance_state.rs +++ b/types/src/v0/impls/instance_state.rs @@ -12,11 +12,12 @@ use super::state::ValidatedState; /// Represents the immutable state of a node. /// /// For mutable state, use `ValidatedState`. -#[derive(Debug, Clone)] +#[derive(derive_more::Debug, Clone)] pub struct NodeState { pub node_id: u64, pub chain_config: crate::v0_3::ChainConfig, pub l1_client: L1Client, + #[debug("{}", peers.name())] pub peers: Arc, pub genesis_header: GenesisHeader, pub genesis_state: ValidatedState, @@ -254,5 +255,9 @@ pub mod mock { fn backoff(&self) -> &BackoffParams { &self.backoff } + + fn name(&self) -> String { + "MockStateCatchup".into() + } } } diff --git a/types/src/v0/impls/l1.rs b/types/src/v0/impls/l1.rs index 84b098087e..229853153c 100644 --- a/types/src/v0/impls/l1.rs +++ b/types/src/v0/impls/l1.rs @@ -303,7 +303,7 @@ impl L1Client { // Update the state snapshot; let mut state = state.lock().await; if head > state.snapshot.head { - tracing::info!(head, old_head = state.snapshot.head, "L1 head updated"); + tracing::debug!(head, old_head = state.snapshot.head, "L1 head updated"); state.snapshot.head = head; // Emit an event about the new L1 head. Ignore send errors; it just means no // one is listening to events right now. @@ -326,7 +326,7 @@ impl L1Client { .ok(); } } - tracing::info!("updated L1 snapshot to {:?}", state.snapshot); + tracing::debug!("updated L1 snapshot to {:?}", state.snapshot); } tracing::error!("L1 block stream ended unexpectedly, trying to re-establish"); diff --git a/types/src/v0/traits.rs b/types/src/v0/traits.rs index e8ee45a3aa..d16cff30eb 100644 --- a/types/src/v0/traits.rs +++ b/types/src/v0/traits.rs @@ -21,6 +21,7 @@ use hotshot_types::{ }, utils::View, }; +use itertools::Itertools; use serde::{de::DeserializeOwned, Serialize}; use crate::{ @@ -31,7 +32,7 @@ use crate::{ use super::impls::NodeState; #[async_trait] -pub trait StateCatchup: Send + Sync + std::fmt::Debug { +pub trait StateCatchup: Send + Sync { /// Try to fetch the given accounts state, failing without retrying if unable. async fn try_fetch_accounts( &self, @@ -122,6 +123,7 @@ pub trait StateCatchup: Send + Sync + std::fmt::Debug { } fn backoff(&self) -> &BackoffParams; + fn name(&self) -> String; } #[async_trait] @@ -193,6 +195,10 @@ impl StateCatchup for Box { fn backoff(&self) -> &BackoffParams { (**self).backoff() } + + fn name(&self) -> String { + (**self).name() + } } #[async_trait] @@ -264,6 +270,10 @@ impl StateCatchup for Arc { fn backoff(&self) -> &BackoffParams { (**self).backoff() } + + fn name(&self) -> String { + (**self).name() + } } /// Catchup from multiple providers tries each provider in a round robin fashion until it succeeds. @@ -285,7 +295,11 @@ impl StateCatchup for Vec { { Ok(tree) => return Ok(tree), Err(err) => { - tracing::warn!(?accounts, ?provider, "failed to fetch accounts: {err:#}"); + tracing::info!( + ?accounts, + provider = provider.name(), + "failed to fetch accounts: {err:#}" + ); } } } @@ -293,7 +307,7 @@ impl StateCatchup for Vec { bail!("could not fetch account from any provider"); } - #[tracing::instrument(skip(self, mt))] + #[tracing::instrument(skip(self, instance, mt))] async fn try_remember_blocks_merkle_tree( &self, instance: &NodeState, @@ -308,7 +322,10 @@ impl StateCatchup for Vec { { Ok(()) => return Ok(()), Err(err) => { - tracing::warn!(?provider, "failed to fetch frontier: {err:#}"); + tracing::info!( + provider = provider.name(), + "failed to fetch frontier: {err:#}" + ); } } } @@ -324,7 +341,10 @@ impl StateCatchup for Vec { match provider.try_fetch_chain_config(commitment).await { Ok(cf) => return Ok(cf), Err(err) => { - tracing::warn!(?provider, "failed to fetch chain config: {err:#}"); + tracing::info!( + provider = provider.name(), + "failed to fetch chain config: {err:#}" + ); } } } @@ -339,6 +359,10 @@ impl StateCatchup for Vec { .max() .expect("provider list not empty") } + + fn name(&self) -> String { + format!("[{}]", self.iter().map(StateCatchup::name).join(",")) + } } #[async_trait] diff --git a/types/src/v0/utils.rs b/types/src/v0/utils.rs index ff7652f365..303899b3a3 100644 --- a/types/src/v0/utils.rs +++ b/types/src/v0/utils.rs @@ -2,7 +2,7 @@ use anyhow::Context; use async_std::task::sleep; use bytesize::ByteSize; use clap::Parser; -use derive_more::{Display, From, Into}; +use derive_more::{From, Into}; use futures::future::BoxFuture; use rand::Rng; use sequencer_utils::{impl_serde_from_string_or_integer, ser::FromStringOrInteger}; @@ -43,8 +43,8 @@ pub struct GenesisHeader { pub timestamp: Timestamp, } -#[derive(Hash, Copy, Clone, Debug, Display, PartialEq, Eq, From, Into)] -#[display(fmt = "{}", "_0.format(&TimestampFormat).unwrap()")] +#[derive(Hash, Copy, Clone, Debug, derive_more::Display, PartialEq, Eq, From, Into)] +#[display("{}", _0.format(&TimestampFormat).unwrap())] pub struct Timestamp(OffsetDateTime); impl_serde_from_string_or_integer!(Timestamp); diff --git a/types/src/v0/v0_1/chain_config.rs b/types/src/v0/v0_1/chain_config.rs index d6f5f8bc29..8ed0e7a908 100644 --- a/types/src/v0/v0_1/chain_config.rs +++ b/types/src/v0/v0_1/chain_config.rs @@ -8,11 +8,11 @@ use serde::{Deserialize, Serialize}; use crate::{FeeAccount, FeeAmount}; #[derive(Default, Hash, Copy, Clone, Debug, Display, PartialEq, Eq, From, Into)] -#[display(fmt = "{_0}")] +#[display("{_0}")] pub struct ChainId(pub U256); #[derive(Hash, Copy, Clone, Debug, Default, Display, PartialEq, Eq, From, Into, Deref)] -#[display(fmt = "{_0}")] +#[display("{_0}")] pub struct BlockSize(pub(crate) u64); /// Global variables for an Espresso blockchain. diff --git a/types/src/v0/v0_1/fee_info.rs b/types/src/v0/v0_1/fee_info.rs index d4354e2845..81e3a55fff 100644 --- a/types/src/v0/v0_1/fee_info.rs +++ b/types/src/v0/v0_1/fee_info.rs @@ -25,7 +25,7 @@ use crate::FeeMerkleTree; From, Into, )] -#[display(fmt = "{_0}")] +#[display("{_0}")] pub struct FeeAmount(pub U256); // New Type for `Address` in order to implement `CanonicalSerialize` and @@ -46,7 +46,7 @@ pub struct FeeAmount(pub U256); From, Into, )] -#[display(fmt = "{_0:x}")] +#[display("{_0:x}")] pub struct FeeAccount(pub Address); #[derive( diff --git a/types/src/v0/v0_1/transaction.rs b/types/src/v0/v0_1/transaction.rs index cbdc301c0a..9e09bc155a 100644 --- a/types/src/v0/v0_1/transaction.rs +++ b/types/src/v0/v0_1/transaction.rs @@ -37,5 +37,5 @@ pub struct Transaction { PartialOrd, Ord, )] -#[display(fmt = "{_0}")] +#[display("{_0}")] pub struct NamespaceId(pub(crate) u64); diff --git a/utils/src/deployer.rs b/utils/src/deployer.rs index a42d4c01dc..aa82bf3ef2 100644 --- a/utils/src/deployer.rs +++ b/utils/src/deployer.rs @@ -53,17 +53,17 @@ pub struct DeployedContracts { /// An identifier for a particular contract. #[derive(Clone, Copy, Debug, Display, PartialEq, Eq, Hash)] pub enum Contract { - #[display(fmt = "ESPRESSO_SEQUENCER_PLONK_VERIFIER_ADDRESS")] + #[display("ESPRESSO_SEQUENCER_PLONK_VERIFIER_ADDRESS")] PlonkVerifier, - #[display(fmt = "ESPRESSO_SEQUENCER_LIGHT_CLIENT_STATE_UPDATE_VK_ADDRESS")] + #[display("ESPRESSO_SEQUENCER_LIGHT_CLIENT_STATE_UPDATE_VK_ADDRESS")] StateUpdateVK, - #[display(fmt = "ESPRESSO_SEQUENCER_LIGHT_CLIENT_ADDRESS")] + #[display("ESPRESSO_SEQUENCER_LIGHT_CLIENT_ADDRESS")] LightClient, - #[display(fmt = "ESPRESSO_SEQUENCER_LIGHT_CLIENT_PROXY_ADDRESS")] + #[display("ESPRESSO_SEQUENCER_LIGHT_CLIENT_PROXY_ADDRESS")] LightClientProxy, - #[display(fmt = "ESPRESSO_SEQUENCER_FEE_CONTRACT_ADDRESS")] + #[display("ESPRESSO_SEQUENCER_FEE_CONTRACT_ADDRESS")] FeeContract, - #[display(fmt = "ESPRESSO_SEQUENCER_FEE_CONTRACT_PROXY_ADDRESS")] + #[display("ESPRESSO_SEQUENCER_FEE_CONTRACT_PROXY_ADDRESS")] FeeContractProxy, }