diff --git a/zebrad/src/components/inbound.rs b/zebrad/src/components/inbound.rs index ecedd9df3..66a2e5d74 100644 --- a/zebrad/src/components/inbound.rs +++ b/zebrad/src/components/inbound.rs @@ -328,7 +328,7 @@ impl Service 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() } } diff --git a/zebrad/src/components/inbound/downloads.rs b/zebrad/src/components/inbound/downloads.rs index f562028da..5178c0646 100644 --- a/zebrad/src/components/inbound/downloads.rs +++ b/zebrad/src/components/inbound/downloads.rs @@ -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, diff --git a/zebrad/src/components/mempool/crawler.rs b/zebrad/src/components/mempool/crawler.rs index 1ffd4a0f2..ced4878c3 100644 --- a/zebrad/src/components/mempool/crawler.rs +++ b/zebrad/src/components/mempool/crawler.rs @@ -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), } } diff --git a/zebrad/src/components/mempool/downloads.rs b/zebrad/src/components/mempool/downloads.rs index c79d61603..eedab09c0 100644 --- a/zebrad/src/components/mempool/downloads.rs +++ b/zebrad/src/components/mempool/downloads.rs @@ -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, diff --git a/zebrad/src/components/sync.rs b/zebrad/src/components/sync.rs index 96f78cbad..7208776b8 100644 --- a/zebrad/src/components/sync.rs +++ b/zebrad/src/components/sync.rs @@ -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::(|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::(|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) -> 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 } } diff --git a/zebrad/src/components/sync/downloads.rs b/zebrad/src/components/sync/downloads.rs index 7b00fc585..81f62a3f6 100644 --- a/zebrad/src/components/sync/downloads.rs +++ b/zebrad/src/components/sync/downloads.rs @@ -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) } diff --git a/zebrad/src/components/sync/gossip.rs b/zebrad/src/components/sync/gossip.rs index 59765e90e..06745349e 100644 --- a/zebrad/src/components/sync/gossip.rs +++ b/zebrad/src/components/sync/gossip.rs @@ -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 diff --git a/zebrad/src/components/sync/recent_sync_lengths.rs b/zebrad/src/components/sync/recent_sync_lengths.rs index a019cec45..d5c1ac8e8 100644 --- a/zebrad/src/components/sync/recent_sync_lengths.rs +++ b/zebrad/src/components/sync/recent_sync_lengths.rs @@ -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" ); diff --git a/zebrad/src/components/tokio.rs b/zebrad/src/components/tokio.rs index 09f2e805a..dd16d7666 100644 --- a/zebrad/src/components/tokio.rs +++ b/zebrad/src/components/tokio.rs @@ -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. diff --git a/zebrad/src/components/tracing/component.rs b/zebrad/src/components/tracing/component.rs index cfe792124..ab8015d21 100644 --- a/zebrad/src/components/tracing/component.rs +++ b/zebrad/src/components/tracing/component.rs @@ -97,7 +97,7 @@ impl Component 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))? diff --git a/zebrad/src/components/tracing/flame.rs b/zebrad/src/components/tracing/flame.rs index be0c923b8..d993fd420 100644 --- a/zebrad/src/components/tracing/flame.rs +++ b/zebrad/src/components/tracing/flame.rs @@ -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(())