diff --git a/Cargo.lock b/Cargo.lock index 681a65fccd924..ed6481ab6f763 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6389,7 +6389,6 @@ dependencies = [ "fdlimit", "futures 0.3.8", "hex", - "lazy_static", "libp2p", "log", "names", @@ -7139,11 +7138,13 @@ dependencies = [ "parity-scale-codec", "parking_lot 0.10.2", "sc-block-builder", + "sc-cli", "sc-client-api", "sc-executor", "sc-keystore", "sc-network", "sc-rpc-api", + "sc-tracing", "sc-transaction-pool", "serde_json", "sp-api", @@ -7381,9 +7382,13 @@ dependencies = [ name = "sc-tracing" version = "2.0.0" dependencies = [ + "ansi_term 0.12.1", "erased-serde", + "lazy_static", "log", + "once_cell", "parking_lot 0.10.2", + "regex", "rustc-hash", "sc-telemetry", "serde", @@ -7392,6 +7397,7 @@ dependencies = [ "sp-tracing", "tracing", "tracing-core", + "tracing-log", "tracing-subscriber", ] diff --git a/client/cli/Cargo.toml b/client/cli/Cargo.toml index 45312202e861b..034a778f41edc 100644 --- a/client/cli/Cargo.toml +++ b/client/cli/Cargo.toml @@ -16,8 +16,6 @@ targets = ["x86_64-unknown-linux-gnu"] log = "0.4.11" atty = "0.2.13" regex = "1.4.2" -lazy_static = "1.4.0" -ansi_term = "0.12.1" tokio = { version = "0.2.21", features = [ "signal", "rt-core", "rt-threaded", "blocking" ] } futures = "0.3.4" fdlimit = "0.2.1" @@ -47,7 +45,7 @@ chrono = "0.4.10" serde = "1.0.111" tracing = "0.1.22" tracing-log = "0.1.1" -tracing-subscriber = "0.2.10" +tracing-subscriber = "0.2.15" sc-cli-proc-macro = { version = "2.0.0", path = "./proc-macro" } thiserror = "1.0.21" @@ -56,6 +54,7 @@ rpassword = "5.0.0" [dev-dependencies] tempfile = "3.1.0" +ansi_term = "0.12.1" [features] wasmtime = [ diff --git a/client/cli/src/config.rs b/client/cli/src/config.rs index ab7a335c1ce64..e4411e49408e5 100644 --- a/client/cli/src/config.rs +++ b/client/cli/src/config.rs @@ -408,22 +408,18 @@ pub trait CliConfiguration: Sized { /// Get the tracing targets from the current object (if any) /// - /// By default this is retrieved from `ImportParams` if it is available. Otherwise its + /// By default this is retrieved from [`SharedParams`] if it is available. Otherwise its /// `None`. fn tracing_targets(&self) -> Result> { - Ok(self.import_params() - .map(|x| x.tracing_targets()) - .unwrap_or_else(|| Default::default())) + Ok(self.shared_params().tracing_targets()) } /// Get the TracingReceiver value from the current object /// - /// By default this is retrieved from `ImportParams` if it is available. Otherwise its + /// By default this is retrieved from [`SharedParams`] if it is available. Otherwise its /// `TracingReceiver::default()`. fn tracing_receiver(&self) -> Result { - Ok(self.import_params() - .map(|x| x.tracing_receiver()) - .unwrap_or_default()) + Ok(self.shared_params().tracing_receiver()) } /// Get the node key from the current object @@ -519,6 +515,7 @@ pub trait CliConfiguration: Sized { dev_key_seed: self.dev_key_seed(is_dev)?, tracing_targets: self.tracing_targets()?, tracing_receiver: self.tracing_receiver()?, + disable_log_reloading: self.is_log_filter_reloading_disabled()?, chain_spec, max_runtime_instances, announce_block: self.announce_block()?, @@ -538,6 +535,11 @@ pub trait CliConfiguration: Sized { Ok(self.shared_params().log_filters().join(",")) } + /// Is log reloading disabled (enabled by default) + fn is_log_filter_reloading_disabled(&self) -> Result { + Ok(self.shared_params().is_log_filter_reloading_disabled()) + } + /// Initialize substrate. This must be done only once per process. /// /// This method: @@ -549,12 +551,16 @@ pub trait CliConfiguration: Sized { let logger_pattern = self.log_filters()?; let tracing_receiver = self.tracing_receiver()?; let tracing_targets = self.tracing_targets()?; + let disable_log_reloading = self.is_log_filter_reloading_disabled()?; sp_panic_handler::set(&C::support_url(), &C::impl_version()); - if let Err(e) = init_logger(&logger_pattern, tracing_receiver, tracing_targets) { - log::warn!("💬 Problem initializing global logging framework: {:}", e) - } + init_logger( + &logger_pattern, + tracing_receiver, + tracing_targets, + disable_log_reloading, + )?; if let Some(new_limit) = fdlimit::raise_fd_limit() { if new_limit < RECOMMENDED_OPEN_FILE_DESCRIPTOR_LIMIT { diff --git a/client/cli/src/lib.rs b/client/cli/src/lib.rs index b543f80a9d3b3..80882924bd3ad 100644 --- a/client/cli/src/lib.rs +++ b/client/cli/src/lib.rs @@ -27,7 +27,6 @@ pub mod arg_enums; mod commands; mod config; mod error; -mod logging; mod params; mod runner; @@ -48,8 +47,13 @@ use structopt::{ StructOpt, }; use tracing_subscriber::{ - filter::Directive, fmt::time::ChronoLocal, layer::SubscriberExt, FmtSubscriber, Layer, + fmt::time::ChronoLocal, + EnvFilter, + FmtSubscriber, + Layer, + layer::SubscriberExt, }; +pub use sc_tracing::logging; pub use logging::PREFIX_LOG_SPAN; #[doc(hidden)] @@ -243,12 +247,16 @@ pub fn init_logger( pattern: &str, tracing_receiver: sc_tracing::TracingReceiver, profiling_targets: Option, + disable_log_reloading: bool, ) -> std::result::Result<(), String> { - fn parse_directives(dirs: impl AsRef) -> Vec { - dirs.as_ref() - .split(',') - .filter_map(|s| s.parse().ok()) - .collect() + use sc_tracing::parse_default_directive; + + // Accept all valid directives and print invalid ones + fn parse_user_directives(mut env_filter: EnvFilter, dirs: &str) -> std::result::Result { + for dir in dirs.split(',') { + env_filter = env_filter.add_directive(parse_default_directive(&dir)?); + } + Ok(env_filter) } if let Err(e) = tracing_log::LogTracer::init() { @@ -257,33 +265,35 @@ pub fn init_logger( )) } - let mut env_filter = tracing_subscriber::EnvFilter::default() + // Initialize filter - ensure to use `parse_default_directive` for any defaults to persist + // after log filter reloading by RPC + let mut env_filter = EnvFilter::default() + // Enable info + .add_directive(parse_default_directive("info") + .expect("provided directive is valid")) // Disable info logging by default for some modules. - .add_directive("ws=off".parse().expect("provided directive is valid")) - .add_directive("yamux=off".parse().expect("provided directive is valid")) - .add_directive("cranelift_codegen=off".parse().expect("provided directive is valid")) + .add_directive(parse_default_directive("ws=off") + .expect("provided directive is valid")) + .add_directive(parse_default_directive("yamux=off") + .expect("provided directive is valid")) + .add_directive(parse_default_directive("cranelift_codegen=off") + .expect("provided directive is valid")) // Set warn logging by default for some modules. - .add_directive("cranelift_wasm=warn".parse().expect("provided directive is valid")) - .add_directive("hyper=warn".parse().expect("provided directive is valid")) - // Enable info for others. - .add_directive(tracing_subscriber::filter::LevelFilter::INFO.into()); + .add_directive(parse_default_directive("cranelift_wasm=warn") + .expect("provided directive is valid")) + .add_directive(parse_default_directive("hyper=warn") + .expect("provided directive is valid")); if let Ok(lvl) = std::env::var("RUST_LOG") { if lvl != "" { - // We're not sure if log or tracing is available at this moment, so silently ignore the - // parse error. - for directive in parse_directives(lvl) { - env_filter = env_filter.add_directive(directive); - } + env_filter = parse_user_directives(env_filter, &lvl)?; } } if pattern != "" { // We're not sure if log or tracing is available at this moment, so silently ignore the // parse error. - for directive in parse_directives(pattern) { - env_filter = env_filter.add_directive(directive); - } + env_filter = parse_user_directives(env_filter, pattern)?; } // If we're only logging `INFO` entries then we'll use a simplified logging format. @@ -293,19 +303,16 @@ pub fn init_logger( }; // Always log the special target `sc_tracing`, overrides global level. + // Required because profiling traces are emitted via `sc_tracing` // NOTE: this must be done after we check the `max_level_hint` otherwise // it is always raised to `TRACE`. env_filter = env_filter.add_directive( - "sc_tracing=trace" - .parse() - .expect("provided directive is valid"), + parse_default_directive("sc_tracing=trace").expect("provided directive is valid") ); // Make sure to include profiling targets in the filter if let Some(profiling_targets) = profiling_targets.clone() { - for directive in parse_directives(profiling_targets) { - env_filter = env_filter.add_directive(directive); - } + env_filter = parse_user_directives(env_filter, &profiling_targets)?; } let enable_color = atty::is(atty::Stream::Stderr); @@ -315,22 +322,42 @@ pub fn init_logger( "%Y-%m-%d %H:%M:%S%.3f".to_string() }); - let subscriber = FmtSubscriber::builder() + let subscriber_builder = FmtSubscriber::builder() .with_env_filter(env_filter) - .with_writer(std::io::stderr) + .with_writer(std::io::stderr as _) .event_format(logging::EventFormat { timer, + enable_color, display_target: !simple, display_level: !simple, display_thread_name: !simple, - enable_color, - }) - .finish() - .with(logging::NodeNameLayer); + }); + if disable_log_reloading { + let subscriber = subscriber_builder + .finish() + .with(logging::NodeNameLayer); + initialize_tracing(subscriber, tracing_receiver, profiling_targets) + } else { + let subscriber_builder = subscriber_builder.with_filter_reloading(); + let handle = subscriber_builder.reload_handle(); + sc_tracing::set_reload_handle(handle); + let subscriber = subscriber_builder + .finish() + .with(logging::NodeNameLayer); + initialize_tracing(subscriber, tracing_receiver, profiling_targets) + } +} +fn initialize_tracing( + subscriber: S, + tracing_receiver: sc_tracing::TracingReceiver, + profiling_targets: Option, +) -> std::result::Result<(), String> +where + S: tracing::Subscriber + Send + Sync + 'static, +{ if let Some(profiling_targets) = profiling_targets { let profiling = sc_tracing::ProfilingLayer::new(tracing_receiver, &profiling_targets); - if let Err(e) = tracing::subscriber::set_global_default(subscriber.with(profiling)) { return Err(format!( "Registering Substrate tracing subscriber failed: {:}!", e @@ -339,7 +366,7 @@ pub fn init_logger( } else { if let Err(e) = tracing::subscriber::set_global_default(subscriber) { return Err(format!( - "Registering Substrate tracing subscriber failed: {:}!", e + "Registering Substrate tracing subscriber failed: {:}!", e )) } } @@ -356,7 +383,7 @@ mod tests { #[test] fn test_logger_filters() { let test_pattern = "afg=debug,sync=trace,client=warn,telemetry,something-with-dash=error"; - init_logger(&test_pattern, Default::default(), Default::default()).unwrap(); + init_logger(&test_pattern, Default::default(), Default::default(), false).unwrap(); tracing::dispatcher::get_default(|dispatcher| { let test_filter = |target, level| { @@ -415,7 +442,7 @@ mod tests { fn log_something_with_dash_target_name() { if env::var("ENABLE_LOGGING").is_ok() { let test_pattern = "test-target=info"; - init_logger(&test_pattern, Default::default(), Default::default()).unwrap(); + init_logger(&test_pattern, Default::default(), Default::default(), false).unwrap(); log::info!(target: "test-target", "{}", EXPECTED_LOG_MESSAGE); } @@ -450,7 +477,8 @@ mod tests { #[test] fn prefix_in_log_lines_entrypoint() { if env::var("ENABLE_LOGGING").is_ok() { - init_logger("", Default::default(), Default::default()).unwrap(); + let test_pattern = "test-target=info"; + init_logger(&test_pattern, Default::default(), Default::default(), false).unwrap(); prefix_in_log_lines_process(); } } @@ -466,7 +494,7 @@ mod tests { #[test] fn do_not_write_with_colors_on_tty_entrypoint() { if env::var("ENABLE_LOGGING").is_ok() { - init_logger("", Default::default(), Default::default()).unwrap(); + init_logger("", Default::default(), Default::default(), false).unwrap(); log::info!("{}", ansi_term::Colour::Yellow.paint(EXPECTED_LOG_MESSAGE)); } } diff --git a/client/cli/src/params/import_params.rs b/client/cli/src/params/import_params.rs index 1efd4383432fb..376a72b8421f5 100644 --- a/client/cli/src/params/import_params.rs +++ b/client/cli/src/params/import_params.rs @@ -17,7 +17,7 @@ // along with this program. If not, see . use crate::arg_enums::{ - ExecutionStrategy, TracingReceiver, WasmExecutionMethod, DEFAULT_EXECUTION_BLOCK_CONSTRUCTION, + ExecutionStrategy, WasmExecutionMethod, DEFAULT_EXECUTION_BLOCK_CONSTRUCTION, DEFAULT_EXECUTION_IMPORT_BLOCK, DEFAULT_EXECUTION_IMPORT_BLOCK_VALIDATOR, DEFAULT_EXECUTION_OFFCHAIN_WORKER, DEFAULT_EXECUTION_OTHER, DEFAULT_EXECUTION_SYNCING, }; @@ -73,32 +73,9 @@ pub struct ImportParams { default_value = "67108864" )] pub state_cache_size: usize, - - /// Comma separated list of targets for tracing. - #[structopt(long = "tracing-targets", value_name = "TARGETS")] - pub tracing_targets: Option, - - /// Receiver to process tracing messages. - #[structopt( - long = "tracing-receiver", - value_name = "RECEIVER", - possible_values = &TracingReceiver::variants(), - case_insensitive = true, - default_value = "Log" - )] - pub tracing_receiver: TracingReceiver, } impl ImportParams { - /// Receiver to process tracing messages. - pub fn tracing_receiver(&self) -> sc_service::TracingReceiver { - self.tracing_receiver.clone().into() - } - - /// Comma separated list of targets for tracing. - pub fn tracing_targets(&self) -> Option { - self.tracing_targets.clone() - } /// Specify the state cache size. pub fn state_cache_size(&self) -> usize { diff --git a/client/cli/src/params/shared_params.rs b/client/cli/src/params/shared_params.rs index 3276e5b7c4ba0..52b1488ea9ccd 100644 --- a/client/cli/src/params/shared_params.rs +++ b/client/cli/src/params/shared_params.rs @@ -19,6 +19,7 @@ use sc_service::config::BasePath; use std::path::PathBuf; use structopt::StructOpt; +use crate::arg_enums::TracingReceiver; /// Shared parameters used by all `CoreParams`. #[derive(Debug, StructOpt)] @@ -44,6 +45,28 @@ pub struct SharedParams { /// By default, all targets log `info`. The global log level can be set with -l. #[structopt(short = "l", long, value_name = "LOG_PATTERN")] pub log: Vec, + + /// Disable feature to dynamically update and reload the log filter. + /// + /// By default this feature is enabled, however it leads to a small performance decrease. + /// The `system_addLogFilter` and `system_resetLogFilter` RPCs will have no effect with this + /// option set. + #[structopt(long = "disable-log-reloading")] + pub disable_log_reloading: bool, + + /// Sets a custom profiling filter. Syntax is the same as for logging: = + #[structopt(long = "tracing-targets", value_name = "TARGETS")] + pub tracing_targets: Option, + + /// Receiver to process tracing messages. + #[structopt( + long = "tracing-receiver", + value_name = "RECEIVER", + possible_values = &TracingReceiver::variants(), + case_insensitive = true, + default_value = "Log" + )] + pub tracing_receiver: TracingReceiver, } impl SharedParams { @@ -75,4 +98,19 @@ impl SharedParams { pub fn log_filters(&self) -> &[String] { &self.log } + + /// Is log reloading disabled + pub fn is_log_filter_reloading_disabled(&self) -> bool { + self.disable_log_reloading + } + + /// Receiver to process tracing messages. + pub fn tracing_receiver(&self) -> sc_service::TracingReceiver { + self.tracing_receiver.clone().into() + } + + /// Comma separated list of targets for tracing. + pub fn tracing_targets(&self) -> Option { + self.tracing_targets.clone() + } } diff --git a/client/executor/Cargo.toml b/client/executor/Cargo.toml index 803a49d1deaaf..c5ce4b86e12f5 100644 --- a/client/executor/Cargo.toml +++ b/client/executor/Cargo.toml @@ -49,7 +49,7 @@ sp-runtime = { version = "2.0.0", path = "../../primitives/runtime" } sp-tracing = { version = "2.0.0", path = "../../primitives/tracing" } sc-tracing = { version = "2.0.0", path = "../tracing" } tracing = "0.1.22" -tracing-subscriber = "0.2.10" +tracing-subscriber = "0.2.15" [features] default = [ "std" ] diff --git a/client/rpc-api/src/system/mod.rs b/client/rpc-api/src/system/mod.rs index fbeec23ea5085..f05f1fada901e 100644 --- a/client/rpc-api/src/system/mod.rs +++ b/client/rpc-api/src/system/mod.rs @@ -108,4 +108,18 @@ pub trait SystemApi { /// known block. #[rpc(name = "system_syncState", returns = "SyncState")] fn system_sync_state(&self) -> Receiver>; + + /// Adds the supplied directives to the current log filter + /// + /// The syntax is identical to the CLI `=`: + /// + /// `sync=debug,state=trace` + #[rpc(name = "system_addLogFilter", returns = "()")] + fn system_add_log_filter(&self, directives: String) + -> Result<(), jsonrpc_core::Error>; + + /// Resets the log filter to Substrate defaults + #[rpc(name = "system_resetLogFilter", returns = "()")] + fn system_reset_log_filter(&self) + -> Result<(), jsonrpc_core::Error>; } diff --git a/client/rpc/Cargo.toml b/client/rpc/Cargo.toml index 0af880f4330bf..e68ac6e4e918f 100644 --- a/client/rpc/Cargo.toml +++ b/client/rpc/Cargo.toml @@ -37,6 +37,7 @@ sc-block-builder = { version = "0.8.0", path = "../../client/block-builder" } sc-keystore = { version = "2.0.0", path = "../keystore" } sp-transaction-pool = { version = "2.0.0", path = "../../primitives/transaction-pool" } sp-blockchain = { version = "2.0.0", path = "../../primitives/blockchain" } +sc-tracing = { version = "2.0.0", path = "../../client/tracing" } hash-db = { version = "0.15.2", default-features = false } parking_lot = "0.10.0" lazy_static = { version = "1.4.0", optional = true } @@ -50,6 +51,7 @@ sp-io = { version = "2.0.0", path = "../../primitives/io" } substrate-test-runtime-client = { version = "2.0.0", path = "../../test-utils/runtime/client" } tokio = "0.1.22" sc-transaction-pool = { version = "2.0.0", path = "../transaction-pool" } +sc-cli = { version = "0.8.0", path = "../cli" } [features] test-helpers = ["lazy_static"] diff --git a/client/rpc/src/system/mod.rs b/client/rpc/src/system/mod.rs index 17fb6b77a5710..f1ebf5f702a27 100644 --- a/client/rpc/src/system/mod.rs +++ b/client/rpc/src/system/mod.rs @@ -197,4 +197,15 @@ impl SystemApi::Number> for Sy let _ = self.send_back.unbounded_send(Request::SyncState(tx)); Receiver(Compat::new(rx)) } + + fn system_add_log_filter(&self, directives: String) -> std::result::Result<(), rpc::Error> { + self.deny_unsafe.check_if_safe()?; + sc_tracing::add_directives(&directives); + sc_tracing::reload_filter().map_err(|_e| rpc::Error::internal_error()) + } + + fn system_reset_log_filter(&self)-> std::result::Result<(), rpc::Error> { + self.deny_unsafe.check_if_safe()?; + sc_tracing::reset_log_filter().map_err(|_e| rpc::Error::internal_error()) + } } diff --git a/client/rpc/src/system/tests.rs b/client/rpc/src/system/tests.rs index 61f1940dc2010..fa3574e9dae02 100644 --- a/client/rpc/src/system/tests.rs +++ b/client/rpc/src/system/tests.rs @@ -24,7 +24,10 @@ use substrate_test_runtime_client::runtime::Block; use assert_matches::assert_matches; use futures::prelude::*; use sp_utils::mpsc::tracing_unbounded; -use std::thread; +use std::{ + process::{Stdio, Command}, env, io::{BufReader, BufRead, Write}, + sync::{Arc, Mutex}, thread, time::Duration +}; struct Status { pub peers: usize, @@ -333,3 +336,81 @@ fn system_network_remove_reserved() { assert_eq!(runtime.block_on(good_fut), Ok(())); assert!(runtime.block_on(bad_fut).is_err()); } + +#[test] +fn test_add_reset_log_filter() { + const EXPECTED_BEFORE_ADD: &'static str = "EXPECTED_BEFORE_ADD"; + const EXPECTED_AFTER_ADD: &'static str = "EXPECTED_AFTER_ADD"; + + // Enter log generation / filter reload + if std::env::var("TEST_LOG_FILTER").is_ok() { + sc_cli::init_logger("test_before_add=debug", Default::default(), Default::default(), false).unwrap(); + for line in std::io::stdin().lock().lines() { + let line = line.expect("Failed to read bytes"); + if line.contains("add_reload") { + assert!(api(None).system_add_log_filter("test_after_add".to_owned()).is_ok(), "`system_add_log_filter` failed"); + } else if line.contains("reset") { + assert!(api(None).system_reset_log_filter().is_ok(), "`system_reset_log_filter` failed"); + } else if line.contains("exit") { + return; + } + log::debug!(target: "test_before_add", "{}", EXPECTED_BEFORE_ADD); + log::debug!(target: "test_after_add", "{}", EXPECTED_AFTER_ADD); + } + } + + // Call this test again to enter the log generation / filter reload block + let test_executable = env::current_exe().expect("Unable to get current executable!"); + let mut child_process = Command::new(test_executable) + .env("TEST_LOG_FILTER", "1") + .args(&["--nocapture", "test_add_reset_log_filter"]) + .stdin(Stdio::piped()) + .stderr(Stdio::piped()) + .spawn() + .unwrap(); + + let child_stderr = child_process.stderr.take().expect("Could not get child stderr"); + let mut child_out = BufReader::new(child_stderr); + let mut child_in = child_process.stdin.take().expect("Could not get child stdin"); + + let child_out_str = Arc::new(Mutex::new(String::new())); + let shared = child_out_str.clone(); + + let _handle = thread::spawn(move || { + let mut line = String::new(); + while let Ok(_) = child_out.read_line(&mut line) { + shared.lock().unwrap().push_str(&line); + line.clear(); + } + }); + + // Initiate logs loop in child process + child_in.write(b"\n").unwrap(); + thread::sleep(Duration::from_millis(100)); + let test1_str = child_out_str.lock().unwrap().clone(); + // Assert that only the first target is present + assert!(test1_str.contains(EXPECTED_BEFORE_ADD)); + assert!(!test1_str.contains(EXPECTED_AFTER_ADD)); + child_out_str.lock().unwrap().clear(); + + // Initiate add directive & reload in child process + child_in.write(b"add_reload\n").unwrap(); + thread::sleep(Duration::from_millis(100)); + let test2_str = child_out_str.lock().unwrap().clone(); + // Assert that both targets are now present + assert!(test2_str.contains(EXPECTED_BEFORE_ADD)); + assert!(test2_str.contains(EXPECTED_AFTER_ADD)); + child_out_str.lock().unwrap().clear(); + + // Initiate logs filter reset in child process + child_in.write(b"reset\n").unwrap(); + thread::sleep(Duration::from_millis(100)); + let test3_str = child_out_str.lock().unwrap().clone(); + // Assert that only the first target is present as it was initially + assert!(test3_str.contains(EXPECTED_BEFORE_ADD)); + assert!(!test3_str.contains(EXPECTED_AFTER_ADD)); + + // Return from child process + child_in.write(b"exit\n").unwrap(); + assert!(child_process.wait().expect("Error waiting for child process").success()); +} diff --git a/client/service/src/config.rs b/client/service/src/config.rs index 0caf05b2485db..20a4995bbc75c 100644 --- a/client/service/src/config.rs +++ b/client/service/src/config.rs @@ -103,6 +103,8 @@ pub struct Configuration { pub dev_key_seed: Option, /// Tracing targets pub tracing_targets: Option, + /// Is log filter reloading disabled + pub disable_log_reloading: bool, /// Tracing receiver pub tracing_receiver: sc_tracing::TracingReceiver, /// The size of the instances cache. diff --git a/client/service/test/src/lib.rs b/client/service/test/src/lib.rs index 28930473f0a0a..cfcf7e9ab38d9 100644 --- a/client/service/test/src/lib.rs +++ b/client/service/test/src/lib.rs @@ -274,6 +274,7 @@ fn node_config, + W = fn() -> std::io::Stderr +> = layer::Layered, Registry>; + +// Handle to reload the tracing log filter +static FILTER_RELOAD_HANDLE: OnceCell> = OnceCell::new(); +// Directives that are defaulted to when resetting the log filter +static DEFAULT_DIRECTIVES: OnceCell>> = OnceCell::new(); +// Current state of log filter +static CURRENT_DIRECTIVES: OnceCell>> = OnceCell::new(); + +/// Initialize FILTER_RELOAD_HANDLE, only possible once +pub fn set_reload_handle(handle: Handle) { + let _ = FILTER_RELOAD_HANDLE.set(handle); +} + +/// Add log filter directive(s) to the defaults +/// +/// The syntax is identical to the CLI `=`: +/// +/// `sync=debug,state=trace` +pub fn add_default_directives(directives: &str) { + DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); + add_directives(directives); +} + +/// Add directives to current directives +pub fn add_directives(directives: &str) { + CURRENT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().push(directives.to_owned()); +} + +/// Reload the logging filter with the supplied directives added to the existing directives +pub fn reload_filter() -> Result<(), String> { + let mut env_filter = EnvFilter::default(); + if let Some(current_directives) = CURRENT_DIRECTIVES.get() { + // Use join and then split in case any directives added together + for directive in current_directives.lock().join(",").split(',').map(|d| d.parse()) { + match directive { + Ok(dir) => env_filter = env_filter.add_directive(dir), + Err(invalid_directive) => { + log::warn!( + target: "tracing", + "Unable to parse directive while setting log filter: {:?}", + invalid_directive, + ); + } + } + } + } + env_filter = env_filter.add_directive( + "sc_tracing=trace" + .parse() + .expect("provided directive is valid"), + ); + log::debug!(target: "tracing", "Reloading log filter with: {}", env_filter); + FILTER_RELOAD_HANDLE.get() + .ok_or("No reload handle present".to_string())? + .reload(env_filter) + .map_err(|e| format!("{}", e)) +} + +/// Resets the log filter back to the original state when the node was started. +/// +/// Includes substrate defaults and CLI supplied directives. +pub fn reset_log_filter() -> Result<(), String> { + *CURRENT_DIRECTIVES + .get_or_init(|| Mutex::new(Vec::new())).lock() = + DEFAULT_DIRECTIVES.get_or_init(|| Mutex::new(Vec::new())).lock().clone(); + reload_filter() +} + +/// Parse `Directive` and add to default directives if successful. +/// +/// Ensures the supplied directive will be restored when resetting the log filter. +pub fn parse_default_directive(directive: &str) -> Result { + let dir = directive + .parse() + .map_err(|_| format!("Unable to parse directive: {}", directive))?; + add_default_directives(directive); + Ok(dir) +} + /// Responsible for assigning ids to new spans, which are not re-used. pub struct ProfilingLayer { targets: Vec<(String, Level)>, @@ -231,15 +330,13 @@ impl ProfilingLayer { /// either with a level, eg: "pallet=trace" /// or without: "pallet" in which case the level defaults to `trace`. /// wasm_tracing indicates whether to enable wasm traces - pub fn new_with_handler(trace_handler: Box, targets: &str) - -> Self - { + pub fn new_with_handler(trace_handler: Box, targets: &str) -> Self { let targets: Vec<_> = targets.split(',').map(|s| parse_target(s)).collect(); Self { targets, trace_handler, span_data: Mutex::new(FxHashMap::default()), - current_span: Default::default() + current_span: Default::default(), } } @@ -461,7 +558,7 @@ mod tests { }; let layer = ProfilingLayer::new_with_handler( Box::new(handler), - "test_target" + "test_target", ); let subscriber = tracing_subscriber::fmt().finish().with(layer); (subscriber, spans, events) diff --git a/client/cli/src/logging.rs b/client/tracing/src/logging.rs similarity index 97% rename from client/cli/src/logging.rs rename to client/tracing/src/logging.rs index ffb4c3dfaafa1..370b09f781b4e 100644 --- a/client/cli/src/logging.rs +++ b/client/tracing/src/logging.rs @@ -79,12 +79,12 @@ impl<'a> MaybeColorWriter<'a> { } } -pub(crate) struct EventFormat { - pub(crate) timer: T, - pub(crate) display_target: bool, - pub(crate) display_level: bool, - pub(crate) display_thread_name: bool, - pub(crate) enable_color: bool, +pub struct EventFormat { + pub timer: T, + pub display_target: bool, + pub display_level: bool, + pub display_thread_name: bool, + pub enable_color: bool, } // NOTE: the following code took inspiration from tracing-subscriber @@ -147,7 +147,7 @@ where } } -pub(crate) struct NodeNameLayer; +pub struct NodeNameLayer; impl Layer for NodeNameLayer where diff --git a/primitives/tracing/Cargo.toml b/primitives/tracing/Cargo.toml index ba370f46b9b6a..c6d4d7b4caccd 100644 --- a/primitives/tracing/Cargo.toml +++ b/primitives/tracing/Cargo.toml @@ -23,7 +23,7 @@ codec = { version = "1.3.1", package = "parity-scale-codec", default-features = tracing = { version = "0.1.22", default-features = false } tracing-core = { version = "0.1.17", default-features = false } log = { version = "0.4.8", optional = true } -tracing-subscriber = { version = "0.2.10", optional = true, features = ["tracing-log"] } +tracing-subscriber = { version = "0.2.15", optional = true, features = ["tracing-log"] } [features] default = [ "std" ] diff --git a/utils/browser/src/lib.rs b/utils/browser/src/lib.rs index 95ec7ca19c9a4..bffd9fbedb28e 100644 --- a/utils/browser/src/lib.rs +++ b/utils/browser/src/lib.rs @@ -105,6 +105,7 @@ where informant_output_format: sc_informant::OutputFormat { enable_color: false, }, + disable_log_reloading: false, }; Ok(config)