diff --git a/CHANGELOG.md b/CHANGELOG.md index d91325377..fdef7c27c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,7 @@ air-gapped signing * fix: `icp cycles buy` says, with neither `--amount` nor `--cycles`, that one of the two is needed; and that a negative `--amount` or `--cycles` (`-1`, `-5t`) is negative, in the same words and with exit status 2 for both, where clap read `-5t` as an unknown flag * fix: `icp cycles buy` says in words what is wrong with a `--gateway` that is not a canister id, a canister that serves no gateway, and one a boundary node cannot route to, where it printed the replica's IC0536 or the HTTP gateway's routing error; CyclePay and Stripe are named only for CyclePay's gateway, any other is "the gateway" * fix: `icp cycles buy` draws the payment QR code black on white on any terminal theme. It used to take the terminal's own colours, which a light theme inverts and a dark theme often renders grey on near-black, and many phone cameras read neither. A terminal without colour support gets the plain drawing as before. +* fix: `icp cycles buy` gives up after five minutes without word of the order, saying where the order stands, where it kept waiting while the gateway was out of reach: a poll now counts as unanswered after 10 seconds, where it had the HTTP client's six minutes, and the give-up and the hour limit are counted on the clock after every poll, so they hold on a network that stalls as on one that refuses # v1.7.0 diff --git a/crates/icp-cli/src/commands/cycles/buy.rs b/crates/icp-cli/src/commands/cycles/buy.rs index 70c864f89..1aadbf933 100644 --- a/crates/icp-cli/src/commands/cycles/buy.rs +++ b/crates/icp-cli/src/commands/cycles/buy.rs @@ -588,6 +588,23 @@ async fn wait_and_report( } return Err(CyclesPurchaseError::WaitTimedOut { order }.into()); } + // The gateway stopped answering for five minutes: the order is said + // as last seen, which is all that is known of it. + Err(CyclesPurchaseError::ContactLost { + gateway, + order, + source, + }) => { + if output != Output::Quiet { + info!("{} {AFTER_HINT}", standing(&order, false)); + } + return Err(CyclesPurchaseError::ContactLost { + gateway, + order, + source, + } + .into()); + } Err(error) => return Err(error.into()), }; diff --git a/crates/icp-cli/src/cyclepay/purchase.rs b/crates/icp-cli/src/cyclepay/purchase.rs index 418329271..729cbaeb3 100644 --- a/crates/icp-cli/src/cyclepay/purchase.rs +++ b/crates/icp-cli/src/cyclepay/purchase.rs @@ -9,12 +9,12 @@ //! //! Nothing here prints. [`wait_for_order`] tells its caller each //! [`PurchasePhase`] the order enters, and hands the last order it saw back -//! inside its error when it is interrupted, so the caller can say where it -//! stands. +//! inside its error when it ends unsettled, so the caller can say where the +//! order stands. use std::future::Future; use std::pin::pin; -use std::time::{Duration, Instant}; +use std::time::Duration; use candid::Principal; use ic_agent::AgentError; @@ -25,7 +25,10 @@ use icp_project::prelude::IC_ROOT_KEY; use num_traits::ToPrimitive; use snafu::{OptionExt, Snafu}; use std::fmt; -use tokio::{select, time::sleep}; +use tokio::{ + select, + time::{Instant, sleep, timeout}, +}; use url::Url; use super::interface::{ @@ -200,6 +203,16 @@ pub enum CyclesPurchaseError { caller: Principal, }, + #[snafu(display( + "cycles gateway {gateway} did not answer a poll of order {id} within {}s", + after.as_secs() + ))] + PollTimedOut { + gateway: Principal, + id: String, + after: Duration, + }, + #[snafu(display("interrupted while waiting for order {}", order.id))] Interrupted { order: Box }, @@ -207,6 +220,18 @@ pub enum CyclesPurchaseError { "gave up waiting for order {} (last status: {})", order.id, order.status_text() ))] WaitTimedOut { order: Box }, + + /// Polls kept failing until the wait gave up. `order` is the order as + /// last seen, and `source` the last poll's failure. + #[snafu(display( + "lost contact with cycles gateway {gateway} while waiting for order {}", + order.id + ))] + ContactLost { + gateway: Principal, + order: Box, + source: Box, + }, } /// What the buyer asked for: a sum to spend, or cycles to receive. @@ -576,16 +601,21 @@ async fn fetch_order( Ok(view.map(OrderView::read)) } -/// Bounds on [`wait_for_order`]. +/// Bounds on [`wait_for_order`]. The two that judge silence count time, not +/// polls, so that they hold whether a network refuses a poll at once or +/// stalls it until [`WaitOptions::poll_timeout`]. #[derive(Clone, Debug)] pub struct WaitOptions { /// Time between polls. pub poll_interval: Duration, - /// Consecutive polls that said nothing of the order (unanswered, - /// refused, or finding none) before the wait gives up: five minutes of - /// them at [`POLL_INTERVAL`], longer than CyclePay's backend is stopped - /// for during an upgrade. - pub max_consecutive_misses: u32, + /// How long one poll may go unanswered before it counts as failed. A + /// connection that stalls rather than drops would otherwise hold the + /// wait for as long as the HTTP client allows a call, six minutes. + pub poll_timeout: Duration, + /// How long since a poll last found the order before the wait gives up + /// on it: polls unanswered, refused, or answered with no order. Longer + /// than CyclePay's backend is stopped for during an upgrade. + pub give_up_after: Duration, /// How long the order is waited on in one run. Its deadline is a day /// away; a buyer who has not paid by now is told where it stands. pub timeout: Duration, @@ -595,7 +625,8 @@ impl Default for WaitOptions { fn default() -> Self { Self { poll_interval: POLL_INTERVAL, - max_consecutive_misses: 100, + poll_timeout: Duration::from_secs(10), + give_up_after: Duration::from_secs(5 * 60), timeout: Duration::from_secs(60 * 60), } } @@ -651,13 +682,16 @@ impl Phases { /// `interrupt` is raced against every poll as well as the sleep between /// them, so an interrupt lands even while a call is stalled. /// -/// A poll that says nothing of the order is tried again, up to -/// [`WaitOptions::max_consecutive_misses`] in a row: one the network never -/// answered, one the backend refused (as it does for a few minutes during -/// an upgrade), or one answered `null` (a replica that has not caught up -/// with a new order, or an unpaid order forgotten once it expired). A -/// terminal status is a success here whatever it is — a refund is an answer -/// — and the caller decides what each one means. +/// A poll that says nothing of the order is tried again: one the network +/// never answered, one the backend refused (as it does for a few minutes +/// during an upgrade), or one answered `null` (a replica that has not caught +/// up with a new order, or an unpaid order forgotten once it expired). A poll +/// gets [`WaitOptions::poll_timeout`] to answer. Once the polls have said +/// nothing of the order for [`WaitOptions::give_up_after`], the wait gives +/// up: with [`CyclesPurchaseError::ContactLost`], carrying the order as last +/// seen, if the last poll failed, and [`CyclesPurchaseError::OrderNotFound`] +/// if it was answered. A terminal status is a success here whatever it is +/// (a refund is an answer), and the caller decides what each one means. pub async fn wait_for_order( calls: &dyn CanisterCalls, gateway: &Gateway, @@ -683,11 +717,16 @@ pub async fn wait_for_order( .map_or(Some(CardOrderStatus::AwaitingPayment), |o| o.status), ); let mut last = initial; - let mut misses = 0u32; let started = Instant::now(); - - let interrupted = |last: Option| { - let order = last.unwrap_or_else(|| OrderView { + // When a poll last found the order. + let mut found = started; + // What the last poll said, when it said nothing of the order: a + // failure, or `None` for an answer with no order in it. Judged only + // against `found`, so one that found it leaves this stale. + let mut missed: Option> = None; + + let known = |last: Option| { + last.unwrap_or_else(|| OrderView { id: id.to_owned(), status: Some(CardOrderStatus::AwaitingPayment), amount: Money::from_minor_units(0, Currency::Usd), @@ -699,48 +738,72 @@ pub async fn wait_for_order( refunded: None, detail: None, destination: None, - }); + }) + }; + let interrupted = |last: Option| { InterruptedSnafu { - order: Box::new(order), + order: Box::new(known(last)), } .fail() }; + // Given up on: out of contact if the last poll failed; not found if the + // gateway answered that it has no such order. + let gave_up = |last: Option, missed: Option| match missed { + Some(source) => Err(CyclesPurchaseError::ContactLost { + gateway: gateway.canister, + order: Box::new(known(last)), + source: Box::new(source), + }), + None => OrderNotFoundSnafu { + gateway: gateway.canister, + id, + caller: calls.caller(), + } + .fail(), + }; loop { + let poll = timeout(options.poll_timeout, fetch_order(calls, gateway, id)); let polled = select! { - polled = fetch_order(calls, gateway, id) => polled, + biased; _ = &mut interrupt => return interrupted(last), + polled = poll => polled.unwrap_or_else(|_| { + PollTimedOutSnafu { + gateway: gateway.canister, + id, + after: options.poll_timeout, + } + .fail() + }), }; match polled { Ok(Some(order)) => { - misses = 0; + found = Instant::now(); if order.is_settled() { return Ok(order); } phases.enter(order.status); - if started.elapsed() > options.timeout { - return WaitTimedOutSnafu { - order: Box::new(order), - } - .fail(); - } last = Some(order); } - Ok(None) | Err(_) if misses < options.max_consecutive_misses => misses += 1, - Ok(None) => { - return OrderNotFoundSnafu { - gateway: gateway.canister, - id, - caller: calls.caller(), - } - .fail(); + Ok(None) => missed = Some(None), + Err(error) => missed = Some(Some(error)), + } + // Both limits are judged after every poll, answered or not, so that + // each holds while the gateway is out of reach. + if let Some(missed) = missed.take_if(|_| found.elapsed() > options.give_up_after) { + return gave_up(last, missed); + } + if started.elapsed() > options.timeout { + return WaitTimedOutSnafu { + order: Box::new(known(last)), } - Err(error) => return Err(error), + .fail(); } select! { - _ = sleep(options.poll_interval) => {} + biased; _ = &mut interrupt => return interrupted(last), + _ = sleep(options.poll_interval) => {} } } } diff --git a/crates/icp-cli/src/cyclepay/tests.rs b/crates/icp-cli/src/cyclepay/tests.rs index 1cfc8371c..c086a36a5 100644 --- a/crates/icp-cli/src/cyclepay/tests.rs +++ b/crates/icp-cli/src/cyclepay/tests.rs @@ -119,6 +119,10 @@ fn rejected(message: &str) -> CallError { } } +/// What an `order_status` poll gets: the order, if any, or the network +/// failing to answer, or rejecting. +type Poll = Result, CallError>; + /// A CyclePay backend whose replies are scripted per method. #[derive(Default)] struct FakeBackend { @@ -130,7 +134,7 @@ struct FakeBackend { create: Mutex>, /// One reply per `order_status` poll, in order. An `Err` is the network /// failing to answer, or rejecting. - status: Mutex, CallError>>>, + status: Mutex>, /// Every call made, as (method, candid argument). calls_seen: Mutex)>>, /// Rejects every call as if the canister did not exist. @@ -139,6 +143,8 @@ struct FakeBackend { refusal: Mutex>, /// Never answers `order_status`, as a backend behind a stalled connection. stall_polls: bool, + /// What every `order_status` poll past the scripted ones answers. + then_polls: Option Poll>, } impl FakeBackend { @@ -149,7 +155,7 @@ impl FakeBackend { } } - fn polls(self, replies: Vec, CallError>>) -> Self { + fn polls(self, replies: Vec) -> Self { *self.status.lock().unwrap() = replies.into(); self } @@ -240,11 +246,9 @@ impl CanisterCalls for FakeBackend { if self.stall_polls { pending::<()>().await; } - let reply = self - .status - .lock() - .unwrap() - .pop_front() + let scripted = self.status.lock().unwrap().pop_front(); + let reply = scripted + .or_else(|| self.then_polls.map(|then| then())) .expect("ran out of scripted order_status replies")?; Ok(Encode!(&reply).unwrap()) } @@ -756,6 +760,22 @@ async fn wait( initial: Option, options: &WaitOptions, ) -> (Result, Vec) { + let (result, phases, _) = wait_timed(fake, initial, options).await; + (result, phases) +} + +/// Run the wait and collect the phases it told of, and how long it took: on +/// a paused clock, as the wait counted it. +async fn wait_timed( + fake: &FakeBackend, + initial: Option, + options: &WaitOptions, +) -> ( + Result, + Vec, + Duration, +) { + let started = tokio::time::Instant::now(); let mut phases = Vec::new(); let result = wait_for_order( fake, @@ -767,7 +787,7 @@ async fn wait( |phase| phases.push(phase), ) .await; - (result, phases) + (result, phases, started.elapsed()) } /// An order as the wait last saw it. @@ -858,48 +878,99 @@ async fn wait_retries_a_poll_that_said_nothing() { Err(unanswered()), Ok(Some(view("co-1", CardOrderStatus::Delivered))), ]); - let options = WaitOptions { - max_consecutive_misses: 3, - ..fast() - }; - let (result, _) = wait(&fake, None, &options).await; + let (result, _) = wait(&fake, None, &fast()).await; assert_eq!(result.unwrap().status, Some(CardOrderStatus::Delivered)); assert_eq!(fake.count_of(ORDER_STATUS_METHOD), 8); } -#[tokio::test] -async fn wait_gives_up_after_consecutive_failed_polls() { +/// On a network that stalls every poll, each poll is given up on at 10 +/// seconds, and the wait 5 minutes after the order was last heard of: by +/// the clock, not by a count of polls, which a stall makes slow. The order +/// is handed back as last seen, over the last poll's failure. +#[tokio::test(start_paused = true)] +async fn a_stalled_network_is_given_up_on_after_5_minutes() { + let fake = FakeBackend { + stall_polls: true, + ..FakeBackend::default() + }; + let (result, phases, took) = wait_timed(&fake, None, &WaitOptions::default()).await; + // A poll every 13 seconds, 10 to time out and 3 to the next, judged as + // each one ends: the first to end past 5 minutes. + assert_eq!(took, Duration::from_secs(23 * 13 + 10)); + assert_eq!(fake.count_of(ORDER_STATUS_METHOD), 24); + match result.unwrap_err() { + CyclesPurchaseError::ContactLost { order, source, .. } => { + assert_eq!(order.id, "co-1"); + assert_eq!(order.status, Some(CardOrderStatus::AwaitingPayment)); + assert!( + matches!(*source, CyclesPurchaseError::PollTimedOut { .. }), + "{source}" + ); + } + other => panic!("unexpected {other:?}"), + } + assert_eq!(phases, vec![PurchasePhase::AwaitingPayment]); +} + +/// On a network that refuses every poll at once, the same 5 minutes, with +/// the last poll's failure. +#[tokio::test(start_paused = true)] +async fn a_refusing_network_is_given_up_on_after_5_minutes() { + let fake = FakeBackend { + then_polls: Some(|| Err(unanswered())), + ..FakeBackend::default() + }; + let (result, phases, took) = wait_timed(&fake, None, &WaitOptions::default()).await; + // A poll every 3 seconds: the first to end past 5 minutes. + assert_eq!(took, Duration::from_secs(101 * 3)); + assert_eq!(fake.count_of(ORDER_STATUS_METHOD), 102); + match result.unwrap_err() { + CyclesPurchaseError::ContactLost { source, .. } => assert!( + matches!(*source, CyclesPurchaseError::GetOrder { .. }), + "{source}" + ), + other => panic!("unexpected {other:?}"), + } + assert_eq!(phases, vec![PurchasePhase::AwaitingPayment]); +} + +/// A gateway that is back within 5 minutes was never given up on: the wait +/// goes on as if nothing had happened. +#[tokio::test(start_paused = true)] +async fn wait_carries_on_once_the_gateway_answers_again() { let fake = FakeBackend::default().polls(vec![ + Ok(Some(view("co-1", CardOrderStatus::AwaitingPayment))), Err(unanswered()), + Ok(None), Err(unanswered()), + Err(rejected("Canister is stopped")), Err(unanswered()), + Ok(Some(view("co-1", CardOrderStatus::Processing))), + Ok(Some(view("co-1", CardOrderStatus::Delivered))), ]); - let options = WaitOptions { - max_consecutive_misses: 2, - ..fast() - }; - let (result, phases) = wait(&fake, None, &options).await; - let err = result.unwrap_err(); - assert!(matches!(err, CyclesPurchaseError::GetOrder { .. }), "{err}"); - assert_eq!(fake.count_of(ORDER_STATUS_METHOD), 3); - assert_eq!(phases, vec![PurchasePhase::AwaitingPayment]); + let (result, phases) = wait(&fake, None, &WaitOptions::default()).await; + assert_eq!(result.unwrap().status, Some(CardOrderStatus::Delivered)); + assert_eq!( + phases, + vec![PurchasePhase::AwaitingPayment, PurchasePhase::Delivering] + ); } -/// An order gone for longer than a replica lags is not the caller's, or -/// was forgotten after expiring unpaid: either way, not found. -#[tokio::test] -async fn wait_calls_an_order_gone_for_long_not_found() { - let fake = FakeBackend::default().polls(vec![Ok(None), Ok(None), Ok(None)]); - let options = WaitOptions { - max_consecutive_misses: 2, - ..fast() +/// An order the gateway keeps answering it has no such order for, for 5 +/// minutes, is not the caller's, or was forgotten after expiring unpaid: +/// either way, not found. +#[tokio::test(start_paused = true)] +async fn wait_calls_an_order_gone_for_5_minutes_not_found() { + let fake = FakeBackend { + then_polls: Some(|| Ok(None)), + ..FakeBackend::default() }; - let (result, phases) = wait(&fake, None, &options).await; + let (result, phases, took) = wait_timed(&fake, None, &WaitOptions::default()).await; + assert_eq!(took, Duration::from_secs(101 * 3)); assert!(matches!( result.unwrap_err(), CyclesPurchaseError::OrderNotFound { .. } )); - assert_eq!(fake.count_of(ORDER_STATUS_METHOD), 3); assert_eq!(phases, vec![PurchasePhase::AwaitingPayment]); } @@ -975,6 +1046,27 @@ async fn wait_times_out() { assert_eq!(phases, vec![PurchasePhase::AwaitingPayment]); } +/// A gateway that answers all along, with an order nobody pays, is waited +/// on for the hour and no longer: the first poll past it ends the wait. +#[tokio::test(start_paused = true)] +async fn wait_gives_up_on_an_unpaid_order_after_an_hour() { + let fake = FakeBackend { + then_polls: Some(|| Ok(Some(view("co-1", CardOrderStatus::AwaitingPayment)))), + ..FakeBackend::default() + }; + let (result, phases, took) = wait_timed(&fake, None, &WaitOptions::default()).await; + let hour = Duration::from_secs(60 * 60); + assert!(took > hour, "{took:?}"); + assert!(took <= hour + POLL_INTERVAL, "{took:?}"); + match result.unwrap_err() { + CyclesPurchaseError::WaitTimedOut { order } => { + assert_eq!(order.status, Some(CardOrderStatus::AwaitingPayment)); + } + other => panic!("unexpected {other:?}"), + } + assert_eq!(phases, vec![PurchasePhase::AwaitingPayment]); +} + #[tokio::test] async fn wait_interrupted_returns_last_order() { // The interrupt is ready from the start, so whether it or the first poll diff --git a/docs/guides/tokens-and-cycles.md b/docs/guides/tokens-and-cycles.md index 0e76ad6c3..2b3a38b11 100644 --- a/docs/guides/tokens-and-cycles.md +++ b/docs/guides/tokens-and-cycles.md @@ -148,6 +148,8 @@ Useful flags: - `--yes` skips the confirmation, which is required when there is no terminal to ask. `--json` prints one object after the order is created (with the amount, net and fee) and one when it settles; `-q` prints only the link, then the final status. Both are for scripts and agents, which have nobody to ask, so both imply `--yes`. - `--gateway ` buys through another cycles gateway: any canister serving the [cycles gateway interface](https://github.com/dfinity/icp-cli/blob/main/crates/icp-cli/src/cyclepay/cycles_gateway.did), whose own payment page, range and fees then apply. The [`ICP_CYCLES_GATEWAY_CANISTER_ID`](../reference/environment-variables.md#icp_cycles_gateway_canister_id) environment variable does the same. CyclePay's gateway is on mainnet only, so without `--gateway` the command needs `-n ic`, or an environment on mainnet, and refuses any other network before placing an order; another gateway may be on any network. +The wait asks the gateway every 3 seconds for up to an hour. If the gateway stops answering (a dropped connection, or the gateway being upgraded), the command keeps trying and gives up after five minutes without word of the order, saying where the order stands as last seen. Giving up, like Ctrl-C, stops the wait, not the order. + Pressing Ctrl-C while waiting stops the wait, not the order: an unpaid order stays payable, and the command says so and exits with status 1. Ctrl-C at the confirmation prompt creates no order. If the cycles cannot be delivered, the gateway refunds the card and the command says so; if the order ends up needing review, your card was charged and the gateway checks the order by hand. Keep the order id: the gateway shows the outcome, as CyclePay's site does under "My purchases". The cycles arrive in your identity's default cycles-ledger account, where `icp deploy` and `icp canister top-up` spend from. Purchases made from the terminal appear under "My purchases" on www.cyclepay.org when the identity is the one you sign in there with: `icp identity link web cyclepay --app 4w3yu-fyaaa-aaaac-beeoa-cai.icp0.io` makes one.