From 1bf2dc5aca30e3dbe97e3e6db314ffd256966fec Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 24 May 2019 16:44:38 +0800 Subject: [PATCH 1/9] feat: wrap the log macros to fix ill formed macros --- Cargo.lock | 37 ++++++------ ckb-bin/Cargo.toml | 1 - script/Cargo.toml | 2 +- script/src/syscalls/debugger.rs | 4 +- script/src/verify.rs | 33 ++++++++--- test/Cargo.toml | 2 +- test/src/main.rs | 4 +- util/app-config/Cargo.toml | 2 +- util/app-config/src/app_config.rs | 2 +- util/app-config/src/lib.rs | 4 +- util/logger/Cargo.toml | 2 +- util/logger/src/lib.rs | 97 ++++++++++++++++++++++++++++++- 12 files changed, 148 insertions(+), 42 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index ecd5a7d2c5..6538f11122 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -317,6 +317,7 @@ dependencies = [ "ckb-chain-spec 0.14.0-pre", "ckb-db 0.14.0-pre", "ckb-instrument 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-miner 0.14.0-pre", "ckb-network 0.14.0-pre", "ckb-pow 0.14.0-pre", @@ -328,7 +329,6 @@ dependencies = [ "ckb-sync 0.14.0-pre", "clap 2.33.0 (registry+https://github.com/rust-lang/crates.io-index)", "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", - "logger 0.14.0-pre", "sentry 0.15.5 (registry+https://github.com/rust-lang/crates.io-index)", "serde 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", "serde_derive 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", @@ -389,7 +389,6 @@ dependencies = [ "futures 0.1.26 (registry+https://github.com/rust-lang/crates.io-index)", "hash 0.14.0-pre", "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", - "logger 0.14.0-pre", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-uint 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "sentry 0.15.5 (registry+https://github.com/rust-lang/crates.io-index)", @@ -499,6 +498,23 @@ dependencies = [ "serde_json 1.0.39 (registry+https://github.com/rust-lang/crates.io-index)", ] +[[package]] +name = "ckb-logger" +version = "0.14.0-pre" +dependencies = [ + "ansi_term 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)", + "backtrace 0.3.20 (registry+https://github.com/rust-lang/crates.io-index)", + "chrono 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", + "crossbeam-channel 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", + "env_logger 0.6.1 (registry+https://github.com/rust-lang/crates.io-index)", + "lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)", + "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", + "parking_lot 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)", + "regex 1.1.6 (registry+https://github.com/rust-lang/crates.io-index)", + "serde 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", + "serde_derive 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", +] + [[package]] name = "ckb-merkle-tree" version = "0.14.0-pre" @@ -1858,23 +1874,6 @@ dependencies = [ "cfg-if 0.1.7 (registry+https://github.com/rust-lang/crates.io-index)", ] -[[package]] -name = "logger" -version = "0.14.0-pre" -dependencies = [ - "ansi_term 0.11.0 (registry+https://github.com/rust-lang/crates.io-index)", - "backtrace 0.3.20 (registry+https://github.com/rust-lang/crates.io-index)", - "chrono 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", - "crossbeam-channel 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", - "env_logger 0.6.1 (registry+https://github.com/rust-lang/crates.io-index)", - "lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", - "parking_lot 0.7.1 (registry+https://github.com/rust-lang/crates.io-index)", - "regex 1.1.6 (registry+https://github.com/rust-lang/crates.io-index)", - "serde 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", - "serde_derive 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", -] - [[package]] name = "lru-cache" version = "0.1.0" diff --git a/ckb-bin/Cargo.toml b/ckb-bin/Cargo.toml index 8911bb6edd..05ffd5723e 100644 --- a/ckb-bin/Cargo.toml +++ b/ckb-bin/Cargo.toml @@ -27,7 +27,6 @@ ckb-pow = { path = "../pow" } ckb-network = { path = "../network"} ckb-rpc = { path = "../rpc"} ckb-resource = { path = "../resource"} -logger = { path = "../util/logger" } numext-fixed-hash = { version = "0.1", features = ["support_rand", "support_heapsize", "support_serde"] } numext-fixed-uint = { version = "0.1", features = ["support_rand", "support_heapsize", "support_serde"] } ctrlc = { version = "3.1", features = ["termination"] } diff --git a/script/Cargo.toml b/script/Cargo.toml index 12c145cede..024922b0ed 100644 --- a/script/Cargo.toml +++ b/script/Cargo.toml @@ -16,7 +16,7 @@ ckb-vm = { git = "https://github.com/nervosnetwork/ckb-vm", rev = "5c443bc", fea faster-hex = "0.3" fnv = "1.0.3" flatbuffers = "0.6.0" -log = "0.4" +ckb-logger = { path = "../util/logger" } ckb-protocol = { path = "../protocol" } serde = "1.0" serde_derive = "1.0" diff --git a/script/src/syscalls/debugger.rs b/script/src/syscalls/debugger.rs index ff72ee0ead..9ea9df29a8 100644 --- a/script/src/syscalls/debugger.rs +++ b/script/src/syscalls/debugger.rs @@ -1,9 +1,9 @@ use crate::syscalls::DEBUG_PRINT_SYSCALL_NUMBER; +use ckb_logger::debug; use ckb_vm::{ registers::{A0, A7}, Error as VMError, Memory, Register, SupportMachine, Syscalls, }; -use log::debug; pub struct Debugger<'a> { prefix: &'a str, @@ -43,7 +43,7 @@ impl<'a, Mac: SupportMachine> Syscalls for Debugger<'a> { machine.add_cycles(buffer.len() as u64 * 10)?; let s = String::from_utf8(buffer).map_err(|_| VMError::ParseError)?; - debug!(target: "script", "{} DEBUG OUTPUT: {}", self.prefix, s); + debug!("{} DEBUG OUTPUT: {}", self.prefix, s); Ok(true) } } diff --git a/script/src/verify.rs b/script/src/verify.rs index e203ef65eb..148acad866 100644 --- a/script/src/verify.rs +++ b/script/src/verify.rs @@ -11,6 +11,7 @@ use ckb_core::script::{Script, DAO_CODE_HASH}; use ckb_core::transaction::{CellInput, CellOutPoint, Witness}; use ckb_core::{BlockNumber, Capacity}; use ckb_core::{Bytes, Cycle}; +use ckb_logger::info; use ckb_resource::bundled; use ckb_store::{ChainStore, LazyLoadCellOutput}; use ckb_vm::{ @@ -20,7 +21,6 @@ use ckb_vm::{ }; use dao::calculate_maximum_withdraw; use fnv::FnvHashMap; -use log::info; use numext_fixed_hash::H256; use std::cmp::min; use std::path::PathBuf; @@ -225,10 +225,20 @@ impl<'a, CS: ChainStore> TransactionScriptsVerifier<'a, CS> { appended_arguments.extend_from_slice(&witness); } - let cycle = self.verify_script(&output.lock, &prefix, &appended_arguments, max_cycles - cycles).map_err(|e| { - info!(target: "script", "Error validating input {} of transaction {:x}: {:?}", i, self.hash, e); - e - })?; + let cycle = self + .verify_script( + &output.lock, + &prefix, + &appended_arguments, + max_cycles - cycles, + ) + .map_err(|e| { + info!( + "Error validating input {} of transaction {:x}: {:?}", + i, self.hash, e + ); + e + })?; let current_cycles = cycles .checked_add(cycle) .ok_or(ScriptError::ExceededMaximumCycles)?; @@ -241,10 +251,15 @@ impl<'a, CS: ChainStore> TransactionScriptsVerifier<'a, CS> { let output = cell_meta.cell_output.as_ref().expect("output already set"); if let Some(ref type_) = output.type_ { let prefix = format!("Transaction {:x}, output {}", self.hash, i); - let cycle = self.verify_script(type_, &prefix, &[], max_cycles - cycles).map_err(|e| { - info!(target: "script", "Error validating output {} of transaction {:x}: {:?}", i, self.hash, e); - e - })?; + let cycle = self + .verify_script(type_, &prefix, &[], max_cycles - cycles) + .map_err(|e| { + info!( + "Error validating output {} of transaction {:x}: {:?}", + i, self.hash, e + ); + e + })?; let current_cycles = cycles .checked_add(cycle) .ok_or(ScriptError::ExceededMaximumCycles)?; diff --git a/test/Cargo.toml b/test/Cargo.toml index 4779158959..d030f1e1d2 100644 --- a/test/Cargo.toml +++ b/test/Cargo.toml @@ -8,7 +8,7 @@ edition = "2018" [dependencies] toml = "0.5.0" jsonrpc-types = { path = "../util/jsonrpc-types" } -logger = { path = "../util/logger" } +ckb-logger = { path = "../util/logger" } ckb-app-config = { path = "../util/app-config" } ckb-core = { path = "../core" } ckb-network = { path = "../network" } diff --git a/test/src/main.rs b/test/src/main.rs index 82c060f01d..0d00602036 100644 --- a/test/src/main.rs +++ b/test/src/main.rs @@ -1,6 +1,6 @@ +use ckb_logger::{self, Config}; use ckb_test::specs::*; use ckb_test::Spec; -use logger::{self, Config}; use std::collections::HashMap; use std::env; @@ -9,7 +9,7 @@ fn main() { filter: Some("info".to_owned()), ..Default::default() }; - let _logger_guard = logger::init(log_config).expect("init Logger"); + let _logger_guard = ckb_logger::init(log_config).expect("init Logger"); let binary = env::args() .nth(1) diff --git a/util/app-config/Cargo.toml b/util/app-config/Cargo.toml index 9c037a7235..6aa19113e6 100644 --- a/util/app-config/Cargo.toml +++ b/util/app-config/Cargo.toml @@ -11,7 +11,7 @@ serde = "1.0" serde_derive = "1.0" toml = "0.5" log = "0.4" -logger = { path = "../../util/logger" } +ckb-logger = { path = "../../util/logger" } sentry = "^0.15.4" ckb-chain-spec = {path = "../../spec"} ckb-network = { path = "../../network"} diff --git a/util/app-config/src/app_config.rs b/util/app-config/src/app_config.rs index 3e635e9620..2cd1ccd8a8 100644 --- a/util/app-config/src/app_config.rs +++ b/util/app-config/src/app_config.rs @@ -11,6 +11,7 @@ use serde_derive::{Deserialize, Serialize}; use ckb_chain_spec::ChainSpec; use ckb_db::DBConfig; +use ckb_logger::Config as LogConfig; use ckb_miner::BlockAssemblerConfig; use ckb_miner::MinerConfig; use ckb_network::NetworkConfig; @@ -20,7 +21,6 @@ use ckb_script::ScriptConfig; use ckb_shared::tx_pool::TxPoolConfig; use ckb_store::StoreConfig; use ckb_sync::Config as SyncConfig; -use logger::Config as LogConfig; use super::sentry_config::SentryConfig; use super::{cli, ExitCode}; diff --git a/util/app-config/src/lib.rs b/util/app-config/src/lib.rs index 797f852907..1db202debf 100644 --- a/util/app-config/src/lib.rs +++ b/util/app-config/src/lib.rs @@ -12,10 +12,10 @@ pub use exit_code::ExitCode; use build_info::Version; use ckb_chain_spec::{consensus::Consensus, ChainSpec}; use ckb_instrument::Format; +use ckb_logger::LoggerInitGuard; use ckb_resource::ResourceLocator; use clap::{value_t, ArgMatches}; use log::info; -use logger::LoggerInitGuard; use std::path::PathBuf; pub struct Setup { @@ -63,7 +63,7 @@ impl Setup { // Initialization of logger must do before sentry, since `logger::init()` and // `sentry_config::init()` both registers custom panic hooks, but `logger::init()` // replaces all hooks previously registered. - let logger_guard = logger::init(self.config.logger().to_owned())?; + let logger_guard = ckb_logger::init(self.config.logger().to_owned())?; let sentry_guard = if self.is_sentry_enabled { let sentry_config = self.config.sentry(); diff --git a/util/logger/Cargo.toml b/util/logger/Cargo.toml index c960a7b888..b6af2cafeb 100644 --- a/util/logger/Cargo.toml +++ b/util/logger/Cargo.toml @@ -1,5 +1,5 @@ [package] -name = "logger" +name = "ckb-logger" version = "0.14.0-pre" license = "MIT" authors = ["Nervos "] diff --git a/util/logger/src/lib.rs b/util/logger/src/lib.rs index 13c520fc69..923e37eeae 100644 --- a/util/logger/src/lib.rs +++ b/util/logger/src/lib.rs @@ -4,8 +4,7 @@ use chrono::prelude::{DateTime, Local}; use crossbeam_channel::unbounded; use env_logger::filter::{Builder, Filter}; use lazy_static::lazy_static; -use log::{LevelFilter, SetLoggerError}; -use log::{Log, Metadata, Record}; +use log::{LevelFilter, Log, Metadata, Record}; use parking_lot::Mutex; use regex::Regex; use serde_derive::{Deserialize, Serialize}; @@ -13,6 +12,100 @@ use std::io::Write; use std::path::PathBuf; use std::{fs, panic, thread}; +pub use log::{self as internal, Level, SetLoggerError}; + +#[doc(hidden)] +#[macro_export] +macro_rules! env { + ($($inner:tt)*) => { + env!($($inner)*) + } +} + +#[macro_export(local_inner_macros)] +macro_rules! trace { + ($( $args:tt )*) => { + $crate::internal::trace!(target: $crate::env!("CARGO_PKG_NAME"), $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! debug { + ($( $args:tt )*) => { + $crate::internal::debug!(target: $crate::env!("CARGO_PKG_NAME"), $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! info { + ($( $args:tt )*) => { + $crate::internal::info!(target: $crate::env!("CARGO_PKG_NAME"), $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! warn { + ($( $args:tt )*) => { + $crate::internal::warn!(target: $crate::env!("CARGO_PKG_NAME"), $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! error { + ($( $args:tt )*) => { + $crate::internal::error!(target: $crate::env!("CARGO_PKG_NAME"), $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! log_enabled { + ($level:expr) => { + $crate::internal::log_enabled!(target: $crate::env!("CARGO_PKG_NAME"), $level); + }; +} + +#[macro_export(local_inner_macros)] +macro_rules! trace_target { + ($target:expr, $( $args:tt )*) => { + $crate::internal::trace!(target: $target, $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! debug_target { + ($target:expr, $( $args:tt )*) => { + $crate::internal::debug!(target: $target, $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! info_target { + ($target:expr, $( $args:tt )*) => { + $crate::internal::info!(target: $target, $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! warn_target { + ($target:expr, $( $args:tt )*) => { + $crate::internal::warn!(target: $target, $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! error_target { + ($target:expr, $( $args:tt )*) => { + $crate::internal::error!(target: $target, $( $args )*); + } +} + +#[macro_export(local_inner_macros)] +macro_rules! log_enabled_target { + ($target:expr, $level:expr) => { + $crate::internal::log_enabled!(target: $target, $level); + }; +} + enum Message { Record(String), Terminate, From 652aa2090a2c52f638b63311882db914cc510c02 Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 11:40:14 +0800 Subject: [PATCH 2/9] chore: apply new log macros to chain --- Cargo.lock | 2 +- chain/Cargo.toml | 2 +- chain/src/chain.rs | 49 +++++++++++++++++++++++++--------------------- 3 files changed, 29 insertions(+), 24 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 6538f11122..ce60129e7d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -405,6 +405,7 @@ dependencies = [ "ckb-chain-spec 0.14.0-pre", "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-notify 0.14.0-pre", "ckb-shared 0.14.0-pre", "ckb-store 0.14.0-pre", @@ -417,7 +418,6 @@ dependencies = [ "faketime 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", "fnv 1.0.6 (registry+https://github.com/rust-lang/crates.io-index)", "hash 0.14.0-pre", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "lru-cache 0.1.0 (git+https://github.com/nervosnetwork/lru-cache?rev=a35fdb8)", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-uint 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", diff --git a/chain/Cargo.toml b/chain/Cargo.toml index fee76c2f7a..a477f172bf 100644 --- a/chain/Cargo.toml +++ b/chain/Cargo.toml @@ -6,7 +6,7 @@ authors = ["Nervos Core Dev "] edition = "2018" [dependencies] -log = "0.4" +ckb-logger = { path = "../util/logger" } ckb-core = { path = "../core" } ckb-shared = { path = "../shared" } ckb-chain-spec = { path = "../spec" } diff --git a/chain/src/chain.rs b/chain/src/chain.rs index 0fd35cdc4b..963eba96d8 100644 --- a/chain/src/chain.rs +++ b/chain/src/chain.rs @@ -7,6 +7,7 @@ use ckb_core::extras::{BlockExt, DaoStats}; use ckb_core::service::{Request, DEFAULT_CHANNEL_SIZE, SIGNAL_CHANNEL_SIZE}; use ckb_core::transaction::{CellOutput, ProposalShortId}; use ckb_core::{BlockNumber, Cycle}; +use ckb_logger::{self, debug, error, info, log_enabled, warn}; use ckb_notify::NotifyController; use ckb_shared::cell_set::CellSetDiff; use ckb_shared::chain_state::ChainState; @@ -20,7 +21,6 @@ use dao::calculate_dao_data; use failure::Error as FailureError; use faketime::unix_time_as_millis; use fnv::{FnvHashMap, FnvHashSet}; -use log::{self, debug, error, info, log_enabled, warn}; use lru_cache::LruCache; use numext_fixed_hash::H256; use numext_fixed_uint::U256; @@ -186,7 +186,7 @@ impl ChainService { let _ = responder.send(self.process_block(block, verify)); }, _ => { - error!(target: "chain", "process_block_receiver closed"); + error!("process_block_receiver closed"); break; }, } @@ -208,12 +208,16 @@ impl ChainService { block: Arc, need_verify: bool, ) -> Result<(), FailureError> { - debug!(target: "chain", "begin processing block: {:x}", block.header().hash()); + debug!("begin processing block: {:x}", block.header().hash()); if block.header().number() < 1 { - warn!(target: "chain", "receive 0 number block: {}-{:x}", block.header().number(), block.header().hash()); + warn!( + "receive 0 number block: {}-{:x}", + block.header().number(), + block.header().hash() + ); } self.insert_block(block, need_verify)?; - debug!(target: "chain", "finish processing block"); + debug!("finish processing block"); Ok(()) } @@ -221,7 +225,7 @@ impl ChainService { if need_verify { let block_verifier = BlockVerifier::new(self.shared.clone()); block_verifier.verify(&block).map_err(|e| { - debug!(target: "chain", "[process_block] verification error {:?}", e); + debug!("[process_block] verification error {:?}", e); e })? } @@ -249,10 +253,8 @@ impl ChainService { let current_total_difficulty = chain_state.total_difficulty().to_owned(); debug!( - target: "chain", "difficulty current = {:#x}, cannon = {:#x}", - current_total_difficulty, - cannon_total_difficulty, + current_total_difficulty, cannon_total_difficulty, ); if parent_ext.txs_verified == Some(false) { @@ -303,9 +305,9 @@ impl ChainService { && (block.header().hash() < chain_state.tip_hash())) { debug!( - target: "chain", "new best block found: {} => {:#x}, difficulty diff = {:#x}", - block.header().number(), block.header().hash(), + block.header().number(), + block.header().hash(), &cannon_total_difficulty - ¤t_total_difficulty ); self.find_fork(&mut fork, chain_state.tip_number(), &block, ext); @@ -338,7 +340,6 @@ impl ChainService { if new_best_block { let tip_header = block.header().to_owned(); info!( - target: "chain", "block: {}, hash: {:#x}, total_diff: {:#x}, txs: {}", tip_header.number(), tip_header.hash(), @@ -363,12 +364,11 @@ impl ChainService { self.notify .notify_new_uncle(Arc::new(detached_block.clone())); } - if log_enabled!(target: "chain", log::Level::Debug) { + if log_enabled!(ckb_logger::Level::Debug) { self.print_chain(&chain_state, 10); } } else { info!( - target: "chain", "uncle: {}, hash: {:#x}, total_diff: {:#x}, txs: {}", block.header().number(), block.header().hash(), @@ -590,7 +590,6 @@ impl ChainService { self.shared.consensus().pow_engine().proof_size(); if b.transactions().len() > 1 { info!( - target: "chain", "[block_verifier] block number: {}, hash: {:#x}, size:{}/{}, cycles: {}/{}", b.header().number(), b.header().hash(), @@ -602,8 +601,11 @@ impl ChainService { } } Err(err) => { - error!(target: "chain", "cell_set_diff {}", serde_json::to_string(&cell_set_diff).unwrap()); - error!(target: "chain", "block {}", serde_json::to_string(b).unwrap()); + error!( + "cell_set_diff {}", + serde_json::to_string(&cell_set_diff).unwrap() + ); + error!("block {}", serde_json::to_string(b).unwrap()); found_error = Some(SharedError::InvalidTransaction(err.to_string())); *verified = Some(false); @@ -620,7 +622,10 @@ impl ChainService { } if found_error.is_some() { - error!(target: "chain", "cell_set {}", serde_json::to_string(&chain_state.cell_set()).unwrap()); + error!( + "cell_set {}", + serde_json::to_string(&chain_state.cell_set()).unwrap() + ); } } else { cell_set_diff.push_new(b); @@ -641,7 +646,7 @@ impl ChainService { } if let Some(err) = found_error { - error!(target: "chain", "fork {}", serde_json::to_string(&fork).unwrap()); + error!("fork {}", serde_json::to_string(&fork).unwrap()); Err(err)? } else { Ok(cell_set_diff) @@ -650,7 +655,7 @@ impl ChainService { // TODO: beatify fn print_chain(&self, chain_state: &ChainState, len: u64) { - debug!(target: "chain", "Chain {{"); + debug!("Chain {{"); let tip = chain_state.tip_number(); let bottom = tip - cmp::min(tip, len); @@ -659,9 +664,9 @@ impl ChainService { let hash = self.shared.block_hash(number).unwrap_or_else(|| { panic!(format!("invaild block number({}), tip={}", number, tip)) }); - debug!(target: "chain", " {} => {:x}", number, hash); + debug!(" {} => {:x}", number, hash); } - debug!(target: "chain", "}}"); + debug!("}}"); } } From ea6f7280fb95b7dbae2f24fd7aa7a48194efb53d Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 11:51:28 +0800 Subject: [PATCH 3/9] chore: apply new log macros to miner --- Cargo.lock | 2 +- miner/Cargo.toml | 2 +- miner/src/block_assembler.rs | 8 ++++---- miner/src/client.rs | 13 ++++++++----- miner/src/miner.rs | 8 ++++---- 5 files changed, 18 insertions(+), 15 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index ce60129e7d..543117200b 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -532,6 +532,7 @@ dependencies = [ "ckb-chain-spec 0.14.0-pre", "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-notify 0.14.0-pre", "ckb-pow 0.14.0-pre", "ckb-shared 0.14.0-pre", @@ -547,7 +548,6 @@ dependencies = [ "futures 0.1.26 (registry+https://github.com/rust-lang/crates.io-index)", "hyper 0.12.29 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-types 0.14.0-pre", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "lru-cache 0.1.0 (git+https://github.com/nervosnetwork/lru-cache?rev=a35fdb8)", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-uint 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", diff --git a/miner/Cargo.toml b/miner/Cargo.toml index f671d20ff0..31e02afcad 100644 --- a/miner/Cargo.toml +++ b/miner/Cargo.toml @@ -6,7 +6,7 @@ authors = ["Nervos Core Dev "] edition = "2018" [dependencies] -log = "0.4" +ckb-logger = { path = "../util/logger" } numext-fixed-hash = { version = "0.1", features = ["support_rand", "support_heapsize", "support_serde"] } numext-fixed-uint = { version = "0.1", features = ["support_rand", "support_heapsize", "support_serde"] } ckb-core = { path = "../core" } diff --git a/miner/src/block_assembler.rs b/miner/src/block_assembler.rs index 6ec47c5624..af0306fd11 100644 --- a/miner/src/block_assembler.rs +++ b/miner/src/block_assembler.rs @@ -11,6 +11,7 @@ use ckb_core::transaction::{ }; use ckb_core::uncle::UncleBlock; use ckb_core::{Bytes, Cycle, Version}; +use ckb_logger::{error, info}; use ckb_notify::NotifyController; use ckb_shared::{shared::Shared, tx_pool::ProposedEntry}; use ckb_store::ChainStore; @@ -25,7 +26,6 @@ use jsonrpc_types::{ EpochNumber as JsonEpochNumber, JsonBytes, Timestamp as JsonTimestamp, TransactionTemplate, UncleTemplate, Unsigned, Version as JsonVersion, }; -use log; use lru_cache::LruCache; use numext_fixed_hash::H256; use std::cmp; @@ -147,7 +147,7 @@ impl BlockAssembler { .store(unix_time_as_millis(), Ordering::SeqCst); } _ => { - log::error!(target: "miner", "new_uncle_receiver closed"); + error!("new_uncle_receiver closed"); break; } }, @@ -163,7 +163,7 @@ impl BlockAssembler { ); }, _ => { - log::error!(target: "miner", "get_block_template_receiver closed"); + error!("get_block_template_receiver closed"); break; }, } @@ -327,7 +327,7 @@ impl BlockAssembler { let (entries, size, cycles) = chain_state.get_proposed_txs(txs_size_limit, txs_cycles_limit); if !entries.is_empty() { - log::info!( + info!( "[get_block_template] candidate txs count: {}, size: {}/{}, cycles:{}/{}", entries.len(), size, diff --git a/miner/src/client.rs b/miner/src/client.rs index 39bb429104..0f1ef0dcb6 100644 --- a/miner/src/client.rs +++ b/miner/src/client.rs @@ -1,5 +1,6 @@ use crate::{MinerConfig, Work}; use ckb_core::block::Block; +use ckb_logger::{debug, error, warn}; use crossbeam_channel::Sender; use futures::sync::{mpsc, oneshot}; use hyper::error::Error as HyperError; @@ -12,7 +13,6 @@ use jsonrpc_types::{ error::Error as RpcFail, id::Id, params::Params, request::MethodCall, response::Output, version::Version, Block as JsonBlock, }; -use log::{debug, error, warn}; use numext_fixed_hash::H256; use serde_json::error::Error as JsonError; use serde_json::{self, json, Value}; @@ -141,11 +141,14 @@ impl Client { match ret { Ok(hash) => { if hash.is_none() { - warn!(target: "miner", "submit_block failed {}", serde_json::to_string(block).unwrap()); + warn!( + "submit_block failed {}", + serde_json::to_string(block).unwrap() + ); } } Err(e) => { - error!(target: "miner", "rpc call submit_block error: {:?}", e); + error!("rpc call submit_block error: {:?}", e); sentry::capture_message( &format!("rpc call submit_block error: {:?}", e), sentry::Level::Error, @@ -157,7 +160,7 @@ impl Client { pub fn poll_block_template(&self) { loop { - debug!(target: "miner", "poll block template..."); + debug!("poll block template..."); self.try_update_block_template(); thread::sleep(time::Duration::from_millis(self.config.poll_interval)); } @@ -175,7 +178,7 @@ impl Client { } } Err(e) => { - error!(target: "miner", "rpc call get_block_template error: {:?}", e); + error!("rpc call get_block_template error: {:?}", e); } } updated diff --git a/miner/src/miner.rs b/miner/src/miner.rs index a7e2ca6cc9..aab0a8d05c 100644 --- a/miner/src/miner.rs +++ b/miner/src/miner.rs @@ -2,11 +2,11 @@ use crate::client::Client; use crate::Work; use ckb_core::block::{Block, BlockBuilder}; use ckb_core::header::{HeaderBuilder, RawHeader, Seal}; +use ckb_logger::{debug, error, info}; use ckb_pow::PowEngine; use crossbeam_channel::Receiver; use failure::Error; use jsonrpc_types::{BlockTemplate, CellbaseTemplate}; -use log::{debug, error, info}; use rand::{thread_rng, Rng}; use std::convert::TryInto; use std::sync::Arc; @@ -41,7 +41,7 @@ impl Miner { self.client.try_update_block_template(); } } - Err(e) => error!(target: "miner", "mining error encountered: {:?}", e), + Err(e) => error!("mining error encountered: {:?}", e), }; } } @@ -123,9 +123,9 @@ impl Miner { if self.new_work_rx.try_recv().is_ok() { break None; } - debug!(target: "miner", "mining header #{} with nonce {}", header.number(), nonce); + debug!("mining header #{} with nonce {}", header.number(), nonce); if let Some(seal) = self.pow.solve_header(header, nonce) { - info!(target: "miner", "found seal: {:?}", seal); + info!("found seal: {:?}", seal); break Some(seal); } nonce = nonce.wrapping_add(1); From 571b7a995e77c167ed36a436edc9695d807d399f Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 12:01:39 +0800 Subject: [PATCH 4/9] chore: apply new log macros to network --- Cargo.lock | 2 +- network/Cargo.toml | 2 +- network/src/compress.rs | 6 +- network/src/config.rs | 6 +- network/src/network.rs | 139 +++++++++++------------- network/src/peer_registry.rs | 4 +- network/src/protocols/discovery.rs | 43 ++++---- network/src/protocols/feeler.rs | 8 +- network/src/protocols/identify.rs | 10 +- network/src/protocols/mod.rs | 57 +++++++--- network/src/protocols/ping.rs | 16 +-- network/src/services/dns_seeding/mod.rs | 30 ++--- network/src/services/outbound_peer.rs | 15 ++- 13 files changed, 175 insertions(+), 163 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 543117200b..878741401a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -567,6 +567,7 @@ dependencies = [ "bs58 0.2.2 (registry+https://github.com/rust-lang/crates.io-index)", "build-info 0.14.0-pre", "bytes 0.4.12 (registry+https://github.com/rust-lang/crates.io-index)", + "ckb-logger 0.14.0-pre", "ckb-util 0.14.0-pre", "criterion 0.2.11 (registry+https://github.com/rust-lang/crates.io-index)", "crossbeam-channel 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", @@ -577,7 +578,6 @@ dependencies = [ "generic-channel 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", "hash 0.14.0-pre", "lazy_static 1.3.0 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "num_cpus 1.10.0 (registry+https://github.com/rust-lang/crates.io-index)", "rand 0.6.5 (registry+https://github.com/rust-lang/crates.io-index)", "resolve 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", diff --git a/network/Cargo.toml b/network/Cargo.toml index 551064809c..3e0a110ad6 100644 --- a/network/Cargo.toml +++ b/network/Cargo.toml @@ -15,7 +15,7 @@ serde = "1.0" serde_derive = "1.0" ckb-util = { path = "../util" } stop-handler = { path = "../util/stop-handler" } -log = "0.4.5" +ckb-logger = { path = "../util/logger" } bytes = "0.4.12" tokio = "0.1.18" futures = "0.1" diff --git a/network/src/compress.rs b/network/src/compress.rs index 24d290f663..61c97bf52e 100644 --- a/network/src/compress.rs +++ b/network/src/compress.rs @@ -1,5 +1,5 @@ use bytes::{Bytes, BytesMut}; -use log::debug; +use ckb_logger::debug; use snap::{Decoder as SnapDecoder, Encoder as SnapEncoder}; use std::io; @@ -51,7 +51,7 @@ impl Message { self.set_compress_flag(); } Err(e) => { - debug!(target: "network", "snappy compress error: {}", e); + debug!("snappy compress error: {}", e); self.inner.unsplit(input); } } @@ -67,7 +67,7 @@ impl Message { match SnapDecoder::new().decompress_vec(&self.inner[1..]) { Ok(res) => Ok(Bytes::from(res)), Err(e) => { - debug!(target: "network", "snappy decompress error: {:?}", e); + debug!("snappy decompress error: {:?}", e); Err(io::ErrorKind::InvalidData.into()) } } diff --git a/network/src/config.rs b/network/src/config.rs index 083e05c9c4..e10709f0b6 100644 --- a/network/src/config.rs +++ b/network/src/config.rs @@ -1,6 +1,6 @@ use crate::errors::{ConfigError, Error}; use crate::PeerId; -use log::info; +use ckb_logger::info; use p2p::{ multiaddr::{Multiaddr, Protocol}, secio, @@ -87,9 +87,9 @@ impl NetworkConfig { fn write_secret_key_to_file(&self) -> Result<(), Error> { let path = self.secret_key_path(); - info!(target: "network", "Generate random key"); + info!("Generate random key"); let random_key_pair = generate_random_key(); - info!(target: "network", "write random secret key to {:?}", path); + info!("write random secret key to {:?}", path); fs::OpenOptions::new() .create(true) .write(true) diff --git a/network/src/network.rs b/network/src/network.rs index 65f2c6d812..8e5233546a 100644 --- a/network/src/network.rs +++ b/network/src/network.rs @@ -13,13 +13,13 @@ use crate::{ Behaviour, CKBProtocol, NetworkConfig, ProtocolId, ProtocolVersion, PublicKey, ServiceControl, }; use build_info::Version; +use ckb_logger::{debug, error, info, trace, warn}; use ckb_util::{Mutex, RwLock}; use fnv::{FnvHashMap, FnvHashSet}; use futures::sync::mpsc::channel; use futures::sync::{mpsc, oneshot}; use futures::Future; use futures::Stream; -use log::{debug, error, info, trace, warn}; use p2p::{ builder::{MetaBuilder, ServiceBuilder}, bytes::Bytes, @@ -139,7 +139,7 @@ impl NetworkState { { self.report_peer(p2p_control, &peer_id, behaviour); } else { - debug!(target: "network", "Report {} failed: not in peer registry", session_id); + debug!("Report {} failed: not in peer registry", session_id); } } @@ -149,19 +149,19 @@ impl NetworkState { peer_id: &PeerId, behaviour: Behaviour, ) { - trace!(target: "network", "report {:?} because {:?}", peer_id, behaviour); + trace!("report {:?} because {:?}", peer_id, behaviour); if self .peer_store .lock() .report(peer_id, behaviour) .is_banned() { - info!(target: "network", "peer {:?} banned", peer_id); + info!("peer {:?} banned", peer_id); self.with_peer_registry_mut(|reg| { if let Some(session_id) = reg.get_key_by_peer_id(peer_id) { reg.remove_peer(session_id); if let Err(err) = p2p_control.disconnect(session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", session_id, err); + debug!("Disconnect failed {:?}, error: {:?}", session_id, err); } } }) @@ -179,7 +179,7 @@ impl NetworkState { { self.ban_peer(p2p_control, &peer_id, timeout); } else { - debug!(target: "network", "Ban session({}) failed: not in peer registry", session_id); + debug!("Ban session({}) failed: not in peer registry", session_id); } } @@ -189,12 +189,12 @@ impl NetworkState { peer_id: &PeerId, timeout: Duration, ) { - info!(target: "network", "ban peer {:?} with {:?}", peer_id, timeout); + info!("ban peer {:?} with {:?}", peer_id, timeout); let peer_opt = self.with_peer_registry_mut(|reg| reg.remove_peer_by_peer_id(peer_id)); if let Some(peer) = peer_opt { self.peer_store.lock().ban_addr(&peer.address, timeout); if let Err(err) = p2p_control.disconnect(peer.session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", peer.session_id, err); + debug!("Disconnect failed {:?}, error: {:?}", peer.session_id, err); } } } @@ -336,11 +336,15 @@ impl NetworkState { pub(crate) fn can_dial(&self, peer_id: &PeerId, addr: &Multiaddr) -> bool { if self.local_peer_id() == peer_id { - trace!(target: "network", "Do not dial self: {:?}, {}", peer_id, addr); + trace!("Do not dial self: {:?}, {}", peer_id, addr); return false; } if self.listened_addresses.read().contains_key(&addr) { - trace!(target: "network", "Do not dial listened address(self): {:?}, {}", peer_id, addr); + trace!( + "Do not dial listened address(self): {:?}, {}", + peer_id, + addr + ); return false; } @@ -348,12 +352,16 @@ impl NetworkState { reg.get_key_by_peer_id(peer_id).is_some() || reg.is_feeler(peer_id) }); if peer_in_registry { - trace!(target: "network", "Do not dial peer in registry: {:?}, {}", peer_id, addr); + trace!("Do not dial peer in registry: {:?}, {}", peer_id, addr); return false; } if let Some(dial_started) = self.dialing_addrs.read().get(peer_id) { - trace!(target: "network", "Do not repeat send dial command to network service: {:?}, {}", peer_id, addr); + trace!( + "Do not repeat send dial command to network service: {:?}, {}", + peer_id, + addr + ); if dial_started.elapsed() > DIAL_HANG_TIMEOUT { sentry::capture_message( &format!( @@ -396,9 +404,9 @@ impl NetworkState { match Multihash::from_bytes(peer_id.as_bytes().to_vec()) { Ok(peer_id_hash) => { addr.push(multiaddr::Protocol::P2p(peer_id_hash)); - debug!(target: "network", "dialing {} with {:?}", addr, target); + debug!("dialing {} with {:?}", addr, target); if let Err(err) = p2p_control.dial(addr.clone(), target) { - debug!(target: "network", "dial failed: {:?}", err); + debug!("dial failed: {:?}", err); } else { self.dialing_addrs .write() @@ -406,7 +414,7 @@ impl NetworkState { } } Err(err) => { - error!(target: "network", "failed to convert peer_id to addr: {}", err); + error!("failed to convert peer_id to addr: {}", err); } } } @@ -439,9 +447,9 @@ impl ServiceHandle for EventHandler { ref address, ref error, } => { - debug!(target: "network", "DialerError({}) {}", address, error); + debug!("DialerError({}) {}", address, error); if error == &P2pError::ConnectSelf { - debug!(target: "network", "add self address: {:?}", address); + debug!("add self address: {:?}", address); let addr = address .iter() .filter(|proto| match proto { @@ -462,17 +470,15 @@ impl ServiceHandle for EventHandler { proto_id, error, } => { - debug!(target: "network", "ProtocolError({}, {}) {}", id, proto_id, error); + debug!("ProtocolError({}, {}) {}", id, proto_id, error); if let Err(err) = context.disconnect(id) { - debug!(target: "network", "Disconnect failed {:?}, error {:?}", id, err); + debug!("Disconnect failed {:?}, error {:?}", id, err); } } ServiceError::SessionTimeout { session_context } => { warn!( - target: "network", "SessionTimeout({}, {})", - session_context.id, - session_context.address, + session_context.id, session_context.address, ); } ServiceError::MuxerError { @@ -480,32 +486,27 @@ impl ServiceHandle for EventHandler { error, } => { debug!( - target: "network", "MuxerError({}, {}), substream error {}, disconnect it", - session_context.id, - session_context.address, - error, + session_context.id, session_context.address, error, ); } ServiceError::ListenError { address, error } => { - debug!(target: "network", "ListenError: address={:?}, error={:?}", address, error); + debug!("ListenError: address={:?}, error={:?}", address, error); } ServiceError::ProtocolSelectError { proto_name, session_context, } => { debug!( - target: "network", "ProtocolSelectError: proto_name={:?}, session_id={}", - proto_name, - session_context.id, + proto_name, session_context.id, ); } ServiceError::SessionBlocked { session_context } => { - debug!(target: "network", "SessionBlocked: {}", session_context.id); + debug!("SessionBlocked: {}", session_context.id); } err => { - debug!(target: "network", "p2p service error: {:?}", err); + debug!("p2p service error: {:?}", err); sentry::capture_message( &format!("p2p service error: {:?}", err), sentry::Level::Warning, @@ -519,10 +520,8 @@ impl ServiceHandle for EventHandler { match event { ServiceEvent::SessionOpen { session_context } => { debug!( - target: "network", "SessionOpen({}, {})", - session_context.id, - session_context.address, + session_context.id, session_context.address, ); let peer_id = session_context .remote_pubkey @@ -537,40 +536,37 @@ impl ServiceHandle for EventHandler { .with_peer_registry(|reg| reg.is_feeler(&peer_id)) { debug!( - target: "network", "feeler connected {} => {}", - session_context.id, - session_context.address, + session_context.id, session_context.address, ); } else { match self.network_state.accept_peer(&session_context) { Ok(Some(evicted_peer)) => { debug!( - target: "network", "evict peer (disonnect it), {} => {}", - evicted_peer.session_id, - evicted_peer.address, + evicted_peer.session_id, evicted_peer.address, ); if let Err(err) = context.disconnect(evicted_peer.session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", evicted_peer.session_id, err); + debug!( + "Disconnect failed {:?}, error: {:?}", + evicted_peer.session_id, err + ); } } Ok(None) => debug!( - target: "network", "{} open, registry {} success", - session_context.id, - session_context.address, + session_context.id, session_context.address, ), Err(err) => { debug!( - target: "network", "registry peer failed {:?} disconnect it, {} => {}", - err, - session_context.id, - session_context.address, + err, session_context.id, session_context.address, ); if let Err(err) = context.disconnect(session_context.id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", session_context.id, err); + debug!( + "Disconnect failed {:?}, error: {:?}", + session_context.id, err + ); } } } @@ -578,10 +574,8 @@ impl ServiceHandle for EventHandler { } ServiceEvent::SessionClose { session_context } => { debug!( - target: "network", "SessionClose({}, {})", - session_context.id, - session_context.address, + session_context.id, session_context.address, ); let peer_id = session_context .remote_pubkey @@ -604,10 +598,8 @@ impl ServiceHandle for EventHandler { .is_some(); if peer_exists { debug!( - target: "network", "{} closed, remove {} from peer_registry", - session_context.id, - session_context.address, + session_context.id, session_context.address, ); self.network_state.with_peer_store_mut(|peer_store| { peer_store.update_status(&peer_id, Status::Disconnected); @@ -615,7 +607,7 @@ impl ServiceHandle for EventHandler { } } _ => { - info!(target: "network", "p2p service event: {:?}", event); + info!("p2p service event: {:?}", event); } } } @@ -646,10 +638,8 @@ impl ServiceHandle for EventHandler { .with_peer_registry(|reg| reg.is_feeler(&peer_id)) { warn!( - target: "network", "Invalid session {}, protocol id {}", - session_context.id, - proto_id, + session_context.id, proto_id, ); } } @@ -676,7 +666,6 @@ impl ServiceHandle for EventHandler { .contains(&session_id) { debug!( - target: "network", "disconnect peer({}) already removed from registry", session_context.id ); @@ -685,7 +674,7 @@ impl ServiceHandle for EventHandler { .write() .insert(session_id); if let Err(err) = context.disconnect(session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", session_id, err); + debug!("Disconnect failed {:?}, error: {:?}", session_id, err); } } } @@ -820,7 +809,6 @@ impl NetworkService { match self.p2p_service.listen(addr.to_owned()) { Ok(listen_address) => { info!( - target: "network", "Listen on address: {}", self.network_state.to_external_url(&listen_address) ); @@ -831,7 +819,6 @@ impl NetworkService { } Err(err) => { warn!( - target: "network", "listen on address {} failed, due to error: {}", addr.clone(), err @@ -843,7 +830,7 @@ impl NetworkService { // dial reserved_nodes for (peer_id, addr) in config.reserved_peers()? { - debug!(target: "network", "dial reserved_peers {:?} {:?}", peer_id, addr); + debug!("dial reserved_peers {:?} {:?}", peer_id, addr); self.network_state .dial_all(self.p2p_service.control(), &peer_id, addr); } @@ -853,7 +840,7 @@ impl NetworkService { }); // dial half bootnodes for (peer_id, addr) in bootnodes { - debug!(target: "network", "dial bootnode {:?} {:?}", peer_id, addr); + debug!("dial bootnode {:?} {:?}", peer_id, addr); self.network_state .dial_all(self.p2p_service.control(), &peer_id, addr); } @@ -893,25 +880,25 @@ impl NetworkService { }) .collect::>(); - debug!(target: "network", "receiving shutdown signal ..."); + debug!("receiving shutdown signal ..."); // Recevied stop signal, doing cleanup let _ = receiver.recv(); for peer in self.network_state.peer_registry.read().peers().values() { - info!(target: "network", "Disconnect peer {}", peer.address); + info!("Disconnect peer {}", peer.address); if let Err(err) = inner_p2p_control.disconnect(peer.session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", peer.session_id, err); + debug!("Disconnect failed {:?}, error: {:?}", peer.session_id, err); } } // Drop senders to stop all corresponding background task drop(bg_signals); if let Err(err) = inner_p2p_control.shutdown() { - warn!(target: "network", "send shutdown message to p2p error: {:?}", err); + warn!("send shutdown message to p2p error: {:?}", err); } - debug!(target: "network", "Waiting tokio runtime to finish ..."); + debug!("Waiting tokio runtime to finish ..."); runtime.shutdown_on_idle().wait().unwrap(); - debug!(target: "network", "Shutdown network service finished!"); + debug!("Shutdown network service finished!"); }) .expect("Start NetworkService failed"); let stop = StopHandler::new(SignalSender::Crossbeam(sender), thread); @@ -955,10 +942,10 @@ impl NetworkController { if let Some(session_id) = reg.get_key_by_peer_id(peer_id) { reg.remove_peer(session_id); if let Err(err) = self.p2p_control.disconnect(session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", session_id, err); + debug!("Disconnect failed {:?}, error: {:?}", session_id, err); } } else { - error!(target: "network", "Cannot find peer {:?}", peer_id); + error!("Cannot find peer {:?}", peer_id); } }) } @@ -1011,13 +998,13 @@ impl NetworkController { } Err(P2pError::IoError(ref err)) if err.kind() == io::ErrorKind::WouldBlock => { if now.elapsed() > P2P_SEND_TIMEOUT { - warn!(target: "network", "broadcast message to {} timeout", proto_id); + warn!("broadcast message to {} timeout", proto_id); return Err(P2pError::IoError(io::ErrorKind::TimedOut.into())); } thread::sleep(P2P_TRY_SEND_INTERVAL); } Err(err) => { - warn!(target: "network", "broadcast message to {} failed: {:?}", proto_id, err); + warn!("broadcast message to {} failed: {:?}", proto_id, err); return Err(err); } } diff --git a/network/src/peer_registry.rs b/network/src/peer_registry.rs index 4cdb99c9d7..97c08767fb 100644 --- a/network/src/peer_registry.rs +++ b/network/src/peer_registry.rs @@ -1,7 +1,7 @@ use crate::peer_store::PeerStore; use crate::{errors::PeerError, Peer, PeerId, SessionType}; +use ckb_logger::debug; use fnv::{FnvHashMap, FnvHashSet}; -use log::debug; use p2p::{multiaddr::Multiaddr, SessionId}; use rand::seq::SliceRandom; use rand::thread_rng; @@ -175,7 +175,7 @@ impl PeerRegistry { // randomly evict a peer let mut rng = thread_rng(); evict_group.choose(&mut rng).map(|peer| { - debug!(target: "network", "evict inbound peer {:?}", peer.peer_id); + debug!("evict inbound peer {:?}", peer.peer_id); peer.session_id }) } diff --git a/network/src/protocols/discovery.rs b/network/src/protocols/discovery.rs index 3aa673f22a..e42a06c4c2 100644 --- a/network/src/protocols/discovery.rs +++ b/network/src/protocols/discovery.rs @@ -1,9 +1,9 @@ // use crate::peer_store::Behaviour; use crate::peer_store::types::PeerAddr; use crate::NetworkState; +use ckb_logger::{debug, error, trace, warn}; use fnv::FnvHashMap; use futures::{sync::mpsc, sync::oneshot, Async, Future, Stream}; -use log::{debug, error, trace, warn}; use std::{sync::Arc, time::Duration}; use p2p::{ @@ -43,33 +43,32 @@ impl DiscoveryProtocol { impl ServiceProtocol for DiscoveryProtocol { fn init(&mut self, context: &mut ProtocolContext) { - debug!(target: "network", "protocol [discovery({})]: init", context.proto_id); + debug!("protocol [discovery({})]: init", context.proto_id); let discovery_task = self .discovery .take() .map(|discovery| { - debug!(target: "network", "Start discovery future_task"); + debug!("Start discovery future_task"); discovery .for_each(|()| Ok(())) .map_err(|err| { - warn!(target: "network", "discovery stream error: {:?}", err); + warn!("discovery stream error: {:?}", err); }) .then(|_| { - debug!(target: "network", "End of discovery"); + debug!("End of discovery"); Ok(()) }) }) .expect("Discovery init only once"); if let Err(err) = context.future_task(discovery_task) { - error!(target: "network", "Start discovery_task failed: {:?}", err); + error!("Start discovery_task failed: {:?}", err); } } fn connected(&mut self, context: ProtocolContextMutRef, _: &str) { let session = context.session; debug!( - target: "network", "protocol [discovery] open on session [{}], address: [{}], type: [{:?}]", session.id, session.address, session.ty ); @@ -78,7 +77,7 @@ impl ServiceProtocol for DiscoveryProtocol { peer_id: session.remote_pubkey.clone().map(|pubkey| pubkey.peer_id()), }; if self.event_sender.unbounded_send(event).is_err() { - debug!(target: "network", "receiver maybe dropped! (ServiceProtocol::connected)"); + debug!("receiver maybe dropped! (ServiceProtocol::connected)"); return; } @@ -87,11 +86,11 @@ impl ServiceProtocol for DiscoveryProtocol { let substream = Substream::new(context, receiver); match self.discovery_handle.substream_sender.try_send(substream) { Ok(_) => { - debug!(target: "network", "Send substream success"); + debug!("Send substream success"); } Err(err) => { // TODO: handle channel is full (wait for poll API?) - warn!(target: "network", "Send substream failed : {:?}", err); + warn!("Send substream failed : {:?}", err); } } } @@ -100,26 +99,26 @@ impl ServiceProtocol for DiscoveryProtocol { let session = context.session; let event = DiscoveryEvent::Disconnected(session.id); if self.event_sender.unbounded_send(event).is_err() { - debug!(target: "network", "receiver maybe dropped! (ServiceProtocol::disconnected)"); + debug!("receiver maybe dropped! (ServiceProtocol::disconnected)"); return; } self.discovery_senders.remove(&session.id); - debug!(target: "network", "protocol [discovery] close on session [{}]", session.id); + debug!("protocol [discovery] close on session [{}]", session.id); } fn received(&mut self, context: ProtocolContextMutRef, data: bytes::Bytes) { let session = context.session; - trace!(target: "network", "[received message]: length={}", data.len()); + trace!("[received message]: length={}", data.len()); if let Some(ref mut sender) = self.discovery_senders.get_mut(&session.id) { // TODO: handle channel is full (wait for poll API?) if let Err(err) = sender.try_send(data.to_vec()) { if err.is_full() { - warn!(target: "network", "channel is full"); + warn!("channel is full"); } else if err.is_disconnected() { - warn!(target: "network", "channel is disconnected"); + warn!("channel is disconnected"); } else { - warn!(target: "network", "other channel error: {:?}", err); + warn!("other channel error: {:?}", err); } self.discovery_senders.remove(&session.id); } @@ -197,7 +196,7 @@ impl DiscoveryService { if let Some(_peer_id) = self.sessions.get(&session_id) { // TODO: wait for peer store update for addr in addrs.into_iter().filter(|addr| self.is_valid_addr(addr)) { - trace!(target: "network", "Add discovered address:{:?}", addr); + trace!("Add discovered address:{:?}", addr); if let Some(peer_id) = extract_peer_id(&addr) { self.network_state.with_peer_store_mut(|peer_store| { peer_store.add_discovered_addr(&peer_id, addr); @@ -234,7 +233,7 @@ impl DiscoveryService { }) }) .collect(); - trace!(target: "network", "discovery send random addrs: {:?}", addrs); + trace!("discovery send random addrs: {:?}", addrs); result .send(addrs) .expect("Send failed (should not happened)"); @@ -253,7 +252,7 @@ impl Future for DiscoveryService { self.handle_event(event); } Async::Ready(None) => { - debug!(target: "network", "discovery service shutdown"); + debug!("discovery service shutdown"); return Ok(Async::Ready(())); } Async::NotReady => break, @@ -273,7 +272,7 @@ impl AddressManager for DiscoveryAddressManager { fn add_new_addrs(&mut self, session_id: SessionId, addrs: Vec) { let event = DiscoveryEvent::AddNewAddrs { session_id, addrs }; if self.event_sender.unbounded_send(event).is_err() { - debug!(target: "network", "receiver maybe dropped! (DiscoveryAddressManager::add_new_addrs)"); + debug!("receiver maybe dropped! (DiscoveryAddressManager::add_new_addrs)"); } } @@ -285,7 +284,7 @@ impl AddressManager for DiscoveryAddressManager { result: sender, }; if self.event_sender.unbounded_send(event).is_err() { - debug!(target: "network", "receiver maybe dropped! (DiscoveryAddressManager::misbehave)"); + debug!("receiver maybe dropped! (DiscoveryAddressManager::misbehave)"); MisbehaveResult::Disconnect } else { receiver.wait().unwrap_or(MisbehaveResult::Disconnect) @@ -296,7 +295,7 @@ impl AddressManager for DiscoveryAddressManager { let (sender, receiver) = oneshot::channel(); let event = DiscoveryEvent::GetRandom { n, result: sender }; if self.event_sender.unbounded_send(event).is_err() { - debug!(target: "network", "receiver maybe dropped! (DiscoveryAddressManager::get_random)"); + debug!("receiver maybe dropped! (DiscoveryAddressManager::get_random)"); Vec::new() } else { receiver.wait().ok().unwrap_or_else(Vec::new) diff --git a/network/src/protocols/feeler.rs b/network/src/protocols/feeler.rs index dd9974211e..294a4e8323 100644 --- a/network/src/protocols/feeler.rs +++ b/network/src/protocols/feeler.rs @@ -1,5 +1,5 @@ use crate::NetworkState; -use log::{debug, info}; +use ckb_logger::{debug, info}; use p2p::{ context::{ProtocolContext, ProtocolContextMutRef}, secio::PublicKey, @@ -35,9 +35,9 @@ impl ServiceProtocol for Feeler { self.network_state.with_peer_store_mut(|peer_store| { peer_store.add_connected_peer(&peer_id, session.address.clone(), session.ty); }); - info!(target: "network", "peer={} FeelerProtocol.connected", session.address); + info!("peer={} FeelerProtocol.connected", session.address); if let Err(err) = context.disconnect(session.id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", session.id, err); + debug!("Disconnect failed {:?}, error: {:?}", session.id, err); } } @@ -51,6 +51,6 @@ impl ServiceProtocol for Feeler { self.network_state.with_peer_registry_mut(|reg| { reg.remove_feeler(&peer_id); }); - info!(target: "network", "peer={} FeelerProtocol.disconnected", session.address); + info!("peer={} FeelerProtocol.disconnected", session.address); } } diff --git a/network/src/protocols/identify.rs b/network/src/protocols/identify.rs index 67e8816cb8..fc4a46ec65 100644 --- a/network/src/protocols/identify.rs +++ b/network/src/protocols/identify.rs @@ -1,6 +1,6 @@ // use crate::peer_store::Behaviour; use crate::NetworkState; -use log::{debug, trace}; +use ckb_logger::{debug, trace}; use p2p::{ multiaddr::{Multiaddr, Protocol}, secio::PeerId, @@ -49,7 +49,6 @@ impl Callback for IdentifyCallback { fn add_remote_listen_addrs(&mut self, peer_id: &PeerId, addrs: Vec) { trace!( - target: "network", "got remote listen addrs from peer_id={:?}, addrs={:?}", peer_id, addrs, @@ -70,11 +69,8 @@ impl Callback for IdentifyCallback { ty: SessionType, ) -> MisbehaveResult { debug!( - target: "network", "peer({:?}, {:?}) reported observed addr {}", - peer_id, - ty, - addr, + peer_id, ty, addr, ); if ty.is_inbound() { @@ -99,7 +95,7 @@ impl Callback for IdentifyCallback { .collect::() }) { - debug!(target: "network", "identify add transformed addr: {:?}", transformed_addr); + debug!("identify add transformed addr: {:?}", transformed_addr); let local_peer_id = self.network_state.local_peer_id(); self.network_state.with_peer_store_mut(|peer_store| { peer_store.add_discovered_addr(local_peer_id, transformed_addr); diff --git a/network/src/protocols/mod.rs b/network/src/protocols/mod.rs index 9ecc230750..e12621fa35 100644 --- a/network/src/protocols/mod.rs +++ b/network/src/protocols/mod.rs @@ -3,8 +3,8 @@ pub(crate) mod feeler; pub(crate) mod identify; pub(crate) mod ping; +use ckb_logger::{debug, error, trace}; use futures::Future; -use log::{debug, error, trace}; use p2p::{ builder::MetaBuilder, bytes::Bytes, @@ -185,7 +185,12 @@ impl ServiceProtocol for CKBHandler { } fn received(&mut self, context: ProtocolContextMutRef, data: bytes::Bytes) { - trace!(target: "network", "[received message]: {}, {}, length={}", self.proto_id, context.session.id, data.len()); + trace!( + "[received message]: {}, {}, length={}", + self.proto_id, + context.session.id, + data.len() + ); let nc = DefaultCKBProtocolContext { proto_id: self.proto_id, network_state: Arc::clone(&self.network_state), @@ -197,7 +202,7 @@ impl ServiceProtocol for CKBHandler { fn notify(&mut self, context: &mut ProtocolContext, token: u64) { if token == std::u64::MAX { - trace!(target: "network", "protocol handler heart beat {}", self.proto_id); + trace!("protocol handler heart beat {}", self.proto_id); } else { let nc = DefaultCKBProtocolContext { proto_id: self.proto_id, @@ -230,25 +235,35 @@ impl CKBProtocolContext for DefaultCKBProtocolContext { .p2p_control .set_service_notify(self.proto_id, interval, token) { - debug!(target: "network", "p2p service set_notify error: {:?}", err); + debug!("p2p service set_notify error: {:?}", err); } } fn quick_send_message(&self, proto_id: ProtocolId, peer_index: PeerIndex, data: Bytes) { - trace!(target: "network", "[send message]: {}, to={}, length={}", proto_id, peer_index, data.len()); + trace!( + "[send message]: {}, to={}, length={}", + proto_id, + peer_index, + data.len() + ); if let Err(err) = self .p2p_control .quick_send_message_to(peer_index, proto_id, data) { - debug!(target: "network", "p2p service quick_send_message error: {:?}", err); + debug!("p2p service quick_send_message error: {:?}", err); } } fn quick_send_message_to(&self, peer_index: PeerIndex, data: Bytes) { - trace!(target: "network", "[send message to]: {}, to={}, length={}", self.proto_id, peer_index, data.len()); + trace!( + "[send message to]: {}, to={}, length={}", + self.proto_id, + peer_index, + data.len() + ); if let Err(err) = self .p2p_control .quick_send_message_to(peer_index, self.proto_id, data) { - debug!(target: "network", "p2p service quick_send_message_to error: {:?}", err); + debug!("p2p service quick_send_message_to error: {:?}", err); } } fn quick_filter_broadcast(&self, target: TargetSession, data: Bytes) { @@ -256,27 +271,37 @@ impl CKBProtocolContext for DefaultCKBProtocolContext { .p2p_control .quick_filter_broadcast(target, self.proto_id, data) { - debug!(target: "network", "p2p service quick_filter_broadcast error: {:?}", err); + debug!("p2p service quick_filter_broadcast error: {:?}", err); } } fn future_task(&self, task: Box + 'static + Send>) { if let Err(err) = self.p2p_control.future_task(task) { - error!(target: "network", "failed to spawn future task: {:?}", err); + error!("failed to spawn future task: {:?}", err); } } fn send_message(&self, proto_id: ProtocolId, peer_index: PeerIndex, data: Bytes) { - trace!(target: "network", "[send message]: {}, to={}, length={}", proto_id, peer_index, data.len()); + trace!( + "[send message]: {}, to={}, length={}", + proto_id, + peer_index, + data.len() + ); if let Err(err) = self.p2p_control.send_message_to(peer_index, proto_id, data) { - debug!(target: "network", "p2p service send_message error: {:?}", err); + debug!("p2p service send_message error: {:?}", err); } } fn send_message_to(&self, peer_index: PeerIndex, data: Bytes) { - trace!(target: "network", "[send message to]: {}, to={}, length={}", self.proto_id, peer_index, data.len()); + trace!( + "[send message to]: {}, to={}, length={}", + self.proto_id, + peer_index, + data.len() + ); if let Err(err) = self .p2p_control .send_message_to(peer_index, self.proto_id, data) { - debug!(target: "network", "p2p service send_message_to error: {:?}", err); + debug!("p2p service send_message_to error: {:?}", err); } } fn filter_broadcast(&self, target: TargetSession, data: Bytes) { @@ -284,12 +309,12 @@ impl CKBProtocolContext for DefaultCKBProtocolContext { .p2p_control .filter_broadcast(target, self.proto_id, data) { - debug!(target: "network", "p2p service filter_broadcast error: {:?}", err); + debug!("p2p service filter_broadcast error: {:?}", err); } } fn disconnect(&self, peer_index: PeerIndex) { if let Err(err) = self.p2p_control.disconnect(peer_index) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", peer_index, err); + debug!("Disconnect failed {:?}, error: {:?}", peer_index, err); } } diff --git a/network/src/protocols/ping.rs b/network/src/protocols/ping.rs index 7339449824..133c51636d 100644 --- a/network/src/protocols/ping.rs +++ b/network/src/protocols/ping.rs @@ -1,6 +1,6 @@ use crate::NetworkState; +use ckb_logger::{debug, trace}; use futures::{sync::mpsc::Receiver, try_ready, Async, Stream}; -use log::{debug, trace}; use p2p::service::ServiceControl; use p2p_ping::Event; use std::sync::Arc; @@ -34,10 +34,10 @@ impl Stream for PingService { match try_ready!(self.event_receiver.poll()) { Some(Ping(peer_id)) => { - trace!(target: "network", "send ping to {:?}", peer_id); + trace!("send ping to {:?}", peer_id); } Some(Pong(peer_id, duration)) => { - trace!(target: "network", "receive pong from {:?} duration {:?}", peer_id, duration); + trace!("receive pong from {:?} duration {:?}", peer_id, duration); if let Some(session_id) = self.network_state.query_session_id(&peer_id) { self.network_state.with_peer_registry_mut(|reg| { if let Some(mut peer) = reg.get_peer_mut(session_id) { @@ -48,29 +48,29 @@ impl Stream for PingService { } } Some(Timeout(peer_id)) => { - debug!(target: "network", "timeout to ping {:?}", peer_id); + debug!("timeout to ping {:?}", peer_id); if let Some(session_id) = self.network_state.with_peer_registry_mut(|reg| { reg.remove_peer_by_peer_id(&peer_id) .map(|peer| peer.session_id) }) { if let Err(err) = self.p2p_control.disconnect(session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", session_id, err); + debug!("Disconnect failed {:?}, error: {:?}", session_id, err); } } } Some(UnexpectedError(peer_id)) => { - debug!(target: "network", "failed to ping {:?}", peer_id); + debug!("failed to ping {:?}", peer_id); if let Some(session_id) = self.network_state.with_peer_registry_mut(|reg| { reg.remove_peer_by_peer_id(&peer_id) .map(|peer| peer.session_id) }) { if let Err(err) = self.p2p_control.disconnect(session_id) { - debug!(target: "network", "Disconnect failed {:?}, error: {:?}", session_id, err); + debug!("Disconnect failed {:?}, error: {:?}", session_id, err); } } } None => { - debug!(target: "network", "ping service shutdown"); + debug!("ping service shutdown"); return Ok(Async::Ready(None)); } } diff --git a/network/src/services/dns_seeding/mod.rs b/network/src/services/dns_seeding/mod.rs index e69f7c8bc8..e1f675bf74 100644 --- a/network/src/services/dns_seeding/mod.rs +++ b/network/src/services/dns_seeding/mod.rs @@ -2,9 +2,9 @@ use std::error::Error; use std::sync::Arc; use std::time::{Duration, Instant}; +use ckb_logger::{debug, error, info, trace, warn}; use faster_hex::hex_decode; use futures::{Async, Future, Poll, Stream}; -use log::{debug, error, info, trace, warn}; use p2p::{multiaddr::Protocol, secio::PeerId}; use resolve::record::Txt; use resolve::{DnsConfig, DnsResolver}; @@ -31,7 +31,7 @@ impl DnsSeedingService { pub(crate) fn new(network_state: Arc, seeds: Vec) -> DnsSeedingService { let wait_until = if network_state.with_peer_store(|peer_store| peer_store.random_peers(1).is_empty()) { - info!(target: "network", "No peer in peer store, start seeding..."); + info!("No peer in peer store, start seeding..."); Instant::now() } else { Instant::now() + Duration::from_secs(11) @@ -59,7 +59,7 @@ impl DnsSeedingService { >= 2 }); if enough_outbound { - debug!(target: "network", "Enough outbound peers"); + debug!("Enough outbound peers"); return Ok(()); } @@ -78,7 +78,7 @@ impl DnsSeedingService { let mut addrs = Vec::new(); for seed in &self.seeds { - debug!(target: "network", "query txt records from: {}", seed); + debug!("query txt records from: {}", seed); match resolver.resolve_record::(seed) { Ok(records) => { for record in records { @@ -86,26 +86,26 @@ impl DnsSeedingService { Ok(record) => match SeedRecord::decode_with_pubkey(&record, &pubkey) { Ok(seed_record) => { let address = seed_record.address(); - trace!(target: "network", "got dns txt address: {}", address); + trace!("got dns txt address: {}", address); addrs.push(address); } Err(err) => { - debug!(target: "network", "decode dns txt record failed: {:?}, {:?}", err, record); + debug!("decode dns txt record failed: {:?}, {:?}", err, record); } }, Err(err) => { - debug!(target: "network", "get dns txt record error: {:?}", err); + debug!("get dns txt record error: {:?}", err); } } } } Err(_) => { - warn!(target: "network", "Invalid domain name: {}", seed); + warn!("Invalid domain name: {}", seed); } } } - debug!(target: "network", "DNS seeding got {} address", addrs.len()); + debug!("DNS seeding got {} address", addrs.len()); self.network_state.with_peer_store_mut(|peer_store| { for mut addr in addrs { match addr.pop() { @@ -115,7 +115,7 @@ impl DnsSeedingService { } } _ => { - debug!(target: "network", "Got addr without peer_id: {}, ignore it", addr); + debug!("Got addr without peer_id: {}, ignore it", addr); } } } @@ -134,21 +134,21 @@ impl Future for DnsSeedingService { Ok(Async::Ready(Some(_))) => { if self.wait_until < Instant::now() { if let Err(err) = self.seeding() { - error!(target: "network", "seeding error: {:?}", err); + error!("seeding error: {:?}", err); } - debug!(target: "network", "DNS seeding finished"); + debug!("DNS seeding finished"); return Ok(Async::Ready(())); } else { - trace!(target: "network", "DNS check interval"); + trace!("DNS check interval"); } } Ok(Async::Ready(None)) => { - warn!(target: "network", "Poll DnsSeedingService interval return None"); + warn!("Poll DnsSeedingService interval return None"); return Err(()); } Ok(Async::NotReady) => break, Err(err) => { - warn!(target: "network", "Poll DnsSeedingService interval error: {:?}", err); + warn!("Poll DnsSeedingService interval error: {:?}", err); return Err(()); } } diff --git a/network/src/services/outbound_peer.rs b/network/src/services/outbound_peer.rs index 7afd396066..0f801be28c 100644 --- a/network/src/services/outbound_peer.rs +++ b/network/src/services/outbound_peer.rs @@ -1,8 +1,8 @@ use crate::peer_store::types::PeerAddr; use crate::NetworkState; +use ckb_logger::{debug, trace, warn}; use faketime::unix_time_as_millis; use futures::{Async, Future, Stream}; -use log::{debug, trace, warn}; use p2p::service::ServiceControl; use std::sync::Arc; use std::time::{Duration, Instant}; @@ -53,10 +53,15 @@ impl OutboundPeerService { paddrs }); let p2p_control = self.p2p_control.clone(); - trace!(target: "network", "count={}, attempt_peers: {:?} is_feeler: {}", count, attempt_peers, is_feeler); + trace!( + "count={}, attempt_peers: {:?} is_feeler: {}", + count, + attempt_peers, + is_feeler + ); for paddr in attempt_peers { let PeerAddr { peer_id, addr, .. } = paddr; - debug!(target: "network", "dial attempt peer: {:?}, is_feeler: {}", addr, is_feeler); + debug!("dial attempt peer: {:?}, is_feeler: {}", addr, is_feeler); if is_feeler { self.network_state.with_peer_registry_mut(|reg| { reg.add_feeler(peer_id.clone()); @@ -95,14 +100,14 @@ impl Future for OutboundPeerService { } } Ok(Async::Ready(None)) => { - warn!(target: "network", "ckb outbound peer service stopped"); + warn!("ckb outbound peer service stopped"); return Ok(Async::Ready(())); } Ok(Async::NotReady) => { return Ok(Async::NotReady); } Err(err) => { - warn!(target: "network", "outbound peer service stopped because: {:?}", err); + warn!("outbound peer service stopped because: {:?}", err); return Err(()); } } From ade371a214993f207cfd3cd1ad8f326741919326 Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 12:08:55 +0800 Subject: [PATCH 5/9] chore: apply new log macros to rpc & notify --- Cargo.lock | 4 ++-- notify/Cargo.toml | 2 +- notify/src/lib.rs | 34 +++++++++++++++++----------------- rpc/Cargo.toml | 2 +- rpc/src/module/experiment.rs | 4 ++-- rpc/src/module/miner.rs | 22 +++++++++++++++------- rpc/src/module/pool.rs | 3 ++- rpc/src/module/test.rs | 4 ++-- 8 files changed, 42 insertions(+), 33 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 878741401a..b62296caaa 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -601,9 +601,9 @@ name = "ckb-notify" version = "0.14.0-pre" dependencies = [ "ckb-core 0.14.0-pre", + "ckb-logger 0.14.0-pre", "crossbeam-channel 0.3.8 (registry+https://github.com/rust-lang/crates.io-index)", "fnv 1.0.6 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "stop-handler 0.14.0-pre", ] @@ -659,6 +659,7 @@ dependencies = [ "ckb-chain-spec 0.14.0-pre", "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-miner 0.14.0-pre", "ckb-network 0.14.0-pre", "ckb-notify 0.14.0-pre", @@ -682,7 +683,6 @@ dependencies = [ "jsonrpc-http-server 10.0.1 (git+https://github.com/nervosnetwork/jsonrpc?rev=7c101f83a8fe34369c1b7a0e9b6721fcb0f91ee0)", "jsonrpc-server-utils 10.1.0 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-types 0.14.0-pre", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "num_cpus 1.10.0 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-uint 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", diff --git a/notify/Cargo.toml b/notify/Cargo.toml index c401fbe78a..b000a01a92 100644 --- a/notify/Cargo.toml +++ b/notify/Cargo.toml @@ -9,5 +9,5 @@ edition = "2018" fnv = "1.0" ckb-core = { path = "../core" } crossbeam-channel = "0.3" -log = "0.4" stop-handler = { path = "../util/stop-handler" } +ckb-logger = { path = "../util/logger" } diff --git a/notify/src/lib.rs b/notify/src/lib.rs index b6ed4ec86f..8d6a50e9b5 100644 --- a/notify/src/lib.rs +++ b/notify/src/lib.rs @@ -2,9 +2,9 @@ use ckb_core::block::Block; use ckb_core::service::Request; +use ckb_logger::{debug, trace, warn}; use crossbeam_channel::{select, Receiver, Sender}; use fnv::FnvHashMap; -use log::{debug, trace, warn}; use std::sync::Arc; use std::thread; use stop_handler::{SignalSender, StopHandler}; @@ -134,12 +134,12 @@ impl NotifyService { // responder, // arguments: (name, capacity), // }) => { - // debug!(target: "notify", "Register new_transaction {:?}", name); + // debug!("Register new_transaction {:?}", name); // let (sender, receiver) = crossbeam_channel::bounded::(capacity); // subscribers.insert(name, sender); // let _ = responder.send(receiver); // } - // _ => warn!(target: "notify", "Register new_transaction channel is closed"), + // _ => warn!("Register new_transaction channel is closed"), // } // } @@ -152,12 +152,12 @@ impl NotifyService { // responder, // arguments: (name, capacity), // }) => { - // debug!(target: "notify", "Register new_tip {:?}", name); + // debug!("Register new_tip {:?}", name); // let (sender, receiver) = crossbeam_channel::bounded::(capacity); // subscribers.insert(name, sender); // let _ = responder.send(receiver); // } - // _ => warn!(target: "notify", "Register new_tip channel is closed"), + // _ => warn!("Register new_tip channel is closed"), // } // } @@ -170,12 +170,12 @@ impl NotifyService { responder, arguments: (name, capacity), }) => { - debug!(target: "notify", "Register new_uncle {:?}", name); + debug!("Register new_uncle {:?}", name); let (sender, receiver) = crossbeam_channel::bounded::(capacity); subscribers.insert(name, sender); let _ = responder.send(receiver); } - _ => warn!(target: "notify", "Register new_uncle channel is closed"), + _ => warn!("Register new_uncle channel is closed"), } } @@ -191,12 +191,12 @@ impl NotifyService { // responder, // arguments: (name, capacity), // }) => { - // debug!(target: "notify", "Register switch_fork {:?}", name); + // debug!("Register switch_fork {:?}", name); // let (sender, receiver) = crossbeam_channel::bounded::(capacity); // subscribers.insert(name, sender); // let _ = responder.send(receiver); // } - // _ => warn!(target: "notify", "Register switch_fork channel is closed"), + // _ => warn!("Register switch_fork channel is closed"), // } // } @@ -206,12 +206,12 @@ impl NotifyService { // ) { // match msg { // Ok(()) => { - // trace!(target: "notify", "event new transaction {:?}", msg); + // trace!("event new transaction {:?}", msg); // for subscriber in subscribers.values() { // let _ = subscriber.send(()); // } // } - // _ => warn!(target: "notify", "new transaction channel is closed"), + // _ => warn!("new transaction channel is closed"), // } // } @@ -221,12 +221,12 @@ impl NotifyService { // ) { // match msg { // Ok(msg) => { - // trace!(target: "notify", "event new tip {:?}", msg); + // trace!("event new tip {:?}", msg); // for subscriber in subscribers.values() { // let _ = subscriber.send(Arc::clone(&msg)); // } // } - // _ => warn!(target: "notify", "new tip channel is closed"), + // _ => warn!("new tip channel is closed"), // } // } @@ -236,12 +236,12 @@ impl NotifyService { ) { match msg { Ok(msg) => { - trace!(target: "notify", "event new uncle {:?}", msg); + trace!("event new uncle {:?}", msg); for subscriber in subscribers.values() { let _ = subscriber.send(Arc::clone(&msg)); } } - _ => warn!(target: "notify", "new uncle channel is closed"), + _ => warn!("new uncle channel is closed"), } } @@ -251,12 +251,12 @@ impl NotifyService { // ) { // match msg { // Ok(msg) => { - // trace!(target: "notify", "event switch fork {:?}", msg); + // trace!("event switch fork {:?}", msg); // for subscriber in subscribers.values() { // let _ = subscriber.send(Arc::clone(&msg)); // } // } - // _ => warn!(target: "notify", "event 3 channel is closed"), + // _ => warn!("event 3 channel is closed"), // } // } } diff --git a/rpc/Cargo.toml b/rpc/Cargo.toml index e6c9b814c9..5be4679291 100644 --- a/rpc/Cargo.toml +++ b/rpc/Cargo.toml @@ -19,6 +19,7 @@ ckb-chain = { path = "../chain" } ckb-miner = { path = "../miner" } ckb-protocol = { path = "../protocol" } ckb-pow = { path = "../pow"} +ckb-logger = { path = "../util/logger"} jsonrpc-core = "10.1" jsonrpc-derive = "10.1" jsonrpc-http-server = { git = "https://github.com/nervosnetwork/jsonrpc", rev = "7c101f83a8fe34369c1b7a0e9b6721fcb0f91ee0" } @@ -26,7 +27,6 @@ jsonrpc-server-utils = "10.1" serde = "1.0" serde_derive = "1.0" serde_json = "1.0" -log = "0.4" flatbuffers = "0.6.0" num_cpus = "1.10" faster-hex = "0.3" diff --git a/rpc/src/module/experiment.rs b/rpc/src/module/experiment.rs index ba1c4fe386..b0dbf339cd 100644 --- a/rpc/src/module/experiment.rs +++ b/rpc/src/module/experiment.rs @@ -4,6 +4,7 @@ use ckb_core::script::Script as CoreScript; use ckb_core::transaction::{ CellOutput as CoreCellOutput, OutPoint as CoreOutPoint, Transaction as CoreTransaction, }; +use ckb_logger::error; use ckb_shared::chain_state::ChainState; use ckb_shared::shared::Shared; use ckb_store::ChainStore; @@ -12,7 +13,6 @@ use dao::calculate_maximum_withdraw; use jsonrpc_core::{Error, Result}; use jsonrpc_derive::rpc; use jsonrpc_types::{Capacity, Cycle, DryRunResult, JsonBytes, OutPoint, Script, Transaction}; -use log::error; use numext_fixed_hash::H256; use serde_derive::Serialize; @@ -69,7 +69,7 @@ impl ExperimentRpc for ExperimentRpcImpl { match DaoWithdrawCalculator::new(&chain_state).calculate(out_point.clone().into(), hash) { Ok(capacity) => Ok(capacity), Err(err) => { - error!(target: "rpc-server", "calculate_dao_maximum_withdraw error {:?}", err); + error!("calculate_dao_maximum_withdraw error {:?}", err); Err(Error::internal_error()) } } diff --git a/rpc/src/module/miner.rs b/rpc/src/module/miner.rs index 1635f4eb3b..9fa00ddc0b 100644 --- a/rpc/src/module/miner.rs +++ b/rpc/src/module/miner.rs @@ -1,5 +1,6 @@ use ckb_chain::chain::ChainController; use ckb_core::block::Block as CoreBlock; +use ckb_logger::{debug, error}; use ckb_miner::BlockAssemblerController; use ckb_network::NetworkController; use ckb_protocol::RelayMessage; @@ -13,7 +14,6 @@ use flatbuffers::FlatBufferBuilder; use jsonrpc_core::{Error, Result}; use jsonrpc_derive::rpc; use jsonrpc_types::{Block, BlockTemplate, Unsigned, Version}; -use log::{debug, error}; use numext_fixed_hash::H256; use std::collections::HashSet; use std::sync::Arc; @@ -61,7 +61,7 @@ impl MinerRpc for MinerRpcImpl { self.block_assembler .get_block_template(bytes_limit, proposals_limit, max_version.map(|v| v.0)) .map_err(|err| { - error!(target: "rpc-server", "get_block_template error {}", err); + error!("get_block_template error {}", err); Error::internal_error() }) } @@ -73,7 +73,7 @@ impl MinerRpc for MinerRpcImpl { let _scope_guard = sentry::Hub::current().push_scope(); sentry::configure_scope(|scope| scope.set_extra("work_id", work_id.clone().into())); - debug!(target: "rpc-server", "[{}] submit block", work_id); + debug!("[{}] submit block", work_id); let block: Arc = Arc::new(data.into()); let resolver = HeaderResolverWrapper::new(block.header(), self.shared.clone()); let header_verify_ret = { @@ -87,7 +87,12 @@ impl MinerRpc for MinerRpcImpl { if header_verify_ret.is_ok() { let ret = self.chain.process_block(Arc::clone(&block), true); if ret.is_ok() { - debug!(target: "rpc-server", "[block_relay] announce new block {} {:x} {}", block.header().number(), block.header().hash(), unix_time_as_millis()); + debug!( + "[block_relay] announce new block {} {:x} {}", + block.header().number(), + block.header().hash(), + unix_time_as_millis() + ); // announce new block let fbb = &mut FlatBufferBuilder::new(); @@ -98,11 +103,11 @@ impl MinerRpc for MinerRpcImpl { .network_controller .quick_broadcast(NetworkProtocol::RELAY.into(), data) { - error!(target: "rpc-server", "Broadcast block failed: {:?}", err); + error!("Broadcast block failed: {:?}", err); } Ok(Some(block.header().hash().to_owned())) } else { - error!(target: "rpc-server", "[{}] submit_block process_block {:?}", work_id, ret); + error!("[{}] submit_block process_block {:?}", work_id, ret); sentry::capture_event(sentry::protocol::Event { message: Some(format!("submit_block process_block {:?}", ret)), level: sentry::Level::Error, @@ -111,7 +116,10 @@ impl MinerRpc for MinerRpcImpl { Ok(None) } } else { - error!(target: "rpc-server", "[{}] submit_block header verifier {:?}", work_id, header_verify_ret); + error!( + "[{}] submit_block header verifier {:?}", + work_id, header_verify_ret + ); Ok(None) } } diff --git a/rpc/src/module/pool.rs b/rpc/src/module/pool.rs index 9e2ef6097a..8600149a29 100644 --- a/rpc/src/module/pool.rs +++ b/rpc/src/module/pool.rs @@ -1,5 +1,6 @@ use crate::error::RPCError; use ckb_core::transaction::Transaction as CoreTransaction; +use ckb_logger::error; use ckb_network::NetworkController; use ckb_protocol::RelayMessage; use ckb_shared::shared::Shared; @@ -57,7 +58,7 @@ impl PoolRpc for PoolRpcImpl { .network_controller .broadcast(NetworkProtocol::RELAY.into(), data) { - log::error!(target: "rpc-server", "Broadcast transaction failed: {:?}", err); + error!("Broadcast transaction failed: {:?}", err); } Ok(tx.hash().to_owned()) } diff --git a/rpc/src/module/test.rs b/rpc/src/module/test.rs index 9429b4c50a..23d42afed3 100644 --- a/rpc/src/module/test.rs +++ b/rpc/src/module/test.rs @@ -1,12 +1,12 @@ use ckb_chain::chain::ChainController; use ckb_core::block::Block as CoreBlock; +use ckb_logger::error; use ckb_network::NetworkController; use ckb_shared::shared::Shared; use ckb_store::ChainStore; use jsonrpc_core::Result; use jsonrpc_derive::rpc; use jsonrpc_types::Block; -use log::error; use numext_fixed_hash::H256; use std::sync::Arc; @@ -51,7 +51,7 @@ impl IntegrationTestRpc for IntegrationTestRpcImpl if ret.is_ok() { Ok(Some(block.header().hash().to_owned())) } else { - error!(target: "rpc-server", "process_block_without_verify error: {:?}", ret); + error!("process_block_without_verify error: {:?}", ret); Ok(None) } } From 958b2c3886f01dafdc6ef58148f1aaebf626281c Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 13:35:19 +0800 Subject: [PATCH 6/9] chore: apply new log macros to verification & shared --- Cargo.lock | 4 +- shared/Cargo.toml | 2 +- shared/src/chain_state.rs | 57 +++++++++++++++---- shared/src/lib.rs | 3 + shared/src/tx_pool/pool.rs | 22 +++++-- shared/src/tx_proposal_table.rs | 24 ++++++-- verification/Cargo.toml | 2 +- verification/src/contextual_block_verifier.rs | 23 ++++++-- verification/src/lib.rs | 2 + verification/src/transaction_verifier.rs | 9 ++- 10 files changed, 117 insertions(+), 31 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index b62296caaa..395440c2b8 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -729,6 +729,7 @@ dependencies = [ "ckb-chain-spec 0.14.0-pre", "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-notify 0.14.0-pre", "ckb-protocol 0.14.0-pre", "ckb-script 0.14.0-pre", @@ -741,7 +742,6 @@ dependencies = [ "failure 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)", "faketime 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", "jsonrpc-types 0.14.0-pre", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "lru-cache 0.1.0 (git+https://github.com/nervosnetwork/lru-cache?rev=a35fdb8)", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-uint 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", @@ -856,6 +856,7 @@ dependencies = [ "ckb-chain-spec 0.14.0-pre", "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-notify 0.14.0-pre", "ckb-pow 0.14.0-pre", "ckb-script 0.14.0-pre", @@ -866,7 +867,6 @@ dependencies = [ "faketime 0.2.0 (registry+https://github.com/rust-lang/crates.io-index)", "fnv 1.0.6 (registry+https://github.com/rust-lang/crates.io-index)", "hash 0.14.0-pre", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "lru-cache 0.1.0 (git+https://github.com/nervosnetwork/lru-cache?rev=a35fdb8)", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-uint 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", diff --git a/shared/Cargo.toml b/shared/Cargo.toml index 989da31211..c7e95c81c6 100644 --- a/shared/Cargo.toml +++ b/shared/Cargo.toml @@ -18,7 +18,7 @@ numext-fixed-hash = { version = "0.1", features = ["support_rand", "support_heap numext-fixed-uint = { version = "0.1", features = ["support_rand", "support_heapsize", "support_serde"] } lru-cache = { git = "https://github.com/nervosnetwork/lru-cache", rev = "a35fdb8" } faketime = "0.2" -log = "0.4" +ckb-logger = { path = "../util/logger" } ckb-traits = { path = "../traits" } failure = "0.1.5" ckb-verification = { path = "../verification" } diff --git a/shared/src/chain_state.rs b/shared/src/chain_state.rs index 0382da486d..6ba7e320e7 100644 --- a/shared/src/chain_state.rs +++ b/shared/src/chain_state.rs @@ -14,6 +14,7 @@ use ckb_core::header::{BlockNumber, Header}; use ckb_core::transaction::CellOutput; use ckb_core::transaction::{OutPoint, ProposalShortId, Transaction}; use ckb_core::Cycle; +use ckb_logger::{debug_target, info_target, trace_target}; use ckb_script::ScriptConfig; use ckb_store::{ChainStore, StoreBatch}; use ckb_traits::BlockMedianTimeContext; @@ -22,7 +23,6 @@ use ckb_util::{FnvHashMap, FnvHashSet}; use ckb_verification::{ContextualTransactionVerifier, TransactionVerifier}; use dao_utils::calculate_transaction_fee; use failure::Error as FailureError; -use log::{debug, info, trace}; use lru_cache::LruCache; use numext_fixed_hash::H256; use numext_fixed_uint::U256; @@ -146,16 +146,24 @@ impl ChainState { fn init_cell_set(store: &CS) -> Result { let mut cell_set = CellSet::new(); let mut count = 0; - info!(target: "chain", "Start: loading live cells ..."); + info_target!(crate::LOG_TARGET_CHAIN, "Start: loading live cells ..."); store.traverse_cell_set(|tx_hash, tx_meta| { count += 1; cell_set.put(tx_hash, tx_meta); if count % 10_000 == 0 { - info!(target: "chain", " loading {} transactions which include live cells ...", count); + info_target!( + crate::LOG_TARGET_CHAIN, + " loading {} transactions which include live cells ...", + count + ); } Ok(()) })?; - info!(target: "chain", "Done: total {} transactions.", count); + info_target!( + crate::LOG_TARGET_CHAIN, + "Done: total {} transactions.", + count + ); Ok(cell_set) } @@ -346,8 +354,18 @@ impl ChainState { let mut tx_pool = self.tx_pool.borrow_mut(); if self.contains_proposal_id(&short_id) { // if tx is proposed, we resolve from proposed, verify again - if let Err(e) = self.proposed_tx_and_descendants(&mut tx_pool, Some(cycles), tx_size, tx) { - debug!(target: "tx_pool", "Failed to add proposed tx {:?}, reason: {:?}", short_id, e); + if let Err(e) = self.proposed_tx_and_descendants( + &mut tx_pool, + Some(cycles), + tx_size, + tx, + ) { + debug_target!( + crate::LOG_TARGET_TX_POOL, + "Failed to add proposed tx {:?}, reason: {:?}", + short_id, + e + ); return Err(e); } tx_pool.update_statics_for_add_tx(tx_size, cycles); @@ -429,7 +447,12 @@ impl ChainState { let ret = self.proposed_tx(tx_pool, entry.cycles, entry.size, entry.transaction); if ret.is_err() { tx_pool.update_statics_for_remove_tx(entry.size, entry.cycles.unwrap_or(0)); - trace!(target: "tx_pool", "proposed tx {:x} failed {:?}", tx_hash, ret); + trace_target!( + crate::LOG_TARGET_TX_POOL, + "proposed tx {:x} failed {:?}", + tx_hash, + ret + ); } } else { tx_pool.enqueue_tx(entry.cycles, entry.size, entry.transaction); @@ -465,7 +488,12 @@ impl ChainState { } Err(e) => { tx_pool.update_statics_for_remove_tx(size, cycles.unwrap_or(0)); - debug!(target: "tx_pool", "Failed to add proposed tx {:x}, reason: {:?}", tx_hash, e); + debug_target!( + crate::LOG_TARGET_TX_POOL, + "Failed to add proposed tx {:x}, reason: {:?}", + tx_hash, + e + ); Err(e) } }, @@ -607,12 +635,21 @@ impl ChainState { for (cycles, size, tx) in entries { let tx_hash = tx.hash().to_owned(); if let Err(e) = self.proposed_tx_and_descendants(&mut tx_pool, cycles, size, tx) { - debug!(target: "tx_pool", "Failed to add proposed tx {:x}, reason: {:?}", tx_hash, e); + debug_target!( + crate::LOG_TARGET_TX_POOL, + "Failed to add proposed tx {:x}, reason: {:?}", + tx_hash, + e + ); } } for (cycles, size, tx) in gaps { - debug!(target: "tx_pool", "tx proposed, add to gap {:x}", tx.hash()); + debug_target!( + crate::LOG_TARGET_TX_POOL, + "tx proposed, add to gap {:x}", + tx.hash() + ); tx_pool.add_gap(cycles, size, tx); } } diff --git a/shared/src/lib.rs b/shared/src/lib.rs index 97a9d73329..3d3e728519 100644 --- a/shared/src/lib.rs +++ b/shared/src/lib.rs @@ -16,3 +16,6 @@ mod tx_proposal_table; #[cfg(test)] mod tests; + +pub(crate) const LOG_TARGET_TX_POOL: &str = "ckb-tx-pool"; +pub(crate) const LOG_TARGET_CHAIN: &str = "ckb-chain"; diff --git a/shared/src/tx_pool/pool.rs b/shared/src/tx_pool/pool.rs index 915b1fee5b..ad6b674a12 100644 --- a/shared/src/tx_pool/pool.rs +++ b/shared/src/tx_pool/pool.rs @@ -5,8 +5,8 @@ use crate::tx_pool::pending::PendingQueue; use crate::tx_pool::proposed::ProposedPool; use ckb_core::transaction::{OutPoint, ProposalShortId, Transaction}; use ckb_core::{Capacity, Cycle}; +use ckb_logger::{error_target, trace_target}; use faketime::unix_time_as_millis; -use log::{self, trace}; use lru_cache::LruCache; #[derive(Debug, Clone)] @@ -85,11 +85,21 @@ impl TxPool { // cycles overflow is possible, currently obtaining cycles is not accurate pub fn update_statics_for_remove_tx(&mut self, tx_size: usize, cycles: Cycle) { let total_tx_size = self.total_tx_size.checked_sub(tx_size).unwrap_or_else(|| { - log::error!(target: "tx_pool", "total_tx_size {} overflow by sub {}", self.total_tx_size, tx_size); + error_target!( + crate::LOG_TARGET_TX_POOL, + "total_tx_size {} overflow by sub {}", + self.total_tx_size, + tx_size + ); 0 }); let total_tx_cycles = self.total_tx_cycles.checked_sub(cycles).unwrap_or_else(|| { - log::error!(target: "tx_pool", "total_tx_cycles {} overflow by sub {}", self.total_tx_cycles, cycles); + error_target!( + crate::LOG_TARGET_TX_POOL, + "total_tx_cycles {} overflow by sub {}", + self.total_tx_cycles, + cycles + ); 0 }); self.total_tx_size = total_tx_size; @@ -117,7 +127,7 @@ impl TxPool { tx: Transaction, unknowns: Vec, ) -> Option { - trace!(target: "tx_pool", "add_orphan {:#x}", &tx.hash()); + trace_target!(crate::LOG_TARGET_TX_POOL, "add_orphan {:#x}", &tx.hash()); self.orphan.add_tx(cycles, size, tx, unknowns.into_iter()) } @@ -128,7 +138,7 @@ impl TxPool { size: usize, tx: Transaction, ) { - trace!(target: "tx_pool", "add_proposed {:#x}", tx.hash()); + trace_target!(crate::LOG_TARGET_TX_POOL, "add_proposed {:#x}", tx.hash()); self.touch_last_txs_updated_at(); self.proposed.add_tx(cycles, fee, size, tx); } @@ -208,7 +218,7 @@ impl TxPool { ) { for tx in txs { let hash = tx.hash(); - trace!(target: "tx_pool", "committed {:#x}", hash); + trace_target!(crate::LOG_TARGET_TX_POOL, "committed {:#x}", hash); for entry in self.proposed.remove_committed_tx(tx) { self.update_statics_for_remove_tx(entry.size, entry.cycles); } diff --git a/shared/src/tx_proposal_table.rs b/shared/src/tx_proposal_table.rs index b8c8b2e9c3..9a5b31d0ae 100644 --- a/shared/src/tx_proposal_table.rs +++ b/shared/src/tx_proposal_table.rs @@ -1,8 +1,8 @@ use ckb_chain_spec::consensus::ProposalWindow; use ckb_core::header::BlockNumber; use ckb_core::transaction::ProposalShortId; +use ckb_logger::trace_target; use ckb_util::FnvHashSet; -use log::trace; use std::collections::BTreeMap; use std::ops::Bound; @@ -57,7 +57,11 @@ impl TxProposalTable { let mut left = self.table.split_off(&proposal_start); ::std::mem::swap(&mut self.table, &mut left); - trace!(target: "chain", "[proposal_finalize] table {:?}", self.table); + trace_target!( + crate::LOG_TARGET_CHAIN, + "[proposal_finalize] table {:?}", + self.table + ); let new_ids = self .table .range((Bound::Unbounded, Bound::Included(&proposal_end))) @@ -76,8 +80,20 @@ impl TxProposalTable { let removed_ids: FnvHashSet = self.set.difference(&new_ids).cloned().collect(); - trace!(target: "chain", "[proposal_finalize] number {} proposal_start {}----proposal_end {}", number , proposal_start, proposal_end); - trace!(target: "chain", "[proposal_finalize] number {} new_ids {:?}----removed_ids {:?}", number, new_ids, removed_ids); + trace_target!( + crate::LOG_TARGET_CHAIN, + "[proposal_finalize] number {} proposal_start {}----proposal_end {}", + number, + proposal_start, + proposal_end + ); + trace_target!( + crate::LOG_TARGET_CHAIN, + "[proposal_finalize] number {} new_ids {:?}----removed_ids {:?}", + number, + new_ids, + removed_ids + ); self.set = new_ids; removed_ids } diff --git a/verification/Cargo.toml b/verification/Cargo.toml index c1ef60fe35..02dcfff9da 100644 --- a/verification/Cargo.toml +++ b/verification/Cargo.toml @@ -19,9 +19,9 @@ occupied-capacity = { path = "../util/occupied-capacity" } lru-cache = { git = "https://github.com/nervosnetwork/lru-cache", rev = "a35fdb8" } ckb-traits = { path = "../traits" } serde_json = "1.0" -log = "0.4" ckb-chain-spec = { path = "../spec" } dao-utils = { path = "../util/dao/utils" } +ckb-logger = {path = "../util/logger"} [dev-dependencies] ckb-db = { path = "../db" } diff --git a/verification/src/contextual_block_verifier.rs b/verification/src/contextual_block_verifier.rs index bb9196fc76..298dca6d6a 100644 --- a/verification/src/contextual_block_verifier.rs +++ b/verification/src/contextual_block_verifier.rs @@ -9,11 +9,11 @@ use ckb_core::transaction::Transaction; use ckb_core::uncle::UncleBlock; use ckb_core::Cycle; use ckb_core::{block::Block, BlockNumber, Capacity, EpochNumber}; +use ckb_logger::error_target; use ckb_store::ChainStore; use ckb_traits::{BlockMedianTimeContext, ChainProvider}; use dao_utils::calculate_transaction_fee; use fnv::FnvHashSet; -use log::error; use lru_cache::LruCache; use numext_fixed_hash::H256; use rayon::iter::{IndexedParallelIterator, IntoParallelRefIterator, ParallelIterator}; @@ -184,10 +184,23 @@ impl<'a, CP: ChainProvider + Clone> CommitVerifier<'a, CP> { let difference: Vec<_> = committed_ids.difference(&proposal_txs_ids).collect(); if !difference.is_empty() { - error!(target: "chain", "Block {} {:x}", self.block.header().number(), self.block.header().hash()); - error!(target: "chain", "proposal_window {:?}", proposal_window); - error!(target: "chain", "committed_ids {} ", serde_json::to_string(&committed_ids).unwrap()); - error!(target: "chain", "proposal_txs_ids {} ", serde_json::to_string(&proposal_txs_ids).unwrap()); + error_target!( + crate::LOG_TARGET, + "Block {} {:x}", + self.block.header().number(), + self.block.header().hash() + ); + error_target!(crate::LOG_TARGET, "proposal_window {:?}", proposal_window); + error_target!( + crate::LOG_TARGET, + "committed_ids {} ", + serde_json::to_string(&committed_ids).unwrap() + ); + error_target!( + crate::LOG_TARGET, + "proposal_txs_ids {} ", + serde_json::to_string(&proposal_txs_ids).unwrap() + ); return Err(Error::Commit(CommitError::Invalid)); } Ok(()) diff --git a/verification/src/lib.rs b/verification/src/lib.rs index 78160df40c..34ebbeb837 100644 --- a/verification/src/lib.rs +++ b/verification/src/lib.rs @@ -18,6 +18,8 @@ pub use crate::transaction_verifier::{ pub const ALLOWED_FUTURE_BLOCKTIME: u64 = 15 * 1000; // 15 Second +pub(crate) const LOG_TARGET: &str = "ckb-chain"; + pub trait Verifier { type Target; fn verify(&self, target: &Self::Target) -> Result<(), Error>; diff --git a/verification/src/transaction_verifier.rs b/verification/src/transaction_verifier.rs index ccb2231eeb..dd77a63562 100644 --- a/verification/src/transaction_verifier.rs +++ b/verification/src/transaction_verifier.rs @@ -5,10 +5,10 @@ use ckb_core::{ cell::{CellMeta, ResolvedOutPoint, ResolvedTransaction}, BlockNumber, Cycle, EpochNumber, }; +use ckb_logger::info_target; use ckb_script::{ScriptConfig, TransactionScriptsVerifier}; use ckb_store::ChainStore; use ckb_traits::BlockMedianTimeContext; -use log; use lru_cache::LruCache; use std::cell::RefCell; use std::collections::HashSet; @@ -402,7 +402,12 @@ where .block_median_time(n, &block_hash) }) .unwrap_or(0); - log::info!("median_time {}, number {}", median_time, n); + info_target!( + crate::LOG_TARGET, + "median_time {}, number {}", + median_time, + n + ); self.median_timestamps_cache .borrow_mut() .insert(n, median_time); From ea1bcf15a773c6e34b4ee2afcfca29358be11b4c Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 13:54:29 +0800 Subject: [PATCH 7/9] chore: apply new log macros to util/* & ckb-bin --- Cargo.lock | 7 +++---- ckb-bin/Cargo.toml | 2 +- ckb-bin/src/helper.rs | 2 +- ckb-bin/src/lib.rs | 2 ++ ckb-bin/src/subcommand/prof.rs | 2 +- ckb-bin/src/subcommand/run.rs | 17 ++++++++++++----- util/app-config/Cargo.toml | 1 - util/app-config/src/exit_code.rs | 4 ++-- util/app-config/src/lib.rs | 19 ++++++++++++------- util/multisig/Cargo.toml | 2 +- util/multisig/src/secp256k1.rs | 5 ++--- 11 files changed, 37 insertions(+), 26 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 395440c2b8..8d23ac37e7 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -328,7 +328,6 @@ dependencies = [ "ckb-store 0.14.0-pre", "ckb-sync 0.14.0-pre", "clap 2.33.0 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "sentry 0.15.5 (registry+https://github.com/rust-lang/crates.io-index)", "serde 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", "serde_derive 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", @@ -369,6 +368,7 @@ dependencies = [ "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", "ckb-instrument 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-miner 0.14.0-pre", "ckb-network 0.14.0-pre", "ckb-notify 0.14.0-pre", @@ -388,7 +388,6 @@ dependencies = [ "faster-hex 0.3.1 (registry+https://github.com/rust-lang/crates.io-index)", "futures 0.1.26 (registry+https://github.com/rust-lang/crates.io-index)", "hash 0.14.0-pre", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-uint 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "sentry 0.15.5 (registry+https://github.com/rust-lang/crates.io-index)", @@ -702,6 +701,7 @@ dependencies = [ "byteorder 1.3.1 (registry+https://github.com/rust-lang/crates.io-index)", "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-protocol 0.14.0-pre", "ckb-resource 0.14.0-pre", "ckb-store 0.14.0-pre", @@ -712,7 +712,6 @@ dependencies = [ "flatbuffers 0.6.0 (registry+https://github.com/rust-lang/crates.io-index)", "fnv 1.0.6 (registry+https://github.com/rust-lang/crates.io-index)", "hash 0.14.0-pre", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "numext-fixed-hash 0.1.4 (registry+https://github.com/rust-lang/crates.io-index)", "proptest 0.9.3 (registry+https://github.com/rust-lang/crates.io-index)", "serde 1.0.91 (registry+https://github.com/rust-lang/crates.io-index)", @@ -2004,9 +2003,9 @@ dependencies = [ name = "multisig" version = "0.1.0" dependencies = [ + "ckb-logger 0.14.0-pre", "crypto 0.14.0-pre", "failure 0.1.5 (registry+https://github.com/rust-lang/crates.io-index)", - "log 0.4.6 (registry+https://github.com/rust-lang/crates.io-index)", "rand 0.6.5 (registry+https://github.com/rust-lang/crates.io-index)", ] diff --git a/ckb-bin/Cargo.toml b/ckb-bin/Cargo.toml index 05ffd5723e..21423e52bc 100644 --- a/ckb-bin/Cargo.toml +++ b/ckb-bin/Cargo.toml @@ -10,10 +10,10 @@ clap = { version = "2" } serde = "1.0" serde_derive = "1.0" toml = "0.5" -log = "0.4" futures = "0.1" crossbeam-channel = "0.3" ckb-app-config = { path = "../util/app-config" } +ckb-logger = { path = "../util/logger" } ckb-util = { path = "../util" } ckb-core = { path = "../core" } ckb-chain = { path = "../chain" } diff --git a/ckb-bin/src/helper.rs b/ckb-bin/src/helper.rs index 3f860a9298..9983e3d32a 100644 --- a/ckb-bin/src/helper.rs +++ b/ckb-bin/src/helper.rs @@ -1,5 +1,5 @@ +use ckb_logger::warn; use ckb_util::{parking_lot::deadlock, Condvar, Mutex}; -use log::warn; use std::sync::Arc; use std::thread; use std::time::Duration; diff --git a/ckb-bin/src/lib.rs b/ckb-bin/src/lib.rs index 8390713508..dd55f6dd23 100644 --- a/ckb-bin/src/lib.rs +++ b/ckb-bin/src/lib.rs @@ -4,6 +4,8 @@ mod subcommand; use build_info::Version; use ckb_app_config::{cli, ExitCode, Setup}; +pub(crate) const LOG_TARGET_MAIN: &str = "main"; + pub fn run_app(version: Version) -> Result<(), ExitCode> { // Always print backtrace on panic. ::std::env::set_var("RUST_BACKTRACE", "full"); diff --git a/ckb-bin/src/subcommand/prof.rs b/ckb-bin/src/subcommand/prof.rs index 6d22e6e9ae..9762e48304 100644 --- a/ckb-bin/src/subcommand/prof.rs +++ b/ckb-bin/src/subcommand/prof.rs @@ -2,11 +2,11 @@ use ckb_app_config::{ExitCode, ProfArgs}; use ckb_chain::chain::ChainController; use ckb_chain::chain::ChainService; use ckb_db::{DBConfig, RocksDB}; +use ckb_logger::info; use ckb_notify::NotifyService; use ckb_shared::shared::{Shared, SharedBuilder}; use ckb_store::ChainStore; use ckb_traits::ChainProvider; -use log::info; use std::sync::Arc; pub fn profile(args: ProfArgs) -> Result<(), ExitCode> { diff --git a/ckb-bin/src/subcommand/run.rs b/ckb-bin/src/subcommand/run.rs index eade55e861..fa2e7d5906 100644 --- a/ckb-bin/src/subcommand/run.rs +++ b/ckb-bin/src/subcommand/run.rs @@ -3,6 +3,7 @@ use build_info::Version; use ckb_app_config::{ExitCode, RunArgs}; use ckb_chain::chain::ChainService; use ckb_db::RocksDB; +use ckb_logger::info_target; use ckb_miner::BlockAssembler; use ckb_network::{CKBProtocol, NetworkService, NetworkState}; use ckb_notify::NotifyService; @@ -12,7 +13,6 @@ use ckb_store::ChainStore; use ckb_sync::{NetTimeProtocol, NetworkProtocol, Relayer, SyncSharedState, Synchronizer}; use ckb_traits::chain_provider::ChainProvider; use ckb_verification::{BlockVerifier, Verifier}; -use log::info; use std::sync::Arc; pub fn run(args: RunArgs, version: Version) -> Result<(), ExitCode> { @@ -36,7 +36,11 @@ pub fn run(args: RunArgs, version: Version) -> Result<(), ExitCode> { let notify = NotifyService::default().start(Some("notify")); let chain_service = ChainService::new(shared.clone(), notify.clone()); let chain_controller = chain_service.start(Some("ChainService")); - info!(target: "main", "chain genesis hash: {:#x}", shared.genesis_hash()); + info_target!( + crate::LOG_TARGET_MAIN, + "chain genesis hash: {:#x}", + shared.genesis_hash() + ); let block_assembler_controller = match (args.config.rpc.miner_enable(), args.config.block_assembler) { @@ -45,7 +49,10 @@ pub fn run(args: RunArgs, version: Version) -> Result<(), ExitCode> { .start(Some("MinerAgent"), ¬ify), ), _ => { - info!(target: "main", "Miner is disabled, edit ckb.toml to enable it"); + info_target!( + crate::LOG_TARGET_MAIN, + "Miner is disabled, edit ckb.toml to enable it" + ); None } @@ -107,10 +114,10 @@ pub fn run(args: RunArgs, version: Version) -> Result<(), ExitCode> { wait_for_exit(); - info!(target: "main", "Finishing work, please wait..."); + info_target!(crate::LOG_TARGET_MAIN, "Finishing work, please wait..."); rpc_server.close(); - info!(target: "main", "Jsonrpc shutdown"); + info_target!(crate::LOG_TARGET_MAIN, "Jsonrpc shutdown"); Ok(()) } diff --git a/util/app-config/Cargo.toml b/util/app-config/Cargo.toml index 6aa19113e6..5e33d1e8f8 100644 --- a/util/app-config/Cargo.toml +++ b/util/app-config/Cargo.toml @@ -10,7 +10,6 @@ clap = { version = "2" } serde = "1.0" serde_derive = "1.0" toml = "0.5" -log = "0.4" ckb-logger = { path = "../../util/logger" } sentry = "^0.15.4" ckb-chain-spec = {path = "../../spec"} diff --git a/util/app-config/src/exit_code.rs b/util/app-config/src/exit_code.rs index 0d1401f2d2..0866afbc7b 100644 --- a/util/app-config/src/exit_code.rs +++ b/util/app-config/src/exit_code.rs @@ -30,8 +30,8 @@ impl From for ExitCode { } } -impl From for ExitCode { - fn from(err: log::SetLoggerError) -> ExitCode { +impl From for ExitCode { + fn from(err: ckb_logger::SetLoggerError) -> ExitCode { eprintln!("Config Error: {:?}", err); ExitCode::Config } diff --git a/util/app-config/src/lib.rs b/util/app-config/src/lib.rs index 1db202debf..d7e88264da 100644 --- a/util/app-config/src/lib.rs +++ b/util/app-config/src/lib.rs @@ -12,12 +12,13 @@ pub use exit_code::ExitCode; use build_info::Version; use ckb_chain_spec::{consensus::Consensus, ChainSpec}; use ckb_instrument::Format; -use ckb_logger::LoggerInitGuard; +use ckb_logger::{info_target, LoggerInitGuard}; use ckb_resource::ResourceLocator; use clap::{value_t, ArgMatches}; -use log::info; use std::path::PathBuf; +pub(crate) const LOG_TARGET_SENTRY: &str = "sentry"; + pub struct Setup { subcommand_name: String, resource_locator: ResourceLocator, @@ -68,10 +69,14 @@ impl Setup { let sentry_guard = if self.is_sentry_enabled { let sentry_config = self.config.sentry(); - info!(target: "sentry", "**Notice**: \ - The ckb process will send stack trace to sentry on Rust panics. \ - This is enabled by default before mainnet, which can be opted out by setting \ - the option `dsn` to empty in the config file. The DSN is now {}", sentry_config.dsn); + info_target!( + crate::LOG_TARGET_SENTRY, + "**Notice**: \ + The ckb process will send stack trace to sentry on Rust panics. \ + This is enabled by default before mainnet, which can be opted out by setting \ + the option `dsn` to empty in the config file. The DSN is now {}", + sentry_config.dsn + ); let guard = sentry_config.init(&version); @@ -81,7 +86,7 @@ impl Setup { Some(guard) } else { - info!(target: "sentry", "sentry is disabled"); + info_target!(crate::LOG_TARGET_SENTRY, "sentry is disabled"); None }; diff --git a/util/multisig/Cargo.toml b/util/multisig/Cargo.toml index 15ae610cdb..9af5da0635 100644 --- a/util/multisig/Cargo.toml +++ b/util/multisig/Cargo.toml @@ -6,9 +6,9 @@ authors = ["Nervos Core Dev "] edition = "2018" [dependencies] +ckb-logger = { path = "../logger" } crypto = { path = "../crypto" } failure = "0.1.5" -log = "0.4" [dev-dependencies] rand = "0.6.5" diff --git a/util/multisig/src/secp256k1.rs b/util/multisig/src/secp256k1.rs index 2a55615295..b56077b7df 100644 --- a/util/multisig/src/secp256k1.rs +++ b/util/multisig/src/secp256k1.rs @@ -1,6 +1,6 @@ use crate::error::{Error, ErrorKind}; +use ckb_logger::{debug, trace}; pub use crypto::secp::{Error as Secp256k1Error, Message, Privkey, Pubkey, Signature}; -use log::{debug, trace}; use std::collections::HashSet; use std::hash::BuildHasher; @@ -27,7 +27,6 @@ where .iter() .filter_map(|sig| { trace!( - target: "multisig", "recover sig {:x?} with message {:x?}", &sig.serialize()[..], &message[..] @@ -35,7 +34,7 @@ where match sig.recover(&message) { Ok(pubkey) => Some(pubkey), Err(err) => { - debug!(target: "multisig", "recover secp256k1 sig error: {}", err); + debug!("recover secp256k1 sig error: {}", err); None } } From 64304c0c8bc81c5443cf278e4f3b13ae930f6923 Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 14:13:52 +0800 Subject: [PATCH 8/9] chore: apply new log macros to sync & relay --- Cargo.lock | 1 + sync/Cargo.toml | 1 + sync/src/lib.rs | 2 + sync/src/relayer/block_proposal_process.rs | 8 +- sync/src/relayer/compact_block_process.rs | 31 ++++- .../relayer/get_block_transactions_process.rs | 8 +- sync/src/relayer/get_transaction_process.rs | 13 +- sync/src/relayer/mod.rs | 60 +++++++-- sync/src/relayer/transaction_hash_process.rs | 14 +- sync/src/relayer/transaction_process.rs | 122 ++++++++++-------- sync/src/synchronizer/block_fetcher.rs | 16 +-- sync/src/synchronizer/block_process.rs | 8 +- sync/src/synchronizer/get_blocks_process.rs | 9 +- sync/src/synchronizer/get_headers_process.rs | 17 ++- sync/src/synchronizer/headers_process.rs | 88 +++++++------ sync/src/synchronizer/mod.rs | 46 ++++--- sync/src/types.rs | 34 +++-- 17 files changed, 297 insertions(+), 181 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 8d23ac37e7..4974475fdc 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -778,6 +778,7 @@ dependencies = [ "ckb-chain-spec 0.14.0-pre", "ckb-core 0.14.0-pre", "ckb-db 0.14.0-pre", + "ckb-logger 0.14.0-pre", "ckb-network 0.14.0-pre", "ckb-notify 0.14.0-pre", "ckb-protocol 0.14.0-pre", diff --git a/sync/Cargo.toml b/sync/Cargo.toml index f136841c63..116587634c 100644 --- a/sync/Cargo.toml +++ b/sync/Cargo.toml @@ -14,6 +14,7 @@ ckb-tx-pool-executor = { path = "../shared/tx-pool-executor" } numext-fixed-hash = { version = "0.1", features = ["support_rand", "support_heapsize", "support_serde"] } numext-fixed-uint = { version = "0.1", features = ["support_rand", "support_heapsize", "support_serde"] } ckb-network = { path = "../network" } +ckb-logger = {path = "../util/logger"} log = "0.4" fnv = "1.0" ckb-protocol = { path = "../protocol" } diff --git a/sync/src/lib.rs b/sync/src/lib.rs index 47cbd5e429..d84dd542b9 100644 --- a/sync/src/lib.rs +++ b/sync/src/lib.rs @@ -30,6 +30,8 @@ pub const STALE_RELAY_AGE_LIMIT: u64 = 30 * 24 * 60 * 60 * 1000; pub const BLOCK_DOWNLOAD_WINDOW: u64 = 1024; pub const PER_FETCH_BLOCK_LIMIT: usize = 128; +pub(crate) const LOG_TARGET_RELAY: &str = "ckb-relay"; + use ckb_network::ProtocolId; pub enum NetworkProtocol { diff --git a/sync/src/relayer/block_proposal_process.rs b/sync/src/relayer/block_proposal_process.rs index ad27080774..d18072317b 100644 --- a/sync/src/relayer/block_proposal_process.rs +++ b/sync/src/relayer/block_proposal_process.rs @@ -1,11 +1,11 @@ use crate::relayer::Relayer; use ckb_core::transaction::{ProposalShortId, Transaction}; +use ckb_logger::warn_target; use ckb_network::CKBProtocolContext; use ckb_protocol::{cast, BlockProposal, FlatbuffersVectorIterator}; use ckb_store::ChainStore; use failure::Error as FailureError; use futures::{self, future::FutureResult, lazy}; -use log::warn; use numext_fixed_hash::H256; use std::convert::TryInto; use std::sync::Arc; @@ -68,7 +68,11 @@ impl<'a, CS: ChainStore + 'static> BlockProposalProcess<'a, CS> { Box::new(lazy(move || -> FutureResult<(), ()> { let ret = tx_pool_executor.verify_and_add_txs_to_pool(asked_txs); if ret.is_err() { - warn!(target: "relay", "BlockProposal add_tx_to_pool error {:?}", ret) + warn_target!( + crate::LOG_TARGET_RELAY, + "BlockProposal add_tx_to_pool error {:?}", + ret + ) } futures::future::ok(()) })) diff --git a/sync/src/relayer/compact_block_process.rs b/sync/src/relayer/compact_block_process.rs index 4e29330b42..33b33163bd 100644 --- a/sync/src/relayer/compact_block_process.rs +++ b/sync/src/relayer/compact_block_process.rs @@ -3,6 +3,7 @@ use crate::relayer::compact_block_verifier::CompactBlockVerifier; use crate::relayer::Relayer; use ckb_core::header::Header; use ckb_core::BlockNumber; +use ckb_logger::debug_target; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::{CompactBlock as FbsCompactBlock, RelayMessage}; use ckb_shared::shared::Shared; @@ -12,7 +13,6 @@ use ckb_verification::{HeaderResolverWrapper, HeaderVerifier, Verifier}; use failure::Error as FailureError; use flatbuffers::FlatBufferBuilder; use fnv::FnvHashMap; -use log::debug; use numext_fixed_hash::H256; use std::convert::TryInto; use std::sync::Arc; @@ -44,7 +44,11 @@ impl<'a, CS: ChainStore + 'static> CompactBlockProcess<'a, CS> { let block_hash = compact_block.header.hash().to_owned(); if self.relayer.state.already_known_compact_block(&block_hash) { - debug!(target: "relay", "discarding already known compact block {:x}", block_hash); + debug_target!( + crate::LOG_TARGET_RELAY, + "discarding already known compact block {:x}", + block_hash + ); return Ok(()); } self.relayer @@ -60,8 +64,8 @@ impl<'a, CS: ChainStore + 'static> CompactBlockProcess<'a, CS> { let current_total_difficulty = parent_header_view.total_difficulty() + compact_block.header.difficulty(); if current_total_difficulty <= *best_known_header.total_difficulty() { - debug!( - target: "relay", + debug_target!( + crate::LOG_TARGET_RELAY, "Received a compact block({:#x}), total difficulty {:#x} <= {:#x}, ignore it", block_hash, current_total_difficulty, @@ -70,7 +74,12 @@ impl<'a, CS: ChainStore + 'static> CompactBlockProcess<'a, CS> { return Ok(()); } } else { - debug!(target: "relay", "UnknownParent: {:#x}, send_getheaders_to_peer({})", block_hash, self.peer); + debug_target!( + crate::LOG_TARGET_RELAY, + "UnknownParent: {:#x}, send_getheaders_to_peer({})", + block_hash, + self.peer + ); self.relayer.shared.send_getheaders_to_peer( self.nc.as_ref(), self.peer, @@ -87,7 +96,11 @@ impl<'a, CS: ChainStore + 'static> CompactBlockProcess<'a, CS> { if pending_compact_blocks.get(&block_hash).is_some() || self.relayer.shared.get_block(&block_hash).is_some() { - debug!(target: "relay", "already processed compact block {:x}", block_hash); + debug_target!( + crate::LOG_TARGET_RELAY, + "already processed compact block {:x}", + block_hash + ); return Ok(()); } else { let resolver = HeaderResolverWrapper::new( @@ -104,7 +117,11 @@ impl<'a, CS: ChainStore + 'static> CompactBlockProcess<'a, CS> { ); let compact_block_verifier = CompactBlockVerifier::new(); if let Err(err) = header_verifier.verify(&resolver) { - debug!(target: "relay", "unexpected header verify failed: {}", err); + debug_target!( + crate::LOG_TARGET_RELAY, + "unexpected header verify failed: {}", + err + ); return Ok(()); } compact_block_verifier.verify(&compact_block)?; diff --git a/sync/src/relayer/get_block_transactions_process.rs b/sync/src/relayer/get_block_transactions_process.rs index 0a224123ed..1c4e3439a3 100644 --- a/sync/src/relayer/get_block_transactions_process.rs +++ b/sync/src/relayer/get_block_transactions_process.rs @@ -1,10 +1,10 @@ use crate::relayer::Relayer; +use ckb_logger::debug_target; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::{cast, GetBlockTransactions, RelayMessage}; use ckb_store::ChainStore; use failure::Error as FailureError; use flatbuffers::FlatBufferBuilder; -use log::debug; use std::convert::TryInto; use std::sync::Arc; @@ -32,7 +32,11 @@ impl<'a, CS: ChainStore> GetBlockTransactionsProcess<'a, CS> { pub fn execute(self) -> Result<(), FailureError> { let block_hash = cast!(self.message.block_hash())?.try_into()?; - debug!(target: "relay", "get_block_transactions {:x}", block_hash); + debug_target!( + crate::LOG_TARGET_RELAY, + "get_block_transactions {:x}", + block_hash + ); let indexes = cast!(self.message.indexes())?; diff --git a/sync/src/relayer/get_transaction_process.rs b/sync/src/relayer/get_transaction_process.rs index 3c2a9a6dd7..905e4c8465 100644 --- a/sync/src/relayer/get_transaction_process.rs +++ b/sync/src/relayer/get_transaction_process.rs @@ -1,11 +1,11 @@ use crate::relayer::Relayer; use ckb_core::transaction::ProposalShortId; +use ckb_logger::{debug_target, trace_target}; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::{GetRelayTransaction as FbsGetRelayTransaction, RelayMessage}; use ckb_store::ChainStore; use failure::Error as FailureError; use flatbuffers::FlatBufferBuilder; -use log::{debug, trace}; use std::convert::TryInto; use std::sync::Arc; @@ -33,7 +33,12 @@ impl<'a, CS: ChainStore> GetTransactionProcess<'a, CS> { pub fn execute(self) -> Result<(), FailureError> { let tx_hash = (*self.message).try_into()?; - trace!(target: "relay", "{} request transaction({:#x})", self.peer, tx_hash); + trace_target!( + crate::LOG_TARGET_RELAY, + "{} request transaction({:#x})", + self.peer, + tx_hash + ); let entry_opt = { let short_id = ProposalShortId::from_tx_hash(&tx_hash); self.relayer @@ -49,8 +54,8 @@ impl<'a, CS: ChainStore> GetTransactionProcess<'a, CS> { let data = fbb.finished_data().into(); self.nc.send_message_to(self.peer, data); } else { - debug!( - target: "realy", + debug_target!( + crate::LOG_TARGET_RELAY, "{} request transaction({:#x}), but not found or without cycles", self.peer, tx_hash, diff --git a/sync/src/relayer/mod.rs b/sync/src/relayer/mod.rs index c696bbbcee..16ee511596 100644 --- a/sync/src/relayer/mod.rs +++ b/sync/src/relayer/mod.rs @@ -29,6 +29,7 @@ use ckb_chain::chain::ChainController; use ckb_core::block::{Block, BlockBuilder}; use ckb_core::transaction::{ProposalShortId, Transaction}; use ckb_core::uncle::UncleBlock; +use ckb_logger::{debug_target, info_target, trace_target}; use ckb_network::{CKBProtocolContext, CKBProtocolHandler, PeerIndex, TargetSession}; use ckb_protocol::{ cast, get_root, short_transaction_id, short_transaction_id_keys, RelayMessage, RelayPayload, @@ -41,7 +42,6 @@ use failure::Error as FailureError; use faketime::unix_time_as_millis; use flatbuffers::FlatBufferBuilder; use fnv::{FnvHashMap, FnvHashSet}; -use log::{debug, info, trace}; use lru_cache::LruCache; use numext_fixed_hash::H256; use std::collections::HashSet; @@ -181,7 +181,7 @@ impl Relayer { message: RelayMessage, ) { if let Err(err) = self.try_process(Arc::clone(&nc), peer, message) { - debug!(target: "relay", "try_process error {}", err); + debug_target!(crate::LOG_TARGET_RELAY, "try_process error {}", err); nc.ban_peer(peer, BAD_MESSAGE_BAN_TIME); } } @@ -216,7 +216,12 @@ impl Relayer { let ret = self.chain.process_block(Arc::clone(&block), true); if ret.is_ok() { - debug!(target: "relay", "[block_relay] relayer accept_block {:x} {}", block.header().hash(), unix_time_as_millis()); + debug_target!( + crate::LOG_TARGET_RELAY, + "[block_relay] relayer accept_block {:x} {}", + block.header().hash(), + unix_time_as_millis() + ); let block_hash = block.header().hash(); self.shared.remove_header_view(&block_hash); let fbb = &mut FlatBufferBuilder::new(); @@ -235,7 +240,11 @@ impl Relayer { .collect(); nc.quick_filter_broadcast(TargetSession::Multi(selected_peers), data); } else { - debug!(target: "relay", "accept_block verify error {:?}", ret); + debug_target!( + crate::LOG_TARGET_RELAY, + "accept_block verify error {:?}", + ret + ); } } @@ -367,8 +376,8 @@ impl Relayer { }) .collect::>(); if !tx_hashes.is_empty() { - debug!( - target: "relay", + debug_target!( + crate::LOG_TARGET_RELAY, "Send get transaction ({} hashes) to {}", tx_hashes.len(), peer, @@ -405,17 +414,26 @@ impl CKBProtocolHandler for Relayer { let msg = match get_root::(&data) { Ok(msg) => msg, _ => { - info!(target: "relay", "Peer {} sends us a malformed message", peer_index); + info_target!( + crate::LOG_TARGET_RELAY, + "Peer {} sends us a malformed message", + peer_index + ); nc.ban_peer(peer_index, BAD_MESSAGE_BAN_TIME); return; } }; - debug!(target: "relay", "received msg {:?} from {}", msg.payload_type(), peer_index); + debug_target!( + crate::LOG_TARGET_RELAY, + "received msg {:?} from {}", + msg.payload_type(), + peer_index + ); let start_time = Instant::now(); self.process(nc, peer_index, msg); - debug!( - target: "relay", + debug_target!( + crate::LOG_TARGET_RELAY, "process message={:?}, peer={}, cost={:?}", msg.payload_type(), peer_index, @@ -429,12 +447,21 @@ impl CKBProtocolHandler for Relayer { peer_index: PeerIndex, version: &str, ) { - info!(target: "relay", "RelayProtocol({}).connected peer={}", version, peer_index); + info_target!( + crate::LOG_TARGET_RELAY, + "RelayProtocol({}).connected peer={}", + version, + peer_index + ); // do nothing } fn disconnected(&mut self, _nc: Arc, peer_index: PeerIndex) { - info!(target: "relay", "RelayProtocol.disconnected peer={}", peer_index); + info_target!( + crate::LOG_TARGET_RELAY, + "RelayProtocol.disconnected peer={}", + peer_index + ); // TODO } @@ -445,13 +472,18 @@ impl CKBProtocolHandler for Relayer { } let start_time = Instant::now(); - trace!(target: "relay", "start notify token={}", token); + trace_target!(crate::LOG_TARGET_RELAY, "start notify token={}", token); match token { TX_PROPOSAL_TOKEN => self.prune_tx_proposal_request(nc.as_ref()), ASK_FOR_TXS_TOKEN => self.ask_for_txs(nc.as_ref()), _ => unreachable!(), } - trace!(target: "relay", "finished notify token={} cost={:?}", token, start_time.elapsed()); + trace_target!( + crate::LOG_TARGET_RELAY, + "finished notify token={} cost={:?}", + token, + start_time.elapsed() + ); } } diff --git a/sync/src/relayer/transaction_hash_process.rs b/sync/src/relayer/transaction_hash_process.rs index 8f848333da..d1ba73ea17 100644 --- a/sync/src/relayer/transaction_hash_process.rs +++ b/sync/src/relayer/transaction_hash_process.rs @@ -1,10 +1,10 @@ use crate::relayer::Relayer; use ckb_core::transaction::ProposalShortId; +use ckb_logger::{debug_target, trace_target}; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::RelayTransactionHash as FbsRelayTransactionHash; use ckb_store::ChainStore; use failure::Error as FailureError; -use log::{debug, trace}; use numext_fixed_hash::H256; use std::convert::TryInto; use std::sync::Arc; @@ -35,8 +35,8 @@ impl<'a, CS: ChainStore> TransactionHashProcess<'a, CS> { let tx_hash: H256 = (*self.message).try_into()?; let short_id = ProposalShortId::from_tx_hash(&tx_hash); if self.relayer.state.already_known_tx(&tx_hash) { - debug!( - target: "relay", + debug_target!( + crate::LOG_TARGET_RELAY, "transaction({:#x}) from {} already known, ignore it", tx_hash, self.peer, @@ -49,16 +49,16 @@ impl<'a, CS: ChainStore> TransactionHashProcess<'a, CS> { .get_tx_with_cycles(&short_id) .is_some() { - trace!( - target: "relay", + trace_target!( + crate::LOG_TARGET_RELAY, "transaction({:#x}) from {} already in transaction pool, ignore it", tx_hash, self.peer, ); self.relayer.state.mark_as_known_tx(tx_hash.clone()); } else { - debug!( - target: "relay", + debug_target!( + crate::LOG_TARGET_RELAY, "transaction({:#x}) from {} not known, get it from the peer", tx_hash, self.peer, diff --git a/sync/src/relayer/transaction_process.rs b/sync/src/relayer/transaction_process.rs index b67c036d7e..03cb937d1d 100644 --- a/sync/src/relayer/transaction_process.rs +++ b/sync/src/relayer/transaction_process.rs @@ -1,13 +1,13 @@ use crate::relayer::Relayer; use crate::relayer::MAX_RELAY_PEERS; use ckb_core::{transaction::Transaction, Cycle}; +use ckb_logger::debug_target; use ckb_network::{CKBProtocolContext, PeerIndex, TargetSession}; use ckb_protocol::{RelayMessage, RelayTransaction as FbsRelayTransaction}; use ckb_store::ChainStore; use failure::Error as FailureError; use flatbuffers::FlatBufferBuilder; use futures::{self, future::FutureResult, lazy}; -use log::debug; use std::convert::TryInto; use std::sync::Arc; use std::time::Duration; @@ -41,7 +41,11 @@ impl<'a, CS: ChainStore + Sync + 'static> TransactionProcess<'a, CS> { let tx_hash = tx.hash(); if self.relayer.state.already_known_tx(&tx_hash) { - debug!(target: "relay", "discarding already known transaction {:#x}", tx_hash); + debug_target!( + crate::LOG_TARGET_RELAY, + "discarding already known transaction {:#x}", + tx_hash + ); return Ok(()); } @@ -61,59 +65,71 @@ impl<'a, CS: ChainStore + Sync + 'static> TransactionProcess<'a, CS> { let peers = Arc::clone(&self.relayer.peers); let tx_hash = tx_hash.clone(); let tx = tx.to_owned(); - Box::new( - lazy( - move|| -> FutureResult<(), ()> { - let tx_pool_executor = Arc::clone(&tx_pool_executor); - let tx_result = tx_pool_executor.verify_and_add_tx_to_pool(tx.to_owned()); - // disconnect peer if cycles mismatch - match tx_result { - Ok(cycles) if cycles == relay_cycles => { - let selected_peers: Vec = { - let mut known_txs = peers.known_txs.lock(); - nc.connected_peers() - .into_iter() - .filter(|target_peer| { - known_txs.insert(*target_peer, tx_hash.clone()) - && (self_peer != *target_peer) - }) - .take(MAX_RELAY_PEERS) - .collect() - }; + Box::new(lazy(move || -> FutureResult<(), ()> { + let tx_pool_executor = Arc::clone(&tx_pool_executor); + let tx_result = tx_pool_executor.verify_and_add_tx_to_pool(tx.to_owned()); + // disconnect peer if cycles mismatch + match tx_result { + Ok(cycles) if cycles == relay_cycles => { + let selected_peers: Vec = { + let mut known_txs = peers.known_txs.lock(); + nc.connected_peers() + .into_iter() + .filter(|target_peer| { + known_txs.insert(*target_peer, tx_hash.clone()) + && (self_peer != *target_peer) + }) + .take(MAX_RELAY_PEERS) + .collect() + }; - let fbb = &mut FlatBufferBuilder::new(); - let message = RelayMessage::build_transaction_hash(fbb, &tx_hash); - fbb.finish(message, None); - let data = fbb.finished_data().into(); - nc.filter_broadcast(TargetSession::Multi(selected_peers), data); - } - Ok(cycles) => { - debug!( - target: "relay", - "peer {} relay wrong cycles tx: {:?} real cycles {} wrong cycles {}", - self_peer, tx, cycles, relay_cycles, - ); - nc.ban_peer(self_peer, DEFAULT_BAN_TIME); - } - Err(err) => { - if err.is_bad_tx() { - debug!(target: "relay", "peer {} relay a invalid tx: {:x}, error: {:?}", self_peer, tx_hash, err); - sentry::capture_message( - &format!( - "ban peer {} {:?}, reason: relay invalid tx: {:?}, error: {:?}", - self_peer, DEFAULT_BAN_TIME, tx, err - ), - sentry::Level::Info, - ); - nc.ban_peer(self_peer, DEFAULT_BAN_TIME); - } else { - debug!(target: "relay", "peer {} relay a conflict or missing input tx: {:x}, error: {:?}", self_peer, tx_hash, err); - } - } + let fbb = &mut FlatBufferBuilder::new(); + let message = RelayMessage::build_transaction_hash(fbb, &tx_hash); + fbb.finish(message, None); + let data = fbb.finished_data().into(); + nc.filter_broadcast(TargetSession::Multi(selected_peers), data); + } + Ok(cycles) => { + debug_target!( + crate::LOG_TARGET_RELAY, + "peer {} relay wrong cycles tx: {:?} real cycles {} wrong cycles {}", + self_peer, + tx, + cycles, + relay_cycles, + ); + nc.ban_peer(self_peer, DEFAULT_BAN_TIME); + } + Err(err) => { + if err.is_bad_tx() { + debug_target!( + crate::LOG_TARGET_RELAY, + "peer {} relay a invalid tx: {:x}, error: {:?}", + self_peer, + tx_hash, + err + ); + sentry::capture_message( + &format!( + "ban peer {} {:?}, reason: relay invalid tx: {:?}, error: {:?}", + self_peer, DEFAULT_BAN_TIME, tx, err + ), + sentry::Level::Info, + ); + nc.ban_peer(self_peer, DEFAULT_BAN_TIME); + } else { + debug_target!( + crate::LOG_TARGET_RELAY, + "peer {} relay a conflict or missing input tx: {:x}, error: {:?}", + self_peer, + tx_hash, + err + ); } - futures::future::ok(()) - }) - ) + } + } + futures::future::ok(()) + })) }); Ok(()) } diff --git a/sync/src/synchronizer/block_fetcher.rs b/sync/src/synchronizer/block_fetcher.rs index 05ce1f1d24..c7953f2396 100644 --- a/sync/src/synchronizer/block_fetcher.rs +++ b/sync/src/synchronizer/block_fetcher.rs @@ -2,9 +2,9 @@ use crate::synchronizer::{BlockStatus, Synchronizer}; use crate::types::HeaderView; use crate::{BLOCK_DOWNLOAD_WINDOW, MAX_BLOCKS_IN_TRANSIT_PER_PEER, PER_FETCH_BLOCK_LIMIT}; use ckb_core::header::Header; +use ckb_logger::{debug, trace}; use ckb_network::PeerIndex; use ckb_store::ChainStore; -use log::{debug, trace}; use numext_fixed_hash::H256; use numext_fixed_uint::U256; use std::cmp; @@ -86,7 +86,6 @@ where { if &ancestor != header.inner() { debug!( - target: "sync", "[block downloader] peer best_known_header is not ancestor of global_best_known_header" ); return false; @@ -98,11 +97,10 @@ where } pub fn fetch(self) -> Option> { - trace!(target: "sync", "[block downloader] BlockFetcher process"); + trace!("[block downloader] BlockFetcher process"); if self.reached_inflight_limit() { trace!( - target: "sync", "[block downloader] inflight count reach limit, can't download any more from peer {}", self.peer ); @@ -113,7 +111,6 @@ where Some(best_known_header) => best_known_header, _ => { trace!( - target: "sync", "[block downloader] peer_best_known_header not found peer={}", self.peer ); @@ -124,7 +121,6 @@ where // This peer has nothing interesting. if !self.is_better_chain(&best_known_header) { trace!( - target: "sync", "[block downloader] best_known_header {} chain {}", best_known_header.total_difficulty(), self.total_difficulty @@ -141,15 +137,11 @@ where let fixed_last_common_header = self.last_common_header(&best_known_header)?; if &fixed_last_common_header == best_known_header.inner() { - trace!( - target: "sync", - "[block downloader] fixed_last_common_header == best_known_header" - ); + trace!("[block downloader] fixed_last_common_header == best_known_header"); return None; } debug!( - target: "sync", "[block downloader] fixed_last_common_header = {} best_known_header = {}", fixed_last_common_header.number(), best_known_header.number() @@ -183,7 +175,7 @@ where && inflight.insert(self.peer, to_fetch_hash.to_owned()) { trace!( - target: "sync", "[Synchronizer] inflight insert {:?}------------{:x}", + "[Synchronizer] inflight insert {:?}------------{:x}", to_fetch.number(), to_fetch_hash ); diff --git a/sync/src/synchronizer/block_process.rs b/sync/src/synchronizer/block_process.rs index 641a0d73af..dacb57d456 100644 --- a/sync/src/synchronizer/block_process.rs +++ b/sync/src/synchronizer/block_process.rs @@ -1,10 +1,10 @@ use crate::synchronizer::Synchronizer; use ckb_core::block::Block; +use ckb_logger::debug; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::Block as PBlock; use ckb_store::ChainStore; use failure::Error as FailureError; -use log::debug; use std::convert::TryInto; pub struct BlockProcess<'a, CS: ChainStore + 'a> { @@ -32,7 +32,11 @@ where pub fn execute(self) -> Result<(), FailureError> { let block: Block = (*self.message).try_into()?; - debug!(target: "sync", "BlockProcess received block {} {:x}", block.header().number(), block.header().hash()); + debug!( + "BlockProcess received block {} {:x}", + block.header().number(), + block.header().hash() + ); if self.synchronizer.peers.new_block_received(&block) { self.synchronizer.process_new_block(self.peer, block); diff --git a/sync/src/synchronizer/get_blocks_process.rs b/sync/src/synchronizer/get_blocks_process.rs index b20b381326..65a99d8faf 100644 --- a/sync/src/synchronizer/get_blocks_process.rs +++ b/sync/src/synchronizer/get_blocks_process.rs @@ -1,11 +1,11 @@ use crate::synchronizer::Synchronizer; use crate::MAX_BLOCKS_IN_TRANSIT_PER_PEER; +use ckb_logger::{debug, warn}; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::{cast, GetBlocks, SyncMessage}; use ckb_store::ChainStore; use failure::Error as FailureError; use flatbuffers::FlatBufferBuilder; -use log::{debug, warn}; use std::cmp::min; use std::convert::TryInto; @@ -40,10 +40,9 @@ where let n_limit = min(MAX_BLOCKS_IN_TRANSIT_PER_PEER as usize, block_hashes.len()); for fbs_h256 in block_hashes.iter().take(n_limit) { let block_hash = fbs_h256.try_into()?; - debug!(target: "sync", "get_blocks {:x} from peer {:?}", block_hash, self.peer); + debug!("get_blocks {:x} from peer {:?}", block_hash, self.peer); if let Some(block) = self.synchronizer.shared.get_block(&block_hash) { debug!( - target: "sync", "respond_block {} {:x} to peer {:?}", block.header().number(), block.header().hash(), @@ -61,13 +60,13 @@ where // We expect that `block_hashes` is sorted descending by height. // So if we cannot find the current one from local, we cannot find // the next either. - debug!(target: "sync", "getblocks stopping since {:x} is not found", block_hash); + debug!("getblocks stopping since {:x} is not found", block_hash); break; } } if n_limit < block_hashes.len() { - warn!(target: "sync", "getblocks stopping at limit {}", n_limit); + warn!("getblocks stopping at limit {}", n_limit); } Ok(()) diff --git a/sync/src/synchronizer/get_headers_process.rs b/sync/src/synchronizer/get_headers_process.rs index 7a82a4fe91..4d756e6a17 100644 --- a/sync/src/synchronizer/get_headers_process.rs +++ b/sync/src/synchronizer/get_headers_process.rs @@ -1,12 +1,12 @@ use crate::synchronizer::Synchronizer; use crate::{MAX_LOCATOR_SIZE, SYNC_USELESS_BAN_TIME}; use ckb_core::header::Header; +use ckb_logger::{debug, info, warn}; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::{cast, GetHeaders, SyncMessage}; use ckb_store::ChainStore; use failure::Error as FailureError; use flatbuffers::FlatBufferBuilder; -use log::{debug, info, warn}; use numext_fixed_hash::H256; use std::convert::TryInto; @@ -37,14 +37,20 @@ where pub fn execute(self) -> Result<(), FailureError> { if self.synchronizer.shared.is_initial_block_download() { - info!(target: "sync", "Ignoring getheaders from peer={} because node is in initial block download", self.peer); + info!( + "Ignoring getheaders from peer={} because node is in initial block download", + self.peer + ); return Ok(()); } let locator = cast!(self.message.block_locator_hashes())?; let locator_size = locator.len(); if locator_size > MAX_LOCATOR_SIZE { - warn!(target: "sync", " getheaders locator size {} from peer={}", locator_size, self.peer); + warn!( + " getheaders locator size {} from peer={}", + locator_size, self.peer + ); cast!(None)?; } @@ -60,7 +66,6 @@ where .locate_latest_common_block(&hash_stop, &block_locator_hashes[..]) { debug!( - target: "sync", "headers latest_common={} tip={} begin", block_number, self.synchronizer.shared.tip_header().number(), @@ -73,7 +78,7 @@ where .get_locator_response(block_number, &hash_stop); // response headers - debug!(target: "sync", "headers len={}", headers.len()); + debug!("headers len={}", headers.len()); let fbb = &mut FlatBufferBuilder::new(); let message = SyncMessage::build_headers(fbb, &headers); @@ -82,7 +87,7 @@ where .send_message_to(self.peer, fbb.finished_data().into()); } else { for hash in &block_locator_hashes[..] { - warn!(target: "sync", "unknown block headers from peer {} {:#x}", self.peer, hash); + warn!("unknown block headers from peer {} {:#x}", self.peer, hash); } // Got 'headers' message without known blocks self.nc.ban_peer(self.peer, SYNC_USELESS_BAN_TIME); diff --git a/sync/src/synchronizer/headers_process.rs b/sync/src/synchronizer/headers_process.rs index cee458e8a7..817fadd68d 100644 --- a/sync/src/synchronizer/headers_process.rs +++ b/sync/src/synchronizer/headers_process.rs @@ -3,13 +3,13 @@ use crate::MAX_HEADERS_LEN; use ckb_core::extras::EpochExt; use ckb_core::header::Header; use ckb_core::BlockNumber; +use ckb_logger::{debug, log_enabled, warn, Level}; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::{cast, FlatbuffersVectorIterator, Headers}; use ckb_store::ChainStore; use ckb_traits::BlockMedianTimeContext; use ckb_verification::{Error as VerifyError, HeaderResolver, HeaderVerifier, Verifier}; use failure::Error as FailureError; -use log::{self, debug, log_enabled, warn}; use numext_fixed_hash::H256; use std::convert::TryInto; use std::sync::Arc; @@ -127,7 +127,6 @@ where if let [parent, header] = &window { if header.parent_hash() != parent.hash() { debug!( - target: "sync", "header.parent_hash {:x} parent.hash {:x}", header.parent_hash(), parent.hash() @@ -157,13 +156,13 @@ where } pub fn execute(self) -> Result<(), FailureError> { - debug!(target: "sync", "HeadersProcess begin"); + debug!("HeadersProcess begin"); let headers = cast!(self.message.headers())?; if headers.len() > MAX_HEADERS_LEN { self.synchronizer.peers.misbehavior(self.peer, 20); - warn!(target: "sync", "HeadersProcess is_oversize"); + warn!("HeadersProcess is_oversize"); return Ok(()); } @@ -182,7 +181,7 @@ where .get_mut(&self.peer) .expect("Peer must exists") .headers_sync_timeout = None; - debug!(target: "sync", "HeadersProcess is_empty (synchronized)"); + debug!("HeadersProcess is_empty (synchronized)"); return Ok(()); } @@ -192,7 +191,7 @@ where if !self.is_continuous(&headers) { self.synchronizer.peers.misbehavior(self.peer, 20); - debug!(target: "sync", "HeadersProcess is not continuous"); + debug!("HeadersProcess is not continuous"); return Ok(()); } @@ -203,7 +202,10 @@ where .peers .misbehavior(self.peer, result.misbehavior); } - debug!(target: "sync", "HeadersProcess accept_first is_valid {:?} headers = {:?}", result, headers[0]); + debug!( + "HeadersProcess accept_first is_valid {:?} headers = {:?}", + result, headers[0] + ); return Ok(()); } @@ -224,23 +226,21 @@ where .peers .misbehavior(self.peer, result.misbehavior); } - debug!(target: "sync", "HeadersProcess accept is invalid {:?}", result); + debug!("HeadersProcess accept is invalid {:?}", result); return Ok(()); } } } - if log_enabled!(target: "sync", log::Level::Debug) { + if log_enabled!(Level::Debug) { let chain_state = self.synchronizer.shared.lock_chain_state(); let peer_best_known = self.synchronizer.peers.get_best_known_header(self.peer); debug!( - target: "sync", "chain: num={}, diff={:#x};", chain_state.tip_number(), chain_state.total_difficulty() ); debug!( - target: "sync", "shared best_known_header: num={}, diff={:#x}, hash={:#x};", shared_best_known.number(), shared_best_known.total_difficulty(), @@ -248,7 +248,6 @@ where ); if let Some(header) = peer_best_known { debug!( - target: "sync", "peer's best_known_header: peer: {}, num={}; diff={:#x}, hash={:#x};", self.peer, header.number(), @@ -256,9 +255,9 @@ where header.hash() ); } else { - debug!(target: "sync", "state: null;"); + debug!("state: null;"); } - debug!(target: "sync", "peer: {}", self.peer); + debug!("peer: {}", self.peer); } if self.received_new_header(&headers) { @@ -287,7 +286,7 @@ where && headers.len() != MAX_HEADERS_LEN && (is_outbound && !is_protected) { - debug!(target: "sync", "Disconnect peer({}) is unprotected outbound", self.peer); + debug!("Disconnect peer({}) is unprotected outbound", self.peer); self.nc.disconnect(self.peer); } @@ -351,23 +350,34 @@ where } pub fn non_contextual_check(&self, state: &mut ValidationResult) -> Result<(), ()> { - self.verifier.verify(&self.resolver).map_err(|error| match error { - VerifyError::Pow(e) => { - debug!(target: "sync", "HeadersProcess accept {:?} pow error {:?}", self.header.number(), e); - state.dos(Some(ValidationError::Verify(VerifyError::Pow(e))), 100); - } - VerifyError::Epoch(e) => { - debug!(target: "sync", "HeadersProcess accept {:?} epoch error {:?}", self.header.number(), e); - state.dos( - Some(ValidationError::Verify(VerifyError::Epoch(e))), - 50, - ); - } - error => { - debug!(target: "sync", "HeadersProcess accept {:?} {:?}", self.header.number(), error); - state.invalid(Some(ValidationError::Verify(error))); - } - }) + self.verifier + .verify(&self.resolver) + .map_err(|error| match error { + VerifyError::Pow(e) => { + debug!( + "HeadersProcess accept {:?} pow error {:?}", + self.header.number(), + e + ); + state.dos(Some(ValidationError::Verify(VerifyError::Pow(e))), 100); + } + VerifyError::Epoch(e) => { + debug!( + "HeadersProcess accept {:?} epoch error {:?}", + self.header.number(), + e + ); + state.dos(Some(ValidationError::Verify(VerifyError::Epoch(e))), 50); + } + error => { + debug!( + "HeadersProcess accept {:?} {:?}", + self.header.number(), + error + ); + state.invalid(Some(ValidationError::Verify(error))); + } + }) } pub fn version_check(&self, state: &mut ValidationResult) -> Result<(), ()> { @@ -382,26 +392,32 @@ where pub fn accept(&self) -> ValidationResult { let mut result = ValidationResult::default(); if self.duplicate_check(&mut result).is_err() { - debug!(target: "sync", "HeadersProcess accept {:?} duplicate", self.header.number()); + debug!("HeadersProcess accept {:?} duplicate", self.header.number()); return result; } if self.prev_block_check(&mut result).is_err() { - debug!(target: "sync", "HeadersProcess accept {:?} prev_block", self.header.number()); + debug!( + "HeadersProcess accept {:?} prev_block", + self.header.number() + ); self.synchronizer .insert_block_status(self.header.hash().to_owned(), BlockStatus::FAILED_MASK); return result; } if self.non_contextual_check(&mut result).is_err() { - debug!(target: "sync", "HeadersProcess accept {:?} non_contextual", self.header.number()); + debug!( + "HeadersProcess accept {:?} non_contextual", + self.header.number() + ); self.synchronizer .insert_block_status(self.header.hash().to_owned(), BlockStatus::FAILED_MASK); return result; } if self.version_check(&mut result).is_err() { - debug!(target: "sync", "HeadersProcess accept {:?} version", self.header.number()); + debug!("HeadersProcess accept {:?} version", self.header.number()); self.synchronizer .insert_block_status(self.header.hash().to_owned(), BlockStatus::FAILED_MASK); return result; diff --git a/sync/src/synchronizer/mod.rs b/sync/src/synchronizer/mod.rs index ad2da799cf..d218b6aa3a 100644 --- a/sync/src/synchronizer/mod.rs +++ b/sync/src/synchronizer/mod.rs @@ -22,6 +22,7 @@ use bitflags::bitflags; use ckb_chain::chain::ChainController; use ckb_core::block::Block; use ckb_core::header::Header; +use ckb_logger::{debug, info, trace}; use ckb_network::{CKBProtocolContext, CKBProtocolHandler, PeerIndex}; use ckb_protocol::{cast, get_root, SyncMessage, SyncPayload}; use ckb_store::ChainStore; @@ -30,7 +31,6 @@ use failure::Error as FailureError; use faketime::unix_time_as_millis; use flatbuffers::FlatBufferBuilder; use hashbrown::HashMap; -use log::{debug, info, trace}; use numext_fixed_hash::H256; use std::cmp::min; use std::sync::atomic::AtomicUsize; @@ -147,7 +147,7 @@ impl Synchronizer { fn process(&self, nc: &CKBProtocolContext, peer: PeerIndex, message: SyncMessage) { if let Err(err) = self.try_process(nc, peer, message) { - debug!(target: "sync", "try_process error: {}", err); + debug!("try_process error: {}", err); nc.ban_peer(peer, BAD_MESSAGE_BAN_TIME); } } @@ -220,7 +220,7 @@ impl Synchronizer { //TODO: process block which we don't request pub fn process_new_block(&self, peer: PeerIndex, block: Block) { if self.orphan_block_pool.contains(&block) { - debug!(target: "sync", "block {:x} already in orphan pool", block.header().hash()); + debug!("block {:x} already in orphan pool", block.header().hash()); return; } @@ -229,7 +229,10 @@ impl Synchronizer { self.insert_new_block(peer, block); } status => { - debug!(target: "sync", "[Synchronizer] process_new_block unexpect status {:?}", status); + debug!( + "[Synchronizer] process_new_block unexpect status {:?}", + status + ); } } } @@ -255,7 +258,7 @@ impl Synchronizer { // Insert the given block into orphan_block_pool if its parent is not found if !known_parent(&block) { debug!( - target: "sync", "insert new orphan block {} {:x}", + "insert new orphan block {} {:x}", block.header().number(), block.header().hash() ); @@ -266,7 +269,7 @@ impl Synchronizer { // Attempt to accept the given block if its parent already exist in database let block = Arc::new(block); if let Err(err) = self.accept_block(peer, &block) { - debug!(target: "sync", "accept block {:?} error {:?}", block, err); + debug!("accept block {:?} error {:?}", block, err); return; } @@ -282,7 +285,7 @@ impl Synchronizer { // its parent, so we treat it as a invalid block as well. if !known_parent(&block) { debug!( - target: "sync", "parent-unknown orphan block, block: {}, {:x}, parent: {:x}", + "parent-unknown orphan block, block: {}, {:x}, parent: {:x}", block.header().number(), block.header().hash(), block.header().parent_hash(), @@ -291,7 +294,7 @@ impl Synchronizer { } if let Err(err) = self.accept_block(peer, &block) { - debug!(target: "sync", "accept descendant orphan block {:?} error {:?}", block, err); + debug!("accept descendant orphan block {:?} error {:?}", block, err); } } } @@ -404,7 +407,7 @@ impl Synchronizer { } } for peer in eviction { - info!(target: "sync", "timeout eviction peer={}", peer); + info!("timeout eviction peer={}", peer); nc.disconnect(peer); } } @@ -458,7 +461,7 @@ impl Synchronizer { } } - debug!(target: "sync", "start sync peer={}", peer); + debug!("start sync peer={}", peer); self.shared.send_getheaders_to_peer(nc, peer, &tip); } } @@ -475,7 +478,7 @@ impl Synchronizer { .collect() }; - trace!(target: "sync", "poll find_blocks_to_fetch select peers"); + trace!("poll find_blocks_to_fetch select peers"); { self.peers.blocks_inflight.write().prune(); } @@ -493,7 +496,7 @@ impl Synchronizer { let message = SyncMessage::build_get_blocks(fbb, v_fetch); fbb.finish(message, None); nc.send_message_to(peer, fbb.finished_data().into()); - debug!(target: "sync", "send_getblocks len={:?} to peer={}", v_fetch.len() , peer); + debug!("send_getblocks len={:?} to peer={}", v_fetch.len(), peer); } } @@ -515,18 +518,17 @@ impl CKBProtocolHandler for Synchronizer { let msg = match get_root::(&data) { Ok(msg) => msg, _ => { - info!(target: "sync", "Peer {} sends us a malformed message", peer_index); + info!("Peer {} sends us a malformed message", peer_index); nc.ban_peer(peer_index, BAD_MESSAGE_BAN_TIME); return; } }; - debug!(target: "sync", "received msg {:?} from {}", msg.payload_type(), peer_index); + debug!("received msg {:?} from {}", msg.payload_type(), peer_index); let start_time = Instant::now(); self.process(nc.as_ref(), peer_index, msg); debug!( - target: "sync", "process message={:?}, peer={}, cost={:?}", msg.payload_type(), peer_index, @@ -540,12 +542,12 @@ impl CKBProtocolHandler for Synchronizer { peer_index: PeerIndex, _version: &str, ) { - info!(target: "sync", "SyncProtocol.connected peer={}", peer_index); + info!("SyncProtocol.connected peer={}", peer_index); self.on_connected(nc.as_ref(), peer_index); } fn disconnected(&mut self, _nc: Arc, peer_index: PeerIndex) { - info!(target: "sync", "SyncProtocol.disconnected peer={}", peer_index); + info!("SyncProtocol.disconnected peer={}", peer_index); if let Some(peer_state) = self.peers.disconnected(peer_index) { // It shouldn't happen // fetch_sub wraps around on overflow, we still check manually @@ -559,7 +561,7 @@ impl CKBProtocolHandler for Synchronizer { fn notify(&mut self, nc: Arc, token: u64) { if !self.peers.state.read().is_empty() { let start_time = Instant::now(); - trace!(target: "sync", "start notify token={}", token); + trace!("start notify token={}", token); match token { SEND_GET_HEADERS_TOKEN => { @@ -575,9 +577,13 @@ impl CKBProtocolHandler for Synchronizer { _ => {} } - trace!(target: "sync", "finished notify token={} cost={:?}", token, start_time.elapsed()); + trace!( + "finished notify token={} cost={:?}", + token, + start_time.elapsed() + ); } else if token == NO_PEER_CHECK_TOKEN { - debug!(target: "sync", "no peers connected"); + debug!("no peers connected"); } } } diff --git a/sync/src/types.rs b/sync/src/types.rs index 034da636c3..98728aee45 100644 --- a/sync/src/types.rs +++ b/sync/src/types.rs @@ -8,6 +8,7 @@ use ckb_core::extras::BlockExt; use ckb_core::extras::EpochExt; use ckb_core::header::{BlockNumber, Header}; use ckb_core::Cycle; +use ckb_logger::{debug, debug_target}; use ckb_network::{CKBProtocolContext, PeerIndex}; use ckb_protocol::SyncMessage; use ckb_shared::chain_state::ChainState; @@ -19,7 +20,6 @@ use ckb_util::{Mutex, MutexGuard}; use faketime::unix_time_as_millis; use flatbuffers::FlatBufferBuilder; use fnv::{FnvHashMap, FnvHashSet}; -use log::debug; use lru_cache::LruCache; use numext_fixed_hash::H256; use numext_fixed_uint::U256; @@ -144,16 +144,28 @@ impl PeerState { last_ask_timeout: Option, ) -> Option { if self.tx_ask_for_map.len() > MAX_ASK_MAP_SIZE { - debug!(target: "relay", "this peer tx_ask_for_map is full, ignore {:#x}", tx_hash); + debug_target!( + crate::LOG_TARGET_RELAY, + "this peer tx_ask_for_map is full, ignore {:#x}", + tx_hash + ); return None; } if self.tx_ask_for_set.len() > MAX_ASK_SET_SIZE { - debug!(target: "relay", "this peer tx_ask_for_set is full, ignore {:#x}", tx_hash); + debug_target!( + crate::LOG_TARGET_RELAY, + "this peer tx_ask_for_set is full, ignore {:#x}", + tx_hash + ); return None; } // This peer already register asked for this tx if self.tx_ask_for_set.contains(&tx_hash) { - debug!(target: "relay", "this peer already register ask tx({:#x})", tx_hash); + debug_target!( + crate::LOG_TARGET_RELAY, + "this peer already register ask tx({:#x})", + tx_hash + ); return None; } @@ -806,18 +818,14 @@ impl SyncSharedState { { if Instant::now() < *last_time + GET_HEADERS_TIMEOUT { debug!( - target: "sync", "last send get headers from {} less than {:?} ago, ignore it", - peer, - GET_HEADERS_TIMEOUT, + peer, GET_HEADERS_TIMEOUT, ); return; } else { debug!( - target: "sync", "Can not get headers from {} in {:?}, retry", - peer, - GET_HEADERS_TIMEOUT, + peer, GET_HEADERS_TIMEOUT, ); } } @@ -825,7 +833,11 @@ impl SyncSharedState { .write() .insert((peer, header.hash().to_owned()), Instant::now()); - debug!(target: "sync", "send_getheaders_to_peer peer={}, hash={:x}", peer, header.hash()); + debug!( + "send_getheaders_to_peer peer={}, hash={:x}", + peer, + header.hash() + ); let locator_hash = self.get_locator(header); let fbb = &mut FlatBufferBuilder::new(); let message = SyncMessage::build_get_headers(fbb, &locator_hash); From dfc944a1ce7be98285cd34a45772e671f1434a6c Mon Sep 17 00:00:00 2001 From: Boyu Yang Date: Fri, 31 May 2019 14:20:00 +0800 Subject: [PATCH 9/9] chore: update the log filter template in configuration --- resource/ckb-miner.toml | 2 +- resource/ckb.toml | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/resource/ckb-miner.toml b/resource/ckb-miner.toml index 027420c8a5..85dd171c17 100644 --- a/resource/ckb-miner.toml +++ b/resource/ckb-miner.toml @@ -16,7 +16,7 @@ spec = "specs/dev.toml" # {{ [logger] filter = "info" # {{ -# integration => filter = "info,network=trace,sync=debug,relay=debug" +# integration => filter = "info,ckb-network=trace,ckb-sync=debug,ckb-relay=debug" # }} color = true log_to_file = true # {{ diff --git a/resource/ckb.toml b/resource/ckb.toml index eacdaa36a5..319105028a 100644 --- a/resource/ckb.toml +++ b/resource/ckb.toml @@ -16,7 +16,7 @@ spec = "specs/dev.toml" # {{ [logger] filter = "info" # {{ -# integration => filter = "info,network=trace,rpc-server=debug,sync=debug,relay=debug,tx_pool=debug" +# integration => filter = "info,ckb-network=trace,ckb-rpc=debug,ckb-sync=debug,ckb-relay=debug,ckb-tx-pool=debug" # }} color = true log_to_file = true # {{