Sign in

Search issue titles and bodies, change requests and comments. Private repositories you cannot read are not included.

vole
Clone

Read only, no credentials:

https://rodent.software/vole.git

Write over SSH with a registered key:

git clone ssh://git@rodent.software:2222/vole.git

A free and open-source forge that lives in your Git repo.

Record a job that never started as could-not-run, not as a failure

70c9ad4eb3f3d0cd39159e647cde77afba75b944 · Keenan Nemetz · 4h ago · parent 9704d735

Record a job that never started as could-not-run, not as a failure

A run that never executed a step was recorded exit=1, steps=nil, and the run page
said the same thing it says when a test fails. With checks required on a protected
branch, a runner that could not build an image red-flagged a commit whose tests
pass, and the only way back was a rerun by hand.

Two facts were collapsed into one: the job ran and something failed, which is the
repository's problem, and the job never ran, which is the machine's. The runner
knows the difference exactly once, and it does not need to guess whose fault it
was: if no step ran, nothing about the commit was tested.

- A record can now say where it stopped: Failure=setup means the attempt ended
  before the job's first step, with the runner's own one-line reason in
  FailureMessage, masked the way the log is. The reason is what the page shows
  instead of making a reader open the log to learn the machine broke.
- A run whose newest attempt has that origin is StatusError, which the pages call
  "could not run". It is not StatusFailed: it is not evidence against the commit.
- The gate reads it as a wait, not a refusal. Landing stays blocked because nothing
  is verified, but the commit is not blamed, and the gap names the reason and the
  rerun command.
- The run list counts and filters it, the run page explains it, and the change list
  says "CI could not run" rather than "CI failed".

A step that exits non-zero is still a failure and still reds the check, because
that one is the code's. `vole runner` still reports a setup failure with exit 1;
the origin is what carries the meaning, so an old runner and an old instance keep
talking.

Not done here, on purpose: a run whose attempts all vanished before reporting (the
lease-loss exhaustion in RequeueExpired) still ends as failed. That run has no
record to say what ran, and a job that repeatedly kills its runner is not
distinguishable from a machine problem from the queue's side; issue #243 is where
that gets a signal. Nor is a setup failure requeued automatically: MaxAttempts is
about flaky tests, not broken runners, and #247 already stops a runner whose
runtime cannot start a container from serving at all. A rerun is a button.

The finish path now takes an attemptOutcome instead of six positional arguments,
which is also what lets a failure after the last step keep the steps that ran
instead of dropping them.

Closes 01M6Z05K5PM58EE3H6VE2P2EYD

ci/agent/agent.go +65−19

