diff --git a/rs/execution_environment/src/execution/call_or_task.rs b/rs/execution_environment/src/execution/call_or_task.rs index e7b3a4bce6b8..fecb9d812a8a 100644 --- a/rs/execution_environment/src/execution/call_or_task.rs +++ b/rs/execution_environment/src/execution/call_or_task.rs @@ -228,7 +228,7 @@ pub fn execute_call_or_task( }; let paused_execution = Box::new(PausedCallOrTaskExecution { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), original, }); ExecuteMessageResult::Paused { @@ -322,6 +322,7 @@ struct OriginalContext { struct PausedCallOrTaskHelper { call_context_id: CallContextId, initial_cycles_balance: Cycles, + executed_wasm_instructions: NumInstructions, } /// A helper that implements and keeps track of update call steps. @@ -330,6 +331,12 @@ struct CallOrTaskHelper { canister: CanisterState, call_context_id: CallContextId, initial_cycles_balance: Cycles, + // Instructions already executed by a Wasm execution that has been paused and + // has not finished yet. Such instructions are not reflected in the + // instruction limits because those are updated only when the Wasm execution + // finishes, so they are tracked here in order to be charged if the execution + // fails before the Wasm execution finishes. + executed_wasm_instructions: NumInstructions, deallocation_sender: DeallocationSender, } @@ -412,17 +419,22 @@ impl CallOrTaskHelper { canister, call_context_id, initial_cycles_balance, + executed_wasm_instructions: NumInstructions::new(0), deallocation_sender: deallocation_sender.clone(), }) } /// Returns a struct with all the necessary information to replay the /// performed update call steps in subsequent rounds. - fn pause(self) -> PausedCallOrTaskHelper { + /// The given `executed_wasm_instructions` are the instructions executed by + /// the Wasm slice that is being paused. + fn pause(self, executed_wasm_instructions: NumInstructions) -> PausedCallOrTaskHelper { self.deallocation_sender.send(Box::new(self.canister)); PausedCallOrTaskHelper { call_context_id: self.call_context_id, initial_cycles_balance: self.initial_cycles_balance, + executed_wasm_instructions: self.executed_wasm_instructions + + executed_wasm_instructions, } } @@ -435,7 +447,8 @@ impl CallOrTaskHelper { paused: PausedCallOrTaskHelper, deallocation_sender: &DeallocationSender, ) -> Result { - let helper = Self::new(clean_canister, original, deallocation_sender)?; + let mut helper = Self::new(clean_canister, original, deallocation_sender)?; + helper.executed_wasm_instructions = paused.executed_wasm_instructions; if helper.initial_cycles_balance != paused.initial_cycles_balance { let msg = match original.call_or_task { CanisterCallOrTask::Update(_) => { @@ -717,6 +730,11 @@ impl PausedExecution for PausedCallOrTaskExecution { self.original.method, clean_canister.canister_id(), ); + // If resuming fails, then the instructions already executed by the paused + // Wasm execution are still charged: they have been executed and hence + // consumed round instructions, but the instruction limits are updated + // only when the Wasm execution finishes. + let executed_wasm_instructions = self.paused_helper.executed_wasm_instructions; let helper = match CallOrTaskHelper::resume( &clean_canister, &self.original, @@ -733,16 +751,15 @@ impl PausedExecution for PausedCallOrTaskExecution { err, ); self.paused_wasm_execution.abort(); - return finish_err( - clean_canister, + let instructions_left = NumInstructions::new( self.original .execution_parameters .instruction_limits - .message(), - err, - self.original, - round, + .message() + .get() + .saturating_sub(executed_wasm_instructions.get()), ); + return finish_err(clean_canister, instructions_left, err, self.original, round); } }; @@ -760,7 +777,7 @@ impl PausedExecution for PausedCallOrTaskExecution { update_round_limits(round_limits, &slice); let paused_execution = Box::new(PausedCallOrTaskExecution { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), original: self.original, }); ExecuteMessageResult::Paused { diff --git a/rs/execution_environment/src/execution/call_or_task/tests.rs b/rs/execution_environment/src/execution/call_or_task/tests.rs index fb5d8e0219f8..e75609376082 100644 --- a/rs/execution_environment/src/execution/call_or_task/tests.rs +++ b/rs/execution_environment/src/execution/call_or_task/tests.rs @@ -720,73 +720,6 @@ fn hitting_access_limit_fails_non_replicated_query() { ); } -#[test] -fn dts_replicated_execution_resume_fails_due_to_cycles_change() { - with_update_and_replicated_query(|method| { - // Test steps: - // 1. Canister A starts running the update|query method. - // 2. While canister A is paused, we change its cycles balance. - // 3. The update|query method resumes, detects the cycles balance mismatch, and - // fails. - let instruction_limit = 1_000_000; - let mut test = ExecutionTestBuilder::new() - .with_instruction_limit(instruction_limit) - .with_slice_instruction_limit(200_000) - .with_manual_execution() - .build(); - - let a_id = test.universal_canister().unwrap(); - - let a = wasm() - .stable64_grow(1) - .stable64_fill(0, 0, 50_000) - .stable64_fill(0, 0, 50_000) - .stable64_fill(0, 0, 50_000) - .stable64_fill(0, 0, 50_000) - .stable64_fill(0, 0, 50_000) - .stable64_fill(0, 0, 50_000) - .stable64_fill(0, 0, 50_000) - .stable64_fill(0, 0, 50_000) - .build(); - - let (ingress_id, _) = test.ingress_raw(a_id, method, a); - - test.execute_slice(a_id); - assert_eq!( - test.canister_state(a_id).next_execution(), - NextExecution::ContinueLong, - ); - - // Change the cycles balance of the clean canister. - let balance = test.canister_state(a_id).system_state.balance(); - test.canister_state_mut(a_id) - .system_state - .add_cycles(balance + Cycles::new(1)); - - test.execute_slice(a_id); - - assert_eq!( - test.canister_state(a_id).next_execution(), - NextExecution::None, - ); - - let err = check_ingress_status(test.ingress_status(&ingress_id)).unwrap_err(); - let message = if method == "update" { - "an update call" - } else { - "a replicated query" - }; - err.assert_contains( - ErrorCode::CanisterWasmEngineError, - &format!( - "Error from Canister {a_id}: Canister encountered a Wasm engine error: \ - Failed to apply system changes: Mismatch in cycles \ - balance when resuming {message}" - ), - ); - }); -} - #[test] fn dts_replicated_execution_resume_fails_due_to_call_context_change() { with_update_and_replicated_query(|method| { diff --git a/rs/execution_environment/src/execution/install.rs b/rs/execution_environment/src/execution/install.rs index 4570e8adaff1..fd7bcf3a94fd 100644 --- a/rs/execution_environment/src/execution/install.rs +++ b/rs/execution_environment/src/execution/install.rs @@ -204,7 +204,7 @@ pub(crate) fn execute_install( ingress_status_with_processing_state(&original.message, original.time); let paused_execution = Box::new(PausedStartExecutionDuringInstall { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), context_sender, context_arg: context.arg, original, @@ -322,7 +322,7 @@ fn install_stage_2b_continue_install_after_start( let ingress_status = ingress_status_with_processing_state(&original.message, original.time); let paused_execution = Box::new(PausedInitExecution { - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), paused_wasm_execution, original, }); @@ -440,7 +440,7 @@ impl PausedInstallCodeExecution for PausedInitExecution { update_round_limits(round_limits, &slice); let paused_execution = Box::new(PausedInitExecution { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), ..*self }); DtsInstallCodeResult::Paused { @@ -550,7 +550,7 @@ impl PausedInstallCodeExecution for PausedStartExecutionDuringInstall { ); let paused_execution = Box::new(PausedStartExecutionDuringInstall { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), ..*self }); DtsInstallCodeResult::Paused { diff --git a/rs/execution_environment/src/execution/install_code.rs b/rs/execution_environment/src/execution/install_code.rs index 81a006fa0e6f..46502312501d 100644 --- a/rs/execution_environment/src/execution/install_code.rs +++ b/rs/execution_environment/src/execution/install_code.rs @@ -27,6 +27,7 @@ use ic_types::{ CanisterLog, CanisterTimer, MemoryAllocation, NumInstructions, Time, messages::CanisterCall, }; use ic_types_cycles::{CompoundCycles, Cycles, CyclesUseCase, Instructions}; +use ic_wasm_types::WasmEngineError::FailedToApplySystemChanges; use ic_wasm_types::WasmHash; use crate::{ @@ -103,6 +104,8 @@ pub(crate) enum InstallCodeStep { pub(crate) struct PausedInstallCodeHelper { steps: Vec, instructions_left: NumInstructions, + initial_cycles_balance: Cycles, + executed_wasm_instructions: NumInstructions, } /// A helper that implements and keeps track of `install_code` steps. @@ -124,12 +127,21 @@ pub(crate) struct InstallCodeHelper { deallocated_wasm_custom_sections_bytes: NumBytes, // The total heap delta of all steps. total_heap_delta: NumBytes, + // The cycles balance of the clean canister state this helper was built from. + initial_cycles_balance: Cycles, + // Instructions already executed by a Wasm execution that has been paused and + // has not finished yet. Such instructions are not reflected in + // `execution_parameters` because the instruction limits are updated only + // when the Wasm execution finishes, so they are tracked here in order to be + // charged if the execution fails before the Wasm execution finishes. + executed_wasm_instructions: NumInstructions, } impl InstallCodeHelper { pub fn new(clean_canister: &CanisterState, original: &OriginalContext) -> Self { Self { steps: vec![], + initial_cycles_balance: clean_canister.system_state.balance(), canister: clean_canister.clone(), message_instruction_limit: original.execution_parameters.instruction_limits.message(), execution_parameters: original.execution_parameters.clone(), @@ -139,6 +151,7 @@ impl InstallCodeHelper { deallocated_bytes: NumBytes::new(0), deallocated_wasm_custom_sections_bytes: NumBytes::new(0), total_heap_delta: NumBytes::new(0), + executed_wasm_instructions: NumInstructions::new(0), } } @@ -233,16 +246,23 @@ impl InstallCodeHelper { /// Returns a struct with all the necessary information to replay the /// performed `install_code` steps in subsequent rounds. - pub fn pause(self) -> PausedInstallCodeHelper { + /// The given `executed_wasm_instructions` are the instructions executed by + /// the Wasm slice that is being paused. + pub fn pause(self, executed_wasm_instructions: NumInstructions) -> PausedInstallCodeHelper { PausedInstallCodeHelper { instructions_left: self.instructions_left(), steps: self.steps, + initial_cycles_balance: self.initial_cycles_balance, + executed_wasm_instructions: self.executed_wasm_instructions + + executed_wasm_instructions, } } /// Replays the previous `install_code` steps on the given clean canister. - /// Returns an error if any step fails. Otherwise, it returns an instance of - /// the helper that can be used to continue the `install_code` execution. + /// Returns an error if the cycles balance of the clean canister differs from + /// the cycles balance at the start of the DTS execution or if any step + /// fails. Otherwise, it returns an instance of the helper that can be used + /// to continue the `install_code` execution. #[allow(clippy::result_large_err)] pub fn resume( clean_canister: &CanisterState, @@ -259,12 +279,36 @@ impl InstallCodeHelper { > { let mut helper = Self::new(clean_canister, original); let paused_instructions_left = paused.instructions_left; + let executed_wasm_instructions = paused.executed_wasm_instructions; + // If resuming fails, then the instructions already executed by the paused + // Wasm execution are charged in addition to the instructions accounted + // for in `paused_instructions_left`: they have been executed and hence + // consumed round instructions, but the instruction limits of the helper + // are updated only when the Wasm execution finishes. + let instructions_left_on_error = NumInstructions::new( + paused_instructions_left + .get() + .saturating_sub(executed_wasm_instructions.get()), + ); + + // The cycles balance of the clean canister must not change during the + // DTS execution. + if helper.initial_cycles_balance != paused.initial_cycles_balance { + let msg = "Mismatch in cycles balance when resuming an install code".to_string(); + let err = HypervisorError::WasmEngineError(FailedToApplySystemChanges(msg)); + let err = (clean_canister.canister_id(), err).into(); + return Err((err, instructions_left_on_error, helper.take_canister_log())); + } + for state_change in paused.steps.into_iter() { helper .replay_step(state_change, original, round) - .map_err(|err| (err, paused_instructions_left, helper.take_canister_log()))?; + .map_err(|err| (err, instructions_left_on_error, helper.take_canister_log()))?; } debug_assert_eq!(paused_instructions_left, helper.instructions_left()); + // Replaying the steps of a Wasm execution that has already finished resets + // this counter, so it is restored after replaying all the steps. + helper.executed_wasm_instructions = executed_wasm_instructions; Ok(helper) } @@ -654,6 +698,9 @@ impl InstallCodeHelper { self.execution_parameters .instruction_limits .update(output.num_instructions_left); + // The instructions of all the slices of this Wasm execution are now + // reflected in the instruction limits above. + self.executed_wasm_instructions = NumInstructions::new(0); debug_assert!( output diff --git a/rs/execution_environment/src/execution/install_code/tests.rs b/rs/execution_environment/src/execution/install_code/tests.rs index 6d78ab13d4f0..a41b01ae641b 100644 --- a/rs/execution_environment/src/execution/install_code/tests.rs +++ b/rs/execution_environment/src/execution/install_code/tests.rs @@ -125,6 +125,62 @@ fn dts_resume_works_in_install_code() { assert_eq!(result, WasmResult::Reply(EmptyBlob.encode())); } +/// Analogously to `dts_resume_fails_due_to_cycles_decrease` for calls, +/// replicated queries, callbacks, and tasks, resuming a paused `install_code` +/// whose canister lost cycles while it was paused fails instead of replaying the +/// recorded steps on a balance that can no longer cover them. +#[test] +fn dts_install_code_resume_fails_due_to_cycles_decrease() { + const INSTRUCTION_LIMIT: u64 = 50_000_000; + let mut test = ExecutionTestBuilder::new() + .with_install_code_instruction_limit(INSTRUCTION_LIMIT) + .with_install_code_slice_instruction_limit(132_000) + .with_create_execution_state_base_cost(0) + .with_manual_execution() + .build(); + let canister_id = test.create_canister(Cycles::new(1_000_000_000_000_000)); + let payload = InstallCodeArgs { + mode: CanisterInstallMode::Install, + canister_id: canister_id.get(), + wasm_module: wat::parse_str(DTS_INSTALL_WAT).unwrap(), + arg: vec![], + sender_canister_version: None, + }; + let ingress_id = test.dts_install_code(payload); + + // The first slice has been executed and the execution is paused. + assert_eq!( + test.canister_state(canister_id).next_execution(), + NextExecution::ContinueInstallCode + ); + assert!(test.canister_state(canister_id).has_paused_install_code()); + + // Decrease the cycles balance of the clean canister. + test.canister_state_mut(canister_id) + .system_state + .remove_cycles(Cycles::new(1)); + + // The next slice detects the cycles balance mismatch and fails the execution. + test.execute_slice(canister_id); + assert_eq!( + test.canister_state(canister_id).next_execution(), + NextExecution::None + ); + + let err = check_ingress_status(test.ingress_status(&ingress_id)).unwrap_err(); + err.assert_contains( + ErrorCode::CanisterWasmEngineError, + &format!( + "Error from Canister {canister_id}: Canister encountered a Wasm engine error: \ + Failed to apply system changes: Mismatch in cycles \ + balance when resuming an install code" + ), + ); + + // The canister has no code installed. + assert!(test.canister_state(canister_id).execution_state.is_none()); +} + #[test] fn dts_abort_works_in_install_code() { const INSTRUCTION_LIMIT: u64 = 50_000_000; diff --git a/rs/execution_environment/src/execution/response.rs b/rs/execution_environment/src/execution/response.rs index 59ccfe6bc0da..b1eb249de445 100644 --- a/rs/execution_environment/src/execution/response.rs +++ b/rs/execution_environment/src/execution/response.rs @@ -114,6 +114,7 @@ struct PausedResponseHelper { refund_for_response_transmission: CompoundCycles, initial_cycles_balance: Cycles, response_sender: CanisterId, + executed_wasm_instructions: NumInstructions, } /// A helper that implements and keeps track of response execution steps. @@ -126,6 +127,12 @@ struct ResponseHelper { refund_for_response_transmission: CompoundCycles, initial_cycles_balance: Cycles, response_sender: CanisterId, + // Instructions already executed by a Wasm execution that has been paused and + // has not finished yet. Such instructions are not reflected in the + // instruction limits because those are updated only when the Wasm execution + // finishes, so they are tracked here in order to be charged if the execution + // fails before the Wasm execution finishes. + executed_wasm_instructions: NumInstructions, applied_subnet_memory_reservation: NumBytes, deallocation_sender: DeallocationSender, } @@ -193,6 +200,7 @@ impl ResponseHelper { refund_for_response_transmission, initial_cycles_balance, response_sender, + executed_wasm_instructions: NumInstructions::new(0), applied_subnet_memory_reservation: NumBytes::new(0), deallocation_sender: deallocation_sender.clone(), }; @@ -295,7 +303,13 @@ impl ResponseHelper { /// Returns a struct with all the necessary information to replay the /// initial steps in subsequent rounds. - fn pause(self, round_limits: &mut RoundLimits) -> PausedResponseHelper { + /// The given `executed_wasm_instructions` are the instructions executed by + /// the Wasm slice that is being paused. + fn pause( + self, + round_limits: &mut RoundLimits, + executed_wasm_instructions: NumInstructions, + ) -> PausedResponseHelper { self.revert_subnet_memory_reservation(round_limits); self.deallocation_sender.send(Box::new(self.canister)); PausedResponseHelper { @@ -305,9 +319,19 @@ impl ResponseHelper { refund_for_response_transmission: self.refund_for_response_transmission, initial_cycles_balance: self.initial_cycles_balance, response_sender: self.response_sender, + executed_wasm_instructions: self.executed_wasm_instructions + + executed_wasm_instructions, } } + /// Resets the instructions executed by a paused Wasm execution because a new + /// Wasm execution (the cleanup callback) is about to start and the + /// instructions of the previous one are already reflected in the instruction + /// limits of the new one. + fn start_new_wasm_execution(&mut self) { + self.executed_wasm_instructions = NumInstructions::new(0); + } + /// Replays validation and the initial steps on the given clean canister and /// returns the helper to continue the DTS execution. /// @@ -346,6 +370,7 @@ impl ResponseHelper { refund_for_response_transmission: paused.refund_for_response_transmission, initial_cycles_balance: clean_canister.system_state.balance(), response_sender: paused.response_sender, + executed_wasm_instructions: paused.executed_wasm_instructions, applied_subnet_memory_reservation: NumBytes::new(0), deallocation_sender: deallocation_sender.clone(), }; @@ -746,6 +771,11 @@ impl PausedExecution for PausedResponseExecution { // The height of the `clean_canister` state increases with every call of // `resume()`. We re-create the helper based on `clean_canister` so that // the Wasm state changes are applied to the up-to-date state. + // If resuming fails, then the instructions already executed by the paused + // Wasm execution are still charged: they have been executed and hence + // consumed round instructions, but the instruction limits are updated + // only when the Wasm execution finishes. + let executed_wasm_instructions = self.helper.executed_wasm_instructions; let (helper, result) = match ResponseHelper::resume( self.helper, &clean_canister, @@ -768,10 +798,14 @@ impl PausedExecution for PausedResponseExecution { err, ); self.paused_wasm_execution.abort(); - let result = wasm_execution_error( - err, - self.execution_parameters.instruction_limits.message(), + let instructions_left = NumInstructions::new( + self.execution_parameters + .instruction_limits + .message() + .get() + .saturating_sub(executed_wasm_instructions.get()), ); + let result = wasm_execution_error(err, instructions_left); (helper, result) } }; @@ -861,6 +895,11 @@ impl PausedExecution for PausedCleanupExecution { // // Note that we don't apply changes from the response callback execution // because the cleanup callback runs only if the response callback fails. + // If resuming fails, then the instructions already executed by the paused + // Wasm execution are still charged: they have been executed and hence + // consumed round instructions, but the instruction limits are updated + // only when the Wasm execution finishes. + let executed_wasm_instructions = self.helper.executed_wasm_instructions; let (helper, result) = match ResponseHelper::resume( self.helper, &clean_canister, @@ -883,10 +922,14 @@ impl PausedExecution for PausedCleanupExecution { err, ); self.paused_wasm_execution.abort(); - let result = wasm_execution_error( - err, - self.execution_parameters.instruction_limits.message(), + let instructions_left = NumInstructions::new( + self.execution_parameters + .instruction_limits + .message() + .get() + .saturating_sub(executed_wasm_instructions.get()), ); + let result = wasm_execution_error(err, instructions_left); (helper, result) } }; @@ -1091,7 +1134,7 @@ fn reserve_cleanup_instructions( #[allow(clippy::too_many_arguments)] fn execute_response_cleanup( clean_canister: CanisterState, - helper: ResponseHelper, + mut helper: ResponseHelper, cleanup_closure: WasmClosure, callback_err: HypervisorError, instructions_left: NumInstructions, @@ -1104,6 +1147,9 @@ fn execute_response_cleanup( execution_parameters .instruction_limits .update(instructions_left); + // The instructions executed by the response callback are reflected in the + // instruction limits updated above. + helper.start_new_wasm_execution(); let func_ref = match original.call_origin { CallOrigin::Ingress(..) | CallOrigin::CanisterUpdate(..) | CallOrigin::SystemTask => { FuncRef::UpdateClosure(cleanup_closure) @@ -1176,7 +1222,7 @@ fn process_response_result( update_round_limits(round_limits, &slice); let paused_execution = Box::new(PausedResponseExecution { paused_wasm_execution, - helper: helper.pause(round_limits), + helper: helper.pause(round_limits, slice.executed_instructions), execution_parameters, reserved_cleanup_instructions, original, @@ -1276,7 +1322,7 @@ fn process_cleanup_result( update_round_limits(round_limits, &slice); let paused_execution = Box::new(PausedCleanupExecution { paused_wasm_execution, - helper: helper.pause(round_limits), + helper: helper.pause(round_limits, slice.executed_instructions), execution_parameters, callback_err, original, diff --git a/rs/execution_environment/src/execution/upgrade.rs b/rs/execution_environment/src/execution/upgrade.rs index b84742d07dda..9c8139da21d5 100644 --- a/rs/execution_environment/src/execution/upgrade.rs +++ b/rs/execution_environment/src/execution/upgrade.rs @@ -193,7 +193,7 @@ pub(crate) fn execute_upgrade( ingress_status_with_processing_state(&original.message, original.time); let paused_execution = Box::new(PausedPreUpgradeExecution { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), context, original, }); @@ -393,7 +393,7 @@ fn upgrade_stage_2_and_3a_create_execution_state_and_call_start( ingress_status_with_processing_state(&original.message, original.time); let paused_execution = Box::new(PausedStartExecutionDuringUpgrade { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), context_sender, context_arg: context.arg, original, @@ -515,7 +515,7 @@ fn upgrade_stage_4a_call_post_upgrade( ingress_status_with_processing_state(&original.message, original.time); let paused_execution = Box::new(PausedPostUpgradeExecution { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), original, }); DtsInstallCodeResult::Paused { @@ -634,7 +634,7 @@ impl PausedInstallCodeExecution for PausedPreUpgradeExecution { update_round_limits(round_limits, &slice); let paused_execution = Box::new(PausedPreUpgradeExecution { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), ..*self }); DtsInstallCodeResult::Paused { @@ -746,7 +746,7 @@ impl PausedInstallCodeExecution for PausedStartExecutionDuringUpgrade { update_round_limits(round_limits, &slice); let paused_execution = Box::new(PausedStartExecutionDuringUpgrade { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), ..*self }); DtsInstallCodeResult::Paused { @@ -854,7 +854,7 @@ impl PausedInstallCodeExecution for PausedPostUpgradeExecution { update_round_limits(round_limits, &slice); let paused_execution = Box::new(PausedPostUpgradeExecution { paused_wasm_execution, - paused_helper: helper.pause(), + paused_helper: helper.pause(slice.executed_instructions), ..*self }); DtsInstallCodeResult::Paused { diff --git a/rs/execution_environment/src/execution_environment/tests.rs b/rs/execution_environment/src/execution_environment/tests.rs index 1b3abc0d8597..3cd04f23f751 100644 --- a/rs/execution_environment/src/execution_environment/tests.rs +++ b/rs/execution_environment/src/execution_environment/tests.rs @@ -17,8 +17,11 @@ use ic_management_canister_types_private::{ use ic_registry_routing_table::{CanisterIdRange, RoutingTable, canister_id_into_u64}; use ic_registry_subnet_type::SubnetType; use ic_replicated_state::{ - CanisterStatus, ReplicatedState, SystemState, - canister_state::{DEFAULT_QUEUE_CAPACITY, WASM_PAGE_SIZE_IN_BYTES}, + CanisterStatus, ExecutionTask, ReplicatedState, SystemState, + canister_state::{ + DEFAULT_QUEUE_CAPACITY, NextExecution, WASM_PAGE_SIZE_IN_BYTES, + execution_state::WasmExecutionMode, + }, metadata_state::subnet_call_context_manager::PreSignatureStash, metadata_state::testing::{NetworkTopologyTesting, SystemMetadataTesting}, testing::{CanisterQueuesTesting, SystemStateTesting}, @@ -31,7 +34,7 @@ use ic_test_utilities_execution_environment::{ }; use ic_test_utilities_metrics::{fetch_histogram_vec_count, metric_vec}; use ic_types::{ - CanisterId, CountBytes, PrincipalId, RegistryVersion, + CanisterId, CountBytes, NumInstructions, PrincipalId, RegistryVersion, canister_http::{CanisterHttpMethod, PricingVersion, Replication, Transform}, consensus::idkg::{IDkgMasterPublicKeyId, PreSigId}, ingress::{IngressState, IngressStatus, WasmResult}, @@ -42,7 +45,8 @@ use ic_types::{ time::UNIX_EPOCH, }; use ic_types_cycles::{ - CanisterCyclesCostSchedule, Cycles, CyclesUseCase, NominalCycles, NominalCyclesTesting, + CanisterCyclesCostSchedule, CompoundCycles, Cycles, CyclesUseCase, Instructions, NominalCycles, + NominalCyclesTesting, }; use ic_types_test_utils::ids::{canister_test_id, node_test_id, subnet_test_id, user_test_id}; use ic_universal_canister::{CallArgs, UNIVERSAL_CANISTER_WASM, call_args, wasm}; @@ -6002,3 +6006,256 @@ fn list_canisters_via_ingress_fails_at_execution() { .contains("list_canisters cannot be called by a user") ); } + +/// Snapshot of the cycles and instruction counters of a canister that are needed +/// to check the accounting of a paused execution that fails to resume. +#[derive(Clone, Copy)] +struct ExecutionAccounting { + consumed_cycles: NominalCycles, + execution_cost: CompoundCycles, + round_instructions: NumInstructions, + executed_instructions: NumInstructions, +} + +impl ExecutionAccounting { + fn take(test: &ExecutionTest, canister_id: CanisterId) -> Self { + Self { + consumed_cycles: test + .canister_state(canister_id) + .system_state + .canister_metrics() + .consumed_cycles_by_use_cases() + .get(&CyclesUseCase::Instructions) + .cloned() + .unwrap_or_default(), + execution_cost: test.canister_execution_cost(canister_id), + round_instructions: test.round_instructions(canister_id), + executed_instructions: test.executed_instructions(), + } + } +} + +/// Decreases the cycles balance of the given canister, which must have a paused +/// execution, and resumes that execution, which must fail. +/// +/// Asserts that the failed execution is charged for exactly the instructions it +/// had already executed: the instructions it reports as used match the round +/// instructions consumed by its slices, and the cycles charged to the canister +/// match the cost of exactly those instructions. +/// +/// `before_execution` must be taken right before the first slice of the paused +/// execution. `before_message` must be taken before the execution cycles were +/// prepaid, which happens when the message execution starts, except for a +/// response callback, whose execution is prepaid already when the caller +/// performs the call; the two snapshots coincide in the former case. +fn resume_paused_execution_after_cycles_decrease( + test: &mut ExecutionTest, + canister_id: CanisterId, + before_message: ExecutionAccounting, + before_execution: ExecutionAccounting, +) { + assert_eq!( + test.canister_state(canister_id).next_execution(), + NextExecution::ContinueLong, + ); + + test.canister_state_mut(canister_id) + .system_state + .remove_cycles(Cycles::new(1)); + + test.execute_slice(canister_id); + assert_eq!( + test.canister_state(canister_id).next_execution(), + NextExecution::None, + ); + + let after = ExecutionAccounting::take(test, canister_id); + + // The failed execution reports exactly the instructions consumed by its + // slices: resuming failed before resuming the Wasm execution, so no further + // instructions were consumed after the last pause. + let executed_instructions = + after.executed_instructions - before_execution.executed_instructions; + assert_eq!( + executed_instructions, + after.round_instructions - before_execution.round_instructions + ); + + // The canister is charged exactly the cost of those instructions. + let expected_cost = test + .cycles_account_manager() + .execution_cost( + executed_instructions, + test.get_own_subnet_cycles_config(), + WasmExecutionMode::Wasm32, + ) + .nominal(); + assert_eq!( + (after.execution_cost - before_execution.execution_cost).nominal(), + expected_cost + ); + assert_eq!( + after.consumed_cycles - before_message.consumed_cycles, + (after.execution_cost - before_message.execution_cost).nominal() + ); +} + +/// Every kind of paused execution re-creates its helper from the current clean +/// canister state when it is resumed, so it relies on the cycles balance of that +/// state not changing while the execution is paused. This test covers all of +/// them: update calls, replicated queries, response callbacks, cleanup +/// callbacks, and canister tasks (heartbeat). The `install_code` case is covered +/// by `dts_install_code_resume_fails_due_to_cycles_decrease`. +#[test] +fn dts_resume_fails_due_to_cycles_decrease() { + // 1. Update calls and replicated queries. + for method in ["update", "query"] { + let mut test = ExecutionTestBuilder::new() + .with_instruction_limit(1_000_000) + .with_slice_instruction_limit(200_000) + .with_manual_execution() + .build(); + + let a_id = test.universal_canister().unwrap(); + + let a = wasm() + .instruction_counter_is_at_least(200_000) + .message_payload() + .append_and_reply() + .build(); + + let (ingress_id, _) = test.ingress_raw(a_id, method, a); + + let before = ExecutionAccounting::take(&test, a_id); + test.execute_slice(a_id); + resume_paused_execution_after_cycles_decrease(&mut test, a_id, before, before); + + let err = check_ingress_status(test.ingress_status(&ingress_id)).unwrap_err(); + let message = if method == "update" { + "an update call" + } else { + "a replicated query" + }; + err.assert_contains( + ErrorCode::CanisterWasmEngineError, + &format!( + "Error from Canister {a_id}: Canister encountered a Wasm engine error: \ + Failed to apply system changes: Mismatch in cycles \ + balance when resuming {message}" + ), + ); + } + + // 2. Response and cleanup callbacks. The response callback traps in the + // cleanup case, so that the long-running callback is the cleanup one. + for cleanup in [false, true] { + let mut test = ExecutionTestBuilder::new() + .with_instruction_limit(100_000_000) + .with_slice_instruction_limit(1_000_000) + .with_manual_execution() + .build(); + + let a_id = test.universal_canister().unwrap(); + let b_id = test.universal_canister().unwrap(); + + let b = wasm().message_payload().append_and_reply().build(); + + let long_execution = wasm() + .instruction_counter_is_at_least(1_000_000) + .message_payload() + .append_and_reply() + .build(); + let call_args = if cleanup { + call_args() + .other_side(b) + .on_reply(wasm().trap()) + .on_cleanup(long_execution) + } else { + call_args().other_side(b).on_reply(long_execution) + }; + let a = wasm().call_simple(b_id, "update", call_args).build(); + + let (ingress_id, _) = test.ingress_raw(a_id, "update", a); + + // The execution of the response callback is prepaid when canister A + // performs the call, so the snapshots are taken before that. + let before_message = ExecutionAccounting::take(&test, a_id); + + // Canister A calls canister B, which replies. + test.execute_message(a_id); + test.induct_messages(); + test.execute_message(b_id); + test.induct_messages(); + + // Start executing the response|cleanup callback. + let before_execution = ExecutionAccounting::take(&test, a_id); + test.execute_slice(a_id); + resume_paused_execution_after_cycles_decrease( + &mut test, + a_id, + before_message, + before_execution, + ); + + let err = check_ingress_status(test.ingress_status(&ingress_id)).unwrap_err(); + let code = if cleanup { + // The error of the trapping response callback takes precedence. + ErrorCode::CanisterCalledTrap + } else { + ErrorCode::CanisterWasmEngineError + }; + assert_eq!(err.code(), code); + assert!( + err.description().contains( + "Failed to apply system changes: Mismatch in cycles \ + balance when resuming a response call" + ), + "unexpected error: {err}" + ); + } + + // 3. Canister tasks, e.g. the heartbeat. + { + let mut test = ExecutionTestBuilder::new() + .with_instruction_limit(100_000_000) + .with_slice_instruction_limit(1_000_000) + .with_manual_execution() + .build(); + + let canister_id = test.universal_canister().unwrap(); + let (ingress_id, _) = test.ingress_raw( + canister_id, + "update", + wasm() + .set_heartbeat( + wasm() + .instruction_counter_is_at_least(1_000_000) + .stable_grow(1) + .build(), + ) + .reply() + .build(), + ); + test.execute_message(canister_id); + check_ingress_status(test.ingress_status(&ingress_id)).unwrap(); + let stable_memory_size = test.execution_state(canister_id).stable_memory.size; + + test.canister_state_mut(canister_id) + .system_state + .task_queue + .enqueue(ExecutionTask::Heartbeat); + + // Start executing the heartbeat. + let before = ExecutionAccounting::take(&test, canister_id); + test.execute_slice(canister_id); + resume_paused_execution_after_cycles_decrease(&mut test, canister_id, before, before); + + // A canister task has no ingress status and the failure is not recorded + // in the canister log, but the state changes of the heartbeat must have + // been dropped along with the failed execution. + assert_eq!( + test.execution_state(canister_id).stable_memory.size, + stable_memory_size + ); + } +} diff --git a/rs/test_utilities/execution_environment/src/lib.rs b/rs/test_utilities/execution_environment/src/lib.rs index 4fffd9477e91..d9d74095462d 100644 --- a/rs/test_utilities/execution_environment/src/lib.rs +++ b/rs/test_utilities/execution_environment/src/lib.rs @@ -292,6 +292,11 @@ pub struct ExecutionTest { subnet_available_callbacks: i64, // The number of instructions executed so far per canister. executed_instructions: HashMap, + // The number of round instructions consumed so far by executing slices of + // canister messages and tasks per canister. Unlike `executed_instructions`, + // this is accumulated for every executed slice and thus also accounts for + // slices of executions that were paused and did not finish (yet). + round_instructions: HashMap, // The total cost of execution so far per canister. execution_cost: HashMap>, // Tracks paused subnet message executions per canister. @@ -444,6 +449,16 @@ impl ExecutionTest { self.executed_instructions.values().sum() } + /// Returns the number of round instructions consumed so far by executing + /// slices of canister messages and tasks of the given canister, including + /// slices of executions that did not finish. + pub fn round_instructions(&self, canister_id: CanisterId) -> NumInstructions { + self.round_instructions + .get(&canister_id) + .copied() + .unwrap_or_else(|| NumInstructions::new(0)) + } + pub fn ingress_memory_capacity(&self) -> NumBytes { self.ingress_memory_capacity } @@ -1960,6 +1975,7 @@ impl ExecutionTest { compute_allocation_used, subnet_memory_reservation: self.subnet_memory_reservation, }; + let remaining_round_instructions_before = round_limits.instructions; let result = execute_canister( &self.exec_env, canister, @@ -1972,6 +1988,13 @@ impl ExecutionTest { state.get_own_subnet_cycles_config(), ); state.metadata.heap_delta_estimate += result.heap_delta; + let slice_instructions_used = + remaining_round_instructions_before - round_limits.instructions; + *self + .round_instructions + .entry(canister_id) + .or_insert_with(|| NumInstructions::new(0)) += + NumInstructions::from(slice_instructions_used.get() as u64); self.subnet_available_memory = round_limits.subnet_available_memory; self.subnet_available_callbacks = round_limits.subnet_available_callbacks; if let Some(instructions_used) = result.instructions_used { @@ -3088,6 +3111,7 @@ impl ExecutionTestBuilder { state: Some(state), message_id: 0, executed_instructions: HashMap::new(), + round_instructions: HashMap::new(), execution_cost: HashMap::new(), paused_subnet_messages: HashMap::new(), xnet_messages: vec![],