Deleted instances remain as running in CRDB after propolis zone is already removed

This happened when I used a script to invoke oxide instance stop for 10 instances successively in a loop, and then delete them with cli in another loop. The requests came back with success response (ignore the two destroyed instances - they will be covered in another ticket):

pisces-2:tests angela$ for i in {1..12}; do oxide instance delete --project try --instance sysbench-mysql-$i; done
success
()
success
()
success
()
success
()
success
()
success
()
success
()
success
()
success
()
error
Error Response: status: 400 Bad Request; headers: {"content-type": "application/json", "x-request-id": "730032c9-f928-4a5b-9244-bc36c14096ef", "content-length": "158", "date": "Tue, 23 May 2023 22:41:07 GMT"}; value: Error { error_code: Some("InvalidRequest"), message: "instance cannot be deleted in state \"destroyed\"", request_id: "730032c9-f928-4a5b-9244-bc36c14096ef" }
error
Error Response: status: 404 Not Found; headers: {"content-type": "application/json", "x-request-id": "dd8a7e48-c584-4fa8-afc8-f4fa7c0c9c7f", "content-length": "160", "date": "Tue, 23 May 2023 22:41:07 GMT"}; value: Error { error_code: Some("ObjectNotFound"), message: "not found: instance with name \"sysbench-mysql-11\"", request_id: "dd8a7e48-c584-4fa8-afc8-f4fa7c0c9c7f" }
success
()

However, these instances are now "shell" records in the instance table - the propolis zones are already gone from the sled:

root@[fd00:1122:3344:106::6]:32221/omicron> select name, state, id, active_sled_id, active_propolis_id from instance where name like 'sysbench%' and state = 'running';
        name        |   state   |                  id                  |            active_sled_id            |          active_propolis_id
--------------------+-----------+--------------------------------------+--------------------------------------+---------------------------------------
  sysbench-mysql-5  | running   | 0dcd991a-36de-4a15-a999-a6fda4efcc92 | aa7c82d9-6e59-406e-b1e3-3648890b4bec | 21078e19-c1e0-4aeb-98aa-5c337352353d
  sysbench-mysql-2  | running   | 2ab5e713-5d25-486a-9083-d5b7cd1e870d | 4f4d89de-b2ba-4a96-b585-1ef2b7a31942 | 06995cdb-54cc-4923-aea8-0fc6f617277c
  sysbench-mysql-9  | running   | 32643226-e283-4fb6-8789-627f6d7383c9 | 434d5f7d-4dd7-42d2-9637-66406ad8d90e | bfe65687-6506-49f0-aa99-0dfc4d03134d
  sysbench-mysql-3  | running   | 4e63cbb7-a36a-4407-a04e-e5a54902b66d | 434d5f7d-4dd7-42d2-9637-66406ad8d90e | 04a7822b-696a-46eb-9a05-001db70b5ab8
  sysbench-mysql-4  | running   | 8ec571b6-1be2-4d56-90aa-0119db534e26 | 434d5f7d-4dd7-42d2-9637-66406ad8d90e | 4b41405d-e38b-444e-b734-39a1859ecfa2
  sysbench-mysql-6  | running   | b44622c9-fb61-4be1-b396-08c9525a2f71 | ec2016cd-6614-45bc-8108-50d5fe04947f | da6443bc-3e3c-4482-ac01-47c0f28f7d41
  sysbench-mysql-8  | running   | baad7458-72d7-4887-9672-b0ced70165de | 72208f88-1b50-4415-8106-e7f1be075f72 | 59846b67-ee59-43ba-bc15-89de88669b51
  sysbench-mysql-12 | running   | caac0098-45f3-4d41-b93c-40622a3b80f7 | 7430cdc2-5bbc-4a19-83af-1821192d787b | 26e0f80e-c8d0-4787-a47c-95b8d0147c62
  sysbench-mysql-7  | running   | eeb46abd-ab90-46e8-ad3e-20a45975bbbf | aa7c82d9-6e59-406e-b1e3-3648890b4bec | 9e88dbaa-822c-425b-b566-6b843956a4c3
  sysbench-mysql-1  | running   | f908e4dd-f6f9-4bcc-8be0-38226b02de60 | 7430cdc2-5bbc-4a19-83af-1821192d787b | 5f00ab9f-5c68-4e71-8ed9-95b46c664924
(12 rows)

I looked into one of the instances, sysbench-mysql-7 which is located on sled gc11. It was set to stopped at 22:40:03

22:40:03.053Z INFO 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): instance updated by sled agent
    instance_id = eeb46abd-ab90-46e8-ad3e-20a45975bbbf
    new_state = stopped
    propolis_id = 9e88dbaa-822c-425b-b566-6b843956a4c3
