sled-agent not serving vmm requests

[askfongjojo]

The issue was seen on sled 13 of rack3. There was a problem with mupdate during that time and we're not sure if it's related at all. Other sleds do not have this particular issue AFAICT. https://github.com/oxidecomputer/colo/issues/88#issuecomment-2423940805 is where we noted the problem, also cloned below:

Looking at sled agent logs it looks like calls to the /vmms/{id}/state endpoint are timing out on sled 13:

15:00:47.203Z WARN SledAgent (dropshot (SledAgent)): request handling cancelled (client disconnected)
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:887
    latency_us = 60005110
    local_addr = [fd00:1122:3344:104::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:10e::3]:36498
    req_id = ccf79204-80fb-4814-a778-59a48ab273a4
    uri = /vmms/90676c5f-a315-4930-a90f-43790839069b/state

I don't know for certain if this is related but it seems suspicious.

The recent sled-agent logs and core files have been uploaded to /staff/rack3/colo-88.

[gjcolombo]

Probably related to #6904. I found a relevant-looking sled agent log snippet (from oxide-sled-agent:default.log.1729284364); this is the point where the system crossed over from successfully servicing VMM requests to failing to do so:

20:38:35.072Z INFO SledAgent (dropshot (SledAgent)): request completed
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:950
    latency_us = 365
    local_addr = [fd00:1122:3344:104::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:10e::3]:61554
    req_id = 27622099-2c46-440c-b189-386adcebecea
    response_code = 200
    uri = /vmms/3bfe0e53-b1e9-4473-8a92-298984d08e17/state
20:38:35.072Z INFO SledAgent (dropshot (SledAgent)): request completed
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:950
    latency_us = 375
    local_addr = [fd00:1122:3344:104::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:10e::3]:64130
    req_id = 616faeea-d021-4145-9ba0-b004bfaf66be
    response_code = 200
    uri = /vmms/08704209-ff3e-4d96-a6e9-901b9b288134/state
20:38:35.098Z INFO SledAgent (dropshot (SledAgent)): request completed
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:950
    latency_us = 210
    local_addr = [fd00:1122:3344:104::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:10e::3]:64130
    req_id = a7997c8e-8f69-414e-83e1-8bf905229a39
    response_code = 200
    uri = /vmms/677d7236-412a-4141-8876-f09cc7dbee44/state
20:38:35.134Z INFO SledAgent (dropshot (SledAgent)): request completed
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:950
    latency_us = 127
    local_addr = [fd00:1122:3344:104::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:10e::3]:64130
    req_id = 2bc807ce-f42e-4921-87a4-930a0b23b513
    response_code = 200
    uri = /vmms/90676c5f-a315-4930-a90f-43790839069b/state

// gjcolombo: 10 seconds elapse

// gjcolombo: note remote port number
20:38:45.544Z INFO SledAgent (dropshot (SledAgent)): accepted connection
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:1105
    local_addr = [fd00:1122:3344:104::1]:12345
    remote_addr = [fd00:1122:3344:111::3]:46877

// gjcolombo: 7 more seconds elapse

20:38:52.095Z INFO SledAgent (dropshot (BootstrapAgent)): accepted connection
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:1105
    local_addr = [fdb0:a840:2504:350::1]:80
    remote_addr = [fdb0:a840:2504:4d0::2]:48619
20:38:52.929Z INFO SledAgent (dropshot (BootstrapAgent)): accepted connection
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:1105
    local_addr = [fdb0:a840:2504:350::1]:80
    remote_addr = [fdb0:a840:2504:1d4::2]:41366

// gjcolombo: several successful requests redacted; these hit the /eip-gateways and /vpc-routes endpoints

// gjcolombo: 60-second client timeout; turns out this was a snapshot request...
20:39:45.265Z WARN SledAgent (dropshot (SledAgent)): request handling cancelled (client disconnected)
    file = /home/build/.cargo/registry/src/index.crates.io-6f17d22bba15001f/dropshot-0.12.0/src/server.rs:887
    latency_us = 59718455
    local_addr = [fd00:1122:3344:104::1]:12345
    method = POST
    remote_addr = [fd00:1122:3344:111::3]:46877
    req_id = b52dafd4-82b6-4d6c-b044-c72619bd0078
    uri = /vmms/3bfe0e53-b1e9-4473-8a92-298984d08e17/disks/31c1a97b-db69-4185-a198-78679c0f1f36/snapshot

I suspect what's happened is that this specific snapshot request is stuck. It's not timing out because it's being serviced via a call to Propolis, and sled agent's Propolis clients don't configure a timeout:

omicron/sled-agent/src/instance.rs

Lines 1654 to 1660 in ca63e9f

	// We use a custom client builder here because the default progenitor
	// one has a timeout of 15s but we want to be able to wait indefinitely.
	let reqwest_client = reqwest::ClientBuilder::new().build().unwrap();
	let client = Arc::new(PropolisClient::new_with_client(
	&format!("http://{}", &self.propolis_addr),
	reqwest_client,
	));

Things to follow up on:

