diff --git a/conformance/lib/record_run.py b/conformance/lib/record_run.py index 0e271b1..a5e6515 100755 --- a/conformance/lib/record_run.py +++ b/conformance/lib/record_run.py @@ -27,6 +27,17 @@ Chainsaw's JUnit carries no stdout — its `` elements hold only `.go::` prefix is optional so a redirected/plain log still attributes. _LOG_HEADER_RE = re.compile( - r"^\s*\|\s*\d{1,2}:\d{2}:\d{2}(?:\.\d+)?\s*\|\s*([A-Za-z0-9][A-Za-z0-9._-]*)\s*\|") + r"^\s*(?:[\w./-]+\.go:\d+:\s*)?" + r"\|\s*\d{1,2}:\d{2}:\d{2}(?:\.\d+)?\s*\|\s*([A-Za-z0-9][A-Za-z0-9._-]*)\s*\|") + +# ANSI colour + the backspace padding Go writes ahead of a `t.Log` continuation. Stripped +# before ANY parsing; neither ever appears at the head of a line, so indentation survives. +_ANSI_RE = re.compile(r"\x1b\[[0-9;]*[A-Za-z]") + + +def _strip_noise(line: str) -> str: + return _ANSI_RE.sub("", line).replace("\b", "") + + +# ===================================================================== output sections +# THE BUG THIS SECTION MACHINERY EXISTS TO KILL — READ BEFORE CHANGING ANYTHING +# ----------------------------------------------------------------------------- +# Chainsaw echoes the script it is ABOUT TO RUN, verbatim, in an indented `=== COMMAND` +# block, and only afterwards prints what the script actually wrote in `=== STDOUT`. Every +# skip-gated test contains its own skip token as SOURCE TEXT (`echo NODE_LOSS_SKIPPED_OK`), +# so a raw whole-log grep finds that token in EVERY run of that test — including runs that +# never took the skip branch. Combined with decide()'s (correct) rule that a skip token +# outranks a pass token, a section-blind scan can never record `proven` for ANY test that +# has a skip gate: the ledger fails closed so hard it records nothing. Observed on +# runs/20260901T235117Z-e9a4b66, where NODE_LOSS_SKIPPED_OK appears twice as source at +# lines 51/62 (`=== COMMAND`) and never in output, yet the run genuinely proved R-STATE-02. +# +# So tokens are attributed to SECTIONS, never to raw lines: +# l.go:52: | 23:51:18 | node-loss | step | CMD | RUN | <- header, no section +# === COMMAND <- marker (indent 8) +# /usr/bin/sh -c set -euo pipefail <- source, indent >= 8 +# echo NODE_LOSS_SKIPPED_OK <- SOURCE, not output +# l.go:52: | 23:52:42 | node-loss | step | SCRIPT | LOG | <- indent 4 => section ends +# === STDOUT <- marker +# NODE_LOSS_VOLUME_AVAILABLE_OK <- the REAL emission +# +# A marker is an INDENTED `=== NAME` on a line of its own. Go's own test markers +# (`=== RUN chainsaw`, `=== PAUSE`, `=== CONT`) are at column 0 and carry a test name +# after the verb, so they match neither the indent nor the end-of-line anchor; they are +# additionally named in _GO_TEST_MARKERS so a future indented variant still cannot open a +# section that would swallow the whole log. +_SECTION_MARKER_RE = re.compile(r"^(\s+)=== ([A-Z][A-Z0-9_]*)\s*$") +_GO_TEST_MARKERS = frozenset({"RUN", "PAUSE", "CONT"}) + +# Pseudo-section for a log that contains NO section markers at all (the plain/redirected +# logs the earlier ledger rows were written from, and the selftest fixtures). Such a log +# never echoes script source, so there is nothing to be confused by and the legacy +# whole-log scan is exactly as safe as it was — narrowing is only needed where a COMMAND +# echo exists. Lines OUTSIDE a section in a log that DOES use sections are attributed to +# "" and are evidence for nothing. +UNSECTIONED = "*" + +# A pass token counts ONLY where Chainsaw's own `contains($stdout, ...)` check looks: +# real stdout. Anything else — source echo, stderr, an unrecognised future section — can +# never manufacture a proof. +PASS_SECTIONS = frozenset({"STDOUT", UNSECTIONED}) + +# Sections that carry SOURCE rather than output. A skip token is honoured in every OTHER +# section (STDOUT, STDERR, any section name added by a later Chainsaw release), because +# over-reading a skip only ever COSTS a proof, while over-reading a pass would fabricate +# one. Unknown section names therefore fail closed in both directions. +SOURCE_SECTIONS = frozenset({"COMMAND"}) + + +def classify_sections(log_text: str) -> list[tuple[str, str]]: + """[(section, line)] for every line of a run log. + + `section` is the enclosing `=== NAME` block, "" for a line inside no block, or + UNSECTIONED for every line when the log declares no sections at all. A block runs from + its marker until the first non-blank line indented LESS than the marker (blank lines do + not end it) or until the next marker; the marker line itself is content of nothing. + """ + rows: list[tuple[str, str]] = [] + cur, cur_indent, sectioned = "", 0, False + for raw in log_text.splitlines(): + line = _strip_noise(raw) + m = _SECTION_MARKER_RE.match(line) + if m and m.group(2) not in _GO_TEST_MARKERS: + sectioned = True + cur, cur_indent = m.group(2), len(m.group(1)) + rows.append(("", line)) + continue + if cur: + if not line.strip() or len(line) - len(line.lstrip()) >= cur_indent: + rows.append((cur, line)) + continue + cur = "" + rows.append(("", line)) + if not sectioned: + return [(UNSECTIONED, line) for _, line in rows] + return rows + + +def scan_texts(lines) -> tuple[str, str]: + """(text a PASS token may be read from, text a SKIP token may be read from). + + Accepts either [(section, line)] pairs from classify_sections() or a plain list of + strings, which is treated as an unsectioned log (legacy whole-log scanning). + """ + pass_lines, skip_lines = [], [] + for item in lines: + section, line = item if isinstance(item, tuple) else (UNSECTIONED, item) + if section in PASS_SECTIONS: + pass_lines.append(line) + if section and section not in SOURCE_SECTIONS: + skip_lines.append(line) + return "\n".join(pass_lines), "\n".join(skip_lines) _RUN_ID_TS_RE = re.compile(r"^(\d{8}T\d{6}Z)-") @@ -203,28 +321,32 @@ def sentinel_map(tests_dir: Path) -> dict[str, dict]: # =============================================================================== log -def attribute_log(log_text: str, known: set[str]) -> tuple[dict[str, list[str]], bool]: - """Split a run log into per-testcase line buckets. +def attribute_log(log_text: str, known: set[str]) -> tuple[dict[str, list[tuple[str, str]]], + bool]: + """Split a run log into per-testcase buckets of (section, line) pairs. Chainsaw prefixes its log lines with `| HH:MM:SS | | | ...` and prints a - script's stdout underneath that header, so the test name is carried by a state machine: - a header naming a KNOWN test switches the current bucket, every following line lands in - it. Requiring the name to be known is what stops run.sh's own `[run.sh]` chatter (and - any other pipe-shaped line) from opening a bogus bucket. + script's sections underneath that header, so the test name is carried by a state + machine: a header naming a KNOWN test switches the current bucket, every following line + lands in it. Requiring the name to be known is what stops run.sh's own `[run.sh]` + chatter (and any other pipe-shaped line) from opening a bogus bucket. + + Section labels come from classify_sections() and travel WITH the lines, so a bucket + still knows which of its lines were script source and which were real output. Returns (buckets, attributed) where `attributed` is False when the log contained no recognisable header at all — the signal for the degraded global scan in decide(). """ - buckets: dict[str, list[str]] = {} + buckets: dict[str, list[tuple[str, str]]] = {} cur: str | None = None attributed = False - for line in log_text.splitlines(): + for section, line in classify_sections(log_text): m = _LOG_HEADER_RE.match(line) if m and m.group(1) in known: cur = m.group(1) attributed = True if cur is not None: - buckets.setdefault(cur, []).append(line) + buckets.setdefault(cur, []).append((section, line)) return buckets, attributed @@ -253,7 +375,7 @@ def decide(layer: str, junit_result: str, sent: dict, lines: list[str], 1. JUnit failure/error -> failed (a red run is recorded as red) 2. JUnit -> junit-skipped (never green; ci/lib.sh rule) 3. ANY declared skip token seen -> skipped (BEATS a green JUnit and beats - the pass token: if any gated + IN REAL OUTPUT the pass token: if any gated step self-skipped, the run did not prove the requirement) 4. no sentinel declared -> proven only for L0/L1, whose skips are already @@ -264,6 +386,13 @@ def decide(layer: str, junit_result: str, sent: dict, lines: list[str], Step 5 requires ALL pass tokens, not just the terminal one: every Chainsaw step here asserts `pass || skip`, so a missing pass token means a step did not reach its proven branch, whatever the JUnit says. + + Steps 3 and 5 read from SECTION-SCOPED text, never from raw lines: a pass token counts + only in `=== STDOUT`, a skip token counts in any section that is not script source. + That narrows WHERE a token is read from and changes nothing about what it means — skip + still outranks pass, and it outranks it within genuine output, which is the only place + either of them was ever evidence. `lines` may be [(section, line)] pairs or plain + strings (an unsectioned log; see scan_texts / UNSECTIONED). """ if junit_result in ("failed", "error"): return (None, "failed", f"JUnit recorded {junit_result}") @@ -271,12 +400,12 @@ def decide(layer: str, junit_result: str, sent: dict, lines: list[str], return (None, "junit-skipped", "JUnit — the test did not execute; a skip is never green") - text = "\n".join(lines) - seen_skip = [t for t in sent["skip"] if t in text] + pass_text, skip_text = scan_texts(lines) + seen_skip = [t for t in sent["skip"] if t in skip_text] if seen_skip: return (seen_skip[0], "skipped", - f"run log carries the SELF-SKIP token {seen_skip[0]!r} — the test exited 0 " - f"without exercising the behaviour, so this is NOT proof") + f"run log OUTPUT carries the SELF-SKIP token {seen_skip[0]!r} — the test " + f"exited 0 without exercising the behaviour, so this is NOT proof") if not sent["pass"] and not sent["skip"]: if layer not in SENTINEL_EXEMPT_LAYERS: @@ -288,14 +417,14 @@ def decide(layer: str, junit_result: str, sent: dict, lines: list[str], f"{layer} offline check exited 0; run_l1_offline.py renders its skips as " f"JUnit , so a green JUnit is truthful without a sentinel") - missing = [t for t in sent["pass"] if t not in text] + missing = [t for t in sent["pass"] if t not in pass_text] if not missing: return (sent["terminal_pass"], "proven", - f"run log carries every declared pass token " + f"run log OUTPUT carries every declared pass token " f"({', '.join(sent['pass'])}) and no skip token [{scope}]") return (None, "unknown-sentinel-absent", - f"run log lacks pass token(s) {', '.join(missing)} for this test [{scope}] — " - f"refusing to infer proof from the JUnit alone") + f"run log OUTPUT lacks pass token(s) {', '.join(missing)} for this test " + f"[{scope}] — refusing to infer proof from the JUnit alone") # ============================================================================= junit @@ -387,9 +516,13 @@ def build_rows(run_dir: Path, tests_dir: Path, env: str, chainsaw_version: str, junit = run_dir / "report.junit.xml" log = run_dir / "run.log" smap = sentinel_map(tests_dir) - buckets, attributed = attribute_log(log.read_text(errors="replace"), set(smap)) + log_text = log.read_text(errors="replace") + buckets, attributed = attribute_log(log_text, set(smap)) uniq = unique_tokens(smap) - all_lines = log.read_text(errors="replace").splitlines() + all_pairs = classify_sections(log_text) + sectioned = any(sec not in ("", UNSECTIONED) for sec, _ in all_pairs) + section_note = ("tokens read from real-output sections only" + if sectioned else "log declares no === sections; whole-log scan") ts = run_timestamp(run_dir, junit) rows: list[dict] = [] @@ -403,17 +536,18 @@ def build_rows(run_dir: Path, tests_dir: Path, env: str, chainsaw_version: str, reqs = sent.get("requirements") or case["requirements"] if name in buckets: - lines, scope = buckets[name], "log scoped to this testcase" + lines, scope = buckets[name], f"log scoped to this testcase; {section_note}" elif not attributed: # Degraded mode: the log had no recognisable Chainsaw header (a redirected or # reformatted log). Fall back to a whole-log scan, but ONLY for tokens owned by # exactly one test, so a token another test emitted can never prove this one. - lines = all_lines + lines = all_pairs sent = dict(sent, **{"pass": [t for t in sent["pass"] if t in uniq], "skip": [t for t in sent["skip"] if t in uniq]}) sent["terminal_pass"] = sent["pass"][-1] if sent["pass"] else None - scope = "DEGRADED: unattributable log, globally-unique tokens only" + scope = ("DEGRADED: unattributable log, globally-unique tokens only; " + + section_note) else: lines, scope = [], "no log lines attributed to this testcase" @@ -552,6 +686,98 @@ def _selftest() -> int: check("an unknown/blank layer fails CLOSED — sentinel required", proof == "unknown-no-sentinel-declared") + # --- SECTION SCOPING: the COMMAND echo is SOURCE, never evidence ------------------- + # Regression cases for the ledger's first real L3 run, which recorded a genuine PASS as + # `skipped` because `echo NODE_LOSS_SKIPPED_OK` — the skip branch NOT taken — is echoed + # inside `=== COMMAND` on every run of a skip-gated test. + nl = {"pass": ["NODE_LOSS_VOLUME_AVAILABLE_OK"], + "skip": ["NODE_LOSS_SKIPPED_OK"], + "terminal_pass": "NODE_LOSS_VOLUME_AVAILABLE_OK"} + _CMD = (" l.go:52: | 23:51:18 | node-loss | step | CMD | RUN |\n" + " === COMMAND\n" + " /usr/bin/sh -c set -euo pipefail\n" + " if ! kubectl get storageclass longhorn >/dev/null 2>&1; then\n" + " echo NODE_LOSS_SKIPPED_OK\n" + "\n" + " exit 0\n" + " fi\n" + " echo NODE_LOSS_VOLUME_AVAILABLE_OK\n" + " l.go:52: | 23:52:42 | node-loss | step | SCRIPT | LOG |\n") + + ran = classify_sections(_CMD + " === STDOUT\n" + " ready nodes: 3\n" + " NODE_LOSS_VOLUME_AVAILABLE_OK\n" + " l.go:52: | 23:52:42 | node-loss | step | SCRIPT | DONE |\n") + sent, proof, _ = decide("L3", "passed", nl, ran, "t") + check("skip token ONLY in the COMMAND echo + pass token in STDOUT is PROVEN", + proof == "proven" and sent == "NODE_LOSS_VOLUME_AVAILABLE_OK") + + selfskipped = classify_sections(_CMD + " === STDOUT\n" + " SKIP: 'longhorn' StorageClass absent\n" + " NODE_LOSS_SKIPPED_OK\n") + sent, proof, _ = decide("L3", "passed", nl, selfskipped, "t") + check("skip token GENUINELY in STDOUT is still 'skipped' (the guarantee holds)", + proof == "skipped" and sent == "NODE_LOSS_SKIPPED_OK") + + neither = classify_sections(_CMD + " === STDOUT\n ready nodes: 3\n") + _, proof, _ = decide("L3", "passed", nl, neither, "t") + check("both tokens in COMMAND and neither in STDOUT is NOT proven", + proof == "unknown-sentinel-absent") + + both_out = classify_sections(" === STDOUT\n" + " NODE_LOSS_VOLUME_AVAILABLE_OK\n" + " NODE_LOSS_SKIPPED_OK\n") + _, proof, _ = decide("L3", "passed", nl, both_out, "t") + check("skip still BEATS pass when both are in genuine output", proof == "skipped") + + stderr_skip = classify_sections(" === STDERR\n NODE_LOSS_SKIPPED_OK\n" + " === STDOUT\n" + " NODE_LOSS_VOLUME_AVAILABLE_OK\n") + _, proof, _ = decide("L3", "passed", nl, stderr_skip, "t") + check("a skip token in a non-source section (STDERR) still costs the proof", + proof == "skipped") + + stderr_pass = classify_sections(" === STDERR\n" + " NODE_LOSS_VOLUME_AVAILABLE_OK\n") + _, proof, _ = decide("L3", "passed", nl, stderr_pass, "t") + check("a pass token OUTSIDE stdout cannot prove anything", + proof == "unknown-sentinel-absent") + + # --- classify_sections: markers, extents, and Go's own `=== RUN` -------------------- + gorows = classify_sections("=== RUN chainsaw\n=== PAUSE chainsaw\n" + "=== CONT chainsaw/node-loss\n" + " === COMMAND\n echo NODE_LOSS_SKIPPED_OK\n" + " l.go:52: | 1:00:00 | node-loss | s | SCRIPT | DONE |\n" + "--- PASS: chainsaw/node-loss (131.09s)\n") + secs = [sec for sec, _ in gorows] + check("Go's column-0 `=== RUN/PAUSE/CONT` never open a section", + secs[:3] == ["", "", ""]) + check("a section covers its indented body and ends at a less-indented line", + secs[3] == "" and secs[4] == "COMMAND" and secs[5] == "" and secs[6] == "") + check("a log with no === markers stays wholly scannable (UNSECTIONED)", + {sec for sec, _ in classify_sections("plain line\n another\n")} == {UNSECTIONED}) + + # --- the preserved run itself, as a fixture ---------------------------------------- + # runs/20260901T235117Z-e9a4b66 IS the bug: NODE_LOSS_SKIPPED_OK twice in `=== COMMAND` + # (source), never in output; NODE_LOSS_VOLUME_AVAILABLE_OK once in `=== STDOUT`. + fixture = CONF_ROOT / "runs" / "20260901T235117Z-e9a4b66" + if (fixture / "run.log").is_file() and (fixture / "report.junit.xml").is_file(): + rows = build_rows(fixture, CONF_ROOT / "tests", "dev", "v0.2.12", "v1.36.4", "sha") + row = next((r for r in rows if r["test"] == "node-loss"), None) + check("preserved real L3 run records node-loss/R-STATE-02 as proven", + row is not None and row["proof"] == "proven" + and row["sentinel"] == "NODE_LOSS_VOLUME_AVAILABLE_OK" + and row["requirements"] == ["R-STATE-02"]) + check("preserved real L3 run attributes (no DEGRADED fallback needed)", + row is not None and "DEGRADED" not in row["note"]) + pairs = classify_sections((fixture / "run.log").read_text(errors="replace")) + secs = {sec for sec, line in pairs if "NODE_LOSS_SKIPPED_OK" in line} + check("every NODE_LOSS_SKIPPED_OK in the preserved log is COMMAND source", + secs == {"COMMAND"}) + secs = {sec for sec, line in pairs + if line.strip() == "NODE_LOSS_VOLUME_AVAILABLE_OK"} + check("the real emission in the preserved log is in STDOUT", secs == {"STDOUT"}) + # --- log attribution -------------------------------------------------------------- log = ("[run.sh] Coverage report first\n" " | 20:41:32 | node-loss | step | SCRIPT | RUN |\n" @@ -561,10 +787,22 @@ def _selftest() -> int: b, attributed = attribute_log(log, {"node-loss", "dr-restore"}) check("log lines are attributed to the testcase whose header preceded them", attributed - and any("NODE_LOSS_SKIPPED_OK" in l for l in b["node-loss"]) - and not any("NODE_LOSS_SKIPPED_OK" in l for l in b["dr-restore"])) + and any("NODE_LOSS_SKIPPED_OK" in l for _, l in b["node-loss"]) + and not any("NODE_LOSS_SKIPPED_OK" in l for _, l in b["dr-restore"])) check("a pass token does NOT leak across testcase boundaries", - not any("DR_RESTORED" in l for l in b["node-loss"])) + not any("DR_RESTORED" in l for _, l in b["node-loss"])) + check("an unsectioned log keeps whole-log scanning (nothing narrowed away)", + all(sec == UNSECTIONED for sec, _ in b["node-loss"])) + + # Chainsaw's real headers carry a Go `t.Log` source prefix and ANSI colour; the earlier + # regex matched neither, so every genuine Chainsaw log silently fell into DEGRADED mode. + real_hdr = (" l.go:52: \x08\x08\x08| 23:51:18 | \x1b[32;1mnode-loss\x1b[0;22m | " + "\x1b[32;1mstep\x1b[0;22m | SCRIPT | LOG |\n" + " === STDOUT\n NODE_LOSS_VOLUME_AVAILABLE_OK\n") + b2, attributed_real = attribute_log(real_hdr, {"node-loss"}) + check("a REAL Chainsaw header (go source prefix + ANSI) attributes, not degrades", + attributed_real and "node-loss" in b2 + and ("STDOUT", " NODE_LOSS_VOLUME_AVAILABLE_OK") in b2["node-loss"]) _, attributed2 = attribute_log("no chainsaw headers at all\n", {"node-loss"}) check("an unattributable log is reported as such (degraded mode)", not attributed2) diff --git a/conformance/lib/status.py b/conformance/lib/status.py index b0e2c01..a91f748 100755 --- a/conformance/lib/status.py +++ b/conformance/lib/status.py @@ -108,7 +108,14 @@ FLUX_API = "kustomize.toolkit.fluxcd.io" # conformance/tests — those are the TESTS; they are the VERIFICATION axis, counted there. # ci/tests — gate unit-test fixtures embed example R-IDs as DATA. # registry.yaml — the requirement mirror itself, not an implementation of anything. -IMPL_EXCLUDE_PREFIXES = ("conformance/tests/", "ci/tests/") +# `conformance/runs/` is excluded for a subtler reason than the test dirs: the ledger and the +# preserved run logs CONTAIN the requirement IDs they are evidence FOR. Counting them as +# implementing evidence makes `last_change` move every time proof is recorded, so a row's +# git_sha always predates it and EVERY proof degrades to stale-proof the instant it is +# committed — recording the proof destroys it. The ledger is the proof record; it must not +# participate in the freshness computation about itself. (Found live 2026-09-01 on the first +# PROVEN row.) +IMPL_EXCLUDE_PREFIXES = ("conformance/tests/", "ci/tests/", "conformance/runs/") IMPL_EXCLUDE_PATHS = ("conformance/requirements/registry.yaml",) diff --git a/conformance/runs/20260901T235117Z-e9a4b66/report.junit.xml b/conformance/runs/20260901T235117Z-e9a4b66/report.junit.xml new file mode 100644 index 0000000..312292b --- /dev/null +++ b/conformance/runs/20260901T235117Z-e9a4b66/report.junit.xml @@ -0,0 +1,4 @@ + + + + \ No newline at end of file diff --git a/conformance/runs/20260901T235117Z-e9a4b66/run.log b/conformance/runs/20260901T235117Z-e9a4b66/run.log new file mode 100644 index 0000000..5cb7413 --- /dev/null +++ b/conformance/runs/20260901T235117Z-e9a4b66/run.log @@ -0,0 +1,232 @@ +[run.sh] Coverage report first (always) +[coverage] 42/51 requirements have a scaffolded test (82.4%); 9 gap(s), 0 safety-critical gap(s). +[coverage] wrote /work/conformance/_artifacts/coverage/coverage.md and /work/conformance/_artifacts/coverage/coverage.json +[run.sh] No L0/L1 offline checks match the selection (layer=l3 reqs='R-STATE-02'). +[run.sh] LIGHT pass: no tests selected. +[run.sh] HEAVY pass: 1 test(s) SERIAL (parallel=1) — node-loss +Version: 0.2.12 +Loading config (/work/conformance/config/chainsaw-config.yaml)... +- Using test file: chainsaw-test +- TestDirs [/work/conformance/tests/l3-fault-injection/node-loss] +- SkipDelete false +- FailFast false +- ReportFormat 'JUNIT-TEST' +- ReportName 'chainsaw-report-heavy' +- ReportPath '/work/conformance/_artifacts' +- Namespace '' +- FullName false +- IncludeTestRegex '' +- ExcludeTestRegex '' +- ApplyTimeout 1m30s +- AssertTimeout 3m0s +- CleanupTimeout 2m0s +- DeleteTimeout 2m0s +- ErrorTimeout 1m0s +- ExecTimeout 3m0s +- DeletionPropagationPolicy Background +- Parallel 1 +- Template true +- NoCluster false +- PauseOnFailure false +Loading tests... +- node-loss (/work/conformance/tests/l3-fault-injection/node-loss) +Loading values... +Running tests... +=== RUN chainsaw +=== PAUSE chainsaw +=== CONT chainsaw +=== RUN chainsaw/node-loss +=== PAUSE chainsaw/node-loss +=== CONT chainsaw/node-loss + l.go:52: | 23:51:18 | node-loss | @chainsaw  | CREATE | OK | v1/Namespace @ chainsaw-fond-marlin + l.go:52: | 23:51:18 | node-loss | volume-stays-available-across-node-loss | TRY | BEGIN | + l.go:52: | 23:51:18 | node-loss | volume-stays-available-across-node-loss | CMD | RUN | + === COMMAND + /usr/bin/sh -c set -euo pipefail + NS="$NAMESPACE" + + # -- Gate 1: skip cleanly (green) if the longhorn tier is not present yet. -- + if ! kubectl get storageclass longhorn >/dev/null 2>&1; then + echo "SKIP: 'longhorn' StorageClass absent — node-loss not applicable on this cluster yet" + echo NODE_LOSS_SKIPPED_OK + exit 0 + fi + + # -- Gate 2: a 3-replica volume + single-node-loss headroom needs >= 3 Ready nodes. -- + READY="$(kubectl get nodes \ + -o jsonpath='{range .items[*]}{.status.conditions[?(@.type=="Ready")].status}{"\n"}{end}' \ + | grep -c '^True$' || true)" + echo "ready nodes: ${READY}" + if [ "${READY:-0}" -lt 3 ]; then + echo "SKIP: only ${READY:-0} Ready node(s) (<3) — node-loss resilience not meaningful yet" + echo NODE_LOSS_SKIPPED_OK + exit 0 + fi + + CANARY="node-loss-canary-$(date +%s%N)" + + # -- GIVEN: a Longhorn PVC (platform default SC = 3 replicas across nodes) + a + # writer pod that writes the canary and flushes it to the replicated volume. -- + kubectl -n "$NS" apply -f - < /data/canary && sync' + echo "wrote canary: $(kubectl -n "$NS" exec writer -- cat /data/canary)" + + # The victim node is the one the attached volume currently lives on. + VICTIM="$(kubectl -n "$NS" get pod writer -o jsonpath='{.spec.nodeName}')" + [ -n "$VICTIM" ] || { echo "FAIL: could not determine writer's node" >&2; exit 1; } + echo "victim node (currently hosts the attached volume): $VICTIM" + + # Best-effort precondition log: if the Longhorn Volume CR is readable, show the + # volume is genuinely 3-replica/healthy before we take a node. Non-fatal (the + # runner is least-privilege and may not have longhorn.io read rights) — the + # data-availability assertion below is the authoritative proof, not this. + PVNAME="$(kubectl -n "$NS" get pvc survivor -o jsonpath='{.spec.volumeName}' 2>/dev/null || true)" + if [ -n "$PVNAME" ]; then + kubectl -n longhorn-system get volumes.longhorn.io "$PVNAME" \ + -o jsonpath='pre-fault robustness={.status.robustness} replicas={.spec.numberOfReplicas}{"\n"}' \ + 2>/dev/null || echo "(Longhorn Volume CR not readable — continuing; data read is the proof)" + fi + + # -- WHEN: FAULT INJECTION — remove the victim node FROM SERVICE. -- + # Label it with THIS test's unique namespace so `finally` can always find and + # uncordon exactly this node; then cordon it; then evict ONLY our own writer + # pod, forcing the volume to detach from the victim. (No `drain` — unrelated + # pods on the node are never touched.) + kubectl label node "$VICTIM" "conformance.home.k3s/cordoned-by=$NS" --overwrite + kubectl cordon "$VICTIM" + echo "cordoned + labelled victim node: $VICTIM" + kubectl -n "$NS" delete pod writer --wait=true --timeout=240s + echo "evicted writer off the victim node; volume detached from $VICTIM" + + # -- THEN: a fresh workload re-binds the SAME volume. The victim is unschedulable, + # so the scheduler MUST place the reader on a SURVIVING node; Longhorn re-attaches + # the volume there from its replicas on the other nodes. -- + apply_pod reader + kubectl -n "$NS" wait --for=condition=Ready pod/reader --timeout=360s + READER_NODE="$(kubectl -n "$NS" get pod reader -o jsonpath='{.spec.nodeName}')" + echo "reader scheduled on surviving node: $READER_NODE (victim was $VICTIM)" + if [ "$READER_NODE" = "$VICTIM" ]; then + echo "FAIL: reader landed back on the cordoned victim node — node was not removed from service" >&2 + exit 1 + fi + + GOT="$(kubectl -n "$NS" exec reader -- cat /data/canary)" + echo "recovered='$GOT' expected='$CANARY'" + [ "$GOT" = "$CANARY" ] || { echo "FAIL: data not available after node loss" >&2; exit 1; } + echo "volume available + data intact from a surviving node" + + # Best-effort reconvergence log: if the Longhorn Volume CR is readable, wait + # (bounded) for robustness to settle back to available (healthy|degraded — both + # serve I/O; a healthy 3-replica volume rebuilds a replica once headroom exists). + # Non-fatal for the same least-privilege reason as the pre-fault log. + if [ -n "$PVNAME" ]; then + for i in $(seq 1 30); do + ROB="$(kubectl -n longhorn-system get volumes.longhorn.io "$PVNAME" \ + -o jsonpath='{.status.robustness}' 2>/dev/null || true)" + [ -z "$ROB" ] && { echo "(Longhorn Volume CR not readable — skipping reconvergence log)"; break; } + echo "post-fault robustness[$i]=$ROB" + case "$ROB" in healthy|degraded) break ;; esac + sleep 10 + done + fi + + echo NODE_LOSS_VOLUME_AVAILABLE_OK + l.go:52: | 23:52:42 | node-loss | volume-stays-available-across-node-loss | SCRIPT | LOG | + === STDOUT + ready nodes: 3 + persistentvolumeclaim/survivor created + pod/writer created + pod/writer condition met + wrote canary: node-loss-canary-1788306678898809444 + victim node (currently hosts the attached volume): k3s-dev-2 + pre-fault robustness=healthy replicas=3 + node/k3s-dev-2 labeled + node/k3s-dev-2 cordoned + cordoned + labelled victim node: k3s-dev-2 + pod "writer" deleted from chainsaw-fond-marlin namespace + evicted writer off the victim node; volume detached from k3s-dev-2 + pod/reader created + pod/reader condition met + reader scheduled on surviving node: k3s-dev-1 (victim was k3s-dev-2) + recovered='node-loss-canary-1788306678898809444' expected='node-loss-canary-1788306678898809444' + volume available + data intact from a surviving node + post-fault robustness[1]=healthy + NODE_LOSS_VOLUME_AVAILABLE_OK + l.go:52: | 23:52:42 | node-loss | volume-stays-available-across-node-loss | SCRIPT | DONE | + l.go:52: | 23:52:42 | node-loss | volume-stays-available-across-node-loss | TRY | END | + l.go:52: | 23:52:42 | node-loss | volume-stays-available-across-node-loss | FINALLY | BEGIN | + l.go:52: | 23:52:42 | node-loss | volume-stays-available-across-node-loss | CMD | RUN | + === COMMAND + /usr/bin/sh -c set -uo pipefail + for n in $(kubectl get nodes -l "conformance.home.k3s/cordoned-by=$NAMESPACE" -o name 2>/dev/null); do + kubectl uncordon "${n#node/}" || true + kubectl label "$n" "conformance.home.k3s/cordoned-by-" || true + echo "restored node to service: ${n#node/}" + done + l.go:52: | 23:52:43 | node-loss | volume-stays-available-across-node-loss | SCRIPT | LOG | + === STDOUT + node/k3s-dev-2 uncordoned + node/k3s-dev-2 unlabeled + restored node to service: k3s-dev-2 + l.go:52: | 23:52:43 | node-loss | volume-stays-available-across-node-loss | SCRIPT | DONE | + l.go:52: | 23:52:43 | node-loss | volume-stays-available-across-node-loss | CMD | RUN | + === COMMAND + /usr/bin/sh -c kubectl -n "$NAMESPACE" delete pod writer reader --ignore-not-found --wait=false || true + kubectl -n "$NAMESPACE" delete pvc survivor --ignore-not-found --wait=false || true + echo "cleanup best-effort; chainsaw namespace teardown finalizes" + l.go:52: | 23:52:43 | node-loss | volume-stays-available-across-node-loss | SCRIPT | LOG | + === STDOUT + pod "reader" deleted from chainsaw-fond-marlin namespace + persistentvolumeclaim "survivor" deleted from chainsaw-fond-marlin namespace + cleanup best-effort; chainsaw namespace teardown finalizes + l.go:52: | 23:52:43 | node-loss | volume-stays-available-across-node-loss | SCRIPT | DONE | + l.go:52: | 23:52:43 | node-loss | volume-stays-available-across-node-loss | FINALLY | END | + l.go:52: | 23:52:43 | node-loss | @chainsaw  | CLEANUP | BEGIN | + l.go:52: | 23:52:43 | node-loss | @chainsaw  | DELETE | OK | v1/Namespace @ chainsaw-fond-marlin + l.go:52: | 23:53:29 | node-loss | @chainsaw  | CLEANUP | END | +--- PASS: chainsaw (0.00s) + --- PASS: chainsaw/node-loss (131.09s) +PASS +Tests Summary... +- Passed tests 1 +- Failed tests 0 +- Skipped tests 0 +Done. +merge_junit: merged 1 report(s) -> /work/conformance/_artifacts/report.junit.xml (tests=1 failures=0 errors=0 skipped=0) +[run.sh] Done. JUnit: /work/conformance/_artifacts/report.junit.xml | Coverage: /work/conformance/_artifacts/coverage/coverage.md diff --git a/conformance/runs/ledger.jsonl b/conformance/runs/ledger.jsonl index e69de29..7d006dc 100644 --- a/conformance/runs/ledger.jsonl +++ b/conformance/runs/ledger.jsonl @@ -0,0 +1 @@ +{"chainsaw_version": "v0.2.12", "env": "dev", "git_sha": "57d4df8c4f992732a49f3e2daddcace866778ab0", "junit_result": "passed", "kube_version": "v1.36.4+k3s1", "layer": "L3", "note": "run log OUTPUT carries every declared pass token (NODE_LOSS_VOLUME_AVAILABLE_OK) and no skip token [log scoped to this testcase; tokens read from real-output sections only]", "proof": "proven", "requirements": ["R-STATE-02"], "run_id": "20260901T235117Z-e9a4b66", "sentinel": "NODE_LOSS_VOLUME_AVAILABLE_OK", "test": "node-loss", "ts_utc": "2026-09-01T23:51:17Z"}