From 0ad314f3d1aa648d7651030464a24ef21f1461d2 Mon Sep 17 00:00:00 2001 From: Felix Murer <9334190+murerfel@users.noreply.github.com> Date: Mon, 7 Nov 2022 08:40:40 +0100 Subject: [PATCH] Investigate and fix sidechain integration test failures (#1087) * Check remaining time before running AURA * Reduce block proposal / calls execution fraction to 0.7 (70%) * More log output for debugging timings on sidechain * Re-introduce sleeps on integration tests again --- cli/demo_direct_call.sh | 5 ++ cli/demo_sidechain.sh | 10 ++++ core-primitives/stf-executor/src/executor.rs | 3 +- docker/docker-compose.yml | 2 +- enclave-runtime/src/top_pool_execution.rs | 46 +++++++++++++------ sidechain/consensus/aura/src/lib.rs | 12 ++--- sidechain/consensus/slots/Cargo.toml | 2 +- sidechain/consensus/slots/src/lib.rs | 3 +- sidechain/consensus/slots/src/slots.rs | 44 ++++++++++++++---- sidechain/rpc-handler/src/import_block_api.rs | 3 +- sidechain/test/Cargo.toml | 2 +- 11 files changed, 98 insertions(+), 34 deletions(-) diff --git a/cli/demo_direct_call.sh b/cli/demo_direct_call.sh index 6c705491b6..9758c41945 100755 --- a/cli/demo_direct_call.sh +++ b/cli/demo_direct_call.sh @@ -89,6 +89,11 @@ echo "* Send ${AMOUNTTRANSFER} funds from Alice's incognito account to Bob's inc $CLIENT trusted --mrenclave ${MRENCLAVE} --direct transfer ${ICGACCOUNTALICE} ${ICGACCOUNTBOB} ${AMOUNTTRANSFER} echo "" +# Prevent getter being executed too early and returning an outdated result, before the transfer was made. +echo "* Waiting 2 seconds" +sleep 2 +echo "" + echo "* Get balance of Alice's incognito account" RESULT=$(${CLIENT} trusted --mrenclave ${MRENCLAVE} balance ${ICGACCOUNTALICE} | xargs) echo $RESULT diff --git a/cli/demo_sidechain.sh b/cli/demo_sidechain.sh index 90813407ff..357618dcb5 100755 --- a/cli/demo_sidechain.sh +++ b/cli/demo_sidechain.sh @@ -110,11 +110,21 @@ echo "* First transfer: Send ${AMOUNTTRANSFER} funds from Alice's incognito acco $CLIENTWORKER1 trusted --mrenclave ${MRENCLAVE} --direct transfer ${ICGACCOUNTALICE} ${ICGACCOUNTBOB} ${AMOUNTTRANSFER} echo "" +# Prevent nonce clash when sending direct trusted calls to different workers. +echo "* Waiting 2 seconds" +sleep 2 +echo "" + # Send funds from Alice to Bobs account, on worker 2. echo "* Second transfer: Send ${AMOUNTTRANSFER} funds from Alice's incognito account to Bob's incognito account (on worker 2)" $CLIENTWORKER2 trusted --mrenclave ${MRENCLAVE} --direct transfer ${ICGACCOUNTALICE} ${ICGACCOUNTBOB} ${AMOUNTTRANSFER} echo "" +# Prevent getter being executed too early and returning an outdated result, before the transfer was made. +echo "* Waiting 2 seconds" +sleep 2 +echo "" + echo "* Get balance of Alice's incognito account (on worker 1)" ALICE_BALANCE=$(${CLIENTWORKER1} trusted --mrenclave ${MRENCLAVE} balance ${ICGACCOUNTALICE} | xargs) echo "$ALICE_BALANCE" diff --git a/core-primitives/stf-executor/src/executor.rs b/core-primitives/stf-executor/src/executor.rs index 0962c3b73c..2a1c85048b 100644 --- a/core-primitives/stf-executor/src/executor.rs +++ b/core-primitives/stf-executor/src/executor.rs @@ -122,9 +122,10 @@ where .get_multiple_storages_verified(storage_hashes, header) .map(into_map)?; + debug!("Apply state diff with {} entries from parentchain block", update_map.len()); Stf::apply_state_diff(state, update_map.into()); - debug!("execute STF, call with nonce {}", trusted_call.nonce); + debug!("execute on STF, call with nonce {}", trusted_call.nonce); let mut extrinsic_call_backs: Vec = Vec::new(); if let Err(e) = Stf::execute_call( state, diff --git a/docker/docker-compose.yml b/docker/docker-compose.yml index 3f3db7fc6b..88b1ab1b13 100644 --- a/docker/docker-compose.yml +++ b/docker/docker-compose.yml @@ -23,7 +23,7 @@ services: /usr/local/bin/integritee-service --clean-reset --ws-external -M integritee-worker-1 -T wss://integritee-worker-1 -u ws://integritee-node -U ws://integritee-worker-1 -P 2011 -w 2101 -p 9912 -h 4645 run --dev --skip-ra" - restart: always + restart: "no" integritee-worker-2: image: integritee-worker:dev container_name: integritee-worker-2 diff --git a/enclave-runtime/src/top_pool_execution.rs b/enclave-runtime/src/top_pool_execution.rs index 3a72392d40..16ad023e52 100644 --- a/enclave-runtime/src/top_pool_execution.rs +++ b/enclave-runtime/src/top_pool_execution.rs @@ -108,14 +108,12 @@ fn execute_top_pool_trusted_calls_internal() -> Result<()> { let sidechain_block_import_queue_worker = GLOBAL_SIDECHAIN_IMPORT_QUEUE_WORKER_COMPONENT.get()?; - let sidechain_block_queue_start = Instant::now(); - let latest_parentchain_header = sidechain_block_import_queue_worker.process_queue(¤t_parentchain_header)?; info!( "Elapsed time to process sidechain block import queue: {} ms", - sidechain_block_queue_start.elapsed().as_millis() + start_time.elapsed().as_millis() ); let stf_executor = GLOBAL_STF_EXECUTOR_COMPONENT.get()?; @@ -132,8 +130,6 @@ fn execute_top_pool_trusted_calls_internal() -> Result<()> { let authority = Ed25519Seal::unseal_from_static_file()?; - info!("Elapsed time before AURA execution: {} ms", start_time.elapsed().as_millis()); - match yield_next_slot( slot_beginning_timestamp, SLOT_DURATION, @@ -141,12 +137,12 @@ fn execute_top_pool_trusted_calls_internal() -> Result<()> { &mut LastSlotSeal, )? { Some(slot) => { - let remaining_time = slot.ends_at - slot.timestamp; - info!( - "Remaining slot time for aura: {} ms, {}% of slot time", - remaining_time.as_millis(), - (remaining_time.as_millis() as f64 / slot.duration.as_millis() as f64) * 100f64 - ); + if slot.duration_remaining().is_none() { + warn!("No time remaining in slot, skipping AURA execution"); + return Ok(()) + } + + log_remaining_slot_duration(&slot, "Before AURA"); let shards = state_handler.list_shards()?; let env = ProposerFactory::::new( @@ -156,7 +152,7 @@ fn execute_top_pool_trusted_calls_internal() -> Result<()> { ); let (blocks, opaque_calls) = exec_aura_on_slot::<_, _, SignedSidechainBlock, _, _, _>( - slot, + slot.clone(), authority, ocall_api.clone(), parentchain_import_dispatcher, @@ -169,13 +165,17 @@ fn execute_top_pool_trusted_calls_internal() -> Result<()> { // Drop lock as soon as we don't need it anymore. drop(_enclave_write_lock); + log_remaining_slot_duration(&slot, "After AURA"); + send_blocks_and_extrinsics::( blocks, opaque_calls, ocall_api, validator_access.as_ref(), extrinsics_factory.as_ref(), - )? + )?; + + log_remaining_slot_duration(&slot, "After broadcasting and sending extrinsic"); }, None => { debug!("No slot yielded. Skipping block production."); @@ -271,3 +271,23 @@ where Ok(()) } + +fn log_remaining_slot_duration>( + slot_info: &SlotInfo, + stage_name: &str, +) { + match slot_info.duration_remaining() { + None => { + info!("No time remaining in slot (id: {:?}, stage: {})", slot_info.slot, stage_name); + }, + Some(remainder) => { + info!( + "Remaining time in slot (id: {:?}, stage {}): {} ms, {}% of slot time", + slot_info.slot, + stage_name, + remainder.as_millis(), + (remainder.as_millis() as f64 / slot_info.duration.as_millis() as f64) * 100f64 + ); + }, + }; +} diff --git a/sidechain/consensus/aura/src/lib.rs b/sidechain/consensus/aura/src/lib.rs index 973e7d9375..d4a508c1e3 100644 --- a/sidechain/consensus/aura/src/lib.rs +++ b/sidechain/consensus/aura/src/lib.rs @@ -104,7 +104,7 @@ impl SLOT_DURATION / 2 - && proposing_remaining_duration(&slot_info, duration_now()) - < SLOT_DURATION.mul_f32(BLOCK_PROPOSAL_SLOT_PORTION + 0.01) + proposing_remaining_duration(&slot_info, duration_now()) + < SLOT_DURATION.mul_f32(BLOCK_PROPOSAL_SLOT_PORTION + 0.01) ); } @@ -546,9 +545,8 @@ mod tests { let slot_info = now_slot_with_default_header(0.into()); assert!( - proposing_remaining_duration(&slot_info, Duration::from_millis(0)) > SLOT_DURATION / 2 - && proposing_remaining_duration(&slot_info, Duration::from_millis(0)) - < SLOT_DURATION.mul_f32(BLOCK_PROPOSAL_SLOT_PORTION + 0.01) + proposing_remaining_duration(&slot_info, Duration::from_millis(0)) + < SLOT_DURATION.mul_f32(BLOCK_PROPOSAL_SLOT_PORTION + 0.01) ); } diff --git a/sidechain/consensus/slots/Cargo.toml b/sidechain/consensus/slots/Cargo.toml index bbd0602531..4e91dab766 100644 --- a/sidechain/consensus/slots/Cargo.toml +++ b/sidechain/consensus/slots/Cargo.toml @@ -37,7 +37,7 @@ its-consensus-common = { path = "../common", default-features = false } itc-parentchain-test = { path = "../../../core/parentchain/test" } its-test = { path = "../../test" } sp-keyring = { git = "https://github.com/paritytech/substrate.git", branch = "polkadot-v0.9.28" } -tokio = "*" +tokio = { version = "1.6.1", features = ["full"] } [features] diff --git a/sidechain/consensus/slots/src/lib.rs b/sidechain/consensus/slots/src/lib.rs index f8b326b455..1f1b000ebe 100644 --- a/sidechain/consensus/slots/src/lib.rs +++ b/sidechain/consensus/slots/src/lib.rs @@ -271,7 +271,8 @@ pub trait SimpleSlotWorker { if !timestamp_within_slot(&slot_info, &proposing.block) { warn!( target: logging_target, - "⌛️ Discarding proposal for slot {}; block production took too long", *slot, + "⌛️ Discarding proposal for slot {}, block number {}; block production took too long", + *slot, proposing.block.block().header().block_number(), ); return None diff --git a/sidechain/consensus/slots/src/slots.rs b/sidechain/consensus/slots/src/slots.rs index 75be0a2425..4e14eed784 100644 --- a/sidechain/consensus/slots/src/slots.rs +++ b/sidechain/consensus/slots/src/slots.rs @@ -80,6 +80,14 @@ impl SlotInfo { last_imported_parentchain_head: parentchain_head, } } + + pub fn duration_remaining(&self) -> Option { + let duration_now = duration_now(); + if self.ends_at <= duration_now { + return None + } + Some(self.ends_at - duration_now) + } } /// The time at which the slot ends. @@ -199,7 +207,7 @@ mod tests { use core::assert_matches::assert_matches; use itc_parentchain_test::parentchain_header_builder::ParentchainHeaderBuilder; use itp_sgx_io::StaticSealedIO; - use itp_types::{Block as ParentchainBlock, Header as ParentchainHeader}; + use itp_types::Block as ParentchainBlock; use its_primitives::{ traits::{Block as BlockT, SignBlock}, types::block::{Block, SignedBlock}, @@ -244,13 +252,7 @@ mod tests { timestamp: duration_now(), duration: SLOT_DURATION, ends_at: duration_now() + SLOT_DURATION, - last_imported_parentchain_head: ParentchainHeader { - parent_hash: Default::default(), - number: 1, - state_root: Default::default(), - extrinsics_root: Default::default(), - digest: Default::default(), - }, + last_imported_parentchain_head: ParentchainHeaderBuilder::default().build(), } } @@ -306,6 +308,32 @@ mod tests { ); } + #[test] + fn duration_remaing_returns_none_if_ends_at_is_in_the_past() { + let slot: SlotInfo = SlotInfo { + slot: 1.into(), + timestamp: duration_now() - Duration::from_secs(5), + duration: SLOT_DURATION, + ends_at: duration_now() + SLOT_DURATION - Duration::from_secs(5), + last_imported_parentchain_head: ParentchainHeaderBuilder::default().build(), + }; + assert!(slot.duration_remaining().is_none()); + } + + #[test] + fn duration_remaining_returns_some_if_ends_at_is_in_the_future() { + let slot: SlotInfo = SlotInfo { + slot: 1.into(), + timestamp: duration_now() - Duration::from_secs(5), + duration: SLOT_DURATION, + ends_at: duration_now() + Duration::from_secs(60), + last_imported_parentchain_head: ParentchainHeaderBuilder::default().build(), + }; + let maybe_duration_remaining = slot.duration_remaining(); + assert!(maybe_duration_remaining.is_some()); + assert!(maybe_duration_remaining.unwrap() > Duration::from_secs(30)); + } + #[test] fn slot_info_ends_at_does_is_correct_even_if_delay_is_more_than_slot_duration() { let timestamp = duration_now(); diff --git a/sidechain/rpc-handler/src/import_block_api.rs b/sidechain/rpc-handler/src/import_block_api.rs index 9dc14e3158..a34ff829ef 100644 --- a/sidechain/rpc-handler/src/import_block_api.rs +++ b/sidechain/rpc-handler/src/import_block_api.rs @@ -46,9 +46,10 @@ where ) })?; - info!("{}. Blocks: {:?}", RPC_METHOD_NAME_IMPORT_BLOCKS, blocks); + debug!("{}. Blocks: {:?}", RPC_METHOD_NAME_IMPORT_BLOCKS, blocks); for block in blocks { + info!("Add block {} to import queue", block.block.header.block_number); let _ = import_fn(block).map_err(|e| { let error = jsonrpc_core::error::Error::invalid_params_with_details( "Failed to import Block.", diff --git a/sidechain/test/Cargo.toml b/sidechain/test/Cargo.toml index f71926cb2f..89aff2efff 100644 --- a/sidechain/test/Cargo.toml +++ b/sidechain/test/Cargo.toml @@ -18,7 +18,7 @@ sp-core = { default_features = false, git = "https://github.com/paritytech/subst # local itp-types = { path = "../../core-primitives/types", default_features = false } -its-primitives = { path = "../primitives", default_features = false } +its-primitives = { path = "../primitives", default_features = false, features = ["full_crypto"] } [features] default = ["std"]