From d642aaf2b70bca940edecc91ad8a445d8353fce9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gr=C3=A9gory=20Demay?= Date: Fri, 2 Oct 2026 07:22:53 +0000 Subject: [PATCH 1/7] feat(minter): report deposit age and failed credit attempts Add an oldest_in_flight_deposit_age_seconds gauge covering every stage from queued to pending mint, deriving each deposit's queued_at from the QueuedDeposit event timestamp so that it survives an event replay, and a failed_credit_attempts counter labelled by reason. Co-Authored-By: Claude Fable 5 --- integration_tests/tests/tests.rs | 11 ++ minter/src/deposit/sweep/finalize/mod.rs | 5 + minter/src/deposit/sweep/finalize/tests.rs | 41 ++++--- minter/src/metrics.rs | 33 +++-- minter/src/state/audit.rs | 2 +- minter/src/state/deposits/mod.rs | 22 +++- minter/src/state/deposits/tests.rs | 135 ++++++++++++++++++--- minter/src/state/mod.rs | 2 + minter/src/state/tests.rs | 8 +- minter/src/storage/mod.rs | 39 +++++- 10 files changed, 251 insertions(+), 47 deletions(-) diff --git a/integration_tests/tests/tests.rs b/integration_tests/tests/tests.rs index ed9592e3..5f7a1904 100644 --- a/integration_tests/tests/tests.rs +++ b/integration_tests/tests/tests.rs @@ -1609,6 +1609,17 @@ 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#"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="unreadable"\} 0 \d+"#, + ) + .assert_contains_metric_matching(r#"failed_credit_attempts\{reason="mismatch"\} 0 \d+"#) .into() .drop() .await; diff --git a/minter/src/deposit/sweep/finalize/mod.rs b/minter/src/deposit/sweep/finalize/mod.rs index ebf72b35..43b9a801 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; @@ -56,6 +57,7 @@ pub async fn credit_finalized_sweeps(runtime: &R) -> bool { Priority::Info, "Finalized sweep {signature} was not returned by getTransaction, retrying later" ); + record_failed_credit_attempt(FailedCreditReason::NotFound); continue; } Err(e) => { @@ -63,6 +65,7 @@ pub async fn credit_finalized_sweeps(runtime: &R) -> bool { Priority::Info, "Failed to fetch finalized sweep {signature}: {e}, retrying later" ); + record_failed_credit_attempt(FailedCreditReason::RpcError); continue; } }; @@ -77,6 +80,7 @@ pub async fn credit_finalized_sweeps(runtime: &R) -> bool { Priority::Info, "Could not read the outcome of sweep {signature}: {e}, retrying later" ); + record_failed_credit_attempt(FailedCreditReason::Unreadable); continue; } Err(SweepSettlementError::Mismatch(e)) => { @@ -84,6 +88,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 6de93349..68a02294 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, MINTER_ADDRESS, account, devnet_sweep, events::{queue, queue_deposit, submit_sweep, succeed_transaction}, @@ -104,26 +104,37 @@ 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); 3] = [ + ( + "the transaction is not returned", + || GetTransactionResult::Consistent(Ok(None)), + FailedCreditReason::NotFound, + ), + ( + "fetching the transaction fails", + || GetTransactionResult::Inconsistent(vec![]), + FailedCreditReason::RpcError, + ), + ( + "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(); @@ -150,6 +161,7 @@ async fn should_keep_deposits_finalized_until_the_outcome_can_be_read() { }, "{name}" ); + assert_eq!(failed_credit_attempt_count(expected_reason), 1, "{name}"); } } @@ -179,6 +191,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/metrics.rs b/minter/src/metrics.rs index 1a5b53c9..8131f151 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}; 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( @@ -115,18 +116,26 @@ 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. Returns 0 if there are no in-flight deposits.", + )?; + 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(), + )?; + } w.encode_gauge( "minter_balance", s.balance().metric_value(), @@ -140,6 +149,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 c85e2449..7a836f81 100644 --- a/minter/src/state/audit.rs +++ b/minter/src/state/audit.rs @@ -78,7 +78,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..5d3f729c 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,13 @@ 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() + } + pub fn status(&self, deposit_id: DepositSolId) -> DepositSolStatus { if let Some(deposit) = self.queued.get(&deposit_id) { return DepositSolStatus::Queued { @@ -142,7 +150,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 +169,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 +211,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 +241,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 +317,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 +332,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..be469b3c 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,106 @@ 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)); + } +} + /// 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 +739,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 a4ce202c..58d9a132 100644 --- a/minter/src/state/mod.rs +++ b/minter/src/state/mod.rs @@ -479,6 +479,7 @@ impl State { account: &Account, address: &Address, balance: DepositBalance, + queued_at: u64, ) { debug_assert_eq!( *address, @@ -497,6 +498,7 @@ impl State { address: *address, balance, }, + queued_at, ); } diff --git a/minter/src/state/tests.rs b/minter/src/state/tests.rs index 2eda06d4..d18ef29d 100644 --- a/minter/src/state/tests.rs +++ b/minter/src/state/tests.rs @@ -103,8 +103,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, @@ -129,12 +130,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 d59d3093..f675d259 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,16 +36,53 @@ thread_local! { #[derive(Default)] pub(crate) struct Metrics { pub post_upgrade_instructions_consumed: u64, + pub failed_credit_attempts: BTreeMap, } impl Metrics { const fn new() -> Self { Self { post_upgrade_instructions_consumed: 0, + failed_credit_attempts: BTreeMap::new(), } } } +/// 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, + Unreadable, + Mismatch, +} + +impl FailedCreditReason { + pub const ALL: [Self; 4] = [ + Self::NotFound, + Self::RpcError, + Self::Unreadable, + Self::Mismatch, + ]; + + pub fn label(self) -> &'static str { + match self { + Self::NotFound => "not_found", + Self::RpcError => "rpc_error", + 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)) +} + /// Appends the event to the event log. pub fn record_event(payload: EventType, runtime: &R) { EVENTS From cda022110096c15e6ca06f4b3bad0756b088c97d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gr=C3=A9gory=20Demay?= Date: Tue, 6 Oct 2026 07:50:25 +0000 Subject: [PATCH 2/7] feat(minter): report the age of the oldest pending mint and failed mint attempts An oldest_pending_mint_age_seconds gauge computed from the created_at_time the ledger deduplicates each mint by, so an alert can fire hours before the deduplication window quarantines the deposit, and a failed_mint_attempts counter by reason, mirroring failed_credit_attempts. Co-Authored-By: Claude Fable 5 --- integration_tests/tests/tests.rs | 7 +++ minter/src/deposit/sweep/mint/mod.rs | 6 ++ minter/src/deposit/sweep/mint/tests.rs | 80 +++++++++++++++++++------- minter/src/metrics.rs | 17 +++++- minter/src/state/deposits/mod.rs | 9 +++ minter/src/state/deposits/tests.rs | 27 +++++++++ minter/src/storage/mod.rs | 37 ++++++++++++ 7 files changed, 162 insertions(+), 21 deletions(-) diff --git a/integration_tests/tests/tests.rs b/integration_tests/tests/tests.rs index 5f7a1904..949d1fa8 100644 --- a/integration_tests/tests/tests.rs +++ b/integration_tests/tests/tests.rs @@ -1610,6 +1610,7 @@ mod metrics_tests { .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+"#, ) @@ -1620,6 +1621,12 @@ mod metrics_tests { 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="call_error"\} 0 \d+"#) .into() .drop() .await; diff --git a/minter/src/deposit/sweep/mint/mod.rs b/minter/src/deposit/sweep/mint/mod.rs index 8d03698e..6576029c 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,6 +85,7 @@ 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; } @@ -118,6 +120,7 @@ async fn process_pending_mint( ScopeGuard::into_inner(quarantine_unless_defused); } Ok(Err(TransferError::TooOld)) => { + record_failed_mint_attempt(FailedMintReason::Expired); log!( Priority::Error, "Quarantining deposit {deposit_id}: the ledger rejected its mint as outside the deduplication window" @@ -128,6 +131,7 @@ async fn process_pending_mint( | TransferError::BadBurn { .. } | TransferError::InsufficientFunds { .. }), )) => { + record_failed_mint_attempt(FailedMintReason::Rejected); log!( Priority::Error, "Quarantining deposit {deposit_id}: the ledger definitively rejected its mint from the minting account: {rejection:?}" @@ -139,6 +143,7 @@ async fn process_pending_mint( | TransferError::CreatedInFuture { .. }), )) => { 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:?}" @@ -146,6 +151,7 @@ async fn process_pending_mint( } 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 5c6533da..2c78bbc5 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, EventsAssert, MINIMUM_DEPOSIT_AMOUNT, PROCESS_DEPOSIT_REQUIRED_CYCLES, account, @@ -109,27 +109,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::LedgerError, + ), + ( + "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(); @@ -137,6 +152,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 { @@ -176,6 +197,7 @@ async fn should_quarantine_pending_mint() { runtime: TestCanisterRuntime, expected_ledger_calls: usize, traps: bool, + expected_reason: Option, } let stale_now = CREDITED_AT_TIME + LEDGER_DEDUPLICATION_WINDOW.as_nanos() as u64 + 1; let cases = [ @@ -184,12 +206,14 @@ async fn should_quarantine_pending_mint() { runtime: TestCanisterRuntime::new().add_times([stale_now; 3]), expected_ledger_calls: 0, traps: false, + expected_reason: Some(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: Some(FailedMintReason::Expired), }, QuarantineCase { name: "the ledger rejects the fee of the mint", @@ -198,6 +222,7 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, + expected_reason: Some(FailedMintReason::Rejected), }, QuarantineCase { name: "the ledger takes the mint for a burn below the minimum", @@ -206,6 +231,7 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, + expected_reason: Some(FailedMintReason::Rejected), }, QuarantineCase { name: "the ledger reports insufficient funds on the minting account", @@ -214,20 +240,24 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, + expected_reason: Some(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: None, }, ]; + let mut expected_attempts = std::collections::BTreeMap::new(); for QuarantineCase { name, runtime, expected_ledger_calls, traps, + expected_reason, } in cases { setup(); @@ -253,6 +283,16 @@ async fn should_quarantine_pending_mint() { EventsAssert::from_recorded().expect_contains_event_eq(EventType::QuarantinedPendingMint { deposit_id: pending.deposit_id, }); + if let Some(reason) = expected_reason { + *expected_attempts.entry(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 8131f151..6f707c85 100644 --- a/minter/src/metrics.rs +++ b/minter/src/metrics.rs @@ -1,5 +1,5 @@ use crate::state::{QuarantineCause, State}; -use crate::storage::{self, FailedCreditReason}; +use crate::storage::{self, FailedCreditReason, FailedMintReason}; use ic_metrics_encoder::MetricsEncoder; const WASM_PAGE_SIZE_IN_BYTES: usize = 65536; @@ -126,6 +126,11 @@ pub fn encode_metrics(w: &mut MetricsEncoder>, s: &State) -> std::io::Re age_seconds(s.deposits().oldest_in_flight_queued_at()).metric_value(), "Age of the oldest in-flight deposit in seconds, from queued until minted. 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, counting up to the deduplication window. 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.", @@ -136,6 +141,16 @@ pub fn encode_metrics(w: &mut MetricsEncoder>, s: &State) -> std::io::Re 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(), diff --git a/minter/src/state/deposits/mod.rs b/minter/src/state/deposits/mod.rs index 5d3f729c..7e30a49d 100644 --- a/minter/src/state/deposits/mod.rs +++ b/minter/src/state/deposits/mod.rs @@ -110,6 +110,15 @@ impl Deposits { 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 { diff --git a/minter/src/state/deposits/tests.rs b/minter/src/state/deposits/tests.rs index be469b3c..f204eab2 100644 --- a/minter/src/state/deposits/tests.rs +++ b/minter/src/state/deposits/tests.rs @@ -711,6 +711,33 @@ mod oldest_in_flight { } } +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| { diff --git a/minter/src/storage/mod.rs b/minter/src/storage/mod.rs index f675d259..667f3519 100644 --- a/minter/src/storage/mod.rs +++ b/minter/src/storage/mod.rs @@ -37,6 +37,7 @@ thread_local! { pub(crate) struct Metrics { pub post_upgrade_instructions_consumed: u64, pub failed_credit_attempts: BTreeMap, + pub failed_mint_attempts: BTreeMap, } impl Metrics { @@ -44,6 +45,7 @@ impl Metrics { Self { post_upgrade_instructions_consumed: 0, failed_credit_attempts: BTreeMap::new(), + failed_mint_attempts: BTreeMap::new(), } } } @@ -83,6 +85,41 @@ 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, + CallError, +} + +impl FailedMintReason { + pub const ALL: [Self; 4] = [ + Self::Expired, + Self::Rejected, + Self::LedgerError, + Self::CallError, + ]; + + pub fn label(self) -> &'static str { + match self { + Self::Expired => "expired", + Self::Rejected => "rejected", + Self::LedgerError => "ledger_error", + Self::CallError => "call_error", + } + } +} + +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 From bea97b9f27d225f538aa5715e62b7905c159fdeb Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gr=C3=A9gory=20Demay?= Date: Thu, 8 Oct 2026 09:29:12 +0000 Subject: [PATCH 3/7] feat(minter): count invalid getTransaction responses separately from RPC errors Co-Authored-By: Claude Opus 5.5 --- integration_tests/tests/tests.rs | 3 +++ minter/src/deposit/sweep/finalize/mod.rs | 15 +++++++++------ minter/src/deposit/sweep/finalize/tests.rs | 18 ++++++++++++++++-- minter/src/storage/mod.rs | 5 ++++- 4 files changed, 32 insertions(+), 9 deletions(-) diff --git a/integration_tests/tests/tests.rs b/integration_tests/tests/tests.rs index 72608c52..550502eb 100644 --- a/integration_tests/tests/tests.rs +++ b/integration_tests/tests/tests.rs @@ -1312,6 +1312,9 @@ mod metrics_tests { .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+"#, ) diff --git a/minter/src/deposit/sweep/finalize/mod.rs b/minter/src/deposit/sweep/finalize/mod.rs index 52b3dbe6..28d76ed9 100644 --- a/minter/src/deposit/sweep/finalize/mod.rs +++ b/minter/src/deposit/sweep/finalize/mod.rs @@ -60,14 +60,17 @@ pub async fn credit_finalized_sweeps(runtime: &R) -> bool { 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); diff --git a/minter/src/deposit/sweep/finalize/tests.rs b/minter/src/deposit/sweep/finalize/tests.rs index 7b39c382..ac90ae3d 100644 --- a/minter/src/deposit/sweep/finalize/tests.rs +++ b/minter/src/deposit/sweep/finalize/tests.rs @@ -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; @@ -116,7 +118,7 @@ async fn should_credit_the_amount_received_by_the_main_account() { #[tokio::test] async fn should_keep_deposits_finalized_until_the_outcome_can_be_read() { type Response = fn() -> GetTransactionResult; - let cases: [(&str, Response, FailedCreditReason); 3] = [ + let cases: [(&str, Response, FailedCreditReason); 4] = [ ( "the transaction is not returned", || GetTransactionResult::Consistent(Ok(None)), @@ -127,6 +129,18 @@ async fn should_keep_deposits_finalized_until_the_outcome_can_be_read() { || 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", || { diff --git a/minter/src/storage/mod.rs b/minter/src/storage/mod.rs index c8728012..059eee9e 100644 --- a/minter/src/storage/mod.rs +++ b/minter/src/storage/mod.rs @@ -57,14 +57,16 @@ impl Metrics { pub enum FailedCreditReason { NotFound, RpcError, + InvalidResponse, Unreadable, Mismatch, } impl FailedCreditReason { - pub const ALL: [Self; 4] = [ + pub const ALL: [Self; 5] = [ Self::NotFound, Self::RpcError, + Self::InvalidResponse, Self::Unreadable, Self::Mismatch, ]; @@ -73,6 +75,7 @@ impl FailedCreditReason { match self { Self::NotFound => "not_found", Self::RpcError => "rpc_error", + Self::InvalidResponse => "invalid_response", Self::Unreadable => "unreadable", Self::Mismatch => "mismatch", } From a0ab710434763ce34a5dec7589cf1b62d9755fce Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gr=C3=A9gory=20Demay?= Date: Thu, 8 Oct 2026 09:29:22 +0000 Subject: [PATCH 4/7] feat(minter): log unexpected failures to credit a finalized sweep as errors Co-Authored-By: Claude Opus 5.5 --- minter/src/deposit/sweep/finalize/mod.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/minter/src/deposit/sweep/finalize/mod.rs b/minter/src/deposit/sweep/finalize/mod.rs index 28d76ed9..b0de1937 100644 --- a/minter/src/deposit/sweep/finalize/mod.rs +++ b/minter/src/deposit/sweep/finalize/mod.rs @@ -54,7 +54,7 @@ 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); @@ -85,7 +85,7 @@ 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); From cc03d5ea6e4ba6012fb7d83c39ba965749f81e55 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gr=C3=A9gory=20Demay?= Date: Thu, 8 Oct 2026 09:30:01 +0000 Subject: [PATCH 5/7] feat(minter): count mints quarantined after an unknown ledger outcome The quarantine guard now only fires when the outcome of the ledger call is unknown, so it can record its own reason without double counting the deliberate quarantines of rejected and expired mints. Co-Authored-By: Claude Opus 5.5 --- integration_tests/tests/tests.rs | 3 +++ minter/src/deposit/sweep/mint/mod.rs | 5 +++++ minter/src/deposit/sweep/mint/tests.rs | 18 ++++++++---------- minter/src/storage/mod.rs | 5 ++++- 4 files changed, 20 insertions(+), 11 deletions(-) diff --git a/integration_tests/tests/tests.rs b/integration_tests/tests/tests.rs index 550502eb..755de0fe 100644 --- a/integration_tests/tests/tests.rs +++ b/integration_tests/tests/tests.rs @@ -1325,6 +1325,9 @@ mod metrics_tests { r#"failed_mint_attempts\{reason="ledger_error"\} 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/mint/mod.rs b/minter/src/deposit/sweep/mint/mod.rs index 6576029c..d9bd3c24 100644 --- a/minter/src/deposit/sweep/mint/mod.rs +++ b/minter/src/deposit/sweep/mint/mod.rs @@ -91,6 +91,7 @@ async fn process_pending_mint( } let quarantine_unless_defused = scopeguard::guard(deposit_id, |deposit_id| { + record_failed_mint_attempt(FailedMintReason::UnknownOutcome); record_quarantined_pending_mint(runtime, deposit_id); }); @@ -120,22 +121,26 @@ 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 diff --git a/minter/src/deposit/sweep/mint/tests.rs b/minter/src/deposit/sweep/mint/tests.rs index 683a0cc3..b2ba5653 100644 --- a/minter/src/deposit/sweep/mint/tests.rs +++ b/minter/src/deposit/sweep/mint/tests.rs @@ -196,7 +196,7 @@ async fn should_quarantine_pending_mint() { runtime: TestCanisterRuntime, expected_ledger_calls: usize, traps: bool, - expected_reason: Option, + expected_reason: FailedMintReason, } let stale_now = CREDITED_AT_TIME + LEDGER_DEDUPLICATION_WINDOW.as_nanos() as u64 + 1; let cases = [ @@ -205,14 +205,14 @@ async fn should_quarantine_pending_mint() { runtime: TestCanisterRuntime::new().add_times([stale_now; 3]), expected_ledger_calls: 0, traps: false, - expected_reason: Some(FailedMintReason::Expired), + 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: Some(FailedMintReason::Expired), + expected_reason: FailedMintReason::Expired, }, QuarantineCase { name: "the ledger rejects the fee of the mint", @@ -221,7 +221,7 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, - expected_reason: Some(FailedMintReason::Rejected), + expected_reason: FailedMintReason::Rejected, }, QuarantineCase { name: "the ledger takes the mint for a burn below the minimum", @@ -230,7 +230,7 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, - expected_reason: Some(FailedMintReason::Rejected), + expected_reason: FailedMintReason::Rejected, }, QuarantineCase { name: "the ledger reports insufficient funds on the minting account", @@ -239,14 +239,14 @@ async fn should_quarantine_pending_mint() { })]), expected_ledger_calls: 1, traps: false, - expected_reason: Some(FailedMintReason::Rejected), + 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: None, + expected_reason: FailedMintReason::UnknownOutcome, }, ]; @@ -282,9 +282,7 @@ async fn should_quarantine_pending_mint() { EventsAssert::from_recorded().expect_contains_event_eq(EventType::QuarantinedPendingMint { deposit_id: pending.deposit_id, }); - if let Some(reason) = expected_reason { - *expected_attempts.entry(reason).or_insert(0_u64) += 1; - } + *expected_attempts.entry(expected_reason).or_insert(0_u64) += 1; for reason in FailedMintReason::ALL { assert_eq!( failed_mint_attempt_count(reason), diff --git a/minter/src/storage/mod.rs b/minter/src/storage/mod.rs index 059eee9e..73fb4aae 100644 --- a/minter/src/storage/mod.rs +++ b/minter/src/storage/mod.rs @@ -97,14 +97,16 @@ pub enum FailedMintReason { Rejected, LedgerError, CallError, + UnknownOutcome, } impl FailedMintReason { - pub const ALL: [Self; 4] = [ + pub const ALL: [Self; 5] = [ Self::Expired, Self::Rejected, Self::LedgerError, Self::CallError, + Self::UnknownOutcome, ]; pub fn label(self) -> &'static str { @@ -113,6 +115,7 @@ impl FailedMintReason { Self::Rejected => "rejected", Self::LedgerError => "ledger_error", Self::CallError => "call_error", + Self::UnknownOutcome => "unknown_outcome", } } } From c32460bc175dd58bfca6fe1357032fa7be510771 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gr=C3=A9gory=20Demay?= Date: Thu, 8 Oct 2026 09:30:27 +0000 Subject: [PATCH 6/7] feat(minter): count mints refused as created in the future separately Co-Authored-By: Claude Opus 5.5 --- integration_tests/tests/tests.rs | 3 +++ minter/src/deposit/sweep/mint/mod.rs | 13 ++++++++++--- minter/src/deposit/sweep/mint/tests.rs | 2 +- minter/src/storage/mod.rs | 5 ++++- 4 files changed, 18 insertions(+), 5 deletions(-) diff --git a/integration_tests/tests/tests.rs b/integration_tests/tests/tests.rs index 755de0fe..e8407fe6 100644 --- a/integration_tests/tests/tests.rs +++ b/integration_tests/tests/tests.rs @@ -1324,6 +1324,9 @@ mod metrics_tests { .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+"#, diff --git a/minter/src/deposit/sweep/mint/mod.rs b/minter/src/deposit/sweep/mint/mod.rs index d9bd3c24..4ed20d6a 100644 --- a/minter/src/deposit/sweep/mint/mod.rs +++ b/minter/src/deposit/sweep/mint/mod.rs @@ -143,9 +143,8 @@ async fn process_pending_mint( 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); @@ -154,6 +153,14 @@ async fn process_pending_mint( "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); diff --git a/minter/src/deposit/sweep/mint/tests.rs b/minter/src/deposit/sweep/mint/tests.rs index b2ba5653..6752fc08 100644 --- a/minter/src/deposit/sweep/mint/tests.rs +++ b/minter/src/deposit/sweep/mint/tests.rs @@ -133,7 +133,7 @@ async fn should_retry_after_transient_failure_with_exactly_the_same_arguments() ledger_time: 0, })) }, - FailedMintReason::LedgerError, + FailedMintReason::CreatedInFuture, ), ( "the call to the ledger fails", diff --git a/minter/src/storage/mod.rs b/minter/src/storage/mod.rs index 73fb4aae..084feee3 100644 --- a/minter/src/storage/mod.rs +++ b/minter/src/storage/mod.rs @@ -96,15 +96,17 @@ pub enum FailedMintReason { Expired, Rejected, LedgerError, + CreatedInFuture, CallError, UnknownOutcome, } impl FailedMintReason { - pub const ALL: [Self; 5] = [ + pub const ALL: [Self; 6] = [ Self::Expired, Self::Rejected, Self::LedgerError, + Self::CreatedInFuture, Self::CallError, Self::UnknownOutcome, ]; @@ -114,6 +116,7 @@ impl FailedMintReason { Self::Expired => "expired", Self::Rejected => "rejected", Self::LedgerError => "ledger_error", + Self::CreatedInFuture => "created_in_future", Self::CallError => "call_error", Self::UnknownOutcome => "unknown_outcome", } From f479ce92b80b910c489457699e37579f708dc2b9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Gr=C3=A9gory=20Demay?= Date: Thu, 8 Oct 2026 13:13:32 +0000 Subject: [PATCH 7/7] docs(minter): describe when the deposit age gauges stop counting Co-Authored-By: Claude Opus 5.5 --- minter/src/metrics.rs | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/minter/src/metrics.rs b/minter/src/metrics.rs index a3e1c827..93238d0c 100644 --- a/minter/src/metrics.rs +++ b/minter/src/metrics.rs @@ -105,12 +105,12 @@ pub fn encode_metrics(w: &mut MetricsEncoder>, s: &State) -> std::io::Re 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. Returns 0 if there are no in-flight deposits.", + "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, counting up to the deduplication window. Returns 0 if there are no pending mints.", + "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",