internal/store/builds_test.go
371 lines · 11388 bytes
1package store
2
3import (
4 "strings"
5 "testing"
6)
7
8// A runner that dies between claiming a build and reporting it leaves the row
9// claimed. The next claim resolves it rather than leaving the build running and
10// the commit pending forever.
11func TestReapStaleBuilds(t *testing.T) {
12 s := open(t)
13 if err := s.MigrateUp(); err != nil {
14 t.Fatal(err)
15 }
16 uid, err := s.CreateUser("cmc", true)
17 if err != nil {
18 t.Fatal(err)
19 }
20 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
21 t.Fatal(err)
22 }
23
24 stuck, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
25 if err != nil {
26 t.Fatal(err)
27 }
28 fresh, err := s.CreateBuild(1, "pages", "abc123", "main", `["true"]`, "", "", true)
29 if err != nil {
30 t.Fatal(err)
31 }
32
33 // Claim both, then age only the first past the deadline.
34 for range 2 {
35 if _, ok, err := s.ClaimBuild(nil, false); err != nil || !ok {
36 t.Fatalf("claim: %v ok=%v", err, ok)
37 }
38 }
39 if _, err := s.DB.Exec(
40 `UPDATE builds SET started_at = '2020-01-01T00:00:00Z' WHERE number = ?`, stuck); err != nil {
41 t.Fatal(err)
42 }
43
44 reaped, err := s.ReapStaleBuilds()
45 if err != nil {
46 t.Fatal(err)
47 }
48 if len(reaped) != 1 || reaped[0].Number != stuck {
49 t.Fatalf("reaped %+v, want only build %d", reaped, stuck)
50 }
51
52 b, err := s.BuildByNumber(1, stuck)
53 if err != nil {
54 t.Fatal(err)
55 }
56 if b.Status != "failure" || b.FinishedAt == "" {
57 t.Fatalf("stale build is %s finished %q, want failure with a timestamp", b.Status, b.FinishedAt)
58 }
59 log, err := s.BuildLog(b.ID)
60 if err != nil {
61 t.Fatal(err)
62 }
63 if !strings.Contains(string(log), "abandoned") {
64 t.Fatalf("log does not say why it failed: %q", log)
65 }
66
67 // A build still inside the deadline is left alone.
68 if b, err := s.BuildByNumber(1, fresh); err != nil || b.Status != "running" {
69 t.Fatalf("fresh build is %v (%v), want running", b.Status, err)
70 }
71}
72
73// Checks on a merge request report how long their build ran, which means
74// pairing ci/<job> statuses with builds on the same commit.
75func TestBuildsForCommitTiming(t *testing.T) {
76 s := open(t)
77 if err := s.MigrateUp(); err != nil {
78 t.Fatal(err)
79 }
80 uid, err := s.CreateUser("cmc", true)
81 if err != nil {
82 t.Fatal(err)
83 }
84 repoID, err := s.CreateRepo("user", uid, "lib", "public")
85 if err != nil {
86 t.Fatal(err)
87 }
88 // Two runs of the same job on one commit: the retry is what counts.
89 for range 2 {
90 if _, err := s.CreateBuild(repoID, "test", "abc123", "main", `["true"]`, "", "", true); err != nil {
91 t.Fatal(err)
92 }
93 }
94 if _, err := s.CreateBuild(repoID, "lint", "def456", "main", `["true"]`, "", "", true); err != nil {
95 t.Fatal(err)
96 }
97 if _, err := s.DB.Exec(`UPDATE builds SET started_at = '2026-08-28T04:42:54Z',
98 finished_at = '2026-08-28T04:44:06Z', status = 'success' WHERE number = 2`); err != nil {
99 t.Fatal(err)
100 }
101
102 byJob, err := s.BuildsForCommit(repoID, "abc123")
103 if err != nil {
104 t.Fatal(err)
105 }
106 if len(byJob) != 1 {
107 t.Fatalf("builds for commit: %+v", byJob)
108 }
109 b := byJob["test"]
110 if b.Number != 2 {
111 t.Fatalf("older run won: %d", b.Number)
112 }
113 if got := b.Elapsed().String(); got != "1m12s" {
114 t.Fatalf("elapsed: %s", got)
115 }
116 // A build that never finished has no duration to report.
117 if d := byJob["lint"].Elapsed(); d != 0 {
118 t.Fatalf("unfinished build reported %s", d)
119 }
120}
121
122// A runner that names repositories claims only their builds, so a runner on a
123// machine that should not execute every repository's steps does not pick one
124// up by being first to ask.
125func TestClaimBuildScopedToRepos(t *testing.T) {
126 s := open(t)
127 if err := s.MigrateUp(); err != nil {
128 t.Fatal(err)
129 }
130 uid, err := s.CreateUser("cmc", true)
131 if err != nil {
132 t.Fatal(err)
133 }
134 mine, err := s.CreateRepo("user", uid, "site", "public")
135 if err != nil {
136 t.Fatal(err)
137 }
138 theirs, err := s.CreateRepo("user", uid, "stranger", "public")
139 if err != nil {
140 t.Fatal(err)
141 }
142 // Queued first, so an unscoped claim would take it.
143 if _, err := s.CreateBuild(theirs, "evil", "abc123", "main", `["true"]`, "", "", true); err != nil {
144 t.Fatal(err)
145 }
146 wanted, err := s.CreateBuild(mine, "deploy", "def456", "main", `["true"]`, "", "", true)
147 if err != nil {
148 t.Fatal(err)
149 }
150
151 b, ok, err := s.ClaimBuild([]int64{mine}, false)
152 if err != nil || !ok {
153 t.Fatalf("claim: %v ok=%v", err, ok)
154 }
155 if b.RepoID != mine || b.Number != wanted {
156 t.Fatalf("claimed repo %d build %d, want repo %d build %d",
157 b.RepoID, b.Number, mine, wanted)
158 }
159
160 // Nothing left for that scope, even though another repo's build is pending.
161 if _, ok, err := s.ClaimBuild([]int64{mine}, false); err != nil || ok {
162 t.Fatalf("second scoped claim: err=%v ok=%v, want no build", err, ok)
163 }
164 // An unscoped runner still takes it.
165 if b, ok, err := s.ClaimBuild(nil, false); err != nil || !ok || b.RepoID != theirs {
166 t.Fatalf("unscoped claim: err=%v ok=%v repo=%d", err, ok, b.RepoID)
167 }
168}
169
170// A log that stops at the cap reads exactly like a build that died mid-step,
171// which is what sent people hunting for a test failure that was never there.
172// It says so instead, once.
173func TestBuildLogSaysWhenItTruncates(t *testing.T) {
174 s := open(t)
175 if err := s.MigrateUp(); err != nil {
176 t.Fatal(err)
177 }
178 uid, err := s.CreateUser("cmc", true)
179 if err != nil {
180 t.Fatal(err)
181 }
182 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
183 t.Fatal(err)
184 }
185 id, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true)
186 if err != nil {
187 t.Fatal(err)
188 }
189
190 chunk := make([]byte, 256<<10)
191 for i := range chunk {
192 chunk[i] = 'x'
193 }
194 // Well past the cap, so plenty of appends land after it.
195 for written := 0; written < MaxBuildLog+(4*len(chunk)); written += len(chunk) {
196 if err := s.AppendBuildLog(id, chunk); err != nil {
197 t.Fatal(err)
198 }
199 }
200
201 log, err := s.BuildLog(id)
202 if err != nil {
203 t.Fatal(err)
204 }
205 if n := strings.Count(string(log), "log truncated"); n != 1 {
206 t.Errorf("truncation notice appears %d times, want exactly 1", n)
207 }
208 if !strings.HasSuffix(string(log), string(truncNotice)) {
209 t.Error("notice is not at the end of the log")
210 }
211 if len(log) > MaxBuildLog+len(truncNotice)+len(chunk) {
212 t.Errorf("log grew to %d, past the cap plus one chunk", len(log))
213 }
214}
215
216// A success is found by tree across commits; an empty tree never matches,
217// so builds queued without one (scheduled, tag) are never reused (#177).
218func TestSuccessBuildForTree(t *testing.T) {
219 s := open(t)
220 if err := s.MigrateUp(); err != nil {
221 t.Fatal(err)
222 }
223 uid, err := s.CreateUser("cmc", true)
224 if err != nil {
225 t.Fatal(err)
226 }
227 repoID, err := s.CreateRepo("user", uid, "app", "public")
228 if err != nil {
229 t.Fatal(err)
230 }
231 if _, err := s.CreateBuild(repoID, "unit", "aaa", "main", `["true"]`, "", "tree1", true); err != nil {
232 t.Fatal(err)
233 }
234 b, _ := s.BuildsForCommit(repoID, "aaa")
235 if _, ok, err := s.ClaimBuild([]int64{repoID}, false); err != nil || !ok {
236 t.Fatalf("claim: ok=%v err=%v", ok, err)
237 }
238 if err := s.FinishBuild(b["unit"].ID, "success"); err != nil {
239 t.Fatal(err)
240 }
241 if prev, ok, _ := s.SuccessBuildForTree(repoID, "tree1", "unit"); !ok || prev.SHA != "aaa" {
242 t.Fatalf("success not found by tree: ok=%v prev=%+v", ok, prev)
243 }
244 if _, ok, _ := s.SuccessBuildForTree(repoID, "tree1", "other"); ok {
245 t.Error("matched a different job")
246 }
247 if _, ok, _ := s.SuccessBuildForTree(repoID, "", "unit"); ok {
248 t.Error("an empty tree matched")
249 }
250}
251
252// A running build whose log stream ended is reaped after StaleLogGrace,
253// well before the deadline; one whose stream is still open is not (#179).
254func TestReapStaleBuildsAfterLogClosed(t *testing.T) {
255 s := open(t)
256 if err := s.MigrateUp(); err != nil {
257 t.Fatal(err)
258 }
259 uid, _ := s.CreateUser("cmc", true)
260 repoID, _ := s.CreateRepo("user", uid, "app", "public")
261 for _, job := range []string{"gone", "alive"} {
262 if _, err := s.CreateBuild(repoID, job, "abc", "main", `["true"]`, "", "", true); err != nil {
263 t.Fatal(err)
264 }
265 if _, ok, err := s.ClaimBuild([]int64{repoID}, false); err != nil || !ok {
266 t.Fatalf("claim %s: %v", job, err)
267 }
268 }
269 builds, _ := s.BuildsForCommit(repoID, "abc")
270 gone := builds["gone"].ID
271 if err := s.MarkBuildLogClosed(gone); err != nil {
272 t.Fatal(err)
273 }
274 // Just closed: within the grace period, nothing is reaped.
275 if stale, _ := s.ReapStaleBuilds(); len(stale) != 0 {
276 t.Fatalf("reaped inside the grace period: %+v", stale)
277 }
278 // Backdate the close past the grace period.
279 if _, err := s.DB.Exec("UPDATE builds SET log_closed_at = '2020-01-01T00:00:00Z' WHERE id = ?", gone); err != nil {
280 t.Fatal(err)
281 }
282 stale, err := s.ReapStaleBuilds()
283 if err != nil {
284 t.Fatal(err)
285 }
286 if len(stale) != 1 || stale[0].ID != gone {
287 t.Fatalf("reaped %+v, want only the build whose log closed", stale)
288 }
289 if b, _ := s.BuildByID(gone); b.Status != "failure" {
290 t.Errorf("reaped build is %s, want failure", b.Status)
291 }
292 if b, _ := s.BuildByID(builds["alive"].ID); b.Status != "running" {
293 t.Errorf("build with an open stream is %s, want running", b.Status)
294 }
295 // Marking is a no-op on a build that is no longer running.
296 if err := s.MarkBuildLogClosed(gone); err != nil {
297 t.Fatal(err)
298 }
299}
300
301// AVG is a float in SQLite; the stats scan it as whole seconds.
302func TestQueueStatsFractionalAverage(t *testing.T) {
303 s := open(t)
304 if err := s.MigrateUp(); err != nil {
305 t.Fatal(err)
306 }
307 uid, err := s.CreateUser("cmc", true)
308 if err != nil {
309 t.Fatal(err)
310 }
311 if _, err := s.CreateRepo("user", uid, "orgo", "public"); err != nil {
312 t.Fatal(err)
313 }
314 for range 2 {
315 if _, err := s.CreateBuild(1, "test", "abc123", "main", `["true"]`, "", "", true); err != nil {
316 t.Fatal(err)
317 }
318 if _, ok, err := s.ClaimBuild(nil, false); err != nil || !ok {
319 t.Fatalf("claim: %v ok=%v", err, ok)
320 }
321 }
322 // Waits of 1 s and 2 s: an average of 1.5.
323 if _, err := s.DB.Exec(`UPDATE builds SET created_at = strftime('%Y-%m-%dT%H:%M:%SZ', started_at, '-' || number || ' seconds')`); err != nil {
324 t.Fatal(err)
325 }
326 q, err := s.QueueStats()
327 if err != nil {
328 t.Fatal(err)
329 }
330 if q.Claimed24h != 2 || q.ClaimWaitAvgS != 1 || q.ClaimWaitMaxS != 2 || q.Pending != 0 || q.Reaped24h != 0 {
331 t.Fatalf("stats: %+v", q)
332 }
333}
334
335// A merge request head from a fork is untrusted. A claim skips it unless
336// the runner asked for untrusted builds, so a runner on someone's laptop
337// never executes a stranger's branch by default.
338func TestClaimBuildSkipsUntrustedUnlessAsked(t *testing.T) {
339 s := open(t)
340 if err := s.MigrateUp(); err != nil {
341 t.Fatal(err)
342 }
343 uid, err := s.CreateUser("cmc", true)
344 if err != nil {
345 t.Fatal(err)
346 }
347 repo, err := s.CreateRepo("user", uid, "app", "public")
348 if err != nil {
349 t.Fatal(err)
350 }
351 // Queued first, so an unfiltered claim would take it.
352 forkBuild, err := s.CreateBuild(repo, "unit", "abc123", "refs/merge-requests/1/head", `["true"]`, "", "", false)
353 if err != nil {
354 t.Fatal(err)
355 }
356 own, err := s.CreateBuild(repo, "unit", "def456", "main", `["true"]`, "", "", true)
357 if err != nil {
358 t.Fatal(err)
359 }
360 b, ok, err := s.ClaimBuild(nil, false)
361 if err != nil || !ok || b.Number != own {
362 t.Fatalf("trusted-only claim: err=%v ok=%v number=%d, want %d", err, ok, b.Number, own)
363 }
364 if _, ok, _ := s.ClaimBuild(nil, false); ok {
365 t.Fatal("trusted-only claim took the fork build")
366 }
367 b, ok, err = s.ClaimBuild(nil, true)
368 if err != nil || !ok || b.Number != forkBuild {
369 t.Fatalf("untrusted claim: err=%v ok=%v number=%d, want %d", err, ok, b.Number, forkBuild)
370 }
371}