Instance failed to start, channel at capacity (32)

[leftwo]

I have some Instances stuck in starting/stopping. All on sled 14, sled

root@oxz_switch0:~# omdb db instance list 2> /dev/null | grep -v running | grep -v stopped                                                                                     
ID                                   STATE    PROPOLIS_ID                          SLED_ID                              HOST_SERIAL NAME                      
051a3617-ec9a-4401-9916-afd3a99be85b starting 315a55c4-a549-4fe2-878d-90408fc3eda4 34a3ed99-5aa2-4828-b4b9-116e6a1767d6 BRM42220026 aaa12-inst    
da2d563b-24dc-455c-863a-aecdc5154e5e starting 9c445772-584b-4a05-81c7-acbae9a816fe 34a3ed99-5aa2-4828-b4b9-116e6a1767d6 BRM42220026 new12-inst
9971a086-b519-4764-bcea-64a3bdb34f1b stopping 9f5f8062-891e-4374-ab38-e985f39cd1c1 34a3ed99-5aa2-4828-b4b9-116e6a1767d6 BRM42220026 new11-inst
b246f449-51be-4da3-86c3-31397a9418dd stopping cb921ea9-ade2-47fc-97a7-ab6f38253116 34a3ed99-5aa2-4828-b4b9-116e6a1767d6 BRM42220026 new13-inst
33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb starting e04e30ee-2a22-4989-ba39-79074c0c6d9f 34a3ed99-5aa2-4828-b4b9-116e6a1767d6 BRM42220026 aaa13-inst

Looking at aaa13-inst (the bottom one):

root@oxz_switch0:~# omdb db instance info 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb 2> /dev/null

== INSTANCE ====================================================================
                        ID: 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
                project ID: a4be3fc6-790c-4d90-b64b-c8ed32028a25
                      name: aaa13-inst
               description: aaa13-inst host
                created at: 2025-04-15 00:44:57.140357 UTC
          last modified at: 2025-04-15 00:44:57.140357 UTC

== CONFIGURATION ===============================================================
                     vCPUs: 2
                    memory: 8 GiB
                  hostname: aaa13-inst
                 boot disk: None
              auto-restart:
                  InstanceAutoRestart {
                      policy: None,
                      cooldown: None,
                  }

== RUNTIME STATE ===============================================================
               nexus state: Vmm
(i)     external API state: Starting
           last updated at: 2025-04-15T17:11:28.738765Z (generation 11)
       needs reincarnation: false
             karmic status: saṃsāra (reincarnation enabled)
      last reincarnated at: None
             active VMM ID: Some(e04e30ee-2a22-4989-ba39-79074c0c6d9f)
             target VMM ID: None
              migration ID: None
              updater lock: UNLOCKED at generation: 13

== ACTIVE VMM ==================================================================
                        ID: e04e30ee-2a22-4989-ba39-79074c0c6d9f
               instance ID: 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
                created at: 2025-04-15 17:11:46.775187 UTC
                     state: starting
                updated at: 2025-04-15T17:11:47.601450Z (generation 2)
          propolis address: fd00:1122:3344:101::1:14:12400
                   sled ID: 34a3ed99-5aa2-4828-b4b9-116e6a1767d6

== ATTACHED DISKS ==============================================================
# ID                                   SIZE   STATE    NAME       
0 536a6543-b089-4572-bde8-0b0635539a32 13 GiB attached aaa13-disk 

On 14 where propolis server is running:

BRM42220026 # /opt/oxide/oxlog/oxlog logs --current --archived --show-empty oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f | xargs ls -l
-rw-r--r--   1 root     root        2637 Apr 15 17:16 /pool/ext/03fee42e-4aa0-404c-8404-beae944ece8f/crypt/debug/oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f/system-illumos-propolis-server:default.log.1744737116
-rw-r--r--   1 root     root           0 Apr 15 17:15 /pool/ext/60403bed-a679-4ac1-82dc-8b920b974898/crypt/zone/oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f/root/var/svc/log/system-illumos-propolis-server:default.log

The propolis log looks usual, and is just waiting:

BRM42220026 # cat /pool/ext/03fee42e-4aa0-404c-8404-beae944ece8f/crypt/debug/oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f/system-illumos-propolis-server:default.log.1744737116 | looker
[ Apr 15 17:11:54 Enabled. ]
[ Apr 15 17:11:54 Rereading configuration. ]
[ Apr 15 17:11:55 Rereading configuration. ]
[ Apr 15 17:11:55 Executing start method ("/opt/oxide/lib/svc/manifest/propolis/propolis.sh"). ]
+ . /lib/svc/share/smf_include.sh
++ SMF_EXIT_OK=0
++ SMF_EXIT_NODAEMON=94
++ SMF_EXIT_ERR_FATAL=95
++ SMF_EXIT_ERR_CONFIG=96
++ SMF_EXIT_MON_DEGRADE=97
++ SMF_EXIT_MON_OFFLINE=98
++ SMF_EXIT_ERR_NOSMF=99
++ SMF_EXIT_ERR_PERM=100
++ svcprop -c -p config/datalink svc:/system/illumos/propolis-server:default
+ DATALINK=oxControlInstance20
++ svcprop -c -p config/gateway svc:/system/illumos/propolis-server:default
+ GATEWAY=fd00:1122:3344:101::1
++ svcprop -c -p config/listen_addr svc:/system/illumos/propolis-server:default
+ LISTEN_ADDR=fd00:1122:3344:101::1:14
++ svcprop -c -p config/listen_port svc:/system/illumos/propolis-server:default
+ LISTEN_PORT=12400
++ svcprop -c -p config/metric_addr svc:/system/illumos/propolis-server:default
+ METRIC_ADDR=dns
+ [[ oxControlInstance20 == unknown ]]
+ [[ fd00:1122:3344:101::1 == unknown ]]
+ ipadm delete-if oxControlInstance20
ipadm: Could not delete oxControlInstance20: Interface does not exist
+ true
+ ipadm create-if -t oxControlInstance20
+ ipadm set-ifprop -t -p mtu=9000 -m ipv4 oxControlInstance20
+ ipadm set-ifprop -t -p mtu=9000 -m ipv6 oxControlInstance20
+ ipadm show-addr oxControlInstance20/ll
ipadm: Could not get address: Object not found
+ ipadm create-addr -t -T addrconf oxControlInstance20/ll
+ ipadm show-addr oxControlInstance20/omicron6
ipadm: Could not get address: Object not found
+ ipadm create-addr -t -T static -a fd00:1122:3344:101::1:14 oxControlInstance20/omicron6
+ route get -inet6 default -inet6 fd00:1122:3344:101::1
default: not in table
+ route add -inet6 default -inet6 fd00:1122:3344:101::1
add net default: gateway fd00:1122:3344:101::1
+ args=('run' '/opt/oxide/propolis-server/blob/OVMF_CODE.fd' "[$LISTEN_ADDR]:$LISTEN_PORT" '--metric-addr' "$METRIC_ADDR")
+ ctrun -l child -o noorphan,regent /opt/oxide/propolis-server/bin/propolis-server run /opt/oxide/propolis-server/blob/OVMF_CODE.fd '[fd00:1122:3344:101::1:14]:12400' --metric-addr dns
[ Apr 15 17:11:56 Method "start" exited with status 0. ]
17:11:56.502Z INFO propolis-server: Starting server...
17:11:56.503Z INFO propolis-server: listening
    local_addr = [fd00:1122:3344:101::1:14]:12400

