1// SPDX-License-Identifier: MIT
2
3package executor
4
5import (
6 "fmt"
7 "slices"
8 "strings"
9 "testing"
10 "time"
11)
12
13const matcherSetup = ` - name: prepare
14 run: |
15 mkdir -p src
16 git init -q .
17 git remote add origin "$GITHUB_SERVER_URL/$GITHUB_REPOSITORY"
18 echo x > src/main.go
19 cat > m.json <<'JSON'
20 {"problemMatcher":[{"owner":"go","severity":"warning","pattern":[{"regexp":"^(.+):(\\d+):(\\d+): (error|warning)?: ?(.*)$","file":1,"line":2,"column":3,"severity":4,"message":5}]}]}
21 JSON
22`
23
24// The workspace of runLocal is hello/hello under the home; the setup step
25// runs in it, so the repository check of OutputManager.GetRepositoryPath finds
26// .git/config there.
27func TestProblemMatcherEndToEnd(t *testing.T) {
28 needTools(t, "bash", "git")
29 rr, res := runResults(t, wfHead+` steps:
30`+matcherSetup+` - name: match
31 run: |
32 echo "::add-matcher::m.json"
33 echo "src/main.go:12:5: error: bad thing"
34 echo "src/main.go:7:1: : just a warning"
35 echo "src/missing.go:1:1: error: no such file"
36 echo "nothing here"
37 echo "::remove-matcher owner=go::"
38 echo "src/main.go:12:5: error: not matched"
39`, nil)
40 if res.Conclusion != ConclusionSuccess {
41 t.Fatalf("%+v", res)
42 }
43 got := rr.results[3].Annotations
44 want := []Annotation{
45 {Level: LevelFailure, Message: "bad thing", File: "src/main.go", StartLine: 12, EndLine: 12, StartColumn: 5, EndColumn: 5},
46 {Level: LevelWarning, Message: "just a warning", File: "src/main.go", StartLine: 7, EndLine: 7, StartColumn: 1, EndColumn: 1},
47 {Level: LevelFailure, Message: "no such file", StartLine: 1, EndLine: 1, StartColumn: 1, EndColumn: 1}, // the file does not exist: dropped
48 }
49 if fmt.Sprint(got) != fmt.Sprint(want) {
50 t.Errorf("annotations\n got %+v\nwant %+v", got, want)
51 }
52 log := logOf(rr.step(t, "match"))
53 for _, w := range []string{"##[error]src/main.go:12:5: error: bad thing", "##[warning]src/main.go:7:1: : just a warning", "\nnothing here\n", "\nsrc/main.go:12:5: error: not matched"} {
54 if !strings.Contains(log+"\n", w) {
55 t.Errorf("log lacks %q:\n%s", w, log)
56 }
57 }
58 // the matched lines are not logged a second time as plain text
59 _, body, _ := strings.Cut(log, "##[endgroup]\n")
60 if strings.Count(body, "bad thing") != 1 {
61 t.Errorf("a matched line is logged twice:\n%s", log)
62 }
63}
64
65// AC6b through a whole step: the catastrophic matcher is retried 3 times (one
66// second each), removed with the runner's warning, and the step goes on; the
67// other matcher keeps working. OutputManager.Remove only edits the list of the
68// step (OutputManager.cs:300-313) while the next step starts from the matchers
69// of the job (ExecutionContext.GetMatchers), so the next step meets the
70// matcher again and removes it again after 3 more timeouts.
71func TestCatastrophicMatcherIsRemovedAfterThreeTimeouts(t *testing.T) {
72 needTools(t, "bash")
73 start := time.Now()
74 rr, res := runResults(t, wfHead+` steps:
75 - name: prepare
76 run: |
77 cat > bad.json <<'JSON'
78 {"problemMatcher":[{"owner":"catastrophic","pattern":[{"regexp":"^((a+)+)$","message":1}]}]}
79 JSON
80 cat > good.json <<'JSON'
81 {"problemMatcher":[{"owner":"good","severity":"warning","pattern":[{"regexp":"^good: (.+)$","message":1}]}]}
82 JSON
83 - name: catastrophic
84 run: |
85 echo "::add-matcher::bad.json"
86 echo "::add-matcher::good.json"
87 echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
88 echo "good: still alive"
89 echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
90 - name: next step
91 run: |
92 echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
93 echo "good: next step"
94`, nil)
95 took := time.Since(start)
96 if res.Conclusion != ConclusionSuccess {
97 t.Fatalf("%+v", res)
98 }
99 if took > 15*time.Second {
100 t.Errorf("the step stalled: %v", took)
101 }
102 log := logOf(rr.step(t, "catastrophic"))
103 const removing = "##[warning]Removing issue matcher 'catastrophic'. Matcher failed 3 times. Error: The Regex engine has timed out while trying to match a pattern to an input string."
104 if strings.Count(log, removing) != 1 {
105 t.Errorf("removal message missing or repeated:\n%s", log)
106 }
107 if !strings.Contains(log, "\naaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!\n##[warning]good: still alive") && !strings.Contains(log, "##[warning]good: still alive") {
108 t.Errorf("the good matcher stopped working:\n%s", log)
109 }
110 // Only one removal: the second long line did not time out again.
111 if n := len(rr.results[3].Annotations); n != 2 {
112 t.Errorf("%d annotations: %+v", n, rr.results[3].Annotations)
113 }
114 next := logOf(rr.step(t, "next step"))
115 if strings.Count(next, "Removing issue matcher 'catastrophic'") != 1 || !strings.Contains(next, "##[warning]good: next step") {
116 t.Errorf("next step:\n%s", next)
117 }
118}
119
120// Mirror of the recording match-catastrophic: the removal is per step
121// (OutputManager.Remove edits the list of the step), so the next step, which
122// does not add anything, starts from the matchers of the job and times out and
123// removes the matcher again after 3 more timeouts; "good" works in both.
124func TestCatastrophicMatcherRemovalIsPerStep(t *testing.T) {
125 needTools(t, "bash")
126 rr, res := runResults(t, wfHead+` steps:
127 - name: prepare
128 run: |
129 cat > bad.json <<'JSON'
130 {"problemMatcher":[{"owner":"catastrophic","pattern":[{"regexp":"^((a+)+)$","message":1}]}]}
131 JSON
132 cat > good.json <<'JSON'
133 {"problemMatcher":[{"owner":"good","severity":"warning","pattern":[{"regexp":"^good: (.+)$","message":1}]}]}
134 JSON
135 - name: first
136 run: |
137 echo "::add-matcher::bad.json"
138 echo "::add-matcher::good.json"
139 echo "good: before the long line"
140 echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
141 echo "good: after the long line"
142 - name: second
143 run: |
144 echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
145 echo "aaa"
146 echo "good: still alive"
147`, nil)
148 if res.Conclusion != ConclusionSuccess {
149 t.Fatalf("%+v", res)
150 }
151 const removing = "##[warning]Removing issue matcher 'catastrophic'. Matcher failed 3 times. Error: The Regex engine has timed out while trying to match a pattern to an input string."
152 // The lines of the log, in order, with the long text of the removal cut.
153 lines := func(log string) []string {
154 var out []string
155 for _, l := range strings.Split(log, "\n") {
156 if strings.HasPrefix(l, removing) {
157 l = removing
158 }
159 out = append(out, l)
160 }
161 return out
162 }
163 has := func(log string, want ...string) bool {
164 got := lines(log)
165 for i := range got {
166 if slices.Equal(got[i:min(i+len(want), len(got))], want) {
167 return true
168 }
169 }
170 return false
171 }
172 const long = "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
173 first := logOf(rr.step(t, "first"))
174 if !has(first, "##[warning]good: before the long line", removing, long, "##[warning]good: after the long line") {
175 t.Errorf("first:\n%s", first)
176 }
177 second := logOf(rr.step(t, "second"))
178 if !has(second, removing, long, "aaa", "##[warning]good: still alive") {
179 t.Errorf("second:\n%s", second)
180 }
181}
182
183func TestMatcherTimeoutFromEnvironment(t *testing.T) {
184 needTools(t, "bash")
185 start := time.Now()
186 rr, _ := runResults(t, wfHead+` steps:
187 - name: fast
188 run: |
189 echo '{"problemMatcher":[{"owner":"c","pattern":[{"regexp":"^((a+)+)$","message":1}]}]}' > bad.json
190 echo "::add-matcher::bad.json"
191 echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"
192`, func(c *Config) {
193 c.Getenv = func(k string) string { return map[string]string{matcherTimeoutKey: "0:0:0.05"}[k] }
194 })
195 if time.Since(start) > 2500*time.Millisecond {
196 t.Errorf("the timeout of the environment was not used: %v", time.Since(start))
197 }
198 if !strings.Contains(logOf(rr.step(t, "fast")), "Removing issue matcher 'c'") {
199 t.Error(logOf(rr.step(t, "fast")))
200 }
201}
202
203func TestAddMatcherErrors(t *testing.T) {
204 needTools(t, "bash")
205 rr, res := runResults(t, wfHead+` steps:
206 - name: bad
207 run: |
208 echo "::add-matcher::"
209 echo "::remove-matcher::"
210 echo "::remove-matcher owner=x::file.json"
211 echo "::add-matcher::missing.json"
212 - name: invalid
213 if: always()
214 run: |
215 echo '{"problemMatcher":[{"owner":"m","pattern":[{"regexp":"(","message":1}]}]}' > b.json
216 echo "::add-matcher::b.json"
217`, nil)
218 if res.Conclusion != ConclusionFailure {
219 t.Fatalf("%+v", res)
220 }
221 log := logOf(rr.step(t, "bad"))
222 for _, w := range []string{
223 "##[warning]File path must be specified.",
224 "##[warning]Either an owner name or a file path must be specified in ##[remove-matcher] command.",
225 "##[warning]Either specify an owner name or a file path in ##[remove-matcher] command. Both values cannot be set.",
226 "##[error]Unable to process command '::add-matcher::missing.json' successfully.",
227 "##[error]Could not find file '",
228 } {
229 if !strings.Contains(log, w) {
230 t.Errorf("log lacks %q:\n%s", w, log)
231 }
232 }
233 if !strings.Contains(logOf(rr.step(t, "invalid")), "##[error]Unable to process command '::add-matcher::b.json' successfully.") {
234 t.Error(logOf(rr.step(t, "invalid")))
235 }
236}
237
238func TestStepSummary(t *testing.T) {
239 needTools(t, "bash")
240 rr, _ := runResults(t, wfHead+` steps:
241 - name: write
242 run: |
243 echo "::add-mask::sekret-value"
244 printf '# Title\nvalue sekret-value\r\nlast line without newline' >> "$GITHUB_STEP_SUMMARY"
245 - name: empty
246 run: 'true'
247 - name: huge
248 run: head -c 1048577 /dev/zero | tr '\0' x >> "$GITHUB_STEP_SUMMARY"
249 - name: exactly one MiB
250 run: head -c 1048576 /dev/zero | tr '\0' x >> "$GITHUB_STEP_SUMMARY"
251`, nil)
252 if r := rr.results[2]; !r.HasSummary || r.Summary != "# Title\nvalue ***\nlast line without newline\n" {
253 t.Errorf("summary %q %v", r.Summary, r.HasSummary)
254 }
255 if rr.results[3].HasSummary {
256 t.Error("no file content, no summary")
257 }
258 if rr.results[4].HasSummary {
259 t.Error("an oversized summary is not sent")
260 }
261 if !strings.Contains(logOf(rr.step(t, "huge")), "##[error]$GITHUB_STEP_SUMMARY upload aborted, supports content up to a size of 1024k, got 1024k.") {
262 t.Errorf("%s", logOf(rr.step(t, "huge"))[:200])
263 }
264 // 1 MiB of x plus one line feed per line is over the limit once rewritten:
265 // the runner adds the "\n"; the contract allows 1 MiB.
266 if r := rr.results[5]; r.HasSummary && len(r.Summary) > stepSummaryLimit {
267 t.Errorf("a summary above the contract limit is sent: %d", len(r.Summary))
268 }
269}
270
271func TestSummaryOffWithoutTheFeature(t *testing.T) {
272 needTools(t, "bash")
273 rr, _ := runResults(t, wfHead+" steps:\n - run: echo hi >> \"$GITHUB_STEP_SUMMARY\"\n", func(c *Config) { c.SendSummaries = false })
274 if rr.results[2].HasSummary {
275 t.Error("summary sent without ci.summaries")
276 }
277}
278
279func TestStepOutcome(t *testing.T) {
280 needTools(t, "bash")
281 rr, res := runResults(t, wfHead+` steps:
282 - run: exit 1
283 continue-on-error: true
284 - run: 'true'
285 - run: exit 2
286`, nil)
287 if res.Conclusion != ConclusionFailure {
288 t.Fatal(res)
289 }
290 if r := rr.results[2]; r.Outcome != ConclusionFailure || rr.steps[1].Conclusion != ConclusionSuccess {
291 t.Errorf("continue-on-error: outcome %v conclusion %v", r.Outcome, rr.steps[1].Conclusion)
292 }
293 if r := rr.results[3]; r.Outcome != ConclusionSuccess {
294 t.Errorf("%+v", r)
295 }
296 if r := rr.results[4]; r.Outcome != ConclusionFailure {
297 t.Errorf("%+v", r)
298 }
299}
300
301func TestStepTimeout(t *testing.T) {
302 needTools(t, "bash")
303 skew := -(60*time.Second - 700*time.Millisecond) // one minute becomes 0.7 s
304 rr, res := runResults(t, wfHead+` steps:
305 - name: slow
306 id: slow
307 timeout-minutes: 1
308 run: |
309 trap 'echo got-int; exit 130' INT
310 echo "before=written" >> "$GITHUB_OUTPUT"
311 sleep 30 & wait
312 - name: after success
313 run: echo "ran after the timeout"
314 - name: after failure
315 if: failure()
316 run: echo "outcome=${{ steps.slow.outcome }} conclusion=${{ steps.slow.conclusion }} status=${{ job.status }} out=${{ steps.slow.outputs.before }}"
317 - name: cancelled()
318 if: cancelled()
319 run: echo "cancelled is true"
320 - name: soft
321 id: soft
322 timeout-minutes: 1
323 continue-on-error: true
324 if: always()
325 run: sleep 30
326 - name: results
327 if: always()
328 run: echo "soft=${{ steps.soft.outcome }}/${{ steps.soft.conclusion }}"
329 - name: fractional
330 timeout-minutes: 0.9
331 run: sleep 1
332 - name: expression
333 timeout-minutes: ${{ fromJSON('0') }}
334 run: echo no timeout
335`, func(c *Config) { c.StepTimeoutSkew = skew })
336 if res.Conclusion != ConclusionFailure {
337 t.Fatalf("%+v", res)
338 }
339 slow := rr.step(t, "slow")
340 if slow.Conclusion != ConclusionFailure {
341 t.Errorf("conclusion %v", slow.Conclusion)
342 }
343 log := logOf(slow)
344 if !strings.Contains(log, "##[error]The action 'slow' has timed out after 1 minutes.") || strings.Contains(log, "The operation was canceled.") {
345 t.Errorf("log:\n%s", log)
346 }
347 if !strings.Contains(log, "got-int") {
348 t.Errorf("the step did not get SIGINT first:\n%s", log)
349 }
350 if a := rr.results[2].Annotations; len(a) == 0 || a[len(a)-1].Message != "The action 'slow' has timed out after 1 minutes." {
351 t.Errorf("annotations %+v", a)
352 }
353 if rr.results[2].Outcome != ConclusionFailure {
354 t.Error("outcome")
355 }
356 if rr.step(t, "after success").Conclusion != ConclusionSkipped {
357 t.Error("success() is false after a timeout")
358 }
359 if l := logOf(rr.step(t, "after failure")); !strings.HasSuffix(l, "outcome=failure conclusion=failure status=failure out=written") {
360 t.Errorf("after failure: %s", l)
361 }
362 if rr.step(t, "cancelled()").Conclusion != ConclusionSkipped {
363 t.Error("a step timeout is not a cancellation")
364 }
365 if l := logOf(rr.step(t, "results")); !strings.HasSuffix(l, "soft=failure/success") {
366 t.Errorf("results: %s", l)
367 }
368 if rr.step(t, "fractional").Conclusion != ConclusionSkipped && rr.step(t, "fractional").Conclusion != ConclusionSuccess {
369 t.Error("fractional")
370 }
371}
372
373func TestStepTimeoutExpressionError(t *testing.T) {
374 needTools(t, "bash")
375 rr, res := runResults(t, wfHead+` steps:
376 - name: bad
377 env:
378 LIMIT: abc
379 timeout-minutes: ${{ env.LIMIT }}
380 run: echo ran
381`, nil)
382 log := logOf(rr.step(t, "bad"))
383 if !strings.Contains(log, "##[error]An error occurred when attempting to determine the step timeout.") || !strings.Contains(log, "\nran") {
384 t.Errorf("%s", log)
385 }
386 if res.Conclusion != ConclusionFailure && res.Conclusion != ConclusionSuccess {
387 t.Fatal(res)
388 }
389}
390
391// save-state keeps the state per action; names are case-insensitive, the
392// first spelling is the key the action sees (STATE_<key>, ActionRunner.cs:255)
393// and entries keep the order they were first saved in.
394func TestSaveStateKeepsTheFirstSpellingAndOrder(t *testing.T) {
395 j := &job{}
396 j.saveState("2", "Foo", "bar")
397 j.saveState("2", "zed", "1")
398 j.saveState("2", "FOO", "baz")
399 j.saveState("3", "x", "y")
400 got := j.intraActionState("2")
401 if fmt.Sprint(got) != fmt.Sprint([]Pair{{"Foo", "baz"}, {"zed", "1"}}) {
402 t.Errorf("%v", got)
403 }
404 if got := j.intraActionState("4"); len(got) != 0 {
405 t.Errorf("%v", got)
406 }
407}
408
409// The hook points phase F calls (see results.go): the additive mask API, the
410// scope of an inner step of a composite action, the timeout helpers.
411func TestAddMaskIsAdditive(t *testing.T) {
412 j := &job{}
413 j.masker.Store(newMasker("first-secret"))
414 before := j.masker.Load()
415 j.addMask("second-secret", "third-secret")
416 if j.masker.Load() != before {
417 t.Error("the masker was replaced")
418 }
419 for _, v := range []string{"first-secret", "second-secret", "third-secret"} {
420 if j.mask("x "+v) != "x ***" {
421 t.Errorf("%q is not masked", v)
422 }
423 }
424}
425
426func TestEmbeddedScopeSharesTheOuterStep(t *testing.T) {
427 rec := newRecorder()
428 rec.StepStarted(4, "outer", time.Now())
429 j := &job{cfg: Config{Reporter: rec}}
430 j.masker.Store(newMasker())
431 outer := &stepRun{j: j, num: 4}
432 inner := &stepRun{j: j, num: 4, scope: j.embeddedScope(outer, "inner-1")}
433 // the outer step has 8 warnings of its own and the inner one 6: ten are
434 // kept, the outer step's own first
435 for range 8 {
436 j.addIssueFor(outer, issue{Level: LevelWarning, Message: "outer"})
437 }
438 for range 6 {
439 j.addIssueFor(inner, issue{Level: LevelWarning, Message: "inner"})
440 }
441 got := j.collector(4).result()
442 if len(got) != 10 || got[7].Message != "outer" || got[8].Message != "inner" || got[9].Message != "inner" {
443 t.Errorf("%d annotations: %+v", len(got), got)
444 }
445 // summaries of inner steps are appended to the outer step's
446 outer.Summary("# outer\n")
447 inner.Summary("# inner 1\n")
448 inner.Summary("# inner 2\n")
449 if j.summaries[4] != "# outer\n# inner 1\n# inner 2\n" {
450 t.Errorf("%q", j.summaries[4])
451 }
452 // save-state of an inner step goes to the key of its scope
453 inner.SaveState("Key", "v")
454 if g := j.intraActionState("inner-1"); len(g) != 1 || g[0].Key != "Key" {
455 t.Errorf("%v", g)
456 }
457 if g := j.intraActionState("4"); len(g) != 0 {
458 t.Errorf("%v", g)
459 }
460}
461
462// Several catastrophic matchers and a step timeout: the step ends at its
463// timeout, not after every matcher has used its 3 attempts on every line
464// (GO-004). Without the cancellation of the matchers the 8 matchers x 3
465// attempts x 1 s of the first line alone hold the step for 24 s.
466func TestCatastrophicMatchersDoNotHoldAStepPastItsTimeout(t *testing.T) {
467 needTools(t, "bash")
468 var matchers []string
469 var adds []string
470 for i := range 8 {
471 matchers = append(matchers, fmt.Sprintf(`{"owner":"bad%d","pattern":[{"regexp":"^((a+)+)$","message":1}]}`, i))
472 }
473 adds = append(adds, `echo '{"problemMatcher":[`+strings.Join(matchers, ",")+`]}' > bad.json`)
474 start := time.Now()
475 rr, _ := runResults(t, wfHead+` steps:
476 - name: slow lines
477 timeout-minutes: 1
478 run: |
479 `+adds[0]+`
480 echo "::add-matcher::bad.json"
481 for i in 1 2 3 4 5 6; do echo "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!"; done
482 sleep 30
483`, func(c *Config) { c.StepTimeoutSkew = -(60*time.Second - 1500*time.Millisecond) })
484 took := time.Since(start)
485 if took > 8*time.Second {
486 t.Errorf("the step overran its timeout: %v", took)
487 }
488 log := logOf(rr.step(t, "slow lines"))
489 if !strings.Contains(log, "The action 'slow lines' has timed out after 1 minutes.") {
490 t.Errorf("no timeout message:\n%s", log)
491 }
492 // the lines that were not matched are still logged
493 if strings.Count(log, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa!") < 6 {
494 t.Errorf("lines lost after the cancellation:\n%s", log)
495 }
496}