diff --git a/Cargo.lock b/Cargo.lock index 634f2be8fc66..d56e6a6f0ca1 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -6896,7 +6896,9 @@ dependencies = [ "ic-crypto-sha2", "ic-crypto-tree-hash", "ic-error-types 0.2.0", + "ic-logger", "ic-management-canister-types-private", + "ic-metrics", "ic-protobuf", "ic-registry-routing-table", "ic-registry-subnet-features", diff --git a/rs/canonical_state/BUILD.bazel b/rs/canonical_state/BUILD.bazel index 99d324ada733..3552348ce297 100644 --- a/rs/canonical_state/BUILD.bazel +++ b/rs/canonical_state/BUILD.bazel @@ -39,6 +39,8 @@ rust_test( deps = [ # Keep sorted. "//rs/crypto/sha2", + "//rs/monitoring/logger", + "//rs/monitoring/metrics", "//rs/registry/subnet_features", "//rs/sys", "//rs/test_utilities/state", diff --git a/rs/canonical_state/Cargo.toml b/rs/canonical_state/Cargo.toml index 8e4d6860e74c..ef9ba3254bf6 100644 --- a/rs/canonical_state/Cargo.toml +++ b/rs/canonical_state/Cargo.toml @@ -31,7 +31,9 @@ assert_matches = { workspace = true } hex = { workspace = true } ic-canonical-state-tree-hash-test-utils = { path = "tree_hash/test_utils" } ic-crypto-sha2 = { path = "../crypto/sha2/" } +ic-logger = { path = "../monitoring/logger" } ic-management-canister-types-private = { path = "../types/management_canister_types" } +ic-metrics = { path = "../monitoring/metrics" } ic-registry-subnet-features = { path = "../registry/subnet_features" } ic-sys = { path = "../sys" } ic-test-utilities-state = { path = "../test_utilities/state" } diff --git a/rs/canonical_state/src/traversal.rs b/rs/canonical_state/src/traversal.rs index 1cd22f3fb21c..4c5c69557329 100644 --- a/rs/canonical_state/src/traversal.rs +++ b/rs/canonical_state/src/traversal.rs @@ -54,7 +54,9 @@ mod tests { CertificationVersion::{self, *}, all_supported_versions, }; + use ic_logger::replica_logger::no_op_logger; use ic_management_canister_types_private::Global; + use ic_metrics::MetricsRegistry; use ic_registry_routing_table::{CanisterIdRange, RoutingTable}; use ic_registry_subnet_features::SubnetFeatures; use ic_registry_subnet_type::SubnetType; @@ -1234,12 +1236,14 @@ mod tests { INITIAL_CYCLES, NumSeconds::from(100_000), ); - canister_state - .system_state - .consume_cycles(CompoundCycles::::new( + canister_state.system_state.consume_cycles( + CompoundCycles::::new( Cycles::new(123_456), CanisterCyclesCostSchedule::Normal, - )); + ), + &no_op_logger(), + &MetricsRegistry::new().int_counter("error_counter", "Test error counter"), + ); let consumed_by_canisters = canister_state .system_state .canister_metrics() diff --git a/rs/cycles_account_manager/src/cycles_account_manager.rs b/rs/cycles_account_manager/src/cycles_account_manager.rs index e730f565e808..da54e8b5a208 100644 --- a/rs/cycles_account_manager/src/cycles_account_manager.rs +++ b/rs/cycles_account_manager/src/cycles_account_manager.rs @@ -316,6 +316,8 @@ impl CyclesAccountManager { cycles: Cycles, subnet_cycles_config: CyclesAccountManagerSubnetConfig, reveal_top_up: bool, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result<(), CanisterOutOfCyclesError> { let threshold = self.freeze_threshold_cycles( canister.system_state.freeze_threshold, @@ -346,6 +348,8 @@ impl CyclesAccountManager { CompoundCycles::new(cycles, subnet_cycles_config.cost_schedule), threshold, reveal_top_up, + log, + charging_error, ) } } @@ -372,6 +376,8 @@ impl CyclesAccountManager { cycles: CompoundCycles, subnet_cycles_config: CyclesAccountManagerSubnetConfig, reveal_top_up: bool, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result<(), CanisterOutOfCyclesError> { self.consume_cycles_impl( system_state, @@ -380,6 +386,8 @@ impl CyclesAccountManager { cycles, subnet_cycles_config, reveal_top_up, + log, + charging_error, ) } @@ -394,6 +402,8 @@ impl CyclesAccountManager { cycles: CompoundCycles, subnet_cycles_config: CyclesAccountManagerSubnetConfig, reveal_top_up: bool, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result<(), CanisterOutOfCyclesError> { let threshold = self.freeze_threshold_cycles( system_state.freeze_threshold, @@ -404,7 +414,14 @@ impl CyclesAccountManager { subnet_cycles_config, system_state.reserved_balance(), ); - self.consume_with_threshold_impl(system_state, cycles, threshold, reveal_top_up) + self.consume_with_threshold_impl( + system_state, + cycles, + threshold, + reveal_top_up, + log, + charging_error, + ) } /// Consumes a direct, final `Instructions` charge (e.g. the cost of @@ -423,6 +440,8 @@ impl CyclesAccountManager { cycles: CompoundCycles, subnet_cycles_config: CyclesAccountManagerSubnetConfig, reveal_top_up: bool, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result<(), CanisterOutOfCyclesError> { self.consume_cycles_impl( system_state, @@ -431,6 +450,8 @@ impl CyclesAccountManager { cycles, subnet_cycles_config, reveal_top_up, + log, + charging_error, )?; let zero_refund = CompoundCycles::::new(Cycles::zero(), subnet_cycles_config.cost_schedule); @@ -446,6 +467,8 @@ impl CyclesAccountManager { canister: &mut CanisterState, amount: NumInstructions, subnet_cycles_config: CyclesAccountManagerSubnetConfig, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result<(), CanisterOutOfCyclesError> { let memory_usage = canister.memory_usage(); let message_memory = canister.message_memory_usage(); @@ -458,6 +481,8 @@ impl CyclesAccountManager { cycles, subnet_cycles_config, reveal_top_up, + log, + charging_error, ) } @@ -481,6 +506,8 @@ impl CyclesAccountManager { subnet_cycles_config: CyclesAccountManagerSubnetConfig, reveal_top_up: bool, execution_mode: WasmExecutionMode, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result, CanisterOutOfCyclesError> { let cost = self.execution_cost(num_instructions, subnet_cycles_config, execution_mode); self.consume_with_threshold_impl( @@ -496,6 +523,8 @@ impl CyclesAccountManager { system_state.reserved_balance(), ), reveal_top_up, + log, + charging_error, ) .map(|_| cost) } @@ -952,8 +981,17 @@ impl CyclesAccountManager { cycles: CompoundCycles, threshold: Cycles, reveal_top_up: bool, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result<(), CanisterOutOfCyclesError> { - self.consume_with_threshold_impl(system_state, cycles, threshold, reveal_top_up) + self.consume_with_threshold_impl( + system_state, + cycles, + threshold, + reveal_top_up, + log, + charging_error, + ) } /// Same as `consume_with_threshold` but without the restriction to @@ -965,6 +1003,8 @@ impl CyclesAccountManager { cycles: CompoundCycles, threshold: Cycles, reveal_top_up: bool, + log: &ReplicaLogger, + charging_error: &IntCounter, ) -> Result<(), CanisterOutOfCyclesError> { let use_case = T::cycles_use_case(); @@ -995,7 +1035,8 @@ impl CyclesAccountManager { reveal_top_up, )?; - system_state.consume_cycles(cycles); + // The balance was verified against the threshold above. + system_state.consume_cycles(cycles, log, charging_error); Ok(()) } @@ -1195,6 +1236,7 @@ impl CyclesAccountManager { &self, rate: CompoundCycles, log: &ReplicaLogger, + charging_error: &IntCounter, canister: &mut CanisterState, duration_since_last_charge: Duration, ) -> Result<(), CanisterOutOfCyclesError> { @@ -1206,6 +1248,8 @@ impl CyclesAccountManager { cycles, Cycles::zero(), false, // caller is system => no need to reveal top up balance + log, + charging_error, ) { info!( log, @@ -1225,6 +1269,7 @@ impl CyclesAccountManager { pub fn charge_canister_for_resource_allocation_and_usage( &self, log: &ReplicaLogger, + charging_error: &IntCounter, canister: &mut CanisterState, duration_since_last_charge: Duration, subnet_cycles_config: CyclesAccountManagerSubnetConfig, @@ -1244,18 +1289,21 @@ impl CyclesAccountManager { self.charge_canister_for_single_resource( memory, log, + charging_error, canister, duration_since_last_charge, )?; self.charge_canister_for_single_resource( message_memory, log, + charging_error, canister, duration_since_last_charge, )?; self.charge_canister_for_single_resource( compute_allocation, log, + charging_error, canister, duration_since_last_charge, )?; diff --git a/rs/cycles_account_manager/tests/cycles_account_manager.rs b/rs/cycles_account_manager/tests/cycles_account_manager.rs index 5c7e3379798d..7d91db452313 100644 --- a/rs/cycles_account_manager/tests/cycles_account_manager.rs +++ b/rs/cycles_account_manager/tests/cycles_account_manager.rs @@ -112,6 +112,7 @@ fn test_can_charge_application_subnets() { cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &log, + &IntCounter::new("no_op", "no_op").unwrap(), &mut canister, duration, subnet_cycles_config, @@ -322,6 +323,8 @@ fn verify_no_cycles_charged_for_message_execution_on_system_subnets() { subnet_cycles_config, false, WASM_EXECUTION_MODE, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.balance(), initial_balance); @@ -365,6 +368,8 @@ fn verify_no_cycles_charged_for_message_execution_on_free_schedule() { subnet_cycles_config, false, WASM_EXECUTION_MODE, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.balance(), initial_balance); @@ -451,6 +456,7 @@ fn charging_removes_canisters_with_insufficient_balance() { cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &log, + &IntCounter::new("no_op", "no_op").unwrap(), &mut canister, Duration::from_secs(1), subnet_cycles_config, @@ -468,6 +474,7 @@ fn charging_removes_canisters_with_insufficient_balance() { cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &log, + &IntCounter::new("no_op", "no_op").unwrap(), &mut canister, Duration::from_secs(1), subnet_cycles_config, @@ -485,6 +492,7 @@ fn charging_removes_canisters_with_insufficient_balance() { cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &log, + &IntCounter::new("no_op", "no_op").unwrap(), &mut canister, Duration::from_secs(1), subnet_cycles_config, @@ -538,6 +546,7 @@ fn charge_canister_for_memory_usage() { cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &log, + &IntCounter::new("no_op", "no_op").unwrap(), &mut canister, HOUR, subnet_cycles_config, @@ -603,6 +612,7 @@ fn do_not_charge_canister_for_memory_usage_free_schedule() { cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &log, + &IntCounter::new("no_op", "no_op").unwrap(), &mut canister, HOUR, subnet_cycles_config, @@ -661,6 +671,7 @@ fn do_not_charge_canister_for_compute_allocation_free_schedule() { cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &log, + &IntCounter::new("no_op", "no_op").unwrap(), &mut canister, HOUR, subnet_cycles_config, @@ -785,6 +796,8 @@ fn test_consume_with_threshold() { CompoundCycles::::new(Cycles::zero(), cost_schedule), threshold, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_ok() ); @@ -796,7 +809,14 @@ fn test_consume_with_threshold() { let amount = CompoundCycles::::new(Cycles::from(i128::MAX as u128), cost_schedule); assert!( cycles_account_manager - .consume_with_threshold(&mut system_state, amount, threshold, false) + .consume_with_threshold( + &mut system_state, + amount, + threshold, + false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap() + ) .is_ok() ); cycles_balance_expected -= amount.real(); @@ -807,7 +827,14 @@ fn test_consume_with_threshold() { assert!( cycles_account_manager - .consume_with_threshold(&mut system_state, amount, threshold, false) + .consume_with_threshold( + &mut system_state, + amount, + threshold, + false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap() + ) .is_ok() ); cycles_balance_expected -= amount.real(); @@ -816,7 +843,14 @@ fn test_consume_with_threshold() { let amount = CompoundCycles::::new(Cycles::new(1), cost_schedule); assert!( cycles_account_manager - .consume_with_threshold(&mut system_state, amount, threshold, false) + .consume_with_threshold( + &mut system_state, + amount, + threshold, + false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap() + ) .is_ok() ); cycles_balance_expected -= amount.real(); @@ -824,7 +858,14 @@ fn test_consume_with_threshold() { assert!( cycles_account_manager - .consume_with_threshold(&mut system_state, amount, threshold, false) + .consume_with_threshold( + &mut system_state, + amount, + threshold, + false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap() + ) .is_err() ); cycles_balance_expected -= amount.real(); @@ -879,6 +920,8 @@ fn cycles_withdraw_for_execution() { amount, subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_ok() ); @@ -892,6 +935,8 @@ fn cycles_withdraw_for_execution() { amount, subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_err() ); @@ -922,6 +967,8 @@ fn cycles_withdraw_for_execution() { compound_exec_cycles_max, subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_ok() ); @@ -955,6 +1002,8 @@ fn cycles_withdraw_for_execution() { compound_exec_cycles_max, subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_err() ); @@ -967,6 +1016,8 @@ fn cycles_withdraw_for_execution() { CompoundCycles::::new(Cycles::new(10), cost_schedule), subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_err() ); @@ -979,6 +1030,8 @@ fn cycles_withdraw_for_execution() { CompoundCycles::::new(Cycles::new(1), cost_schedule), subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_err() ); @@ -991,6 +1044,8 @@ fn cycles_withdraw_for_execution() { CompoundCycles::::new(Cycles::zero(), cost_schedule), subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_ok() ); @@ -1045,6 +1100,8 @@ fn do_not_withdraw_cycles_for_execution_free_schedule() { amount, subnet_cycles_config, false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .is_ok() ); @@ -1090,6 +1147,8 @@ fn withdraw_execution_cycles_consumes_cycles() { ), false, WASM_EXECUTION_MODE, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); let consumed_cycles_after = system_state.canister_metrics().consumed_cycles(); @@ -1151,6 +1210,8 @@ fn consume_cycles_updates_consumed_cycles() { DEFAULT_REFERENCE_SUBNET_SIZE, ), false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); let consumed_cycles_after = system_state.canister_metrics().consumed_cycles(); @@ -1177,6 +1238,8 @@ fn consume_cycles_for_memory_drains_reserved_balance() { CompoundCycles::::new(Cycles::new(2_000_000), cost_schedule), Cycles::new(0), false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.reserved_balance(), Cycles::new(0)); @@ -1202,6 +1265,8 @@ fn consume_cycles_for_compute_drains_reserved_balance() { ), Cycles::new(0), false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.reserved_balance(), Cycles::new(0)); @@ -1224,6 +1289,8 @@ fn consume_cycles_for_uninstall_drains_reserved_balance() { CompoundCycles::::new(Cycles::new(2_000_000), cost_schedule), Cycles::new(0), false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.reserved_balance(), Cycles::new(0)); @@ -1263,6 +1330,8 @@ fn consume_cycles_for_execution_does_not_drain_reserved_balance() { subnet_cycles_config, false, WASM_EXECUTION_MODE, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_ne!(prepaid.real(), Cycles::zero()); @@ -1637,6 +1706,8 @@ fn variable_execution_cost_matches_refund() { subnet_cycles_config, false, WASM_EXECUTION_MODE, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); diff --git a/rs/embedders/BUILD.bazel b/rs/embedders/BUILD.bazel index 0482ff920195..cdb5cfda6e69 100644 --- a/rs/embedders/BUILD.bazel +++ b/rs/embedders/BUILD.bazel @@ -250,6 +250,7 @@ rust_test( "//rs/types/types", "@crate_index//:maplit", "@crate_index//:more-asserts", + "@crate_index//:prometheus", "@crate_index//:strum", ], ) diff --git a/rs/embedders/fuzz/src/wasm_executor.rs b/rs/embedders/fuzz/src/wasm_executor.rs index e1867e907735..8229aebf4248 100644 --- a/rs/embedders/fuzz/src/wasm_executor.rs +++ b/rs/embedders/fuzz/src/wasm_executor.rs @@ -110,7 +110,12 @@ pub fn run_fuzzer(module: ICWasmModule) { } canister_state_changes .system_state_modifications - .apply_balance_changes(&mut system_state); + .apply_balance_changes( + &mut system_state, + &no_op_logger(), + &MetricsRegistry::new() + .int_counter("error_counter", "Fuzzing error counter"), + ); } WasmExecutionResult::Paused(_, _) => (), // Only possible via execute_dts } diff --git a/rs/embedders/src/wasmtime_embedder/system_api/sandbox_safe_system_state.rs b/rs/embedders/src/wasmtime_embedder/system_api/sandbox_safe_system_state.rs index 24f93b6dec91..91c517ce0473 100644 --- a/rs/embedders/src/wasmtime_embedder/system_api/sandbox_safe_system_state.rs +++ b/rs/embedders/src/wasmtime_embedder/system_api/sandbox_safe_system_state.rs @@ -35,6 +35,7 @@ use ic_types_cycles::{ Instructions, RequestAndResponseTransmission, }; use ic_wasm_types::WasmEngineError; +use prometheus::IntCounter; use serde::{Deserialize, Serialize}; use std::str::FromStr; use std::sync::Arc; @@ -390,6 +391,7 @@ impl SystemStateModifications { is_composite_query: bool, metrics: &Metrics, logger: &ReplicaLogger, + charging_error: &IntCounter, ) -> HypervisorResult { // Append delta logs. if !self.canister_log.is_empty() { @@ -401,7 +403,7 @@ impl SystemStateModifications { // Verify total cycle change is not positive and update cycles balance. self.validate_cycle_change(system_state.canister_id() == CYCLES_MINTING_CANISTER_ID)?; - self.apply_balance_changes(system_state); + self.apply_balance_changes(system_state, logger, charging_error); // Verify we don't accept more cycles than are available from call // context and update the call context balance. @@ -561,7 +563,12 @@ impl SystemStateModifications { } /// Applies the balance change to the given state. - pub fn apply_balance_changes(&self, state: &mut SystemState) { + pub fn apply_balance_changes( + &self, + state: &mut SystemState, + logger: &ReplicaLogger, + charging_error: &IntCounter, + ) { let initial_balance = state.balance(); // `self.cycles_balance_change` consists of: @@ -593,14 +600,15 @@ impl SystemStateModifications { instructions, request_and_response_transmission, } = self.consumed_cycles_by_use_case; + // The cycle changes were validated above, so the balance covers them. if let Some(x) = burned { - state.consume_cycles(x); + state.consume_cycles(x, logger, charging_error); } if let Some(x) = instructions { - state.consume_cycles(x); + state.consume_cycles(x, logger, charging_error); } if let Some(x) = request_and_response_transmission { - state.consume_cycles(x); + state.consume_cycles(x, logger, charging_error); } // Apply the reserved cycles. This must succeed because the cycle @@ -1437,6 +1445,7 @@ mod tests { use ic_config::subnet_config::CyclesAccountManagerConfig; use ic_cycles_account_manager::{CyclesAccountManager, CyclesAccountManagerSubnetConfig}; use ic_limits::SMALL_APP_SUBNET_MAX_SIZE; + use ic_logger::replica_logger::no_op_logger; use ic_registry_subnet_type::SubnetType; use ic_replicated_state::{NetworkTopology, SystemState}; use ic_test_utilities_types::ids::{canister_test_id, subnet_test_id, user_test_id}; @@ -1450,6 +1459,7 @@ mod tests { BurnedCycles, CanisterCyclesCostSchedule, CompoundCycles, Cycles, CyclesUseCase, CyclesUseCaseKind, Instructions, RequestAndResponseTransmission, }; + use prometheus::IntCounter; use super::{CanisterStatusView, SandboxSafeSystemState, SystemStateModifications}; use crate::wasmtime_embedder::system_api::{ @@ -1482,7 +1492,11 @@ mod tests { }, ); - system_state_modifications.apply_balance_changes(&mut system_state); + system_state_modifications.apply_balance_changes( + &mut system_state, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); assert_eq!(initial_cycles_balance - removed, system_state.balance()); @@ -1501,7 +1515,11 @@ mod tests { }, ); - system_state_modifications.apply_balance_changes(&mut system_state); + system_state_modifications.apply_balance_changes( + &mut system_state, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); assert_eq!(initial_cycles_balance - removed, system_state.balance()); @@ -1520,7 +1538,11 @@ mod tests { }, ); - system_state_modifications.apply_balance_changes(&mut system_state); + system_state_modifications.apply_balance_changes( + &mut system_state, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); assert_eq!(initial_cycles_balance + added, system_state.balance()); @@ -1539,7 +1561,11 @@ mod tests { }, ); - system_state_modifications.apply_balance_changes(&mut system_state); + system_state_modifications.apply_balance_changes( + &mut system_state, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); assert_eq!(initial_cycles_balance + added, system_state.balance()); } diff --git a/rs/embedders/tests/sandbox_safe_system_state.rs b/rs/embedders/tests/sandbox_safe_system_state.rs index 4efd9d87c89c..ccc07162ba45 100644 --- a/rs/embedders/tests/sandbox_safe_system_state.rs +++ b/rs/embedders/tests/sandbox_safe_system_state.rs @@ -265,6 +265,7 @@ fn correct_charging_source_canister_for_a_request() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); let no_op_counter: IntCounter = IntCounter::new("no_op", "no_op").unwrap(); @@ -483,6 +484,7 @@ fn call_increases_cycles_consumed_metric() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert!(system_state.canister_metrics().consumed_cycles().get() > 0); @@ -575,6 +577,7 @@ fn test_inter_canister_call( false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); diff --git a/rs/embedders/tests/system_api.rs b/rs/embedders/tests/system_api.rs index da0afe019c47..75935c83e43b 100644 --- a/rs/embedders/tests/system_api.rs +++ b/rs/embedders/tests/system_api.rs @@ -33,6 +33,7 @@ use ic_types::{ use ic_types_cycles::{CanisterCyclesCostSchedule, Cycles}; use maplit::btreemap; use more_asserts::assert_le; +use prometheus::IntCounter; use std::{ collections::{BTreeMap, BTreeSet}, convert::From, @@ -1303,6 +1304,7 @@ fn certified_data_set() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.certified_data, vec![10; 32]) @@ -1499,6 +1501,7 @@ fn call_perform_not_enough_cycles_does_not_trap() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.balance(), initial_cycles); @@ -1558,6 +1561,7 @@ fn cycles_burn128_clamps_to_available_cycles() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(system_state.balance(), freeze_limit); @@ -1720,6 +1724,7 @@ fn push_output_request_respects_memory_limits() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(1, system_state.queues().output_queues_len()); @@ -1821,6 +1826,7 @@ fn push_output_request_oversized_request_memory_limits() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!(1, system_state.queues().output_queues_len()); @@ -1859,6 +1865,7 @@ fn ic0_global_timer_set_is_propagated_from_sandbox() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); assert_eq!( @@ -2122,6 +2129,7 @@ fn ic0_call_with_best_effort_response() { false, &NoOpMetrics {}, &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); diff --git a/rs/execution_environment/src/canister_manager.rs b/rs/execution_environment/src/canister_manager.rs index 485da60a882b..8c1b70c7c143 100644 --- a/rs/execution_environment/src/canister_manager.rs +++ b/rs/execution_environment/src/canister_manager.rs @@ -83,6 +83,8 @@ const MAX_SLICE_SIZE_BYTES: u64 = 2_000_000; pub(crate) struct CanisterManager { hypervisor: Arc, log: ReplicaLogger, + /// Critical error for charges exceeding the canister's cycles balance. + charging_from_balance_error: IntCounter, config: CanisterMgrConfig, cycles_account_manager: Arc, fd_factory: Arc, @@ -92,6 +94,7 @@ impl CanisterManager { pub(crate) fn new( hypervisor: Arc, log: ReplicaLogger, + charging_from_balance_error: IntCounter, config: CanisterMgrConfig, cycles_account_manager: Arc, fd_factory: Arc, @@ -99,6 +102,7 @@ impl CanisterManager { CanisterManager { hypervisor, log, + charging_from_balance_error, config, cycles_account_manager, fd_factory, @@ -941,6 +945,8 @@ impl CanisterManager { subnet_cycles_config, reveal_top_up, wasm_execution_mode, + &self.log, + round_counters.charging_from_balance_error, ) { Ok(cycles) => cycles, Err(err) => { @@ -1557,7 +1563,8 @@ impl CanisterManager { Arc::clone(&self.fd_factory), ); - system_state.consume_cycles(creation_fee); + // The creation fee was already withdrawn from the sender's balance. + system_state.consume_cycles(creation_fee, &self.log, &self.charging_from_balance_error); let mut new_canister = CanisterState::new( system_state, None, @@ -1787,6 +1794,8 @@ impl CanisterManager { canister, instructions, subnet_cycles_config, + &self.log, + &self.charging_from_balance_error, ) .map_err(|err| CanisterManagerError::WasmChunkStoreError { message: format!("Error charging for 'upload_chunk': {err}"), @@ -2013,6 +2022,8 @@ impl CanisterManager { cycles_for_instructions, subnet_cycles_config, reveal_top_up, + &self.log, + &self.charging_from_balance_error, ) .map_err(CanisterManagerError::NotEnoughCycles)?; @@ -2350,6 +2361,8 @@ impl CanisterManager { subnet_cycles_config, reveal_top_up, wasm_execution_mode, + &self.log, + &self.charging_from_balance_error, ) { Ok(cycles) => cycles, Err(err) => { @@ -2726,6 +2739,8 @@ impl CanisterManager { canister, num_instructions, subnet_cycles_config, + &self.log, + &self.charging_from_balance_error, ) .map_err(CanisterManagerError::NotEnoughCycles)?; let cost = self @@ -2951,6 +2966,8 @@ impl CanisterManager { canister, instructions, subnet_cycles_config, + &self.log, + &self.charging_from_balance_error, ) .map_err(CanisterManagerError::NotEnoughCycles)?; let cost = self diff --git a/rs/execution_environment/src/canister_manager/tests.rs b/rs/execution_environment/src/canister_manager/tests.rs index fc18a9d41454..1a385ef692f1 100644 --- a/rs/execution_environment/src/canister_manager/tests.rs +++ b/rs/execution_environment/src/canister_manager/tests.rs @@ -276,6 +276,7 @@ impl CanisterManagerBuilder { CanisterManager::new( hypervisor, no_op_logger(), + no_op_counter(), canister_manager_config( self.subnet_id, subnet_type, @@ -9220,14 +9221,14 @@ fn assert_canister_metrics_can_be_retrieved( let memory_cycles = CompoundCycles::::new(Cycles::new(1), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(memory_cycles); + .consume_cycles(memory_cycles, &no_op_logger(), &no_op_counter()); // `Instructions` follow the prepay/refund flow where metrics are updated // only during the refund step. let instructions_cycles = CompoundCycles::::new(Cycles::new(2), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(instructions_cycles); + .consume_cycles(instructions_cycles, &no_op_logger(), &no_op_counter()); test.canister_state_mut(canister_id) .system_state .refund_cycles( @@ -9239,24 +9240,24 @@ fn assert_canister_metrics_can_be_retrieved( CompoundCycles::::new(Cycles::new(3), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(ingress_induction_cycles); + .consume_cycles(ingress_induction_cycles, &no_op_logger(), &no_op_counter()); let compute_allocation_cycles = CompoundCycles::::new(Cycles::new(4), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(compute_allocation_cycles); + .consume_cycles(compute_allocation_cycles, &no_op_logger(), &no_op_counter()); let canister_creation_cycles = CompoundCycles::::new(Cycles::new(5), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(canister_creation_cycles); + .consume_cycles(canister_creation_cycles, &no_op_logger(), &no_op_counter()); let uninstall_cycles = CompoundCycles::::new(Cycles::new(6), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(uninstall_cycles); + .consume_cycles(uninstall_cycles, &no_op_logger(), &no_op_counter()); // `RequestAndResponseTransmission` follow the prepay/refund flow where // metrics are updated only during the refund step. @@ -9264,7 +9265,11 @@ fn assert_canister_metrics_can_be_retrieved( CompoundCycles::::new(Cycles::new(8), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(request_and_response_transmission_cycles); + .consume_cycles( + request_and_response_transmission_cycles, + &no_op_logger(), + &no_op_counter(), + ); test.canister_state_mut(canister_id) .system_state .refund_cycles( @@ -9280,7 +9285,7 @@ fn assert_canister_metrics_can_be_retrieved( let burned_cycles = CompoundCycles::::new(Cycles::new(10), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(burned_cycles); + .consume_cycles(burned_cycles, &no_op_logger(), &no_op_counter()); let expected_cycles_consumed = CyclesConsumed::new( memory_cycles.nominal(), diff --git a/rs/execution_environment/src/execution/call_or_task.rs b/rs/execution_environment/src/execution/call_or_task.rs index fc7a2964ff18..a5eca77a461e 100644 --- a/rs/execution_environment/src/execution/call_or_task.rs +++ b/rs/execution_environment/src/execution/call_or_task.rs @@ -81,6 +81,8 @@ pub fn execute_call_or_task( subnet_cycles_config, reveal_top_up, wasm_execution_mode, + round.log, + round.counters.charging_from_balance_error, ) { Ok(cycles) => cycles, Err(err) => { @@ -610,6 +612,7 @@ impl CallOrTaskHelper { false, round.hypervisor.metrics(), round.log, + round.counters.charging_from_balance_error, ) { return finish_err( diff --git a/rs/execution_environment/src/execution/common.rs b/rs/execution_environment/src/execution/common.rs index 6fe63760a695..6e43b7ab1826 100644 --- a/rs/execution_environment/src/execution/common.rs +++ b/rs/execution_environment/src/execution/common.rs @@ -633,6 +633,7 @@ fn try_apply_canister_state_changes( is_composite_query: bool, metrics: &HypervisorMetrics, log: &ReplicaLogger, + charging_error: &IntCounter, ) -> HypervisorResult { subnet_available_memory .try_decrement( @@ -650,6 +651,7 @@ fn try_apply_canister_state_changes( is_composite_query, metrics, log, + charging_error, ) } @@ -701,6 +703,9 @@ pub fn apply_canister_state_changes( is_composite_query, metrics, log, + // Applying the balance changes must not run into charges that the balance + // cannot cover: the cycle changes were validated before they are applied. + state_changes_error, ) { Ok(request_stats) => { if let Some(ExecutionStateChanges { diff --git a/rs/execution_environment/src/execution/install_code.rs b/rs/execution_environment/src/execution/install_code.rs index 22a3c4c190d9..9f12a2629d9b 100644 --- a/rs/execution_environment/src/execution/install_code.rs +++ b/rs/execution_environment/src/execution/install_code.rs @@ -712,6 +712,7 @@ impl InstallCodeHelper { false, // Install cannot happen in composite_query. round.hypervisor.metrics(), round.log, + round.counters.charging_from_balance_error, ); match output.wasm_result { diff --git a/rs/execution_environment/src/execution/response/tests.rs b/rs/execution_environment/src/execution/response/tests.rs index db3781cc48b2..a312fc3194c0 100644 --- a/rs/execution_environment/src/execution/response/tests.rs +++ b/rs/execution_environment/src/execution/response/tests.rs @@ -2,6 +2,7 @@ use assert_matches::assert_matches; use ic_base_types::{NumBytes, NumSeconds}; use ic_error_types::ErrorCode; use ic_interfaces::execution_environment::MessageMemoryUsage; +use ic_logger::replica_logger::no_op_logger; use ic_management_canister_types_private::CanisterStatusType; use ic_replicated_state::NumWasmPages; use ic_replicated_state::canister_state::NextExecution; @@ -22,6 +23,7 @@ use ic_types::{ComputeAllocation, MemoryAllocation}; use ic_types_cycles::{CanisterCyclesCostSchedule, Cycles, CyclesUseCase}; use ic_universal_canister::{call_args, wasm}; use more_asserts::{assert_ge, assert_gt, assert_lt}; +use prometheus::IntCounter; #[test] fn execute_response_when_stopping_status() { @@ -2644,7 +2646,11 @@ fn subnet_available_memory_does_not_change_on_response_resume_failure() { // Change the cycles balance to force the response resuming to fail. test.canister_state_mut(a_id) .system_state - .burn_remaining_balance_for_uninstall(CanisterCyclesCostSchedule::Normal); + .burn_remaining_balance_for_uninstall( + CanisterCyclesCostSchedule::Normal, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); test.execute_slice(a_id); assert_eq!( @@ -2733,7 +2739,11 @@ fn subnet_available_memory_does_not_change_on_cleanup_resume_failure() { // Change the cycles balance to force the cleanup resuming to fail. test.canister_state_mut(a_id) .system_state - .burn_remaining_balance_for_uninstall(CanisterCyclesCostSchedule::Normal); + .burn_remaining_balance_for_uninstall( + CanisterCyclesCostSchedule::Normal, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); test.execute_slice(a_id); assert_eq!( diff --git a/rs/execution_environment/src/execution_environment.rs b/rs/execution_environment/src/execution_environment.rs index 3c9c2f24ff21..498a49447be9 100644 --- a/rs/execution_environment/src/execution_environment.rs +++ b/rs/execution_environment/src/execution_environment.rs @@ -360,6 +360,8 @@ impl<'a> ConsumedCyclesForInstructions<'a> { round_limits: &mut RoundLimits, subnet_cycles_config: CyclesAccountManagerSubnetConfig, failed_charge: &IntCounter, + log: &ReplicaLogger, + charging_error: &IntCounter, ) { canister.scheduler_state.install_code_debit += self.install_code_debit; let memory_usage = canister.memory_usage(); @@ -371,6 +373,8 @@ impl<'a> ConsumedCyclesForInstructions<'a> { self.consumed_cycles, subnet_cycles_config, true, /* we only log the error, but do not return it to the user => do reveal top up balance */ + log, + charging_error, ); if let Err(err) = res { failed_charge.inc(); @@ -535,6 +539,10 @@ impl ExecutionEnvironment { &self.metrics.state_changes_error } + pub fn charging_from_balance_error(&self) -> &IntCounter { + &self.metrics.charging_from_balance_error + } + pub fn canister_not_found_error(&self) -> &IntCounter { &self.metrics.canister_not_found_error } @@ -674,6 +682,8 @@ impl ExecutionEnvironment { round_limits, subnet_cycles_config, &self.metrics.failed_subnet_message_charge, + &self.log, + &self.metrics.charging_from_balance_error, ); self.process_canister_manager_result(Err(err), state, msg, current_round) } @@ -1067,6 +1077,8 @@ impl ExecutionEnvironment { induction_cost, subnet_cycles_config, false, // we ignore the error anyway => no need to reveal top up balance + &self.log, + &self.metrics.charging_from_balance_error, ); } } diff --git a/rs/execution_environment/src/lib.rs b/rs/execution_environment/src/lib.rs index ed29ac0c7ea7..92fb8655b394 100644 --- a/rs/execution_environment/src/lib.rs +++ b/rs/execution_environment/src/lib.rs @@ -60,6 +60,11 @@ pub use scheduler::{ use std::{path::Path, sync::Arc}; use tokio::sync::mpsc::Sender; +/// Critical error for charges by the canister manager that exceed the +/// canister's cycles balance. +const CRITICAL_ERROR_CANISTER_MANAGER_CHARGING_FROM_BALANCE: &str = + "canister_manager_charging_from_balance"; + /// When executing a wasm method of query type, this enum indicates if we are /// running in an replicated or non-replicated context. This information is /// needed for various purposes and in particular to support the CoW memory @@ -385,6 +390,7 @@ fn setup_execution_helper( let canister_manager = Arc::new(CanisterManager::new( Arc::clone(&hypervisor), logger.clone(), + metrics_registry.error_counter(CRITICAL_ERROR_CANISTER_MANAGER_CHARGING_FROM_BALANCE), canister_manager_config, Arc::clone(&cycles_account_manager), Arc::clone(&fd_factory), diff --git a/rs/execution_environment/src/query_handler/query_cache/tests.rs b/rs/execution_environment/src/query_handler/query_cache/tests.rs index 622320999292..0645d037c1ac 100644 --- a/rs/execution_environment/src/query_handler/query_cache/tests.rs +++ b/rs/execution_environment/src/query_handler/query_cache/tests.rs @@ -9,6 +9,7 @@ use ic_base_types::CanisterId; use ic_error_types::ErrorCode; use ic_heap_bytes::{DeterministicHeapBytes, HeapBytes, total_bytes}; use ic_interfaces::execution_environment::{SystemApiCallCounters, SystemApiCallId}; +use ic_logger::replica_logger::no_op_logger; use ic_management_canister_types_private::{ CanisterIdRecord, CanisterStatusResultV2, CanisterStatusType, Payload, }; @@ -27,6 +28,7 @@ use ic_types::{ }; use ic_types_cycles::{CanisterCyclesCostSchedule, CompoundCycles, Memory}; use ic_universal_canister::call_args; +use prometheus::IntCounter; use std::{collections::BTreeMap, sync::Arc, time::Duration}; const MAX_EXPIRY_TIME: Duration = Duration::from_secs(10); @@ -613,12 +615,11 @@ fn query_cache_ignores_balance_changes_when_query_does_not_read_balance() { assert_eq!(res_1, Ok(WasmResult::Reply(vec![42]))); // Change the canister balance. - test.canister_state_mut(b_id) - .system_state - .consume_cycles(CompoundCycles::::new( - 1_u64.into(), - CanisterCyclesCostSchedule::Normal, - )); + test.canister_state_mut(b_id).system_state.consume_cycles( + CompoundCycles::::new(1_u64.into(), CanisterCyclesCostSchedule::Normal), + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); // Run the same query for the second time. let res_2 = test.non_replicated_query(a_id, method, q); @@ -646,12 +647,11 @@ fn query_cache_ignores_balance_and_time_changes_when_query_is_static() { assert_eq!(res_1, Ok(WasmResult::Reply(vec![42]))); // Change the canister balance. - test.canister_state_mut(b_id) - .system_state - .consume_cycles(CompoundCycles::::new( - 1_u64.into(), - CanisterCyclesCostSchedule::Normal, - )); + test.canister_state_mut(b_id).system_state.consume_cycles( + CompoundCycles::::new(1_u64.into(), CanisterCyclesCostSchedule::Normal), + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); // Change the time. test.state_mut().metadata.batch_time += Duration::from_secs(1); @@ -802,12 +802,11 @@ fn query_cache_returns_different_results_for_different_canister_balances() { assert_eq!(res_1, Ok(WasmResult::Reply(vec![42]))); // Change the canister balance. - test.canister_state_mut(b_id) - .system_state - .consume_cycles(CompoundCycles::::new( - 1_u64.into(), - CanisterCyclesCostSchedule::Normal, - )); + test.canister_state_mut(b_id).system_state.consume_cycles( + CompoundCycles::::new(1_u64.into(), CanisterCyclesCostSchedule::Normal), + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); let res_2 = test.non_replicated_query(a_id, method, q); let m = query_cache_metrics(&test); @@ -832,12 +831,11 @@ fn query_cache_returns_different_results_for_different_canister_balance128s() { assert_eq!(res_1, Ok(WasmResult::Reply(vec![42]))); // Change the canister balance. - test.canister_state_mut(b_id) - .system_state - .consume_cycles(CompoundCycles::::new( - 1_u64.into(), - CanisterCyclesCostSchedule::Normal, - )); + test.canister_state_mut(b_id).system_state.consume_cycles( + CompoundCycles::::new(1_u64.into(), CanisterCyclesCostSchedule::Normal), + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); let res_2 = test.non_replicated_query(a_id, method, q); let m = query_cache_metrics(&test); @@ -873,12 +871,11 @@ fn query_cache_returns_different_results_on_combined_invalidation() { test.canister_state_mut(b_id) .system_state .bump_canister_version(); - test.canister_state_mut(b_id) - .system_state - .consume_cycles(CompoundCycles::::new( - 1_u64.into(), - CanisterCyclesCostSchedule::Normal, - )); + test.canister_state_mut(b_id).system_state.consume_cycles( + CompoundCycles::::new(1_u64.into(), CanisterCyclesCostSchedule::Normal), + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); let res_2 = test.non_replicated_query(a_id, method, q); assert_eq!(res_1, res_2); @@ -924,12 +921,14 @@ fn query_cache_frees_memory_after_invalidated_entries() { assert_gt!(heap_bytes, BIG_RESPONSE_SIZE); // Set the canister balance to 42, so the second reply will have just 42 bytes. - test.canister_state_mut(id) - .system_state - .consume_cycles(CompoundCycles::::new( + test.canister_state_mut(id).system_state.consume_cycles( + CompoundCycles::::new( ((BIG_RESPONSE_SIZE - SMALL_RESPONSE_SIZE) as u64).into(), CanisterCyclesCostSchedule::Normal, - )); + ), + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); // The new 42 reply must invalidate and replace the previous 1MB reply in the cache. let res = test diff --git a/rs/execution_environment/src/scheduler.rs b/rs/execution_environment/src/scheduler.rs index c63b673ffdcf..94e04d9d6f2d 100644 --- a/rs/execution_environment/src/scheduler.rs +++ b/rs/execution_environment/src/scheduler.rs @@ -871,6 +871,7 @@ impl SchedulerImpl { .cycles_account_manager .charge_canister_for_resource_allocation_and_usage( &self.log, + self.exec_env.charging_from_balance_error(), canister, duration_since_last_charge, subnet_cycles_config, @@ -888,9 +889,11 @@ impl SchedulerImpl { canister.system_state.clear_canister_history(); canister.remove_log(); // Burn the remaining balance of the canister. - canister - .system_state - .burn_remaining_balance_for_uninstall(cost_schedule); + canister.system_state.burn_remaining_balance_for_uninstall( + cost_schedule, + &self.log, + self.exec_env.charging_from_balance_error(), + ); canister .canister_snapshots .delete_snapshots(&mut unflushed_checkpoint_ops); diff --git a/rs/execution_environment/src/scheduler/tests/metrics.rs b/rs/execution_environment/src/scheduler/tests/metrics.rs index d55d70e000a8..76c9a60f1b00 100644 --- a/rs/execution_environment/src/scheduler/tests/metrics.rs +++ b/rs/execution_environment/src/scheduler/tests/metrics.rs @@ -42,6 +42,7 @@ use ic_types_cycles::{ }; use ic_types_test_utils::ids::{canister_test_id, message_test_id, subnet_test_id, user_test_id}; use more_asserts::assert_ge; +use prometheus::IntCounter; use std::time::Duration; #[test] @@ -1433,7 +1434,11 @@ fn consumed_cycles_for_instructions_are_updated_from_valid_canisters() { CompoundCycles::::new(Cycles::from(1000_u128), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(removed_cycles); + .consume_cycles( + removed_cycles, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); test.state_metrics().observe( test.state().metadata.own_subnet_id, @@ -1548,7 +1553,11 @@ fn consumed_cycles_are_updated_from_deleted_canisters() { CompoundCycles::::new(Cycles::from(1000_u128), cost_schedule); test.canister_state_mut(canister_id) .system_state - .consume_cycles(removed_cycles); + .consume_cycles( + removed_cycles, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), + ); test.inject_call_to_ic00( Method::DeleteCanister, diff --git a/rs/messaging/src/scheduling/valid_set_rule.rs b/rs/messaging/src/scheduling/valid_set_rule.rs index 0f092b1b8336..85e66002049f 100644 --- a/rs/messaging/src/scheduling/valid_set_rule.rs +++ b/rs/messaging/src/scheduling/valid_set_rule.rs @@ -25,7 +25,7 @@ use ic_types::{ }, time::expiry_time_from_now, }; -use prometheus::{Histogram, HistogramVec, IntCounterVec, IntGauge}; +use prometheus::{Histogram, HistogramVec, IntCounter, IntCounterVec, IntGauge}; use std::sync::Arc; struct VsrMetrics { @@ -40,6 +40,8 @@ struct VsrMetrics { /// Memory currently used by payloads of statuses in the ingress /// history. ingress_history_size: IntGauge, + /// Critical error for ingress induction costs exceeding the cycles balance. + charging_from_balance_error: IntCounter, } const METRIC_INDUCTED_INGRESS_MESSAGES: &str = "mr_inducted_ingress_message_count"; @@ -48,6 +50,8 @@ const METRIC_UNRELIABLE_INDUCT_INGRESS_MESSAGE_DURATION: &str = "mr_unreliable_induct_ingress_message_duration_seconds"; const METRIC_INGRESS_HISTORY_SIZE: &str = "mr_ingress_history_size_bytes"; +const CRITICAL_ERROR_CHARGING_FROM_BALANCE: &str = "mr_charging_from_balance"; + const LABEL_STATUS: &str = "status"; const LABEL_VALUE_SUCCESS: &str = "success"; @@ -76,6 +80,8 @@ impl VsrMetrics { METRIC_INGRESS_HISTORY_SIZE, "Memory currently used by payloads of statuses in the ingress history", ); + let charging_from_balance_error = + metrics_registry.error_counter(CRITICAL_ERROR_CHARGING_FROM_BALANCE); // Initialize all `inducted_ingress_messages` counters with zero, so they are // all exported from process start (`IntCounterVec` is really a map). @@ -98,6 +104,7 @@ impl VsrMetrics { inducted_ingress_payload_sizes, unreliable_induct_ingress_message_duration, ingress_history_size, + charging_from_balance_error, } } } @@ -310,6 +317,8 @@ impl> cost, subnet_cycles_config, reveal_top_up, + &self.log, + &self.metrics.charging_from_balance_error, ) { return Err(IngressInductionError::CanisterOutOfCycles(err)); } diff --git a/rs/replicated_state/src/canister_state/system_state.rs b/rs/replicated_state/src/canister_state/system_state.rs index d9bfb3563510..684e4b6c9729 100644 --- a/rs/replicated_state/src/canister_state/system_state.rs +++ b/rs/replicated_state/src/canister_state/system_state.rs @@ -1024,11 +1024,21 @@ impl SystemState { log: &ReplicaLogger, charging_from_balance_error: &IntCounter, ) { + let debit = CompoundCycles::::new( + self.ingress_induction_cycles_debit, + cost_schedule, + ); + // Charge only the part of the debit that the balance can cover. Dropping the + // rest is legitimate here (making some of the postponed charges free), so it + // must be capped before `consume_cycles()`, which reports what it cannot + // charge as a critical error. + // // We rely on saturating operations of `Cycles` here. - let remaining_debit = self.ingress_induction_cycles_debit - self.cycles_balance; + let uncharged_debit = debit.real() - self.cycles_balance; + self.ingress_induction_cycles_debit = Cycles::zero(); if strict { - debug_assert_eq!(remaining_debit.get(), 0); - if remaining_debit.get() > 0 { + debug_assert_eq!(uncharged_debit.get(), 0); + if uncharged_debit.get() > 0 { // This case is unreachable and may happen only due to a bug: if the // caller has reduced the cycles balance below the cycles debit. charging_from_balance_error.inc(); @@ -1036,17 +1046,17 @@ impl SystemState { log, "[EXC-BUG]: Debited cycles exceed the cycles balance of {} by {}", canister_id, - remaining_debit, + uncharged_debit, ); // Continue the execution by dropping the remaining debit, which makes // some of the postponed charges free. } } - self.consume_cycles(CompoundCycles::::new( - self.ingress_induction_cycles_debit, - cost_schedule, - )); - self.ingress_induction_cycles_debit = Cycles::zero(); + self.consume_cycles( + debit.minus_uncharged(uncharged_debit), + log, + charging_from_balance_error, + ); } /// This method is used for maintaining the backwards compatibility. @@ -2044,7 +2054,18 @@ impl SystemState { /// the consumed amount. Should be used either for cases where a prepayment /// needs to be made (that will be refunded later with `refund_cycles`) or /// a direct charge happens without a prepayment (e.g. when paying for memory). - pub fn consume_cycles(&mut self, requested_amount: CompoundCycles) { + /// + /// The balances are required to cover the requested amount: the part that + /// they cannot cover is neither charged nor reported as consumed, and is + /// reported as a critical error instead. Callers that intend to charge only + /// what the balances can cover must cap the requested amount themselves, + /// e.g. with `CompoundCycles::minus_uncharged()`. + pub fn consume_cycles( + &mut self, + requested_amount: CompoundCycles, + log: &ReplicaLogger, + charging_from_balance_error: &IntCounter, + ) { let requested_real = requested_amount.real(); let use_case = T::cycles_use_case(); let remaining_amount = match use_case { @@ -2065,9 +2086,28 @@ impl SystemState { | CyclesUseCase::BurnedCycles | CyclesUseCase::DroppedMessages => requested_real, }; + // The balance may not cover the whole amount, in which case the subtraction + // below saturates at zero and the uncovered part is never actually charged. + // Charge and report only the part that the balance could cover, so that the + // consumed cycles metrics never exceed the cycles removed from the balance. + let uncharged_amount = remaining_amount - self.cycles_balance; self.cycles_balance -= remaining_amount; + if !uncharged_amount.is_zero() { + // This case is unreachable and may happen only due to a bug: every caller + // is expected to either cover the requested amount or cap it beforehand. + charging_from_balance_error.inc(); + error!( + log, + "[EXC-BUG]: Charging {} for {} exceeds the cycles balance of {} by {}", + requested_real, + use_case.as_str(), + self.canister_id, + uncharged_amount, + ); + } + let charged_amount = requested_amount.minus_uncharged(uncharged_amount); self.observe_consumed_cycles_with_use_case( - requested_amount.nominal(), + charged_amount.nominal(), NominalCycles::zero(), use_case, ConsumingCycles::Prepayment, @@ -2117,9 +2157,16 @@ impl SystemState { pub fn burn_remaining_balance_for_uninstall( &mut self, cost_schedule: CanisterCyclesCostSchedule, + log: &ReplicaLogger, + charging_from_balance_error: &IntCounter, ) { + // The balances cover the whole amount by construction. let balance = self.cycles_balance + self.reserved_balance; - self.consume_cycles(CompoundCycles::::new(balance, cost_schedule)); + self.consume_cycles( + CompoundCycles::::new(balance, cost_schedule), + log, + charging_from_balance_error, + ); } /// Observes the consumed cycles for HTTPS outcalls. This should only be diff --git a/rs/replicated_state/src/canister_state/tests.rs b/rs/replicated_state/src/canister_state/tests.rs index 54cbc898899f..af339b771792 100644 --- a/rs/replicated_state/src/canister_state/tests.rs +++ b/rs/replicated_state/src/canister_state/tests.rs @@ -30,8 +30,8 @@ use ic_types::methods::{Callback, WasmClosure}; use ic_types::time::{CoarseTime, UNIX_EPOCH}; use ic_types::{CountBytes, Time}; use ic_types_cycles::{ - CanisterCyclesCostSchedule, CompoundCycles, Cycles, CyclesUseCase, Instructions, NominalCycles, - NominalCyclesTesting, + CanisterCyclesCostSchedule, CompoundCycles, Cycles, CyclesUseCase, Instructions, + Memory as MemoryUseCase, NominalCycles, NominalCyclesTesting, }; use ic_wasm_types::CanisterModule; use prometheus::IntCounter; @@ -857,6 +857,50 @@ fn canister_state_ingress_induction_cycles_debit() { ); } +#[test] +fn canister_state_ingress_induction_cycles_debit_exceeding_balance() { + let system_state = &mut CanisterStateFixture::new().canister_state.system_state; + let initial_balance = system_state.balance(); + let ingress_induction_debit = Cycles::new(42); + let cost_schedule = CanisterCyclesCostSchedule::Normal; + system_state.add_postponed_charge_to_ingress_induction_cycles_debit(ingress_induction_debit); + + // Mimic a cleanup callback burning the cycles balance below the pending debit. + let remaining_balance = Cycles::new(10); + system_state.remove_cycles(initial_balance - remaining_balance); + assert_eq!(remaining_balance, system_state.balance()); + assert_eq!(Cycles::zero(), system_state.debited_balance()); + + system_state.apply_ingress_induction_cycles_debit( + system_state.canister_id(), + cost_schedule, + false, // strict + &no_op_logger(), + &mock_metrics(), + ); + + // The whole balance is charged and the rest of the debit is dropped. + assert_eq!( + Cycles::zero(), + system_state.ingress_induction_cycles_debit() + ); + assert_eq!(Cycles::zero(), system_state.balance()); + // Only the charged part of the debit is reported as consumed; the dropped part + // must not show up in the consumed cycles metrics. + assert_eq!( + system_state.canister_metrics().consumed_cycles().get(), + remaining_balance.get() + ); + assert_eq!( + *system_state + .canister_metrics() + .consumed_cycles_by_use_cases() + .get(&CyclesUseCase::IngressInduction) + .unwrap(), + NominalCycles::new(remaining_balance.get()), + ); +} + const INITIAL_CYCLES: Cycles = Cycles::new(1 << 36); #[test] @@ -866,7 +910,7 @@ fn update_balance_and_consumed_cycles_correctly() { let cost_schedule = CanisterCyclesCostSchedule::Normal; let prepaid_cycles = CompoundCycles::::new(initial_consumed_cycles, cost_schedule); - system_state.consume_cycles(prepaid_cycles); + system_state.consume_cycles(prepaid_cycles, &no_op_logger(), &mock_metrics()); assert_eq!( system_state.balance(), INITIAL_CYCLES - initial_consumed_cycles @@ -894,7 +938,7 @@ fn update_balance_and_consumed_cycles_by_use_case_correctly() { let cycles_to_consume = Cycles::from(1000_u128); let cost_schedule = CanisterCyclesCostSchedule::Normal; let prepaid_cycles = CompoundCycles::::new(cycles_to_consume, cost_schedule); - system_state.consume_cycles(prepaid_cycles); + system_state.consume_cycles(prepaid_cycles, &no_op_logger(), &mock_metrics()); let refund = CompoundCycles::::new(Cycles::from(100_u128), cost_schedule); system_state.refund_cycles(prepaid_cycles, refund); @@ -912,6 +956,75 @@ fn update_balance_and_consumed_cycles_by_use_case_correctly() { ); } +#[test] +fn consume_cycles_exceeding_balance_reports_only_the_charged_amount() { + let mut system_state = CanisterStateFixture::new().canister_state.system_state; + let cost_schedule = CanisterCyclesCostSchedule::Normal; + let charging_from_balance_error = mock_metrics(); + // Request more cycles than the balance can cover. + let requested_cycles = + CompoundCycles::::new(INITIAL_CYCLES + Cycles::new(1000), cost_schedule); + system_state.consume_cycles( + requested_cycles, + &no_op_logger(), + &charging_from_balance_error, + ); + + // The balance is drained and only the drained amount is reported as consumed, + // i.e. the part of the request that the balance could not cover is not. That part + // is reported as a critical error instead. + assert_eq!(1, charging_from_balance_error.get()); + assert_eq!(Cycles::zero(), system_state.balance()); + assert_eq!( + NominalCycles::new(INITIAL_CYCLES.get()), + system_state.canister_metrics().consumed_cycles() + ); + assert_eq!( + *system_state + .canister_metrics() + .consumed_cycles_by_use_cases() + .get(&CyclesUseCase::Instructions) + .unwrap(), + NominalCycles::new(INITIAL_CYCLES.get()), + ); +} + +#[test] +fn consume_cycles_exceeding_balance_and_reserved_balance_reports_only_the_charged_amount() { + let mut system_state = CanisterStateFixture::new().canister_state.system_state; + let cost_schedule = CanisterCyclesCostSchedule::Normal; + let charging_from_balance_error = mock_metrics(); + let reserved_cycles = Cycles::new(1000); + system_state.reserve_cycles(reserved_cycles).unwrap(); + + // Request more cycles than the reserved balance and the balance together can cover. + let requested_cycles = + CompoundCycles::::new(INITIAL_CYCLES + Cycles::new(500), cost_schedule); + system_state.consume_cycles( + requested_cycles, + &no_op_logger(), + &charging_from_balance_error, + ); + + // Both balances are drained, only the drained amount is reported as consumed and + // the part that they could not cover is reported as a critical error. + assert_eq!(1, charging_from_balance_error.get()); + assert_eq!(Cycles::zero(), system_state.balance()); + assert_eq!(Cycles::zero(), system_state.reserved_balance()); + assert_eq!( + NominalCycles::new(INITIAL_CYCLES.get()), + system_state.canister_metrics().consumed_cycles() + ); + assert_eq!( + *system_state + .canister_metrics() + .consumed_cycles_by_use_cases() + .get(&CyclesUseCase::Memory) + .unwrap(), + NominalCycles::new(INITIAL_CYCLES.get()), + ); +} + #[test] fn canister_state_callback_round_trip() { use ic_protobuf::state::canister_state_bits::v1 as pb; diff --git a/rs/replicated_state/src/canister_states/tests.rs b/rs/replicated_state/src/canister_states/tests.rs index fde77f4e9552..04d2df8dd387 100644 --- a/rs/replicated_state/src/canister_states/tests.rs +++ b/rs/replicated_state/src/canister_states/tests.rs @@ -9,7 +9,9 @@ use crate::{ ExportedFunctions, InputQueueType, Memory, SchedulerState, SystemState, }; use ic_base_types::NumSeconds; +use ic_logger::replica_logger::no_op_logger; use ic_management_canister_types_private::{CanisterChangeDetails, CanisterChangeOrigin}; +use ic_metrics::MetricsRegistry; use ic_registry_subnet_type::SubnetType; use ic_test_utilities_types::ids::canister_test_id; use ic_test_utilities_types::messages::RequestBuilder; @@ -864,12 +866,14 @@ fn total_consumed_cycles_combines_hot_and_cold() { }; fn consume(canister: &mut Arc, amount: u128) { - Arc::make_mut(canister) - .system_state - .consume_cycles(CompoundCycles::::new( + Arc::make_mut(canister).system_state.consume_cycles( + CompoundCycles::::new( Cycles::new(amount), CanisterCyclesCostSchedule::Normal, - )); + ), + &no_op_logger(), + &MetricsRegistry::new().int_counter("error_counter", "Test error counter"), + ); } // Consuming cycles does not create any work, so the canister stays cold. diff --git a/rs/test_utilities/execution_environment/src/lib.rs b/rs/test_utilities/execution_environment/src/lib.rs index 08d96f86d5c6..9c114ecc1a45 100644 --- a/rs/test_utilities/execution_environment/src/lib.rs +++ b/rs/test_utilities/execution_environment/src/lib.rs @@ -2387,6 +2387,8 @@ impl ExecutionTest { CompoundCycles::::new(cycles, cost_schedule), Cycles::zero(), false, + &no_op_logger(), + &IntCounter::new("no_op", "no_op").unwrap(), ) .unwrap(); } diff --git a/rs/types/cycles/src/compound_cycles.rs b/rs/types/cycles/src/compound_cycles.rs index 9285b7512a47..87b52921d809 100644 --- a/rs/types/cycles/src/compound_cycles.rs +++ b/rs/types/cycles/src/compound_cycles.rs @@ -129,6 +129,27 @@ impl CompoundCycles { pub fn is_zero(&self) -> bool { self.real.is_zero() && self.nominal.is_zero() } + + /// Returns this amount reduced by the part of `real()` that could not be + /// charged, e.g. because the balance it was to be subtracted from did not + /// cover it. Such an amount is never removed from any balance, so it must + /// not be reported in the consumed cycles metrics either. + /// + /// Both parts are reduced by `uncharged`, saturating at zero: they coincide + /// under the normal cost schedule, while under the free cost schedule the + /// real part is zero, so nothing can be left uncharged and this is a no-op. + pub fn minus_uncharged(self, uncharged: Cycles) -> Self { + debug_assert!( + uncharged <= self.real, + "Expected the uncharged amount {uncharged} to be at most the real amount {}", + self.real + ); + Self { + real: self.real - uncharged, + nominal: self.nominal - NominalCycles::new_private(uncharged.get()), + _cycles_use_case_marker: self._cycles_use_case_marker, + } + } } impl Add for CompoundCycles {