fix: close the four defects keeping the e2e nightly red (#1007)

* fix: stop the e2e analyser inventing failures and let a detach outlast its seal

go-junit-report emits <error message="No test result found"> for a === RUN with
no matching result line, and attaches the test's own captured log as the body.
The analyser counted those as failures, so the baremetal cell reported 25
failures against a junit file recording 1, with log output reading as
assertions. Separate the marker from a real error in both the parse and the
roll-up, count the unresolved cases and say so in the summary.

The gateway gave a detach 30s while the daemon budgets 180s for the ebs.unmount
seal and 180s more for the QMP unplug chain, so any detach whose seal replayed a
WAL was reported as ServerInternal while it went on to succeed.

Also switch four nightly job gates from always() to !cancelled(): always()
overrides cancellation, so a cancelled run kept starting jobs.

* fix: serialise the e2e workflows on one group and retry a dropped libvirt

e2e.yml had no concurrency block at all, so every push to dev could provision
alongside every other push and alongside the nightly. All four workflows that
build on these hypervisors now share e2e-hypervisors, queued rather than
cancelled. A per-environment group is not expressible: GitHub picks the group
before it picks a runner, and the environment is a property of the runner.

tofu apply also failed outright on a transient libvirt connect, which fails a
45-minute job in 90 seconds and reports it as a test failure. retry_run retries
only when that attempt's own output names a connection failure, so a real
failure still fails once.

Also collect the unfiltered journal from the matrix cells and the node journal
from cell-21: the unit filter drops the kernel and OOM lines that explain why
one node behaved unlike its siblings, and a passing run's journal is what makes
a failing one readable.

* fix: build the baremetal junit from the unfiltered suite log

run-baremetal-e2e.sh streams the full suite output to suite-output.log and a
grep-filtered summary to its stdout, which the workflow tees into
test-baremetal.log. That filter anchors --- PASS at column 0 and Go indents
every subtest result by four spaces, so the junit was generated from a log with
no subtest results in it: go-junit-report saw each === RUN with no outcome and
emitted <error message="No test result found">.

17 of cell-28's 39 testcases and 93 of cell-20's 120 were that. Regenerating
cell-28 from suite-output.log gives 39 tests, 0 failures, 0 errors.

* fix: converge released EIPs instead of trusting a fire-and-forget teardown

A disassociate leaves the ENI running, so the orphan sweep's owning-port test
never fires for it. The teardown then rests entirely on vpc.delete-nat, which is
core NATS and is lost whenever vpcd is restarting — and the intent KV watch is
UpdatesOnly, so the same window hides the write that would have driven a repair
pass. The dnat_and_snat row and its host /32 route to a released public address
survived until something else happened to touch them, which for a live ENI was
nothing at all.

Give the sweep the second test it was missing: AddEIP is the only writer of
dnat_and_snat, so the floating IPs intent asks for are the complete set of
addresses that may hold one, and a row for any other address is stale however
alive its port. Ports and external IPs travel together in LiveEIPs, both unioned
from the start-of-pass snapshot and the fresh re-read, so a mid-pass launch is
still spared. The host unbind now runs even when the row had already gone, which
is the state a crash between the OVN delete and the unbind leaves.

Run that sweep on the startup pass too. Startup is the pass that follows the
blind window, so skipping it deferred repair of exactly the changes that were
missed. The port-group and ENI-port sweeps stay gated there for the in-flight
create they were written for; the EIP sweep re-reads intent immediately before
deciding and abandons the whole sweep if that read fails, which is the same
protection by a stronger route.

* fix: keep a release verify off the hypervisors an e2e run is using

release.yml is the fifth workflow that provisions on the ci-single pool and had
no concurrency block at all, so a tag push could land a tofu apply on the same
libvirt host a nightly cell was mid-provision on. The group goes on the verify
job rather than the workflow: the build jobs touch no hypervisor and should not
queue behind a nightly.

* fix: stop cell-27 handing a 50-minute suite a 50-minute job

The rds suite is budgeted 50m in suite-sets.sh and cell-27 took the matrix
default of 50 minutes for the whole job, so provisioning, install, the suite and
teardown had to fit inside the suite's allowance alone. It never could: the last
measured run spent 6 minutes reaching the suite and was killed 44 minutes into
it, mid-TestAutomatedBackups. A job timeout reports "The operation was canceled"
and nothing else, which is why this cell has no verdict in any nightly rather
than a failure anyone could read.

cell-27 gets 75 minutes, and the select job now refuses to start a run whose job
budget does not clear its suite budget plus a setup allowance. The inner timeout
firing first is the property that matters: go test says where it stopped and
what failed, and the job timeout says nothing at all. cell-29 already had the
same fix applied by hand; nothing stopped the next suite from repeating it.

* fix: converge host EIP plumbing against intent, not against the NAT row

The released-EIP sweep landed and did not fire. Its premise was that a stranded
dnat_and_snat row is what a stranded host route can be found by, and on the path
that actually strands one there is no row left. AddEIP scrubs the predecessor
row sharing the private IP before installing the new one, so when reconcile
re-added the instance's auto-assigned address it silently deleted the released
EIP's row — and applyEIPs runs ahead of the sweep, which then walked a table
with nothing stale in it while the /32 route and its proxy-ARP stayed up.

Give the sweep the host's own inventory. ListEIPIngress reads the EIPs back from
the FORWARD accepts EnsureEIPIngress stamps with its own comment, so a binding is
found by what installed it rather than by a row some other path is free to
delete. Anything plumbed that intent no longer asks for is torn down, which also
covers a crash between the OVN delete and the unbind. A failed inventory fails
the pass: an empty list and an unreadable one are indistinguishable, and reading
the second as the first is a sweep that reports success having done nothing.

Close the window inside the pass too. The predecessor scrub now reads the row it
is about to drop and releases that address's host state, so the strand does not
exist between applyEIPs and the sweep rather than merely being repaired a step
later.

* fix: retry the release verify's libvirt calls like every other job does

The verify job drives the same libvirt provider on the same hypervisors as the
e2e cells, where a dropped connection under concurrent load is the steady state
and is retried. Here it was a hard failure that reads as a broken release. It
was skipped earlier only because the job checks out mulga and not spinifex, so
the shared helpers were not on disk — a sparse checkout of .github/scripts costs
nothing and makes apply and destroy behave like their e2e counterparts.

* fix: do not report a rebooting DB instance available on the pre-reboot agent's health

RegisterDBInstance stamped a fresh LastSeen while leaving Agent.EngineHealth at
the value the previous agent process reported. After a reboot the new agent
registers before it has probed anything, so the record read as a healthy engine
with a beat newer than the transition, and the reconciler moved the instance to
available while PostgreSQL was still starting up. A client that connects the
moment the status turns green then gets "the database system is starting up".

A register now discards the previous process's verdict and records when this
agent process started. The restart reconciler requires that registration to be
newer than the transition, which also closes the window where a beat lands
between the engine being stopped and the VM going down.

* test: record the credential kubectl sent when an EKS call comes back Unauthorized

The IRSA pod subtest's first kubectl is the gateway-CA configmap, which lands
before the pod dumps are registered, so a 401 there left no evidence at all. A
verbose read-only probe reports whether an Authorization header was sent, which
separates a token the apiserver rejected from one the exec plugin never made.

* fix: report a starting engine promptly, and budget CI jobs from the suite

The agent waited a full heartbeat interval before its first beat, so a restart
could not be observed as finished for up to 30 seconds after the engine was
already serving. Beat at startup instead, and report every 5 seconds until the
engine has answered once — the control plane is actively waiting on that beat,
and the steady-state cadence it hands back is for a database already serving.

The rds suite is the one most sensitive to what else the hypervisor is doing:
its DB VMs serialise behind a 4 GiB semaphore, so its wall clock is set by how
long it waits for the budget. The same pass ran 45m beside four nightly cells
and overran 50m beside nine, panicking with two tests still running. Raise its
budget to 60m.

That budget was then larger than the jobs meant to contain it. A job cancelled
on timeout reports only "The operation was canceled" and takes the artifacts
with it, so the inner `go test` timeout must always fire first — and it could
not for rds on e2e.yml, nor for storagefault or diskperf, which have asked for
90m and 180m inside a 60m job since they were added. Both workflows now resolve
their job budget from suite-sets.sh rather than carrying a literal: e2e.yml
from the largest requested suite, e2e-suites.yml per matrix leg, so a leg is
bounded by its own suite and not by the longest one beside it. The default push
set resolves to exactly the timeouts both workflows had before.

* fix: check a permutation cell's job budget against the suites it runs

The guard only saw cells that name a suite, so the nine that run a topology's
nightly subset were never checked against it — the same class of mistake the
guard exists to catch, in the majority of the cells. Bound each by the longest
suite in its subset: max() and not sum(), because 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. Every cell clears it today.

* fix: report why a PostgreSQL engine would not start, and stop failing a stop that landed

Three defects, all found by the first rds pass that ever ran deep enough to
reach them.

A wait that saw an instance reach `failed` called t.Fatalf from inside the
polling condition, and testify runs that condition on its own goroutine. The
Goexit killed the tick and left the collector empty, which reads as the
condition being satisfied — so the wait returned successfully on an instance it
had just declared broken, logged "reached status available" about one that was
failed, and let the test carry on against it. Six conditions across four suites
call Fatal or require the same way. EventuallyErr now runs its condition on the
test's goroutine, which makes all six behave as written.

A DB VM stop has two drivers: the API call and the reconciler resuming one whose
caller it assumes has died. When they overlap the loser is told the VM is not in
a state to be stopped — which is the state the stop was heading for — and the
customer's StopDBInstance returned InvalidDBInstanceState for a stop that had
just completed. Both paths now treat a refused command the way they already
treat an unanswered one: it says nothing about the VM, so the fleet view
settles it.

PostgreSQL had no equivalent of the engine log tail MariaDB has carried since it
was added, so a postmaster that refuses a setting produced "engine did not
respond on /run/postgresql:5432" and nothing else — on a guest with no SSH,
whose console records only that pg_ctl could not start the server. The probe now
quotes the tail of the log the image already directs the postmaster to, and the
reboot and modify paths carry the agent's reason into the failure the way the
create path always has. The reason reaches the customer through StatusInfos.

The rds suite's budget goes to 90m and cell-27's job to 100m. Its wall clock is
what the DB-VM queue costs rather than what the tests do — single tests logged
11m, 22m and 26m waiting for budget — and the pass above still had three of
seventeen tests running at 60m.

* fix: keep a DB VM recoverable when its agent cannot start, and flush the volume before a snapshot

An rds-agent that failed to construct exited, so a transient IMDS credential
resolution took the guest down for good: rds-datadir and rds-init cascade on the
missing handoff, the engine never starts, and the control plane sees only silence
until it declares the instance failed ten minutes later. Construction is retried
like every other boot step instead.

OpenRC skips start_post when the start itself fails, which is the one case with
no diagnostic at all — the console carried nothing but "died". The log mirror
moves out of the handoff wait so a failed start uses it too.

A snapshot quiesced the engine and nothing else. The engine repairs its own files
from the WAL, but postgresql.conf sits beside them and it does not: a restore
came up on a torn tail and the postmaster stopped on a syntax error at the
unterminated include hook. The quiesce now flushes the whole data mount, and the
hook is renamed into place rather than appended, so a boot that finds a half
written one replaces it instead of appending after its open quote.

* fix: flush the config cloud-init wrote before a reset can take it

A DB instance rebooted seconds after it went available came back with no
RDS_GATEWAY_URL, so rds-agent could not reach the control plane and the engine
never started. cloud-init writes agent.env once, per-instance, and never again;
a reboot is a QMP system_reset with no guest shutdown, so the file was still
dirty page cache when the machine reset under it and the next boot read nothing.
The handoff wait now syncs, which is the point at which the agent has proved it
read that file.

* fix: stop dropping an EIP teardown published while vpcd is restarting

DisassociateAddress publishes vpc.delete-nat fire-and-forget. On run
34046316024 vpcd disconnected from NATS at 03:51:26.73 and its replacement
subscribed at 03:51:27.09; the publish landed at 03:51:26.92, in the gap, and
went nowhere. ReleaseAddress then returned the address to the pool two minutes
later with its /32 host route still delivering to the guest that had held it.

vpc.delete-nat now uses request-reply like vpc.add-nat, and retries only on
no-responders — which returns immediately, so the cost is paid solely when
nothing is listening. A teardown that still fails is logged as an error naming
the address rather than lost silently. Neither is fatal to the caller: the
reconciler's orphan sweep remains the backstop.

vpc.add-nat on the EIP path stays fire-and-forget. The shared helper blocks it
on the flows barrier for up to 45s, and associating an address should not
inherit that.

Two reconcile passes in that run had the address absent from intent and did not
sweep its host route, and the journal cannot say why: the sweep logged only when
it acted, so a route it kept was indistinguishable from one it never saw. It now
logs the bindings it found, kept and wanted.

* ci: render one run-level table for the e2e nightly

Reading a nightly meant opening nineteen jobs, and the Actions UI does not
separate a cell that failed from one cancelled out from under it — a
distinction every investigation of this suite has needed, and one the run
34046316024 analysis had to reach for the jobs API to get.

A final job, needs: every cell and if: always(), renders cell, topology,
result, duration, runner and per-cell test counts into the step summary, with
run-level totals, the three slowest cells and the failing test names.

Result, duration and runner come from the jobs API so a cell that died before
writing junit still gets a row. Counts come from a new junit-only artifact per
cell rather than the full cell artifact, so the roll-up does not pull nineteen
journals it has no use for.

Verified against run 34046316024: 14 success, 2 cancelled, 1 failure, with the
two cancellations shown as cancelled rather than folded into failure.

* fix: assert EC2's actual EIP semantics, and probe EKS auth on an authenticated path

natuplink asserted that an instance's auto-assigned public IP is still plumbed
after an EIP associated to the same instance is torn down. EC2 does the
opposite: associating an EIP releases the auto-assigned address back into the
pool, and it cannot be reused. Our datapath already does that — run 34059879666
shows 192.168.0.72's ingress removed at 07:09:44.000, 36ms before .73's was
installed — so the test was asserting behaviour neither AWS nor we have.

It now asserts the release at the point it happens, and that no public delivery
remains after the teardown. This surfaced only once the teardown itself started
working: the run's other assertions passed, including .73's removal, which was
the failure before.

Our records still disagree with our datapath — the ENI keeps the released
address, which is why termination tears the old one down twice and never the
current one. That is the remaining half of mulga-7zc9w and is not fixed here;
it needs an IPAM release on the associate path.

Separately, AuthDiagnostics read /version, which is anonymously readable, so its
200 was consistent with both branches it claimed to distinguish. It now runs
auth whoami, reads kube-system, and invokes the credential plugin directly,
reporting exit code, stderr and whether a token was produced — never the token,
since CI logs outlive it.

* test: capture per-guest state when a spread guest never answers SSH

TestMultinodeSpread's only failure dump is dumpPlacementNATDiag, which collects
OVN, OVS, ARP and route state aimed at the NAT and EIP half of the test. The
failure it actually hits is a guest that never accepted SSH — run 34040324968,
the guest on node3 at 10.100.2.5 — and for that it recorded no console, no port
binding and no tap state. There was no way to tell from the artifact whether the
guest booted at all.

Now dumps, per guest: the console, the NB logical switch port, the SB port
binding, the OVS interface backing its tap, and br-int's port list. Probed on
every node rather than the expected one, because a port bound on the wrong
chassis is exactly what a hosting-node-only dump cannot show.

Covers all three guests, not just the failing one, so a working guest is
available as the control.

* ci: sample hypervisor load either side of every cell

Eight runner names map onto three hypervisors, so cells that never share a
runner still share a host: when cell 10's SSH wait expired on run 34040324968,
cells 22, 17, 18 and 28 were concurrently live, two of them multi-node. Nothing
in the artifacts measured host load, which left co-tenancy as an explanation
that could be neither confirmed nor ruled out.

Records loadavg, MemAvailable, SwapFree, the cpu line carrying steal, and the
QEMU process count before and after each cell, into the cell artifact.

* ci: note that main's missing concurrency block is why the nightly runs ungrouped

Three refs carry three different groupings: main has no concurrency block at
all, dev uses e2e-nightly, this branch uses e2e-hypervisors. Scheduled runs load
the workflow from the default branch, so every cron nightly runs ungrouped and
cannot queue against anything — which is how a dispatch of 34050630627 ran
alongside the scheduled 34046316024 and cost it cells 24 and 27.

e2e-hypervisors is the right group and deliberately broader than dev's, since
e2e.yml, e2e-suites.yml and e2e-ddil.yml draw on the same runner pools. Nothing
on a feature branch can fix this; the block has to reach main.
This commit is contained in:
Ben Duncan
2026-09-06 16:53:32 -05:00
committed by GitHub
parent c2aad92044
commit 18853cef31
54 changed files with 2024 additions and 227 deletions
+44 -4
View File
@@ -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 <testsuite timestamp>, 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 <error> 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
@@ -174,6 +174,55 @@ func TestParseFile_SkipsEmptyParentFailure(t *testing.T) {
}
}
// go-junit-report emits <error message="No test result found"> 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(`<?xml version="1.0"?>
<testsuites><testsuite name="" tests="3" failures="1" errors="2">
<testcase name="TestLB/Internal_ALB" time="0.0"><error message="No test result found"><![CDATA[
lb_test.go:88: ALB internal: 20/20 successful, 2 unique
]]></error></testcase>
<testcase name="TestLB/Internal_NLB" time="0.0"><error message="No test result found"></error></testcase>
<testcase name="TestX/RealFailure" time="0.5"><failure message="Failed"><![CDATA[
foo_test.go:10:
Messages: real assertion message
]]></failure></testcase>
</testsuite></testsuites>`)
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 <error> 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(`<?xml version="1.0"?>
<testsuites><testsuite name="" tests="1" failures="0" errors="1">
<testcase name="TestX" time="0.5"><error message="panic"><![CDATA[
foo_test.go:10: panic: runtime error: index out of range
]]></error></testcase>
</testsuite></testsuites>`)
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
+2 -1
View File
@@ -129,7 +129,8 @@
"arch": "x86_64",
"runner": "ci-single",
"extra": "rds",
"suite": "rds"
"suite": "rds",
"timeout_minutes": 100
},
{
"cell": 29,
+34
View File
@@ -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"
}
+220
View File
@@ -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-<n>-<run_id> 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 += ["", "<details><summary>Failing tests</summary>", ""]
for cell, names in failing_detail:
lines.append(f"- **cell {cell}** — " + ", ".join(f"`{n}`" for n in names))
lines += ["", "</details>"]
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())
+20 -3
View File
@@ -73,9 +73,12 @@ E2E_SUITES_NIGHTLY_MULTI="multinode cert lb"
# e2e_suite_timeout <suite>
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 <suite-list> <floor-minutes> [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
+9 -1
View File
@@ -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
# <error message="No test result found"> — 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
+10 -2
View File
@@ -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"
+153 -11
View File
@@ -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
+27 -18
View File
@@ -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"
+67 -6
View File
@@ -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"
+18 -2
View File
@@ -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:
+1
View File
@@ -41,3 +41,4 @@ Thumbs.db
# Test reports
*-report.txt
/rds-agent
+7 -1
View File
@@ -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)
+60
View File
@@ -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)
@@ -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])
}
}
-52
View File
@@ -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 {
+9 -4
View File
@@ -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)
}
}
}
+19 -3
View File
@@ -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())
}
}
}
+31
View File
@@ -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)
}
}
+15 -4
View File
@@ -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) {
+45
View File
@@ -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) {
+22
View File
@@ -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 {
+29
View File
@@ -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)
}
}
+32 -12
View File
@@ -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
}
@@ -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"
+32 -12
View File
@@ -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
}
@@ -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"
+28 -6
View File
@@ -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
@@ -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
+7 -1
View File
@@ -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) {
@@ -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")
}
+10 -1
View File
@@ -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,
})
}
+8
View File
@@ -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
+26
View File
@@ -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)
+12 -2
View File
@@ -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
}
+107 -1
View File
@@ -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.
+27 -10
View File
@@ -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 {
+4
View File
@@ -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"`
+31
View File
@@ -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.
+31
View File
@@ -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")
}
}
+93 -22
View File
@@ -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 {
+105 -1
View File
@@ -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()
+31 -19
View File
@@ -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
+62
View File
@@ -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
}
+17 -10
View File
@@ -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)
+50 -5
View File
@@ -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.
+49
View File
@@ -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")
}
+8 -3
View File
@@ -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)
},
}
}
+6
View File
@@ -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")
+81
View File
@@ -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" }
+22 -4
View File
@@ -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
+79 -1
View File
@@ -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 {
+13 -2
View File
@@ -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