22:40:03.057Z DEBG 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): received new runtime state from sled agent
    instance_id = eeb46abd-ab90-46e8-ad3e-20a45975bbbf
    runtime_state = InstanceRuntimeState { run_state: Stopped, sled_id: aa7c82d9-6e59-406e-b1e3-3648890b4bec, propolis_id: 9e88dbaa-822c-425b-b566-6b843956a4c3, dst_propolis_id: None, propolis_addr: Some([fd00:1122:3344:103::24]:12400), migration_id: None, propolis_gen: Generation(2), ncpus: InstanceCpuCount(4), memory: ByteCount(17179869184), hostname: "sysbench-mysql7", gen: Generation(8), time_updated: 2023-05-23T22:40:03.055815407Z }
22:40:07.620Z INFO 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): instance updated by sled agent
    instance_id = eeb46abd-ab90-46e8-ad3e-20a45975bbbf
    new_state = stopped
    propolis_id = 9e88dbaa-822c-425b-b566-6b843956a4c3

The zone was removed at 22:40:08 according to the sled-agent log for gc11:

21:57:38.679Z INFO SledAgent (InstanceManager): Started propolis in zone: oxz_propolis-server_9e88dbaa-822c-425b-b566-6b843956a4c3
    instance_id = eeb46abd-ab90-46e8-ad3e-20a45975bbbf
22:40:08.497Z WARN SledAgent (InstanceManager): Halting and removing zone: oxz_propolis-server_9e88dbaa-822c-425b-b566-6b843956a4c3
    instance_id = eeb46abd-ab90-46e8-ad3e-20a45975bbbf

but the delete saga was created 44 seconds later, at 22:40:52, presumably because nexus was busy taking deletion requests of other instances:

22:40:52.231Z DEBG 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): authorize result
    action = Delete
    actor = Some(Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. })
    actor_id = 001de000-05e4-4000-8000-000000004007
    authenticated = true
    local_addr = 172.30.1.5:443
    method = DELETE
    remote_addr = 172.20.17.42:61913
    req_id = d1b9476f-784b-4bc0-9d59-c551592ac7a2
    resource = Instance { parent: Project { parent: Silo { parent: Fleet, key: 001de000-5110-4000-8000-000000000000, lookup_type: ById(001de000-5110-4000-8000-000000000000) }, key: 549f44d7-b0cd-4532-b94d-9cae7baab5d3, lookup_type: ByName("try") }, key: eeb46abd-ab90-46e8-ad3e-20a45975bbbf, lookup_type: ByName("sysbench-mysql-7") }
    result = Ok(())
    uri = /v1/instances/sysbench-mysql-7?project=try
