From 203acda6593c5da4e97179e204f6c08e0012c05e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Tue, 20 Oct 2020 12:51:51 +0200 Subject: [PATCH] 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 | 2 + substrate/frame/support/Cargo.toml | 2 + substrate/frame/support/src/debug.rs | 49 ++++++++++++++++++++++++- substrate/primitives/tracing/src/lib.rs | 4 +- substrate/test-utils/runtime/src/lib.rs | 14 +++++++ 5 files changed, 69 insertions(+), 2 deletions(-) diff --git a/substrate/Cargo.lock b/substrate/Cargo.lock index c91f31a686..c9f09f3b87 100644 --- a/substrate/Cargo.lock +++ b/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]] diff --git a/substrate/frame/support/Cargo.toml b/substrate/frame/support/Cargo.toml index 1811d620f1..3d40b65637 100644 --- a/substrate/frame/support/Cargo.toml +++ b/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"] diff --git a/substrate/frame/support/src/debug.rs b/substrate/frame/support/src/debug.rs index 86b40f1664..04f5c529f0 100644 --- a/substrate/frame/support/src/debug.rs +++ b/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"); + } + } +} diff --git a/substrate/primitives/tracing/src/lib.rs b/substrate/primitives/tracing/src/lib.rs index fb074d5579..cb67d8a0c5 100644 --- a/substrate/primitives/tracing/src/lib.rs +++ b/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")] diff --git a/substrate/test-utils/runtime/src/lib.rs b/substrate/test-utils/runtime/src/lib.rs index 5ab4d99dee..e772a28ee3 100644 --- a/substrate/test-utils/runtime/src/lib.rs +++ b/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, other: Vec, 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, other: Vec, 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 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 for Runtime {