diff --git a/.github/actions/e2e-analyze/analyze.go b/.github/actions/e2e-analyze/analyze.go index 73ab4d76a..8bed92be4 100644 --- a/.github/actions/e2e-analyze/analyze.go +++ b/.github/actions/e2e-analyze/analyze.go @@ -91,9 +91,12 @@ type SuiteReport struct { Label string // short name, e.g. "single" Total int FailCount int - Root *Failure // nil if no failures - Cascades []Failure // everything else that failed in this suite - Buckets [][]Failure // failures grouped by signature (root's bucket first) + // Unresolved counts testcases go-junit-report could not find an outcome + // for. They are not failures and the suite can be green with hundreds. + Unresolved int + Root *Failure // nil if no failures + Cascades []Failure // everything else that failed in this suite + Buckets [][]Failure // failures grouped by signature (root's bucket first) // EndedAt is go-junit-report's , which records when // the XML was produced — i.e. when the suite finished, not when it began. EndedAt time.Time @@ -366,7 +369,7 @@ func computeLeafSet(cases []junitTC) map[string]bool { func computeRolledUpSet(cases []junitTC) map[string]bool { rolledUp := make(map[string]bool, len(cases)) for _, tc := range cases { - if tc.Failure == nil && tc.Error == nil { + if tc.Failure == nil && !isRealError(tc.Error) { continue } // Mark every ancestor: the failure belongs to the deepest case that @@ -412,6 +415,18 @@ func parseStartTime(s string) time.Time { return t } +// noResultMessage is go-junit-report's marker for a testcase it saw start and +// never saw finish. On cell-20 it accounted for 93 of the 120 testcases and 24 +// of the 25 reported failures, none of which had failed. +const noResultMessage = "No test result found" + +// isRealError separates a genuine from the parser's no-result marker. +// A parent must not be treated as rolled up by a child whose outcome is merely +// unknown, or the parent's own failure is dropped along with it. +func isRealError(e *junitFailure) bool { + return e != nil && strings.TrimSpace(e.Message) != noResultMessage +} + // suiteLabel turns "junit-single.xml" into "single". func suiteLabel(path string) string { base := filepath.Base(path) @@ -457,6 +472,17 @@ func ParseFile(path string, data []byte) (SuiteReport, error) { case tc.Failure != nil: body = tc.Failure.Body case tc.Error != nil: + // go-junit-report emits this when a `=== RUN` line has no + // matching result line. It means the outcome is unknown, not + // that the test errored, and it attaches the test's own log + // output — which then reads as an assertion. + if !isRealError(tc.Error) { + rep.Unresolved++ + if leaf { + cumul += tc.Time + } + continue + } body = tc.Error.Body default: if leaf { @@ -553,6 +579,18 @@ func ParseFile(path string, data []byte) (SuiteReport, error) { } // Render writes the markdown report. +// writeUnresolved names the testcases whose outcome the parser could not read. +// Worth surfacing because a suite that leaves most of its subtests unresolved +// is reporting on far less than its test count suggests. +func writeUnresolved(b *strings.Builder, s SuiteReport) { + if s.Unresolved == 0 { + return + } + fmt.Fprintf(b, "ℹ️ %d of %d testcases have no result line in the log, so `go-junit-report` "+ + "could not read their outcome. Not failures — but this suite reports on %d tests, not %d.\n\n", + s.Unresolved, s.Total, s.Total-s.Unresolved, s.Total) +} + func Render(r Report) string { var b strings.Builder fmt.Fprintf(&b, "## %s\n\n", r.Title) @@ -579,9 +617,11 @@ func Render(r Report) string { for _, s := range r.Suites { if s.FailCount == 0 { fmt.Fprintf(&b, "### Suite `%s`: ✅ pass (%d tests)\n\n", s.Label, s.Total) + writeUnresolved(&b, s) continue } fmt.Fprintf(&b, "### Suite `%s`: %d failed, 1 root cause likely\n\n", s.Label, s.FailCount) + writeUnresolved(&b, s) if s.Root != nil { // XML order is completion order, so "earliest" only means earliest diff --git a/.github/actions/e2e-analyze/analyze_test.go b/.github/actions/e2e-analyze/analyze_test.go index 0312d9352..2bc0119b2 100644 --- a/.github/actions/e2e-analyze/analyze_test.go +++ b/.github/actions/e2e-analyze/analyze_test.go @@ -174,6 +174,55 @@ func TestParseFile_SkipsEmptyParentFailure(t *testing.T) { } } +// go-junit-report emits for a `=== RUN` +// with no matching result line, and attaches the test's own log output. On a +// baremetal cell that was 93 of 120 testcases and 24 of 25 reported failures, +// none of which had failed: "ALB internal: 20/20 successful" read as an error. +func TestParseFile_NoResultFoundIsNotAFailure(t *testing.T) { + xml := []byte(` + + + + +`) + sr, err := ParseFile("junit-x.xml", xml) + if err != nil { + t.Fatalf("ParseFile: %v", err) + } + if sr.FailCount != 1 { + t.Fatalf("FailCount = %d, want 1 (no-result entries are not failures)", sr.FailCount) + } + if sr.Unresolved != 2 { + t.Fatalf("Unresolved = %d, want 2", sr.Unresolved) + } + if sr.Root == nil || sr.Root.Name != "TestX/RealFailure" { + t.Fatalf("expected the real failure as root, got %+v", sr.Root) + } +} + +// An that is not the parser's no-result marker is a genuine error and +// must still be reported. +func TestParseFile_KeepsARealError(t *testing.T) { + xml := []byte(` + + +`) + sr, err := ParseFile("junit-x.xml", xml) + if err != nil { + t.Fatalf("ParseFile: %v", err) + } + if sr.FailCount != 1 || sr.Unresolved != 0 { + t.Fatalf("FailCount = %d, Unresolved = %d, want 1 and 0", sr.FailCount, sr.Unresolved) + } +} + func TestParseFile_SkipsParentRolledUpBySubtests(t *testing.T) { // A parent that logs during cleanup gets a non-empty body, and a t.Log like // "DB instance … is gone" — which passing tests emit too — reads exactly diff --git a/.github/e2e-cells.json b/.github/e2e-cells.json index c48b539f7..12ef9ba84 100644 --- a/.github/e2e-cells.json +++ b/.github/e2e-cells.json @@ -129,7 +129,8 @@ "arch": "x86_64", "runner": "ci-single", "extra": "rds", - "suite": "rds" + "suite": "rds", + "timeout_minutes": 100 }, { "cell": 29, diff --git a/.github/scripts/ci-fmt.sh b/.github/scripts/ci-fmt.sh index 189b2af57..d69313fc5 100644 --- a/.github/scripts/ci-fmt.sh +++ b/.github/scripts/ci-fmt.sh @@ -61,3 +61,37 @@ quiet_run() { return "$rc" fi } + +# Connection-layer failures from the libvirt tofu provider. The socket drops +# when a hypervisor is carrying several environments at once, which is the +# steady state here. A resource that failed to build says something else. +CI_LIBVIRT_TRANSIENT='Unable to Connect to Libvirt|error connecting to libvirt|procedure interrupted|Cannot recv data|Cannot write data|End of file while reading data' + +# retry_run LABEL LOG_FILE -- CMD ARGS … +# quiet_run with a bounded retry, taken only when that attempt's own output +# names a libvirt connection failure. Every other failure is reported on the +# first attempt, so a real bug never becomes a slow flake. +retry_run() { + local label="$1" log="$2"; shift 2 + local _attempts="${CI_RETRY_ATTEMPTS:-3}" _delay="${CI_RETRY_DELAY:-30}" _i _rc=1 _mark + for ((_i = 1; _i <= _attempts; _i++)); do + _mark=$(wc -c < "$log" 2>/dev/null || echo 0) + # rc must be read inside the else: an `if` whose condition fails and has no + # else exits 0, so reading $? after `fi` reports success for a failed run. + if "$@" >> "$log" 2>&1; then + if [[ $_i -gt 1 ]]; then ok "$label (libvirt recovered on attempt $_i)"; else ok "$label"; fi + return 0 + else + _rc=$? + fi + tail -c "+$((_mark + 1))" "$log" | grep -Eq "$CI_LIBVIRT_TRANSIENT" || break + [[ $_i -eq $_attempts ]] && break + warn "$label: libvirt connection dropped (attempt $_i/$_attempts), retrying in ${_delay}s" + sleep "$_delay" + done + bad "$label (rc=$_rc) — last 80 lines of $(basename "$log"):" + group_open "tail $(basename "$log")" + tail -n 80 "$log" + group_close + return "$_rc" +} diff --git a/.github/scripts/e2e-run-summary.py b/.github/scripts/e2e-run-summary.py new file mode 100644 index 000000000..e1f9efb94 --- /dev/null +++ b/.github/scripts/e2e-run-summary.py @@ -0,0 +1,220 @@ +#!/usr/bin/env python3 +"""Render one run-level table for the e2e nightly into the job summary. + +Reading a nightly meant opening nineteen jobs, and the Actions UI does not +distinguish a cell that failed from one that was cancelled out from under it — +a distinction every investigation of this suite has needed. + +Inputs (env): + GITHUB_TOKEN Token with actions:read. + GITHUB_REPOSITORY owner/repo. + GITHUB_RUN_ID Run to summarise. + JUNIT_ROOT Directory holding downloaded junit-cell-* artifacts. + GITHUB_STEP_SUMMARY Appended to. + +Test counts come from the junit artifacts; result, duration and runner come +from the jobs API, so a cell that died before writing junit still gets a row. +""" + +from __future__ import annotations + +import glob +import json +import os +import sys +import urllib.error +import urllib.request +import xml.etree.ElementTree as ET +from datetime import datetime + +API = "https://api.github.com" + +# A cell whose job produced no verdict is not a pass and not a failure. Keeping +# them apart is the point of the table. +VERDICT_ICON = { + "success": "✅", + "failure": "❌", + "cancelled": "🚫", + "skipped": "⏭️", + "timed_out": "⏱️", +} + + +def fetch_jobs(repo: str, run_id: str, token: str) -> list[dict]: + jobs: list[dict] = [] + page = 1 + while True: + url = f"{API}/repos/{repo}/actions/runs/{run_id}/jobs?per_page=100&page={page}" + req = urllib.request.Request( + url, + headers={ + "Authorization": f"Bearer {token}", + "Accept": "application/vnd.github+json", + "X-GitHub-Api-Version": "2022-11-28", + }, + ) + try: + with urllib.request.urlopen(req, timeout=30) as resp: + payload = json.load(resp) + except (urllib.error.URLError, TimeoutError) as exc: + print(f"::warning::jobs API page {page} failed: {exc}", file=sys.stderr) + break + batch = payload.get("jobs", []) + jobs.extend(batch) + if len(batch) < 100: + break + page += 1 + return jobs + + +def duration_s(job: dict) -> int | None: + started, completed = job.get("started_at"), job.get("completed_at") + if not started or not completed: + return None + fmt = "%Y-%m-%dT%H:%M:%SZ" + try: + return int((datetime.strptime(completed, fmt) - datetime.strptime(started, fmt)).total_seconds()) + except ValueError: + return None + + +def human(seconds: int | None) -> str: + if seconds is None: + return "—" + if seconds < 0: + return "0s" + return f"{seconds // 60}m{seconds % 60:02d}s" if seconds >= 60 else f"{seconds}s" + + +def junit_counts(root: str) -> dict[str, dict]: + """Map cell number to its aggregate junit counts and failing test names.""" + per_cell: dict[str, dict] = {} + for path in glob.glob(os.path.join(root, "**", "junit-*.xml"), recursive=True): + cell = cell_from_artifact_path(path) + if cell is None: + continue + acc = per_cell.setdefault(cell, {"tests": 0, "failures": 0, "skipped": 0, "failing": []}) + try: + root_el = ET.parse(path).getroot() + except ET.ParseError as exc: + print(f"::warning::unparseable junit {path}: {exc}", file=sys.stderr) + continue + suites = root_el.iter("testsuite") if root_el.tag != "testsuite" else [root_el] + for suite in suites: + acc["tests"] += int(suite.get("tests") or 0) + acc["failures"] += int(suite.get("failures") or 0) + int(suite.get("errors") or 0) + acc["skipped"] += int(suite.get("skipped") or 0) + for case in root_el.iter("testcase"): + if case.find("failure") is not None or case.find("error") is not None: + name = case.get("name") or "?" + if name not in acc["failing"]: + acc["failing"].append(name) + return per_cell + + +def cell_from_artifact_path(path: str) -> str | None: + """Recover the cell number from a junit-cell-- artifact directory.""" + for part in path.split(os.sep): + if part.startswith("junit-cell-"): + rest = part[len("junit-cell-"):] + cell = rest.split("-", 1)[0] + return cell if cell.isdigit() else None + return None + + +def cell_number(job_name: str) -> str | None: + """cell-19 (single/static/debian-13) -> 19.""" + if not job_name.startswith("cell-"): + return None + cell = job_name[len("cell-"):].split(" ", 1)[0] + return cell if cell.isdigit() else None + + +def main() -> int: + repo = os.environ.get("GITHUB_REPOSITORY", "") + run_id = os.environ.get("GITHUB_RUN_ID", "") + token = os.environ.get("GITHUB_TOKEN", "") + summary_path = os.environ.get("GITHUB_STEP_SUMMARY", "") + junit_root = os.environ.get("JUNIT_ROOT", "") + + if not (repo and run_id and token and summary_path): + print("::warning::e2e-run-summary: missing required environment", file=sys.stderr) + return 0 + + jobs = fetch_jobs(repo, run_id, token) + counts = junit_counts(junit_root) if junit_root and os.path.isdir(junit_root) else {} + + rows = [] + for job in jobs: + cell = cell_number(job.get("name", "")) + if cell is None: + continue + rows.append((int(cell), job)) + rows.sort(key=lambda r: r[0]) + + lines = [f"## e2e nightly — run summary ({len(rows)} cells)", ""] + if not rows: + lines.append("No cell jobs found for this run.") + write(summary_path, lines) + return 0 + + lines += [ + "| Cell | Topology | Result | Duration | Runner | Tests | Failed | Skipped |", + "| --- | --- | --- | --- | --- | --- | --- | --- |", + ] + + tally: dict[str, int] = {} + total_tests = total_failed = total_seconds = 0 + failing_detail: list[tuple[int, list[str]]] = [] + + for cell, job in rows: + name = job.get("name", "") + # A cell dispatched to a reusable workflow reports as + # "cell-20 (baremetal/pxe/real-hw) / Bare-Metal Single-Node E2E". + topo = name.split("(", 1)[1].split(")", 1)[0] if "(" in name else "—" + verdict = job.get("conclusion") or job.get("status") or "unknown" + tally[verdict] = tally.get(verdict, 0) + 1 + secs = duration_s(job) + total_seconds += secs or 0 + c = counts.get(str(cell), {}) + total_tests += c.get("tests", 0) + total_failed += c.get("failures", 0) + if c.get("failing"): + failing_detail.append((cell, c["failing"])) + lines.append( + f"| {cell} | {topo} | {VERDICT_ICON.get(verdict, '❔')} {verdict} | {human(secs)} " + f"| {job.get('runner_name') or '—'} | {c.get('tests', '—')} " + f"| {c.get('failures', '—')} | {c.get('skipped', '—')} |" + ) + + verdicts = ", ".join(f"{n} {v}" for v, n in sorted(tally.items(), key=lambda kv: -kv[1])) + lines += [ + "", + f"**Cells:** {verdicts}", + f"**Tests:** {total_tests} run, {total_failed} failed", + f"**Cell wall clock:** {human(total_seconds)} across all cells", + ] + + slowest = sorted(rows, key=lambda r: duration_s(r[1]) or 0, reverse=True)[:3] + if slowest: + lines.append( + "**Slowest:** " + ", ".join(f"cell {c} ({human(duration_s(j))})" for c, j in slowest) + ) + + if failing_detail: + lines += ["", "
Failing tests", ""] + for cell, names in failing_detail: + lines.append(f"- **cell {cell}** — " + ", ".join(f"`{n}`" for n in names)) + lines += ["", "
"] + + write(summary_path, lines) + return 0 + + +def write(path: str, lines: list[str]) -> None: + with open(path, "a", encoding="utf-8") as fh: + fh.write("\n".join(lines) + "\n") + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/.github/scripts/suite-sets.sh b/.github/scripts/suite-sets.sh index 2b1f53499..f0160d151 100644 --- a/.github/scripts/suite-sets.sh +++ b/.github/scripts/suite-sets.sh @@ -73,9 +73,12 @@ E2E_SUITES_NIGHTLY_MULTI="multinode cert lb" # e2e_suite_timeout e2e_suite_timeout() { case "$1" in - # rds serialises its DB VMs behind a 4 GiB semaphore, so its wall clock is - # set by how long it waits for the budget, not by how long a test runs. - rds) echo "50m" ;; + # rds serialises its DB VMs behind a 3 GiB semaphore, so its wall clock is + # what the queue costs, not what the tests do: single tests logged 11m, 22m + # and 26m waiting for budget. 17 tests at that concurrency is over an hour + # before anything goes wrong, and the first pass to run deep into the suite + # still had three left at 60m. + rds) echo "90m" ;; # diskperf runs two 16 GiB fio profiles per repetition, each on a volume it # creates first. One pass is ~20 minutes on the bare-metal cell and a # baseline capture at SPINIFEX_DISKPERF_REPS=3 is three times that. @@ -88,6 +91,20 @@ e2e_suite_timeout() { esac } +# One matrix leg per suite, carrying the job budget that suite needs. The outer +# timeout must always be later than the `go test` one inside it: go test reports +# where it stopped, a cancelled job reports only "The operation was canceled". +# e2e_suite_matrix [allowance-minutes] +e2e_suite_matrix() { + local list="$1" floor="$2" allowance="${3:-15}" suite budget + for suite in ${list}; do + budget="$(e2e_suite_timeout "${suite}")" + budget=$((${budget%m} + allowance)) + if [ "${budget}" -lt "${floor}" ]; then budget="${floor}"; fi + printf '%s\t%s\n' "${suite}" "${budget}" + done | jq -cRs 'split("\n")|map(select(length>0)|split("\t")|{suite:.[0],timeout:(.[1]|tonumber)})' +} + # Fail loudly when a narrowed list names a suite its topology cannot run. This # is the guard that stops the lists drifting again: a suite added to a nightly # subset without also being declared eligible above stops the job here rather diff --git a/.github/workflows/e2e-baremetal.yml b/.github/workflows/e2e-baremetal.yml index a3cb3bf5a..16d612575 100644 --- a/.github/workflows/e2e-baremetal.yml +++ b/.github/workflows/e2e-baremetal.yml @@ -192,7 +192,15 @@ jobs: - name: Generate JUnit report if: always() run: | - LOG="${ARTIFACT_DIR}/test-baremetal.log" + # suite-output.log, not test-baremetal.log. The harness streams the + # full suite output to the first and a grep-filtered summary to its + # stdout, and that filter anchors --- PASS at column 0, so every + # indented subtest result is dropped. Parsed from the filtered log, + # go-junit-report saw a === RUN with no result and emitted + # — 17 of 39 testcases on a + # green cell-28, 93 of 120 on cell-20. + LOG="${ARTIFACT_DIR}/suite-output.log" + [ -s "$LOG" ] || LOG="${ARTIFACT_DIR}/test-baremetal.log" [ -f "$LOG" ] || exit 0 go-junit-report -in "$LOG" -out "${ARTIFACT_DIR}/junit-baremetal.xml" || true diff --git a/.github/workflows/e2e-ddil.yml b/.github/workflows/e2e-ddil.yml index 9333ff466..42d5cd8b1 100644 --- a/.github/workflows/e2e-ddil.yml +++ b/.github/workflows/e2e-ddil.yml @@ -10,6 +10,14 @@ on: required: false default: "" +# Shared with e2e-nightly.yml, e2e-suites.yml and e2e-ddil.yml: every one of +# them provisions on the same runner pools and the same hypervisors, so two in +# flight compete for their disks and their libvirt guests. Queued rather than +# cancelled — a run in progress is someone's result, not a stale one. +concurrency: + group: e2e-hypervisors + cancel-in-progress: false + permissions: contents: read # actions: read lets the otel-job-id action look up this job's numeric id via @@ -103,7 +111,7 @@ jobs: quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "tofu destroy (pre-clean)" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false || true quiet_run "scrub-env (pre-clean)" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false ok "VMs provisioned" - name: Bootstrap via Binary Install @@ -228,7 +236,7 @@ jobs: source "${GITHUB_WORKSPACE}/spinifex/.github/scripts/ci-fmt.sh" quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "telemetry flush" "$TOFU_LOG" timeout 120 ./flush-telemetry.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu destroy" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu destroy" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false quiet_run "scrub-env" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" || true ok "teardown complete" diff --git a/.github/workflows/e2e-nightly.yml b/.github/workflows/e2e-nightly.yml index 543c8b0a1..ca3f28074 100644 --- a/.github/workflows/e2e-nightly.yml +++ b/.github/workflows/e2e-nightly.yml @@ -20,12 +20,18 @@ permissions: # flight at once compete for their disks and their libvirt guests. Queue the # second rather than cancelling it: a dispatch is usually a verification run # and discarding it loses the result someone is waiting on. +# +# The group is shared with e2e.yml, e2e-suites.yml and e2e-ddil.yml, which draw +# on the same runner pools. A per-workflow group let a push-triggered E2E land +# on top of a nightly cell and take libvirt down under both. concurrency: - group: e2e-nightly + group: e2e-hypervisors cancel-in-progress: false # Scheduled runs are loaded from the default branch (main), so the schedule -# trigger must stay in sync on main for cron to fire. +# trigger must stay in sync on main for cron to fire — and so must the +# concurrency block above. main currently has none, which is why the nightly +# cron runs ungrouped and a dispatch on any branch can land on top of it. env: GIT_BRANCH: ${{ github.event_name == 'schedule' && 'dev' || github.ref_name }} UBUNTU_GOLD_IMAGE: /mnt/disk1/gold-images/spinifex-image-builder-ubuntu-26.04.qcow2 @@ -47,11 +53,17 @@ jobs: steps: - uses: actions/checkout@v7 with: - sparse-checkout: .github/e2e-cells.json + sparse-checkout: | + .github/e2e-cells.json + .github/scripts/suite-sets.sh sparse-checkout-cone-mode: false - id: pick env: CELLS: ${{ github.event_name == 'workflow_dispatch' && inputs.cells || '' }} + # Provision, install and teardown around the suite. Measured at ~6 + # minutes single-node and ~10 multi-node, so this is the floor the + # job budget must carry on top of the suite's own. + SETUP_ALLOWANCE_MIN: 10 run: | if [ -z "$CELLS" ]; then sel=$(jq -c . .github/e2e-cells.json) @@ -65,6 +77,44 @@ jobs: echo "any=$any" >> "$GITHUB_OUTPUT" echo "selected: $(jq -c '[.[].cell]' <<<"$sel")" + # The inner timeout must always fire before the outer one. go test + # reports where it stopped and the suite's own failure; a job timeout + # reports only "The operation was canceled". cell-27 ran a 50m rds + # suite inside a 50m job and could never finish either way. + . .github/scripts/suite-sets.sh + # Cells with no suite are filtered in jq, not with an empty-field test: + # tab is IFS whitespace, so read collapses a run of them and an empty + # middle column silently shifts every later one left. + bad=0 + while IFS=$'\t' read -r cell suite budget; do + want="$(e2e_suite_timeout "$suite")"; want="${want%m}" + if [ "$budget" -lt $((want + SETUP_ALLOWANCE_MIN)) ]; then + echo "::error::cell-$cell gives suite '$suite' ${want}m inside a ${budget}m job. Raise timeout_minutes in .github/e2e-cells.json to at least $((want + SETUP_ALLOWANCE_MIN)), or lower the suite budget in suite-sets.sh." >&2 + bad=1 + fi + done < <(jq -r '.[]|select((.suite//"")!="")|[.cell,.suite,(.timeout_minutes//50)]|@tsv' <<<"$sel") + + # A permutation cell names no suite and runs the nightly subset for its + # topology, so its bound is the longest of those. max() and not sum(): + # whichever suite hangs must panic on its own timeout first, and a sum + # would demand a budget the set has never come close to using. + while IFS=$'\t' read -r cell topo budget; do + case "$topo" in + *multi) set -- ${E2E_SUITES_NIGHTLY_MULTI} ;; + *) set -- ${E2E_SUITES_NIGHTLY_SINGLE} ;; + esac + want=0 + for suite in "$@"; do + t="$(e2e_suite_timeout "$suite")"; t="${t%m}" + [ "$t" -gt "$want" ] && want="$t" + done + if [ "$budget" -lt $((want + SETUP_ALLOWANCE_MIN)) ]; then + echo "::error::cell-$cell runs the $topo nightly subset, whose longest suite asks ${want}m, inside a ${budget}m job. Raise timeout_minutes in .github/e2e-cells.json to at least $((want + SETUP_ALLOWANCE_MIN))." >&2 + bad=1 + fi + done < <(jq -r '.[]|select((.suite//"")=="")|[.cell,.topo,(.timeout_minutes//50)]|@tsv' <<<"$sel") + [ "$bad" -eq 0 ] + matrix: name: "cell-${{ matrix.cell }} (${{ matrix.topo }}/${{ matrix.net }}/${{ matrix.host }}${{ matrix.extra && format('/{0}', matrix.extra) || '' }})" @@ -133,6 +183,22 @@ jobs: "${RUNNER_TEMP}/spinifex-tests.tar" \ --extra-suites "${MATRIX_SUITE}" + # Eight runner names map onto three hypervisors, so cells that never share + # a runner still share a host. Nothing measured that, which left "the host + # was loaded" as an unfalsifiable explanation for every timeout. Sampled + # either side of the cell so the next occurrence can be correlated. + - name: Sample hypervisor load (before) + if: always() + run: | + mkdir -p "${ARTIFACT_DIR}" + { + echo "=== before: $(date -u +%Y-%m-%dT%H:%M:%SZ) runner=${RUNNER_NAME} host=$(hostname) ===" + echo "loadavg: $(cat /proc/loadavg)" + grep -E '^(MemTotal|MemAvailable|SwapFree):' /proc/meminfo || true + echo "cpu(steal is field 8): $(grep '^cpu ' /proc/stat || true)" + echo "running qemu: $(pgrep -c qemu-system-x86 || echo 0)" + } >> "${ARTIFACT_DIR}/hypervisor-load.txt" + - name: Provision VMs working-directory: mulga/scripts/tofu-cluster env: @@ -148,11 +214,13 @@ jobs: ubuntu-*) TOFU_VAR_ARGS="-var=host_image_override=${UBUNTU_GOLD_IMAGE}" ;; esac + source "${GITHUB_WORKSPACE}/spinifex/.github/scripts/ci-fmt.sh" tofu init -input=false >> "$TOFU_LOG" 2>&1 tofu workspace select -or-create "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars ${TOFU_VAR_ARGS} -auto-approve -input=false >> "$TOFU_LOG" 2>&1 || true ./scrub-env.sh "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 || true - tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars ${TOFU_VAR_ARGS} -auto-approve -input=false >> "$TOFU_LOG" 2>&1 + # shellcheck disable=SC2086 + retry_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars ${TOFU_VAR_ARGS} -auto-approve -input=false - name: Bootstrap via Binary Install working-directory: mulga/scripts/tofu-cluster @@ -544,6 +612,18 @@ jobs: if [ $rc -ne 0 ]; then echo "reboot: FAILED" >> "${ARTIFACT_DIR}/suite-status.txt"; fi exit $rc + - name: Sample hypervisor load (after) + if: always() + run: | + mkdir -p "${ARTIFACT_DIR}" + { + echo "=== after: $(date -u +%Y-%m-%dT%H:%M:%SZ) runner=${RUNNER_NAME} host=$(hostname) ===" + echo "loadavg: $(cat /proc/loadavg)" + grep -E '^(MemTotal|MemAvailable|SwapFree):' /proc/meminfo || true + echo "cpu(steal is field 8): $(grep '^cpu ' /proc/stat || true)" + echo "running qemu: $(pgrep -c qemu-system-x86 || echo 0)" + } >> "${ARTIFACT_DIR}/hypervisor-load.txt" + - name: Collect e2e artifacts if: always() working-directory: mulga/scripts/tofu-cluster @@ -568,6 +648,11 @@ jobs: > "${ARTIFACT_DIR}/spinifex-journal-node${idx}.log" 2>/dev/null ssh "${SSH_OPTS[@]}" tf-user@${IP} 'sudo journalctl -u openvswitch-ipsec.service --no-pager --output=short-iso --since "60 min ago"' \ > "${ARTIFACT_DIR}/openvswitch-ipsec-node${idx}.log" 2>/dev/null + # The unit filter above drops kernel and OOM messages, which are + # exactly what explains one node behaving unlike its siblings. + # Gzipped on the far side; the whole journal is far larger. + ssh "${SSH_OPTS[@]}" tf-user@${IP} 'sudo journalctl --no-pager --output=short-iso --since "90 min ago" | gzip -6' \ + > "${ARTIFACT_DIR}/full-journal-node${idx}.log.gz" 2>/dev/null # ovn-controller and ovs-vswitchd log to files, never to journald: # without these a cross-chassis black-hole cannot be attributed to # IPsec versus SB port binding. @@ -621,6 +706,17 @@ jobs: if-no-files-found: warn retention-days: 14 + # The XML on its own, so the roll-up can read every cell's counts without + # pulling nineteen journals it has no use for. + - name: Upload junit only + if: always() + uses: actions/upload-artifact@v7 + with: + name: junit-cell-${{ matrix.cell }}-${{ github.run_id }} + path: ${{ env.ARTIFACT_DIR }}/junit-*.xml + if-no-files-found: ignore + retention-days: 14 + # Gated like every other step, not just always(): a cell the dispatch # deselected never checked out or ran tofu init, so destroying would fail # on missing plugins and report the cell red for correctly doing nothing. @@ -636,9 +732,11 @@ jobs: case "$MATRIX_HOST" in ubuntu-*) TOFU_VAR_ARGS="-var=host_image_override=${UBUNTU_GOLD_IMAGE}" ;; esac + source "${GITHUB_WORKSPACE}/spinifex/.github/scripts/ci-fmt.sh" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 timeout 120 ./flush-telemetry.sh "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 || true - tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars ${TOFU_VAR_ARGS} -auto-approve -input=false >> "$TOFU_LOG" 2>&1 + # shellcheck disable=SC2086 + retry_run "tofu destroy" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars ${TOFU_VAR_ARGS} -auto-approve -input=false ./scrub-env.sh "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 || true - name: Upload tofu log @@ -684,7 +782,7 @@ jobs: name: cell-28 (baremetal/diskperf) needs: baremetal if: >- - always() && ( + !cancelled() && ( github.event_name == 'schedule' || inputs.cells == '' || contains(format(',{0},', inputs.cells), ',28,') @@ -886,6 +984,22 @@ jobs: EOF ./test/test-workload.sh --env /tmp/cell21.env --benchmark + # The node's own journal, which nothing else preserves: the serial log + # stops at login and the harness owns the only node there is. Pulled + # before teardown and never fatal, so a passing night keeps it too. + - name: Collect node journal + if: always() && steps.smoke.outputs.node_ip != '' + env: + NODE_IP: ${{ steps.smoke.outputs.node_ip }} + run: | + mkdir -p /tmp/cell21-artifacts-$GITHUB_RUN_ID + timeout 180 ssh -o BatchMode=yes -o StrictHostKeyChecking=no \ + -o UserKnownHostsFile=/dev/null -o ConnectTimeout=10 \ + -i "$HOME/.ssh/spinifex-key" "spinifex@${NODE_IP}" \ + 'sudo journalctl -b --no-pager --output=short-iso | gzip -6' \ + > "/tmp/cell21-artifacts-$GITHUB_RUN_ID/node-journal.log.gz" || + echo "::warning::could not pull the node journal from ${NODE_IP}" + - name: Collect logs if: always() run: | @@ -949,7 +1063,7 @@ jobs: # them together would need 32 GiB on one box. needs: [iso-single] if: >- - always() && ( + !cancelled() && ( github.event_name == 'schedule' || inputs.cells == '' || contains(format(',{0},', inputs.cells), ',22,') ) @@ -1104,13 +1218,14 @@ jobs: # bottlebrush, so "a different label" would not have separated them. needs: on # a matrix job waits for every leg, so this starts on a quiet machine. # - # always() because a failed cell must not silently skip the benchmark and - # leave a green-looking night with no number in it. + # !cancelled() rather than always(): a failed cell must not silently skip the + # benchmark and leave a green-looking night with no number in it, but always() + # also overrides cancellation and keeps the run starting jobs after a cancel. performance: name: cell-23 (predastore/throughput) needs: [matrix, baremetal, iso-single, iso-multi] if: >- - always() && ( + !cancelled() && ( github.event_name == 'schedule' || inputs.cells == '' || contains(format(',{0},', inputs.cells), ',23,') ) @@ -1222,7 +1337,7 @@ jobs: name: cell-24 (predastore/fault-injection) needs: [matrix, baremetal, iso-single, iso-multi, performance] if: >- - always() && ( + !cancelled() && ( github.event_name == 'schedule' || inputs.cells == '' || contains(format(',{0},', inputs.cells), ',24,') ) @@ -1332,3 +1447,30 @@ jobs: run: | pkill -KILL -f '/bin/s3d -config' || true rm -rf "$STRESS_RESULTS_ROOT" + + # Reading a nightly meant opening every cell job, and the Actions UI does not + # separate a cell that failed from one cancelled out from under it. needs: + # every cell so this runs last; always() so a red run is the one it describes. + summary: + name: run summary + needs: [select, matrix, baremetal, diskperf, iso-single, iso-multi, performance, stress] + if: always() + runs-on: ubuntu-26.04 + steps: + - uses: actions/checkout@v7 + with: + sparse-checkout: .github/scripts/e2e-run-summary.py + sparse-checkout-cone-mode: false + + - name: Collect junit + uses: actions/download-artifact@v7 + with: + pattern: junit-cell-*-${{ github.run_id }} + path: junit + continue-on-error: true + + - name: Write run summary + env: + GITHUB_TOKEN: ${{ secrets.GITHUB_TOKEN }} + JUNIT_ROOT: junit + run: python3 .github/scripts/e2e-run-summary.py diff --git a/.github/workflows/e2e-suites.yml b/.github/workflows/e2e-suites.yml index 5c16c6510..630cac569 100644 --- a/.github/workflows/e2e-suites.yml +++ b/.github/workflows/e2e-suites.yml @@ -43,6 +43,14 @@ on: required: false default: "" +# Shared with e2e-nightly.yml, e2e-suites.yml and e2e-ddil.yml: every one of +# them provisions on the same runner pools and the same hypervisors, so two in +# flight compete for their disks and their libvirt guests. Queued rather than +# cancelled — a run in progress is someone's result, not a stale one. +concurrency: + group: e2e-hypervisors + cancel-in-progress: false + permissions: contents: read # actions: read lets the otel-job-id action look up a provision job's numeric @@ -143,10 +151,9 @@ jobs: LIST="${REQUESTED:-${E2E_SUITES_SINGLE}}" e2e_suites_assert_subset "single_suites" "${LIST}" "${E2E_SUITES_SINGLE}" echo "list=${LIST}" >> "$GITHUB_OUTPUT" - # Unquoted on purpose: the space-separated list must word-split into - # one JSON element per suite. - # shellcheck disable=SC2086 - JSON=$(printf '%s\n' ${LIST} | jq -R . | jq -cs .) + # 45 is the floor this job has always had, so resolving each leg's + # budget can only raise it — storagefault and rds ask for more. + JSON=$(e2e_suite_matrix "${LIST}" 45) echo "matrix=${JSON}" >> "$GITHUB_OUTPUT" - name: Reclaim docker build cache @@ -182,7 +189,7 @@ jobs: quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "tofu destroy (pre-clean)" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false || true quiet_run "scrub-env (pre-clean)" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false ok "VM provisioned" - name: Bootstrap via Binary Install @@ -311,14 +318,16 @@ jobs: retention-days: 14 single_suite: - name: Single env · suite + name: Single env · ${{ matrix.suite }} needs: single_provision runs-on: [self-hosted, ci-single] - timeout-minutes: 45 + # Per leg, from suite-sets.sh: one number for every suite would have to be + # storagefault's, and every other leg would then hang for 105 minutes. + timeout-minutes: ${{ matrix.timeout }} strategy: fail-fast: false matrix: - suite: ${{ fromJSON(needs.single_provision.outputs.matrix) }} + include: ${{ fromJSON(needs.single_provision.outputs.matrix) }} env: WAN_IP: ${{ needs.single_provision.outputs.wan_ip }} SSH_KEY: ${{ needs.single_provision.outputs.ssh_key }} @@ -518,7 +527,7 @@ jobs: find "$WS" -name '.terraform.tfstate.lock.info' -delete 2>/dev/null quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "telemetry flush" "$TOFU_LOG" timeout 120 ./flush-telemetry.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false quiet_run "scrub-env" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" ok "teardown complete" @@ -629,7 +638,7 @@ jobs: quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "tofu destroy (pre-clean)" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false || true quiet_run "scrub-env (pre-clean)" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false ok "3-node cluster provisioned" - name: Bootstrap via Binary Install @@ -671,10 +680,9 @@ jobs: LIST="${REQUESTED:-${E2E_SUITES_MULTI}}" e2e_suites_assert_subset "multi_suites" "${LIST}" "${E2E_SUITES_MULTI}" echo "list=${LIST}" >> "$GITHUB_OUTPUT" - # Unquoted on purpose: the space-separated list must word-split into - # one JSON element per suite. - # shellcheck disable=SC2086 - JSON=$(printf '%s\n' ${LIST} | jq -R . | jq -cs .) + # 60 is the floor this job has always had; multi-node legs carry a + # heavier setup than single-node ones, which is why it is higher. + JSON=$(e2e_suite_matrix "${LIST}" 60) echo "matrix=${JSON}" >> "$GITHUB_OUTPUT" - name: Build multinode binaries on runner @@ -724,14 +732,15 @@ jobs: retention-days: 14 multi_suite: - name: Multi env · suite + name: Multi env · ${{ matrix.suite }} needs: multi_provision runs-on: [self-hosted, ci-multi] - timeout-minutes: 60 + # See the note on single_suite: the budget is the suite's, not the job's. + timeout-minutes: ${{ matrix.timeout }} strategy: fail-fast: false matrix: - suite: ${{ fromJSON(needs.multi_provision.outputs.matrix) }} + include: ${{ fromJSON(needs.multi_provision.outputs.matrix) }} env: NODE1_IP: ${{ needs.multi_provision.outputs.node1_ip }} SSH_KEY: ${{ needs.multi_provision.outputs.ssh_key }} @@ -903,7 +912,7 @@ jobs: find "$WS" -name '.terraform.tfstate.lock.info' -delete 2>/dev/null quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "telemetry flush" "$TOFU_LOG" timeout 120 ./flush-telemetry.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false quiet_run "scrub-env" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" ok "teardown complete" diff --git a/.github/workflows/e2e.yml b/.github/workflows/e2e.yml index 89d91750a..af89a551f 100644 --- a/.github/workflows/e2e.yml +++ b/.github/workflows/e2e.yml @@ -24,6 +24,14 @@ on: required: false default: "" +# Shared with e2e-nightly.yml, e2e-suites.yml and e2e-ddil.yml: every one of +# them provisions on the same runner pools and the same hypervisors, so two in +# flight compete for their disks and their libvirt guests. Queued rather than +# cancelled — a run in progress is someone's result, not a stale one. +concurrency: + group: e2e-hypervisors + cancel-in-progress: false + permissions: contents: read statuses: write @@ -41,6 +49,57 @@ env: SPINIFEX_OTEL_ATTRS: ci.run_id=${{ github.run_id }},ci.workflow=${{ github.workflow }} jobs: + # The inner timeout must fire before the outer one. `go test` reports where it + # stopped and the suite's own failure; a job cancelled on timeout reports only + # "The operation was canceled" and takes the artifacts with it. + # + # A job budget cannot be a literal here because the suite set is a dispatch + # input: storagefault asks for 90m and diskperf for 180m, both eligible on one + # node, so any fixed number is either wrong for them or wasteful for everyone + # else. Resolving it from suite-sets.sh keeps the one source of truth and + # leaves the default push set at exactly the 60m it has always had. + plan: + name: Resolve Job Budgets + runs-on: ubuntu-26.04 + timeout-minutes: 5 + outputs: + single_timeout: ${{ steps.budgets.outputs.single_timeout }} + multi_timeout: ${{ steps.budgets.outputs.multi_timeout }} + steps: + - uses: actions/checkout@v7 + with: + path: spinifex + sparse-checkout: .github/scripts + + - name: Resolve Budgets + id: budgets + env: + # Provision, install and teardown around the suites, plus the headroom + # a multi-suite job needs for whatever ran before the one that hangs. + SETUP_ALLOWANCE_MIN: 15 + # What the job has always had. Kept as a floor so resolving the budget + # can only ever raise it, never quietly shorten an existing run. + FLOOR_MIN: 60 + run: | + . "${GITHUB_WORKSPACE}/spinifex/.github/scripts/suite-sets.sh" + # Only max() is a sound bound: the suites share one job, so a sum would + # demand hours for a set that has never taken them. Max is what makes + # the hanging suite panic on its own timeout first, which is the point. + budget() { + local want="${FLOOR_MIN}" s t + for s in $(echo "${SUITES}" | sed 's/e2e-//g' | tr ' ' '\n' | grep -xE "$1"); do + t="$(e2e_suite_timeout "${s}")" + t=$(( ${t%m} + SETUP_ALLOWANCE_MIN )) + [ "${t}" -gt "${want}" ] && want="${t}" + done + echo "${want}" + } + single=$(budget "${E2E_SUITES_SINGLE_RE}") + multi=$(budget "${E2E_SUITES_MULTI_RE}") + echo "single_timeout=${single}" >> "$GITHUB_OUTPUT" + echo "multi_timeout=${multi}" >> "$GITHUB_OUTPUT" + echo "suites='${SUITES}' -> single ${single}m, multi ${multi}m" + e2e_single: name: Single-Node E2E # The dispatch check gates on exactly the suites this job's Run step @@ -52,8 +111,9 @@ jobs: # tear down. Push triggers keep running via the null-check on # inputs.suites. if: github.event_name != 'workflow_dispatch' || contains(github.event.inputs.suites, 'e2e-single') || contains(github.event.inputs.suites, 'e2e-iam') || contains(github.event.inputs.suites, 'e2e-cert') || contains(github.event.inputs.suites, 'e2e-eks') || contains(github.event.inputs.suites, 'e2e-ecs') || contains(github.event.inputs.suites, 'e2e-storagegrowth') || contains(github.event.inputs.suites, 'e2e-partialblock') || contains(github.event.inputs.suites, 'e2e-rds') + needs: plan runs-on: [self-hosted, ci-single] - timeout-minutes: 60 + timeout-minutes: ${{ fromJSON(needs.plan.outputs.single_timeout) }} env: TOFU_LOG: /tmp/e2e-tofu-single-${{ github.run_id }}.log ARTIFACT_DIR: /tmp/spinifex-e2e-artifacts-${{ github.run_id }} @@ -153,7 +213,7 @@ jobs: quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "tofu destroy (pre-clean)" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false || true quiet_run "scrub-env (pre-clean)" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false ok "VM provisioned" - name: Bootstrap via Binary Install @@ -525,7 +585,7 @@ jobs: find "$WS" -name '.terraform.tfstate.lock.info' -delete 2>/dev/null quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "telemetry flush" "$TOFU_LOG" timeout 120 ./flush-telemetry.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false quiet_run "scrub-env" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" ok "teardown complete" @@ -554,8 +614,9 @@ jobs: # provisions the 3-node env when requested on its own, and the env stays # unprovisioned when none of them are asked for. if: github.event_name != 'workflow_dispatch' || contains(github.event.inputs.suites, 'e2e-multinode') || contains(github.event.inputs.suites, 'e2e-lb') || contains(github.event.inputs.suites, 'e2e-cert') + needs: plan runs-on: [self-hosted, ci-multi] - timeout-minutes: 60 + timeout-minutes: ${{ fromJSON(needs.plan.outputs.multi_timeout) }} env: TOFU_LOG: /tmp/e2e-tofu-multi-${{ github.run_id }}.log ARTIFACT_DIR: /tmp/spinifex-e2e-multi-artifacts-${{ github.run_id }} @@ -651,7 +712,7 @@ jobs: quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "tofu destroy (pre-clean)" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false || true quiet_run "scrub-env (pre-clean)" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false ok "3-node cluster provisioned" - name: Bootstrap via Binary Install @@ -980,7 +1041,7 @@ jobs: find "$WS" -name '.terraform.tfstate.lock.info' -delete 2>/dev/null quiet_run "tofu workspace select" "$TOFU_LOG" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" quiet_run "telemetry flush" "$TOFU_LOG" timeout 120 ./flush-telemetry.sh "${SPINIFEX_CI_ENV}" || true - quiet_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false + retry_run "tofu destroy" "$TOFU_LOG" timeout 600 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false quiet_run "scrub-env" "$TOFU_LOG" ./scrub-env.sh "${SPINIFEX_CI_ENV}" ok "teardown complete" diff --git a/.github/workflows/release.yml b/.github/workflows/release.yml index 40a41d96c..311ced8f9 100644 --- a/.github/workflows/release.yml +++ b/.github/workflows/release.yml @@ -148,6 +148,13 @@ jobs: verify: needs: release runs-on: [ self-hosted, ci-single ] + # Shared with the e2e workflows: this job provisions on the same runner + # pools and the same hypervisors, so two in flight compete for their disks + # and their libvirt guests. Job-level, so the build jobs are not queued + # behind a nightly that has nothing to do with them. + concurrency: + group: e2e-hypervisors + cancel-in-progress: false timeout-minutes: 25 env: TOFU_LOG: /tmp/release-verify-${{ github.run_id }}.log @@ -174,6 +181,13 @@ jobs: sparse-checkout: scripts/tofu-cluster path: mulga + # Only the shared shell helpers: this job builds nothing from source, but + # it drives the same libvirt provider the e2e cells retry around. + - uses: actions/checkout@v7 + with: + sparse-checkout: .github/scripts + path: spinifex + - name: Download Release Assets uses: actions/download-artifact@v8 with: @@ -183,11 +197,12 @@ jobs: - name: Provision VM working-directory: mulga/scripts/tofu-cluster run: | + source "${GITHUB_WORKSPACE}/spinifex/.github/scripts/ci-fmt.sh" tofu init -input=false >> "$TOFU_LOG" 2>&1 tofu workspace select -or-create "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false >> "$TOFU_LOG" 2>&1 || true ./scrub-env.sh "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 || true - tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false >> "$TOFU_LOG" 2>&1 + retry_run "tofu apply" "$TOFU_LOG" tofu apply -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false - name: Bootstrap via Binary Install working-directory: mulga/scripts/tofu-cluster @@ -200,8 +215,9 @@ jobs: if: always() working-directory: mulga/scripts/tofu-cluster run: | + source "${GITHUB_WORKSPACE}/spinifex/.github/scripts/ci-fmt.sh" tofu workspace select -or-create "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 - tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false >> "$TOFU_LOG" 2>&1 + retry_run "tofu destroy" "$TOFU_LOG" tofu destroy -var-file=envs/${SPINIFEX_CI_ENV}.tfvars -auto-approve -input=false ./scrub-env.sh "${SPINIFEX_CI_ENV}" >> "$TOFU_LOG" 2>&1 || true baremetal: diff --git a/.gitignore b/.gitignore index 7fe86d71f..0b2dab0fc 100644 --- a/.gitignore +++ b/.gitignore @@ -41,3 +41,4 @@ Thumbs.db # Test reports *-report.txt +/rds-agent diff --git a/cmd/rds-agent/command.go b/cmd/rds-agent/command.go index d9e2920ea..8ec94982d 100644 --- a/cmd/rds-agent/command.go +++ b/cmd/rds-agent/command.go @@ -50,7 +50,13 @@ func newCommandRegistry(engine engineOps, storage storageOps) commandRegistry { if err != nil { return "", err } - return "", engine.Quiesce(ctx, params[handlers_rds.CommandParamQuiesceLabel], hold) + if err := engine.Quiesce(ctx, params[handlers_rds.CommandParamQuiesceLabel], hold); err != nil { + return "", err + } + // After the hold, so what is flushed is the engine's checkpointed + // state. Its own files are not the risk — those it repairs from the + // WAL — but the parameter file beside them it never opens. + return "", storage.SyncDataMount(ctx) }, handlers_rds.CommandUnquiesce: func(ctx context.Context, cmd handlers_rds.Command) (string, error) { return "", engine.Unquiesce(ctx) diff --git a/cmd/rds-agent/engine.go b/cmd/rds-agent/engine.go index c56b494c5..821ba6342 100644 --- a/cmd/rds-agent/engine.go +++ b/cmd/rds-agent/engine.go @@ -8,6 +8,7 @@ import ( "os/exec" "os/user" "path/filepath" + "slices" "strconv" "strings" "syscall" @@ -107,6 +108,10 @@ var engineLayouts = map[string]engineLayout{ service: "postgresql", dataMount: "/var/lib/postgresql", port: 5432, + // logfile in the image's /etc/conf.d/postgresql. The postmaster states + // which setting it refused there and nowhere else — the console shows only + // that pg_ctl could not start it, on a guest with no SSH. + errorLog: "/var/log/postgresql/postmaster.log", newProbe: newPostgresProbe, newEngine: newPostgresEngineFromCatalog, }, @@ -131,6 +136,61 @@ var engineLayouts = map[string]engineLayout{ }, } +// How much of the engine's error log a probe reason carries. The server names +// what it refused on in its last few lines, and the reason reaches a customer +// through StatusInfos, so this quotes the tail rather than the whole file. +const ( + engineErrorLogTailBytes = 4096 + engineErrorLogTailLines = 4 +) + +// Appends the last few lines of the engine's error log to reason. An unset path, +// an unreadable file or an empty one leaves reason alone: the probe's own +// statement is still true, and a guessed cause would be worse than none. +func withEngineLogTail(reason, path string) string { + tail := engineLogTail(path) + if tail == "" { + return reason + } + return reason + "; the engine's log ends: " + tail +} + +func engineLogTail(path string) string { + if path == "" { + return "" + } + f, err := os.Open(path) + if err != nil { + return "" + } + defer func() { _ = f.Close() }() + + info, err := f.Stat() + if err != nil { + return "" + } + offset := max(info.Size()-engineErrorLogTailBytes, 0) + buf := make([]byte, info.Size()-offset) + if _, err := f.ReadAt(buf, offset); err != nil { + return "" + } + + lines := strings.Split(string(buf), "\n") + // A read that started mid-file almost certainly started mid-line, and half a + // line is more misleading than one fewer. + if offset > 0 && len(lines) > 0 { + lines = lines[1:] + } + kept := make([]string, 0, engineErrorLogTailLines) + for i := len(lines) - 1; i >= 0 && len(kept) < engineErrorLogTailLines; i-- { + if line := strings.TrimSpace(lines[i]); line != "" { + kept = append(kept, line) + } + } + slices.Reverse(kept) + return strings.Join(kept, " | ") +} + // Builds the health probe the image's engine supplies. func newProbe(cfg config, run probeRunner) (*engineProbe, error) { layout, err := layoutFor(cfg) diff --git a/cmd/rds-agent/engine_mariadb_log_test.go b/cmd/rds-agent/engine_log_test.go similarity index 76% rename from cmd/rds-agent/engine_mariadb_log_test.go rename to cmd/rds-agent/engine_log_test.go index ad38fe94a..4f89e7e55 100644 --- a/cmd/rds-agent/engine_mariadb_log_test.go +++ b/cmd/rds-agent/engine_log_test.go @@ -148,7 +148,7 @@ func TestEngineLogTail(t *testing.T) { }, { name: "drops a line the byte cap cut in half", - body: strings.Repeat("x", mariadbErrorLogTailBytes) + "\nlast\n", + body: strings.Repeat("x", engineErrorLogTailBytes) + "\nlast\n", want: "last", wantMissing: "x", }, @@ -209,3 +209,54 @@ func TestWithEngineLogTailLeavesReasonAloneWithoutALog(t *testing.T) { t.Errorf("withEngineLogTail() = %q, want the reason unchanged", got) } } + +const postgresConfD = "../../scripts/images/rds-postgres/postgresql.confd" + +// "engine did not respond" is where a postmaster that refused a setting lands, +// and it is the same message as an engine that never got as far as trying. Only +// the server's own log separates them, and the guest has no other way out. +func TestPostgresProbe_QuotesTheEngineLogWhenTheEngineIsAbsent(t *testing.T) { + log := writeEngineLog(t, strings.Join([]string{ + `2026-09-06 10:20:33 UTC [712] LOG: starting PostgreSQL 18.0`, + `2026-09-06 10:20:33 UTC [712] FATAL: could not map anonymous shared memory`, + "", + }, "\n")) + + state, message := postgresProbeState("/run/postgresql", log, + func(context.Context, string, ...string) (int, string, error) { return 2, "", nil })(t.Context(), 5432) + + if state != engineAbsent { + t.Errorf("state = %v, want absent", state) + } + if !strings.Contains(message, "could not map anonymous shared memory") { + t.Errorf("message = %q, want the postmaster's own refusal quoted", message) + } +} + +func TestPostgresProbe_SurvivesAnAbsentEngineLog(t *testing.T) { + state, message := postgresProbeState("/run/postgresql", filepath.Join(t.TempDir(), "nope.log"), + func(context.Context, string, ...string) (int, string, error) { return 2, "", nil })(t.Context(), 5432) + + if state != engineAbsent { + t.Errorf("state = %v, want absent", state) + } + if message != "engine did not respond on /run/postgresql:5432" { + t.Errorf("message = %q, want the bare reason when there is no log to quote", message) + } +} + +// The layout names a path the image has to be directing the postmaster to, or +// the tail above quotes nothing on the one failure it exists for. +func TestPostgresErrorLogPathMatchesTheImage(t *testing.T) { + raw, err := os.ReadFile(postgresConfD) + if err != nil { + t.Fatalf("read postgresql.confd: %v", err) + } + m := regexp.MustCompile(`(?m)^logfile="(.*)"$`).FindStringSubmatch(string(raw)) + if m == nil { + t.Fatal("postgresql.confd has no logfile assignment") + } + if got := engineLayouts[enginePostgres].errorLog; got != m[1] { + t.Errorf("layout errorLog = %q, but the image sets logfile = %q", got, m[1]) + } +} diff --git a/cmd/rds-agent/engine_mariadb.go b/cmd/rds-agent/engine_mariadb.go index 9fe96d9ce..1bc32ab38 100644 --- a/cmd/rds-agent/engine_mariadb.go +++ b/cmd/rds-agent/engine_mariadb.go @@ -100,11 +100,6 @@ const ( // rds-init keeps for the platform and never hands to the customer. mariadbSuperuser = "root" mariadbProbeConnectTimeoutSeconds = 3 - // How much of the engine's error log a probe reason carries. The server names - // what it refused on in its last few lines, and the reason reaches a customer - // through StatusInfos, so this quotes the tail rather than the whole file. - mariadbErrorLogTailBytes = 4096 - mariadbErrorLogTailLines = 4 // How much of the probe client's stderr a reason carries, on the same grounds // as the log tail above. mariadbProbeStderrMaxBytes = 512 @@ -280,53 +275,6 @@ func collapseProbeStderr(stderr string) string { return line } -// Appends the last few lines of the engine's error log to reason. An unset path, -// an unreadable file or an empty one leaves reason alone: the probe's own -// statement is still true, and a guessed cause would be worse than none. -func withEngineLogTail(reason, path string) string { - tail := engineLogTail(path) - if tail == "" { - return reason - } - return reason + "; the engine's log ends: " + tail -} - -func engineLogTail(path string) string { - if path == "" { - return "" - } - f, err := os.Open(path) - if err != nil { - return "" - } - defer func() { _ = f.Close() }() - - info, err := f.Stat() - if err != nil { - return "" - } - offset := max(info.Size()-mariadbErrorLogTailBytes, 0) - buf := make([]byte, info.Size()-offset) - if _, err := f.ReadAt(buf, offset); err != nil { - return "" - } - - lines := strings.Split(string(buf), "\n") - // A read that started mid-file almost certainly started mid-line, and half a - // line is more misleading than one fewer. - if offset > 0 && len(lines) > 0 { - lines = lines[1:] - } - kept := make([]string, 0, mariadbErrorLogTailLines) - for i := len(lines) - 1; i >= 0 && len(kept) < mariadbErrorLogTailLines; i-- { - if line := strings.TrimSpace(lines[i]); line != "" { - kept = append(kept, line) - } - } - slices.Reverse(kept) - return strings.Join(kept, " | ") -} - func readPidFile(path string) (int, error) { raw, err := os.ReadFile(path) if err != nil { diff --git a/cmd/rds-agent/engine_postgres.go b/cmd/rds-agent/engine_postgres.go index c266ea3e1..51837b291 100644 --- a/cmd/rds-agent/engine_postgres.go +++ b/cmd/rds-agent/engine_postgres.go @@ -47,10 +47,10 @@ const postgresProbeBinary = "pg_isready" // enforcement rule — libpq reads a host beginning with / as a socket directory, // and the generated `local ... peer` line covers it. func newPostgresProbe(cfg config, run probeRunner) *engineProbe { - return newEngineProbe(cfg.EnginePort, postgresProbeState(cfg.SocketDir, run)) + return newEngineProbe(cfg.EnginePort, postgresProbeState(cfg.SocketDir, cfg.EngineErrorLog, run)) } -func postgresProbeState(host string, run probeRunner) probeStateFn { +func postgresProbeState(host, errorLog string, run probeRunner) probeStateFn { return func(ctx context.Context, port int64) (engineState, string) { portArg := strconv.FormatInt(port, 10) code, _, err := run(ctx, postgresProbeBinary, "-h", host, "-p", portArg, "-q") @@ -63,9 +63,14 @@ func postgresProbeState(host string, run probeRunner) probeStateFn { case code == 0: return engineServing, "" case code == 1: - return engineRecovering, "engine is rejecting connections (startup or recovery)" + return engineRecovering, withEngineLogTail( + "engine is rejecting connections (startup or recovery)", errorLog) default: - return engineAbsent, fmt.Sprintf("engine did not respond on %s:%s", host, portArg) + // A postmaster that refused a setting never opens the socket, so this is + // the state a bad parameter lands in. The reason for it is only in the + // server's own log, and it reaches the customer through StatusInfos. + return engineAbsent, withEngineLogTail( + fmt.Sprintf("engine did not respond on %s:%s", host, portArg), errorLog) } } } diff --git a/cmd/rds-agent/heartbeat.go b/cmd/rds-agent/heartbeat.go index 4f006a2eb..cb0253b99 100644 --- a/cmd/rds-agent/heartbeat.go +++ b/cmd/rds-agent/heartbeat.go @@ -90,10 +90,26 @@ func (h *heartbeater) beat(ctx context.Context) { h.setInterval(time.Duration(out.HeartbeatIntervalSeconds) * time.Second) } +// How often a not-yet-serving engine is reported. The control plane owns the +// steady-state cadence, but while the engine has never answered it is actively +// waiting on this instance — a restart is not finished until a healthy beat +// lands — and a full interval of silence there is pure added downtime. +const startupHeartbeatInterval = 5 * time.Second + +func (h *heartbeater) nextInterval() time.Duration { + if h.probe != nil && !h.probe.seenHealthy && startupHeartbeatInterval < h.interval { + return startupHeartbeatInterval + } + return h.interval +} + // A timer rather than a ticker, so a cadence change takes effect on the next -// beat, not at a restart. +// beat, not at a restart. The first beat is not waited for: a just-registered +// agent has told the control plane nothing about the engine yet, and holding +// that back for an interval makes every restart look longer than it was. func (h *heartbeater) Run(ctx context.Context) { - timer := time.NewTimer(h.interval) + h.beat(ctx) + timer := time.NewTimer(h.nextInterval()) defer timer.Stop() for { select { @@ -101,7 +117,7 @@ func (h *heartbeater) Run(ctx context.Context) { return case <-timer.C: h.beat(ctx) - timer.Reset(h.interval) + timer.Reset(h.nextInterval()) } } } diff --git a/cmd/rds-agent/heartbeat_test.go b/cmd/rds-agent/heartbeat_test.go index 2a56ac970..6e428d6f3 100644 --- a/cmd/rds-agent/heartbeat_test.go +++ b/cmd/rds-agent/heartbeat_test.go @@ -88,3 +88,34 @@ func (r *countingServingRecorder) RecordServingParameters(context.Context) error r.calls++ return nil } + +// A restart is not finished until a healthy beat lands, so the two cadence +// rules that shorten it are worth pinning: report at once rather than after a +// full interval, and keep reporting quickly while the engine has never served. +func TestHeartbeater_ReportsPromptlyUntilTheEngineHasServed(t *testing.T) { + code := 2 + probe := newPostgresProbe(testProbeConfig(), func(context.Context, string, ...string) (int, string, error) { + return code, "", nil + }) + cp := newFakeControlPlane() + h := newHeartbeater(cp, probe, nil, 0) + + if got := h.nextInterval(); got != startupHeartbeatInterval { + t.Errorf("interval before the engine has served = %s, want %s", got, startupHeartbeatInterval) + } + + ctx, cancel := context.WithCancel(context.Background()) + go h.Run(ctx) + waitFor(t, func() bool { return len(cp.snapshotStates()) > 0 }, "the first heartbeat") + cancel() + + if states := cp.snapshotStates(); states[0].health != handlers_rds.EngineHealthStarting { + t.Errorf("first beat health = %q, want %q", states[0].health, handlers_rds.EngineHealthStarting) + } + + code = 0 + h.beat(context.Background()) + if got := h.nextInterval(); got != h.interval { + t.Errorf("interval after the engine served = %s, want the control plane's %s", got, h.interval) + } +} diff --git a/cmd/rds-agent/main.go b/cmd/rds-agent/main.go index cfe9c0a2c..1d667c6dd 100644 --- a/cmd/rds-agent/main.go +++ b/cmd/rds-agent/main.go @@ -22,15 +22,26 @@ import ( func main() { cfg := loadConfig(defaultEnvFile) - agent, err := New(cfg) + ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) + defer stop() + + // Retried rather than fatal: construction resolves the IMDS credential chain, + // so a metadata service that is not answering yet would otherwise end the + // process with the engine still down and nothing left to bring it back. + var agent *Agent + err := retry(ctx, "startup", func(context.Context) error { + var err error + agent, err = New(cfg) + return err + }) if err != nil { + if errors.Is(err, context.Canceled) { + return + } slog.Error("rds-agent: startup failed", "err", err) os.Exit(1) } - ctx, stop := signal.NotifyContext(context.Background(), syscall.SIGINT, syscall.SIGTERM) - defer stop() - // A shutdown signal cancels whatever boot retry loop was running; that is a // clean stop, not a failure. if err := agent.Run(ctx); err != nil && !errors.Is(err, context.Canceled) { diff --git a/cmd/rds-agent/quiesce_test.go b/cmd/rds-agent/quiesce_test.go index a92f14822..804ce284a 100644 --- a/cmd/rds-agent/quiesce_test.go +++ b/cmd/rds-agent/quiesce_test.go @@ -2,6 +2,7 @@ package main import ( "context" + "errors" "slices" "strings" "sync" @@ -132,6 +133,50 @@ func TestCommandRegistry_QuiesceCarriesTheLabelAndDeadline(t *testing.T) { } } +// The engine's own hold settles only the files it owns. Everything else on that +// volume — the parameter file the platform writes beside the datadir — is dirty +// page cache until this, and a snapshot of it restores an engine that will not +// start. +func TestCommandRegistry_QuiesceFlushesTheDataMount(t *testing.T) { + storage := &fakeStorage{} + reply := newCommander(nil, newCommandRegistry(&fakeEngine{}, storage), 0).execute(context.Background(), + quiesceCommand("cmd-5a", "360")) + + if reply.Status != handlers_rds.CommandStatusSucceeded { + t.Fatalf("reply = %+v, want succeeded", reply) + } + if !storage.synced { + t.Error("the data mount was not flushed, so the snapshot may not hold what the guest wrote") + } +} + +// A snapshot taken after a flush that did not happen is the failure this whole +// path exists to prevent, so it is reported rather than swallowed. The hold is +// left on the engine: it expires on its own deadline. +func TestCommandRegistry_QuiesceFailsWhenTheDataMountCannotBeFlushed(t *testing.T) { + storage := &fakeStorage{syncErr: errors.New("input/output error")} + reply := newCommander(nil, newCommandRegistry(&fakeEngine{}, storage), 0).execute(context.Background(), + quiesceCommand("cmd-5b", "360")) + + if reply.Status != handlers_rds.CommandStatusFailed { + t.Fatalf("reply = %+v, want failed", reply) + } + if !strings.Contains(reply.Message, "input/output error") { + t.Errorf("reply message = %q, want the flush error", reply.Message) + } +} + +func quiesceCommand(id, deadline string) handlers_rds.Command { + return handlers_rds.Command{ + CommandID: id, + Type: handlers_rds.CommandQuiesce, + Parameters: []handlers_rds.Parameter{ + {Name: handlers_rds.CommandParamQuiesceLabel, Value: "orders-db-pre-upgrade"}, + {Name: handlers_rds.CommandParamQuiesceDeadlineSeconds, Value: deadline}, + }, + } +} + // A hold the guest chose the length of would not be the bound the control plane // is relying on, so a missing or unreadable deadline is refused. func TestCommandRegistry_QuiesceRejectsAnUnusableDeadline(t *testing.T) { diff --git a/cmd/rds-agent/storage.go b/cmd/rds-agent/storage.go index 0056d4ce5..cfa90c4c1 100644 --- a/cmd/rds-agent/storage.go +++ b/cmd/rds-agent/storage.go @@ -8,6 +8,8 @@ import ( "os" "path/filepath" "strings" + + "golang.org/x/sys/unix" ) // The in-guest half of a storage grow: the control plane has already grown the @@ -17,6 +19,9 @@ type storageOps interface { // Extends the filesystem at the data mount onto its whole device, and // reports what it did for the command reply. GrowFilesystem(ctx context.Context) (string, error) + // Flushes every dirty page on the data mount to its device. A backup hold + // settles the engine's own files and nothing else on that filesystem. + SyncDataMount(ctx context.Context) error } // Tool names rather than paths: the image installs them from @@ -50,6 +55,23 @@ func newGuestStorage(cfg config, run commandRunner) *guestStorage { } } +// syncfs rather than fsync: the whole filesystem, not one file. Config the +// engine never opens lives on this volume too, and a snapshot that catches it +// half-written leaves a restored instance the engine cannot start from. +func (g *guestStorage) SyncDataMount(ctx context.Context) error { + f, err := os.Open(g.dataMount) + if err != nil { + return fmt.Errorf("open the data mount %s to flush it: %w", g.dataMount, err) + } + defer func() { _ = f.Close() }() + + if err := unix.Syncfs(int(f.Fd())); err != nil { + return fmt.Errorf("flush the data mount %s: %w", g.dataMount, err) + } + slog.InfoContext(ctx, "rds-agent: data mount flushed for backup", "dataMount", g.dataMount) + return nil +} + // The device and filesystem behind the data mount, resolved from the kernel's // own mount table rather than from anything the control plane asserted. type dataMount struct { diff --git a/cmd/rds-agent/storage_test.go b/cmd/rds-agent/storage_test.go index 98b2f8fd7..485a85385 100644 --- a/cmd/rds-agent/storage_test.go +++ b/cmd/rds-agent/storage_test.go @@ -15,8 +15,10 @@ import ( // is that the command reaches it rather than what it does to a filesystem. type fakeStorage struct { grown bool + synced bool message string err error + syncErr error } var _ storageOps = (*fakeStorage)(nil) @@ -26,6 +28,11 @@ func (f *fakeStorage) GrowFilesystem(context.Context) (string, error) { return f.message, f.err } +func (f *fakeStorage) SyncDataMount(context.Context) error { + f.synced = true + return f.syncErr +} + // runLog records what a grow shelled out to, in order, so the test asserts on // the tools invoked rather than on a filesystem it would have to create. type runLog struct { @@ -227,3 +234,25 @@ func TestCommandRegistry_GrowFilesystemReachesTheGuestStorage(t *testing.T) { t.Errorf("reply = %+v, want succeeded carrying what the grow reported", reply) } } + +func TestSyncDataMount_FlushesTheMountItWasGiven(t *testing.T) { + g := &guestStorage{dataMount: t.TempDir()} + + if err := g.SyncDataMount(context.Background()); err != nil { + t.Fatalf("SyncDataMount: %v", err) + } +} + +// The control plane snapshots on the strength of this reply, so a mount that is +// not there has to be an error rather than a flush of nothing. +func TestSyncDataMount_FailsWhenTheMountIsNotThere(t *testing.T) { + g := &guestStorage{dataMount: filepath.Join(t.TempDir(), "absent")} + + err := g.SyncDataMount(context.Background()) + if err == nil { + t.Fatal("SyncDataMount succeeded on a mount that does not exist") + } + if !strings.Contains(err.Error(), "absent") { + t.Errorf("error = %v, want the mount it could not open", err) + } +} diff --git a/scripts/images/rds-mariadb/rds-agent.initd b/scripts/images/rds-mariadb/rds-agent.initd index d3d4cee33..eb4e7e220 100644 --- a/scripts/images/rds-mariadb/rds-agent.initd +++ b/scripts/images/rds-mariadb/rds-agent.initd @@ -40,6 +40,28 @@ start_pre() { fi } +# The agent's log is inside a guest nothing can reach, so anything that is not +# mirrored here is lost. Used by both the failed start and the handoff timeout. +mirror_agent_log() { + if [ -s "${output_log}" ]; then + einfo "last ${handoff_tail} lines of ${output_log}:" + tail -n "${handoff_tail}" "${output_log}" 2>/dev/null | while IFS= read -r _line; do + einfo " [rds-agent] ${_line}" + done + else + einfo "${output_log} is empty — the agent produced no output at all" + fi +} + +# OpenRC skips start_post when the start itself fails, which is the one case +# with no diagnostic at all: the console reports only that the process died. +start() { + default_start && return 0 + eerror "rds-agent exited during start" + mirror_agent_log + return 1 +} + start_post() { # Resolve this after start_pre loads agent.env so custom handoff directories # are shared by the agent, this wait, and rds-init. @@ -53,18 +75,10 @@ start_post() { while [ ! -f "${HANDOFF_ENV}" ]; do if [ "${_waited}" -ge "${handoff_timeout}" ]; then eend 1 "no bootstrap handoff after ${handoff_timeout}s" - # Mirror the agent's own tail onto the console. The log lives inside a - # guest nothing can reach when this fails — an unreachable gateway is - # the usual cause — so the host-side console capture is the only way - # the dial error survives, and without it the failure reads as silence. - if [ -s "${output_log}" ]; then - einfo "last ${handoff_tail} lines of ${output_log}:" - tail -n "${handoff_tail}" "${output_log}" 2>/dev/null | while IFS= read -r _line; do - einfo " [rds-agent] ${_line}" - done - else - einfo "${output_log} is empty — the agent produced no output at all" - fi + # An unreachable gateway is the usual cause, and the host-side console + # capture is the only way that dial error survives — without it the + # failure reads as silence. + mirror_agent_log # The agent keeps retrying, so it is left running: rds-init fails on # the missing handoff and the engine stays down, which is what the # control plane observes. @@ -73,5 +87,11 @@ start_post() { sleep 1 _waited=$((_waited + 1)) done + + # A handoff means the agent read agent.env, which cloud-init wrote seconds + # ago and only into page cache. A reboot is a QMP reset with no guest + # shutdown, so anything not yet written back is gone and the next boot has + # no gateway URL to reach the control plane with. + sync eend 0 } diff --git a/scripts/images/rds-mariadb/rds-agent_initd_test.sh b/scripts/images/rds-mariadb/rds-agent_initd_test.sh index ca042c55d..d4089d614 100755 --- a/scripts/images/rds-mariadb/rds-agent_initd_test.sh +++ b/scripts/images/rds-mariadb/rds-agent_initd_test.sh @@ -22,9 +22,16 @@ export AGENT_ENV="${CASE}/agent.env" export handoff_timeout=0 EEND_STATUS= +# A file rather than a variable: the mirror pipes tail into a while loop, which +# POSIX sh runs in a subshell, so an assignment there would not survive it. +CONSOLE="${CASE}/console" +: >"${CONSOLE}" ebegin() { :; } -einfo() { :; } +einfo() { printf '%s\n' "$*" >>"${CONSOLE}"; } +eerror() { printf '%s\n' "$*" >>"${CONSOLE}"; } eend() { EEND_STATUS=$1; } +SYNCED= +sync() { SYNCED=1; } start_pre start_post @@ -45,4 +52,28 @@ if [ "${RDS_ENGINE:-}" != "mariadb" ]; then exit 1 fi +# cloud-init writes agent.env once and never again, so the copy the next boot +# reads is whatever reached the disk. A reboot is a reset with no guest +# shutdown, and an unflushed agent.env leaves the agent with no gateway URL. +if [ "${SYNCED}" != "1" ]; then + echo "FAIL: the handoff wait did not flush the config cloud-init wrote" >&2 + exit 1 +fi + +# A start that fails is the one case OpenRC runs no start_post for, so without +# this the console carries nothing but "died" and the reason is lost with the +# guest. +export output_log="${CASE}/agent.log" +printf 'rds-agent: startup failed err="build IMDS signer: no credentials"\n' >"${output_log}" +: >"${CONSOLE}" +default_start() { return 1; } +if start; then + echo "FAIL: start reported success when the agent died" >&2 + exit 1 +fi +if ! grep -q "build IMDS signer" "${CONSOLE}"; then + echo "FAIL: a failed start did not mirror the agent log to the console" >&2 + exit 1 +fi + echo "rds-agent.initd: all tests passed" diff --git a/scripts/images/rds-postgres/rds-agent.initd b/scripts/images/rds-postgres/rds-agent.initd index 34011febd..bbfffe260 100644 --- a/scripts/images/rds-postgres/rds-agent.initd +++ b/scripts/images/rds-postgres/rds-agent.initd @@ -40,6 +40,28 @@ start_pre() { fi } +# The agent's log is inside a guest nothing can reach, so anything that is not +# mirrored here is lost. Used by both the failed start and the handoff timeout. +mirror_agent_log() { + if [ -s "${output_log}" ]; then + einfo "last ${handoff_tail} lines of ${output_log}:" + tail -n "${handoff_tail}" "${output_log}" 2>/dev/null | while IFS= read -r _line; do + einfo " [rds-agent] ${_line}" + done + else + einfo "${output_log} is empty — the agent produced no output at all" + fi +} + +# OpenRC skips start_post when the start itself fails, which is the one case +# with no diagnostic at all: the console reports only that the process died. +start() { + default_start && return 0 + eerror "rds-agent exited during start" + mirror_agent_log + return 1 +} + start_post() { # Resolve this after start_pre loads agent.env so custom handoff directories # are shared by the agent, this wait, and rds-init. @@ -53,18 +75,10 @@ start_post() { while [ ! -f "${HANDOFF_ENV}" ]; do if [ "${_waited}" -ge "${handoff_timeout}" ]; then eend 1 "no bootstrap handoff after ${handoff_timeout}s" - # Mirror the agent's own tail onto the console. The log lives inside a - # guest nothing can reach when this fails — an unreachable gateway is - # the usual cause — so the host-side console capture is the only way - # the dial error survives, and without it the failure reads as silence. - if [ -s "${output_log}" ]; then - einfo "last ${handoff_tail} lines of ${output_log}:" - tail -n "${handoff_tail}" "${output_log}" 2>/dev/null | while IFS= read -r _line; do - einfo " [rds-agent] ${_line}" - done - else - einfo "${output_log} is empty — the agent produced no output at all" - fi + # An unreachable gateway is the usual cause, and the host-side console + # capture is the only way that dial error survives — without it the + # failure reads as silence. + mirror_agent_log # The agent keeps retrying, so it is left running: rds-init fails on # the missing handoff and the engine stays down, which is what the # control plane observes. @@ -73,5 +87,11 @@ start_post() { sleep 1 _waited=$((_waited + 1)) done + + # A handoff means the agent read agent.env, which cloud-init wrote seconds + # ago and only into page cache. A reboot is a QMP reset with no guest + # shutdown, so anything not yet written back is gone and the next boot has + # no gateway URL to reach the control plane with. + sync eend 0 } diff --git a/scripts/images/rds-postgres/rds-agent_initd_test.sh b/scripts/images/rds-postgres/rds-agent_initd_test.sh index 185a1c04e..2e055b752 100644 --- a/scripts/images/rds-postgres/rds-agent_initd_test.sh +++ b/scripts/images/rds-postgres/rds-agent_initd_test.sh @@ -22,9 +22,16 @@ export AGENT_ENV="${CASE}/agent.env" export handoff_timeout=0 EEND_STATUS= +# A file rather than a variable: the mirror pipes tail into a while loop, which +# POSIX sh runs in a subshell, so an assignment there would not survive it. +CONSOLE="${CASE}/console" +: >"${CONSOLE}" ebegin() { :; } -einfo() { :; } +einfo() { printf '%s\n' "$*" >>"${CONSOLE}"; } +eerror() { printf '%s\n' "$*" >>"${CONSOLE}"; } eend() { EEND_STATUS=$1; } +SYNCED= +sync() { SYNCED=1; } start_pre start_post @@ -45,4 +52,28 @@ if [ "${RDS_ENGINE:-}" != "postgres" ]; then exit 1 fi +# cloud-init writes agent.env once and never again, so the copy the next boot +# reads is whatever reached the disk. A reboot is a reset with no guest +# shutdown, and an unflushed agent.env leaves the agent with no gateway URL. +if [ "${SYNCED}" != "1" ]; then + echo "FAIL: the handoff wait did not flush the config cloud-init wrote" >&2 + exit 1 +fi + +# A start that fails is the one case OpenRC runs no start_post for, so without +# this the console carries nothing but "died" and the reason is lost with the +# guest. +export output_log="${CASE}/agent.log" +printf 'rds-agent: startup failed err="build IMDS signer: no credentials"\n' >"${output_log}" +: >"${CONSOLE}" +default_start() { return 1; } +if start; then + echo "FAIL: start reported success when the agent died" >&2 + exit 1 +fi +if ! grep -q "build IMDS signer" "${CONSOLE}"; then + echo "FAIL: a failed start did not mirror the agent log to the console" >&2 + exit 1 +fi + echo "rds-agent.initd: all tests passed" diff --git a/scripts/images/rds-postgres/rds-init b/scripts/images/rds-postgres/rds-init index 3c9711774..efdeedffc 100644 --- a/scripts/images/rds-postgres/rds-init +++ b/scripts/images/rds-postgres/rds-init @@ -579,6 +579,33 @@ EOF mv -f "${_tmp}" "${PGDATA}/conf.d/90-rds-init.conf" } +# postgresql.conf is on the data volume, so the hook is asserted every boot +# rather than only at initdb — a restored volume may predate it. +# +# Rewritten and renamed rather than appended to. It is the only file rds-init +# puts on that volume without the engine's knowledge, so a torn tail is the one +# corruption the engine cannot repair from its own WAL: the postmaster stops on +# a syntax error and the instance never comes up. +install_include_hook() { + _conf="${PGDATA}/postgresql.conf" + _tmp="${PGDATA}/.postgresql.conf.new" + + if grep -q "^include_dir = 'conf.d'" "${_conf}" 2>/dev/null; then + return 0 + fi + # Any half-written hook this script left behind goes rather than being kept: + # the guard above does not match one, so appending after its unterminated + # quote would stop the postmaster on a file it could not have started from. + grep -v "^include_dir = 'conf" "${_conf}" 2>/dev/null >"${_tmp}" || : + printf "\n# Managed by rds-init: parameter-group values (10-) then platform settings (90-).\ninclude_dir = 'conf.d'\n" \ + >>"${_tmp}" + + chown "${PG_USER}:${PG_USER}" "${_tmp}" + chmod 0600 "${_tmp}" + mv -f "${_tmp}" "${_conf}" || + fail "the include hook could not be installed into ${_conf}" +} + # Everything refreshed on every boot: the include hook, the client # authentication rules, the resolved parameters, the serving cert, the TLS # enforcement those parameters ask for and the platform's own connectivity @@ -588,12 +615,7 @@ install_runtime_config() { install -d -m 1775 -o "${PG_USER}" -g "${PG_USER}" "${SOCKET_DIR}" install -d -m 0755 -o "${PG_USER}" -g "${PG_USER}" "${LOG_DIR}" - # postgresql.conf is on the data volume, so the hook is asserted every boot - # rather than only at initdb — a restored volume may predate it. - if ! grep -q "^include_dir = 'conf.d'" "${PGDATA}/postgresql.conf"; then - printf "\n# Managed by rds-init: parameter-group values (10-) then platform settings (90-).\ninclude_dir = 'conf.d'\n" \ - >> "${PGDATA}/postgresql.conf" - fi + install_include_hook write_pg_hba install_parameters diff --git a/scripts/images/rds-postgres/rds-init_test.sh b/scripts/images/rds-postgres/rds-init_test.sh index ecc41250f..4ef95895a 100644 --- a/scripts/images/rds-postgres/rds-init_test.sh +++ b/scripts/images/rds-postgres/rds-init_test.sh @@ -1267,6 +1267,42 @@ if run_ok "restore-scope-setup"; then fi fi +# --- Case 14: a half-written include hook is repaired, not appended after --- +# postgresql.conf is the one file rds-init puts on the data volume without the +# engine's knowledge, so a torn tail is the one corruption no WAL replay repairs: +# the guard does not match an unterminated hook, and appending after it leaves an +# open quote the postmaster stops on. +reset_state +write_handoff initialize 's3cr3t' appdb +write_parameters +if run_ok "torn-hook-setup"; then + # The shape a snapshot of an unflushed append restores: the hook cut short. + sed "s/^include_dir = 'conf.d'$/include_dir = 'conf/" "${PGDATA}/postgresql.conf" \ + >"${PGDATA}/postgresql.conf.torn" + mv -f "${PGDATA}/postgresql.conf.torn" "${PGDATA}/postgresql.conf" + write_handoff attach '' appdb + write_parameters + if run_ok "torn-hook"; then + grep -q "^include_dir = 'conf.d'$" "${PGDATA}/postgresql.conf" \ + && pass "torn-hook: the hook is back" || fail "torn-hook: no usable hook" + grep -c "^include_dir = 'conf" "${PGDATA}/postgresql.conf" | grep -qx 1 \ + && pass "torn-hook: the torn line is gone rather than appended after" \ + || fail "torn-hook: the torn line survived beside the new one" + fi +fi + +# --- Case 14a: the hook is written whole or not at all --- +# Appended in place, a snapshot could catch it half-written; renamed over, the +# file a restore reads is either the old one or the complete new one. +reset_state +write_handoff initialize 's3cr3t' appdb +write_parameters +if run_ok "hook-atomic"; then + [ -e "${PGDATA}/.postgresql.conf.new" ] \ + && fail "hook-atomic: the temp file was left behind" \ + || pass "hook-atomic: no temp file survives the install" +fi + if [ "${FAILS}" -eq 0 ]; then echo "PASS: all rds-init cases" exit 0 diff --git a/spinifex/gateway/ec2/volume/DetachVolume.go b/spinifex/gateway/ec2/volume/DetachVolume.go index cac434ed1..e049e0d76 100644 --- a/spinifex/gateway/ec2/volume/DetachVolume.go +++ b/spinifex/gateway/ec2/volume/DetachVolume.go @@ -17,6 +17,12 @@ import ( "github.com/nats-io/nats.go" ) +// detachRequestTimeout must outlast the daemon's own detach budget, which is +// the 180s ebs.unmount seal followed by the 180s QMP unplug chain. At 30s the +// gateway returned ServerInternal on every detach whose seal replayed a WAL, +// while that detach went on to succeed. +const detachRequestTimeout = 7 * time.Minute + // ValidateDetachVolumeInput validates the input parameters for DetachVolume. func ValidateDetachVolumeInput(input *ec2.DetachVolumeInput) error { if input == nil { @@ -92,7 +98,7 @@ func DetachVolume(ctx context.Context, input *ec2.DetachVolumeInput, natsConn *n reqMsg.Data = jsonData reqMsg.Header.Set(utils.AccountIDHeader, accountID) utils.InjectTraceContext(ctx, reqMsg.Header) - msg, err := natsConn.RequestMsg(reqMsg, 30*time.Second) + msg, err := natsConn.RequestMsg(reqMsg, detachRequestTimeout) if err != nil { slog.ErrorContext(ctx, "DetachVolume: NATS request failed", "instanceId", instanceID, "volumeId", volumeID, "err", err) if errors.Is(err, nats.ErrNoResponders) { diff --git a/spinifex/gateway/ec2/volume/DetachVolume_test.go b/spinifex/gateway/ec2/volume/DetachVolume_test.go index 01760f646..2cc820980 100644 --- a/spinifex/gateway/ec2/volume/DetachVolume_test.go +++ b/spinifex/gateway/ec2/volume/DetachVolume_test.go @@ -4,6 +4,7 @@ import ( "context" "encoding/json" "testing" + "time" "github.com/aws/aws-sdk-go/aws" "github.com/aws/aws-sdk-go/service/ec2" @@ -153,3 +154,12 @@ func TestDetachVolume_WithoutForceStillReportsTheMissingInstance(t *testing.T) { require.Error(t, err) assert.Equal(t, awserrors.ErrorInvalidInstanceIDNotFound, err.Error()) } + +// The gateway's deadline must outlast the daemon's, or a detach that is still +// working is reported to the caller as ServerInternal. The daemon spends up to +// 180s sealing and then up to 180s on the QMP unplug chain. +func TestDetachVolume_DeadlineOutlastsTheDaemonBudget(t *testing.T) { + const daemonBudget = 180*time.Second + 3*time.Minute + assert.Greater(t, detachRequestTimeout, daemonBudget, + "detachRequestTimeout must exceed the daemon's seal plus unplug budget") +} diff --git a/spinifex/handlers/ec2/eip/service_impl.go b/spinifex/handlers/ec2/eip/service_impl.go index 4a236539d..73f17e35a 100644 --- a/spinifex/handlers/ec2/eip/service_impl.go +++ b/spinifex/handlers/ec2/eip/service_impl.go @@ -790,12 +790,21 @@ func (s *EIPServiceImpl) ReleaseAddressByInstanceID(instanceID string) error { // publishNATEvent publishes a NAT lifecycle event to NATS for vpcd (fire-and-forget). // PortName must use topology.Port(eniID) to match the OVN logical switch port name; // a mismatch causes OVN to never program the DNAT flow. +// vpc.delete-nat goes through the shared helper so an undelivered teardown is +// retried across a vpcd restart and reported when it still fails. vpc.add-nat +// stays fire-and-forget here: the shared helper blocks it on the flows barrier, +// and associating an address must not inherit that latency. func (s *EIPServiceImpl) publishNATEvent(topic, vpcID, externalIP, logicalIP, eniID, mac string) { + portName := topology.Port(eniID) + if topic == "vpc.delete-nat" { + utils.PublishNATEvent(s.natsConn, topic, vpcID, externalIP, logicalIP, portName, mac) + return + } utils.PublishEvent(s.natsConn, topic, natEvent{ VpcId: vpcID, ExternalIP: externalIP, LogicalIP: logicalIP, - PortName: topology.Port(eniID), + PortName: portName, MAC: mac, }) } diff --git a/spinifex/handlers/rds/agent.go b/spinifex/handlers/rds/agent.go index 17f42ff6d..25d938e7e 100644 --- a/spinifex/handlers/rds/agent.go +++ b/spinifex/handlers/rds/agent.go @@ -190,6 +190,14 @@ func (s *Service) RegisterDBInstance(ctx context.Context, input *RegisterDBInsta if input.EngineVersion != "" { rec.Agent.EngineVersion = input.EngineVersion } + // A register is a fresh agent process that has not probed the engine yet, so + // the previous process's verdict stops standing in for one. Carrying it + // forward is what let a rebooting instance read healthy on a stamped LastSeen + // while the engine was still starting up. + started := now + rec.Agent.StartedAt = &started + rec.Agent.EngineHealth = EngineHealthStarting + rec.Agent.Message = "" rec.Agent.LastSeen = &now rec.UpdatedAt = now diff --git a/spinifex/handlers/rds/agent_test.go b/spinifex/handlers/rds/agent_test.go index 1bfe14bc8..16c138367 100644 --- a/spinifex/handlers/rds/agent_test.go +++ b/spinifex/handlers/rds/agent_test.go @@ -523,6 +523,32 @@ func TestRegisterDBInstance_NewVMResetsRegisteredAt(t *testing.T) { assert.True(t, second.Agent.RegisteredAt.After(*first.Agent.RegisteredAt)) } +// The register that follows a reboot must not let the pre-reboot verdict stand +// on a freshly stamped LastSeen: that combination reads as a healthy engine and +// is what returned an instance to available while PostgreSQL was still starting. +func TestRegisterDBInstance_DiscardsThePreviousProcessEngineHealth(t *testing.T) { + t.Parallel() + svc := newTestService(t) + rec := defaultRecord() + rec.Agent.InstanceID = testInstance + rec.Agent.EngineHealth = EngineHealthHealthy + rec.Agent.Message = "serving" + seedInstance(t, svc, rec) + + before := time.Now().UTC() + _, err := svc.RegisterDBInstance(context.Background(), + &RegisterDBInstanceInput{DBInstanceIdentifier: testDBID, InstanceID: testInstance}, testAccountID) + require.NoError(t, err) + + stored, _ := readRecord(t, svc) + assert.Equal(t, EngineHealthStarting, stored.Agent.EngineHealth, + "a fresh agent has not probed the engine, so it reports nothing about it yet") + assert.Empty(t, stored.Agent.Message) + require.NotNil(t, stored.Agent.StartedAt) + assert.False(t, stored.Agent.StartedAt.Before(before), + "StartedAt must move on every agent start, unlike RegisteredAt") +} + func TestRegisterDBInstance_UnknownInstance(t *testing.T) { t.Parallel() svc := newTestService(t) diff --git a/spinifex/handlers/rds/lifecycle.go b/spinifex/handlers/rds/lifecycle.go index 024fbca67..1dc5bb3ca 100644 --- a/spinifex/handlers/rds/lifecycle.go +++ b/spinifex/handlers/rds/lifecycle.go @@ -38,6 +38,11 @@ type instanceCommander interface { // only be changed through the stopped-instance path. var ErrInstanceNotOnNode = errors.New("rds: no node is holding this DB VM") +// The owning node refused the command because the VM is not in a state for it. +// A stop gets this when something else is already stopping the VM, which is +// where the stop was going, so only the fleet view settles it. +var ErrInstanceStateRefused = errors.New("rds: the DB VM is not in a state for this command") + // How long a VM stop, start or reboot may take before the command is treated as // lost. A stop drains and seals the data volume, which is the long pole. const instanceCommandTimeout = 90 * time.Second @@ -159,8 +164,10 @@ func (s *Service) stopInstanceVM(ctx context.Context, accountID, instanceID stri err := s.deps.Instances.StopInstance(ctx, instanceID) // A command no node answered usually means the VM is already down, which is // where the stop was going anyway; a command a node accepted says nothing - // about the VM yet. Both are settled by the same fleet-wide wait. - if err != nil && !errors.Is(err, ErrInstanceNotOnNode) { + // about the VM yet. A refused one means another driver — the reconciler + // resuming this same stop — got there first, which is also where it was + // going. All three are settled by the same fleet-wide wait. + if err != nil && !errors.Is(err, ErrInstanceNotOnNode) && !errors.Is(err, ErrInstanceStateRefused) { return err } return s.waitForVMStopped(ctx, accountID, instanceID) @@ -433,6 +440,9 @@ func (c *natsInstanceCommander) send(ctx context.Context, instanceID string, att strings.Contains(err.Error(), awserrors.ErrorInvalidInstanceIDNotFound) { return fmt.Errorf("%w: %s", ErrInstanceNotOnNode, instanceID) } + if strings.Contains(err.Error(), awserrors.ErrorIncorrectInstanceState) { + return fmt.Errorf("%w: %s", ErrInstanceStateRefused, instanceID) + } return err } diff --git a/spinifex/handlers/rds/lifecycle_test.go b/spinifex/handlers/rds/lifecycle_test.go index 5e73460ff..e4c1ec503 100644 --- a/spinifex/handlers/rds/lifecycle_test.go +++ b/spinifex/handlers/rds/lifecycle_test.go @@ -45,7 +45,10 @@ type fakeInstanceCommander struct { // stopNotOnNode is the same for a stop, which then has to confirm the VM is // really down rather than assume it. stopNotOnNode bool - err error + // stopRefused models the node answering that the VM is not in a state to be + // stopped, which is what the loser of two concurrent stops is told. + stopRefused bool + err error // The VM state an accepted stop takes down. Nil models a node that accepts // the command and never lands it. vm *fakeInstanceState @@ -58,6 +61,9 @@ func (f *fakeInstanceCommander) StopInstance(_ context.Context, instanceID strin if f.stopNotOnNode { return ErrInstanceNotOnNode } + if f.stopRefused { + return ErrInstanceStateRefused + } if f.err != nil { return f.err } @@ -443,6 +449,43 @@ func TestStopDBInstance_FailsWhenNoNodeAnsweredButTheVMIsStillRunning(t *testing assert.Contains(t, rec.FailureReason, `"running", not stopped`) } +// Two things drive a stop: the caller and the reconciler resuming one whose +// caller it assumes has died. The loser is told the VM is not in a state to be +// stopped — which is the state the stop was heading for — so reporting that to +// the customer fails a stop that in fact happened. +func TestStopDBInstance_SucceedsWhenAnotherDriverAlreadyStoppedTheVM(t *testing.T) { + t.Parallel() + h := newLifecycleHarness(t, false) + h.cmdr.stopRefused = true + h.vmState.state = "stopped" + seedInstance(t, h.svc, availableRecord()) + + out, err := h.svc.StopDBInstance(t.Context(), + &rds.StopDBInstanceInput{DBInstanceIdentifier: aws.String(testDBID)}, testAccountID) + require.NoError(t, err) + + assert.Equal(t, string(StatusStopped), aws.StringValue(out.DBInstance.DBInstanceStatus)) + assert.Equal(t, StatusStopped, h.record(t).Status) +} + +// The refusal still says nothing about the VM. A node that refuses the command +// while the VM keeps running must not be read as the stop having landed. +func TestStopDBInstance_FailsWhenARefusedCommandLeavesTheVMRunning(t *testing.T) { + t.Parallel() + h := newLifecycleHarness(t, false) + h.cmdr.stopRefused = true + h.vmState.state = instanceStateRunning + seedInstance(t, h.svc, availableRecord()) + + _, err := h.svc.StopDBInstance(t.Context(), + &rds.StopDBInstanceInput{DBInstanceIdentifier: aws.String(testDBID)}, testAccountID) + require.Error(t, err) + + rec := h.record(t) + assert.Equal(t, StatusFailed, rec.Status) + assert.Contains(t, rec.FailureReason, `"running", not stopped`) +} + // The same unanswered command is the normal shape of a VM that is genuinely // down, and that stop has to converge rather than fail. func TestStopDBInstance_CompletesWhenTheFleetConfirmsTheVMIsDown(t *testing.T) { @@ -513,6 +556,25 @@ func TestReconciler_DoesNotCallAStillRunningVMStopped(t *testing.T) { assert.Equal(t, StatusStopping, h.record(t).Status) } +// The caller the pass assumed had died is alive and already stopping the VM, so +// the reconciler's own command is refused. Retrying that until the bound would +// fail an instance whose stop is landing. +func TestReconciler_ResumesAStopTheLiveCallerIsAlreadyDriving(t *testing.T) { + t.Parallel() + h := newLifecycleHarness(t, false) + h.cmdr.stopRefused = true + h.vmState.state = "stopped" + rec := availableRecord() + rec.Status = StatusStopping + started := time.Now().UTC() + rec.TransitionStartedAt = &started + seedInstance(t, h.svc, rec) + + require.NoError(t, onePass(t, NewReconciler(h.svc, "node-a"))) + + assert.Equal(t, StatusStopped, h.record(t).Status) +} + // The data volume, the customer ENI and the DNS record are all retained, // so a start comes back on the same datadir at the same address. func TestStopDBInstance_RetainsTheEndpointAndTheVolume(t *testing.T) { @@ -714,6 +776,31 @@ func TestReconciler_IgnoresAHeartbeatPredatingTheRestart(t *testing.T) { assert.Equal(t, StatusRebooting, h.record(t).Status) } +// The engine is stopped before the VM is rebooted, so a beat can still land in +// between and report the engine that is on its way out. Only the agent process +// registering again proves the restart happened. +func TestReconciler_IgnoresAHeartbeatFromTheAgentTheRestartReplaces(t *testing.T) { + t.Parallel() + h := newLifecycleHarness(t, false) + now := time.Now().UTC() + started := now.Add(-time.Minute) + rec := restartingRecord(StatusRebooting, started, now) + predecessor := started.Add(-time.Hour) + rec.Agent.StartedAt = &predecessor + seedInstance(t, h.svc, rec) + + require.NoError(t, onePass(t, NewReconciler(h.svc, "node-a"))) + assert.Equal(t, StatusRebooting, h.record(t).Status) + + restarted := started.Add(time.Second) + rec = h.record(t) + rec.Agent.StartedAt = &restarted + seedInstance(t, h.svc, rec) + + require.NoError(t, onePass(t, NewReconciler(h.svc, "node-a"))) + assert.Equal(t, StatusAvailable, h.record(t).Status) +} + // A restart that never comes back has to end somewhere: the customer sees a // broken instance either way, and failed is the state they can act on. func TestReconciler_MarksFailedWhenARestartOverrunsItsBound(t *testing.T) { @@ -730,6 +817,25 @@ func TestReconciler_MarksFailedWhenARestartOverrunsItsBound(t *testing.T) { assert.Contains(t, rec.FailureReason, "did not report healthy") } +// The bound says only that the engine never came back. What the agent last +// reported says why, and a restart is the case where it is a parameter the +// engine refused — which the customer has to change to get the instance back. +func TestReconciler_CarriesTheAgentsReasonIntoAFailedRestart(t *testing.T) { + t.Parallel() + h := newLifecycleHarness(t, false) + started := time.Now().UTC().Add(-2 * transitionTimeout) + rec := restartingRecord(StatusRebooting, started, started.Add(-time.Minute)) + rec.Agent.Message = `engine did not respond on /run/postgresql:5432; the engine's log ends: ` + + `FATAL: invalid value for parameter "max_connections"` + seedInstance(t, h.svc, rec) + + require.NoError(t, onePass(t, NewReconciler(h.svc, "node-a"))) + + stored := h.record(t) + assert.Equal(t, StatusFailed, stored.Status) + assert.Contains(t, stored.FailureReason, `invalid value for parameter "max_connections"`) +} + // What the next start recovers is the engine's own guarantee. Telling a MariaDB // customer a write-ahead log will bring back an Aria or MyISAM table would be a // false assurance about exactly the data most at risk. diff --git a/spinifex/handlers/rds/reconciler.go b/spinifex/handlers/rds/reconciler.go index 537bd7fc6..f2139a8b2 100644 --- a/spinifex/handlers/rds/reconciler.go +++ b/spinifex/handlers/rds/reconciler.go @@ -466,15 +466,22 @@ func (r *Reconciler) reconcileCreating(ctx context.Context, kv jetstream.KeyValu } timeout := r.svc.bootstrapTimeout() if time.Since(rec.CreatedAt) > timeout { - reason := fmt.Sprintf("the database engine did not report healthy within %s of creation", timeout) - if rec.Agent.Message != "" { - reason += ": " + rec.Agent.Message - } - return r.transition(ctx, kv, rev, rec, StatusFailed, reason) + return r.transition(ctx, kv, rev, rec, StatusFailed, withAgentReason(rec, + fmt.Sprintf("the database engine did not report healthy within %s of creation", timeout))) } return nil } +// The bound says only that the engine never arrived. The agent's last message +// says why — a postmaster's own refusal, quoted out of a guest with no other +// way to report one — and it is the half a customer can act on. +func withAgentReason(rec *DBInstanceRecord, reason string) string { + if rec.Agent.Message == "" { + return reason + } + return reason + ": " + rec.Agent.Message +} + // Reboot and start both end the same way: the engine comes back and says so. // The API call that began them returns before that happens, so this is what // actually lands the instance in available. @@ -487,12 +494,19 @@ func (r *Reconciler) reconcileRestarting(ctx context.Context, kv jetstream.KeyVa if err != nil { return err } + // A beat can land between the transition starting and the VM actually going + // down, and the engine it reports on is the one being replaced. The agent + // process registering again is the event that separates the two; a record + // written before agents reported it carries none, and keeps the old rule. + if agentStarted := rec.Agent.StartedAt; healthy && agentStarted != nil && !agentStarted.After(started) { + healthy = false + } if healthy { return r.transition(ctx, kv, rev, rec, StatusAvailable, "") } if time.Since(started) > transitionTimeout { - return r.transition(ctx, kv, rev, rec, StatusFailed, - fmt.Sprintf("the database engine did not report healthy within %s of %s", transitionTimeout, rec.Status)) + return r.transition(ctx, kv, rev, rec, StatusFailed, withAgentReason(rec, + fmt.Sprintf("the database engine did not report healthy within %s of %s", transitionTimeout, rec.Status))) } return nil } @@ -550,8 +564,8 @@ func (r *Reconciler) reconcileModifying(ctx context.Context, kv jetstream.KeyVal } if !healthy { if overrun { - return r.transition(ctx, kv, rev, rec, StatusFailed, - fmt.Sprintf("the database engine did not report healthy within %s of the modification", transitionTimeout)) + return r.transition(ctx, kv, rev, rec, StatusFailed, withAgentReason(rec, + fmt.Sprintf("the database engine did not report healthy within %s of the modification", transitionTimeout))) } return nil } @@ -581,7 +595,10 @@ func (r *Reconciler) reconcileStopping(ctx context.Context, kv jetstream.KeyValu return errors.New("rds reconciler: no instance command path configured") } err := r.svc.deps.Instances.StopInstance(ctx, rec.InstanceID) - if errors.Is(err, ErrInstanceNotOnNode) { + // Refused is the mirror of not-held: the caller this pass assumed had died is + // alive and already stopping the VM. Neither says where the VM got to, so both + // hand the answer to the fleet rather than treating the command as the truth. + if errors.Is(err, ErrInstanceNotOnNode) || errors.Is(err, ErrInstanceStateRefused) { err = r.svc.confirmVMStopped(ctx, accountID, rec.InstanceID) } if err == nil { diff --git a/spinifex/handlers/rds/records.go b/spinifex/handlers/rds/records.go index c8e46776f..b2c1a32ea 100644 --- a/spinifex/handlers/rds/records.go +++ b/spinifex/handlers/rds/records.go @@ -476,6 +476,10 @@ type AgentState struct { EngineHealth EngineHealth `json:"engineHealth,omitempty"` Message string `json:"message,omitempty"` RegisteredAt *time.Time `json:"registeredAt,omitempty"` + // When the agent process now reporting registered. Unlike RegisteredAt it + // moves on every agent start, so it is what proves a restart happened + // rather than that the VM was already up. + StartedAt *time.Time `json:"startedAt,omitempty"` // The last *persisted* beat. Beats in between are held in leader memory, so // this trails the truth by up to the persist floor. LastSeen *time.Time `json:"lastSeen,omitempty"` diff --git a/spinifex/network/host/eip_ingress.go b/spinifex/network/host/eip_ingress.go index 09ad9c84c..ed3fff973 100644 --- a/spinifex/network/host/eip_ingress.go +++ b/spinifex/network/host/eip_ingress.go @@ -129,6 +129,37 @@ func EnsureEIPIngress(ctx context.Context, r Runner, eip, gwLrpIP, poolGateway, return nil } +// ListEIPIngress returns the EIPs this host currently plumbs, read back from +// the FORWARD rules EnsureEIPIngress stamps with its own comment. The OVN NAT +// row is not a record of host state — it can be deleted by a path that never +// touches the route — so the sweep needs the host's own inventory. +func ListEIPIngress(ctx context.Context, r Runner) ([]string, error) { + out, err := r.Run(ctx, "iptables", "-t", "filter", "-S", "FORWARD") + if err != nil { + return nil, fmt.Errorf("list FORWARD rules: %s: %w", string(out), err) + } + seen := make(map[string]struct{}) + eips := make([]string, 0, 4) + for line := range strings.SplitSeq(string(out), "\n") { + if !strings.Contains(line, "--comment "+eipIngressComment) { + continue + } + fields := strings.Fields(line) + for i := 0; i < len(fields)-1; i++ { + if fields[i] != "-s" && fields[i] != "-d" { + continue + } + eip := strings.TrimSuffix(fields[i+1], "/32") + if _, dup := seen[eip]; dup { + continue + } + seen[eip] = struct{}{} + eips = append(eips, eip) + } + } + return eips, nil +} + // RemoveEIPIngress tears down the host state for an EIP on disassociate or // release. Missing pieces are not errors (idempotent teardown); the proxy // neighbor is removed from whatever uplink currently faces the pool. diff --git a/spinifex/network/host/eip_ingress_test.go b/spinifex/network/host/eip_ingress_test.go index 4a01cbfa4..2281c9cb1 100644 --- a/spinifex/network/host/eip_ingress_test.go +++ b/spinifex/network/host/eip_ingress_test.go @@ -195,3 +195,34 @@ func TestRemoveEIPIngress_MissingStateNotError(t *testing.T) { t.Fatalf("missing state must not be an error, got: %v", err) } } + +// iptables -S renders the two ingress accepts one per direction, so both -s and +// -d carry the EIP and the same address must be reported once. Rules without +// the comment belong to other subsystems and are not ours to sweep. +func TestListEIPIngress(t *testing.T) { + r := newStubRunner() + r.expect("iptables -t filter -S FORWARD", []byte(strings.Join([]string{ + "-P FORWARD DROP", + "-A FORWARD -i spx-nat-host -s 192.168.0.53/32 -m comment --comment spinifex-eip-ingress -j ACCEPT", + "-A FORWARD -o spx-nat-host -d 192.168.0.53/32 -m comment --comment spinifex-eip-ingress -j ACCEPT", + "-A FORWARD -o spx-nat-host -d 192.168.0.52/32 -m comment --comment spinifex-eip-ingress -j ACCEPT", + "-A FORWARD -s 10.0.0.0/8 -j ACCEPT", + }, "\n")), nil) + + got, err := ListEIPIngress(context.Background(), r) + if err != nil { + t.Fatalf("ListEIPIngress: %v", err) + } + want := []string{"192.168.0.53", "192.168.0.52"} + if strings.Join(got, ",") != strings.Join(want, ",") { + t.Fatalf("ListEIPIngress = %v, want %v", got, want) + } +} + +func TestListEIPIngress_ErrorSurfaces(t *testing.T) { + r := newStubRunner() + r.expect("iptables -t filter -S FORWARD", []byte("permission denied"), fmt.Errorf("exit 4")) + if _, err := ListEIPIngress(context.Background(), r); err == nil { + t.Fatal("expected an error when the inventory cannot be read") + } +} diff --git a/spinifex/network/policy/nat.go b/spinifex/network/policy/nat.go index 4cf8f8d42..714b49f50 100644 --- a/spinifex/network/policy/nat.go +++ b/spinifex/network/policy/nat.go @@ -5,7 +5,9 @@ import ( "errors" "fmt" "log/slog" + "maps" "net/netip" + "slices" "github.com/mulgadc/spinifex/spinifex/network/ovn" "github.com/mulgadc/spinifex/spinifex/network/ovn/nbdb" @@ -35,6 +37,14 @@ type NATGWSpec struct { SubnetCIDR string } +// LiveEIPs is what a prune pass treats as current: the owning ENI port names +// intent still carries, and the external IPs intent still asks for. A +// dnat_and_snat row failing either test is stale and gets swept. +type LiveEIPs struct { + Ports map[string]struct{} + ExternalIPs map[string]struct{} +} + // NATManager owns NAT-rule lifecycle. Mode is fixed at construction. type NATManager interface { // AddEIP installs a dnat_and_snat rule, cleaning stale rules for the @@ -49,12 +59,12 @@ type NATManager interface { // identically. Idempotent. DeleteEIP(ctx context.Context, vpcID, externalIP, logicalIP, portName string) error - // PruneOrphanEIPs deletes every dnat_and_snat row whose stamped - // spinifex:logical_port owning ENI is absent from livePorts (the set of live - // intent port names), flushing the host ARP entry and unbinding routed-mode + // PruneOrphanEIPs deletes every dnat_and_snat row that live no longer + // accounts for — its owning ENI is gone, or its external IP is one intent no + // longer asks for — flushing the host ARP entry and unbinding routed-mode // host state for each. Rows with no stamped logical port are left untouched // (owner undeterminable). Returns the number of rows removed. - PruneOrphanEIPs(ctx context.Context, livePorts map[string]struct{}) (int, error) + PruneOrphanEIPs(ctx context.Context, live LiveEIPs) (int, error) // AddNATGateway installs the (snat, SubnetCIDR) rule; rejects overlap. AddNATGateway(ctx context.Context, gw NATGWSpec) error @@ -127,10 +137,13 @@ func WithNeighPrimer(p NeighPrimer) Option { // HostEIPBinder plumbs routed-mode host state for an EIP: the /32 route into // OVN via the gateway LRP and proxy-ARP on the uplink. Bind fires on every // AddEIP (fresh and idempotent) so reconcile re-ensures host state after -// reboot; Unbind fires on DeleteEIP. +// reboot; Unbind fires on DeleteEIP. List reads back what is plumbed now, so a +// prune can find bindings whose NAT row has already gone; leaving it nil skips +// the host sweep. type HostEIPBinder struct { Bind func(eip EIPSpec, gwLrpIP string) error Unbind func(externalIP string) error + List func() ([]string, error) } // WithHostEIPBinder injects the routed-mode host plumbing hooks fired on EIP @@ -292,10 +305,22 @@ func (m *natManager) AddEIP(ctx context.Context, eip EIPSpec) error { // Scrub any predecessor row sharing this private IP under a different external // IP: dnat_and_snat is 1:1 per private IP, and a stale row's SNAT half (keyed on // logical_ip) blackholes the new EIP. Router-scoped — private IPs repeat per VPC. + // Read it first: dropping the row unnoticed strands the predecessor's host + // route and proxy-ARP, and no later sweep can find them without the row. + predecessor, err := m.ovn.FindNATByLogicalIP(ctx, router, "dnat_and_snat", eip.LogicalIP) + if err != nil { + slog.Warn("policy: predecessor NAT lookup failed before AddEIP", + "logical_ip", eip.LogicalIP, "err", err) + } if err := m.ovn.DeleteNAT(ctx, router, "dnat_and_snat", eip.LogicalIP); err != nil && !errors.Is(err, ovn.ErrNATNotFound) { slog.Warn("policy: stale logical-IP NAT cleanup failed before AddEIP", "logical_ip", eip.LogicalIP, "err", err) + } else if predecessor != nil && predecessor.ExternalIP != eip.ExternalIP { + m.releaseHostEIP(predecessor.ExternalIP, "external IP replaced on the same private IP") + slog.Info("policy: released predecessor host EIP before AddEIP", + "old_external_ip", predecessor.ExternalIP, "new_external_ip", eip.ExternalIP, + "logical_ip", eip.LogicalIP) } if err := m.ovn.AddNAT(ctx, router, natRule); err != nil { @@ -437,7 +462,7 @@ func (m *natManager) DeleteEIP(ctx context.Context, vpcID, externalIP, logicalIP return nil } -func (m *natManager) PruneOrphanEIPs(ctx context.Context, livePorts map[string]struct{}) (int, error) { +func (m *natManager) PruneOrphanEIPs(ctx context.Context, live LiveEIPs) (int, error) { nats, err := m.ovn.ListNATs(ctx) if err != nil { return 0, fmt.Errorf("list NATs for orphan EIP prune: %w", err) @@ -454,33 +479,79 @@ func (m *natManager) PruneOrphanEIPs(ctx context.Context, livePorts map[string]s if port == "" { continue } - if _, live := livePorts[port]; live { + _, portLive := live.Ports[port] + _, ipWanted := live.ExternalIPs[n.ExternalIP] + if portLive && ipWanted { continue } + // A disassociate leaves the ENI running, so the owner test alone never + // fires and a lost vpc.delete-nat leaks the row and its host /32 route. + reason := "owning ENI absent from intent" + if portLive { + reason = "external IP no longer in intent" + } removed, derr := m.ovn.DeleteAllNATsByExternalIP(ctx, "dnat_and_snat", n.ExternalIP) if derr != nil { slog.Warn("policy: orphan EIP prune delete failed", "external_ip", n.ExternalIP, "logical_port", port, "err", derr) continue } - if removed == 0 { + pruned += removed + // Runs even when the row had already gone: that is the state a crash + // between the OVN delete and the unbind leaves behind. + m.releaseHostEIP(n.ExternalIP, reason) + slog.Info("policy: pruned stale dnat_and_snat", + "reason", reason, "external_ip", n.ExternalIP, "logical_ip", n.LogicalIP, + "logical_port", port, "rows_removed", removed) + } + return pruned, m.pruneHostEIPs(live) +} + +// pruneHostEIPs removes host plumbing for every external IP intent no longer +// asks for. The NAT row is not the record of that plumbing — AddEIP's +// predecessor scrub, a lost teardown or a crash mid-delete each leave a route +// and its proxy-ARP behind with no row left to find them by. +func (m *natManager) pruneHostEIPs(live LiveEIPs) error { + if m.mode != NATModeRouted || m.hostBinder == nil || m.hostBinder.List == nil { + return nil + } + bound, err := m.hostBinder.List() + if err != nil { + return fmt.Errorf("list host EIP bindings for prune: %w", err) + } + kept := make([]string, 0, len(bound)) + for _, eip := range bound { + if _, wanted := live.ExternalIPs[eip]; wanted { + kept = append(kept, eip) continue } - pruned += removed - // Flush host ARP so the freed external IP is not shadowed by the dead - // owner's MAC, and tear down routed-mode host plumbing. Best-effort. - if err := m.neigh(n.ExternalIP); err != nil { - slog.Warn("policy: orphan EIP prune neighbour flush failed", "external_ip", n.ExternalIP, "err", err) - } - if m.mode == NATModeRouted && m.hostBinder != nil { - if err := m.hostBinder.Unbind(n.ExternalIP); err != nil { - slog.Warn("policy: orphan EIP prune host unbind failed", "external_ip", n.ExternalIP, "err", err) - } - } - slog.Info("policy: pruned orphan dnat_and_snat — owning ENI absent from intent", - "external_ip", n.ExternalIP, "logical_ip", n.LogicalIP, "logical_port", port) + m.releaseHostEIP(eip, "host binding for an external IP absent from intent") + slog.Info("policy: pruned stale host EIP ingress", "external_ip", eip) + } + // The keep decision was silent, so a route that outlived its address could not + // be told from one the sweep never saw. Both sides are logged now. + if len(bound) > 0 { + slog.Info("policy: host EIP prune considered bindings", + "bound", bound, "kept", kept, "wanted", slices.Sorted(maps.Keys(live.ExternalIPs))) + } + return nil +} + +// releaseHostEIP tears down the host state an external IP no longer warrants: +// the ARP entry that would shadow a recycled address, and the routed-mode /32 +// route and proxy-ARP. Best-effort — a failure is a leak the next pass sweeps. +func (m *natManager) releaseHostEIP(externalIP, reason string) { + if err := m.neigh(externalIP); err != nil { + slog.Warn("policy: host EIP neighbour flush failed", + "external_ip", externalIP, "reason", reason, "err", err) + } + if m.mode != NATModeRouted || m.hostBinder == nil { + return + } + if err := m.hostBinder.Unbind(externalIP); err != nil { + slog.Warn("policy: host EIP unbind failed", + "external_ip", externalIP, "reason", reason, "err", err) } - return pruned, nil } func (m *natManager) AddNATGateway(ctx context.Context, gw NATGWSpec) error { diff --git a/spinifex/network/policy/nat_test.go b/spinifex/network/policy/nat_test.go index c1d5eb061..53827ec1c 100644 --- a/spinifex/network/policy/nat_test.go +++ b/spinifex/network/policy/nat_test.go @@ -2,6 +2,7 @@ package policy import ( "context" + "errors" "testing" "github.com/stretchr/testify/assert" @@ -488,7 +489,10 @@ func TestNATManager_PruneOrphanEIPs(t *testing.T) { ExternalIDs: map[string]string{"spinifex:logical_port": "port-eni-gone"}, })) - live := map[string]struct{}{"port-eni-live": {}} + live := LiveEIPs{ + Ports: map[string]struct{}{"port-eni-live": {}}, + ExternalIPs: map[string]struct{}{"192.168.1.10": {}}, + } pruned, err := nm.PruneOrphanEIPs(ctx, live) require.NoError(t, err) assert.Equal(t, 1, pruned, "exactly the stamped orphan dnat_and_snat must be pruned") @@ -500,6 +504,106 @@ func TestNATManager_PruneOrphanEIPs(t *testing.T) { assert.Contains(t, flushed, "192.168.1.11", "orphan external IP ARP must be flushed on prune") } +// A released address whose ENI is still running fails only the external-IP test. +// The row and, in routed mode, the host /32 route must both go — this is the state +// a lost vpc.delete-nat leaves after a disassociate. +func TestNATManager_PruneOrphanEIPs_ReleasedAddressUnbindsHost(t *testing.T) { + ctx := context.Background() + m := mock.New() + seedRouter(t, m, "vpc-live") + var unbound []string + nm, err := NewNATManager(m, NATModeRouted, WithHostEIPBinder(HostEIPBinder{ + Bind: func(EIPSpec, string) error { return nil }, + Unbind: func(ip string) error { unbound = append(unbound, ip); return nil }, + })) + require.NoError(t, err) + + require.NoError(t, m.AddNAT(ctx, topology.VPCRouter("vpc-live"), &nbdb.NAT{ + Type: "dnat_and_snat", ExternalIP: "192.168.0.43", LogicalIP: "10.0.1.10", + ExternalIDs: map[string]string{"spinifex:logical_port": "port-eni-live"}, + })) + + // The ENI is live; only the address is gone from intent. + pruned, err := nm.PruneOrphanEIPs(ctx, LiveEIPs{ + Ports: map[string]struct{}{"port-eni-live": {}}, + ExternalIPs: map[string]struct{}{}, + }) + require.NoError(t, err) + assert.Equal(t, 1, pruned) + assert.Nil(t, findNAT(m, "dnat_and_snat", "10.0.1.10"), "released address row must be pruned") + assert.Contains(t, unbound, "192.168.0.43", "host /32 route for a released address must be unbound") +} + +// The NAT row is not the record of host plumbing. AddEIP's predecessor scrub +// deletes the row for the address it replaces, so a sweep that only walks rows +// cannot see the route that address left behind — the host's own inventory can. +func TestNATManager_PruneOrphanEIPs_SweepsHostBindingWithNoRow(t *testing.T) { + ctx := context.Background() + m := mock.New() + seedRouter(t, m, "vpc-live") + var unbound []string + nm, err := NewNATManager(m, NATModeRouted, WithHostEIPBinder(HostEIPBinder{ + Bind: func(EIPSpec, string) error { return nil }, + Unbind: func(ip string) error { unbound = append(unbound, ip); return nil }, + List: func() ([]string, error) { return []string{"192.168.0.52", "192.168.0.53"}, nil }, + })) + require.NoError(t, err) + + pruned, err := nm.PruneOrphanEIPs(ctx, LiveEIPs{ + Ports: map[string]struct{}{"port-eni-live": {}}, + ExternalIPs: map[string]struct{}{"192.168.0.52": {}}, + }) + require.NoError(t, err) + assert.Equal(t, 0, pruned, "no row existed to prune") + assert.Equal(t, []string{"192.168.0.53"}, unbound, + "only the binding intent no longer asks for must be swept") +} + +// A failed inventory must fail the pass rather than read as a clean sweep: +// an empty list is indistinguishable from "nothing is plumbed". +func TestNATManager_PruneOrphanEIPs_HostInventoryErrorSurfaces(t *testing.T) { + ctx := context.Background() + m := mock.New() + nm, err := NewNATManager(m, NATModeRouted, WithHostEIPBinder(HostEIPBinder{ + Bind: func(EIPSpec, string) error { return nil }, + Unbind: func(string) error { return nil }, + List: func() ([]string, error) { return nil, errors.New("iptables unavailable") }, + })) + require.NoError(t, err) + + _, err = nm.PruneOrphanEIPs(ctx, LiveEIPs{}) + require.Error(t, err) +} + +// Replacing the address on a private IP drops the predecessor's row, so the +// unbind has to happen here — after this returns there is nothing left to find +// the stranded route by. +func TestNATManager_AddEIP_ReleasesReplacedAddressHostState(t *testing.T) { + ctx := context.Background() + m := mock.New() + seedRouter(t, m, "vpc-1") + seedGatewayPortIP(t, m, "vpc-1", "100.127.0.10", nil) + var unbound []string + nm, err := NewNATManager(m, NATModeRouted, WithHostEIPBinder(HostEIPBinder{ + Bind: func(EIPSpec, string) error { return nil }, + Unbind: func(ip string) error { unbound = append(unbound, ip); return nil }, + })) + require.NoError(t, err) + + base := EIPSpec{VPCID: "vpc-1", LogicalIP: "10.0.1.10", PortName: "port-eni-a", MAC: "02:00:00:00:00:01"} + auto := base + auto.ExternalIP = "192.168.0.52" + require.NoError(t, nm.AddEIP(ctx, auto)) + + user := base + user.ExternalIP = "192.168.0.53" + require.NoError(t, nm.AddEIP(ctx, user)) + + assert.Equal(t, []string{"192.168.0.52"}, unbound, + "the replaced address must lose its host plumbing when its row is scrubbed") + assert.NotNil(t, findNAT(m, "dnat_and_snat", "10.0.1.10"), "the new EIP row must be installed") +} + func TestNATManager_DeleteEIP_IdempotentOnMissing(t *testing.T) { ctx := context.Background() m := mock.New() diff --git a/spinifex/network/reconcile/apply.go b/spinifex/network/reconcile/apply.go index 335e5c8bd..104a8e2ea 100644 --- a/spinifex/network/reconcile/apply.go +++ b/spinifex/network/reconcile/apply.go @@ -753,12 +753,18 @@ func (r *reconciler) floatingIPSpecs(intent IntentState) []policy.EIPSpec { return specs } -// pruneOrphanEIPs sweeps dnat_and_snat rows whose stamped owning ENI is gone from -// intent. vpc.delete-nat is fire-and-forget and can be lost, leaking rows across -// dead VPCs; NATManager.PruneOrphanEIPs deletes any row whose spinifex:logical_port -// is absent from the live-port set. The live set is keyed the same way -// floatingIPSpecs derives PortName (topology.Port(p.PortID) for auto-assigned ports, -// e.PortName for user EIPs), so a currently-live auto-assigned EIP is never pruned. +// pruneOrphanEIPs sweeps dnat_and_snat rows intent no longer accounts for. +// vpc.delete-nat is fire-and-forget and can be lost, so a row survives its own +// teardown in two shapes: the whole ENI went away (VPC torn down, instance +// terminated), or the ENI is still running and only the address was released. +// The owner set catches the first; the external-IP set catches the second, which +// a live-port test alone can never see — a disassociate is exactly the case where +// the port stays live. AddEIP is the sole writer of dnat_and_snat, so +// floatingIPSpecs is the complete set of addresses that may legitimately hold one. +// +// Ports are keyed the same way floatingIPSpecs derives PortName +// (topology.Port(p.PortID) for auto-assigned ports, e.PortName for user EIPs), so a +// currently-live auto-assigned EIP is never pruned. // // PruneOrphanEIPs lists OVN NAT rows live, but the intent handed to a prune pass is // snapshotted at the start of the pass and the apply phase can block for tens of @@ -766,19 +772,21 @@ func (r *reconciler) floatingIPSpecs(intent IntentState) []policy.EIPSpec { // live dnat_and_snat row — created synchronously at launch — that the stale snapshot // does not carry, so matching live rows against the snapshot alone sweeps the fresh // row and blackholes the guest's public IP. Re-read intent (when a loader is wired) -// and union its ports into the live set so a mid-pass launch counts as live; skip the -// prune entirely if the re-read fails rather than risk a false sweep against a snapshot -// known to be stale. +// and union it in so a mid-pass launch counts as live; skip the prune entirely if the +// re-read fails rather than risk a false sweep against a snapshot known to be stale. func (r *reconciler) pruneOrphanEIPs(ctx context.Context, intent IntentState, res *passResult) { - live := make(map[string]struct{}, len(intent.Ports)+len(intent.EIPs)) - addLivePorts(live, intent) + live := policy.LiveEIPs{ + Ports: make(map[string]struct{}, len(intent.Ports)+len(intent.EIPs)), + ExternalIPs: make(map[string]struct{}, len(intent.Ports)+len(intent.EIPs)), + } + r.addLive(live, intent) fresh, err := r.reloadForPrune(ctx) if err != nil { slog.Warn("reconcile/apply: fresh intent re-read failed; skipping orphan EIP prune", "err", err) res.fail(classEIP, "orphan-prune", err) return } - addLivePorts(live, fresh) + r.addLive(live, fresh) if pruned, err := r.nat.PruneOrphanEIPs(ctx, live); err != nil { slog.Warn("reconcile/apply: orphan EIP prune failed", "err", err) res.fail(classEIP, "orphan-prune", err) @@ -787,19 +795,23 @@ func (r *reconciler) pruneOrphanEIPs(ctx context.Context, intent IntentState, re } } -// addLivePorts adds intent's owning-port names — auto-assigned/ELB ports keyed as -// topology.Port(portID), user EIP ports by their stamped PortName — to live. Keyed -// identically to floatingIPSpecs and the dnat_and_snat spinifex:logical_port stamp so -// the orphan prune matches a live row to its owner. -func addLivePorts(live map[string]struct{}, intent IntentState) { +// addLive unions intent into the prune's live set: every owning-port name — +// auto-assigned/ELB ports keyed as topology.Port(portID), user EIP ports by their +// stamped PortName — and every external IP floatingIPSpecs would install. Keyed +// identically to the dnat_and_snat spinifex:logical_port stamp so the prune matches +// a live row to its owner. +func (r *reconciler) addLive(live policy.LiveEIPs, intent IntentState) { for portID := range intent.Ports { - live[topology.Port(portID)] = struct{}{} + live.Ports[topology.Port(portID)] = struct{}{} } for _, e := range intent.EIPs { if e.PortName != "" { - live[e.PortName] = struct{}{} + live.Ports[e.PortName] = struct{}{} } } + for _, spec := range r.floatingIPSpecs(intent) { + live.ExternalIPs[spec.ExternalIP] = struct{}{} + } } // applyPublicInstanceEgress exempts every public-IP instance from its subnet egress diff --git a/spinifex/network/reconcile/apply_test.go b/spinifex/network/reconcile/apply_test.go index e3ae46a32..07f4d1d4b 100644 --- a/spinifex/network/reconcile/apply_test.go +++ b/spinifex/network/reconcile/apply_test.go @@ -251,6 +251,33 @@ func TestReconcile_ApplyOnlyKeepsOrphanPortGroup(t *testing.T) { } } +// The EIP sweep is not gated with the topology sweeps. Startup follows the one +// window where a KV watch and a fire-and-forget vpc.delete-nat both miss a +// teardown, so an apply-only pass that skipped it would leave a released public +// address delivering to a guest until the resync. +func TestReconcile_ApplyOnlyStillPrunesReleasedEIP(t *testing.T) { + rec, m := newTestReconciler(t) + ctx := context.Background() + + router := topology.VPCRouter("vpc-a") + if err := m.CreateLogicalRouter(ctx, &nbdb.LogicalRouter{Name: router}); err != nil { + t.Fatalf("CreateLogicalRouter: %v", err) + } + if err := m.AddNAT(ctx, router, &nbdb.NAT{ + Type: "dnat_and_snat", ExternalIP: "192.168.0.43", LogicalIP: "10.0.1.10", + ExternalIDs: map[string]string{"spinifex:logical_port": topology.Port("eni-a")}, + }); err != nil { + t.Fatalf("AddNAT released: %v", err) + } + + if err := rec.ReconcileApplyOnly(ctx, freshIntent(t)); err != nil { + t.Fatalf("ReconcileApplyOnly: %v", err) + } + if findNATByExternal(m, "dnat_and_snat", "192.168.0.43") != nil { + t.Errorf("startup pass left a dnat_and_snat for an address absent from intent") + } +} + // ReconcileApplyOnly must not prune orphan ENI LSPs on startup (in-flight ports // before subscribers converge); full Reconcile must prune them. func TestReconcile_ApplyOnlyKeepsOrphanLSP(t *testing.T) { @@ -753,6 +780,9 @@ func TestReconcile_PruneOrphanEIPs_SweepsAbsentOwners(t *testing.T) { } intent := freshIntent(t) // Ports has eni-a only + live := intent.Ports["eni-a"] + live.PublicIP = netip.MustParseAddr("192.168.1.10") + intent.Ports["eni-a"] = live r.pruneOrphanEIPs(ctx, intent, &passResult{}) if findNATByExternal(m, "dnat_and_snat", "192.168.1.10") == nil { @@ -763,6 +793,37 @@ func TestReconcile_PruneOrphanEIPs_SweepsAbsentOwners(t *testing.T) { } } +// A disassociate releases the address and leaves the ENI running, so the owning +// port stays live and an owner-keyed prune never fires. When vpc.delete-nat is +// lost — publishing into the window where vpcd is restarting drops it, since the +// topic is fire-and-forget core NATS — the row and its host /32 route to a +// released public IP survive. Intent no longer carries the address, so the prune +// must sweep it on the external-IP test alone. +func TestReconcile_PruneOrphanEIPs_SweepsReleasedAddressOnLivePort(t *testing.T) { + r, m := newTestReconciler(t) + ctx := context.Background() + + router := topology.VPCRouter("vpc-a") + if err := m.CreateLogicalRouter(ctx, &nbdb.LogicalRouter{Name: router}); err != nil { + t.Fatalf("CreateLogicalRouter: %v", err) + } + // eni-a is still running; only its EIP was disassociated. + if err := m.AddNAT(ctx, router, &nbdb.NAT{ + Type: "dnat_and_snat", ExternalIP: "192.168.0.43", LogicalIP: "10.0.1.10", + ExternalIDs: map[string]string{"spinifex:logical_port": topology.Port("eni-a")}, + }); err != nil { + t.Fatalf("AddNAT released: %v", err) + } + + // freshIntent's eni-a carries no PublicIP and EIPs is empty — the state after + // a successful DisassociateAddress. + r.pruneOrphanEIPs(ctx, freshIntent(t), &passResult{}) + + if findNATByExternal(m, "dnat_and_snat", "192.168.0.43") != nil { + t.Errorf("dnat_and_snat for a released address must be pruned even though its ENI is live") + } +} + // A guest launched during a long apply phase has a live dnat_and_snat row that the // start-of-pass snapshot does not carry. When a fresh-intent loader is wired, the // prune must union its ports and spare that row, while still sweeping a genuine orphan. @@ -800,6 +861,7 @@ func TestReconcile_PruneOrphanEIPs_SparesMidPassLaunch(t *testing.T) { fresh.Ports["eni-fresh"] = topology.PortSpec{ PortID: "eni-fresh", SubnetID: "subnet-a", VPCID: "vpc-a", PrivateIP: netip.MustParseAddr("10.0.1.20"), + PublicIP: netip.MustParseAddr("192.168.1.20"), } return fresh, nil } diff --git a/spinifex/network/reconcile/reconcile.go b/spinifex/network/reconcile/reconcile.go index b523e83bb..01b1d2c1a 100644 --- a/spinifex/network/reconcile/reconcile.go +++ b/spinifex/network/reconcile/reconcile.go @@ -32,9 +32,12 @@ type Reconciler interface { // Reconcile returns a scan failure as-is, and wraps ErrPassIncomplete when // the scan succeeded but some resources did not converge. Reconcile(ctx context.Context, intent IntentState) error - // ReconcileApplyOnly skips orphan-pruning. Startup uses this to avoid - // racing peer subscribers that haven't processed in-flight create events - // yet; legitimate orphans are pruned on the next drift tick. + // ReconcileApplyOnly skips the port-group and ENI-port orphan sweeps, which + // startup uses to avoid racing peer subscribers that haven't processed + // in-flight create events yet; those orphans are pruned on the next drift + // tick. The EIP sweep still runs: it re-reads intent immediately before + // deciding and abandons the sweep if that read fails, and a stale row there + // is a released public address still delivering traffic. ReconcileApplyOnly(ctx context.Context, intent IntentState) error } @@ -270,7 +273,13 @@ func (r *reconciler) ReconcileApplyOnly(ctx context.Context, intent IntentState) return r.reconcile(ctx, intent, false) } -func (r *reconciler) reconcile(ctx context.Context, intent IntentState, pruneOrphans bool) error { +// reconcile applies intent. pruneTopology gates the port-group and ENI-port +// sweeps only; the EIP sweep runs on every pass, including startup. Startup is +// the pass that follows the window where a KV watch (UpdatesOnly) and a +// fire-and-forget vpc.delete-nat both miss a change, so it is exactly the pass +// that must repair one — and skipping it leaves a released public address still +// delivering to a guest until the resync. +func (r *reconciler) reconcile(ctx context.Context, intent IntentState, pruneTopology bool) error { actual, err := scanActual(ctx, r.ovn) if err != nil { return fmt.Errorf("scan actual OVN state: %w", err) @@ -278,7 +287,7 @@ func (r *reconciler) reconcile(ctx context.Context, intent IntentState, pruneOrp slog.Info("reconcile: starting", "local_az", r.localAZ, - "prune_orphans", pruneOrphans, + "prune_topology", pruneTopology, "intent_vpcs", len(intent.VPCs), "intent_subnets", len(intent.Subnets), "intent_ports", len(intent.Ports), @@ -293,13 +302,11 @@ func (r *reconciler) reconcile(ctx context.Context, intent IntentState, pruneOrp res := &passResult{} r.applyVPCs(ctx, intent, actual, res) r.applySubnets(ctx, intent, actual, res) - r.applySGs(ctx, intent, actual, pruneOrphans, res) - r.applyPorts(ctx, intent, actual, pruneOrphans, res) + r.applySGs(ctx, intent, actual, pruneTopology, res) + r.applyPorts(ctx, intent, actual, pruneTopology, res) r.applyIGWs(ctx, intent, actual, res) r.applyEIPs(ctx, intent, actual, res) - if pruneOrphans { - r.pruneOrphanEIPs(ctx, intent, res) - } + r.pruneOrphanEIPs(ctx, intent, res) r.applyNATGWs(ctx, intent, actual, res) r.applyIGWRoutes(ctx, intent, actual, res) r.applyNATGWRoutes(ctx, intent, actual, res) diff --git a/spinifex/utils/nats.go b/spinifex/utils/nats.go index a76188895..b49acdaba 100644 --- a/spinifex/utils/nats.go +++ b/spinifex/utils/nats.go @@ -688,22 +688,67 @@ func AddNAT(nc *nats.Conn, vpcID, externalIP, logicalIP, portName, mac string) e }, addNATTimeout) } -// PublishNATEvent sends a NAT lifecycle event. vpc.add-nat uses request-reply (prevents ARP races); -// vpc.delete-nat is fire-and-forget. Use AddNAT directly when failure must trigger a rollback. +// deleteNATTimeout bounds the vpc.delete-nat request-reply. The handler deletes +// the OVN row and unbinds host plumbing, each under its own 10 s context, so the +// ceiling is above both. It is a ceiling and not a cost: the reply normally lands +// in milliseconds. +const deleteNATTimeout = 15 * time.Second + +// A teardown published while vpcd is restarting has no subscriber and is dropped +// on the floor, leaving a /32 host route delivering a released address to the +// guest that used to hold it. The gap is short — a restart resubscribes in a few +// hundred milliseconds — so a small bounded retry closes it. Only ErrNoResponders +// is retried, and that returns immediately, so the added latency is bounded by +// the delay and paid only when nothing is listening. +const ( + deleteNATRetries = 3 + deleteNATRetryDelay = 500 * time.Millisecond +) + +// PublishNATEvent sends a NAT lifecycle event. Both topics use request-reply: +// vpc.add-nat to prevent ARP races, vpc.delete-nat so an undelivered teardown is +// reported rather than lost. Neither is fatal to the caller — the reconciler's +// orphan sweep is the backstop. Use AddNAT directly when failure must trigger a +// rollback. func PublishNATEvent(nc *nats.Conn, topic, vpcID, externalIP, logicalIP, portName, mac string) { evt := natEvent{ VpcId: vpcID, ExternalIP: externalIP, LogicalIP: logicalIP, PortName: portName, MAC: mac, } - if topic == "vpc.add-nat" { + switch topic { + case "vpc.add-nat": if err := RequestEvent(nc, topic, evt, addNATTimeout); err != nil { slog.Warn("PublishNATEvent: failed to add NAT rule — OVN dnat_and_snat rule not created; restart vpcd or re-associate EIP to recover", "topic", topic, "externalIP", externalIP, "logicalIP", logicalIP, "err", err) } - return + case "vpc.delete-nat": + if err := deleteNAT(nc, evt); err != nil { + slog.Error("PublishNATEvent: failed to delete NAT rule — the host route and proxy-ARP for this address may still deliver to its old guest; the reconciler's orphan sweep is the remaining repair", + "topic", topic, "externalIP", externalIP, "logicalIP", logicalIP, "err", err) + } + default: + PublishEvent(nc, topic, evt) } - PublishEvent(nc, topic, evt) +} + +// deleteNAT requests the teardown, retrying only while nothing is subscribed. +func deleteNAT(nc *nats.Conn, evt natEvent) error { + var err error + for attempt := range deleteNATRetries { + if attempt > 0 { + time.Sleep(deleteNATRetryDelay) + } + if err = RequestEvent(nc, "vpc.delete-nat", evt, deleteNATTimeout); err == nil { + return nil + } + if !errors.Is(err, nats.ErrNoResponders) { + return err + } + slog.Warn("vpc.delete-nat has no subscriber; retrying", + "externalIP", evt.ExternalIP, "attempt", attempt+1, "attempts", deleteNATRetries) + } + return err } // RequestEvent marshals event as JSON and sends a synchronous NATS request, blocking until the subscriber acks. diff --git a/spinifex/utils/nats_test.go b/spinifex/utils/nats_test.go index 631796eed..32676dbff 100644 --- a/spinifex/utils/nats_test.go +++ b/spinifex/utils/nats_test.go @@ -1309,3 +1309,52 @@ func TestGather_ResponderGrace_ZeroKeepsTheFullDeadline(t *testing.T) { assert.True(t, sum.TimedOut) assert.False(t, sum.SettledEarly) } + +// A teardown published into the gap where vpcd has unsubscribed but its +// replacement has not yet subscribed must be retried, not dropped: the address +// is released while its host route still delivers to the guest that held it. +func TestPublishNATEvent_DeleteRetriesAcrossSubscriberGap(t *testing.T) { + ns := startTestNATSServer(t) + + nc, err := nats.Connect(ns.ClientURL()) + require.NoError(t, err) + defer nc.Close() + + // Subscribe only after the first attempt would have found nobody home. + got := make(chan string, 1) + time.AfterFunc(deleteNATRetryDelay/2, func() { + _, serr := nc.Subscribe("vpc.delete-nat", func(msg *nats.Msg) { + var evt natEvent + _ = json.Unmarshal(msg.Data, &evt) + got <- evt.ExternalIP + _ = msg.Respond([]byte(`{"success":true}`)) + }) + assert.NoError(t, serr) + }) + + PublishNATEvent(nc, "vpc.delete-nat", "vpc-a", "192.168.0.73", "172.31.0.4", "port-eni-a", "") + + select { + case eip := <-got: + assert.Equal(t, "192.168.0.73", eip) + case <-time.After(5 * time.Second): + t.Fatal("vpc.delete-nat was never delivered") + } +} + +// The retry is bounded: with nothing ever subscribing it gives up rather than +// blocking the API call that issued the disassociate. +func TestPublishNATEvent_DeleteGivesUpWithNoSubscriber(t *testing.T) { + ns := startTestNATSServer(t) + + nc, err := nats.Connect(ns.ClientURL()) + require.NoError(t, err) + defer nc.Close() + + start := time.Now() + PublishNATEvent(nc, "vpc.delete-nat", "vpc-a", "192.168.0.73", "172.31.0.4", "port-eni-a", "") + elapsed := time.Since(start) + + assert.Less(t, elapsed, deleteNATTimeout, + "no-responders must fail fast rather than burn the reply timeout") +} diff --git a/spinifex/vpcd/vpcd.go b/spinifex/vpcd/vpcd.go index 1acd8d721..c88aa3ca0 100644 --- a/spinifex/vpcd/vpcd.go +++ b/spinifex/vpcd/vpcd.go @@ -729,9 +729,9 @@ func launchService(cfg *Config) error { return fmt.Errorf("construct reconciler: %w", err) } - // Startup reconcile (leader-gated, apply-only). Orphan pruning is skipped because intent may be stale: - // a peer's vpc.create-sg could be mid-flight and a prune would sweep those port groups as orphans. - // Drift loop uses full Reconcile. + // Startup reconcile (leader-gated, apply-only). Topology pruning is skipped because intent may be + // stale: a peer's vpc.create-sg could be mid-flight and a prune would sweep those port groups as + // orphans. The EIP sweep still runs — see ReconcileApplyOnly. Drift loop uses full Reconcile. // startupErr seeds the drift loop's backoff so a resource the bootstrap pass // could not converge is retried on the short requeue, not a full interval. var startupErr error @@ -967,6 +967,11 @@ func hostEIPBinder(pool *external.ExternalPoolConfig) policy.HostEIPBinder { defer cancel() return host.RemoveEIPIngress(ctx, runner, externalIP, gateway, uplinkHint) }, + List: func() ([]string, error) { + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + return host.ListEIPIngress(ctx, runner) + }, } } diff --git a/tests/e2e/eks/eks_test.go b/tests/e2e/eks/eks_test.go index e6898732f..77cda0944 100644 --- a/tests/e2e/eks/eks_test.go +++ b/tests/e2e/eks/eks_test.go @@ -516,6 +516,12 @@ func runIRSAPod(t *testing.T, c *harness.AWSClient, env *harness.Env, artifacts const caConfigMap = "irsa-pod-gateway-ca" out, err := kc.Run(30*time.Second, "create", "configmap", caConfigMap, "-n", "default", "--from-file=ca.pem="+caPath) + if err != nil { + // This is the first kubectl of the subtest, so it lands before the pod + // dumps below are registered and would otherwise fail with no evidence. + harness.DumpFile(t, artifacts, "gateway-ca-configmap-auth.txt", + []byte(kc.AuthDiagnostics(30*time.Second))) + } require.NoErrorf(t, err, "create gateway-ca configmap:\n%s", out) t.Cleanup(func() { _, _ = kc.Run(30*time.Second, "delete", "configmap", caConfigMap, "-n", "default", "--ignore-not-found") diff --git a/tests/e2e/harness/kubectl.go b/tests/e2e/harness/kubectl.go index 63941a11f..d5b8cc0bb 100644 --- a/tests/e2e/harness/kubectl.go +++ b/tests/e2e/harness/kubectl.go @@ -4,8 +4,11 @@ package harness import ( "bytes" + "encoding/json" + "fmt" "os" "os/exec" + "strings" "testing" "time" ) @@ -62,6 +65,84 @@ func (k *Kubectl) Run(timeout time.Duration, args ...string) (string, error) { } } +// AuthDiagnostics reproduces the credential exchange behind a failing call +// without mutating anything. `Unauthorized` on its own says only that the +// apiserver refused the request, and the two explanations — a token it rejected +// versus one the exec plugin never produced — need different fixes. +// +// It probes an authenticated path rather than `/version`, which is anonymously +// readable and so returns 200 under either explanation, and it invokes the +// credential plugin directly so a plugin that failed is named rather than +// inferred from a missing header. +func (k *Kubectl) AuthDiagnostics(timeout time.Duration) string { + var b strings.Builder + + b.WriteString("=== kubectl auth whoami ===\n") + out, err := k.Run(timeout, "auth", "whoami") + b.WriteString(out) + if err != nil { + b.WriteString("\nerror: " + err.Error() + "\n") + } + + // kube-system is not anonymously readable, so a 200 here proves a credential + // was both produced and accepted. + b.WriteString("\n=== GET /api/v1/namespaces/kube-system ===\n") + out, err = k.Run(timeout, "--v=8", "get", "--raw", "/api/v1/namespaces/kube-system") + b.WriteString(out) + if err != nil { + b.WriteString("\nerror: " + err.Error() + "\n") + } + + b.WriteString("\n=== credential plugin, invoked directly ===\n") + b.WriteString(k.execPluginProbe(timeout)) + return b.String() +} + +// execPluginProbe runs the kubeconfig's own exec credential plugin and reports +// whether it produced a token. The token itself is never printed — CI logs are +// retained for weeks and it is a live cluster credential. +func (k *Kubectl) execPluginProbe(timeout time.Duration) string { + spec, err := k.Run(timeout, "config", "view", "--raw", "-o", + "jsonpath={.users[0].user.exec.command}{range .users[0].user.exec.args[*]} {@}{end}") + if err != nil { + return "could not read exec block from kubeconfig: " + err.Error() + "\n" + spec + } + argv := strings.Fields(strings.TrimSpace(spec)) + if len(argv) == 0 { + return "kubeconfig user has no exec credential plugin\n" + } + + bin, err := exec.LookPath(argv[0]) + if err != nil { + return "exec plugin " + argv[0] + " not on PATH: " + err.Error() + "\n" + } + cmd := exec.Command(bin, argv[1:]...) //nolint:gosec // argv comes from the kubeconfig this test wrote + cmd.Env = append(os.Environ(), k.AWSEnv...) + var stdout, stderr bytes.Buffer + cmd.Stdout, cmd.Stderr = &stdout, &stderr + + var b strings.Builder + fmt.Fprintf(&b, "argv: %s\n", strings.Join(argv, " ")) + runErr := runWithTimeout(cmd, timeout) + fmt.Fprintf(&b, "exit: %v\n", runErr) + fmt.Fprintf(&b, "stderr: %s\n", strings.TrimSpace(stderr.String())) + + var cred struct { + Status struct { + Token string `json:"token"` + ExpirationTimestamp string `json:"expirationTimestamp"` + } `json:"status"` + } + if jsonErr := json.Unmarshal(stdout.Bytes(), &cred); jsonErr != nil { + fmt.Fprintf(&b, "stdout did not parse as an ExecCredential: %v (%d bytes)\n", + jsonErr, stdout.Len()) + return b.String() + } + fmt.Fprintf(&b, "token produced: %t (%d chars), expires: %q\n", + cred.Status.Token != "", len(cred.Status.Token), cred.Status.ExpirationTimestamp) + return b.String() +} + type timeoutError struct{} func (*timeoutError) Error() string { return "kubectl timed out" } diff --git a/tests/e2e/harness/wait.go b/tests/e2e/harness/wait.go index a5dcb28f2..b49a13e06 100644 --- a/tests/e2e/harness/wait.go +++ b/tests/e2e/harness/wait.go @@ -7,7 +7,6 @@ import ( "testing" "time" - "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -20,11 +19,30 @@ func Eventually(t *testing.T, cond func() bool, timeout, interval time.Duration, // EventuallyErr is like Eventually but lets cond return an error for the // failure message. Useful when the probe itself yields diagnostic detail. +// +// cond runs on the test's own goroutine, so a t.Fatal or a require inside it +// aborts the test as written. Under testify's EventuallyWithT it did not: the +// Goexit killed only the tick goroutine and left the collector empty, which +// reads as the condition being satisfied — so the wait returned successfully on +// a resource it had just declared broken, and the test carried on against it. +// +// The cost is that a cond which never returns hangs past the timeout instead of +// being abandoned. Every cond here is a bounded client call, and the go test +// timeout names the blocked call in its stack — better evidence than a bare +// "condition never satisfied" would be. func EventuallyErr(t *testing.T, cond func() error, timeout, interval time.Duration) { t.Helper() - require.EventuallyWithT(t, func(c *assert.CollectT) { - assert.NoError(c, cond()) - }, timeout, interval) + deadline := time.Now().Add(timeout) + for { + err := cond() + if err == nil { + return + } + if !time.Now().Before(deadline) { + t.Fatalf("condition not met in %s: %v", timeout, err) + } + time.Sleep(interval) + } } // RetryWithReset runs fn as "attempt-1"; on failure it calls ResetAllNodes and diff --git a/tests/e2e/multinode/placement_nat_test.go b/tests/e2e/multinode/placement_nat_test.go index e05abe55b..a62c5cf84 100644 --- a/tests/e2e/multinode/placement_nat_test.go +++ b/tests/e2e/multinode/placement_nat_test.go @@ -445,6 +445,7 @@ func spreadSetupPrivateTrio(t *testing.T, fix *Fixture, b spreadBastion) spreadP } privIPs := make([]string, 0, len(privIDs)) + eniIDs := make([]string, 0, len(privIDs)) for _, id := range privIDs { out, err := c.EC2.DescribeInstances(&ec2.DescribeInstancesInput{ InstanceIds: []*string{aws.String(id)}, @@ -452,12 +453,28 @@ func spreadSetupPrivateTrio(t *testing.T, fix *Fixture, b spreadBastion) spreadP require.NoError(t, err, "describe-instances private") require.NotEmpty(t, out.Reservations, "no Reservations for %s", id) require.NotEmpty(t, out.Reservations[0].Instances, "no Instances for %s", id) - ip := aws.StringValue(out.Reservations[0].Instances[0].PrivateIpAddress) + inst := out.Reservations[0].Instances[0] + ip := aws.StringValue(inst.PrivateIpAddress) require.NotEmptyf(t, ip, "%s has no PrivateIpAddress", id) privIPs = append(privIPs, ip) + eni := "" + if len(inst.NetworkInterfaces) > 0 { + eni = aws.StringValue(inst.NetworkInterfaces[0].NetworkInterfaceId) + } + eniIDs = append(eniIDs, eni) } harness.Detail(t, "private_ips", privIPs) + // The failure this phase is most likely to hit is a guest that never answers + // SSH, and the NAT/EIP dump says nothing about one. Registered before the + // wait so it fires on the guest that failed, and covers all three so a + // working guest is available as the control. + t.Cleanup(func() { + if t.Failed() { + dumpSpreadGuestDiag(t, fix, privIDs, privIPs, eniIDs, hostingNodes) + } + }) + harness.Step(t, "wait for private SSH via bastion (x%d)", len(privIPs)) for i, privIP := range privIPs { waitForSSHViaBastion(t, b.KeyPath, b.PublicIP, privIP, fmt.Sprintf("priv #%d (%s)", i, privIDs[i])) @@ -779,6 +796,67 @@ func waitForNATGatewayStateBest(c *harness.AWSClient, id, target string, timeout // dumpPlacementNATDiag fans out datapath probes (ARP, xfrm, OVS/OVN state) to every // cluster node on failure and writes results under t's artifact dir. Best-effort: // SSH errors are logged but never re-fail the test. +// dumpSpreadGuestDiag captures, for every spread guest, the evidence needed to +// tell "the guest never booted" from "the guest booted and its port never +// bound": its console, its logical switch port in NB and its port binding in SB, +// and the OVS interface backing its tap on the node it landed on. +func dumpSpreadGuestDiag(t *testing.T, fix *Fixture, ids, ips, enis, nodes []string) { + t.Helper() + if fix.Env == nil || fix.Cluster == nil || len(fix.Cluster.Nodes) == 0 { + t.Logf("dumpSpreadGuestDiag: no env or cluster nodes; skipping") + return + } + artifactDir := fix.ArtifactDir(t) + ssh := harness.NewPeerSSH() + + for i, id := range ids { + ip, eni, node := at(ips, i), at(enis, i), at(nodes, i) + t.Logf("dumpSpreadGuestDiag: guest %s ip=%s eni=%s node=%s", id, ip, eni, node) + + console, err := harness.InstanceConsole(fix.AWS, id) + if err != nil { + console = fmt.Sprintf("(get-console-output failed: %v)", err) + } else if console == "" { + console = "(console empty — the guest may never have started)" + } + harness.DumpFile(t, artifactDir, fmt.Sprintf("guest-%s-console.log", id), []byte(console)) + + port := "port-" + eni + probes := []struct{ name, cmd string }{ + {"nb-lsp", fmt.Sprintf("sudo ovn-nbctl --no-leader-only list logical_switch_port %s 2>&1 || true", port)}, + {"sb-port-binding", fmt.Sprintf("sudo ovn-sbctl --no-leader-only find port_binding logical_port=%s 2>&1 || true", port)}, + {"ovs-interface", fmt.Sprintf("sudo ovs-vsctl --columns=name,ofport,external_ids,link_state find interface external_ids:iface-id=%s 2>&1 || true", port)}, + {"ovs-ports", "sudo ovs-vsctl list-ports br-int 2>&1 || true"}, + {"tap-link", fmt.Sprintf("ip -d link show | grep -A2 %s 2>&1 || true", eni)}, + } + + // Every node, not just the hosting one: a port bound on the wrong chassis + // is exactly the failure a hosting-node-only dump cannot show. + for _, n := range fix.Cluster.Nodes { + for _, p := range probes { + ctx, cancel := context.WithTimeout(context.Background(), 20*time.Second) + out, rerr := ssh.Run(ctx, n.Addr, p.cmd) + cancel() + header := fmt.Sprintf("# guest=%s eni=%s expected_node=%s host=%s cmd=%s\n", + id, eni, node, n.Addr, p.cmd) + if rerr != nil { + header += fmt.Sprintf("# (ssh error: %v)\n", rerr) + } + name := fmt.Sprintf("guest-%s-%s-%s.log", id, n.Name, p.name) + harness.DumpFile(t, artifactDir, name, append([]byte(header), out...)) + } + } + } +} + +// at reads s[i] tolerantly: a diagnostic must not panic on a short slice. +func at(s []string, i int) string { + if i < len(s) { + return s[i] + } + return "" +} + func dumpPlacementNATDiag(t *testing.T, fix *Fixture, bastionPubIP, bastionID string) { t.Helper() if fix.Env == nil { diff --git a/tests/e2e/natuplink/natuplink_test.go b/tests/e2e/natuplink/natuplink_test.go index b4bdd4a49..08cffac5f 100644 --- a/tests/e2e/natuplink/natuplink_test.go +++ b/tests/e2e/natuplink/natuplink_test.go @@ -578,6 +578,14 @@ func phaseEIPIngress(t *testing.T, fix *fixture, def harness.VPCInfo, probe egre }, 2*time.Minute, 3*time.Second) assertDNATExempt(t, eip) + // EC2 releases an instance's auto-assigned public IPv4 when an EIP is + // associated: "that public IPv4 address is released back into Amazon's pool + // ... You cannot reuse the public IPv4 address previously associated". + harness.Step(t, "associating the EIP released the auto-assigned %s", probe.publicIP) + harness.EventuallyErr(t, func() error { + return eipHostPlumbingGone(probe.publicIP) + }, 2*time.Minute, 3*time.Second) + harness.Step(t, "open SG for SSH from anywhere, TCP handshake to EIP %s:22", eip) perms := []*ec2.IpPermission{{ IpProtocol: aws.String("tcp"), FromPort: aws.Int64(22), ToPort: aws.Int64(22), @@ -619,8 +627,11 @@ func phaseEIPIngress(t *testing.T, fix *fixture, def harness.VPCInfo, probe egre return eipHostPlumbingGone(eip) }, 2*time.Minute, 3*time.Second) - harness.Step(t, "auto-assigned public IP %s still plumbed after EIP teardown", probe.publicIP) - require.NoError(t, eipHostPlumbing(probe.publicIP, gwIP)) + // The auto-assigned address went back to the pool at associate time, so + // disassociating leaves the instance with no public delivery at all. It does + // not come back — matching EC2, where a stop/start is what issues a new one. + harness.Step(t, "no public delivery remains after the EIP teardown") + require.NoError(t, eipHostPlumbingGone(probe.publicIP)) } // eipHostPlumbing returns nil when the full Tier 2 host state for eip is in