sc-executor: Improve logging (#10869)

Improves the logging by switching to `tracing` for a better log output. Besides that, it also adds a
trace for the function being executed.

substrate/Cargo.lock

@@ -8253,7 +8253,6 @@ dependencies = [
  "hex-literal",
  "lazy_static",
  "libsecp256k1",
- "log 0.4.14",
  "lru 0.6.6",
  "parity-scale-codec",
  "parking_lot 0.11.2",

substrate/client/executor/Cargo.toml

@@ -31,10 +31,10 @@ sc-executor-common = { version = "0.10.0-dev", path = "common" }
 sc-executor-wasmi = { version = "0.10.0-dev", path = "wasmi" }
 sc-executor-wasmtime = { version = "0.10.0-dev", path = "wasmtime", optional = true }
 parking_lot = "0.11.2"
-log = "0.4.8"
 libsecp256k1 = "0.7"
 sp-core-hashing-proc-macro = { version = "4.0.0-dev", path = "../../primitives/core/hashing/proc-macro" }
 lru = "0.6.6"
+tracing = "0.1.29"
 
 [dev-dependencies]
 wat = "1.0"
@@ -45,7 +45,6 @@ sp-state-machine = { version = "0.11.0", path = "../../primitives/state-machine"
 sp-runtime = { version = "5.0.0", path = "../../primitives/runtime" }
 sp-maybe-compressed-blob = { version = "4.1.0-dev", path = "../../primitives/maybe-compressed-blob" }
 sc-tracing = { version = "4.0.0-dev", path = "../tracing" }
-tracing = "0.1.29"
 tracing-subscriber = "0.2.19"
 paste = "1.0"
 regex = "1"

substrate/client/executor/src/native_executor.rs

@@ -35,7 +35,6 @@ use std::{
 };
 
 use codec::{Decode, Encode};
-use log::trace;
 use sc_executor_common::{
 	runtime_blob::RuntimeBlob,
 	wasm_runtime::{InvokeMethod, WasmInstance, WasmModule},
@@ -301,6 +300,12 @@ where
 		_use_native: bool,
 		_native_call: Option<NC>,
 	) -> (Result<NativeOrEncoded<R>>, bool) {
+		tracing::trace!(
+			target: "executor",
+			%method,
+			"Executing function",
+		);
+
 		let result = self.with_instance(
 			runtime_code,
 			ext,
@@ -422,10 +427,10 @@ impl RuntimeSpawn for RuntimeInstanceSpawn {
 				let async_ext = match new_async_externalities(scheduler.clone()) {
 					Ok(val) => val,
 					Err(e) => {
-						log::error!(
+						tracing::error!(
 							target: "executor",
-							"Failed to setup externalities for async context: {}",
+							error = %e,
-							e,
+							"Failed to setup externalities for async context.",
 						);
 
 						// This will drop sender and receiver end will panic
@@ -438,10 +443,10 @@ impl RuntimeSpawn for RuntimeInstanceSpawn {
 				)) {
 					Ok(val) => val,
 					Err(e) => {
-						log::error!(
+						tracing::error!(
 							target: "executor",
-							"Failed to setup runtime extension for async externalities: {}",
+							error = %e,
-							e,
+							"Failed to setup runtime extension for async externalities",
 						);
 
 						// This will drop sender and receiver end will panic
@@ -476,7 +481,7 @@ impl RuntimeSpawn for RuntimeInstanceSpawn {
 					Err(error) => {
 						// If execution is panicked, the `join` in the original runtime code will
 						// panic as well, since the sender is dropped without sending anything.
-						log::error!("Call error in spawned task: {}", error);
+						tracing::error!(error = %error, "Call error in spawned task");
 					},
 				}
 			}),
@@ -518,10 +523,10 @@ fn preregister_builtin_ext(module: Arc<dyn WasmModule>) {
 			RuntimeInstanceSpawn::with_externalities_and_module(module, ext)
 		{
 			if let Err(e) = ext.register_extension(RuntimeSpawnExt(Box::new(runtime_spawn))) {
-				trace!(
+				tracing::trace!(
 					target: "executor",
-					"Failed to register `RuntimeSpawnExt` instance on externalities: {:?}",
+					error = ?e,
-					e,
+					"Failed to register `RuntimeSpawnExt` instance on externalities",
 				)
 			}
 		}
@@ -543,6 +548,12 @@ impl<D: NativeExecutionDispatch + 'static> CodeExecutor for NativeElseWasmExecut
 		use_native: bool,
 		native_call: Option<NC>,
 	) -> (Result<NativeOrEncoded<R>>, bool) {
+		tracing::trace!(
+			target: "executor",
+			function = %method,
+			"Executing function",
+		);
+
 		let mut used_native = false;
 		let result = self.wasm.with_instance(
 			runtime_code,
@@ -558,11 +569,11 @@ impl<D: NativeExecutionDispatch + 'static> CodeExecutor for NativeElseWasmExecut
 				match (use_native, can_call_with, native_call) {
 					(_, false, _) | (false, _, _) => {
 						if !can_call_with {
-							trace!(
+							tracing::trace!(
 								target: "executor",
-								"Request for native execution failed (native: {}, chain: {})",
+								native = %self.native_version.runtime_version,
-								self.native_version.runtime_version,
+								chain = %onchain_version,
-								onchain_version,
+								"Request for native execution failed",
 							);
 						}
 
@@ -572,12 +583,11 @@ impl<D: NativeExecutionDispatch + 'static> CodeExecutor for NativeElseWasmExecut
 						})
 					},
 					(true, true, Some(call)) => {
-						trace!(
+						tracing::trace!(
 							target: "executor",
-							"Request for native execution with native call succeeded \
+							native = %self.native_version.runtime_version,
-							(native: {}, chain: {}).",
+							chain = %onchain_version,
-							self.native_version.runtime_version,
+							"Request for native execution with native call succeeded"
-							onchain_version,
 						);
 
 						used_native = true;
@@ -587,11 +597,11 @@ impl<D: NativeExecutionDispatch + 'static> CodeExecutor for NativeElseWasmExecut
 						Ok(res)
 					},
 					_ => {
-						trace!(
+						tracing::trace!(
 							target: "executor",
-							"Request for native execution succeeded (native: {}, chain: {})",
+							native = %self.native_version.runtime_version,
-							self.native_version.runtime_version,
+							chain = %onchain_version,
-							onchain_version
+							"Request for native execution succeeded",
 						);
 
 						used_native = true;

substrate/client/executor/src/wasm_runtime.rs

@@ -103,23 +103,23 @@ impl VersionedRuntime {
 				let result = f(&self.module, &mut *instance, self.version.as_ref(), ext);
 				if let Err(e) = &result {
 					if new_inst {
-						log::warn!(
+						tracing::warn!(
 							target: "wasm-runtime",
-							"Fresh runtime instance failed with {}",
+							error = %e,
-							e,
+							"Fresh runtime instance failed",
 						)
 					} else {
-						log::warn!(
+						tracing::warn!(
 							target: "wasm-runtime",
-							"Evicting failed runtime instance: {}",
+							error = %e,
-							e,
+							"Evicting failed runtime instance",
 						);
 					}
 				} else {
 					*locked = Some(instance);
 
 					if new_inst {
-						log::debug!(
+						tracing::debug!(
 							target: "wasm-runtime",
 							"Allocated WASM instance {}/{}",
 							index + 1,
@@ -131,7 +131,7 @@ impl VersionedRuntime {
 				result
 			},
 			None => {
-				log::warn!(target: "wasm-runtime", "Ran out of free WASM instances");
+				tracing::warn!(target: "wasm-runtime", "Ran out of free WASM instances");
 
 				// Allocate a new instance
 				let mut instance = self.module.new_instance()?;
@@ -259,7 +259,7 @@ impl RuntimeCache {
 
 			match result {
 				Ok(ref result) => {
-					log::debug!(
+					tracing::debug!(
 						target: "wasm-runtime",
 						"Prepared new runtime version {:?} in {} ms.",
 						result.version,
@@ -267,7 +267,7 @@ impl RuntimeCache {
 					);
 				},
 				Err(ref err) => {
-					log::warn!(target: "wasm-runtime", "Cannot create a runtime: {:?}", err);
+					tracing::warn!(target: "wasm-runtime", error = ?err, "Cannot create a runtime");
 				},
 			}