Merge pull request nervosnetwork#4240 from eval-exec/exec/improve-exi…

…t-signal-related-log-level

Improve exit signal related log message

block-filter/src/filter.rs

@@ -1,5 +1,5 @@
 use ckb_async_runtime::tokio::{self, task::block_in_place};
-use ckb_logger::{debug, warn};
+use ckb_logger::{debug, info, warn};
 use ckb_shared::Shared;
 use ckb_stop_handler::{new_tokio_exit_rx, CancellationToken};
 use ckb_store::{ChainDB, ChainStore};
@@ -63,7 +63,7 @@ impl BlockFilter {
                         new_block_watcher.borrow_and_update();
                     }
                     _ = stop_rx.cancelled() => {
-                        debug!("BlockFilter received exit signal, exit now");
+                        info!("BlockFilter received exit signal, exit now");
                         break
                     },
                     else => break,

chain/src/chain.rs

@@ -257,7 +257,7 @@ impl ChainService {
                         },
                     },
                     recv(signal_receiver) -> _ => {
-                        debug!("ChainService received exit signal, exit now");
+                        info!("ChainService received exit signal, exit now");
                         break;
                     }
                 }

ckb-bin/src/helper.rs

@@ -8,7 +8,7 @@ pub fn deadlock_detection() {}
 #[cfg(feature = "deadlock_detection")]
 pub fn deadlock_detection() {
     use ckb_channel::select;
-    use ckb_logger::{debug, warn};
+    use ckb_logger::warn;
     use ckb_stop_handler::{new_crossbeam_exit_rx, register_thread};
     use ckb_util::parking_lot::deadlock;
     use std::{thread, time::Duration};
@@ -36,7 +36,7 @@ pub fn deadlock_detection() {
 
                 },
                 recv(stop_rx) -> _ =>{
-                    debug!("deadlock_detection received exit signal, stopped");
+                    info!("deadlock_detection received exit signal, stopped");
                     return;
                 }
             }

ckb-bin/src/lib.rs

@@ -8,7 +8,7 @@ mod subcommand;
 use ckb_app_config::{cli, ExitCode, Setup};
 use ckb_async_runtime::new_global_runtime;
 use ckb_build_info::Version;
-use ckb_logger::{debug, info};
+use ckb_logger::info;
 use ckb_network::tokio;
 use helper::raise_fd_limit;
 use setup_guard::SetupGuard;
@@ -80,9 +80,9 @@ pub fn run_app(version: Version) -> Result<(), ExitCode> {
         handle.drop_guard();
 
         tokio::task::block_in_place(|| {
-            debug!("waiting all tokio tasks done");
+            info!("waiting all tokio tasks exit...");
             handle_stop_rx.blocking_recv();
-            info!("ckb shutdown");
+            info!("all tokio tasks and threads have exited, ckb shutdown");
         });
     }
 

miner/src/client.rs

@@ -4,7 +4,7 @@ use ckb_app_config::MinerClientConfig;
 use ckb_async_runtime::Handle;
 use ckb_channel::Sender;
 use ckb_jsonrpc_types::{Block as JsonBlock, BlockTemplate};
-use ckb_logger::{debug, error};
+use ckb_logger::{debug, error, info};
 use ckb_stop_handler::{new_tokio_exit_rx, CancellationToken};
 use ckb_types::{
     packed::{Block, Byte32},
@@ -87,7 +87,7 @@ impl Rpc {
                         });
                     },
                     _ = stop_rx.cancelled() => {
-                        debug!("Rpc server received exit signal, exit now");
+                        info!("Rpc server received exit signal, exit now");
                         break
                     },
                     else => break
@@ -235,7 +235,7 @@ Otherwise ckb-miner does not work properly and will behave as it stopped committ
         let stop_rx: CancellationToken = new_tokio_exit_rx();
         let graceful = server.with_graceful_shutdown(async move {
             stop_rx.cancelled().await;
-            debug!("Miner client received exit signal, exit now");
+            info!("Miner client received exit signal, exit now");
         });
 
         if let Err(e) = graceful.await {
@@ -255,7 +255,7 @@ Otherwise ckb-miner does not work properly and will behave as it stopped committ
                     self.fetch_block_template().await;
                 }
                 _ = stop_rx.cancelled() => {
-                    debug!("Miner client pool_block_template received exit signal, exit now");
+                    info!("Miner client pool_block_template received exit signal, exit now");
                     break
                 },
                 else => break,

miner/src/miner.rs

