diff --git a/app/igneum-app/src/engine.rs b/app/igneum-app/src/engine.rs index 81fdd6efc..361b5fa21 100644 --- a/app/igneum-app/src/engine.rs +++ b/app/igneum-app/src/engine.rs @@ -2089,7 +2089,10 @@ impl Engine { self.miners[i].watch.event(t, crate::watchdog::Event::WorkerRestart(&reason)); } if let Some(c) = self.st().mining.cards.get_mut(card) { - c.message = short(text, 160); + // the restart note never hides the fault reason the card already shows + if !(c.message.starts_with("worker fault: ") && (text.contains("worker killed by a guard") || text.contains("worker exited"))) { + c.message = short(text, 160); + } } } return; diff --git a/docs/bench-log.md b/docs/bench-log.md index 7a70cb436..2459884eb 100644 --- a/docs/bench-log.md +++ b/docs/bench-log.md @@ -1051,3 +1051,49 @@ moving (150.8M at the height, then stepping down as PC 2's card paused for a pro the chain; a consensus rule changed under a running network with miners on three platforms. The first measurement of v2 on the devnet's own regime (two large miners, bursty parallel blocks) needs PC 2 back from its job; the cloud numbers stand meanwhile (settle 157 to 272 s, no swing). + +## 4 October 2026, miner fault guards and the app watchdog measured against a fake worker (miner-community-lead, app owner) + +Machine: Apple M5 Max, load average 17 to 92 (other agents' builds and runs throughout), everything at nice 19 under +`tools/lock/with-lock.sh run`. These are recoveries and seconds, not hash rates: nothing here is a performance number. +Private test networks only: one `igneumd` (devnet suffix 9950, ports 29950 to 29953) for the miner scenarios and the +app's own private node (suffix 9960, ports 29960 and 29961) for the app scenarios; the live devnet was not touched. +Worker: `tools/reliability/fake-worker.mjs`, a stand-in that speaks the serve protocol and misbehaves on command +(jobs done in 0.3 ms, 0 hashes, silence, wrong hashes, refused prepares); it never hashes, so no block was found +and the fake rate of about 157 MH/s inside jobs is an invented number. Miner: fork branch `miner-reliability` +(`aea5ac6d`, `501363e0`, `945153ab`), `igneum-miner` release with `--status-secs 10`. App: `app/igneum-app` at +`f39e240` plus the card-message fix, `IGNEUM_APP_STATUS_SECS=10`. Harness: `tools/reliability/run.mjs` and +`app-run.mjs`; every scenario states what must and must not appear, and the detectors were shown to fire on the +faulting scenarios and stay quiet on the healthy stretches before any number below was kept. + +Miner guards (review round 4 M26, M27, X21), one fresh miner process per scenario: + +| Scenario | What the worker did | Result | Seconds | +|---|---|---|---| +| slow-first (M26) | 5 s jobs for the first 25 s, then the true rate, 47x faster | one trip, one restart, STATUS lines every 10 s throughout (8 in 85 s, max gap 10.1 s), 4 healthy intervals after it with no further trip; the old guard tripped on every interval and printed nothing | slow start to trip 40.1, trip to worker restarted 2.0 | +| fake-fast (the gfx1036 fault) | jobs "done" in 0.3 ms with the full count | the job-time guard fired on the first such job; STATUS with `faults=1` printed after the trip; one restart | trip 0.0 after injection, worker restarted 2.0, ready 2.5, first healthy STATUS 12.5 | +| fake-fast-stays | the same fault persists | trips at 0.2, 3.2, 8.7 s with restart delays 2 then 4 s; the third trip in the window ends the miner with exit 43 (`WORKER FAULT 3 guard trips in 10 minutes`) | injection to exit 8.8 | +| badfound (X21) | a wrong hash on every found | 3 `WORKER MISMATCH` lines, then `WORKER FAULT cpu re-check: 3 consecutive mismatches`; 3 wrong shares seen, 0 submitted; STATUS shows `mismatched=3`; one restart | first mismatch 0.3, trip 0.5, first healthy STATUS after the trip 2.9 | +| silent | stops answering with jobs queued | STATUS lines kept printing during the silence (5; the old loop printed none and never restarted); the stall guard fired at 60 s; one restart | silence to trip 60.1, trip to first healthy STATUS 12.9 | +| prepare-flap (M27) | refuses every prepare across epochs of 60 DAA (a 3-thread CPU block producer on genesis bits 0x1f100000) | 5 epochs turned (333 blocks in 5 min); one `PREPARE sent` per epoch, each answered `prepare-failed`, each retry held (`PREPARE held ... within 30 s of the last prepare`) and the epoch turned before a retry was due: 5 sends, 5 held, 0 repeats; before the limiter a refused prepare was re-sent at the next job fill, a pack write and a GPU build each time | smallest gap between sends 50.6 | + +Two defects the harness found on the way, both fixed on the branch: after a guard kill with the job queue not full, +the fill loop's `continue` re-ran the failed stdin write forever (140,000 lines in 45 s, no restart, no STATUS; +`501363e0`); and the 60 s line-read timeout meant no STATUS line at all while a worker was silent (`945153ab`: the +read now waits one status interval). The "first healthy STATUS" figures above are bounded by the 10 s status interval: +the worker is back about 2.5 s after a trip, the next STATUS line reports it. + +App watchdog (`src/watchdog.rs`), one engine run, the fake worker as the Metal worker, steps in order: + +| Step | What happened | Result | Seconds | +|---|---|---|---| +| own-restart | the worker reports jobs done in 0.3 ms | the miner's guard restarted the worker; the card showed the fault and `worker faults 1`; the app did NOT restart the miner (same pid, app restarts 0) | fault on the card 1.0 after injection, mining again 9.1 after the fault | +| zero-once | jobs complete with 0 hashes | `watchdog: hash rate 0 for 60 s while the node is synced`; one app restart; mining on the new miner process | zero to restart 79.6 (60 s rule plus the status interval and the quit grace), restart to mining 11.3, zero to mining 91.0 | +| zero-faulted | the same again inside five minutes | card `faulted: hash rate 0 for 60 s while the node is synced (restarted once already)`; 45 s later still faulted, no miner process, no further restart; the node kept running and the app stayed up; `resume` cleared it and mining resumed | zero to faulted 75.4 | +| no-status | the miner process stopped with SIGSTOP | `watchdog: no status line from the miner for 90 s`; the stopped process killed; mining on a new process | quiet to restart 90.4, restart to mining 11.0 | +| node-silent | the node process stopped with SIGSTOP | the app restarted the node in-process (the remote-job restart kind), the new node synced, mining resumed | quiet to restart 150.7 (120 s rule plus the 30 s terminate grace on a process that cannot answer SIGTERM), restart to synced 7.2, quiet to mining 160.0 | + +Not measured: any real GPU. The job-time and interval guards, exit 43 and the app's faulted card have not run on an +RTX 5090, the gfx1036 or a Metal card; the first real run is owed from the fleet logs. The "no status" rule has not +been tried against a hung RPC (only a stopped process). Unit tests: `cargo test -p igneum-miner -- guard` (7) and +`cargo test -- watchdog` in `app/igneum-app` (11), both replaying recorded STATUS and WORKER FAULT lines. diff --git a/docs/fud-ledger.md b/docs/fud-ledger.md index cb96e9b04..660e6c3f8 100644 --- a/docs/fud-ledger.md +++ b/docs/fud-ledger.md @@ -1730,7 +1730,9 @@ Evidence: the files above. Experiment: `igneum-miner` with `IGNEUM_POW_DAY_MS=14 ### M26. The interval fault guard freezes its baseline and loops "On a trip you skip the STATUS print, so the baseline it would have updated stays frozen, and you roll the counters back to it. Any healthy rate over ten times a slow first interval trips again every interval, forever, with no STATUS line and no `faults=` for the app to read." -Status: Open (4 October 2026). +Status: Fixed (4 October 2026, evening), fork commits `aea5ac6d`, `501363e0` and `945153ab` on `miner-reliability` (`igneum/miner/src/guard.rs`; the second fixes a fill loop that spun forever after a guard kill, found by the test network). Replaced: Open (4 October 2026). + +Fix: `IntervalGuard` builds its baseline from the healthy intervals of the current worker process (a moving average, two intervals before it can trip) and forgets it when the worker restarts; the STATUS line is printed on a trip, with `faults=`; `RestartPolicy` restarts a guard-killed worker after 2 s, doubling per trip inside ten minutes, and the third trip ends the miner with exit 43 so the app shows a faulted card instead of a loop. The 60 s no-line timeout no longer skips the guards and the STATUS line. Measured against a fake worker on a private test network: `docs/bench-log.md`, "4 October 2026, miner fault guards and the app watchdog measured against a fake worker". Answer: Correct. `igneum/miner/src/main.rs:1404-1418` with the update at `:1452-1454` skipped by `continue`; the restart has no cap and no growing back-off (`:1213-1216`). A slow first interval (a game on the GPU, a foreground self-heal build on a slow card) is enough. Fix: update the baseline on a trip, or compare to the previous interval; cap restarts with a growing back-off. Review id R4.2.1. @@ -1739,7 +1741,7 @@ Evidence: the file above. Experiment: `--status-secs 10` with a GPU stress tool ### M27. A flapping node makes the worker rebuild once per template "A prepare goes out whenever the wanted pair differs from the prepared one. No count, no interval, no once-per-epoch. Each one writes a pack on the CPU with the job loop stalled and costs the worker a full build; `prepare-failed` resends on the next fill." -Status: Open (4 October 2026). +Status: Fixed (4 October 2026, evening), fork commit `aea5ac6d` on `miner-reliability` (`guard::PrepareLimiter`): one `prepare` per pair per epoch, one retry after `prepare-failed`, none within 30 s of the last; a held prepare is printed once (`PREPARE held ...`). Measured with a worker that refused every prepare across three epochs: `docs/bench-log.md`, the same entry as M26. Replaced: Open (4 October 2026). Answer: Correct. `igneum/miner/src/main.rs:1113-1165, 1337-1339`; `worker.cpp:644-658`; `host.c:1208-1225`. Estimated loss 30 to 60 percent against a node that alternates seeds per template; a stale home node on a fork is the realistic trigger. Fix: at most one prepare per pair per epoch and none within 30 s of the last. Review id R4.2.2. @@ -1757,7 +1759,7 @@ Evidence: the files above. Experiment: a tampered pack with matching vectors mus ### X21. A wrong program burns power with a green rate "The CPU re-check counts mismatches and does nothing: no threshold, no stop. The app reads `hash`, `now`, `template_age` and `synced` from STATUS and nothing else, so `mismatched=` and `WORKER FAULT` never reach the card." -Status: Open (4 October 2026). +Status: Fixed (4 October 2026, evening), fork commit `aea5ac6d` (`guard::MismatchGuard`: three consecutive CPU re-check mismatches kill the worker, `WORKER FAULT cpu re-check ...`) and app commit `f39e240` on `miner-reliability` (`app/igneum-app/src/watchdog.rs`: the app reads `mismatched=`, `faults=` and the `WORKER FAULT` lines, shows them on the card, and its own watchdog restarts a miner once for no status in 90 s or a zero rate for 60 s while synced, then marks the card faulted; a silent node is restarted in-process). Measured: `docs/bench-log.md`, the same entry as M26. Replaced: Open (4 October 2026). Answer: Correct. `igneum/miner/src/main.rs:1250-1261`; `app/igneum-app/src/engine.rs:~1762-1780` (zero matches for either string). The PowerShell launcher matches them (`igneum-common.ps1:843`), which is what README.txt and TEST.md describe. Fix: stop the worker after 3 consecutive mismatches and show it on the card; the app reads both fields. Review id R4.2.3. diff --git a/site/bench.html b/site/bench.html index da16e38f0..cd03746f3 100644 --- a/site/bench.html +++ b/site/bench.html @@ -69,7 +69,7 @@ footer{border-top:1px solid var(--line);padding-block:32px 48px;font-size:13px;c

Engineering log

Every measurement the project has made, newest at the bottom, written by the people and agents who ran it, with the commands and hardware. Prototype numbers are not mining numbers and say so.

- +

Igneum bench log

Append-only. Every number here was measured on the machine named, on the date given.

2026-10-03 proto-metal / igneum-bench, first run

@@ -304,7 +304,15 @@ footer{border-top:1px solid var(--line);padding-block:32px 48px;font-size:13px;c

Hash-rate step under v2 (hop.sh "half:4:600;all:1:600", 14:57 UTC) against the morning's v1 schedule, first 600 s of each step (results/2026-10-04/v2/compare.md): 2-min rate back within 10% of 60/min after 157 s (v1 161 s) on the step up and 172 s (v1 272 s) on the step down; neither rule holds the 3-min criterion inside 600 s on 12 CPU miners. After 300 s the v1 step-up difficulty swung 128k to 134k to 89k (max/min 1.51, std log D 0.169), the v2 one climbed 102k to 117k (1.15, 0.053); on the step down v2 reached the one-thread level (82k) by 600 s, v1 was at 100k after 600 s and 97k after 900 s. One run each, CPU miners, the v2 series has a bridged gap in its first two rows.

Devnet: docs/plans/difficulty-v2-rollout-devnet.md. The gap found: the app launched igneumd without an override file, so an OTA-delivered v2 node would have forked at N; fixed with node_override_params in the packaged config (igneum-app.json, one NODE_OVERRIDE_PARAMS line in packaging/mac/packaged-config.sh read by both packagers; the engine writes <app data>/app/override-params.json and passes the flag). Rule: N = DAA at the manifest publish + 10,800 at least; since N is baked at the cut, choose DAA + 14,400 when committing the line and check at publish.

4 October 2026, difficulty rule v2 activated on the live devnet at DAA 33,000 by height switch, no fresh chain

-

Rollout: the cloud rehearsal in the morning (12 nodes, one chain through N + 600), then the devnet. Node 1, the observer node and the seed were restarted on the v2 binary with --override-params-file carrying {"difficulty_v2_activation_daa": 33000}; the three app machines received the same height through the signed update manifest (the engine writes it to the node's override file and restarts the node at a safe moment), the two PCs within two minutes of an update-now job, the Apple M5 Max on its next check; the height had first been set to 46,500 and was moved to 33,000 at 16:55 UTC by the same route. The height passed at 17:37 UTC: node 1 and the seed shared the sink (ab6bb0a7147b at block 33,291), the observer followed, both PCs' nodes processed blocks normally, difficulty kept moving (150.8M at the height, then stepping down as PC 2's card paused for a proving job). No node forked; no restart of the chain; a consensus rule changed under a running network with miners on three platforms. The first measurement of v2 on the devnet's own regime (two large miners, bursty parallel blocks) needs PC 2 back from its job; the cloud numbers stand meanwhile (settle 157 to 272 s, no swing).

+

Rollout: the cloud rehearsal in the morning (12 nodes, one chain through N + 600), then the devnet. Node 1, the observer node and the seed were restarted on the v2 binary with --override-params-file carrying {"difficulty_v2_activation_daa": 33000}; the three app machines received the same height through the signed update manifest (the engine writes it to the node's override file and restarts the node at a safe moment), the two PCs within two minutes of an update-now job, the Apple M5 Max on its next check; the height had first been set to 46,500 and was moved to 33,000 at 16:55 UTC by the same route. The height passed at 17:37 UTC: node 1 and the seed shared the sink (ab6bb0a7147b at block 33,291), the observer followed, both PCs' nodes processed blocks normally, difficulty kept moving (150.8M at the height, then stepping down as PC 2's card paused for a proving job). No node forked; no restart of the chain; a consensus rule changed under a running network with miners on three platforms. The first measurement of v2 on the devnet's own regime (two large miners, bursty parallel blocks) needs PC 2 back from its job; the cloud numbers stand meanwhile (settle 157 to 272 s, no swing).

+

4 October 2026, miner fault guards and the app watchdog measured against a fake worker (miner-community-lead, app owner)

+

Machine: Apple M5 Max, load average 17 to 92 (other agents' builds and runs throughout), everything at nice 19 under tools/lock/with-lock.sh run. These are recoveries and seconds, not hash rates: nothing here is a performance number. Private test networks only: one igneumd (devnet suffix 9950, ports 29950 to 29953) for the miner scenarios and the app's own private node (suffix 9960, ports 29960 and 29961) for the app scenarios; the live devnet was not touched. Worker: tools/reliability/fake-worker.mjs, a stand-in that speaks the serve protocol and misbehaves on command (jobs done in 0.3 ms, 0 hashes, silence, wrong hashes, refused prepares); it never hashes, so no block was found and the fake rate of about 157 MH/s inside jobs is an invented number. Miner: fork branch miner-reliability (aea5ac6d, 501363e0, 945153ab), igneum-miner release with --status-secs 10. App: app/igneum-app at f39e240 plus the card-message fix, IGNEUM_APP_STATUS_SECS=10. Harness: tools/reliability/run.mjs and app-run.mjs; every scenario states what must and must not appear, and the detectors were shown to fire on the faulting scenarios and stay quiet on the healthy stretches before any number below was kept.

+

Miner guards (review round 4 M26, M27, X21), one fresh miner process per scenario:

+
ScenarioWhat the worker didResultSeconds
slow-first (M26)5 s jobs for the first 25 s, then the true rate, 47x fasterone trip, one restart, STATUS lines every 10 s throughout (8 in 85 s, max gap 10.1 s), 4 healthy intervals after it with no further trip; the old guard tripped on every interval and printed nothingslow start to trip 40.1, trip to worker restarted 2.0
fake-fast (the gfx1036 fault)jobs "done" in 0.3 ms with the full countthe job-time guard fired on the first such job; STATUS with faults=1 printed after the trip; one restarttrip 0.0 after injection, worker restarted 2.0, ready 2.5, first healthy STATUS 12.5
fake-fast-staysthe same fault persiststrips at 0.2, 3.2, 8.7 s with restart delays 2 then 4 s; the third trip in the window ends the miner with exit 43 (WORKER FAULT 3 guard trips in 10 minutes)injection to exit 8.8
badfound (X21)a wrong hash on every found3 WORKER MISMATCH lines, then WORKER FAULT cpu re-check: 3 consecutive mismatches; 3 wrong shares seen, 0 submitted; STATUS shows mismatched=3; one restartfirst mismatch 0.3, trip 0.5, first healthy STATUS after the trip 2.9
silentstops answering with jobs queuedSTATUS lines kept printing during the silence (5; the old loop printed none and never restarted); the stall guard fired at 60 s; one restartsilence to trip 60.1, trip to first healthy STATUS 12.9
prepare-flap (M27)refuses every prepare across epochs of 60 DAA (a 3-thread CPU block producer on genesis bits 0x1f100000)5 epochs turned (333 blocks in 5 min); one PREPARE sent per epoch, each answered prepare-failed, each retry held (PREPARE held ... within 30 s of the last prepare) and the epoch turned before a retry was due: 5 sends, 5 held, 0 repeats; before the limiter a refused prepare was re-sent at the next job fill, a pack write and a GPU build each timesmallest gap between sends 50.6
+

Two defects the harness found on the way, both fixed on the branch: after a guard kill with the job queue not full, the fill loop's continue re-ran the failed stdin write forever (140,000 lines in 45 s, no restart, no STATUS; 501363e0); and the 60 s line-read timeout meant no STATUS line at all while a worker was silent (945153ab: the read now waits one status interval). The "first healthy STATUS" figures above are bounded by the 10 s status interval: the worker is back about 2.5 s after a trip, the next STATUS line reports it.

+

App watchdog (src/watchdog.rs), one engine run, the fake worker as the Metal worker, steps in order:

+
StepWhat happenedResultSeconds
own-restartthe worker reports jobs done in 0.3 msthe miner's guard restarted the worker; the card showed the fault and worker faults 1; the app did NOT restart the miner (same pid, app restarts 0)fault on the card 1.0 after injection, mining again 9.1 after the fault
zero-oncejobs complete with 0 hasheswatchdog: hash rate 0 for 60 s while the node is synced; one app restart; mining on the new miner processzero to restart 79.6 (60 s rule plus the status interval and the quit grace), restart to mining 11.3, zero to mining 91.0
zero-faultedthe same again inside five minutescard faulted: hash rate 0 for 60 s while the node is synced (restarted once already); 45 s later still faulted, no miner process, no further restart; the node kept running and the app stayed up; resume cleared it and mining resumedzero to faulted 75.4
no-statusthe miner process stopped with SIGSTOPwatchdog: no status line from the miner for 90 s; the stopped process killed; mining on a new processquiet to restart 90.4, restart to mining 11.0
node-silentthe node process stopped with SIGSTOPthe app restarted the node in-process (the remote-job restart kind), the new node synced, mining resumedquiet to restart 150.7 (120 s rule plus the 30 s terminate grace on a process that cannot answer SIGTERM), restart to synced 7.2, quiet to mining 160.0
+

Not measured: any real GPU. The job-time and interval guards, exit 43 and the app's faulted card have not run on an RTX 5090, the gfx1036 or a Metal card; the first real run is owed from the fleet logs. The "no status" rule has not been tried against a hung RPC (only a stopped process). Unit tests: cargo test -p igneum-miner -- guard (7) and cargo test -- watchdog in app/igneum-app (11), both replaying recorded STATUS and WORKER FAULT lines.

diff --git a/tools/reliability/app-run.mjs b/tools/reliability/app-run.mjs index 49f0f6d62..2b9ef375f 100755 --- a/tools/reliability/app-run.mjs +++ b/tools/reliability/app-run.mjs @@ -118,7 +118,7 @@ S['own-restart'] = async () => { const st1 = await poll(); verdict('own-restart', [ { ok: !!st0, what: 'the card mined with a rate above 0 on the fake worker' }, - { ok: !!faulted && /worker fault/.test(card(faulted).message || ''), what: `the card showed the WORKER FAULT reason (${JSON.stringify(card(faulted || {}).message)})` }, + { ok: !!faulted && /worker fault|killed by a guard/.test(card(faulted).message || ''), what: `the card showed the worker fault (${JSON.stringify(card(faulted || {}).message)})` }, { ok: !!back, what: 'mining resumed after the miner restarted its own worker' }, { ok: st1 && card(st1).pid === pid0 && card(st1).restarts === r0, what: `the app did not restart the miner (pid ${pid0} -> ${card(st1 || {}).pid}, app restarts ${r0} -> ${card(st1 || {}).restarts})` }, ], { inject_to_fault_on_card: s(tFault - tInject), fault_to_mining_again: s(tBack - tFault) }); diff --git a/tools/reliability/run.mjs b/tools/reliability/run.mjs index 945dc8484..5afd8ede7 100755 --- a/tools/reliability/run.mjs +++ b/tools/reliability/run.mjs @@ -13,14 +13,14 @@ // 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 (the block producer), the worker refuses every prepare: at most two +// 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 } from 'node:fs'; +import { mkdirSync, rmSync, writeFileSync, existsSync, appendFileSync, readFileSync } from 'node:fs'; import { fileURLToPath } from 'node:url'; import { dirname, join } from 'node:path'; @@ -82,7 +82,13 @@ function startMiner(secs, extra = []) { log(`miner pid ${p.pid} log ${f}`); return m; } -const find = (m, re, after = 0) => m.lines.filter(l => l.t >= after && re.test(l.text)); +// 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); } @@ -112,12 +118,17 @@ S['slow-first'] = async () => { 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 === 0, what: `no WORKER FAULT after a slow first interval (saw ${faults.length})` }, + { 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))})` }, - ], { status_lines: status.length, faults: faults.length }); + { 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 () => { @@ -129,7 +140,7 @@ S['fake-fast'] = async () => { setMode('fast'); const fault = await waitFor(m, /WORKER FAULT/, 60000, tInject); if (fault) setMode('ok'); - const killed = await waitFor(m, /worker killed by a guard/, 20000, tInject); + 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 @@ -142,8 +153,9 @@ S['fake-fast'] = async () => { await sleep(15000); stop(m); const statusAfterFault = fault ? find(m, / STATUS '.*faults=[1-9]/, fault.t) : []; - const faultsTotal = find(m, /WORKER FAULT/).filter(l => !l.err).length; + 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)' }, @@ -168,8 +180,8 @@ S['fake-fast-stays'] = async () => { setMode('fast'); const end = Date.now() + 300000; while (m.exit === null && Date.now() < end) await sleep(500); - const faults = find(m, /WORKER FAULT/).filter(l => !l.err); - const delays = find(m, /restarting it in (\d+) s/).map(l => Number(/restarting it in (\d+) s/.exec(l.text)[1])); + 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})` }, @@ -188,7 +200,7 @@ S['badfound'] = async () => { await sleep(15000); const tInject = Date.now(); setMode('badfound'); - const mism = await waitFor(m, /WORKER MISMATCH/, 30000, tInject); + 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); @@ -201,8 +213,9 @@ S['badfound'] = async () => { } await sleep(12000); stop(m); + if (!restarted) recovered = null; const statusMism = find(m, / STATUS '.*mismatched=[1-9]/); - const mismCount = find(m, /WORKER MISMATCH/).length; + 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)' }, @@ -235,6 +248,7 @@ S['silent'] = async () => { } 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' }, @@ -250,9 +264,11 @@ S['silent'] = async () => { 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}`, '2', '400', 'cpu', '--engine', 'igneum-pow', '--no-vote', '--payout-label', 'cpu'], { stdio: ['ignore', 'ignore', 'ignore'] }); + 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); @@ -260,7 +276,7 @@ S['prepare-flap'] = async () => { 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/); + 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 = []; @@ -279,11 +295,11 @@ S['prepare-flap'] = async () => { { 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 }); + ], { 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: '0x1f010000' }); +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; }