Search for e04e30ee, the propolis ID (zone ID) for aaa13-inst

BRM23230018 # for log in $(/opt/oxide/oxlog/oxlog logs --archived --current $(zoneadm list | grep nexus)); do echo "search $log for aaa13" >> /tmp/fff;grep aaa13-inst $log | looker >> /tmp/fff; don

Here is the stop in the nexus log:
search /pool/ext/268b43d0-37df-4956-ac61-ea92abeb975d/crypt/debug/oxz_nexus_e05c41d4-3e97-4ba9-a260-8b5bedd17b9f/oxide-nexus:default.log.1744738200 for aaa13

17:11:24.318Z DEBG e05c41d4-3e97-4ba9-a260-8b5bedd17b9f (dropshot_external): roles
   actor_id = f0356066-0677-4bac-a557-3891f02dee37
   authenticated = true
   local_addr = 172.30.2.6:443
   method = POST
   remote_addr = 172.20.2.15:40101
   req_id = c2115bc8-a87f-4611-8724-d67111793fbd
   roles = RoleSet { roles: {} }
   uri = /v1/instances/aaa13-inst/stop?project=alan

Then, the start in the nexus log on 17:

17:11:46.663Z DEBG e05c41d4-3e97-4ba9-a260-8b5bedd17b9f (dropshot_external): roles
    actor_id = f0356066-0677-4bac-a557-3891f02dee37
    authenticated = true
    local_addr = 172.30.2.6:443
    method = POST
    remote_addr = 172.20.2.15:51002
    req_id = 19ea8b0a-51c1-4574-bfa7-e7ca4bd11e4a
    roles = RoleSet { roles: {} }
    uri = /v1/instances/aaa13-inst/start?project=alan

Saga create for instance start:

17:11:46.708Z INFO e05c41d4-3e97-4ba9-a260-8b5bedd17b9f (ServerContext): preparing saga
    file = nexus/src/app/saga.rs:255
    saga_id = ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6
    saga_name = instance-start

…

Finish??

17:11:47.701Z INFO e05c41d4-3e97-4ba9-a260-8b5bedd17b9f (ServerContext): saga finished
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/steno-0.4.1/src/sec.rs:1025
    result = success
    saga_id = ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6
    saga_name = instance-start
    sec_id = e05c41d4-3e97-4ba9-a260-8b5bedd17b9f
17:11:47.701Z INFO e05c41d4-3e97-4ba9-a260-8b5bedd17b9f (ServerContext): saga finished
    file = nexus/src/app/saga.rs:404
    saga_id = ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6
    saga_name = instance-start

omdb saga output for the instance start saga.

root@oxz_switch0:~# /tmp/omdb-saga db sagas show ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6
 id                                   | time_created                   | name           | state                 
--------------------------------------+--------------------------------+----------------+-----------------------
 ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.708453 UTC | instance-start | SagaCachedState(Done) 

                             saga id | event time                     | node id                                   | event type | data
------------------------------------ | ------------------------------ | ----------------------------------------- | ---------- | ---
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.713511 UTC |  10: start                                | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.716112 UTC |  10: start                                | succeeded  | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.719560 UTC |   0: instance_start.generate_propolis_id  | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.722653 UTC |   0: instance_start.generate_propolis_id  | succeeded  | "e04e30ee-2a22-4989-ba39-79074c0c6d9f"
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.725685 UTC |   1: instance_start.alloc_server          | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.758035 UTC |   1: instance_start.alloc_server          | succeeded  | "34a3ed99-5aa2-4828-b4b9-116e6a1767d6"
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.761691 UTC |   2: instance_start.alloc_propolis_ip     | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.769357 UTC |   2: instance_start.alloc_propolis_ip     | succeeded  | "fd00:1122:3344:101::1:14"
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.772964 UTC |   3: instance_start.create_vmm_record     | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.779976 UTC |   3: instance_start.create_vmm_record     | succeeded  | {"id":"e04e30ee-2a22-4989-ba39-79074c0c6d9f","instance_id":"33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb","propolis_ip":"fd00:1122:3344:101::1:14/128","propolis_port":12400,"runtime":{"gen":1,"state":"Creating","time_state_updated":"2025-04-15T17:11:46.775187Z"},"sled_id":"34a3ed99-5aa2-4828-b4b9-116e6a1767d6","time_created":"2025-04-15T17:11:46.775187Z","time_deleted":null}
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.783131 UTC |   4: instance_start.mark_as_starting      | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.835031 UTC |   4: instance_start.mark_as_starting      | succeeded  | {"auto_restart":{"cooldown":null,"policy":null},"boot_disk_id":null,"hostname":"aaa13-inst","identity":{"description":"aaa13-inst host","id":"33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb","name":"aaa13-inst","time_created":"2025-04-15T00:44:57.140357Z","time_deleted":null,"time_modified":"2025-04-15T00:44:57.140357Z"},"memory":8589934592,"ncpus":2,"project_id":"a4be3fc6-790c-4d90-b64b-c8ed32028a25","runtime_state":{"dst_propolis_id":null,"gen":11,"migration_id":null,"nexus_state":"Vmm","propolis_id":"e04e30ee-2a22-4989-ba39-79074c0c6d9f","time_last_auto_restarted":null,"time_updated":"2025-04-15T17:11:28.738765Z"},"updater_gen":13,"updater_id":null,"user_data":[35,99,108,111,117,100,45,99,111,110,102,105,103,10,109,97,110,97,103,101,95,101,116,99,95,104,111,115,116,115,58,32,116,114,117,101,10]}
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:46.837925 UTC |   5: instance_start.dpd_ensure            | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.214648 UTC |   5: instance_start.dpd_ensure            | succeeded  | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.219940 UTC |   6: instance_start.v2p_ensure            | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.224423 UTC |   6: instance_start.v2p_ensure            | succeeded  | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.227440 UTC |   7: instance_start.ensure_registered     | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.614684 UTC |   7: instance_start.ensure_registered     | succeeded  | {"id":"e04e30ee-2a22-4989-ba39-79074c0c6d9f","instance_id":"33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb","propolis_ip":"fd00:1122:3344:101::1:14/128","propolis_port":12400,"runtime":{"gen":2,"state":"Starting","time_state_updated":"2025-04-15T17:11:47.601450025Z"},"sled_id":"34a3ed99-5aa2-4828-b4b9-116e6a1767d6","time_created":"2025-04-15T17:11:46.775187Z","time_deleted":null}
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.618591 UTC |   8: instance_start.add_virtual_resources | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.633850 UTC |   8: instance_start.add_virtual_resources | succeeded  | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.636340 UTC |   9: instance_start.ensure_running        | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.684363 UTC |   9: instance_start.ensure_running        | succeeded  | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.688496 UTC |  11: end                                  | started    | 
ffcdd938-e1da-4607-a8d1-f3c5df0ee4f6 | 2025-04-15 17:11:47.691436 UTC |  11: end                                  | succeeded  | 

