From b29277239ae155372bfc44faa4695f79eb23e693 Mon Sep 17 00:00:00 2001
From: Arkadiy Paronyan <arkady.paronyan@gmail.com>
Date: Thu, 8 Aug 2019 09:34:09 +0200
Subject: [PATCH] Improve console output (#3326)
* Cache idle state
* Display import error by default
---
substrate/core/client/src/client.rs | 8 +++++-
substrate/core/network/src/protocol/sync.rs | 32 +++++++++++++++++----
substrate/core/service/src/lib.rs | 2 +-
3 files changed, 35 insertions(+), 7 deletions(-)
diff --git a/substrate/core/client/src/client.rs b/substrate/core/client/src/client.rs
index fa60c80e3a1..0360c532d27 100644
--- a/substrate/core/client/src/client.rs
+++ b/substrate/core/client/src/client.rs
@@ -1242,6 +1242,9 @@ impl<B, E, Block, RA> Client<B, E, Block, RA> where
let last_best = self.backend.blockchain().info().best_hash;
let to_finalize_hash = self.backend.blockchain().expect_block_hash_from_id(&id)?;
self.apply_finality_with_block_hash(operation, to_finalize_hash, justification, last_best, notify)
+ }).map_err(|e| {
+ warn!("Block finalization error:\n{:?}", e);
+ e
})
}
@@ -1501,7 +1504,10 @@ impl<'a, B, E, Block, RA> consensus::BlockImport<Block> for &'a Client<B, E, Blo
) -> Result<ImportResult, Self::Error> {
self.lock_import_and_run(|operation| {
self.apply_block(operation, import_block, new_cache)
- }).map_err(|e| ConsensusError::ClientImport(e.to_string()).into())
+ }).map_err(|e| {
+ warn!("Block import error:\n{:?}", e);
+ ConsensusError::ClientImport(e.to_string()).into()
+ })
}
/// Check block preconditions.
diff --git a/substrate/core/network/src/protocol/sync.rs b/substrate/core/network/src/protocol/sync.rs
index 80b0662c6bb..bd67c6cde7e 100644
--- a/substrate/core/network/src/protocol/sync.rs
+++ b/substrate/core/network/src/protocol/sync.rs
@@ -119,7 +119,9 @@ pub struct ChainSync<B: BlockT> {
queue_blocks: HashSet<B::Hash>,
/// The best block number that we are currently importing.
best_importing_number: NumberFor<B>,
- request_builder: Option<BoxFinalityProofRequestBuilder<B>>
+ request_builder: Option<BoxFinalityProofRequestBuilder<B>>,
+ /// A flag that caches idle state with no pending requests.
+ is_idle: bool,
}
/// All the data we have about a Peer that we are trying to sync with
@@ -289,7 +291,8 @@ impl<B: BlockT> ChainSync<B> {
required_block_attributes,
queue_blocks: Default::default(),
best_importing_number: Zero::zero(),
- request_builder
+ request_builder,
+ is_idle: false,
}
}
@@ -346,7 +349,6 @@ impl<B: BlockT> ChainSync<B> {
info!("New peer with unknown genesis hash {} ({}).", info.best_hash, info.best_number);
return Err(BadPeer(who, i32::min_value()))
}
-
// If there are more than `MAJOR_SYNC_BLOCKS` in the import queue then we have
// enough to do in the import queue that it's not worth kicking off
// an ancestor search, which is what we do in the next match case below.
@@ -398,6 +400,7 @@ impl<B: BlockT> ChainSync<B> {
),
recently_announced: Default::default()
});
+ self.is_idle = false;
Ok(Some(ancestry_request::<B>(common_best)))
}
@@ -410,6 +413,7 @@ impl<B: BlockT> ChainSync<B> {
state: PeerSyncState::Available,
recently_announced: Default::default(),
});
+ self.is_idle = false;
Ok(None)
}
}
@@ -487,12 +491,16 @@ impl<B: BlockT> ChainSync<B> {
/// Get an iterator over all block requests of all peers.
pub fn block_requests(&mut self) -> impl Iterator<Item = (PeerId, BlockRequest<B>)> + '_ {
+ if self.is_idle {
+ return Either::Left(std::iter::empty())
+ }
if self.queue_blocks.len() > MAX_IMPORTING_BLOCKS {
trace!(target: "sync", "Too many blocks in the queue.");
return Either::Left(std::iter::empty())
}
let blocks = &mut self.blocks;
let attrs = &self.required_block_attributes;
+ let mut have_requests = false;
let iter = self.peers.iter_mut().filter_map(move |(id, peer)| {
if !peer.state.is_available() {
trace!(target: "sync", "Peer {} is busy", id);
@@ -500,13 +508,17 @@ impl<B: BlockT> ChainSync<B> {
}
if let Some((range, req)) = peer_block_request(id, peer, blocks, attrs) {
peer.state = PeerSyncState::DownloadingNew(range.start);
- trace!(target: "sync", "new block request for {}", id);
+ trace!(target: "sync", "New block request for {}", id);
+ have_requests = true;
Some((id.clone(), req))
} else {
- trace!(target: "sync", "no new block request for {}", id);
+ trace!(target: "sync", "No new block request for {}", id);
None
}
});
+ if !have_requests {
+ self.is_idle = true;
+ }
Either::Right(iter)
}
@@ -526,6 +538,7 @@ impl<B: BlockT> ChainSync<B> {
trace!(target: "sync", "Reversing incoming block list");
blocks.reverse()
}
+ self.is_idle = false;
match &mut peer.state {
PeerSyncState::DownloadingNew(start_block) => {
self.blocks.clear_peer_download(&who);
@@ -641,6 +654,7 @@ impl<B: BlockT> ChainSync<B> {
return Ok(OnBlockJustification::Nothing)
};
+ self.is_idle = false;
if let PeerSyncState::DownloadingJustification(hash) = peer.state {
peer.state = PeerSyncState::Available;
@@ -679,6 +693,7 @@ impl<B: BlockT> ChainSync<B> {
return Ok(OnBlockFinalityProof::Nothing)
};
+ self.is_idle = false;
if let PeerSyncState::DownloadingFinalityProof(hash) = peer.state {
peer.state = PeerSyncState::Available;
@@ -792,6 +807,7 @@ impl<B: BlockT> ChainSync<B> {
self.best_importing_number = Zero::zero()
}
+ self.is_idle = false;
output.into_iter()
}
@@ -805,10 +821,12 @@ impl<B: BlockT> ChainSync<B> {
number,
)
}
+ self.is_idle = false;
}
pub fn on_finality_proof_import(&mut self, req: (B::Hash, NumberFor<B>), res: Result<(B::Hash, NumberFor<B>), ()>) {
self.extra_finality_proofs.try_finalize_root(req, res, true);
+ self.is_idle = false;
}
/// Notify about finalization of the given block.
@@ -863,6 +881,7 @@ impl<B: BlockT> ChainSync<B> {
);
peer.common_number = new_common_number;
}
+ self.is_idle = false;
}
/// Call when a node announces a new block.
@@ -908,6 +927,7 @@ impl<B: BlockT> ChainSync<B> {
} else if known {
peer.common_number = number
}
+ self.is_idle = false;
// known block case
if known || self.is_already_downloading(&hash) {
@@ -987,6 +1007,7 @@ impl<B: BlockT> ChainSync<B> {
self.peers.remove(&who);
self.extra_justifications.peer_disconnected(&who);
self.extra_finality_proofs.peer_disconnected(&who);
+ self.is_idle = false;
}
/// Restart the sync process.
@@ -1000,6 +1021,7 @@ impl<B: BlockT> ChainSync<B> {
let info = self.client.info();
self.best_queued_hash = info.chain.best_hash;
self.best_queued_number = info.chain.best_number;
+ self.is_idle = false;
debug!(target:"sync", "Restarted with {} ({})", self.best_queued_number, self.best_queued_hash);
let old_peers = std::mem::replace(&mut self.peers, HashMap::new());
old_peers.into_iter().filter_map(move |(id, _)| {
diff --git a/substrate/core/service/src/lib.rs b/substrate/core/service/src/lib.rs
index f28d41019b5..8b8c0893d35 100644
--- a/substrate/core/service/src/lib.rs
+++ b/substrate/core/service/src/lib.rs
@@ -671,7 +671,7 @@ fn build_network_future<
let polling_dur = before_polling.elapsed();
log!(
target: "service",
- if polling_dur >= Duration::from_millis(50) { Level::Warn } else { Level::Trace },
+ if polling_dur >= Duration::from_millis(50) { Level::Debug } else { Level::Trace },
"Polling the network future took {:?}",
polling_dur
);
--
GitLab