Commit `631ccdc137`

631ccdc1372e120416b96898dd26804f3c1c45e7

parent: c3f59fc38f

Verified · cmc ci/build: success ci/test: success

cmc <hello@cleberg.net> · 2026-09-07 05:04 UTC

store, control, wiki: fail a build whose log stream ended with no outcome

The reaper keyed only on a fixed deadline, so a build whose runner died
sat running for the better part of an hour. The end of the runner's log
stream is the last thing the server hears from a dying runner; recorded
on the build, and the scheduler fails the build two minutes later if no
outcome has followed. Migration 0046.

Ref #179

Layout: unified · split

.gitbay/wiki/Admin.org +4 −1

		@@ -398,7 +398,10 @@ necessity, so the boundary is you choosing how to start it.
398	398	that has polled as a runner: when it last polled, the =-repos= scope it
399	399	asked for, and the build it holds. A build a runner claimed and never
400	400	reported is failed by the scheduler's minute tick, whether or not any
401		runner is still alive.
	401	runner is still alive: within about two minutes of its log stream ending
	402	with no outcome reported — the runner reports right after closing the
	403	stream, retrying for half a minute if gitbayd is unreachable — or, if no
	404	stream was ever seen, at the deadline.
402	405
403	406	Instance admin on the runner account only authorizes the claim/report
404	407	protocol; it grants no repo access. A build that pushes back — a pages

internal/control/build.go +6

		@@ -461,6 +461,12 @@ func runRunnerLog(c *Ctx, args []string) int {
461	461	if dropped > 0 {
462	462	slog.Warn("build log incomplete", "build", id, "dropped_chunks", dropped)
463	463	}
	464	// The stream ending is the last thing the server hears
	465	// from a runner that is about to die; note the time so
	466	// the scheduler can fail the build if no outcome follows.
	467	if err := c.Store.MarkBuildLogClosed(id); err != nil {
	468	slog.Warn("marking build log closed", "build", id, "err", err)
	469	}
464	470	return c.emit(map[string]string{"log": "ok"}, func(w io.Writer) {})
465	471	}
466	472	case <-watch.C:

internal/control/runnernext_test.go +26

		@@ -215,3 +215,29 @@ func TestRunnerNextClaimsBuildWhenReachabilityCannotBeChecked(t *testing.T) {
215	215	t.Fatalf("build status = %q, want running: an unchecked build must still be claimable", b.Status)
216	216	}
217	217	}
	218
	219	// runner log records when the stream ended, so a build whose runner then
	220	// vanishes is failed within minutes rather than at the deadline (#179).
	221	func TestRunnerLogMarksStreamClosed(t *testing.T) {
	222	st, repo, uid := newQueueTestRepo(t)
	223	root := t.TempDir()
	224	if _, err := st.CreateBuild(repo.ID, "unit", strings.Repeat("a", 40), "main", "[]", "", "", true); err != nil {
	225	t.Fatal(err)
	226	}
	227	b, ok, err := st.ClaimBuild([]int64{repo.ID})
	228	if err != nil \|\| !ok {
	229	t.Fatalf("claim: %v", err)
	230	}
	231	c, _ := runnerCtx(st, uid, root)
	232	c.Stdin = strings.NewReader("hello\n") // one chunk, then EOF: the stream ends
	233	if code := runRunnerLog(c, []string{fmt.Sprint(b.ID)}); code != 0 {
	234	t.Fatalf("runner log exited %d", code)
	235	}
	236	got, _ := st.BuildByID(b.ID)
	237	if got.LogClosedAt == "" {
	238	t.Fatal("log_closed_at not set when the stream ended")
	239	}
	240	if got.Status != "running" {
	241	t.Errorf("status %s, want still running until the runner reports", got.Status)
	242	}
	243	}

