mock_upcloud/

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,
    /// **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,
    /// **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,
}

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,
            reboot_pass_lo_ms: 900_000,
            reboot_pass_hi_ms: 1_100_000,
            poweroff_notice_ms: 10_000,
            storage_grow_ms: 37_000,
            vnc_settle_ms: 2_000,
            sync_tail_maintenance_ms: 4_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}");
    }
}