Then, sled agent on 14. I'm just showing logs for "aaa13-inst" or "e04e30ee-2a22-4989-ba39-79074c0c6d9f"

Instance starting up:

2025-04-15 17:11:47.603Z INFO SledAgent/644 (InstanceManager) on BRM42220026: ensuring instance is registered
    file = sled-agent/src/instance_manager.rs:584
    hardware = InstanceHardware { properties: InstanceProperties { ncpus: InstanceCpuCount(2), memory: ByteCount(8589934592), hostname: Hostname("aaa13-inst") }, <output removed>
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    metadata = InstanceMetadata { silo_id: 17acdd30-316f-43d8-a586-23a64b0899a8, project_id: a4be3fc6-790c-4d90-b64b-c8ed32028a25 }
    migration_id = None
    propolis_addr = [fd00:1122:3344:101::1:14]:12400
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
    vmm_runtime = VmmRuntimeState { state: Starting, gen: Generation(2), time_updated: 2025-04-15T17:11:47.601450025Z }
2025-04-15 17:11:47.603Z INFO SledAgent/644 (InstanceManager) on BRM42220026: registering new instance
    file = sled-agent/src/instance_manager.rs:617
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    migration_id = None
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:47.603Z INFO SledAgent/644 (InstanceManager) on BRM42220026: initializing new Instance
    file = sled-agent/src/instance.rs:1769
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    migration_id = None
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
    state = InstanceInitialState { hardware: InstanceHardware { properties: InstanceProperties { ncpus: InstanceCpuCount(2), memory: ByteCount(8589934592), hostname: Hostname("aaa13-inst") } <output removed>
2025-04-15 17:11:47.603Z INFO SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request completed
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:867
    latency_us = 1469
    local_addr = [fd00:1122:3344:101::1]:12345
    method = PUT
    remote_addr = [fd00:1122:3344:103::4]:53416
    req_id = e1db1ec4-ffd2-4d12-b8c7-dbafae398972
    response_code = 200
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:47.683Z INFO SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request completed
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:867
    latency_us = 229
    local_addr = [fd00:1122:3344:101::1]:12345
    method = PUT
    remote_addr = [fd00:1122:3344:103::4]:65332
    req_id = 3a3e5142-ea47-466d-b703-40f9ca68ff05
    response_code = 200
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:11:47.768Z INFO SledAgent/644 (InstanceManager) on BRM42220026: Configuring new Omicron zone: oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
    file = illumos-utils/src/zone.rs:302
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:47.809Z INFO SledAgent/644 (InstanceManager) on BRM42220026: Installing Omicron zone: oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
    file = illumos-utils/src/zone.rs:340
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:49.142Z INFO SledAgent/644 (InstanceManager) on BRM42220026: Profile for oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f:
    <!DOCTYPE service_bundle SYSTEM "/usr/share/lib/xml/dtd/service_bundle.dtd.1">
    <service_bundle type="profile" name="omicron">
      <service version="1" type="service" name="system/illumos/propolis-server">
        <instance enabled="true" name="default">
          <property_group type="application" name="config">
            <propval type="astring" name="datalink" value='oxControlInstance20'/>
            <propval type="astring" name="gateway" value='fd00:1122:3344:101::1'/>
            <propval type="astring" name="listen_addr" value='fd00:1122:3344:101::1:14'/>
            <propval type="astring" name="listen_port" value='12400'/>
            <propval type="astring" name="metric_addr" value='dns'/>
          </property_group>
        </instance>
      </service>
    </service_bundle>
    file = sled-agent/src/profile.rs:34
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:49.142Z INFO SledAgent/644 (InstanceManager) on BRM42220026: Booting oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f zone
    file = illumos-utils/src/running_zone.rs:482
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
    zone = oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:49.410Z WARN SledAgent/644 (InstanceManager) on BRM42220026: wait for service svc:/milestone/single-user:default in zone Some("oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f") failed: Property not found. retry in 37.022827ms
    file = illumos-utils/src/svc.rs:36
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
    zone = oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:49.501Z WARN SledAgent/644 (InstanceManager) on BRM42220026: wait for service svc:/milestone/single-user:default in zone Some("oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f") failed: Property not found. retry in 60.48713ms
    file = illumos-utils/src/svc.rs:36
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
    zone = oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:49.592Z WARN SledAgent/644 (InstanceManager) on BRM42220026: wait for service svc:/milestone/single-user:default in zone Some("oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f") failed: Property not found. retry in 244.00409ms
    file = illumos-utils/src/svc.rs:36
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
    zone = oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f

wait for service continues for a while, then this:

2025-04-15 17:11:55.500Z WARN SledAgent/644 (InstanceManager) on BRM42220026: wait for service svc:/milestone/single-user:default in zone Some("oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f") failed: Property not found. retry in 1.082165435s
    file = illumos-utils/src/svc.rs:36
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
    zone = oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:56.669Z INFO SledAgent/644 (InstanceManager) on BRM42220026: Started propolis in zone: oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
    file = sled-agent/src/instance.rs:2320
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:11:56.729Z INFO SledAgent/644 (InstanceManager) on BRM42220026: Propolis SMF service is online
    file = sled-agent/src/instance.rs:2331
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
2025-04-15 17:12:53.302Z WARN SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 59994932
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:101::21]:55219
    req_id = 16cf7cd8-bc56-47f0-9b7e-b1dcb3b7d2b3
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:13:38.591Z WARN SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60002289
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:103::4]:55904
    req_id = b72721d7-3de9-4603-88f3-e01092d371fe
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state

keeps going

2025-04-15 17:15:59.047Z WARN SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60002002
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:101::21]:46229
    req_id = 5e9bc566-7533-436f-a723-3be65508657f
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:16:26.189Z INFO SledAgent/644 (DumpSetup-worker) on BRM42220026: Archiving 105 log files from oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f zone
    file = sled-agent/src/dump_setup.rs:1001
