Skip to content

Commit 6cc0ff2

Browse files
committed
fix: detect runtime crashes in e2e harness and preserve retry evidence
A non-zero act exit with no parseable job failure was classified transient and retried up to five times. A real runtime crash (cascade CLI or act) emits a goroutine dump that corrupts act's --json stream, so the job-failure parse misses and a genuine crash is misclassified as a flake, burning the retry budget while the CI log expires before the stack trace can be read. Detect Go-runtime crash signatures (panic:, fatal error:, a goroutine dump header, a fatal signal) in act's raw output and treat them as definitive, non-transient failures so they surface immediately with their reason. Anchor on real runtime signatures so a benign log line mentioning the word panic does not misfire. On retry-budget exhaustion, persist the last attempt's full act stdout/stderr to a per scenario+attempt file under e2e/_artifacts and reference its path in the returned error, so the next genuine failure keeps its stack-trace origin. Signed-off-by: Joshua Temple <joshua.temple@stablekernel.com>
1 parent 7dc7b5f commit 6cc0ff2

8 files changed

Lines changed: 443 additions & 21 deletions

File tree

‎e2e/.gitignore‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1,3 +1,6 @@
11
# Test artifacts
22
*.log
33
coverage.out
4+
5+
# Captured act stdout/stderr from exhausted scenario retries
6+
_artifacts/

‎e2e/harness/act.go‎

Lines changed: 37 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -368,6 +368,13 @@ func (a *ActRunner) RunWorkflowFromRepo(ctx context.Context, opts RunOpts) (*Ext
368368
Jobs: make(map[string]*JobResultExtended),
369369
Logs: logs.String(),
370370
}
371+
// The parse fallback bypasses ParseActOutput's crash detection, so run
372+
// it directly here against the raw logs: a crash dump is the most likely
373+
// reason the JSON stream failed to parse, and it must not be lost.
374+
if crashed, reason := detectCrashSignature(cleanedLogs); crashed {
375+
result.Crashed = true
376+
result.CrashReason = reason
377+
}
371378
}
372379

