ci: re-run mis-timestamped checks that stall the merge queue (#16182)

This commit is contained in:
Shrinath Rao
2026-11-01 13:39:50 +00:00
committed by GitHub
parent 10c70aaf3c
commit 90b99fe4dd
3 changed files with 462 additions and 6 deletions
+231
View File
@@ -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) => `<!-- stuck-run-reaper:mq-timestamp:${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 };
@@ -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, []);
}
});
+37 -6
View File
@@ -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 });