From 7705439e42249c432aec8630359b144374d287aa Mon Sep 17 00:00:00 2001 From: PEDRO LOBATO CARCAMO Date: Thu, 10 Sep 2026 19:46:22 -0600 Subject: [PATCH] Run each test file in its own process: the parent runner drops file tails under CI load MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit CI (ubuntu-latest, 2 vCPU) reported 1035 of 1074 tests with fail 0 and exit 0 on 3 of 3 attempts for a tree that is whole (main after #167), each attempt missing the tail of different files. The same tree reports 1074 locally and on an idle 4-core VPS, and that VPS reproduces the drop (1069) as soon as CPU load is added. The loss is `node --test`'s parent runner losing the end of a child's piped output on --test-force-exit; it is load-dependent, and CI is always loaded, so the gate's retries could never save it. tools/test-gate.js: stop using the parent runner. Every file runs as `node --test --test-isolation=none --test-force-exit `, its stdout is read to EOF before anything is counted, and the per-file summaries are summed (sumSummaries: a file with no summary voids the attempt as NO_SUMMARY, it is never subtracted quietly). Bounded pool (TEST_GATE_CONCURRENCY, default min(4, cores - 1)); one watchdog covers the whole attempt. --test-force-exit stays: 26 files never exit without it. .github/workflows/ci.yml: 300 s per attempt, 2 attempts (measured: ~10 s local, 77 s on the 4-core VPS at concurrency 1). tests/tool-prompt.test.js (P14): threshold 400 -> 1500 ms. Measured 50 ms on a Mac, 210-225 ms on the VPS idle, 445 ms under load; the quadratic regression it guards was ~2 s, so 1500 still catches it and stops flaking on a shared runner. tests/test-count-gate.test.js: three tests for sumSummaries. Baseline 1074 -> 1077. Verified: gate PASS 1077/128 locally; on the VPS under six CPU hogs, single attempt, 2 of 3 runs PASS 1074 and the third failed loudly on P14 — never a short pass. --- .github/workflows/ci.yml | 17 ++-- tests/expected-counts.json | 2 +- tests/test-count-gate.test.js | 27 ++++++- tests/tool-prompt.test.js | 6 +- tools/test-gate.js | 141 ++++++++++++++++++++++++++-------- 5 files changed, 153 insertions(+), 40 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 26f3a17..786a2fb 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -18,7 +18,7 @@ jobs: test: runs-on: ubuntu-latest # Must exceed the gate's own worst case (TEST_GATE_TIMEOUT_MS x - # TEST_GATE_ATTEMPTS, pinned below to 3 x 150s = 7.5 min) plus npm ci and + # TEST_GATE_ATTEMPTS, pinned below to 2 x 300s = 10 min) plus npm ci and # lint. With the old 10 here and the gate's 10-minute default watchdog, the # job died at 10 min and the watchdog — the thing that makes the gate unable # to hang — could never fire. @@ -39,8 +39,13 @@ jobs: # unset, killing the five suites that load controllers. The value # itself is never read by any test. API_KEY: ci-test-key - # The whole suite runs in ~5s locally. 150s per attempt is ~30x - # headroom for a cold shared runner, and 3 attempts still fit inside - # timeout-minutes above, so a hung runner is reported by the gate as - # TIMEOUT instead of looking like CI infrastructure flake. - TEST_GATE_TIMEOUT_MS: 150000 + # The gate runs one node process per test file (the parent runner + # dropped file tails on this loaded 2-vCPU box: 1035 of 1074 on 3 of + # 3 attempts, 2026-09-11). Measured: ~10s locally, 77s on an idle + # 4-core VPS at concurrency 1. 300s per attempt is ~4x that, and 2 + # attempts still fit inside timeout-minutes above, so a hung process + # is reported by the gate as TIMEOUT instead of looking like CI + # infrastructure flake. A short attempt is no longer expected at all; + # the second attempt is a safety net, not the mechanism. + TEST_GATE_TIMEOUT_MS: 300000 + TEST_GATE_ATTEMPTS: 2 diff --git a/tests/expected-counts.json b/tests/expected-counts.json index 238293d..bddd907 100644 --- a/tests/expected-counts.json +++ b/tests/expected-counts.json @@ -1,5 +1,5 @@ { - "tests": 1074, + "tests": 1077, "suites": 128, "note": "Authoritative count. Verify with the per-file sum in AGENTS.md (\"The test gate\"). The -a on that grep is load-bearing: tool-prompt.test.js emits bytes that make grep call the stream binary, and without -a its whole summary line — 133 tests — is silently dropped from the sum.", "updated": "2026-09-11" diff --git a/tests/test-count-gate.test.js b/tests/test-count-gate.test.js index 8b80ee0..77307f6 100644 --- a/tests/test-count-gate.test.js +++ b/tests/test-count-gate.test.js @@ -1,7 +1,7 @@ const { test } = require('node:test') const assert = require('node:assert/strict') -const { parseSummary, evaluate, formatVerdict, computeBlessed, PER_FILE_SUM } = require('../tools/test-gate.js') +const { parseSummary, sumSummaries, evaluate, formatVerdict, computeBlessed, PER_FILE_SUM } = require('../tools/test-gate.js') const SPEC_TAIL = [ '✔ some passing test (1.2ms)', @@ -290,3 +290,28 @@ test('DEFECT 4: the per-file sum the gate hands you keeps grep -a', () => { assert.match(PER_FILE_SUM, /--test-force-exit/) assert.match(PER_FILE_SUM, /s\+=\$3/, 'it must still sum the third column') }) + +/* ---------------------------------------------------- per-file sum (2026-09-11) -- */ +// The gate no longer goes through node's parent runner (it dropped file tails +// under CI load: 1035 of 1074, fail 0, exit 0). One process per file, summed. + +const fileSummary = (tests, suites, fail = 0) => + parseSummary(`ℹ tests ${tests}\nℹ suites ${suites}\nℹ pass ${tests - fail}\nℹ fail ${fail}\nℹ cancelled 0\nℹ skipped 0\nℹ todo 0\n`) + +test('sumSummaries adds one summary per file, key by key', () => { + assert.deepEqual(sumSummaries([fileSummary(3, 1), fileSummary(5, 2, 1)]), + { tests: 8, suites: 3, pass: 7, fail: 1, cancelled: 0, skipped: 0, todo: 0 }) +}) + +test('sumSummaries: a file with no summary voids the attempt — it is never subtracted quietly', () => { + assert.equal(sumSummaries([fileSummary(3, 1), null]), null) + assert.equal(sumSummaries([]), null) +}) + +test('a dead file in a per-file attempt fails the gate as NO_SUMMARY, not as a shorter pass', () => { + const summary = sumSummaries([fileSummary(3, 1), null]) + const v = evaluate({ summary, exitCode: 0, expected: { tests: 3, suites: 1 } }) + assert.equal(v.ok, false) + assert.equal(v.reason, 'NO_SUMMARY') + assert.equal(v.retryable, false) +}) diff --git a/tests/tool-prompt.test.js b/tests/tool-prompt.test.js index 7d0dcf8..695fef0 100644 --- a/tests/tool-prompt.test.js +++ b/tests/tool-prompt.test.js @@ -2450,7 +2450,11 @@ test('loop 2 (P14): 8000 llaves de inicio de linea sin "name" en ~127 KB no son assert.equal(whole.toolCalls.length, 0) assert.equal(streamed.calls.length, 0) assert.equal(whole.cleanedText, text) - assert.ok(elapsed < 400, `8000 llaves de inicio de linea tardaron ${elapsed} ms (era ~2 s)`) + // Umbral medido, no adivinado (2026-09-11): 50 ms en un M-series, 210-225 ms en un + // VPS de 4 cores sin carga, 445 ms con 6 hogs de CPU. La regresion cuadratica que + // guarda era ~2 s aqui (~8 s en ese VPS): 1500 ms la sigue cazando de sobra y deja + // de parpadear en un runner de CI compartido, donde 400 era ~2x el tiempo idle. + assert.ok(elapsed < 1500, `8000 llaves de inicio de linea tardaron ${elapsed} ms (era ~2 s)`) }) test('loop 2 (P15): cada reparacion del salvage es punto fijo de su propio producto, y el producto solo se acepta si parsea ESTRICTO', () => { diff --git a/tools/test-gate.js b/tools/test-gate.js index 3050923..b47e376 100644 --- a/tools/test-gate.js +++ b/tools/test-gate.js @@ -25,14 +25,26 @@ * reached through `src/utils/chat-helpers.js`, keep the loop alive), so the run * hangs forever instead of finishing short. * - * So instead: run the suite, then check the reported counts against a committed - * baseline. A run that comes back short is retried — the loss is a race, so a - * genuinely deleted test is short on EVERY attempt while a truncated one is not - * — and if it is still short, the gate exits non-zero and says so loudly. + * So the gate does not use the parent runner at all. Every test file runs in + * its own node process with `--test-isolation=none` (the tests execute in that + * very process — there is no runner child underneath whose pipe could be cut) + * plus `--test-force-exit`; the gate reads each process's stdout to EOF before + * it counts anything, and the per-file summaries are summed. That sum is then + * checked against a committed baseline: short is a failure, never a pass. A + * short attempt is still retried — a genuinely deleted test is short on EVERY + * attempt while a flake is not — and if it stays short the gate exits non-zero + * and says so loudly. + * + * Why the parent runner had to go (2026-09-11): on GitHub's 2-vCPU runner it + * came back short on 3 of 3 attempts for a tree that was whole (1035 of 1074, + * fail 0, exit 0), each time missing the TAIL of different files. Reproduced + * on a 4-core VPS by adding CPU load (1069, then 1074 on the retry). The loss + * is load-dependent, and CI is always loaded. */ const { spawn } = require('node:child_process') const fs = require('node:fs') +const os = require('node:os') const path = require('node:path') const ROOT = path.resolve(__dirname, '..') @@ -41,12 +53,12 @@ const BASELINE_FILE = path.join(TESTS_DIR, 'expected-counts.json') const SUMMARY_KEYS = ['tests', 'suites', 'pass', 'fail', 'cancelled', 'skipped', 'todo'] -// The independent check on this gate: it never goes through the parent runner, -// so the truncation race cannot touch it. `-a` is load-bearing — some test files -// emit bytes that make grep declare the stream binary and suppress the summary -// line, silently subtracting that whole file from the sum. +// The manual cross-check: the same per-file sum the gate computes, in shell. +// `-a` is load-bearing — some test files emit bytes that make grep declare the +// stream binary and suppress the summary line, silently subtracting that whole +// file from the sum. const PER_FILE_SUM = - 'for f in tests/*.test.js; do node --test --test-force-exit "$f"; done | ' + + 'for f in tests/*.test.js; do node --test --test-isolation=none --test-force-exit "$f"; done | ' + 'grep -aE \'^. tests [0-9]+$\' | awk \'{s+=$3}END{print s}\'' // Matches both reporters: spec ("ℹ tests 972") and tap ("# tests 972"). @@ -75,7 +87,24 @@ function parseSummary (output) { return found } -const verdict = (ok, reason, code, retryable, message, summary) => +/** + * Add up one summary per test file. A single file without a summary makes the + * whole attempt count for nothing (null → NO_SUMMARY): a file whose process + * died before reporting must never be silently subtracted from the total. + * @param {(ReturnType)[]} summaries + */ +function sumSummaries (summaries) { + if (!Array.isArray(summaries) || summaries.length === 0) return null + const total = {} + for (const key of SUMMARY_KEYS) total[key] = 0 + for (const s of summaries) { + if (!s) return null + for (const key of SUMMARY_KEYS) total[key] += s[key] + } + return total +} + +const verdict =(ok, reason, code, retryable, message, summary) => ({ ok, reason, code, retryable, message, summary: summary || null }) /** @@ -183,29 +212,80 @@ function readBaseline () { return null } +/** + * One attempt over `files`. Each file gets its own node process + * (`--test --test-isolation=none --test-force-exit `): the tests run in + * that process itself, so there is no runner-to-child pipe to lose data on. + * The gate buffers each process's stdout+stderr until 'close' — which fires + * only after BOTH pipes have ended — and only then parses its summary. A + * bounded pool keeps the box from thrashing; one watchdog covers the whole + * attempt and, on expiry, kills whatever is still running and reports TIMEOUT. + * + * @returns {Promise<{output:string,exitCode:number|null,timedOut:boolean,summary:ReturnType}>} + * `exitCode` is 0 only if every file's process exited 0; `summary` is the + * per-file sum, or null if any file produced none. + */ function runOnce (files, watchdogMs) { return new Promise((resolve) => { - const child = spawn(process.execPath, - ['--test', '--test-force-exit', ...files], - { cwd: ROOT, stdio: ['ignore', 'pipe', 'pipe'] }) + if (files.length === 0) { + resolve({ output: '', exitCode: 0, timedOut: false, summary: null }) + return + } + const concurrency = Math.max(1, Number(process.env.TEST_GATE_CONCURRENCY) || + Math.min(4, os.availableParallelism() - 1)) - let output = '' + const results = [] + const running = new Set() + let next = 0 let timedOut = false - const capture = (chunk) => { output += chunk; process.stdout.write(chunk) } - child.stdout.setEncoding('utf8'); child.stdout.on('data', capture) - child.stderr.setEncoding('utf8'); child.stderr.on('data', capture) + let output = '' - // Nothing here may hang: if the runner stops making progress we kill it and - // report a TIMEOUT, which is a failure, never a pass. + // Nothing here may hang: if the attempt stops making progress we kill what + // is left and report a TIMEOUT, which is a failure, never a pass. const timer = setTimeout(() => { timedOut = true - child.kill('SIGKILL') + for (const child of running) child.kill('SIGKILL') }, watchdogMs) - child.on('close', (code) => { + const finish = () => { clearTimeout(timer) - resolve({ output, exitCode: timedOut ? null : code, timedOut }) - }) + const badExit = results.find((r) => r.exitCode !== 0) + resolve({ + output, + exitCode: timedOut ? null : (badExit ? badExit.exitCode : 0), + timedOut, + summary: sumSummaries(results.map((r) => r.summary)) + }) + } + + const launch = () => { + while (!timedOut && running.size < concurrency && next < files.length) { + const file = files[next++] + const child = spawn(process.execPath, + ['--test', '--test-isolation=none', '--test-force-exit', file], + { cwd: ROOT, stdio: ['ignore', 'pipe', 'pipe'] }) + running.add(child) + + let buf = '' + const capture = (chunk) => { buf += chunk } + child.stdout.setEncoding('utf8'); child.stdout.on('data', capture) + child.stderr.setEncoding('utf8'); child.stderr.on('data', capture) + + child.on('close', (code) => { + running.delete(child) + const summary = parseSummary(buf) + process.stdout.write(buf) + output += buf + if (!summary && !timedOut) { + console.error(`[gate] ${file}: no summary block (exit ${code}) — its process ended before reporting`) + } + results.push({ file, exitCode: code, summary }) + if (running.size === 0 && (timedOut || next >= files.length)) finish() + else launch() + }) + } + } + launch() }) } @@ -220,8 +300,7 @@ async function main () { // won and the whole suite ran anyway. Here the filter is honoured, and the // count gate is skipped because a partial run cannot meet a whole-suite count. if (filters.length > 0) { - const { output, exitCode, timedOut } = await runOnce(filters, watchdogMs) - const summary = parseSummary(output) + const { summary, exitCode, timedOut } = await runOnce(filters, watchdogMs) if (timedOut) { console.error(formatVerdict(evaluate({ summary, exitCode, expected: { tests: 0, suites: 0 }, timedOut }))); process.exit(4) } console.error(`${BAR}\nTEST GATE: SKIPPED — filtered run of ${filters.length} file(s); ` + 'the whole-suite count gate does not apply. Run `npm test` with no arguments before claiming a green suite.\n' + @@ -246,8 +325,7 @@ async function main () { let last = null for (let attempt = 1; attempt <= attemptsAllowed; attempt++) { - const { output, exitCode, timedOut } = await runOnce(files, watchdogMs) - const summary = parseSummary(output) + const { summary, exitCode, timedOut } = await runOnce(files, watchdogMs) if (bless) { const health = evaluate({ summary, exitCode, expected: NO_BASELINE, timedOut }) @@ -282,8 +360,9 @@ async function main () { if (last.ok) { if (attempt > 1) { console.error(`${BAR}\nNOTE: attempt(s) 1..${attempt - 1} came back SHORT and were retried.\n` + - 'That is node dropping a child\'s buffered stdout on --test-force-exit, not a broken test.\n' + - `This attempt reported the full ${expected.tests}.\n${BAR}`) + 'Each file runs in its own process and is read to EOF, so this is no longer expected:\n' + + 'look at the short attempt(s) above (a "[gate] : no summary" line, or a file that\n' + + `registered fewer tests) before trusting this one. This attempt reported the full ${expected.tests}.\n${BAR}`) } console.error(formatVerdict(last)) process.exit(0) @@ -300,7 +379,7 @@ async function main () { if (last.reason === 'SHORT_RUN' || last.reason === 'SHORT_SUITES') { console.error(`Short on all ${attemptsAllowed} attempts. A truncation flake does not survive that many\n` + 'retries, so treat this as real: a test file threw at load, was deleted, or stopped registering tests.\n' + - 'Confirm with the per-file sum, which does not go through the parent runner:\n' + + 'Confirm by hand with the same per-file sum the gate computes:\n' + ` ${PER_FILE_SUM}\n` + 'Keep the -a: without it grep calls tool-prompt.test.js\'s output binary and drops its\n' + 'summary line, quietly subtracting 133 tests from the number you are trusting.') @@ -308,7 +387,7 @@ async function main () { process.exit(last.code) } -module.exports = { parseSummary, evaluate, formatVerdict, computeBlessed, PER_FILE_SUM } +module.exports = { parseSummary, sumSummaries, evaluate, formatVerdict, computeBlessed, PER_FILE_SUM } if (require.main === module) { main().catch((err) => {