From ab19bf7c278ddd500a3555a876a0f0115a6c8e66 Mon Sep 17 00:00:00 2001 From: Eval EXEC Date: Tue, 16 Jan 2024 09:11:24 +0800 Subject: [PATCH] Add more log message for debug --- Cargo.lock | 1 + chain/src/consume_orphan.rs | 5 ++++- sync/Cargo.toml | 1 + sync/src/synchronizer/block_fetcher.rs | 10 ++++----- sync/src/tests/sync_shared.rs | 27 +++++++++++++++++++++++ sync/src/tests/synchronizer/basic_sync.rs | 10 ++++++++- util/logger-service/src/lib.rs | 1 - 7 files changed, 47 insertions(+), 8 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 851f932b471..e96a573edef 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1462,6 +1462,7 @@ dependencies = [ "ckb-dao-utils", "ckb-error", "ckb-logger", + "ckb-logger-service", "ckb-metrics", "ckb-network", "ckb-reward-calculator", diff --git a/chain/src/consume_orphan.rs b/chain/src/consume_orphan.rs index 9e214743792..1585d2a536f 100644 --- a/chain/src/consume_orphan.rs +++ b/chain/src/consume_orphan.rs @@ -290,7 +290,10 @@ impl ConsumeOrphan { let parent_status = self.shared.get_block_status(&parent_hash); if parent_status.contains(BlockStatus::BLOCK_PARTIAL_STORED) { debug!( - "parent has stored, processing descendant directly {}", + "parent {} has stored: {:?}, processing descendant directly {}-{}", + parent_hash, + parent_status, + lonely_block.block().number(), lonely_block.block().hash() ); self.descendant_processor.process_descendant(lonely_block); diff --git a/sync/Cargo.toml b/sync/Cargo.toml index 22f919e19fb..51831afd65a 100644 --- a/sync/Cargo.toml +++ b/sync/Cargo.toml @@ -48,6 +48,7 @@ ckb-chain = { path = "../chain", version = "= 0.114.0-pre", features = ["mock"] faux = "^0.1" once_cell = "1.8.0" ckb-systemtime = { path = "../util/systemtime", version = "= 0.114.0-pre" , features = ["enable_faketime"]} +ckb-logger-service = { path = "../util/logger-service", version = "= 0.114.0-pre" } [features] default = [] diff --git a/sync/src/synchronizer/block_fetcher.rs b/sync/src/synchronizer/block_fetcher.rs index 50f82033481..484d0977f16 100644 --- a/sync/src/synchronizer/block_fetcher.rs +++ b/sync/src/synchronizer/block_fetcher.rs @@ -152,15 +152,15 @@ impl BlockFetcher { return None; } - if matches!(self.ibd, IBDState::In) { - if best_known.number() <= self.active_chain.unverified_tip_number() { - debug!("In IBD mode, Peer {}'s best_known: {} is less or equal than unverified_tip : {}, won't request block from this peer", + if matches!(self.ibd, IBDState::In) + && best_known.number() <= self.active_chain.unverified_tip_number() + { + debug!("In IBD mode, Peer {}'s best_known: {} is less or equal than unverified_tip : {}, won't request block from this peer", self.peer, best_known.number(), self.active_chain.unverified_tip_number() ); - return None; - } + return None; }; let state = self.sync_shared.state(); diff --git a/sync/src/tests/sync_shared.rs b/sync/src/tests/sync_shared.rs index bc3c383e9a0..23effa21148 100644 --- a/sync/src/tests/sync_shared.rs +++ b/sync/src/tests/sync_shared.rs @@ -4,6 +4,8 @@ use crate::tests::util::{build_chain, inherit_block}; use crate::SyncShared; use ckb_chain::start_chain_services; +use ckb_logger::info; +use ckb_logger_service::LoggerInitGuard; use ckb_shared::block_status::BlockStatus; use ckb_shared::SharedBuilder; use ckb_store::{self, ChainStore}; @@ -11,6 +13,7 @@ use ckb_test_chain_utils::always_success_cellbase; use ckb_types::core::{BlockBuilder, BlockView, Capacity}; use ckb_types::packed::Byte32; use ckb_types::prelude::*; +use std::fmt::format; use std::sync::Arc; #[test] @@ -142,6 +145,8 @@ fn test_insert_parent_unknown_block() { #[test] fn test_switch_valid_fork() { + let _log_guard: LoggerInitGuard = + ckb_logger_service::init_for_test("info,ckb_chain=debug").expect("init log"); let (shared, chain) = build_chain(4); let make_valid_block = |shared, parent_hash| -> BlockView { let header = inherit_block(shared, &parent_hash).build().header(); @@ -162,9 +167,20 @@ fn test_switch_valid_fork() { let block_hash = shared.store().get_block_hash(number).unwrap(); shared.store().get_block(&block_hash).unwrap(); } + + info!( + "chain tip is {}={}", + shared.active_chain().tip_number(), + shared.active_chain().tip_hash() + ); let mut valid_fork = Vec::new(); for _ in 2..shared.active_chain().tip_number() { let block = make_valid_block(shared.shared(), parent_hash.clone()); + info!( + "blocking insert valid fork: {}-{}", + block.number(), + block.hash() + ); assert!(shared .blocking_insert_new_block(&chain, Arc::new(block.clone())) .expect("insert fork")); @@ -178,6 +194,9 @@ fn test_switch_valid_fork() { .active_chain() .get_block_status(&block.header().hash()), BlockStatus::BLOCK_STORED, + "block {}-{} should be BLOCK_STORED", + block.number(), + block.hash() ); } @@ -185,6 +204,11 @@ fn test_switch_valid_fork() { // Make the fork switch as the main chain. for _ in tip_number..tip_number + 2 { let block = inherit_block(shared.shared(), &parent_hash.clone()).build(); + info!( + "blocking insert fork block: {}-{}", + block.number(), + block.hash() + ); assert!(shared .blocking_insert_new_block(&chain, Arc::new(block.clone())) .expect("insert fork")); @@ -198,6 +222,9 @@ fn test_switch_valid_fork() { .active_chain() .get_block_status(&block.header().hash()), BlockStatus::BLOCK_VALID, + "block {}-{} should be BLOCK_VALID", + block.number(), + block.hash() ); } } diff --git a/sync/src/tests/synchronizer/basic_sync.rs b/sync/src/tests/synchronizer/basic_sync.rs index 3765e79d555..79b9069319d 100644 --- a/sync/src/tests/synchronizer/basic_sync.rs +++ b/sync/src/tests/synchronizer/basic_sync.rs @@ -10,6 +10,7 @@ use ckb_channel::bounded; use ckb_dao::DaoCalculator; use ckb_dao_utils::genesis_dao_data; use ckb_logger::info; +use ckb_logger_service::LoggerInitGuard; use ckb_network::SupportProtocols; use ckb_reward_calculator::RewardCalculator; use ckb_shared::{Shared, SharedBuilder}; @@ -33,6 +34,7 @@ const DEFAULT_CHANNEL: usize = 128; #[test] fn basic_sync() { + let _log_guard: LoggerInitGuard = ckb_logger_service::init_for_test("debug").expect("init log"); let _faketime_guard = ckb_systemtime::faketime(); _faketime_guard.set_faketime(0); let thread_name = "fake_time=0".to_string(); @@ -46,11 +48,17 @@ fn basic_sync() { node1.connect(&mut node2, SupportProtocols::Sync.protocol_id()); info!("node1 and node2 connected"); + let now = std::time::Instant::now(); let (signal_tx1, signal_rx1) = bounded(DEFAULT_CHANNEL); - node1.start(thread_name.clone(), signal_tx1, |data| { + node1.start(thread_name.clone(), signal_tx1, move |data| { let msg = packed::SyncMessage::from_slice(&data) .expect("sync message") .to_enum(); + + assert!( + now.elapsed().as_secs() <= 10, + "node1 should got block(3)'s SendBlock message within 10 seconds" + ); // terminate thread after 3 blocks if let packed::SyncMessageUnionReader::SendBlock(reader) = msg.as_reader() { let block = reader.block().to_entity().into_view(); diff --git a/util/logger-service/src/lib.rs b/util/logger-service/src/lib.rs index 48500e736e8..37c7eb26846 100644 --- a/util/logger-service/src/lib.rs +++ b/util/logger-service/src/lib.rs @@ -530,7 +530,6 @@ fn setup_panic_logger() { /// Only used by unit test /// Initializes the [Logger](struct.Logger.html) and run the logging service. -#[cfg(test)] pub fn init_for_test(filter: &str) -> Result { setup_panic_logger(); let config: Config = Config {