test failed in CI: `app::background::tasks::populate_switch_ports::tests::test_switch1_comes_up_late`

[bnaecker]

This test failed on a CI run on #10534:

https://github.com/oxidecomputer/omicron/pull/10534/checks?check_run_id=79570615602

Log showing the specific test failure:

https://buildomat.eng.oxide.computer/wg/0/details/01KT7G8DCZ660QZZ4JWBYT8F5M/vKy6chpHoq098zym3392IT9aQ8BAK409vTvnqGsFV29od6cB/01KT9RZQ0RY5NGSMDTHB5156BH#S9793

Excerpt from the log showing the failure:

2026-06-04T17:31:41.225Z	  stdout ───
2026-06-04T17:31:41.225Z	
2026-06-04T17:31:41.225Z	    running 1 test
2026-06-04T17:31:41.225Z	    test app::background::tasks::populate_switch_ports::tests::test_switch1_comes_up_late has been running for over 60 seconds
2026-06-04T17:31:41.225Z	  stderr ───
2026-06-04T17:31:41.225Z	    log file: /var/tmp/omicron_tmp/omicron_nexus-841e1fd6fbb51d9c-test_switch1_comes_up_late.16170.0.log
2026-06-04T17:31:41.225Z	    note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-841e1fd6fbb51d9c-test_switch1_comes_up_late.16170.0.log"
2026-06-04T17:31:41.226Z	    DB URL: postgresql://root@[::1]:62611/omicron?sslmode=disable
2026-06-04T17:31:41.226Z	    DB address: [::1]:62611
2026-06-04T17:31:41.226Z	    log file: /var/tmp/omicron_tmp/omicron_nexus-841e1fd6fbb51d9c-test_switch1_comes_up_late.16170.2.log
2026-06-04T17:31:41.226Z	    note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-841e1fd6fbb51d9c-test_switch1_comes_up_late.16170.2.log"
2026-06-04T17:31:41.226Z	    log file: /var/tmp/omicron_tmp/omicron_nexus-841e1fd6fbb51d9c-test_switch1_comes_up_late.16170.3.log
2026-06-04T17:31:41.226Z	    note: configured to log to "/var/tmp/omicron_tmp/omicron_nexus-841e1fd6fbb51d9c-test_switch1_comes_up_late.16170.3.log"
2026-06-04T17:31:41.226Z	
2026-06-04T17:31:41.226Z	    (test timed out)

Looks like cargo-nextest timed this out after 900s, and then the next run passed right away, after just 6.2s

[jgallagher]

I think what happened here is:

1. We start the dendrite instance for switch 0. From omicron_nexus-841e1fd6fbb51d9c-test_switch1_comes_up_late.16170.0.log:

17:16:47.140Z DEBG test_switch1_comes_up_late: Starting Dendrite
    switch_slot = switch0

and almost immediately afterwards, the top of .tmpo7esD2/dendrite_stdout is consistent with this: we have a listen address of [::1]:0, and discover we've bound to port 44399:

17:16:47.227Z INFO dpd: starting dpd
    build_info = BuildInfo { version: "0.2.0", git_sha: "cc0c307c617f2988aafdca4e3bd35ea178b64801", git_commit_timestamp: "2026-05-21T23:55:23.000000000Z", git_branch: "main", rustc_semver: "1.90.0", rustc_channel: "stable", rustc_host_triple: "x86_64-unknown-illumos", rustc_commit_sha: "1159e78c4747b02ef996e55082b704c09b970588", cargo_triple: "x86_64-unknown-illumos", debug: false, opt_level: 3, sde_commit_sha: "2a6b33211c9675996dcb99fe939045506667ae94" }
    config = Config { log_file: None, log_format: Json, port_config: None, xcvr_defaults: None, mac_base: None, listen_addresses: [[::1]:0], dns_servers: [], rack_id: None, sled_id: None, sled_model: None, sled_revision: None, sled_serial: None, asic_config: AsicConfig, enable_rpw: true, nexus_address: Some(127.0.0.1:63173), mgs_address: Some([::1]:48334) }
