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}