From 309980b62c2ad6487ab5786f690c64a6a1930db8 Mon Sep 17 00:00:00 2001 From: Joakim Persson Date: Thu, 10 Sep 2026 20:48:33 +0200 Subject: [PATCH] fix(pi-ext): stop the feed tick from launching overlapping mines "[mempalace ext] feed (tick) failed: mine timed out after 30000ms" was parked as cosmetic on 2026-08-27. It is not cosmetic: the tight deadline was the trigger, but the defect is a positive feedback loop that puts multiple writers on a single-writer palace. lastFeedAt was assigned only AFTER a successful await. The Promise.race abandons our WAIT and cannot cancel the server's work, so on a mine that takes longer than the deadline -- measured at 30-60s in normal operation, against a 30s deadline -- the catch ran with lastFeedAt UNCHANGED. That left both guards in the agent_settled handler open at once: the debounce test (`Date.now() - lastFeedAt < feedDebounceMs`) passed because lastFeedAt was still stale, and feedInFlight was already null because `run` had settled. Every subsequent settled turn therefore launched another mine on top of the one still running, each making the next slower and the next timeout likelier -- which is why operators saw the message many times per session instead of at most once per 10-minute debounce window. Fix, three lines: - move `lastFeedAt = Date.now()` to before the await, so a timeout still starts the debounce clock. A timeout is not a "did not happen": the mine is running server-side and `mine --mode convos` dedups by source_file and is idempotent. - raise MEMPALACE_FEED_MINE_TIMEOUT_MS from 30_000 to 300_000. The mine is the slowest thing this extension does yet carried the tightest deadline: 4x tighter than the prepare step before it (120_000) and 10x tighter than the init handshake (300_000), a fast call. All three were introduced together in 29e660e and this one was never revisited. 300_000 matches the init timeout because liveness is the only job left for this deadline -- it cannot cancel the server's work, so it must sit far above the slowest honest completion. Simulated both guards over 10 minutes of settled turns at 20s intervals with a 60s mine: BEFORE 16 mines launched, 15 of them overlapping an already-running mine; AFTER 2 launched, 0 overlapping. With a mine that exceeds even the new deadline (400s): BEFORE 16/15, AFTER still 2/0 -- the lastFeedAt move is what actually fixes it, and it holds even when the timeout still fires. The raise stops the spurious message; the move stops the pile-up. NOT fixed here: the message still goes to process.stderr, which pi renders into the TUI input field. That needs a pi-side channel or a log file, and is tracked separately. After this change the message should be rare, and when it does appear it means something real: a mine exceeding five minutes. --- extensions/pi/mempalace.ts | 35 +++++++++++++++++++++++++++++++++-- 1 file changed, 33 insertions(+), 2 deletions(-) diff --git a/extensions/pi/mempalace.ts b/extensions/pi/mempalace.ts index 1371116..58d699d 100644 --- a/extensions/pi/mempalace.ts +++ b/extensions/pi/mempalace.ts @@ -855,7 +855,22 @@ export default async function mempalaceExtension(pi: ExtensionAPI) { const feedWing = process.env.MEMPALACE_FEED_WING ?? "wing_conversations"; const feedDebounceMs = num(process.env.MEMPALACE_FEED_DEBOUNCE_MS, 600_000); const feedPrepareTimeoutMs = num(process.env.MEMPALACE_FEED_PREPARE_TIMEOUT_MS, 120_000); - const feedMineTimeoutMs = num(process.env.MEMPALACE_FEED_MINE_TIMEOUT_MS, 30_000); + // 300_000, raised from 30_000 on 2026-09-10. The mine is the SLOWEST thing + // this extension does — it offers every qualifying session transcript to a + // SINGLE-WRITER palace, measured at 30–60s in normal operation and growing + // with the corpus — yet it carried by far the TIGHTEST deadline: 4x tighter + // than the prepare step that precedes it (120_000) and 10x tighter than the + // init handshake (300_000), which is a fast call. All three were introduced + // together in 29e660e (2026-08-12) and this one was never revisited, so the + // deadline fired during entirely normal operation and the resulting message + // read as an error when nothing had gone wrong. + // + // Matched to the init timeout because liveness is the ONLY legitimate job + // left for this deadline: the Promise.race below abandons our WAIT, it cannot + // cancel the server's work, so the deadline buys nothing except an escape + // from a permanently hung call. It must therefore sit far above the slowest + // honest completion, not near it. + const feedMineTimeoutMs = num(process.env.MEMPALACE_FEED_MINE_TIMEOUT_MS, 300_000); let lastFeedAt = 0; // 0 => the first settled turn also acts as a catch-up let feedInFlight: Promise | null = null; @@ -909,6 +924,23 @@ export default async function mempalaceExtension(pi: ExtensionAPI) { try { const source = await prepareFeed(reason); if (!source) return; + // Record the attempt HERE, before awaiting — not after a successful + // wait. The race below abandons only our WAIT; the mine keeps running + // server-side, and `mine --mode convos` dedups by source_file and is + // idempotent, so a timeout is emphatically not a "did not happen". + // + // Leaving lastFeedAt stale on the timeout path defeated the debounce + // guard in the agent_settled handler below (`Date.now() - lastFeedAt < + // feedDebounceMs`): with lastFeedAt unchanged that guard passed on EVERY + // settled turn, and because `run` had already settled, feedInFlight was + // null too — so BOTH guards stood open. Each settled turn then launched + // another mine while the previous one was still running: overlapping + // writers queueing on a single-writer palace, each making the next one + // slower and the next timeout likelier. That positive feedback loop, + // not the tight deadline by itself, is why operators saw "mine timed out + // after 30000ms" many times per session rather than at most once per + // debounce window. + lastFeedAt = Date.now(); await Promise.race([ client.callTool("mempalace_mine", { source, @@ -927,7 +959,6 @@ export default async function mempalaceExtension(pi: ExtensionAPI) { ), ), ]); - lastFeedAt = Date.now(); } catch (err) { process.stderr.write( `[mempalace ext] feed (${reason}) failed: ${(err as Error).message}\n`,