blueprint_executor unable to backfill omicron zones after getting stuck in waiting for time sync

[askfongjojo]

I expunged a disk on a sled in the dublin lab (sled 15) that was expected to lead to these diffs (fixed - were inverted originally):

    datasets:
    -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
    dataset name                                                                                                dataset id                             disposition    quota     reservation   compression
    -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
...  
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/cockroachdb                                                  a042ad80-9378-462d-abe2-4ffbfcf1b781   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crucible                                                           3465507a-8666-4b95-bab3-e6b1a41b13e7   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/clickhouse                                                   b77683cb-06d3-4ff8-8ea0-273e028aebdb   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/internal_dns                                                 ebedcdd9-251b-49b6-8bf3-08caf663e473   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/zone                                                         e9833406-4481-4b22-9ed1-8a576c1f389e   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/zone/oxz_clickhouse_fdeabeab-c7d9-4368-a6af-1a339a00310b     2e9965d7-8982-4f03-af6b-c83543da4388   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/zone/oxz_cockroachdb_84852644-b3a1-4816-8ea2-84892d885c39    dccf1567-cd53-4fcb-a755-e59d9fff122d   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/zone/oxz_crucible_d0ec1728-9b33-41cf-ad07-02f498d77247       c71dab11-3053-4610-92ab-1aefd12246a2   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/zone/oxz_internal_dns_fd45a90b-4670-4ecc-886a-b86e66ab1838   71301b1d-34ed-4e35-a74d-ddf1676188db   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/zone/oxz_ntp_ad78e840-9360-4b8d-9287-4dd19e6a51e1            943373eb-2190-4e04-a65c-e30480a9aa72   - in service   none      none          off        
     └─                                                                                                                                                + expunged                                        
*   oxp_342b9661-b423-4aca-8c63-531252fdc722/crypt/debug                                                        b8bd16f2-66b4-4e59-a483-9fb2fd06bf36   - in service   100 GiB   none          gzip-9     
     └─                                                                                                                                                + expunged                                        
+   oxp_14955990-3463-4734-a653-852250f6b275/crypt/cockroachdb                                                  5b00771f-f9d0-47ac-b014-4e2e6329bd42   in service     none      none          off        
+   oxp_14955990-3463-4734-a653-852250f6b275/crypt/clickhouse                                                   b2c0184b-ff2f-40f5-b387-c6ace38c1c29   in service     none      none          off        
+   oxp_14955990-3463-4734-a653-852250f6b275/crypt/zone/oxz_clickhouse_e0504fdd-5c45-4209-aa03-edafc8d94393     a3b7224b-131f-4172-8903-dafbe2c0057a   in service     none      none          off        
+   oxp_14955990-3463-4734-a653-852250f6b275/crypt/zone/oxz_cockroachdb_714185f6-3407-4366-a060-a4623c92a962    42298e40-b942-409d-8863-4fb318f95932   in service     none      none          off        
+   oxp_14955990-3463-4734-a653-852250f6b275/crypt/zone/oxz_ntp_558843e4-96ad-4bf6-b4c2-200bf0fb8520            157d682b-fe04-48e1-90d7-f1253fe844f8   expunged       none      none          off        
+   oxp_14955990-3463-4734-a653-852250f6b275/crypt/zone/oxz_ntp_e81dd898-d063-41b3-a13a-418a8c031345            21292d97-1166-4c0b-aa72-f4374735e38c   in service     none      none          off      


    omicron zones:
    ---------------------------------------------------------------------------------------------------------------
    zone type      zone id                                image source      disposition      underlay IP           
    ---------------------------------------------------------------------------------------------------------------
...
*   boundary_ntp   ad78e840-9360-4b8d-9287-4dd19e6a51e1   install dataset   - in service     fd00:1122:3344:102::10
     └─                                                                     + expunged ⏳                           
*   clickhouse     fdeabeab-c7d9-4368-a6af-1a339a00310b   install dataset   - in service     fd00:1122:3344:102::5 
     └─                                                                     + expunged ⏳                           
*   cockroach_db   84852644-b3a1-4816-8ea2-84892d885c39   install dataset   - in service     fd00:1122:3344:102::3 
     └─                                                                     + expunged ⏳                           
*   crucible       d0ec1728-9b33-41cf-ad07-02f498d77247   install dataset   - in service     fd00:1122:3344:102::6 
     └─                                                                     + expunged ⏳                           
*   internal_dns   fd45a90b-4670-4ecc-886a-b86e66ab1838   install dataset   - in service     fd00:1122:3344:2::1   
     └─                                                                     + expunged ⏳                           
