diff --git a/testing/chaos/README.md b/testing/chaos/README.md index 7d21a1d..401c40e 100644 --- a/testing/chaos/README.md +++ b/testing/chaos/README.md @@ -257,27 +257,52 @@ since they use beacon discovery. Results written to `sim-results/` (configurable via `logging.output_dir`): +- `status.txt` -- How the run ended, plus the scenario, the seed and the + container names it used; one `key=value` per line - `analysis.txt` -- Summary: panics, errors, sessions, metrics - `metadata.txt` -- Seed, node count, edges, adjacency list - `runner.log` -- Orchestration events (topology, netem, churn, traffic) with timestamps - `fips-node-nXX.log` -- Per-node log output +The `status` field reads: + +- `completed` -- ran for its configured duration +- `interrupted` -- a signal cut the run short, so the artifacts are real + but describe less time than the scenario asked for +- `aborted` -- the run raised part way through; same caveat, and + `runner.log` carries the traceback +- `setup-failed` -- the containers never started +- `teardown-failed` -- the mesh ran but its logs or analysis could not be + produced + +A `setup-failed` directory holds `runner.log` and `status.txt` and nothing +else. Nothing is harvested, because container names are global to the host +and reading them after a failed setup describes whichever run holds them +now. So `analysis.txt` in a result directory is proof that this scenario's +own mesh existed. A directory with no `status.txt` was written before this +was the case and says nothing either way. + Exit codes: - `0` -- Ran to completion, no panics, every assertion passed -- `1` -- The scenario file could not be loaded, teardown itself raised, or a - second interrupt arrived while the first was being handled +- `1` -- The scenario file could not be loaded, or a second interrupt + arrived while the first was being handled - `2` -- Panics found in the collected node logs. Also what the argument parser exits with when it rejects the command line, before any run starts - `3` -- A post-run assertion failed -- `4` -- Setup, warmup or the simulation loop raised, so the run did not - complete; `runner.log` carries the traceback +- `4` -- Setup, warmup, the simulation loop or teardown raised, so the run + did not complete; `runner.log` carries the traceback Codes 2 and 3 describe what a mesh that ran did. Code 4 says there is nothing to describe, and takes precedence over both. Code 2 is dual-use: a run that never started cannot have panicked, so read it together with whether `runner.log` exists. +A run stopped by a signal exits on this same ladder rather than one of its +own: what it collected before stopping is still worth reporting, and +`status.txt` says it was cut short. `chaos.sh` reports 130 for a Ctrl-C of +its own accord. + ## Creating Custom Scenarios 1. Copy an existing scenario from `scenarios/`. diff --git a/testing/chaos/sim/logs.py b/testing/chaos/sim/logs.py index 0033635..e698002 100644 --- a/testing/chaos/sim/logs.py +++ b/testing/chaos/sim/logs.py @@ -29,9 +29,18 @@ __all__ = ["AnalysisResult", "analyze_logs", "collect_logs", "write_sim_metadata def collect_logs(container_names: list[str], output_dir: str) -> dict[str, str]: - """Collect all output (stdout + stderr) from all containers.""" + """Collect all output (stdout + stderr) from all containers. + + Raises RuntimeError if any container's output could not be read, or if + there was nothing to read. `docker logs` writes its own failures to + stderr and exits non-zero, so without the returncode check the daemon's + "No such container" reply was stored as though it were the node's log + and analysed as a mesh with no panics, no errors and no sessions -- + which reads exactly like a clean run. + """ os.makedirs(output_dir, exist_ok=True) logs = {} + failed = [] for name in container_names: try: @@ -41,17 +50,35 @@ def collect_logs(container_names: list[str], output_dir: str) -> dict[str, str]: text=True, timeout=30, ) - raw = result.stdout + result.stderr - log_text = strip_ansi(raw) - logs[name] = log_text - - path = os.path.join(output_dir, f"{name}.log") - with open(path, "w") as f: - f.write(log_text) - - except (subprocess.TimeoutExpired, Exception) as e: + except Exception as e: log.warning("Failed to collect logs from %s: %s", name, e) - logs[name] = "" + failed.append(name) + continue + + if result.returncode != 0: + log.warning( + "docker logs %s exited %d: %s", + name, result.returncode, result.stderr.strip(), + ) + failed.append(name) + continue + + # A container's own stderr comes back on our stderr, so both + # streams are log content on the success path. + log_text = strip_ansi(result.stdout + result.stderr) + logs[name] = log_text + + path = os.path.join(output_dir, f"{name}.log") + with open(path, "w") as f: + f.write(log_text) + + if failed: + raise RuntimeError( + f"could not collect logs from {len(failed)}/{len(container_names)} " + f"containers: {', '.join(failed)}" + ) + if not logs: + raise RuntimeError("no container logs were collected") return logs diff --git a/testing/chaos/sim/runner.py b/testing/chaos/sim/runner.py index 61f2ce1..cd34cd0 100644 --- a/testing/chaos/sim/runner.py +++ b/testing/chaos/sim/runner.py @@ -20,6 +20,7 @@ from .docker_exec import docker_compose from .link_swap import LinkSwapManager from .links import LinkManager from .logs import AnalysisResult, analyze_logs, collect_logs, write_sim_metadata +from .naming import name_suffix from .netem import NetemManager from .nodes import NodeManager from .peer_churn import PeerChurnManager @@ -45,6 +46,13 @@ class SimRunner: # of run() carries the fact that the simulation did not complete. self.aborted = False + # Whether this run ever owned containers. Teardown runs from a + # finally, so it runs after a failed setup too, and container names + # are global: without this it would harvest whatever currently + # answers to them. topology and compose_file are both set well + # before the containers start and so cannot stand in for it. + self._containers_started = False + # Shared set of currently-down node IDs (updated by NodeManager, # read by NetemManager, LinkManager, TrafficManager) self._down_nodes: set[str] = set() @@ -190,6 +198,7 @@ class SimRunner: # 5. Start containers log.info("Starting %d containers...", len(self.topology.nodes)) docker_compose(self.compose_file, ["up", "-d"]) + self._containers_started = True # 6. Set up veth pairs for Ethernet edges (before netem) # @@ -427,11 +436,57 @@ class SimRunner: def assertions_failed(self) -> bool: return any(not o.passed for o in self.assertion_outcomes) + def _run_status(self) -> str: + """Name for how the run itself ended, before teardown is considered.""" + if self.aborted: + return "aborted" + if self._interrupted: + return "interrupted" + return "completed" + + def _write_status(self, status: str) -> None: + """Record how the run ended, for a reader who has only this directory. + + One field per line so it can be grepped. The container names are + included because they are the handle on everything else the run + touched, and because a directory that names them cannot be mistaken + for a directory assembled from some other scenario's mesh. + + Never raises. Both callers run this immediately before stopping the + containers, so letting a full disk or a vanished output directory + out of here would leak the mesh it was about to tear down. + """ + try: + os.makedirs(self.output_dir, exist_ok=True) + path = os.path.join(self.output_dir, "status.txt") + with open(path, "w") as f: + f.write(f"status={status}\n") + f.write(f"scenario={self.scenario.name}\n") + f.write(f"seed={self.scenario.seed}\n") + f.write(f"containers=fips-node-nNN{name_suffix()}\n") + except Exception: + log.exception("Could not write status file") + def _teardown(self) -> AnalysisResult | None: """Stop dynamic elements, collect logs, analyze, stop containers.""" - result = None + if not self._containers_started: + # There is no mesh to harvest. Snapshots, logs, analysis and + # assertions all address containers by a name that is global to + # the host, so running them here would describe whoever holds + # those names now and leave a plausible report of a run that + # never happened. Leaving them out makes the presence of + # analysis.txt proof that this scenario's own mesh existed. + self._write_status("setup-failed") + if self.compose_file: + # `up -d` can fail part way through, so this run may own + # containers or a network even with no mesh to speak of. + log.info("Stopping containers...") + docker_compose(self.compose_file, ["down"], check=False) + return None - if self.topology and self.compose_file: + result = None + status = self._run_status() + try: # Evaluate post-run assertions before doing any teardown so # control sockets are still reachable. self._evaluate_assertions() @@ -516,8 +571,19 @@ class SimRunner: if self.veth_mgr: log.info("Cleaning up veth pairs...") self.veth_mgr.teardown_all() - - # Stop containers + except Exception: + # Same reasoning as run(): logging keeps the traceback in + # runner.log, where re-raising would send it to stderr instead + # and past the exit ladder, which would report a harvest that + # fell over as a bad command line. + log.exception("Teardown failed") + self.aborted = True + status = "teardown-failed" + result = None + finally: + # Status first: it is the one artifact that must exist whatever + # else happens, and stopping containers can still time out. + self._write_status(status) log.info("Stopping containers...") docker_compose( self.compose_file,