@@ -882,18 +882,33 @@ func (s *runnerSession) run(remote, cache string, job *runnerJob, lease time.Dur
882 882 if job.Image == "" {
883 883 // A run queued before images were required has no environment to start.
884 884 // Fail it with a record rather than guessing at the host.
885 fmt.Fprintf(log, "\nthis run has no image; re-queue it from a workflow that declares image or image-file\n")
886 s.finish(remote, co, job, log, stream, 1, nil, nil, nil, box)
885 const noImage = "this run has no image; re-queue it from a workflow that declares image or image-file"
886 fmt.Fprintf(log, "\n%s\n", noImage)
887 s.finish(remote, co, job, log, stream, attemptOutcome{
888 Exit: 1, Failure: runs.FailureSetup, Message: noImage,
889 }, box)
887 890 return
888 891 }
889 892 jobBox := &jobSandbox{}
890 893 defer jobBox.Stop()
894 // The steps that ran, so a failure after them keeps what did run and a failure
895 // before them can say that nothing did.
896 var steps []runs.StepResult
891 897 fail := func(format string, args ...any) {
892 898 jobBox.StopWithLogs(log)
893 899 msg := mask.String(fmt.Sprintf(format, args...))
894 900 fmt.Fprintf(os.Stderr, "vole runner: %s\n", msg)
895 901 fmt.Fprintf(log, "\n%s\n", msg)
896 s.finish(remote, co, job, log, stream, 1, nil, nil, nil, box)
902 out := attemptOutcome{Exit: 1, Steps: steps}
903 if len(steps) == 0 {
904 // Nothing was tested. The attempt stopped in the runner's own setup (the
905 // image build, the container, the network) or in a definition the workflow
906 // got wrong; either way the commit is not what failed, so the record says
907 // where it stopped and why.
908 out.Failure = runs.FailureSetup
909 out.Message = failureLine(msg)
910 }
911 s.finish(remote, co, job, log, stream, out, box)
897 912 }
898 913 // A job that asked to act as an account it cannot act as is broken as written, not
899 914 // degraded: fail it before the image is pulled and say why.
@@ -932,7 +947,7 @@ func (s *runnerSession) run(remote, cache string, job *runnerJob, lease time.Dur
932 947 if errors.Is(err, errCanceled) {
933 948 // The build was stopped on a heartbeat, and the log already says why. The
934 949 // attempt still has a story: report it with the work that did happen.
935 s.finish(remote, co, job, log, stream, 1, nil, nil, nil, box)
950 s.finish(remote, co, job, log, stream, attemptOutcome{Exit: 1}, box)
936 951 return
937 952 }
938 953 fail("%s", err)
@@ -1075,7 +1090,7 @@ func (s *runnerSession) run(remote, cache string, job *runnerJob, lease time.Dur
1075 1090 }
1076 1091 jobBox.job = sandbox
1077 1092
1078 steps := make([]runs.StepResult, 0, len(job.Steps))
1093 steps = make([]runs.StepResult, 0, len(job.Steps))
1079 1094 // The job's budget starts with its first step. An image build has its own cap, so a
1080 1095 // slow pull must not eat the time the steps were given.
1081 1096 var deadline time.Time
@@ -1125,7 +1140,7 @@ func (s *runnerSession) run(remote, cache string, job *runnerJob, lease time.Dur
1125 1140 // the timings are what a reader asks for first after "what had it done".
1126 1141 steps = append(steps, result)
1127 1142 jobBox.StopWithLogs(log)
1128 s.finish(remote, co, job, log, stream, code, steps, nil, nil, box)
1143 s.finish(remote, co, job, log, stream, attemptOutcome{Exit: code, Steps: steps}, box)
1129 1144 return
1130 1145 }
1131 1146 if code != 0 {
@@ -1134,7 +1149,7 @@ func (s *runnerSession) run(remote, cache string, job *runnerJob, lease time.Dur
1134 1149 result.Finished = time.Now().UTC()
1135 1150 steps = append(steps, result)
1136 1151 jobBox.StopWithLogs(log)
1137 s.finish(remote, co, job, log, stream, code, steps, nil, nil, box)
1152 s.finish(remote, co, job, log, stream, attemptOutcome{Exit: code, Steps: steps}, box)
1138 1153 return
1139 1154 }
1140 1155 steps = append(steps, result)
@@ -1160,7 +1175,9 @@ func (s *runnerSession) run(remote, cache string, job *runnerJob, lease time.Dur
1160 1175 fail("%s", err)
1161 1176 return
1162 1177 }
1163 s.finish(remote, co, job, log, stream, 0, steps, arts, releaseArts, box)
1178 s.finish(remote, co, job, log, stream, attemptOutcome{
1179 Steps: steps, Artifacts: arts, ReleaseArtifacts: releaseArts,
1180 }, box)
1164 1181 }
1165 1182
1166 1183 // cacheFor returns the mount for one job's cache and the lock that keeps eviction
@@ -1224,6 +1241,34 @@ func trimJobCache(ctx context.Context, root string, max int64) {
1224 1241 }
1225 1242 }
1226 1243
1244 // attemptOutcome is what the runner has to say about a finished attempt: the exit
1245 // code, the steps that ran, what it published, and — when the attempt stopped before
1246 // its first step — where it stopped and the runner's own reason. A setup failure is
1247 // not a verdict about the commit, so it is carried apart from the exit code rather
1248 // than folded into it.
1249 type attemptOutcome struct {
1250 Exit int
1251 Steps []runs.StepResult
1252 Artifacts []runnerArtifact
1253 ReleaseArtifacts []runnerArtifact
1254 // Failure is empty when a step decided the result, or runs.FailureSetup when no
1255 // step ever started. Message is the one-line reason that goes with it, already
1256 // masked.
1257 Failure string
1258 Message string
1259 }
1260
1261 // failureLine is the one line a record keeps for a failure that never reached a
1262 // step. The message is already masked, so this only makes it display text: one line,
1263 // bounded to what a record accepts.
1264 func failureLine(msg string) string {
1265 line := strings.Join(strings.Fields(msg), " ")
1266 if len(line) > runs.MaxFailureMessage {
1267 line = strings.ToValidUTF8(line[:runs.MaxFailureMessage], "")
1268 }
1269 return line
1270 }
1271
1227 1272 // finish uploads this attempt's log, sends its record to the server with the
1228 1273 // finish message, and then attaches any release pointers the build published.
1229 1274 //
@@ -1236,7 +1281,7 @@ func trimJobCache(ctx context.Context, root string, max int64) {
1236 1281 // A log that cannot be stored does not lose the result: the record then names no log
1237 1282 // and the failure is reported on stderr rather than swallowed. A record the server
1238 1283 // does not accept is not reported at all.
1239 func (s *runnerSession) finish(remote string, co checkout, job *runnerJob, log *spool, stream *logStream, exit int, steps []runs.StepResult, arts, releaseArts []runnerArtifact, box runnerBox) {
1284 func (s *runnerSession) finish(remote string, co checkout, job *runnerJob, log *spool, stream *logStream, out attemptOutcome, box runnerBox) {
1240 1285 if err := log.seal(); err != nil {
1241 1286 fmt.Fprintf(os.Stderr, "vole runner: could not seal the log for %s: %v\n", job.ID, err)
1242 1287 }
@@ -1245,19 +1290,20 @@ func (s *runnerSession) finish(remote string, co checkout, job *runnerJob, log *
1245 1290 fmt.Fprintf(os.Stderr, "vole runner: log stream for %s failed: %v\n", job.ID, streamErr)
1246 1291 // The step ranges describe bytes the server does not have. Keep the timings,
1247 1292 // which are still true, and drop the claims about the log.
1248 for i := range steps {
1249 steps[i].LogOffset, steps[i].LogSize = 0, 0
1293 for i := range out.Steps {
1294 out.Steps[i].LogOffset, out.Steps[i].LogSize = 0, 0
1250 1295 }
1251 1296 }
1252 artifacts := make([]runs.Artifact, 0, len(arts))
1253 for _, a := range arts {
1297 artifacts := make([]runs.Artifact, 0, len(out.Artifacts))
1298 for _, a := range out.Artifacts {
1254 1299 artifacts = append(artifacts, runs.Artifact{Name: a.Name, OID: a.OID, Size: a.Size})
1255 1300 }
1256 1301 rec := runs.Record{
1257 1302 RunID: job.ID, Attempt: job.Attempt, Repo: job.Repo, Ref: job.Ref, SHA: job.SHA,
1258 1303 Workflow: job.Workflow, WorkflowSHA: job.WorkflowSHA, Job: job.Job,
1259 StepsSHA: job.StepsSHA, Exit: exit, Finished: time.Now().UTC(),
1260 Signer: s.name, Steps: steps, Artifacts: artifacts,
1304 StepsSHA: job.StepsSHA, Exit: out.Exit, Finished: time.Now().UTC(),
1305 Signer: s.name, Steps: out.Steps, Artifacts: artifacts,
1306 Failure: out.Failure, FailureMessage: out.Message,
1261 1307 // The machine this attempt ran on. The runner binary's own build target,
1262 1308 // which is the honest thing it can say: a live probe would add a subprocess
1263 1309 // and a platform quirk for a fact the binary already knows.
@@ -1314,12 +1360,12 @@ func (s *runnerSession) finish(remote string, co checkout, job *runnerJob, log *
1314 1360 // The result is stored. A tagged build's release pointers are product metadata
1315 1361 // and still live on the branch; attach them only after the record, so a release
1316 1362 // cannot exist without the build that produced it.
1317 if len(releaseArts) > 0 {
1318 if err := publishReleases(remote, co, job, releaseArts, log); err != nil {
1363 if len(out.ReleaseArtifacts) > 0 {
1364 if err := publishReleases(remote, co, job, out.ReleaseArtifacts, log); err != nil {
1319 1365 fmt.Fprintf(os.Stderr, "vole runner: could not attach %d artifact(s) to %s: %v\n",
1320 len(releaseArts), job.Tag, err)
1366 len(out.ReleaseArtifacts), job.Tag, err)
1321 1367 fmt.Fprintf(log, "\nrelease: could not attach %d artifact(s) to %s: %v\n",
1322 len(releaseArts), job.Tag, err)
1368 len(out.ReleaseArtifacts), job.Tag, err)
1323 1369 }
1324 1370 }
1325 1371 }