2025-04-15 17:16:39.001Z WARN SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60002291
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:103::4]:42128
    req_id = 5f6ff7c4-73d9-4193-b6ea-88805cb42af5
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state

keeps going with client disconnected till we get our first channel at capacity:

2025-04-15 17:23:39.865Z WARN SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60002119
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:103::4]:54526
    req_id = 73bbf99d-8ce3-4773-808d-44a9b95be82a
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:23:40.023Z INFO SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request completed
    error_message_external = Service Unavailable
    error_message_internal = Failed to send request to Instance: channel at capacity (32)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:855
    latency_us = 126
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:103::4]:54635
    req_id = 7d2b0372-4d11-476a-8ded-237c34f4b66a
    response_code = 503
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:24:00.073Z WARN SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60003144
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:101::21]:40151
    req_id = d7791bcf-d50d-4ed4-88fc-9e483984741e
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:24:00.195Z INFO SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request completed
    error_message_external = Service Unavailable
    error_message_internal = Failed to send request to Instance: channel at capacity (32)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:855
    latency_us = 142
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:101::21]:55477
    req_id = 6e9bc399-44c1-445c-ac55-800186b8d007
    response_code = 503
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:24:14.433Z WARN SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60002699
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:12a::30]:47426
    req_id = e8591ff3-e95b-4f36-865e-27a672c1d5ee
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
2025-04-15 17:24:14.558Z INFO SledAgent/644 (dropshot (SledAgent)) on BRM42220026: request completed
    error_message_external = Service Unavailable
    error_message_internal = Failed to send request to Instance: channel at capacity (32)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:855
    latency_us = 139
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:12a::30]:36786
    req_id = b7dce702-73d5-425f-a036-2463e05f0000
    response_code = 503
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state

There are a few more interleaved client disconnect messages, but it goes to be all channel at capacity messages from this point on.

[leftwo]

Logs for sled agent, nexus, propolis, and others are in /staff/core/omicron-7983/

[leftwo]

Some history. Sleds 15 and 17 have been expunged and added back some 8 times each, switching back and forth between them.

The most recent expungement then addition back of sled 17 completed here:

set target blueprint e94e40c7-c2ed-40cf-9496-54634bc4861c to disabled                                                                                                                                                                            
Done at Tue Apr 15 16:29:43 UTC 2025  

At about Tue Apr 15 17:13:03 UTC 2025, two instances were stopped (unrelated to the problems above)

oxide instance stop --project alan --instance new10-inst                                                                                                                                                                                         
oxide instance stop --project alan --instance manydisk-inst  

Then, sled 15 was clean slated at about Tue Apr 15 17:13:24 UTC 2025
Then expunged later:

Tue Apr 15 17:15:53 UTC 2025                                
omdb --destructive nexus sleds expunge 750718d8-9205-4941-9113-c237b7468679                                             
note: using Nexus URL http://[fd00:1122:3344:101::21]:12221                                                             
note: using database URL postgresql://root@[fd00:1122:3344:101::3]:32221,[fd00:1122:3344:103::3]:32221,[fd00:1122:3344:103::22]:32221/omicron?sslmode=disable                                                                                    
note: database schema version matches expected (135.0.0)                                                                
WARNING: This operation will PERMANENTLY and IRRECOVABLY mark sled 750718d8-9205-4941-9113-c237b7468679 (BRM27230037) expunged. To proceed, type the sled's serial number.                                                                       
sled serial number〉BRM27230037                             
expunged sled 750718d8-9205-4941-9113-c237b7468679 (previous policy: InService(Provisionable))                          

Tue Apr 15 17:17:39 UTC 2025                                
omdb db sleds                                               
note: using database URL postgresql://root@[fd00:1122:3344:101::3]:32221,[fd00:1122:3344:103::3]:32221,[fd00:1122:3344:103::22]:32221/omicron?sslmode=disable                                                                                    
note: database schema version matches expected (135.0.0)                                                                
note: listing all commissioned sleds (use -F to filter, e.g. -F in-service)                                             
 SERIAL       IP                             ROLE      POLICY      STATE   ID                                                                                                                                                                    
 BRM42220026  [fd00:1122:3344:101::1]:12345  scrimlet  in service  active  34a3ed99-5aa2-4828-b4b9-116e6a1767d6                                                                                                                                  
 BRM27230037  [fd00:1122:3344:129::1]:12345  -         expunged    active  750718d8-9205-4941-9113-c237b7468679                                                                                                                                  
 BRM23230018  [fd00:1122:3344:103::1]:12345  scrimlet  in service  active  b6279720-b2aa-4baa-86ba-7ab66f0be547                                                                                                                                  
 BRM23230010  [fd00:1122:3344:12a::1]:12345  -         in service  active  bcbdab06-49bc-4e7b-8aca-55beb084dc49  

[leftwo]

The oximeter log from this time is at: /staff/core/omicron-7983/14-BRM42220026/oxide-oximeter:default.log.1744737296

[gjcolombo]

There are a couple of VMMs that are interesting here. One of them, the cb92 VMM, successfully reaches the Destroyed state in this snippet:

17:11:26.803Z INFO SledAgent (InstanceManager): Publishing instance state update to Nexus
    file = sled-agent/src/instance.rs:853
    instance_id = b246f449-51be-4da3-86c3-31397a9418dd
    propolis_id = cb921ea9-ade2-47fc-97a7-ab6f38253116
    state = SledVmmState { vmm_state: VmmRuntimeState { state: Stopping, gen: Generation(7), time_updated: 2025-04-15T17:11:26.803355949Z }, migration_in: None, migration_out: None }
17:11:26.840Z INFO SledAgent (InstanceManager): observed new Propolis state
    file = sled-agent/src/instance.rs:1003
    instance_id = b246f449-51be-4da3-86c3-31397a9418dd
    propolis_id = cb921ea9-ade2-47fc-97a7-ab6f38253116
    state = ObservedPropolisState { vmm_state: PropolisInstanceState(Destroyed), migration_in: None, migration_out: None, time: 2025-04-15T17:11:26.840922199Z }
17:11:26.840Z INFO SledAgent (InstanceManager): updated state after observing Propolis state change
    file = sled-agent/src/instance.rs:1018
    instance_id = b246f449-51be-4da3-86c3-31397a9418dd
    new_vmm_state = VmmRuntimeState { state: Destroyed, gen: Generation(8), time_updated: 2025-04-15T17:11:26.840922199Z }
    propolis_id = cb921ea9-ade2-47fc-97a7-ab6f38253116
17:12:38.247Z WARN SledAgent (dropshot (SledAgent)): request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60000202
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:129::30]:40445
    req_id = 1540b3d8-c28b-4131-9c46-cc8dc434b33f
    uri = /vmms/cb921ea9-ade2-47fc-97a7-ab6f38253116/state
