Skip to content
31 changes: 31 additions & 0 deletions bin/__deep-probe-mock.cjs
Original file line number Diff line number Diff line change
@@ -0,0 +1,31 @@
#!/usr/bin/env node
'use strict';
// Test fixture — a fake provider CLI for deep-probe / stall integration tests.
// Behavior is chosen by MOCK_MODE; MOCK_DELAY_MS controls the slow/hang timing.
// probe_ok (default) — print PROBE_OK, exit 0
// quota — print a 429/RESOURCE_EXHAUSTED line to stderr, exit 1
// auth — print a 401 unauthorized line to stderr, exit 1
// slow_ok — print a short preamble, wait MOCK_DELAY_MS, then PROBE_OK, exit 0
// hang — print a short preamble, then never output/exit (until killed)
const mode = process.env.MOCK_MODE || 'probe_ok';
const delay = Number(process.env.MOCK_DELAY_MS || 0);

function main() {
if (mode === 'quota') {
process.stderr.write('RESOURCE_EXHAUSTED (code 429): Individual quota reached. Resets in 32h54m.\n');
process.exit(1);
} else if (mode === 'auth') {
process.stderr.write('HTTP 401 unauthorized: invalid api key\n');
process.exit(1);
} else if (mode === 'hang') {
process.stdout.write('PREAMBLE'.repeat(25)); // ~200-byte preamble, then silence forever
setInterval(() => {}, 1 << 30);
} else if (mode === 'slow_ok') {
process.stdout.write('PREAMBLE'.repeat(25)); // small preamble (<500B), like the real slow slots
setTimeout(() => { process.stdout.write('\nPROBE_OK\n'); process.exit(0); }, delay);
} else {
process.stdout.write('PROBE_OK\n');
process.exit(0);
}
}
main();
45 changes: 45 additions & 0 deletions bin/call-quorum-slot-quota-reset.test.cjs
Original file line number Diff line number Diff line change
@@ -0,0 +1,45 @@
'use strict';

// P4 — parse a provider's quota-reset window from its error text so the cooldown
// matches the real quota (rolling ~33h) instead of the fixed 30-min failure TTL.
// Motivated by antigravity-1 (Google 429 "Resets in 32h54m49s") being re-probed and
// re-failed every 30 min all session.

const { describe, it } = require('node:test');
const assert = require('node:assert/strict');
const { parseQuotaResetMs } = require('./call-quorum-slot.cjs');

const H = 3600000, M = 60000, S = 1000;

describe('parseQuotaResetMs — quota reset-window parser', () => {
it('parses the compact Google form "Resets in 32h54m49s"', () => {
assert.equal(parseQuotaResetMs('RESOURCE_EXHAUSTED (code 429): Resets in 32h54m49s.'),
32 * H + 54 * M + 49 * S);
});

it('parses "resets in 1h30m" and "resets in 45m"', () => {
assert.equal(parseQuotaResetMs('quota reached, resets in 1h30m'), 1 * H + 30 * M);
assert.equal(parseQuotaResetMs('resets in 45m'), 45 * M);
});

it('parses verbose "try again in 30 minutes" / "in 2 hours" / "in 45 seconds"', () => {
assert.equal(parseQuotaResetMs('rate limited, try again in 30 minutes'), 30 * M);
assert.equal(parseQuotaResetMs('quota exceeded; available in 2 hours'), 2 * H);
assert.equal(parseQuotaResetMs('retry in 45 seconds'), 45 * S);
});

it('returns null when no reset window is present', () => {
assert.equal(parseQuotaResetMs('429 Too Many Requests'), null);
assert.equal(parseQuotaResetMs('some unrelated error'), null);
assert.equal(parseQuotaResetMs(''), null);
assert.equal(parseQuotaResetMs(null), null);
});

it('clamps absurd windows to 48h (defends against a malformed "9999h")', () => {
assert.equal(parseQuotaResetMs('resets in 9999h'), 48 * H);
});

it('does not misfire on a bare number without a unit', () => {
assert.equal(parseQuotaResetMs('error 500 on attempt 3'), null);
});
});
90 changes: 73 additions & 17 deletions bin/call-quorum-slot.cjs
Original file line number Diff line number Diff line change
Expand Up @@ -223,6 +223,37 @@ function classifyErrorType(msg) {
return 'UNKNOWN';
}

