zecfoundation
/
zebra
mirror of https://github.com/ZcashFoundation/zebra.git
1
0
Fork 0
Code Issues Projects Releases Wiki Activity

Reduce log level of components (#3418) 

* reduce log level of components

* revert some log downgrades

* dedupe log
This commit is contained in:
Alfredo Garcia 2022-01-28 14:24:53 -03:00 committed by GitHub
parent 4f0d7bd737
commit 3c1ba59001
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
11 changed files with 80 additions and 79 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
zebrad/src/components/inbound.rs
View File

@ -328,7 +328,7 @@ impl Service<zn::Request> for Inbound {
if !peers.is_empty() {
async { Ok(zn::Response::Peers(peers)) }.boxed()
} else {
info!("ignoring `Peers` request from remote peer because our address book is empty");
debug!("ignoring `Peers` request from remote peer because our address book is empty");
async { Ok(zn::Response::Nil) }.boxed()
}
}

14
zebrad/src/components/inbound/downloads.rs
View File

@ -177,7 +177,7 @@ where
#[instrument(skip(self, hash), fields(hash = %hash))]
pub fn download_and_verify(&mut self, hash: block::Hash) -> DownloadAction {
if self.cancel_handles.contains_key(&hash) {
tracing::debug!(
debug!(
?hash,
queue_len = self.pending.len(),
?MAX_INBOUND_CONCURRENCY,
@ -191,7 +191,7 @@ where
}
if self.pending.len() >= MAX_INBOUND_CONCURRENCY {
tracing::debug!(
debug!(
?hash,
queue_len = self.pending.len(),
?MAX_INBOUND_CONCURRENCY,
@ -277,7 +277,7 @@ where
if let Some(block_height) = block.coinbase_height() {
if block_height > max_lookahead_height {
tracing::info!(
debug!(
?hash,
?block_height,
?tip_height,
@ -289,7 +289,7 @@ where
Err("gossiped block height too far ahead")?;
} else if block_height < min_accepted_height {
tracing::debug!(
debug!(
?hash,
?block_height,
?tip_height,
@ -302,7 +302,7 @@ where
Err("gossiped block height behind the finalized tip")?;
}
} else {
tracing::info!(
debug!(
?hash,
"gossiped block with no height: dropped downloaded block"
);
@ -327,7 +327,7 @@ where
tokio::select! {
biased;
_ = &mut cancel_rx => {
tracing::trace!("task cancelled prior to completion");
trace!("task cancelled prior to completion");
metrics::counter!("gossip.cancelled.count", 1);
Err(("canceled".into(), hash))
}
@ -341,7 +341,7 @@ where
"blocks are only queued once"
);
tracing::debug!(
debug!(
?hash,
queue_len = self.pending.len(),
?MAX_INBOUND_CONCURRENCY,

3
zebrad/src/components/mempool/crawler.rs
View File

@ -219,8 +219,7 @@ where
// log individual response errors
match result {
Ok(response) => self.handle_response(response).await?,
// TODO: Reduce the log level of the errors (#2655).
Err(error) => info!("Failed to crawl peer for mempool transactions: {}", error),
Err(error) => debug!("Failed to crawl peer for mempool transactions: {}", error),
}
}

10
zebrad/src/components/mempool/downloads.rs
View File

@ -257,7 +257,7 @@ where
let txid = gossiped_tx.id();
if self.cancel_handles.contains_key(&txid) {
tracing::debug!(
debug!(
?txid,
queue_len = self.pending.len(),
?MAX_INBOUND_CONCURRENCY,
@ -272,7 +272,7 @@ where
}
if self.pending.len() >= MAX_INBOUND_CONCURRENCY {
tracing::info!(
debug!(
?txid,
queue_len = self.pending.len(),
?MAX_INBOUND_CONCURRENCY,
@ -350,7 +350,7 @@ where
})
.await;
tracing::debug!(?txid, ?result, "verified transaction for the mempool");
debug!(?txid, ?result, "verified transaction for the mempool");
result.map_err(|e| TransactionDownloadVerifyError::Invalid(e.into()))
}
@ -372,7 +372,7 @@ where
tokio::select! {
biased;
_ = &mut cancel_rx => {
tracing::trace!("task cancelled prior to completion");
trace!("task cancelled prior to completion");
metrics::counter!("mempool.cancelled.verify.tasks.total", 1);
Err((TransactionDownloadVerifyError::Cancelled, txid))
}
@ -386,7 +386,7 @@ where
"transactions are only queued once"
);
tracing::debug!(
debug!(
?txid,
queue_len = self.pending.len(),
?MAX_INBOUND_CONCURRENCY,

99
zebrad/src/components/sync.rs
View File

@ -354,7 +354,7 @@ where
'sync: loop {
if started_once {
tracing::info!(timeout = ?SYNC_RESTART_DELAY, "waiting to restart sync");
info!(timeout = ?SYNC_RESTART_DELAY, "waiting to restart sync");
self.prospective_tips = HashSet::new();
self.downloads.cancel_all();
self.update_metrics();
@ -363,9 +363,9 @@ where
started_once = true;
}
tracing::info!("starting sync, obtaining new tips");
info!("starting sync, obtaining new tips");
if let Err(e) = self.obtain_tips().await {
tracing::warn!(?e, "error obtaining tips");
warn!(?e, "error obtaining tips");
continue 'sync;
}
self.update_metrics();
@ -375,7 +375,7 @@ where
while let Poll::Ready(Some(rsp)) = futures::poll!(self.downloads.next()) {
match rsp {
Ok(hash) => {
tracing::trace!(?hash, "verified and committed block to state");
trace!(?hash, "verified and committed block to state");
}
Err(e) => {
if Self::should_restart_sync(e) {
@ -399,7 +399,7 @@ where
);
}
while self.downloads.in_flight() > self.lookahead_limit {
tracing::trace!(
trace!(
tips.len = self.prospective_tips.len(),
in_flight = self.downloads.in_flight(),
lookahead_limit = self.lookahead_limit,
@ -408,7 +408,7 @@ where
match self.downloads.next().await.expect("downloads is nonempty") {
Ok(hash) => {
tracing::trace!(?hash, "verified and committed block to state");
trace!(?hash, "verified and committed block to state");
}
Err(e) => {
@ -421,7 +421,7 @@ where
}
// Once we're below the lookahead limit, we can keep extending the tips.
tracing::info!(
info!(
tips.len = self.prospective_tips.len(),
in_flight = self.downloads.in_flight(),
lookahead_limit = self.lookahead_limit,
@ -429,13 +429,13 @@ where
);
if let Err(e) = self.extend_tips().await {
tracing::warn!(?e, "error extending tips");
warn!(?e, "error extending tips");
continue 'sync;
}
self.update_metrics();
}
tracing::info!("exhausted prospective tip set");
info!("exhausted prospective tip set");
}
}
@ -458,8 +458,11 @@ where
})
.map_err(|e| eyre!(e))?;
tracing::info!(tip = ?block_locator.first().unwrap(), "trying to obtain new chain tips");
tracing::debug!(?block_locator, "got block locator");
debug!(
tip = ?block_locator.first().expect("we have at least one block locator object"),
?block_locator,
"got block locator and trying to obtain new chain tips"
);
let mut requests = FuturesUnordered::new();
for attempt in 0..FANOUT {
@ -486,7 +489,7 @@ where
.map_err::<Report, _>(|e| eyre!(e))
{
Ok(zn::Response::BlockHashes(hashes)) => {
tracing::trace!(?hashes);
trace!(?hashes);
// zcashd sometimes appends an unrelated hash at the start
// or end of its response.
@ -512,7 +515,7 @@ where
}
}
tracing::debug!(hashes.len = ?hashes.len(), ?first_unknown);
debug!(hashes.len = ?hashes.len(), ?first_unknown);
let unknown_hashes = if let Some(index) = first_unknown {
&hashes[index..]
@ -520,7 +523,7 @@ where
continue;
};
tracing::trace!(?unknown_hashes);
trace!(?unknown_hashes);
let new_tip = if let Some(end) = unknown_hashes.rchunks_exact(2).next() {
CheckedTip {
@ -528,20 +531,20 @@ where
expected_next: end[1],
}
} else {
tracing::debug!("discarding response that extends only one block");
debug!("discarding response that extends only one block");
continue;
};
// Make sure we get the same tips, regardless of the
// order of peer responses
if !download_set.contains(&new_tip.expected_next) {
tracing::debug!(?new_tip,
debug!(?new_tip,
"adding new prospective tip, and removing existing tips in the new block hash list");
self.prospective_tips
.retain(|t| !unknown_hashes.contains(&t.expected_next));
self.prospective_tips.insert(new_tip);
} else {
tracing::debug!(
debug!(
?new_tip,
"discarding prospective tip: already in download set"
);
@ -554,27 +557,27 @@ where
download_set.extend(unknown_hashes);
let new_download_len = download_set.len();
let new_hashes = new_download_len - prev_download_len;
tracing::debug!(new_hashes, "added hashes to download set");
debug!(new_hashes, "added hashes to download set");
metrics::histogram!("sync.obtain.response.hash.count", new_hashes as f64);
}
Ok(_) => unreachable!("network returned wrong response"),
// We ignore this error because we made multiple fanout requests.
Err(e) => tracing::debug!(?e),
Err(e) => debug!(?e),
}
}
tracing::debug!(?self.prospective_tips);
debug!(?self.prospective_tips);
// Check that the new tips we got are actually unknown.
for hash in &download_set {
tracing::debug!(?hash, "checking if state contains hash");
debug!(?hash, "checking if state contains hash");
if self.state_contains(*hash).await? {
return Err(eyre!("queued download of hash behind our chain tip"));
}
}
let new_downloads = download_set.len();
tracing::debug!(new_downloads, "queueing new downloads");
debug!(new_downloads, "queueing new downloads");
metrics::gauge!("sync.obtain.queued.hash.count", new_downloads as f64);
// security: use the actual number of new downloads from all peers,
@ -591,9 +594,9 @@ where
let tips = std::mem::take(&mut self.prospective_tips);
let mut download_set = IndexSet::new();
tracing::info!(tips = ?tips.len(), "trying to extend chain tips");
debug!(tips = ?tips.len(), "trying to extend chain tips");
for tip in tips {
tracing::debug!(?tip, "asking peers to extend chain tip");
debug!(?tip, "asking peers to extend chain tip");
let mut responses = FuturesUnordered::new();
for attempt in 0..FANOUT {
if attempt > 0 {
@ -617,8 +620,8 @@ where
.map_err::<Report, _>(|e| eyre!(e))
{
Ok(zn::Response::BlockHashes(hashes)) => {
tracing::debug!(first = ?hashes.first(), len = ?hashes.len());
tracing::trace!(?hashes);
debug!(first = ?hashes.first(), len = ?hashes.len());
trace!(?hashes);
// zcashd sometimes appends an unrelated hash at the
// start or end of its response. Check the first hash
@ -631,7 +634,7 @@ where
[first_hash, expected_hash, rest @ ..]
if expected_hash == &tip.expected_next =>
{
tracing::debug!(?first_hash,
debug!(?first_hash,
?tip.expected_next,
?tip.tip,
"unexpected first hash, but the second matches: using the hashes after the match");
@ -640,14 +643,14 @@ where
// We ignore these responses
[] => continue,
[single_hash] => {
tracing::debug!(?single_hash,
debug!(?single_hash,
?tip.expected_next,
?tip.tip,
"discarding response containing a single unexpected hash");
continue;
}
[first_hash, second_hash, rest @ ..] => {
tracing::debug!(?first_hash,
debug!(?first_hash,
?second_hash,
rest_len = ?rest.len(),
?tip.expected_next,
@ -672,22 +675,22 @@ where
expected_next: end[1],
}
} else {
tracing::debug!("discarding response that extends only one block");
debug!("discarding response that extends only one block");
continue;
};
tracing::trace!(?unknown_hashes);
trace!(?unknown_hashes);
// Make sure we get the same tips, regardless of the
// order of peer responses
if !download_set.contains(&new_tip.expected_next) {
tracing::debug!(?new_tip,
debug!(?new_tip,
"adding new prospective tip, and removing any existing tips in the new block hash list");
self.prospective_tips
.retain(|t| !unknown_hashes.contains(&t.expected_next));
self.prospective_tips.insert(new_tip);
} else {
tracing::debug!(
debug!(
?new_tip,
"discarding prospective tip: already in download set"
);
@ -700,18 +703,18 @@ where
download_set.extend(unknown_hashes);
let new_download_len = download_set.len();
let new_hashes = new_download_len - prev_download_len;
tracing::debug!(new_hashes, "added hashes to download set");
debug!(new_hashes, "added hashes to download set");
metrics::histogram!("sync.extend.response.hash.count", new_hashes as f64);
}
Ok(_) => unreachable!("network returned wrong response"),
// We ignore this error because we made multiple fanout requests.
Err(e) => tracing::debug!(?e),
Err(e) => debug!(?e),
}
}
}
let new_downloads = download_set.len();
tracing::debug!(new_downloads, "queueing new downloads");
debug!(new_downloads, "queueing new downloads");
metrics::gauge!("sync.extend.queued.hash.count", new_downloads as f64);
// security: use the actual number of new downloads from all peers,
@ -734,15 +737,15 @@ where
//
// So we just download and verify the genesis block here.
while !self.state_contains(self.genesis_hash).await? {
tracing::info!("starting genesis block download and verify");
info!("starting genesis block download and verify");
self.downloads
.download_and_verify(self.genesis_hash)
.await
.map_err(|e| eyre!(e))?;
match self.downloads.next().await.expect("downloads is nonempty") {
Ok(hash) => tracing::trace!(?hash, "verified and committed block to state"),
Ok(hash) => trace!(?hash, "verified and committed block to state"),
Err(e) => {
tracing::warn!(?e, "could not download or verify genesis block, retrying");
warn!(?e, "could not download or verify genesis block, retrying");
tokio::time::sleep(GENESIS_TIMEOUT_RETRY).await;
}
}
@ -753,7 +756,7 @@ where
/// Queue download and verify tasks for each block that isn't currently known to our node
async fn request_blocks(&mut self, hashes: IndexSet<block::Hash>) -> Result<(), Report> {
tracing::debug!(hashes.len = hashes.len(), "requesting blocks");
debug!(hashes.len = hashes.len(), "requesting blocks");
for hash in hashes.into_iter() {
self.downloads.download_and_verify(hash).await?;
}
@ -801,7 +804,7 @@ where
BlockDownloadVerifyError::Invalid(VerifyChainError::Checkpoint(
VerifyCheckpointError::AlreadyVerified { .. },
)) => {
tracing::debug!(error = ?e, "block was already verified, possibly from a previous sync run, continuing");
debug!(error = ?e, "block was already verified, possibly from a previous sync run, continuing");
false
}
BlockDownloadVerifyError::Invalid(VerifyChainError::Block(
@ -809,16 +812,16 @@ where
source: BlockError::AlreadyInChain(_, _),
},
)) => {
tracing::debug!(error = ?e, "block is already in chain, possibly from a previous sync run, continuing");
debug!(error = ?e, "block is already in chain, possibly from a previous sync run, continuing");
false
}
BlockDownloadVerifyError::CancelledDuringDownload
| BlockDownloadVerifyError::CancelledDuringVerification => {
tracing::debug!(error = ?e, "block verification was cancelled, continuing");
debug!(error = ?e, "block verification was cancelled, continuing");
false
}
BlockDownloadVerifyError::BehindTipHeightLimit => {
tracing::debug!(
debug!(
error = ?e,
"block height is behind the current state tip, \
assuming the syncer will eventually catch up to the state, continuing"
@ -831,7 +834,7 @@ where
VerifyBlockError::Commit(ref source),
)) if format!("{:?}", source).contains("block is already committed to the state") => {
// TODO: improve this by checking the type (#2908)
tracing::debug!(error = ?e, "block is already committed, possibly from a previous sync run, continuing");
debug!(error = ?e, "block is already committed, possibly from a previous sync run, continuing");
false
}
BlockDownloadVerifyError::DownloadFailed(ref source)
@ -839,7 +842,7 @@ where
{
// TODO: improve this by checking the type (#2908)
// restart after a certain number of NotFound errors?
tracing::debug!(error = ?e, "block was not found, possibly from a peer that doesn't have the block yet, continuing");
debug!(error = ?e, "block was not found, possibly from a peer that doesn't have the block yet, continuing");
false
}
@ -860,14 +863,14 @@ where
|| err_str.contains("block is already committed to the state")
|| err_str.contains("NotFound")
{
tracing::error!(?e,
error!(?e,
"a BlockDownloadVerifyError that should have been filtered out was detected, \
which possibly indicates a programming error in the downcast inside \
zebrad::components::sync::downloads::Downloads::download_and_verify"
)
}
tracing::warn!(?e, "error downloading and verifying block");
warn!(?e, "error downloading and verifying block");
true
}
}

18
zebrad/src/components/sync/downloads.rs
View File

@ -228,14 +228,14 @@ where
// if we waited for readiness and did the service call in the spawned
// tasks, all of the spawned tasks would race each other waiting for the
// network to become ready.
tracing::debug!("waiting to request block");
debug!("waiting to request block");
let block_req = self
.network
.ready()
.await
.map_err(|e| eyre!(e))?
.call(zn::Request::BlocksByHash(std::iter::once(hash).collect()));
tracing::debug!("requested block");
debug!("requested block");
// This oneshot is used to signal cancellation to the download task.
let (cancel_tx, mut cancel_rx) = oneshot::channel::<()>();
@ -250,7 +250,7 @@ where
let rsp = tokio::select! {
biased;
_ = &mut cancel_rx => {
tracing::trace!("task cancelled prior to download completion");
trace!("task cancelled prior to download completion");
metrics::counter!("sync.cancelled.download.count", 1);
return Err(BlockDownloadVerifyError::CancelledDuringDownload)
}
@ -309,13 +309,15 @@ where
if let Some(block_height) = block.coinbase_height() {
if block_height > max_lookahead_height {
tracing::info!(
info!(
?hash,
?block_height,
?tip_height,
?max_lookahead_height,
lookahead_limit = ?lookahead_limit,
"synced block height too far ahead of the tip: dropped downloaded block"
"synced block height too far ahead of the tip: dropped downloaded block. \
Hint: Try increasing the value of the lookahead_limit field \
in the sync section of the configuration file."
);
metrics::counter!("sync.max.height.limit.dropped.block.count", 1);
@ -330,7 +332,7 @@ where
// (or blocks far ahead of the current state tip).
Err(BlockDownloadVerifyError::AboveLookaheadHeightLimit)?;
} else if block_height < min_accepted_height {
tracing::debug!(
debug!(
?hash,
?block_height,
?tip_height,
@ -343,7 +345,7 @@ where
Err(BlockDownloadVerifyError::BehindTipHeightLimit)?;
}
} else {
tracing::info!(
debug!(
?hash,
"synced block with no height: dropped downloaded block"
);
@ -361,7 +363,7 @@ where
let verification = tokio::select! {
biased;
_ = &mut cancel_rx => {
tracing::trace!("task cancelled prior to verification");
trace!("task cancelled prior to verification");
metrics::counter!("sync.cancelled.verify.count", 1);
return Err(BlockDownloadVerifyError::CancelledDuringVerification)
}

2
zebrad/src/components/sync/gossip.rs
View File

@ -72,7 +72,7 @@ where
let request = zn::Request::AdvertiseBlock(tip_action.best_tip_hash());
let height = tip_action.best_tip_height();
info!(?height, ?request, "sending committed block broadcast");
debug!(?height, ?request, "sending committed block broadcast");
// broadcast requests don't return errors, and we'd just want to ignore them anyway
let _ = broadcast_network

3
zebrad/src/components/sync/recent_sync_lengths.rs
View File

@ -76,8 +76,7 @@ impl RecentSyncLengths {
self.recent_lengths.truncate(Self::MAX_RECENT_LENGTHS);
// TODO: remove or downgrade this log to debug
tracing::info!(
debug!(
recent_lengths = ?self.recent_lengths,
"sending recent sync lengths"
);

4
zebrad/src/components/tokio.rs
View File

@ -61,7 +61,7 @@ impl RuntimeRun for Runtime {
});
// Don't wait for long blocking tasks before shutting down
tracing::info!(
info!(
?TOKIO_SHUTDOWN_TIMEOUT,
"waiting for async tokio tasks to shut down"
);
@ -82,7 +82,6 @@ impl RuntimeRun for Runtime {
#[cfg(unix)]
mod imp {
use tokio::signal::unix::{signal, SignalKind};
use tracing::info;
pub(super) async fn shutdown() {
// If both signals are received, select! chooses one of them at random.
@ -115,7 +114,6 @@ mod imp {
#[cfg(not(unix))]
mod imp {
use tracing::info;
pub(super) async fn shutdown() {
// Wait for Ctrl-C in Windows terminals.

2
zebrad/src/components/tracing/component.rs
View File

@ -97,7 +97,7 @@ impl<A: abscissa_core::Application> Component<A> for Tracing {
fn before_shutdown(&self, _kind: Shutdown) -> Result<(), FrameworkError> {
if let Some(ref grapher) = self.flamegrapher {
tracing::info!("writing flamegraph");
info!("writing flamegraph");
grapher
.write_flamegraph()
.map_err(|e| FrameworkErrorKind::ComponentError.context(e))?

2
zebrad/src/components/tracing/flame.rs
View File

@ -37,7 +37,7 @@ impl Grapher {
let writer = BufWriter::new(out);
let mut opts = inferno::flamegraph::Options::default();
info!("writing flamegraph to disk...");
debug!("writing flamegraph to disk...");
inferno::flamegraph::from_reader(&mut opts, reader, writer)?;
Ok(())