+   boundary_ntp   e81dd898-d063-41b3-a13a-418a8c031345   install dataset   in service       fd00:1122:3344:102::22
+   clickhouse     e0504fdd-5c45-4209-aa03-edafc8d94393   install dataset   in service       fd00:1122:3344:102::23
+   cockroach_db   714185f6-3407-4366-a060-a4623c92a962   install dataset   in service       fd00:1122:3344:102::24
+   internal_ntp   558843e4-96ad-4bf6-b4c2-200bf0fb8520   install dataset   expunged ⏳       fd00:1122:3344:102::21

The executor ended with the following warnings:

root@oxz_switch0:~# omdb nexus background-tasks show blueprint_executor 
task: "blueprint_executor"
  configured period: every 1m
  currently executing: no
  last completed activation: iter 292, triggered by a periodic timer firing
    started at 2025-03-19T05:37:35.210Z (49s ago) and ran for 18866ms
    target blueprint: e7894fab-7808-4e40-b5db-025972456c79                                                                                                                                                                                                                                                                                                                                                                                   
    execution:        enabled                                                                                                                                                                                                                                                                                                                                                                                                                
    status:           completed (13 steps)                                                                                                                                                                                                                                                                                                                                                                                                   
    warning:          at: Deploy single-node clickhouse cluster: failed to initialize single-node clickhouse database: Communication Error: error sending request for url (http://[fd00:1122:3344:102::23]:8888/init)                                                                                                                                                                                         
...

The complete output is attached here.

blueprint_executor_output.txt

Here are some relevant error messages from the sled-agent on the sled involved:

06:36:35.697Z INFO SledAgent (dropshot (SledAgent)): request completed
    error_message_external = Service Unavailable
    error_message_internal = Time not yet synchronized
    file = /home/build/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/dropshot-0.16.0/src/server.rs:855
    latency_us = 505909
    local_addr = [fd00:1122:3344:102::1]:12345
    method = PUT
    remote_addr = [fd00:1122:3344:104::5]:35762
    req_id = 4f9c25ad-4130-4c29-828e-3d6e6f893b97
    response_code = 503
    uri = /omicron-config
06:36:36.942Z WARN SledAgent (ServiceManager): Zone failed to start
    file = sled-agent/src/services.rs:3391
    zone = oxz_cockroachdb_714185f6-3407-4366-a060-a4623c92a962
06:36:36.943Z WARN SledAgent (ServiceManager): Zone failed to start
    file = sled-agent/src/services.rs:3391
    zone = oxz_clickhouse_e0504fdd-5c45-4209-aa03-edafc8d94393

[askfongjojo]

Dublin is on these commits btw:

root@oxz_switch0:~# pilot host ls
CUBBY IP                        SERIAL      IMAGE
14    fe80::aa40:25ff:fe04:351  BRM42220026 ci 52d7df4/9a14106 2025-03-18 21:44
15    fe80::aa40:25ff:fe04:614  BRM27230037 ci 52d7df4/9a14106 2025-03-18 21:44
16    fe80::aa40:25ff:fe04:6d3  BRM23230018 ci 52d7df4/9a14106 2025-03-18 21:44
17    fe80::aa40:25ff:fe04:851  BRM23230010 ci 52d7df4/9a14106 2025-03-18 21:44

The ntp zone that's also expunged in that same physical disk was a boundary ntp. It seemed to have been recreated successfully but I was unable to reach 1.1.1.1 from within the zone. I compared its opte port nat and router entries with the other boundary ntp's opte port (on sled 14) and didn't see anything that was obviously wrong:

BRM27230037 # zlogin oxz_ntp_e81dd898-d063-41b3-a13a-418a8c031345
[Connected to zone 'oxz_ntp_e81dd898-d063-41b3-a13a-418a8c031345' pts/3]
Last login: Wed Mar 19 06:05:33 on pts/3
The illumos Project     helios-2.0.23277        March 2025
root@oxz_ntp_e81dd898:~# ifconfig
lo0: flags=2001000849<UP,LOOPBACK,RUNNING,MULTICAST,IPv4,VIRTUAL> mtu 8232 index 1
        inet 127.0.0.1 netmask ff000000 
opte13: flags=1005843<UP,BROADCAST,RUNNING,MULTICAST,MULTI_BCAST,DHCP,IPv4> mtu 1500 index 2
        inet 172.30.3.6 netmask ffffffff broadcast 172.30.3.6
        ether a8:40:25:ff:80:2 
oxControlService15: flags=1001000842<BROADCAST,RUNNING,MULTICAST,IPv4,FIXEDMTU> mtu 9000 index 3
        inet 0.0.0.0 netmask 0 
        ether 2:8:20:d6:8:27 
lo0: flags=2002000849<UP,LOOPBACK,RUNNING,MULTICAST,IPv6,VIRTUAL> mtu 8252 index 1
        inet6 ::1/128 
opte13: flags=20002001840<RUNNING,MULTICAST,MULTI_BCAST,IPv6> mtu 1500 index 2
        inet6 ::/0 
        ether a8:40:25:ff:80:2 
oxControlService15: flags=21002004841<UP,RUNNING,MULTICAST,DHCP,IPv6,FIXEDMTU> mtu 9000 index 3
        inet6 fe80::8:20ff:fed6:827/10 
        ether 2:8:20:d6:8:27 
oxControlService15:1: flags=21002000841<UP,RUNNING,MULTICAST,IPv6,FIXEDMTU> mtu 9000 index 3
        inet6 fd00:1122:3344:102::22/64 
root@oxz_ntp_e81dd898:~# exit
logout

[Connection to zone 'oxz_ntp_e81dd898-d063-41b3-a13a-418a8c031345' pts/3 closed]
BRM27230037 # opteadm dump-layer -p opte13 nat
Port opte13 - Layer nat
======================================================================
Inbound Flows
----------------------------------------------------------------------
PROTO  SRC IP  SPORT  DST IP  DPORT  HITS  ACTION

Outbound Flows
----------------------------------------------------------------------
PROTO  SRC IP  SPORT  DST IP  DPORT  HITS  ACTION

Inbound Rules
----------------------------------------------------------------------
ID   PRI  HITS  PREDICATES  ACTION
DEF  --   0     --          "allow"

Outbound Rules
----------------------------------------------------------------------
ID   PRI  HITS  PREDICATES                    ACTION
0    100  95    inner.ether.ether_type=IPv4   "Stateful: 172.20.29.5:16384-32767"
                meta: router-target=ig        
                                              
1    255  0     meta: router-target-class=ig  "Deny"
DEF  --   0     --                            "allow"

BRM27230037 # opteadm dump-layer -p opte13 router
Port opte13 - Layer router
======================================================================
Inbound Flows
----------------------------------------------------------------------
PROTO  SRC IP  SPORT  DST IP  DPORT  HITS  ACTION

Outbound Flows
----------------------------------------------------------------------
PROTO  SRC IP  SPORT  DST IP  DPORT  HITS  ACTION

Inbound Rules
----------------------------------------------------------------------
ID   PRI  HITS  PREDICATES  ACTION
DEF  --   0     --          "allow"

Outbound Rules
----------------------------------------------------------------------
ID   PRI  HITS  PREDICATES                           ACTION
5    27   0     inner.ip.dst=172.30.2.0/24           "Meta: Target = Subnet: 172.30.2.0/24"
4    27   0     inner.ip.dst=172.30.3.0/24           "Meta: Target = Subnet: 172.30.3.0/24"
3    27   0     inner.ip.dst=172.30.1.0/24           "Meta: Target = Subnet: 172.30.1.0/24"
2    75   122   inner.ip.dst=0.0.0.0/0               "Meta: Target = IG(None)"
6    139  0     inner.ip6.dst=fd77:e9d2:9cd9:1::/64  "Meta: Target = Subnet: fd77:e9d2:9cd9:1::/64"
1    139  0     inner.ip6.dst=fd77:e9d2:9cd9:2::/64  "Meta: Target = Subnet: fd77:e9d2:9cd9:2::/64"
0    139  0     inner.ip6.dst=fd77:e9d2:9cd9:3::/64  "Meta: Target = Subnet: fd77:e9d2:9cd9:3::/64"
7    267  0     inner.ip6.dst=::/0                   "Meta: Target = IG(None)"
DEF  --   0     --                                   "deny"

[FelixMcFelix]

It doesn't look like the OPTE port is seeing anything inbound. We could be losing those packets on the way out, or the replies on the way back in.

BRM27230037 # kstat -m xde -n opte13
module: xde                             instance: 0
name:   opte13                          class:    net
        crtime                          17404.434950110
        in_bypass                       0
        in_drop                         0
        in_drop_handle_pkt              0
        in_drop_layer                   0
        in_drop_tcp_err                 0
        in_hairpin                      0
        in_modified                     0
        in_process_err                  0
        in_uft_hit                      0
        in_uft_miss                     0
        out_bypass                      0
        out_drop                        297
        out_drop_handle_pkt             96
        out_drop_layer                  201
        out_drop_tcp_err                0
        out_hairpin                     70
        out_modified                    484
        out_process_err                 0
        out_uft_hit                     172
        out_uft_miss                    679
        snaptime                        43990.492560452

It looks as though we have SNAT rules in place in the switches:

root@oxz_switch0:~# swadm nat ls
External IP   Port low  Port high  Internal IP            Inner MAC          VNI
172.20.29.1   0         65535      fd00:1122:3344:104::1  a8:40:25:ff:80:00  100
172.20.29.2   0         65535      fd00:1122:3344:102::1  a8:40:25:ff:ef:56  100
172.20.29.3   0         65535      fd00:1122:3344:103::1  a8:40:25:ff:bc:d8  100
172.20.29.4   0         65535      fd00:1122:3344:104::1  a8:40:25:ff:a9:41  100
172.20.29.5   0         16383      fd00:1122:3344:101::1  a8:40:25:ff:80:01  100
172.20.29.5   16384     32767      fd00:1122:3344:102::1  a8:40:25:ff:b5:f0  100
172.20.29.11  0         16383      fd00:1122:3344:102::1  a8:40:25:f0:00:00  5757293
...

root@oxz_switch1:~# swadm nat ls
External IP   Port low  Port high  Internal IP            Inner MAC          VNI
172.20.29.1   0         65535      fd00:1122:3344:104::1  a8:40:25:ff:80:00  100
172.20.29.2   0         65535      fd00:1122:3344:102::1  a8:40:25:ff:ef:56  100
172.20.29.3   0         65535      fd00:1122:3344:103::1  a8:40:25:ff:bc:d8  100
172.20.29.4   0         65535      fd00:1122:3344:104::1  a8:40:25:ff:a9:41  100
172.20.29.5   0         16383      fd00:1122:3344:101::1  a8:40:25:ff:80:01  100
172.20.29.5   16384     32767      fd00:1122:3344:102::1  a8:40:25:ff:b5:f0  100
172.20.29.11  0         16383      fd00:1122:3344:102::1  a8:40:25:f0:00:00  5757293
...

swadm table dump pipe.Ingress.nat_ingress.ingress_ipv4 on each switch corroborates this. snooping on the underlay looks like we're getting some form of reply?

root@oxz_ntp_e81dd898:~# ping 1.1.1.1
no answer from 1.1.1.1

...

BRM27230037 # snoop -rd cxgbe0 'udp and dst port 6081'
Using device cxgbe0 (promiscuous mode)
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=110
fd00:1122:3344:102::1 -> fd5c:cfec:26f1:9520::1 UDP D=6081 S=6053 LEN=114
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=118
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=110
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=110
fd00:1122:3344:102::1 -> fd5c:cfec:26f1:9520::1 UDP D=6081 S=6053 LEN=114
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=118
fd00:1122:3344:102::1 -> fd5c:cfec:26f1:9520::1 UDP D=6081 S=6053 LEN=114
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=118
fd00:1122:3344:102::1 -> fd5c:cfec:26f1:9520::1 UDP D=6081 S=6053 LEN=114
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=118
fd00:1122:3344:102::1 -> fd5c:cfec:26f1:9520::1 UDP D=6081 S=6053 LEN=114
 UNSPECIFIED -> fd00:1122:3344:102::1 UDP D=6081 S=6081 LEN=118

The above took a few tries to have request and reply traffic both hashed onto cxgbe0 -- but they are there. So why isn't our OPTE port seeing them? Let's dig into a pcap here (snoop -rd cxgbe0 -o /tmp/ks.pcap 'udp and dst port 6081', stored now on /staff/kyle/omicron-7824.pcap).

OPTE is looking for two things -- any packet's inner frame hitting this port should have the destination mac address a8:40:25:ff:80:2 (visible in opteadm list-ports, or ifconfig in the zone), and that the VNI should be 100. Picking one of these packets at random:

...It's coming in with the wrong destination MAC address. Compare against the swadm nat ls output above, which is rewriting to a8:40:25:ff:b5:f0 -- one of these halves is programmed with the wrong MAC address.

[askfongjojo]

Here is the state.json output file from omdb reconfigurator export.

[askfongjojo]

For more context, this is the third disk I expunged. The first two went well (and I checked the two boundary_ntp's outbound access after the blueprint_executor reported it's completion every time). I generated some additional blueprints in between just to see if the state has changed after cleanup. The ones I actually set as target are in the following:

root@oxz_switch0:~# history | egrep 'enabled|expunge-disk'
   11  omdb -w nexus sleds expunge-disk 08ea1878-0c3e-4d6f-aef8-890df175e72b 
   18  omdb -w nexus blueprints target set 47835b0e-b850-4c61-8419-57c9711a306a enabled
   22  omdb -w nexus blueprints target set 0ed36354-53f6-4272-b4a2-a401024eb05c enabled
   31  omdb -w nexus sleds expunge-disk 400bc5ae-1b2b-40ef-948f-64f801665b69
   57  omdb -w nexus blueprints target set 2dee0f70-f5ec-4979-bf3c-c39d67895cb0 enabled
   66  omdb -w nexus sleds expunge-disk 12e91ce4-7d54-4fd0-904b-f9e269615b6c
   74  omdb -w nexus blueprints target set e7894fab-7808-4e40-b5db-025972456c79 enabled

[jgallagher]

Thanks @FelixMcFelix for tracking down the mismatched MACs; that made the followup debugging much faster. The MAC address configured on the sled-agent side (a8:40:25:ff:80:02) is consistent with the MAC used in the new, in-service boundary NTP zone that's running after Angela expunged the disk. The MAC address configured on the switch (a8:40:25:ff:b5:f0) matches the old, no-longer-running boundary NTP zone. We inspected cockroachdb and confirmed that blueprint execution updated the network_interface table correctly:

root@[fd00:1122:3344:101::21]:32221/omicron> select id, ip, mac, name, time_created, time_deleted from service_network_interface where ip = '172.30.3.6' order by time_created asc;
                   id                  |     ip     |       mac       |                   name                   |         time_created          |         time_deleted
---------------------------------------+------------+-----------------+------------------------------------------+-------------------------------+--------------------------------
  868555ff-250e-4294-8e91-45c9b746ad56 | 172.30.3.6 | 184993468888560 | ntp-ad78e840-9360-4b8d-9287-4dd19e6a51e1 | 2025-03-18 19:21:26.456921+00 | 2025-03-19 05:31:16.440013+00
  ffb114d6-5b87-49e0-8e1a-0ea0b3706090 | 172.30.3.6 | 184993468874754 | ntp-e81dd898-d063-41b3-a13a-418a8c031345 | 2025-03-19 05:31:16.586515+00 | NULL
(2 rows)

The switch is misconfigured due to a distributed deadlock:

1. The sync_service_zone_nat RPW bases its content on the latest inventory collection's zone config.
2. In its inventory report, sled-agent reports its current ledgered zone configuration. sled-agent will only commit the zones ledger after successfully applying the requested config. This sled is still reporting the config from the parent blueprint (which includes expunged zones!), because it hasn't successfully been able to start all the zones requested by the current blueprint.
3. sled-agent cannot fully satisfy the incoming zones config: it includes both a boundary NTP zone and other zones that depend on time sync. It has started the new NTP zone, but is waiting for it to time sync before starting the zones that depend on that. But the boundary NTP zone cannot sync because the switch is misconfigured. (Goto step 1.)

I'm actively reworking how sled-agent ledgers and realizes the incoming configs from Nexus (this is primarily #5086, but has several other related issues). This will also change how inventory is reported, which will necessitate changing the sync_service_zone_nat in some way. I think the fact that it operates on inventory is wrong even before those changes, but I'm not sure about the details - could it instead read from service_network_interface? If not, could we address whatever is wrong with that via a rendezvous table that Reconfigurator populates during execution?

@davepacheco noted the planner could be more conservative here:

If the planner is putting an NTP zone on a sled and something else, we know that's going to get stuck on timesync. If it's boundary NTP, we don't fully control whether timesync can happen. We might want to split that into two steps instead and wait for timesync? But I'm not sure if this is worth it once we have the above fixes.

Agreed on both points - the planner could do this, and also it doesn't seem worth it once we've fixed the above, and at least items 2 and 3 need to be fixed anyway to address other issues.

[jgallagher]

I'm actively reworking how sled-agent ledgers and realizes the incoming configs from Nexus (this is primarily #5086, but has several other related issues). This will also change how inventory is reported, which will necessitate changing the sync_service_zone_nat in some way.

This work has landed (#8064). Inventory now reports the ledgered config separately from running zones. The sync_service_zone_nat RPW acts on the running zones reported by sleds, but critically, sled-agent can now report that some of the zones have started while others have not. This should address this issue: once sled-agent is able to start the boundary NTP zone, that will be reflected in inventory, which means the RPW will be able to sync NAT settings correctly, which will allow time to sync and other zones to start.