Start a job again after 5 s the first time its fresh container is stopped (#223)
* Start a job again after 5 s the first time its fresh container is stopped
- CI / Typecheck and bundlesuccess
- CI / Unit tests (1/2)Failed
- CI / Unit tests (2/2)Failed
6 files changed+41−9
Files (6)
modifiedapps/diffinery/docs/actions/runners.md+1−1View file
| @@ -437,7 +437,7 @@ | ||
| 437 | 437 | | `403 admin access required` | The runner's token or account lacks admin on the repository, or the token isn't `admin`-scoped. | |
| 438 | 438 | | `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`. | |
| 439 | 439 | | `E: Unable to locate package ...` | Run `apt-get update` first; the image ships without package lists. | |
| 440 | -| 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); `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`. | | |
| 440 | +| 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`. | | |
| 441 | 441 | | `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). | |
| 442 | 442 | | `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. | |
| 443 | 443 | | `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−1View file
| @@ -216,7 +216,7 @@ | ||
| 216 | 216 | | Hosted job containers at once | 100 per size | `max_instances` of each runner container class. | |
| 217 | 217 | | 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. | |
| 218 | 218 | | 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. | |
| 219 | -| 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. 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. | | |
| 219 | +| 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. | | |
| 220 | 220 | | 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. | |
| 221 | 221 | | 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. | |
| 222 | 222 | | 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/actions.ts+26−4View file
| @@ -77,6 +77,14 @@ | ||
| 77 | 77 | /** Seconds before the next start of a job whose container got no machine: 30 s, doubling to 5 minutes. */ |
| 78 | 78 | export const placementDelay = (tries: number): number => Math.min(30 * 2 ** (tries - 1), 300); |
| 79 | 79 | /** |
| 80 | + * A container the platform stops after it started but before its runner fetched the job (it happens | |
| 81 | + * to a share of the containers a burst of jobs starts): nothing ran and little was billed, so the first | |
| 82 | + * time the job starts again after QUICK_RETRY_SECONDS, not counted toward MAX_PLACEMENT_TRIES. Another | |
| 83 | + * such stop waits like any other (placementDelay). | |
| 84 | + */ | |
| 85 | +export const QUICK_RETRIES = 1; | |
| 86 | +export const QUICK_RETRY_SECONDS = 5; | |
| 87 | +/** | |
| 80 | 88 | * While a deploy's container rollout updates instances, a new container can still start on the |
| 81 | 89 | * previous runner image. A hosted runner that reports another image than the deployed one |
| 82 | 90 | * (RUNNER_IMAGE) is turned away before it runs anything, and the job is placed again, up to this |
| @@ -217,6 +225,7 @@ | ||
| 217 | 225 | gate_since: string | null; |
| 218 | 226 | gate_state: string | null; |
| 219 | 227 | placement_tries: number; |
| 228 | + early_stops: number; | |
| 220 | 229 | runner_info: string | null; |
| 221 | 230 | /** Set on a job a partial re-run copied from an earlier attempt: the job that actually ran. */ |
| 222 | 231 | carried_from?: string | null; |
| @@ -1543,18 +1552,28 @@ | ||
| 1543 | 1552 | * in). Put the job back in line and have the run's workflow start it again after a pause, or fail it |
| 1544 | 1553 | * once it has waited MAX_PLACEMENT_TRIES times. |
| 1545 | 1554 | */ |
| 1546 | - private async placementFailed(jobId: string, why: string): Promise<void> { | |
| 1555 | + private async placementFailed(jobId: string, why: string, o: { quick?: boolean } = {}): Promise<void> { | |
| 1547 | 1556 | const job = this.jobRow(jobId); |
| 1548 | 1557 | if (job.status === "completed") return; |
| 1558 | + if (o.quick) { | |
| 1559 | + this.sql.exec("UPDATE jobs SET early_stops = early_stops + 1 WHERE id = ?", jobId); | |
| 1560 | + return this.backInLine(job, why, job.placement_tries, QUICK_RETRY_SECONDS, "not counted: the first stop like this is retried at once"); | |
| 1561 | + } | |
| 1549 | 1562 | const tries = job.placement_tries + 1; |
| 1550 | 1563 | if (tries > MAX_PLACEMENT_TRIES) { |
| 1551 | 1564 | await this.completeJob(jobId, { conclusion: "failure", outputs: {}, failure: { message: `No hosted runner could be started: Diffinery tried ${MAX_PLACEMENT_TRIES} times over about half an hour (${why}). Re-run the job to try again.` } }); |
| 1552 | 1565 | return; |
| 1553 | 1566 | } |
| 1567 | + await this.backInLine(job, why, tries, placementDelay(tries), `wait ${tries} of ${MAX_PLACEMENT_TRIES}`); | |
| 1568 | + } | |
| 1569 | + | |
| 1570 | + /** Puts a job whose runner never started back in line, says why in its log, and has the run's workflow start it again in `delay` seconds. */ | |
| 1571 | + private async backInLine(job: JobRow, why: string, tries: number, delay: number, count: string): Promise<void> { | |
| 1572 | + const jobId = job.id; | |
| 1554 | 1573 | this.sql.exec("UPDATE jobs SET status = 'queued', container = NULL, token_hash = NULL, placement_tries = ? WHERE id = ?", tries, jobId); |
| 1555 | 1574 | // The log says why it waits, so a slow start can be told apart (no machine free, a rollout's stale image). |
| 1556 | 1575 | const seq = (this.sql.exec<{ n: number | null }>("SELECT max(seq) AS n FROM logs WHERE job_id = ?", jobId).one().n ?? -1) + 1; |
| 1557 | - 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 }; | |
| 1576 | + 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 }; | |
| 1558 | 1577 | this.sql.exec("INSERT INTO logs (job_id, seq, t, step, text) VALUES (?, ?, ?, ?, ?)", jobId, seq, line.t, line.step, line.text); |
| 1559 | 1578 | this.sql.exec("UPDATE jobs SET log_chars = coalesce(log_chars, 0) + ? WHERE id = ?", line.text.length, jobId); |
| 1560 | 1579 | this.repo.broadcast(`job:${jobId}`, { action: "logs", lines: [line] }); |
| @@ -1563,7 +1582,7 @@ | ||
| 1563 | 1582 | this.repo.broadcast(`run:${job.run_id}`, { action: "job", jobId }); |
| 1564 | 1583 | try { |
| 1565 | 1584 | const instance = await this.env.RUN_WORKFLOW.get(job.run_id); |
| 1566 | - await instance.sendEvent({ type: `job-${jobId}`, payload: { retryInSeconds: placementDelay(tries) } }); | |
| 1585 | + await instance.sendEvent({ type: `job-${jobId}`, payload: { retryInSeconds: delay } }); | |
| 1567 | 1586 | } catch (e) { |
| 1568 | 1587 | console.error("could not ask the run's workflow to start the job again", e); |
| 1569 | 1588 | await this.completeJob(jobId, { conclusion: "failure", outputs: {}, failure: { message: `Could not start a runner: ${why}` } }); |
| @@ -1653,7 +1672,10 @@ | ||
| 1653 | 1672 | if (j.status === "queued") return; |
| 1654 | 1673 | // Stopped before the runner fetched the job, so no step ran: place it again. During a |
| 1655 | 1674 | // container rollout a new container can exit (or never get a machine) before it reports in. |
| 1656 | - if (j.status === "waiting" && !j.labels) return this.placementFailed(jobId, exitCode ? `the runner exited with code ${exitCode} before it started the job` : "the container stopped before the runner started"); | |
| 1675 | + if (j.status === "waiting" && !j.labels) { | |
| 1676 | + if (exitCode) return this.placementFailed(jobId, `the runner exited with code ${exitCode} before it started the job`); | |
| 1677 | + return this.placementFailed(jobId, "the container stopped before the runner started", { quick: !requested && (j.early_stops ?? 0) < QUICK_RETRIES }); | |
| 1678 | + } | |
| 1657 | 1679 | // Stopped without reporting while a newer runner image is deployed than the one it ran on: a rollout replaced it. |
| 1658 | 1680 | const ran = j.runner_info ? (JSON.parse(j.runner_info) as JobRunnerInfo).image : undefined; |
| 1659 | 1681 | if (!j.labels && ran && this.env.RUNNER_IMAGE && ran !== this.env.RUNNER_IMAGE) return this.runnerReplaced(j); |
modifiedapps/diffinery/src/repo/schema.ts+2−0View file
| @@ -198,6 +198,8 @@ | ||
| 198 | 198 | ["jobs", "log_chars", "INTEGER NOT NULL DEFAULT 0"], |
| 199 | 199 | // 1 while a queued job waits for one of the repository's hosted runner slots (an account's share, lib/quotas.ts fleetLimits). |
| 200 | 200 | ["jobs", "fleet_held", "INTEGER NOT NULL DEFAULT 0"], |
| 201 | + // Times the platform stopped the job's container before its runner started (repo/actions.ts QUICK_RETRY_SECONDS). | |
| 202 | + ["jobs", "early_stops", "INTEGER NOT NULL DEFAULT 0"], | |
| 201 | 203 | // The registered self-hosted runner that claimed the job (null for hosted jobs and personal-token claims). |
| 202 | 204 | ["jobs", "runner_id", "INTEGER"], |
| 203 | 205 | // 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/src/runner/workflow.ts+2−2View file
| @@ -1,7 +1,7 @@ | ||
| 1 | 1 | import { WorkflowEntrypoint, type WorkflowEvent, type WorkflowStep } from "cloudflare:workers"; |
| 2 | 2 | import type { Env } from "../env.js"; |
| 3 | 3 | import { graphFromLevels, runGraph, type JobNode } from "../repo/job-graph.js"; |
| 4 | -import { MAX_PLACEMENT_TRIES, MAX_RUNNER_RESTARTS } from "../repo/actions.js"; | |
| 4 | +import { MAX_PLACEMENT_TRIES, MAX_RUNNER_RESTARTS, QUICK_RETRIES } from "../repo/actions.js"; | |
| 5 | 5 | |
| 6 | 6 | export interface RunParams { |
| 7 | 7 | repoId: string; |
| @@ -65,7 +65,7 @@ | ||
| 65 | 65 | return; |
| 66 | 66 | } |
| 67 | 67 | const pause = event.payload?.retryInSeconds; |
| 68 | - if (!pause || i >= MAX_PLACEMENT_TRIES + MAX_RUNNER_RESTARTS) return; | |
| 68 | + if (!pause || i >= MAX_PLACEMENT_TRIES + MAX_RUNNER_RESTARTS + QUICK_RETRIES) return; | |
| 69 | 69 | await step.sleep(`pause ${jobId} ${i + 1}`, `${pause} seconds`); |
| 70 | 70 | await step.do(`relaunch ${jobId} ${i + 1}`, () => repo().relaunchJob(jobId)); |
| 71 | 71 | } |
modifiedapps/diffinery/test/unit/actions-runtime.test.ts+9−1View file
| @@ -1,7 +1,7 @@ | ||
| 1 | 1 | import { describe, expect, it } from "vitest"; |
| 2 | 2 | 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"; |
| 3 | 3 | import { DatabaseSync } from "node:sqlite"; |
| 4 | -import { Actions, MAX_ACTIVE_RUNS, MAX_PLACEMENT_TRIES, MAX_RUNNER_RESTARTS, parseRunnerInfo, placementDelay, STALE_IMAGE_TRIES } from "../../src/repo/actions.js"; | |
| 4 | +import { Actions, MAX_ACTIVE_RUNS, MAX_PLACEMENT_TRIES, MAX_RUNNER_RESTARTS, parseRunnerInfo, placementDelay, QUICK_RETRY_SECONDS, STALE_IMAGE_TRIES } from "../../src/repo/actions.js"; | |
| 5 | 5 | import { fleetLimits } from "../../src/lib/quotas.js"; |
| 6 | 6 | import { testD1 } from "./stubs/d1.js"; |
| 7 | 7 | import { DEFAULT_ARTIFACT_QUOTA, Runtime, artifactFileName, artifactObjectKeys } from "../../src/repo/runtime.js"; |
| @@ -773,7 +773,15 @@ | ||
| 773 | 773 | await actions.relaunchJob("j1"); |
| 774 | 774 | expect(job("j1")).toMatchObject({ status: "waiting", container: "job-j1" }); |
| 775 | 775 | expect(running()).toEqual([{ id: "j1" }]); |
| 776 | + // The first such stop starts it again after QUICK_RETRY_SECONDS, uncounted; another one waits as usual. | |
| 776 | 777 | await actions.containerStopped("j1", null); |
| 778 | + expect(job("j1")).toMatchObject({ status: "queued", placement_tries: 1 }); | |
| 779 | + expect(events.at(-1)).toEqual({ type: "job-j1", payload: { retryInSeconds: QUICK_RETRY_SECONDS } }); | |
| 780 | + expect(log("j1").at(-1)).toBe(`##[warning]No hosted runner could start the job yet: the container stopped before the runner started. Diffinery tries again in ${QUICK_RETRY_SECONDS} s (not counted: the first stop like this is retried at once).`); | |
| 781 | + expect(running()).toEqual([]); | |
| 782 | + await actions.relaunchJob("j1"); | |
| 783 | + expect(job("j1")).toMatchObject({ status: "waiting", container: "job-j1" }); | |
| 784 | + await actions.containerStopped("j1", 0); | |
| 777 | 785 | expect(job("j1")).toMatchObject({ status: "queued", placement_tries: 2 }); |
| 778 | 786 | expect(events.at(-1)).toEqual({ type: "job-j1", payload: { retryInSeconds: placementDelay(2) } }); |
| 779 | 787 | expect(log("j1").at(-1)).toMatch(/: the container stopped before the runner started\. Diffinery tries again in 60 s \(wait 2 of \d+\)\.$/); |