Instance state change gets 404 during start saga; Nexus marks VMM as Failed but propolis keeps running. #11560

Activity

1. paudmir commented on Oct 22, 2026

   

   paudmir

   on Oct 22, 2026

   ContributorAuthor

   More actions

   Similar race condition for the core at /staff/dogfood/BRM22250001/omicron-11560/core.oxz_propolis-server_cc50860d-2eea-410e-a820-cbb63a32658e.propolis-server.6245.1792278272
   Stack: https://github.com/oxidecomputer/product-assurance/issues/727#issuecomment-6327701929

   VMM record is deleted and an attempt to reincarnate pops up

   2026-10-17 23:03:42.458Z INFO 61420090-2657-4888-9d57-8f7e36f652a4/4199 (ServerContext) on oxz_nexus_61420090-2657-4888-9d57-8f7e36f652a4: instance update (VMM destroyed): marking VMM record deleted
       instance_id = ab173424-17fa-4e96-8200-4c0d37eb6fa4
       propolis_id = 6bb75bd5-99e9-46ec-93a4-989b421aabf5
       saga_id = 836463a4-42a3-44f4-8beb-c60f7111fd29
       saga_name = instance-update
   2026-10-17 23:03:42.905Z INFO 61420090-2657-4888-9d57-8f7e36f652a4/4199 (ServerContext) on oxz_nexus_61420090-2657-4888-9d57-8f7e36f652a4: attempting to reincarnate instance...
       background_task = instance_reincarnation
       instance_id = ab173424-17fa-4e96-8200-4c0d37eb6fa4
       instance_state = Failed
       last_auto_restarted_at = None
       reincarnation_reason = instance failed
   2026-10-17 23:03:42.945Z WARN 61420090-2657-4888-9d57-8f7e36f652a4/4199 (dropshot_external) on oxz_nexus_61420090-2657-4888-9d57-8f7e36f652a4: request completed after handler was already cancelled
       error_message_external = The instance was running but is no longer reachable. It is being moved to the Failed state.
       error_message_internal = Error Response: status: 404 Not Found; headers: {"content-type": "application/json", "x-request-id": "4d0897e0-f420-43eb-8df6-69da4f017557", "content-length": "120", "date": "Sat, 17 Oct 2026 23:03:26 GMT"}; value: Error { error_code: Some("NO_SUCH_INSTANCE"), message: "Not Found", request_id: "4d08 \u{2026}
       method = POST
       req_id = 57786059-fd7d-49b2-9ce7-c921960e2b2c
       response_code = 503
       uri = /v1/instances/alldisks-instance-main-68346/stop?project=product-assurance
   2026-10-17 23:03:43.151Z INFO 61420090-2657-4888-9d57-8f7e36f652a4/4199 (ServerContext) on oxz_nexus_61420090-2657-4888-9d57-8f7e36f652a4: sled reservation starting
       instance_id = ab173424-17fa-4e96-8200-4c0d37eb6fa4
       propolis_id = bdf6f9c1-243d-446d-97eb-bdb9c260896d
       reservation_reason = start
   2026-10-17 23:03:43.642Z INFO 61420090-2657-4888-9d57-8f7e36f652a4/4199 (dropshot_external) on oxz_nexus_61420090-2657-4888-9d57-8f7e36f652a4: set intended instance state
       instance_id = ab173424-17fa-4e96-8200-4c0d37eb6fa4
       intended_state = stopped
       method = POST
       req_id = 12de76eb-fd3e-4e6b-8914-1b7374a96dd9
       uri = /v1/instances/alldisks-instance-main-68346/stop?project=product-assurance
   

   A minute later, propolis show a YouAreNoLongerActive warning and an error mentioning the scrubbing of volume failed.

   2026-10-17 23:04:30.806Z ERRO propolis-server/6245 (crucible-15f13a6e-4a7d-4537-bd6d-73489f37321d) on oxz_propolis-server_cc50860d-2eea-410e-a820-cbb63a32658e: received NoLongerActive 15f13a6e-4a7d-4537-bd6d-73489f37321d 71712c8d-61a5-419b-927d-f1dcd114f1fd 3
        = downstairs
       client = 2
   2026-10-17 23:04:30.807Z WARN propolis-server/6245 (crucible-15f13a6e-4a7d-4537-bd6d-73489f37321d) on oxz_propolis-server_cc50860d-2eea-410e-a820-cbb63a32658e: saw YouAreNoLongerActive with our gen 2 < 3 and same upstairs UUID
        = downstairs
       client = 2
   2026-10-17 23:04:30.807Z WARN propolis-server/6245 (crucible-15f13a6e-4a7d-4537-bd6d-73489f37321d) on oxz_propolis-server_cc50860d-2eea-410e-a820-cbb63a32658e: disabling clients due to NoLongerActive
   2026-10-17 23:04:30.822Z ERRO propolis-server/6245 (crucible-15f13a6e-4a7d-4537-bd6d-73489f37321d) on oxz_propolis-server_cc50860d-2eea-410e-a820-cbb63a32658e: Scrub of volume 15f13a6e-4a7d-4537-bd6d-73489f37321d failed: Upstairs is not active
   thread 'tokio-rt-vmm' (10) panicked at /home/build/.cargo/git/checkouts/crucible-0a48bd218bc2bbbc/bd62980/upstairs/src/client.rs:853:18:
   8c2fe16b-2342-4eb5-98c2-63ef729aa871 [0] enqueue should not be called from state Connecting { state: WaitConnect, mode: New }
   note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
   

   Zone bundle can be found at /staff/dogfood/BRM22250001/omicron-11560/cc50860d.tar.gz
2. paudmir

   changed the title [-]Instance state change get 404 during start saga; Nexus marks VMM as Failed but propolis keeps running.[/-] [+]Instance state change gets 404 during start saga; Nexus marks VMM as Failed but propolis keeps running.[/+] on Oct 23, 2026
3. hawkw commented on Oct 24, 2026

   

   hawkw

   on Oct 24, 2026

   Member

   More actions

   Do we know what's attempting to stop the instances here? Is it an automated product-assurance thing? Nexus is supposed to fail calls to stop an instance that hasn't started yet, but perhaps we've broken that check somehow.
4. hawkw commented on Oct 24, 2026

   

   hawkw

   on Oct 24, 2026

   Member

   More actions

   I think this logic is probably wrong:

   omicron/nexus/src/app/instance.rs

   Lines 1354 to 1357 in ed9659c

   	| InstanceStateChangeRequest::Reboot
   	| InstanceStateChangeRequest::Stop => match effective_state {
   	InstanceState::Creating
   	| InstanceState::Starting

   What I think is happening here is that we are allowing the stop request through to the sled-agent when the VMM's state is (probably) Creating, because a Creating VMM is represented externally as a Starting instance:

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

   Lines 328 to 337 in ed9659c

   	// - If the instance has a VMM but the VMM is "creating", return
   	// `InstanceState::Starting`, rather than
   	// `InstanceState::Creating`.
   	// If we are still creating the VMM, this is because we are
   	// attempting to *start* the instance; instances may be created
   	// without creating a VMM to run them, and then started later.
   	(
   	InstanceState::Vmm,
   	Some(VmmState::Creating | VmmState::Starting),
   	) => instance::InstanceState::Starting,

   However, when the VMM is Creating, we may not yet have sent an instance-ensure request to the sled-agent to create that VMM, so sled-agent doesn't know it's supposed to have a Propolis process for it yet. In that state, the sled-agent will (correctly) inform Nexus that it doesn't know about that VMM, at which point Nexus will move it to Failed. Only once the VMM has moved to Starting do we know that the sled-agent is aware of it; we should reject requests to stop an instance while the VMM is in the Creating state.
5. hawkw

   added

   bugSomething that isn't working.Something that isn't working.

   nexusRelated to nexusRelated to nexus

   on Oct 24, 2026
6. hawkw

   added the

   Bug

   issue type on Oct 24, 2026
7. paudmir commented on Oct 26, 2026

   

   paudmir

   on Oct 26, 2026

   ContributorAuthor

   More actions

   4. Do we know what's attempting to stop the instances here? Is it an automated product-assurance thing? Nexus is supposed to fail calls to stop an instance that hasn't started yet, but perhaps we've broken that check somehow.

   Yups, this s an automated product-assurance thing :) https://github.com/oxidecomputer/product-assurance/blob/main/pytest_tests/tests/functional/test_all_disk_types.py#L502
8. hawkw commented on Oct 27, 2026

   

   hawkw

   on Oct 27, 2026

   Last edited by hawkw

   Member

   More actions

   Doing some more digging into why the start saga keeps running in this case. I think I know what's going on there too.

   When the VMM has been marked as Failed by the stop request, which bumped its generation number, the subsequent write to the VMM record when the instance-start saga's sis_ensure_registered action tries to advance the VMM from Creating to Starting fails because the generation number has advanced by the transition to Failed. However, when we write the new VMM state here:

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

   Lines 363 to 386 in 5c1b8ba

   	let err = err.clone();
   	let new_runtime = new_runtime.clone();
   	async move {
   	let vmm_update_result = self
   	.vmm_update_runtime_on_connection(
   	&conn,
   	&vmm_id,
   	new_runtime,
   	)
   	.await?;
   	let found_vmm = vmm_update_result.found;
   	let vmm_updated = match vmm_update_result.status {
   	UpdateStatus::Updated => true,
   	UpdateStatus::NotUpdatedButExists => false
   	};
   	let migration_out_updated = match migration_out {
   	Some(migration) => {
   	let r = self.migration_update_source_on_connection(
   	&conn, &vmm_id, migration,
   	)
   	.await?;

   we just...say "okay, it wasn't updated", and don't indicate that it has transitioned to a state that is incompatible with the update we tried to apply. Then, because notify_vmm_updated succeeded, the call to Nexus::instance_ensure_registered here returns a db::model::Vmm that's...synthesized from the state we received from the sled-agent, rather than reflective of what's actually in the DB:

   omicron/nexus/src/app/instance.rs

   Lines 1763 to 1774 in 5c1b8ba

   	Ok(state) => {
   	self.notify_vmm_updated(opctx, *propolis_id, &state).await?;
   	let runtime = state.vmm_state;
   	Ok(db::model::Vmm {
   	time_state_updated: runtime.time_updated,
   	generation: runtime.generation.into(),
   	state: DbVmmState::from(runtime.state),
   	failure_reason: db::model::VmmFailureReason::from_vmm_state(
   	runtime.state,
   	),
   	..initial_vmm.clone()
   	})

   Basically, we are assuming that because notify_vmm_updated did not fail, whatever we were trying to write is actually the instance's state, but because that function returns Ok when the generation number has not advanced (intended to make it idempotent), we are essentially lying about what the state that's been written is. Then, the saga just keeps on going under the assumption that the VMM has advanced to Starting, when it really should unwind since the VMM is now Failed.

   I think notify_vmm_updated and the DataStore::vmm_and_migration_update_runtime function it calls need to return the VmmRuntimeState` in the db, regardless of whether or not the generation has been advanced by that call. That way, the caller can see if the state they were trying to write has made it to the database, and (in the saga case), we can unwind if the VMM has failed or been destroyed.
9. hawkw

   self-assigned this

   on Oct 27, 2026
10. hawkw

    added 4 commits that reference this issue on Oct 27, 2026

    [sled-agent-sim] add a way to interrupt VMM registration

    ...

    46659f7

    [sled-agent-sim] add a way to interrupt VMM registration

    ...

    daae088

    [sled-agent-sim] add a way to interrupt VMM registration

    ...

    19e44ce

    [sled-agent-sim] add a way to interrupt VMM registration (#11606)

    ...

    8a0957c
11. hawkw

    closed this as completedin #11631on Oct 30, 2026
12. hawkw

    added 3 commits that reference this issue on Oct 30, 2026

    [nexus] retry ensuring VMMs are unregistered (#11629)

    ...

    2e9c595

    [nexus] ensure VMMs are unregistered even if register action fails (#…

    ...

    31660f5

    [nexus] unwind instance-start sagas if they race with the VMM going a…

    ...

    778db1c