Commit 286e0c3891

286e0c38917d6a5a20ed0ea843d53793618eacff

parent: 6421e2fd3b

Verified · cmc

cmc <hello@cleberg.net> · 2026-09-28 07:49 UTC

runner: name the failed step and report it

Ref #266

Layout: unified · split

cmd/gitbay-runner/isolate.go +17 −17
@@ -76,25 +76,25 @@ func (r *runner) checkIsolation() error {
76 } 76 }
77} 77}
78 78
79// runSteps executes a job's steps and reports whether all succeeded. The 79// runSteps executes a job's steps. Returns nil when every step succeeded.
80// clone has already happened, outside any container and with the runner's 80// The clone has already happened, outside any container and with the
81// key: the container never sees GIT_SSH_COMMAND, the key, or the runner's 81// runner's key: the container never sees GIT_SSH_COMMAND, the key, or the
82// environment — it gets the workspace and nothing else. 82// runner's environment — it gets the workspace and nothing else.
83type stepRunner func(cmd *exec.Cmd, deadline time.Time) (bool, string) 83type stepRunner func(cmd *exec.Cmd, deadline time.Time) (bool, string)
84 84
85func (r *runner) runSteps(j job, dir string, env []string, sink io.Writer, deadline time.Time, runStep stepRunner) bool { 85func (r *runner) runSteps(j job, dir string, env []string, sink io.Writer, deadline time.Time, runStep stepRunner) *failure {
86 if r.isolation == isolationNone { 86 if r.isolation == isolationNone {
87 for _, step := range j.Steps { 87 for i, step := range j.Steps {
88 fmt.Fprintf(sink, "$ %s\n", step) 88 fmt.Fprintf(sink, "$ %s\n", step)
89 cmd := exec.Command(toolpath.Look("sh"), "-c", step) 89 cmd := exec.Command(toolpath.Look("sh"), "-c", step)
90 cmd.Dir, cmd.Env = dir, env 90 cmd.Dir, cmd.Env = dir, env
91 cmd.Stdout, cmd.Stderr = sink, sink 91 cmd.Stdout, cmd.Stderr = sink, sink
92 if ok, why := runStep(cmd, deadline); !ok { 92 if ok, why := runStep(cmd, deadline); !ok {
93 fmt.Fprintf(sink, "%s\n", why) 93 fmt.Fprintf(sink, "step %d/%d failed: %s\n", i+1, len(j.Steps), why)
94 return false 94 return &failure{Step: i + 1, Reason: why}
95 } 95 }
96 } 96 }
97 return true 97 return nil
98 } 98 }
99 return r.runStepsPodman(j, dir, env, sink, deadline, runStep) 99 return r.runStepsPodman(j, dir, env, sink, deadline, runStep)
100} 100}
@@ -103,7 +103,7 @@ func (r *runner) runSteps(j job, dir string, env []string, sink io.Writer, deadl
103// step in it with `podman exec`. One container per job, not per step, 103// step in it with `podman exec`. One container per job, not per step,
104// because steps share state — a build step writes what a test step reads 104// because steps share state — a build step writes what a test step reads
105// — and per-step containers would break that. 105// — and per-step containers would break that.
106func (r *runner) runStepsPodman(j job, dir string, env []string, sink io.Writer, deadline time.Time, runStep stepRunner) bool { 106func (r *runner) runStepsPodman(j job, dir string, env []string, sink io.Writer, deadline time.Time, runStep stepRunner) *failure {
107 podman := toolpath.Look("podman") 107 podman := toolpath.Look("podman")
108 image := j.Image 108 image := j.Image
109 if image == "" { 109 if image == "" {
@@ -124,7 +124,7 @@ func (r *runner) runStepsPodman(j job, dir string, env []string, sink io.Writer,
124 envFile := filepath.Join(r.workdir, fmt.Sprintf("env-%d", j.ID)) 124 envFile := filepath.Join(r.workdir, fmt.Sprintf("env-%d", j.ID))
125 if err := writeEnvFile(envFile, fileEnv); err != nil { 125 if err := writeEnvFile(envFile, fileEnv); err != nil {
126 fmt.Fprintf(sink, "preparing the build environment: %v\n", err) 126 fmt.Fprintf(sink, "preparing the build environment: %v\n", err)
127 return false 127 return &failure{Reason: "preparing the build environment failed"}
128 } 128 }
129 defer os.Remove(envFile) 129 defer os.Remove(envFile)
130 130
@@ -137,7 +137,7 @@ func (r *runner) runStepsPodman(j job, dir string, env []string, sink io.Writer,
137 dir, f, err := r.cgroups.create(j.ID, r.memory, r.cpus) 137 dir, f, err := r.cgroups.create(j.ID, r.memory, r.cpus)
138 if err != nil { 138 if err != nil {
139 fmt.Fprintf(sink, "preparing the build cgroup: %v\n", err) 139 fmt.Fprintf(sink, "preparing the build cgroup: %v\n", err)
140 return false 140 return &failure{Reason: "preparing the build cgroup failed"}
141 } 141 }
142 cgroupFD = f 142 cgroupFD = f
143 defer f.Close() 143 defer f.Close()
@@ -179,22 +179,22 @@ func (r *runner) runStepsPodman(j job, dir string, env []string, sink io.Writer,
179 fmt.Fprintf(sink, "\nThis runner does not pull images. Ask an operator to provision %s "+ 179 fmt.Fprintf(sink, "\nThis runner does not pull images. Ask an operator to provision %s "+
180 "on the runner host (podman pull, or podman build) before a job names it.\n", image) 180 "on the runner host (podman pull, or podman build) before a job names it.\n", image)
181 } 181 }
182 return false 182 return &failure{Reason: "starting the build container failed"}
183 } 183 }
184 defer exec.Command(podman, append(r.podmanGlobal(), "rm", "--force", name)...).Run() 184 defer exec.Command(podman, append(r.podmanGlobal(), "rm", "--force", name)...).Run()
185 185
186 for _, step := range j.Steps { 186 for i, step := range j.Steps {
187 fmt.Fprintf(sink, "$ %s\n", step) 187 fmt.Fprintf(sink, "$ %s\n", step)
188 cmd := exec.Command(podman, append(r.podmanGlobal(), "exec", "--workdir", "/workspace", name, "sh", "-c", step)...) 188 cmd := exec.Command(podman, append(r.podmanGlobal(), "exec", "--workdir", "/workspace", name, "sh", "-c", step)...)
189 cmd.Env = []string{"PATH=" + os.Getenv("PATH"), "HOME=" + r.podmanHome()} 189 cmd.Env = []string{"PATH=" + os.Getenv("PATH"), "HOME=" + r.podmanHome()}
190 intoCgroup(cmd, cgroupFD) 190 intoCgroup(cmd, cgroupFD)
191 cmd.Stdout, cmd.Stderr = sink, sink 191 cmd.Stdout, cmd.Stderr = sink, sink
192 if ok, why := runStep(cmd, deadline); !ok { 192 if ok, why := runStep(cmd, deadline); !ok {
193 fmt.Fprintf(sink, "%s\n", why) 193 fmt.Fprintf(sink, "step %d/%d failed: %s\n", i+1, len(j.Steps), why)
194 return false 194 return &failure{Step: i + 1, Reason: why}
195 } 195 }
196 } 196 }
197 return true 197 return nil
198} 198}
199 199
200// podmanGlobal are the flags every podman invocation needs, before the 200// podmanGlobal are the flags every podman invocation needs, before the
cmd/gitbay-runner/main.go +33 −11
@@ -11,6 +11,7 @@ package main
11 11
12import ( 12import (
13 "encoding/json" 13 "encoding/json"
14 "errors"
14 "flag" 15 "flag"
15 "fmt" 16 "fmt"
16 "io" 17 "io"
@@ -274,11 +275,12 @@ func (r *runner) step() (bool, error) {
274 } 275 }
275 j := env.Data 276 j := env.Data
276 log.Printf("build %d: %s %s @ %.10s", j.ID, j.Repo, j.Job, j.SHA) 277 log.Printf("build %d: %s %s @ %.10s", j.ID, j.Repo, j.Job, j.SHA)
277 status := "failure" 278 f := r.run(j)
278 if r.run(j) { 279 status := "success"
279 status = "success" 280 if f != nil {
281 status = "failure"
280 } 282 }
281 if err := r.reportDone(j.ID, status); err != nil { 283 if err := r.reportDone(j.ID, status, f); err != nil {
282 return true, err 284 return true, err
283 } 285 }
284 log.Printf("build %d: %s", j.ID, status) 286 log.Printf("build %d: %s", j.ID, status)
@@ -315,16 +317,36 @@ func (s *logSink) broken() bool {
315 return s.w == nil 317 return s.w == nil
316} 318}
317 319
320// failure says where a build stopped: Step is the 1-based step that
321// failed, 0 when the build stopped before its first step (the clone, the
322// container), and Reason is one short line (#266).
323type failure struct {
324 Step int
325 Reason string
326}
327
328// exitReason is how a finished command's failure reads in a build's log
329// and on the build: "exit 1" for a command that exited, the error
330// otherwise (a signal, a start failure).
331func exitReason(err error) string {
332 var ee *exec.ExitError
333 if errors.As(err, &ee) && ee.ExitCode() >= 0 {
334 return fmt.Sprintf("exit %d", ee.ExitCode())
335 }
336 return err.Error()
337}
338
318// run clones, checks out, and executes the steps, streaming output to the 339// run clones, checks out, and executes the steps, streaming output to the
319// server. Returns whether every step succeeded. 340// server. Returns nil when every step succeeded, else where the build
320func (r *runner) run(j job) bool { 341// stopped.
342func (r *runner) run(j job) *failure {
321 dir := filepath.Join(r.workdir, fmt.Sprintf("build-%d", j.ID)) 343 dir := filepath.Join(r.workdir, fmt.Sprintf("build-%d", j.ID))
322 defer os.RemoveAll(dir) 344 defer os.RemoveAll(dir)
323 345
324 home, doneHome, err := buildHome(r.workdir, j) 346 home, doneHome, err := buildHome(r.workdir, j)
325 if err != nil { 347 if err != nil {
326 log.Printf("build %d: build home: %v", j.ID, err) 348 log.Printf("build %d: build home: %v", j.ID, err)
327 return false 349 return &failure{Reason: "preparing the build home failed"}
328 } 350 }
329 defer doneHome() 351 defer doneHome()
330 352
@@ -333,13 +355,13 @@ func (r *runner) run(j job) bool {
333 pipe, err := logCmd.StdinPipe() 355 pipe, err := logCmd.StdinPipe()
334 if err != nil { 356 if err != nil {
335 log.Printf("build %d: log pipe: %v", j.ID, err) 357 log.Printf("build %d: log pipe: %v", j.ID, err)
336 return false 358 return &failure{Reason: "opening the log stream failed"}
337 } 359 }
338 sink := &logSink{w: pipe} 360 sink := &logSink{w: pipe}
339 logCmd.Stdout, logCmd.Stderr = io.Discard, io.Discard 361 logCmd.Stdout, logCmd.Stderr = io.Discard, io.Discard
340 if err := logCmd.Start(); err != nil { 362 if err := logCmd.Start(); err != nil {
341 log.Printf("build %d: log stream: %v", j.ID, err) 363 log.Printf("build %d: log stream: %v", j.ID, err)
342 return false 364 return &failure{Reason: "opening the log stream failed"}
343 } 365 }
344 // The server ends the log session with exit 3 when the build is 366 // The server ends the log session with exit 3 when the build is
345 // cancelled; any other end is a lost stream, which the sink absorbs. 367 // cancelled; any other end is a lost stream, which the sink absorbs.
@@ -384,7 +406,7 @@ func (r *runner) run(j job) bool {
384 select { 406 select {
385 case err := <-done: 407 case err := <-done:
386 if err != nil { 408 if err != nil {
387 return false, fmt.Sprintf("step failed: %v", err) 409 return false, exitReason(err)
388 } 410 }
389 return true, "" 411 return true, ""
390 case <-cancelled: 412 case <-cancelled:
@@ -425,7 +447,7 @@ func (r *runner) run(j job) bool {
425 cmd.Stdout, cmd.Stderr = sink, sink 447 cmd.Stdout, cmd.Stderr = sink, sink
426 if ok, why := runStep(cmd, deadline); !ok { 448 if ok, why := runStep(cmd, deadline); !ok {
427 fmt.Fprintf(sink, "git %s: %s\n", args[0], why) 449 fmt.Fprintf(sink, "git %s: %s\n", args[0], why)
428 return false 450 return &failure{Reason: "git " + args[0] + ": " + why}
429 } 451 }
430 } 452 }
431 453
cmd/gitbay-runner/report.go +22 −2
@@ -4,6 +4,8 @@ import (
4 "errors" 4 "errors"
5 "fmt" 5 "fmt"
6 "os/exec" 6 "os/exec"
7 "strconv"
8 "strings"
7 "time" 9 "time"
8) 10)
9 11
@@ -16,12 +18,30 @@ import (
16// Only a connection-level failure is retried — ssh exits 255 for those. 18// Only a connection-level failure is retried — ssh exits 255 for those.
17// Any other exit is the server's answer, and asking again would not 19// Any other exit is the server's answer, and asking again would not
18// change it. Four retries over about thirty seconds outlasts a restart. 20// change it. Four retries over about thirty seconds outlasts a restart.
19func (r *runner) reportDone(id int64, status string) error { 21func (r *runner) reportDone(id int64, status string, f *failure) error {
22 args := doneArgs(id, status, f)
20 return reportWithRetry(func() (string, error) { 23 return reportWithRetry(func() (string, error) {
21 return r.ssh(nil, "runner", "done", fmt.Sprint(id), status) 24 return r.ssh(nil, args...)
22 }, id, retryDelays) 25 }, id, retryDelays)
23} 26}
24 27
28// doneArgs is the runner done command for a build's outcome. The reason
29// is single-quoted: ssh joins arguments with spaces, and the server
30// splits the line again with POSIX rules.
31func doneArgs(id int64, status string, f *failure) []string {
32 args := []string{"runner", "done", fmt.Sprint(id), status}
33 if f == nil {
34 return args
35 }
36 if f.Step > 0 {
37 args = append(args, "--step", strconv.Itoa(f.Step))
38 }
39 if f.Reason != "" {
40 args = append(args, "--reason", "'"+strings.ReplaceAll(f.Reason, "'", `'\''`)+"'")
41 }
42 return args
43}
44
25var retryDelays = []time.Duration{2 * time.Second, 4 * time.Second, 8 * time.Second, 16 * time.Second} 45var retryDelays = []time.Duration{2 * time.Second, 4 * time.Second, 8 * time.Second, 16 * time.Second}
26 46
27func reportWithRetry(report func() (string, error), id int64, delays []time.Duration) error { 47func reportWithRetry(report func() (string, error), id int64, delays []time.Duration) error {
cmd/gitbay-runner/report_test.go +23
@@ -3,8 +3,11 @@ package main
3import ( 3import (
4 "errors" 4 "errors"
5 "os/exec" 5 "os/exec"
6 "strings"
6 "testing" 7 "testing"
7 "time" 8 "time"
9
10 "gitbay.org/gitbay/internal/protocol"
8) 11)
9 12
10// exitErr fabricates the error ssh returns for a given exit status. 13// exitErr fabricates the error ssh returns for a given exit status.
@@ -61,3 +64,23 @@ func TestReportGivesUp(t *testing.T) {
61 t.Fatalf("err=%v calls=%d, want three attempts then an error", err, calls) 64 t.Fatalf("err=%v calls=%d, want three attempts then an error", err, calls)
62 } 65 }
63} 66}
67
68// The reason survives the trip: ssh joins arguments with spaces and the
69// server splits the line again with POSIX rules (#266).
70func TestDoneArgsNameTheFailedStep(t *testing.T) {
71 got := doneArgs(7, "failure", &failure{Step: 3, Reason: "can't: exit 1"})
72 argv, err := protocol.Tokenize(strings.Join(got, " "))
73 if err != nil {
74 t.Fatal(err)
75 }
76 want := []string{"runner", "done", "7", "failure", "--step", "3", "--reason", "can't: exit 1"}
77 if strings.Join(argv, "|") != strings.Join(want, "|") {
78 t.Fatalf("server reads %q, want %q", argv, want)
79 }
80 if got := doneArgs(7, "success", nil); strings.Join(got, " ") != "runner done 7 success" {
81 t.Fatalf("success: %q", got)
82 }
83 if got := doneArgs(7, "failure", &failure{Reason: "git clone: exit 128"}); strings.Contains(strings.Join(got, " "), "--step") {
84 t.Fatalf("a failure before any step sent a step: %q", got)
85 }
86}
cmd/gitbay-runner/steps_test.go added +33
@@ -0,0 +1,33 @@
1package main
2
3import (
4 "os"
5 "os/exec"
6 "strings"
7 "testing"
8 "time"
9)
10
11// The failing step is named by number in the log and in the outcome
12// reported to the server (#266).
13func TestRunStepsNamesTheFailedStep(t *testing.T) {
14 r := &runner{isolation: isolationNone}
15 run := func(cmd *exec.Cmd, _ time.Time) (bool, string) {
16 if err := cmd.Run(); err != nil {
17 return false, exitReason(err)
18 }
19 return true, ""
20 }
21 env := []string{"PATH=" + os.Getenv("PATH")}
22 var log strings.Builder
23 f := r.runSteps(job{Steps: []string{"true", "exit 3", "true"}}, t.TempDir(), env, &log, time.Now().Add(time.Minute), run)
24 if f == nil || f.Step != 2 || f.Reason != "exit 3" {
25 t.Fatalf("failure %+v, want step 2, exit 3", f)
26 }
27 if !strings.Contains(log.String(), "step 2/3 failed: exit 3\n") {
28 t.Fatalf("log does not name the step:\n%s", log.String())
29 }
30 if f := r.runSteps(job{Steps: []string{"true"}}, t.TempDir(), env, &log, time.Now().Add(time.Minute), run); f != nil {
31 t.Fatalf("a passing job failed: %+v", f)
32 }
33}
e2e/ci_test.go +1 −1
@@ -144,7 +144,7 @@ func TestCI(t *testing.T) {
144 t.Fatalf("ok log:\n%s", out) 144 t.Fatalf("ok log:\n%s", out)
145 } 145 }
146 out, _, _ = inst.ssh(t, aliceKey, "", "build", "log", "alice/app", brokenN) 146 out, _, _ = inst.ssh(t, aliceKey, "", "build", "log", "alice/app", brokenN)
147 if !strings.Contains(out, "step failed") { 147 if !strings.Contains(out, "step 1/1 failed: exit 1") {
148 t.Fatalf("broken log:\n%s", out) 148 t.Fatalf("broken log:\n%s", out)
149 } 149 }
150 // Statuses resolved, with target URLs pointing at the build pages. 150 // Statuses resolved, with target URLs pointing at the build pages.