test failed in CI: omicron-nexus::test_all integration_tests::demo_saga::test_demo_saga

[sunshowers]

This test failed on a CI run on #6382:

• https://github.com/oxidecomputer/omicron/runs/28904588566

Log showing the specific test failure:

• https://buildomat.eng.oxide.computer/wg/0/details/01J5HWQSG5E84795E8VSVP46VP/ekL0MjAiUdwn7V5MJjAnGEiOPz5GyuiSQNOtUyEpcJ0BlEvu/01J5HWRA8WV9MP33WJRDQDXKTT#S5300

Excerpt from the log showing the failure:

5300	2024-08-18T05:08:11.743Z	        FAIL [  12.012s] omicron-nexus::test_all integration_tests::demo_saga::test_demo_saga
5301	2024-08-18T05:08:11.743Z	
5302	2024-08-18T05:08:11.743Z	--- STDOUT:              omicron-nexus::test_all integration_tests::demo_saga::test_demo_saga ---
5303	2024-08-18T05:08:11.743Z	
5304	2024-08-18T05:08:11.743Z	running 1 test
5305	2024-08-18T05:08:11.743Z	test integration_tests::demo_saga::test_demo_saga ... FAILED
5306	2024-08-18T05:08:11.744Z	
5307	2024-08-18T05:08:11.744Z	failures:
5308	2024-08-18T05:08:11.744Z	
5309	2024-08-18T05:08:11.744Z	failures:
5310	2024-08-18T05:08:11.744Z	    integration_tests::demo_saga::test_demo_saga
5311	2024-08-18T05:08:11.744Z	
5312	2024-08-18T05:08:11.744Z	test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 356 filtered out; finished in 11.97s
5313	2024-08-18T05:08:11.744Z	
5314	2024-08-18T05:08:11.744Z	
5315	2024-08-18T05:08:11.744Z	--- STDERR:              omicron-nexus::test_all integration_tests::demo_saga::test_demo_saga ---
5316	2024-08-18T05:08:11.744Z	log file: /var/tmp/omicron_tmp/test_all-9db623fb1941bb12-test_demo_saga.86163.0.log
5317	2024-08-18T05:08:11.744Z	note: configured to log to "/var/tmp/omicron_tmp/test_all-9db623fb1941bb12-test_demo_saga.86163.0.log"
5318	2024-08-18T05:08:11.744Z	DB URL: postgresql://root@[::1]:34479/omicron?sslmode=disable
5319	2024-08-18T05:08:11.744Z	DB address: [::1]:34479
5320	2024-08-18T05:08:11.744Z	log file: /var/tmp/omicron_tmp/test_all-9db623fb1941bb12-test_demo_saga.86163.2.log
5321	2024-08-18T05:08:11.744Z	note: configured to log to "/var/tmp/omicron_tmp/test_all-9db623fb1941bb12-test_demo_saga.86163.2.log"
5322	2024-08-18T05:08:11.744Z	log file: /var/tmp/omicron_tmp/test_all-9db623fb1941bb12-test_demo_saga.86163.3.log
5323	2024-08-18T05:08:11.744Z	note: configured to log to "/var/tmp/omicron_tmp/test_all-9db623fb1941bb12-test_demo_saga.86163.3.log"
5324	2024-08-18T05:08:11.744Z	found sagas (before): []
5325	2024-08-18T05:08:11.744Z	found sagas (after): [Saga { id: 7a368bd7-7d70-4c6e-8f67-ca55883aa6ac, state: Running }]
5326	2024-08-18T05:08:11.744Z	thread 'integration_tests::demo_saga::test_demo_saga' panicked at nexus/tests/integration_tests/demo_saga.rs:47:68:
5327	2024-08-18T05:08:11.744Z	called `Result::unwrap()` on an `Err` value: Error Response: status: 404 Not Found; headers: {"content-type": "application/json", "x-request-id": "9b836ae0-4371-4012-8513-0a64b8626cc5", "content-length": "170", "date": "Sun, 18 Aug 2024 05:08:11 GMT"}; value: Error { error_code: Some("Not Found"), message: "demo saga with id 1dbc1a62-d748-4b15-8cbb-ae32499389be (demo_saga)", request_id: "9b836ae0-4371-4012-8513-0a64b8626cc5" }
5328	2024-08-18T05:08:11.744Z	stack backtrace:
5329	2024-08-18T05:08:11.744Z	   0: rust_begin_unwind
5330	2024-08-18T05:08:11.744Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5
5331	2024-08-18T05:08:11.744Z	   1: core::panicking::panic_fmt
5332	2024-08-18T05:08:11.744Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14
5333	2024-08-18T05:08:11.745Z	   2: core::result::unwrap_failed
5334	2024-08-18T05:08:11.745Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/result.rs:1679:5
5335	2024-08-18T05:08:11.745Z	   3: unwrap<progenitor_client::progenitor_client::ResponseValue<()>, progenitor_client::progenitor_client::Error<nexus_client::types::Error>>
5336	2024-08-18T05:08:11.745Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/result.rs:1102:23
5337	2024-08-18T05:08:11.745Z	   4: {async_fn#0}
5338	2024-08-18T05:08:11.745Z	             at ./tests/integration_tests/demo_saga.rs:47:5
5339	2024-08-18T05:08:11.745Z	   5: {async_block#0}
5340	2024-08-18T05:08:11.745Z	             at ./tests/integration_tests/demo_saga.rs:21:1
5341	2024-08-18T05:08:11.745Z	   6: poll<&mut dyn core::future::future::Future<Output=()>>
5342	2024-08-18T05:08:11.745Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/future/future.rs:123:9
5343	2024-08-18T05:08:11.745Z	   7: poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
5344	2024-08-18T05:08:11.745Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/future/future.rs:123:9
5345	2024-08-18T05:08:11.745Z	   8: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
5346	2024-08-18T05:08:11.745Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:673:57
5347	2024-08-18T05:08:11.745Z	   9: 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=()>>>>>
5348	2024-08-18T05:08:11.745Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/coop.rs:107:5
5349	2024-08-18T05:08:11.745Z	  10: 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=()>>>>>
5350	2024-08-18T05:08:11.745Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/coop.rs:73:5
5351	2024-08-18T05:08:11.745Z	  11: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
5352	2024-08-18T05:08:11.745Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:673:25
5353	2024-08-18T05:08:11.745Z	  12: tokio::runtime::scheduler::current_thread::Context::enter
5354	2024-08-18T05:08:11.745Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:412:19
5355	2024-08-18T05:08:11.745Z	  13: {closure#0}<core::pin::Pin<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>>
5356	2024-08-18T05:08:11.745Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:672:36
5357	2024-08-18T05:08:11.745Z	  14: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
5358	2024-08-18T05:08:11.745Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:751:68
5359	2024-08-18T05:08:11.746Z	  15: tokio::runtime::context::scoped::Scoped<T>::set
5360	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/context/scoped.rs:40:9
5361	2024-08-18T05:08:11.746Z	  16: tokio::runtime::context::set_scheduler::{{closure}}
5362	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/context.rs:180:26
5363	2024-08-18T05:08:11.746Z	  17: 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<()>)>
5364	2024-08-18T05:08:11.746Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/thread/local.rs:283:12
5365	2024-08-18T05:08:11.746Z	  18: std::thread::local::LocalKey<T>::with
5366	2024-08-18T05:08:11.746Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/thread/local.rs:260:9
5367	2024-08-18T05:08:11.746Z	  19: tokio::runtime::context::set_scheduler
5368	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/context.rs:180:9
5369	2024-08-18T05:08:11.746Z	  20: tokio::runtime::scheduler::current_thread::CoreGuard::enter
5370	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:751:27
5371	2024-08-18T05:08:11.746Z	  21: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
5372	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:660:19
5373	2024-08-18T05:08:11.746Z	  22: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
5374	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:180:28
5375	2024-08-18T05:08:11.746Z	  23: tokio::runtime::context::runtime::enter_runtime
5376	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/context/runtime.rs:65:16
5377	2024-08-18T05:08:11.746Z	  24: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
5378	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/scheduler/current_thread/mod.rs:168:9
5379	2024-08-18T05:08:11.746Z	  25: tokio::runtime::runtime::Runtime::block_on_inner
5380	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/runtime.rs:361:47
5381	2024-08-18T05:08:11.746Z	  26: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
5382	2024-08-18T05:08:11.746Z	             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.2/src/runtime/runtime.rs:335:13
5383	2024-08-18T05:08:11.746Z	  27: test_demo_saga
5384	2024-08-18T05:08:11.746Z	             at ./tests/integration_tests/demo_saga.rs:21:1
5385	2024-08-18T05:08:11.746Z	  28: test_all::integration_tests::demo_saga::test_demo_saga::{{closure}}
5386	2024-08-18T05:08:11.747Z	             at ./tests/integration_tests/demo_saga.rs:22:61
5387	2024-08-18T05:08:11.747Z	  29: core::ops::function::FnOnce::call_once
5388	2024-08-18T05:08:11.747Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5
5389	2024-08-18T05:08:11.747Z	  30: core::ops::function::FnOnce::call_once
5390	2024-08-18T05:08:11.747Z	             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5
5391	2024-08-18T05:08:11.747Z	note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
5392	2024-08-18T05:08:11.747Z	WARN: dropped CockroachInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
5393	2024-08-18T05:08:11.747Z	WARN: temporary directory leaked: "/var/tmp/omicron_tmp/.tmpAmqAKR"
5394	2024-08-18T05:08:11.747Z	If you would like to access the database for debugging, run the following:
5395	2024-08-18T05:08:11.747Z	
5396	2024-08-18T05:08:11.747Z	# Run the database
5397	2024-08-18T05:08:11.747Z	cargo xtask db-dev run --no-populate --store-dir "/var/tmp/omicron_tmp/.tmpAmqAKR/data"
5398	2024-08-18T05:08:11.747Z	# Access the database. Note the port may change if you run multiple databases.
5399	2024-08-18T05:08:11.747Z	cockroach sql --host=localhost:32221 --insecure
5400	2024-08-18T05:08:11.751Z	WARN: dropped ClickHouseInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
5401	2024-08-18T05:08:11.751Z	WARN: dropped DendriteInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
5402	2024-08-18T05:08:11.751Z	WARN: dendrite temporary directory leaked: /var/tmp/omicron_tmp/.tmpioUB6l
5403	2024-08-18T05:08:11.751Z	WARN: dropped DendriteInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
5404	2024-08-18T05:08:11.751Z	WARN: dendrite temporary directory leaked: /var/tmp/omicron_tmp/.tmpzyeLyy
5405	2024-08-18T05:08:11.751Z	WARN: dropped MgdInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
5406	2024-08-18T05:08:11.751Z	WARN: mgd temporary directory leaked: /var/tmp/omicron_tmp/.tmpyOCDKK
5407	2024-08-18T05:08:11.751Z	WARN: dropped MgdInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
5408	2024-08-18T05:08:11.751Z	WARN: mgd temporary directory leaked: /var/tmp/omicron_tmp/.tmpQQic04
5409	2024-08-18T05:08:11.751Z	

[sunshowers]

cc @davepacheco I've seen this test flake out a few times.

[davepacheco]

Sorry for the trouble! I'm working on #6388 to fix this.