Fix logging from inside the WASM runtime (#7355)

* Fix logging from inside the WASM runtime

When using `RuntimeLogger` to log something from the runtime, we didn't
set any logging level. So, we actually did not log anything from the
runtime as logging is disabled by default. This pr fixes that by setting
the logging level to `TRACE`. It also adds a test to ensure this does
not break again ;)

* Update frame/support/src/debug.rs

substrate/Cargo.lock

@@ -1659,6 +1659,7 @@ dependencies = [
  "pretty_assertions",
  "serde",
  "smallvec 1.4.1",
+ "sp-api",
  "sp-arithmetic",
  "sp-core",
  "sp-inherents",
@@ -1667,6 +1668,7 @@ dependencies = [
  "sp-state-machine",
  "sp-std",
  "sp-tracing",
+ "substrate-test-runtime-client",
 ]
 
 [[package]]

substrate/frame/support/Cargo.toml

@@ -36,6 +36,8 @@ smallvec = "1.4.1"
 pretty_assertions = "0.6.1"
 frame-system = { version = "2.0.0", path = "../system" }
 parity-util-mem = { version = "0.7.0", features = ["primitive-types"] }
+substrate-test-runtime-client = { version = "2.0.0", path = "../../test-utils/runtime/client" }
+sp-api = { version = "2.0.0", default-features = false, path = "../../primitives/api" }
 
 [features]
 default = ["std"]

substrate/frame/support/src/debug.rs

@@ -170,8 +170,16 @@ impl RuntimeLogger {
 	/// This is a no-op when running natively (`std`).
 	#[cfg(not(feature = "std"))]
 	pub fn init() {
-		static LOGGER: RuntimeLogger = 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);
 	}
 }
 
@@ -198,3 +206,42 @@ impl log::Log for RuntimeLogger {
 
 	fn flush(&self) {}
 }
+
+#[cfg(test)]
+mod tests {
+	use substrate_test_runtime_client::{
+		ExecutionStrategy, TestClientBuilderExt, DefaultTestClientBuilderExt,
+		TestClientBuilder, runtime::TestAPI,
+	};
+	use sp_api::ProvideRuntimeApi;
+	use sp_runtime::generic::BlockId;
+
+	#[test]
+	fn ensure_runtime_logger_works() {
+		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_implementation"])
+			.output()
+			.unwrap();
+
+		let output = dbg!(String::from_utf8(output.stderr).unwrap());
+		assert!(output.contains("Hey I'm runtime"));
+	}
+
+	/// This is no actual test. It will be called by `ensure_runtime_logger_works`
+	/// to check that the runtime can print from the wasm side using the
+	/// `RuntimeLogger`.
+	#[test]
+	fn ensure_runtime_logger_works_implementation() {
+		if std::env::var("RUN_TEST").is_ok() {
+			sp_tracing::try_init_simple();
+
+			let client = TestClientBuilder::new().set_execution_strategy(ExecutionStrategy::AlwaysWasm).build();
+			let runtime_api = client.runtime_api();
+			let block_id = BlockId::Number(0);
+			runtime_api.do_trace_log(&block_id).expect("Logging should not fail");
+		}
+	}
+}

substrate/primitives/tracing/src/lib.rs

@@ -107,7 +107,9 @@ pub use crate::types::{
 /// Ignores any error. Useful for testing.
 #[cfg(feature = "std")]
 pub fn try_init_simple() {
-	let _ = tracing_subscriber::fmt().with_writer(std::io::stderr).try_init();
+	let _ = tracing_subscriber::fmt()
+		.with_env_filter(tracing_subscriber::EnvFilter::from_default_env())
+		.with_writer(std::io::stderr).try_init();
 }
 
 #[cfg(feature = "std")]

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

@@ -340,6 +340,8 @@ cfg_if! {
 				/// Test that ensures that we can call a function that takes multiple
 				/// arguments.
 				fn test_multiple_arguments(data: Vec<u8>, other: Vec<u8>, num: u32);
+				/// Traces log "Hey I'm runtime."
+				fn do_trace_log();
 			}
 		}
 	} else {
@@ -391,6 +393,8 @@ cfg_if! {
 				/// Test that ensures that we can call a function that takes multiple
 				/// arguments.
 				fn test_multiple_arguments(data: Vec<u8>, other: Vec<u8>, num: u32);
+				/// Traces log "Hey I'm runtime."
+				fn do_trace_log();
 			}
 		}
 	}
@@ -698,6 +702,11 @@ cfg_if! {
 					assert_eq!(&data[..], &other[..]);
 					assert_eq!(data.len(), num as usize);
 				}
+
+				fn do_trace_log() {
+					frame_support::debug::RuntimeLogger::init();
+					frame_support::debug::trace!("Hey I'm runtime");
+				}
 			}
 
 			impl sp_consensus_aura::AuraApi<Block, AuraId> for Runtime {
@@ -944,6 +953,11 @@ cfg_if! {
 					assert_eq!(&data[..], &other[..]);
 					assert_eq!(data.len(), num as usize);
 				}
+
+				fn do_trace_log() {
+					frame_support::debug::RuntimeLogger::init();
+					frame_support::debug::trace!("Hey I'm runtime");
+				}
 			}
 
 			impl sp_consensus_aura::AuraApi<Block, AuraId> for Runtime {