internal/store/builds_test.go
603 lines · 18445 bytes
1package store
2
3import (
4 "errors"
5 "strings"
6 "testing"
7)
8
9// A runner that dies between claiming a build and reporting it leaves the row
10// claimed. The next claim resolves it rather than leaving the build running and
11// the commit pending forever.
12func TestReapStaleBuilds(t *testing.T) {
13 s := open(t)
14 if err := s.MigrateUp(); err != nil {
15 t.Fatal(err)
16 }
17 uid, err := s.CreateUser("cmc", true)
18 if err != nil {
19 t.Fatal(err)
20 }
21 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
22 t.Fatal(err)
23 }
24
25 stuck, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
26 if err != nil {
27 t.Fatal(err)
28 }
29 fresh, err := s.CreateBuild(1, "pages", "abc123", "main", `["true"]`, "", "", true)
30 if err != nil {
31 t.Fatal(err)
32 }
33
34 // Claim both, then age only the first past the deadline.
35 for range 2 {
36 if _, ok, err := s.ClaimBuild(nil, false); err != nil || !ok {
37 t.Fatalf("claim: %v ok=%v", err, ok)
38 }
39 }
40 if _, err := s.DB.Exec(
41 `UPDATE builds SET started_at = '2020-01-01T00:00:00Z' WHERE number = ?`, stuck); err != nil {
42 t.Fatal(err)
43 }
44
45 reaped, err := s.ReapStaleBuilds()
46 if err != nil {
47 t.Fatal(err)
48 }
49 if len(reaped) != 1 || reaped[0].Number != stuck {
50 t.Fatalf("reaped %+v, want only build %d", reaped, stuck)
51 }
52
53 b, err := s.BuildByNumber(1, stuck)
54 if err != nil {
55 t.Fatal(err)
56 }
57 if b.Status != "failure" || b.FinishedAt == "" {
58 t.Fatalf("stale build is %s finished %q, want failure with a timestamp", b.Status, b.FinishedAt)
59 }
60 log, err := s.BuildLog(b.ID)
61 if err != nil {
62 t.Fatal(err)
63 }
64 if !strings.Contains(string(log), "abandoned") {
65 t.Fatalf("log does not say why it failed: %q", log)
66 }
67
68 // A build still inside the deadline is left alone.
69 if b, err := s.BuildByNumber(1, fresh); err != nil || b.Status != "running" {
70 t.Fatalf("fresh build is %v (%v), want running", b.Status, err)
71 }
72}
73
74// Checks on a merge request report how long their build ran, which means
75// pairing ci/<job> statuses with builds on the same commit.
76func TestBuildsForCommitTiming(t *testing.T) {
77 s := open(t)
78 if err := s.MigrateUp(); err != nil {
79 t.Fatal(err)
80 }
81 uid, err := s.CreateUser("cmc", true)
82 if err != nil {
83 t.Fatal(err)
84 }
85 repoID, err := s.CreateRepo("user", uid, "lib", "public")
86 if err != nil {
87 t.Fatal(err)
88 }
89 // Two runs of the same job on one commit: the retry is what counts.
90 for range 2 {
91 if _, err := s.CreateBuild(repoID, "test", "abc123", "main", `["true"]`, "", "", true); err != nil {
92 t.Fatal(err)
93 }
94 }
95 if _, err := s.CreateBuild(repoID, "lint", "def456", "main", `["true"]`, "", "", true); err != nil {
96 t.Fatal(err)
97 }
98 if _, err := s.DB.Exec(`UPDATE builds SET started_at = '2026-08-28T04:42:54Z',
99 finished_at = '2026-08-28T04:44:06Z', status = 'success' WHERE number = 2`); err != nil {
100 t.Fatal(err)
101 }
102
103 byJob, err := s.BuildsForCommit(repoID, "abc123")
104 if err != nil {
105 t.Fatal(err)
106 }
107 if len(byJob) != 1 {
108 t.Fatalf("builds for commit: %+v", byJob)
109 }
110 b := byJob["test"]
111 if b.Number != 2 {
112 t.Fatalf("older run won: %d", b.Number)
113 }
114 if got := b.Elapsed().String(); got != "1m12s" {
115 t.Fatalf("elapsed: %s", got)
116 }
117 // A build that never finished has no duration to report.
118 if d := byJob["lint"].Elapsed(); d != 0 {
119 t.Fatalf("unfinished build reported %s", d)
120 }
121}
122
123// A runner that names repositories claims only their builds, so a runner on a
124// machine that should not execute every repository's steps does not pick one
125// up by being first to ask.
126func TestClaimBuildScopedToRepos(t *testing.T) {
127 s := open(t)
128 if err := s.MigrateUp(); err != nil {
129 t.Fatal(err)
130 }
131 uid, err := s.CreateUser("cmc", true)
132 if err != nil {
133 t.Fatal(err)
134 }
135 mine, err := s.CreateRepo("user", uid, "site", "public")
136 if err != nil {
137 t.Fatal(err)
138 }
139 theirs, err := s.CreateRepo("user", uid, "stranger", "public")
140 if err != nil {
141 t.Fatal(err)
142 }
143 // Queued first, so an unscoped claim would take it.
144 if _, err := s.CreateBuild(theirs, "evil", "abc123", "main", `["true"]`, "", "", true); err != nil {
145 t.Fatal(err)
146 }
147 wanted, err := s.CreateBuild(mine, "deploy", "def456", "main", `["true"]`, "", "", true)
148 if err != nil {
149 t.Fatal(err)
150 }
151
152 b, ok, err := s.ClaimBuild([]int64{mine}, false)
153 if err != nil || !ok {
154 t.Fatalf("claim: %v ok=%v", err, ok)
155 }
156 if b.RepoID != mine || b.Number != wanted {
157 t.Fatalf("claimed repo %d build %d, want repo %d build %d",
158 b.RepoID, b.Number, mine, wanted)
159 }
160
161 // Nothing left for that scope, even though another repo's build is pending.
162 if _, ok, err := s.ClaimBuild([]int64{mine}, false); err != nil || ok {
163 t.Fatalf("second scoped claim: err=%v ok=%v, want no build", err, ok)
164 }
165 // An unscoped runner still takes it.
166 if b, ok, err := s.ClaimBuild(nil, false); err != nil || !ok || b.RepoID != theirs {
167 t.Fatalf("unscoped claim: err=%v ok=%v repo=%d", err, ok, b.RepoID)
168 }
169}
170
171// A log that stops at the cap reads exactly like a build that died mid-step,
172// which is what sent people hunting for a test failure that was never there.
173// It says so instead, once.
174func TestBuildLogSaysWhenItTruncates(t *testing.T) {
175 s := open(t)
176 if err := s.MigrateUp(); err != nil {
177 t.Fatal(err)
178 }
179 uid, err := s.CreateUser("cmc", true)
180 if err != nil {
181 t.Fatal(err)
182 }
183 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
184 t.Fatal(err)
185 }
186 id, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
187 if err != nil {
188 t.Fatal(err)
189 }
190
191 chunk := make([]byte, 256<<10)
192 for i := range chunk {
193 chunk[i] = 'x'
194 }
195 // Well past the cap, so plenty of appends land after it.
196 for written := 0; written < MaxBuildLog+(4*len(chunk)); written += len(chunk) {
197 if err := s.AppendBuildLog(id, chunk); err != nil {
198 t.Fatal(err)
199 }
200 }
201
202 log, err := s.BuildLog(id)
203 if err != nil {
204 t.Fatal(err)
205 }
206 if n := strings.Count(string(log), "log truncated"); n != 1 {
207 t.Errorf("truncation notice appears %d times, want exactly 1", n)
208 }
209 if !strings.HasSuffix(string(log), string(truncNotice)) {
210 t.Error("notice is not at the end of the log")
211 }
212 if len(log) > MaxBuildLog+len(truncNotice)+len(chunk) {
213 t.Errorf("log grew to %d, past the cap plus one chunk", len(log))
214 }
215}
216
217// A success is found by tree across commits; an empty tree never matches,
218// so builds queued without one (scheduled, tag) are never reused (#177).
219func TestSuccessBuildForTree(t *testing.T) {
220 s := open(t)
221 if err := s.MigrateUp(); err != nil {
222 t.Fatal(err)
223 }
224 uid, err := s.CreateUser("cmc", true)
225 if err != nil {
226 t.Fatal(err)
227 }
228 repoID, err := s.CreateRepo("user", uid, "app", "public")
229 if err != nil {
230 t.Fatal(err)
231 }
232 if _, err := s.CreateBuild(repoID, "unit", "aaa", "main", `["true"]`, "", "tree1", true); err != nil {
233 t.Fatal(err)
234 }
235 b, _ := s.BuildsForCommit(repoID, "aaa")
236 if _, ok, err := s.ClaimBuild([]int64{repoID}, false); err != nil || !ok {
237 t.Fatalf("claim: ok=%v err=%v", ok, err)
238 }
239 if err := s.FinishBuild(b["unit"].ID, "success"); err != nil {
240 t.Fatal(err)
241 }
242 if prev, ok, _ := s.SuccessBuildForTree(repoID, "tree1", "unit", ""); !ok || prev.SHA != "aaa" {
243 t.Fatalf("success not found by tree: ok=%v prev=%+v", ok, prev)
244 }
245 if _, ok, _ := s.SuccessBuildForTree(repoID, "tree1", "other", ""); ok {
246 t.Error("matched a different job")
247 }
248 if _, ok, _ := s.SuccessBuildForTree(repoID, "", "unit", ""); ok {
249 t.Error("an empty tree matched")
250 }
251}
252
253// A result stands for another commit only when it came from a trusted
254// build on the same image: a fork's green build, or one on an image the
255// job has since left, proves nothing about the repository's own (#258).
256func TestSuccessReuseNeedsTrustAndImage(t *testing.T) {
257 s := open(t)
258 if err := s.MigrateUp(); err != nil {
259 t.Fatal(err)
260 }
261 uid, _ := s.CreateUser("cmc", true)
262 repoID, _ := s.CreateRepo("user", uid, "app", "public")
263 for _, b := range []struct {
264 sha, image string
265 trusted bool
266 }{
267 {"aaa", "", false},
268 {"bbb", "localhost/old:1", true},
269 } {
270 if _, err := s.CreateBuild(repoID, "unit", b.sha, "main", `["true"]`, b.image, "tree1", b.trusted); err != nil {
271 t.Fatal(err)
272 }
273 claimed, ok, err := s.ClaimBuild([]int64{repoID}, true)
274 if err != nil || !ok {
275 t.Fatalf("claim: ok=%v err=%v", ok, err)
276 }
277 if err := s.FinishBuild(claimed.ID, "success"); err != nil {
278 t.Fatal(err)
279 }
280 }
281 if prev, ok, _ := s.SuccessBuildForTree(repoID, "tree1", "unit", ""); ok {
282 t.Fatalf("reused build %d: untrusted, or on another image", prev.Number)
283 }
284 if prev, ok, _ := s.SuccessBuildForTree(repoID, "tree1", "unit", "localhost/old:1"); !ok || prev.SHA != "bbb" {
285 t.Fatalf("trusted build on the same image not found: ok=%v prev=%+v", ok, prev)
286 }
287 if _, ok, _ := s.SuccessBuildFor(repoID, "aaa", "unit"); ok {
288 t.Error("an untrusted success stood for its commit")
289 }
290}
291
292// A running build whose log stream ended is reaped after StaleLogGrace,
293// well before the deadline; one whose stream is still open is not (#179).
294func TestReapStaleBuildsAfterLogClosed(t *testing.T) {
295 s := open(t)
296 if err := s.MigrateUp(); err != nil {
297 t.Fatal(err)
298 }
299 uid, _ := s.CreateUser("cmc", true)
300 repoID, _ := s.CreateRepo("user", uid, "app", "public")
301 for _, job := range []string{"gone", "alive"} {
302 if _, err := s.CreateBuild(repoID, job, "abc", "main", `["true"]`, "", "", true); err != nil {
303 t.Fatal(err)
304 }
305 if _, ok, err := s.ClaimBuild([]int64{repoID}, false); err != nil || !ok {
306 t.Fatalf("claim %s: %v", job, err)
307 }
308 }
309 builds, _ := s.BuildsForCommit(repoID, "abc")
310 gone := builds["gone"].ID
311 if err := s.MarkBuildLogClosed(gone); err != nil {
312 t.Fatal(err)
313 }
314 // Just closed: within the grace period, nothing is reaped.
315 if stale, _ := s.ReapStaleBuilds(); len(stale) != 0 {
316 t.Fatalf("reaped inside the grace period: %+v", stale)
317 }
318 // Backdate the close past the grace period.
319 if _, err := s.DB.Exec("UPDATE builds SET log_closed_at = '2020-01-01T00:00:00Z' WHERE id = ?", gone); err != nil {
320 t.Fatal(err)
321 }
322 stale, err := s.ReapStaleBuilds()
323 if err != nil {
324 t.Fatal(err)
325 }
326 if len(stale) != 1 || stale[0].ID != gone {
327 t.Fatalf("reaped %+v, want only the build whose log closed", stale)
328 }
329 if b, _ := s.BuildByID(gone); b.Status != "failure" {
330 t.Errorf("reaped build is %s, want failure", b.Status)
331 }
332 if b, _ := s.BuildByID(builds["alive"].ID); b.Status != "running" {
333 t.Errorf("build with an open stream is %s, want running", b.Status)
334 }
335 // Marking is a no-op on a build that is no longer running.
336 if err := s.MarkBuildLogClosed(gone); err != nil {
337 t.Fatal(err)
338 }
339}
340
341// AVG is a float in SQLite; the stats scan it as whole seconds.
342func TestQueueStatsFractionalAverage(t *testing.T) {
343 s := open(t)
344 if err := s.MigrateUp(); err != nil {
345 t.Fatal(err)
346 }
347 uid, err := s.CreateUser("cmc", true)
348 if err != nil {
349 t.Fatal(err)
350 }
351 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
352 t.Fatal(err)
353 }
354 for range 2 {
355 if _, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true); err != nil {
356 t.Fatal(err)
357 }
358 if _, ok, err := s.ClaimBuild(nil, false); err != nil || !ok {
359 t.Fatalf("claim: %v ok=%v", err, ok)
360 }
361 }
362 // Waits of 1 s and 2 s: an average of 1.5.
363 if _, err := s.DB.Exec(`UPDATE builds SET created_at = strftime('%Y-%m-%dT%H:%M:%SZ', started_at, '-' || number || ' seconds')`); err != nil {
364 t.Fatal(err)
365 }
366 q, err := s.QueueStats()
367 if err != nil {
368 t.Fatal(err)
369 }
370 if q.Claimed24h != 2 || q.ClaimWaitAvgS != 1 || q.ClaimWaitMaxS != 2 || q.Pending != 0 || q.Reaped24h != 0 {
371 t.Fatalf("stats: %+v", q)
372 }
373}
374
375// ListBuilds narrows on ref, status and job independently, and combines
376// when more than one is given (#224).
377func TestListBuildsFilters(t *testing.T) {
378 s := open(t)
379 if err := s.MigrateUp(); err != nil {
380 t.Fatal(err)
381 }
382 uid, err := s.CreateUser("cmc", true)
383 if err != nil {
384 t.Fatal(err)
385 }
386 repoID, err := s.CreateRepo("user", uid, "app", "public")
387 if err != nil {
388 t.Fatal(err)
389 }
390 if _, err := s.CreateBuild(repoID, "unit", "aaa", "main", `["true"]`, "", "", true); err != nil {
391 t.Fatal(err)
392 }
393 if _, err := s.CreateBuild(repoID, "lint", "bbb", "feature", `["true"]`, "", "", true); err != nil {
394 t.Fatal(err)
395 }
396 if err := s.FinishBuild(mustClaim(t, s, repoID).ID, "failure"); err != nil {
397 t.Fatal(err)
398 }
399
400 all, err := s.ListBuilds(repoID, BuildFilter{}, 10)
401 if err != nil || len(all) != 2 {
402 t.Fatalf("unfiltered: %+v %v", all, err)
403 }
404 if byRef, err := s.ListBuilds(repoID, BuildFilter{Ref: "main"}, 10); err != nil || len(byRef) != 1 || byRef[0].Ref != "main" {
405 t.Fatalf("by ref: %+v %v", byRef, err)
406 }
407 if byJob, err := s.ListBuilds(repoID, BuildFilter{Job: "lint"}, 10); err != nil || len(byJob) != 1 || byJob[0].Job != "lint" {
408 t.Fatalf("by job: %+v %v", byJob, err)
409 }
410 if byStatus, err := s.ListBuilds(repoID, BuildFilter{Status: "failure"}, 10); err != nil || len(byStatus) != 1 || byStatus[0].Status != "failure" {
411 t.Fatalf("by status: %+v %v", byStatus, err)
412 }
413 if combined, err := s.ListBuilds(repoID, BuildFilter{Ref: "main", Status: "failure"}, 10); err != nil || len(combined) != 1 {
414 t.Fatalf("combined filter: %+v %v", combined, err)
415 }
416 if none, err := s.ListBuilds(repoID, BuildFilter{Ref: "main", Status: "pending"}, 10); err != nil || len(none) != 0 {
417 t.Fatalf("non-matching combination: %+v %v", none, err)
418 }
419}
420
421// mustClaim claims the oldest pending build for repoID, failing the test
422// if none is available.
423func mustClaim(t *testing.T, s *Store, repoID int64) Build {
424 t.Helper()
425 b, ok, err := s.ClaimBuild([]int64{repoID}, false)
426 if err != nil || !ok {
427 t.Fatalf("claim: %v ok=%v", err, ok)
428 }
429 return b
430}
431
432// A merge request head from a fork is untrusted. A claim skips it unless
433// the runner asked for untrusted builds, so a runner on someone's laptop
434// never executes a stranger's branch by default.
435func TestClaimBuildSkipsUntrustedUnlessAsked(t *testing.T) {
436 s := open(t)
437 if err := s.MigrateUp(); err != nil {
438 t.Fatal(err)
439 }
440 uid, err := s.CreateUser("cmc", true)
441 if err != nil {
442 t.Fatal(err)
443 }
444 repo, err := s.CreateRepo("user", uid, "app", "public")
445 if err != nil {
446 t.Fatal(err)
447 }
448 // Queued first, so an unfiltered claim would take it.
449 forkBuild, err := s.CreateBuild(repo, "unit", "abc123", "refs/merge-requests/1/head", `["true"]`, "", "", false)
450 if err != nil {
451 t.Fatal(err)
452 }
453 own, err := s.CreateBuild(repo, "unit", "def456", "main", `["true"]`, "", "", true)
454 if err != nil {
455 t.Fatal(err)
456 }
457 b, ok, err := s.ClaimBuild(nil, false)
458 if err != nil || !ok || b.Number != own {
459 t.Fatalf("trusted-only claim: err=%v ok=%v number=%d, want %d", err, ok, b.Number, own)
460 }
461 if _, ok, _ := s.ClaimBuild(nil, false); ok {
462 t.Fatal("trusted-only claim took the fork build")
463 }
464 b, ok, err = s.ClaimBuild(nil, true)
465 if err != nil || !ok || b.Number != forkBuild {
466 t.Fatalf("untrusted claim: err=%v ok=%v number=%d, want %d", err, ok, b.Number, forkBuild)
467 }
468}
469
470// A follower's channel closes on each kind of change to its build, and
471// only its build.
472func TestBuildLogWaitWakes(t *testing.T) {
473 s := open(t)
474 if err := s.MigrateUp(); err != nil {
475 t.Fatal(err)
476 }
477 uid, err := s.CreateUser("cmc", true)
478 if err != nil {
479 t.Fatal(err)
480 }
481 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
482 t.Fatal(err)
483 }
484 newBuild := func() int64 {
485 t.Helper()
486 id, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
487 if err != nil {
488 t.Fatal(err)
489 }
490 return id
491 }
492 closed := func(ch <-chan struct{}) bool {
493 select {
494 case <-ch:
495 return true
496 default:
497 return false
498 }
499 }
500
501 a, b := newBuild(), newBuild()
502 wa, wb := s.BuildLogWait(a), s.BuildLogWait(b)
503 if err := s.AppendBuildLog(a, []byte("x")); err != nil {
504 t.Fatal(err)
505 }
506 if !closed(wa) {
507 t.Error("append did not wake its build")
508 }
509 if closed(wb) {
510 t.Error("append woke another build")
511 }
512
513 mustClaim(t, s, 1) // claims a, the oldest
514 wa = s.BuildLogWait(a)
515 if err := s.FinishBuild(a, "success"); err != nil {
516 t.Fatal(err)
517 }
518 if !closed(wa) {
519 t.Error("finish did not wake")
520 }
521
522 if err := s.CancelBuild(b); err != nil {
523 t.Fatal(err)
524 }
525 if !closed(wb) {
526 t.Error("cancel did not wake")
527 }
528}
529
530// Offsets are bytes, not characters: || stores the log as text, and a
531// multibyte character must not shift where the next read starts.
532func TestBuildLogFrom(t *testing.T) {
533 s := open(t)
534 if err := s.MigrateUp(); err != nil {
535 t.Fatal(err)
536 }
537 uid, err := s.CreateUser("cmc", true)
538 if err != nil {
539 t.Fatal(err)
540 }
541 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
542 t.Fatal(err)
543 }
544 id, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
545 if err != nil {
546 t.Fatal(err)
547 }
548 first := "héllo — ok\n"
549 for _, c := range []string{first, "wörld\n"} {
550 if err := s.AppendBuildLog(id, []byte(c)); err != nil {
551 t.Fatal(err)
552 }
553 }
554 status, all, err := s.BuildLogFrom(id, 0)
555 if err != nil || status != "pending" || string(all) != first+"wörld\n" {
556 t.Fatalf("from 0: %q %q %v", status, all, err)
557 }
558 _, rest, err := s.BuildLogFrom(id, int64(len(first)))
559 if err != nil || string(rest) != "wörld\n" {
560 t.Fatalf("from %d: %q %v", len(first), rest, err)
561 }
562 _, none, err := s.BuildLogFrom(id, int64(len(all)))
563 if err != nil || len(none) != 0 {
564 t.Fatalf("from the end: %q %v", none, err)
565 }
566 if _, _, err := s.BuildLogFrom(9999, 0); err != ErrNotFound {
567 t.Fatalf("missing build: %v", err)
568 }
569}
570
571// Where a failed build stopped is recorded while it runs, before the
572// outcome, and a finished build is not rewritten (#266).
573func TestSetBuildFailure(t *testing.T) {
574 s := open(t)
575 if err := s.MigrateUp(); err != nil {
576 t.Fatal(err)
577 }
578 uid, _ := s.CreateUser("cmc", true)
579 repoID, _ := s.CreateRepo("user", uid, "app", "public")
580 if _, err := s.CreateBuild(repoID, "unit", "abc", "main", `["true","false"]`, "", "", true); err != nil {
581 t.Fatal(err)
582 }
583 b, ok, err := s.ClaimBuild(nil, false)
584 if err != nil || !ok {
585 t.Fatalf("claim: ok=%v err=%v", ok, err)
586 }
587 if err := s.SetBuildFailure(b.ID, 2, "exit 1"); err != nil {
588 t.Fatal(err)
589 }
590 if err := s.FinishBuild(b.ID, "failure"); err != nil {
591 t.Fatal(err)
592 }
593 got, err := s.BuildByID(b.ID)
594 if err != nil {
595 t.Fatal(err)
596 }
597 if got.FailedStep != 2 || got.FailedReason != "exit 1" {
598 t.Fatalf("failed step %d reason %q", got.FailedStep, got.FailedReason)
599 }
600 if err := s.SetBuildFailure(b.ID, 1, "late"); !errors.Is(err, ErrNotFound) {
601 t.Fatalf("rewrote a finished build: %v", err)
602 }
603}