test failed in CI: `db::datastore::audit_log::tests::test_audit_log_basic`

[hawkw]

This test failed on a CI run on pull request #10272:

https://github.com/oxidecomputer/omicron/pull/10272/checks?check_run_id=71517696811

Log showing the specific test failure:

https://buildomat.eng.oxide.computer/wg/0/details/01KP98FXFYMJ7D1KC38FZQ3BRF/aZXP2KtlvQfKTNyUg7TiDJ0dBTmvR5uJajKWGr1mInO0H8eC/01KP98GD37DA22Q5V854VW7GP2#S7790

Excerpt from the log showing the failure:

    log file: /var/tmp/omicron_tmp/nexus_db_queries-9cbcb5772a5baf98-test_audit_log.66775.0.log
    note: configured to log to "/var/tmp/omicron_tmp/nexus_db_queries-9cbcb5772a5baf98-test_audit_log.66775.0.log"

    thread 'db::datastore::audit_log::tests::test_audit_log_basic' (66776) panicked at nexus/db-queries/src/db/datastore/audit_log.rs:359:9:
    2026-04-15 19:16:44.154913 UTC was not between 2026-04-15 19:16:44.154913040 UTC and 2026-04-15 19:16:44.197883029 UTC
    stack backtrace:
       0: __rustc::rust_begin_unwind
                 at /rustc/4a4ef493e3a1488c6e321570238084b38948f6db/library/std/src/panicking.rs:689:5
       1: core::panicking::panic_fmt
                 at /rustc/4a4ef493e3a1488c6e321570238084b38948f6db/library/core/src/panicking.rs:80:14
       2: {async_block#0}
                 at ./src/db/datastore/audit_log.rs:359:9
       3: poll<&mut dyn core::future::future::Future<Output=()>>
                 at /rustc/4a4ef493e3a1488c6e321570238084b38948f6db/library/core/src/future/future.rs:133:9
       4: poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                 at /rustc/4a4ef493e3a1488c6e321570238084b38948f6db/library/core/src/future/future.rs:133:9
       5: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:778:70
       6: with_budget<core::task::poll::Poll<()>, tokio::runtime::scheduler::current_thread::{impl#9}::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/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/task/coop/mod.rs:167:5
       7: budget<core::task::poll::Poll<()>, tokio::runtime::scheduler::current_thread::{impl#9}::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/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/task/coop/mod.rs:133:5
       8: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:778:25
       9: <tokio::runtime::scheduler::current_thread::Context>::enter::<core::task::poll::Poll<()>, <tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}::{closure#0}>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:451:19
      10: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:777:44
      11: <tokio::runtime::scheduler::current_thread::CoreGuard>::enter::<<tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, core::option::Option<()>>::{closure#0}
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:865:68
      12: <tokio::runtime::context::scoped::Scoped<tokio::runtime::scheduler::Context>>::set::<<tokio::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, core::option::Option<()>>::{closure#0}, (alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core>, core::option::Option<()>)>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/context/scoped.rs:40:9
      13: tokio::runtime::context::set_scheduler::<(alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core>, core::option::Option<()>), <tokio::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, core::option::Option<()>>::{closure#0}>::{closure#0}
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/context.rs:181:38
      14: 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#9}::enter::{closure_env#0}<tokio::runtime::scheduler::current_thread::{impl#9}::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/4a4ef493e3a1488c6e321570238084b38948f6db/library/std/src/thread/local.rs:513:12
      15: <std::thread::local::LocalKey<tokio::runtime::context::Context>>::with::<tokio::runtime::context::set_scheduler<(alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core>, core::option::Option<()>), <tokio::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, core::option::Option<()>>::{closure#0}>::{closure#0}, (alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core>, core::option::Option<()>)>
                 at /rustc/4a4ef493e3a1488c6e321570238084b38948f6db/library/std/src/thread/local.rs:477:20
      16: tokio::runtime::context::set_scheduler::<(alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core>, core::option::Option<()>), <tokio::runtime::scheduler::current_thread::CoreGuard>::enter<<tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, core::option::Option<()>>::{closure#0}>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/context.rs:181:17
      17: <tokio::runtime::scheduler::current_thread::CoreGuard>::enter::<<tokio::runtime::scheduler::current_thread::CoreGuard>::block_on<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>::{closure#0}, core::option::Option<()>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:865:27
      18: <tokio::runtime::scheduler::current_thread::CoreGuard>::block_on::<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:765:24
      19: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:205:33
      20: tokio::runtime::context::runtime::enter_runtime::<<tokio::runtime::scheduler::current_thread::CurrentThread>::block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>::{closure#0}, ()>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/context/runtime.rs:65:16
      21: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/scheduler/current_thread/mod.rs:193:9
      22: <tokio::runtime::runtime::Runtime>::block_on_inner::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/runtime.rs:371:52
      23: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                 at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.52.0/src/runtime/runtime.rs:345:18
      24: test_audit_log_basic
                 at ./src/db/datastore/audit_log.rs:381:36
      25: nexus_db_queries::db::datastore::audit_log::tests::test_audit_log_basic::{closure#0}
                 at ./src/db/datastore/audit_log.rs:238:36
      26: <nexus_db_queries::db::datastore::audit_log::tests::test_audit_log_basic::{closure#0} as core::ops::function::FnOnce<()>>::call_once
                 at /rustc/4a4ef493e3a1488c6e321570238084b38948f6db/library/core/src/ops/function.rs:250:5
      27: core::ops::function::FnOnce::call_once
                 at /rustc/4a4ef493e3a1488c6e321570238084b38948f6db/library/core/src/ops/function.rs:250:5
    note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
    WARN: dropped CockroachInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
    WARN: temporary directory leaked: "/var/tmp/omicron_tmp/.tmp2m9Oy9"
    	If you would like to access the database for debugging, run the following:

    	# Run the database
    	cargo xtask db-dev run --no-populate --store-dir "/var/tmp/omicron_tmp/.tmp2m9Oy9/data"
    	# Access the database. Note the port may change if you run multiple databases.
    	cockroach sql --host=localhost:32221 --insecure

Notes

I haven't't actually looked at the relevant code, but just from the assertion failure message, this sure looks like an assertion about a timestamp that loses precision when roundtripped through CRDB. Note that the assertion expected the timestamp 2026-04-15 19:16:44.154913 UTC to be between 2026-04-15 19:16:44.154913040 UTC and 2026-04-15 19:16:44.197883029 UTC --- the lower bound of that range is basically the same timestamp but with the last three decimal places lopped off, which is probably what's gone wrong here. I think we have some test helpers for handling loss of precision in timestamps someplace?

[smklein]

This also flaked yesterday on #9351