1. Why is this snapshot request stuck? Does this disk (31c1a97b-db69-4185-a198-78679c0f1f36) have a downstairs on another sled that's in bad repair? @askfongjojo, @augustuswm: Propolis logs from VMM 3bfe0e53-b1e9-4473-8a92-298984d08e17 might be helpful here, if we don't have them already and we're not immediately sure that something is wrong with this specific Crucible disk.
2. Allocating guest memory is (or should be) much faster than it was when we configured this Propolis client. Should we really be running this client without a timeout? (Another related question: is it safe to do that, or will timing out a Propolis operation throw something off between Propolis and sled agent?)
3. Because each individual instance has its own driver task, it seems like we could (and should) rework InstanceManager so that it doesn't block waiting for each individual reply for a specific instance. That is, functions like issue_snapshot_request seem like they could spawn a separate tokio task that sends a message to the Instance in question, awaits the reply, and then forwards the reply back to the task that originally handled the relevant HTTP request. I say "seems" here because I haven't looked too hard, and this may be harder than it first appears!

[gjcolombo]

I should add that I also took a very quick peek at the core file, but all it reveals at first glance is that all of the tokio threads in the agent are currently idle. That's consistent with the observations above. I don't know if we have any techniques available to parse the tokio task wheel manually to figure out where the InstanceManager task most recently awaited.

[hawkw]

@gjcolombo

Because each individual instance has its own driver task, it seems like we could (and should) rework InstanceManager so that it doesn't block waiting for each individual reply for a specific instance. That is, functions like issue_snapshot_request seem like they could spawn a separate tokio task that sends a message to the Instance in question, awaits the reply, and then forwards the reply back to the task that originally handled the relevant HTTP request. I say "seems" here because I haven't looked too hard, and this may be harder than it first appears!

I think this seems quite doable and is almost certainly a good idea. The only thing that should be synchronous in the InstanceManager ought to be the actual routing of requests to instances and management of the "table of running instances" state. Potentially, I think we might not even need to spawn a separate task here, although I'll have to take another look at the code.

Happy to take a crack at this change unless you were planning to imminently.

[gjcolombo]

Happy to take a crack at this change unless you were planning to imminently.

It's all yours if you want it! Let me know if you'd like me to pitch in.

[gjcolombo]

One additional note re this and #6904: Although transferring requests from the InstanceManager to an individual Instance without blocking would have allowed requests to other VMMs to go through, requests to the snapshotting VM could still block (since the InstanceRunner still won't be responding). An operation like InstanceManagerRunner::use_only_these_disks would therefore still block indefinitely if the InstanceManager decided that it needed to dispatch a call to the affected Instance. Making Instance calls not block the InstanceManager is still righteous, but we still need to figure out what to do about seemingly-stuck calls to Propolis.

[askfongjojo]

1. Why is this snapshot request stuck? Does this disk (31c1a97b-db69-4185-a198-78679c0f1f36) have a downstairs on another sled that's in bad repair?

Yes, it indeed has a downstairs on sled 9 (BRM42220063) so that would explain why the snapshot task was stuck:

root@oxz_switch1:~# omdb db disks info 31c1a97b-db69-4185-a198-78679c0f1f36
HOST_SERIAL DISK_NAME                                          INSTANCE_NAME   PROPOLIS_ZONE                                            VOLUME_ID                            DISK_STATE 
BRM42220064 issue-collector-21dce8b6-7be8-4f31-8d52-958-f9cad9 issue-collector oxz_propolis-server_3bfe0e53-b1e9-4473-8a92-298984d08e17 b209a8e3-9dca-41b7-aa9d-9a7d232c602f attached   
HOST_SERIAL REGION                               ZONE                                              PHYSICAL_DISK                        
BRM44220017 f4112406-22c4-46d2-a6b5-9f22bd49a90d oxz_crucible_1455c069-853c-49cd-853a-3ea81b89acd4 c5058411-d64a-42d6-acda-903e65171d25 
BRM42220063 a5f0cf81-3686-471f-87da-22efbb533a78 oxz_crucible_816f26a7-4c28-4a39-b9ad-a036678520ab a7787335-6d18-4a96-910b-4d841f72dab4 
BRM42220073 25db1691-243f-4d92-bafd-8af0dc724af0 oxz_crucible_cf667caf-304c-40c4-acce-f0eb05d011ef e1f7c8aa-c45b-412c-9466-f3a490877b0a 

[askfongjojo]

Before we have a fix to avoid the blocking behavior, what would be a reasonable workaround in this case? Would restarting sled-agent free up InstanceManager to serve other requests? Would the snapshot task retry indefinitely because it's a saga (not sure at what point it would give up and unwind)?

[gjcolombo]

Would restarting sled-agent free up InstanceManager to serve other requests?

Good call--I think this should work, at least as far as instance management is concerned. All the existing Propolis zones will be reaped when the new sled agent starts, but any affected instances should go to Failed and then be restarted. The new sled agent will otherwise have a brand new instance manager task with an empty instance table.

Would the snapshot task retry indefinitely because it's a saga (not sure at what point it would give up and unwind)?

The next snapshot saga retry should produce a permanent error, since this request is directed at a particular VMM, and sled agent will now return "no such VMM" instead of stalling and timing out. Assuming the saga recognizes that it now has a permanent error it should unwind at that point.

[askfongjojo]

Thanks @gjcolombo. @augustuswm - There is no rush but it sounds like we can put sled 13 back in service with a sled-agent restart.

[augustuswm]

Sounds good. I will do that now.

[augustuswm]

That looks to have worked. VMs on sled 13 were replaced, and then stop + start operations afterwards were successful.