...
17:16:47.262Z DEBG dpd: registered endpoint
    local_addr = [::1]:44399
    method = DELETE
    path = /all-settings
    server_id = 1
    unit = api-server
    versions = all

2. We start the dendrite instance for switch 1. From the same Nexus log less than a second later:

17:16:47.936Z DEBG test_switch1_comes_up_late: Starting Dendrite
    switch_slot = switch1

We do not have the corresponding dendrite_stdout file for this dpd instance, because this test explicitly shuts down the switch1 dpd instance:

17:16:52.800Z DEBG test_switch1_comes_up_late: Stopping Dendrite
    switch_slot = switch1

This cleans up after itself and removes its tempdir. However, based on the next item, I believe this dpd was bound to port 33974.

3. The test then tried to restart dpd. This doesn't have a corresponding "Restarting Dendrite" log entry, but we do have .tmpeR4rW5/dendrite_stdout which shows we tried to start dpd with an explicit port in the listen address:

17:16:58.177Z INFO dpd: starting dpd
    build_info = BuildInfo { version: "0.2.0", git_sha: "cc0c307c617f2988aafdca4e3bd35ea178b64801", git_commit_timestamp: "2026-05-21T23:55:23.000000000Z", git_branch: "main", rustc_semver: "1.90.0", rustc_channel: "stable", rustc_host_triple: "x86_64-unknown-illumos", rustc_commit_sha: "1159e78c4747b02ef996e55082b704c09b970588", cargo_triple: "x86_64-unknown-illumos", debug: false, opt_level: 3, sde_commit_sha: "2a6b33211c9675996dcb99fe939045506667ae94" }
    config = Config { log_file: None, log_format: Json, port_config: None, xcvr_defaults: None, mac_base: None, listen_addresses: [[::1]:33974], dns_servers: [], rack_id: None, sled_id: None, sled_model: None, sled_revision: None, sled_serial: None, asic_config: AsicConfig, enable_rpw: true, nexus_address: Some(127.0.0.1:63173), mgs_address: Some([::1]:45313) }

which is consistent with the way restart_dendrite() works:

omicron/nexus/test-utils/src/nexus_test.rs

Lines 253 to 258 in 4bb7276

	// Must have been stopped - get stored port
	self.stopped_dendrite_ports
	.write()
	.unwrap()
	.remove(&switch_slot)
	.expect("Dendrite not running and no stored port from stop_dendrite")

However, this dpd failed to bind to this port for some reason we don't get in the logs:

17:16:58.204Z ERRO dpd: failed to launch api server 1 on [::1]:33974: failed to bind to [::1]:33974
    
    Stack backtrace:
       0: anyhow::kind::Adhoc::new
    unit = api-server-manager

4. restart_dendrite() sat in this infinite loop, retrying every 50ms to talk to a dpd that failed to bind to its listening port:

   omicron/nexus/test-utils/src/nexus_test.rs

   Lines 290 to 298 in 4bb7276

   	loop {
   	match dpd_client.switch_identifiers().await {
   	Ok(_) => break,
   	Err(_) => {
   	tokio::time::sleep(std::time::Duration::from_millis(50))
   	.await;
   	}
   	}
   	}

[jgallagher]

Some TODOs / questions:

1. We should add logging to restart_dendrite().
2. dpd should log its full error chain (at least when binding, but presumably it has similar issues other places, since getting this right is annoyingly difficult).
3. The restart_dendrite() loop should have a timeout and not wait for nextest to kill it.
4. Is the strategy here of "restart dendrite on the same port it was listening on before" inherently racy? It seems like it must be, but also fixing this might be tough - we'd need to update DNS and ensure any cached clients in the Nexus test infrastructure were updated, if those exist.

EDIT: 1 and 3 are covered by #10570. 2 is oxidecomputer/dendrite#299. TBD on 4 (which is presumably the real cause of the flake - maybe something else snuck in a bind on that port in between our shutdown and restart?).