373380
normalizeWorkflowResult(result, opts.WorkflowPath, exitCode)
@@ -384,19 +391,37 @@ func (a *ActRunner) RunWorkflowFromRepo(ctx context.Context, opts RunOpts) (*Ext
384391
// up as a green-but-empty scenario (#25).
385392
func normalizeWorkflowResult(result *ExtendedWorkflowResult, workflowPath string, exitCode int) {
386393
if exitCode != 0 {
387-
// ExecError means act could NOT run the workflow to a conclusion: a
388-
// genuine act/docker transport or exec hiccup where no job reached a
389-
// conclusion. It must NOT cover the case where act ran the workflow and
390-
// a job genuinely concluded "failure" - that is a real, deterministic
391-
// defect and retrying it would mask a real failure as transient.
392-
//
393-
// So only tag ExecError when the non-zero exit is unaccompanied by any
394-
// parsed job-level failure. If a job concluded "failure" (or the
395-
// reconciled conclusion is already "failure"), this was a real outcome.
396-
execError := !hasJobFailure(result)
394+
// Classify BEFORE forcing the conclusion to "failure": hasJobFailure
395+
// keys off result.Conclusion, so overwriting it first would make every
396+
// non-zero exit look like a real job failure and defeat the transient
397+
// path.
398+
switch {
399+
case result != nil && result.Crashed:
400+
// A Go-runtime crash (cascade CLI or act) corrupts the --json stream
401+
// so no "Job failed" event parses. Left to the ExecError heuristic
402+
// below it would look like a job-less hiccup and be retried away as a
403+
// transient flake, burning the retry budget and letting the stack
404+
// trace expire. A crash is a definitive defect: keep ExecError false
405+
// so the scenario runner does NOT retry it, and surface the crash
406+
// reason.
407+
result.ExecError = false
408+
result.Error = fmt.Sprintf("workflow crashed: %s", result.CrashReason)
409+
case hasJobFailure(result):
410+
// act ran the workflow and a job genuinely concluded "failure". That
411+
// is a real, deterministic defect, not a transport hiccup, so it must
412+
// not be retried.
413+
result.ExecError = false
414+
result.Error = "workflow execution failed"
415+
default:
416+
// A non-zero exit with no parsed job failure and no crash signature
417+
// is a benign act/docker transport or exec hiccup: tag it transient
418+
// so the scenario runner may retry from a clean slate.
419+
result.ExecError = true
420+
result.Error = "workflow execution failed"
421+
}
422+
// A non-zero exit is always a failure; set the conclusion after
423+
// classification so hasJobFailure above saw the pre-exit conclusion.
397424
result.Conclusion = "failure"
398-
result.Error = "workflow execution failed"
399-
result.ExecError = execError
400425
}
401426

402427
if workflowPath != "" && len(result.Jobs) == 0 && result.Conclusion != "failure" {

‎e2e/harness/crash_test.go‎

Lines changed: 146 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,146 @@
1+
package harness
2+
3+
import (
4+
"strings"
5+
"testing"
6+
)
7+
8+
// goroutineDump is a representative Go runtime panic + goroutine dump as it
9+
// appears interleaved in act's stdout/stderr when the cascade CLI (or act
10+
// itself) crashes mid-run. The dump corrupts act's --json stream, so no
11+
// "Job failed" event is parseable and the run would otherwise be misclassified
12+
// as a transient flake and retried away.
13+
const goroutineDump = `time="2026-06-13T00:00:00Z" level=info msg="⭐ Run Main cascade orchestrate"
14+
panic: runtime error: invalid memory address or nil pointer dereference
15+
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x10a3f20]
16+
17+
goroutine 1 [running]:
18+
github.com/stablekernel/cascade/internal/orchestrate.(*Planner).Plan(0x0)
19+
/cascade/internal/orchestrate/planner.go:142 +0x1a0
20+
main.main()
21+
/cascade/main.go:33 +0x9c
22+
`
23+
24+
// TestDetectCrashSignature_GoPanicAndGoroutineDump verifies a real Go-runtime
25+
// crash signature in raw act output is detected so it can be treated as a
26+
// definitive failure rather than a transient flake.
27+
func TestDetectCrashSignature_GoPanicAndGoroutineDump(t *testing.T) {
28+
t.Parallel()
29+
30+
tests := []struct {
31+
name string
32+
logs string
33+
wantCrash bool
34+
wantReasony string // substring expected in the reason when wantCrash
35+
}{
36+
{
37+
name: "panic plus goroutine dump",
38+
logs: goroutineDump,
39+
wantCrash: true,
40+
wantReasony: "panic",
41+
},
42+
{
43+
name: "fatal error at line start",
44+
logs: "some log\nfatal error: concurrent map writes\n\ngoroutine 7 [running]:\n",
45+
wantCrash: true,
46+
wantReasony: "fatal error",
47+
},
48+
{
49+
name: "goroutine dump with runtime frame",
50+
logs: "goroutine 42 [running]:\nruntime.gopanic(0x1, 0x2)\n\t/usr/local/go/src/runtime/panic.go:884\n",
51+
wantCrash: true,
52+
wantReasony: "goroutine",
53+
},
54+
{
55+
name: "SIGSEGV signal line",
56+
logs: "unexpected\n[signal SIGSEGV: segmentation violation code=0x1 addr=0x0]\n",
57+
wantCrash: true,
58+
wantReasony: "SIGSEGV",
59+
},
60+
{
61+
name: "benign log mentioning the word panic in prose is not a crash",
62+
logs: `{"jobID":"deploy","msg":"Do not panic: rollback is automatic","level":"info"}`,
63+
wantCrash: false,
64+
},
65+
{
66+
name: "benign log mentioning goroutine count in prose is not a crash",
67+
logs: `{"jobID":"deploy","msg":"started 8 goroutines for the worker pool","level":"info"}`,
68+
wantCrash: false,
69+
},
70+
{
71+
name: "ordinary successful output has no crash signature",
72+
logs: `{"jobID":"build","jobResult":"success","msg":"🏁 Job succeeded","level":"info"}`,
73+
wantCrash: false,
74+
},
75+
}
76+
77+
for _, tt := range tests {
78+
tt := tt
79+
t.Run(tt.name, func(t *testing.T) {
80+
t.Parallel()
81+
crashed, reason := detectCrashSignature(tt.logs)
82+
if crashed != tt.wantCrash {
83+
t.Fatalf("detectCrashSignature crashed = %v, want %v (reason=%q)", crashed, tt.wantCrash, reason)
84+
}
85+
if tt.wantCrash {
86+
if reason == "" {
87+
t.Fatalf("expected a non-empty crash reason when crashed")
88+
}
89+
if tt.wantReasony != "" && !strings.Contains(strings.ToLower(reason), strings.ToLower(tt.wantReasony)) {
90+
t.Fatalf("crash reason %q does not mention %q", reason, tt.wantReasony)
91+
}
92+
}
93+
})
94+
}
95+
}
96+
97+
// TestParseActOutput_SetsCrashFields verifies the parser surfaces a runtime
98+
// crash on the result so the classifier downstream can act on it.
99+
func TestParseActOutput_SetsCrashFields(t *testing.T) {
100+
t.Parallel()
101+
102+
result, err := ParseActOutput(goroutineDump)
103+
if err != nil {
104+
t.Fatalf("ParseActOutput returned error: %v", err)
105+
}
106+
if !result.Crashed {
107+
t.Fatalf("expected Crashed=true for a panic+goroutine dump")
108+
}
109+
if result.CrashReason == "" {
110+
t.Fatalf("expected a non-empty CrashReason")
111+
}
112+
}
113+
114+
// TestNormalizeWorkflowResult_CrashIsNotTransient is the core safety guarantee:
115+
// a non-zero act exit carrying a Go-runtime crash signature must be classified
116+
// as a REAL (non-transient) failure so the scenario runner does not retry it as
117+
// a flake and the stack trace surfaces.
118+
func TestNormalizeWorkflowResult_CrashIsNotTransient(t *testing.T) {
119+
t.Parallel()
120+
121+
result := &ExtendedWorkflowResult{
122+
Conclusion: "success",
123+
Jobs: map[string]*JobResultExtended{},
124+
Logs: goroutineDump,
125+
Crashed: true,
126+
CrashReason: "panic: runtime error: invalid memory address or nil pointer " +
127+
"dereference",
128+
}
129+
normalizeWorkflowResult(result, ".github/workflows/orchestrate.yaml", 2)
130+
131+
if result.Conclusion != "failure" {
132+
t.Fatalf("Conclusion = %q, want failure", result.Conclusion)
133+
}
134+
if result.ExecError {
135+
t.Fatalf("a crash must NOT be tagged as a transient ExecError")
136+
}
137+
if !strings.Contains(strings.ToLower(result.Error), "crash") {
138+
t.Fatalf("error %q should describe the crash", result.Error)
139+
}
140+
141+
// And it must not be retried by the classifier.
142+
failErr := workflowFailureError("orchestrate", result)
143+
if IsTransientWorkflowError(failErr) {
144+
t.Fatalf("a crash failure must not be classified transient: %v", failErr)
145+
}
146+
}

‎e2e/harness/parser.go‎

Lines changed: 61 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ package harness
33
import (
44
"bufio"
55
"encoding/json"
6+
"regexp"
67
"strings"
78
"time"
89
)
@@ -37,6 +38,58 @@ type ExtendedWorkflowResult struct {
3738
// mismatch (which must fail deterministically). A run that parsed real job
3839
// events and concluded "failure" leaves ExecError false.
3940
ExecError bool
41+
// Crashed is true when act's raw output carries a Go-runtime crash
42+
// signature (a panic, a goroutine dump, a SIGSEGV/SIGABRT, or a fatal
43+
// error) from the cascade CLI or act itself. A crash corrupts act's --json
44+
// stream so no "Job failed" event is parseable, which would otherwise let a
45+
// genuine crash masquerade as a transient flake and be retried away. When
46+
// Crashed is true the run is a definitive failure, NOT a transient one.
47+
Crashed bool
48+
// CrashReason is the first matched crash-signature line, captured so the
49+
// failure surfaces the stack-trace origin rather than a generic message.
50+
CrashReason string
51+
}
52+
53+
// goroutineDumpRE matches the header of a Go goroutine dump, e.g.
54+
// "goroutine 1 [running]:". This is the anchored runtime signature emitted on a
55+
// panic or fatal error; it does not match prose that merely contains the word
56+
// "goroutine".
57+
var goroutineDumpRE = regexp.MustCompile(`(?m)^goroutine \d+ \[`)
58+
59+
// signalCrashRE matches a Go runtime fatal-signal line, e.g.
60+
// "[signal SIGSEGV: segmentation violation ...]" or a SIGABRT report.
61+
var signalCrashRE = regexp.MustCompile(`signal SIG(SEGV|ABRT|BUS|FPE|ILL)`)
62+
63+
// detectCrashSignature reports whether raw act stdout/stderr carries a Go
64+
// runtime crash signature, returning the first matched signature line as the
65+
// reason. It anchors on real runtime signatures (a goroutine dump header, a
66+
// "panic:" or "fatal error:" at the start of a line, a fatal signal report) so
67+
// it does not misfire on benign occurrences of the words "panic" or
68+
// "goroutine" inside an ordinary log line (e.g. a deploy script's prose).
69+
func detectCrashSignature(logs string) (bool, string) {
70+
if logs == "" {
71+
return false, ""
72+
}
73+
74+
scanner := bufio.NewScanner(strings.NewReader(logs))
75+
// A crash dump line can be long (a deeply nested stack frame); raise the
76+
// scanner's token limit so a long frame cannot truncate detection.
77+
scanner.Buffer(make([]byte, 0, 64*1024), 1024*1024)
78+
for scanner.Scan() {
79+
line := scanner.Text()
80+
trimmed := strings.TrimSpace(line)
81+
switch {
82+
case strings.HasPrefix(trimmed, "panic:"):
83+
return true, trimmed
84+
case strings.HasPrefix(trimmed, "fatal error:"):
85+
return true, trimmed
86+
case goroutineDumpRE.MatchString(line):
87+
return true, trimmed
88+
case signalCrashRE.MatchString(line):
89+
return true, trimmed
90+
}
91+
}
92+
return false, ""
4093
}
4194

4295
// JobResultExtended contains detailed result of a single job
@@ -141,5 +194,13 @@ func ParseActOutput(output string) (*ExtendedWorkflowResult, error) {
141194
}
142195
}
143196

197+
// A Go-runtime crash (cascade CLI or act) can corrupt the --json stream so
198+
// no "Job failed" event parses; flag it from the raw logs so the classifier
199+
// treats it as a definitive failure rather than a transient flake.
200+
if crashed, reason := detectCrashSignature(output); crashed {
201+
result.Crashed = true
202+
result.CrashReason = reason
203+
}
204+
144205
return result, scanner.Err()
145206
}

‎e2e/harness/scenario_retry.go‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -2,8 +2,12 @@ package harness
22

33
import (
44
"context"
5+
"errors"
56
"fmt"
7+
"os"
68
"os/exec"
9+
"path/filepath"
10+
"regexp"
711
"testing"
812
"time"
913
)
@@ -30,6 +34,45 @@ var scenarioRetryBackoff = 5 * time.Second
3034
// path stays a single, testable seam over the docker CLI).
3135
var pruneBetweenAttempts = pruneDockerNetworks
3236

37+
// artifactDir is where the raw act stdout/stderr of an exhausted scenario is
38+
// persisted so a future CI failure yields the stack-trace origin instead of an
39+
// expired log. It is a var so unit tests can redirect it to a temp dir. The
40+
// default lives under the e2e module so captured logs are easy to find and are
41+
// covered by e2e/.gitignore (which ignores *.log).
42+
var artifactDir = "_artifacts"
43+
44+
// artifactNameUnsafe matches any run of characters that are not safe in a
45+
// cross-platform filename. The scenario name (which can contain spaces and
46+
// slashes) is sanitized through it so each artifact path is a single, safe
47+
// filename.
48+
var artifactNameUnsafe = regexp.MustCompile(`[^A-Za-z0-9._-]+`)
49+
50+
// persistAttemptEvidence writes the raw act logs carried by err to a per
51+
// scenario+attempt artifact file and returns its path. It is best effort: if no
52+
// logs are available or the write fails, it returns "" and the caller proceeds
53+
// without an artifact reference (the scenario result must never be masked by an
54+
// artifact-write failure). The filename is unique per scenario+attempt so
55+
// parallel scenarios never collide.
56+
func persistAttemptEvidence(scenario string, attempt int, err error) string {
57+
var we *workflowError
58+
if !errors.As(err, &we) {
59+
return ""
60+
}
61+
logs := we.actLogs()
62+
if logs == "" {
63+
return ""
64+
}
65+
if mkErr := os.MkdirAll(artifactDir, 0o755); mkErr != nil {
66+
return ""
67+
}
68+
safe := artifactNameUnsafe.ReplaceAllString(scenario, "_")
69+
path := filepath.Join(artifactDir, fmt.Sprintf("%s-attempt%d.log", safe, attempt))
70+
if wrErr := os.WriteFile(path, []byte(logs), 0o644); wrErr != nil {
71+
return ""
72+
}
73+
return path
74+
}
75+
3376
// logger is the minimal logging surface a scenario attempt needs. *testing.T
3477
// satisfies it, and unit tests can supply a fake to assert on retry logging.
3578
type logger interface {
@@ -81,6 +124,15 @@ func runScenarioWithRetry(ctx context.Context, log logger, name string, attempt
81124
log.Logf("scenario %q: exhausted %d attempts; last failure was transient: %v",
82125
name, scenarioRetryAttempts, err)
83126
}
127+
128+
// The budget is exhausted. Persist the last attempt's raw act stdout/stderr
129+
// so the stack-trace origin survives the CI log's retention window, and
130+
// reference the artifact path in the returned error.
131+
if path := persistAttemptEvidence(name, scenarioRetryAttempts, lastErr); path != "" {
132+
log.Logf("scenario %q: wrote last-attempt act log to %s", name, path)
133+
return fmt.Errorf("scenario %q failed after %d attempts (act log: %s): %w",
134+
name, scenarioRetryAttempts, path, lastErr)
135+
}
84136
return fmt.Errorf("scenario %q failed after %d attempts: %w", name, scenarioRetryAttempts, lastErr)
85137
}
86138

0 commit comments

Comments
 (0)