Fix logging from inside the WASM runtime

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"]

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);
 	}
 }
 
@@ -185,6 +193,7 @@ impl log::Log for RuntimeLogger {
 	}
 
 	fn log(&self, record: &log::Record) {
+		debug(&"Hey2");
 		use fmt::Write;
 		let mut w = sp_std::Writer::default();
 		let _ = core::write!(&mut w, "{}", record.args());
@@ -198,3 +207,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");
+		}
+	}
+}

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")]

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 {