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

@@ -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

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"

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<OpaqueCall> = Vec::new();
 		if let Err(e) = Stf::execute_call(
 			state,

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

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(&current_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,21 +130,19 @@ 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,
 		latest_parentchain_header,
 		&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::<Block, _, _, _>::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::<Block, _, _, _, _>(
 				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<B: BlockTrait<Hash = H256>>(
+	slot_info: &SlotInfo<B>,
+	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
+			);
+		},
+	};
+}

sidechain/consensus/aura/src/lib.rs

@@ -104,7 +104,7 @@ impl<AuthorityPair, ParentchainBlock, SidechainBlock, Environment, OcallApi, Imp
 
 /// The fraction of total block time we are allowed to be producing the block. So that we have
 /// enough time send create and send the block to fellow validateers.
-pub const BLOCK_PROPOSAL_SLOT_PORTION: f32 = 0.8;
+pub const BLOCK_PROPOSAL_SLOT_PORTION: f32 = 0.7;
 
 #[derive(PartialEq, Eq, Debug)]
 pub enum SlotClaimStrategy {
@@ -535,9 +535,8 @@ mod tests {
 
 		// hard to compare actual numbers but we can at least ensure that the general concept works
 		assert!(
-			proposing_remaining_duration(&slot_info, duration_now()) > 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)
 		);
 	}
 

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]

sidechain/consensus/slots/src/lib.rs

@@ -271,7 +271,8 @@ pub trait SimpleSlotWorker<ParentchainBlock: ParentchainBlockTrait> {
 		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

sidechain/consensus/slots/src/slots.rs

@@ -80,6 +80,14 @@ impl<ParentchainBlock: ParentchainBlockTrait> SlotInfo<ParentchainBlock> {
 			last_imported_parentchain_head: parentchain_head,
 		}
 	}
+
+	pub fn duration_remaining(&self) -> Option<Duration> {
+		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<ParentchainBlock> = 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<ParentchainBlock> = 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();

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.",

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"]