// ─── P4 — parse a provider's quota-reset window from its error text ──────────
// Quota errors often carry the reset time ("Resets in 32h54m49s", "resets in 30
// minutes", "try again in 3600 seconds"). The default 30-min failure TTL is far
// shorter than a rolling daily quota (~33h), so a quota-dead slot was re-probed and
// re-failed every 30 min. Parsing the real reset lets the cooldown match it exactly.
// Returns milliseconds until reset (clamped to [0, 48h]) or null if not present.
function parseQuotaResetMs(msg) {
if (!msg) return null;
const s = String(msg);
const MAX = 48 * 3600 * 1000;
const clamp = (ms) => (ms > 0 ? Math.min(ms, MAX) : null);
// Compact form: 32h54m49s / 1h30m / 45m / 90s, optionally after "resets in".
let m = s.match(/resets?\s+in\s+((?:\d+\s*[hms]\s*){1,3})/i) || s.match(/\b((?:\d+\s*[hms]\s*){2,3})\b/i);
if (m) {
let ms = 0, mm; const re = /(\d+)\s*([hms])/gi;
while ((mm = re.exec(m[1]))) {
const n = Number(mm[1]); const u = mm[2].toLowerCase();
ms += n * (u === 'h' ? 3600000 : u === 'm' ? 60000 : 1000);
}
const c = clamp(ms); if (c) return c;
}
// Verbose: "resets in 30 minutes" / "try again in 2 hours" / "in 45 seconds".
m = s.match(/(?:resets?|try again|retry|available)\s+(?:in\s+)?(\d+)\s*(hours?|minutes?|seconds?|hrs?|mins?|secs?)\b/i);
if (m) {
const n = Number(m[1]); const u = m[2].toLowerCase();
const mult = u.startsWith('h') ? 3600000 : u.startsWith('m') ? 60000 : 1000;
return clamp(n * mult);
}
return null;
}

