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.
This commit is contained in:
Joakim Persson
2026-09-10 20:48:33 +02:00
parent e2b060a940
commit 309980b62c
+33 -2
View File
@@ -855,7 +855,22 @@ export default async function mempalaceExtension(pi: ExtensionAPI) {
const feedWing = process.env.MEMPALACE_FEED_WING ?? "wing_conversations"; const feedWing = process.env.MEMPALACE_FEED_WING ?? "wing_conversations";
const feedDebounceMs = num(process.env.MEMPALACE_FEED_DEBOUNCE_MS, 600_000); const feedDebounceMs = num(process.env.MEMPALACE_FEED_DEBOUNCE_MS, 600_000);
const feedPrepareTimeoutMs = num(process.env.MEMPALACE_FEED_PREPARE_TIMEOUT_MS, 120_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 lastFeedAt = 0; // 0 => the first settled turn also acts as a catch-up
let feedInFlight: Promise<void> | null = null; let feedInFlight: Promise<void> | null = null;
@@ -909,6 +924,23 @@ export default async function mempalaceExtension(pi: ExtensionAPI) {
try { try {
const source = await prepareFeed(reason); const source = await prepareFeed(reason);
if (!source) return; 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([ await Promise.race([
client.callTool("mempalace_mine", { client.callTool("mempalace_mine", {
source, source,
@@ -927,7 +959,6 @@ export default async function mempalaceExtension(pi: ExtensionAPI) {
), ),
), ),
]); ]);
lastFeedAt = Date.now();
} catch (err) { } catch (err) {
process.stderr.write( process.stderr.write(
`[mempalace ext] feed (${reason}) failed: ${(err as Error).message}\n`, `[mempalace ext] feed (${reason}) failed: ${(err as Error).message}\n`,