test failed in CI: `test_migration_source_failed_destroyed_can_unwind`

[jgallagher]

This test failed on a CI run on #8737:

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

Log showing the specific test failure:

https://buildomat.eng.oxide.computer/wg/0/details/01K1TQ4A11CREWBV1GJQZN7WKR/dDpeYeJeu0ea2NU3lvQQGCHxexJEJtpUODSzcDE0Sw0roTkC/01K1TQ4MYXC885GG10HRCDXS1B

Excerpt from the log showing the failure:

 stdout ───

   running 1 test
   test app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind ... FAILED

   failures:

   failures:
       app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind

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

 stderr ───
   log file: /var/tmp/omicron_tmp/omicron_nexus-7d8c6d7d4c95a475-test_migration_source_failed_destroyed_can_unwind.94910.0.log
   note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-7d8c6d7d4c95a475-test_migration_source_failed_destroyed_can_unwind.94910.0.log"
   DB URL: postgresql://root@[::1]:42535/omicron?sslmode=disable
   DB address: [::1]:42535
   log file: /var/tmp/omicron_tmp/omicron_nexus-7d8c6d7d4c95a475-test_migration_source_failed_destroyed_can_unwind.94910.2.log
   note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-7d8c6d7d4c95a475-test_migration_source_failed_destroyed_can_unwind.94910.2.log"
   log file: /var/tmp/omicron_tmp/omicron_nexus-7d8c6d7d4c95a475-test_migration_source_failed_destroyed_can_unwind.94910.3.log
   note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-7d8c6d7d4c95a475-test_migration_source_failed_destroyed_can_unwind.94910.3.log"

   thread 'app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind' panicked at sled-agent/src/sim/collection.rs:274:65:
   called `Result::unwrap()` on an `Err` value: InternalError { internal_message: "Communication Error: error sending request for url (http://127.0.0.1:42165/vmms/d7e136b0-d474-4210-a27b-da80cb782ba7)" }
   stack backtrace:
      0: __rustc::rust_begin_unwind
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:697:5
      1: core::panicking::panic_fmt
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/panicking.rs:75:14
      2: core::result::unwrap_failed
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/result.rs:1732:5
      3: unwrap<(), omicron_common::api::external::error::Error>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/result.rs:1137:23
      4: {async_fn#0}<omicron_sled_agent::sim::instance::SimInstance>
                at /work/oxidecomputer/omicron/sled-agent/src/sim/collection.rs:274:13
      5: {async_fn#0}
                at /work/oxidecomputer/omicron/sled-agent/src/sim/sled_agent.rs:523:58
      6: {async_fn#0}
                at /work/oxidecomputer/omicron/sled-agent/src/sim/http_entrypoints.rs:823:38
      7: {async_block#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>, fn(dropshot::handler::RequestContext<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>, dropshot::extractor::path::Path<sled_agent_api::VmmPathParam>) -> omicron_sled_agent::sim::http_entrypoints::{impl#1}::from::instance_poke_post::{async_fn_env#0}, omicron_sled_agent::sim::http_entrypoints::{impl#1}::from::instance_poke_post::{async_fn_env#0}, dropshot::handler::HttpResponseUpdatedNoContent, dropshot::error::HttpError, dropshot::extractor::path::Path<sled_agent_api::VmmPathParam>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/handler.rs:664:78
      8: poll<alloc::boxed::Box<(dyn core::future::future::Future<Output=core::result::Result<http::response::Response<dropshot::body::Body>, dropshot::handler::HandlerError>> + core::marker::Send), alloc::alloc::Global>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/future/future.rs:124:9
      9: {async_block#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>, fn(dropshot::handler::RequestContext<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>, dropshot::extractor::path::Path<sled_agent_api::VmmPathParam>) -> omicron_sled_agent::sim::http_entrypoints::{impl#1}::from::instance_poke_post::{async_fn_env#0}, (dropshot::extractor::path::Path<sled_agent_api::VmmPathParam>), dropshot::handler::HttpResponseUpdatedNoContent>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/handler.rs:785:16
     10: poll<alloc::boxed::Box<(dyn core::future::future::Future<Output=core::result::Result<http::response::Response<dropshot::body::Body>, dropshot::handler::HandlerError>> + core::marker::Send), alloc::alloc::Global>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/future/future.rs:124:9
     11: {async_block#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.2/src/server.rs:937:69
     12: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/core.rs:365:17
     13: with_mut<tokio::runtime::task::core::Stage<dropshot::server::http_request_handle::{async_fn#0}::{async_block_env#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>>, core::task::poll::Poll<()>, tokio::runtime::task::core::{impl#6}::poll::{closure_env#0}<dropshot::server::http_request_handle::{async_fn#0}::{async_block_env#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>, alloc::sync::Arc<tokio::runtime::scheduler::current_thread::Handle, alloc::alloc::Global>>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/loom/std/unsafe_cell.rs:16:9
     14: poll<dropshot::server::http_request_handle::{async_fn#0}::{async_block_env#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>, alloc::sync::Arc<tokio::runtime::scheduler::current_thread::Handle, alloc::alloc::Global>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/core.rs:354:13
     15: tokio::runtime::task::harness::poll_future::{{closure}}
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/harness.rs:535:19
     16: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/panic/unwind_safe.rs:272:9
     17: do_call<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<dropshot::server::http_request_handle::{async_fn#0}::{async_block_env#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>, alloc::sync::Arc<tokio::runtime::scheduler::current_thread::Handle, alloc::alloc::Global>>>, core::task::poll::Poll<()>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:589:40
     18: __rust_try
     19: try<core::task::poll::Poll<()>, core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<dropshot::server::http_request_handle::{async_fn#0}::{async_block_env#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>, alloc::sync::Arc<tokio::runtime::scheduler::current_thread::Handle, alloc::alloc::Global>>>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:552:19
     20: catch_unwind<core::panic::unwind_safe::AssertUnwindSafe<tokio::runtime::task::harness::poll_future::{closure_env#0}<dropshot::server::http_request_handle::{async_fn#0}::{async_block_env#0}<alloc::sync::Arc<omicron_sled_agent::sim::sled_agent::SledAgent, alloc::alloc::Global>>, alloc::sync::Arc<tokio::runtime::scheduler::current_thread::Handle, alloc::alloc::Global>>>, core::task::poll::Poll<()>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panic.rs:359:14
     21: tokio::runtime::task::harness::poll_future
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/harness.rs:523:18
     22: tokio::runtime::task::harness::Harness<T,S>::poll_inner
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/harness.rs:210:27
     23: tokio::runtime::task::harness::Harness<T,S>::poll
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/harness.rs:155:15
     24: tokio::runtime::task::raw::poll
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/raw.rs:325:5
     25: tokio::runtime::task::raw::RawTask::poll
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/raw.rs:255:18
     26: tokio::runtime::task::LocalNotified<S>::run
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/task/mod.rs:509:9
     27: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:789:25
     28: with_budget<(), tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure#0}::{closure_env#1}<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.47.0/src/task/coop/mod.rs:167:5
     29: budget<(), tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure#0}::{closure_env#1}<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.47.0/src/task/coop/mod.rs:133:5
     30: {closure#0}<(), tokio::runtime::scheduler::current_thread::{impl#8}::block_on::{closure#0}::{closure_env#1}<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.47.0/src/runtime/scheduler/current_thread/mod.rs:368:43
     31: tokio::runtime::scheduler::current_thread::Context::enter
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:432:19
     32: tokio::runtime::scheduler::current_thread::Context::run_task
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:368:23
     33: {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.47.0/src/runtime/scheduler/current_thread/mod.rs:785:35
     34: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:68
     35: tokio::runtime::context::scoped::Scoped<T>::set
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/scoped.rs:40:9
     36: tokio::runtime::context::set_scheduler::{{closure}}
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:26
     37: 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/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/thread/local.rs:315:12
     38: std::thread::local::LocalKey<T>::with
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/thread/local.rs:279:15
     39: tokio::runtime::context::set_scheduler
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:9
     40: tokio::runtime::scheduler::current_thread::CoreGuard::enter
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:27
     41: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:729:19
     42: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:200:28
     43: tokio::runtime::context::runtime::enter_runtime
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/runtime.rs:65:16
     44: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:188:9
     45: tokio::runtime::runtime::Runtime::block_on_inner
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:356:47
     46: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:330:13
     47: test_migration_source_failed_destroyed_can_unwind
                at ./src/app/sagas/instance_update/mod.rs:2209:5
     48: omicron_nexus::app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind::{{closure}}
                at ./src/app/sagas/instance_update/mod.rs:2212:6
     49: core::ops::function::FnOnce::call_once
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/ops/function.rs:250:5
     50: core::ops::function::FnOnce::call_once
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/ops/function.rs:250:5
   note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

   thread 'app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind' panicked at clients/sled-agent-client/src/lib.rs:369:14:
   instance_finish_transition() failed unexpectedly: reqwest::Error { kind: Request, url: "http://[::1]:33095/vmms/d7e136b0-d474-4210-a27b-da80cb782ba7/poke", source: hyper_util::client::legacy::Error(SendRequest, hyper::Error(IncompleteMessage)) }
   stack backtrace:
      0: __rustc::rust_begin_unwind
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/panicking.rs:697:5
      1: core::panicking::panic_fmt
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/panicking.rs:75:14
      2: core::result::unwrap_failed
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/result.rs:1732:5
      3: core::result::Result<T,E>::expect
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/result.rs:1089:23
      4: {async_block#0}
                at /work/oxidecomputer/omicron/clients/sled-agent-client/src/lib.rs:365:9
      5: poll<alloc::boxed::Box<(dyn core::future::future::Future<Output=()> + core::marker::Send), alloc::alloc::Global>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/future/future.rs:124:9
      6: {async_fn#0}
                at ./src/app/sagas/test_helpers.rs:141:38
      7: {async_fn#0}
                at ./src/app/sagas/instance_update/mod.rs:2452:70
      8: {async_fn#0}
                at ./src/app/sagas/instance_update/mod.rs:2332:51
      9: {async_block#0}
                at ./src/app/sagas/instance_update/mod.rs:2367:30
     10: poll<alloc::boxed::Box<(dyn core::future::future::Future<Output=omicron_nexus::app::sagas::instance_update::RealParams> + core::marker::Send), alloc::alloc::Global>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/future/future.rs:124:9
     11: {async_fn#0}<omicron_nexus::app::sagas::instance_update::SagaDoActualInstanceUpdate, omicron_nexus::app::sagas::instance_update::test::{impl#0}::run_unwinding_test::{async_fn#0}::{closure_env#0}, omicron_nexus::app::sagas::instance_update::test::{impl#0}::run_unwinding_test::{async_fn#0}::{closure_env#1}>
                at ./src/app/sagas/test_helpers.rs:597:36
     12: {async_fn#0}
                at ./src/app/sagas/instance_update/mod.rs:2394:14
     13: {async_fn#0}
                at ./src/app/sagas/instance_update/mod.rs:2217:14
     14: {async_block#0}
                at ./src/app/sagas/instance_update/mod.rs:2209:5
     15: poll<&mut dyn core::future::future::Future<Output=()>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/future/future.rs:124:9
     16: poll<&mut core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/future/future.rs:124:9
     17: {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.47.0/src/runtime/scheduler/current_thread/mod.rs:742:54
     18: 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-1949cf8c6b5b557f/tokio-1.47.0/src/task/coop/mod.rs:167:5
     19: 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-1949cf8c6b5b557f/tokio-1.47.0/src/task/coop/mod.rs:133:5
     20: {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.47.0/src/runtime/scheduler/current_thread/mod.rs:742:25
     21: tokio::runtime::scheduler::current_thread::Context::enter
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:432:19
     22: {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.47.0/src/runtime/scheduler/current_thread/mod.rs:741:36
     23: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:68
     24: tokio::runtime::context::scoped::Scoped<T>::set
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/scoped.rs:40:9
     25: tokio::runtime::context::set_scheduler::{{closure}}
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:26
     26: 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/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/thread/local.rs:315:12
     27: std::thread::local::LocalKey<T>::with
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/std/src/thread/local.rs:279:15
     28: tokio::runtime::context::set_scheduler
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context.rs:176:9
     29: tokio::runtime::scheduler::current_thread::CoreGuard::enter
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:829:27
     30: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:729:19
     31: {closure#0}<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:200:28
     32: tokio::runtime::context::runtime::enter_runtime
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/context/runtime.rs:65:16
     33: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/scheduler/current_thread/mod.rs:188:9
     34: tokio::runtime::runtime::Runtime::block_on_inner
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:356:47
     35: block_on<core::pin::Pin<&mut dyn core::future::future::Future<Output=()>>>
                at /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.47.0/src/runtime/runtime.rs:330:13
     36: test_migration_source_failed_destroyed_can_unwind
                at ./src/app/sagas/instance_update/mod.rs:2209:5
     37: omicron_nexus::app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind::{{closure}}
                at ./src/app/sagas/instance_update/mod.rs:2212:6
     38: core::ops::function::FnOnce::call_once
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/ops/function.rs:250:5
     39: core::ops::function::FnOnce::call_once
                at /rustc/6b00bc3880198600130e1cf62b8f8a93494488cc/library/core/src/ops/function.rs:250:5

[jgallagher]

Seen again on #9291: https://buildomat.eng.oxide.computer/wg/0/details/01K9A98CFY3YS3YXC7G2T9ZGYW/s0sPXum7qa0kAtbXvBKijf3G4ybi4o2utolvWY9GaQVWe4zS/01K9A98VAPF4KTFH45VWV4NP51

[hawkw]

Welp, this is one of my tests, but the failure sure doesn't look directly related to the test code. It looks like we're seeing an error from Hyper indicating that it couldn't parse an HTTP message:

   thread 'app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind' panicked at clients/sled-agent-client/src/lib.rs:369:14:
   instance_finish_transition() failed unexpectedly: reqwest::Error { kind: Request, url: "http://[::1]:33095/vmms/d7e136b0-d474-4210-a27b-da80cb782ba7/poke", source: hyper_util::client::legacy::Error(SendRequest, hyper::Error(IncompleteMessage)) }

Which feels weird!

[bnaecker]

I hit this again here on #11074

[smklein]

Okay let me try to break down a hypothesis, for the case where this test fails with:

thread 'app::sagas::instance_update::test::test_migration_source_failed_destroyed_can_unwind' (2) panicked at nexus/db-model/src/vmm_state.rs:364:17:
assertion `left == right` failed: if the instance state is not `InstanceState::Vmm`, there should be no VMM state
left: Some(Migrating)
right: None

I see y'all commenting that there are potentially also issues with Hyper here, about parsing HTTP messages - I dunno about that. Sorry! Just commenting on the other failure mode I'm seeing here.

what is the test doing

The test is setting up:

• A source VMM with "MigrationState::Failed" and a "NexusVmmState::Destroyed"
• A target VMM with "MigrationState::InProgress", and a "NexusVmmState::Running"

then it invokes a helper run_unwinding_test, which calls action_failure_can_unwind for the SagaDoActualInstanceUpdate saga. This injects failures triggering unwind for every node in the saga DAG, and also runs some setup (for before) and checks (for after).

In this test, the "after-saga-unwinds" cleanup helper (called, unsurprisingly, after_unwinding) also does some database manipulation to get the instance ready for the next request: it (1) calls instance_update_runtime to force the instance into state NoVmm, and clears out the propolis_id/dst_propolis_id/migration_id columns, all as setup to... (2) delete the instance.

So: we have a test which messes with instance state, then manually tweaks it so it can be deleted. But the test cleanup is not touching VMM rows at all.

meanwhile, as you know, background tasks

So the instance_watcher background task is invoking instance_and_vmm_list_by_sled_agent, and reaching out to VMMs, to query for their states, and call process_vmm_update with any new information about them.

Notably, as @sunshowers discovered, this instance_and_vmm_list_by_sled_agent can return VMMs for instances that have been deleted, because we do not filter down to instance_dsl::time_deleted.is_null() when enumerating the instance/vmm combos.

When the instance_watcher gets data back from VMMs on sled agents, it uses InstanceStateComputer::compute_state_from to decide what the VMM state should be. And this function is a giant match statement of instance_state x vmm_state, for which some combinations cause debug assertion errors. In this case, the assertion says that we're in vmm_state = Migrating (unfortunately we aren't logging the instance_state - but it's probably Destroyed).

putting it together

• If the test creates a target VMM (database state: running, sled agent state: migrating)
• ... and then tries to clean up in after_unwinding by deleting the instance
• ... AND ALSO the instance_watcher background task runs, and can see this instance/VMM pair
• ... then we have a scenario where: "instance = Destroyed, sled-agent-queried-vmm = migrating"
• ... which triggers this exact assertion error

blame game?

So there are a couple different axes of blame we could assign here. IMO this is nuanced.

"instance_and_vmm_list_by_sled_agent should not be returning VMMs for deleted instances!" -> Okay, so, I understand the desire to properly filter for time_deleted.is_null() - but I wonder if this means that the instance watcher would actually be prevented from ever seeing cases like this, where an orphaned VMM should be moved into a failed/deleted state, but it is not currently, for whatever reason. If we think: "that should never happen in prod", then sure, we could set this extra filter. However, right now, this is (accidentally?) acting as a guard against an instance getting deleted and orphaning a non-failed VMM -- the query + background task would notice the VMM, mark it as failed, and allow it to clean up.

"maybe the instance_watcher should be responsible for filtering out instances that fall outside the bucket of InstanceState::Vmm, and handle them accordingly" -> this seems kinda reasonable to me? It basically sets up the instance_watcher to cope with a broader swathe of possible states, regardless of how they showed up?

"test cleanup seems broken here" -> Sure - we wouldn't have been able to delete this instance normally, so, yeah, agreed that we could clean this up. However, I do think it's possible that we could still trigger this issue in the watcher in situations where the VMM reports that it is "failed", then we delete the instance record, then instance_watcher runs again.

[hawkw]

Hmm, yeah, this is all kind of a mess. I think I agree with @smklein's analysis overall. Regarding the "blame game"/what should we do about it, though, I have some thoughts.

First of all, I do think it's important that this is a situation that the control plane should not let you get into outside of the test, since deleting an instance record through the API checks that it is either Stopped (InstanceState::NoVmm) or that the vmm record is Failed. See project_delete_instance which enforces these states:

omicron/nexus/db-queries/src/db/datastore/instance.rs

Lines 1361 to 1376 in 6db4c7e

	pub async fn project_delete_instance(
	&self,
	opctx: &OpContext,
	authz_instance: &authz::Instance,
	) -> DeleteResult {
	// This is subject to change, but for now we're going to say that an
	// instance must be "stopped" or "failed" in order to delete it. The
	// delete operation sets "time_deleted" (just like with other objects)
	// and also sets the state to "destroyed".
	self.project_delete_instance_in_states(
	&opctx,
	authz_instance,
	&[InstanceState::NoVmm, InstanceState::Failed],
	)
	.await
	}

So I'm pretty sure that this can't happen when normally deleting instances. This is IMO kind of the test's fault for not going through the path that doesn't allow this to happen, and not cleaning up the VMM records.

Re:

"test cleanup seems broken here" -> Sure - we wouldn't have been able to delete this instance normally, so, yeah, agreed that we could clean this up. However, I do think it's possible that we could still trigger this issue in the watcher in situations where the VMM reports that it is "failed", then we delete the instance record, then instance_watcher runs again.

Hm, I think the scenario you're describing here is possible, but I'm not convinced it should be possible. The query that instance_watcher runs, instance_and_vmm_list_by_sled_agent, explicitly filters out instances where the VMM is not running (VmmState::NONEXISTENT_STATES):

omicron/nexus/db-queries/src/db/datastore/instance.rs

Lines 1015 to 1019 in 6db4c7e

	// Ignore VMMs which are in states that are not known to exist on a
	// sled. Since this query drives instance-watcher health checking,
	// it is not necessary to perform health checks for VMMs that don't
	// actually exist in real life.
	.filter(vmm_dsl::state.ne_all(VmmState::NONEXISTENT_STATES));

NONEXISTENT_STATES doesn't currently include Failed:

omicron/nexus/db-model/src/vmm_state.rs

Lines 87 to 92 in 6db4c7e

	/// States in which a VMM record is present in the database but is not
	/// resident on a sled, either because it does not yet exist, was produced
	/// by an unwound update saga and will never exist, or has already been
	/// destroyed.
	pub const NONEXISTENT_STATES: &'static [Self] =
	&[Self::Creating, Self::SagaUnwound, Self::Destroyed];

but I'm not convinced this is right. I'm not sure why we would want the instance watcher task to continue health checking a Failed VMM, since that should be a terminal state in which the VMM process no longer exists.

So, my take is that I think we should fix the test, and make instance_watcher ignore instances where the active VMM is Failed. There's a different task (instance_watcher) whose job it is to start update sagas to ensure that the Failed VMM is propagated to the instance record's state.

[sunshowers]

@hawkw @smklein I asked claude to write me a reproducer for how we can get to this state in production, and it came up with #11101. So I don't think just ignoring this in instance_watcher is correct.

[hawkw]

@sunshowers FWIW, my suggestion was not that we should just fix the test and ignore this state in production, it was that we should fix the test and change the query to ignore instances that have active VMMs that are already Failed. I'll have to take a closer look at the reproducer to see if that's sufficient to handle the case it's simulating or if there's an unrelated thing I've overlooked here. In any case it's probably worth having the additional test though!

[hawkw]

Oh, okay, I see the problem that @sunshowers' test reproduces: we currently allow an instance to be stopped if it's active VMMs has Failed, even if it still has a migration target VMM that's in the Migrating state. I think this scenario can occur if the source VMM crashes after the migration has completed successfully but before the migration target VMM has informed Nexus of that fact.

This is a real bug, and we should fix it. However, I don't think this is really related to the instance_watcher task at all, and I think that (since instance watcher does not currently health check migration targets) the change to make it skip instances whose active VMM has already Failed is still the right solution there...but it also won't fix the handling of stop requests when an instance is mid-migration. I'll add that I think this issue has worse consequences than just producing an instance state combination that hits a debug assertion, since in real life, it would mean that we have leaked the migration target VMM which will keep running forever and cannot be stopped (since the instance "is already Stopped" from Nexus' perspective).

I think the handling of stop requests during a migration probably deserves its own issue. We should probably either not allow the instance to be stopped until the migration has resolved (the easy way out) or make sure that we stop both the current active VMM and the migration target, and that we don't transition to NoVmm if there is still an active migration target, and wait in Stopping until it also reports that it has stopped (in the update saga).

[hawkw]

I think the handling of stop requests during a migration probably deserves its own issue. We should probably either not allow the instance to be stopped until the migration has resolved (the easy way out) or make sure that we stop both the current active VMM and the migration target, and that we don't transition to NoVmm if there is still an active migration target, and wait in Stopping until it also reports that it has stopped (in the update saga).

Heh. Looking at the current code, of course we allow Migrating instances to be stopped:

omicron/nexus/src/app/instance.rs

Line 1357 in 9a27657

| InstanceState::Migrating => true,

...but we don't actually make any attempt to tell the migration target VMM to stop; we just try to stop the active VMM:

omicron/nexus/src/app/instance.rs

Lines 1388 to 1456 in 9a27657

	pub(crate) async fn instance_request_state(
	&self,
	opctx: &OpContext,
	prev_instance_state: &db::model::Instance,
	prev_vmm_state: &Option<db::model::Vmm>,
	requested: InstanceStateChangeRequest,
	) -> Result<(), InstanceStateChangeError> {
	match self.select_runtime_change_action(
	prev_instance_state,
	prev_vmm_state,
	&requested,
	)? {
	InstanceStateChangeRequestAction::AlreadyDone => Ok(()),
	InstanceStateChangeRequestAction::UpdateRuntime(new_runtime) => {
	let instance_id =
	InstanceUuid::from_untyped_uuid(prev_instance_state.id());
	let changed = self
	.datastore()
	.instance_update_runtime(&instance_id, &new_runtime)
	.await
	.map_err(InstanceStateChangeError::Other)?;
	if !changed {
	// TODO(eliza): perhaps we should refetch the instance here
	// and return Ok if it was in the desired state...
	Err(InstanceStateChangeError::Other(Error::conflict(
	"The instance was previously in a state that allowed \
	the requested state change, but the instance's state \
	changed before the request could be completed",
	)))
	} else {
	Ok(())
	}
	}
	InstanceStateChangeRequestAction::SendToSled {
	sled_id,
	propolis_id,
	} => {
	let sa = self.sled_client(&sled_id).await?;
	let instance_put_result = sa
	.vmm_put_state(
	&propolis_id,
	&VmmPutStateBody { state: requested.into() },
	)
	.await
	.map(|res| res.into_inner().updated_runtime.map(Into::into))
	.map_err(|e| SledAgentInstanceError(e));
	// If the operation succeeded, write the instance state back,
	// returning any subsequent errors that occurred during that
	// write.
	//
	// If the operation failed, kick the sled agent error back up to
	// the caller to let it decide how to handle it.
	//
	// When creating the zone for the first time, we just get
	// Ok(None) here, in which case, there's nothing to write back.
	match instance_put_result {
	Ok(Some(ref state)) => self
	.notify_vmm_updated(opctx, propolis_id, state)
	.await
	.map_err(Into::into),
	Ok(None) => Ok(()),
	Err(e) => Err(InstanceStateChangeError::SledAgent(e)),
	}
	}
	}
	}

I think whether or not this is correct depends on what the actual propolis-servers will do in a situation where we just tell the active VMM to stop. Does that get queued after the migration completes, or does it cause the migration source VMM to tell the migration target VMM that it has to stop? Determining this will answer whether our handling of stopping a migrating VM is totally wrong in all cases, or if it's just the "active VMM failed before the target informs us that the migration completed" case that's wrong.

[hawkw]

Okay, hold up a second. I re-read Rain/Claude's test from #11101 and it turns out that what it's actually triggering is something much stupider than I thought. instance_watcher's query JOINs instance and vmm records on the instance's ID being the same as the vmm's instance_id, so it doesn't actually care about whether the VMM it's talking to is the active or migration target VMM. But, in #10580, I changed instance_watcher to use InstanceStateComputer to determine the InstanceState corresponding to an observed VMM state. The problem is that InstanceStateComputer assumes that the provided VMM state is that of the active VMM, and not a migration target VMM, so it hits the assertion because the target VMM still says it's Migrating. That's dumb.

With that said, I think the fix for this is probably still that we shouldn't allow the instance to be moved to NoVmm until both the target and active VMMs are gone.

[hawkw]

Okay, hold up a second. I re-read Rain/Claude's test from #11101 and it turns out that what it's actually triggering is something much stupider than I thought. instance_watcher's query JOINs instance and vmm records on the instance's ID being the same as the vmm's instance_id, so it doesn't actually care about whether the VMM it's talking to is the active or migration target VMM. But, in #10580, I changed instance_watcher to use InstanceStateComputer to determine the InstanceState corresponding to an observed VMM state. The problem is that InstanceStateComputer assumes that the provided VMM state is that of the active VMM, and not a migration target VMM, so it hits the assertion because the target VMM still says it's Migrating. That's dumb.

I think that this stupid problem may have an equally stupid solution, actually: as I mentioned, PR #10580 changed the code in instance_watcher to use InstanceStateComputer as it was previously using a dumb From implementation to determine the state based on a VMM observation that generated the wrong states, and which I removed. It occurs to me that really, we could just always say that the instance state is Vmm when calling into the InstanceStateComputer in instance_watcher, since what that code is really trying to do is "what is the external API InstanceState that would correspond to this VmmState" in order to label metrics and determine if the instance needs an update saga. So we don't actually need to use the real instance state here. That would solve the problem of crashing upon seeing a migration target VMM for an instance that has no active VMM.

But again, I think we need to make sure that we aren't actually leaking the migration target VMM if something like this happens in real life. Which we cannot adequately test with the sled-agent simulator.

[smklein]

Okay, summarizing this, because I think there are multiple issues here, and I'd like to file them separately:

1. The original flake stands as-is, independent of all this discussion about migration.
2. The issue rain found: instance_watcher can pass non-active VMM states to InstanceStateComputer. This happened to be triggered in her test with a setup using migrations. As @hawkw suggested, we could always pass an instance state of Vmm here, rather than than using the instance record.
3. Stopping an instance mid-migration can leak the target VMM. This is what @hawkw called out - nexus allows Migrating instances to stop, but only tells the active VMM to stop (and does nothing to the target). It's also pretty coupled with the question of "What does real propolis do when told to stop mid-migration".

I can update #11100 to fix both (1) and (2), but (3) should probably be its own issue.

Does that cover all the loose threads we've found so far?