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 <pierre.krieger1708@gmail.com> * 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 <bkchr@users.noreply.github.com> * 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 <bkchr@users.noreply.github.com> * Update client/cli/src/config.rs Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * 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 <bkchr@users.noreply.github.com> * 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 <bkchr@users.noreply.github.com> * 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 <bkchr@users.noreply.github.com> * Apply suggestions from code review Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com> * 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 <mattrutherford@users.noreply.github.com> Co-authored-by: David <dvdplm@gmail.com> Co-authored-by: Pierre Krieger <pierre.krieger1708@gmail.com> Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>
2026-06-12 18:11:10 +00:00 · 2020-12-03 13:17:44 +00:00
parent f717a20446
commit 56c97ce604
18 changed files with 365 additions and 97 deletions
@@ -24,6 +24,8 @@
 //!
 //! Currently we provide `Log` (default), `Telemetry` variants for `Receiver`

+pub mod logging;
+
 use rustc_hash::FxHashMap;
 use std::fmt;
 use std::time::{Duration, Instant};
@@ -37,12 +39,109 @@ use tracing::{
 	span::{Attributes, Id, Record},
 	subscriber::Subscriber,
 };
-use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}};
+use tracing_subscriber::{
+	fmt::time::ChronoLocal,
+	CurrentSpan,
+	EnvFilter,
+	layer::{self, Layer, Context},
+	fmt as tracing_fmt,
+	Registry,
+};

 use sc_telemetry::{telemetry, SUBSTRATE_INFO};
 use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
+use tracing_subscriber::reload::Handle;
+use once_cell::sync::OnceCell;
+use tracing_subscriber::filter::Directive;
+
 const ZERO_DURATION: Duration = Duration::from_nanos(0);

