diff --git a/integration_tests/tests/tests.rs b/integration_tests/tests/tests.rs index df00a34a..e8407fe6 100644 --- a/integration_tests/tests/tests.rs +++ b/integration_tests/tests/tests.rs @@ -1304,6 +1304,33 @@ mod metrics_tests { // Only the init and minter public key events should have been recorded .assert_contains_metric_matching(r#"total_event_count 2 \d+"#) .assert_contains_metric_matching(r#"minter_balance 0 \d+"#) + .assert_contains_metric_matching(r#"oldest_in_flight_deposit_age_seconds 0 \d+"#) + .assert_contains_metric_matching(r#"oldest_pending_mint_age_seconds 0 \d+"#) + .assert_contains_metric_matching( + r#"failed_credit_attempts\{reason="not_found"\} 0 \d+"#, + ) + .assert_contains_metric_matching( + r#"failed_credit_attempts\{reason="rpc_error"\} 0 \d+"#, + ) + .assert_contains_metric_matching( + r#"failed_credit_attempts\{reason="invalid_response"\} 0 \d+"#, + ) + .assert_contains_metric_matching( + r#"failed_credit_attempts\{reason="unreadable"\} 0 \d+"#, + ) + .assert_contains_metric_matching(r#"failed_credit_attempts\{reason="mismatch"\} 0 \d+"#) + .assert_contains_metric_matching(r#"failed_mint_attempts\{reason="expired"\} 0 \d+"#) + .assert_contains_metric_matching(r#"failed_mint_attempts\{reason="rejected"\} 0 \d+"#) + .assert_contains_metric_matching( + r#"failed_mint_attempts\{reason="ledger_error"\} 0 \d+"#, + ) + .assert_contains_metric_matching( + r#"failed_mint_attempts\{reason="created_in_future"\} 0 \d+"#, + ) + .assert_contains_metric_matching(r#"failed_mint_attempts\{reason="call_error"\} 0 \d+"#) + .assert_contains_metric_matching( + r#"failed_mint_attempts\{reason="unknown_outcome"\} 0 \d+"#, + ) .into() .drop() .await; diff --git a/minter/src/deposit/sweep/finalize/mod.rs b/minter/src/deposit/sweep/finalize/mod.rs index 1914336a..b0de1937 100644 --- a/minter/src/deposit/sweep/finalize/mod.rs +++ b/minter/src/deposit/sweep/finalize/mod.rs @@ -6,6 +6,7 @@ use crate::{ Sweep, SweepSettlementError, audit::process_event, event::EventType, mutate_state, read_state, }, + storage::{FailedCreditReason, record_failed_credit_attempt}, }; use canlog::log; use cksol_types_internal::log::Priority; @@ -53,21 +54,26 @@ pub async fn credit_finalized_sweeps(runtime: &R) -> bool { Ok(Some(outcome)) => outcome, Ok(None) => { log!( - Priority::Info, + Priority::Error, "Finalized sweep {signature} was not returned by getTransaction, retrying later" ); + record_failed_credit_attempt(FailedCreditReason::NotFound); + continue; + } + Err(e) if e.is_response_untrustworthy() => { + log!( + Priority::Error, + "Failed to fetch finalized sweep {signature}: {e}, retrying later" + ); + record_failed_credit_attempt(FailedCreditReason::InvalidResponse); continue; } Err(e) => { - let priority = if e.is_response_untrustworthy() { - Priority::Error - } else { - Priority::Info - }; log!( - priority, + Priority::Info, "Failed to fetch finalized sweep {signature}: {e}, retrying later" ); + record_failed_credit_attempt(FailedCreditReason::RpcError); continue; } }; @@ -79,9 +85,10 @@ pub async fn credit_finalized_sweeps(runtime: &R) -> bool { }, Err(SweepSettlementError::Unreadable(e)) => { log!( - Priority::Info, + Priority::Error, "Could not read the outcome of sweep {signature}: {e}, retrying later" ); + record_failed_credit_attempt(FailedCreditReason::Unreadable); continue; } Err(SweepSettlementError::Mismatch(e)) => { @@ -89,6 +96,7 @@ pub async fn credit_finalized_sweeps(runtime: &R) -> bool { Priority::Error, "Quarantining the deposits of sweep {signature}: {e}" ); + record_failed_credit_attempt(FailedCreditReason::Mismatch); EventType::QuarantinedSweep { signature } } }; diff --git a/minter/src/deposit/sweep/finalize/tests.rs b/minter/src/deposit/sweep/finalize/tests.rs index 78b2ab26..ac90ae3d 100644 --- a/minter/src/deposit/sweep/finalize/tests.rs +++ b/minter/src/deposit/sweep/finalize/tests.rs @@ -3,7 +3,7 @@ use crate::{ constants::MAX_CONCURRENT_RPC_CALLS, deposit::sweep::deposit_status, state::{event::EventType, read_state, reset_state}, - storage::reset_events, + storage::{FailedCreditReason, failed_credit_attempt_count, reset_events}, test_fixtures::{ EventsAssert, GetTransactionResult, account, devnet_sweep, events::{queue, submit_sweep_to, succeed_transaction}, @@ -15,7 +15,9 @@ use crate::{ use cksol_types::{DepositSolId, DepositSolStatus}; use sol_rpc_types::Lamport; use solana_signature::Signature; -use solana_transaction_status_client_types::EncodedConfirmedTransactionWithStatusMeta; +use solana_transaction_status_client_types::{ + EncodedConfirmedTransactionWithStatusMeta, EncodedTransaction, TransactionBinaryEncoding, +}; const FRESH_SWEEP_SIGNATURE_INDEX: usize = 0x80; @@ -108,26 +110,49 @@ async fn should_credit_the_amount_received_by_the_main_account() { devnet_sweep::DEPOSITS.len() ); }); + for reason in FailedCreditReason::ALL { + assert_eq!(failed_credit_attempt_count(reason), 0, "{reason:?}"); + } } #[tokio::test] async fn should_keep_deposits_finalized_until_the_outcome_can_be_read() { type Response = fn() -> GetTransactionResult; - let cases: [(&str, Response); 3] = [ - ("the transaction is not returned", || { - GetTransactionResult::Consistent(Ok(None)) - }), - ("fetching the transaction fails", || { - GetTransactionResult::Inconsistent(vec![]) - }), - ("the metadata cannot be read", || { - let mut outcome = devnet_sweep::derived_outcome(); - outcome.transaction.meta = None; - transaction_response(outcome) - }), + let cases: [(&str, Response, FailedCreditReason); 4] = [ + ( + "the transaction is not returned", + || GetTransactionResult::Consistent(Ok(None)), + FailedCreditReason::NotFound, + ), + ( + "fetching the transaction fails", + || GetTransactionResult::Inconsistent(vec![]), + FailedCreditReason::RpcError, + ), + ( + "the providers agree on a transaction that cannot be decoded", + || { + let mut outcome = devnet_sweep::derived_outcome(); + outcome.transaction.transaction = EncodedTransaction::Binary( + "not a transaction".to_string(), + TransactionBinaryEncoding::Base64, + ); + transaction_response(outcome) + }, + FailedCreditReason::InvalidResponse, + ), + ( + "the metadata cannot be read", + || { + let mut outcome = devnet_sweep::derived_outcome(); + outcome.transaction.meta = None; + transaction_response(outcome) + }, + FailedCreditReason::Unreadable, + ), ]; - for (name, response) in cases { + for (name, response, expected_reason) in cases { setup(); let sweep_signature = finalize_devnet_sweep(); let events_before = EventsAssert::from_recorded(); @@ -154,6 +179,7 @@ async fn should_keep_deposits_finalized_until_the_outcome_can_be_read() { }, "{name}" ); + assert_eq!(failed_credit_attempt_count(expected_reason), 1, "{name}"); } } @@ -183,6 +209,7 @@ async fn should_quarantine_deposits_if_the_outcome_does_not_match_the_plan() { signature: sweep_signature.into() } ); + assert_eq!(failed_credit_attempt_count(FailedCreditReason::Mismatch), 1); } fn setup() { diff --git a/minter/src/deposit/sweep/mint/mod.rs b/minter/src/deposit/sweep/mint/mod.rs index 8d03698e..4ed20d6a 100644 --- a/minter/src/deposit/sweep/mint/mod.rs +++ b/minter/src/deposit/sweep/mint/mod.rs @@ -8,6 +8,7 @@ use crate::{ PendingMint, State, TaskType, audit::process_event, event::EventType, mutate_state, read_state, }, + storage::{FailedMintReason, record_failed_mint_attempt}, }; use canlog::log; use cksol_types::{DepositSolId, Memo, MintMemo}; @@ -84,11 +85,13 @@ async fn process_pending_mint( Priority::Error, "Quarantining deposit {deposit_id}: its pending mint is older than the deduplication window of the ledger" ); + record_failed_mint_attempt(FailedMintReason::Expired); record_quarantined_pending_mint(runtime, deposit_id); return; } let quarantine_unless_defused = scopeguard::guard(deposit_id, |deposit_id| { + record_failed_mint_attempt(FailedMintReason::UnknownOutcome); record_quarantined_pending_mint(runtime, deposit_id); }); @@ -118,34 +121,49 @@ async fn process_pending_mint( ScopeGuard::into_inner(quarantine_unless_defused); } Ok(Err(TransferError::TooOld)) => { + ScopeGuard::into_inner(quarantine_unless_defused); + record_failed_mint_attempt(FailedMintReason::Expired); log!( Priority::Error, "Quarantining deposit {deposit_id}: the ledger rejected its mint as outside the deduplication window" ); + record_quarantined_pending_mint(runtime, deposit_id); } Ok(Err( rejection @ (TransferError::BadFee { .. } | TransferError::BadBurn { .. } | TransferError::InsufficientFunds { .. }), )) => { + ScopeGuard::into_inner(quarantine_unless_defused); + record_failed_mint_attempt(FailedMintReason::Rejected); log!( Priority::Error, "Quarantining deposit {deposit_id}: the ledger definitively rejected its mint from the minting account: {rejection:?}" ); + record_quarantined_pending_mint(runtime, deposit_id); } Ok(Err( - transient @ (TransferError::TemporarilyUnavailable - | TransferError::GenericError { .. } - | TransferError::CreatedInFuture { .. }), + transient + @ (TransferError::TemporarilyUnavailable | TransferError::GenericError { .. }), )) => { ScopeGuard::into_inner(quarantine_unless_defused); + record_failed_mint_attempt(FailedMintReason::LedgerError); log!( Priority::Info, "Failed to mint deposit {deposit_id}, retrying on the next round: {transient:?}" ); } + Ok(Err(clock_skew @ TransferError::CreatedInFuture { .. })) => { + ScopeGuard::into_inner(quarantine_unless_defused); + record_failed_mint_attempt(FailedMintReason::CreatedInFuture); + log!( + Priority::Info, + "Failed to mint deposit {deposit_id}, retrying on the next round: {clock_skew:?}" + ); + } Err(ic_error) => { ScopeGuard::into_inner(quarantine_unless_defused); + record_failed_mint_attempt(FailedMintReason::CallError); log!( Priority::Info, "Failed to mint deposit {deposit_id}, retrying on the next round: {ic_error}" diff --git a/minter/src/deposit/sweep/mint/tests.rs b/minter/src/deposit/sweep/mint/tests.rs index 9a1bd870..6752fc08 100644 --- a/minter/src/deposit/sweep/mint/tests.rs +++ b/minter/src/deposit/sweep/mint/tests.rs @@ -3,7 +3,7 @@ use crate::{ constants::{GET_BALANCE_CYCLES, LEDGER_DEDUPLICATION_WINDOW, MAX_PENDING_MINTS_PER_ROUND}, deposit::sweep::{deposit_sol, timer::MAX_DEPOSITS_PER_SWEEP}, state::{TaskType, event::EventType, mutate_state, read_state, reset_state}, - storage::reset_events, + storage::{FailedMintReason, failed_mint_attempt_count, reset_events}, test_fixtures::{ BLOCK_INDEX, DEPOSIT_SOL_REQUIRED_CYCLES, EventsAssert, MINIMUM_DEPOSIT_AMOUNT, account, flow::deposit::{DepositFlow, PendingMintFlow, SweepFlow}, @@ -108,27 +108,42 @@ async fn should_record_duplicate_reply_as_minted() { #[tokio::test] async fn should_retry_after_transient_failure_with_exactly_the_same_arguments() { type AddFailure = fn(TestCanisterRuntime) -> TestCanisterRuntime; - let transient_failures: [(&str, AddFailure); 4] = [ - ("the ledger is temporarily unavailable", |runtime| { - runtime.add_stub_response::(Err(TransferError::TemporarilyUnavailable)) - }), - ("the ledger returns a generic error", |runtime| { - runtime.add_stub_response::(Err(TransferError::GenericError { - error_code: Nat::from(42_u8), - message: "out of luck".to_string(), - })) - }), - ("the minter clock is ahead of the ledger", |runtime| { - runtime.add_stub_response::(Err(TransferError::CreatedInFuture { - ledger_time: 0, - })) - }), - ("the call to the ledger fails", |runtime| { - runtime.add_stub_error(IcError::CallPerformFailed) - }), + let transient_failures: [(&str, AddFailure, FailedMintReason); 4] = [ + ( + "the ledger is temporarily unavailable", + |runtime| { + runtime.add_stub_response::(Err(TransferError::TemporarilyUnavailable)) + }, + FailedMintReason::LedgerError, + ), + ( + "the ledger returns a generic error", + |runtime| { + runtime.add_stub_response::(Err(TransferError::GenericError { + error_code: Nat::from(42_u8), + message: "out of luck".to_string(), + })) + }, + FailedMintReason::LedgerError, + ), + ( + "the minter clock is ahead of the ledger", + |runtime| { + runtime.add_stub_response::(Err(TransferError::CreatedInFuture { + ledger_time: 0, + })) + }, + FailedMintReason::CreatedInFuture, + ), + ( + "the call to the ledger fails", + |runtime| runtime.add_stub_error(IcError::CallPerformFailed), + FailedMintReason::CallError, + ), ]; - for (name, add_failure) in transient_failures { + let mut expected_attempts = std::collections::BTreeMap::new(); + for (name, add_failure, expected_reason) in transient_failures { setup(); let pending = credited_pending_mint(); let events_before = EventsAssert::from_recorded(); @@ -136,6 +151,12 @@ async fn should_retry_after_transient_failure_with_exactly_the_same_arguments() process_pending_mints(failing_runtime.clone()).await; + *expected_attempts.entry(expected_reason).or_insert(0_u64) += 1; + assert_eq!( + failed_mint_attempt_count(expected_reason), + expected_attempts[&expected_reason], + "{name}" + ); assert_eq!( deposit_status(pending.deposit_id), DepositSolStatus::Finalized { @@ -175,6 +196,7 @@ async fn should_quarantine_pending_mint() { runtime: TestCanisterRuntime, expected_ledger_calls: usize, traps: bool, + expected_reason: FailedMintReason, } let stale_now = CREDITED_AT_TIME + LEDGER_DEDUPLICATION_WINDOW.as_nanos() as u64 + 1; let cases = [ @@ -183,12 +205,14 @@ async fn should_quarantine_pending_mint() { runtime: TestCanisterRuntime::new().add_times([stale_now; 3]), expected_ledger_calls: 0, traps: false, + expected_reason: FailedMintReason::Expired, }, QuarantineCase { name: "the ledger rejects the mint as too old", runtime: mint_runtime([Err(TransferError::TooOld)]), expected_ledger_calls: 1, traps: false, + expected_reason: FailedMintReason::Expired, }, QuarantineCase { name: "the ledger rejects the fee of the mint", @@ -197,6 +221,7 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, + expected_reason: FailedMintReason::Rejected, }, QuarantineCase { name: "the ledger takes the mint for a burn below the minimum", @@ -205,6 +230,7 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, + expected_reason: FailedMintReason::Rejected, }, QuarantineCase { name: "the ledger reports insufficient funds on the minting account", @@ -213,20 +239,24 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, + expected_reason: FailedMintReason::Rejected, }, QuarantineCase { name: "the callback traps after the ledger minted because mint index is not u64", runtime: mint_runtime([Ok(Nat::from(u128::MAX))]), expected_ledger_calls: 1, traps: true, + expected_reason: FailedMintReason::UnknownOutcome, }, ]; + let mut expected_attempts = std::collections::BTreeMap::new(); for QuarantineCase { name, runtime, expected_ledger_calls, traps, + expected_reason, } in cases { setup(); @@ -252,6 +282,14 @@ async fn should_quarantine_pending_mint() { EventsAssert::from_recorded().expect_contains_event_eq(EventType::QuarantinedPendingMint { deposit_id: pending.deposit_id, }); + *expected_attempts.entry(expected_reason).or_insert(0_u64) += 1; + for reason in FailedMintReason::ALL { + assert_eq!( + failed_mint_attempt_count(reason), + expected_attempts.get(&reason).copied().unwrap_or(0), + "{name}: {reason:?}" + ); + } assert_eq!(runtime.set_timer_call_count(), 0, "{name}"); } } diff --git a/minter/src/metrics.rs b/minter/src/metrics.rs index e8dae4a6..93238d0c 100644 --- a/minter/src/metrics.rs +++ b/minter/src/metrics.rs @@ -1,8 +1,9 @@ use crate::state::{QuarantineCause, State}; -use crate::storage; +use crate::storage::{self, FailedCreditReason, FailedMintReason}; use ic_metrics_encoder::MetricsEncoder; const WASM_PAGE_SIZE_IN_BYTES: usize = 65536; +const NANOS_PER_SECOND: u64 = 1_000_000_000; pub fn encode_metrics(w: &mut MetricsEncoder>, s: &State) -> std::io::Result<()> { w.encode_gauge( @@ -96,18 +97,41 @@ pub fn encode_metrics(w: &mut MetricsEncoder>, s: &State) -> std::io::Re s.failed_transactions().len().metric_value(), "Number of failed Solana transactions.", )?; - let oldest_incomplete_withdrawal_age_seconds = s - .oldest_incomplete_withdrawal_created_at() - .map(|created_at| { - let now = ic_cdk::api::time(); - now.saturating_sub(created_at) / 1_000_000_000 - }) - .unwrap_or(0); w.encode_gauge( "oldest_incomplete_withdrawal_age_seconds", - oldest_incomplete_withdrawal_age_seconds.metric_value(), + age_seconds(s.oldest_incomplete_withdrawal_created_at()).metric_value(), "Age of the oldest incomplete withdrawal request in seconds. Returns 0 if there are no incomplete withdrawals.", )?; + w.encode_gauge( + "oldest_in_flight_deposit_age_seconds", + age_seconds(s.deposits().oldest_in_flight_queued_at()).metric_value(), + "Age of the oldest in-flight deposit in seconds, from queued until minted, dropped or quarantined. Returns 0 if there are no in-flight deposits.", + )?; + w.encode_gauge( + "oldest_pending_mint_age_seconds", + age_seconds(s.deposits().oldest_pending_mint_created_at()).metric_value(), + "Age of the oldest pending ckSOL mint in seconds, from the created_at_time the ledger deduplicates it by. Returns 0 if there are no pending mints.", + )?; + let mut failed_credit_attempts = w.counter_vec( + "failed_credit_attempts", + "Number of failed attempts to credit the deposits of a finalized sweep, by reason.", + )?; + for reason in FailedCreditReason::ALL { + failed_credit_attempts = failed_credit_attempts.value( + &[("reason", reason.label())], + storage::failed_credit_attempt_count(reason).metric_value(), + )?; + } + let mut failed_mint_attempts = w.counter_vec( + "failed_mint_attempts", + "Number of failed attempts to mint a pending deposit on the ckSOL ledger, by reason.", + )?; + for reason in FailedMintReason::ALL { + failed_mint_attempts = failed_mint_attempts.value( + &[("reason", reason.label())], + storage::failed_mint_attempt_count(reason).metric_value(), + )?; + } w.encode_gauge( "minter_balance", s.balance().metric_value(), @@ -126,6 +150,12 @@ pub fn encode_metrics(w: &mut MetricsEncoder>, s: &State) -> std::io::Re Ok(()) } +fn age_seconds(start: Option) -> u64 { + start + .map(|start| ic_cdk::api::time().saturating_sub(start) / NANOS_PER_SECOND) + .unwrap_or(0) +} + pub trait MetricValue { fn metric_value(&self) -> f64; } diff --git a/minter/src/state/audit.rs b/minter/src/state/audit.rs index 9e73f94a..d93b62ed 100644 --- a/minter/src/state/audit.rs +++ b/minter/src/state/audit.rs @@ -50,7 +50,7 @@ fn apply_state_transition(state: &mut State, payload: &EventType, timestamp: u64 address, balance, } => { - state.process_queued_deposit(*deposit_id, account, address, *balance); + state.process_queued_deposit(*deposit_id, account, address, *balance, timestamp); } EventType::CreditedSweep { signature, diff --git a/minter/src/state/deposits/mod.rs b/minter/src/state/deposits/mod.rs index cb1637cd..7e30a49d 100644 --- a/minter/src/state/deposits/mod.rs +++ b/minter/src/state/deposits/mod.rs @@ -63,6 +63,7 @@ pub struct Deposits { dropped: BTreeMap, quarantined: BTreeMap, in_flight_ids: BTreeMap, + queued_at_by_id: BTreeMap, } impl Deposits { @@ -102,6 +103,22 @@ impl Deposits { self.in_flight_ids.get(account).copied() } + /// Returns the timestamp (in nanoseconds) at which the oldest in-flight deposit was queued. + /// A deposit is in flight from the moment it is queued until it is minted, dropped or + /// quarantined, whatever sweep stage it has reached in between. + pub fn oldest_in_flight_queued_at(&self) -> Option { + self.queued_at_by_id.values().min().copied() + } + + /// Returns the smallest `created_at_time` of the pending mints, the timestamp the + /// deduplication window of the oldest pending mint starts at. + pub fn oldest_pending_mint_created_at(&self) -> Option { + self.pending_mints + .values() + .map(|pending| pending.created_at_time) + .min() + } + pub fn status(&self, deposit_id: DepositSolId) -> DepositSolStatus { if let Some(deposit) = self.queued.get(&deposit_id) { return DepositSolStatus::Queued { @@ -142,7 +159,12 @@ impl Deposits { DepositSolStatus::NotFound } - pub(super) fn queue(&mut self, deposit_id: DepositSolId, deposit: QueuedDeposit) { + pub(super) fn queue( + &mut self, + deposit_id: DepositSolId, + deposit: QueuedDeposit, + queued_at: u64, + ) { assert_eq!( deposit_id, self.next_id, "Attempted to queue deposit {deposit_id} out of sequence, expected {}", @@ -156,6 +178,7 @@ impl Deposits { deposit.account ); self.queued.insert(deposit_id, deposit); + self.queued_at_by_id.insert(deposit_id, queued_at); self.next_id += 1; } @@ -197,6 +220,7 @@ impl Deposits { .unwrap_or_else(|| panic!("Attempted to drop sweep {signature} that is not swept")); for (deposit_id, deposit) in sweep.deposits() { self.release_in_flight(*deposit_id, &deposit.account); + self.queued_at_by_id.remove(deposit_id); self.dropped.insert( *deposit_id, SweptDeposit { @@ -226,6 +250,9 @@ impl Deposits { }, ) })); + for deposit_id in sweep.deposits().keys() { + self.queued_at_by_id.remove(deposit_id); + } } fn release_in_flight(&mut self, deposit_id: DepositSolId, account: &Account) { @@ -299,6 +326,7 @@ impl Deposits { panic!("Attempted to mint deposit {deposit_id} that has no pending mint") }); self.release_in_flight(deposit_id, &pending.account()); + self.queued_at_by_id.remove(&deposit_id); self.minted.insert( deposit_id, MintedSweep { @@ -313,6 +341,7 @@ impl Deposits { let pending = self.pending_mints.remove(&deposit_id).unwrap_or_else(|| { panic!("Attempted to quarantine deposit {deposit_id} that has no pending mint") }); + self.queued_at_by_id.remove(&deposit_id); self.quarantined.insert( deposit_id, QuarantinedDeposit { diff --git a/minter/src/state/deposits/tests.rs b/minter/src/state/deposits/tests.rs index d8079d5b..f204eab2 100644 --- a/minter/src/state/deposits/tests.rs +++ b/minter/src/state/deposits/tests.rs @@ -53,8 +53,8 @@ mod queue { #[test] fn should_assign_sequential_ids_and_keep_accounts_in_flight() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); - deposits.queue(1, queued_deposit(1)); + deposits.queue(0, queued_deposit(0), 0); + deposits.queue(1, queued_deposit(1), 0); assert_eq!(deposits.next_id(), 2); assert_eq!( @@ -69,7 +69,7 @@ mod queue { #[test] fn should_report_the_status_of_queued_and_unknown_deposits() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); + deposits.queue(0, queued_deposit(0), 0); assert_eq!( deposits.status(0), @@ -83,16 +83,16 @@ mod queue { #[test] #[should_panic(expected = "out of sequence")] fn should_panic_if_deposit_id_out_of_sequence() { - Deposits::default().queue(1, queued_deposit(1)); + Deposits::default().queue(1, queued_deposit(1), 0); } #[test] #[should_panic(expected = "already has one in flight")] fn should_panic_if_account_already_in_flight() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); + deposits.queue(0, queued_deposit(0), 0); - deposits.queue(1, queued_deposit_of(queued_deposit(0).account, 200)); + deposits.queue(1, queued_deposit_of(queued_deposit(0).account, 200), 0); } } @@ -105,9 +105,9 @@ mod sweep { #[test] fn should_move_queued_deposits_to_a_sweep_and_return_the_expected_received_amount() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); - deposits.queue(1, queued_deposit(1)); - deposits.queue(2, queued_deposit(2)); + deposits.queue(0, queued_deposit(0), 0); + deposits.queue(1, queued_deposit(1), 0); + deposits.queue(2, queued_deposit(2), 0); let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); let expected_received = deposits.sweep( @@ -166,7 +166,7 @@ mod sweep { #[should_panic(expected = "Attempted to sweep unknown or already swept deposit 0")] fn should_panic_when_sweeping_already_swept_deposit() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); + deposits.queue(0, queued_deposit(0), 0); deposits.sweep( &[0], MINTER_ADDRESS, @@ -186,8 +186,8 @@ mod sweep { #[should_panic(expected = "the plan builds")] fn should_panic_when_the_message_does_not_match_the_plan() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); - deposits.queue(1, queued_deposit(1)); + deposits.queue(0, queued_deposit(0), 0); + deposits.queue(1, queued_deposit(1), 0); deposits.sweep( &[0, 1], @@ -212,8 +212,8 @@ mod sweep { #[should_panic(expected = "Attempted to record sweep")] fn should_panic_when_reusing_a_sweep_signature() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); - deposits.queue(1, queued_deposit(1)); + deposits.queue(0, queued_deposit(0), 0); + deposits.queue(1, queued_deposit(1), 0); let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); deposits.sweep( &[0], @@ -288,9 +288,9 @@ mod finalize_swept { #[test] fn should_move_the_sweep_to_finalized() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); - deposits.queue(1, queued_deposit(1)); - deposits.queue(2, queued_deposit(2)); + deposits.queue(0, queued_deposit(0), 0); + deposits.queue(1, queued_deposit(1), 0); + deposits.queue(2, queued_deposit(2), 0); let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); deposits.sweep( &[2, 0], @@ -387,7 +387,7 @@ mod credit_sweep { #[should_panic(expected = "Attempted to credit sweep")] fn should_panic_when_the_sweep_is_not_finalized() { let mut deposits = Deposits::default(); - deposits.queue(0, queued_deposit(0)); + deposits.queue(0, queued_deposit(0), 0); let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); deposits.sweep( &[0], @@ -616,11 +616,133 @@ mod quarantine_sweep { } } +mod oldest_in_flight { + use super::{ + CREDIT_TIMESTAMP, Deposits, LedgerMintIndex, MINTER_ADDRESS, SWEEP_SIGNATURE_INDEX, mint, + queued_deposit, signature, sweep_message, + }; + + #[test] + fn should_report_no_queued_at_without_in_flight_deposits() { + assert_eq!(Deposits::default().oldest_in_flight_queued_at(), None); + } + + #[test] + fn should_report_the_oldest_queued_at_until_the_deposit_is_minted() { + let mut deposits = Deposits::default(); + deposits.queue(0, queued_deposit(0), 10); + deposits.queue(1, queued_deposit(1), 20); + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(10)); + + let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); + deposits.sweep( + &[0], + MINTER_ADDRESS, + &sweep_message([(0, queued_deposit(0))]), + &sweep_signature, + ); + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(10)); + + deposits.finalize_swept(&sweep_signature); + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(10)); + + deposits.credit_sweep(&sweep_signature, &[mint(0, 100)], CREDIT_TIMESTAMP); + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(10)); + + deposits.mint(0, LedgerMintIndex::from(42)); + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(20)); + } + + #[test] + fn should_stop_tracking_the_deposits_of_a_dropped_sweep() { + let mut deposits = Deposits::default(); + deposits.queue(0, queued_deposit(0), 10); + deposits.queue(1, queued_deposit(1), 20); + let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); + deposits.sweep( + &[0], + MINTER_ADDRESS, + &sweep_message([(0, queued_deposit(0))]), + &sweep_signature, + ); + + deposits.drop_swept(&sweep_signature); + + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(20)); + } + + #[test] + fn should_stop_tracking_the_deposits_of_a_quarantined_sweep() { + let mut deposits = Deposits::default(); + deposits.queue(0, queued_deposit(0), 10); + deposits.queue(1, queued_deposit(1), 20); + let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); + deposits.sweep( + &[0], + MINTER_ADDRESS, + &sweep_message([(0, queued_deposit(0))]), + &sweep_signature, + ); + deposits.finalize_swept(&sweep_signature); + + deposits.quarantine_sweep(&sweep_signature); + + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(20)); + } + + #[test] + fn should_stop_tracking_a_quarantined_pending_mint() { + let mut deposits = Deposits::default(); + deposits.queue(0, queued_deposit(0), 10); + deposits.queue(1, queued_deposit(1), 20); + let sweep_signature = signature(SWEEP_SIGNATURE_INDEX); + deposits.sweep( + &[0], + MINTER_ADDRESS, + &sweep_message([(0, queued_deposit(0))]), + &sweep_signature, + ); + deposits.finalize_swept(&sweep_signature); + deposits.credit_sweep(&sweep_signature, &[mint(0, 100)], CREDIT_TIMESTAMP); + + deposits.quarantine_pending_mint(0); + + assert_eq!(deposits.oldest_in_flight_queued_at(), Some(20)); + } +} + +mod oldest_pending_mint { + use super::{CREDIT_TIMESTAMP, Deposits, LedgerMintIndex, credited_sweep, mint}; + + #[test] + fn should_report_no_created_at_time_without_pending_mints() { + assert_eq!(Deposits::default().oldest_pending_mint_created_at(), None); + } + + #[test] + fn should_report_the_created_at_time_until_the_deposit_is_minted() { + let (mut deposits, _) = credited_sweep(&[mint(0, 100), mint(1, 200)]); + assert_eq!( + deposits.oldest_pending_mint_created_at(), + Some(CREDIT_TIMESTAMP) + ); + + deposits.mint(0, LedgerMintIndex::from(42)); + assert_eq!( + deposits.oldest_pending_mint_created_at(), + Some(CREDIT_TIMESTAMP) + ); + + deposits.mint(1, LedgerMintIndex::from(43)); + assert_eq!(deposits.oldest_pending_mint_created_at(), None); + } +} + /// Queues `N` distinct deposits under the ids `0..N` and returns them in that order. fn queue_deposits(deposits: &mut Deposits) -> [QueuedDeposit; N] { std::array::from_fn(|index| { let deposit = queued_deposit(index as DepositSolId); - deposits.queue(index as DepositSolId, deposit); + deposits.queue(index as DepositSolId, deposit, 0); deposit }) } @@ -644,7 +766,7 @@ fn finalized_sweep(deposit_ids: &[DepositSolId]) -> (Deposits, Signature) { .expect("BUG: a sweep needs at least one deposit"); let mut deposits = Deposits::default(); for deposit_id in 0..=highest_swept { - deposits.queue(deposit_id, queued_deposit(deposit_id)); + deposits.queue(deposit_id, queued_deposit(deposit_id), 0); } let swept: Vec<_> = deposit_ids .iter() diff --git a/minter/src/state/mod.rs b/minter/src/state/mod.rs index df6eef83..dd9a1423 100644 --- a/minter/src/state/mod.rs +++ b/minter/src/state/mod.rs @@ -403,6 +403,7 @@ impl State { account: &Account, address: &Address, balance: DepositBalance, + queued_at: u64, ) { debug_assert_eq!( *address, @@ -421,6 +422,7 @@ impl State { address: *address, balance, }, + queued_at, ); } diff --git a/minter/src/state/tests.rs b/minter/src/state/tests.rs index 434d6d2f..23f09c65 100644 --- a/minter/src/state/tests.rs +++ b/minter/src/state/tests.rs @@ -102,8 +102,9 @@ mod queued_deposits { #[test] fn should_replay_queued_deposits_like_direct_transitions() { + let queued_at = |deposit_id| 10 * (deposit_id + 1); let queued = |deposit_id| Event { - timestamp: 0, + timestamp: queued_at(deposit_id), payload: EventType::QueuedDeposit { deposit_id, account: queued_deposit(deposit_id).account, @@ -128,12 +129,17 @@ mod queued_deposits { &deposit.account, &deposit.address, deposit.balance, + queued_at(deposit_id), ); } let replayed = replay_events([init, key_fetched, queued(0), queued(1)]); assert_eq!(replayed, expected); + assert_eq!( + replayed.deposits().oldest_in_flight_queued_at(), + Some(queued_at(0)) + ); } } diff --git a/minter/src/storage/mod.rs b/minter/src/storage/mod.rs index 5f07210d..084feee3 100644 --- a/minter/src/storage/mod.rs +++ b/minter/src/storage/mod.rs @@ -6,7 +6,7 @@ use ic_stable_structures::{ DefaultMemoryImpl, StableLog, memory_manager::{MemoryId, MemoryManager, VirtualMemory}, }; -use std::cell::RefCell; +use std::{cell::RefCell, collections::BTreeMap}; const EVENT_LOG_INDEX_MEMORY_ID: MemoryId = MemoryId::new(0); const EVENT_LOG_DATA_MEMORY_ID: MemoryId = MemoryId::new(1); @@ -36,6 +36,8 @@ thread_local! { #[derive(Default)] pub(crate) struct Metrics { pub post_upgrade_instructions_consumed: u64, + pub failed_credit_attempts: BTreeMap, + pub failed_mint_attempts: BTreeMap, pub withdrawal_transaction_rebroadcasts: u64, } @@ -43,11 +45,92 @@ impl Metrics { const fn new() -> Self { Self { post_upgrade_instructions_consumed: 0, + failed_credit_attempts: BTreeMap::new(), + failed_mint_attempts: BTreeMap::new(), withdrawal_transaction_rebroadcasts: 0, } } } +/// Why an attempt to credit the deposits of a finalized sweep failed. +#[derive(Clone, Copy, Debug, PartialEq, Eq, PartialOrd, Ord)] +pub enum FailedCreditReason { + NotFound, + RpcError, + InvalidResponse, + Unreadable, + Mismatch, +} + +impl FailedCreditReason { + pub const ALL: [Self; 5] = [ + Self::NotFound, + Self::RpcError, + Self::InvalidResponse, + Self::Unreadable, + Self::Mismatch, + ]; + + pub fn label(self) -> &'static str { + match self { + Self::NotFound => "not_found", + Self::RpcError => "rpc_error", + Self::InvalidResponse => "invalid_response", + Self::Unreadable => "unreadable", + Self::Mismatch => "mismatch", + } + } +} + +pub(crate) fn record_failed_credit_attempt(reason: FailedCreditReason) { + with_unstable_metrics_mut(|m| *m.failed_credit_attempts.entry(reason).or_insert(0) += 1); +} + +pub(crate) fn failed_credit_attempt_count(reason: FailedCreditReason) -> u64 { + with_unstable_metrics(|m| m.failed_credit_attempts.get(&reason).copied().unwrap_or(0)) +} + +/// Why an attempt to mint a pending deposit on the ckSOL ledger failed. +#[derive(Clone, Copy, Debug, PartialEq, Eq, PartialOrd, Ord)] +pub enum FailedMintReason { + Expired, + Rejected, + LedgerError, + CreatedInFuture, + CallError, + UnknownOutcome, +} + +impl FailedMintReason { + pub const ALL: [Self; 6] = [ + Self::Expired, + Self::Rejected, + Self::LedgerError, + Self::CreatedInFuture, + Self::CallError, + Self::UnknownOutcome, + ]; + + pub fn label(self) -> &'static str { + match self { + Self::Expired => "expired", + Self::Rejected => "rejected", + Self::LedgerError => "ledger_error", + Self::CreatedInFuture => "created_in_future", + Self::CallError => "call_error", + Self::UnknownOutcome => "unknown_outcome", + } + } +} + +pub(crate) fn record_failed_mint_attempt(reason: FailedMintReason) { + with_unstable_metrics_mut(|m| *m.failed_mint_attempts.entry(reason).or_insert(0) += 1); +} + +pub(crate) fn failed_mint_attempt_count(reason: FailedMintReason) -> u64 { + with_unstable_metrics(|m| m.failed_mint_attempts.get(&reason).copied().unwrap_or(0)) +} + /// Appends the event to the event log. pub fn record_event(payload: EventType, runtime: &R) { EVENTS