diff --git a/substrate/client/api/src/call_executor.rs b/substrate/client/api/src/call_executor.rs index 2d19c9fe35..a19df74326 100644 --- a/substrate/client/api/src/call_executor.rs +++ b/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 { /// No changes are made. fn runtime_version(&self, id: &BlockId) -> Result; - /// 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>>( + fn prove_execution( &self, - mut state: S, - overlay: &mut OverlayedChanges, - method: &str, - call_data: &[u8], - ) -> Result<(Vec, 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>>( - &self, - trie_state: &sp_state_machine::TrieBackend>, - overlay: &mut OverlayedChanges, + at: &BlockId, method: &str, call_data: &[u8], ) -> Result<(Vec, StorageProof), sp_blockchain::Error>; diff --git a/substrate/client/light/src/call_executor.rs b/substrate/client/light/src/call_executor.rs index f666d83631..144e0cbf96 100644 --- a/substrate/client/light/src/call_executor.rs +++ b/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, ) -> ClientResult> { - 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, Local::Error>, Result, 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, + method: &str, + call_data: &[u8], + ) -> ClientResult<(Vec, 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) -> ClientResult { - 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>>( - &self, - _state: &sp_state_machine::TrieBackend>, - _changes: &mut OverlayedChanges, - _method: &str, - _call_data: &[u8], - ) -> ClientResult<(Vec, 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( - mut state: S, - executor: &E, - method: &str, - call_data: &[u8], -) -> ClientResult<(Vec, StorageProof)> -where - Block: BlockT, - S: StateBackend>, - E: CallExecutor, -{ - let trie_state = state.as_trie_backend().ok_or_else(|| { - Box::new(sp_state_machine::ExecutionError::UnableToGenerateProof) - as Box - })?; - - // 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( remote_proof: StorageProof, ) -> ClientResult> where - Header: HeaderT, + Header: HeaderT, E: CodeExecutor + Clone + 'static, H: Hasher, H::Out: Ord + codec::Codec + 'static, diff --git a/substrate/client/light/src/fetcher.rs b/substrate/client/light/src/fetcher.rs index fcdc7ad7ba..5740e407a5 100644 --- a/substrate/client/light/src/fetcher.rs +++ b/substrate/client/light/src/fetcher.rs @@ -53,21 +53,21 @@ pub use sc_client_api::{ }; /// Remote data checker. -pub struct LightDataChecker> { +pub struct LightDataChecker> { blockchain: Arc>, executor: E, spawn_handle: Box, - _hasher: PhantomData<(B, H)>, + _marker: PhantomData, } -impl> LightDataChecker { +impl> LightDataChecker { /// Create new light data checker. pub fn new( blockchain: Arc>, executor: E, spawn_handle: Box, ) -> 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> LightDataChecker { request: &RemoteChangesRequest, remote_proof: ChangesProof, cht_size: NumberFor, - ) -> ClientResult, u32)>> - where - H: Hasher, - H::Out: Ord + codec::Codec, - { + ) -> ClientResult, 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> LightDataChecker { 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::( + let result_range = key_changes_proof_check_with_db::, _>( ChangesTrieConfigurationRange { config: config_range .config @@ -171,11 +167,7 @@ impl> LightDataChecker { cht_size: NumberFor, remote_roots: &BTreeMap, 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> LightDataChecker { // 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::( + cht::check_proof_on_proving_backend::>( local_cht_root, block, remote_changes_trie_root, @@ -231,12 +221,10 @@ impl> LightDataChecker { } } -impl FetchChecker for LightDataChecker +impl FetchChecker for LightDataChecker where Block: BlockT, E: CodeExecutor + Clone + 'static, - H: Hasher, - H::Out: Ord + codec::Codec + 'static, S: BlockchainStorage, { 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::( + cht::check_proof::>( request.cht_root, request.block, remote_header_hash, @@ -262,7 +250,7 @@ where request: &RemoteReadRequest, remote_proof: StorageProof, ) -> ClientResult, Option>>> { - read_proof_check::( + read_proof_check::, _>( 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::( + read_child_proof_check::, _>( convert_hash(request.header.state_root()), remote_proof, &child_info, @@ -293,7 +281,7 @@ where request: &RemoteCallRequest, remote_proof: StorageProof, ) -> ClientResult> { - check_execution_proof::<_, _, H>( + check_execution_proof::<_, _, HashFor>( &self.executor, self.spawn_handle.clone(), request, diff --git a/substrate/client/light/src/lib.rs b/substrate/client/light/src/lib.rs index ed48c05258..0c874326ef 100644 --- a/substrate/client/light/src/lib.rs +++ b/substrate/client/light/src/lib.rs @@ -37,7 +37,7 @@ pub fn new_fetch_checker>( blockchain: Arc>, executor: E, spawn_handle: Box, -) -> LightDataChecker, B, S> +) -> LightDataChecker where E: CodeExecutor, { diff --git a/substrate/client/service/src/client/call_executor.rs b/substrate/client/service/src/client/call_executor.rs index 6d4fe3c360..2fae972d34 100644 --- a/substrate/client/service/src/client/call_executor.rs +++ b/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, + at: &BlockId, method: &str, call_data: &[u8], strategy: ExecutionStrategy, @@ -154,12 +154,17 @@ where ) -> sp_blockchain::Result> { 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>>( + fn prove_execution( &self, - trie_state: &sp_state_machine::TrieBackend>, - overlay: &mut OverlayedChanges, + at: &BlockId, method: &str, call_data: &[u8], - ) -> Result<(Vec, StorageProof), sp_blockchain::Error> { - let state_runtime_code = sp_state_machine::backend::BackendRuntimeCode::new(trie_state); + ) -> sp_blockchain::Result<(Vec, 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 + })?; + + 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, _, _>( - trie_state, - overlay, + &trie_backend, + &mut Default::default(), &self.executor, self.spawn_handle.clone(), method, diff --git a/substrate/client/service/src/client/client.rs b/substrate/client/service/src/client/client.rs index 901321f395..a0d294908c 100644 --- a/substrate/client/service/src/client/client.rs +++ b/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]))) } diff --git a/substrate/client/service/test/src/client/light.rs b/substrate/client/service/test/src/client/light.rs index 8d1411214d..90f87670c0 100644 --- a/substrate/client/service/test/src/client/light.rs +++ b/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 for DummyCallExecutor { unreachable!() } - fn prove_at_trie_state>>( + fn prove_execution( &self, - _trie_state: &sp_state_machine::TrieBackend>, - _overlay: &mut OverlayedChanges, - _method: &str, - _call_data: &[u8], + _: &BlockId, + _: &str, + _: &[u8], ) -> Result<(Vec, StorageProof), ClientError> { unreachable!() } @@ -452,7 +451,6 @@ fn code_is_executed_at_genesis_only() { type TestChecker = LightDataChecker< NativeExecutor, - BlakeTwo256, Block, DummyStorage, >; diff --git a/substrate/primitives/state-machine/src/ext.rs b/substrate/primitives/state-machine/src/ext.rs index e5dee79091..5f22714d4d 100644 --- a/substrate/primitives/state-machine/src/ext.rs +++ b/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, ) { - 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) -> (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) -> (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, ) -> (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, value: Vec) { - 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 { 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::>()); - 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::>()); - 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())) diff --git a/substrate/primitives/state-machine/src/lib.rs b/substrate/primitives/state-machine/src/lib.rs index 924ceaf9d8..1588a42f41 100644 --- a/substrate/primitives/state-machine/src/lib.rs +++ b/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>, 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, } 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( - 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(),