4e79f63157
docs/bench-log.md: the fake-worker measurements (slow start one trip and 2.0 s restart, fake-fast guard in under 0.1 s, exit 43 at 8.8 s, CPU re-check stop at 0.5 s, stall guard at 60.1 s with STATUS lines through the silence, one prepare per epoch with refused retries held; app: zero-rate restart at 79.6 s and faulted at 75.4 s on the repeat, no-status restart at 90.4 s, silent node restarted at 150.7 s and synced 7.2 s later; no double restart on the miner's own worker restart). Two defects the harness found are named with their fork commits. docs/fud-ledger.md and the round-4 review table: M26, M27, X21 Fixed with the commits. engine.rs: the miner's restart note no longer hides the fault reason on the card. tools/reliability: the harness matches the miner's stderr lines where they are printed there. Co-Authored-By: Claude Fable 5.1 <noreply@anthropic.com>
313 lines
17 KiB
JavaScript
Executable file
313 lines
17 KiB
JavaScript
Executable file
#!/usr/bin/env node
|
|
// Miner fault guards measured on a private test network (ports 29950 to 29953, devnet suffix 9950, data under the
|
|
// scratch directory): one igneumd, one CPU block producer when a scenario needs epochs, and the miner under test
|
|
// driving fake-worker.mjs, which misbehaves on command through a control file. Never touches the live devnet.
|
|
//
|
|
// node tools/reliability/run.mjs --miner <igneum-miner> [--node <igneumd>] [--only slow-first,fake-fast,...]
|
|
//
|
|
// Scenarios (each a fresh miner process; the fake worker's mode is switched by rewriting the control file):
|
|
// slow-first the first 25 s of jobs take 5 s each, then the true rate (100x): the old guard tripped on every
|
|
// interval from the second on (M26); expected now: no fault, STATUS every 10 s throughout
|
|
// fake-fast 3 healthy intervals, then jobs "done" in 0.3 ms: one fault, a STATUS line with faults=1,
|
|
// the worker back after the 2 s delay; the mode returns to ok at the fault
|
|
// fake-fast-stays the same, but the fault persists: three trips at growing delay, then exit 43
|
|
// badfound wrong hashes on every found: three consecutive CPU re-check mismatches stop the worker (X21)
|
|
// silent the worker stops answering: STATUS lines keep coming, the stall guard fires at 60 s
|
|
// prepare-flap with epochs every 60 DAA (a 3-thread CPU block producer on easy genesis bits), the worker refuses every prepare: at most two
|
|
// sends per pair per epoch, 30 s apart (M27)
|
|
//
|
|
// A watcher is trusted only once it fires on a known-good and a known-bad case: every scenario states what must
|
|
// appear AND what must not, and the run fails if the fault detector saw nothing in the scenarios that fault.
|
|
|
|
import { spawn } from 'node:child_process';
|
|
import { mkdirSync, rmSync, writeFileSync, existsSync, appendFileSync, readFileSync } from 'node:fs';
|
|
import { fileURLToPath } from 'node:url';
|
|
import { dirname, join } from 'node:path';
|
|
|
|
const here = dirname(fileURLToPath(import.meta.url));
|
|
const args = process.argv.slice(2);
|
|
const opt = (n, d) => { const i = args.indexOf(n); return i >= 0 ? args[i + 1] : d; };
|
|
const MINER = opt('--miner');
|
|
const NODE = opt('--node', join(here, '../../vendor/igneum-node/target-integration/release/igneumd'));
|
|
const ONLY = opt('--only', '').split(',').filter(Boolean);
|
|
const SCRATCH = process.env.SCRATCH || `/tmp/igneum-reliability-${process.pid}`;
|
|
const BASE = 29950, SUFFIX = 9950;
|
|
const FAKE = join(here, 'fake-worker.mjs');
|
|
if (!MINER || !existsSync(MINER)) { console.error('need --miner <igneum-miner with the guards>'); process.exit(2); }
|
|
if (!existsSync(NODE)) { console.error(`missing node ${NODE}`); process.exit(2); }
|
|
|
|
const t0 = Date.now();
|
|
const since = () => ((Date.now() - t0) / 1000).toFixed(1);
|
|
const log = (...a) => console.log(new Date().toISOString().slice(11, 23), `t=${since()}s`, ...a);
|
|
const sleep = (ms) => new Promise(r => setTimeout(r, ms));
|
|
const started = [];
|
|
process.on('exit', () => { for (const p of started) { try { p.kill('SIGKILL'); } catch {} } });
|
|
process.on('SIGINT', () => process.exit(130));
|
|
|
|
rmSync(SCRATCH, { recursive: true, force: true }); mkdirSync(SCRATCH, { recursive: true });
|
|
const CTL = join(SCRATCH, 'ctl');
|
|
const setMode = (m) => { writeFileSync(CTL, m + '\n'); log(`fake worker mode -> ${m}`); };
|
|
|
|
function startNode(env = {}) {
|
|
const dir = join(SCRATCH, 'node'); mkdirSync(dir, { recursive: true });
|
|
const a = ['--devnet', `--devnet-suffix=${SUFFIX}`, '--nodnsseed', '--disable-upnp', '--nologfiles', '--enable-unsynced-mining', '--outpeers=0',
|
|
`--appdir=${dir}`, `--rpclisten=127.0.0.1:${BASE}`, `--rpclisten-json=127.0.0.1:${BASE + 2}`, `--evm-rpclisten=127.0.0.1:${BASE + 3}`,
|
|
`--listen=127.0.0.1:${BASE + 1}`, '--loglevel=warn', '--yes'];
|
|
const p = spawn(NODE, a, { stdio: ['ignore', 'pipe', 'pipe'], env: { ...process.env, ...env } });
|
|
started.push(p);
|
|
const f = join(SCRATCH, 'node.log');
|
|
p.stdout.on('data', d => appendFileSync(f, d)); p.stderr.on('data', d => appendFileSync(f, d));
|
|
log(`node pid ${p.pid} grpc ${BASE}`);
|
|
return p;
|
|
}
|
|
|
|
/// The miner under test: lines are kept with the receipt time (the miner's own unix stamp when the line carries one).
|
|
function startMiner(secs, extra = []) {
|
|
const a = ['mine', `grpc://127.0.0.1:${BASE}`, '1', String(secs), 'wt', '--worker', FAKE, '--status-secs', '10', '--no-vote', '--payout-label', 'wt', ...extra];
|
|
const p = spawn(MINER, a, { stdio: ['ignore', 'pipe', 'pipe'], env: { ...process.env, FAKE_WORKER_CTL: CTL } });
|
|
started.push(p);
|
|
const m = { proc: p, lines: [], exit: null };
|
|
const f = join(SCRATCH, `miner-${Date.now()}.log`);
|
|
const take = (err) => (chunk) => {
|
|
for (const text of chunk.toString().split('\n')) {
|
|
if (!text) continue;
|
|
const stamp = /^(\d{10})\.(\d{3}) /.exec(text);
|
|
const t = stamp ? Number(stamp[1]) * 1000 + Number(stamp[2]) : Date.now();
|
|
m.lines.push({ t, err, text });
|
|
appendFileSync(f, (err ? '! ' : '') + text + '\n');
|
|
}
|
|
};
|
|
p.stdout.on('data', take(false)); p.stderr.on('data', take(true));
|
|
p.on('exit', (code) => { m.exit = code; log(`miner exited ${code}`); });
|
|
log(`miner pid ${p.pid} log ${f}`);
|
|
return m;
|
|
}
|
|
// stdout only by default: the miner prints WORKER FAULT and the exit line on both streams
|
|
const find = (m, re, after = 0, both = false) => m.lines.filter(l => l.t >= after && (both || !l.err) && re.test(l.text));
|
|
async function waitForErr(m, re, timeoutMs, after = 0) {
|
|
const end = Date.now() + timeoutMs;
|
|
while (Date.now() < end) { const h = find(m, re, after, true); if (h.length) return h[0]; if (m.exit !== null) return null; await sleep(200); }
|
|
return null;
|
|
}
|
|
async function waitFor(m, re, timeoutMs, after = 0) {
|
|
const end = Date.now() + timeoutMs;
|
|
while (Date.now() < end) { const h = find(m, re, after); if (h.length) return h[0]; if (m.exit !== null) return null; await sleep(200); }
|
|
return null;
|
|
}
|
|
const stop = (m) => { try { m.proc.kill('SIGTERM'); } catch {} };
|
|
const s = (ms) => (ms / 1000).toFixed(1) + ' s';
|
|
const results = [];
|
|
function verdict(name, checks, metrics) {
|
|
const pass = checks.every(c => c.ok);
|
|
results.push({ name, pass, checks, metrics });
|
|
log(`${pass ? 'PASS' : 'FAIL'} ${name}`);
|
|
for (const c of checks) log(` ${c.ok ? 'ok ' : 'FAIL'} ${c.what}`);
|
|
for (const [k, v] of Object.entries(metrics)) log(` ${k}: ${v}`);
|
|
}
|
|
|
|
const S = {};
|
|
|
|
S['slow-first'] = async () => {
|
|
setMode('slow');
|
|
const m = startMiner(120);
|
|
const ready = await waitFor(m, /worker: ready/, 20000);
|
|
await sleep(25000);
|
|
setMode('ok');
|
|
await sleep(60000);
|
|
stop(m);
|
|
const faults = find(m, /WORKER FAULT/);
|
|
const status = find(m, / STATUS '/);
|
|
const gaps = status.slice(1).map((l, i) => l.t - status[i].t);
|
|
const restarted = find(m, /worker restarted/);
|
|
const lastFault = faults.length ? faults[faults.length - 1].t : 0;
|
|
const healthyAfter = find(m, / STATUS '.*now=(?!0\.00)/, lastFault);
|
|
verdict('slow-first', [
|
|
{ ok: !!ready, what: 'worker reported ready' },
|
|
{ ok: faults.length <= 1, what: `at most one WORKER FAULT after a slow start (saw ${faults.length}; the old guard tripped on every interval)` },
|
|
{ ok: faults.length === restarted.length, what: `every fault was followed by one restart (faults ${faults.length}, restarts ${restarted.length})` },
|
|
{ ok: status.length >= 7, what: `STATUS lines kept coming (${status.length} in 85 s)` },
|
|
{ ok: gaps.every(g => g < 25000), what: `no STATUS gap over 25 s (max ${s(Math.max(0, ...gaps))})` },
|
|
{ ok: healthyAfter.length >= 3, what: `healthy STATUS lines after the last fault with no further trip (${healthyAfter.length})` },
|
|
], { status_lines: status.length, faults: faults.length, restarts: restarted.length, slow_to_fault: faults.length && ready ? s(faults[0].t - ready.t) : 'none', fault_to_restart: faults.length && restarted.length ? s(restarted[0].t - faults[0].t) : 'n/a' });
|
|
};
|
|
|
|
S['fake-fast'] = async () => {
|
|
setMode('ok');
|
|
const m = startMiner(180);
|
|
await waitFor(m, /worker: ready/, 20000);
|
|
await sleep(36000);
|
|
const tInject = Date.now();
|
|
setMode('fast');
|
|
const fault = await waitFor(m, /WORKER FAULT/, 60000, tInject);
|
|
if (fault) setMode('ok');
|
|
const killed = await waitForErr(m, /worker killed by a guard/, 20000, tInject);
|
|
const restarted = await waitFor(m, /worker restarted/, 30000, tInject);
|
|
const ready = await waitFor(m, /worker: ready/, 30000, restarted ? restarted.t : tInject);
|
|
// the first STATUS after the restart with a rate above 0
|
|
let recovered = null;
|
|
const end = Date.now() + 40000;
|
|
while (!recovered && Date.now() < end) {
|
|
recovered = find(m, / STATUS '.*now=(?!0\.00)/, ready ? ready.t : tInject)[0] || null;
|
|
if (!recovered) await sleep(300);
|
|
}
|
|
await sleep(15000);
|
|
stop(m);
|
|
const statusAfterFault = fault ? find(m, / STATUS '.*faults=[1-9]/, fault.t) : [];
|
|
const faultsTotal = find(m, /WORKER FAULT/).length;
|
|
const restarts = find(m, /worker restarted/).length;
|
|
if (!restarted) recovered = null; // a rate after the restart only counts once there was a restart
|
|
verdict('fake-fast', [
|
|
{ ok: !!fault, what: 'the guard fired on jobs done in 0.3 ms' },
|
|
{ ok: statusAfterFault.length > 0, what: 'a STATUS line with faults=1 was printed after the trip (the old guard printed none)' },
|
|
{ ok: !!killed && !!restarted, what: 'the worker was killed by the guard and restarted' },
|
|
{ ok: !!recovered, what: 'a STATUS line with a rate above 0 followed the restart' },
|
|
{ ok: faultsTotal === 1 && restarts === 1, what: `exactly one fault and one restart (faults ${faultsTotal}, restarts ${restarts})` },
|
|
], {
|
|
inject_to_fault: fault ? s(fault.t - tInject) : 'n/a',
|
|
fault_to_restarted: fault && restarted ? s(restarted.t - fault.t) : 'n/a',
|
|
fault_to_ready: fault && ready ? s(ready.t - fault.t) : 'n/a',
|
|
fault_to_first_healthy_status: fault && recovered ? s(recovered.t - fault.t) : 'n/a',
|
|
inject_to_first_healthy_status: recovered ? s(recovered.t - tInject) : 'n/a',
|
|
});
|
|
};
|
|
|
|
S['fake-fast-stays'] = async () => {
|
|
setMode('ok');
|
|
const m = startMiner(600);
|
|
await waitFor(m, /worker: ready/, 20000);
|
|
await sleep(36000);
|
|
const tInject = Date.now();
|
|
setMode('fast');
|
|
const end = Date.now() + 300000;
|
|
while (m.exit === null && Date.now() < end) await sleep(500);
|
|
const faults = find(m, /WORKER FAULT/);
|
|
const delays = find(m, /restarting it in (\d+) s/, 0, true).map(l => Number(/restarting it in (\d+) s/.exec(l.text)[1]));
|
|
const gaveUp = find(m, /exiting with code 43/);
|
|
verdict('fake-fast-stays', [
|
|
{ ok: faults.length >= 3, what: `three or more faults (${faults.length})` },
|
|
{ ok: delays.length >= 2 && delays[0] === 2 && delays[1] === 4, what: `restart delays grow 2, 4 s (saw ${delays.join(', ')})` },
|
|
{ ok: m.exit === 43 && gaveUp.length === 1, what: `the miner gave up with exit 43 (exit ${m.exit})` },
|
|
], {
|
|
inject_to_exit: s((m.lines.at(-1)?.t || Date.now()) - tInject),
|
|
fault_times: faults.map(l => s(l.t - tInject)).join(', '),
|
|
});
|
|
};
|
|
|
|
S['badfound'] = async () => {
|
|
setMode('ok');
|
|
const m = startMiner(180);
|
|
await waitFor(m, /worker: ready/, 20000);
|
|
await sleep(15000);
|
|
const tInject = Date.now();
|
|
setMode('badfound');
|
|
const mism = await waitForErr(m, /WORKER MISMATCH/, 30000, tInject); // stderr
|
|
const fault = await waitFor(m, /WORKER FAULT cpu re-check: 3 consecutive mismatches/, 60000, tInject);
|
|
if (fault) setMode('ok');
|
|
const restarted = await waitFor(m, /worker restarted/, 30000, tInject);
|
|
const ready = await waitFor(m, /worker: ready/, 30000, restarted ? restarted.t : tInject);
|
|
let recovered = null;
|
|
const end = Date.now() + 40000;
|
|
while (!recovered && Date.now() < end) {
|
|
recovered = find(m, / STATUS '.*now=(?!0\.00)/, ready ? ready.t : tInject)[0] || null;
|
|
if (!recovered) await sleep(300);
|
|
}
|
|
await sleep(12000);
|
|
stop(m);
|
|
if (!restarted) recovered = null;
|
|
const statusMism = find(m, / STATUS '.*mismatched=[1-9]/);
|
|
const mismCount = find(m, /WORKER MISMATCH/, 0, true).length;
|
|
verdict('badfound', [
|
|
{ ok: !!mism, what: 'the CPU re-check rejected the wrong hash' },
|
|
{ ok: !!fault, what: 'three consecutive mismatches stopped the worker (X21)' },
|
|
{ ok: mismCount <= 4, what: `no more than 4 wrong shares were accepted before the stop (${mismCount})` },
|
|
{ ok: statusMism.length > 0, what: 'STATUS shows mismatched= above 0 for the app to read' },
|
|
{ ok: !!restarted && !!recovered, what: 'the worker restarted and a rate above 0 followed' },
|
|
], {
|
|
inject_to_first_mismatch: mism ? s(mism.t - tInject) : 'n/a',
|
|
inject_to_fault: fault ? s(fault.t - tInject) : 'n/a',
|
|
fault_to_first_healthy_status: fault && recovered ? s(recovered.t - fault.t) : 'n/a',
|
|
});
|
|
};
|
|
|
|
S['silent'] = async () => {
|
|
setMode('ok');
|
|
const m = startMiner(240);
|
|
await waitFor(m, /worker: ready/, 20000);
|
|
await sleep(15000);
|
|
const tInject = Date.now();
|
|
setMode('silent');
|
|
const fault = await waitFor(m, /WORKER FAULT no job completed/, 120000, tInject);
|
|
if (fault) setMode('ok');
|
|
const restarted = await waitFor(m, /worker restarted/, 30000, tInject);
|
|
const ready = await waitFor(m, /worker: ready/, 30000, restarted ? restarted.t : tInject);
|
|
let recovered = null;
|
|
const end = Date.now() + 40000;
|
|
while (!recovered && Date.now() < end) {
|
|
recovered = find(m, / STATUS '.*now=(?!0\.00)/, ready ? ready.t : tInject)[0] || null;
|
|
if (!recovered) await sleep(300);
|
|
}
|
|
await sleep(12000);
|
|
stop(m);
|
|
if (!restarted) recovered = null;
|
|
const statusDuringSilence = fault ? find(m, / STATUS '/, tInject).filter(l => l.t < fault.t) : [];
|
|
verdict('silent', [
|
|
{ ok: !!fault, what: 'the stall guard fired on a worker that stopped answering' },
|
|
{ ok: fault && fault.t - tInject >= 55000 && fault.t - tInject <= 90000, what: `the stall guard fired between 55 and 90 s after the silence began (${fault ? s(fault.t - tInject) : 'n/a'})` },
|
|
{ ok: statusDuringSilence.length >= 4, what: `STATUS lines kept printing while the worker was silent (${statusDuringSilence.length}; the old loop printed none)` },
|
|
{ ok: !!restarted && !!recovered, what: 'the worker restarted and a rate above 0 followed' },
|
|
], {
|
|
silence_to_fault: fault ? s(fault.t - tInject) : 'n/a',
|
|
fault_to_first_healthy_status: fault && recovered ? s(recovered.t - fault.t) : 'n/a',
|
|
silence_to_first_healthy_status: recovered ? s(recovered.t - tInject) : 'n/a',
|
|
});
|
|
};
|
|
|
|
S['prepare-flap'] = async () => {
|
|
// a CPU block producer so the DAA moves and epochs turn every 60 blocks (lead 20)
|
|
const cpu = spawn(MINER, ['mine', `grpc://127.0.0.1:${BASE}`, '3', '400', 'cpu', '--engine', 'igneum-pow', '--no-vote', '--payout-label', 'cpu', '--status-secs', '30'], { stdio: ['ignore', 'pipe', 'pipe'] });
|
|
started.push(cpu);
|
|
log(`cpu block producer pid ${cpu.pid}`);
|
|
// the block producer's log, for the block count (the node logs at warn level)
|
|
const cf = join(SCRATCH, 'cpu-miner.log'); cpu.stdout.on('data', d => appendFileSync(cf, d)); cpu.stderr.on('data', d => appendFileSync(cf, d));
|
|
setMode('preparefail');
|
|
const m = startMiner(360);
|
|
await waitFor(m, /worker: ready/, 20000);
|
|
await sleep(300000);
|
|
stop(m); try { cpu.kill('SIGTERM'); } catch {}
|
|
const sent = find(m, /PREPARE sent for epoch seed (\S+) day (\d+)/);
|
|
const held = find(m, /PREPARE held/);
|
|
const failed = find(m, /could not prepare/, 0, true); // stderr
|
|
const changes = find(m, /SEED CHANGE/);
|
|
// per epoch (between SEED CHANGE lines): sends per pair and the smallest gap between any two sends
|
|
const epochs = [];
|
|
const bounds = [0, ...changes.map(l => l.t), Infinity];
|
|
for (let i = 0; i + 1 < bounds.length; i++) {
|
|
const inEpoch = sent.filter(l => l.t >= bounds[i] && l.t < bounds[i + 1]);
|
|
const perPair = {};
|
|
for (const l of inEpoch) { const k = /epoch seed (\S+) day (\d+)/.exec(l.text).slice(1).join('/'); perPair[k] = (perPair[k] || 0) + 1; }
|
|
epochs.push({ sends: inEpoch.length, maxPerPair: Math.max(0, ...Object.values(perPair)) });
|
|
}
|
|
const gaps = sent.slice(1).map((l, i) => l.t - sent[i].t);
|
|
verdict('prepare-flap', [
|
|
{ ok: changes.length >= 2, what: `epochs turned (${changes.length} seed changes in 5 min)` },
|
|
{ ok: sent.length >= 2, what: `prepares were sent (${sent.length})` },
|
|
{ ok: failed.length >= 1, what: `the worker refused them (${failed.length} prepare-failed)` },
|
|
{ ok: epochs.every(e => e.maxPerPair <= 2), what: `at most two sends per pair per epoch (${epochs.map(e => e.maxPerPair).join(', ')})` },
|
|
{ ok: gaps.every(g => g >= 29500), what: `every send at least 30 s after the previous (min gap ${gaps.length ? s(Math.min(...gaps)) : 'n/a'})` },
|
|
{ ok: held.length >= 1, what: `the miner said why it held a prepare (${held.length} lines)` },
|
|
], { sends: sent.length, held: held.length, seed_changes: changes.length, blocks_by_the_cpu_producer: (() => { try { return (readFileSync(join(SCRATCH, 'cpu-miner.log'), 'utf8').match(/ACCEPTED block/g) || []).length; } catch { return 'n/a'; } })() });
|
|
};
|
|
|
|
const names = ONLY.length ? ONLY : Object.keys(S);
|
|
startNode({ IGNEUM_POW_EPOCH_BLOCKS: '60', IGNEUM_POW_EPOCH_LEAD: '20', IGNEUM_DEVNET_GENESIS_BITS: '0x1f100000' });
|
|
await sleep(4000);
|
|
for (const n of names) {
|
|
if (!S[n]) { log(`unknown scenario ${n}`); continue; }
|
|
log(`=== ${n}`);
|
|
try { await S[n](); } catch (e) { log(`scenario ${n} threw: ${e.stack || e}`); results.push({ name: n, pass: false, checks: [{ ok: false, what: String(e) }], metrics: {} }); }
|
|
await sleep(2000);
|
|
}
|
|
const report = { date: new Date().toISOString(), miner: MINER, node: NODE, scratch: SCRATCH, results };
|
|
writeFileSync(join(SCRATCH, 'report.json'), JSON.stringify(report, null, 2));
|
|
console.log(JSON.stringify(report, null, 2));
|
|
process.exit(results.every(r => r.pass) ? 0 : 1);
|