22:40:52.231Z DEBG 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): saga create
    dag = {"end_node":9,"graph":{"edge_property":"directed","edges":[[0,1,null],[1,2,null],[2,3,null],[3,4,null],[4,5,null],[5,6,null],[6,7,null],[8,0,null],[7,9,null]],"node_holes":[],"nodes":[{"Action":{"action_name":"instance_delete.v2p_ensure_undo","label":"V2PEnsureUndo","name":"v2p_ensure_undo"}},{"Action":{"action_name":"instance_delete.v2p_ensure","label":"V2PEnsure","name":"v2p_ensure"}},{"Action":{"action_name":"instance_delete.delete_asic_configuration","label":"DeleteAsicConfiguration","name":"delete_asic_configuration"}},{"Action":{"action_name":"instance_delete.instance_delete_record","label":"InstanceDeleteRecord","name":"no_result1"}},{"Action":{"action_name":"instance_delete.delete_network_interfaces","label":"DeleteNetworkInterfaces","name":"no_result2"}},{"Action":{"action_name":"instance_delete.deallocate_external_ip","label":"DeallocateExternalIp","name":"no_result3"}},{"Action":{"action_name":"instance_delete.virtual_resources_account","label":"VirtualResourcesAccount","name":"no_result4"}},{"Action":{"action_name":"instance_delete.sled_resources_account","label":"SledResourcesAccount","name":"no_result5"}},{"Start":{"params":{"authz_instance":{"key":"eeb46abd-ab90-46e8-ad3e-20a45975bbbf","lookup_type":{"ByName":"sysbench-mysql-7"},"parent":{"key":"549f44d7-b0cd-4532-b94d-9cae7baab5d3","lookup_type":{"ByName":"try"},"parent":{"key":"001de000-5110-4000-8000-000000000000","lookup_type":{"ById":"001de000-5110-4000-8000-000000000000"},"parent":null}}},"instance":{"identity":{"description":"jammy load generator","id":"eeb46abd-ab90-46e8-ad3e-20a45975bbbf","name":"sysbench-mysql-7","time_created":"2023-05-23T21:57:24.310610Z","time_deleted":null,"time_modified":"2023-05-23T21:57:24.310610Z"},"project_id":"549f44d7-b0cd-4532-b94d-9cae7baab5d3","runtime_state":{"dst_propolis_id":null,"gen":8,"hostname":"sysbench-mysql7","memory":17179869184,"migration_id":null,"ncpus":4,"propolis_gen":2,"propolis_id":"9e88dbaa-822c-425b-b566-6b843956a4c3","propolis_ip":"fd00:1122:3344:103::24/128","sled_id":"aa7c82d9-6e59-406e-b1e3-3648890b4bec","state":"stopped","time_updated":"2023-05-23T22:40:03.055815Z"},...
22:40:54.908Z DEBG 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): authorize result
    action = Delete
    actor = Some(Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. })
    actor_id = 001de000-05e4-4000-8000-000000004007
    authenticated = true
    resource = Instance { parent: Project { parent: Silo { parent: Fleet, key: 001de000-5110-4000-8000-000000000000, lookup_type: ById(001de000-5110-4000-8000-000000000000) }, key: 549f44d7-b0cd-4532-b94d-9cae7baab5d3, lookup_type: ByName("try") }, key: eeb46abd-ab90-46e8-ad3e-20a45975bbbf, lookup_type: ByName("sysbench-mysql-7") }
    result = Ok(())
    saga_id = 5a04bdd4-7936-4bbf-a3ba-df1a54a10518
    saga_name = instance-delete
    saga_node = InstanceDeleteRecord
22:40:54.932Z DEBG 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): authorize result
    action = Modify
    actor = Some(Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. })
    actor_id = 001de000-05e4-4000-8000-000000004007
    authenticated = true
    resource = Instance { parent: Project { parent: Silo { parent: Fleet, key: 001de000-5110-4000-8000-000000000000, lookup_type: ById(001de000-5110-4000-8000-000000000000) }, key: 549f44d7-b0cd-4532-b94d-9cae7baab5d3, lookup_type: ByName("try") }, key: eeb46abd-ab90-46e8-ad3e-20a45975bbbf, lookup_type: ByName("sysbench-mysql-7") }
    result = Ok(())
    saga_id = 5a04bdd4-7936-4bbf-a3ba-df1a54a10518
    saga_name = instance-delete
    saga_node = DeleteNetworkInterfaces
22:40:54.957Z DEBG 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): authorize result
    action = Read
    actor = Some(Actor::SiloUser { silo_user_id: 001de000-05e4-4000-8000-000000004007, silo_id: 001de000-5110-4000-8000-000000000000, .. })
    actor_id = 001de000-05e4-4000-8000-000000004007
    authenticated = true
    resource = Instance { parent: Project { parent: Silo { parent: Fleet, key: 001de000-5110-4000-8000-000000000000, lookup_type: ById(001de000-5110-4000-8000-000000000000) }, key: 549f44d7-b0cd-4532-b94d-9cae7baab5d3, lookup_type: ByName("try") }, key: eeb46abd-ab90-46e8-ad3e-20a45975bbbf, lookup_type: ByName("sysbench-mysql-7") }
    result = Ok(())
    saga_id = 5a04bdd4-7936-4bbf-a3ba-df1a54a10518
    saga_name = instance-delete
    saga_node = SledResourcesAccount
22:40:54.966Z INFO 496eabae-738d-4497-a183-1b75bf912c7c (ServerContext): request completed
    local_addr = 172.30.1.5:443
    method = DELETE
    remote_addr = 172.20.17.42:61913
    req_id = d1b9476f-784b-4bc0-9d59-c551592ac7a2
    response_code = 204
    uri = /v1/instances/sysbench-mysql-7?project=try

I didn't find any saga error in the log but the saga also doesn't exist in the database:

root@[fd00:1122:3344:106::6]:32221/omicron> select * from saga where id = '5a04bdd4-7936-4bbf-a3ba-df1a54a10518';
  id | creator | time_created | name | saga_dag | saga_state | current_sec | adopt_generation | adopt_time
-----+---------+--------------+------+----------+------------+-------------+------------------+-------------
(0 rows)

At 22:42:40, I tried to recreate a VM with the same name but that failed with an object already exists error. These VMs are now ghost records and cannot be removed because the VMs don't have a backend and can't be stopped/deleted.

The complete nexus log is located in catacomb.eng.oxide.computer:/data/staff/dogfood/may-23/.

Start with the Nexus DELETE /v1/instances entry point, the instance-delete saga nodes, and the sled-agent logs showing zone removal. Reproduce the stop/delete sequence and compare saga completion with the instance and saga database records; done means deleted instances do not remain as running ghost records after their propolis zones are removed.