test failed in CI: omicron-omdb::test_all_output test_omdb_success_cases

[hawkw]

This test failed on a CI run on pull request #6541.

Log showing the specific test failure:

https://buildomat.eng.oxide.computer/wg/0/details/01J76SDJMRSAKXDSCDB937HA7W/HHiBDL096VXGcptoEmeZYVs0fOREFldEtGAm1fVPnfzCKYF8/01J76SDWEK961ZM8FDZSAAQK5T#S5326

Excerpt from the log showing the failure:

        FAIL [  27.348s] omicron-omdb::test_all_output test_omdb_success_cases

--- STDOUT:              omicron-omdb::test_all_output test_omdb_success_cases ---

running 1 test
running commands with args: ["db", "disks", "list"]
running commands with args: ["db", "dns", "show"]
running commands with args: ["db", "dns", "diff", "external", "2"]
running commands with args: ["db", "dns", "names", "external", "2"]
running commands with args: ["db", "instances"]
running commands with args: ["db", "reconfigurator-save", "/var/tmp/omicron_tmp/.tmpR2fILx/reconfigurator-save.out"]
running commands with args: ["db", "sleds"]
running commands with args: ["db", "sleds", "-F", "discretionary"]
running commands with args: ["mgs", "inventory"]
running commands with args: ["nexus", "background-tasks", "doc"]
running commands with args: ["nexus", "background-tasks", "show"]
running commands with args: ["nexus", "background-tasks", "show", "saga_recovery"]
running commands with args: ["nexus", "background-tasks", "show", "blueprint_loader", "blueprint_executor"]
running commands with args: ["nexus", "background-tasks", "show", "dns_internal"]
running commands with args: ["nexus", "background-tasks", "show", "dns_external"]
running commands with args: ["nexus", "background-tasks", "show", "all"]
running commands with args: ["nexus", "sagas", "list"]
running commands with args: ["--destructive", "nexus", "sagas", "demo-create"]
running commands with args: ["nexus", "sagas", "list"]
running commands with args: ["--destructive", "nexus", "background-tasks", "activate", "inventory_collection"]
running commands with args: ["nexus", "blueprints", "list"]
running commands with args: ["nexus", "blueprints", "show", "a6d89be3-2cdd-40a4-8183-445b3f76ee84"]
running commands with args: ["nexus", "blueprints", "show", "current-target"]
running commands with args: ["nexus", "blueprints", "diff", "a6d89be3-2cdd-40a4-8183-445b3f76ee84", "current-target"]
@@ -90,10 +90,13 @@
  sim-b6d65341  [::1]:REDACTED_PORT  scrimlet  in service  active  ..........<REDACTED_UUID>...........
 ---------------------------------------------
 stderr:
 note: using database URL postgresql://root@[::1]:REDACTED_PORT/omicron?sslmode=disable
 note: database schema version matches expected (<redacted database version>)
+thread 'tokio-runtime-worker' panicked at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-bb8-diesel-0.2.1/src/async_traits.rs:97:14:
+called `Result::unwrap()` on an `Err` value: JoinError::Cancelled(Id(39))
+note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
 =============================================
 EXECUTING COMMAND: omdb ["mgs", "inventory"]
 termination: Exited(0)
 ---------------------------------------------
 stdout:

test test_omdb_success_cases ... FAILED

failures:

failures:
    test_omdb_success_cases

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 2 filtered out; finished in 27.00s


--- STDERR:              omicron-omdb::test_all_output test_omdb_success_cases ---
log file: /var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_cases.19955.0.log
note: configured to log to "/var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_cases.19955.0.log"
DB URL: postgresql://root@[::1]:34453/omicron?sslmode=disable
DB address: [::1]:34453
log file: /var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_cases.19955.2.log
note: configured to log to "/var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_cases.19955.2.log"
log file: /var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_cases.19955.3.log
note: configured to log to "/var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_cases.19955.3.log"
log file: /var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_case.19955.4.log
note: configured to log to "/var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_case.19955.4.log"
thread 'test_omdb_success_cases' panicked at dev-tools/omdb/tests/test_all_output.rs:242:5:
assertion failed: string doesn't match the contents of file: "tests/successes.out" see diffset above
                set EXPECTORATE=overwrite if these changes are intentional
