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
@@ -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