Diffinery

codician/diffinerypublic

Open-source, agent-first GitHub and GitHub Actions alternative that runs on your own Cloudflare account: git hosting, pull requests, code review and drop-in GitHub Actions YAML on Workers, Durable Objects, R2 and Containers.

Jobs turned away during a runner image rollout start again every 20 s (#242)

* Jobs turned away during a runner image rollout start again every 20 s, not after a growing back-off
test-bot authored 1 parent c996868commit a7fb4e794ac6bb7c5be73794f31920d062c1da22Browse files
6 files changed+88−28
Files (6)
modifiedapps/diffinery/docs/actions/runners.md+1−1View file
@@ -440,7 +440,7 @@
440440 | `403 admin access required` | The runner's token or account lacks admin on the repository, or the token isn't `admin`-scoped. |
441441 | `no runner agent given` or `runner agent not found at ...` | Pass `--agent /path/to/agent.mjs` or set `DIFFINERY_RUNNER_AGENT`. Build it with `pnpm --filter @diffinery/runner build`. |
442442 | `E: Unable to locate package ...` | Run `apt-get update` first; the image ships without package lists. |
443-| A hosted job starts a minute or more late, and its log begins with `No hosted runner could start the job yet: ...` | No machine was free (`there is no container instance that can be provided`), the container stopped before the runner started, or a deploy was rolling out and the runner came up on the previous image. Diffinery puts the job back in line and tries again (after 30 s, then 1, 2, 4 and 5 minutes, up to 8 times; a first container stop before the runner started is retried after 5 s and not counted); `placementTries` in the jobs API counts the waits. Nothing to fix for an occasional wait. If a large matrix often waits, cap it with `strategy.max-parallel`. |
443+| A hosted job starts a minute or more late, and its log begins with `No hosted runner could start the job yet: ...` | No machine was free (`there is no container instance that can be provided`), the container stopped before the runner started, or a deploy was rolling out and the runner came up on the previous image. Diffinery puts the job back in line and tries again (after 30 s, then 1, 2, 4 and 5 minutes, up to 8 times; a first container stop before the runner started is retried after 5 s and not counted; a runner on the previous image during a deploy is retried every 20 s for up to 10 minutes, not counted, and then runs on whichever image it got); `placementTries` in the jobs API counts the waits. Nothing to fix for an occasional wait. If a large matrix often waits, cap it with `strategy.max-parallel`. |
444444 | `The platform replaced this job's runner with a new version while step ... ran` or `The platform stopped this job's container while step ... ran` | A deploy replaced the job's container mid-step (rare), or the platform stopped or moved it. Re-run the job. A job that can only read starts again by itself instead: give jobs that only build and test `permissions: contents: read`, no `environment:` and no secrets other than `GITHUB_TOKEN`. See Platform updates under [Limits and timeouts](#limits-and-timeouts). |
445445 | `The runner stopped unexpectedly (exit code N).` | The hosted container exited, often from running out of memory. Reduce parallelism in the job (for example `make -j2`) or move it to a self-hosted runner. |
446446 | `Connection refused` or `Connection timed out` on SSH (`git@...`), SMTP or a database port, on a hosted runner | The instance sets [`EGRESS=web`](/docs/self-hosting/configuration#egress), which lets hosted jobs use only HTTP and HTTPS. Use an `https://` remote or API, or run the job on a self-hosted runner. diffinery.com doesn't set it. |
modifiedapps/diffinery/docs/reference/limits.md+1−0View file
@@ -222,6 +222,7 @@
222222 | Hosted jobs at once on the instance | 80 | `HOSTED_JOBS_LIMIT`, kept under the container classes' `max_instances` with room for jobs starting side by side. Past it, every account's next hosted job waits as queued, as for its own quota, until one finishes. Self-hosted jobs don't count. |
223223 | Hosted jobs at once per account | Half the instance's, 40 | Whatever the account's quota says, so no account can keep the others' jobs from starting. A repository can use all of its account's share. Further jobs stay queued and start, oldest first, as running ones finish. |
224224 | No free container | Wait, then retry, 8 times | When the platform has no container free for a job (many jobs starting at once, or just after a deploy), the start fails on the platform's side in a way that passes ("Container sidecar is shutting down", a dropped connection), or the job's container stops before its runner fetched the job, the job goes back to queued and starts again after 30 seconds, then 1, 2, 4 and 5 minutes. The first time a job's container stops before its runner fetched the job (the platform stops a share of the containers a burst starts), it starts again after 5 seconds instead, and that try isn't counted. After 8 tries, about half an hour, it fails with `No hosted runner could be started`. Only jobs whose runner never started are retried, so no step runs twice. |
225+| Runner on the previous image during a deploy | Retried every 20 s, up to 30 times | While a deploy rolls out a new runner image, a runner that comes up on the previous image is turned away before it runs anything and the job starts again 20 s later. These waits don't count toward the 8 above. After 30 (about 10 minutes, longer than a rollout takes) the job runs on whichever image it gets. |
225226 | Unfinished runs per repository | 500 | Past it, a `workflow_dispatch` or `repository_dispatch` is refused with `429 this repository has 500 unfinished workflow runs, the most allowed; wait for some to finish`, and other events start no run. |
226227 | Self-hosted runners per repository | 100, each with at most 20 labels | Registering one more gets `429 this repository has 100 self-hosted runners, the most allowed; remove one first`. A registration token works for an hour. |
227228 | Purging unreachable objects | Repositories of up to 300,000 objects | A larger repository gets `422`; ask a site administrator. See [Removing a secret that was pushed](/docs/security/push-protection#removing-a-secret-that-was-pushed). |
modifiedapps/diffinery/src/repo/RepoDO.ts+4−3View file
@@ -324,7 +324,7 @@
324324 * fires at the earliest running job's deadline (Actions.enforceJobDeadlines).
325325 */
326326 armAlarm(at: number | null): void {
327- const next = this.earliest(at, this.actions.hasAccountHeldJobs() ? Date.now() + HELD_RETRY_MS : null, this.actions.nextJobDeadline(), this.actions.nextStuckRunCheck());
327+ const next = this.earliest(at, this.actions.hasAccountHeldJobs() ? Date.now() + HELD_RETRY_MS : null, this.actions.nextJobDeadline(), this.actions.nextStuckRunCheck(), this.actions.nextImageRetry());
328328 this.ctx.waitUntil(next === null ? this.ctx.storage.deleteAlarm() : this.ctx.storage.setAlarm(next));
329329 }
330330
@@ -348,10 +348,11 @@
348348 if (purging) return this.purge(purging);
349349 await this.queue.process();
350350 if (this.actions.hasAccountHeldJobs()) await this.actions.releaseAccountHeld();
351+ await this.actions.relaunchImageHeld();
351352 await this.actions.enforceJobDeadlines();
352353 await this.actions.repairStuckRuns();
353- // Wake up again for held jobs, running jobs' deadlines and stuck runs, keeping the queue's own alarm if it set an earlier one.
354- const want = this.earliest(this.actions.hasAccountHeldJobs() ? Date.now() + HELD_RETRY_MS : null, this.actions.nextJobDeadline(), this.actions.nextStuckRunCheck());
354+ // Wake up again for held jobs, rollout waits, running jobs' deadlines and stuck runs, keeping the queue's own alarm if it set an earlier one.
355+ const want = this.earliest(this.actions.hasAccountHeldJobs() ? Date.now() + HELD_RETRY_MS : null, this.actions.nextJobDeadline(), this.actions.nextStuckRunCheck(), this.actions.nextImageRetry());
355356 if (want !== null) {
356357 const current = await this.ctx.storage.getAlarm();
357358 if (current === null || current <= Date.now() || current > want) await this.ctx.storage.setAlarm(want);
modifiedapps/diffinery/src/repo/actions.ts+50−12View file
@@ -112,10 +112,14 @@
112112 /**
113113 * While a deploy's container rollout updates instances, a new container can still start on the
114114 * previous runner image. A hosted runner that reports another image than the deployed one
115- * (RUNNER_IMAGE) is turned away before it runs anything, and the job is placed again, up to this
116- * many times; after that it runs on whatever image it got rather than wait on a stuck rollout.
115+ * (RUNNER_IMAGE) is turned away before it runs anything, and the job starts again after
116+ * STALE_IMAGE_RETRY_SECONDS, up to this many times (about 10 minutes, longer than a rollout takes);
117+ * after that it runs on whatever image it got rather than wait on a stuck rollout. These waits are
118+ * fixed and not counted toward MAX_PLACEMENT_TRIES: a rollout ends by itself within minutes, and
119+ * backing off past its end (30 s doubling) only made jobs start late.
117120 */
118-export const STALE_IMAGE_TRIES = 4;
121+export const STALE_IMAGE_TRIES = 30;
122+export const STALE_IMAGE_RETRY_SECONDS = 20;
119123 /**
120124 * A deploy's container rollout can stop a hosted runner while its job runs. A job stopped before
121125 * any of its steps but checkout ran is started again from the beginning on a new runner, this many
@@ -251,6 +255,9 @@
251255 gate_state: string | null;
252256 placement_tries: number;
253257 early_stops: number;
258+ /** Times a runner on the previous image was turned away (STALE_IMAGE_TRIES), and when the job starts again, in ms since the epoch. */
259+ stale_tries?: number;
260+ image_retry_at?: number | null;
254261 runner_info: string | null;
255262 /** Set on a job a partial re-run copied from an earlier attempt: the job that actually ran. */
256263 carried_from?: string | null;
@@ -1599,7 +1606,19 @@
15991606 private async backInLine(job: JobRow, why: string, tries: number, delay: number, count: string): Promise<void> {
16001607 const jobId = job.id;
16011608 this.sql.exec("UPDATE jobs SET status = 'queued', container = NULL, token_hash = NULL, placement_tries = ? WHERE id = ?", tries, jobId);
1602- // The log says why it waits, so a slow start can be told apart (no machine free, a rollout's stale image).
1609+ await this.waiting(job, why, delay, count);
1610+ try {
1611+ const instance = await this.env.RUN_WORKFLOW.get(job.run_id);
1612+ await instance.sendEvent({ type: `job-${jobId}`, payload: { retryInSeconds: delay } });
1613+ } catch (e) {
1614+ console.error("could not ask the run's workflow to start the job again", e);
1615+ await this.completeJob(jobId, { conclusion: "failure", outputs: {}, failure: { message: `Could not start a runner: ${why}` } });
1616+ }
1617+ }
1618+
1619+ /** The log line of a job back in line, so a slow start can be told apart (no machine free, a rollout's stale image); it stops using minutes meanwhile. */
1620+ private async waiting(job: JobRow, why: string, delay: number, count: string): Promise<void> {
1621+ const jobId = job.id;
16031622 const seq = (this.sql.exec<{ n: number | null }>("SELECT max(seq) AS n FROM logs WHERE job_id = ?", jobId).one().n ?? -1) + 1;
16041623 const line = { t: new Date().toISOString(), step: -1, text: `##[warning]No hosted runner could start the job yet: ${why}. Diffinery tries again in ${delay} s (${count}).`, seq };
16051624 this.sql.exec("INSERT INTO logs (job_id, seq, t, step, text) VALUES (?, ?, ?, ?, ?)", jobId, seq, line.t, line.step, line.text);
@@ -1608,12 +1627,31 @@
16081627 // Not running while it waits: it holds none of the account's hosted jobs and uses no minutes.
16091628 await endCompute(this.env, jobId).catch((e: unknown) => console.error("compute usage failed", e));
16101629 this.repo.broadcast(`run:${job.run_id}`, { action: "job", jobId });
1611- try {
1612- const instance = await this.env.RUN_WORKFLOW.get(job.run_id);
1613- await instance.sendEvent({ type: `job-${jobId}`, payload: { retryInSeconds: delay } });
1614- } catch (e) {
1615- console.error("could not ask the run's workflow to start the job again", e);
1616- await this.completeJob(jobId, { conclusion: "failure", outputs: {}, failure: { message: `Could not start a runner: ${why}` } });
1630+ }
1631+
1632+ /**
1633+ * A runner on the previous image was turned away during a rollout (refuseStaleRunner): the job goes
1634+ * back in line and this object starts it again after STALE_IMAGE_RETRY_SECONDS (relaunchImageHeld,
1635+ * from the alarm), without the run's workflow, which keeps waiting for the job to finish.
1636+ */
1637+ private async waitForImage(job: JobRow, why: string): Promise<void> {
1638+ const tries = (job.stale_tries ?? 0) + 1;
1639+ const at = Date.now() + STALE_IMAGE_RETRY_SECONDS * 1000;
1640+ this.sql.exec("UPDATE jobs SET status = 'queued', container = NULL, token_hash = NULL, stale_tries = ?, image_retry_at = ? WHERE id = ?", tries, at, job.id);
1641+ await this.waiting(job, why, STALE_IMAGE_RETRY_SECONDS, `rollout wait ${tries} of ${STALE_IMAGE_TRIES}, not counted`);
1642+ this.repo.alarmBy(at);
1643+ }
1644+
1645+ /** When the next job waiting out a rollout starts again (waitForImage), in ms since the epoch. */
1646+ nextImageRetry(): number | null {
1647+ return this.sql.exec<{ at: number | null }>("SELECT min(image_retry_at) AS at FROM jobs WHERE status = 'queued' AND image_retry_at IS NOT NULL").one().at;
1648+ }
1649+
1650+ /** Starts again the jobs whose rollout wait is over (waitForImage). */
1651+ async relaunchImageHeld(at = Date.now()): Promise<void> {
1652+ for (const { id } of this.sql.exec<{ id: string }>("SELECT id FROM jobs WHERE status = 'queued' AND image_retry_at IS NOT NULL AND image_retry_at <= ? ORDER BY rowid", at).toArray()) {
1653+ this.sql.exec("UPDATE jobs SET image_retry_at = NULL WHERE id = ?", id);
1654+ await this.launch(id);
16171655 }
16181656 }
16191657
@@ -2225,8 +2263,8 @@
22252263 */
22262264 private async refuseStaleRunner(job: JobRow, runner: JobRunnerInfo | null, deployed: string | null = null): Promise<void> {
22272265 const want = deployed ?? this.env.RUNNER_IMAGE;
2228- if (!want || job.labels || runner?.image === want || job.placement_tries >= STALE_IMAGE_TRIES) return;
2229- await this.placementFailed(job.id, `a runner started on ${runner?.image ?? "an older image"} while the deploy of ${want} was rolling out`);
2266+ if (!want || job.labels || runner?.image === want || (job.stale_tries ?? 0) >= STALE_IMAGE_TRIES) return;
2267+ await this.waitForImage(job, `a runner started on ${runner?.image ?? "an older image"} while the deploy of ${want} was rolling out`);
22302268 throw new HttpError(409, `this runner's image (${runner?.image ?? "unknown"}) was replaced by ${want}; the job starts again on a new runner`);
22312269 }
22322270
modifiedapps/diffinery/src/repo/schema.ts+3−0View file
@@ -200,6 +200,9 @@
200200 ["jobs", "fleet_held", "INTEGER NOT NULL DEFAULT 0"],
201201 // Times the platform stopped the job's container before its runner started (repo/actions.ts QUICK_RETRY_SECONDS).
202202 ["jobs", "early_stops", "INTEGER NOT NULL DEFAULT 0"],
203+ // Runners on the previous image turned away during a rollout, and when the job starts again (repo/actions.ts STALE_IMAGE_TRIES).
204+ ["jobs", "stale_tries", "INTEGER NOT NULL DEFAULT 0"],
205+ ["jobs", "image_retry_at", "INTEGER"],
203206 // The registered self-hosted runner that claimed the job (null for hosted jobs and personal-token claims).
204207 ["jobs", "runner_id", "INTEGER"],
205208 // Times a hosted job's container couldn't get a machine and the job went back in line (repo/actions.ts MAX_PLACEMENT_TRIES).
modifiedapps/diffinery/test/unit/actions-runtime.test.ts+29−12View file
@@ -1,7 +1,7 @@
11 import { describe, expect, it } from "vitest";
22 import { BodyTooLarge, STEP_OPS, batchParts, blockKey, chunkKey, compose, finalKey, listStaged, parseBlockList, parseRange, planCompose, putStream, runComposeStep, stagingPrefix, type BlobBucket, type ComposeLimits, type ComposeStep } from "../../src/lib/blob-store.js";
33 import { DatabaseSync } from "node:sqlite";
4-import { Actions, JOB_DEADLINE_GRACE_MS, MAX_ACTIVE_RUNS, MAX_PLACEMENT_TRIES, MAX_RUNNER_RESTARTS, parseRunnerInfo, placementDelay, QUICK_RETRY_SECONDS, STALE_IMAGE_TRIES } from "../../src/repo/actions.js";
4+import { Actions, JOB_DEADLINE_GRACE_MS, MAX_ACTIVE_RUNS, MAX_PLACEMENT_TRIES, MAX_RUNNER_RESTARTS, parseRunnerInfo, placementDelay, QUICK_RETRY_SECONDS, STALE_IMAGE_RETRY_SECONDS, STALE_IMAGE_TRIES } from "../../src/repo/actions.js";
55 import { fleetLimits } from "../../src/lib/quotas.js";
66 import { testD1 } from "./stubs/d1.js";
77 import { DEFAULT_ARTIFACT_QUOTA, Runtime, artifactFileName, artifactObjectKeys } from "../../src/repo/runtime.js";
@@ -888,7 +888,7 @@
888888 expect(events.filter((e) => e.type === "job-m1")).toHaveLength(1);
889889 });
890890
891- it("a hosted runner on an image other than the deployed one is turned away and the job placed again, up to STALE_IMAGE_TRIES", async () => {
891+ it("a hosted runner on an image other than the deployed one is turned away and the job starts again every STALE_IMAGE_RETRY_SECONDS, up to STALE_IMAGE_TRIES", async () => {
892892 const sql = sqlStorage();
893893 sql.exec(REPO_SCHEMA);
894894 migrateRepoSchema(sql as unknown as SqlStorage);
@@ -900,8 +900,9 @@
900900 broadcast: () => {},
901901 deploys: { jobCompleted: () => {} },
902902 runtime: { sweepJob: async () => {} },
903- alarmBy: () => {},
903+ alarmBy: (at: number) => void alarms.push(at),
904904 } as unknown as RepoDO;
905+ const alarms: number[] = [];
905906 const DB = testD1();
906907 DB.sqlite.prepare("INSERT INTO accounts (id, login, kind, status, created_at) VALUES ('acme', 'acme', 'org', 'active', ?)").run(new Date().toISOString());
907908 const env = {
@@ -918,22 +919,38 @@
918919 sql.exec("UPDATE jobs SET labels = '[\"self-hosted\"]' WHERE id = 's1'");
919920 const a = actions as unknown as { launch(id: string): Promise<void>; refuseStaleRunner(job: unknown, runner: unknown, deployed?: string): Promise<void>; jobRow(id: string): unknown };
920921 const refuse = (id: string, image?: string, deployed?: string) => a.refuseStaleRunner(a.jobRow(id), image ? { image } : null, deployed);
921- const job = (id = "j1") => sql.exec("SELECT status, placement_tries FROM jobs WHERE id = ?", id).toArray()[0];
922+ const job = (id = "j1") => sql.exec("SELECT status, placement_tries, stale_tries FROM jobs WHERE id = ?", id).toArray()[0];
923+ const logs = () => sql.exec<{ text: string }>("SELECT text FROM logs WHERE job_id = 'j1' ORDER BY seq").toArray().map((l) => l.text);
922924
923925 await a.launch("j1");
924926 // The deployed image runs the job.
925927 await expect(refuse("j1", "diffinery-runner:new")).resolves.toBeUndefined();
926928 expect(job()).toMatchObject({ status: "waiting", placement_tries: 0 });
927- // The previous image (or one that doesn't say) is turned away, and the job waits to start again.
928- for (const [i, image] of ["diffinery-runner:old", undefined, "diffinery-runner:old", "diffinery-runner:old"].entries()) {
929- await expect(refuse("j1", image)).rejects.toMatchObject({ status: 409 });
930- expect(job()).toMatchObject({ status: "queued", placement_tries: i + 1 });
931- expect(events.at(-1)).toEqual({ type: "job-j1", payload: { retryInSeconds: placementDelay(i + 1) } });
932- await actions.relaunchJob("j1");
929+ // The previous image (or one that doesn't say) is turned away. The job starts again after a short fixed
930+ // wait, from this object's alarm rather than the run's workflow, and the waits don't count as placement tries.
931+ for (let i = 0; i < STALE_IMAGE_TRIES; i++) {
932+ const before = Date.now();
933+ await expect(refuse("j1", i === 1 ? undefined : "diffinery-runner:old")).rejects.toMatchObject({ status: 409 });
934+ expect(job()).toMatchObject({ status: "queued", placement_tries: 0, stale_tries: i + 1 });
935+ const at = actions.nextImageRetry()!;
936+ expect(at).toBeGreaterThanOrEqual(before + STALE_IMAGE_RETRY_SECONDS * 1000);
937+ expect(alarms.at(-1)).toBe(at);
938+ // Not before its time.
939+ await actions.relaunchImageHeld(at - 1);
940+ expect(job()).toMatchObject({ status: "queued" });
941+ await actions.relaunchImageHeld(at);
942+ expect(job()).toMatchObject({ status: "waiting" });
943+ expect(actions.nextImageRetry()).toBeNull();
933944 }
945+ expect(events).toEqual([]);
946+ expect(logs()[0]).toBe(`##[warning]No hosted runner could start the job yet: a runner started on diffinery-runner:old while the deploy of diffinery-runner:new was rolling out. Diffinery tries again in ${STALE_IMAGE_RETRY_SECONDS} s (rollout wait 1 of ${STALE_IMAGE_TRIES}, not counted).`);
934947 // A rollout that doesn't finish doesn't hold the job up past STALE_IMAGE_TRIES.
935- expect(job()).toMatchObject({ status: "waiting", placement_tries: STALE_IMAGE_TRIES });
936948 await expect(refuse("j1", "diffinery-runner:old")).resolves.toBeUndefined();
949+ // A job cancelled while it waits isn't started again.
950+ sql.exec("UPDATE jobs SET status = 'queued', image_retry_at = 1 WHERE id = 'j1'");
951+ sql.exec("UPDATE jobs SET status = 'completed' WHERE id = 'j1'");
952+ await actions.relaunchImageHeld();
953+ expect(job()).toMatchObject({ status: "completed" });
937954 // Self-hosted runners run any image.
938955 await expect(refuse("s1", "my-image")).resolves.toBeUndefined();
939956
@@ -943,7 +960,7 @@
943960 await expect(refuse("j2", "diffinery-runner:next", "diffinery-runner:next")).resolves.toBeUndefined();
944961 expect(job("j2")).toMatchObject({ status: "waiting", placement_tries: 0 });
945962 await expect(refuse("j2", "diffinery-runner:new", "diffinery-runner:next")).rejects.toMatchObject({ status: 409 });
946- expect(job("j2")).toMatchObject({ status: "queued", placement_tries: 1 });
963+ expect(job("j2")).toMatchObject({ status: "queued", stale_tries: 1 });
947964 });
948965
949966 it("a running job whose runner froze is ended at its timeout plus JOB_DEADLINE_GRACE_MS, and a healthy one is left alone", async () => {