stack backtrace:
   0: rust_begin_unwind
             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/panicking.rs:652:5
   1: core::panicking::panic_fmt
             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/panicking.rs:72:14
   2: assert_contents<&str>
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/expectorate-1.1.0/src/lib.rs:64:9
   3: {async_fn#0}
             at ./tests/test_all_output.rs:242:5
   4: {async_block#0}
             at ./tests/test_all_output.rs:116:1
   5: poll<&mut dyn core::future::future::Future<Output=()>>
             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/future/future.rs:123:9
   6: poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/future/future.rs:123:9
   7: {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-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:673:57
   8: 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/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:107:5
   9: 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/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/coop.rs:73:5
  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-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:673:25
  11: tokio::runtime::scheduler::current_thread::Context::enter
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:412:19
  12: {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-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:672:36
  13: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:751:68
  14: tokio::runtime::context::scoped::Scoped<T>::set
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/scoped.rs:40:9
  15: tokio::runtime::context::set_scheduler::{{closure}}
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:26
  16: 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/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/thread/local.rs:283:12
  17: std::thread::local::LocalKey<T>::with
             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/std/src/thread/local.rs:260:9
  18: tokio::runtime::context::set_scheduler
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context.rs:180:9
  19: tokio::runtime::scheduler::current_thread::CoreGuard::enter
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:751:27
  20: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:660:19
  21: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:180:28
  22: tokio::runtime::context::runtime::enter_runtime
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/context/runtime.rs:65:16
  23: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/scheduler/current_thread/mod.rs:168:9
  24: tokio::runtime::runtime::Runtime::block_on_inner
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/runtime.rs:361:47
  25: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
             at /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.39.3/src/runtime/runtime.rs:335:13
  26: test_omdb_success_cases
             at ./tests/test_all_output.rs:116:1
  27: test_all_output::test_omdb_success_cases::{{closure}}
             at ./tests/test_all_output.rs:117:70
  28: core::ops::function::FnOnce::call_once
             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/library/core/src/ops/function.rs:250:5
  29: core::ops::function::FnOnce::call_once
             at /rustc/3f5fd8dd41153bc5fdca9427e9e05be2c767ba23/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/.tmpONBmQt"
	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/.tmpONBmQt/data"
	# Access the database. Note the port may change if you run multiple databases.
	cockroach sql --host=localhost:32221 --insecure
WARN: dropped ClickHouseInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
failed to clean up ClickHouse data dir:
- /var/tmp/omicron_tmp/test_all_output-19380a1e3eacd977-test_omdb_success_cases.19955.1-clickhouse-2f2yqq: File exists (os error 17)
WARN: dropped DendriteInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
WARN: dendrite temporary directory leaked: /var/tmp/omicron_tmp/.tmpbDrpvz
WARN: dropped DendriteInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
WARN: dendrite temporary directory leaked: /var/tmp/omicron_tmp/.tmpIPi8ZB
WARN: dropped MgdInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
WARN: mgd temporary directory leaked: /var/tmp/omicron_tmp/.tmpCbz2cz
WARN: dropped MgdInstance without cleaning it up first (there may still be a child process running and a temporary directory leaked)
WARN: mgd temporary directory leaked: /var/tmp/omicron_tmp/.tmpsRdqcy

It looks like a Tokio task was cancelled for...some kind of reason, which is sketching me out a bit. This failure threw me for a bit of a loop because PR #6541 does change OMDB output, so I briefly thought that the test failure was actually telling me I'd forgotten to update the expected output, but that's pretty clearly not the case.

[davepacheco]

Looks like a dup of #6505? #6516 should help catch this...

[hawkw]

Closing this as a duplicate of #6505.