From 0a07aff199889cf759401f2b4459256d42c0494c Mon Sep 17 00:00:00 2001 From: Josh Siviour Date: Tue, 19 May 2026 15:59:41 +1000 Subject: [PATCH] ci(e2e-go): cluster JUnit failures + name likely root cause (#230) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * ci(e2e-go): cluster JUnit failures + name likely root cause New composite action `.github/actions/e2e-analyze` runs after `go-junit-report` converts each suite log. For every `` it strips ANSI, normalises dynamic noise (EC2 IDs, UUIDs, IPs, timestamps, file:line) to a stable signature, picks the earliest non-cascade failure per suite as the likely root cause, and buckets the rest by signature. Output is appended to `$GITHUB_STEP_SUMMARY` and written to `/analysis.md` so it travels with the artifact bundle. Cascade markers (`must populate fix.`, `Should NOT be empty`, `Expected value not to be nil`) collapse the typical "one upstream phase fails, ten downstream `require.NotEmpty` assertions trip" pattern into a single grouped entry under the real first failure. The analyser is advisory — it always exits 0. The existing "Fail job if any suite failed" gate keeps owning exit-code semantics. Stage 1 of `docs/development/improvements/e2e-go-failure-analysis.md` (mulga-siv-102). Stage 2 (per-failure log slicing) and Stage 3 (rule-based hints via `tests/e2e/.failure-rules.yaml`, placeholder seeded here) are independent follow-ups. CI wiring: - e2e-go.yml: new "Analyze e2e failures" step between "Publish test summary" and the artifact upload, always-runs. - spinifex.yml: new `make test-actions` step so the golden-file tests under `.github/actions/e2e-analyze/testdata/` run on every PR. - Makefile: `test-actions` target; kept out of `test-cover` so CI-only tooling doesn't dilute coverage %. Golden fixtures: a synthetic cascade-vpcs case (one Phase 5 InvalidParameterValue root + 15 downstream cascades), one real single-failure case captured from run 26037892507, and a clean no-failures case. * ci(e2e-go): per-failure log bundles with time-window slicing Stage 2 of the e2e failure analyzer. For each failure surfaced by Stage 1, materialise /analysis/NN-/ containing: failure.txt — summary (test, start, duration, file-site, error) journal.log — spinifex-journal.log sliced to [StartAt - 5s, StartAt + Duration + 5s] test.log — test-.log block between `=== RUN ` and the matching `--- FAIL` marker — any files the harness already dropped at // Report links each entry to its bundle so a reader on the Actions page goes straight to the relevant slice. Workflow now invokes journalctl with --output=short-iso so the analyzer can parse wall-clock timestamps for the journal window. Lines without a parseable timestamp inherit the previous line's classification (keeps multi-line records and stack traces contiguous). Render output is unchanged when BundlePath is empty, so the Stage 1 golden snapshots still match. * ci(e2e-go): restore GOTOOLCHAIN=auto after setup-go v6 bump setup-go@v6 flipped the GOTOOLCHAIN default from "auto" to "local", which makes Go refuse to auto-download the toolchain version named in go.mod. The self-hosted ci-single runner ships /usr/local/go older than spinifex/go.mod's `go 1.26.3`, and build-install-artifacts.sh prepends that path so the system Go wins the resolution race. Under v5 ("auto"), Go silently fetched 1.26.3 on demand; under v6 ("local"), the Build Install Artifacts step errors out: go: spinifex/go.mod requires go >= 1.26.3 (running go 1.26.1; GOTOOLCHAIN=local) Re-set the env to "auto" so behaviour matches pre-v6 runs. * ci(e2e-go): re-export GOTOOLCHAIN=auto after setup-go Workflow-level env doesn't help: setup-go@v6 writes GOTOOLCHAIN=local to $GITHUB_ENV, which overrides workflow env in every later step. Add a dedicated step right after setup-go that appends GOTOOLCHAIN=auto to $GITHUB_ENV so the Build Install Artifacts step (which uses /usr/local/go from a stale runner path) can self-heal by fetching the toolchain named in go.mod, matching pre-v6 behaviour. * fix(vpcd): add flows-ready barrier after dnat_and_snat add handleAddNAT wrote the NAT rule to OVN NB and returned immediately, mirroring the gap siv-105 closed for handleIGWAttach but on the NAT add path. ec2d/RunInstances then returned success while ovn-northd was still compiling NB->SB and ovn-controller hadn't installed the DNAT/SNAT flows on the gateway chassis, so the freshly launched VM was unreachable on its public IP for whatever flow-install latency the chassis happened to incur. Reproduced in CI run 26072432957 Phase8b_VPCSubnetE2E: VM at 192.168.0.212 timed out at 3min while diagnostics showed Port_Binding up=true for both the VM eni and the chassis-redirect gateway. SB-side convergence was complete; the missing piece was the same `ovn-nbctl --wait=hv sync` barrier siv-105 added to IGW attach, applied at the end of handleAddNAT as well. Reuses the existing package-var `waitForFlowsHV` so tests can stub it; no new infra. Parallel unit test asserts the call site fires exactly once per add-nat. * ci(e2e-analyze): real-artifact fixes for journal slicing Three bugs surfaced after Stage 2 ran against real CI artifacts in run 26072432957: 1. Regex `[+-]\d{4}` rejected the colon-offset form (e.g. `+10:00`) that systemd's `journalctl --output=short-iso` actually emits on most versions. Added a parser that tries RFC3339 first and falls back to the no-colon `-0700` layout. Result: 0-line journal slices become populated. 2. go-junit-report's `timestamp` attr on records the moment the XML was produced (post-suite), not when the tests started. Computing StartAt as `that + cumulative-priors` placed every failure AFTER the journal collection ended, so windows always missed. Workflow now writes `${ARTIFACT_DIR}/test-.start` right before running each suite; analyzer prefers that file over the junit timestamp. 3. Persisted `OffsetFromSuiteStart` on each Failure so the suite-start override can recompute StartAt without re-parsing the XML. Unit tests added for the colon-offset journal format. End-to-end test (TestWriteBundles_EndToEnd) still passes with the new layout. * ci(e2e-analyze): skip parent testcases when summing suite offsets go-junit-report emits one for the parent Go test AND each subtest, with the parent's time = sum of its children. ParseFile was summing every testcase into the suite-cumulative-offset counter, so every leaf's offset was inflated by ~the parent's total duration. Visible on run 26073817490 as Phase8b's StartAt landing 13 minutes after the suite finished collecting logs — beyond the journal window, so the per-failure journal slice was empty. Pre-compute the leaf set per suite (a name is a leaf iff no other testcase name starts with `/`) and only accumulate cumul on leaves. Golden snapshots updated; the offset for the only failure in each fixture now matches the actual leaf-sum start time. * test(e2e-harness): capture IP-targeted datapath state on Phase8b SSH fail Phase 1 diagnostics for mulga-siv-111. The Phase8b SSH timeout reproduced on the e2e-failure-analysis branch with siv-105's IGW barrier AND the new add-nat barrier BOTH firing cleanly, so the residual gap is downstream of `--wait=hv sync` — most likely stale OVS conntrack, stale upstream-host ARP, or an OF flow-install miss. DumpVPCFlowDiagnostics now takes a VPCDiagnosticsOpts carrying the external IP, logical IP, and per-test artifact dir. When set, the helper greps `ovs-ofctl dump-flows br-int`, `conntrack -L`, and `ip -4 neigh show` for the external IP / logical IP and snapshots `ovn-nbctl find NAT external_ip=…`. Each capture is both printed inline (existing affordance) and written to a separate file under fix.Artifacts so the Stage 2 analyzer bundler picks it up alongside the journal + test-log slices, no analyzer changes needed. Phase8b's caller now passes pubIP / privIP / fix.Artifacts so the captures fire on the next failure; updates the t.Fatalf message to point at siv-111 instead of siv-105 (which is the now-closed parent). * fix(e2e-single): authorize SSH ingress on fresh-VPC default SG in Phase8b Phase 8b stands up a non-default VPC and runs an instance there. Its auto-created default SG denies all ingress, so the SSH probe times out even when every datapath barrier converges — OF flow captures show the SYN reaches OVN, gets DNAT'd at table 13, then drops at the ACL between tables 13 and 17. The bash driver relies on admin init having pre-baked this rule on the *default* VPC's default SG; a fresh VPC has not. Add a DescribeSecurityGroups + AuthorizeSSHIngress step between route-table setup and run-instances, using the existing harness helper. Fix surfaced via mulga-siv-111's Phase 1 diagnostics (OF flow + ACL drop counts), invalidating the H1/H2/H3 stale-state hypotheses in the bead plan doc. --- .github/actions/e2e-analyze/README.md | 104 ++ .github/actions/e2e-analyze/action.yml | 38 + .github/actions/e2e-analyze/analyze.go | 552 ++++++++++ .github/actions/e2e-analyze/analyze_test.go | 191 ++++ .github/actions/e2e-analyze/bundle.go | 208 ++++ .github/actions/e2e-analyze/bundle_test.go | 229 ++++ .github/actions/e2e-analyze/main.go | 78 ++ .github/actions/e2e-analyze/slice.go | 176 ++++ .../testdata/cascade-vpcs/analysis.md | 23 + .../testdata/cascade-vpcs/junit-single.xml | 143 +++ .../testdata/no-failures/analysis.md | 3 + .../testdata/no-failures/junit-single.xml | 8 + .../testdata/single-failure/analysis.md | 11 + .../testdata/single-failure/junit-single.xml | 993 ++++++++++++++++++ .github/workflows/e2e-go.yml | 26 +- .github/workflows/spinifex.yml | 3 + Makefile | 8 +- spinifex/services/vpcd/topology.go | 11 + spinifex/services/vpcd/topology_test.go | 49 + tests/e2e/.failure-rules.yaml | 22 + tests/e2e/harness/diag.go | 144 ++- tests/e2e/single/vpc_test.go | 33 +- 22 files changed, 3047 insertions(+), 6 deletions(-) create mode 100644 .github/actions/e2e-analyze/README.md create mode 100644 .github/actions/e2e-analyze/action.yml create mode 100644 .github/actions/e2e-analyze/analyze.go create mode 100644 .github/actions/e2e-analyze/analyze_test.go create mode 100644 .github/actions/e2e-analyze/bundle.go create mode 100644 .github/actions/e2e-analyze/bundle_test.go create mode 100644 .github/actions/e2e-analyze/main.go create mode 100644 .github/actions/e2e-analyze/slice.go create mode 100644 .github/actions/e2e-analyze/testdata/cascade-vpcs/analysis.md create mode 100644 .github/actions/e2e-analyze/testdata/cascade-vpcs/junit-single.xml create mode 100644 .github/actions/e2e-analyze/testdata/no-failures/analysis.md create mode 100644 .github/actions/e2e-analyze/testdata/no-failures/junit-single.xml create mode 100644 .github/actions/e2e-analyze/testdata/single-failure/analysis.md create mode 100644 .github/actions/e2e-analyze/testdata/single-failure/junit-single.xml create mode 100644 tests/e2e/.failure-rules.yaml diff --git a/.github/actions/e2e-analyze/README.md b/.github/actions/e2e-analyze/README.md new file mode 100644 index 000000000..5afa9ec76 --- /dev/null +++ b/.github/actions/e2e-analyze/README.md @@ -0,0 +1,104 @@ +# e2e-analyze + +Post-test failure-clustering action for the Go E2E suites. + +## What it does + +Runs after `go-junit-report` has converted each suite's stdout into +`junit-.xml`. For every JUnit file matched by `junit-glob`: + +1. Parses each `` with a `` / `` child. +2. Strips ANSI escapes, then normalises dynamic noise (UUIDs, EC2 IDs, + IPs, timestamps, request-ids, source line numbers) to produce a stable + _signature_ per failure. +3. Picks the **earliest non-cascade** failure per suite as the likely + root cause. "Cascade" = failure message matches a fixture-dependency + marker (`must populate fix.`, `Should NOT be empty`, + `Expected value not to be nil`). When every failure is a cascade + (whole suite tripped on one upstream gap), the earliest cascade is + the fallback root. +4. Buckets the remaining failures by signature and renders a markdown + report. The report is appended to `$GITHUB_STEP_SUMMARY` and also + written to `/analysis.md` so it travels with the uploaded + artifact bundle. + +The action **never fails the job** — exit-code semantics stay with the +existing "Fail job if any suite failed" gate. + +## Inputs + +| Input | Required | Description | +|--------------|----------|-------------| +| `junit-glob` | yes | Shell glob for the JUnit XML files (e.g. `${ARTIFACT_DIR}/junit-*.xml`). | +| `log-dir` | yes | Directory the rendered report is written into (`analysis.md`). | +| `title` | no | Heading at the top of the summary section. Default `E2E failure analysis`. | + +## Outputs + +None. The summary is appended to `$GITHUB_STEP_SUMMARY`; the same +content lands at `/analysis.md`. + +## Local invocation + +Outside Actions, the analyser prints to stdout instead of appending to a +summary file: + +```sh +cd spinifex/.github/actions/e2e-analyze +go run . -junit-glob "/tmp/artifacts/junit-*.xml" -log-dir /tmp/artifacts +``` + +## Tests + +Golden-file tests live in `testdata/`. Each subdir holds a scenario: + +| Scenario | Source | +|--------------------|-------------------------------------------| +| `cascade-vpcs` | Synthetic: one Phase 5 root + 15 cascades | +| `single-failure` | Real artifact from run `26037892507` | +| `no-failures` | Synthetic: clean run | + +Run normally: + +```sh +go test ./.github/actions/e2e-analyze/ +``` + +When the report format changes intentionally, regenerate the snapshots: + +```sh +go test ./.github/actions/e2e-analyze/ -update +``` + +## Per-failure bundles (Stage 2) + +After parsing, the action materialises a bundle directory per failure +under `/analysis/NN-/`. The report links to it from +each entry so a reader on the Actions page can click straight through +to the relevant log slice. + +Each bundle contains: + +| File | Source | +|-------------------|-----------------------------------------------------------------------------------| +| `failure.txt` | Synthesised summary: test, start, duration, file-site, error line. | +| `journal.log` | `spinifex-journal.log` sliced to `[StartAt − 5s, StartAt + Duration + 5s]`. | +| `test.log` | `test-.log` block between `=== RUN ` and the matching `--- FAIL`. | +| `` | Anything the harness already dropped into `//` at run-time. | + +The journal slice relies on the workflow running +`journalctl --output=short-iso` so timestamps are parseable. Lines +without a parseable timestamp inherit the previous line's +in-window/out-of-window classification (so multi-line records and stack +traces stay contiguous). + +## Roadmap + +- **Stage 1 (shipped):** first-failure surfacing + cascade clustering. +- **Stage 2 (this update):** time-window correlation — per-failure bundle + with sliced journal + test-log + any per-test artifacts. +- **Stage 3:** rule-based root-cause classifier driven by + `spinifex/tests/e2e/.failure-rules.yaml`. + +See `docs/development/improvements/e2e-go-failure-analysis.md` in the +parent mulga repo. diff --git a/.github/actions/e2e-analyze/action.yml b/.github/actions/e2e-analyze/action.yml new file mode 100644 index 000000000..a639ceb4f --- /dev/null +++ b/.github/actions/e2e-analyze/action.yml @@ -0,0 +1,38 @@ +name: E2E Failure Analyzer +description: >- + Post-test analyzer for the Go E2E suites. Parses junit-*.xml emitted by + go-junit-report, clusters failures by signature, picks the earliest + non-cascade failure per suite as the likely root cause, and appends a + human-readable report to $GITHUB_STEP_SUMMARY. Always exits 0 — the + existing "Fail job if any suite failed" gate keeps owning exit-code + semantics. + +inputs: + junit-glob: + description: Shell glob matching JUnit XML files to analyze. + required: true + log-dir: + description: >- + Artifact directory. The rendered report is also written to + $log-dir/analysis.md so it travels with the uploaded artifact. + required: true + title: + description: Heading rendered at the top of the summary section. + required: false + default: "E2E failure analysis" + +runs: + using: composite + steps: + - id: analyze + shell: bash + working-directory: ${{ github.action_path }} + env: + ANALYZE_JUNIT_GLOB: ${{ inputs.junit-glob }} + ANALYZE_LOG_DIR: ${{ inputs.log-dir }} + ANALYZE_TITLE: ${{ inputs.title }} + run: | + go run . \ + -junit-glob "$ANALYZE_JUNIT_GLOB" \ + -log-dir "$ANALYZE_LOG_DIR" \ + -title "$ANALYZE_TITLE" diff --git a/.github/actions/e2e-analyze/analyze.go b/.github/actions/e2e-analyze/analyze.go new file mode 100644 index 000000000..654db6cf6 --- /dev/null +++ b/.github/actions/e2e-analyze/analyze.go @@ -0,0 +1,552 @@ +// Package main implements the e2e-analyze GitHub Action. +// +// Stage 1 of docs/development/improvements/e2e-go-failure-analysis.md: +// cluster failures from go-junit-report's junit-*.xml by error signature, +// pick the earliest non-cascade failure per suite as the likely root cause, +// and render a human-readable report. +// +// This file contains the pure logic (parsing, signature extraction, +// clustering, rendering). Side-effect handling lives in main.go. +package main + +import ( + "encoding/xml" + "fmt" + "path/filepath" + "regexp" + "sort" + "strings" + "time" +) + +// JUnit XML schema produced by go-junit-report v2. Stable across versions +// we care about; only fields used downstream are decoded. +type junitSuites struct { + XMLName xml.Name `xml:"testsuites"` + Suites []junitSuite `xml:"testsuite"` +} + +type junitSuite struct { + Name string `xml:"name,attr"` + Tests int `xml:"tests,attr"` + Failures int `xml:"failures,attr"` + Errors int `xml:"errors,attr"` + Skipped int `xml:"skipped,attr"` + Timestamp string `xml:"timestamp,attr"` + Time float64 `xml:"time,attr"` + Cases []junitTC `xml:"testcase"` +} + +type junitTC struct { + Name string `xml:"name,attr"` + Classname string `xml:"classname,attr"` + Time float64 `xml:"time,attr"` + Failure *junitFailure `xml:"failure"` + Error *junitFailure `xml:"error"` + Skipped *junitSkipped `xml:"skipped"` + SystemOut string `xml:"system-out"` +} + +type junitFailure struct { + Message string `xml:"message,attr"` + Type string `xml:"type,attr"` + Body string `xml:",chardata"` +} + +type junitSkipped struct { + Message string `xml:"message,attr"` +} + +// Failure is the analyzer's normalized view of one failed testcase. +type Failure struct { + SuiteFile string // e.g. "single" (derived from junit-single.xml) + Name string // e.g. "TestSingleNode/Phase5_LaunchInstance" + Duration float64 // seconds + Order int // position within the suite (0-based) + StartAt time.Time // estimated wall-clock start: suite.timestamp + sum(prior durations) + Error string // last meaningful error line, ANSI-stripped + FileHint string // e.g. "vpc_test.go:227", parsed from failure body + Cascade bool // signature matched a known downstream pattern + Signature string // normalized error key for bucketing + // OffsetFromSuiteStart is sum(prior testcase durations) at the time + // this test started. Persisted separately from StartAt so a caller + // that has a more authoritative suite wall-clock origin (e.g. a + // `test-.start` file written by the workflow before the suite + // runs) can recompute StartAt without re-parsing the XML. + OffsetFromSuiteStart time.Duration + // BundlePath is the relative path (from log-dir) to the per-failure + // bundle written by Stage 2's WriteBundles. Empty when bundles were + // not generated (e.g. unit tests that call Render directly). + BundlePath string +} + +// SuiteReport summarises one junit-*.xml file. +type SuiteReport struct { + File string // basename, e.g. "junit-single.xml" + 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) +} + +// Report is the full analysis across every junit file. +type Report struct { + Title string + Suites []SuiteReport +} + +// ansiSeq matches ANSI CSI escapes the harness sprinkles through log +// output (colours, bold). Three forms in the wild: +// - real ESC: `\x1b[36m…` +// - U+FFFD replacement (XML serialiser dropped the ESC byte): `�[36m…` +// - bare CSI with the leading byte gone entirely: `[36m…` +// +// All three are stripped so colour state doesn't fork the signature bucket. +var ansiSeq = regexp.MustCompile( + "\x1b\\[[0-9;]*[a-zA-Z]" + // real ESC CSI + "|�\\[[0-9;]*[a-zA-Z]" + // replacement-char CSI + "|\\[[0-9]{1,2}(?:;[0-9]{1,2})*m", // bare colour code, "mode" form only +) + +// cascadeMarkers are message fragments that only appear in tests that +// depend on a fixture field populated by an earlier phase. Their presence +// means the failure is downstream of some other failure that happened +// first; the report collapses them under that root cause. +var cascadeMarkers = []string{ + "must populate fix.", + "Should NOT be empty", + "Expected value not to be nil", +} + +// noiseReplacers normalise dynamic identifiers so that "ten failures, same +// bug" bucket together. Pattern ordering matters: longer/more-specific +// patterns must precede the catch-alls. +var noiseReplacers = []struct { + re *regexp.Regexp + repl string +}{ + {regexp.MustCompile(`\b(vpc|subnet|sg|rtb|igw|i|ami|vol|snap|rtbassoc|key)-[0-9a-f]{8,}\b`), `${1}-`}, + {regexp.MustCompile(`\b[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}\b`), ``}, + {regexp.MustCompile(`\b[0-9a-f]{32,}\b`), ``}, + {regexp.MustCompile(`\b\d{1,3}(\.\d{1,3}){3}(:\d+)?\b`), ``}, + {regexp.MustCompile(`\b\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d+)?(?:Z|[+-]\d{2}:?\d{2})?\b`), ``}, + {regexp.MustCompile(`request-id:\s*\S+`), `request-id: `}, + {regexp.MustCompile(`(_test\.go):\d+`), `${1}:`}, + {regexp.MustCompile(`\s+`), ` `}, +} + +// fileHintRe pulls the last "foo_test.go:NNN" we see in a failure body so +// the report can point a reader at the source line. Test files dominate the +// hint set; harness/helper file matches go through goFileLineRe below. +var fileHintRe = regexp.MustCompile(`([A-Za-z0-9_]+_test\.go:\d+)`) + +// goFileLineRe matches any "foo.go:NNN:" prefix (test or non-test). Used to +// surface harness/helper-level error text like +// `ec2helpers.go:164: describe-vpcs: InvalidParameterValue …` which Go test +// emits when a non-test file calls t.Errorf. +var goFileLineRe = regexp.MustCompile(`^[A-Za-z0-9_]+\.go:\d+:\s*(.+)$`) + +// testifyErrorPlaceholder is testify's "Error:" boilerplate when the +// assertion failed because of a wrapped error. The next non-blank line in +// the trace holds the actual error text. +const testifyErrorPlaceholder = "Received unexpected error:" + +// stripANSI removes CSI escapes; leaves everything else intact. +func stripANSI(s string) string { + return ansiSeq.ReplaceAllString(s, "") +} + +// extractErrorLine finds the most useful single-line summary in a failure +// body. Priority order, highest first: +// 1. Testify "Messages:" line — user-supplied context, the most signal-rich. +// 2. Testify "Error:" content (with one-line lookahead when the placeholder +// "Received unexpected error:" defers to the next line). +// 3. Leading "foo.go:NNN: text" content line — t.Errorf from non-test code. +// 4. Last `_test.go:NNN: text` line — bare t.Fatalf/Errorf from a test file. +// 5. First non-empty line of the body. +func extractErrorLine(body string) string { + body = stripANSI(body) + lines := strings.Split(body, "\n") + + var ( + msgLine string + errLine string + goFileLine string + lastTestLine string + ) + for i, raw := range lines { + l := strings.TrimSpace(raw) + if l == "" { + continue + } + if strings.HasPrefix(l, "Messages:") { + msgLine = strings.TrimSpace(strings.TrimPrefix(l, "Messages:")) + continue + } + if strings.HasPrefix(l, "Error:") && errLine == "" { + content := strings.TrimSpace(strings.TrimPrefix(l, "Error:")) + if content == testifyErrorPlaceholder { + // Look ahead for the wrapped error text on the next non-blank line. + for j := i + 1; j < len(lines); j++ { + nxt := strings.TrimSpace(lines[j]) + if nxt == "" { + continue + } + if strings.HasPrefix(nxt, "Test:") || strings.HasPrefix(nxt, "Messages:") { + break + } + content = content + " " + nxt + break + } + } + errLine = content + continue + } + if m := goFileLineRe.FindStringSubmatch(l); m != nil { + // Keep the LAST occurrence: t.Log / harness traces emit + // progress lines from the same file:line pattern before the + // failing assertion finally fires. + goFileLine = strings.TrimSpace(m[1]) + continue + } + if fileHintRe.MatchString(l) { + lastTestLine = l + } + } + switch { + case msgLine != "": + return msgLine + case errLine != "": + return errLine + case goFileLine != "": + return goFileLine + case lastTestLine != "": + // "vpc_test.go:227: Eventually: condition not met …" → trim the file prefix. + if i := strings.Index(lastTestLine, ": "); i > 0 { + return strings.TrimSpace(lastTestLine[i+2:]) + } + return lastTestLine + } + // Last resort: first non-empty line of the body. + for _, raw := range lines { + l := strings.TrimSpace(raw) + if l != "" { + return l + } + } + return "" +} + +// errorTraceRe extracts the path from testify's "Error Trace:" line — e.g. +// +// Error Trace: tests/e2e/harness/ec2helpers.go:164 +// +// — which points at the assertion site even when it lives in helper code +// outside *_test.go. +var errorTraceRe = regexp.MustCompile(`Error Trace:\s*(\S+\.go:\d+)`) + +// extractFileHint returns the most precise pointer at the assertion site +// we can pull from the failure body: testify Error Trace wins, otherwise +// the last `*_test.go:NNN` line in the body. +func extractFileHint(body string) string { + body = stripANSI(body) + if m := errorTraceRe.FindStringSubmatch(body); m != nil { + return m[1] + } + all := fileHintRe.FindAllString(body, -1) + if len(all) == 0 { + return "" + } + return all[len(all)-1] +} + +// signature normalises an error line so different runs of the same root +// cause bucket together. Empty signatures (e.g. parent-test placeholders +// where the failure body is empty) bucket together under "". +func signature(errLine string) string { + s := strings.ToLower(errLine) + for _, r := range noiseReplacers { + s = r.re.ReplaceAllString(s, r.repl) + } + return strings.TrimSpace(s) +} + +// isCascade reports whether the error line contains any of the well-known +// fixture-propagation markers — i.e. "this test failed because something +// upstream of it failed first". +func isCascade(errLine string) bool { + for _, m := range cascadeMarkers { + if strings.Contains(errLine, m) { + return true + } + } + return false +} + +// computeLeafSet returns the testcase names that are leaves — i.e. no +// other testcase name in `cases` starts with `/`. go-junit-report +// emits one for the parent Go test AND each subtest, with the +// parent's time = sum of its children, so summing every entry into the +// suite's cumulative offset double-counts. Restrict accumulation to +// leaves only. +func computeLeafSet(cases []junitTC) map[string]bool { + leaf := make(map[string]bool, len(cases)) + for _, tc := range cases { + leaf[tc.Name] = true + } + for _, tc := range cases { + // Strip the deepest path segment; any ancestor of this test is + // not a leaf. + name := tc.Name + for { + i := strings.LastIndex(name, "/") + if i <= 0 { + break + } + name = name[:i] + if _, ok := leaf[name]; ok { + leaf[name] = false + } + } + } + return leaf +} + +// parseStartTime turns a junit timestamp attr (RFC3339) into a time.Time; +// zero value if unparseable. +func parseStartTime(s string) time.Time { + if s == "" { + return time.Time{} + } + t, err := time.Parse(time.RFC3339, s) + if err != nil { + return time.Time{} + } + return t +} + +// suiteLabel turns "junit-single.xml" into "single". +func suiteLabel(path string) string { + base := filepath.Base(path) + base = strings.TrimSuffix(base, ".xml") + base = strings.TrimPrefix(base, "junit-") + if base == "" { + return filepath.Base(path) + } + return base +} + +// ParseFile decodes one junit-*.xml file into our normalized failure list. +// Returns the suite label, total testcase count, and the (ordered) failures. +func ParseFile(path string, data []byte) (SuiteReport, error) { + var doc junitSuites + if err := xml.Unmarshal(data, &doc); err != nil { + return SuiteReport{}, fmt.Errorf("parse %s: %w", path, err) + } + + rep := SuiteReport{ + File: filepath.Base(path), + Label: suiteLabel(path), + } + + order := 0 + for _, suite := range doc.Suites { + start := parseStartTime(suite.Timestamp) + // go-junit-report emits a testcase for both the parent Go test + // (e.g. `TestSingleNode`) AND each subtest (`TestSingleNode/PhaseX`). + // The parent's `time` attribute is the aggregate of its children, so + // summing every testcase double-counts. Pre-compute the leaf set so + // only leaves contribute to the suite's running offset. + isLeaf := computeLeafSet(suite.Cases) + cumul := 0.0 + for _, tc := range suite.Cases { + rep.Total++ + leaf := isLeaf[tc.Name] + var body string + switch { + case tc.Failure != nil: + body = tc.Failure.Body + case tc.Error != nil: + body = tc.Error.Body + default: + if leaf { + cumul += tc.Time + } + continue + } + + // Skip the synthetic parent-test "Failed" stub that go-junit-report + // emits for any Go test whose subtests failed. It has an empty body + // and would otherwise outrank real failures by XML order. + trimmed := strings.TrimSpace(stripANSI(body)) + if trimmed == "" { + if leaf { + cumul += tc.Time + } + continue + } + + errLine := extractErrorLine(body) + offset := time.Duration(cumul * float64(time.Second)) + f := Failure{ + SuiteFile: rep.Label, + Name: tc.Name, + Duration: tc.Time, + Order: order, + Error: errLine, + FileHint: extractFileHint(body), + Cascade: isCascade(errLine), + Signature: signature(errLine), + OffsetFromSuiteStart: offset, + } + if !start.IsZero() { + f.StartAt = start.Add(offset) + } + rep.FailCount++ + rep.Cascades = append(rep.Cascades, f) // temp staging; split below + order++ + if leaf { + cumul += tc.Time + } + } + } + + if rep.FailCount == 0 { + rep.Cascades = nil + return rep, nil + } + + all := rep.Cascades + rep.Cascades = nil + + // Root = earliest non-cascade. If every failure is a cascade (the whole + // suite tripped on the same upstream gap), fall back to earliest overall. + rootIdx := -1 + for i, f := range all { + if !f.Cascade { + rootIdx = i + break + } + } + if rootIdx == -1 { + rootIdx = 0 + } + root := all[rootIdx] + rep.Root = &root + + // Bucket the remainder by signature so the report can collapse the + // "ten failures, same bug" pattern. + bucketKeys := []string{} + buckets := map[string][]Failure{} + for i, f := range all { + if i == rootIdx { + continue + } + if _, seen := buckets[f.Signature]; !seen { + bucketKeys = append(bucketKeys, f.Signature) + } + buckets[f.Signature] = append(buckets[f.Signature], f) + rep.Cascades = append(rep.Cascades, f) + } + + // Largest bucket first; ties broken by first-seen order so output is + // deterministic across runs. + sort.SliceStable(bucketKeys, func(i, j int) bool { + return len(buckets[bucketKeys[i]]) > len(buckets[bucketKeys[j]]) + }) + for _, k := range bucketKeys { + rep.Buckets = append(rep.Buckets, buckets[k]) + } + + return rep, nil +} + +// Render writes the markdown report. Format is documented in +// docs/development/improvements/e2e-go-failure-analysis.md (Stage 1). +func Render(r Report) string { + var b strings.Builder + fmt.Fprintf(&b, "## %s\n\n", r.Title) + + totalFail := 0 + for _, s := range r.Suites { + totalFail += s.FailCount + } + if totalFail == 0 { + b.WriteString("✅ No failures across any suite.\n") + return b.String() + } + + for _, s := range r.Suites { + if s.FailCount == 0 { + fmt.Fprintf(&b, "### Suite `%s`: ✅ pass (%d tests)\n\n", s.Label, s.Total) + continue + } + fmt.Fprintf(&b, "### Suite `%s`: %d failed, 1 root cause likely\n\n", s.Label, s.FailCount) + + if s.Root != nil { + b.WriteString("**Root cause (earliest non-cascade)**\n\n") + fmt.Fprintf(&b, "- Test: `%s`\n", s.Root.Name) + if !s.Root.StartAt.IsZero() { + fmt.Fprintf(&b, "- Start: %s (duration %.1fs)\n", + s.Root.StartAt.Format("15:04:05"), s.Root.Duration) + } else { + fmt.Fprintf(&b, "- Duration: %.1fs\n", s.Root.Duration) + } + if s.Root.Error != "" { + fmt.Fprintf(&b, "- Error: %s\n", oneLine(s.Root.Error)) + } + if s.Root.FileHint != "" { + fmt.Fprintf(&b, "- File: `%s`\n", s.Root.FileHint) + } + if s.Root.BundlePath != "" { + fmt.Fprintf(&b, "- Bundle: `%s/`\n", s.Root.BundlePath) + } + b.WriteString("\n") + } + + if len(s.Buckets) > 0 { + fmt.Fprintf(&b, "**Cascaded failures (%d) — grouped by signature**\n\n", + len(s.Cascades)) + for _, bucket := range s.Buckets { + sample := bucket[0] + label := oneLine(sample.Error) + if label == "" { + label = "(no error message)" + } + fmt.Fprintf(&b, "- %d× %s\n", len(bucket), label) + // List up to 5 test names per bucket; collapse the rest. + const cap = 5 + for i, f := range bucket { + if i == cap && len(bucket) > cap { + fmt.Fprintf(&b, " - … and %d more\n", len(bucket)-cap) + break + } + if f.BundlePath != "" { + fmt.Fprintf(&b, " - `%s` → `%s/`\n", f.Name, f.BundlePath) + } else { + fmt.Fprintf(&b, " - `%s`\n", f.Name) + } + } + } + b.WriteString("\n") + } + } + + return b.String() +} + +// oneLine collapses whitespace and caps length so a runaway assertion +// message doesn't blow out the summary card width. +func oneLine(s string) string { + s = strings.TrimSpace(s) + s = strings.ReplaceAll(s, "\n", " ") + s = strings.ReplaceAll(s, "\r", " ") + s = regexp.MustCompile(`\s+`).ReplaceAllString(s, " ") + const max = 160 + if len(s) > max { + s = s[:max-1] + "…" + } + return s +} diff --git a/.github/actions/e2e-analyze/analyze_test.go b/.github/actions/e2e-analyze/analyze_test.go new file mode 100644 index 000000000..8644e3a23 --- /dev/null +++ b/.github/actions/e2e-analyze/analyze_test.go @@ -0,0 +1,191 @@ +package main + +import ( + "flag" + "os" + "path/filepath" + "sort" + "strings" + "testing" +) + +// updateGolden lets `go test ./.github/actions/e2e-analyze/ -update` rewrite +// the expected analysis.md files when the rendering format changes +// intentionally. Day-to-day, leave it unset: tests diff against the on-disk +// snapshot to catch unintended drift in signature extraction or layout. +var updateGolden = flag.Bool("update", false, "rewrite testdata/*/analysis.md from current output") + +// TestGoldenFixtures runs the full ParseFile + Render pipeline against each +// fixture directory under testdata/ and asserts the output matches the +// adjacent analysis.md snapshot. Each subdir is one named scenario; the +// fixture XMLs match the same junit-*.xml glob the production action uses +// so behaviour stays representative of CI. +func TestGoldenFixtures(t *testing.T) { + entries, err := os.ReadDir("testdata") + if err != nil { + t.Fatalf("read testdata: %v", err) + } + for _, e := range entries { + if !e.IsDir() { + continue + } + name := e.Name() + t.Run(name, func(t *testing.T) { + dir := filepath.Join("testdata", name) + matches, err := filepath.Glob(filepath.Join(dir, "junit-*.xml")) + if err != nil { + t.Fatalf("glob: %v", err) + } + sort.Strings(matches) + if len(matches) == 0 { + t.Fatalf("no junit-*.xml fixtures in %s", dir) + } + + rep := Report{Title: "E2E failure analysis"} + for _, p := range matches { + data, err := os.ReadFile(p) + if err != nil { + t.Fatalf("read %s: %v", p, err) + } + sr, err := ParseFile(p, data) + if err != nil { + t.Fatalf("parse %s: %v", p, err) + } + rep.Suites = append(rep.Suites, sr) + } + + got := Render(rep) + goldenPath := filepath.Join(dir, "analysis.md") + if *updateGolden { + if err := os.WriteFile(goldenPath, []byte(got), 0o644); err != nil { + t.Fatalf("write golden: %v", err) + } + return + } + want, err := os.ReadFile(goldenPath) + if err != nil { + t.Fatalf("read golden (run with -update to seed): %v", err) + } + if string(want) != got { + t.Errorf("rendered output differs from %s\n--- want ---\n%s\n--- got ---\n%s", + goldenPath, string(want), got) + } + }) + } +} + +func TestSignatureCollapsesNoise(t *testing.T) { + a := signature("describe-vpcs: InvalidParameterValue request-id: abc-123 vpc-deadbeefcafe1234") + b := signature("describe-vpcs: InvalidParameterValue request-id: xyz-999 vpc-1111222233334444") + if a != b { + t.Errorf("signatures should collapse to same bucket:\n a=%q\n b=%q", a, b) + } + if !strings.Contains(a, "") || !strings.Contains(a, "vpc-") { + t.Errorf("expected normalised placeholders in signature, got %q", a) + } +} + +func TestCascadeDetection(t *testing.T) { + cases := []struct { + in string + want bool + }{ + {"Phase 5 must populate fix.InstanceID", true}, + {"Should NOT be empty", true}, + {"Expected value not to be nil", true}, + {"describe-vpcs: InvalidParameterValue", false}, + {"Eventually: condition not met within 3m0s", false}, + } + for _, c := range cases { + if got := isCascade(c.in); got != c.want { + t.Errorf("isCascade(%q) = %v, want %v", c.in, got, c.want) + } + } +} + +func TestExtractErrorLine_MessagesWinsOverError(t *testing.T) { + body := ` lifecycle_test.go:28: + Error Trace: tests/e2e/single/lifecycle_test.go:28 + Error: Should NOT be empty + Messages: Phase 5 must populate fix.InstanceID + Test: TestSingleNode/Phase5a_pre_ClusterStats` + got := extractErrorLine(body) + want := "Phase 5 must populate fix.InstanceID" + if got != want { + t.Errorf("extractErrorLine = %q, want %q", got, want) + } +} + +func TestExtractErrorLine_FallsBackToLastTestLine(t *testing.T) { + body := " vpc_test.go:227: Eventually: condition not met within 3m0s: [SSH handshake never completed]" + got := extractErrorLine(body) + if !strings.HasPrefix(got, "Eventually:") { + t.Errorf("expected fallback to test-line content, got %q", got) + } +} + +func TestExtractFileHint_PicksLastMatch(t *testing.T) { + body := "ec2helpers.go:50: setup\n vpc_test.go:227: Eventually: condition not met" + got := extractFileHint(body) + want := "vpc_test.go:227" + if got != want { + t.Errorf("extractFileHint = %q, want %q", got, want) + } +} + +func TestParseFile_SkipsEmptyParentFailure(t *testing.T) { + // The synthetic "TestSingleNode" parent gets a + // with no body whenever any subtest fails. The analyzer must skip it so + // it doesn't outrank the real first failure on XML order. + 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 (empty parent should be skipped)", sr.FailCount) + } + if sr.Root == nil || sr.Root.Name != "TestX/RealFailure" { + t.Fatalf("expected real failure as root, got %+v", sr.Root) + } +} + +func TestParseFile_CascadeFallbackWhenAllCascades(t *testing.T) { + // If every failure is a cascade marker, the earliest one becomes root + // so the report isn't blank. + xml := []byte(` + + + +`) + sr, err := ParseFile("junit-x.xml", xml) + if err != nil { + t.Fatalf("ParseFile: %v", err) + } + if sr.Root == nil || sr.Root.Name != "TestX/A" { + t.Fatalf("expected TestX/A as fallback root, got %+v", sr.Root) + } +} + +func TestRender_NoFailuresIsClean(t *testing.T) { + out := Render(Report{ + Title: "E2E failure analysis", + Suites: []SuiteReport{ + {File: "junit-single.xml", Label: "single", Total: 3, FailCount: 0}, + }, + }) + if !strings.Contains(out, "No failures") { + t.Errorf("expected zero-failure banner, got:\n%s", out) + } +} diff --git a/.github/actions/e2e-analyze/bundle.go b/.github/actions/e2e-analyze/bundle.go new file mode 100644 index 000000000..be974e0cc --- /dev/null +++ b/.github/actions/e2e-analyze/bundle.go @@ -0,0 +1,208 @@ +package main + +// Stage 2 of docs/development/improvements/e2e-go-failure-analysis.md: +// for each failure surfaced by Stage 1, materialise a per-failure bundle +// directory containing the failure summary, a time-window slice of the +// daemon journal, a testcase-window slice of the suite's stdout log, and +// any per-test artifacts the harness already dumped at run-time. + +import ( + "errors" + "fmt" + "io/fs" + "os" + "path/filepath" + "regexp" + "strings" + "time" +) + +// bundlePad is the per-failure window padding either side of the +// [StartAt, StartAt+Duration] testcase span. Five seconds matches the +// plan doc: long enough to catch the daemon's pre-test setup and +// post-test cleanup chatter, short enough to keep the slice focused. +const bundlePad = 5 * time.Second + +// nameSanitiseRe replaces characters unsafe in directory names with `_`. +// Tracks tests/e2e/harness/artifacts.go which uses the same convention +// when the test's own dump dir is created, so we can pick its contents +// up by path without a second translation table. +var nameSanitiseRe = regexp.MustCompile(`[^A-Za-z0-9._-]+`) + +func sanitiseTestName(s string) string { + return nameSanitiseRe.ReplaceAllString(s, "_") +} + +// ApplySuiteStartFiles overrides each failure's StartAt by reading +// /test-.start (RFC3339 timestamp written by the +// workflow before the suite runs). Required because go-junit-report's +// `timestamp` attribute on records the time the XML was +// produced — i.e. after the suite has finished — so it can't be used +// as the suite wall-clock origin for journal slicing. +// +// Missing or unparseable files are silently ignored: the analyzer +// falls back to the junit timestamp and the bundle still gets created, +// it just may have an empty (or off-window) journal slice. +func ApplySuiteStartFiles(rep *Report, logDir string) { + if logDir == "" { + return + } + for si := range rep.Suites { + s := &rep.Suites[si] + startPath := filepath.Join(logDir, fmt.Sprintf("test-%s.start", s.Label)) + data, err := os.ReadFile(startPath) + if err != nil { + continue + } + ts, err := time.Parse(time.RFC3339, strings.TrimSpace(string(data))) + if err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: parse %s: %v\n", startPath, err) + continue + } + if s.Root != nil { + s.Root.StartAt = ts.Add(s.Root.OffsetFromSuiteStart) + } + for ci := range s.Cascades { + s.Cascades[ci].StartAt = ts.Add(s.Cascades[ci].OffsetFromSuiteStart) + } + for bi := range s.Buckets { + for fi := range s.Buckets[bi] { + f := &s.Buckets[bi][fi] + f.StartAt = ts.Add(f.OffsetFromSuiteStart) + } + } + } +} + +// WriteBundles materialises per-failure bundles under /analysis/. +// Mutates rep in-place so each Failure.BundlePath holds the relative +// path the renderer will link from the summary. +// +// Failures with no parseable wall-clock start still get a bundle dir +// (and the testcase-window test.log slice), but no journal slice — the +// time window is unknown. +// +// Errors are non-fatal: a bundle that partially fails still gets linked +// from the report so a reader sees what's available, and the analyzer +// keeps printing warnings so CI logs surface the gap. +func WriteBundles(rep *Report, logDir string) { + if logDir == "" { + return + } + base := filepath.Join(logDir, "analysis") + if err := os.MkdirAll(base, 0o755); err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: mkdir %s: %v\n", base, err) + return + } + + for si := range rep.Suites { + s := &rep.Suites[si] + if s.Root != nil { + writeOneBundle(logDir, base, s.Label, s.Root) + } + for ci := range s.Cascades { + writeOneBundle(logDir, base, s.Label, &s.Cascades[ci]) + } + // Bucket entries share storage with Cascades but live in a + // separate slice in SuiteReport; mirror the bundle path so the + // renderer's bucket loop sees it too. + for bi := range s.Buckets { + for fi := range s.Buckets[bi] { + f := &s.Buckets[bi][fi] + if bp := findBundlePath(s, f.Name); bp != "" { + f.BundlePath = bp + } + } + } + } +} + +// findBundlePath looks up a Failure's already-written BundlePath by test +// name within a suite. Buckets reference the same logical failure as +// Cascades but are independent slice values, so we copy the path across +// rather than re-deriving it. +func findBundlePath(s *SuiteReport, testName string) string { + if s.Root != nil && s.Root.Name == testName { + return s.Root.BundlePath + } + for _, c := range s.Cascades { + if c.Name == testName { + return c.BundlePath + } + } + return "" +} + +func writeOneBundle(logDir, base, suiteLabel string, f *Failure) { + name := fmt.Sprintf("%02d-%s", f.Order+1, sanitiseTestName(f.Name)) + dir := filepath.Join(base, name) + if err := os.MkdirAll(dir, 0o755); err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: mkdir %s: %v\n", dir, err) + return + } + f.BundlePath = filepath.Join("analysis", name) + + writeFailureSummary(dir, suiteLabel, f) + + if !f.StartAt.IsZero() { + start := f.StartAt.Add(-bundlePad) + end := f.StartAt.Add(time.Duration(f.Duration * float64(time.Second))).Add(bundlePad) + journalSrc := filepath.Join(logDir, "spinifex-journal.log") + if _, err := SliceJournal(journalSrc, start, end, filepath.Join(dir, "journal.log")); err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: slice journal for %s: %v\n", f.Name, err) + } + } + + testLogSrc := filepath.Join(logDir, fmt.Sprintf("test-%s.log", suiteLabel)) + if _, err := SliceTestLog(testLogSrc, f.Name, filepath.Join(dir, "test.log")); err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: slice test log for %s: %v\n", f.Name, err) + } + + // Per-test artifact subdir written by harness.ArtifactDir lives at + // //. Copy any files into + // the bundle so qemu/ovs/etc. dumps already collected by the test + // travel alongside the analysis. + perTestSrc := filepath.Join(logDir, strings.ReplaceAll(f.Name, "/", "_")) + if entries, err := os.ReadDir(perTestSrc); err == nil { + for _, e := range entries { + if e.IsDir() { + continue + } + _ = copyFile(filepath.Join(perTestSrc, e.Name()), filepath.Join(dir, e.Name())) + } + } else if !os.IsNotExist(err) && !errorsIsNotDir(err) { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: read per-test dir %s: %v\n", perTestSrc, err) + } +} + +// errorsIsNotDir handles the case where the harness wrote a file at the +// per-test name instead of a directory — best-effort skip. +func errorsIsNotDir(err error) bool { + var pe *fs.PathError + if !errors.As(err, &pe) { + return false + } + return pe.Err != nil && strings.Contains(pe.Err.Error(), "not a directory") +} + +func writeFailureSummary(dir, suiteLabel string, f *Failure) { + var b strings.Builder + fmt.Fprintf(&b, "Suite: %s\n", suiteLabel) + fmt.Fprintf(&b, "Test: %s\n", f.Name) + if !f.StartAt.IsZero() { + fmt.Fprintf(&b, "Start: %s\n", f.StartAt.Format(time.RFC3339)) + } + fmt.Fprintf(&b, "Duration: %.3fs\n", f.Duration) + if f.FileHint != "" { + fmt.Fprintf(&b, "Site: %s\n", f.FileHint) + } + if f.Cascade { + b.WriteString("Cascade: yes (downstream of another failure)\n") + } + if f.Error != "" { + b.WriteString("\nError:\n") + b.WriteString(oneLine(f.Error)) + b.WriteString("\n") + } + _ = os.WriteFile(filepath.Join(dir, "failure.txt"), []byte(b.String()), 0o644) +} diff --git a/.github/actions/e2e-analyze/bundle_test.go b/.github/actions/e2e-analyze/bundle_test.go new file mode 100644 index 000000000..0957fe3c0 --- /dev/null +++ b/.github/actions/e2e-analyze/bundle_test.go @@ -0,0 +1,229 @@ +package main + +import ( + "fmt" + "os" + "path/filepath" + "strings" + "testing" + "time" +) + +func TestSliceJournal_KeepsOnlyWindow(t *testing.T) { + src := filepath.Join(t.TempDir(), "journal.log") + dst := filepath.Join(t.TempDir(), "out.log") + body := strings.Join([]string{ + "2026-05-19T12:32:30+1000 host spinifex-daemon[1]: pre", + " continuation of pre", + "2026-05-19T12:32:35+1000 host spinifex-daemon[1]: IN window", + " multiline inside window", + "2026-05-19T12:32:45+1000 host spinifex-daemon[1]: post", + "", + }, "\n") + if err := os.WriteFile(src, []byte(body), 0o644); err != nil { + t.Fatalf("write src: %v", err) + } + start, _ := time.Parse(time.RFC3339, "2026-05-19T12:32:33+10:00") + end, _ := time.Parse(time.RFC3339, "2026-05-19T12:32:40+10:00") + n, err := SliceJournal(src, start, end, dst) + if err != nil { + t.Fatalf("SliceJournal: %v", err) + } + if n != 2 { + t.Fatalf("written = %d, want 2", n) + } + got, _ := os.ReadFile(dst) + if !strings.Contains(string(got), "IN window") || !strings.Contains(string(got), "multiline inside window") { + t.Errorf("missing in-window content:\n%s", got) + } + if strings.Contains(string(got), "pre") || strings.Contains(string(got), "post") { + t.Errorf("kept out-of-window content:\n%s", got) + } +} + +func TestSliceJournal_AcceptsRFC3339ColonOffset(t *testing.T) { + // systemd's `journalctl --output=short-iso` ships RFC3339 timestamps + // (offset includes a colon, e.g. "+10:00") on most versions. Earlier + // regex only matched "+1000" — make sure both forms work. + src := filepath.Join(t.TempDir(), "journal.log") + dst := filepath.Join(t.TempDir(), "out.log") + body := strings.Join([]string{ + "2026-05-19T12:32:30+10:00 host spinifex-daemon[1]: pre", + "2026-05-19T12:32:35+10:00 host spinifex-daemon[1]: IN window", + "2026-05-19T12:32:50+10:00 host spinifex-daemon[1]: post", + "", + }, "\n") + if err := os.WriteFile(src, []byte(body), 0o644); err != nil { + t.Fatalf("write src: %v", err) + } + start, _ := time.Parse(time.RFC3339, "2026-05-19T12:32:33+10:00") + end, _ := time.Parse(time.RFC3339, "2026-05-19T12:32:40+10:00") + n, err := SliceJournal(src, start, end, dst) + if err != nil { + t.Fatalf("SliceJournal: %v", err) + } + if n != 1 { + t.Fatalf("written = %d, want 1", n) + } + got, _ := os.ReadFile(dst) + if !strings.Contains(string(got), "IN window") { + t.Errorf("missing in-window content:\n%s", got) + } +} + +func TestSliceJournal_MissingSrcIsNotError(t *testing.T) { + dst := filepath.Join(t.TempDir(), "out.log") + n, err := SliceJournal("/no/such/file", time.Now(), time.Now(), dst) + if err != nil { + t.Fatalf("unexpected err: %v", err) + } + if n != 0 { + t.Errorf("written = %d, want 0", n) + } +} + +func TestSliceTestLog_PicksOneTestcase(t *testing.T) { + src := filepath.Join(t.TempDir(), "test.log") + dst := filepath.Join(t.TempDir(), "out.log") + body := strings.Join([]string{ + "=== RUN TestSingleNode", + " before subtests", + "=== RUN TestSingleNode/Phase5_LaunchInstance", + " runinstances", + " ec2helpers.go:164: describe-vpcs: InvalidParameterValue", + "--- FAIL: TestSingleNode/Phase5_LaunchInstance (2.50s)", + "=== RUN TestSingleNode/Phase6_Volumes", + " other content", + "--- FAIL: TestSingleNode/Phase6_Volumes (0.10s)", + "--- FAIL: TestSingleNode (10.0s)", + "", + }, "\n") + if err := os.WriteFile(src, []byte(body), 0o644); err != nil { + t.Fatalf("write src: %v", err) + } + n, err := SliceTestLog(src, "TestSingleNode/Phase5_LaunchInstance", dst) + if err != nil { + t.Fatalf("SliceTestLog: %v", err) + } + if n != 4 { + t.Fatalf("written = %d, want 4 (RUN + 2 inner + FAIL)", n) + } + got, _ := os.ReadFile(dst) + s := string(got) + if !strings.Contains(s, "describe-vpcs: InvalidParameterValue") { + t.Errorf("missing failure line:\n%s", s) + } + if strings.Contains(s, "Phase6_Volumes") || strings.Contains(s, "before subtests") { + t.Errorf("leaked sibling test content:\n%s", s) + } +} + +func TestSliceTestLog_UnknownTestcaseIsEmpty(t *testing.T) { + src := filepath.Join(t.TempDir(), "test.log") + dst := filepath.Join(t.TempDir(), "out.log") + if err := os.WriteFile(src, []byte("=== RUN TestX\n--- PASS: TestX (0.0s)\n"), 0o644); err != nil { + t.Fatalf("write src: %v", err) + } + n, err := SliceTestLog(src, "TestY", dst) + if err != nil { + t.Fatalf("SliceTestLog: %v", err) + } + if n != 0 { + t.Errorf("written = %d, want 0", n) + } + if _, err := os.Stat(dst); err != nil { + t.Errorf("dst not created: %v", err) + } +} + +// TestWriteBundles_EndToEnd builds a fake artifact dir with a junit XML, +// a journal log, a test log, and a per-test artifact subdir, then runs +// the full ParseFile → WriteBundles pipeline and asserts the bundle dir +// contains everything the report links to. +func TestWriteBundles_EndToEnd(t *testing.T) { + dir := t.TempDir() + + junit := ` + + + + +` + if err := os.WriteFile(filepath.Join(dir, "junit-single.xml"), []byte(junit), 0o644); err != nil { + t.Fatalf("write junit: %v", err) + } + + journal := strings.Join([]string{ + "2026-05-19T12:32:20+1000 host spinifex-daemon[1]: too-early", + "2026-05-19T12:32:30+1000 host spinifex-daemon[1]: in-window-start", + "2026-05-19T12:32:32+1000 host spinifex-daemon[1]: describe-vpcs filter=is_default", + "2026-05-19T12:32:50+1000 host spinifex-daemon[1]: too-late", + "", + }, "\n") + if err := os.WriteFile(filepath.Join(dir, "spinifex-journal.log"), []byte(journal), 0o644); err != nil { + t.Fatalf("write journal: %v", err) + } + + testlog := strings.Join([]string{ + "=== RUN TestSingleNode/Phase5_LaunchInstance", + " ec2helpers.go:164: describe-vpcs: InvalidParameterValue", + "--- FAIL: TestSingleNode/Phase5_LaunchInstance (2.50s)", + "", + }, "\n") + if err := os.WriteFile(filepath.Join(dir, "test-single.log"), []byte(testlog), 0o644); err != nil { + t.Fatalf("write test log: %v", err) + } + + // Per-test artifact subdir (matches harness.ArtifactDir convention). + perTest := filepath.Join(dir, "TestSingleNode_Phase5_LaunchInstance") + if err := os.MkdirAll(perTest, 0o755); err != nil { + t.Fatalf("mkdir per-test: %v", err) + } + if err := os.WriteFile(filepath.Join(perTest, "qemu-console.log"), []byte("[qemu] boot\n"), 0o644); err != nil { + t.Fatalf("write per-test file: %v", err) + } + + data, _ := os.ReadFile(filepath.Join(dir, "junit-single.xml")) + sr, err := ParseFile("junit-single.xml", data) + if err != nil { + t.Fatalf("ParseFile: %v", err) + } + rep := Report{Title: "E2E failure analysis", Suites: []SuiteReport{sr}} + WriteBundles(&rep, dir) + + if rep.Suites[0].Root == nil { + t.Fatal("no root") + } + bp := rep.Suites[0].Root.BundlePath + if bp == "" { + t.Fatal("BundlePath not set") + } + bundle := filepath.Join(dir, bp) + for _, want := range []string{"failure.txt", "journal.log", "test.log", "qemu-console.log"} { + if _, err := os.Stat(filepath.Join(bundle, want)); err != nil { + t.Errorf("missing %s in bundle %s: %v", want, bp, err) + } + } + + jl, _ := os.ReadFile(filepath.Join(bundle, "journal.log")) + if !strings.Contains(string(jl), "describe-vpcs filter=is_default") { + t.Errorf("journal.log lacks in-window line:\n%s", jl) + } + if strings.Contains(string(jl), "too-early") || strings.Contains(string(jl), "too-late") { + t.Errorf("journal.log includes out-of-window content:\n%s", jl) + } + + tl, _ := os.ReadFile(filepath.Join(bundle, "test.log")) + if !strings.Contains(string(tl), "--- FAIL: TestSingleNode/Phase5_LaunchInstance") { + t.Errorf("test.log missing FAIL marker:\n%s", tl) + } + + out := Render(rep) + wantLink := fmt.Sprintf("- Bundle: `%s/`", bp) + if !strings.Contains(out, wantLink) { + t.Errorf("render missing bundle link %q:\n%s", wantLink, out) + } +} diff --git a/.github/actions/e2e-analyze/main.go b/.github/actions/e2e-analyze/main.go new file mode 100644 index 000000000..f1e449604 --- /dev/null +++ b/.github/actions/e2e-analyze/main.go @@ -0,0 +1,78 @@ +package main + +import ( + "flag" + "fmt" + "os" + "path/filepath" + "sort" +) + +func main() { + var junitGlob, logDir, title string + flag.StringVar(&junitGlob, "junit-glob", os.Getenv("ANALYZE_JUNIT_GLOB"), "glob matching junit-*.xml files") + flag.StringVar(&logDir, "log-dir", os.Getenv("ANALYZE_LOG_DIR"), "artifact dir to write analysis.md into") + flag.StringVar(&title, "title", os.Getenv("ANALYZE_TITLE"), "report heading") + flag.Parse() + + if title == "" { + title = "E2E failure analysis" + } + if junitGlob == "" { + fmt.Fprintln(os.Stderr, "::error::e2e-analyze: -junit-glob is required") + os.Exit(0) // analyzer is advisory only; existing gate owns exit code + } + + paths, err := filepath.Glob(junitGlob) + if err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: bad glob %q: %v\n", junitGlob, err) + os.Exit(0) + } + sort.Strings(paths) + + report := Report{Title: title} + for _, p := range paths { + data, err := os.ReadFile(p) + if err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: read %s: %v\n", p, err) + continue + } + sr, err := ParseFile(p, data) + if err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: %v\n", err) + continue + } + report.Suites = append(report.Suites, sr) + } + + // Stage 2: prefer authoritative per-suite start times written by the + // workflow over junit-report's conversion-time `timestamp` attribute, + // then materialise per-failure bundles so Render can link them. + if logDir != "" { + ApplySuiteStartFiles(&report, logDir) + WriteBundles(&report, logDir) + } + + out := Render(report) + + if logDir != "" { + if err := os.MkdirAll(logDir, 0o755); err == nil { + if err := os.WriteFile(filepath.Join(logDir, "analysis.md"), []byte(out), 0o644); err != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: write analysis.md: %v\n", err) + } + } + } + + if summaryPath := os.Getenv("GITHUB_STEP_SUMMARY"); summaryPath != "" { + f, err := os.OpenFile(summaryPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) + if err == nil { + defer f.Close() + if _, werr := f.WriteString(out); werr != nil { + fmt.Fprintf(os.Stderr, "::warning::e2e-analyze: append summary: %v\n", werr) + } + } + } else { + // Local invocation (developer running the tool by hand). Mirror to stdout. + fmt.Print(out) + } +} diff --git a/.github/actions/e2e-analyze/slice.go b/.github/actions/e2e-analyze/slice.go new file mode 100644 index 000000000..5f831af17 --- /dev/null +++ b/.github/actions/e2e-analyze/slice.go @@ -0,0 +1,176 @@ +package main + +// Stage 2 of docs/development/improvements/e2e-go-failure-analysis.md: +// per-failure log slicers used by bundle.go to materialise time-window / +// testcase-window log excerpts next to each named failure. + +import ( + "bufio" + "io" + "os" + "regexp" + "strings" + "time" +) + +// shortIsoTSRe matches the timestamp prefix produced by +// `journalctl --output=short-iso`. The offset format varies across +// systemd versions: most ship "+10:00" (RFC3339), some ship "+1000" +// (no colon). Match either — the parser below picks the right layout. +var shortIsoTSRe = regexp.MustCompile(`^(\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:[+-]\d{2}:?\d{2}|Z))\s`) + +// shortIsoLayouts are tried in order; the first parse that succeeds wins. +var shortIsoLayouts = []string{ + time.RFC3339, // 2026-05-19T12:32:30+10:00 + "2006-01-02T15:04:05-0700", // 2026-05-19T12:32:30+1000 +} + +func parseShortIso(s string) (time.Time, error) { + var lastErr error + for _, layout := range shortIsoLayouts { + t, err := time.Parse(layout, s) + if err == nil { + return t, nil + } + lastErr = err + } + return time.Time{}, lastErr +} + +// SliceJournal copies lines from src whose `short-iso` timestamp falls in +// [start, end] to dst. Lines without a parseable timestamp inherit the +// previous line's classification — that keeps multi-line journal records +// (stack traces, panics) intact rather than orphaning their continuation +// lines. Lines that precede the first parseable timestamp are dropped. +// +// Returns the number of lines written; missing src is not an error (the +// journal may be empty if collection failed). +func SliceJournal(src string, start, end time.Time, dst string) (int, error) { + f, err := os.Open(src) + if err != nil { + if os.IsNotExist(err) { + return 0, nil + } + return 0, err + } + defer f.Close() + + out, err := os.Create(dst) + if err != nil { + return 0, err + } + defer out.Close() + + bw := bufio.NewWriter(out) + defer bw.Flush() + + sc := bufio.NewScanner(f) + // Journal lines can be long (panic dumps); bump scanner buffer. + sc.Buffer(make([]byte, 0, 64*1024), 1024*1024) + + keep := false + written := 0 + for sc.Scan() { + line := sc.Text() + if m := shortIsoTSRe.FindStringSubmatch(line); m != nil { + ts, err := parseShortIso(m[1]) + if err != nil { + continue + } + keep = !ts.Before(start) && !ts.After(end) + } + if keep { + if _, err := bw.WriteString(line); err != nil { + return written, err + } + if err := bw.WriteByte('\n'); err != nil { + return written, err + } + written++ + } + } + return written, sc.Err() +} + +// runRePrefix and finishRePrefix bracket a single testcase's output in +// `go test -v` stdout. Subtests have their own `=== RUN` / `--- FAIL` +// markers, so slicing on the exact testcase name yields just that test's +// lines (including any nested phase logs). +var ( + runRe = regexp.MustCompile(`^=== RUN\s+(\S+)$`) + finishRe = regexp.MustCompile(`^\s*---\s+(PASS|FAIL|SKIP):\s+(\S+)\s+\(`) +) + +// SliceTestLog copies lines belonging to the named testcase from src to +// dst. The block starts at `=== RUN ` and ends at the matching +// `--- PASS|FAIL|SKIP: (…)` line (inclusive). If the testcase is +// never seen the destination file is created empty so the bundle has a +// stable shape. +// +// Returns the number of lines written; missing src is not an error. +func SliceTestLog(src, testName, dst string) (int, error) { + f, err := os.Open(src) + if err != nil { + if os.IsNotExist(err) { + return 0, nil + } + return 0, err + } + defer f.Close() + + out, err := os.Create(dst) + if err != nil { + return 0, err + } + defer out.Close() + + bw := bufio.NewWriter(out) + defer bw.Flush() + + sc := bufio.NewScanner(f) + sc.Buffer(make([]byte, 0, 64*1024), 1024*1024) + + in := false + written := 0 + for sc.Scan() { + line := sc.Text() + if !in { + if m := runRe.FindStringSubmatch(strings.TrimRight(line, "\r")); m != nil && m[1] == testName { + in = true + } else { + continue + } + } + if _, err := bw.WriteString(line); err != nil { + return written, err + } + if err := bw.WriteByte('\n'); err != nil { + return written, err + } + written++ + if m := finishRe.FindStringSubmatch(line); m != nil && m[2] == testName { + return written, nil + } + } + return written, sc.Err() +} + +// copyFile is a small helper used when bundling pre-collected per-test +// artifacts. Best-effort: missing src is silently skipped. +func copyFile(src, dst string) error { + in, err := os.Open(src) + if err != nil { + if os.IsNotExist(err) { + return nil + } + return err + } + defer in.Close() + out, err := os.Create(dst) + if err != nil { + return err + } + defer out.Close() + _, err = io.Copy(out, in) + return err +} diff --git a/.github/actions/e2e-analyze/testdata/cascade-vpcs/analysis.md b/.github/actions/e2e-analyze/testdata/cascade-vpcs/analysis.md new file mode 100644 index 000000000..b5be0ecb8 --- /dev/null +++ b/.github/actions/e2e-analyze/testdata/cascade-vpcs/analysis.md @@ -0,0 +1,23 @@ +## E2E failure analysis + +### Suite `single`: 16 failed, 1 root cause likely + +**Root cause (earliest non-cascade)** + +- Test: `TestSingleNode/Phase5_LaunchInstance` +- Start: 12:30:00 (duration 2.5s) +- Error: Received unexpected error: InvalidParameterValue (HTTP 400) +- File: `tests/e2e/harness/ec2helpers.go:164` + +**Cascaded failures (15) — grouped by signature** + +- 14× Phase 5 must populate fix.InstanceID + - `TestSingleNode/Phase5a_pre_ClusterStats` + - `TestSingleNode/Phase5a_Metadata` + - `TestSingleNode/Phase5b_DescribeInstances` + - `TestSingleNode/Phase5c_StopStart` + - `TestSingleNode/Phase6_Volumes` + - … and 9 more +- 1× Phase 2 must populate fix.AZName + - `TestSingleNode/Phase8_NatGW` + diff --git a/.github/actions/e2e-analyze/testdata/cascade-vpcs/junit-single.xml b/.github/actions/e2e-analyze/testdata/cascade-vpcs/junit-single.xml new file mode 100644 index 000000000..e40abfc99 --- /dev/null +++ b/.github/actions/e2e-analyze/testdata/cascade-vpcs/junit-single.xml @@ -0,0 +1,143 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + diff --git a/.github/actions/e2e-analyze/testdata/no-failures/analysis.md b/.github/actions/e2e-analyze/testdata/no-failures/analysis.md new file mode 100644 index 000000000..d95cea666 --- /dev/null +++ b/.github/actions/e2e-analyze/testdata/no-failures/analysis.md @@ -0,0 +1,3 @@ +## E2E failure analysis + +✅ No failures across any suite. diff --git a/.github/actions/e2e-analyze/testdata/no-failures/junit-single.xml b/.github/actions/e2e-analyze/testdata/no-failures/junit-single.xml new file mode 100644 index 000000000..a0f7000b5 --- /dev/null +++ b/.github/actions/e2e-analyze/testdata/no-failures/junit-single.xml @@ -0,0 +1,8 @@ + + + + + + + + diff --git a/.github/actions/e2e-analyze/testdata/single-failure/analysis.md b/.github/actions/e2e-analyze/testdata/single-failure/analysis.md new file mode 100644 index 000000000..b2a02471a --- /dev/null +++ b/.github/actions/e2e-analyze/testdata/single-failure/analysis.md @@ -0,0 +1,11 @@ +## E2E failure analysis + +### Suite `single`: 1 failed, 1 root cause likely + +**Root cause (earliest non-cascade)** + +- Test: `TestSingleNode/Phase8b_VPCSubnetE2E` +- Start: 00:26:18 (duration 200.5s) +- Error: Eventually: condition not met within 3m0s: [SSH handshake 192.168.0.202:22 never completed] +- File: `vpc_test.go:227` + diff --git a/.github/actions/e2e-analyze/testdata/single-failure/junit-single.xml b/.github/actions/e2e-analyze/testdata/single-failure/junit-single.xml new file mode 100644 index 000000000..55e89222c --- /dev/null +++ b/.github/actions/e2e-analyze/testdata/single-failure/junit-single.xml @@ -0,0 +1,993 @@ + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + i-0c615e5dd74050f53 as /dev/sdf�[0m + volume_test.go:68: �[2m· attach-volume vol-a885f79173e0a8030 -> i-0c615e5dd74050f53 as /dev/sdf�[0m + volume_test.go:76: volume vol-a885f79173e0a8030 reached state in-use +�[2m· detach-volume vol-a885f79173e0a8030�[0m + volume_test.go:90: �[2m· detach-volume vol-a885f79173e0a8030�[0m + volume_test.go:96: volume vol-a885f79173e0a8030 reached state available +�[2m· delete-volume vol-a885f79173e0a8030�[0m + volume_test.go:98: �[2m· delete-volume vol-a885f79173e0a8030�[0m]]> + + + + + + + + + + + + + + + + + + e2e-test-updated�[0m + tags_test.go:95: �[2m· 6f overwrite instance Name -> e2e-test-updated�[0m +�[2m· 6g delete-tags Key=DeleteMe (no value)�[0m + tags_test.go:114: �[2m· 6g delete-tags Key=DeleteMe (no value)�[0m +�[2m· 6h delete-tags Key=Environment,Value=production (no-op)�[0m + tags_test.go:130: �[2m· 6h delete-tags Key=Environment,Value=production (no-op)�[0m +�[2m· 6i delete-tags Key=Environment,Value=testing (instance only)�[0m + tags_test.go:148: �[2m· 6i delete-tags Key=Environment,Value=testing (instance only)�[0m +�[2m· 6j final describe-tags resource-id=i-0c615e5dd74050f53 want=1�[0m + tags_test.go:171: �[2m· 6j final describe-tags resource-id=i-0c615e5dd74050f53 want=1�[0m]]> + + + + + + i-0c615e5dd74050f53 (should fail)�[0m + lifecycle_test.go:84: �[2m· attach-volume vol-8d3e1335938a378cd -> i-0c615e5dd74050f53 (should fail)�[0m +�[2m· delete-volume vol-8d3e1335938a378cd�[0m + lifecycle_test.go:94: �[2m· delete-volume vol-8d3e1335938a378cd�[0m]]> + + + + + + + + + 1 ━━�[0m +�[2m· run-instances ami=ami-6f60f2b3bf04b5453 type=t3.small count=2�[0m + lifecycle_test.go:309: �[2m· run-instances ami=ami-6f60f2b3bf04b5453 type=t3.small count=2�[0m +�[2msibling_1�[0m=i-9bfadd8ebd378f846 �[2msibling_2�[0m=i-448a9e2bf45c58658 + lifecycle_test.go:327: �[2msibling_1�[0m=i-9bfadd8ebd378f846 �[2msibling_2�[0m=i-448a9e2bf45c58658 + lifecycle_test.go:342: instance i-9bfadd8ebd378f846 reached state running + lifecycle_test.go:342: instance i-448a9e2bf45c58658 reached state running +�[2m· terminate-instances i-9bfadd8ebd378f846 i-448a9e2bf45c58658�[0m + lifecycle_test.go:345: �[2m· terminate-instances i-9bfadd8ebd378f846 i-448a9e2bf45c58658�[0m + lifecycle_test.go:352: instance i-9bfadd8ebd378f846 reached state terminated + lifecycle_test.go:352: instance i-448a9e2bf45c58658 reached state terminated]]> + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + + =3 root+alice+bob)�[0m + iam_test.go:148: �[2m· list-users (>=3 root+alice+bob)�[0m +�[2m· list-users --path-prefix "/engineering/" (expect 1)�[0m + iam_test.go:154: �[2m· list-users --path-prefix "/engineering/" (expect 1)�[0m + iam_test.go:193: �[2m· create-user "iam-phase1-ephemeral" (delete idempotency probe)�[0m +�[2m· delete-user "iam-phase1-ephemeral"�[0m + iam_test.go:197: �[2m· delete-user "iam-phase1-ephemeral"�[0m +�[2m· delete-user "iam-phase1-ephemeral" again (expect NoSuchEntity)�[0m + iam_test.go:201: �[2m· delete-user "iam-phase1-ephemeral" again (expect NoSuchEntity)�[0m]]> + + + + + + Inactive�[0m + iam_test.go:268: �[2m· update-access-key AKIA4984AE57CF8D721A879A -> Inactive�[0m +�[2m· update-access-key AKIA4984AE57CF8D721A879A -> Active�[0m + iam_test.go:279: �[2m· update-access-key AKIA4984AE57CF8D721A879A -> Active�[0m +�[2m· delete-access-key AKIAA1CD38D4F0E573216E11 (key 2)�[0m + iam_test.go:287: �[2m· delete-access-key AKIAA1CD38D4F0E573216E11 (key 2)�[0m]]> + + + + + + =5)�[0m]]> + + + + + + + + + + + + + + + + =5)�[0m]]> + + + + + + + + + + + + + + + + + + beta blocked�[0m + account_test.go:296: �[2m· cross-account stop alpha->beta blocked�[0m +�[2m· cross-account terminate beta->alpha blocked�[0m + account_test.go:304: �[2m· cross-account terminate beta->alpha blocked�[0m +�[2m· cross-account reboot alpha->beta blocked�[0m + account_test.go:312: �[2m· cross-account reboot alpha->beta blocked�[0m +�[2m· stop alpha instance for cross-account start/modify/console tests�[0m + account_test.go:321: �[2m· stop alpha instance for cross-account start/modify/console tests�[0m + account_test.go:326: instance i-a3072c2387630b8ee reached state stopped +�[2m· cross-account start beta->alpha blocked�[0m + account_test.go:328: �[2m· cross-account start beta->alpha blocked�[0m +�[2m· cross-account modify-instance-attribute beta->alpha blocked�[0m + account_test.go:336: �[2m· cross-account modify-instance-attribute beta->alpha blocked�[0m +�[2m· cross-account get-console-output beta->alpha blocked�[0m + account_test.go:345: �[2m· cross-account get-console-output beta->alpha blocked�[0m +�[2m· restart alpha instance�[0m + account_test.go:354: �[2m· restart alpha instance�[0m + account_test.go:359: instance i-a3072c2387630b8ee reached state running]]> + + + + + + + + + + + + + + + + + + + + + + + + InvalidVolume.NotFound�[0m + account_test.go:895: �[2m· non-existent volume id -> InvalidVolume.NotFound�[0m +�[2m· non-existent snapshot id -> InvalidSnapshot.NotFound�[0m + account_test.go:903: �[2m· non-existent snapshot id -> InvalidSnapshot.NotFound�[0m]]> + + + + + + vpc-39eff985799c43069�[0m + vpc_test.go:133: �[2m· attach-internet-gateway igw-1520b5a34480da982 -> vpc-39eff985799c43069�[0m +�[2migw�[0m=igw-1520b5a34480da982 + vpc_test.go:139: �[2migw�[0m=igw-1520b5a34480da982 +�[2m· create-route-table (vpc=vpc-39eff985799c43069)�[0m + vpc_test.go:142: �[2m· create-route-table (vpc=vpc-39eff985799c43069)�[0m +�[2m· associate-route-table rtb-662df5e424cbdb60c <- subnet-22aba054e10588254�[0m + vpc_test.go:159: �[2m· associate-route-table rtb-662df5e424cbdb60c <- subnet-22aba054e10588254�[0m +�[2m· create-route 0.0.0.0/0 -> igw-1520b5a34480da982�[0m + vpc_test.go:176: �[2m· create-route 0.0.0.0/0 -> igw-1520b5a34480da982�[0m +�[2mrtb�[0m=rtb-662df5e424cbdb60c �[2massoc�[0m=rtbassoc-5510bf1dc6924eb0b �[2mroute�[0m=0.0.0.0/0->igw-1520b5a34480da982 + vpc_test.go:192: �[2mrtb�[0m=rtb-662df5e424cbdb60c �[2massoc�[0m=rtbassoc-5510bf1dc6924eb0b �[2mroute�[0m=0.0.0.0/0->igw-1520b5a34480da982 +�[2m· run-instances ami=ami-6f60f2b3bf04b5453 subnet=subnet-22aba054e10588254�[0m + vpc_test.go:195: �[2m· run-instances ami=ami-6f60f2b3bf04b5453 subnet=subnet-22aba054e10588254�[0m +�[2minstance�[0m=i-3177888cba3796d42 + vpc_test.go:216: �[2minstance�[0m=i-3177888cba3796d42 + vpc_test.go:218: instance i-3177888cba3796d42 reached state running +�[2mpublic_ip�[0m=192.168.0.202 �[2mprivate_ip�[0m=10.99.1.4 + vpc_test.go:224: �[2mpublic_ip�[0m=192.168.0.202 �[2mprivate_ip�[0m=10.99.1.4 +�[2m· waiting for SSH handshake 192.168.0.202:22�[0m + vpc_test.go:227: �[2m· waiting for SSH handshake 192.168.0.202:22�[0m + vpc_test.go:227: Eventually: condition not met within 3m0s: [SSH handshake 192.168.0.202:22 never completed]]]> + + + + + + igw-79c2e643660b4b7e3 + vpc_test.go:350: �[2mdefault_route�[0m=0.0.0.0/0->igw-79c2e643660b4b7e3]]> + + + igw-79c2e643660b4b7e3�[0m + vpc_test.go:415: �[2m· create-route 0.0.0.0/0 -> igw-79c2e643660b4b7e3�[0m +�[2m· associate-route-table rtb-5e6c46936f3e44167 <- subnet-cd62e4c1c3cb50c63�[0m + vpc_test.go:434: �[2m· associate-route-table rtb-5e6c46936f3e44167 <- subnet-cd62e4c1c3cb50c63�[0m +�[2mcustom_assoc�[0m=rtbassoc-da6377d37847d3d4a + vpc_test.go:450: �[2mcustom_assoc�[0m=rtbassoc-da6377d37847d3d4a +�[2m· disassociate-route-table rtbassoc-da6377d37847d3d4a�[0m + vpc_test.go:452: �[2m· disassociate-route-table rtbassoc-da6377d37847d3d4a�[0m +�[2m· delete-route 0.0.0.0/0�[0m + vpc_test.go:460: �[2m· delete-route 0.0.0.0/0�[0m +�[2m· delete-route-table rtb-5e6c46936f3e44167�[0m + vpc_test.go:468: �[2m· delete-route-table rtb-5e6c46936f3e44167�[0m]]> + + + + + + bastion:/tmp/key.pem�[0m + natgw_test.go:139: �[2m· scp keypair -> bastion:/tmp/key.pem�[0m +�[2m· wait for private SSH via bastion�[0m + natgw_test.go:151: �[2m· wait for private SSH via bastion�[0m +�[2m· baseline: private VM has no internet�[0m + natgw_test.go:172: �[2m· baseline: private VM has no internet�[0m +�[2m· allocate-address (NAT EIP)�[0m + natgw_test.go:178: �[2m· allocate-address (NAT EIP)�[0m +�[2meip�[0m=192.168.0.203 �[2malloc�[0m=eipalloc-2d81753157cd62a50 + natgw_test.go:195: �[2meip�[0m=192.168.0.203 �[2malloc�[0m=eipalloc-2d81753157cd62a50 +�[2m· create-nat-gateway in subnet-cd62e4c1c3cb50c63�[0m + natgw_test.go:197: �[2m· create-nat-gateway in subnet-cd62e4c1c3cb50c63�[0m +�[2mnat_gw�[0m=nat-812216dd5105180c5 + natgw_test.go:216: �[2mnat_gw�[0m=nat-812216dd5105180c5 + natgw_test.go:218: nat gateway nat-812216dd5105180c5 reached state available +�[2m· create-route-table�[0m + natgw_test.go:223: �[2m· create-route-table�[0m +�[2m· associate-route-table rtb-8d6a4abd5f666ec13 <- subnet-2360a40e28371e214�[0m + natgw_test.go:241: �[2m· associate-route-table rtb-8d6a4abd5f666ec13 <- subnet-2360a40e28371e214�[0m +�[2m· create-route 0.0.0.0/0 -> nat-812216dd5105180c5�[0m + natgw_test.go:259: �[2m· create-route 0.0.0.0/0 -> nat-812216dd5105180c5�[0m +�[2m· verify private VM reaches 8.8.8.8 via NAT GW�[0m + natgw_test.go:279: �[2m· verify private VM reaches 8.8.8.8 via NAT GW�[0m +�[2m· delete-nat-gateway nat-812216dd5105180c5�[0m + natgw_test.go:293: �[2m· delete-nat-gateway nat-812216dd5105180c5�[0m + natgw_test.go:318: nat gateway nat-812216dd5105180c5 reached state deleted +�[2m· verify private VM lost internet after NAT GW teardown�[0m + natgw_test.go:329: �[2m· verify private VM lost internet after NAT GW teardown�[0m]]> + + + target:172.31.0.6:8080�[0m + datapath_test.go:199: �[2m· 8e-4 allowed traffic client -> target:172.31.0.6:8080�[0m +�[2mstep4�[0m=allowed_traffic_ok + datapath_test.go:208: �[2mstep4�[0m=allowed_traffic_ok +�[2m· 8e-5 denied traffic client -> target:22 (no SSH ingress)�[0m + datapath_test.go:213: �[2m· 8e-5 denied traffic client -> target:22 (no SSH ingress)�[0m +�[2mstep5�[0m=denied_traffic_ok + datapath_test.go:217: �[2mstep5�[0m=denied_traffic_ok +�[2m· 8e-6 revoke target-sg ingress, retest (sync RequestEvent contract)�[0m + datapath_test.go:222: �[2m· 8e-6 revoke target-sg ingress, retest (sync RequestEvent contract)�[0m +�[2m· 8e-6 verify client -> target:8080 now blocked�[0m + datapath_test.go:240: �[2m· 8e-6 verify client -> target:8080 now blocked�[0m +�[2mstep6�[0m=revoke_blocked_ok + datapath_test.go:244: �[2mstep6�[0m=revoke_blocked_ok +�[2m· 8e-7 re-authorize target-sg ingress, verify traffic restored�[0m + datapath_test.go:250: �[2m· 8e-7 re-authorize target-sg ingress, verify traffic restored�[0m +�[2mstep7�[0m=restore_ok + datapath_test.go:271: �[2mstep7�[0m=restore_ok + datapath_test.go:127: instance i-eae6263d9b9fda069 reached state terminated + datapath_test.go:127: instance i-9d9411a83549d34e3 reached state terminated]]> + + + + + + + + + + + + diff --git a/.github/workflows/e2e-go.yml b/.github/workflows/e2e-go.yml index d9fecf9d9..28c8c1f90 100644 --- a/.github/workflows/e2e-go.yml +++ b/.github/workflows/e2e-go.yml @@ -98,6 +98,15 @@ jobs: # warms across runs. cache: false + - name: Re-enable Go toolchain auto-download + # setup-go@v6 exports GOTOOLCHAIN=local to $GITHUB_ENV (v5 left it + # "auto"). build-install-artifacts.sh prepends /usr/local/go/bin to + # PATH on the self-hosted runner, and that Go is older than + # spinifex/go.mod's `go` directive; under "local" the build fails + # with `requires go >= X.Y.Z`. Restoring "auto" lets the resolved + # Go self-heal by fetching the named minor on demand. + run: echo "GOTOOLCHAIN=auto" >> "$GITHUB_ENV" + - name: Build Install Artifacts working-directory: mulga/scripts/tofu-cluster run: | @@ -211,6 +220,10 @@ jobs: for SUITE in ${SUITES_RUN}; do \ echo \"::group::suite \$SUITE\"; \ printf '\n%s%s━━ suite %s ━━%s\n' \"\$B\" \"\$C\" \"\$SUITE\" \"\$R\"; \ + # Record suite wall-clock start so the analyzer can locate + # the right journal window. junit-report's timestamp attr + # marks conversion time, not test start, so we cannot use it. + date -u +%Y-%m-%dT%H:%M:%SZ > '${ARTIFACT_DIR}/test-'\$SUITE'.start'; \ GITHUB_ACTIONS=true FORCE_COLOR=1 SPINIFEX_E2E=1 SPINIFEX_MODE=single \ ARTIFACT_DIR='${ARTIFACT_DIR}' \ ./\$SUITE.test -test.v -test.timeout=30m \ @@ -246,7 +259,10 @@ jobs: ssh "${SSH_OPTS[@]}" "$VM" "tar -C '${ARTIFACT_DIR}' -cf - . 2>/dev/null || true" \ | tar -C "${ARTIFACT_DIR}" -xf - 2>/dev/null ok "artifacts pulled to ${ARTIFACT_DIR}" - ssh "${SSH_OPTS[@]}" "$VM" 'sudo journalctl -u "spinifex-*" --no-pager --since "60 min ago"' \ + # `-o short-iso` writes RFC3339-ish timestamps (e.g. + # `2026-05-19T12:32:34+1000 host …`) so the analyzer can window-slice + # the journal around each failure's wall-clock span. + ssh "${SSH_OPTS[@]}" "$VM" 'sudo journalctl -u "spinifex-*" --no-pager --output=short-iso --since "60 min ago"' \ > "${ARTIFACT_DIR}/spinifex-journal.log" 2>/dev/null ok "journal: $(wc -l < "${ARTIFACT_DIR}/spinifex-journal.log" 2>/dev/null || echo 0) lines" @@ -271,6 +287,14 @@ jobs: junit-glob: ${{ env.ARTIFACT_DIR }}/junit-*.xml title: "Go E2E results" + - name: Analyze e2e failures + if: always() + uses: ./spinifex/.github/actions/e2e-analyze + with: + junit-glob: ${{ env.ARTIFACT_DIR }}/junit-*.xml + log-dir: ${{ env.ARTIFACT_DIR }} + title: "E2E failure analysis" + - uses: actions/upload-artifact@v7 if: always() with: diff --git a/.github/workflows/spinifex.yml b/.github/workflows/spinifex.yml index 996cfe67a..6b19e58af 100644 --- a/.github/workflows/spinifex.yml +++ b/.github/workflows/spinifex.yml @@ -61,6 +61,9 @@ jobs: - name: Run Tests with Coverage run: make -C spinifex test-cover + - name: Run Action Tests + run: make -C spinifex test-actions + - name: Check Diff Coverage run: cd spinifex && scripts/diff-coverage.sh coverage.out --base HEAD~1 diff --git a/Makefile b/Makefile index b21c3c053..7c4269347 100644 --- a/Makefile +++ b/Makefile @@ -126,6 +126,12 @@ test-race: @echo -e "\n....Running tests with race detector for $(GO_PROJECT_NAME)...." $(_Q)LOG_IGNORE=1 go test -race -timeout 300s ./spinifex/... $(_RACEQ) +# Unit tests for in-repo GitHub Actions (e.g. .github/actions/e2e-analyze). +# Kept out of `test-cover` so coverage % isn't diluted by CI-only tooling. +test-actions: + @echo -e "\n....Running action tests...." + LOG_IGNORE=1 go test -timeout 60s ./.github/actions/... + # Check that new/changed code meets coverage threshold (runs tests first) diff-coverage: test-cover @QUIET=$(QUIET) scripts/diff-coverage.sh $(COVERPROFILE) @@ -275,7 +281,7 @@ ansible-dev-reset: ansible-dev-deploy: cd scripts/ansible && ansible-playbook playbooks/dev-deploy.yml -.PHONY: build build-ui build-installer build-lb-agent build-system-image build-microvm-image install-microvm go_build go_run preflight test test-cover test-race diff-coverage bench run \ +.PHONY: build build-ui build-installer build-lb-agent build-system-image build-microvm-image install-microvm go_build go_run preflight test test-cover test-race test-actions diff-coverage bench run \ deploy reinstall clean \ install-system install-go install-aws quickinstall \ lint fix govulncheck \ diff --git a/spinifex/services/vpcd/topology.go b/spinifex/services/vpcd/topology.go index 71cf2d607..b195bd56d 100644 --- a/spinifex/services/vpcd/topology.go +++ b/spinifex/services/vpcd/topology.go @@ -1361,6 +1361,17 @@ func (h *TopologyHandler) handleAddNAT(msg *nats.Msg) { "logical_ip", evt.LogicalIP, "port", evt.PortName, ) + + // Block until ovn-northd compiles the new NAT into SB and every chassis + // has installed the resulting flows. handleIGWAttach has the same + // barrier (mulga-siv-105); without one here, the publisher (typically + // ec2d/RunInstances) returns success while the DNAT/SNAT flows for the + // VM's public IP are still being installed on the gateway chassis, so + // the freshly launched VM is unreachable on its public IP for whatever + // flow-install latency the chassis happens to incur. Reproduced in CI + // run 26072432957 Phase8b — Port_Binding showed up=true at the 3min + // timeout, but SSH never completed handshake. + _ = waitForFlowsHV() respond(msg, nil) } diff --git a/spinifex/services/vpcd/topology_test.go b/spinifex/services/vpcd/topology_test.go index bf462482b..a38518c9c 100644 --- a/spinifex/services/vpcd/topology_test.go +++ b/spinifex/services/vpcd/topology_test.go @@ -923,6 +923,55 @@ func TestTopologyHandler_IGWAttach_InvokesFlowBarrier(t *testing.T) { } } +// TestTopologyHandler_AddNAT_InvokesFlowBarrier asserts handleAddNAT +// calls waitForFlowsHV after writing the dnat_and_snat row to NB. +// Without this barrier, RunInstances returns success while OF flows for +// the new public IP are still being installed on the gateway chassis, +// and the freshly launched VM is unreachable on its public IP for the +// flow-install latency. Reproduced in CI run 26072432957 Phase8b. +func TestTopologyHandler_AddNAT_InvokesFlowBarrier(t *testing.T) { + orig := waitForFlowsHV + var called int + waitForFlowsHV = func() error { called++; return nil } + defer func() { waitForFlowsHV = orig }() + + _, nc := startTestNATS(t) + mock := NewMockOVNClient() + _ = mock.Connect(context.Background()) + ctx := context.Background() + + topo := NewTopologyHandler(mock) + subs, err := topo.Subscribe(nc) + require.NoError(t, err) + defer func() { + for _, s := range subs { + _ = s.Unsubscribe() + } + }() + + require.NoError(t, mock.CreateLogicalRouter(ctx, &nbdb.LogicalRouter{ + Name: "vpc-vpc-natbarrier", + ExternalIDs: map[string]string{ + "spinifex:vpc_id": "vpc-natbarrier", + "spinifex:cidr": "10.0.0.0/16", + }, + })) + + evt := NATEvent{ + VpcId: "vpc-natbarrier", + ExternalIP: "192.168.0.250", + LogicalIP: "10.0.1.4", + } + data, _ := json.Marshal(evt) + resp, err := nc.Request(TopicAddNAT, data, 5_000_000_000) + require.NoError(t, err) + assertSuccess(t, resp, "add NAT") + + if called != 1 { + t.Errorf("expected waitForFlowsHV to run exactly once after add-nat, got %d", called) + } +} + func TestTopologyHandler_IGWAttach_WithExternalPool(t *testing.T) { _, nc := startTestNATS(t) mock := NewMockOVNClient() diff --git a/tests/e2e/.failure-rules.yaml b/tests/e2e/.failure-rules.yaml new file mode 100644 index 000000000..f3af6d0ee --- /dev/null +++ b/tests/e2e/.failure-rules.yaml @@ -0,0 +1,22 @@ +# Rule table consumed by .github/actions/e2e-analyze in Stage 3 of +# docs/development/improvements/e2e-go-failure-analysis.md. +# +# Stage 1 (current) ignores this file. Stage 3 will match a failure's +# normalised signature against `match` / `also_match` regexes and surface +# `hint` text inline in the GITHUB_STEP_SUMMARY analysis report. +# +# Add rules in the same PR as the test or feature that surfaced the +# failure. Rules are advisory only — they never gate the build. +# +# Schema (Stage 3 will validate): +# - id: stable identifier (kebab-case) +# match: Go-syntax regex against the normalised signature line +# also_match: optional second regex (must also match) +# hint: | +# Free text shown in the analysis report when match fires. +# Multi-line; markdown rendered. +# artifacts: [list of relative paths under ARTIFACT_DIR to surface] +# +# Empty list keeps the analyser additive — no rules means no hints. + +rules: [] diff --git a/tests/e2e/harness/diag.go b/tests/e2e/harness/diag.go index 0360806b7..4b60f8cce 100644 --- a/tests/e2e/harness/diag.go +++ b/tests/e2e/harness/diag.go @@ -6,7 +6,9 @@ import ( "bytes" "encoding/base64" "fmt" + "os" "os/exec" + "path/filepath" "strings" "testing" "time" @@ -15,6 +17,27 @@ import ( "github.com/aws/aws-sdk-go/service/ec2" ) +// VPCDiagnosticsOpts carries the optional context dumpVPCFlowDiagnostics +// uses to target IP-specific captures (OF flows, conntrack, ARP, NAT +// lookup). Empty fields mean "skip the captures that need this input" +// — the unconditional captures (console-output, ovn-nbctl/sbctl show) +// still run. +type VPCDiagnosticsOpts struct { + // ExternalIP is the public IP the test was probing (e.g. the + // dnat_and_snat external address). When set, the helper greps + // br-int flows / conntrack / host ARP for this IP. + ExternalIP string + // LogicalIP is the VM's private IP. When set, the OF-flow grep + // also matches this address so we see both halves of the NAT + // translation. + LogicalIP string + // ArtifactDir is the per-test bundle directory (typically + // `fix.Artifacts`). When set, every capture is also persisted as + // a separate file so the Stage 2 analyzer bundler picks it up + // alongside the journal + test-log slices. + ArtifactDir string +} + // DumpVPCFlowDiagnostics emits a triage bundle for VPC/IGW datapath failures // (e.g. Phase8b SSH-to-public-IP timeout). Dumps the guest's console tail // (boot + cloud-init state) plus a slim OVN state snapshot to identify @@ -25,16 +48,19 @@ import ( // - mulga-siv-105 (handleIGWAttach lacks flows-ready barrier) // - mulga-siv-106 (handleVPCCreate doesn't store spinifex:cidr) // - mulga-siv-107 (dnat_and_snat double-delete race) +// - mulga-siv-111 (EIP-recycle stale OVS state; this is the Phase 1 +// diagnostics surface that closes the bead's first acceptance gate) // // Skips silently if OVN tooling / passwordless sudo aren't available, so the // helper is safe to call from developer laptops too. -func DumpVPCFlowDiagnostics(t *testing.T, c *AWSClient, instanceID, label string) { +func DumpVPCFlowDiagnostics(t *testing.T, c *AWSClient, instanceID, label string, opts VPCDiagnosticsOpts) { t.Helper() fmt.Printf("\n%s%s── DIAGNOSTICS: %s (instance=%s) ──%s\n", colorBold, colorCyan, label, instanceID, colorReset) dumpConsoleOutput(t, c, instanceID) dumpOVNState(t, instanceID) + dumpDatapathState(t, opts) fmt.Printf("%s%s── END DIAGNOSTICS ──%s\n\n", colorBold, colorCyan, colorReset) } @@ -110,6 +136,122 @@ func dumpOVNState(t *testing.T, instanceID string) { } } +// dumpDatapathState captures OVS / kernel-side state keyed on the +// external IP being probed. The signal disambiguates between three +// hypotheses on the residual SSH-timeout-despite-barrier failure +// (mulga-siv-111): (1) stale conntrack, (2) stale upstream ARP, (3) +// missing OF flow install. Each capture also writes to a separate +// file under opts.ArtifactDir when set, so the Stage 2 analyzer +// bundler picks them up. +// +// Skipped silently when the IP-specific inputs aren't supplied or the +// shell tools aren't available. +func dumpDatapathState(t *testing.T, opts VPCDiagnosticsOpts) { + t.Helper() + if opts.ExternalIP == "" { + return + } + if err := exec.Command("sudo", "-n", "true").Run(); err != nil { + fmt.Printf(" datapath: passwordless sudo unavailable (%v); skipping captures\n", err) + return + } + + type capture struct { + filename string + label string + argv []string + // grepFor, when non-empty, post-filters stdout to lines + // containing this substring. Lets us keep ovs-ofctl / conntrack + // output tight without an external pipe. + grepFor []string + } + caps := []capture{ + { + filename: "ovs-flows-extip.txt", + label: "ovs-ofctl dump-flows br-int (filtered)", + argv: []string{"ovs-ofctl", "dump-flows", "br-int"}, + grepFor: []string{opts.ExternalIP, opts.LogicalIP}, + }, + { + filename: "conntrack-extip.txt", + label: "conntrack -L (filtered)", + argv: []string{"conntrack", "-L"}, + grepFor: []string{opts.ExternalIP}, + }, + { + filename: "ip-neigh-extip.txt", + label: "ip neigh show (host ARP, filtered)", + argv: []string{"ip", "-4", "neigh", "show"}, + grepFor: []string{opts.ExternalIP}, + }, + { + filename: "ovn-nat-extip.txt", + label: "ovn-nbctl find NAT external_ip", + argv: []string{"ovn-nbctl", "--bare", "--columns=_uuid,type,external_ip,logical_ip,external_mac,logical_port", + "find", "NAT", "external_ip=" + opts.ExternalIP}, + }, + } + + for _, cap := range caps { + fmt.Printf(" --- %s ---\n", cap.label) + var stdout, stderr bytes.Buffer + cmd := exec.Command("sudo", append([]string{"-n"}, cap.argv...)...) + cmd.Stdout = &stdout + cmd.Stderr = &stderr + cmd.Env = append(cmd.Env, "PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin") + err := runWithTimeout(cmd, 5*time.Second) + body := stdout.String() + if len(cap.grepFor) > 0 { + body = filterLines(body, cap.grepFor) + } + if err != nil { + body = fmt.Sprintf("(capture failed: %v; stderr=%q)\n%s", err, stderr.String(), body) + } else if strings.TrimSpace(body) == "" { + body = "(no matches)\n" + } + for _, line := range strings.Split(strings.TrimRight(body, "\n"), "\n") { + fmt.Printf(" %s\n", line) + } + if opts.ArtifactDir != "" { + path := filepath.Join(opts.ArtifactDir, cap.filename) + header := fmt.Sprintf("$ sudo %s\n", strings.Join(cap.argv, " ")) + if len(cap.grepFor) > 0 { + header += "# filtered to lines matching: " + strings.Join(cap.grepFor, ", ") + "\n" + } + if werr := os.WriteFile(path, []byte(header+body), 0o644); werr != nil { + fmt.Printf(" (artifact write failed: %v)\n", werr) + } + } + } +} + +// filterLines returns only stdout lines that contain any of needles. +// Empty needles slice → input passes through unchanged. Empty needle +// strings are skipped so a caller can pass `opts.LogicalIP` without +// guarding for the empty case. +func filterLines(body string, needles []string) string { + var clean []string + for _, n := range needles { + if n != "" { + clean = append(clean, n) + } + } + if len(clean) == 0 { + return body + } + var b strings.Builder + for _, line := range strings.Split(body, "\n") { + for _, n := range clean { + if strings.Contains(line, n) { + b.WriteString(line) + b.WriteByte('\n') + break + } + } + } + return b.String() +} + func runWithTimeout(cmd *exec.Cmd, timeout time.Duration) error { if err := cmd.Start(); err != nil { return err diff --git a/tests/e2e/single/vpc_test.go b/tests/e2e/single/vpc_test.go index e9756a1c4..85d4d3d34 100644 --- a/tests/e2e/single/vpc_test.go +++ b/tests/e2e/single/vpc_test.go @@ -191,6 +191,28 @@ func phase8b_VPCSubnetE2E(t *testing.T, fix *Fixture) { }) harness.Detail(t, "rtb", rtbID, "assoc", assocID, "route", "0.0.0.0/0->"+igwID) + // --- Security group ---------------------------------------------------- + // Fresh VPC's auto-created default SG denies all ingress. Authorize + // tcp/22 from anywhere so the SSH probe below can complete — the bash + // driver relies on the *default* VPC's default SG having been pre-baked + // with this rule by admin init, but a newly-created VPC has not. + // Without this step Phase 8b SSH times out via an ACL drop between OVN + // tables 13 (DNAT) and 17 (NAT commit) even when every datapath barrier + // is satisfied (tracking mulga-siv-111). + harness.Step(t, "describe-security-groups (default) vpc=%s", vpcID) + sgOut, err := c.EC2.DescribeSecurityGroups(&ec2.DescribeSecurityGroupsInput{ + Filters: []*ec2.Filter{ + {Name: aws.String("vpc-id"), Values: []*string{aws.String(vpcID)}}, + {Name: aws.String("group-name"), Values: []*string{aws.String("default")}}, + }, + }) + require.NoError(t, err, "describe-security-groups default") + require.NotEmpty(t, sgOut.SecurityGroups, "no default SG for vpc=%s", vpcID) + defaultSGID := aws.StringValue(sgOut.SecurityGroups[0].GroupId) + require.NotEmpty(t, defaultSGID, "default SG GroupId empty") + harness.AuthorizeSSHIngress(t, c, defaultSGID) + harness.Detail(t, "default_sg", defaultSGID, "ingress", "tcp/22<-0.0.0.0/0") + // --- Public instance --------------------------------------------------- harness.Step(t, "run-instances ami=%s subnet=%s", fix.AMIID, pubSubnetID) runOut, err := c.EC2.RunInstances(&ec2.RunInstancesInput{ @@ -226,11 +248,16 @@ func phase8b_VPCSubnetE2E(t *testing.T, fix *Fixture) { // --- SSH + external connectivity --------------------------------------- // Use the non-fatal probe so we can dump VPC/IGW datapath diagnostics // before Fatal. Same 3min budget — fresh-VPC unreachability beyond that - // is a real product bug (mulga-siv-105), not test flake. + // is a real product bug (mulga-siv-105 + mulga-siv-111), not test flake. if !trySSHReady(pubIP, 22, fix.KeyPath, 3*time.Minute) { harness.DumpVPCFlowDiagnostics(t, c, instID, - fmt.Sprintf("Phase 8b SSH timeout — vpc=%s igw=%s pub=%s", vpcID, igwID, pubIP)) - t.Fatalf("SSH handshake %s:22 never completed within 3min (see diagnostics above; tracking mulga-siv-105)", pubIP) + fmt.Sprintf("Phase 8b SSH timeout — vpc=%s igw=%s pub=%s", vpcID, igwID, pubIP), + harness.VPCDiagnosticsOpts{ + ExternalIP: pubIP, + LogicalIP: privIP, + ArtifactDir: fix.Artifacts, + }) + t.Fatalf("SSH handshake %s:22 never completed within 3min (see diagnostics above; tracking mulga-siv-111)", pubIP) } tgt := harness.SSHTarget{User: "ec2-user", Host: pubIP, Port: 22, KeyPath: fix.KeyPath}