internal/store/builds.go +33 −6

		@@ -24,6 +24,9 @@ type Build struct {
24	24	CreatedAt string
25	25	StartedAt string
26	26	FinishedAt string
	27	// LogClosedAt is when the runner's log stream ended; "" while it is
	28	// open or was never opened. Set on a running build only.
	29	LogClosedAt string
27	30	// Trusted is false for a merge request head fetched from another
28	31	// repository: its steps run without the target's secrets.
29	32	Trusted bool
		@@ -62,14 +65,14 @@ func (s *Store) CreateBuild(repoID int64, job, sha, ref, stepsJSON, image, tree
62	65	}
63	66
64	67	const buildSelect = `
65		SELECT id, repo_id, number, job, sha, ref, steps, image, tree, status, created_at, started_at, finished_at, trusted
	68	SELECT id, repo_id, number, job, sha, ref, steps, image, tree, status, created_at, started_at, finished_at, log_closed_at, trusted
66	69	FROM builds`
67	70
68	71	func scanBuild(row interface{ Scan(...any) error }) (Build, error) {
69	72	var b Build
70	73	var trusted int
71	74	err := row.Scan(&b.ID, &b.RepoID, &b.Number, &b.Job, &b.SHA, &b.Ref, &b.Steps, &b.Image, &b.Tree,
72		&b.Status, &b.CreatedAt, &b.StartedAt, &b.FinishedAt, &trusted)
	75	&b.Status, &b.CreatedAt, &b.StartedAt, &b.FinishedAt, &b.LogClosedAt, &trusted)
73	76	b.Trusted = trusted != 0
74	77	return b, err
75	78	}
		@@ -131,14 +134,38 @@ func staleBuildDeadline() time.Duration {
131	134	return StaleBuildDeadline
132	135	}
133	136
134		// ReapStaleBuilds fails every build that has been running past the deadline and
135		// returns them, so the caller can resolve their commit statuses. A runner that
	137	// StaleLogGrace is how long a running build may go on after its log
	138	// stream ended before it is treated as abandoned. The runner reports the
	139	// outcome right after closing the stream, retrying for about thirty
	140	// seconds if the server is unreachable; two minutes outlasts that.
	141	const StaleLogGrace = 2 * time.Minute
	142
	143	// MarkBuildLogClosed records that the runner's log stream for a build
	144	// ended, on a build still running. A build that finishes normally is
	145	// reported moments later and the mark is moot; one that is not has lost
	146	// its runner, and ReapStaleBuilds fails it after StaleLogGrace rather
	147	// than at the deadline (#179).
	148	func (s *Store) MarkBuildLogClosed(id int64) error {
	149	_, err := s.DB.Exec(`
	150	UPDATE builds SET log_closed_at = strftime('%Y-%m-%dT%H:%M:%SZ','now')
	151	WHERE id = ? AND status = 'running' AND log_closed_at = ''`, id)
	152	return err
	153	}
	154
	155	// ReapStaleBuilds fails every running build whose runner is gone and
	156	// returns them, so the caller can resolve their commit statuses: one whose
	157	// log stream ended more than StaleLogGrace ago with no outcome reported,
	158	// or one running past the deadline with no stream ever seen. A runner that
136	159	// dies between claiming a build and reporting it otherwise leaves the row
137	160	// claimed forever, and the commit pending forever with it.
138	161	func (s *Store) ReapStaleBuilds() ([]Build, error) {
139		cutoff := time.Now().UTC().Add(-staleBuildDeadline()).Format("2006-01-02T15:04:05Z")
	162	const layout = "2006-01-02T15:04:05Z"
	163	now := time.Now().UTC()
	164	cutoff := now.Add(-staleBuildDeadline()).Format(layout)
	165	logCutoff := now.Add(-StaleLogGrace).Format(layout)
140	166	rows, err := s.DB.Query(buildSelect+
141		" WHERE status = 'running' AND started_at != '' AND started_at < ?", cutoff)
	167	" WHERE status = 'running' AND ((started_at != '' AND started_at < ?)"+
	168	" OR (log_closed_at != '' AND log_closed_at < ?))", cutoff, logCutoff)
142	169	if err != nil {
143	170	return nil, err
144	171	}

internal/store/builds_test.go +49

		@@ -248,3 +248,52 @@ func TestSuccessBuildForTree(t *testing.T) {
248	248	t.Error("an empty tree matched")
249	249	}
250	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).
	254	func 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}); 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	}

internal/store/migrations/0046_build_log_closed.down.sql added +1

		@@ -0,0 +1 @@
	1	ALTER TABLE builds DROP COLUMN log_closed_at;

internal/store/migrations/0046_build_log_closed.up.sql added +5

		@@ -0,0 +1,5 @@
	1	-- When a build's log stream from the runner ended. A runner reports a
	2	-- build's outcome right after closing the stream; a stream that closed
	3	-- with no outcome following means the runner is gone, and the build can
	4	-- be failed within minutes instead of at the deadline (#179).
	5	ALTER TABLE builds ADD COLUMN log_closed_at TEXT NOT NULL DEFAULT '';

Commit 631ccdc137

Commit `631ccdc137`