From 451acfb7c58b829939547d62d7f916935cec8604 Mon Sep 17 00:00:00 2001 From: Eric Boothe Date: Wed, 10 Jun 2026 11:37:28 -0600 Subject: [PATCH] fix(eval): cluster-child per-pass telemetry + full stderr crash capture MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The canonical A-1 cluster child died at ~56 min under BOTH a 12GB and a 20GB heap — cap-independent death time — and the orchestrator kept only 200 chars of err.message, discarding the V8 GC dump that says which heap space exhausted and every trace of how far the loop got. Two hour-long runs were undiagnosable. - the child logs every pass to stderr AND _cluster-progress.log next to the report (pass time, maxDelta, non-finite cell, heapUsed/rss, sample size) — live-tailable, survives tmp cleanup - on crash the orchestrator keeps a 2500-char stderr tail (classifying V8 heap-dump signatures as OOM) and prints the last lines; on success it surfaces the per-pass telemetry in the orchestrator log - a 12-min/pass real-model cluster is never a black box again Diagnosis itself is the next step (probe converges in 2 passes under 6GB on a strided sample; the engine-mirrored full surface dies — trajectory unknown until an instrumented run lands). Co-Authored-By: Claude Fable 5 --- CHANGELOG.md | 7 +++++++ eval/per-sheet-eval.mjs | 36 +++++++++++++++++++++++++++++++++--- 2 files changed, 40 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 63be9a8..28d1620 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,13 @@ input cells). **A cluster member is never size-skipped** (`MAX_SHEET_SIZE_MB` silently dropped the monster sheets from the cluster → partial-cluster wrong fixed point; regression red pre-fix with `clustersTotal=0`). New `EVAL_CLUSTER_TIMEOUT_MS` (default 60min). +- **cluster child per-pass telemetry + full crash capture** — the canonical A-1 cluster + child died at ~56 min under BOTH a 12GB and a 20GB heap (cap-independent death time), + and the 200-char error truncation discarded the V8 GC dump that says which space + exhausted. The child now logs pass/delta/heap per pass (stderr + `_cluster-progress.log` + next to the report) and the orchestrator keeps a real stderr tail. The probe-vs-canonical + discrepancy (probe: 2 passes, <6GB observed; canonical child: dead at ~56 min) is the + open diagnosis. - **per-sheet-eval exit gate is crash-honest** — a hard-failed sheet (crash/OOM/error) contributes zero tested cells, so the accuracy-only exit gate exited 0 on a run where the 17-sheet cluster child OOMed and only 3 standalone sheets were scored (observed live: diff --git a/eval/per-sheet-eval.mjs b/eval/per-sheet-eval.mjs index dcb2b5c..a8f5c27 100644 --- a/eval/per-sheet-eval.mjs +++ b/eval/per-sheet-eval.mjs @@ -503,10 +503,12 @@ process.stdout.write(JSON.stringify({ accuracy: total > 0 ? correct/total : 0, c const evalScript = ` import { readFile } from 'fs/promises'; +import { appendFileSync } from 'fs'; ${importLines} const cn = s => { let n=0; for(const c of s) n = n*26+c.charCodeAt(0)-64; return n; }; const nc = n => { let s=''; while(n>0){n--;s=String.fromCharCode(65+(n%26))+s;n=Math.floor(n/26);} return s; }; +const _TEL_LOG = ${JSON.stringify(join(dirname(resolve(OUTPUT_FILE)), '_cluster-progress.log').replace(/\\/g, '/'))}; const ctx = { // Seeded with the (scoped or full) ground truth, parsed DIRECTLY into // ctx.values — single copy. The old parse-allGt-then-copy-every-entry pattern @@ -554,12 +556,24 @@ const clusterFns = [${members.map((_, i) => `compute_${i}`).join(', ')}]; const MAX_ITER = 200, TOL = 1e-6; const _clusterSet = new Set(${JSON.stringify(clusterSheets)}); const _SAMPLE_SAFETY_CAP = 4000; +// Per-pass telemetry to stderr (stdout carries the result JSON). A real-model +// pass is ~12+ minutes; a child that dies on pass N must leave a record of +// passes 1..N-1 (delta trajectory + heap) or the crash is undiagnosable — the +// first A-1 canonical runs died silent at ~56 min under TWO different heap caps. +const _t0 = Date.now(); +const _tel = (m) => { + const line = '[cluster ' + ((Date.now() - _t0) / 60000).toFixed(1) + 'm] ' + m + String.fromCharCode(10); + try { process.stderr.write(line); } catch {} + try { appendFileSync(_TEL_LOG, line); } catch {} +}; +_tel('seeded ' + Object.keys(ctx.values).length + ' GT cells; starting convergence loop'); let _sampleKeys = null, _before = null; const _deltaHist = []; let _iters = 0, _conv = false, _nonFinite = null, _err = null, _nonFiniteSettled = 0; try { for (let _ci = 0; _ci < MAX_ITER; _ci++) { _iters = _ci + 1; + const _tp = Date.now(); for (const fn of clusterFns) fn(ctx); const v = ctx.values; if (_sampleKeys === null) { @@ -597,6 +611,10 @@ try { if (d > maxDelta) maxDelta = d; _before[i] = _cur; } + { + const _mu = process.memoryUsage(); + _tel('pass ' + _iters + ': ' + ((Date.now() - _tp) / 60000).toFixed(1) + 'min, maxDelta=' + (Number.isFinite(maxDelta) ? maxDelta.toExponential(2) : String(maxDelta)) + ', nonFinite=' + (anyNonFinite ? ('YES @' + _nonFinite) : 'no') + ', heapUsed=' + (_mu.heapUsed / 1073741824).toFixed(1) + 'GB, rss=' + (_mu.rss / 1073741824).toFixed(1) + 'GB, sample=' + _sampleKeys.length); + } if (anyNonFinite) { // Keep iterating so a TRANSIENT cold-0 can warm. Bound the churn (#61): stop fast // when the FINITE surface has SETTLED while a cell stays non-finite (STRUCTURAL @@ -677,13 +695,17 @@ process.stdout.write(JSON.stringify({ results, iters: _iters, converged: _conv, try { const safeEnv = { ...process.env }; delete safeEnv.ANTHROPIC_API_KEY; - const { stdout: evalOut } = await execAsync( + const { stdout: evalOut, stderr: evalErr } = await execAsync( 'node', [`--max-old-space-size=${NODE_HEAP_MB}`, tmpScript], { timeout: EVAL_CLUSTER_TIMEOUT_MS, maxBuffer: 50 * 1024 * 1024, env: safeEnv } ); const out = JSON.parse(evalOut); const elapsed = Date.now() - evalStart; + // Surface the child's per-pass telemetry (delta trajectory, heap) in the + // orchestrator log — a multi-pass real-model cluster is ~12 min/pass and + // must not be a black box. + for (const l of String(evalErr || '').split('\n').filter(l => l.startsWith('[cluster '))) console.log(` ${l}`); clusterMeta.push({ clusterSheets, iters: out.iters, converged: !!out.converged, nonFiniteCell: out.nonFiniteCell || null }); Object.assign(namedCellValues, out.namedCellValues || {}); if (out.error) { @@ -700,11 +722,19 @@ process.stdout.write(JSON.stringify({ results, iters: _iters, converged: _conv, }); } catch (err) { const elapsed = Date.now() - evalStart; - const isOOM = err.killed || err.signal === 'SIGKILL' || (err.message && err.message.includes('ENOMEM')); + // V8's fatal heap dump ("<--- Last few GCs --->" + which space exhausted) + // lands on stderr — keep a real tail of it, not 200 chars of err.message + // (two silent ~56-min A-1 cluster deaths were undiagnosable from the + // truncated message alone). The child's per-pass telemetry is also on + // stderr / in _cluster-progress.log next to the report. + const stderrTail = (err.stderr ? String(err.stderr) : String(err.message || '')).slice(-2500); + const isOOM = err.killed || err.signal === 'SIGKILL' || (err.message && err.message.includes('ENOMEM')) + || /heap out of memory|Last few GCs/i.test(stderrTail); const reason = isOOM ? 'OOM' : (err.signal || 'crash'); console.log(` XX cluster [${clusterSheets.join(', ')}]: ${reason} ${elapsed}ms`); + if (stderrTail) console.log(` stderr tail:\n${stderrTail.split('\n').slice(-12).map(l => ' | ' + l).join('\n')}`); clusterMeta.push({ clusterSheets, iters: 0, converged: false, nonFiniteCell: null }); - return members.map(m => { completed++; return { sheetName: m.sheetName, accuracy: 0, correct: 0, total: 0, failures: [], elapsed, status: isOOM ? 'oom' : 'crash', error: isOOM ? `OOM (killed after ${(elapsed / 1000).toFixed(1)}s)` : err.message?.slice(0, 200) }; }); + return members.map(m => { completed++; return { sheetName: m.sheetName, accuracy: 0, correct: 0, total: 0, failures: [], elapsed, status: isOOM ? 'oom' : 'crash', error: `${reason} after ${(elapsed / 1000).toFixed(1)}s; stderr tail: ${stderrTail.slice(-1200)}` }; }); } }