diff --git a/chain/src/chain.rs b/chain/src/chain.rs index 93f4260347..ba04f3f0c8 100644 --- a/chain/src/chain.rs +++ b/chain/src/chain.rs @@ -204,7 +204,13 @@ impl Chain { // Make sure sync_head is available for later use when needed. store.reset_head()?; - debug!(LOGGER, "Chain init: {:?}", head); + debug!( + LOGGER, + "Chain init: {} @ {} [{}]", + head.total_difficulty.into_num(), + head.height, + head.last_block_h + ); Ok(Chain { db_root: db_root, @@ -370,7 +376,7 @@ impl Chain { /// Check for orphans, once a block is successfully added pub fn check_orphans(&self, mut last_block_hash: Hash) { - debug!( + trace!( LOGGER, "chain: check_orphans: # orphans {}", self.orphans.len(), diff --git a/chain/src/pipe.rs b/chain/src/pipe.rs index 7d7b297d30..fa8e73cb02 100644 --- a/chain/src/pipe.rs +++ b/chain/src/pipe.rs @@ -97,7 +97,7 @@ pub fn process_block(b: &Block, mut ctx: BlockContext) -> Result, Er // internal validation and saving operations let result = txhashset::extending(&mut txhashset, |mut extension| { validate_block(b, &mut ctx, &mut extension)?; - debug!( + trace!( LOGGER, "pipe: process_block: {} at {} is valid, save and append.", b.hash(), diff --git a/chain/src/txhashset.rs b/chain/src/txhashset.rs index 3cc5621ac2..e67c44d3ef 100644 --- a/chain/src/txhashset.rs +++ b/chain/src/txhashset.rs @@ -253,7 +253,7 @@ where { let commit_index = trees.commit_index.clone(); - debug!(LOGGER, "Starting new txhashset extension."); + trace!(LOGGER, "Starting new txhashset extension."); let mut extension = Extension::new(trees, commit_index); res = inner(&mut extension); @@ -273,12 +273,12 @@ where } Ok(r) => { if rollback { - debug!(LOGGER, "Rollbacking txhashset extension."); + debug!(LOGGER, "Rollbacking txhashset extension. sizes {:?}", sizes); trees.output_pmmr_h.backend.discard(); trees.rproof_pmmr_h.backend.discard(); trees.kernel_pmmr_h.backend.discard(); } else { - debug!(LOGGER, "Committing txhashset extension."); + debug!(LOGGER, "Committing txhashset extension. sizes {:?}", sizes); trees.output_pmmr_h.backend.sync()?; trees.rproof_pmmr_h.backend.sync()?; trees.kernel_pmmr_h.backend.sync()?; @@ -287,7 +287,7 @@ where trees.kernel_pmmr_h.last_pos = sizes.2; } - debug!(LOGGER, "TxHashSet extension done."); + trace!(LOGGER, "TxHashSet extension done."); Ok(r) } } diff --git a/grin/src/miner.rs b/grin/src/miner.rs index 94d2b16654..d580353b22 100644 --- a/grin/src/miner.rs +++ b/grin/src/miner.rs @@ -26,7 +26,6 @@ use adapters::PoolToChainAdapter; use core::consensus; use core::core; use core::core::Proof; -use core::core::target::Difficulty; use core::core::{Block, BlockHeader, Transaction}; use core::core::hash::{Hash, Hashed}; use pow::{cuckoo, MiningWorker}; @@ -130,7 +129,6 @@ impl Miner { pub fn inner_loop_async( &self, plugin_miner: &mut PluginMiner, - difficulty: Difficulty, b: &mut Block, cuckoo_size: u32, head: &BlockHeader, @@ -140,12 +138,13 @@ impl Miner { ) -> Option { debug!( LOGGER, - "(Server ID: {}) Mining at Cuckoo{} for at most {} secs at height {} and difficulty {}.", + "(Server ID: {}) Mining Cuckoo{} for max {}s on {} @ {} [{}].", self.debug_output_id, cuckoo_size, attempt_time_per_block, + b.header.total_difficulty, b.header.height, - b.header.total_difficulty + b.header.hash() ); // look for a pow for at most attempt_time_per_block sec on the @@ -175,10 +174,10 @@ impl Miner { let proof_diff = proof.clone().to_difficulty(); trace!( LOGGER, - "Found cuckoo solution for nonce {} of difficulty {} (difficulty target {})", + "Found cuckoo solution! nonce {} gave difficulty {} (block diff {})", s.get_nonce_as_u64(), proof_diff.into_num(), - difficulty.into_num() + (b.header.total_difficulty.clone() - head.total_difficulty.clone()).into_num() ); if proof_diff > (b.header.total_difficulty.clone() - head.total_difficulty.clone()) { @@ -270,13 +269,14 @@ impl Miner { debug!( LOGGER, - "(Server ID: {}) Mining at Cuckoo{} for {} secs (will wait for last solution) \ - on block {} at difficulty {}.", + "(Server ID: {}) Mining Cuckoo{} for max {}s (will wait for last solution) \ + on {} @ {} [{}].", self.debug_output_id, cuckoo_size, attempt_time_per_block, - latest_hash, - b.header.total_difficulty + b.header.total_difficulty, + b.header.height, + latest_hash ); let mut iter_count = 0; @@ -296,7 +296,7 @@ impl Miner { let proof_diff = proof.clone().to_difficulty(); trace!( LOGGER, - "Found cuckoo solution for nonce {} of difficulty {} (difficulty target {})", + "Found cuckoo solution for nonce {} of difficulty {} (cumulative diff {})", b.header.nonce, proof_diff.into_num(), b.header.total_difficulty.into_num() @@ -388,12 +388,13 @@ impl Miner { debug!( LOGGER, - "(Server ID: {}) Mining at Cuckoo{} for at most {} secs on block {} at difficulty {}.", + "(Server ID: {}) Mining Cuckoo{} for max {}s on {} @ {} [{}].", self.debug_output_id, cuckoo_size, attempt_time_per_block, - latest_hash, - b.header.total_difficulty + b.header.total_difficulty, + b.header.height, + latest_hash ); let mut iter_count = 0; @@ -486,8 +487,7 @@ impl Miner { } loop { - debug!(LOGGER, "in miner loop..."); - trace!(LOGGER, "key_id: {:?}", key_id); + trace!(LOGGER, "in miner loop. key_id: {:?}", key_id); // get the latest chain state and build a block on top of it let head = self.chain.head_header().unwrap(); @@ -526,7 +526,6 @@ impl Miner { if use_async { sol = self.inner_loop_async( &mut p, - (b.header.total_difficulty.clone() - head.total_difficulty.clone()), &mut b, cuckoo_size, &head, @@ -575,7 +574,7 @@ impl Miner { e ); } - debug!(LOGGER, "resetting key_id in miner to None"); + trace!(LOGGER, "resetting key_id in miner to None"); key_id = None; } else { debug!( @@ -630,7 +629,7 @@ impl Miner { debug!( LOGGER, - "(Server ID: {}) Built new block with {} inputs and {} outputs, network difficulty: {}, block cumulative difficulty {}", + "(Server ID: {}) Built new block with {} inputs and {} outputs, network difficulty: {}, cumulative difficulty {}", self.debug_output_id, b.inputs.len(), b.outputs.len(), diff --git a/grin/src/seed.rs b/grin/src/seed.rs index 8b0f8751d5..2123371fd8 100644 --- a/grin/src/seed.rs +++ b/grin/src/seed.rs @@ -87,14 +87,6 @@ fn monitor_peers( // regularly check if we need to acquire more peers and if so, gets // them from db let total_count = peers.all_peers().len(); - debug!( - LOGGER, - "monitor_peers: {} most_work_peers, {} connected, {} total known", - peers.most_work_peers().len(), - peers.connected_peers().len(), - total_count, - ); - let mut healthy_count = 0; let mut banned_count = 0; let mut defunct_count = 0; @@ -120,7 +112,10 @@ fn monitor_peers( debug!( LOGGER, - "monitor_peers: all {} = {} healthy + {} banned + {} defunct", + "monitor_peers: {} connected ({} most_work). \ + all {} = {} healthy + {} banned + {} defunct", + peers.connected_peers().len(), + peers.most_work_peers().len(), total_count, healthy_count, banned_count, @@ -214,7 +209,7 @@ fn listen_for_addrs( let connect_peer = p2p.connect(&addr); match connect_peer { Ok(p) => { - debug!(LOGGER, "connect_and_req: ok. attempting send_peer_request"); + trace!(LOGGER, "connect_and_req: ok. attempting send_peer_request"); if let Ok(p) = p.try_read() { let _ = p.send_peer_request(capab); } diff --git a/grin/src/sync.rs b/grin/src/sync.rs index 30e25677a6..0041e8f531 100644 --- a/grin/src/sync.rs +++ b/grin/src/sync.rs @@ -266,11 +266,13 @@ fn needs_syncing( ); if peer.info.total_difficulty <= local_diff { + let ch = chain.head().unwrap(); info!( LOGGER, - "synchronized at {:?} @ {:?}", - local_diff, - chain.head().unwrap().height + "synchronised at {} @ {} [{}]", + local_diff.into_num(), + ch.height, + ch.last_block_h ); if !header_only { let _ = chain.reset_head(); @@ -279,7 +281,7 @@ fn needs_syncing( } } } else { - info!(LOGGER, "sync: no peers available, disabling sync"); + warn!(LOGGER, "sync: no peers available, disabling sync"); return false; } } else { diff --git a/p2p/src/conn.rs b/p2p/src/conn.rs index 1f5fa58d70..521381af72 100644 --- a/p2p/src/conn.rs +++ b/p2p/src/conn.rs @@ -206,7 +206,7 @@ fn poll( // check the read end if let Some(h) = try_break!(error_tx, read_header(conn)) { let msg = Message::from_header(h, conn); - debug!( + trace!( LOGGER, "Received message header, type {:?}, len {}.", msg.header.msg_type, diff --git a/p2p/src/handshake.rs b/p2p/src/handshake.rs index 96b6438584..3f6d06ab20 100644 --- a/p2p/src/handshake.rs +++ b/p2p/src/handshake.rs @@ -174,7 +174,7 @@ impl Handshake { }; write_message(conn, shake, Type::Shake)?; - debug!(LOGGER, "Success handshake with {}.", peer_info.addr); + trace!(LOGGER, "Success handshake with {}.", peer_info.addr); // when more than one protocol version is supported, choosing should go here Ok(peer_info) diff --git a/p2p/src/peer.rs b/p2p/src/peer.rs index 9e85db3434..9bed8ef959 100644 --- a/p2p/src/peer.rs +++ b/p2p/src/peer.rs @@ -161,7 +161,7 @@ impl Peer { /// if the remote peer is known to already have the block. pub fn send_block(&self, b: &core::Block) -> Result<(), Error> { if !self.tracking_adapter.has(b.hash()) { - debug!(LOGGER, "Send block {} to {}", b.hash(), self.info.addr); + trace!(LOGGER, "Send block {} to {}", b.hash(), self.info.addr); self.connection.as_ref().unwrap().send(b, msg::Type::Block) } else { debug!( @@ -176,7 +176,7 @@ impl Peer { pub fn send_compact_block(&self, b: &core::CompactBlock) -> Result<(), Error> { if !self.tracking_adapter.has(b.hash()) { - debug!( + trace!( LOGGER, "Send compact block {} to {}", b.hash(), @@ -205,7 +205,7 @@ impl Peer { .unwrap() .send(bh, msg::Type::Header) } else { - debug!( + trace!( LOGGER, "Suppress header send {} to {} (already seen)", bh.hash(), diff --git a/p2p/src/peers.rs b/p2p/src/peers.rs index 392fdcdc8d..33d2f14295 100644 --- a/p2p/src/peers.rs +++ b/p2p/src/peers.rs @@ -331,7 +331,7 @@ impl Peers { } } } - debug!( + trace!( LOGGER, "broadcast_header: {}, {} at {}, to {} peers, done.", bh.hash(), @@ -600,7 +600,7 @@ impl NetAdapter for Peers { /// A list of peers has been received from one of our peers. fn peer_addrs_received(&self, peer_addrs: Vec) { - debug!(LOGGER, "Received {} peer addrs, saving.", peer_addrs.len()); + trace!(LOGGER, "Received {} peer addrs, saving.", peer_addrs.len()); for pa in peer_addrs { if let Ok(e) = self.exists_peer(pa) { if e { diff --git a/p2p/src/protocol.rs b/p2p/src/protocol.rs index 25eeae0aa2..1b1157fe19 100644 --- a/p2p/src/protocol.rs +++ b/p2p/src/protocol.rs @@ -75,7 +75,7 @@ impl MessageHandler for Protocol { Type::GetBlock => { let h: Hash = msg.body()?; - debug!(LOGGER, "handle_payload: GetBlock {}", h); + trace!(LOGGER, "handle_payload: GetBlock {}", h); let bo = adapter.get_block(h); if let Some(b) = bo { @@ -88,7 +88,7 @@ impl MessageHandler for Protocol { let b: core::Block = msg.body()?; let bh = b.hash(); - debug!(LOGGER, "handle_payload: Block {}", bh); + trace!(LOGGER, "handle_payload: Block {}", bh); adapter.block_received(b, self.addr); Ok(None) diff --git a/p2p/src/serv.rs b/p2p/src/serv.rs index 1c9bccb509..8f5e03e66e 100644 --- a/p2p/src/serv.rs +++ b/p2p/src/serv.rs @@ -130,7 +130,7 @@ impl Server { return Ok(p); } - debug!(LOGGER, "connect_peer: connecting to {}", addr); + trace!(LOGGER, "connect_peer: connecting to {}", addr); match TcpStream::connect_timeout(addr, Duration::from_secs(10)) { Ok(mut stream) => { let addr = SocketAddr::new(self.config.host, self.config.port); diff --git a/wallet/src/types.rs b/wallet/src/types.rs index 2c48a0e887..a56dec3bd2 100644 --- a/wallet/src/types.rs +++ b/wallet/src/types.rs @@ -525,7 +525,7 @@ impl WalletData { info!(LOGGER, "Acquiring wallet lock ..."); let action = || { - debug!(LOGGER, "Attempting to acquire wallet lock"); + trace!(LOGGER, "making lock file for wallet lock"); OpenOptions::new() .write(true) .create_new(true)