From 5d021c5e34c0f224a0c0529c84f59b9d025eb5ab Mon Sep 17 00:00:00 2001 From: igneum-labs <337424239+igneum-labs@users.noreply.github.com> Date: Wed, 7 Oct 2026 18:18:43 +0000 Subject: [PATCH] MF-14: a worker never waits on the program export longer than one retry interval without the reason shown PC 2, 7 October 2026 18:34 BST: two rows sat on "exporting this hour's program" for 18 minutes while a third card mined. The export ran on a thread per card under one lock with no bound on the wait, and a result that never came left the slot in the building state for ever. - watchdog::export_wait: inside one interval (the ladder rung, at least 30 s) the row keeps its word; past it the row names what blocks the export; past two intervals the wait ends and the worker retries on its own interval. - engine: EXPORT_HOLDER names the card whose export holds the pack lock and for how long, EXPORT_LAST_ERROR the last failure (the node not at the epoch, no seeds.txt); export_blocker() reads them for the row; build_seq ignores a late result after the wait ended; a failed export retries on the ladder, never a flat five minutes. - docs/plans/miner-faults.md: MF-14 with rule, test and gate line. Test known-failed first: an export that never returns is named at one interval and given up at two. Gates: app tests 260 + 33 + 8 green on igneum-build-2; the tree gate GREEN, 56 checks. Co-Authored-By: Claude Fable 5.1 --- app/igneum-app/src/engine.rs | 90 ++++++++++++++++++++++++++++++---- app/igneum-app/src/watchdog.rs | 48 ++++++++++++++++++ docs/plans/miner-faults.md | 1 + 3 files changed, 130 insertions(+), 9 deletions(-) diff --git a/app/igneum-app/src/engine.rs b/app/igneum-app/src/engine.rs index 2e98ca445..51ceaf48d 100644 --- a/app/igneum-app/src/engine.rs +++ b/app/igneum-app/src/engine.rs @@ -58,7 +58,8 @@ pub enum Cmd { Job(crate::jobrun::Event), JobsAllow(bool), JobsCheck, - WorkerBuilt(usize, Result), + /// (card index, the ask's sequence, the result): a result whose sequence is not the slot's current ask is ignored (MF-14) + WorkerBuilt(usize, u64, Result), /// local minus the latest block's timestamp, seconds (from the node's EVM RPC) ClockSample(f64), /// the node readiness probe answered (src/execrpc.rs probe): did the RPC answer, does the exec follower hold a record @@ -640,6 +641,9 @@ struct MinerSlot { starts: u32, restarts: u32, building: bool, + /// MF-14: when the export or build was asked, and its sequence (a result from an earlier ask is ignored) + building_since: Option, + build_seq: u64, needs_rebuild: bool, prepared: bool, // the pack is exported (and the worker built) for the next start last_status: Option, @@ -1164,9 +1168,15 @@ impl Engine { self.job_action(a); } } - Cmd::WorkerBuilt(card, result) => { + Cmd::WorkerBuilt(card, seq, result) => { if let Some(m) = self.miners.iter_mut().find(|m| m.card == card) { + if seq != m.build_seq { + // a late answer from an export the wait rule already gave up on (MF-14): nothing to apply + self.shared.log(&format!("miner {}: a late export result (ask {seq}, now {}) ignored", m.label, m.build_seq)); + return; + } m.building = false; + m.building_since = None; match result { Ok(p) => { if p != m.worker { @@ -1178,11 +1188,15 @@ impl Engine { m.restart_at = Some(Instant::now()); } Err(e) => { - self.shared.event("error", &format!("worker build failed: {e}")); - m.restart_at = Some(Instant::now() + Duration::from_secs(300)); + // MF-14: on the ladder, the reason on the row, never a flat five minutes + let attempt = m.watch.watchdog_restarts().saturating_add(1); + let delay = crate::watchdog::retry_delay_s(attempt); + self.shared.event("error", &format!("worker build failed: {e}; retry in {delay} s")); + m.restart_at = Some(Instant::now() + Duration::from_secs(delay)); if let Some(c) = self.st().mining.cards.get_mut(card) { - c.state = "failed".into(); - c.message = e; + c.state = "restarting".into(); + c.restart_in_s = delay; + c.message = format!("{e}; retry in {delay} s"); } } } @@ -2236,6 +2250,8 @@ impl Engine { starts: 0, restarts: 0, building: false, + building_since: None, + build_seq: 0, needs_rebuild, prepared: false, last_status: None, @@ -2414,6 +2430,9 @@ impl Engine { fn prepare_worker(&mut self, i: usize) { let card_idx = self.miners[i].card; self.miners[i].building = true; + self.miners[i].building_since = Some(Instant::now()); + self.miners[i].build_seq = self.miners[i].build_seq.wrapping_add(1); + let seq = self.miners[i].build_seq; let build = self.miners[i].needs_rebuild; if let Some(c) = self.st().mining.cards.get_mut(card_idx) { c.state = "starting".into(); @@ -2424,9 +2443,10 @@ impl Engine { let vendor = self.st().mining.cards.get(card_idx).map(|c| c.vendor.clone()).unwrap_or_default(); let worker = self.miners[i].worker.clone(); let force = std::mem::take(&mut self.miners[i].pack_force); + let label = self.miners[i].label.clone(); std::thread::spawn(move || { - let r = if build { build_worker_from_source(&shared, &bins, &vendor) } else { export_pack(&shared, &bins, force).map(|_| worker) }; - shared.send(Cmd::WorkerBuilt(card_idx, r)); + let r = if build { build_worker_from_source(&shared, &bins, &vendor) } else { export_pack(&shared, &bins, force, &label).map(|_| worker) }; + shared.send(Cmd::WorkerBuilt(card_idx, seq, r)); }); } @@ -4431,6 +4451,35 @@ impl Engine { continue; } if self.miners[i].building { + // MF-14: a worker never waits on the export longer than one retry interval without the reason shown; + // past two intervals the wait ends and the worker retries on its own interval, the other cards untouched + let waited = self.miners[i].building_since.map(|t| now.duration_since(t).as_secs_f64()).unwrap_or(0.0); + let interval = crate::watchdog::retry_delay_s(self.miners[i].watch.watchdog_restarts().saturating_add(1)) as f64; + let blocker = export_blocker(&self.miners[i].label); + match crate::watchdog::export_wait(waited, interval, &blocker) { + crate::watchdog::ExportWait::Waiting => {} + crate::watchdog::ExportWait::Say(line) => { + if let Some(c) = self.st().mining.cards.get_mut(card_idx) { + if c.message != line { + c.message = line.clone(); + self.shared.log(&format!("miner {}: {line}", self.miners[i].label)); + } + } + } + crate::watchdog::ExportWait::GiveUp(reason) => { + self.miners[i].building = false; + self.miners[i].building_since = None; + self.miners[i].build_seq = self.miners[i].build_seq.wrapping_add(1); // the thread's answer is ignored + let t = self.secs(now); + let verdict = self.miners[i].watch.event(t, crate::watchdog::Event::Exited(crate::watchdog::MINER_GAVE_UP_CODE)); + let v = match verdict { + crate::watchdog::Action::Restart { delay_s, attempt, .. } => crate::watchdog::Action::Restart { reason: reason.clone(), delay_s, attempt }, + _ => crate::watchdog::Action::Restart { reason: reason.clone(), delay_s: crate::watchdog::retry_delay_s(1), attempt: 1 }, + }; + self.watchdog_verdict(i, v, &[]); + self.miners[i].prepared = false; + } + } continue; } if let Some(at) = self.miners[i].restart_at { @@ -5891,6 +5940,21 @@ fn civil_from_days(z: i64) -> (i64, u32, u32) { /// OpenCL worker start then refused ("the epoch seed bytes do not give the pack's IGNEUM_SEEDW_INIT") until the next /// export. The second export of a pair rewrites the same pack, which is harmless. static EXPORT_LOCK: std::sync::Mutex<()> = std::sync::Mutex::new(()); +/// MF-14: who holds the export now (the miner label and since when) and the last export's error, for the row of a +/// card that waits behind it. +static EXPORT_HOLDER: std::sync::Mutex> = std::sync::Mutex::new(None); +static EXPORT_LAST_ERROR: std::sync::Mutex> = std::sync::Mutex::new(None); + +/// What blocks `label`'s export now, in plain words, or empty. +fn export_blocker(label: &str) -> String { + if let Some((who, since)) = EXPORT_HOLDER.lock().unwrap_or_else(|e| e.into_inner()).clone() { + if who != label { + return format!("another card's export holds the pack lock ({who}, {} s)", since.elapsed().as_secs()); + } + return format!("this card's export is still running ({} s)", since.elapsed().as_secs()); + } + EXPORT_LAST_ERROR.lock().unwrap_or_else(|e| e.into_inner()).clone().map(|e| format!("the last export failed: {e}")).unwrap_or_default() +} /// When the pack was last exported: an export under `EXPORT_REUSE_S` old is reused unless forced (MF-4, 7 October /// 2026: a card whose worker failed every few seconds exported on every restart and held two healthy cards in /// "loading the program" past the watchdog). @@ -5900,8 +5964,16 @@ const EXPORT_REUSE_S: u64 = 60; /// Exports this hour's program pack from the node to \packs\devnet (the prebuilt workers read it with --pack). /// One export per minute serves every card; `force` (a refused pack) exports again now. #[allow(unused_variables)] -fn export_pack(shared: &Arc, bins: &Bins, force: bool) -> Result<(), String> { +fn export_pack(shared: &Arc, bins: &Bins, force: bool, label: &str) -> Result<(), String> { let _one_at_a_time = EXPORT_LOCK.lock().unwrap_or_else(|e| e.into_inner()); + *EXPORT_HOLDER.lock().unwrap_or_else(|e| e.into_inner()) = Some((label.to_string(), Instant::now())); + let r = export_pack_locked(shared, bins, force); + *EXPORT_HOLDER.lock().unwrap_or_else(|e| e.into_inner()) = None; + *EXPORT_LAST_ERROR.lock().unwrap_or_else(|e| e.into_inner()) = r.as_ref().err().cloned(); + r +} + +fn export_pack_locked(shared: &Arc, bins: &Bins, force: bool) -> Result<(), String> { let pack = shared.runtime.app_dir.join("packs").join("devnet"); let _ = std::fs::create_dir_all(&pack); if !force && pack.join("seeds.txt").exists() { diff --git a/app/igneum-app/src/watchdog.rs b/app/igneum-app/src/watchdog.rs index cec7068aa..4df6b33bf 100644 --- a/app/igneum-app/src/watchdog.rs +++ b/app/igneum-app/src/watchdog.rs @@ -42,6 +42,34 @@ pub const EARLY_EXIT_S: f64 = 120.0; /// A card whose worker failed its self-test is held this long before the next try (or until its driver changes). pub const SELF_TEST_HOLD_S: u64 = 1800; +/// MF-14 (PC 2, 7 October 2026 18:34 BST: two rows sat on "exporting this hour's program" for 18 minutes while a third +/// card mined): a worker never waits on the program export longer than one retry interval without the reason shown; +/// past two intervals the wait is over, the row names what blocked it and the worker retries on its own interval. +#[derive(Debug, Clone, PartialEq, Eq)] +pub enum ExportWait { + /// inside one interval: the row keeps "exporting this hour's program" + Waiting, + /// past one interval: the row says how long and what blocks the export + Say(String), + /// past two intervals: the wait ends; the reason, for the restart on the ladder + GiveUp(String), +} + +/// `waited_s` since the export was asked, `interval_s` the card's current retry interval (the ladder rung, at least +/// 30 s), `blocker` what holds the export now (another card's export, the pack directory lock, the node not at the +/// epoch, the last export error), or empty when nothing is known. +pub fn export_wait(waited_s: f64, interval_s: f64, blocker: &str) -> ExportWait { + let interval = interval_s.max(30.0); + let what = if blocker.trim().is_empty() { "the export has not returned".to_string() } else { blocker.trim().to_string() }; + if waited_s >= 2.0 * interval { + ExportWait::GiveUp(format!("the program export did not return in {} s ({what}); the worker retries on its own interval", waited_s as u64)) + } else if waited_s >= interval { + ExportWait::Say(format!("exporting this hour's program: {} s so far ({what})", waited_s as u64)) + } else { + ExportWait::Waiting + } +} + /// The delay before restart number `attempt` (1-based) of a card: the ladder, then its last step for ever. pub fn retry_delay_s(attempt: u32) -> u64 { let i = (attempt.max(1) as usize - 1).min(RETRY_LADDER_S.len() - 1); @@ -823,6 +851,26 @@ mod tests { assert_eq!(w.watchdog_restarts(), 0); } + /// MF-14: known-failed first (an export that never returns), then the known-good shapes. + #[test] + fn an_export_that_never_returns_is_named_and_given_up_within_two_intervals() { + // the PC 2 shape: 18 minutes on "exporting" behind another card's export; with a 30 s interval the row + // names the blocker at 30 s and the wait ends at 60 s + assert_eq!(export_wait(31.0, 30.0, "another card's export holds the pack lock (Intel Arc B580, 31 s)"), ExportWait::Say("exporting this hour's program: 31 s so far (another card's export holds the pack lock (Intel Arc B580, 31 s))".into())); + match export_wait(1080.0, 30.0, "") { + ExportWait::GiveUp(r) => { assert!(r.starts_with("the program export did not return in 1080 s (the export has not returned)")); assert!(r.ends_with("retries on its own interval")); } + other => panic!("{other:?}"), + } + assert!(matches!(export_wait(60.0, 30.0, "the node is not at the epoch yet"), ExportWait::GiveUp(_))); + // a normal export (5 to 25 s) says nothing + assert_eq!(export_wait(5.0, 30.0, ""), ExportWait::Waiting); + assert_eq!(export_wait(25.0, 120.0, ""), ExportWait::Waiting); + // a longer rung widens the wait, never below 30 s + assert_eq!(export_wait(100.0, 120.0, "x"), ExportWait::Waiting); + assert!(matches!(export_wait(125.0, 120.0, "x"), ExportWait::Say(_))); + assert!(matches!(export_wait(45.0, 10.0, "x"), ExportWait::Say(_)), "the floor is 30 s even on the 10 s rung"); + } + #[test] fn a_deliberate_stop_is_not_a_fault() { let mut w = CardWatch::new(); diff --git a/docs/plans/miner-faults.md b/docs/plans/miner-faults.md index c576c8fbc..ddd4d4c29 100644 --- a/docs/plans/miner-faults.md +++ b/docs/plans/miner-faults.md @@ -35,6 +35,7 @@ Standing rules behind every row (branch `miner-reliability`, off `release-0.3.19 | MF-11 | 7 Oct 2026, PC 2 (1ccfe586), silent from 10:46Z after the 0.3.19 update-now (the update-return lane's row; code on update-return 0b423697, the app half on update-return-21b a64c193f) | The app did not come back and nothing reached the PC for hours; the only recovery was a hand on the power button; the stale relay logon task popped "Windows cannot find 'igneum-agent'" at every boot | A power loss or hard reset of the whole PC (Kernel-Power 41, EventLog 6008, no BugCheck 1001, no minidump; three such events that day, the third with the 5060 Ti enclosure attached and no TDR, WHEA or Thunderbolt trace), while the update itself had returned in 10 s (10:34:28Z quit, 10:34:38Z "[ok] updated to 0.3.19"); the relay agent dead since 6 October behind a UAC prompt; the Windows helper's return path checked nothing after the installer's exit; the tuner at 575 W with proving on the same card nine minutes before the first drop | (1) the helper owns the return: exe set kept beside the app, the app launched by the helper (/IGNOTA=2), api/state polled 120 s, the kept set restored, one intake line either way; the host restarts a dead engine and answers the Restart Manager; the first act after an update is the read-back line; a boot after a power loss posts FAULT pc-restart; (2) the relay agent as the per-user logon task IgneumRelayService (LeastPrivilege, no UAC, restart on failure, full path, stale IgneumRelayAgent* removed), the start-app kind, the per-install hostname; (3) every wake request carries the ping; the console says "job channel silent since