+// The layered Subscriber as built up in `init_logger()`.
+// Used in the reload `Handle`.
+type SCSubscriber<
+	N = tracing_fmt::format::DefaultFields,
+	E = logging::EventFormat<ChronoLocal>,
+	W = fn() -> std::io::Stderr
+> = layer::Layered<tracing_fmt::Layer<Registry, N, E, W>, Registry>;
+
+// Handle to reload the tracing log filter
+static FILTER_RELOAD_HANDLE: OnceCell<Handle<EnvFilter, SCSubscriber>> = OnceCell::new();
+// Directives that are defaulted to when resetting the log filter
+static DEFAULT_DIRECTIVES: OnceCell<Mutex<Vec<String>>> = OnceCell::new();
+// Current state of log filter
+static CURRENT_DIRECTIVES: OnceCell<Mutex<Vec<String>>> = OnceCell::new();
+
+/// Initialize FILTER_RELOAD_HANDLE, only possible once
+pub fn set_reload_handle(handle: Handle<EnvFilter, SCSubscriber>) {
+	let _ = FILTER_RELOAD_HANDLE.set(handle);
+}
+
+/// Add log filter directive(s) to the defaults
+///
+/// The syntax is identical to the CLI `<target>=<level>`:
+///
+/// `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<Directive, String> {
+	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<dyn TraceHandler>, targets: &str)
-		-> Self
-	{
+	pub fn new_with_handler(trace_handler: Box<dyn TraceHandler>, 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)
@@ -0,0 +1,317 @@
+// This file is part of Substrate.
+
+// Copyright (C) 2020 Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: GPL-3.0-or-later WITH Classpath-exception-2.0
+
+// This program is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+
+// This program is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+
+// You should have received a copy of the GNU General Public License
+// along with this program. If not, see <https://www.gnu.org/licenses/>.
+
+use std::fmt::{self, Write};
+use ansi_term::Colour;
+use tracing::{span::Attributes, Event, Id, Level, Subscriber};
+use tracing_log::NormalizeEvent;
+use tracing_subscriber::{
+	fmt::{
+		time::{FormatTime, SystemTime},
+		FmtContext, FormatEvent, FormatFields,
+	},
+	layer::Context,
+	registry::LookupSpan,
+	Layer,
+};
+use regex::Regex;
+
+/// Span name used for the logging prefix. See macro `sc_cli::prefix_logs_with!`
+pub const PREFIX_LOG_SPAN: &str = "substrate-log-prefix";
+
+/// A writer that may write to `inner_writer` with colors.
+///
+/// This is used by [`EventFormat`] to kill colors when `enable_color` is `false`.
+///
+/// It is required to call [`MaybeColorWriter::write`] after all writes are done,
+/// because the content of these writes is buffered and will only be written to the
+/// `inner_writer` at that point.
+struct MaybeColorWriter<'a> {
+	enable_color: bool,
+	buffer: String,
+	inner_writer: &'a mut dyn fmt::Write,
+}
+
+impl<'a> fmt::Write for MaybeColorWriter<'a> {
+	fn write_str(&mut self, buf: &str) -> fmt::Result {
+		self.buffer.push_str(buf);
+		Ok(())
+	}
+}
+
+impl<'a> MaybeColorWriter<'a> {
+	/// Creates a new instance.
+	fn new(enable_color: bool, inner_writer: &'a mut dyn fmt::Write) -> Self {
+		Self {
+			enable_color,
+			inner_writer,
+			buffer: String::new(),
+		}
+	}
+
+	/// Write the buffered content to the `inner_writer`.
+	fn write(&mut self) -> fmt::Result {
+		lazy_static::lazy_static! {
+			static ref RE: Regex = Regex::new("\x1b\\[[^m]+m").expect("Error initializing color regex");
+		}
+
+		if !self.enable_color {
+			let replaced = RE.replace_all(&self.buffer, "");
+			self.inner_writer.write_str(&replaced)
+		} else {
+			self.inner_writer.write_str(&self.buffer)
+		}
+	}
+}
+
+pub struct EventFormat<T = SystemTime> {
+	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
+//
+//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L449
+impl<S, N, T> FormatEvent<S, N> for EventFormat<T>
+where
+	S: Subscriber + for<'a> LookupSpan<'a>,
+	N: for<'a> FormatFields<'a> + 'static,
+	T: FormatTime,
+{
+	fn format_event(
+		&self,
+		ctx: &FmtContext<S, N>,
+		writer: &mut dyn fmt::Write,
+		event: &Event,
+	) -> fmt::Result {
+		let writer = &mut MaybeColorWriter::new(self.enable_color, writer);
+		let normalized_meta = event.normalized_metadata();
+		let meta = normalized_meta.as_ref().unwrap_or_else(|| event.metadata());
+		time::write(&self.timer, writer, self.enable_color)?;
+
+		if self.display_level {
+			let fmt_level = { FmtLevel::new(meta.level(), self.enable_color) };
+			write!(writer, "{} ", fmt_level)?;
+		}
+
+		if self.display_thread_name {
+			let current_thread = std::thread::current();
+			match current_thread.name() {
+				Some(name) => {
+					write!(writer, "{} ", FmtThreadName::new(name))?;
+				}
+				// fall-back to thread id when name is absent and ids are not enabled
+				None => {
+					write!(writer, "{:0>2?} ", current_thread.id())?;
+				}
+			}
+		}
+
+		// Custom code to display node name
+		if let Some(span) = ctx.lookup_current() {
+			let parents = span.parents();
+			for span in std::iter::once(span).chain(parents) {
+				let exts = span.extensions();
+				if let Some(node_name) = exts.get::<NodeName>() {
+					write!(writer, "{}", node_name.as_str())?;
+					break;
+				}
+			}
+		}
+
+		if self.display_target {
+			write!(writer, "{}:", meta.target())?;
+		}
+		ctx.format_fields(writer, event)?;
+		writeln!(writer)?;
+
+		writer.write()
+	}
+}
+
+pub struct NodeNameLayer;
+
+impl<S> Layer<S> for NodeNameLayer
+where
+	S: Subscriber + for<'a> LookupSpan<'a>,
+{
+	fn new_span(&self, attrs: &Attributes<'_>, id: &Id, ctx: Context<'_, S>) {
+		let span = ctx
+			.span(id)
+			.expect("new_span has been called for this span; qed");
+
+		if span.name() != PREFIX_LOG_SPAN {
+			return;
+		}
+
+		let mut extensions = span.extensions_mut();
+
+		if extensions.get_mut::<NodeName>().is_none() {
+			let mut s = String::new();
+			let mut v = NodeNameVisitor(&mut s);
+			attrs.record(&mut v);
+
+			if !s.is_empty() {
+				let fmt_fields = NodeName(s);
+				extensions.insert(fmt_fields);
+			}
+		}
+	}
+}
+
+struct NodeNameVisitor<'a, W: std::fmt::Write>(&'a mut W);
+
+macro_rules! write_node_name {
+	($method:ident, $type:ty, $format:expr) => {
+		fn $method(&mut self, field: &tracing::field::Field, value: $type) {
+			if field.name() == "name" {
+				write!(self.0, $format, value).expect("no way to return the err; qed");
+			}
+		}
+	};
+}
+
+impl<'a, W: std::fmt::Write> tracing::field::Visit for NodeNameVisitor<'a, W> {
+	write_node_name!(record_debug, &dyn std::fmt::Debug, "[{:?}] ");
+	write_node_name!(record_str, &str, "[{}] ");
+	write_node_name!(record_i64, i64, "[{}] ");
+	write_node_name!(record_u64, u64, "[{}] ");
+	write_node_name!(record_bool, bool, "[{}] ");
+}
+
+#[derive(Debug)]
+struct NodeName(String);
+
+impl NodeName {
+	fn as_str(&self) -> &str {
+		self.0.as_str()
+	}
+}
+
+struct FmtLevel<'a> {
+	level: &'a Level,
+	ansi: bool,
+}
+
+impl<'a> FmtLevel<'a> {
+	pub(crate) fn new(level: &'a Level, ansi: bool) -> Self {
+		Self { level, ansi }
+	}
+}
+
+const TRACE_STR: &str = "TRACE";
+const DEBUG_STR: &str = "DEBUG";
+const INFO_STR: &str = " INFO";
+const WARN_STR: &str = " WARN";
+const ERROR_STR: &str = "ERROR";
+
+impl<'a> fmt::Display for FmtLevel<'a> {
+	fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+		if self.ansi {
+			match *self.level {
+				Level::TRACE => write!(f, "{}", Colour::Purple.paint(TRACE_STR)),
+				Level::DEBUG => write!(f, "{}", Colour::Blue.paint(DEBUG_STR)),
+				Level::INFO => write!(f, "{}", Colour::Green.paint(INFO_STR)),
+				Level::WARN => write!(f, "{}", Colour::Yellow.paint(WARN_STR)),
+				Level::ERROR => write!(f, "{}", Colour::Red.paint(ERROR_STR)),
+			}
+		} else {
+			match *self.level {
+				Level::TRACE => f.pad(TRACE_STR),
+				Level::DEBUG => f.pad(DEBUG_STR),
+				Level::INFO => f.pad(INFO_STR),
+				Level::WARN => f.pad(WARN_STR),
+				Level::ERROR => f.pad(ERROR_STR),
+			}
+		}
+	}
+}
+
+struct FmtThreadName<'a> {
+	name: &'a str,
+}
+
+impl<'a> FmtThreadName<'a> {
+	pub(crate) fn new(name: &'a str) -> Self {
+		Self { name }
+	}
+}
+
+// NOTE: the following code has been duplicated from tracing-subscriber
+//
+//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/format/mod.rs#L845
+impl<'a> fmt::Display for FmtThreadName<'a> {
+	fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+		use std::sync::atomic::{
+			AtomicUsize,
+			Ordering::{AcqRel, Acquire, Relaxed},
+		};
+
+		// Track the longest thread name length we've seen so far in an atomic,
+		// so that it can be updated by any thread.
+		static MAX_LEN: AtomicUsize = AtomicUsize::new(0);
+		let len = self.name.len();
+		// Snapshot the current max thread name length.
+		let mut max_len = MAX_LEN.load(Relaxed);
+
+		while len > max_len {
+			// Try to set a new max length, if it is still the value we took a
+			// snapshot of.
+			match MAX_LEN.compare_exchange(max_len, len, AcqRel, Acquire) {
+				// We successfully set the new max value
+				Ok(_) => break,
+				// Another thread set a new max value since we last observed
+				// it! It's possible that the new length is actually longer than
+				// ours, so we'll loop again and check whether our length is
+				// still the longest. If not, we'll just use the newer value.
+				Err(actual) => max_len = actual,
+			}
+		}
+
+		// pad thread name using `max_len`
+		write!(f, "{:>width$}", self.name, width = max_len)
+	}
+}
+
+// NOTE: the following code has been duplicated from tracing-subscriber
+//
+//       https://github.com/tokio-rs/tracing/blob/2f59b32/tracing-subscriber/src/fmt/time/mod.rs#L252
+mod time {
+	use ansi_term::Style;
+	use std::fmt;
+	use tracing_subscriber::fmt::time::FormatTime;
+
+	pub(crate) fn write<T>(timer: T, writer: &mut dyn fmt::Write, with_ansi: bool) -> fmt::Result
+	where
+		T: FormatTime,
+	{
+		if with_ansi {
+			let style = Style::new().dimmed();
+			write!(writer, "{}", style.prefix())?;
+			timer.format_time(writer)?;
+			write!(writer, "{}", style.suffix())?;
+		} else {
+			timer.format_time(writer)?;
+		}
+		writer.write_char(' ')?;
+		Ok(())
+	}
+}