function writeFailureLog(slotName, errorMsg, stderrText) {
try {
const pp = require('./planning-paths.cjs');
Expand All @@ -234,22 +265,36 @@ function writeFailureLog(slotName, errorMsg, stderrText) {
const rawPattern = (stderrText && stderrText.length > 0) ? stderrText : errorMsg;
const pattern = rawPattern.replace(/\x1b\[[0-9;]*m/g, '').slice(0, 200);

// P4: for QUOTA failures, parse the provider's reset window so the cooldown matches
// the real quota (rolling ~33h) instead of the 30-min TTL.
const quotaResetMs = error_type === 'QUOTA' ? parseQuotaResetMs(rawPattern) : null;
const cooldownUntil = quotaResetMs ? new Date(Date.now() + quotaResetMs).toISOString() : null;

// Lock-free read-modify-write under an exclusive writer lock so parallel slots
// never lose records (and a torn read never wipes the whole log).
atomicUpdateJson(logPath, (current) => {
let records = Array.isArray(current) ? current : [];

// Garbage-collect stale records (older than 60 minutes) to prevent unbounded growth
const gcCutoff = Date.now() - 60 * 60 * 1000;
records = records.filter(r => new Date(r.last_seen).getTime() > gcCutoff);
// Garbage-collect stale records (older than 60 minutes) to prevent unbounded growth.
// EXCEPT: keep records whose cooldown_until is still in the future (a quota-dead slot
// whose reset is hours away must survive GC, or P4's long cooldown is lost after 60 min).
const now = Date.now();
const gcCutoff = now - 60 * 60 * 1000;
records = records.filter(r =>
new Date(r.last_seen).getTime() > gcCutoff ||
(r.cooldown_until && new Date(r.cooldown_until).getTime() > now));

// Update or insert record
const existing = records.find(r => r.slot === slotName && r.error_type === error_type);
if (existing) {
existing.count++;
existing.last_seen = new Date().toISOString();
// Keep the latest known reset (a fresh quota message may push it out).
if (cooldownUntil) existing.cooldown_until = cooldownUntil;
} else {
records.push({ slot: slotName, error_type, pattern, count: 1, last_seen: new Date().toISOString() });
const rec = { slot: slotName, error_type, pattern, count: 1, last_seen: new Date().toISOString() };
if (cooldownUntil) rec.cooldown_until = cooldownUntil;
records.push(rec);
}
return records;
}, []);
Expand Down Expand Up @@ -560,6 +605,12 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo
const MAX_BUF = 10 * 1024 * 1024;
let l1Truncated = false;
let l1OriginalSize = 0;
// P2: clamp the initial idle/hard timers to the max-safe bound. Node fires setTimeout
// delays above 2^31-1 ms IMMEDIATELY (silently disabling the timer), so an oversized
// idle_timeout_ms/hard_timeout_ms would leave a slot with no timeout at all. Mirrors
// stallTimeoutFor()'s clamp, which previously guarded only the stall window.
idleTimeoutMs = Math.min(idleTimeoutMs, TIMEOUT_MAX);
hardTimeoutMs = Math.min(hardTimeoutMs, TIMEOUT_MAX);

// Kill entire process group, then destroy streams to force 'close' even if
// grandchildren keep the pipes open (the common case with ccr/opencode).
Expand Down Expand Up @@ -599,21 +650,25 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo
let rateLimitHits = 0;
const RATE_LIMIT_THRESHOLD = 2; // kill after 2 consecutive rate-limit messages
let totalBytesReceived = 0;
// Tighter idle timeout when the CLI has produced < STALL_BYTE_THRESHOLD bytes
// (header-only → probably hung). Per-slot override via providers.json
// `stall_timeout_ms` (see stallTimeoutFor): slow models (e.g. GLM-5.2[1m],
// MiniMax-M3) legitimately emit a small preamble then pause >30s mid-generation
// — they are slow, not stalled — so they need a longer threshold to avoid being
// false-killed.
// P2 — STALL detection = "no FIRST byte", NOT "model is thinking".
// Prior bug: the idle window was tightened to STALL_TIMEOUT_MS whenever total output
// was < 500 bytes, so a slow model that emitted a short preamble (e.g. 202-byte CLI
// framing) then paused >30s mid-generation was false-killed as STALL. A stall timeout
// is meant for "the process stopped writing", not "the model is still generating".
// Fix: a dedicated first-byte timer catches the genuine dead-on-arrival hang (zero bytes
// by STALL_TIMEOUT_MS); once ANY byte arrives it is cleared and the normal per-chunk
// idle window governs — so slow thinkers stream fine. Per-slot `stall_timeout_ms`
// (stallTimeoutFor) still tunes the first-byte budget for slow-to-start providers.
const STALL_TIMEOUT_MS = stallTimeoutFor(provider);
const STALL_BYTE_THRESHOLD = 500; // below this = "just a header, probably stalled"
let firstByteTimer = setTimeout(() => {
if (totalBytesReceived === 0 && !timedOut) { timedOut = true; timeoutType = 'STALL'; killGroup(); }
}, STALL_TIMEOUT_MS);

child.stdout.on('data', d => {
totalBytesReceived += d.length;
clearTimeout(firstByteTimer); // first byte seen → past the dead-on-arrival window
clearTimeout(idleTimer);
// Adaptive idle: use tighter 30s timeout when CLI has barely produced output (header-only stall)
const effectiveIdle = totalBytesReceived < STALL_BYTE_THRESHOLD ? STALL_TIMEOUT_MS : idleTimeoutMs;
idleTimer = setTimeout(() => { timedOut = true; timeoutType = totalBytesReceived < STALL_BYTE_THRESHOLD ? 'STALL' : 'IDLE'; killGroup(); }, effectiveIdle);
idleTimer = setTimeout(() => { timedOut = true; timeoutType = 'IDLE'; killGroup(); }, idleTimeoutMs);
const chunk = d.toString();
l1OriginalSize += chunk.length;
if (stdout.length < MAX_BUF) {
Expand All @@ -639,9 +694,9 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo
});
child.stderr.on('data', d => {
totalBytesReceived += d.length;
clearTimeout(firstByteTimer); // first byte seen (stderr counts) → past dead-on-arrival
clearTimeout(idleTimer);
const effectiveIdle = totalBytesReceived < STALL_BYTE_THRESHOLD ? STALL_TIMEOUT_MS : idleTimeoutMs;
idleTimer = setTimeout(() => { timedOut = true; timeoutType = totalBytesReceived < STALL_BYTE_THRESHOLD ? 'STALL' : 'IDLE'; killGroup(); }, effectiveIdle);
idleTimer = setTimeout(() => { timedOut = true; timeoutType = 'IDLE'; killGroup(); }, idleTimeoutMs);
const chunk = d.toString().slice(0, 4096);
stderr += chunk;
// Check stderr for rate-limit patterns too (gemini logs to stderr)
Expand All @@ -659,6 +714,7 @@ function runSubprocess(provider, prompt, idleTimeoutMs, hardTimeoutMs, allowedTo
child.on('close', (code) => {
clearTimeout(idleTimer);
clearTimeout(hardTimer);
clearTimeout(firstByteTimer);
if (timedOut) {
// Content-based reclassification: when STALL fires, inspect the partial
// stdout/stderr for known error patterns before using the generic label.
Expand Down Expand Up @@ -1106,4 +1162,4 @@ if (require.main === module) {
}

// ─── Test exports (SHELL-ESCAPE-01, TRUNC-01, INFRA-367) ───────────────────────
module.exports = { buildSpawnArgs, stallTimeoutFor, recordTelemetry, findProjectRoot, writeFailureLog, atomicUpdateJson, VERDICTS, VERDICT_LINE_RE, parseVerdictLine };
module.exports = { buildSpawnArgs, stallTimeoutFor, recordTelemetry, findProjectRoot, writeFailureLog, atomicUpdateJson, parseQuotaResetMs, VERDICTS, VERDICT_LINE_RE, parseVerdictLine };
85 changes: 85 additions & 0 deletions bin/quorum-preflight-deep-integration.test.cjs
Original file line number Diff line number Diff line change
@@ -0,0 +1,85 @@
'use strict';

// P1 — LIVE deep-probe integration harness. Spawns a real (mock) provider CLI through
// deepProbeSlot and asserts the end-to-end classification. This is the harness that was
// deferred when P1's policy landed; it exercises the actual subprocess path, not just the
// pure classifier. The reviewers' "quota-dead slot blocked before review" case is the
// quota test below (deep probe downgrades → the P3 gate would then block).

const { describe, it } = require('node:test');
const assert = require('node:assert/strict');
const fs = require('fs');
const path = require('path');
const { deepProbeSlot, computeQuorumGate } = require('./quorum-preflight.cjs');

const MOCK = path.join(__dirname, '__deep-probe-mock.cjs');
try { fs.chmodSync(MOCK, 0o755); } catch (_) {}

function mockProvider(mode, extra = {}) {
return {
name: `mock-${mode}`,
type: 'subprocess',
resolvedCli: MOCK, // resolveSpawnTarget prefers resolvedCli (absolute)
args_template: ['{prompt}'], // honored verbatim by resolveArgsTemplate
deep_probe: { prompt: 'respond with: PROBE_OK', expect: 'PROBE_OK', timeout_ms: 4000 },
env: { MOCK_MODE: mode, ...extra },
};
}

describe('deepProbeSlot — live spawn classification (integration)', () => {
it('healthy slot (prints PROBE_OK) → ok, OK', async () => {
const r = await deepProbeSlot(mockProvider('probe_ok'), 10000);
assert.equal(r.ok, true);
assert.equal(r.classification, 'OK');
});

it('quota-dead slot (429/RESOURCE_EXHAUSTED) → DOWNGRADED (the L1/L2-missed case)', async () => {
const r = await deepProbeSlot(mockProvider('quota'), 10000);
assert.equal(r.ok, false);
assert.equal(r.classification, 'QUOTA');
});

it('auth-dead slot (401) → DOWNGRADED', async () => {
const r = await deepProbeSlot(mockProvider('auth'), 10000);
assert.equal(r.ok, false);
assert.equal(r.classification, 'AUTH');
});

it('slow-but-healthy slot (preamble, ~1.5s pause, then PROBE_OK) → ok, NOT killed', async () => {
// The P2 shape at the deep-probe layer: a short preamble then a pause. Must pass.
const r = await deepProbeSlot(mockProvider('slow_ok', { MOCK_DELAY_MS: '1500' }), 10000);
assert.equal(r.ok, true);
assert.equal(r.classification, 'OK');
});

it('hung slot (preamble then silence) → timeout is INCONCLUSIVE, never downgraded (P2-safe)', async () => {
// A tight per-probe timeout fires; a timeout must NOT downgrade (would re-create the
// slow-slot false-kill). ok stays true.
const prov = mockProvider('hang');
prov.deep_probe = { prompt: 'x', expect: 'PROBE_OK', timeout_ms: 800 };
const r = await deepProbeSlot(prov, 10000);
assert.equal(r.ok, true);
assert.equal(r.classification, 'INCONCLUSIVE');
});

it('unspawnable slot (no target) → SKIP, never false-kills', async () => {
const r = await deepProbeSlot({ name: 'x', type: 'subprocess', args_template: ['{prompt}'] }, 10000);
assert.equal(r.ok, true);
assert.equal(r.classification, 'SKIP');
});

it('E2E (reviewers\' key test): a quota-dead slot is downgraded → gate BLOCKS before review', async () => {
// 3 slots pass L1/L2, max_quorum_size=3, but one is quota-dead. The deep probe catches
// it (L1/L2 could not), dropping available to 2/3 → computeQuorumGate blocks. Without the
// deep gate this quorum would have dispatched a real review on a dead slot.
const slots = ['probe_ok', 'probe_ok', 'quota'];
const results = await Promise.all(slots.map((m) =>
deepProbeSlot(mockProvider(m), 10000).then(r => ({ m, r }))));
let available = slots.length;
for (const { r } of results) if (r.ok === false) available -= 1;
assert.equal(available, 2, 'the quota-dead slot must be downgraded by the deep probe');
const gate = computeQuorumGate(available, 3, false);
assert.equal(gate.blocked, true, 'reduced (2/3) panel must block before any review runs');
assert.equal(gate.waiver_required, true);
});
});
Loading
Loading