#!/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 [--node ] [--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 '); 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);