Say in the job's log why it waits for a hosted runner (#212)
* Say in the job's log why it waits for a hosted runner
- CI / Typecheck and bundleFailed
- CI / Unit tests (1/2)Failed
- CI / Unit tests (2/2)Failed
3 files changed+11−1
modifiedapps/diffinery/docs/actions/runners.md+1−1View file
| @@ -169,7 +169,7 @@ | ||
| 169 | 169 | |
| 170 | 170 | If the container stops unexpectedly (for example it runs out of memory), the job fails with `The runner stopped unexpectedly (exit code N).` A container that stops before its runner fetched the job is replaced instead, since no step ran. |
| 171 | 171 | |
| 172 | -The log's first lines name where the job ran, for example `Runner: image diffinery-runner:96dbbe31790f, in fra06, EEUR, container 6f1c…`. On hosted runners a `Host:` line names the host's processor (Cloudflare's hosts mix AMD EPYC generations, so the same job can run up to about twice as fast on one host as on another), and the line before the job's conclusion says how much of the vCPUs' time the host gave to other work (steal). The jobs API returns the same as `runner` (`image`, `location`, `instance`, and `cpu` on hosted runners), next to `runner_name`. `GET /meta` names the image the last deploy set as `runner_image`. While a deploy's rollout is updating instances, a new container can still start on the previous image. Diffinery turns that runner away before it runs anything and starts the job again on another container (after 30 s, then 1, 2 and 4 minutes). After four tries, the job runs on whatever image it got rather than wait for a rollout that has stalled. The jobs API's `placementTries` counts the times a job went back in line before a runner took it, and `restarts` counts the times it started again because the platform replaced its runner. | |
| 172 | +The log's first lines name where the job ran, for example `Runner: image diffinery-runner:96dbbe31790f, in fra06, EEUR, container 6f1c…`. On hosted runners a `Host:` line names the host's processor (Cloudflare's hosts mix AMD EPYC generations, so the same job can run up to about twice as fast on one host as on another), and the line before the job's conclusion says how much of the vCPUs' time the host gave to other work (steal). The jobs API returns the same as `runner` (`image`, `location`, `instance`, and `cpu` on hosted runners), next to `runner_name`. `GET /meta` names the image the last deploy set as `runner_image`. While a deploy's rollout is updating instances, a new container can still start on the previous image. Diffinery turns that runner away before it runs anything and starts the job again on another container (after 30 s, then 1, 2 and 4 minutes). After four tries, the job runs on whatever image it got rather than wait for a rollout that has stalled. The jobs API's `placementTries` counts the times a job went back in line before a runner took it (each time, the job's log gets a line saying why: no machine was free, the container stopped before the runner started, or a runner on the previous image was turned away), and `restarts` counts the times it started again because the platform replaced its runner. | |
| 173 | 173 | |
| 174 | 174 | ### Windows and macOS |
| 175 | 175 |
modifiedapps/diffinery/src/repo/actions.ts+6−0View file
| @@ -1553,6 +1553,12 @@ | ||
| 1553 | 1553 | return; |
| 1554 | 1554 | } |
| 1555 | 1555 | this.sql.exec("UPDATE jobs SET status = 'queued', container = NULL, token_hash = NULL, placement_tries = ? WHERE id = ?", tries, jobId); |
| 1556 | + // The log says why it waits, so a slow start can be told apart (no machine free, a rollout's stale image). | |
| 1557 | + const seq = (this.sql.exec<{ n: number | null }>("SELECT max(seq) AS n FROM logs WHERE job_id = ?", jobId).one().n ?? -1) + 1; | |
| 1558 | + const line = { t: new Date().toISOString(), step: -1, text: `##[warning]No hosted runner could start the job yet: ${why}. Diffinery tries again in ${placementDelay(tries)} s (wait ${tries} of ${MAX_PLACEMENT_TRIES}).`, seq }; | |
| 1559 | + this.sql.exec("INSERT INTO logs (job_id, seq, t, step, text) VALUES (?, ?, ?, ?, ?)", jobId, seq, line.t, line.step, line.text); | |
| 1560 | + this.sql.exec("UPDATE jobs SET log_chars = coalesce(log_chars, 0) + ? WHERE id = ?", line.text.length, jobId); | |
| 1561 | + this.repo.broadcast(`job:${jobId}`, { action: "logs", lines: [line] }); | |
| 1556 | 1562 | // Not running while it waits: it holds none of the account's hosted jobs and uses no minutes. |
| 1557 | 1563 | await endCompute(this.env, jobId).catch((e: unknown) => console.error("compute usage failed", e)); |
| 1558 | 1564 | this.repo.broadcast(`run:${job.run_id}`, { action: "job", jobId }); |
modifiedapps/diffinery/test/unit/actions-runtime.test.ts+4−0View file
| @@ -746,6 +746,9 @@ | ||
| 746 | 746 | await launch("j1"); |
| 747 | 747 | expect(job("j1")).toMatchObject({ status: "queued", conclusion: null, container: null, placement_tries: 1 }); |
| 748 | 748 | expect(events).toEqual([{ type: "job-j1", payload: { retryInSeconds: placementDelay(1) } }]); |
| 749 | + // Its log says why it waits. | |
| 750 | + const log = (id: string) => sql.exec<{ text: string }>("SELECT text FROM logs WHERE job_id = ? ORDER BY seq", id).toArray().map((l) => l.text); | |
| 751 | + expect(log("j1")).toEqual([`##[warning]No hosted runner could start the job yet: ${startError}. Diffinery tries again in ${placementDelay(1)} s (wait 1 of ${MAX_PLACEMENT_TRIES}).`]); | |
| 749 | 752 | // While it waits it isn't running, so it holds none of the account's hosted jobs (lib/quotas.ts). |
| 750 | 753 | expect(running()).toEqual([]); |
| 751 | 754 | |
| @@ -757,6 +760,7 @@ | ||
| 757 | 760 | await actions.containerStopped("j1", null); |
| 758 | 761 | expect(job("j1")).toMatchObject({ status: "queued", placement_tries: 2 }); |
| 759 | 762 | expect(events.at(-1)).toEqual({ type: "job-j1", payload: { retryInSeconds: placementDelay(2) } }); |
| 763 | + expect(log("j1").at(-1)).toMatch(/: the container stopped before the runner started\. Diffinery tries again in 60 s \(wait 2 of \d+\)\.$/); | |
| 760 | 764 | expect(running()).toEqual([]); |
| 761 | 765 | // The same when the runner exits with a code before it fetched the job; and a container that |
| 762 | 766 | // exits after the job went back in line (its token revoked) leaves the job in line. |