Instance stuck in starting on dogfood

[iximeow]

i tried to create an instance on dogfood after updating this week and it ended up stuck in Starting.

switch 0 on dogfood seems in some kind of nebulous unhappy state (issue to come: short of it, we accidentally filled the switch zone with a core file when copying an old one out, and everything there went sideways), but separately the instance-start saga for this instance seems stuck in instance_start.dpd_ensure:

root@oxz_switch1:~# /tmp/omdb-saga db sagas show 727d4812-9383-4df3-985b-0c1bce68d5ad
note: database URL not specified.  Will search DNS.
note: (override with --db-url or OMDB_DB_URL)
note: using DNS server for subnet fd00:1122:3344::/48
note: (if this is not right, use --dns-server to specify an alternate DNS server)
note: using database URL postgresql://root@[fd00:1122:3344:109::3]:32221,[fd00:1122:3344:105::3]:32221,[fd00:1122:3344:10b::3]:32221,[fd00:1122:3344:107::3]:32221,[fd00:1122:3344:108::3]:32221/omicron?sslmode=disable
WARN: found schema version 144.0.0, expected 7.0.0
It's possible the database is running a version that's different from what this
tool understands.  This may result in errors or incorrect output.
 id                                   | time_created                   | name           | state
--------------------------------------+--------------------------------+----------------+--------------------------
 727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.112472 UTC | instance-start | SagaCachedState(Running)

                             saga id | event time                     | node id                                  | event type | data
------------------------------------ | ------------------------------ | ---------------------------------------- | ---------- | ---
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.120631 UTC |  10: start                               | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.126739 UTC |  10: start                               | succeeded  |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.130584 UTC |   0: instance_start.generate_propolis_id | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.134919 UTC |   0: instance_start.generate_propolis_id | succeeded  | "b5bf8281-09fc-43e1-b12c-c91c0bb18543"
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.138944 UTC |   1: instance_start.alloc_server         | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.179417 UTC |   1: instance_start.alloc_server         | succeeded  | "b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88"
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.183787 UTC |   2: instance_start.alloc_propolis_ip    | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.193104 UTC |   2: instance_start.alloc_propolis_ip    | succeeded  | "fd00:1122:3344:106::1:9b7"
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.196560 UTC |   3: instance_start.create_vmm_record    | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.205571 UTC |   3: instance_start.create_vmm_record    | succeeded  | {"id":"b5bf8281-09fc-43e1-b12c-c91c0bb18543","instance_id":"bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4","propolis_ip":"fd00:1122:3344:106::1:9b7/128","propolis_port":12400,"runtime":{"gen":1,"state":"Creating","time_state_updated":"2025-05-23T00:24:21.200216Z"},"sled_id":"b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88","time_created":"2025-05-23T00:24:21.200216Z","time_deleted":null}
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.208748 UTC |   4: instance_start.mark_as_starting     | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.314530 UTC |   4: instance_start.mark_as_starting     | succeeded  | {"auto_restart":{"cooldown":null,"policy":null},"boot_disk_id":null,"hostname":"ixi-600g-mem","identity":{"description":"beeeeeg memory (shouldn't panic a sled, probably)","id":"bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4","name":"ixi-600g-mem","time_created":"2025-05-23T00:24:19.204040Z","time_deleted":null,"time_modified":"2025-05-23T00:24:19.204040Z"},"intended_state":"Running","memory":644245094400,"ncpus":2,"project_id":"9c4152f9-4317-4269-9018-66142964d21c","runtime_state":{"dst_propolis_id":null,"gen":3,"migration_id":null,"nexus_state":"Vmm","propolis_id":"b5bf8281-09fc-43e1-b12c-c91c0bb18543","time_last_auto_restarted":null,"time_updated":"2025-05-23T00:24:19.204040Z"},"updater_gen":1,"updater_id":null,"user_data":[]}
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.318499 UTC |   5: instance_start.dpd_ensure           | started    |

very unfortunately, enough of the instance's state was determined that we started by looking for a Propolis issue, and came up blank for a while even though it looks convincing from omdb:

