From d5e4533c1e6857891b40efb5fb776bfed9a34a81 Mon Sep 17 00:00:00 2001 From: Johnathan Corgan Date: Thu, 10 Sep 2026 19:18:42 +0000 Subject: [PATCH] fix(testing): make the chaos veth restore and the iface-binding suite hold on a loaded CI host ethernet-churn failed on master and next alike, as a tree that did not converge. The daemon was not the cause: the harness left ring links down and reported them restored, and under host load those dead links lined up until every link was down at once. Finding that turned up several more harness defects, fixed together here. The iface-binding suite built its host veth names from FIPS_CI_NAME_SUFFIX, and an interface name gets fifteen characters. On a runner that sets the suffix to a timestamp and a pid, ip(8) refused the name before the first pair existed. GitHub's job does not set the suffix, so it passed there. The names now use the four-hex-character token from sim.naming, as the chaos simulation and the NAT topology script already do, and the reaper in ci-cleanup.sh matches the new shape under both the scoped and the unscoped sweep. A churned node's restart recreates each veth pair it shared with its neighbours. A stopped container's network namespace can outlive the stop by about two minutes, and while it does, renaming the survivor's new end fails with "File exists". The harness ignored that, read the old interface's MAC, logged success, and left the new end down. The restore now deletes any interface holding the final or temporary name first, checks every add, move and rename, and waits for both ends to report operstate up. A restore that still fails raises as a harness fault. A container PID docker cannot report now raises instead of reading as "not running", and a pair is deferred only for a neighbour churn itself stopped. The survivor's end of a recreated link also gets its netem parameters back; before, that direction ran unshaped. The runner hands one down-node set to every manager, and node churn and traffic stored it as `down_nodes or set()`. The set is empty when they are built, so each kept a private copy: traffic started iperf3 on stopped containers, and netem and link flaps tried to shape them. Every manager and event schedule drew from one random stream in wall-clock order, so host load changed which node churn stopped next. Each consumer now has its own stream derived from the seed. The topology and ephemeral node choice stay on the seed's own stream, so generated topologies do not change, but every other runtime draw does. The final tree snapshot now waits for three consecutive agreeing reads, five seconds apart and bounded at ninety seconds, instead of being taken the moment the stopped nodes were restored. A red chaos scenario lost its results directory with the worktree the CI worker deletes. Each scenario's results are now scoped to the run, and a red prints its status, assertions, final tree and each node's log tail into the run log. ethernet-churn's baseline had been calibrated on the broken restore. On the fixed harness, sixteen runs across master-line and next-line code, twelve of them under contention and across three seeds, all ended with 4 nodes answering, 1 root and 3 parented, and the scenario now asserts exactly that. The scenario loader also checked the parented floor against one root only; it now checks it against max_roots, since a mesh with R roots can parent at most n - R nodes. --- testing/chaos/scenarios/ethernet-churn.yaml | 47 ++-- testing/chaos/sim/netem.py | 40 +++- testing/chaos/sim/nodes.py | 11 +- testing/chaos/sim/runner.py | 111 ++++++++-- testing/chaos/sim/scenario.py | 19 +- testing/chaos/sim/traffic.py | 5 +- testing/chaos/sim/veth.py | 229 +++++++++++++++----- testing/ci-cleanup.sh | 20 +- testing/ci-local.sh | 56 ++++- testing/iface-binding/test.sh | 28 ++- 10 files changed, 437 insertions(+), 129 deletions(-) diff --git a/testing/chaos/scenarios/ethernet-churn.yaml b/testing/chaos/scenarios/ethernet-churn.yaml index ca9b3cde..89149afe 100644 --- a/testing/chaos/scenarios/ethernet-churn.yaml +++ b/testing/chaos/scenarios/ethernet-churn.yaml @@ -79,35 +79,34 @@ node_churn: protect_connectivity: true assertions: - # The mesh re-forms after each interface comes back. + # The mesh re-forms after each interface comes back, fully. # - # Calibrated 2026-09-02 against four runs, all at this file's fixed seed 42 - # and therefore an identical churn schedule, so the spread is container - # timing rather than differing scenarios: + # Calibrated 2026-09-10 against sixteen runs, eight on master-line code and + # eight on next-line code, on a harness that fails a veth restore it cannot + # complete and waits for the tree to settle before the final snapshot. Twelve + # ran beside the other five CI chaos scenarios and four CPU busy loops; seeds + # 42 (twelve runs), 7 and 1234: # - # nodes answering 4 in all four runs - # distinct roots 2 in all four runs - # nodes parented 2 in all four runs - # traffic 3-5 sessions, 206-388 MB + # nodes answering 4 in all sixteen + # distinct roots 1 in all sixteen + # nodes parented 3 in all sixteen + # settle 11-22 s + # traffic 4-11 sessions per run, 3.8-11.7 GB # - # `max_roots: 1` was wrong and failed every run: the harness restores - # stopped nodes immediately before the final snapshot, so a node that has - # just restarted has not re-parented yet and is briefly its own root. That - # is the scenario working, not failing. + # So the thresholds are full convergence: every node answers, one root, three + # parented. A red here is a mesh that did not re-form. # - # The ceiling is 3, one step beyond the observed maximum of 2, with the - # parented floor at its complement. A mesh that genuinely collapsed — every - # node islanded — still fails, which is all this assertion is for. Do not - # read a pass as convergence. - # - # READ BEFORE RETUNING: four runs is a thin sample. `churn-mixed` documents - # what happens when a threshold is set one step outside a small one — it - # ends up inside the real distribution and reddens runs whatever the daemon - # does. Widen on evidence; tighten only against a much larger sample. + # READ BEFORE RETUNING: the 2026-09-02 calibration recorded 2 roots and 2 + # parented in all four of its runs, and that was not the daemon. The veth + # restore then failed silently whenever a stopped node's namespace outlived + # the stop, and in every later run that was inspected, the node islanded at + # the snapshot was one whose links the harness had left down. Before widening these, read the red run's runner.log for a + # harness fault; a failed restore now aborts the run rather than reaching + # this assertion. baseline: - min_nodes_reporting: 3 - max_roots: 3 - min_nodes_parented: 2 + min_nodes_reporting: 4 + max_roots: 1 + min_nodes_parented: 3 # The point of the scenario. Traffic must actually have crossed Ethernet # links while interfaces were being taken away underneath it — a green tree diff --git a/testing/chaos/sim/netem.py b/testing/chaos/sim/netem.py index 3ac8d0e2..e95d8548 100644 --- a/testing/chaos/sim/netem.py +++ b/testing/chaos/sim/netem.py @@ -370,22 +370,42 @@ class NetemManager: # Re-apply Ethernet veth netem veth_states = self.veth_states.get(container) if veth_states: - for iface, state in veth_states.items(): - cmd = ( - f"tc qdisc del dev {iface} root 2>/dev/null || true && " - f"tc qdisc add dev {iface} root netem {state.params.to_tc_args()}" - ) - result = docker_exec_quiet(container, cmd, timeout=10) - if result is not None: - log.debug("Re-applied veth netem on %s:%s", container, iface) - else: - log.warning("Failed to re-apply veth netem on %s:%s", container, iface) + for state in veth_states.values(): + self._apply_veth(state) log.info( "Re-applied veth netem on %s (%d Ethernet peers)", container, len(veth_states), ) + # And on each running neighbour's end of those links. The restore + # recreates the whole pair, so the survivor's end is a new interface + # with no qdisc, and without this that direction of every restored + # link ran unshaped for the rest of the run. + for peer_id in sorted(self.topology.nodes[node_id].peers): + if peer_id in self.down_nodes: + continue + if self.topology.transport_for_edge(node_id, peer_id) != "ethernet": + continue + peer_container = self.topology.container_name(peer_id) + state = self.veth_states.get(peer_container, {}).get( + veth_interface_name(peer_id, node_id) + ) + if state is not None: + self._apply_veth(state) + + def _apply_veth(self, state: VethNetemState): + """Install a veth end's current netem parameters as its root qdisc.""" + cmd = ( + f"tc qdisc del dev {state.iface} root 2>/dev/null || true && " + f"tc qdisc add dev {state.iface} root netem {state.params.to_tc_args()}" + ) + result = docker_exec_quiet(state.container, cmd, timeout=10) + if result is not None: + log.debug("Re-applied veth netem on %s:%s", state.container, state.iface) + else: + log.warning("Failed to re-apply veth netem on %s:%s", state.container, state.iface) + def mutate(self): """Randomly mutate netem params on a fraction of links.""" if not self.config.mutation.policies: diff --git a/testing/chaos/sim/nodes.py b/testing/chaos/sim/nodes.py index 2a69f7c3..75565d6b 100644 --- a/testing/chaos/sim/nodes.py +++ b/testing/chaos/sim/nodes.py @@ -50,7 +50,10 @@ class NodeManager: self.rng = rng self.netem_mgr = netem_mgr self.veth_mgr = veth_mgr - self.down_nodes = down_nodes or set() + # `is not None`, not `or`: the runner passes its shared set while it + # is still empty, and an empty set is falsy, so `or` replaced it with + # a private one and no other manager ever saw a node go down. + self.down_nodes = down_nodes if down_nodes is not None else set() self.on_node_restart = on_node_restart self.node_states: dict[str, NodeState] = { nid: NodeState(node_id=nid) for nid in topology.nodes @@ -173,7 +176,11 @@ class NodeManager: # Re-create veth pairs (container restart destroys netns) if self.veth_mgr: time.sleep(1) - self.veth_mgr.setup_node(node_id) + # Churn's own record, not the shared set: netem's safety net also + # adds to that set, on a docker hiccup or a crash churn did not + # cause, and a pair deferred on that basis would never be rebuilt. + stopped = {nid for nid, ns in self.node_states.items() if ns.is_down} + self.veth_mgr.setup_node(node_id, stopped) # Re-apply netem after a brief delay for the container to initialize if self.netem_mgr: diff --git a/testing/chaos/sim/runner.py b/testing/chaos/sim/runner.py index 502febe6..1d9df9de 100644 --- a/testing/chaos/sim/runner.py +++ b/testing/chaos/sim/runner.py @@ -42,11 +42,21 @@ from .veth import VethManager log = logging.getLogger(__name__) +# The final snapshot waits for this many identical consecutive tree reads, +# taken this far apart, so the tree must hold still for two intervals. +SETTLE_READS = 3 +SETTLE_INTERVAL_SECS = 5 +SETTLE_TIMEOUT_SECS = 90 + class SimRunner: def __init__(self, scenario: Scenario): self.scenario = scenario + # Setup draws only: the topology and the ephemeral node choice, made + # once and in a fixed order. Everything drawn while the simulation + # runs comes from `_stream` instead. self.rng = random.Random(scenario.seed) + self._streams: dict[str, random.Random] = {} self.topology: SimTopology | None = None self.compose_file: str | None = None # Claimed in _setup; the compose file refers to it as external, so @@ -317,14 +327,16 @@ class SimRunner: if s.netem.enabled: bw = s.bandwidth if s.bandwidth.enabled else None ig = s.ingress if s.ingress.enabled else None - self.netem_mgr = NetemManager(self.topology, s.netem, self.rng, bandwidth=bw, ingress=ig) + self.netem_mgr = NetemManager( + self.topology, s.netem, self._stream("netem"), bandwidth=bw, ingress=ig + ) self.netem_mgr.down_nodes = self._down_nodes log.info("Applying initial per-link netem...") self.netem_mgr.setup_initial() if s.link_flaps.enabled: self.link_mgr = LinkManager( - self.topology, s.link_flaps, self.rng, netem_mgr=self.netem_mgr + self.topology, s.link_flaps, self._stream("flaps"), netem_mgr=self.netem_mgr ) if s.link_swap.enabled: @@ -333,7 +345,7 @@ class SimRunner: "link_swap requires netem.enabled (depends on per-link tc state)" ) self.link_swap_mgr = LinkSwapManager( - self.topology, s.link_swap, self.netem_mgr, self.rng, + self.topology, s.link_swap, self.netem_mgr, self._stream("swap"), ) if s.assertions.bloom_send_rate is not None: @@ -343,12 +355,12 @@ class SimRunner: if s.traffic.enabled: self.traffic_mgr = TrafficManager( - self.topology, s.traffic, self.rng, down_nodes=self._down_nodes + self.topology, s.traffic, self._stream("traffic"), down_nodes=self._down_nodes ) if s.node_churn.enabled: self.node_mgr = NodeManager( - self.topology, s.node_churn, self.rng, + self.topology, s.node_churn, self._stream("churn"), netem_mgr=self.netem_mgr, down_nodes=self._down_nodes, veth_mgr=self.veth_mgr, on_node_restart=self._handle_node_restart, @@ -356,7 +368,7 @@ class SimRunner: if s.peer_churn.enabled: self.peer_churn_mgr = PeerChurnManager( - self.topology, s.peer_churn, self.rng, + self.topology, s.peer_churn, self._stream("peer-churn"), down_nodes=self._down_nodes, ephemeral_nodes=self._ephemeral_nodes, ) @@ -411,11 +423,11 @@ class SimRunner: log.info("Simulation running for %ds...", duration) # Schedule first events - next_netem = self._schedule_next(start, s.netem.mutation.interval_secs) if self.netem_mgr else float("inf") - next_flap = self._schedule_next(start, s.link_flaps.interval_secs) if self.link_mgr else float("inf") - next_traffic = self._schedule_next(start, s.traffic.interval_secs) if self.traffic_mgr else float("inf") - next_churn = self._schedule_next(start, s.node_churn.interval_secs) if self.node_mgr else float("inf") - next_peer_churn = self._schedule_next(start, s.peer_churn.interval_secs) if self.peer_churn_mgr else float("inf") + next_netem = self._schedule_next(start, s.netem.mutation.interval_secs, "netem") if self.netem_mgr else float("inf") + next_flap = self._schedule_next(start, s.link_flaps.interval_secs, "flaps") if self.link_mgr else float("inf") + next_traffic = self._schedule_next(start, s.traffic.interval_secs, "traffic") if self.traffic_mgr else float("inf") + next_churn = self._schedule_next(start, s.node_churn.interval_secs, "churn") if self.node_mgr else float("inf") + next_peer_churn = self._schedule_next(start, s.peer_churn.interval_secs, "peer-churn") if self.peer_churn_mgr else float("inf") # Bloom-send-rate assertion: sample at window_secs before end. bloom_window_start_at = float("inf") @@ -452,34 +464,34 @@ class SimRunner: # Netem mutation if self.netem_mgr and now >= next_netem: self.netem_mgr.mutate() - next_netem = self._schedule_next(now, s.netem.mutation.interval_secs) + next_netem = self._schedule_next(now, s.netem.mutation.interval_secs, "netem") # Link flaps if self.link_mgr: if now >= next_flap: self.link_mgr.maybe_flap() - next_flap = self._schedule_next(now, s.link_flaps.interval_secs) + next_flap = self._schedule_next(now, s.link_flaps.interval_secs, "flaps") self.link_mgr.restore_expired() # Traffic generation if self.traffic_mgr: if now >= next_traffic: self.traffic_mgr.maybe_spawn() - next_traffic = self._schedule_next(now, s.traffic.interval_secs) + next_traffic = self._schedule_next(now, s.traffic.interval_secs, "traffic") self.traffic_mgr.cleanup_expired() # Node churn if self.node_mgr: if now >= next_churn: self.node_mgr.maybe_kill() - next_churn = self._schedule_next(now, s.node_churn.interval_secs) + next_churn = self._schedule_next(now, s.node_churn.interval_secs, "churn") self.node_mgr.restore_expired() # Peer churn (topology mutation) if self.peer_churn_mgr: if now >= next_peer_churn: self.peer_churn_mgr.maybe_churn() - next_peer_churn = self._schedule_next(now, s.peer_churn.interval_secs) + next_peer_churn = self._schedule_next(now, s.peer_churn.interval_secs, "peer-churn") # Status line down_links = self.link_mgr.down_count if self.link_mgr else 0 @@ -709,7 +721,11 @@ class SimRunner: json.dump(iperf_results, f, indent=2) log.info("Saved %d iperf3 results to %s", len(iperf_results), iperf_path) - # Take final tree snapshot while nodes are still running + # Take final tree snapshot while nodes are still running, once the + # tree has stopped moving. A node restored a moment ago is its own + # root until it re-parents, so a snapshot taken straight after the + # restore reads a mesh still converging. + self._settle_tree() self._take_snapshot("final") # Collect logs before stopping containers @@ -847,6 +863,46 @@ class SimRunner: return result + def _settle_tree(self): + """Wait until consecutive tree reads agree, or the settle time runs out. + + Compares each answering node's root and parent. A fixed delay would + either waste time on a mesh that settled at once or cut off one that + had not. Running out is logged and is not a failure in itself: the + final snapshot is taken anyway, and the assertions judge what it + shows. + + A read that no node answered never counts toward agreement. It does + not catch a node that stays its own root for longer than the reads + span, which is a tree that is stable and wrong, and is left to the + assertions. + """ + started = time.time() + previous = None + agreeing = 0 + while not self._interrupted: + trees = snapshot_all_trees(self.topology) + shape = { + nid: (data.get("root"), data.get("parent")) + for nid, data in trees.items() + } + if not shape: + agreeing = 0 + else: + agreeing = agreeing + 1 if shape == previous else 1 + previous = shape + waited = time.time() - started + if agreeing >= SETTLE_READS: + log.info("Tree settled after %.0fs", waited) + return + if waited >= SETTLE_TIMEOUT_SECS: + log.warning( + "Tree still changing after %.0fs; taking the final snapshot anyway", + waited, + ) + return + self._sleep(SETTLE_INTERVAL_SECS) + def _take_snapshot(self, label: str): """Query all nodes via control socket and save tree/MMP/congestion snapshots.""" if not self.topology: @@ -883,9 +939,24 @@ class SimRunner: len(self.topology.nodes), ) - def _schedule_next(self, now: float, interval) -> float: - """Schedule the next event using a Range interval.""" - return now + self.rng.uniform(interval.min, interval.max) + def _schedule_next(self, now: float, interval, kind: str) -> float: + """Schedule the next event of one kind using a Range interval.""" + return now + self._stream(f"{kind}-schedule").uniform(interval.min, interval.max) + + def _stream(self, name: str) -> random.Random: + """Return the random stream for one consumer, derived from the seed. + + One stream shared by every manager was drawn in wall-clock order, and + a manager that returns early draws nothing, so host load changed + which node the churn stopped next. Under heavy host load that walked + the stops around the ring. A stream per consumer means one manager's + draws no longer shift another's. It does not make a schedule a + function of the seed alone: a manager's own draws can still depend on + mesh state at the tick, such as which nodes are down. + """ + if name not in self._streams: + self._streams[name] = random.Random(f"{self.scenario.seed}:{name}") + return self._streams[name] def _sleep(self, seconds: float): """Sleep in small increments so SIGINT can break out.""" diff --git a/testing/chaos/sim/scenario.py b/testing/chaos/sim/scenario.py index 19e59954..de6e5dee 100644 --- a/testing/chaos/sim/scenario.py +++ b/testing/chaos/sim/scenario.py @@ -880,14 +880,21 @@ def load_scenario(path: str) -> Scenario: + ", ".join(sorted(_ASSERTION_KEYS["baseline"])) + "; a block with none asserts nothing" ) - if vals.get("min_nodes_parented", 0) > 0 or vals.get("max_roots"): + if vals.get("min_nodes_parented", 0) > 0: + # Every root is its own parent, so a mesh with R roots has at most + # n - R nodes parented. Checked against the roots ceiling rather + # than against one root: a floor above n - max_roots reds a run + # that sits exactly at the ceiling the file itself allows, so the + # two thresholds contradict each other there. n = s.topology.num_nodes - if vals.get("min_nodes_parented", 0) > n - 1: + roots = vals.get("max_roots", 1) + floor = vals["min_nodes_parented"] + if floor > n - roots: raise ValueError( - f"assertions.baseline.min_nodes_parented: " - f"{vals['min_nodes_parented']} exceeds {n - 1}, the most a " - f"{n}-node mesh can reach — the root is its own parent, so " - f"this could never pass" + f"assertions.baseline.min_nodes_parented: {floor} exceeds " + f"{n - roots}, the most a {n}-node mesh with {roots} " + f"root(s) can reach — each root is its own parent, so a " + f"run at the max_roots ceiling could never pass" ) s.assertions.baseline = BaselineAssertion(**vals) diff --git a/testing/chaos/sim/traffic.py b/testing/chaos/sim/traffic.py index 8d9d1e56..28acabe0 100644 --- a/testing/chaos/sim/traffic.py +++ b/testing/chaos/sim/traffic.py @@ -44,7 +44,10 @@ class TrafficManager: self.topology = topology self.config = config self.rng = rng - self.down_nodes = down_nodes or set() + # `is not None`, not `or`: the runner passes its shared set while it + # is still empty, and an empty set is falsy, so `or` replaced it with + # a private one and no other manager ever saw a node go down. + self.down_nodes = down_nodes if down_nodes is not None else set() self.npub_cache = npub_cache or {} self.active_sessions: list[TrafficSession] = [] self.completed_results: list[dict] = [] diff --git a/testing/chaos/sim/veth.py b/testing/chaos/sim/veth.py index a60a25fe..cb1a2228 100644 --- a/testing/chaos/sim/veth.py +++ b/testing/chaos/sim/veth.py @@ -34,12 +34,36 @@ from __future__ import annotations import logging import subprocess +import time -from .docker_exec import docker_exec_quiet +from .docker_exec import DockerExecError, docker_exec, docker_exec_quiet from .topology import SimTopology, veth_interface_name log = logging.getLogger(__name__) +# How long a freshly raised veth end may take to report operstate up. The +# kernel publishes the carrier change through linkwatch, which is deferred, so +# a read straight after `ip link set up` can still see the old state. Long +# enough for at least two reads under host load, since one slow `docker exec` +# must not abort a run whose link is up. +OPERSTATE_WAIT_SECS = 15 + +# Timeout for each `docker exec` a restore makes. The run blocks on these, and +# a timeout aborts it, so this errs long: a loaded host is the normal case. +EXEC_TIMEOUT_SECS = 30 + + +class VethSetupError(RuntimeError): + """A veth pair could not be created, placed, renamed or raised. + + Raised rather than logged. A pair that fails part way leaves a ring link + down while the run carries on, and what reaches the verdict is then a tree + that did not converge: a daemon failure in every respect a reader can see. + Letting this propagate aborts the run, so the fault is reported as the + harness's own. + """ + + class VethManager: """Manages veth pairs for Ethernet-transport edges.""" @@ -102,12 +126,13 @@ class VethManager: len(self._host_pairs), ) - def setup_node(self, node_id: str): + def setup_node(self, node_id: str, down_nodes: set[str] | None = None): """Re-create veth endpoints for a single node after container restart. When a container restarts (node churn), its network namespace is destroyed. We re-create the veth pairs for all Ethernet edges - involving this node. + involving this node. ``down_nodes`` names the neighbours churn has + stopped, whose pairs are left for their own restart. """ image = self._get_image() for a, b in self.topology.ethernet_edges(): @@ -117,7 +142,7 @@ class VethManager: host_a = self.topology.veth_host_name(a, b, "a") _run_host(["ip", "link", "delete", host_a], image, check=False) # Re-create - self._create_veth_pair(a, b, image) + self._create_veth_pair(a, b, image, down_nodes or set()) def teardown_all(self): """Clean up all veth pairs.""" @@ -126,18 +151,40 @@ class VethManager: _run_host(["ip", "link", "delete", host_a], image, check=False) self._host_pairs.clear() - def _create_veth_pair(self, node_a: str, node_b: str, image: str): - """Create a single veth pair between two containers.""" + def _create_veth_pair( + self, node_a: str, node_b: str, image: str, down_nodes: set[str] | None = None + ): + """Create a single veth pair between two containers. + + ``down_nodes`` is None at first setup, when every container must be + running. On a restore it names the nodes churn has stopped. + """ container_a = self.topology.container_name(node_a) container_b = self.topology.container_name(node_b) - # Get container PIDs - pid_a = _get_container_pid(container_a) - pid_b = _get_container_pid(container_b) + pid_a = _container_pid(container_a) + pid_b = _container_pid(container_b) if pid_a is None or pid_b is None: - log.warning( - "Cannot create veth %s--%s: container PID not found", node_a, node_b - ) + stopped = [n for n, pid in ((node_a, pid_a), (node_b, pid_b)) if pid is None] + names = ", ".join(stopped) + if down_nodes is None: + raise VethSetupError( + f"veth {node_a}--{node_b}: {names} not running at setup" + ) + if all(n in down_nodes for n in stopped): + # Stopped by churn: it has no namespace to join, and its own + # restart recreates this pair. + log.info("Veth %s--%s deferred: %s down", node_a, node_b, names) + else: + # Not raised: a container that exited on its own is a daemon + # failure, and aborting here would report it as the harness's. + # Nothing recreates this pair, so say so loudly. + log.warning( + "Veth %s--%s not recreated: %s not running, and churn did " + "not stop all of them; the link stays absent for the rest " + "of the run", + node_a, node_b, names, + ) return # Generate names @@ -146,68 +193,146 @@ class VethManager: final_a = veth_interface_name(node_a, node_b) final_b = veth_interface_name(node_b, node_a) + # Clear both final names and both temporary names out of the + # containers first. A stopped node's network namespace can outlive + # the stop by minutes, and while it does the survivor still holds its + # old `ve-X-Y`, whose peer sits in that namespace; the rename below + # then fails with "File exists". Deleting the survivor's end removes + # its peer too. A temporary name is left behind only by a restore + # that failed after the move, and it blocks the next move the same + # way. + _purge_links(container_a, [final_a, host_a]) + _purge_links(container_b, [final_b, host_b]) + # Clean up a stale pair left by this scenario. The token makes the # name unique to this run, so a pair orphaned by an earlier run is # no longer reclaimed here — `ci-cleanup.sh` reaps those instead. _run_host(["ip", "link", "delete", host_a], image, check=False) - # Create veth pair on host - ok = _run_host([ - "ip", "link", "add", host_a, "type", "veth", "peer", "name", host_b, - ], image) - if not ok: - log.warning("Failed to create veth pair %s/%s", host_a, host_b) - return - - # Move into container namespaces - _run_host(["ip", "link", "set", host_a, "netns", str(pid_a)], image) - _run_host(["ip", "link", "set", host_b, "netns", str(pid_b)], image) - - # Rename and bring up inside containers - docker_exec_quiet( - container_a, - f"ip link set {host_a} name {final_a} && ip link set {final_a} up", - timeout=10, - ) - docker_exec_quiet( - container_b, - f"ip link set {host_b} name {final_b} && ip link set {final_b} up", - timeout=10, + _require_host( + ["ip", "link", "add", host_a, "type", "veth", "peer", "name", host_b], + image, ) + _require_host(["ip", "link", "set", host_a, "netns", str(pid_a)], image) + _require_host(["ip", "link", "set", host_b, "netns", str(pid_b)], image) - # Query MAC addresses + _raise_link(container_a, host_a, final_a) + _raise_link(container_b, host_b, final_b) + _await_up(container_a, final_a) + _await_up(container_b, final_b) + + # Read only after both ends are proven renamed and up. Before, a + # failed rename left the old interface under the final name, and this + # read its MAC and reported the restore as a success. mac_a = _get_mac_in_container(container_a, final_a) mac_b = _get_mac_in_container(container_b, final_b) - - if mac_a: - self.topology.nodes[node_a].ethernet_macs[node_b] = mac_a - if mac_b: - self.topology.nodes[node_b].ethernet_macs[node_a] = mac_b + if not mac_a or not mac_b: + raise VethSetupError( + f"veth {node_a}--{node_b} is up but its MAC could not be read " + f"({final_a}: {mac_a or '?'}, {final_b}: {mac_b or '?'})" + ) + self.topology.nodes[node_a].ethernet_macs[node_b] = mac_a + self.topology.nodes[node_b].ethernet_macs[node_a] = mac_b self._host_pairs.append((node_a, node_b, host_a, host_b)) log.info( "Veth %s(%s) -- %s(%s) MAC: %s / %s", - node_a, final_a, node_b, final_b, - mac_a or "?", mac_b or "?", + node_a, final_a, node_b, final_b, mac_a, mac_b, ) -def _get_container_pid(container: str) -> int | None: - """Get the PID of a running Docker container.""" +def _in_container(container: str, cmd: str, what: str, timeout: int = EXEC_TIMEOUT_SECS) -> str: + """Run a command inside a container, raising `VethSetupError` on failure.""" + try: + return docker_exec(container, cmd, timeout=timeout) + except (DockerExecError, subprocess.TimeoutExpired) as e: + raise VethSetupError(f"{what} in {container} failed: {e}") from e + + +def _purge_links(container: str, names: list[str]): + """Delete each named interface in a container if it exists, in one exec. + + An absent name is the ordinary case and is skipped. A delete that fails + raises, since the rename that follows would then fail on the name too, + unless the name is gone by then: a lingering namespace can be reaped + between the check and the delete, taking the survivor's end with it. + """ + script = "; ".join( + f"if ip link show {name} >/dev/null 2>&1; then " + f"ip link delete {name} || ! ip link show {name} >/dev/null 2>&1 || exit 1; fi" + for name in names + ) + _in_container(container, script, f"deleting stale {', '.join(names)}") + + +def _require_host(cmd: list[str], image: str): + """Run a host-namespace ``ip`` command, raising `VethSetupError` on failure.""" + if not _run_host(cmd, image): + raise VethSetupError(f"host command failed: {' '.join(cmd)}") + + +def _raise_link(container: str, temp: str, final: str): + """Rename a moved veth end to its final name and set it up.""" + _in_container( + container, + f"ip link set {temp} name {final} && ip link set {final} up", + f"renaming {temp} to {final}", + ) + + +def _await_up(container: str, iface: str): + """Wait for an interface's operstate to read ``up``, else raise. + + A veth end reports up only once both ends are up, so this proves the + pair is joined as well as that this end was raised. + """ + deadline = time.monotonic() + OPERSTATE_WAIT_SECS + state = None + reads = 0 + while True: + state = docker_exec_quiet( + container, f"cat /sys/class/net/{iface}/operstate", timeout=EXEC_TIMEOUT_SECS + ) + state = state.strip() if state is not None else None + reads += 1 + if state == "up": + return + if reads >= 2 and time.monotonic() >= deadline: + raise VethSetupError( + f"{iface} in {container} reads operstate {state or '?'}, " + f"not up, {OPERSTATE_WAIT_SECS}s after it was raised" + ) + time.sleep(0.2) + + +def _container_pid(container: str) -> int | None: + """Return a container's PID, or None when docker reports it not running. + + Raises `VethSetupError` when docker cannot be asked. A timed-out or failed + inspect of a running container used to read as "not running", so under + host load a live link was skipped and never recreated. + """ try: result = subprocess.run( ["docker", "inspect", "-f", "{{.State.Pid}}", container], capture_output=True, text=True, - timeout=10, + timeout=EXEC_TIMEOUT_SECS, ) - if result.returncode == 0: - pid = int(result.stdout.strip()) - return pid if pid > 0 else None - except (subprocess.TimeoutExpired, ValueError): - pass - return None + except subprocess.TimeoutExpired as e: + raise VethSetupError(f"docker inspect {container} timed out") from e + if result.returncode != 0: + raise VethSetupError( + f"docker inspect {container} failed: {result.stderr.strip()}" + ) + try: + pid = int(result.stdout.strip()) + except ValueError as e: + raise VethSetupError( + f"docker inspect {container} returned no PID: {result.stdout.strip()!r}" + ) from e + return pid if pid > 0 else None def _get_mac_in_container(container: str, iface: str) -> str | None: @@ -215,7 +340,7 @@ def _get_mac_in_container(container: str, iface: str) -> str | None: result = docker_exec_quiet( container, f"cat /sys/class/net/{iface}/address", - timeout=5, + timeout=EXEC_TIMEOUT_SECS, ) if result is not None: return result.strip() diff --git a/testing/ci-cleanup.sh b/testing/ci-cleanup.sh index 010394d4..92dcf79d 100755 --- a/testing/ci-cleanup.sh +++ b/testing/ci-cleanup.sh @@ -204,13 +204,19 @@ VETH_NODE_ID='(0[0-9]|[1-9][0-9]+)' # from the simulation itself rather than repeated here, so widening it cannot # leave this matching the old width. Empty output means "reap nothing". # -# Two producers, two shapes. The chaos simulation makes vh{token}{NN}{MM}{a,b}; -# the NAT lab (nat/scripts/setup-topology.sh) makes vn{a,b}{token}{0,1}, using -# the RUN-wide suffix rather than any chaos scenario's. Widening this regex is +# Three producers, three shapes. The chaos simulation makes +# vh{token}{NN}{MM}{a,b}; the NAT lab (nat/scripts/setup-topology.sh) makes +# vn{a,b}{token}{0,1}; the interface-binding suite +# (iface-binding/test.sh) makes vhifb{token}{a,b,c,d}. The last two use the +# RUN-wide suffix rather than any chaos scenario's. Widening this regex is # only half the fix: the token set is derived separately below, so a suffix -# list carrying no NAT suffix leaves the NAT half matching nothing while +# list carrying no run-wide suffix leaves those halves matching nothing while # looking correct. ci-local.sh's ci_teardown therefore appends the run-wide # suffix to --veth-suffixes. +# +# vhifb is listed before the bare vh shape in each alternation only for +# readability; the shapes are anchored and cannot overlap, because a node id +# is digits and `ifb` is not. veth_pattern() { # vh{token}{NN}{MM}{a,b}: the token is 4 hex or wholly absent — never a # part of one — and the two node ids follow. Anchored and shaped this @@ -219,7 +225,7 @@ veth_pattern() { # single run, no missing or empty suffix list may widen this back out to # every run. if [[ -z "$RUN_ID" && -z "$VETH_SUFFIXES" ]]; then - printf '^vh([0-9a-f]{4})?%s%s[ab]$|^vn[ab]([0-9a-f]{4})?[01]$' \ + printf '^vhifb([0-9a-f]{4})?[a-d]$|^vh([0-9a-f]{4})?%s%s[ab]$|^vn[ab]([0-9a-f]{4})?[01]$' \ "$VETH_NODE_ID" "$VETH_NODE_ID" return 0 fi @@ -253,8 +259,8 @@ veth_pattern() { veth_warn "no interface tokens derived from: ${sfx[*]}" return 0 fi - printf '^vh(%s)%s%s[ab]$|^vn[ab](%s)[01]$' \ - "$alt" "$VETH_NODE_ID" "$VETH_NODE_ID" "$alt" + printf '^vhifb(%s)[a-d]$|^vh(%s)%s%s[ab]$|^vn[ab](%s)[01]$' \ + "$alt" "$alt" "$VETH_NODE_ID" "$VETH_NODE_ID" "$alt" } # ip(8) in a privileged --net=host container, matching how the simulation diff --git a/testing/ci-local.sh b/testing/ci-local.sh index 8c3759f1..14939572 100755 --- a/testing/ci-local.sh +++ b/testing/ci-local.sh @@ -661,6 +661,47 @@ run_static() { record "static-$topology" $rc } +# Lines kept from each node's log when a red scenario's results are printed. +CHAOS_DUMP_LINES=300 + +# Print a red chaos scenario's results into the run log. +# +# A CI worker that runs each job in a worktree it deletes afterwards, under a +# private /tmp, loses the results directory when the run ends, and the log is +# the only record that survives. Without this such a red cannot be traced node +# by node. The runner's own log is not repeated here: it already reached the run +# log as the scenario's output. Each node log is capped, so the total grows with +# node count; the largest CI scenario has ten nodes. +chaos_dump() { + local name="$1" base="$2" dir f + dir="$(find "$base" -mindepth 1 -maxdepth 1 -type d 2>/dev/null | sort | tail -n 1)" + if [[ -z "$dir" ]]; then + echo "[chaos/$name] no results directory under $base" + return 0 + fi + echo "===== chaos-$name results from $dir =====" + for f in status.txt assertions.txt; do + [[ -f "$dir/$f" ]] || continue + echo "----- $f -----" + cat "$dir/$f" + done + if [[ -f "$dir/tree-snapshot-final.json" ]]; then + echo "----- final tree: node, root, parent -----" + python3 -c ' +import json, sys +for node, tree in sorted(json.load(open(sys.argv[1])).items()): + print(node, tree.get("root"), tree.get("parent")) +' "$dir/tree-snapshot-final.json" || true + fi + for f in "$dir"/fips-node-*.log; do + [[ -f "$f" ]] || continue + echo "----- $(basename "$f"), last $CHAOS_DUMP_LINES lines -----" + tail -n "$CHAOS_DUMP_LINES" "$f" + done + echo "===== end of chaos-$name results =====" + return 0 +} + # Run a chaos scenario run_chaos() { local name="$1" @@ -678,11 +719,17 @@ run_chaos() { suffix="$(ci_chaos_suffix "$name")" local -x FIPS_CI_NAME_SUFFIX="$suffix" + # The same scoping for the results, so a red can find the directory this + # run wrote rather than guess among earlier runs' timestamps. + local results="$SCRIPT_DIR/chaos/sim-results/ci$suffix" + local -x FIPS_SIM_OUTPUT="$results" + info "[chaos/$name] Running simulation" if bash testing/chaos/scripts/chaos.sh "$@" 2>&1; then rc=0 else rc=1 + chaos_dump "$name" "$results" fi record "chaos-$name" $rc @@ -1345,9 +1392,12 @@ run_integration() { record "chaos-$scenario" 0 else record "chaos-$scenario" 1 - # Show tail of failure log - echo "--- chaos-$scenario output (last 20 lines) ---" - tail -20 "$logfile" 2>/dev/null || true + # The whole log, not its tail: the child printed the results + # directory into it, and this is the only place that reaches + # the run log. The sed keeps the last frame of each line the + # progress display redraws with carriage returns. + echo "--- chaos-$scenario output ---" + sed 's/.*\r//' "$logfile" 2>/dev/null || true echo "---" fi rm -f "$logfile" diff --git a/testing/iface-binding/test.sh b/testing/iface-binding/test.sh index eccf4cce..aca65341 100755 --- a/testing/iface-binding/test.sh +++ b/testing/iface-binding/test.sh @@ -46,10 +46,30 @@ BOOT_IFACE="ve-boot0" # Host-side veth names, scoped per run: these live in the host (or Docker VM) # namespace for the moment between creation and the move into the containers, # where two concurrent runs would otherwise collide on one name. -HOST_VETH_A="vhifb${FIPS_CI_NAME_SUFFIX:-0}a" -HOST_VETH_B="vhifb${FIPS_CI_NAME_SUFFIX:-0}b" -HOST_VETH_C="vhifb${FIPS_CI_NAME_SUFFIX:-0}c" -HOST_VETH_D="vhifb${FIPS_CI_NAME_SUFFIX:-0}d" +# +# The scope comes from a four-hex hash of the run suffix, not from the suffix +# itself. An interface name gets 15 characters and the suffix alone can spend +# 24 of them (`-20260910t025205-2802512`), so interpolating it produced +# `vhifb-20260910t025205-2802512b` and ip(8) refused the name outright. The +# chaos simulation had already met this and answers it in `sim.naming`, which +# the NAT topology script also calls; this uses the same token so the reaper +# in `ci-cleanup.sh` can match these interfaces by the same rule. +# +# Empty for an empty suffix, so a bare run keeps short unscoped names. +veth_token() { + local suffix="${FIPS_CI_NAME_SUFFIX:-}" + if [ -z "$suffix" ]; then + echo "" + return 0 + fi + PYTHONPATH="$TESTING_DIR/chaos" python3 -m sim.naming "$suffix" +} + +VETH_TOKEN="$(veth_token)" +HOST_VETH_A="vhifb${VETH_TOKEN}a" +HOST_VETH_B="vhifb${VETH_TOKEN}b" +HOST_VETH_C="vhifb${VETH_TOKEN}c" +HOST_VETH_D="vhifb${VETH_TOKEN}d" SKIP_BUILD=false KEEP_UP=false