fix(conformance): ledger read tokens from Chainsaw's COMMAND echo, not real output
The run ledger mis-classified the FIRST real L3 execution — a genuine PASS recorded as
`skipped`. Diagnosis, from the preserved log, section-classified:
line 51 COMMAND echo NODE_LOSS_SKIPPED_OK <- script SOURCE
line 190 STDOUT NODE_LOSS_VOLUME_AVAILABLE_OK <- the only REAL emission
Chainsaw echoes each script into a `=== COMMAND` block before running it, and every
skip-gated test contains `echo <TEST>_SKIPPED_OK` as source text. record_run.py scanned the
raw log without distinguishing sections, so it matched the skip token in the echo.
NODE_LOSS_SKIPPED_OK never appeared in output at all.
SEVERITY: since every skip-gated test embeds its own skip token as source, and skip outranks
pass, THE LEDGER COULD NEVER HAVE RECORDED `proven` FOR ANY TEST WITH A SKIP GATE. It would
have silently recorded nothing forever while appearing to work. It failed CLOSED — the right
direction — but a ledger that always fails closed is an expensive way to write "unknown".
FIX: classify_sections() splits the log on indented `=== NAME` markers (a section runs to the
first non-blank line indented LESS than its marker). Verified against the real log's actual
markers, including that Go's column-0 `=== RUN/PAUSE/CONT` lines carry a test name and must
never open a section. Then:
PASS tokens are read from STDOUT ONLY — exactly where Chainsaw's own contains($stdout,…)
looks, so a source echo or stderr can never manufacture a proof.
SKIP tokens are read from every section that is NOT COMMAND, so an unknown future section
name fails closed in BOTH directions.
Lines outside any section prove nothing — this also closes a second false-positive vector:
a FAILING Chainsaw run prints the assertion expression, which contains both tokens.
A log with no markers is scanned whole exactly as before (such logs have no COMMAND echo).
SECOND BUG, same root: _LOG_HEADER_RE never matched a real Chainsaw log — the lines are
` l.go:52: <BS>| 23:51:18 | <ANSI>node-loss<ANSI> | …`, not `| … |`. EVERY genuine run was
silently falling into DEGRADED whole-log mode. Now strips ANSI/backspace noise first and
accepts the Go source prefix, so runs attribute per-testcase as designed.
Safety properties re-asserted, not assumed: skip still beats pass WITHIN real output; unknown
layers still require a sentinel; JUnit failed/error/skipped still outrank everything; missing
JUnit or log still exits 3. Negative control: with scan_texts forced section-blind in a
throwaway copy, exactly the new cases fail — they do catch this bug.
Includes the preserved run directory 20260901T235117Z-e9a4b66 (report.junit.xml + run.log)
for R-STATE-02 / node-loss — 131s, cordon -> evict -> volume stayed available -> reader
re-attached -> clean teardown, the first L3 fault-injection test ever executed on this
cluster. The ledger row is recorded in the FOLLOWING commit, deliberately: git_sha is sampled
at record time and a dirty tree records `-dirty`, which is unresolvable and correctly degrades
to stale-proof. Recording against this clean commit is the honest way to get a resolvable sha
— NOT a --git-sha override, which would be a lever for recording a clean sha over a dirty
tree and was deliberately not added.
Serves: R-TEST-01..04, R-STATE-02.
Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
This commit is contained in:
jakman85andClaude Opus 5 committed
1 parent
e9a4b669d4
commit
57d4df8c4f
3 files changed
+503
-29
No files matched your search
+267
-29
@@ -27,6 +27,17 @@ Chainsaw's JUnit carries no stdout — its `<testcase>` elements hold only `<pro
|
||||
|
||||
*** A COMMITTED JUnit ALONE WOULD RECORD `DR_RESTORE_SKIPPED_OK` AS PROOF OF R-STATE-03. ***
|
||||
|
||||
AND THE SECOND TRAP, WHICH IS THE MIRROR OF THE FIRST
|
||||
------------------------------------------------------
|
||||
Chainsaw echoes each script's SOURCE into an indented `=== COMMAND` block before running
|
||||
it, so `echo NODE_LOSS_SKIPPED_OK` — the skip branch that was NOT taken — is present in
|
||||
the log of every run of that test. A section-blind grep therefore reads a skip token out
|
||||
of the source of every skip-gated test and can never record `proven` for any of them: the
|
||||
ledger fails closed so completely that it records nothing and proves nothing. Tokens are
|
||||
consequently read from SECTIONS (see classify_sections): a pass token only from
|
||||
`=== STDOUT`, a skip token from any section that is not script source. Skip still beats
|
||||
pass — within genuine output, which is the only place either was ever evidence.
|
||||
|
||||
That is the fake-green this project refuses, and it would be worse than no ledger at all
|
||||
because it would look authoritative. THE SENTINEL TOKEN IS THE ONLY THING THAT SEPARATES
|
||||
PROVEN FROM SKIPPED, AND IT EXISTS ONLY IN THE RUN LOG. Hence: this tool requires BOTH
|
||||
@@ -149,10 +160,117 @@ _SENTINEL_RE = re.compile(r"contains\(\s*\$stdout\s*,\s*['\"]([A-Za-z0-9_]+)['\"
|
||||
# mis-classifying a SKIP token as a pass would manufacture one.
|
||||
_SKIP_TOKEN_RE = re.compile(r"_SKIP")
|
||||
|
||||
# A Chainsaw log line header: `| 20:41:32 | node-loss | step-name | TRY | RUN | ...`
|
||||
# Field 2 is the test name; it is how stdout is attributed back to a testcase.
|
||||
# A Chainsaw log line header, as it really appears (Go `t.Log` prefixes the source site and
|
||||
# pads it with backspaces, and the fields are ANSI-coloured — both are stripped first):
|
||||
# l.go:52: | 23:51:18 | node-loss | volume-stays-available... | SCRIPT | LOG |
|
||||
# Field 2 is the test name; it is how output is attributed back to a testcase. The
|
||||
# `<file>.go:<line>:` 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 | <test> | <step> | ...` 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 <skipped/> -> 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 <skipped/> — 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 <skipped/>, 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)
|
||||
|
||||
|
||||
@@ -0,0 +1,4 @@
|
||||
<testsuites name="chainsaw-report" tests="1" failures="0" errors="0" time="0.000000"><testsuite name="/work/conformance/tests/l3-fault-injection/node-loss" tests="1" failures="0" errors="0" id="0" time="">
|
||||
<testcase name="node-loss" classname="" time="131.090121" />
|
||||
</testsuite>
|
||||
</testsuites>
|
||||
@@ -0,0 +1,232 @@
|
||||
[1m[run.sh][0m 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
|
||||
[1m[run.sh][0m No L0/L1 offline checks match the selection (layer=l3 reqs='R-STATE-02').
|
||||
[1m[run.sh][0m LIGHT pass: no tests selected.
|
||||
[1m[run.sh][0m 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 | [32;1mnode-loss[0;22m | [32;1m@chainsaw [0;22m | [32;1mCREATE[0;22m | [32;1mOK[0;22m | v1/Namespace @ chainsaw-fond-marlin
|
||||
l.go:52: | 23:51:18 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mTRY[0;22m | [36;1mBEGIN[0;22m |
|
||||
l.go:52: | 23:51:18 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mCMD[0;22m | [36;1mRUN[0;22m |
|
||||
=== 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 - <<EOF
|
||||
apiVersion: v1
|
||||
kind: PersistentVolumeClaim
|
||||
metadata:
|
||||
name: survivor
|
||||
spec:
|
||||
accessModes: [ReadWriteOnce]
|
||||
storageClassName: longhorn
|
||||
resources:
|
||||
requests:
|
||||
storage: 1Gi
|
||||
EOF
|
||||
|
||||
apply_pod() {
|
||||
kubectl -n "$NS" apply -f - <<EOF
|
||||
apiVersion: v1
|
||||
kind: Pod
|
||||
metadata:
|
||||
name: $1
|
||||
spec:
|
||||
restartPolicy: Never
|
||||
containers:
|
||||
- name: app
|
||||
image: busybox:1.36.1
|
||||
command: ["sh", "-c", "sleep 3600"]
|
||||
volumeMounts:
|
||||
- name: data
|
||||
mountPath: /data
|
||||
volumes:
|
||||
- name: data
|
||||
persistentVolumeClaim:
|
||||
claimName: survivor
|
||||
EOF
|
||||
}
|
||||
|
||||
apply_pod writer
|
||||
kubectl -n "$NS" wait --for=condition=Ready pod/writer --timeout=240s
|
||||
printf '%s' "$CANARY" | kubectl -n "$NS" exec -i writer -- sh -c 'cat > /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 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mSCRIPT[0;22m | [36;1mLOG[0;22m |
|
||||
=== 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 | [32;1mnode-loss[0;22m | [32;1mvolume-stays-available-across-node-loss[0;22m | [32;1mSCRIPT[0;22m | [32;1mDONE[0;22m |
|
||||
l.go:52: | 23:52:42 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mTRY[0;22m | [36;1mEND[0;22m |
|
||||
l.go:52: | 23:52:42 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mFINALLY[0;22m | [36;1mBEGIN[0;22m |
|
||||
l.go:52: | 23:52:42 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mCMD[0;22m | [36;1mRUN[0;22m |
|
||||
=== 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 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mSCRIPT[0;22m | [36;1mLOG[0;22m |
|
||||
=== STDOUT
|
||||
node/k3s-dev-2 uncordoned
|
||||
node/k3s-dev-2 unlabeled
|
||||
restored node to service: k3s-dev-2
|
||||
l.go:52: | 23:52:43 | [32;1mnode-loss[0;22m | [32;1mvolume-stays-available-across-node-loss[0;22m | [32;1mSCRIPT[0;22m | [32;1mDONE[0;22m |
|
||||
l.go:52: | 23:52:43 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mCMD[0;22m | [36;1mRUN[0;22m |
|
||||
=== 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 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mSCRIPT[0;22m | [36;1mLOG[0;22m |
|
||||
=== 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 | [32;1mnode-loss[0;22m | [32;1mvolume-stays-available-across-node-loss[0;22m | [32;1mSCRIPT[0;22m | [32;1mDONE[0;22m |
|
||||
l.go:52: | 23:52:43 | [36;1mnode-loss[0;22m | [36;1mvolume-stays-available-across-node-loss[0;22m | [36;1mFINALLY[0;22m | [36;1mEND[0;22m |
|
||||
l.go:52: | 23:52:43 | [36;1mnode-loss[0;22m | [36;1m@chainsaw [0;22m | [36;1mCLEANUP[0;22m | [36;1mBEGIN[0;22m |
|
||||
l.go:52: | 23:52:43 | [32;1mnode-loss[0;22m | [32;1m@chainsaw [0;22m | [32;1mDELETE[0;22m | [32;1mOK[0;22m | v1/Namespace @ chainsaw-fond-marlin
|
||||
l.go:52: | 23:53:29 | [36;1mnode-loss[0;22m | [36;1m@chainsaw [0;22m | [36;1mCLEANUP[0;22m | [36;1mEND[0;22m |
|
||||
--- 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)
|
||||
[1m[run.sh][0m Done. JUnit: /work/conformance/_artifacts/report.junit.xml | Coverage: /work/conformance/_artifacts/coverage/coverage.md
|
||||
Reference in new issue
Block a user