diff --git a/substrate/client/rpc/src/system/tests.rs b/substrate/client/rpc/src/system/tests.rs index 41d6029ddd..6e22004cd6 100644 --- a/substrate/client/rpc/src/system/tests.rs +++ b/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); } diff --git a/substrate/client/tracing/src/logging/directives.rs b/substrate/client/tracing/src/logging/directives.rs index 39dee2b061..0e6d949a41 100644 --- a/substrate/client/tracing/src/logging/directives.rs +++ b/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::::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() diff --git a/substrate/client/tracing/src/logging/mod.rs b/substrate/client/tracing/src/logging/mod.rs index 1023879e3d..c3cc3e0851 100644 --- a/substrate/client/tracing/src/logging/mod.rs +++ b/substrate/client/tracing/src/logging/mod.rs @@ -70,6 +70,20 @@ macro_rules! enable_log_reloading { }}; } +/// Convert a `Option` to a [`log::LevelFilter`]. +/// +/// `None` is interpreted as `Info`. +fn to_log_level_filter(level_filter: Option) -> 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( directives: &str, @@ -134,15 +148,7 @@ where } let max_level_hint = Layer::::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)