deploy/upcloud/src/wait.rs
//! Bounded waiting, and saying what was being waited for when the budget runs
//! out.
//!
//! Every wait in this procedure has a timeout — a re-image that hangs is worse
//! than one that fails, because the box is in pieces while it hangs. And every
//! timeout message names **what** was waited for and **what was last seen**:
//! `timed out after 600 s waiting for storage … to be online; last seen:
//! "maintenance"` is a fault an operator can act on, `timeout` is not.
//!
//! [`Clock`] is a trait so the timeout tests run in microseconds against
//! [`FakeClock`] instead of really sleeping for ten minutes.
use std::cell::Cell;
use std::time::Instant;
/// Time, injectable. Milliseconds since an arbitrary origin — a monotonic
/// counter rather than `Instant`, because an `Instant` cannot be faked.
pub trait Clock {
fn now_ms(&self) -> u64;
fn sleep_ms(&self, ms: u64);
}
/// The real one.
pub struct SystemClock {
start: Instant,
}
impl Default for SystemClock {
fn default() -> Self {
SystemClock {
start: Instant::now(),
}
}
}
impl Clock for SystemClock {
fn now_ms(&self) -> u64 {
self.start.elapsed().as_millis() as u64
}
fn sleep_ms(&self, ms: u64) {
std::thread::sleep(std::time::Duration::from_millis(ms));
}
}
/// A clock that jumps instead of sleeping, so a fifteen-minute budget is
/// exhausted in a test that takes no time at all.
#[derive(Default)]
pub struct FakeClock {
now: Cell<u64>,
}
impl FakeClock {
pub fn new() -> FakeClock {
FakeClock::default()
}
pub fn elapsed_ms(&self) -> u64 {
self.now.get()
}
}
impl Clock for FakeClock {
fn now_ms(&self) -> u64 {
self.now.get()
}
fn sleep_ms(&self, ms: u64) {
self.now.set(self.now.get() + ms);
}
}
/// What one poll saw.
#[derive(Clone, Debug, PartialEq, Eq)]
pub enum Progress {
/// The condition holds. Stop.
Done,
/// It does not yet. The string is what was observed, and it is what the
/// timeout message will quote.
Waiting(String),
}
/// One bounded wait.
#[derive(Clone, Copy, Debug)]
pub struct Budget {
pub timeout_ms: u64,
pub poll_ms: u64,
/// How often to print a line while waiting. Fifteen minutes of silence is
/// indistinguishable from a hang, so this is not optional.
pub report_every_ms: u64,
}
impl Budget {
pub fn new(timeout_ms: u64, poll_ms: u64) -> Budget {
Budget {
timeout_ms,
poll_ms,
report_every_ms: 30_000,
}
}
}
/// Poll `probe` until it says [`Progress::Done`] or the budget runs out.
///
/// A probe **error** is not fatal by itself: the API answers `502` now and then,
/// and a re-image that abandoned a running install because of one bad reply
/// would be worse than useless. The error is reported, remembered, and quoted if
/// the budget expires with the condition still unmet — so a wait that ended in
/// twenty consecutive 502s says so rather than blaming the state machine.
pub fn wait_for<C, F>(
clock: &C,
what: &str,
budget: Budget,
log: &mut dyn FnMut(&str),
mut probe: F,
) -> Result<u64, String>
where
C: Clock,
F: FnMut() -> Result<Progress, String>,
{
let started = clock.now_ms();
// No initial value: every path that reaches the timeout check has assigned
// one, and an initialiser here would be a string the compiler can prove is
// never read (`installtest/src/lib.rs`'s `wait_for_ssh` is written the same
// way, for the same reason).
let mut last;
let mut last_report = started;
loop {
match probe() {
Ok(Progress::Done) => return Ok(clock.now_ms().saturating_sub(started)),
Ok(Progress::Waiting(seen)) => last = seen,
Err(e) => last = format!("the probe failed: {e}"),
}
let now = clock.now_ms();
let waited = now.saturating_sub(started);
if waited >= budget.timeout_ms {
return Err(format!(
"timed out after {} s waiting for {what}; last seen: {last}",
budget.timeout_ms / 1000
));
}
if now.saturating_sub(last_report) >= budget.report_every_ms {
last_report = now;
log(&format!(
" … {waited_s} s of {budget_s} s waiting for {what} — {last}",
waited_s = waited / 1000,
budget_s = budget.timeout_ms / 1000
));
}
clock.sleep_ms(budget.poll_ms);
}
}
#[cfg(test)]
mod tests {
use super::*;
fn silent() -> impl FnMut(&str) {
|_: &str| {}
}
#[test]
fn a_condition_that_becomes_true_ends_the_wait() {
let clock = FakeClock::new();
let mut n = 0;
let took = wait_for(
&clock,
"the storage to be online",
Budget::new(60_000, 1_000),
&mut silent(),
|| {
n += 1;
if n >= 3 {
Ok(Progress::Done)
} else {
Ok(Progress::Waiting("maintenance".into()))
}
},
)
.unwrap();
assert_eq!(n, 3);
assert_eq!(took, 2_000, "two sleeps of a second before the third probe");
}
/// Red-first, seen with `format!("timed out")` as the message: the test read
/// `assert!(err.contains("maintenance"))` → `assertion failed: err.contains(..)`,
/// which is exactly the operator's position at 03:00 — a timeout that says
/// nothing about what it was watching.
#[test]
fn a_timeout_names_the_thing_and_quotes_what_it_last_saw() {
let clock = FakeClock::new();
let err = wait_for(
&clock,
"the storage to be online",
Budget::new(10_000, 1_000),
&mut silent(),
|| Ok(Progress::Waiting("maintenance".into())),
)
.unwrap_err();
assert!(err.contains("timed out after 10 s"), "{err}");
assert!(err.contains("the storage to be online"), "{err}");
assert!(err.contains("maintenance"), "{err}");
assert!(clock.elapsed_ms() >= 10_000);
}
#[test]
fn a_probe_error_does_not_end_the_wait_but_is_quoted_at_the_end() {
let clock = FakeClock::new();
let err = wait_for(
&clock,
"the server to stop",
Budget::new(5_000, 1_000),
&mut silent(),
|| Err("GET /server/{uuid} answered 502 — bad gateway".into()),
)
.unwrap_err();
assert!(err.contains("502"), "{err}");
assert!(err.contains("the server to stop"), "{err}");
}
#[test]
fn progress_is_printed_so_a_long_wait_is_not_silence() {
let clock = FakeClock::new();
let mut lines: Vec<String> = Vec::new();
let mut log = |s: &str| lines.push(s.to_string());
let budget = Budget {
timeout_ms: 120_000,
poll_ms: 5_000,
report_every_ms: 30_000,
};
let _ = wait_for(&clock, "the install", budget, &mut log, || {
Ok(Progress::Waiting("no banner".into()))
});
assert!(lines.len() >= 3, "120 s at one line per 30 s: {lines:?}");
assert!(lines[0].contains("the install"), "{:?}", lines[0]);
}
}