From ed973840d3186c47b3944309481a4a9828454e76 Mon Sep 17 00:00:00 2001 From: garrytan Date: Fri, 16 Oct 2026 23:17:09 +0000 Subject: [PATCH] feat(pregate): timing check flags elapsed-time bounds and sleep-then-assert in added test lines (W4) lib/pregate/checks/timing.ts prints TIMING_ASSERTION: : and a TIMING_ASSERTIONS summary; gstack-timing-ok: in any comment syntax on the line or the line above escapes one. It warns (PREGATE_TIMING_ASSERTION): measured on gstack (9 of 47 test-touching commits, 263 hits in the tree) and gbrain (37 of 95 commits; 31 of 38 sites of the five timing-flake fixes), blocking would stop a fifth to two fifths of test changes. Adds the /review checklist rule and the /investigate timing-flake playbook. Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com> (cherry picked from commit a3b86b10b2373af7d9eb026dabd6b38d062a9fe1) --- bin/gstack-doctor-components.sh | 1 + docs/pregate.md | 54 +++++ docs/troubleshooting.md | 14 ++ investigate/sections/flake.md | 24 ++ investigate/sections/flake.md.tmpl | 24 ++ lib/pregate/checks/timing.ts | 225 ++++++++++++++++++ lib/pregate/index.ts | 3 +- lib/result-codes.ts | 6 + review/checklist.md | 4 + test/fixtures/module-size-ratchet.json | 1 + .../fixtures/pregate-timing/flaky.test.ts.txt | 62 +++++ .../fixtures/pregate-timing/test_flaky.py.txt | 25 ++ test/pregate-selection.test.ts | 4 +- test/pregate-timing.test.ts | 118 +++++++++ 14 files changed, 562 insertions(+), 3 deletions(-) create mode 100644 lib/pregate/checks/timing.ts create mode 100644 test/fixtures/pregate-timing/flaky.test.ts.txt create mode 100644 test/fixtures/pregate-timing/test_flaky.py.txt create mode 100644 test/pregate-timing.test.ts diff --git a/bin/gstack-doctor-components.sh b/bin/gstack-doctor-components.sh index c00b7b679..31abe645b 100644 --- a/bin/gstack-doctor-components.sh +++ b/bin/gstack-doctor-components.sh @@ -246,6 +246,7 @@ gstack_result_anchor() { QUEUE_VERIFY_MISMATCH) printf '%s' 'queue-verify-mismatch' ;; QUEUE_GATE_MISSING) printf '%s' 'queue-gate-missing' ;; GATE_AHEAD_ATTEMPT_INVALID) printf '%s' 'gate-ahead-attempt-invalid' ;; + PREGATE_TIMING_ASSERTION) printf '%s' 'pregate-timing-assertion' ;; *) return 1 ;; esac } diff --git a/docs/pregate.md b/docs/pregate.md index 5532c51a4..fd6708b6a 100644 --- a/docs/pregate.md +++ b/docs/pregate.md @@ -97,6 +97,12 @@ Two stages with separate clocks, both printed: searched for the old value; a consumer the branch did not update fails with `file:line`. +- `timing`: added or changed test lines that compare an elapsed wall-clock or + CPU time against a bound, or sleep and then assert, print + `TIMING_ASSERTION: : ` and a + `TIMING_ASSERTIONS: found= escaped= files=` summary. It warns + (`PREGATE_TIMING_ASSERTION`); it does not block. See [timing](#timing). + - `guards`: each guard in `.gstack/pregate.json` whose `when` globs match a touched file (renames included) runs its `command` in its own process, under the verified launch Bun, with its own `timeout_s` (default `--timeout`). A @@ -246,6 +252,54 @@ guard is a *command* with its own fix line. Older gstack refuses unknown keys that reads them ships. The worked gbrain configuration is in [gbrain worked configs](#gbrain-worked-configs). + +## Timing assertions + +`timing` reads only the lines the branch added or changed in test code (test +files and files under `test/`, `tests/`, `spec/` or `__tests__/`; never +fixture trees). It reports three patterns: + +| Pattern | Example | +|---|---| +| `wall-time-bound` | `expect(Date.now() - t0).toBeLessThan(400)`, `expect(elapsedMs).toBeLessThanOrEqual(2_000)`, `assert elapsed < 0.5` | +| `cpu-time-bound` | `expect(cpuMs(() => parse(x))).toBeLessThan(150)`, `assert time.process_time() - c0 < 0.2` | +| `sleep-then-assert` | `await Bun.sleep(50); expect(calls).toBe(1)` (a fixed sleep, not a polling loop) | + +A comparison with `0`, a named bound (`timeoutMs`, `TTL_MS`), a timestamp +ordered against a bare `Date.now()` and a `while (… Date.now() < deadline)` +poll are not reported. Changing the bound of an existing assertion is a changed +line, so it is reported. + +**Escape.** When the bound is the contract (a hang check with wide headroom, a +CPU-time bound on a pure function), put `gstack-timing-ok: ` in a +comment, in any comment syntax (`//`, `#`, `/* */`, `--`), on the line or +the line above. The reason is required; an empty one is still reported with +`(gstack-timing-ok needs a reason)`. `--explain` lists every escape and its +reason. + +**Warn, not block (measured 2026-10-16).** The detector was run over: + +- gstack's own test tree: 263 hits in 123 of 1,566 test files (176 + `wall-time-bound`, 87 `sleep-then-assert`), mostly real timing assertions, + most of them generous "does not hang" bounds. +- gstack's last 51 commits on main: 9 of the 47 that touched tests would have + been flagged (29 hits; #3190 alone has 7). +- gbrain's last 100 commits on master: 37 of the 95 that touched tests would + have been flagged (147 hits). +- The five gbrain timing-flake fixes (#6050, #6493, #6726, #6746, #6862): 31 of + 38 fix sites were flagged before the fix. The misses are flakes with no + timing comparison on the line (an injected deadline in #6050, a + `Promise.race` with a sleep and a deadline parameter in #6862) and ratio or + percentile checks computed far from the clock read. The correct fix in + #6726 (wall clock to thread CPU time) is still a bound and is reported 21 + times. + +Blocking would stop about a fifth of gstack's and two fifths of gbrain's +test-touching commits, including correct fixes, so the check warns. A repo +that wants it stricter keeps the warning in its review rule (the /review +checklist has the same rule) and /investigate's flake playbook says what to do +with a timing flake: never raise the bound. + ## Sealed output: the pre-push hook and `gstack-pregate sealed` diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index f94e2f9ec..d6e8b53f3 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -3537,3 +3537,17 @@ and the current one. Record the live attempt, or prepare a new one with `gate-ahead --after ` and run the gate there without editing tracked files. + +### `PREGATE_TIMING_ASSERTION` + +**Meaning.** A test line the branch added or changed compares an elapsed +wall-clock or CPU time against a bound, or sleeps for a fixed time and then +asserts. Under machine load such a test fails without a code change. The +`timing` check warns; it does not block (the measurement is in +[docs/pregate.md#timing](pregate.md#timing)). + +**Fix.** Assert on the outcome instead: an injected clock, a forced deadline, +an event or a poll with a deadline. When the bound is the contract, add +`gstack-timing-ok: ` in a comment on the line or the line above. Never +raise a bound to make a flake pass; /investigate's flake playbook covers the +diagnosis. diff --git a/investigate/sections/flake.md b/investigate/sections/flake.md index 11feda351..96b6eac8f 100644 --- a/investigate/sections/flake.md +++ b/investigate/sections/flake.md @@ -48,3 +48,27 @@ relaxation (review tag RH-15) and needs the owner's decision, not a merge. `gh run list` comparison with the first-moved `headSha`, and a routing note for the owner: `fix in this PR` | `rerun; cause outside the PR: ` | `owner decision needed: `. + +### Timing flakes (`TIMING_ASSERTION`) + +When the failing line compares an elapsed time with a bound or sleeps and then +asserts (`gstack-pregate`'s `timing` check prints it as +`TIMING_ASSERTION: : `): + +1. **Same-load distributions.** Log the asserted value on every run and run the + file N ≥ 20 times on `origin/` and on the PR head under the same load + (same machine, same concurrency, beside the same shard). Report min, p50, + p95, max and failures against the bound for both. A distribution that moved + on the PR head is a regression in the PR; the same distribution on both is a + test that depends on machine load. +2. **Forced probe.** Inject the delay the load causes (a sleep inside the + measured span behind a test-only hook, or a starved CPU) and show the + assertion failing every time. +3. **Fix the measurement, never the bound.** Assert on the outcome, an injected + clock, a forced deadline or a poll with a deadline instead of a fixed sleep; + a complexity bound measures thread CPU time against a same-run baseline. + When a bound stays the contract, the line carries + `gstack-timing-ok: `. Raising the bound is not a fix. +4. **Rerun only with outside-cause evidence:** the same-load distributions show + no PR regression and the failed run's load is on record (CI log, runner + metrics). Put both in `## Flake evidence`. diff --git a/investigate/sections/flake.md.tmpl b/investigate/sections/flake.md.tmpl index dfb852acb..bd8de9e61 100644 --- a/investigate/sections/flake.md.tmpl +++ b/investigate/sections/flake.md.tmpl @@ -41,3 +41,27 @@ skip until the cause is named and probed. `gh run list` comparison with the first-moved `headSha`, and a routing note for the owner: `fix in this PR` | `rerun; cause outside the PR: ` | `owner decision needed: `. + +### Timing flakes (`TIMING_ASSERTION`) + +When the failing line compares an elapsed time with a bound or sleeps and then +asserts (`gstack-pregate`'s `timing` check prints it as +`TIMING_ASSERTION: : `): + +1. **Same-load distributions.** Log the asserted value on every run and run the + file N ≥ 20 times on `origin/` and on the PR head under the same load + (same machine, same concurrency, beside the same shard). Report min, p50, + p95, max and failures against the bound for both. A distribution that moved + on the PR head is a regression in the PR; the same distribution on both is a + test that depends on machine load. +2. **Forced probe.** Inject the delay the load causes (a sleep inside the + measured span behind a test-only hook, or a starved CPU) and show the + assertion failing every time. +3. **Fix the measurement, never the bound.** Assert on the outcome, an injected + clock, a forced deadline or a poll with a deadline instead of a fixed sleep; + a complexity bound measures thread CPU time against a same-run baseline. + When a bound stays the contract, the line carries + `gstack-timing-ok: `. Raising the bound is not a fix. +4. **Rerun only with outside-cause evidence:** the same-load distributions show + no PR regression and the failed run's load is on record (CI log, runner + metrics). Put both in `## Flake evidence`. diff --git a/lib/pregate/checks/timing.ts b/lib/pregate/checks/timing.ts new file mode 100644 index 000000000..7c9d75d91 --- /dev/null +++ b/lib/pregate/checks/timing.ts @@ -0,0 +1,225 @@ +/** + * pregate check `timing` (tier 1, preflight; field list 2 W4): added or + * changed test lines that compare an elapsed wall-clock or CPU time against a + * bound, or that sleep and then assert. Each hit prints + * TIMING_ASSERTION: : ; a hit is escaped by + * gstack-timing-ok: in any comment syntax on the line or the line + * above (the reason is required). The check warns; see docs/pregate.md#timing + * for the measurement behind warn rather than block. Field incident: gbrain's + * master went red on a 461 ms run against a 400 ms bound, and five such flakes + * were fixed by hand in one week. + */ +import { spawnSync } from 'node:child_process'; +import * as fs from 'node:fs'; +import * as path from 'node:path'; +import { baseInputs, sha256 } from '../context'; +import { isTestFile } from '../import-graph'; +import type { CheckDef, CheckResult, PregateContext } from '../types'; + +export type TimingPattern = 'wall-time-bound' | 'cpu-time-bound' | 'sleep-then-assert'; +export interface TimingHit { file: string; line: number; pattern: TimingPattern; escape?: { reason: string } | { missingReason: true } } + +const CODE_EXT = /\.(?:[cm]?[jt]sx?|py|rb|go|rs|java|kt|swift|exs?|php|cs)$/; +const TEST_DIR = /(?:^|\/)(?:test|tests|spec|__tests__)\//; +const FIXTURE_DIR = /(?:^|\/)(?:fixtures|__fixtures__|testdata)\//; + +const WALL_SOURCE = /\b(?:Date\.now|performance\.now|process\.hrtime(?:\.bigint)?|Bun\.nanoseconds|time\.(?:time|monotonic|perf_counter)(?:_ns)?|System\.(?:nanoTime|currentTimeMillis)|Instant\.now|time\.Now|time\.Since|Process\.clock_gettime)\s*\(|\bnew Date\(\)\.getTime\(\)/; +const CPU_SOURCE = /\b(?:process\.cpuUsage|process\.resourceUsage|time\.(?:process_time|thread_time)(?:_ns)?|resource\.getrusage|\w*[cC]pu(?:Ms|Time|Usage|Nanos|Micros)\w*)\s*\(/; +const BOUND_NAME = /timeout|deadline|budget|limit|max|min|interval|delay|grace|ttl|cap\b|wait/i; +const ELAPSED_NAME = /^(?:ms|dt|secs?|seconds|nanos)$|^(?:elapsed|duration|took|latency|wall|cpu)|(?:Elapsed|Duration|Latency|Took|Ms|_ms|Millis|Nanos|_ns|Seconds|Secs)$/; +const ASSERT_CALL = /\bexpect\s*\(|\bassert\w*\b|\bt\.(?:ok|true|false|is)\s*\(|\.should\b/; +const SLEEP = /\b(?:await\s+(?:Bun\.sleep|sleep|delay|wait|setTimeoutPromise|timers\.setTimeout|scheduler\.wait)\s*\(|await\s+new\s+Promise\s*(?:<[^>]*>)?\s*\(\s*\(?\s*\w*\s*\)?\s*=>\s*setTimeout\s*\(|time\.sleep\s*\(|Thread\.sleep\s*\(|Bun\.sleepSync\s*\(|Atomics\.wait\s*\()/; +const ZERO_SLEEP = /^(?:await\s+)?(?:\w+(?:\.\w+)?\s*\(\s*0\s*\)|new\s+Promise[^;]*?setTimeout\s*\(\s*\w+\s*,\s*0\s*\))/; +const POLL = /\bwhile\b|\buntil\b|\bfor\s*\(|\bdo\s*\{/; +const ESCAPE = /(?:\/\/|\/\*|#|--|/g, '').trim(); + return /[A-Za-z]{2}/.test(reason) ? { reason } : { missingReason: true }; +} + +const identRe = (name: string) => new RegExp('(? { + const vars = new Map(); + for (let pass = 0; pass < 2; pass++) { + for (const line of lines) { + const m = ASSIGN.exec(line); + if (!m || vars.has(m[1]!)) continue; + const rhs = m[2]!.replace(/^await\s+/, ''); + const leads = (re: RegExp) => { const r = re.exec(rhs); return !!r && r.index === 0; }; + if (leads(CPU_SOURCE)) { vars.set(m[1]!, 'cpu'); continue; } + if (leads(WALL_SOURCE)) { vars.set(m[1]!, 'wall'); continue; } + if (!ARITHMETIC.test(rhs) || /[\w$]\s*\(/.test(rhs.replace(WALL_SOURCE, '0').replace(CPU_SOURCE, '0').replace(/\bMath\.\w+\s*\(/g, '('))) continue; + if (CPU_SOURCE.test(rhs)) { vars.set(m[1]!, 'cpu'); continue; } + if (WALL_SOURCE.test(rhs)) { vars.set(m[1]!, 'wall'); continue; } + for (const [name, kind] of vars) if (identRe(name).test(rhs)) { vars.set(m[1]!, kind); break; } + } + } + return vars; +} + +/** The clock kind a code fragment measures, from a clock call, a clock variable or an elapsed-time name; null when it reads no time. */ +function timeOperand(code: string, vars: Map): 'wall' | 'cpu' | null { + if (CPU_SOURCE.test(code)) return 'cpu'; + if (WALL_SOURCE.test(code)) return 'wall'; + let kind: 'wall' | 'cpu' | null = null; + for (const [, ident] of code.matchAll(/(? /^\s*0(?:\.0+)?n?\s*$/.test(s); +const bareClock = (s: string) => /^\s*(?:Date\.now\(\)|performance\.now\(\)|new Date\(\)\.getTime\(\))\s*$/.test(s); + +/** The clock kind of an asserted comparison between a time operand and a bound; a comparison with 0 is a sanity check, and a timestamp ordered against a bare now() is not an elapsed time. */ +function boundKind(line: string, vars: Map): 'wall' | 'cpu' | null { + const code = line.replace(/'(?:[^'\\]|\\.)*'|"(?:[^"\\]|\\.)*"|`(?:[^`\\]|\\.)*`/g, "''").replace(/\s\/\/.*$|^\s*\/\/.*$|\s#\s.*$/, ''); + for (const m of code.matchAll(/\.(?:toBeLessThan|toBeLessThanOrEqual|toBeGreaterThan|toBeGreaterThanOrEqual|toBeWithin)\s*\(/g)) { + const bound = parenArgs(code, m.index! + m[0].length - 1); + const open = code.lastIndexOf('expect(', m.index!); + if (open < 0 || isZero(bound)) continue; + const actual = parenArgs(code, open + 'expect'.length); + if (bareClock(bound) && !timeOperand(actual, vars)) continue; + const kind = timeOperand(actual, vars) ?? timeOperand(bound, vars); + if (kind) return kind; + } + for (const m of code.matchAll(/\b(?:assertLess|assertLessEqual|assertGreater|assertGreaterEqual)\s*\(/g)) { + const args = parenArgs(code, m.index! + m[0].length - 1); + if (isZero(args.split(',')[1] ?? '')) continue; + const kind = timeOperand(args, vars); + if (kind) return kind; + } + const asserted: string[] = []; + for (const m of code.matchAll(/\b(?:expect|assert(?:\.\w+)?|t\.(?:ok|true|false))\s*\(/g)) asserted.push(parenArgs(code, m.index! + m[0].length - 1)); + const py = /^\s*assert\s+(.+)$/.exec(code); + if (py) asserted.push(py[1]!); + for (const segment of asserted) { + const clean = segment.replace(/=>/g, ' '); + for (const c of clean.matchAll(/([^<>=!&|,(]+?)\s*(<=?|>=?)\s*([^<>=&|,)]+)/g)) { + if (isZero(c[3]!) || isZero(c[1]!)) continue; + if (bareClock(c[3]!) && !timeOperand(c[1]!, vars)) continue; + const kind = timeOperand(c[1]!, vars) ?? timeOperand(c[3]!, vars); + if (kind) return kind; + } + } + return null; +} + +/** True when the sleep sits outside a string literal and outside a polling loop. */ +function fixedSleepAt(lines: readonly string[], i: number): boolean { + const line = lines[i]!; + const at = line.search(SLEEP); + if (at < 0) return false; + const before = line.slice(0, at); + if (((before.match(/'/g)?.length ?? 0) % 2) || ((before.match(/"/g)?.length ?? 0) % 2) || ((before.match(/`/g)?.length ?? 0) % 2)) return false; + if (ZERO_SLEEP.test(line.slice(at)) || POLL.test(line)) return false; + for (let k = i - 1; k >= 0 && k >= i - 2; k--) { + const prev = lines[k]!.trim(); + if (!prev) continue; + if (POLL.test(prev) && /\{\s*$/.test(prev)) return false; + break; + } + return true; +} + +/** + * Timing hits in one file's text. `added` holds the 1-based line numbers the + * branch added or changed; 'all' scans every line (the measurement mode). + */ +export function scanTiming(file: string, text: string, added: ReadonlySet | 'all'): TimingHit[] { + const lines = text.split('\n'); + const isAdded = (n: number) => added === 'all' || added.has(n); + const vars = clockVariables(lines); + const hits: TimingHit[] = []; + const escapeAt = (...ns: number[]) => { + for (const n of ns) { const e = escapeReason(lines[n - 1]); if (e) return e; } + return undefined; + }; + for (let i = 0; i < lines.length; i++) { + const n = i + 1; + const line = lines[i]!; + const kind = boundKind(line, vars); + if (kind && isAdded(n)) { hits.push({ file, line: n, pattern: kind === 'cpu' ? 'cpu-time-bound' : 'wall-time-bound', escape: escapeAt(n, n - 1) }); continue; } + if (!fixedSleepAt(lines, i)) continue; + let seen = 0; + for (let j = i + 1; j < lines.length && seen < 3; j++) { + const next = lines[j]!.trim(); + if (!next || /^(?:\/\/|#|\*|\/\*)/.test(next)) continue; + seen++; + if (SLEEP.test(next)) break; + if (!ASSERT_CALL.test(next)) continue; + if (isAdded(n) || isAdded(j + 1)) hits.push({ file, line: n, pattern: 'sleep-then-assert', escape: escapeAt(n, n - 1, j + 1, j) }); + break; + } + } + return hits; +} + +/** Added line numbers per test file, merge-base to the working tree; an untracked test file counts whole. */ +export function addedTestLines(ctx: PregateContext): Map | 'all'> { + const out = new Map | 'all'>(); + const files = ctx.touched.filter(t => t.status !== 'D' && scansTiming(t.path)); + if (!files.length) return out; + const diff = spawnSync('git', ['diff', '--no-color', '--unified=0', '--diff-filter=ACMR', '-M', ctx.mergeBase, '--', ...files.map(t => t.path)], { cwd: ctx.repoRoot, encoding: 'utf8', timeout: 60_000, maxBuffer: 256 * 1024 * 1024, env: ctx.env }); + let current: Set | null = null; + for (const line of (diff.stdout ?? '').split('\n')) { + const header = /^\+\+\+ b\/(.+)$/.exec(line); + if (header) { current = new Set(); out.set(header[1]!, current); continue; } + const hunk = /^@@ -\d+(?:,\d+)? \+(\d+)(?:,(\d+))? @@/.exec(line); + if (hunk && current) { const start = Number(hunk[1]); const count = hunk[2] === undefined ? 1 : Number(hunk[2]); for (let k = 0; k < count; k++) current.add(start + k); } + } + for (const t of files) if (!out.has(t.path) && t.uncommitted && t.status === 'A') out.set(t.path, 'all'); + return out; +} + +function run(ctx: PregateContext): CheckResult { + const added = addedTestLines(ctx); + const hits: TimingHit[] = []; + for (const [file, lines] of added) { + let text: string; + try { text = fs.readFileSync(path.join(ctx.repoRoot, file), 'utf8'); } catch { continue; } + hits.push(...scanTiming(file, text, lines)); + } + const inputs = baseInputs(ctx, { hits: sha256(hits.map(h => h.file + ':' + h.line + ':' + h.pattern + ':' + (h.escape && 'reason' in h.escape ? h.escape.reason : '')).join('\n')) }); + const open = hits.filter(h => !h.escape || 'missingReason' in h.escape); + const escaped = hits.filter(h => h.escape && 'reason' in h.escape); + const summary = 'TIMING_ASSERTIONS: found=' + open.length + ' escaped=' + escaped.length + ' files=' + added.size; + for (const h of escaped) ctx.explain.push('timing: ' + h.file + ':' + h.line + ' ' + h.pattern + ' escaped: ' + (h.escape as { reason: string }).reason); + if (!open.length) return { id: 'timing', stage: 'preflight', status: 'pass', inputs, lines: escaped.length ? [summary] : undefined, detail: 'no timing assertion in the added lines of ' + added.size + ' test file(s)' + (escaped.length ? ' (' + escaped.length + ' escaped with gstack-timing-ok)' : '') }; + const counts = (['wall-time-bound', 'cpu-time-bound', 'sleep-then-assert'] as const).map(p => [p, open.filter(h => h.pattern === p).length] as const).filter(([, c]) => c > 0); + return { + id: 'timing', stage: 'preflight', status: 'warn', inputs, code: 'PREGATE_TIMING_ASSERTION', + lines: [...open.map(h => 'TIMING_ASSERTION: ' + h.file + ':' + h.line + ' ' + h.pattern + (h.escape ? ' (gstack-timing-ok needs a reason)' : '')), summary], + detail: open.length + ' timing-dependent assertion(s) in added test lines (' + counts.map(([p, c]) => c + ' ' + p).join(', ') + ')' + (escaped.length ? '; ' + escaped.length + ' escaped' : ''), + fix: 'assert on the outcome, an injected clock or a forced deadline instead of elapsed time or a fixed sleep; when the bound is the contract, add gstack-timing-ok: in a comment on the line or the line above (docs/pregate.md#timing)', + }; +} + +export const timingCheck: CheckDef = { id: 'timing', stage: 'preflight', tier: 1, downgradable: true, needsRepoCommands: false, run }; diff --git a/lib/pregate/index.ts b/lib/pregate/index.ts index 76b5f7d73..de053c8fe 100644 --- a/lib/pregate/index.ts +++ b/lib/pregate/index.ts @@ -21,11 +21,12 @@ import { literalsCheck } from './checks/literals'; import { regenCheck } from './checks/regen'; import { secretsCheck } from './checks/secrets'; import { straysCheck } from './checks/strays'; +import { timingCheck } from './checks/timing'; import { NON_DOWNGRADABLE } from './config'; import { withFingerprint } from './context'; import type { CheckDef, CheckResult, PregateContext, Stage } from './types'; -export const CHECKS: readonly CheckDef[] = [regenCheck, secretsCheck, straysCheck, literalsCheck, guardsCheck, lanesCheck]; +export const CHECKS: readonly CheckDef[] = [regenCheck, secretsCheck, straysCheck, literalsCheck, timingCheck, guardsCheck, lanesCheck]; export const CHECK_IDS = CHECKS.map(c => c.id); export const PREGATE_OUT_REL = '.gstack/tmp/pregate.json'; export const PREGATE_TIER2 = ['ratchets', 'lint', 'links', 'hermetic', 'patches', 'integrator'] as const; diff --git a/lib/result-codes.ts b/lib/result-codes.ts index 060d9b4cf..87a203f32 100644 --- a/lib/result-codes.ts +++ b/lib/result-codes.ts @@ -730,6 +730,12 @@ export const RESULT_CODES = { summary: 'the gate-ahead attempt is unknown, already recorded, or its worktree no longer holds the gated commit', fix: 'list attempts with gstack-ship-queue gate-ahead --list, then record the live one, or prepare a new attempt', }, + // Field list 2 W4 (pregate `timing`). + PREGATE_TIMING_ASSERTION: { + anchor: 'pregate-timing-assertion', + summary: 'an added or changed test line compares an elapsed wall-clock or CPU time against a bound, or sleeps and then asserts (a warning, not a block)', + fix: 'assert on the outcome, an injected clock or a forced deadline instead; when the bound is the contract, add `gstack-timing-ok: ` in a comment on the line or the line above', + }, } as const satisfies Record; export type ResultCodeName = keyof typeof RESULT_CODES; diff --git a/review/checklist.md b/review/checklist.md index ca5bd7934..9a332ff48 100644 --- a/review/checklist.md +++ b/review/checklist.md @@ -110,6 +110,10 @@ A gate is anything that would have made this change fail: a test, an assertion, - Date-key lookups that assume "today" covers 24h — report at 8am PT only sees midnight→8am under today's key - Mismatched time windows between related features — one uses hourly buckets, another uses daily keys for the same data +#### Timing-Dependent Tests +- An added or changed test line that compares an elapsed wall-clock or CPU time with a bound (`expect(Date.now() - t0).toBeLessThan(400)`, `assert elapsed < 0.5`) or sleeps a fixed time and then asserts, with no `gstack-timing-ok: ` comment on the line or the line above. `gstack-pregate` prints these as `TIMING_ASSERTION: : `; suggest asserting on the outcome, an injected clock, a forced deadline or a poll with a deadline +- A diff that raises an existing timing bound or adds a retry to make a flake pass: the bound is not the cause; route it to /investigate's flake recipe (timing flakes) + #### Type Coercion at Boundaries - Values crossing Ruby→JSON→JS boundaries where type could change (numeric vs string) — hash/digest inputs must normalize types - Hash/digest inputs that don't call `.to_s` or equivalent before serialization — `{ cores: 8 }` vs `{ cores: "8" }` produce different hashes diff --git a/test/fixtures/module-size-ratchet.json b/test/fixtures/module-size-ratchet.json index 060ada325..a9af432d2 100644 --- a/test/fixtures/module-size-ratchet.json +++ b/test/fixtures/module-size-ratchet.json @@ -109,6 +109,7 @@ { "file": "lib/pregate/checks/literals.ts", "movedFrom": "(new: pre-gate check, C8)" }, { "file": "lib/pregate/checks/lanes.ts", "movedFrom": "(new: pre-gate check with the pipefail runner and requires-remote obligations, C8)" }, { "file": "lib/pregate/checks/guards.ts", "movedFrom": "(new: pre-gate repo guards, field wave CD1)" }, + { "file": "lib/pregate/checks/timing.ts", "movedFrom": "(new: pre-gate timing-assertion check, field list 2 W4)" }, { "file": "lib/pregate/runtime.ts", "movedFrom": "(new: the verified launch Bun for repo commands, field wave CD1)" }, { "file": "lib/sealed-guard.ts", "movedFrom": "(new: the sealed-output guard shared by the pre-push hook and gstack-pregate sealed, field wave CD4)" }, { "file": "lib/pregate/regate.ts", "movedFrom": "(new: the regate verdict from a fresh tree receipt plus migration collisions, field wave CD3)" }, diff --git a/test/fixtures/pregate-timing/flaky.test.ts.txt b/test/fixtures/pregate-timing/flaky.test.ts.txt new file mode 100644 index 000000000..4be659a10 --- /dev/null +++ b/test/fixtures/pregate-timing/flaky.test.ts.txt @@ -0,0 +1,62 @@ +import { expect, test } from 'bun:test'; +import { cpuMs } from './helpers/cpu'; + +test('wall-clock bounds', async () => { + const t0 = Date.now(); + run(); + expect(Date.now() - t0).toBeLessThan(400); // HIT wall-time-bound + const started = performance.now(); + const elapsed = performance.now() - started; + expect(elapsed).toBeLessThan(500); // HIT wall-time-bound + expect(result.elapsedMs).toBeLessThanOrEqual(2_000); // HIT wall-time-bound + expect(r.wall).toBeGreaterThan(1500); // HIT wall-time-bound + assert.ok(Date.now() - t0 < 1000); // HIT wall-time-bound + expect(input.deadlineAt - Date.now()).toBeLessThanOrEqual(1_500_000); // HIT wall-time-bound +}); + +test('CPU-time bounds', () => { + const ms = cpuMs(() => parse(input)); + expect(ms).toBeLessThan(150); // HIT cpu-time-bound + expect(cpuMs(() => parse(input))).toBeLessThan(1000); // HIT cpu-time-bound + const usage = process.cpuUsage(); + expect(process.cpuUsage(usage).user / 1000).toBeLessThan(200); // HIT cpu-time-bound +}); + +test('sleep then assert', async () => { + fire(); + await Bun.sleep(50); // HIT sleep-then-assert + expect(calls).toBe(1); + await new Promise((r) => setTimeout(r, 100)); // HIT sleep-then-assert + + expect(seen).toEqual(['a']); +}); + +test('not timing-dependent', async () => { + expect(result.elapsedMs).toBeGreaterThanOrEqual(0); // CLEAN + expect(entity.ttl_ms).toBeGreaterThan(1000); // CLEAN + expect(opts.timeoutMs).toBeLessThanOrEqual(60_000); // CLEAN + expect(CAPTURE_LONG_MS + 10_000).toBeLessThan(DEFAULT_SHARD_TIMEOUT_MS); // CLEAN + expect(lease.expiresAt).toBeGreaterThan(Date.now()); // CLEAN + expect(stats.reportMtimeMs).toBeLessThan(later); // CLEAN + expect(kept.length).toBeLessThan(items.length); // CLEAN + for (let i = 0; i < 4; i++) expect(step(i)).toBe('question'); // CLEAN + const log = path.join(dir, `run-${Date.now()}.log`); + expect(log.length).toBeGreaterThan(10); // CLEAN + expect(spawn(['bash', '-c', 'sleep 2; echo --timeout-ms 600']).status).toBe(0); // CLEAN + while (!fs.existsSync(ready) && Date.now() < deadline) await Bun.sleep(10); // CLEAN + expect(fs.existsSync(ready)).toBe(true); + await new Promise((r) => setTimeout(r, 0)); // CLEAN + expect(flushed).toBe(true); + const src = text.indexOf('await Bun.sleep(100)'); // CLEAN + expect(src).toBeGreaterThan(-1); +}); + +test('escapes', async () => { + // gstack-timing-ok: the 30 s cap is the product contract, measured at 2 s p99 under full suite load + expect(Date.now() - t0).toBeLessThan(30_000); // ESCAPED wall-time-bound + expect(Date.now() - t0).toBeLessThan(5_000); /* gstack-timing-ok: a hang check; the call returns in 40 ms */ // ESCAPED wall-time-bound + // gstack-timing-ok: + expect(Date.now() - t0).toBeLessThan(5_000); // UNREASONED wall-time-bound + await Bun.sleep(1100); // gstack-timing-ok: the mtime resolution is one second; the assert reads the file, not a race // ESCAPED sleep-then-assert + expect(stat.mtimeMs).not.toBe(before); +}); diff --git a/test/fixtures/pregate-timing/test_flaky.py.txt b/test/fixtures/pregate-timing/test_flaky.py.txt new file mode 100644 index 000000000..4e5fb8f5f --- /dev/null +++ b/test/fixtures/pregate-timing/test_flaky.py.txt @@ -0,0 +1,25 @@ +import time + +def test_wall_bound(): + t0 = time.monotonic() + run() + elapsed = time.monotonic() - t0 + assert elapsed < 0.5 # HIT wall-time-bound + +def test_cpu_bound(): + c0 = time.process_time() + run() + assert time.process_time() - c0 < 0.2 # HIT cpu-time-bound + +def test_sleep_then_assert(): + fire() + time.sleep(0.1) # HIT sleep-then-assert + assert calls == 1 + +def test_escaped(): + t0 = time.monotonic() + # gstack-timing-ok: the watchdog contract is two seconds and the call is a no-op + assert time.monotonic() - t0 < 2 # ESCAPED wall-time-bound + +def test_clean(): + assert len(rows) < 10 # CLEAN diff --git a/test/pregate-selection.test.ts b/test/pregate-selection.test.ts index 764076ace..8df3c62e8 100644 --- a/test/pregate-selection.test.ts +++ b/test/pregate-selection.test.ts @@ -98,7 +98,7 @@ describe('gstack-pregate (bin)', () => { const repo = fixture(); const help = runBin(repo, 'gstack-pregate', ['--help']); expect(help.out).toContain('Exit codes: 0 ok · 1 fail · 2 usage · 3 refused or needs a flag'); - expect(help.out).toContain('stage 1 mechanical preflight (regen, secrets, strays, literals, guards)'); + expect(help.out).toContain('stage 1 mechanical preflight (regen, secrets, strays, literals, timing, guards)'); expect(help.out).toContain('stage 2 test execution (lanes)'); expect(runBin(repo, 'gstack-pregate', ['bogus']).status).toBe(EXIT.usage); expect(pregate(repo, ['--only', 'hermetic']).status).toBe(EXIT.usage); @@ -122,7 +122,7 @@ describe('gstack-pregate (bin)', () => { const out = readOut(repo); expect(out.schema_version).toBe(1); expect(out.tree).toMatch(/^[0-9a-f]{40}$/); - expect(out.checks.map((c: any) => [c.id, c.status, c.stage])).toEqual([['regen', 'pass', 'preflight'], ['secrets', 'pass', 'preflight'], ['strays', 'pass', 'preflight'], ['literals', 'pass', 'preflight'], ['guards', 'pass', 'preflight'], ['lanes', 'pass', 'tests']]); + expect(out.checks.map((c: any) => [c.id, c.status, c.stage])).toEqual([['regen', 'pass', 'preflight'], ['secrets', 'pass', 'preflight'], ['strays', 'pass', 'preflight'], ['literals', 'pass', 'preflight'], ['timing', 'pass', 'preflight'], ['guards', 'pass', 'preflight'], ['lanes', 'pass', 'tests']]); for (const c of out.checks) { expect(c.inputs.tree).toBe(out.tree); expect(typeof c.ms).toBe('number'); } expect(check(repo, 'lanes').inputs.command).toMatch(/^[0-9a-f]{64}$/); expect(out.verdict).toBe('pass'); diff --git a/test/pregate-timing.test.ts b/test/pregate-timing.test.ts new file mode 100644 index 000000000..b791f08a6 --- /dev/null +++ b/test/pregate-timing.test.ts @@ -0,0 +1,118 @@ +/** + * pregate check `timing` (field list 2 W4): added or changed test lines + * that compare an elapsed wall-clock or CPU time against a bound, or sleep + * and then assert, print TIMING_ASSERTION lines and warn; a + * `gstack-timing-ok: ` comment on the line or the line above + * escapes one. The fixture sources mark each line HIT, CLEAN, ESCAPED or + * UNREASONED with the expected pattern; they are .txt so this repo's own + * pregate never reads them as tests. + */ +import { afterEach, describe, expect, test } from 'bun:test'; +import * as fs from 'node:fs'; +import * as path from 'node:path'; +import { EXIT } from '../lib/headless-artifacts'; +import { scanTiming, scansTiming, type TimingHit } from '../lib/pregate/checks/timing'; +import { CHECK_IDS } from '../lib/pregate/index'; +import { validateConfig } from '../lib/pregate/config'; +import { BASE_PREGATE, cleanup, commit, makeFixtureRepo, runBin, write, type FixtureRepo } from './helpers/pregate-fixture'; + +const FIXTURES = path.join(import.meta.dir, 'fixtures', 'pregate-timing'); +const read = (name: string) => fs.readFileSync(path.join(FIXTURES, name), 'utf8'); + +/** Expected outcomes from the fixture's own markers: line → [marker, pattern]. */ +function markers(text: string): Map { + const out = new Map(); + text.split('\n').forEach((l, i) => { const m = /(?:\/\/|#) (HIT|CLEAN|ESCAPED|UNREASONED)(?: ([a-z-]+))?\s*$/.exec(l); if (m) out.set(i + 1, [m[1]!, m[2]]); }); + return out; +} + +function outcome(h: TimingHit | undefined): string { + if (!h) return 'CLEAN'; + if (!h.escape) return 'HIT ' + h.pattern; + return ('reason' in h.escape ? 'ESCAPED ' : 'UNREASONED ') + h.pattern; +} + +describe('timing detector over marked fixtures', () => { + for (const [file, as] of [['flaky.test.ts.txt', 'test/flaky.test.ts'], ['test_flaky.py.txt', 'tests/test_flaky.py']] as const) { + test(`${file}: every marked line gets its marked outcome and no unmarked line is flagged`, () => { + const text = read(file); + const hits = scanTiming(as, text, 'all'); + const byLine = new Map(hits.map(h => [h.line, h])); + const expected = markers(text); + expect(expected.size).toBeGreaterThanOrEqual(5); + for (const [line, [marker, pattern]] of expected) expect(`${line}: ${outcome(byLine.get(line))}`).toBe(`${line}: ${pattern ? `${marker} ${pattern}` : marker}`); + expect(hits.filter(h => !expected.has(h.line)).map(h => `${h.line} ${h.pattern}`)).toEqual([]); + }); + } + + test('only added lines count: an unchanged bound is not reported, a changed one is', () => { + const text = read('flaky.test.ts.txt'); + const line = text.split('\n').findIndex(l => l.includes('toBeLessThan(400)')) + 1; + expect(scanTiming('test/flaky.test.ts', text, new Set([1, 2, 3]))).toEqual([]); + expect(scanTiming('test/flaky.test.ts', text, new Set([line])).map(h => [h.line, h.pattern])).toEqual([[line, 'wall-time-bound']]); + }); + + test('a sleep-then-assert pair is reported when only its assertion changed', () => { + const text = read('flaky.test.ts.txt'); + const lines = text.split('\n'); + const sleep = lines.findIndex(l => l.includes('await Bun.sleep(50)')) + 1; + expect(scanTiming('test/flaky.test.ts', text, new Set([sleep + 1])).map(h => [h.line, h.pattern])).toEqual([[sleep, 'sleep-then-assert']]); + }); + + test('scope: test code only, never fixtures or product code', () => { + expect(scansTiming('test/x.test.ts')).toBe(true); + expect(scansTiming('test/helpers/poll.ts')).toBe(true); + expect(scansTiming('tests/test_x.py')).toBe(true); + expect(scansTiming('src/x.spec.js')).toBe(true); + expect(scansTiming('lib/retry.ts')).toBe(false); + expect(scansTiming('test/fixtures/pregate-timing/flaky.test.ts.txt')).toBe(false); + expect(scansTiming('test/fixtures/sample.test.ts')).toBe(false); + expect(scansTiming('docs/timing.md')).toBe(false); + }); +}); + +const repos: FixtureRepo[] = []; +afterEach(() => { while (repos.length) cleanup(repos.pop()!); }); +const pregate = (repo: FixtureRepo, args: string[]) => runBin(repo, 'gstack-pregate', ['--base', 'main', '--stage', 'preflight', '--only', 'timing', ...args]); + +describe('gstack-pregate --only timing (real subprocess, fixture repo)', () => { + test('a branch adding a wall-clock bound warns with TIMING_ASSERTION file:line and still exits ok; the escape clears it', () => { + const repo = makeFixtureRepo(); repos.push(repo); + const body = "const test = require('node:test');\nconst assert = require('node:assert');\ntest('fast', () => {\n const t0 = Date.now();\n require('../lib/util.js').add(1, 2);\n assert.ok(Date.now() - t0 < 400);\n});\n"; + commit(repo, { 'test/speed.test.js': body }); + const r = pregate(repo, []); + expect(r.status).toBe(EXIT.ok); + expect(r.out).toMatch(/^preflight {2}timing {4}warn .*1 timing-dependent assertion\(s\) in added test lines \(1 wall-time-bound\) \(PREGATE_TIMING_ASSERTION\)/m); + expect(r.out).toContain('timing: TIMING_ASSERTION: test/speed.test.js:6 wall-time-bound'); + expect(r.out).toContain('timing: TIMING_ASSERTIONS: found=1 escaped=0 files=1'); + expect(r.out).toMatch(/^PREGATE: warn /m); + commit(repo, { 'test/speed.test.js': body.replace(' assert.ok(', ' // gstack-timing-ok: a hang check with 100x headroom\n assert.ok(') }); + const ok = pregate(repo, ['--explain']); + expect(ok.status).toBe(EXIT.ok); + expect(ok.out).toMatch(/^preflight {2}timing {4}pass .*1 escaped with gstack-timing-ok/m); + expect(ok.out + ok.err).toContain('timing: test/speed.test.js:7 wall-time-bound escaped: a hang check with 100x headroom'); + }); + + test('an escape without a reason is still reported, and an untouched existing bound is not', () => { + const repo = makeFixtureRepo(); repos.push(repo); + repo.git('checkout', '-q', 'main'); + write(repo.work, 'test/old.test.js', "const assert = require('node:assert');\nconst t0 = Date.now();\nassert.ok(Date.now() - t0 < 400);\n"); + repo.git('add', '-A'); repo.git('commit', '-q', '-m', 'old bound'); repo.git('push', '-q', 'origin', 'main'); + repo.git('checkout', '-q', 'feature'); repo.git('merge', '-q', '--ff-only', 'main'); + commit(repo, { 'test/old.test.js': "const assert = require('node:assert');\nconst t0 = Date.now();\nassert.ok(Date.now() - t0 < 400);\nassert.ok(true);\n", 'test/new.test.js': "const t0 = Date.now();\n// gstack-timing-ok:\nexpect(Date.now() - t0).toBeLessThan(400);\n" }); + const r = pregate(repo, []); + expect(r.out).toContain('timing: TIMING_ASSERTION: test/new.test.js:3 wall-time-bound (gstack-timing-ok needs a reason)'); + expect(r.out).not.toContain('test/old.test.js:3'); + expect(r.out).toContain('TIMING_ASSERTIONS: found=1 escaped=0 files=2'); + }); + + test('a docs-only branch passes and timing is a known, downgradable check id', () => { + const repo = makeFixtureRepo(); repos.push(repo); + commit(repo, { 'docs/README.md': '# docs\nmore\n' }); + const r = pregate(repo, []); + expect(r.status).toBe(EXIT.ok); + expect(r.out).toMatch(/^preflight {2}timing {4}pass .*no timing assertion in the added lines of 0 test file\(s\)/m); + expect(CHECK_IDS).toContain('timing'); + expect(validateConfig({ ...BASE_PREGATE, warn: ['timing'] }, CHECK_IDS)).toEqual([]); + }); +});