@@ -105,7 +105,7 @@ impl Miner {
                     },
                 },
                 recv(stop_rx) -> _msg => {
-                    debug!("miner received exit signal, stopped");
+                    info!("miner received exit signal, stopped");
                     break;
                 }
             };

network/src/network.rs

@@ -1127,11 +1127,12 @@ impl NetworkService {
                 loop {
                     tokio::select! {
                         _ = receiver.cancelled() => {
-                            debug!("NetworkService receive exit signal, start shutdown...");
+                            info!("NetworkService receive exit signal, start shutdown...");
                             let _ = p2p_control.shutdown().await;
                             // Drop senders to stop all corresponding background task
                             drop(bg_signals);
 
+                            info!("NetworkService shutdown now");
                             break;
                         },
                         else => {

notify/src/lib.rs

@@ -1,7 +1,7 @@
 //! TODO(doc): @quake
 use ckb_app_config::NotifyConfig;
 use ckb_async_runtime::Handle;
-use ckb_logger::{debug, error, trace};
+use ckb_logger::{debug, error, info, trace};
 use ckb_stop_handler::{new_tokio_exit_rx, CancellationToken};
 use ckb_types::packed::Byte32;
 use ckb_types::{
@@ -178,7 +178,7 @@ impl NotifyService {
                     Some(msg) = network_alert_register_receiver.recv() => { self.handle_register_network_alert(msg) },
                     Some(msg) = network_alert_receiver.recv() => { self.handle_notify_network_alert(msg) },
                     _ = signal_receiver.cancelled() => {
-                        debug!("NotifyService received exit signal, exit now");
+                        info!("NotifyService received exit signal, exit now");
                         break;
                     }
                     else => break,

sync/src/synchronizer/mod.rs

@@ -146,7 +146,7 @@ impl BlockFetchCMD {
                     }
                 }
                 recv(stop_signal) -> _ => {
-                    debug!("thread BlockDownload received exit signal, exit now");
+                    info!("BlockDownload received exit signal, exit now");
                     return;
                 }
             }

sync/src/types/header_map/mod.rs

@@ -1,5 +1,5 @@
 use ckb_async_runtime::Handle;
-use ckb_logger::debug;
+use ckb_logger::info;
 use ckb_stop_handler::{new_tokio_exit_rx, CancellationToken};
 use ckb_types::packed::Byte32;
 use std::sync::Arc;
@@ -56,7 +56,7 @@ impl HeaderMap {
                         map.limit_memory();
                     }
                     _ = stop_rx.cancelled() => {
-                        debug!("HeaderMap limit_memory received exit signal, exit now");
+                        info!("HeaderMap limit_memory received exit signal, exit now");
                         break
                     },
                 }

tx-pool/src/chunk_process.rs

@@ -4,7 +4,7 @@ use crate::try_or_return_with_snapshot;
 use crate::{error::Reject, service::TxPoolService};
 use ckb_chain_spec::consensus::Consensus;
 use ckb_error::Error;
-use ckb_logger::debug;
+use ckb_logger::info;
 use ckb_snapshot::Snapshot;
 use ckb_store::data_loader_wrapper::AsDataLoader;
 use ckb_traits::{CellDataProvider, ExtensionProvider, HeaderProvider};
@@ -85,7 +85,7 @@ impl ChunkProcess {
                     }
                 },
                 _ = self.signal.cancelled() => {
-                    debug!("TxPool received exit signal, exit now");
+                    info!("TxPool chunk_command service received exit signal, exit now");
                     break
                 },
                 else => break,

tx-pool/src/service.rs

@@ -14,8 +14,8 @@ use ckb_chain_spec::consensus::Consensus;
 use ckb_channel::oneshot;
 use ckb_error::AnyError;
 use ckb_jsonrpc_types::BlockTemplate;
+use ckb_logger::error;
 use ckb_logger::info;
-use ckb_logger::{debug, error};
 use ckb_network::{NetworkController, PeerIndex};
 use ckb_snapshot::Snapshot;
 use ckb_stop_handler::new_tokio_exit_rx;
@@ -517,6 +517,7 @@ impl TxPoolServiceBuilder {
                     _ = signal_receiver.cancelled() => {
                         info!("TxPool is saving, please wait...");
                         process_service.save_pool().await;
+                        info!("TxPool process_service exit now");
                         break
                     },
                     else => break,
@@ -543,7 +544,7 @@ impl TxPoolServiceBuilder {
                                 block_assembler::process(service_clone, &message).await;
                             },
                             _ = signal_receiver.cancelled() => {
-                                debug!("TxPool received exit signal, exit now");
+                                info!("TxPool block_assembler process service received exit signal, exit now");
                                 break
                             },
                             else => break,
@@ -578,7 +579,7 @@ impl TxPoolServiceBuilder {
                                 queue.clear();
                             }
                             _ = signal_receiver.cancelled() => {
-                                debug!("TxPool received exit signal, exit now");
+                                info!("TxPool block_assembler process service received exit signal, exit now");
                                 break
                             },
                             else => break,
@@ -616,7 +617,7 @@ impl TxPoolServiceBuilder {
                         service.update_block_assembler_after_tx_pool_reorg().await;
                     },
                     _ = signal_receiver.cancelled() => {
-                        debug!("TxPool received exit signal, exit now");
+                        info!("TxPool reorg process service received exit signal, exit now");
                         break
                     },
                     else => break,

util/app-config/src/tests/ckb_run_replay.bats

@@ -24,7 +24,7 @@ function ckb_run { #@test
   run _ckb_run
   [ "$status" -eq 0 ]
   # assert_output --regexp "ckb_chain::chain.*block number:.*, hash:.*, size:.*, cycles:.*"
-  assert_output --regexp "ckb_bin  ckb shutdown"
+  assert_output --regexp "INFO ckb_bin  all tokio tasks and threads have exited, ckb shutdown"
 }
 
 function ckb_replay { #@test

util/app-config/src/tests/graceful_shutdown.bats

@@ -3,13 +3,12 @@ bats_load_library 'bats-assert'
 bats_load_library 'bats-support'
 
 _ckb_graceful_shutdown() {
-  ckb run -C ${CKB_DIRNAME} &> ${TMP_DIR}/ckb_run.log &
+  ckb run --indexer -C ${CKB_DIRNAME} &> ${TMP_DIR}/ckb_run.log &
   PID=$!
   sleep 10
   kill ${PID}
 
   while kill -0 ${PID}; do
-      echo "waiting for ckb to exit"
       sleep 1
   done
 
@@ -20,24 +19,25 @@ function ckb_graceful_shutdown { #@test
   run _ckb_graceful_shutdown
 
   [ "$status" -eq 0 ]
+
   assert_output --regexp "INFO ckb_bin::subcommand::run  Trapped exit signal, exiting..."
-  assert_output --regexp "DEBUG ckb_stop_handler::stop_register  received exit signal, broadcasting exit signal to all threads"
-  assert_output --regexp "DEBUG ckb_tx_pool::chunk_process  TxPool received exit signal, exit now"
-  assert_output --regexp "DEBUG ckb_sync::types::header_map  HeaderMap limit_memory received exit signal, exit now"
-  assert_output --regexp "DEBUG ckb_chain::chain  ChainService received exit signal, exit now"
-  assert_output --regexp "DEBUG ckb_sync::synchronizer  thread BlockDownload received exit signal, exit now"
-  assert_output --regexp "DEBUG ckb_network::network  NetworkService receive exit signal, start shutdown..."
+  assert_output --regexp "INFO ckb_chain::chain  ChainService received exit signal, exit now"
+  assert_output --regexp "INFO ckb_sync::synchronizer  BlockDownload received exit signal, exit now"
+  assert_output --regexp "INFO ckb_tx_pool::chunk_process  TxPool chunk_command service received exit signal, exit now"
   assert_output --regexp "INFO ckb_tx_pool::service  TxPool is saving, please wait..."
-  assert_output --regexp "DEBUG ckb_tx_pool::service  TxPool received exit signal, exit now"
-  assert_output --regexp "DEBUG ckb_block_filter::filter  BlockFilter received exit signal, exit now"
-  assert_output --regexp "DEBUG ckb_network::services::dump_peer_store  dump peer store before exit"
-  assert_output --regexp "DEBUG ckb_notify  NotifyService received exit signal, exit now"
-  assert_output --regexp "DEBUG ckb_stop_handler::stop_register  wait thread ChainService done"
-  assert_output --regexp "DEBUG ckb_stop_handler::stop_register  wait thread BlockDownload done"
-  assert_output --regexp "DEBUG ckb_stop_handler::stop_register  all ckb threads have been stopped"
-  assert_output --regexp "DEBUG ckb_bin  waiting all tokio tasks done"
+  assert_output --regexp "INFO ckb_tx_pool::service  TxPool reorg process service received exit signal, exit now"
+  assert_output --regexp "INFO ckb_indexer::service  Indexer received exit signal, exit now"
+  assert_output --regexp "INFO ckb_notify  NotifyService received exit signal, exit now"
+  assert_output --regexp "INFO ckb_block_filter::filter  BlockFilter received exit signal, exit now"
+  assert_output --regexp "INFO ckb_sync::types::header_map  HeaderMap limit_memory received exit signal, exit now"
+  assert_output --regexp "INFO ckb_network::network  NetworkService receive exit signal, start shutdown..."
+  assert_output --regexp "INFO ckb_network::network  NetworkService shutdown now"
   assert_output --regexp "INFO ckb_tx_pool::process  TxPool save successfully"
-  assert_output --regexp "INFO ckb_bin  ckb shutdown"
+  assert_output --regexp "INFO ckb_tx_pool::service  TxPool process_service exit now"
+  assert_output --regexp "INFO ckb_stop_handler::stop_register  wait thread ChainService done"
+  assert_output --regexp "INFO ckb_stop_handler::stop_register  wait thread BlockDownload done"
+  assert_output --regexp "INFO ckb_bin  waiting all tokio tasks exit..."
+  assert_output --regexp "INFO ckb_bin  all tokio tasks and threads have exited, ckb shutdown"
 }
 
 teardown_file() {

util/indexer/src/service.rs

@@ -16,7 +16,7 @@ use ckb_jsonrpc_types::{
     IndexerScriptSearchMode, IndexerScriptType, IndexerSearchKey, IndexerTip, IndexerTx,
     IndexerTxWithCell, IndexerTxWithCells, JsonBytes, Uint32,
 };
-use ckb_logger::{debug, error, info};
+use ckb_logger::{error, info};
 use ckb_notify::NotifyController;
 use ckb_stop_handler::{new_tokio_exit_rx, CancellationToken};
 use ckb_store::ChainStore;
@@ -118,7 +118,7 @@ impl IndexerService {
                         }
                     }
                     _ = stop.cancelled() => {
-                        debug!("Indexer received exit signal, exit now");
+                        info!("Indexer received exit signal, exit now");
                         break
                     },
                     else => break,
@@ -204,7 +204,7 @@ impl IndexerService {
                         }
                     }
                     _ = stop.cancelled() => {
-                        debug!("Indexer received exit signal, exit now");
+                        info!("Indexer received exit signal, exit now");
                         break
                     },
                 }

util/metrics-service/src/lib.rs

@@ -10,7 +10,7 @@ use hyper::{
 use prometheus::Encoder as _;
 
 use ckb_async_runtime::Handle;
-use ckb_logger::debug;
+use ckb_logger::info;
 use ckb_metrics_config::{Config, Exporter, Target};
 use ckb_stop_handler::{new_tokio_exit_rx, CancellationToken};
 use ckb_util::strings;
@@ -66,7 +66,7 @@ fn run_exporter(exporter: Exporter, handle: &Handle) -> Result<(), String> {
                     .with_graceful_shutdown(async {
                         let exit_rx: CancellationToken = new_tokio_exit_rx();
                         exit_rx.cancelled().await;
-                        debug!("prometheus server received exit signal, exit now");
+                        info!("prometheus server received exit signal, exit now");
                     });
                 if let Err(err) = server.await {
                     ckb_logger::error!("prometheus server error: {}", err);

util/stop-handler/src/stop_register.rs

@@ -1,5 +1,5 @@
 use ckb_channel::TrySendError;
-use ckb_logger::{debug, error, info, trace, warn};
+use ckb_logger::{debug, info, trace, warn};
 use ckb_util::Mutex;
 use tokio_util::sync::CancellationToken;
 
@@ -17,7 +17,7 @@ pub fn wait_all_ckb_services_exit() {
     for (name, join_handle) in handles.thread_handles.drain(..) {
         match join_handle.join() {
             Ok(_) => {
-                debug!("wait thread {} done", name);
+                info!("wait thread {} done", name);
             }
             Err(e) => {
                 warn!("wait thread {}: ERROR: {:?}", name, e)
@@ -61,9 +61,9 @@ pub fn broadcast_exit_signals() {
         .iter()
         .for_each(|tx| match tx.try_send(()) {
             Ok(_) => {}
-            Err(TrySendError::Full(_)) => error!("send exit signal to channel failed since the channel is full, this should not happen"),
+            Err(TrySendError::Full(_)) => info!("ckb process has received exit signal"),
             Err(TrySendError::Disconnected(_)) => {
-                info!("broadcast thread: channel is disconnected")
+                debug!("broadcast thread: channel is disconnected")
             }
         });
 }