17:12:38.254Z WARN SledAgent (dropshot (SledAgent)): request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 59999725
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:103::4]:59963
    req_id = 9d67b79d-a7f0-41dc-8408-2efbbb638697
    uri = /vmms/cb921ea9-ade2-47fc-97a7-ab6f38253116/state

The "updated state after observing Propolis state change" message indicates we made it here:

omicron/sled-agent/src/instance.rs

Lines 937 to 951 in 1cb9fed

	let response = match update {
	InstanceMonitorUpdate::State(state) => {
	self.observe_state(&ObservedPropolisState::new(&state));
	// If Propolis still has an active VM, just publish this state
	// update and resume normal operation. Otherwise, go through the
	// Propolis teardown sequence.
	if !self.state.vmm_is_halted() {
	self.publish_state_to_nexus().await;
	ControlFlow::Continue(())
	} else {
	self.terminate().await;
	ControlFlow::Break(())
	}
	}

Since the VMM is now Destroyed, this should take the terminate branch, which calls remove_propolis_zone:

omicron/sled-agent/src/instance.rs

Lines 1446 to 1498 in 1cb9fed

	/// Immediately terminates this instance's Propolis zone and cleans up any
	/// runtime objects associated with the instance.
	///
	/// This routine is safe to call even if the instance's zone was never
	/// started. It is also safe to call multiple times on a single instance.
	async fn remove_propolis_zone(&mut self) {
	let zname = propolis_zone_name(&self.propolis_id);
	// First fetch the running state.
	//
	// If there is nothing here, then there is no `RunningZone`, and so
	// there's no zone or resources to clean up at all.
	let mut running_state = if let Some(state) = self.running_state.take() {
	state
	} else {
	debug!(
	self.log,
	"Instance::terminate() called with no running state"
	);
	return;
	};
	// Ask the sled-agent's metrics task to stop tracking statistics for our
	// control VNIC and any OPTE ports in the zone as well.
	self.metrics_queue
	.untrack_zone_links(&running_state.running_zone)
	.await;
	// Take a zone bundle whenever this instance stops.
	if let Err(e) = self
	.zone_bundler
	.create(
	&running_state.running_zone,
	ZoneBundleCause::TerminatedInstance,
	)
	.await
	{
	error!(
	self.log,
	"Failed to take zone bundle for terminated instance";
	"zone_name" => &zname,
	"reason" => ?e,
	);
	}
	// Ensure that no zone exists. This succeeds even if no zone was ever
	// created.
	// NOTE: we call`Zones::halt_and_remove_logged` directly instead of
	// `RunningZone::stop` in case we're called between creating the
	// zone and assigning `running_state`.
	warn!(self.log, "Halting and removing zone: {}", zname);
	let result = tokio::time::timeout(

The VMM was previously running, so running_state is Some and this routine should eventually reach the "Halting and removing zone" logging statement on line 1497. However, this isn't visible in the logs, and checking the sled shows that the Propolis zone is still up (and correctly reporting that it's in the Destroyed state). Suspicious!

If we look more closely at the e04e VMM from the OP, we see something even stranger:

17:11:56.669Z INFO SledAgent (InstanceManager): Started propolis in zone: oxz_propolis-server_e04e30ee-2a22-4989-ba39-79074c0c6d9f
    file = sled-agent/src/instance.rs:2320
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
17:11:56.729Z INFO SledAgent (InstanceManager): Propolis SMF service is online
    file = sled-agent/src/instance.rs:2331
    instance_id = 33fca24f-6e8f-4e1d-9aaf-ecc8faefeeeb
    propolis_id = e04e30ee-2a22-4989-ba39-79074c0c6d9f
17:12:53.302Z WARN SledAgent (dropshot (SledAgent)): request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 59994932
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:101::21]:55219
    req_id = 16cf7cd8-bc56-47f0-9b7e-b1dcb3b7d2b3
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state
17:13:38.591Z WARN SledAgent (dropshot (SledAgent)): request handling cancelled (client disconnected)
    file = /home/alan/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:801
    latency_us = 60002289
    local_addr = [fd00:1122:3344:101::1]:12345
    method = GET
    remote_addr = [fd00:1122:3344:103::4]:55904
    req_id = b72721d7-3de9-4603-88f3-e01092d371fe
    uri = /vmms/e04e30ee-2a22-4989-ba39-79074c0c6d9f/state

That "SMF service is online" log line is from here:

omicron/sled-agent/src/instance.rs

Lines 2326 to 2354 in 1cb9fed

	self.zone_builder_factory
	.zones_api()
	.wait_for_service(Some(&zname), &fmri, self.log.clone())
	.await
	.map_err(|_| Error::Timeout(fmri.to_string()))?;
	info!(self.log, "Propolis SMF service is online");
	// Notify the metrics task about the instance zone's datalinks.
	if !self.metrics_queue.track_zone_links(&running_zone).await {
	error!(
	self.log,
	"Failed to track one or more datalinks in the zone, \
	some metrics will not be produced";
	"zone_name" => running_zone.name(),
	);
	}
	// 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,
	));
	// Although the instance is online, the HTTP server may not be running
	// yet. Wait for it to respond to requests, so users of the instance
	// don't need to worry about initialization races.
	wait_for_http_server(&self.log, &client).await?;

Almost immediately after the zone is started, sled-agent tries to create a Propolis client and ping the new Propolis server with it. This should produce either a "Propolis HTTP server online" message or a warning about how the server is unreachable, but neither of these appears in the logs. In this case, the Propolis server is online, but its logs show that its Dropshot server never serviced any requests, and the server isn't hosting a VM.

A quick pstack on the sled-agent process shows no busy-waiting threads or threads stuck on OS locks, which suggests that whatever we're stuck on is wedged at an await point.

With that in mind: one thing the VM startup and shutdown paths have in common is a call to the sled-agent instrumentation infrastructure to set up kstat tracking for the new Propolis zone's OPTE links:

omicron/sled-agent/src/instance.rs

Lines 2333 to 2341 in 1cb9fed

	// Notify the metrics task about the instance zone's datalinks.
	if !self.metrics_queue.track_zone_links(&running_zone).await {
	error!(
	self.log,
	"Failed to track one or more datalinks in the zone, \
	some metrics will not be produced";
	"zone_name" => running_zone.name(),
	);
	}

In the VM startup case, this is the only thing that happens between the point where sled-agent launches a new Propolis zone and the point where it sends a request to the new Propolis server. That strongly suggests sled-agent is getting hung up on this call to track_zone_links.

Following the bouncing ball a little bit: track_zone_links sends a message to a singleton MetricsRequestQueue (shared by all instances on the sled). The queue handler, metrics_task, calls add_datalink and remove_datalink in response to these zone-change requests, which in turn call KstatSampler::add_target, which sends a request that's handled in KstatSamplerWorker::Run:

