The quiesce tests seem to be flaky

[jmpesp]

Locally, the quiesce tests seem to be flaky:

-------
    failures:
        app::quiesce::test::test_quiesce_easy

    test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 179 filtered out; finished in 30.47s
    
  stderr ───
    log file: /dangerzone/tmp/omicron_nexus-dc18ba054d049c54-test_quiesce_easy.26897.0.log
    note: configured to log to "/dangerzone/tmp/omicron_nexus-dc18ba054d049c54-test_quiesce_easy.26897.0.log"
    DB URL: postgresql://root@[::1]:56066/omicron?sslmode=disable
    DB address: [::1]:56066
    log file: /dangerzone/tmp/omicron_nexus-dc18ba054d049c54-test_quiesce_easy.26897.2.log
    note: configured to log to "/dangerzone/tmp/omicron_nexus-dc18ba054d049c54-test_quiesce_easy.26897.2.log"
    time_requested: 2025-09-25T15:24:53.907870863Z | time_quiesced: 2025-09-25T15:24:56.591531625Z
    duration_total: 2.773802175s | before: 2025-09-25 15:24:53.893479022 UTC | after: 2025-09-25 15:24:56.646460324 UTC | (after - before): PT2.752981302S

    thread 'app::quiesce::test::test_quiesce_easy' panicked at nexus/src/app/quiesce.rs:605:9:
    assertion failed: duration_total <= (after - before).to_std().unwrap()
    stack backtrace:
       0:         0x22e455ee - std::backtrace_rs::backtrace::libunwind::trace::h2a5855593bdf7971
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/../../backtrace/src/backtrace/libunwind.rs:117:9
       1:         0x22e455ee - std::backtrace_rs::backtrace::trace_unsynchronized::h77df4a8ff549fc2a
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/../../backtrace/src/backtrace/mod.rs:66:14
       2:         0x22e455ee - std::sys::backtrace::_print_fmt::he967099ff6502847
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/sys/backtrace.rs:66:9
       3:         0x22e455ee - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::hac6301e3beb5b43c
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/sys/backtrace.rs:39:26
       4:         0x22e92653 - core::fmt::rt::Argument::fmt::h406c27fd1e7b79da
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/fmt/rt.rs:173:76
       5:         0x22e92653 - core::fmt::write::he235fe5c32bd192f
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/fmt/mod.rs:1465:25
       6:         0x22e3a422 - std::io::default_write_fmt::h8b11782cf3cbfb03
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/io/mod.rs:639:11
       7:         0x22e3a422 - std::io::Write::write_fmt::h1b47e1cf4163f721
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/io/mod.rs:1954:13
       8:         0x22e45442 - std::sys::backtrace::BacktraceLock::print::hd5408b4ebe11b421
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/sys/backtrace.rs:42:9
       9:         0x22e49170 - std::panicking::default_hook::{{closure}}::h692ee85fa0930b8d
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:300:27
      10:         0x22e48f4d - std::panicking::default_hook::hd370a4a489052f60
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:327:9
      11:         0x22e49cc0 - std::panicking::rust_panic_with_hook::h0aef764ab51e4cad
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:833:13
      12:         0x22e49985 - std::panicking::begin_panic_handler::{{closure}}::h95c6fc51d1e834de
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:699:13
      13:         0x22e45ab9 - std::sys::backtrace::__rust_end_short_backtrace::h1cf9451894e45d77
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/sys/backtrace.rs:168:18
      14:         0x22e4964c - __rustc[5224e6b81cd82a8f]::rust_begin_unwind
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:697:5
      15:         0x22e8da9f - core::panicking::panic_fmt::h3e09b00363b9565a
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/panicking.rs:75:14
      16:         0x22e8db2b - core::panicking::panic::h7b44b50a8b0391e5
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/panicking.rs:145:5
      17:         0x13881f81 - verify_quiesced
                                   at /home/james/src/oxidecomputer/omicron/nexus/src/app/quiesce.rs:605:9
      18:         0x15430f2a - {async_fn#0}
                                   at /home/james/src/oxidecomputer/omicron/nexus/src/app/quiesce.rs:657:9
      19:         0x1543058b - {async_block#0}
                                   at /home/james/src/oxidecomputer/omicron/nexus/src/app/quiesce.rs:631:5
      20:         0x191bd14b - poll<&mut dyn core::future::future::Future<Output=()>>
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/future/future.rs:124:9
      21:         0x191b7a0d - poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/future/future.rs:124:9
      22:         0x16ee8985 - {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:742:70
      23:         0x16ee87df - with_budget<core::task::poll::Poll<()>, tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure#0}::{closure#0}::{closure_env#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/task/coop/mod.rs:167:5
      24:         0x16ee87df - budget<core::task::poll::Poll<()>, tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure#0}::{closure#0}::{closure_env#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/task/coop/mod.rs:133:5
      25:         0x16ee87df - {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:742:25
      26:         0x16ee5df3 - tokio::runtime::scheduler::current_thread::Context::enter::h324e7e16f13ab805
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:432:19
      27:         0x16ee74dd - {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:741:44
      28:         0x16ee7257 - tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}::h39cc579cf66cc44f
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:68
      29:         0x13d14a96 - tokio::runtime::context::scoped::Scoped<T>::set::h97b1993993e190ed
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/scoped.rs:40:9
      30:         0x169ba733 - tokio::runtime::context::set_scheduler::{{closure}}::h4bd40452bb8d7dd8
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:38
      31:         0x174dc324 - try_with<tokio::runtime::context::Context, tokio::runtime::context::set_scheduler::{closure_env#0}<(alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core, alloc::alloc::Global>, core::option::Option<()>), tokio::runtime::scheduler::current_thread::{impl#8}::enter::{closure_env#0}<tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure_env#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>, core::option::Option<()>>>, (alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core, alloc::alloc::Global>, core::option::Option<()>)>
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/thread/local.rs:315:12
      32:         0x174d935d - std::thread::local::LocalKey<T>::with::hc2ba557c9f3c5703
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/thread/local.rs:279:20
      33:         0x169ba6ab - tokio::runtime::context::set_scheduler::h5892752ef93a68c3
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:17
      34:         0x16ee6d7c - tokio::runtime::scheduler::current_thread::CoreGuard::enter::h2c3e547d525af95b
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:27
      35:         0x16ee72c1 - tokio::runtime::scheduler::current_thread::CoreGuard::block_on::hbee79958fad26ac3
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:729:24
      36:         0x16ecf795 - {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:200:33
      37:         0x149b8acc - tokio::runtime::context::runtime::enter_runtime::h5b22455f38eb1a87
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/runtime.rs:65:16
      38:         0x16ecf14c - block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:188:9
      39:         0x179d14d1 - tokio::runtime::runtime::Runtime::block_on_inner::h4ca9b8b7ee5e1590
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:356:52
      40:         0x179d16f5 - block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                                   at /home/james/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:330:18
      41:         0x1388a528 - test_quiesce_easy
                                   at /home/james/src/oxidecomputer/omicron/nexus/src/app/quiesce.rs:631:5
      42:         0x15430275 - omicron_nexus::app::quiesce::test::test_quiesce_easy::{{closure}}::h53e15dd3efb18699
                                   at /home/james/src/oxidecomputer/omicron/nexus/src/app/quiesce.rs:632:68
      43:         0x141cf698 - core::ops::function::FnOnce::call_once::h79dcac8b56ae39b3
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/ops/function.rs:250:5
      44:         0x194482bb - core::ops::function::FnOnce::call_once::hf688302fb1d74a07
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/ops/function.rs:250:5
      45:         0x194482bb - test::__rust_begin_short_backtrace::hf22dcb3d56ca0998
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/test/src/lib.rs:648:18
      46:         0x194474de - test::run_test_in_process::{{closure}}::hee8ac2349b7684fd
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/test/src/lib.rs:671:74
      47:         0x194474de - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h48db316caf5fae7c
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/panic/unwind_safe.rs:272:9
      48:         0x194474de - std::panicking::catch_unwind::do_call::hf73e8f47297f10a4
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:589:40
      49:         0x194474de - std::panicking::catch_unwind::hfba8b5786822dbb5
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:552:19
      50:         0x194474de - std::panic::catch_unwind::h857398966fa79eea
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panic.rs:359:14
      51:         0x194474de - test::run_test_in_process::ha9c6081199a876ab
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/test/src/lib.rs:671:27
      52:         0x194474de - test::run_test::{{closure}}::h9d8360475dce93d2
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/test/src/lib.rs:592:43
      53:         0x19409a83 - test::run_test::{{closure}}::ha95736c1de59ebfe
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/test/src/lib.rs:622:41
      54:         0x19409a83 - std::sys::backtrace::__rust_begin_short_backtrace::hfe30362f17296f49
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/sys/backtrace.rs:152:18
      55:         0x1940d215 - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::h4fea01cd9abb0140
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/thread/mod.rs:559:17
      56:         0x1940d215 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h826262d2c69a2b03
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/panic/unwind_safe.rs:272:9
      57:         0x1940d215 - std::panicking::catch_unwind::do_call::h272f6126d391be98
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:589:40
      58:         0x1940d215 - std::panicking::catch_unwind::h1d54a8ea20a25932
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panicking.rs:552:19
      59:         0x1940d215 - std::panic::catch_unwind::he4e0cf1e555d3ad4
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/panic.rs:359:14
      60:         0x1940d215 - std::thread::Builder::spawn_unchecked_::{{closure}}::h4765b016ffa7974f
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/thread/mod.rs:557:30
      61:         0x1940d215 - core::ops::function::FnOnce::call_once{{vtable.shim}}::ha75243f73f5d38ab
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/core/src/ops/function.rs:250:5
      62:         0x22e4d7cf - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hedfba83416541f70
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/alloc/src/boxed.rs:1966:9
      63:         0x22e4d7cf - std::sys::pal::unix::thread::Thread::new::thread_start::h51c10c3cf848ec37
                                   at /rustc/29483883eed69d5fb4db01964cdf2af4d86e9cb2/library/std/src/sys/pal/unix/thread.rs:107:17
      64: 0xfffffc7fee286777 - _thrp_setup
      65: 0xfffffc7fee286ac0 - <unknown>

This is running with the following diff:

diff --git a/nexus/src/app/quiesce.rs b/nexus/src/app/quiesce.rs
index 853425e39..8eb4c1824 100644
--- a/nexus/src/app/quiesce.rs
+++ b/nexus/src/app/quiesce.rs
@@ -590,6 +590,10 @@ mod test {
         let duration_draining_db = Duration::from(duration_draining_db);
         let duration_recording_quiesce =
             Duration::from(duration_recording_quiesce);
+
+        eprintln!("time_requested: {:?} | time_quiesced: {:?}", time_requested, time_quiesced);
+        eprintln!("duration_total: {:?} | before: {} | after: {} | (after - before): {}", duration_total, before, after, (after - before));
+
         assert!(time_requested >= before);
         assert!(time_requested <= after);
         assert!(time_quiesced >= before);

I've attached the Nexus log for this to the issue.

omicron_nexus-dc18ba054d049c54-test_quiesce_easy.26897.0.log

[davepacheco]

The test is grabbing wall clock timestamps before (before it initiates the quiesce) and after (after quiesce finishes) and comparing the duration between those timestamps to the duration recorded by the quiesce subsystem for how long that took. The latter is a monotonic time. The assertion is expecting that the wall time elapsed between before and after is not smaller than the reported quiesce duration.

First, it doesn't seem right to compare wall clock duration and monotonic duration in this way. The test is using wall timestamps because it's also comparing them to time_requested and time_quiesced, which are wall timestamps, and ought to have the relationships that it's asserting (assuming no actual discontinuities in the clock). But rather than use these timestamps for both types of comparisons, I think it should just grab two types of timestamps both before and after, one wall-time and one monotonic, just like the subsystem itself does. Then it can compare like-for-like.

That said, I'm a little surprised this turned out to be untrue. This is telling us that the machine reports 2.773802175s having elapsed in 2.752981302s of wall time. I could imagine this might happen if the machine's clock were fast and being slewed to real-time by NTP or something.

[jmpesp]

In this case, the theory is correct: the machine's clock is fast and being slewed:

$ pfexec chronyc tracking
Reference ID    : CE6C0085 (ntp3.torix.ca)
Stratum         : 2
Ref time (UTC)  : Thu Sep 25 17:10:23 2025
System time     : 313.719085693 seconds fast of NTP time
Last offset     : +0.000380962 seconds
RMS offset      : 0.105379850 seconds
Frequency       : 18.778 ppm fast
Residual freq   : +0.035 ppm
Skew            : 0.573 ppm
Root delay      : 0.005428036 seconds
Root dispersion : 0.001005025 seconds
Update interval : 520.0 seconds
Leap status     : Normal

It's very surprising that it's out this much!

I tried patching with 9090 and it seems to address the problem.