From 2e44a508eb28b23391c8f767693c1058197ab305 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Mon, 19 Oct 2020 17:03:33 +0200 Subject: [PATCH 1/2] 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 ;) --- Cargo.lock | 2 ++ frame/support/Cargo.toml | 2 ++ frame/support/src/debug.rs | 50 ++++++++++++++++++++++++++++++++++- primitives/tracing/src/lib.rs | 4 ++- test-utils/runtime/src/lib.rs | 14 ++++++++++ 5 files changed, 70 insertions(+), 2 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 15408ba75af6c..64739b3275e05 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1595,6 +1595,7 @@ dependencies = [ "pretty_assertions", "serde", "smallvec 1.4.1", + "sp-api", "sp-arithmetic", "sp-core", "sp-inherents", @@ -1603,6 +1604,7 @@ dependencies = [ "sp-state-machine", "sp-std", "sp-tracing", + "substrate-test-runtime-client", ] [[package]] diff --git a/frame/support/Cargo.toml b/frame/support/Cargo.toml index 1811d620f1083..3d40b65637262 100644 --- a/frame/support/Cargo.toml +++ b/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/frame/support/src/debug.rs b/frame/support/src/debug.rs index 86b40f1664dcf..59d3b7be28618 100644 --- a/frame/support/src/debug.rs +++ b/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"); + } + } +} diff --git a/primitives/tracing/src/lib.rs b/primitives/tracing/src/lib.rs index fb074d5579c82..cb67d8a0c5a22 100644 --- a/primitives/tracing/src/lib.rs +++ b/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/test-utils/runtime/src/lib.rs b/test-utils/runtime/src/lib.rs index 5ab4d99dee0ad..e772a28ee33a2 100644 --- a/test-utils/runtime/src/lib.rs +++ b/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 { From 4281d7e39ef7608ba36f404123c59a96b3df39d7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Bastian=20K=C3=B6cher?= Date: Mon, 19 Oct 2020 18:28:02 +0200 Subject: [PATCH 2/2] Update frame/support/src/debug.rs --- frame/support/src/debug.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/frame/support/src/debug.rs b/frame/support/src/debug.rs index 59d3b7be28618..04f5c529f0aff 100644 --- a/frame/support/src/debug.rs +++ b/frame/support/src/debug.rs @@ -193,7 +193,6 @@ 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());