omicron/oximeter/instruments/src/kstat/sampler.rs

Lines 402 to 659 in 1cb9fed

	loop {
	tokio::select! {
	_ = creation_prune_interval.tick() => {
	if let Err(e) = self.prune_creation_times() {
	error!(
	self.log,
	"failed to prune creation times";
	"error" => ?e,
	);
	}
	}
	maybe_id = sample_timeouts.next(), if !sample_timeouts.is_empty() => {
	let Some((id, interval)) = maybe_id else {
	unreachable!();
	};
	match self.sample_one(id) {
	Ok(Some(samples)) => {
	if samples.is_empty() {
	debug!(
	self.log,
	"no new samples from target, requeueing";
	"id" => ?id,
	);
	sample_timeouts.push(YieldIdAfter::new(id, interval));
	continue;
	}
	let n_samples = samples.len();
	debug!(
	self.log,
	"pulled samples from target";
	"id" => ?id,
	"n_samples" => n_samples,
	);
	// Append any samples to the per-target queues.
	//
	// This returns None if there was no queue, and logs
	// the error internally. We'll just go round the
	// loop again in that case.
	let Some(n_overflow_samples) =
	self.append_per_target_samples(id, samples) else {
	continue;
	};
	// Safety: We only get here if the `sample_one()`
	// method works, which means we have a record of the
	// target, and it's not expired.
	if n_overflow_samples > 0 {
	let SampledObject::Kstat(ks) = self.targets.get(&id).unwrap() else {
	unreachable!();
	};
	self.increment_dropped_sample_counter(
	id,
	ks.target.name().to_string(),
	n_overflow_samples,
	).await;
	}
	// Send the total number of samples we've actually
	// taken and the number we've appended over to any
	// testing code which might be listening.
	#[cfg(all(test, target_os = "illumos"))]
	sample_count_tx.send(SampleCounts {
	total: n_samples,
	overflow: n_overflow_samples,
	}).unwrap();
	trace!(
	self.log,
	"re-queueing target for sampling";
	"id" => ?id,
	"interval" => ?interval,
	);
	sample_timeouts.push(YieldIdAfter::new(id, interval));
	}
	Ok(None) => {
	debug!(
	self.log,
	"sample timeout triggered for non-existent target";
	"id" => ?id,
	);
	}
	Err(Error::Expired(expiration)) => {
	error!(
	self.log,
	"expiring kstat after too many failures";
	"id" => ?id,
	"reason" => ?expiration.reason,
	"error" => ?expiration.error,
	);
	let _ = self.targets.insert(id, SampledObject::Expired(expiration));
	self.increment_expired_target_counter().await;
	}
	Err(e) => {
	error!(
	self.log,
	"failed to sample kstat target, requeueing";
	"id" => ?id,
	"error" => ?e,
	);
	sample_timeouts.push(YieldIdAfter::new(id, interval));
	}
	}
	}
	maybe_request = self.inbox.recv() => {
	let Some(request) = maybe_request else {
	debug!(self.log, "inbox returned None, exiting");
	return;
	};
	trace!(
	self.log,
	"received request on inbox";
	"request" => ?request,
	);
	match request {
	Request::AddTarget {
	target,
	details,
	reply_tx,
	} => {
	match self.add_target(target, details) {
	Ok(id) => {
	let timeout = YieldIdAfter::new(id, details.interval);
	sample_timeouts.push(timeout);
	trace!(
	self.log,
	"added target with timeout";
	"id" => ?id,
	"details" => ?details,
	);
	match reply_tx.send(Ok(id)) {
	Ok(_) => trace!(self.log, "sent reply"),
	Err(e) => error!(
	self.log,
	"failed to send reply";
	"id" => ?id,
	"error" => ?e,
	)
	}
	}
	Err(e) => {
	error!(
	self.log,
	"failed to add target";
	"error" => ?e,
	);
	match reply_tx.send(Err(e)) {
	Ok(_) => trace!(self.log, "sent reply"),
	Err(e) => error!(
	self.log,
	"failed to send reply";
	"error" => ?e,
	)
	}
	}
	}
	}
	Request::UpdateTarget { target, details, reply_tx } => {
	match self.update_target(target, details) {
	Ok(id) => {
	let timeout = YieldIdAfter::new(id, details.interval);
	sample_timeouts.push(timeout);
	trace!(
	self.log,
	"updated target with timeout";
	"id" => ?id,
	"details" => ?details,
	);
	match reply_tx.send(Ok(id)) {
	Ok(_) => trace!(self.log, "sent reply"),
	Err(e) => error!(
	self.log,
	"failed to send reply";
	"id" => ?id,
	"error" => ?e,
	)
	}
	}
	Err(e) => {
	error!(
	self.log,
	"failed to update target";
	"error" => ?e,
	);
	match reply_tx.send(Err(e)) {
	Ok(_) => trace!(self.log, "sent reply"),
	Err(e) => error!(
	self.log,
	"failed to send reply";
	"error" => ?e,
	)
	}
	}
	}
	}
	Request::RemoveTarget { id, reply_tx } => {
	self.targets.remove(&id);
	if let Some(remaining_samples) = self.samples.lock().unwrap().remove(&id) {
	if !remaining_samples.is_empty() {
	warn!(
	self.log,
	"target removed with queued samples";
	"id" => ?id,
	"n_samples" => remaining_samples.len(),
	);
	}
	}
	match reply_tx.send(Ok(())) {
	Ok(_) => trace!(self.log, "sent reply"),
	Err(e) => error!(
	self.log,
	"failed to send reply";
	"error" => ?e,
	)
	}
	}
	Request::TargetStatus { id, reply_tx } => {
	trace!(
	self.log,
	"request for target status";
	"id" => ?id,
	);
	let response = match self.targets.get(&id) {
	None => Err(Error::NoSuchTarget),
	Some(SampledObject::Kstat(k)) => {
	Ok(TargetStatus::Ok {
	last_collection: k.time_of_last_collection,
	})
	}
	Some(SampledObject::Expired(e)) => {
	Ok(TargetStatus::Expired {
	reason: e.reason,
	error: e.error.to_string(),
	expired_at: e.expired_at,
	})
	}
	};
	match reply_tx.send(response) {
	Ok(_) => trace!(self.log, "sent reply"),
	Err(e) => error!(
	self.log,
	"failed to send reply";
	"id" => ?id,
	"error" => ?e,
	),
	}
	}
	#[cfg(all(test, target_os = "illumos"))]
	Request::CreationTimes { reply_tx } => {
	debug!(self.log, "request for creation times");
	reply_tx.send(self.creation_times.clone()).unwrap();
	debug!(self.log, "sent reply for creation times");
	}
	}
	}
	}
	}

