Use host max log level when initializing the RuntimeLogger (#8655)

* Use host max log level when initializing the `RuntimeLogger`

This should fix performance problems introduced by logging under certain
circumstances. Before we always called into the host and the host was
doing the log filtering, now as the correct max log level is set, we
don't call into the host for every log line to check if it should be
logged. However, we would still call into the host to determine if
something should be logged when `something=trace` is given as we don't
forward the log targets that are enabled.

* Finish the pr

substrate/primitives/core/src/lib.rs

@@ -281,7 +281,7 @@ pub trait TypeId {
 
 /// A log level matching the one from `log` crate.
 ///
-/// Used internally by `sp_io::log` method.
+/// Used internally by `sp_io::logging::log` method.
 #[derive(Encode, Decode, PassByEnum, Copy, Clone)]
 pub enum LogLevel {
 	/// `Error` log level.
@@ -334,6 +334,53 @@ impl From<LogLevel> for log::Level {
 	}
 }
 
+/// Log level filter that expresses which log levels should be filtered.
+///
+/// This enum matches the [`log::LogLevelFilter`] enum.
+#[derive(Encode, Decode, PassByEnum, Copy, Clone)]
+pub enum LogLevelFilter {
+	/// `Off` log level filter.
+	Off = 0,
+	/// `Error` log level filter.
+	Error = 1,
+	/// `Warn` log level filter.
+	Warn = 2,
+	/// `Info` log level filter.
+	Info = 3,
+	/// `Debug` log level filter.
+	Debug = 4,
+	/// `Trace` log level filter.
+	Trace = 5,
+}
+
+impl From<LogLevelFilter> for log::LevelFilter {
+	fn from(l: LogLevelFilter) -> Self {
+		use self::LogLevelFilter::*;
+		match l {
+			Off => Self::Off,
+			Error => Self::Error,
+			Warn => Self::Warn,
+			Info => Self::Info,
+			Debug => Self::Debug,
+			Trace => Self::Trace,
+		}
+	}
+}
+
+impl From<log::LevelFilter> for LogLevelFilter {
+	fn from(l: log::LevelFilter) -> Self {
+		use log::LevelFilter::*;
+		match l {
+			Off => Self::Off,
+			Error => Self::Error,
+			Warn => Self::Warn,
+			Info => Self::Info,
+			Debug => Self::Debug,
+			Trace => Self::Trace,
+		}
+	}
+}
+
 /// Encodes the given value into a buffer and returns the pointer and the length as a single `u64`.
 ///
 /// When Substrate calls into Wasm it expects a fixed signature for functions exported

substrate/primitives/io/src/lib.rs

@@ -47,7 +47,7 @@ use sp_core::{
 use sp_keystore::{KeystoreExt, SyncCryptoStore};
 
 use sp_core::{
-	OpaquePeerId, crypto::KeyTypeId, ed25519, sr25519, ecdsa, H256, LogLevel,
+	OpaquePeerId, crypto::KeyTypeId, ed25519, sr25519, ecdsa, H256, LogLevel, LogLevelFilter,
 	offchain::{
 		Timestamp, HttpRequestId, HttpRequestStatus, HttpError, StorageKind, OpaqueNetworkState,
 	},
@@ -1082,6 +1082,11 @@ pub trait Logging {
 			)
 		}
 	}
+
+	/// Returns the max log level used by the host.
+	fn max_level() -> LogLevelFilter {
+		log::max_level().into()
+	}
 }
 
 #[derive(Encode, Decode)]

substrate/primitives/runtime/src/runtime_logger.rs

@@ -40,22 +40,15 @@ impl RuntimeLogger {
 		static LOGGER: RuntimeLogger = RuntimeLogger;
 		let _ = log::set_logger(&LOGGER);
 
-		// Set max level to `TRACE` to ensure we propagate
-		// all log entries to the native side that will do the
-		// final filtering on what should be printed.
-		//
-		// If we don't set any level, logging is disabled
-		// completly.
-		log::set_max_level(log::LevelFilter::Trace);
+		// Use the same max log level as used by the host.
+		log::set_max_level(sp_io::logging::max_level().into());
 	}
 }
 
 impl log::Log for RuntimeLogger {
-	fn enabled(&self, _metadata: &log::Metadata) -> bool {
-		// to avoid calling to host twice, we pass everything
-		// and let the host decide what to print.
-		// If someone is initializing the logger they should
-		// know what they are doing.
+	fn enabled(&self, _: &log::Metadata) -> bool {
+		// The final filtering is done by the host. This is not perfect, as we would still call into
+		// the host for log lines that will be thrown away.
 		true
 	}
 
@@ -81,11 +74,13 @@ mod tests {
 		TestClientBuilder, runtime::TestAPI,
 	};
 	use sp_api::{ProvideRuntimeApi, BlockId};
+	use std::{env, str::FromStr};
 
 	#[test]
-	fn ensure_runtime_logger_works() {
-		if std::env::var("RUN_TEST").is_ok() {
+	fn ensure_runtime_logger_respects_host_max_log_level() {
+		if env::var("RUN_TEST").is_ok() {
 			sp_tracing::try_init_simple();
+			log::set_max_level(log::LevelFilter::from_str(&env::var("RUST_LOG").unwrap()).unwrap());
 
 			let client = TestClientBuilder::new()
 				.set_execution_strategy(ExecutionStrategy::AlwaysWasm).build();
@@ -93,16 +88,18 @@ mod tests {
 			let block_id = BlockId::Number(0);
 			runtime_api.do_trace_log(&block_id).expect("Logging should not fail");
 		} else {
-			let executable = std::env::current_exe().unwrap();
-			let output = std::process::Command::new(executable)
-				.env("RUN_TEST", "1")
-				.env("RUST_LOG", "trace")
-				.args(&["--nocapture", "ensure_runtime_logger_works"])
-				.output()
-				.unwrap();
+			for (level, should_print) in &[("trace", true), ("info", false)] {
+				let executable = std::env::current_exe().unwrap();
+				let output = std::process::Command::new(executable)
+					.env("RUN_TEST", "1")
+					.env("RUST_LOG", level)
+					.args(&["--nocapture", "ensure_runtime_logger_respects_host_max_log_level"])
+					.output()
+					.unwrap();
 
-			let output = dbg!(String::from_utf8(output.stderr).unwrap());
-			assert!(output.contains("Hey I'm runtime"));
+				let output = String::from_utf8(output.stderr).unwrap();
+				assert!(output.contains("Hey I'm runtime") == *should_print);
+			}
 		}
 	}
 }

substrate/test-utils/runtime/src/lib.rs

@@ -1019,7 +1019,7 @@ cfg_if! {
 				}
 
 				fn do_trace_log() {
-					log::error!("Hey I'm runtime: {}", log::STATIC_MAX_LEVEL);
+					log::trace!("Hey I'm runtime: {}", log::STATIC_MAX_LEVEL);
 				}
 			}