Add more log message for debug

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);

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 = []

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();

sync/src/tests/sync_shared.rs

@@ -4,13 +4,16 @@
 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};
 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,13 +194,21 @@ 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()
         );
     }
 
     let tip_number = shared.active_chain().tip_number();
     // 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()
         );
     }
 }

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();

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<LoggerInitGuard, SetLoggerError> {
     setup_panic_logger();
     let config: Config = Config {