root@oxz_switch1:~# omdb db instance info bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
note: database URL not specified.  Will search DNS.
note: (override with --db-url or OMDB_DB_URL)
note: using DNS server for subnet fd00:1122:3344::/48
note: (if this is not right, use --dns-server to specify an alternate DNS server)
note: using database URL postgresql://root@[fd00:1122:3344:109::3]:32221,[fd00:1122:3344:105::3]:32221,[fd00:1122:3344:10b::3]:32221,[fd00:1122:3344:107::3]:32221,[fd00:1122:3344:108::3]:32221/omicron?sslmode=disable
note: database schema version matches expected (144.0.0)

== INSTANCE ====================================================================
                        ID: bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
                project ID: 9c4152f9-4317-4269-9018-66142964d21c
                      name: ixi-600g-mem
               description: beeeeeg memory (shouldn't panic a sled, probably)
                created at: 2025-05-23 00:24:19.204040 UTC
          last modified at: 2025-05-23 00:24:19.204040 UTC

== CONFIGURATION ===============================================================
                     vCPUs: 2
                    memory: 600 GiB
                  hostname: ixi-600g-mem
                 boot disk: None
              auto-restart:
                  InstanceAutoRestart {
                      policy: None,
                      cooldown: None,
                  }

== RUNTIME STATE ===============================================================
               nexus state: Vmm
(i)     external API state: Starting
            intended state: running
           last updated at: 2025-05-23T00:24:19.204040Z (generation 3)
       needs reincarnation: false
             karmic status: saṃsāra (reincarnation enabled)
      last reincarnated at: None
             active VMM ID: Some(b5bf8281-09fc-43e1-b12c-c91c0bb18543)
             target VMM ID: None
              migration ID: None
              updater lock: UNLOCKED at generation: 1

== ACTIVE VMM ==================================================================
                        ID: b5bf8281-09fc-43e1-b12c-c91c0bb18543
               instance ID: bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
                created at: 2025-05-23 00:24:21.200216 UTC
                     state: creating
                updated at: 2025-05-23T00:24:21.200216Z (generation 1)
          propolis address: fd00:1122:3344:106::1:9b7:12400
                   sled ID: b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88

at the very least, we probably should have timed out and failed the instance start at some point?

[iximeow]

we collected logs about this instance here with pilot host exec -c 'grep -h bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4 $(/opt/oxide/oxlog/oxlog logs oxz_nexus* --archived -A=-1h) | grep -v <my IP> | looker' 8 > /tmp/instance_logs. in this case, the Nexus of interest happens to be on sled 8, which is also the Nexus that happens to serve console traffic. so, grep -v <my IP> to exclude my console tab polling Nexus for state about the instance which we're also trying to debug.

the tail of those logs then:

00:24:21.321Z INFO 65a11c18-7f59-41ac-b9e7-680627f996e7 (ServerContext): start saga: ensuring instance dpd configuration
    file = nexus/src/app/sagas/instance_start.rs:482
    instance_id = bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
    saga_id = 727d4812-9383-4df3-985b-0c1bce68d5ad
    saga_name = instance-start
    start_reason = AutoStart
00:24:21.330Z INFO 65a11c18-7f59-41ac-b9e7-680627f996e7 (ServerContext): looking up instance's primary network interface
    file = nexus/src/app/instance_network.rs:271
    instance_id = bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
00:24:21.360Z DEBG 65a11c18-7f59-41ac-b9e7-680627f996e7 (ServerContext): authorize result
    action = ListChildren
    actor = Some(Actor::SiloUser { silo_user_id: c535df7e-e84a-4e21-8a2a-95c1d2a1e647, silo_id: 7bd7623a-68ed-4636-8ecb-b59e3b068787, .. })
    actor_id = c535df7e-e84a-4e21-8a2a-95c1d2a1e647
    authenticated = true
    resource = Instance { parent: Project { parent: Silo { parent: Fleet, key: 7bd7623a-68ed-4636-8ecb-b59e3b068787, lookup_type: ById(7bd7623a-68ed-4636-8ecb-b59e3b068787) }, key: 9c4152f9-4317-4269-9018-66142964d21c, lookup_type: ById(9c4152f9-4317-4269-9018-66142964d21c) }, key: bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4, lookup_type: ById(bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4) }
    result = Ok(())
    saga_id = 727d4812-9383-4df3-985b-0c1bce68d5ad
    saga_name = instance-start
    saga_node = DpdEnsure
00:24:21.380Z DEBG 65a11c18-7f59-41ac-b9e7-680627f996e7 (ServerContext): authorize result
    action = ListChildren
    actor = Some(Actor::SiloUser { silo_user_id: c535df7e-e84a-4e21-8a2a-95c1d2a1e647, silo_id: 7bd7623a-68ed-4636-8ecb-b59e3b068787, .. })
    actor_id = c535df7e-e84a-4e21-8a2a-95c1d2a1e647
    authenticated = true
    resource = Instance { parent: Project { parent: Silo { parent: Fleet, key: 7bd7623a-68ed-4636-8ecb-b59e3b068787, lookup_type: ById(7bd7623a-68ed-4636-8ecb-b59e3b068787) }, key: 9c4152f9-4317-4269-9018-66142964d21c, lookup_type: ById(9c4152f9-4317-4269-9018-66142964d21c) }, key: bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4, lookup_type: ById(bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4) }
    result = Ok(())
    saga_id = 727d4812-9383-4df3-985b-0c1bce68d5ad
    saga_name = instance-start
    saga_node = DpdEnsure
00:24:21.426Z INFO 65a11c18-7f59-41ac-b9e7-680627f996e7 (ServerContext): looking up instance's external IPs
    file = nexus/src/app/instance_network.rs:308
    instance_id = bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
00:24:21.456Z DEBG 65a11c18-7f59-41ac-b9e7-680627f996e7 (ServerContext): notifying dendrite of updates
    instance_id = Some(bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4 (instance))
    switch = switch0

where this saga getting stuck trying to notify Dendrite on switch = switch0 is what led us to the relationship between the unhappy switch zone observed above and this stuck saga.

[iximeow]

... of course, trying to stop the instance does nothing good. it seems that perhaps it did begin an attempt to stop the instance, though. we see at 01:57:25 that sled-agent returned a 404 about the instance:

01:57:25.742Z INFO 20b100d0-84c3-4119-aa9b-0c632b0b6a3a (ServerContext): sled-agent error indicates that this instance's VMM has failed!
    background_task = instance_watcher
    error = Error Response: status: 404 Not Found; headers: {"content-type": "application/json", "x-request-id": "6c6e4edb-bd5e-4d52-acfe-be532fd8e608", "content-length": "120", "date": "Fri, 23 May 2025 01:57:25 GMT"}; value: Error { error_code: Some("NO_SUCH_INSTANCE"), message: "Not Found", request_id: "6c6e4edb-bd5e-4d52-acfe-be532fd8e608" }
    file = nexus/src/app/background/tasks/instance_watcher.rs:159
    instance_id = bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
    sled_id = b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88
    vmm_id = b5bf8281-09fc-43e1-b12c-c91c0bb18543
01:57:25.742Z DEBG 20b100d0-84c3-4119-aa9b-0c632b0b6a3a (ServerContext): updating instance state
    background_task = instance_watcher
    instance_id = bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
    sled_id = b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88
    state = SledVmmState { vmm_state: VmmRuntimeState { state: Failed, gen: Generation(68), time_updated: 2025-05-23T01:57:25.742175342Z }, migration_in: None, migration_out: None }
    vmm_id = b5bf8281-09fc-43e1-b12c-c91c0bb18543
01:57:25.742Z INFO 20b100d0-84c3-4119-aa9b-0c632b0b6a3a (ServerContext): received new VMM runtime state from sled agent
    background_task = instance_watcher
    file = nexus/src/app/instance.rs:2140
    instance_id = bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4
    migration_state = Migrations { migration_in: None, migration_out: None }
    propolis_id = b5bf8281-09fc-43e1-b12c-c91c0bb18543
    sled_id = b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88
    vmm_id = b5bf8281-09fc-43e1-b12c-c91c0bb18543
    vmm_state = VmmRuntimeState { state: Failed, gen: Generation(68), time_updated: 2025-05-23T01:57:25.742175342Z }

in the mean time, we restarted switch 0, dpd_ensure succeeded, the instance seems to have even started! note the hour and a half delay between dpd_ensure being very committed to ensuring dpd state. but, at this point it was racing with its own failure:

727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 00:24:21.318499 UTC |   5: instance_start.dpd_ensure            | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:40.400432 UTC |   5: instance_start.dpd_ensure            | succeeded  |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:40.406182 UTC |   6: instance_start.v2p_ensure            | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:40.411212 UTC |   6: instance_start.v2p_ensure            | succeeded  |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:40.414847 UTC |   7: instance_start.ensure_registered     | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:41.537457 UTC |   7: instance_start.ensure_registered     | succeeded  | {"id":"b5bf8281-09fc-43e1-b12c-c91c0bb18543","instance_id":"bf2e1d9e-fcb4-47fe-9cc5-c2e9a268fda4","propolis_ip":"fd00:1122:3344:106::1:9b7/128","propolis_port":12400,"runtime":{"gen":2,"state":"Starting","time_state_updated":"2025-05-23T01:57:41.526453504Z"},"sled_id":"b886b58a-1e3f-4be1-b9f2-0c2e66c6bc88","time_created":"2025-05-23T00:24:21.200216Z","time_deleted":null}
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:41.541548 UTC |   8: instance_start.add_virtual_resources | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:41.569554 UTC |   8: instance_start.add_virtual_resources | succeeded  |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:41.572285 UTC |   9: instance_start.ensure_running        | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:42.070330 UTC |   9: instance_start.ensure_running        | succeeded  |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:42.073853 UTC |  11: end                                  | started    |
727d4812-9383-4df3-985b-0c1bce68d5ad | 2025-05-23 01:57:42.076527 UTC |  11: end                                  | succeeded  |

and so finally settled with the instance in Failed.

[askfongjojo]

Related: #6896

[internet-diglett]

omicron/nexus/src/app/mod.rs

Lines 1205 to 1233 in e050434

	info!(log, "Determining switch slots managed by switch zones");
	let mut switch_zone_addrs = HashMap::new();
	for addr in switch_zone_addresses {
	let mgs_client = MgsClient::new(
	&format!("http://[{}]:{}", addr, MGS_PORT),
	log.new(o!("component" => "MgsClient")),
	);
	info!(log, "determining switch slot managed by dendrite zone"; "zone_address" => #?addr);
	let switch_slot = match mgs_client.sp_local_switch_id().await {
	Ok(switch) => {
	info!(
	log,
	"identified switch slot for dendrite zone";
	"slot" => #?switch,
	"zone_address" => #?addr
	);
	switch.slot
	}
	Err(e) => {
	warn!(
	log,
	"failed to identify switch slot for dendrite";
	"zone_address" => #?addr,
	"reason" => #?e
	);
	return Err(e.to_string());
	}
	};

Looks like we're being a little too strict here. In a situation where there is a DNS entry for a switch zone's Dendrite service, but that service is unavailable, this resolution process will bail out (currently we just retry later). In situations where a switch zone's MGS becomes permanently unavailable, this function will always return an error. We should probably always return whatever we could successfully find and let the caller inspect the contents and decide what to do.

[internet-diglett]

Also, it looks like we're stuck in starting instead of failing because the logic in the function that calls the above code will retry instead of bail out:

omicron/nexus/src/app/mod.rs

Lines 1169 to 1189 in d196e0c

	loop {
	let switch_zone_addresses = match resolver
	.lookup_all_ipv6(ServiceName::Dendrite)
	.await
	{
	Ok(addrs) => addrs,
	Err(e) => {
	error!(log, "failed to resolve addresses for Dendrite services"; "error" => %e);
	return Err(e.to_string());
	}
	};
	match map_switch_zone_addrs(&log, switch_zone_addresses).await {
	Ok(mappings) => {
	return Ok(mappings);
	}
	Err(e) => {
	warn!(log, "Failed to map switch zone addr: {e}, retrying");
	tokio::time::sleep(std::time::Duration::from_secs(2)).await;
	}
	}
	}

[jgallagher]

In situations where a switch zone's MGS becomes permanently unavailable, this function will always return an error. We should probably always return whatever we could successfully find and let the caller inspect the contents and decide what to do.

Just a drive-by comment - I think this may be a little trickier than it sounds, because it requires changes to error handling in higher-level callers. For example, dpd_clients() bases the map of SwitchLocation -> dpd_client::Client it returns on this mapping:

omicron/nexus/src/app/mod.rs

Lines 1113 to 1116 in 33d4f82

	let mappings = switch_zone_address_mappings(resolver, log).await?;
	let clients: HashMap<SwitchLocation, dpd_client::Client> = mappings
	.iter()
	.map(|(location, addr)| {

If we change that to return only the clients for switches we can talk to, then this bit of notify_dentrite_nat_state() will presumably fail because boundary_switches is loaded from the database and will have both switches in it, so the clients.get(switch) lookup will fail for the one we don't return:

omicron/nexus/src/app/instance_network.rs

Lines 743 to 755 in 33d4f82

	for switch in &boundary_switches {
	debug!(log, "notifying dendrite of updates";
	"instance_id" => ?instance_id,
	"switch" => switch.to_string());
	let clients = super::dpd_clients(resolver, log).await.map_err(|e| {
	Error::internal_error(&format!("failed to get dpd clients: {e}"))
	})?;
	let client_result = clients.get(switch).ok_or_else(|| {
	Error::internal_error(&format!(
	"unable to find dendrite client for {switch}"
	))
	});

which means instance_ensure_dpd_config() will fail even if it could have ensured NAT entries for the one present switch:

omicron/nexus/src/app/instance_network.rs

Lines 411 to 419 in 33d4f82

	notify_dendrite_nat_state(
	datastore,
	log,
	resolver,
	opctx_alloc,
	Some(instance_id),
	true,
	)
	.await?;

and so on. I assume there are other call chains like this that may have some error handling dominoes falling down if only one switch is present. (Obviously we have to be able to handle that case! But I think we've implicitly assumed we always have both, and untangling that may be a pretty significant piece of work.)

[askfongjojo]

I tried reproducing the issue on a racklet.

1. svcadm disable dendrite in switch 0 alone does not cause instance start/stop operations to be stuck
2. zoneadm -z oxz_switch halt does replicate the situation when new or existing instances cannot be started/stopped

Side note:
In scenario 2, zoneadm -z oxz_switch boot caused mgs to be in maintenance

mgs: initializing http server listening at [fd00:1122:3344:104::2]:12225: failed to bind to [fd00:1122:3344:104::2]:12225
[ Aug 26 19:36:28 Stopping because all processes in service exited. ]
[ Aug 26 19:36:28 Executing stop method (:kill). ]
[ Aug 26 19:36:28 Restarting too quickly, changing state to maintenance. ]

I had to reboot the scrimlet to allow the instances previously stuck in starting or stopping states to move to running and stopped eventually.

[jgallagher]

1. svcadm disable dendrite in switch 0 alone does not cause instance start/stop operations to be stuck

I think you'd need to disable MGS, not dendrite. This function looks up dendrite in DNS, but then steals just the address part and builds a client to talk to MGS:

omicron/nexus/src/app/mod.rs

Lines 1208 to 1211 in d196e0c

	let mgs_client = MgsClient::new(
	&format!("http://[{}]:{}", addr, MGS_PORT),
	log.new(o!("component" => "MgsClient")),
	);

I assume this was added before MGS had entries in DNS.