diff --git a/.github/scripts/mq-timestamp-unstick.js b/.github/scripts/mq-timestamp-unstick.js new file mode 100644 index 0000000000..696f44f8e2 --- /dev/null +++ b/.github/scripts/mq-timestamp-unstick.js @@ -0,0 +1,231 @@ +// Merge queue ignores a passed check whose completed_at predates its own run; re-running that job unsticks it. + +const OK_CONCLUSIONS = new Set(["SUCCESS", "SKIPPED", "NEUTRAL"]); +const SETTLE_MINUTES = 5; +// Skipped jobs legitimately report completedAt a second or two before their run's createdAt. +const SKEW_SECONDS = 120; + +const ENTRIES_QUERY = `query($owner:String!,$repo:String!,$branch:String!){ + repository(owner:$owner,name:$repo){ mergeQueue(branch:$branch){ entries(first:100){ nodes{ + state enqueuedAt headCommit{oid} pullRequest{number headRefOid} + }}}}}`; + +const CONTEXTS = `statusCheckRollup{ contexts(first:100){ pageInfo{hasNextPage} nodes{ __typename + ... on CheckRun{ databaseId name status conclusion startedAt completedAt detailsUrl + isRequired(pullRequestNumber:$pr) + checkSuite{ workflowRun{ databaseId createdAt updatedAt } } } + ... on StatusContext{ context state createdAt isRequired(pullRequestNumber:$pr) } }}}`; + +const CHECKS_QUERY = `query($owner:String!,$repo:String!,$mg:GitObjectID!,$head:GitObjectID!,$pr:Int!){ + repository(owner:$owner,name:$repo){ + mg: object(oid:$mg){ ... on Commit{ ${CONTEXTS} } } + head: object(oid:$head){ ... on Commit{ ${CONTEXTS} } } + }}`; + +const markerFor = (sha) => ``; +const ms = (s) => (s ? Date.parse(s) : NaN); +const maxMs = (...xs) => Math.max(...xs.filter((x) => !isNaN(x))); + +function normalize(rollup) { + if (!rollup) return { checks: [], truncated: false }; + const { pageInfo, nodes } = rollup.contexts; + const checks = nodes + .filter((n) => n.isRequired) + .map((n) => + n.__typename === "CheckRun" + ? { + kind: "check", + name: n.name, + jobId: n.databaseId, + url: n.detailsUrl, + done: n.status === "COMPLETED", + ok: n.status === "COMPLETED" && OK_CONCLUSIONS.has(n.conclusion), + result: n.status === "COMPLETED" ? n.conclusion : n.status, + startedAt: n.startedAt, + completedAt: n.completedAt, + runId: n.checkSuite?.workflowRun?.databaseId, + runCreatedAt: n.checkSuite?.workflowRun?.createdAt, + runUpdatedAt: n.checkSuite?.workflowRun?.updatedAt, + } + : { + kind: "status", + name: n.context, + done: n.state !== "PENDING" && n.state !== "EXPECTED", + ok: n.state === "SUCCESS", + result: n.state, + completedAt: n.createdAt, + }, + ); + return { checks, truncated: pageInfo.hasNextPage }; +} + +function evaluateEntry({ entry, mgRollup, headRollup, now }) { + const skip = (reason) => ({ act: false, reason, offenders: [] }); + if (entry.state !== "AWAITING_CHECKS") return skip(`state ${entry.state}`); + if (!entry.headCommit) return skip("no merge-group commit yet"); + + const mg = normalize(mgRollup); + const head = normalize(headRollup); + if (mg.truncated || head.truncated) return skip("more than 100 check contexts; not evaluated"); + if (mg.checks.length === 0) return skip("no required checks reported on the merge-group commit"); + + const mgNames = new Set(mg.checks.map((c) => c.name)); + const missing = [...new Set(head.checks.map((c) => c.name))].filter((n) => !mgNames.has(n)); + if (missing.length) return skip(`required check(s) not reported yet: ${missing.join(", ")}`); + + const pending = mg.checks.filter((c) => !c.done); + if (pending.length) return skip(`still running: ${pending.map((c) => c.name).join(", ")}`); + const bad = mg.checks.filter((c) => !c.ok); + if (bad.length) return skip(`not passing: ${bad.map((c) => `${c.name}=${c.result}`).join(", ")}`); + + const enqueued = ms(entry.enqueuedAt); + const settled = maxMs( + enqueued, + ...mg.checks.flatMap((c) => [ms(c.completedAt), ms(c.startedAt), ms(c.runCreatedAt), ms(c.runUpdatedAt)]), + ); + const settleMs = SETTLE_MINUTES * 60 * 1000; + if (now - settled < settleMs) { + return skip(`all required checks passed ${Math.floor((now - settled) / 60000)}m ago; waiting ${SETTLE_MINUTES}m`); + } + + const skew = SKEW_SECONDS * 1000; + const offenders = mg.checks.filter((c) => { + if (c.kind !== "check" || !c.jobId) return false; + const done = ms(c.completedAt); + return [ms(c.runCreatedAt), ms(c.startedAt), enqueued].some((t) => !isNaN(t) && done < t - skew); + }); + if (offenders.length === 0) + return skip("all required checks passed and no mis-timestamped check found; not this bug"); + + // Re-running two jobs of the same run would race on one new attempt, so take one per run. + const perRun = new Map(); + // A summary job re-runs in seconds and was the proven fix (#16139, #16140, #16120); prefer it. + const ordered = [...offenders].sort((a, b) => /summary/i.test(b.name) - /summary/i.test(a.name)); + for (const o of ordered) if (!perRun.has(o.runId)) perRun.set(o.runId, o); + return { act: true, reason: "mis-timestamped required check(s)", offenders: [...perRun.values()] }; +} + +async function hasMarker(github, owner, repo, pr, marker) { + const comments = await github.paginate(github.rest.issues.listComments, { + owner, + repo, + issue_number: pr, + per_page: 100, + }); + return comments.some((c) => (c.body || "").includes(marker)); +} + +async function run({ github, context, core, dryRun, now = Date.now() }) { + const { owner, repo } = context.repo; + const rows = []; + const log = (pr, sha, decision, detail) => { + core.info(`[mq-unstick${dryRun ? " (dry-run)" : ""}] PR #${pr} ${sha.slice(0, 9)}: ${decision} - ${detail}`); + rows.push([`#${pr}`, sha.slice(0, 9), decision, detail]); + }; + + const data = await github.graphql(ENTRIES_QUERY, { owner, repo, branch: "main" }); + const entries = data.repository.mergeQueue?.entries.nodes || []; + core.info(`${entries.length} merge queue entr${entries.length === 1 ? "y" : "ies"}`); + + for (const entry of entries) { + const pr = entry.pullRequest.number; + const sha = entry.headCommit?.oid || ""; + if (entry.state !== "AWAITING_CHECKS" || !sha) { + log( + pr, + sha || "-", + "skip", + entry.state !== "AWAITING_CHECKS" ? `state ${entry.state}` : "no merge-group commit yet", + ); + continue; + } + const checks = await github.graphql(CHECKS_QUERY, { + owner, + repo, + mg: sha, + head: entry.pullRequest.headRefOid, + pr, + }); + const verdict = evaluateEntry({ + entry, + mgRollup: checks.repository.mg?.statusCheckRollup, + headRollup: checks.repository.head?.statusCheckRollup, + now, + }); + if (!verdict.act) { + log(pr, sha, "skip", verdict.reason); + continue; + } + + const marker = markerFor(sha); + if (await hasMarker(github, owner, repo, pr, marker)) { + log(pr, sha, "skip", "already re-ran once for this merge-group commit"); + continue; + } + + const rerun = []; + for (const o of verdict.offenders) { + const { data: wr } = await github.request("GET /repos/{owner}/{repo}/actions/runs/{run_id}", { + owner, + repo, + run_id: o.runId, + }); + const what = `${o.name} (job ${o.jobId}, completed ${o.completedAt}, run created ${o.runCreatedAt})`; + if (wr.run_attempt > 1) { + log(pr, sha, "skip", `${what}: run already on attempt ${wr.run_attempt}`); + continue; + } + if (dryRun) { + log(pr, sha, "would re-run", what); + continue; + } + try { + await github.request("POST /repos/{owner}/{repo}/actions/jobs/{job_id}/rerun", { + owner, + repo, + job_id: o.jobId, + }); + rerun.push(o); + log(pr, sha, "re-ran", what); + } catch (e) { + log(pr, sha, "error", `${what}: re-run failed: ${e.message}`); + } + } + + if (rerun.length === 0) continue; + const names = rerun.map((o) => `\`${o.name}\``).join(", "); + const links = rerun + .map((o) => `[${o.name}](${o.url || `${context.serverUrl}/${owner}/${repo}/actions/runs/${o.runId}`})`) + .join(", "); + const body = [ + marker, + `Merge queue was stuck: ${names} reported success with a timestamp older than its run, so the queue ignored it. Re-ran ${links} to unstick it.`, + ].join("\n"); + try { + await github.rest.issues.createComment({ owner, repo, issue_number: pr, body }); + } catch (e) { + core.warning(`Could not comment on PR #${pr}: ${e.message}`); + } + } + + await core.summary + .addHeading(`Merge-queue unstick${dryRun ? " (dry-run)" : ""}`, 3) + .addRaw( + `Acts only when an AWAITING_CHECKS entry has every required check passed (none missing vs the PR), ` + + `has sat ${SETTLE_MINUTES}+ min since enqueue and since the latest of each check's completed/started/run-created/run-updated time, ` + + `and has a required check whose completed_at is over ${SKEW_SECONDS}s before its run's created_at, its started_at, or the enqueue time. ` + + `Then re-runs that job once per merge-group SHA; it never edits check results.`, + ) + .addTable([ + [ + { data: "PR", header: true }, + { data: "Merge-group SHA", header: true }, + { data: "Decision", header: true }, + { data: "Why / what", header: true }, + ], + ...rows, + ]) + .write(); +} + +module.exports = { run, evaluateEntry, markerFor, SETTLE_MINUTES, SKEW_SECONDS }; diff --git a/.github/scripts/mq-timestamp-unstick.test.js b/.github/scripts/mq-timestamp-unstick.test.js new file mode 100644 index 0000000000..e16a97d0ab --- /dev/null +++ b/.github/scripts/mq-timestamp-unstick.test.js @@ -0,0 +1,194 @@ +#!/usr/bin/env node +// Run with: node --test .github/scripts/mq-timestamp-unstick.test.js (runs before the reaper acts). +const { test } = require("node:test"); +const assert = require("node:assert"); +const { evaluateEntry, run, markerFor } = require("./mq-timestamp-unstick.js"); + +const NOW = Date.parse("2026-11-01T10:20:00Z"); +const entry = (over = {}) => ({ + state: "AWAITING_CHECKS", + enqueuedAt: "2026-11-01T09:50:00Z", + headCommit: { oid: "abc123def456" }, + pullRequest: { number: 16139, headRefOid: "fff000" }, + ...over, +}); +const checkRun = (name, over = {}) => ({ + __typename: "CheckRun", + databaseId: 1000 + name.length, + name, + status: "COMPLETED", + conclusion: "SUCCESS", + startedAt: "2026-11-01T09:53:00Z", + completedAt: "2026-11-01T10:05:00Z", + detailsUrl: `https://example.test/job/${name}`, + isRequired: true, + checkSuite: { + workflowRun: { databaseId: 41290642768, createdAt: "2026-11-01T09:52:10Z", updatedAt: "2026-11-01T10:05:00Z" }, + }, + ...over, +}); +const status = (context, state = "SUCCESS") => ({ + __typename: "StatusContext", + context, + state, + createdAt: "2026-11-01T09:55:00Z", + isRequired: true, +}); +const rollup = (nodes, hasNextPage = false) => ({ contexts: { pageInfo: { hasNextPage }, nodes } }); +// Real incident: run created 09:52:10Z, unit_tests_summary completed_at 09:21:49Z. +const stale = checkRun("unit_tests_summary", { + startedAt: "2026-11-01T09:21:40Z", + completedAt: "2026-11-01T09:21:49Z", +}); +const healthy = () => [ + checkRun("ci-gate"), + checkRun("playwright_summary", { conclusion: "SKIPPED" }), + status("ent-build-status-check"), +]; + +test("acts on the incident signature and picks the offending job", () => { + const v = evaluateEntry({ + entry: entry(), + mgRollup: rollup([...healthy(), stale]), + headRollup: rollup(healthy()), + now: NOW, + }); + assert.strictEqual(v.act, true); + assert.deepStrictEqual( + v.offenders.map((o) => o.name), + ["unit_tests_summary"], + ); +}); + +test("skips when timestamps are sane (not this bug)", () => { + const v = evaluateEntry({ entry: entry(), mgRollup: rollup(healthy()), headRollup: rollup(healthy()), now: NOW }); + assert.strictEqual(v.act, false); + assert.match(v.reason, /not this bug/); +}); + +test("tolerates skipped jobs reporting completedAt a second before run creation", () => { + const skipped = checkRun("api_tests_summary", { + conclusion: "SKIPPED", + startedAt: "2026-11-01T09:52:11Z", + completedAt: "2026-11-01T09:52:09Z", + }); + const v = evaluateEntry({ + entry: entry(), + mgRollup: rollup([...healthy(), skipped]), + headRollup: rollup(healthy()), + now: NOW, + }); + assert.strictEqual(v.act, false); +}); + +test("skips while a required check is still running", () => { + const running = checkRun("ui_code_quality", { status: "IN_PROGRESS", conclusion: null, completedAt: null }); + const v = evaluateEntry({ + entry: entry(), + mgRollup: rollup([...healthy(), stale, running]), + headRollup: rollup(healthy()), + now: NOW, + }); + assert.strictEqual(v.act, false); + assert.match(v.reason, /still running: ui_code_quality/); +}); + +test("skips when a required check failed", () => { + const failed = checkRun("db_tests_summary", { conclusion: "FAILURE" }); + const v = evaluateEntry({ + entry: entry(), + mgRollup: rollup([...healthy(), stale, failed]), + headRollup: rollup(healthy()), + now: NOW, + }); + assert.strictEqual(v.act, false); + assert.match(v.reason, /db_tests_summary=FAILURE/); +}); + +test("skips when a check required on the PR is missing from the merge-group commit", () => { + const head = rollup([...healthy(), checkRun("js-license-check")]); + const v = evaluateEntry({ entry: entry(), mgRollup: rollup([...healthy(), stale]), headRollup: head, now: NOW }); + assert.strictEqual(v.act, false); + assert.match(v.reason, /not reported yet: js-license-check/); +}); + +test("waits for the settle window after the last trustworthy finish signal", () => { + const justNow = Date.parse("2026-11-01T10:07:00Z"); + const v = evaluateEntry({ + entry: entry(), + mgRollup: rollup([...healthy(), stale]), + headRollup: rollup(healthy()), + now: justNow, + }); + assert.strictEqual(v.act, false); + assert.match(v.reason, /waiting 5m/); +}); + +test("skips non-AWAITING_CHECKS entries and truncated rollups", () => { + assert.strictEqual(evaluateEntry({ entry: entry({ state: "MERGEABLE" }), now: NOW }).act, false); + const v = evaluateEntry({ + entry: entry(), + mgRollup: rollup([...healthy(), stale], true), + headRollup: rollup(healthy()), + now: NOW, + }); + assert.match(v.reason, /more than 100/); +}); + +test("takes one offending job per workflow run, preferring the summary job", () => { + const stale2 = checkRun("ui_code_quality", { databaseId: 9, completedAt: "2026-11-01T09:04:57Z" }); + const v = evaluateEntry({ + entry: entry(), + mgRollup: rollup([...healthy(), stale2, stale]), + headRollup: rollup(healthy()), + now: NOW, + }); + assert.deepStrictEqual( + v.offenders.map((o) => o.name), + ["unit_tests_summary"], + ); +}); + +function fakes({ comments = [], runAttempt = 1 } = {}) { + const writes = []; + const github = { + graphql: async (q) => + q.includes("mergeQueue") + ? { repository: { mergeQueue: { entries: { nodes: [entry()] } } } } + : { + repository: { + mg: { statusCheckRollup: rollup([...healthy(), stale]) }, + head: { statusCheckRollup: rollup(healthy()) }, + }, + }, + paginate: async () => comments, + rest: { issues: { listComments: () => {}, createComment: async (p) => writes.push(["comment", p]) } }, + request: async (route, p) => { + if (route.startsWith("GET")) return { data: { run_attempt: runAttempt } }; + writes.push([route, p]); + return { data: {} }; + }, + }; + const summary = { addHeading: () => summary, addRaw: () => summary, addTable: () => summary, write: async () => {} }; + const core = { info: () => {}, warning: () => {}, summary }; + const context = { repo: { owner: "o", repo: "r" }, serverUrl: "https://github.com" }; + return { github, core, context, writes }; +} + +test("run re-runs the job and posts one marked comment", async () => { + const f = fakes(); + await run({ ...f, dryRun: false, now: NOW }); + assert.deepStrictEqual( + f.writes.map((w) => w[0]), + ["POST /repos/{owner}/{repo}/actions/jobs/{job_id}/rerun", "comment"], + ); + assert.ok(f.writes[1][1].body.startsWith(markerFor("abc123def456"))); +}); + +test("run makes no writes in dry-run, with a marker, or on a re-run attempt", async () => { + for (const opts of [{}, { comments: [{ body: markerFor("abc123def456") }] }, { runAttempt: 2 }]) { + const f = fakes(opts); + await run({ ...f, dryRun: Object.keys(opts).length === 0, now: NOW }); + assert.deepStrictEqual(f.writes, []); + } +}); diff --git a/.github/workflows/stuck-run-reaper.yml b/.github/workflows/stuck-run-reaper.yml index 5b5bf29419..1999de9446 100644 --- a/.github/workflows/stuck-run-reaper.yml +++ b/.github/workflows/stuck-run-reaper.yml @@ -8,15 +8,18 @@ name: Playwright e2e Stuck-Run-Reaper # It never held a runner; swept after a separate, much longer threshold. # Every cancellation is explained (on the PR when there is one) with wording # specific to the case, so a cancellation is never misread as a blocked runner. +# A separate job re-runs merge-queue checks GitHub ignores for a completed_at older than their run. on: schedule: # Every 15 minutes. Worst-case a stuck job lives ~threshold + 15m. - cron: "*/15 * * * *" + # Every 10 minutes for the merge-queue unstick job. + - cron: "*/10 * * * *" workflow_dispatch: inputs: dry_run: - description: "Report stuck runs but do NOT cancel or comment" + description: "Report stuck runs and stuck merge-queue entries but do NOT cancel, re-run or comment" type: boolean default: false threshold_minutes: @@ -28,12 +31,8 @@ on: type: string default: "24" -concurrency: - group: stuck-run-reaper - cancel-in-progress: false - permissions: - actions: write # force-cancel workflow runs + actions: write # force-cancel workflow runs, re-run merge-queue jobs pull-requests: write # comment on the PR explaining the cancellation contents: read @@ -42,8 +41,12 @@ jobs: name: Reap runs stuck waiting for an EKS runner # MUST run on a GitHub-hosted runner — it must not depend on the same # self-hosted EKS pool it is policing. + if: github.event_name != 'schedule' || github.event.schedule == '*/15 * * * *' runs-on: ubuntu-latest timeout-minutes: 10 + concurrency: + group: stuck-run-reaper + cancel-in-progress: false steps: - name: Cancel runs stuck waiting for an EKS runner uses: actions/github-script@v9 @@ -315,3 +318,31 @@ jobs: ...summaryRows, ]) .write(); + + unstick-merge-queue: + name: Unstick merge-queue entries with mis-timestamped checks + if: github.event_name != 'schedule' || github.event.schedule == '*/10 * * * *' + runs-on: ubuntu-latest + timeout-minutes: 10 + concurrency: + group: stuck-run-reaper-merge-queue + cancel-in-progress: false + steps: + - uses: actions/checkout@v5 + with: + sparse-checkout: .github/scripts + persist-credentials: false + + - name: Self-test detection logic + run: node --test .github/scripts/mq-timestamp-unstick.test.js + + - name: Re-run mis-timestamped jobs blocking the merge queue + uses: actions/github-script@v9 + with: + # Same human PAT as the reaper: reads the merge queue and authors the PR comment as a person. + github-token: ${{ secrets.ORG_ADMIN_TOKEN }} + script: | + const inputs = context.payload.inputs || {}; + const dryRun = inputs.dry_run === true || inputs.dry_run === "true"; + const { run } = require(`${process.env.GITHUB_WORKSPACE}/.github/scripts/mq-timestamp-unstick.js`); + await run({ github, context, core, dryRun });