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..04f5c529f0aff 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); } } @@ -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/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 {