test failed in CI: test_action_failure_can_unwind_idempotently

[jgallagher]

This test failed on a CI run on main:

https://github.com/oxidecomputer/omicron/runs/35336066776

Log showing the specific test failure:

https://buildomat.eng.oxide.computer/wg/0/details/01JH3SGM88HYJRX2P30PVTX25R/l2UBDTeLgUKqwvZkXuDKCc0wKv3Bd0zf7MsDvSY49k0w3bmG/01JH3SH3ADNRFE3549NB6G8TV7

Excerpt from the log showing the failure:

6547	2025-01-08T20:55:53.308Z	running 1 test
6548	2025-01-08T20:55:53.308Z	test app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently has been running for over 60 seconds
6549	2025-01-08T20:55:53.308Z	test app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently ... FAILED
6550	2025-01-08T20:55:53.308Z	
6551	2025-01-08T20:55:53.308Z	failures:
6552	2025-01-08T20:55:53.308Z	
6553	2025-01-08T20:55:53.308Z	failures:
6554	2025-01-08T20:55:53.308Z	    app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently
6555	2025-01-08T20:55:53.308Z	
6556	2025-01-08T20:55:53.308Z	test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 140 filtered out; finished in 610.58s
6557	2025-01-08T20:55:53.308Z	
6558	2025-01-08T20:55:53.308Z	──── STDERR:             omicron-nexus app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently
6559	2025-01-08T20:55:53.308Z	log file: /var/tmp/omicron_tmp/omicron_nexus-f37402b959767028-test_action_failure_can_unwind_idempotently.64536.0.log
6560	2025-01-08T20:55:53.308Z	note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-f37402b959767028-test_action_failure_can_unwind_idempotently.64536.0.log"
6561	2025-01-08T20:55:53.308Z	DB URL: postgresql://root@[::1]:36933/omicron?sslmode=disable
6562	2025-01-08T20:55:53.308Z	DB address: [::1]:36933
6563	2025-01-08T20:55:53.308Z	log file: /var/tmp/omicron_tmp/omicron_nexus-f37402b959767028-test_action_failure_can_unwind_idempotently.64536.2.log
6564	2025-01-08T20:55:53.308Z	note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-f37402b959767028-test_action_failure_can_unwind_idempotently.64536.2.log"
6565	2025-01-08T20:55:53.308Z	log file: /var/tmp/omicron_tmp/omicron_nexus-f37402b959767028-test_action_failure_can_unwind_idempotently.64536.3.log
6566	2025-01-08T20:55:53.308Z	note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-f37402b959767028-test_action_failure_can_unwind_idempotently.64536.3.log"
6567	2025-01-08T20:55:53.308Z	thread 'app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently' panicked at nexus/src/app/sagas/instance_create.rs:1330:9:
6568	2025-01-08T20:55:53.308Z	assertion failed: test_helpers::no_sled_resource_instance_records_exist(cptestctx).await
6569	2025-01-08T20:55:53.308Z	stack backtrace:
6570	2025-01-08T20:55:53.308Z	   0: rust_begin_unwind
6571	2025-01-08T20:55:53.308Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/panicking.rs:665:5
6572	2025-01-08T20:55:53.308Z	   1: core::panicking::panic_fmt
6573	2025-01-08T20:55:53.308Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panicking.rs:74:14
6574	2025-01-08T20:55:53.308Z	   2: core::panicking::panic
6575	2025-01-08T20:55:53.308Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/panicking.rs:148:5
6576	2025-01-08T20:55:53.308Z	   3: {async_fn#0}
6577	2025-01-08T20:55:53.308Z	             at ./src/app/sagas/instance_create.rs:1330:9
6578	2025-01-08T20:55:53.309Z	   4: {async_block#0}
6579	2025-01-08T20:55:53.309Z	             at ./src/app/sagas/instance_create.rs:1401:64
6580	2025-01-08T20:55:53.309Z	   5: poll<alloc::boxed::Box<(dyn core::future::future::Future<Output=()> + core::marker::Send), alloc::alloc::Global>>
6581	2025-01-08T20:55:53.309Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/future/future.rs:123:9
6582	2025-01-08T20:55:53.309Z	   6: {async_fn#0}<omicron_nexus::app::sagas::instance_create::SagaInstanceCreate, omicron_nexus::app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently::{async_block#0}::test_action_failure_can_unwind_idempotently::{async_fn#0}::{closure_env#0}, omicron_nexus::app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently::{async_block#0}::test_action_failure_can_unwind_idempotently::{async_fn#0}::{closure_env#1}>
6583	2025-01-08T20:55:53.309Z	             at ./src/app/sagas/test_helpers.rs:761:22
6584	2025-01-08T20:55:53.309Z	   7: {async_fn#0}
6585	2025-01-08T20:55:53.309Z	             at ./src/app/sagas/instance_create.rs:1404:10
6586	2025-01-08T20:55:53.309Z	   8: {async_block#0}
6587	2025-01-08T20:55:53.309Z	             at ./src/app/sagas/instance_create.rs:1382:5
6588	2025-01-08T20:55:53.309Z	   9: poll<&mut dyn core::future::future::Future<Output=()>>
6589	2025-01-08T20:55:53.309Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/future/future.rs:123:9
6590	2025-01-08T20:55:53.309Z	  10: poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6591	2025-01-08T20:55:53.309Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/future/future.rs:123:9
6592	2025-01-08T20:55:53.309Z	  11: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
6593	2025-01-08T20:55:53.309Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:696:57
6594	2025-01-08T20:55:53.309Z	  12: 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=()>>>>>
6595	2025-01-08T20:55:53.309Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/coop.rs:107:5
6596	2025-01-08T20:55:53.310Z	  13: 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=()>>>>>
6597	2025-01-08T20:55:53.310Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/coop.rs:73:5
6598	2025-01-08T20:55:53.310Z	  14: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
6599	2025-01-08T20:55:53.310Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:696:25
6600	2025-01-08T20:55:53.310Z	  15: tokio::runtime::scheduler::current_thread::Context::enter
6601	2025-01-08T20:55:53.310Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:423:19
6602	2025-01-08T20:55:53.310Z	  16: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
6603	2025-01-08T20:55:53.310Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:695:36
6604	2025-01-08T20:55:53.310Z	  17: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
6605	2025-01-08T20:55:53.310Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:774:68
6606	2025-01-08T20:55:53.310Z	  18: tokio::runtime::context::scoped::Scoped<T>::set
6607	2025-01-08T20:55:53.310Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/context/scoped.rs:40:9
6608	2025-01-08T20:55:53.310Z	  19: tokio::runtime::context::set_scheduler::{{closure}}
6609	2025-01-08T20:55:53.310Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/context.rs:180:26
6610	2025-01-08T20:55:53.310Z	  20: 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<()>)>
6611	2025-01-08T20:55:53.311Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:283:12
6612	2025-01-08T20:55:53.311Z	  21: std::thread::local::LocalKey<T>::with
6613	2025-01-08T20:55:53.311Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/std/src/thread/local.rs:260:9
6614	2025-01-08T20:55:53.311Z	  22: tokio::runtime::context::set_scheduler
6615	2025-01-08T20:55:53.311Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/context.rs:180:9
6616	2025-01-08T20:55:53.311Z	  23: tokio::runtime::scheduler::current_thread::CoreGuard::enter
6617	2025-01-08T20:55:53.311Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:774:27
6618	2025-01-08T20:55:53.311Z	  24: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
6619	2025-01-08T20:55:53.311Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:683:19
6620	2025-01-08T20:55:53.311Z	  25: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6621	2025-01-08T20:55:53.311Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:191:28
6622	2025-01-08T20:55:53.311Z	  26: tokio::runtime::context::runtime::enter_runtime
6623	2025-01-08T20:55:53.311Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/context/runtime.rs:65:16
6624	2025-01-08T20:55:53.311Z	  27: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6625	2025-01-08T20:55:53.312Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/scheduler/current_thread/mod.rs:179:9
6626	2025-01-08T20:55:53.312Z	  28: tokio::runtime::runtime::Runtime::block_on_inner
6627	2025-01-08T20:55:53.312Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/runtime.rs:361:47
6628	2025-01-08T20:55:53.312Z	  29: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
6629	2025-01-08T20:55:53.312Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.40.0/src/runtime/runtime.rs:335:13
6630	2025-01-08T20:55:53.312Z	  30: test_action_failure_can_unwind_idempotently
6631	2025-01-08T20:55:53.312Z	             at ./src/app/sagas/instance_create.rs:1382:5
6632	2025-01-08T20:55:53.312Z	  31: omicron_nexus::app::sagas::instance_create::test::test_action_failure_can_unwind_idempotently::{{closure}}
6633	2025-01-08T20:55:53.312Z	             at ./src/app/sagas/instance_create.rs:1385:6
6634	2025-01-08T20:55:53.312Z	  32: core::ops::function::FnOnce::call_once
6635	2025-01-08T20:55:53.312Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5
6636	2025-01-08T20:55:53.312Z	  33: core::ops::function::FnOnce::call_once
6637	2025-01-08T20:55:53.312Z	             at /rustc/eeb90cda1969383f56a2637cbd3037bdf598841c/library/core/src/ops/function.rs:250:5
6638	2025-01-08T20:55:53.312Z	note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
6639	2025-01-08T20:55:53.312Z	WARN: dropped CockroachInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
6640	2025-01-08T20:55:53.312Z	WARN: temporary directory leaked: "/var/tmp/omicron_tmp/.tmpko9qLO"
6641	2025-01-08T20:55:53.312Z		If you would like to access the database for debugging, run the following:
6642	2025-01-08T20:55:53.312Z	
6643	2025-01-08T20:55:53.312Z		# Run the database
6644	2025-01-08T20:55:53.315Z		cargo xtask db-dev run --no-populate --store-dir "/var/tmp/omicron_tmp/.tmpko9qLO/data"
6645	2025-01-08T20:55:53.315Z		# Access the database. Note the port may change if you run multiple databases.
6646	2025-01-08T20:55:53.315Z		cockroach sql --host=localhost:32221 --insecure
6647	2025-01-08T20:55:53.315Z	WARN: dropped ClickHouse process without cleaning it up first (there may still be a child process running (PID 64595) and a temporary directory leaked, /var/tmp/omicron_tmp/omicron_nexus-f37402b959767028-test_action_failure_can_unwind_idempotently.64536.1-clickhouse-dDJoQB)
6648	2025-01-08T20:55:53.315Z	WARN: dropped DendriteInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
6649	2025-01-08T20:55:53.316Z	WARN: dendrite temporary directory leaked: /var/tmp/omicron_tmp/.tmpREdji8
6650	2025-01-08T20:55:53.316Z	WARN: dropped DendriteInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
6651	2025-01-08T20:55:53.316Z	WARN: dendrite temporary directory leaked: /var/tmp/omicron_tmp/.tmpPHNNBd
6652	2025-01-08T20:55:53.316Z	WARN: dropped MgdInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
6653	2025-01-08T20:55:53.316Z	WARN: mgd temporary directory leaked: /var/tmp/omicron_tmp/.tmpcKDNtQ
6654	2025-01-08T20:55:53.316Z	WARN: dropped MgdInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
6655	2025-01-08T20:55:53.316Z	WARN: mgd temporary directory leaked: /var/tmp/omicron_tmp/.tmpyBjzta

[jgallagher]

It looks like this has failed on main at least one other time, this one on helios:

https://github.com/oxidecomputer/omicron/runs/35333189905