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