The self.inbox.recv() arm of this select! handles the "add target" messages. The sample_timeouts branch of this select has an await point when it calls increment_dropped_sample_counter, which sends to a bounded channel:

omicron/oximeter/instruments/src/kstat/sampler.rs

Lines 840 to 847 in 1cb9fed

	match self.self_stat_queue.send(sample).await {
	Ok(_) => trace!(self.log, "sent dropped sample counter stat"),
	Err(e) => error!(
	self.log,
	"failed to send dropped sample counter to self stat queue";
	"error" => ?e,
	),
	}

That channel is created here:

omicron/oximeter/instruments/src/kstat/sampler.rs

Lines 1121 to 1134 in 1cb9fed

	pub fn with_sample_limit(
	log: &Logger,
	limit: usize,
	) -> Result<Self, Error> {
	let samples = Arc::new(Mutex::new(BTreeMap::new()));
	let (self_stat_tx, self_stat_rx) = mpsc::channel(4096);
	let (outbox, inbox) = mpsc::channel(1);
	let worker = KstatSamplerWorker::new(
	log.new(o!("component" => "kstat-sampler-worker")),
	inbox,
	self_stat_tx,
	samples.clone(),
	limit,
	)?;

And it's read from here:

omicron/oximeter/instruments/src/kstat/sampler.rs

Lines 1236 to 1263 in 1cb9fed

	impl oximeter::Producer for KstatSampler {
	fn produce(
	&mut self,
	) -> Result<Box<(dyn Iterator<Item = Sample>)>, MetricsError> {
	// Swap the _entries_ of all the existing per-target sample queues, but
	// we need to leave empty queues in their place. I.e., we can't remove
	// keys.
	let mut samples = Vec::new();
	for (_id, queue) in self.samples.lock().unwrap().iter_mut() {
	samples.append(queue);
	}
	// Append any self-stat samples as well.
	let mut rx = self.self_stat_rx.lock().unwrap();
	loop {
	match rx.try_recv() {
	Ok(sample) => samples.push(sample),
	Err(mpsc::error::TryRecvError::Empty) => break,
	Err(mpsc::error::TryRecvError::Disconnected) => {
	panic!("kstat stampler self-stat queue tx disconnected");
	}
	}
	}
	drop(rx);
	Ok(Box::new(samples.into_iter()))
	}
	}

This suggests a possible problem: if Oximeter doesn't regularly query the KstatSampler producer, the self_stat channel can fill up, which prevents the sampler worker from processing new requests, which puts backpressure on the MetricsRequestQueue, which blocks instance workers that are trying to set up/tear down Propolis zones.

The next question here (which I don't believe we've bottomed out on yet) is why this produce call isn't being reached. On our debugging call we observed some warning- and error-level statements in the Oximeter logs, but (for my part) I haven't completely pieced together how these would cause the sled-agent producer never to be successfully queried again.

[hawkw]

This suggests a possible problem: if Oximeter doesn't regularly query the KstatSampler producer, the self_stat channel can fill up, which prevents the sampler worker from processing new requests, which puts backpressure on the MetricsRequestQueue, which blocks instance workers that are trying to set up/tear down Propolis zones.

Yeah, I am fairly confident this is one of the issues we should resolve --- although, as you mentioned, the root cause appears to be that the kstat samples aren't being collected by Oximeter, which we still don't have a great handle on. The problem, as I'm describing it, is that there is a single "backpressure domain" that extends all the way from the producer endpoint to the InstanceRunner operations, since the metrics task will await send calls on the channel to the producer endpoint, and consumes messages from the request queue that InstanceRunner tasks send to.

Potential solutions to this include (non-exhaustively):

• Using mpsc::Sender::try_send() rather than mpsc::Sender::send() for the kstat sample channel. This is the obvious naive solution, but it has the rather unfortunate downside of discarding the latest samples when the channel is full, which doesn't really seem what we want.
• Using a different, more ring-buffer-like channel that discards the oldest samples first when the channel is full. IMHO, if we start discarding samples, discarding oldest first is probably more desirable, so that if samples are eventually collected, we've retained the most recent (and thus most relevant) data. I did something like this in the MGS Oximeter metrics implementation by using Tokio's tokio::sync::broadcast channel rather than a tokio::sync::mpsc channel. The broadcast channel, as a multi-producer, multi-consumer channel, will drop old messages when a receiver lags behind, which can be used to implement the "classic ring buffer" behavior.
• Decoupling the requests from InstanceRunners to track/untrack links from the kstat sample queue entirely. It's possible we can keep the current behavior for both channels, but make one of them filling up not exert backpressure on the other. This might involve something like running the kstat bits in a separate task which communicates with the task that manages what links are tracked via something other than a queue-based channel (e.g. a shared hashmap in a tokio::sync::watch) or something like that. I'm not sure how practical this is OTTOMH as I haven't looked too deeply at this code, but it could potentially allow us to decouple the two "backpressure domains" without starting to discard samples.

[gjcolombo]

@leftwo, @bnaecker, and I stared at this for a while longer and think we have a bead on the problem.

It turns out that the reason sled-agent's metrics producer isn't being queried is that Oximeter doesn't think that producer exists:

OXIMETER_ID                          ID                                   TIME_CREATED             TIME_MODIFIED            KIND     IP                       PORT  INTERVAL     
a53b0dc3-f605-4bdc-bd5d-b2302ebcf48e 8faa6a72-8d01-43b1-8f5a-4b582827d713 2025-04-14T18:34:50.421Z 2025-04-16T17:49:13.853Z Service  fd00:1122:3344:101::21   35980 10       
a53b0dc3-f605-4bdc-bd5d-b2302ebcf48e e05c41d4-3e97-4ba9-a260-8b5bedd17b9f 2025-04-14T17:02:05.880Z 2025-04-16T17:48:50.301Z Service  fd00:1122:3344:103::4    45167 10       
a53b0dc3-f605-4bdc-bd5d-b2302ebcf48e e145261c-a63c-45ac-acd3-18a1fed3aee8 2025-04-15T17:18:14.318Z 2025-04-16T17:49:06.497Z Service  fd00:1122:3344:12a::30   62048 10       

Notice that there are no SledAgent entries in this table. If we look at the beginning of the symptomatic sled-agent logs, we find the following:

16:58:47.714Z WARN SledAgent: failed to register as a producer with Nexus, will retry
    delay = 58.196905353s
    error = "Communication Error: error sending request for url (http://[fd00:1122:3344:102::4]:12221/metrics/producers)"
    file = oximeter/producer/src/lib.rs:420
    sled_id = 34a3ed99-5aa2-4828-b4b9-116e6a1767d6
17:00:00.952Z WARN SledAgent: failed to register as a producer with Nexus, will retry
    delay = 66.889988322s
    error = "Communication Error: error sending request for url (http://[fd00:1122:3344:102::4]:12221/metrics/producers)"
    file = oximeter/producer/src/lib.rs:420
    sled_id = 34a3ed99-5aa2-4828-b4b9-116e6a1767d6

// gjc: 93-minute gap

18:33:43.213Z WARN SledAgent: failed to register as a producer with Nexus, will retry
    delay = 245.81144ms
    error = "Communication Error: error sending request for url (http://[fd00:1122:3344:102::4]:12221/metrics/producers)"
    file = oximeter/producer/src/lib.rs:420
    sled_id = 34a3ed99-5aa2-4828-b4b9-116e6a1767d6
18:33:43.496Z WARN SledAgent: failed to register as a producer with Nexus, will retry
    delay = 293.306648ms
    error = "Communication Error: error sending request for url (http://[fd00:1122:3344:102::4]:12221/metrics/producers)"
    file = oximeter/producer/src/lib.rs:420
    sled_id = 34a3ed99-5aa2-4828-b4b9-116e6a1767d6

The first few failures are preceded by messages from the sled-agent startup sequence. This is consistent with sled-agent coming up, starting its Oximeter producer registration loop, failing to contact Nexus a few times (notice the minute-long backoff delays in the first two messages), and then eventually reaching Nexus and falling silent. But what's up with the subsequent registration failures?

Nexus expects Oximeter producers to re-register themselves periodically in order to remain active (i.e. not subject to garbage collection):

omicron/nexus/metrics-producer-gc/src/lib.rs

Lines 52 to 88 in 2f3776b

	/// Make one garbage collection pass over the metrics producers.
	pub async fn prune_expired_producers(
	opctx: &OpContext,
	datastore: &DataStore,
	expiration: DateTime<Utc>,
	) -> Result<PrunedProducers, Error> {
	// Get the list of expired producers we need to prune.
	let expired_producers =
	ExpiredProducers::new(opctx, datastore, expiration).await?;
	// Build a FuturesUnordered to prune each expired producer.
	let mut all_prunes = expired_producers
	.producer_client_pairs()
	.map(|(producer, client)| async {
	let result = unregister_producer(
	opctx, datastore, producer, client, &opctx.log,
	)
	.await;
	(producer.id(), result)
	})
	.collect::<FuturesUnordered<_>>();
	// Collect all the results.
	let mut successes = BTreeSet::new();
	let mut failures = BTreeMap::new();
	while let Some((id, result)) = all_prunes.next().await {
	match result {
	Ok(()) => {
	successes.insert(id);
	}
	Err(err) => {
	failures.insert(id, err);
	}
	}
	}
	Ok(PrunedProducers { successes, failures })
	}

Sled-agent re-registers itself in this loop:

omicron/oximeter/producer/src/lib.rs

Lines 307 to 341 in 2f3776b

	/// A backround task that periodically renews this producer's lease with Nexus.
	async fn registration_task(
	find_nexus: FindNexus,
	log: Logger,
	endpoint: ApiProducerEndpoint,
	) {
	loop {
	debug!(
	log,
	"registering / renewing oximeter producer lease with Nexus"
	);
	let address = match &find_nexus {
	FindNexus::ByAddr(addr) => *addr,
	FindNexus::WithResolver(resolver) => {
	resolve_nexus_with_backoff(&log, resolver).await
	}
	};
	debug!(log, "using nexus address for registration"; "addr" => ?address);
	let lease_duration =
	register_with_backoff(address, &log, &endpoint).await;
	debug!(log, "registered with nexus successfully");
	// Wait for a reasonable fraction of the renewal period, and then hit
	// 'em again.
	let wait =
	lease_duration.checked_div(RENEWAL_RATE).unwrap_or(lease_duration);
	debug!(
	log,
	"pausing until time to renew lease";
	"lease_duration" => ?lease_duration,
	"wait_period" => ?wait,
	);
	tokio::time::sleep(wait).await;
	}
	}

This code selects a Nexus address via DNS resolution, then passes it to register_with_backoff, which actually calls Nexus's producer registration endpoint (and which logs the "failed to register as a producer" message seen above). There's a TOCTTOU here: if DNS returns a particular Nexus address, and that Nexus is permanently taken offline (e.g. via expungement) before the registration routine can reach it, then the routine will loop forever; eventually, Nexus will decide the producer registration for the relevant sled is too old and will garbage-collect it.

In this case, we happen to know that the chosen Nexus address (102::4:12221) belonged to an expunged Nexus; to corroborate this, we can look at the system's blueprint history and observe that a new blueprint was created at around the time re-registration began to fail:

T ENA ID                                   PARENT                               TIME_CREATED             
      778aeecd-2852-4bca-b4ed-d0c4bfac445b <none>                               2025-04-14T17:00:59.568Z 
      cc6203ef-23ad-4617-83a7-7cc3a4e7a08a 778aeecd-2852-4bca-b4ed-d0c4bfac445b 2025-04-14T18:34:17.435Z 
      d49108a3-42a5-4d84-aec1-1ab95c621fed cc6203ef-23ad-4617-83a7-7cc3a4e7a08a 2025-04-14T18:57:32.620Z 

So, all told, we think we've seen the following here:

1. World begins; environment goes through RSS; all sleds register themselves as Oximeter producers
2. A sled decides to re-register itself as an Oximeter producer and obtains a Nexus address via DNS
3. The sled sits in a loop trying to register with the resolved address
4. Before that sled can successfully register itself, the relevant Nexus goes offline and its sled is expunged
5. Eventually, one of Nexus's metrics producer GC tasks decides that the sled's producer registration is too old and removes it
6. Oximeter therefore stops collecting metrics from that sled
7. The sled's internal KstatSampler queue fills up and ends up exerting backpressure on the entire instance management subsystem, as described above

The two main problems here are that

1. if Oximeter stops querying sled-agent metrics for long enough, then instance start and stop grind to a halt; I think we'll track that issue in this ticket
2. sled-agent's registration loop should try re-resolving addresses every once in a while; this is tracked by DNS-based producer registration should query DNS more frequently #6158

[gjcolombo]

One addendum: after investigating all of this, we curled the sled-agent metrics collection endpoint on the wedged sled, and confirmed that this immediately unwedged all its blocked instances.

[bnaecker]

The other relevant issue here on the internals of the sled-agent link tracking is #7869.

[leftwo]

Why the three instances would not "activate" after propolis-server received the information it needed is #7398

[bnaecker]

I've been playing around with this, and although I like the watch approach in many ways, I don't think it's a great fit in this case. I'm happy to go into details, but I think I'm going to fix the most egregious bugs here:

• moving from a bounded queue with blocking send() calls to a ring-buffer, like the broadcast channel
• changing the API of the MetricsRequestQueue to better report errors, and possibly use try_send() instead of send().