Init RuntimeLogger automatically for each runtime api call (#8128)

* Init `RuntimeLogger` automatically for each runtime api call

This pr change the runtime api in such a way to always and automatically
enable the `RuntimeLogger`. This enables the user to use `log` or
`tracing` from inside the runtime to create log messages. As logging
introduces some extra code and especially increases the size of the wasm
blob. It is advised to disable all logging completely with
`sp-api/disable-logging` when doing the wasm builds for the on-chain
wasm runtime.

Besides these changes, the pr also brings most of the logging found in
frame to the same format "runtime::*".

* Update frame/im-online/src/lib.rs

Co-authored-by: Guillaume Thiolliere <gui.thiolliere@gmail.com>

* Update test-utils/runtime/Cargo.toml

* Fix test

* Don't use tracing in the runtime, as we don't support it :D

* Fixes

Co-authored-by: Guillaume Thiolliere <gui.thiolliere@gmail.com>

substrate/primitives/api/Cargo.toml

@@ -23,6 +23,8 @@ sp-state-machine = { version = "0.9.0", optional = true, path = "../state-machin
 hash-db = { version = "0.15.2", optional = true }
 thiserror = { version = "1.0.21", optional = true }
 
+log = { version = "0.4.14", default-features = false }
+
 [dev-dependencies]
 sp-test-primitives = { version = "2.0.0", path = "../test-primitives" }
 
@@ -37,4 +39,15 @@ std = [
 	"sp-version/std",
 	"hash-db",
 	"thiserror",
+	"log/std",
+]
+# Special feature to disable logging completly.
+#
+# By default `sp-api` initializes the `RuntimeLogger` for each runtime api function. However,
+# logging functionality increases the code size. It is recommended to enable this feature when
+# building a runtime for registering it on chain.
+#
+# This sets the max logging level to `off` for `log`.
+disable-logging = [
+	"log/max_level_off",
 ]

substrate/primitives/api/proc-macro/src/impl_runtime_apis.rs

@@ -162,6 +162,7 @@ fn generate_dispatch_function(impls: &[ItemImpl]) -> Result<TokenStream> {
 fn generate_wasm_interface(impls: &[ItemImpl]) -> Result<TokenStream> {
 	let input = Ident::new("input", Span::call_site());
 	let c = generate_crate_access(HIDDEN_INCLUDES_ID);
+
 	let impl_calls = generate_impl_calls(impls, &input)?
 		.into_iter()
 		.map(|(trait_, fn_name, impl_, attrs)| {
@@ -183,6 +184,8 @@ fn generate_wasm_interface(impls: &[ItemImpl]) -> Result<TokenStream> {
 						}
 					};
 
+					#c::init_runtime_logger();
+
 					let output = { #impl_ };
 					#c::to_substrate_wasm_fn_return_value(&output)
 				}

substrate/primitives/api/src/lib.rs

@@ -30,6 +30,19 @@
 //! api, the [`ApiExt`] trait, the [`CallApiAt`] trait and the [`ConstructRuntimeApi`] trait.
 //!
 //! On a meta level this implies, the client calls the generated API from the client perspective.
+//!
+//!
+//! # Logging
+//!
+//! Substrate supports logging from the runtime in native and in wasm. For that purpose it provides
+//! the [`RuntimeLogger`](sp_runtime::runtime_logger::RuntimeLogger). This runtime logger is
+//! automatically enabled for each call into the runtime through the runtime api. As logging
+//! introduces extra code that isn't actually required for the logic of your runtime and also
+//! increases the final wasm blob size, it is recommended to disable the logging for on-chain
+//! wasm blobs. This can be done by enabling the `disable-logging` feature of this crate. Be aware
+//! that this feature instructs `log` and `tracing` to disable logging at compile time by setting
+//! the `max_level_off` feature for these crates. So, you should not enable this feature for a
+//! native build as otherwise the node will not output any log messages.
 
 #![cfg_attr(not(feature = "std"), no_std)]
 
@@ -386,6 +399,12 @@ pub trait ConstructRuntimeApi<Block: BlockT, C: CallApiAt<Block>> {
 	fn construct_runtime_api<'a>(call: &'a C) -> ApiRef<'a, Self::RuntimeApi>;
 }
 
+/// Init the [`RuntimeLogger`](sp_runtime::runtime_logger::RuntimeLogger).
+pub fn init_runtime_logger() {
+	#[cfg(not(feature = "disable-logging"))]
+	sp_runtime::runtime_logger::RuntimeLogger::init();
+}
+
 /// An error describing which API call failed.
 #[cfg(feature = "std")]
 #[derive(Debug, thiserror::Error)]

substrate/primitives/api/test/Cargo.toml

@@ -15,6 +15,7 @@ targets = ["x86_64-unknown-linux-gnu"]
 sp-api = { version = "3.0.0", path = "../" }
 substrate-test-runtime-client = { version = "2.0.0", path = "../../../test-utils/runtime/client" }
 sp-version = { version = "3.0.0", path = "../../version" }
+sp-tracing = { version = "3.0.0", path = "../../tracing" }
 sp-runtime = { version = "3.0.0", path = "../../runtime" }
 sp-blockchain = { version = "3.0.0", path = "../../blockchain" }
 sp-consensus = { version = "0.9.0", path = "../../consensus/common" }
@@ -28,6 +29,7 @@ rustversion = "1.0.0"
 criterion = "0.3.0"
 substrate-test-runtime-client = { version = "2.0.0", path = "../../../test-utils/runtime/client" }
 sp-core = { version = "3.0.0", path = "../../core" }
+log = "0.4.14"
 
 [[bench]]
 name = "bench"

substrate/primitives/api/test/tests/runtime_calls.rs

@@ -215,3 +215,34 @@ fn call_runtime_api_with_multiple_arguments() {
 		.test_multiple_arguments(&block_id, data.clone(), data.clone(), data.len() as u32)
 		.unwrap();
 }
+
+#[test]
+fn disable_logging_works() {
+	if std::env::var("RUN_TEST").is_ok() {
+		sp_tracing::try_init_simple();
+
+		let mut builder = TestClientBuilder::new()
+			.set_execution_strategy(ExecutionStrategy::AlwaysWasm);
+		builder.genesis_init_mut().set_wasm_code(
+			substrate_test_runtime_client::runtime::wasm_binary_logging_disabled_unwrap().to_vec(),
+		);
+
+		let client = builder.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");
+		log::error!("Logging from native works");
+	} else {
+		let executable = std::env::current_exe().unwrap();
+		let output = std::process::Command::new(executable)
+			.env("RUN_TEST", "1")
+			.env("RUST_LOG", "info")
+			.args(&["--nocapture", "disable_logging_works"])
+			.output()
+			.unwrap();
+
+		let output = dbg!(String::from_utf8(output.stderr).unwrap());
+		assert!(!output.contains("Hey I'm runtime"));
+		assert!(output.contains("Logging from native works"));
+	}
+}

substrate/primitives/runtime/Cargo.toml

@@ -22,7 +22,7 @@ sp-application-crypto = { version = "3.0.0", default-features = false, path = ".
 sp-arithmetic = { version = "3.0.0", default-features = false, path = "../arithmetic" }
 sp-std = { version = "3.0.0", default-features = false, path = "../std" }
 sp-io = { version = "3.0.0", default-features = false, path = "../io" }
-log = { version = "0.4.8", optional = true }
+log = { version = "0.4.14", default-features = false }
 paste = "1.0"
 rand = { version = "0.7.2", optional = true }
 impl-trait-for-tuples = "0.2.1"
@@ -34,6 +34,9 @@ either = { version = "1.5", default-features = false }
 serde_json = "1.0.41"
 rand = "0.7.2"
 sp-state-machine = { version = "0.9.0", path = "../state-machine" }
+sp-api = { version = "3.0.0", path = "../api" }
+substrate-test-runtime-client = { version = "2.0.0", path = "../../test-utils/runtime/client" }
+sp-tracing = { version = "3.0.0", path = "../../primitives/tracing" }
 
 [features]
 bench = []
@@ -43,7 +46,7 @@ std = [
 	"sp-application-crypto/std",
 	"sp-arithmetic/std",
 	"codec/std",
-	"log",
+	"log/std",
 	"sp-core/std",
 	"rand",
 	"sp-std/std",

substrate/primitives/runtime/src/lib.rs

@@ -57,6 +57,7 @@ pub mod transaction_validity;
 pub mod random_number_generator;
 mod runtime_string;
 mod multiaddress;
+pub mod runtime_logger;
 
 pub use crate::runtime_string::*;
 

substrate/primitives/runtime/src/runtime_logger.rs

@@ -0,0 +1,108 @@
+// This file is part of Substrate.
+
+// Copyright (C) 2021 Parity Technologies (UK) Ltd.
+// SPDX-License-Identifier: Apache-2.0
+
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+// 	http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+//! A logger that can be used to log from the runtime.
+//!
+//! See [`RuntimeLogger`] for more docs.
+
+/// Runtime logger implementation - `log` crate backend.
+///
+/// The logger should be initialized if you want to display
+/// logs inside the runtime that is not necessarily running natively.
+pub struct RuntimeLogger;
+
+impl RuntimeLogger {
+	/// Initialize the logger.
+	///
+	/// This is a no-op when running natively (`std`).
+	#[cfg(feature = "std")]
+	pub fn init() {}
+
+	/// Initialize the logger.
+	///
+	/// This is a no-op when running natively (`std`).
+	#[cfg(not(feature = "std"))]
+	pub fn init() {
+		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);
+	}
+}
+
+impl log::Log for RuntimeLogger {
+	fn enabled(&self, _metadata: &log::Metadata) -> bool {
+		// to avoid calling to host twice, we pass everything
+		// and let the host decide what to print.
+		// If someone is initializing the logger they should
+		// know what they are doing.
+		true
+	}
+
+	fn log(&self, record: &log::Record) {
+		use sp_std::fmt::Write;
+		let mut w = sp_std::Writer::default();
+		let _ = ::core::write!(&mut w, "{}", record.args());
+
+		sp_io::logging::log(
+			record.level().into(),
+			record.target(),
+			w.inner(),
+		);
+	}
+
+	fn flush(&self) {}
+}
+
+#[cfg(test)]
+mod tests {
+	use substrate_test_runtime_client::{
+		ExecutionStrategy, TestClientBuilderExt, DefaultTestClientBuilderExt,
+		TestClientBuilder, runtime::TestAPI,
+	};
+	use sp_api::{ProvideRuntimeApi, BlockId};
+
+	#[test]
+	fn ensure_runtime_logger_works() {
+		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");
+		} else {
+			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"])
+				.output()
+				.unwrap();
+
+			let output = dbg!(String::from_utf8(output.stderr).unwrap());
+			assert!(output.contains("Hey I'm runtime"));
+		}
+	}
+}