Improve state related logs to use a more uniform format (#9452)

* Improve `state` related logs to use a more uniform format

The logging before wasn't that uniform and not that great to read/parse.
Now we are using a uniform format for all the logs. Besides these
changes, there are some minor changes around the code that calls the
state machine.

* Make CI happy

* Use HexDisplay for `ext_id`

substrate/client/api/src/call_executor.rs

@@ -22,10 +22,7 @@ use codec::{Decode, Encode};
 use sc_executor::{NativeVersion, RuntimeVersion};
 use sp_core::NativeOrEncoded;
 use sp_externalities::Extensions;
-use sp_runtime::{
-	generic::BlockId,
-	traits::{Block as BlockT, HashFor},
-};
+use sp_runtime::{generic::BlockId, traits::Block as BlockT};
 use sp_state_machine::{ExecutionManager, ExecutionStrategy, OverlayedChanges, StorageProof};
 use std::{cell::RefCell, panic::UnwindSafe, result};
 
@@ -100,31 +97,12 @@ pub trait CallExecutor<B: BlockT> {
 	/// No changes are made.
 	fn runtime_version(&self, id: &BlockId<B>) -> Result<RuntimeVersion, sp_blockchain::Error>;
 
-	/// Execute a call to a contract on top of given state, gathering execution proof.
+	/// Prove the execution of the given `method`.
 	///
 	/// No changes are made.
-	fn prove_at_state<S: sp_state_machine::Backend<HashFor<B>>>(
+	fn prove_execution(
 		&self,
-		mut state: S,
-		overlay: &mut OverlayedChanges,
-		method: &str,
-		call_data: &[u8],
-	) -> Result<(Vec<u8>, StorageProof), sp_blockchain::Error> {
-		let trie_state = state.as_trie_backend().ok_or_else(|| {
-			sp_blockchain::Error::from_state(Box::new(
-				sp_state_machine::ExecutionError::UnableToGenerateProof,
-			) as Box<_>)
-		})?;
-		self.prove_at_trie_state(trie_state, overlay, method, call_data)
-	}
-
-	/// Execute a call to a contract on top of given trie state, gathering execution proof.
-	///
-	/// No changes are made.
-	fn prove_at_trie_state<S: sp_state_machine::TrieBackendStorage<HashFor<B>>>(
-		&self,
-		trie_state: &sp_state_machine::TrieBackend<S, HashFor<B>>,
-		overlay: &mut OverlayedChanges,
+		at: &BlockId<B>,
 		method: &str,
 		call_data: &[u8],
 	) -> Result<(Vec<u8>, StorageProof), sp_blockchain::Error>;

substrate/client/light/src/call_executor.rs

@@ -30,11 +30,11 @@ use sp_core::{
 use sp_externalities::Extensions;
 use sp_runtime::{
 	generic::BlockId,
-	traits::{Block as BlockT, HashFor, Header as HeaderT},
+	traits::{Block as BlockT, Header as HeaderT},
 };
 use sp_state_machine::{
-	self, create_proof_check_backend, execution_proof_check_on_trie_backend,
-	Backend as StateBackend, ExecutionManager, ExecutionStrategy, OverlayedChanges, StorageProof,
+	create_proof_check_backend, execution_proof_check_on_trie_backend, ExecutionManager,
+	ExecutionStrategy, OverlayedChanges, StorageProof,
 };
 
 use sp_api::{ProofRecorder, StorageTransactionCache};
@@ -85,9 +85,10 @@ where
 		strategy: ExecutionStrategy,
 		extensions: Option<Extensions>,
 	) -> ClientResult<Vec<u8>> {
-		match self.backend.is_local_state_available(id) {
-			true => self.local.call(id, method, call_data, strategy, extensions),
-			false => Err(ClientError::NotAvailableOnLightClient),
+		if self.backend.is_local_state_available(id) {
+			self.local.call(id, method, call_data, strategy, extensions)
+		} else {
+			Err(ClientError::NotAvailableOnLightClient)
 		}
 	}
 
@@ -116,8 +117,8 @@ where
 		// there's no actual way/need to specify native/wasm execution strategy on light node
 		// => we can safely ignore passed values
 
-		match self.backend.is_local_state_available(at) {
-			true => CallExecutor::contextual_call::<
+		if self.backend.is_local_state_available(at) {
+			CallExecutor::contextual_call::<
 				fn(
 					Result<NativeOrEncoded<R>, Local::Error>,
 					Result<NativeOrEncoded<R>, Local::Error>,
@@ -136,60 +137,37 @@ where
 				recorder,
 				extensions,
 			)
-			.map_err(|e| ClientError::Execution(Box::new(e.to_string()))),
-			false => Err(ClientError::NotAvailableOnLightClient),
+		} else {
+			Err(ClientError::NotAvailableOnLightClient)
+		}
+	}
+
+	fn prove_execution(
+		&self,
+		at: &BlockId<Block>,
+		method: &str,
+		call_data: &[u8],
+	) -> ClientResult<(Vec<u8>, StorageProof)> {
+		if self.backend.is_local_state_available(at) {
+			self.local.prove_execution(at, method, call_data)
+		} else {
+			Err(ClientError::NotAvailableOnLightClient)
 		}
 	}
 
 	fn runtime_version(&self, id: &BlockId<Block>) -> ClientResult<RuntimeVersion> {
-		match self.backend.is_local_state_available(id) {
-			true => self.local.runtime_version(id),
-			false => Err(ClientError::NotAvailableOnLightClient),
+		if self.backend.is_local_state_available(id) {
+			self.local.runtime_version(id)
+		} else {
+			Err(ClientError::NotAvailableOnLightClient)
 		}
 	}
 
-	fn prove_at_trie_state<S: sp_state_machine::TrieBackendStorage<HashFor<Block>>>(
-		&self,
-		_state: &sp_state_machine::TrieBackend<S, HashFor<Block>>,
-		_changes: &mut OverlayedChanges,
-		_method: &str,
-		_call_data: &[u8],
-	) -> ClientResult<(Vec<u8>, StorageProof)> {
-		Err(ClientError::NotAvailableOnLightClient)
-	}
-
 	fn native_runtime_version(&self) -> Option<&NativeVersion> {
 		None
 	}
 }
 
-/// Prove contextual execution using given block header in environment.
-///
-/// Method is executed using passed header as environment' current block.
-/// Proof includes both environment preparation proof and method execution proof.
-pub fn prove_execution<Block, S, E>(
-	mut state: S,
-	executor: &E,
-	method: &str,
-	call_data: &[u8],
-) -> ClientResult<(Vec<u8>, StorageProof)>
-where
-	Block: BlockT,
-	S: StateBackend<HashFor<Block>>,
-	E: CallExecutor<Block>,
-{
-	let trie_state = state.as_trie_backend().ok_or_else(|| {
-		Box::new(sp_state_machine::ExecutionError::UnableToGenerateProof)
-			as Box<dyn sp_state_machine::Error>
-	})?;
-
-	// execute method + record execution proof
-	let (result, exec_proof) =
-		executor.prove_at_trie_state(&trie_state, &mut Default::default(), method, call_data)?;
-
-	Ok((result, exec_proof))
-}
-
 /// Check remote contextual execution proof using given backend.
 ///
 /// Proof should include the method execution proof.
@@ -200,7 +178,7 @@ pub fn check_execution_proof<Header, E, H>(
 	remote_proof: StorageProof,
 ) -> ClientResult<Vec<u8>>
 where
-	Header: HeaderT,
+	Header: HeaderT<Hash = H::Out>,
 	E: CodeExecutor + Clone + 'static,
 	H: Hasher,
 	H::Out: Ord + codec::Codec + 'static,

substrate/client/light/src/fetcher.rs

@@ -53,21 +53,21 @@ pub use sc_client_api::{
 };
 
 /// Remote data checker.
-pub struct LightDataChecker<E, H, B: BlockT, S: BlockchainStorage<B>> {
+pub struct LightDataChecker<E, B: BlockT, S: BlockchainStorage<B>> {
 	blockchain: Arc<Blockchain<S>>,
 	executor: E,
 	spawn_handle: Box<dyn SpawnNamed>,
-	_hasher: PhantomData<(B, H)>,
+	_marker: PhantomData<B>,
 }
 
-impl<E, H, B: BlockT, S: BlockchainStorage<B>> LightDataChecker<E, H, B, S> {
+impl<E, B: BlockT, S: BlockchainStorage<B>> LightDataChecker<E, B, S> {
 	/// Create new light data checker.
 	pub fn new(
 		blockchain: Arc<Blockchain<S>>,
 		executor: E,
 		spawn_handle: Box<dyn SpawnNamed>,
 	) -> Self {
-		Self { blockchain, executor, spawn_handle, _hasher: PhantomData }
+		Self { blockchain, executor, spawn_handle, _marker: PhantomData }
 	}
 
 	/// Check remote changes query proof assuming that CHT-s are of given size.
@@ -76,11 +76,7 @@ impl<E, H, B: BlockT, S: BlockchainStorage<B>> LightDataChecker<E, H, B, S> {
 		request: &RemoteChangesRequest<B::Header>,
 		remote_proof: ChangesProof<B::Header>,
 		cht_size: NumberFor<B>,
-	) -> ClientResult<Vec<(NumberFor<B>, u32)>>
-	where
-		H: Hasher,
-		H::Out: Ord + codec::Codec,
-	{
+	) -> ClientResult<Vec<(NumberFor<B>, u32)>> {
 		// since we need roots of all changes tries for the range begin..max
 		// => remote node can't use max block greater that one that we have passed
 		if remote_proof.max_block > request.max_block.0 ||
@@ -135,7 +131,7 @@ impl<E, H, B: BlockT, S: BlockchainStorage<B>> LightDataChecker<E, H, B, S> {
 		let mut result = Vec::new();
 		let proof_storage = InMemoryChangesTrieStorage::with_proof(remote_proof);
 		for config_range in &request.changes_trie_configs {
-			let result_range = key_changes_proof_check_with_db::<H, _>(
+			let result_range = key_changes_proof_check_with_db::<HashFor<B>, _>(
 				ChangesTrieConfigurationRange {
 					config: config_range
 						.config
@@ -171,11 +167,7 @@ impl<E, H, B: BlockT, S: BlockchainStorage<B>> LightDataChecker<E, H, B, S> {
 		cht_size: NumberFor<B>,
 		remote_roots: &BTreeMap<NumberFor<B>, B::Hash>,
 		remote_roots_proof: StorageProof,
-	) -> ClientResult<()>
-	where
-		H: Hasher,
-		H::Out: Ord + codec::Codec,
-	{
+	) -> ClientResult<()> {
 		// all the checks are sharing the same storage
 		let storage = remote_roots_proof.into_memory_db();
 
@@ -204,16 +196,14 @@ impl<E, H, B: BlockT, S: BlockchainStorage<B>> LightDataChecker<E, H, B, S> {
 					// check if the proofs storage contains the root
 					// normally this happens in when the proving backend is created, but since
 					// we share the storage for multiple checks, do it here
-					let mut cht_root = H::Out::default();
-					cht_root.as_mut().copy_from_slice(local_cht_root.as_ref());
-					if !storage.contains(&cht_root, EMPTY_PREFIX) {
+					if !storage.contains(&local_cht_root, EMPTY_PREFIX) {
 						return Err(ClientError::InvalidCHTProof.into())
 					}
 
 					// check proof for single changes trie root
-					let proving_backend = TrieBackend::new(storage, cht_root);
+					let proving_backend = TrieBackend::new(storage, local_cht_root);
 					let remote_changes_trie_root = remote_roots[&block];
-					cht::check_proof_on_proving_backend::<B::Header, H>(
+					cht::check_proof_on_proving_backend::<B::Header, HashFor<B>>(
 						local_cht_root,
 						block,
 						remote_changes_trie_root,
@@ -231,12 +221,10 @@ impl<E, H, B: BlockT, S: BlockchainStorage<B>> LightDataChecker<E, H, B, S> {
 	}
 }
 
-impl<E, Block, H, S> FetchChecker<Block> for LightDataChecker<E, H, Block, S>
+impl<E, Block, S> FetchChecker<Block> for LightDataChecker<E, Block, S>
 where
 	Block: BlockT,
 	E: CodeExecutor + Clone + 'static,
-	H: Hasher,
-	H::Out: Ord + codec::Codec + 'static,
 	S: BlockchainStorage<Block>,
 {
 	fn check_header_proof(
@@ -248,7 +236,7 @@ where
 		let remote_header =
 			remote_header.ok_or_else(|| ClientError::from(ClientError::InvalidCHTProof))?;
 		let remote_header_hash = remote_header.hash();
-		cht::check_proof::<Block::Header, H>(
+		cht::check_proof::<Block::Header, HashFor<Block>>(
 			request.cht_root,
 			request.block,
 			remote_header_hash,
@@ -262,7 +250,7 @@ where
 		request: &RemoteReadRequest<Block::Header>,
 		remote_proof: StorageProof,
 	) -> ClientResult<HashMap<Vec<u8>, Option<Vec<u8>>>> {
-		read_proof_check::<H, _>(
+		read_proof_check::<HashFor<Block>, _>(
 			convert_hash(request.header.state_root()),
 			remote_proof,
 			request.keys.iter(),
@@ -279,7 +267,7 @@ where
 			Some((ChildType::ParentKeyId, storage_key)) => ChildInfo::new_default(storage_key),
 			None => return Err(ClientError::InvalidChildType),
 		};
-		read_child_proof_check::<H, _>(
+		read_child_proof_check::<HashFor<Block>, _>(
 			convert_hash(request.header.state_root()),
 			remote_proof,
 			&child_info,
@@ -293,7 +281,7 @@ where
 		request: &RemoteCallRequest<Block::Header>,
 		remote_proof: StorageProof,
 	) -> ClientResult<Vec<u8>> {
-		check_execution_proof::<_, _, H>(
+		check_execution_proof::<_, _, HashFor<Block>>(
 			&self.executor,
 			self.spawn_handle.clone(),
 			request,

substrate/client/light/src/lib.rs

@@ -37,7 +37,7 @@ pub fn new_fetch_checker<E, B: BlockT, S: BlockchainStorage<B>>(
 	blockchain: Arc<Blockchain<S>>,
 	executor: E,
 	spawn_handle: Box<dyn SpawnNamed>,
-) -> LightDataChecker<E, HashFor<B>, B, S>
+) -> LightDataChecker<E, B, S>
 where
 	E: CodeExecutor,
 {

substrate/client/service/src/client/call_executor.rs

@@ -18,7 +18,7 @@
 
 use super::{client::ClientConfig, wasm_override::WasmOverride, wasm_substitutes::WasmSubstitutes};
 use codec::{Decode, Encode};
-use sc_client_api::{backend, call_executor::CallExecutor};
+use sc_client_api::{backend, call_executor::CallExecutor, HeaderBackend};
 use sc_executor::{NativeVersion, RuntimeInfo, RuntimeVersion};
 use sp_api::{ProofRecorder, StorageTransactionCache};
 use sp_core::{
@@ -28,7 +28,7 @@ use sp_core::{
 use sp_externalities::Extensions;
 use sp_runtime::{
 	generic::BlockId,
-	traits::{Block as BlockT, HashFor, NumberFor},
+	traits::{Block as BlockT, NumberFor},
 };
 use sp_state_machine::{
 	self, backend::Backend as _, ExecutionManager, ExecutionStrategy, Ext, OverlayedChanges,
@@ -146,7 +146,7 @@ where
 
 	fn call(
 		&self,
-		id: &BlockId<Block>,
+		at: &BlockId<Block>,
 		method: &str,
 		call_data: &[u8],
 		strategy: ExecutionStrategy,
@@ -154,12 +154,17 @@ where
 	) -> sp_blockchain::Result<Vec<u8>> {
 		let mut changes = OverlayedChanges::default();
 		let changes_trie =
-			backend::changes_tries_state_at_block(id, self.backend.changes_trie_storage())?;
-		let state = self.backend.state_at(*id)?;
+			backend::changes_tries_state_at_block(at, self.backend.changes_trie_storage())?;
+		let state = self.backend.state_at(*at)?;
 		let state_runtime_code = sp_state_machine::backend::BackendRuntimeCode::new(&state);
 		let runtime_code =
 			state_runtime_code.runtime_code().map_err(sp_blockchain::Error::RuntimeCode)?;
-		let runtime_code = self.check_override(runtime_code, id)?;
+
+		let runtime_code = self.check_override(runtime_code, at)?;
+
+		let at_hash = self.backend.blockchain().block_hash_from_id(at)?.ok_or_else(|| {
+			sp_blockchain::Error::UnknownBlock(format!("Could not find block hash for {:?}", at))
+		})?;
 
 		let return_data = StateMachine::new(
 			&state,
@@ -172,6 +177,7 @@ where
 			&runtime_code,
 			self.spawn_handle.clone(),
 		)
+		.set_parent_hash(at_hash)
 		.execute_using_consensus_failure_handler::<_, NeverNativeValue, fn() -> _>(
 			strategy.get_manager(),
 			None,
@@ -210,6 +216,10 @@ where
 
 		let changes = &mut *changes.borrow_mut();
 
+		let at_hash = self.backend.blockchain().block_hash_from_id(at)?.ok_or_else(|| {
+			sp_blockchain::Error::UnknownBlock(format!("Could not find block hash for {:?}", at))
+		})?;
+
 		match recorder {
 			Some(recorder) => {
 				let trie_state = state.as_trie_backend().ok_or_else(|| {
@@ -240,7 +250,8 @@ where
 					extensions.unwrap_or_default(),
 					&runtime_code,
 					self.spawn_handle.clone(),
-				);
+				)
+				.set_parent_hash(at_hash);
 				// TODO: https://github.com/paritytech/substrate/issues/4455
 				// .with_storage_transaction_cache(storage_transaction_cache.as_mut().map(|c| &mut **c))
 				state_machine.execute_using_consensus_failure_handler(
@@ -267,7 +278,8 @@ where
 				)
 				.with_storage_transaction_cache(
 					storage_transaction_cache.as_mut().map(|c| &mut **c),
-				);
+				)
+				.set_parent_hash(at_hash);
 				state_machine.execute_using_consensus_failure_handler(
 					execution_manager,
 					native_call.map(|n| || (n)().map_err(|e| Box::new(e) as Box<_>)),
@@ -292,19 +304,27 @@ where
 			.map_err(|e| sp_blockchain::Error::VersionInvalid(format!("{:?}", e)).into())
 	}
 
-	fn prove_at_trie_state<S: sp_state_machine::TrieBackendStorage<HashFor<Block>>>(
+	fn prove_execution(
 		&self,
-		trie_state: &sp_state_machine::TrieBackend<S, HashFor<Block>>,
-		overlay: &mut OverlayedChanges,
+		at: &BlockId<Block>,
 		method: &str,
 		call_data: &[u8],
-	) -> Result<(Vec<u8>, StorageProof), sp_blockchain::Error> {
-		let state_runtime_code = sp_state_machine::backend::BackendRuntimeCode::new(trie_state);
+	) -> sp_blockchain::Result<(Vec<u8>, StorageProof)> {
+		let mut state = self.backend.state_at(*at)?;
+
+		let trie_backend = state.as_trie_backend().ok_or_else(|| {
+			Box::new(sp_state_machine::ExecutionError::UnableToGenerateProof)
+				as Box<dyn sp_state_machine::Error>
+		})?;
+
+		let state_runtime_code = sp_state_machine::backend::BackendRuntimeCode::new(trie_backend);
 		let runtime_code =
 			state_runtime_code.runtime_code().map_err(sp_blockchain::Error::RuntimeCode)?;
+		let runtime_code = self.check_override(runtime_code, at)?;
+
 		sp_state_machine::prove_execution_on_trie_backend::<_, _, NumberFor<Block>, _, _>(
-			trie_state,
-			overlay,
+			&trie_backend,
+			&mut Default::default(),
 			&self.executor,
 			self.spawn_handle.clone(),
 			method,

substrate/client/service/src/client/client.rs

@@ -46,7 +46,7 @@ use sc_client_api::{
 	CallExecutor, ExecutorProvider, KeyIterator, ProofProvider, UsageProvider,
 };
 use sc_executor::RuntimeVersion;
-use sc_light::{call_executor::prove_execution, fetcher::ChangesProof};
+use sc_light::fetcher::ChangesProof;
 use sc_telemetry::{telemetry, TelemetryHandle, SUBSTRATE_INFO};
 use sp_api::{
 	ApiExt, ApiRef, CallApiAt, CallApiAtParams, ConstructRuntimeApi, Core as CoreApi,
@@ -1312,8 +1312,8 @@ where
 			&mut [well_known_keys::CODE, well_known_keys::HEAP_PAGES].iter().map(|v| *v),
 		)?;
 
-		let state = self.state_at(id)?;
-		prove_execution(state, &self.executor, method, call_data)
+		self.executor
+			.prove_execution(id, method, call_data)
 			.map(|(r, p)| (r, StorageProof::merge(vec![p, code_proof])))
 	}
 

substrate/client/service/test/src/client/light.rs

@@ -47,7 +47,7 @@ use sp_core::{testing::TaskExecutor, NativeOrEncoded, H256};
 use sp_externalities::Extensions;
 use sp_runtime::{
 	generic::BlockId,
-	traits::{BlakeTwo256, Block as _, HashFor, Header as HeaderT, NumberFor},
+	traits::{BlakeTwo256, Block as _, Header as HeaderT, NumberFor},
 	Digest, Justifications,
 };
 use sp_state_machine::{ExecutionManager, OverlayedChanges};
@@ -248,12 +248,11 @@ impl CallExecutor<Block> for DummyCallExecutor {
 		unreachable!()
 	}
 
-	fn prove_at_trie_state<S: sp_state_machine::TrieBackendStorage<HashFor<Block>>>(
+	fn prove_execution(
 		&self,
-		_trie_state: &sp_state_machine::TrieBackend<S, HashFor<Block>>,
-		_overlay: &mut OverlayedChanges,
-		_method: &str,
-		_call_data: &[u8],
+		_: &BlockId<Block>,
+		_: &str,
+		_: &[u8],
 	) -> Result<(Vec<u8>, StorageProof), ClientError> {
 		unreachable!()
 	}
@@ -452,7 +451,6 @@ fn code_is_executed_at_genesis_only() {
 
 type TestChecker = LightDataChecker<
 	NativeExecutor<substrate_test_runtime_client::LocalExecutor>,
-	BlakeTwo256,
 	Block,
 	DummyStorage,
 >;

substrate/primitives/state-machine/src/ext.rs

@@ -206,7 +206,7 @@ where
 		trace!(
 			target: "state",
 			method = "Get",
-			ext_id = self.id,
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
 			key = %HexDisplay::from(&key),
 			result = ?result.as_ref().map(HexDisplay::from),
 			result_encoded = %HexDisplay::from(
@@ -228,10 +228,12 @@ where
 			.map(|x| x.map(|x| H::hash(x)))
 			.unwrap_or_else(|| self.backend.storage_hash(key).expect(EXT_NOT_ALLOWED_TO_FAIL));
 
-		trace!(target: "state", "{:04x}: Hash {}={:?}",
-			self.id,
-			HexDisplay::from(&key),
-			result,
+		trace!(
+			target: "state",
+			method = "Hash",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			key = %HexDisplay::from(&key),
+			?result,
 		);
 		result.map(|r| r.encode())
 	}
@@ -246,11 +248,13 @@ where
 				self.backend.child_storage(child_info, key).expect(EXT_NOT_ALLOWED_TO_FAIL)
 			});
 
-		trace!(target: "state", "{:04x}: GetChild({}) {}={:?}",
-			self.id,
-			HexDisplay::from(&child_info.storage_key()),
-			HexDisplay::from(&key),
-			result.as_ref().map(HexDisplay::from)
+		trace!(
+			target: "state",
+			method = "ChildGet",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			child_info = %HexDisplay::from(&child_info.storage_key()),
+			key = %HexDisplay::from(&key),
+			result = ?result.as_ref().map(HexDisplay::from)
 		);
 
 		result
@@ -266,11 +270,13 @@ where
 				self.backend.child_storage_hash(child_info, key).expect(EXT_NOT_ALLOWED_TO_FAIL)
 			});
 
-		trace!(target: "state", "{:04x}: ChildHash({}) {}={:?}",
-			self.id,
-			HexDisplay::from(&child_info.storage_key()),
-			HexDisplay::from(&key),
-			result,
+		trace!(
+			target: "state",
+			method = "ChildHash",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			child_info = %HexDisplay::from(&child_info.storage_key()),
+			key = %HexDisplay::from(&key),
+			?result,
 		);
 
 		result.map(|r| r.encode())
@@ -283,10 +289,12 @@ where
 			_ => self.backend.exists_storage(key).expect(EXT_NOT_ALLOWED_TO_FAIL),
 		};
 
-		trace!(target: "state", "{:04x}: Exists {}={:?}",
-			self.id,
-			HexDisplay::from(&key),
-			result,
+		trace!(
+			target: "state",
+			method = "Exists",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			key = %HexDisplay::from(&key),
+			%result,
 		);
 
 		result
@@ -303,11 +311,13 @@ where
 				.expect(EXT_NOT_ALLOWED_TO_FAIL),
 		};
 
-		trace!(target: "state", "{:04x}: ChildExists({}) {}={:?}",
-			self.id,
-			HexDisplay::from(&child_info.storage_key()),
-			HexDisplay::from(&key),
-			result,
+		trace!(
+			target: "state",
+			method = "ChildExists",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			child_info = %HexDisplay::from(&child_info.storage_key()),
+			key = %HexDisplay::from(&key),
+			%result,
 		);
 		result
 	}
@@ -402,7 +412,7 @@ where
 		trace!(
 			target: "state",
 			method = "Put",
-			ext_id = self.id,
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
 			key = %HexDisplay::from(&key),
 			value = ?value.as_ref().map(HexDisplay::from),
 			value_encoded = %HexDisplay::from(
@@ -423,11 +433,13 @@ where
 		key: StorageKey,
 		value: Option<StorageValue>,
 	) {
-		trace!(target: "state", "{:04x}: PutChild({}) {}={:?}",
-			self.id,
-			HexDisplay::from(&child_info.storage_key()),
-			HexDisplay::from(&key),
-			value.as_ref().map(HexDisplay::from)
+		trace!(
+			target: "state",
+			method = "ChildPut",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			child_info = %HexDisplay::from(&child_info.storage_key()),
+			key = %HexDisplay::from(&key),
+			value = ?value.as_ref().map(HexDisplay::from),
 		);
 		let _guard = guard();
 
@@ -436,9 +448,11 @@ where
 	}
 
 	fn kill_child_storage(&mut self, child_info: &ChildInfo, limit: Option<u32>) -> (bool, u32) {
-		trace!(target: "state", "{:04x}: KillChild({})",
-			self.id,
-			HexDisplay::from(&child_info.storage_key()),
+		trace!(
+			target: "state",
+			method = "ChildKill",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			child_info = %HexDisplay::from(&child_info.storage_key()),
 		);
 		let _guard = guard();
 		self.mark_dirty();
@@ -447,14 +461,19 @@ where
 	}
 
 	fn clear_prefix(&mut self, prefix: &[u8], limit: Option<u32>) -> (bool, u32) {
-		trace!(target: "state", "{:04x}: ClearPrefix {}",
-			self.id,
-			HexDisplay::from(&prefix),
+		trace!(
+			target: "state",
+			method = "ClearPrefix",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			prefix = %HexDisplay::from(&prefix),
 		);
 		let _guard = guard();
 
 		if sp_core::storage::well_known_keys::starts_with_child_storage_key(prefix) {
-			warn!(target: "trie", "Refuse to directly clear prefix that is part or contains of child storage key");
+			warn!(
+				target: "trie",
+				"Refuse to directly clear prefix that is part or contains of child storage key",
+			);
 			return (false, 0)
 		}
 
@@ -469,10 +488,12 @@ where
 		prefix: &[u8],
 		limit: Option<u32>,
 	) -> (bool, u32) {
-		trace!(target: "state", "{:04x}: ClearChildPrefix({}) {}",
-			self.id,
-			HexDisplay::from(&child_info.storage_key()),
-			HexDisplay::from(&prefix),
+		trace!(
+			target: "state",
+			method = "ChildClearPrefix",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			child_info = %HexDisplay::from(&child_info.storage_key()),
+			prefix = %HexDisplay::from(&prefix),
 		);
 		let _guard = guard();
 
@@ -482,10 +503,12 @@ where
 	}
 
 	fn storage_append(&mut self, key: Vec<u8>, value: Vec<u8>) {
-		trace!(target: "state", "{:04x}: Append {}={}",
-			self.id,
-			HexDisplay::from(&key),
-			HexDisplay::from(&value),
+		trace!(
+			target: "state",
+			method = "Append",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			key = %HexDisplay::from(&key),
+			value = %HexDisplay::from(&value),
 		);
 
 		let _guard = guard();
@@ -501,15 +524,24 @@ where
 	fn storage_root(&mut self) -> Vec<u8> {
 		let _guard = guard();
 		if let Some(ref root) = self.storage_transaction_cache.transaction_storage_root {
-			trace!(target: "state", "{:04x}: Root(cached) {}",
-				self.id,
-				HexDisplay::from(&root.as_ref()),
+			trace!(
+				target: "state",
+				method = "StorageRoot",
+				ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+				storage_root = %HexDisplay::from(&root.as_ref()),
+				cached = true,
 			);
 			return root.encode()
 		}
 
 		let root = self.overlay.storage_root(self.backend, self.storage_transaction_cache);
-		trace!(target: "state", "{:04x}: Root {}", self.id, HexDisplay::from(&root.as_ref()));
+		trace!(
+			target: "state",
+			method = "StorageRoot",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			storage_root = %HexDisplay::from(&root.as_ref()),
+			cached = false,
+		);
 		root.encode()
 	}
 
@@ -522,10 +554,13 @@ where
 				.storage(prefixed_storage_key.as_slice())
 				.and_then(|k| Decode::decode(&mut &k[..]).ok())
 				.unwrap_or_else(|| empty_child_trie_root::<Layout<H>>());
-			trace!(target: "state", "{:04x}: ChildRoot({})(cached) {}",
-				self.id,
-				HexDisplay::from(&storage_key),
-				HexDisplay::from(&root.as_ref()),
+			trace!(
+				target: "state",
+				method = "ChildStorageRoot",
+				ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+				child_info = %HexDisplay::from(&storage_key),
+				storage_root = %HexDisplay::from(&root.as_ref()),
+				cached = true,
 			);
 			root.encode()
 		} else {
@@ -549,11 +584,15 @@ where
 					self.overlay.set_storage(prefixed_storage_key.into_inner(), Some(root.clone()));
 				}
 
-				trace!(target: "state", "{:04x}: ChildRoot({}) {}",
-					self.id,
-					HexDisplay::from(&storage_key.as_ref()),
-					HexDisplay::from(&root.as_ref()),
+				trace!(
+					target: "state",
+					method = "ChildStorageRoot",
+					ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+					child_info = %HexDisplay::from(&storage_key.as_ref()),
+					storage_root = %HexDisplay::from(&root.as_ref()),
+					cached = false,
 				);
+
 				root
 			} else {
 				// empty overlay
@@ -561,11 +600,16 @@ where
 					.storage(prefixed_storage_key.as_slice())
 					.and_then(|k| Decode::decode(&mut &k[..]).ok())
 					.unwrap_or_else(|| empty_child_trie_root::<Layout<H>>());
-				trace!(target: "state", "{:04x}: ChildRoot({})(no_change) {}",
-					self.id,
-					HexDisplay::from(&storage_key.as_ref()),
-					HexDisplay::from(&root.as_ref()),
+
+				trace!(
+					target: "state",
+					method = "ChildStorageRoot",
+					ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+					child_info = %HexDisplay::from(&storage_key.as_ref()),
+					storage_root = %HexDisplay::from(&root.as_ref()),
+					cached = false,
 				);
+
 				root.encode()
 			}
 		}
@@ -574,12 +618,13 @@ where
 	fn storage_index_transaction(&mut self, index: u32, hash: &[u8], size: u32) {
 		trace!(
 			target: "state",
-			"{:04x}: IndexTransaction ({}): {}, {} bytes",
-			self.id,
-			index,
-			HexDisplay::from(&hash),
-			size,
+			method = "IndexTransaction",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			%index,
+			tx_hash = %HexDisplay::from(&hash),
+			%size,
 		);
+
 		self.overlay.add_transaction_index(IndexOperation::Insert {
 			extrinsic: index,
 			hash: hash.to_vec(),
@@ -591,11 +636,12 @@ where
 	fn storage_renew_transaction_index(&mut self, index: u32, hash: &[u8]) {
 		trace!(
 			target: "state",
-			"{:04x}: RenewTransactionIndex ({}): {}",
-			self.id,
-			index,
-			HexDisplay::from(&hash),
+			method = "RenewTransactionIndex",
+			ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+			%index,
+			tx_hash = %HexDisplay::from(&hash),
 		);
+
 		self.overlay
 			.add_transaction_index(IndexOperation::Renew { extrinsic: index, hash: hash.to_vec() });
 	}
@@ -612,10 +658,11 @@ where
 		{
 			trace!(
 				target: "state",
-				"{:04x}: ChangesRoot({})(cached) {:?}",
-				self.id,
-				HexDisplay::from(&parent_hash),
-				root,
+				method = "ChangesRoot",
+				ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+				parent_hash = %HexDisplay::from(&parent_hash),
+				?root,
+				cached = true,
 			);
 
 			Ok(Some(root.encode()))
@@ -626,8 +673,8 @@ where
 				Decode::decode(&mut parent_hash).map_err(|e| {
 					trace!(
 						target: "state",
-						"Failed to decode changes root parent hash: {}",
-						e,
+						error = %e,
+						"Failed to decode changes root parent hash",
 					)
 				})?,
 				true,
@@ -636,10 +683,11 @@ where
 
 			trace!(
 				target: "state",
-				"{:04x}: ChangesRoot({}) {:?}",
-				self.id,
-				HexDisplay::from(&parent_hash),
-				root,
+				method = "ChangesRoot",
+				ext_id = %HexDisplay::from(&self.id.to_le_bytes()),
+				parent_hash = %HexDisplay::from(&parent_hash),
+				?root,
+				cached = false,
 			);
 
 			root.map(|r| r.map(|o| o.encode()))

substrate/primitives/state-machine/src/lib.rs

@@ -172,7 +172,6 @@ mod execution {
 	use super::*;
 	use codec::{Codec, Decode, Encode};
 	use hash_db::Hasher;
-	use log::{trace, warn};
 	use sp_core::{
 		hexdisplay::HexDisplay,
 		storage::ChildInfo,
@@ -181,6 +180,7 @@ mod execution {
 	};
 	use sp_externalities::Extensions;
 	use std::{collections::HashMap, fmt, panic::UnwindSafe, result};
+	use tracing::{trace, warn};
 
 	const PROOF_CLOSE_TRANSACTION: &str = "\
 		Closing a transaction that was started in this function. Client initiated transactions
@@ -305,6 +305,10 @@ mod execution {
 		storage_transaction_cache: Option<&'a mut StorageTransactionCache<B::Transaction, H, N>>,
 		runtime_code: &'a RuntimeCode<'a>,
 		stats: StateMachineStats,
+		/// The hash of the block the state machine will be executed on.
+		///
+		/// Used for logging.
+		parent_hash: Option<H::Out>,
 	}
 
 	impl<'a, B, H, N, Exec> Drop for StateMachine<'a, B, H, N, Exec>
@@ -352,6 +356,7 @@ mod execution {
 				storage_transaction_cache: None,
 				runtime_code,
 				stats: StateMachineStats::default(),
+				parent_hash: None,
 			}
 		}
 
@@ -368,6 +373,14 @@ mod execution {
 			self
 		}
 
+		/// Set the given `parent_hash` as the hash of the parent block.
+		///
+		/// This will be used for improved logging.
+		pub fn set_parent_hash(mut self, parent_hash: H::Out) -> Self {
+			self.parent_hash = Some(parent_hash);
+			self
+		}
+
 		/// Execute a call using the given state backend, overlayed changes, and call executor.
 		///
 		/// On an error, no prospective changes are written to the overlay.
@@ -415,13 +428,15 @@ mod execution {
 				Some(&mut self.extensions),
 			);
 
-			let id = ext.id;
+			let ext_id = ext.id;
+
 			trace!(
-				target: "state", "{:04x}: Call {} at {:?}. Input={:?}",
-				id,
-				self.method,
-				self.backend,
-				HexDisplay::from(&self.call_data),
+				target: "state",
+				ext_id = %HexDisplay::from(&ext_id.to_le_bytes()),
+				method = %self.method,
+				parent_hash = %self.parent_hash.map(|h| format!("{:?}", h)).unwrap_or_else(|| String::from("None")),
+				input = ?HexDisplay::from(&self.call_data),
+				"Call",
 			);
 
 			let (result, was_native) = self.exec.call(
@@ -438,10 +453,11 @@ mod execution {
 				.expect("Runtime is not able to call this function in the overlay; qed");
 
 			trace!(
-				target: "state", "{:04x}: Return. Native={:?}, Result={:?}",
-				id,
-				was_native,
-				result,
+				target: "state",
+				ext_id = %HexDisplay::from(&ext_id.to_le_bytes()),
+				?was_native,
+				?result,
+				"Return",
 			);
 
 			(result, was_native)
@@ -554,7 +570,7 @@ mod execution {
 
 	/// Prove execution using the given state backend, overlayed changes, and call executor.
 	pub fn prove_execution<B, H, N, Exec, Spawn>(
-		mut backend: B,
+		backend: &mut B,
 		overlay: &mut OverlayedChanges,
 		exec: &Exec,
 		spawn_handle: Spawn,
@@ -1137,10 +1153,10 @@ mod tests {
 		};
 
 		// fetch execution proof from 'remote' full node
-		let remote_backend = trie_backend::tests::test_trie();
+		let mut remote_backend = trie_backend::tests::test_trie();
 		let remote_root = remote_backend.storage_root(std::iter::empty()).0;
 		let (remote_result, remote_proof) = prove_execution::<_, _, u64, _, _>(
-			remote_backend,
+			&mut remote_backend,
 			&mut Default::default(),
 			&executor,
 			TaskExecutor::new(),