crates/mock-upcloud/src/clock.rs
//! **Virtual time, and the measured durations it plays back.**
//!
//! Every duration in [`Timings`] was measured against the live UpCloud account
//! or against a KVM guest of the same image. At `speed = 1.0` the mock waits
//! exactly as long as the provider does, which is the mode to use when the thing
//! under test is a TIMEOUT. At `speed = 0.0` nothing waits and the clock jumps,
//! which is the mode the 100 000-run storm uses — the ORDER of the states and
//! their RELATIVE lengths are unchanged, so a client that skips its poll loop
//! still fails, it just fails in microseconds.
//!
//! The clock is virtual rather than "sleep less" because a shortened sleep still
//! sleeps: 100 000 server creates at one millisecond each is a hundred seconds
//! of doing nothing, per resource, and there are five per run. A monotonically
//! advanced counter costs nothing and is exactly as ordered.
use std::sync::atomic::{AtomicU64, Ordering};
use std::time::{Duration, Instant};
/// The measured durations. Milliseconds, because the guest install was measured
/// at 10 011 ms and rounding it to 10 s throws away the only digit that says it
/// was measured.
#[derive(Clone, Copy, Debug)]
pub struct Timings {
/// **98–105 s.** MEASURED across the estate re-lays; the mock draws
/// uniformly in the range from the run's seed, because a client that
/// happened to be tuned to 100 s exactly is a client that will break.
pub server_create_lo_ms: u64,
pub server_create_hi_ms: u64,
/// **≈60 s** for a front or a twin: a server with its own boot disk and
/// nothing else.
pub server_delete_ms: u64,
/// **The extra per attached member volume.** MEASURED: an appliance
/// carrying four member volumes stayed in `maintenance` for more than five
/// minutes. 60 s + 4 × 65 s = 320 s, which is the >5 min that was seen.
pub server_delete_per_volume_ms: u64,
/// A storage create: it is `maintenance` for this long before `online`.
pub storage_create_ms: u64,
/// A storage delete.
pub storage_delete_ms: u64,
/// A soft stop that the guest answers.
pub stop_soft_ms: u64,
/// A hard stop: the plug, so it is quick.
pub stop_hard_ms: u64,
/// **Start → `started` for a disk boot: ≈10 s.** MEASURED 2026-09-19
/// (private-gunnar-ops RESUME-2026-09-19, "`started` in 10 s"). It was
/// 20 000 here, unmeasured — behaviour 45.
pub start_ms: u64,
/// A plan change (the resize proper), server already stopped.
pub resize_ms: u64,
/// **10 011 ms**, MEASURED under KVM on this estate's own boxes:
/// `INSTALL-OK` from the installer's first instruction. Kept because it is
/// a real measurement of a real thing — but it is NOT what the appliance
/// does, see below.
pub guest_install_ms: u64,
/// **2 001 / 2 751 / 4 752 ms**, MEASURED on the appliance's UART across
/// three re-images. This is the guest's own clock, observed from inside.
pub guest_install_uart_lo_ms: u64,
pub guest_install_uart_hi_ms: u64,
/// **110 000–253 000 ms**, MEASURED by the ladder as `install-time`, wall,
/// from outside, across the same three re-images.
///
/// **Two observers, two orders of magnitude, one word.** The installer is
/// not slow — the PROVIDER is: create, media sync, firmware, boot order,
/// DHCP. A bar set at 60 s against the ladder's number reads RED forever
/// and tempts somebody to move the bar, when the number to move is the
/// provider's and the thing to report is which observer said what. See
/// [`Timings::reimage_observers`].
pub provider_wall_lo_ms: u64,
pub provider_wall_hi_ms: u64,
/// The Ubuntu template's first boot, during which `dpkg lock-frontend` is
/// held by `unattended-upgrade-shutdown --wait-for-signal` — for the LIFE
/// of the boot, so `apt-get update` blocks rather than failing (behaviour
/// 21). This is how long the mock's guest stays in that state; the real one
/// never leaves it.
pub template_first_boot_ms: u64,
// ── the direct-upload import, and the wait that follows it ──────────────
/// **The upload itself.** MEASURED: 43 485 184 bytes (41.47 MiB) `created
/// 09:36:16Z`, `completed 09:36:21Z` — five seconds, so about 120 ms per
/// MiB. `read_bytes == written_bytes == 43485184`, both checksums present,
/// the sha256 matching the local file exactly.
pub import_upload_ms_per_mib: u64,
/// **The wait NOBODY is doing any work during.** After every byte has
/// arrived and been checksummed, the storage sits in `syncing` for this
/// long. MEASURED 100–130 s: the poller read `syncing` at 65 s and at 97 s
/// while the import object already said `completed`.
///
/// And it is paid TWICE per appliance re-image, by design: the ladder
/// uploads the same 43 MB medium once as a CD-ROM and again as a virtio
/// DISK, because `korp-installer` probes virtio and nothing else. Two
/// `POST /storage`, two imports, two syncs — about four minutes of pure
/// waiting per re-image.
pub storage_sync_lo_ms: u64,
pub storage_sync_hi_ms: u64,
/// **A clone, MEASURED 2026-09-20** (gunnar `deploy/upcloud/tests/clone_probe.rs`):
/// the call 728 ms, then `maintenance` → `online` in **47 s, with NO
/// `syncing` at all**. This crate said "NOT MEASURED" and made a clone sync
/// like an import for years of storm; the measurement existed in the next
/// repository over (ledger X3, behaviour 53).
pub clone_online_ms: u64,
/// **The old pessimistic guess, kept by name only**
/// ([`crate::Fault::CloneSyncsLikeImport`]): the clone waits in `syncing`
/// for this long, like an import. Contradicted by the measurement above.
pub clone_sync_lo_ms: u64,
pub clone_sync_hi_ms: u64,
/// What a clone costs before the sync even starts (the volume is
/// `maintenance` while the copy is set up). Used only under the guess.
pub clone_prepare_ms: u64,
// ── added by lane T13 (BEHAVIOURS-LEDGER.md) ─────────────────────────────
/// **A start whose guest powers itself off inside the start operation.**
/// MEASURED 2026-09-19: `POST /start` → `maintenance` t+10…t+130 s →
/// `stopped` at t+140 s, and 2026-09-15: `stopped` 146 s after. The API
/// NEVER reads `started` (behaviour 46). Counted from the `start` call.
/// This is the FLOOR the API reports even when a real guest behind the mock
/// finished its install in 2 s: the API reports UpCloud time.
pub install_pass_lo_ms: u64,
pub install_pass_hi_ms: u64,
/// **An installer start DOES read `started` — briefly.** MEASURED
/// 2026-09-21 08:42 (private-gunnar-ops `.reimage/reinstall-receipt.json`,
/// the live re-image, `done: true`): step `start` at 377 421 ms, a read of
/// `started` at 381 091 ms ("the hypervisor reports the installer
/// running"), `maintenance` at 381 174 ms, `stopped` at 530 945 ms. The
/// 2026-09-19 "never `started`" was polled every 10 s from t+10 s
/// (RESUME-2026-09-19:17-23), which cannot see a window this short. So:
/// `started` from `installer_started_ms` for `installer_started_window_ms`
/// — the window is only BOUNDED by the reads (≤ 83 ms after one that saw
/// it), not measured — then `maintenance` until the pass ends.
pub installer_started_ms: u64,
pub installer_started_window_ms: u64,
/// **Behaviour 72: the installer's `started`, held for WALL ms** (0 = off,
/// the virtual window alone). MEASURED on the REAL gunnar.rs: the twin's
/// keep medium read `started` at the kit's first read, `maintenance` 6–8 s
/// later (2026-10-02, 2026-10-03). mock-upcloud-kvm `--installer-started-s N`.
pub installer_started_wall_ms: u64,
/// **The REBOOTING medium's pass (behaviour 69): 900–1100 s, read `started`
/// throughout.** gunnar deploy/upcloud plan.rs: every measured pass
/// ≥ 900 s; 1000–1100 s live on 2026-09-08. At its end the guest reboots.
pub reboot_pass_lo_ms: u64,
pub reboot_pass_hi_ms: u64,
/// **The lag between the guest powering off and the API saying `stopped`,**
/// used only when a REAL guest outlives the floor above: the API may not
/// say `stopped` while the machine still runs, and says it this long after
/// the machine is gone. Bounded by the 10 s polls that measured it.
pub poweroff_notice_ms: u64,
/// **How long an armed [`crate::faults::Fault::StopHeldInMaintenance`]
/// holds a stopping server in `maintenance`**, WALL ms from the stop
/// request (a caller's soft window is real seconds). 150 s: past the kit's
/// 120 s window, as the real test2 was at +130.6 s on 2026-10-01.
pub stop_held_ms: u64,
/// **How many starts an armed [`crate::faults::Fault::StartNoCapacity`] or
/// [`crate::faults::Fault::StartFallsBack`] spoils** before it disarms
/// itself (behaviour 71). 2: the real gunnar.rs's fall-back and its 409.
pub start_fault_n: u32,
/// **How long a start that falls back reads `maintenance`** before
/// `stopped`, WALL ms (behaviour 71): 2:30, as main read on 2026-10-03.
pub start_fallback_ms: u64,
/// **How long an armed [`crate::faults::Fault::StartErrorStateOnce`] holds a started
/// server in `error`** (behaviour 78), virtual ms: 20 min — gunnar.rs's main read `error`
/// after its keep medium ran (~02:55Z) and booted its disk at 03:15Z, 2026-10-25.
pub error_state_ms: u64,
/// **A size grow: `maintenance` for 37 s, then `online`.** MEASURED
/// 2026-09-14 on a detached 1→2 GiB volume (DATA-SET-GROWTH-DESIGN §2).
/// It was instant here (behaviour 55).
pub storage_grow_ms: u64,
/// **The VNC toggle's settle.** The PUT returns before the console has
/// moved; read inside this window and the OLD port comes back. MEASURED as
/// the pause the working tools need (gunnar `console.rs`, 2 s).
pub vnc_settle_ms: u64,
/// **The last leg of an import: `syncing` → `maintenance` → `online`.**
/// MEASURED as a sequence (clone_probe: "maintenance, syncing, maintenance,
/// online"); the split of the 100–130 s between the two legs is not, so
/// this is carved out of the sync range rather than added to it.
pub sync_tail_maintenance_ms: u64,
/// **How long an armed [`crate::faults::Fault::UtilityDhcpLateFirstBoot`] keeps a
/// server's first boot without a utility lease**, WALL ms from its first ask. 90 s:
/// past the one DHCP attempt a boot makes before it moves on (test3-holger-rs r6).
pub dhcp_late_first_boot_ms: u64,
}
impl Timings {
/// **The same re-image, as the two observers see it.**
///
/// Returns `(guest_uart_ms, ladder_wall_ms)`. They differ by two orders of
/// magnitude and they are both right: the first is the guest's own install,
/// the second is everything the provider does around it. Reporting one
/// number for "install" is what makes a 60-second bar unpassable and makes
/// moving the bar look reasonable.
pub fn reimage_observers(&self, seed: u64, tag: &str) -> (u64, u64) {
let mut r = crate::rng::SplitMix64::derive(seed, &format!("reimage/{tag}"));
(
r.range(self.guest_install_uart_lo_ms, self.guest_install_uart_hi_ms),
r.range(self.provider_wall_lo_ms, self.provider_wall_hi_ms),
)
}
}
impl Default for Timings {
fn default() -> Self {
Timings {
server_create_lo_ms: 98_000,
server_create_hi_ms: 105_000,
server_delete_ms: 60_000,
server_delete_per_volume_ms: 65_000,
storage_create_ms: 3_000,
storage_delete_ms: 4_000,
stop_soft_ms: 12_000,
stop_hard_ms: 2_000,
start_ms: 10_000,
resize_ms: 25_000,
guest_install_ms: 10_011,
guest_install_uart_lo_ms: 2_001,
guest_install_uart_hi_ms: 4_752,
provider_wall_lo_ms: 110_000,
provider_wall_hi_ms: 253_000,
template_first_boot_ms: 45_000,
import_upload_ms_per_mib: 120,
storage_sync_lo_ms: 100_000,
storage_sync_hi_ms: 130_000,
clone_online_ms: 47_000,
// The old guess: identical to the storage sync. By name only.
clone_sync_lo_ms: 100_000,
clone_sync_hi_ms: 130_000,
clone_prepare_ms: 3_000,
install_pass_lo_ms: 130_000,
install_pass_hi_ms: 146_000,
installer_started_ms: 3_600,
installer_started_window_ms: 100,
installer_started_wall_ms: 0,
reboot_pass_lo_ms: 900_000,
reboot_pass_hi_ms: 1_100_000,
poweroff_notice_ms: 10_000,
stop_held_ms: 150_000,
start_fault_n: 2,
start_fallback_ms: 150_000,
error_state_ms: 1_200_000,
storage_grow_ms: 37_000,
vnc_settle_ms: 2_000,
sync_tail_maintenance_ms: 4_000,
dhcp_late_first_boot_ms: 90_000,
}
}
}
/// Virtual milliseconds since the mock started.
///
/// `speed` is how many virtual milliseconds pass per real millisecond, so `1.0`
/// is real time. At `0.0` real time contributes nothing and the clock only
/// moves when something [`Clock::advance`]s it — which the request handlers do,
/// by the smallest amount that lets the next scheduled transition happen. That
/// is what makes a storm run at CPU speed without reordering anything.
pub struct Clock {
started: Instant,
speed_milli: u64,
/// Virtual ms added on top of the elapsed-real contribution.
pushed: AtomicU64,
}
impl Clock {
/// `speed` in thousandths, so the knob is an integer and two mocks with the
/// same knob are the same mock. `1000` = real time, `0` = virtual only.
pub fn new(speed_milli: u64) -> Clock {
Clock {
started: Instant::now(),
speed_milli,
pushed: AtomicU64::new(0),
}
}
pub fn faithful() -> Clock {
Clock::new(1000)
}
pub fn virtual_only() -> Clock {
Clock::new(0)
}
pub fn speed_milli(&self) -> u64 {
self.speed_milli
}
/// Now, in virtual milliseconds.
pub fn now_ms(&self) -> u64 {
let real = self.started.elapsed().as_millis() as u64;
real.saturating_mul(self.speed_milli) / 1000 + self.pushed.load(Ordering::SeqCst)
}
/// Push the virtual clock forward. Used by the handlers when `speed_milli`
/// is 0.
///
/// **This sentence used to say the wrong thing, and it cost an afternoon.**
/// It claimed a read of an object mid-transition "advances time to the
/// moment the transition completes, so the SECOND poll sees it done".
/// `Estate::tick` does no such thing and says so in its own comment: it
/// advances HALFWAY to the next deadline, on purpose, so that a client must
/// poll several times as it does against the provider. Halving a 12 000 ms
/// stop takes about FOURTEEN polls to close.
///
/// That is fine for a client with its own loop and fatal for one with a
/// BUDGET: MEASURED 2026-09-21, `UpCloudLtd/upcloud` 5.44.1 waiting for a
/// server to reach `stopped` before a filesystem resize gave up while the
/// mock still said `maintenance`, and the resize was then refused
/// `SERVER_STATE_ILLEGAL` — a defect that belongs to neither the estate nor
/// the provider. **Drive terraform against a mock with a non-zero
/// `--speed`** (20 000 is 20× faster than the account and still real
/// waiting); `--speed 0` is for in-process callers that poll without a
/// wall-clock budget.
pub fn advance_ms(&self, ms: u64) {
self.pushed.fetch_add(ms, Ordering::SeqCst);
}
/// The gap the mock should let a caller experience for a scheduled `at_ms`.
/// At real speed this is a real sleep; at virtual speed it is nothing, and
/// the caller is expected to [`Clock::advance_ms`] instead.
pub fn real_wait_for(&self, at_ms: u64) -> Option<Duration> {
if self.speed_milli == 0 {
return None;
}
let now = self.now_ms();
if at_ms <= now {
return None;
}
let virt = at_ms - now;
Some(Duration::from_millis(virt.saturating_mul(1000) / self.speed_milli))
}
}
#[cfg(test)]
mod tests {
use super::*;
#[test]
fn virtual_clock_only_moves_when_pushed() {
let c = Clock::virtual_only();
assert_eq!(c.now_ms(), 0);
std::thread::sleep(Duration::from_millis(30));
assert_eq!(c.now_ms(), 0, "real time must not leak in at speed 0");
c.advance_ms(98_000);
assert_eq!(c.now_ms(), 98_000);
}
#[test]
fn faithful_clock_tracks_real_time() {
let c = Clock::faithful();
std::thread::sleep(Duration::from_millis(40));
let n = c.now_ms();
assert!((30..400).contains(&n), "{n}");
}
#[test]
fn a_speed_knob_scales_the_wait_not_the_order() {
let c = Clock::new(100_000); // 100x
let w = c.real_wait_for(100_000).unwrap();
assert!(w <= Duration::from_millis(1100), "{w:?}");
assert_eq!(Clock::virtual_only().real_wait_for(100_000), None);
}
/// **Two observers, two orders of magnitude.** The guest's own install is
/// seconds; the ladder's wall measurement of the same re-image is minutes.
/// A bar set against one and named after the other is unpassable forever.
#[test]
fn the_installer_is_not_slow_the_provider_is() {
let t = Timings::default();
for tag in ["a", "b", "c", "d", "e"] {
let (uart, wall) = t.reimage_observers(42, tag);
assert!((2_001..=4_752).contains(&uart), "uart {uart}");
assert!((110_000..=253_000).contains(&wall), "wall {wall}");
assert!(
wall > uart * 20,
"the gap is two orders of magnitude, and it is the PROVIDER's: {wall} vs {uart}"
);
}
// And it replays: the same seed and tag give the same pair, so a row
// that reported a number can be re-derived rather than re-measured.
assert_eq!(t.reimage_observers(42, "a"), t.reimage_observers(42, "a"));
assert_ne!(t.reimage_observers(42, "a"), t.reimage_observers(43, "a"));
}
/// The measured upload: 43 485 184 bytes in five seconds. If this table
/// ever stops reproducing that, the numbers behind the re-image's cost
/// have stopped being the measured ones.
#[test]
fn the_measured_iso_uploads_in_five_seconds() {
let t = Timings::default();
let mib = 43_485_184u64 / (1024 * 1024);
let ms = mib * t.import_upload_ms_per_mib;
assert!((4_500..=5_500).contains(&ms), "{ms} ms for {mib} MiB");
}
/// And then the storage waits twenty times longer than the upload took,
/// doing nothing, twice per re-image.
#[test]
fn the_sync_dwarfs_the_upload_and_is_paid_twice() {
let t = Timings::default();
let upload = (43_485_184u64 / (1024 * 1024)) * t.import_upload_ms_per_mib;
assert!(t.storage_sync_lo_ms > upload * 15, "the wait is the cost, not the transfer");
let one_medium = upload + t.storage_sync_lo_ms;
let a_reimage = 2 * one_medium;
assert!(a_reimage > 200_000, "two media is over three minutes: {a_reimage} ms");
}
/// The delete of an appliance with four member volumes is the >5 min that
/// was measured; the front's is the ~60 s. One table, both numbers.
#[test]
fn delete_of_a_four_volume_appliance_exceeds_five_minutes() {
let t = Timings::default();
let front = t.server_delete_ms;
let appliance = t.server_delete_ms + 4 * t.server_delete_per_volume_ms;
assert!((55_000..=65_000).contains(&front), "{front}");
assert!(appliance > 300_000, "{appliance}");
}
}