RPC to allow setting the log filter (#7474)

* Add filter reload handle

* add RPC, move logging module from cli to tracing

* remove dup fn

* working example

* Update client/rpc-api/src/system/mod.rs

Co-authored-by: Pierre Krieger <[email protected]>

* Prefer "set" to "reload"

* Re-enable the commented out features of the logger

* Remove duplicate code

* cleanup

* unneeded lvar

* Bump to latest patch release

* Add new CLI option to disable log filter reloading,

Move profiling CLI options to SharedParams

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <[email protected]>

* Applied suggestions from reviews

* Fix calls to init_logger()

* Handle errors when parsing logging directives

* Deny `system_setLogFilter` RPC by default

* One more time

* Don't ignore parse errors for log directives set via CLI or RPC

* Improve docs

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <[email protected]>

* Update client/cli/src/config.rs

Co-authored-by: Bastian Köcher <[email protected]>

* fix merge errors

* include default directives with system_setLogFilter RPC,

implement system_rawSetLogFilter RPC to exclude defaults

* docs etc...

* update test

* refactor: rename fn

* Add a test for system_set_log_filter – NOTE: the code should likely change to return an error when bad directives are passed

* Update client/cli/src/lib.rs

Co-authored-by: Bastian Köcher <[email protected]>

* Address review grumbles

* Add doc note on panicking behaviour

* print all invalid directives before panic

* change RPCs to: addLogFilter and resetLogFilter

* make CLI log directives default

* add comments

* restore previous behaviour to panic when hard-coded directives are invalid

* change/refactor directive parsing

* fix line width

* add test for log filter reloading

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <[email protected]>

* finish up suggestions from code review

* improve test

* change expect message

* change fn name

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <[email protected]>

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <[email protected]>

* add docs, remove unused fn

* propagate Err on invalid log directive

* Update tracing-subscriber version

* Improve docs for `disable_log_reloading` CLI param

Co-authored-by: Matt <[email protected]>
Co-authored-by: David <[email protected]>
Co-authored-by: Pierre Krieger <[email protected]>
Co-authored-by: Bastian Köcher <[email protected]>

Author: 4 people

Cargo.lock

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

client/cli/Cargo.toml

@@ -408,22 +408,18 @@ pub trait CliConfiguration<DCV: DefaultConfigurationValues = ()>: 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<Option<String>> {
-		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<TracingReceiver> {
-		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<DCV: DefaultConfigurationValues = ()>: 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<DCV: DefaultConfigurationValues = ()>: Sized {
 		Ok(self.shared_params().log_filters().join(","))
 	}
 
+	/// Is log reloading disabled (enabled by default)
+	fn is_log_filter_reloading_disabled(&self) -> Result<bool> {
+		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<DCV: DefaultConfigurationValues = ()>: 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 {

client/cli/src/config.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<String>,
+	disable_log_reloading: bool,
 ) -> std::result::Result<(), String> {
-	fn parse_directives(dirs: impl AsRef<str>) -> Vec<Directive> {
-		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<EnvFilter, String> {
+		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<S>(
+	subscriber: S,
+	tracing_receiver: sc_tracing::TracingReceiver,
+	profiling_targets: Option<String>,
+) -> 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));
 		}
 	}

client/cli/src/lib.rs

@@ -17,7 +17,7 @@
 // along with this program. If not, see <https://www.gnu.org/licenses/>.
 
 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<String>,
-
-	/// 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<String> {
-		self.tracing_targets.clone()
-	}
 
 	/// Specify the state cache size.
 	pub fn state_cache_size(&self) -> usize {