Set max log level when changing the log directives via RPC (#8721)

Before this pr changing the log directives would not change the max log
level. This means that if the node was started with `info` logging and
some `trace` logging was enabled, this `trace` wouldn't be logged. To
fix this we also need to update the max log level. This max log level is
used by the log macros to early return.

substrate/client/rpc/src/system/tests.rs

@@ -24,10 +24,7 @@ use substrate_test_runtime_client::runtime::Block;
 use assert_matches::assert_matches;
 use futures::prelude::*;
 use sp_utils::mpsc::tracing_unbounded;
-use std::{
-	process::{Stdio, Command}, env, io::{BufReader, BufRead, Write},
-	sync::{Arc, Mutex}, thread, time::Duration
-};
+use std::{process::{Stdio, Command}, env, io::{BufReader, BufRead, Write}, thread};
 
 struct Status {
 	pub peers: usize,
@@ -352,6 +349,7 @@ fn system_network_reserved_peers() {
 fn test_add_reset_log_filter() {
 	const EXPECTED_BEFORE_ADD: &'static str = "EXPECTED_BEFORE_ADD";
 	const EXPECTED_AFTER_ADD: &'static str = "EXPECTED_AFTER_ADD";
+	const EXPECTED_WITH_TRACE: &'static str = "EXPECTED_WITH_TRACE";
 
 	// Enter log generation / filter reload
 	if std::env::var("TEST_LOG_FILTER").is_ok() {
@@ -359,12 +357,17 @@ fn test_add_reset_log_filter() {
 		for line in std::io::stdin().lock().lines() {
 			let line = line.expect("Failed to read bytes");
 			if line.contains("add_reload") {
-				api(None).system_add_log_filter("test_after_add".into()).expect("`system_add_log_filter` failed");
+				api(None).system_add_log_filter("test_after_add".into())
+					.expect("`system_add_log_filter` failed");
+			} else if line.contains("add_trace") {
+				api(None).system_add_log_filter("test_before_add=trace".into())
+					.expect("`system_add_log_filter` failed");
 			} else if line.contains("reset") {
 				api(None).system_reset_log_filter().expect("`system_reset_log_filter` failed");
 			} else if line.contains("exit") {
 				return;
 			}
+			log::trace!(target: "test_before_add", "{}", EXPECTED_WITH_TRACE);
 			log::debug!(target: "test_before_add", "{}", EXPECTED_BEFORE_ADD);
 			log::debug!(target: "test_after_add", "{}", EXPECTED_AFTER_ADD);
 		}
@@ -384,44 +387,35 @@ fn test_add_reset_log_filter() {
 	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 read_line = || {
 		let mut line = String::new();
-		while let Ok(_) = child_out.read_line(&mut line) {
-			shared.lock().unwrap().push_str(&line);
-			line.clear();
-		}
-	});
+		child_out.read_line(&mut line).expect("Reading a line");
+		line
+	};
 
 	// 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();
+	assert!(read_line().contains(EXPECTED_BEFORE_ADD));
 
 	// 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();
+	assert!(read_line().contains(EXPECTED_BEFORE_ADD));
+	assert!(read_line().contains(EXPECTED_AFTER_ADD));
+
+	// Check that increasing the max log level works
+	child_in.write(b"add_trace\n").unwrap();
+	assert!(read_line().contains(EXPECTED_WITH_TRACE));
+	assert!(read_line().contains(EXPECTED_BEFORE_ADD));
+	assert!(read_line().contains(EXPECTED_AFTER_ADD));
 
 	// 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));
+	assert!(read_line().contains(EXPECTED_BEFORE_ADD));
 
 	// Return from child process
 	child_in.write(b"exit\n").unwrap();
 	assert!(child_process.wait().expect("Error waiting for child process").success());
+
+	// Check for EOF
+	assert_eq!(child_out.read_line(&mut String::new()).unwrap(), 0);
 }

substrate/client/tracing/src/logging/directives.rs

@@ -81,11 +81,12 @@ pub fn reload_filter() -> Result<(), String> {
 			}
 		}
 	}
-	env_filter = env_filter.add_directive(
-		"sc_tracing=trace"
-			.parse()
-			.expect("provided directive is valid"),
-	);
+
+	// Set the max logging level for the `log` macros.
+	let max_level_hint =
+		tracing_subscriber::Layer::<tracing_subscriber::FmtSubscriber>::max_level_hint(&env_filter);
+	log::set_max_level(super::to_log_level_filter(max_level_hint));
+
 	log::debug!(target: "tracing", "Reloading log filter with: {}", env_filter);
 	FILTER_RELOAD_HANDLE
 		.get()

substrate/client/tracing/src/logging/mod.rs

@@ -70,6 +70,20 @@ macro_rules! enable_log_reloading {
 	}};
 }
 
+/// Convert a `Option<LevelFilter>` to a [`log::LevelFilter`].
+///
+/// `None` is interpreted as `Info`.
+fn to_log_level_filter(level_filter: Option<LevelFilter>) -> log::LevelFilter {
+	match level_filter {
+		Some(LevelFilter::INFO) | None => log::LevelFilter::Info,
+		Some(LevelFilter::TRACE) => log::LevelFilter::Trace,
+		Some(LevelFilter::WARN) => log::LevelFilter::Warn,
+		Some(LevelFilter::ERROR) => log::LevelFilter::Error,
+		Some(LevelFilter::DEBUG) => log::LevelFilter::Debug,
+		Some(LevelFilter::OFF) => log::LevelFilter::Off,
+	}
+}
+
 /// Common implementation to get the subscriber.
 fn prepare_subscriber<N, E, F, W>(
 	directives: &str,
@@ -134,15 +148,7 @@ where
 	}
 
 	let max_level_hint = Layer::<FmtSubscriber>::max_level_hint(&env_filter);
-
-	let max_level = match max_level_hint {
-		Some(LevelFilter::INFO) | None => log::LevelFilter::Info,
-		Some(LevelFilter::TRACE) => log::LevelFilter::Trace,
-		Some(LevelFilter::WARN) => log::LevelFilter::Warn,
-		Some(LevelFilter::ERROR) => log::LevelFilter::Error,
-		Some(LevelFilter::DEBUG) => log::LevelFilter::Debug,
-		Some(LevelFilter::OFF) => log::LevelFilter::Off,
-	};
+	let max_level = to_log_level_filter(max_level_hint);
 
 	tracing_log::LogTracer::builder()
 		.with_max_level(max_level)