From 2cb9173079f325ef5330bc7b5d5384a23a42ca40 Mon Sep 17 00:00:00 2001 From: Lan Nguyen Si Date: Sun, 16 Aug 2026 23:06:12 +0200 Subject: [PATCH 1/2] agent-memory-sync: fix macOS fs.watch arming race in watch integration test triggers (partial) Root-caused the pre-existing watch-trigger stall (agent-tasks f876dff6): a bare fs.watch() on macOS can silently and permanently miss a write issued immediately after the watch reports armed (nodejs/node#52601), independent of chokidar and independent of CPU load - proven via an isolated repro bypassing both. Fix lives on the test side since no deadline size can recover a lost event: applyTriggerWithRetry re-applies a trigger edit until a progress signal confirms it landed, budgeted well under the unmodified 90s inactivity deadline. deleteRetrySafe makes the two delete-based triggers safe to retry. This measurably fixes the proven mechanism, but an interleaved matched-control run under the full documented load scenario still failed repeatedly on two specific tests on both the fixed and unmodified arms. One failure's raw output showed evidence of a second, different mechanism this change does not fix: the parent test-runner's own delayed stderr-pipe read under heavy contention, which can make an already-completed tick look like a stall. Left open with instrumentation notes in tests/helpers/watch-process.ts for a follow-up. --- packages/agent-memory-sync/CHANGELOG.md | 1 + .../agent-memory-sync/src/commands/watch.ts | 24 ++- .../agent-memory-sync/tests/helpers/cli.ts | 25 ++- .../tests/helpers/watch-process.ts | 204 +++++++++++++++++- .../integration/watch-mirror-delete.test.ts | 20 +- .../tests/integration/watch-restore.test.ts | 8 +- .../unit/watch-process-trigger-retry.test.ts | 124 +++++++++++ 7 files changed, 385 insertions(+), 21 deletions(-) create mode 100644 packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts diff --git a/packages/agent-memory-sync/CHANGELOG.md b/packages/agent-memory-sync/CHANGELOG.md index d0fc265..f966d5f 100644 --- a/packages/agent-memory-sync/CHANGELOG.md +++ b/packages/agent-memory-sync/CHANGELOG.md @@ -14,3 +14,4 @@ is dated instead. The format is loosely based on - `withTickDeadline` (test helper) gained an inactivity mode: it resets its deadline on either the ready line or the new push-start line, so a per-tick test budget bounds the gap since the last observed signal instead of the tick's total duration. A second, independent absolute cap (2.5x the inactivity budget) still bounds a tick that keeps signaling forever, failing with a distinct message. - A pre-existing failure class under this package's documented load scenario stalls before either progress signal can fire: a chokidar filesystem-event delivery issue under CPU contention, present at the merge base too, at roughly a 30-40% failure rate under load on both. No timeout size fixes this; it is out of scope for this change and tracked as a follow-up. - New unit tests in `tests/unit/watch-process-inactivity.test.ts` pin the inactivity and absolute-cap semantics directly, without a real spawn. +- Partially root-caused and partially fixed the follow-up above (agent-tasks f876dff6, status: partial — see that task's final report for full detail). Isolated outside chokidar entirely (a standalone script, no test harness), a bare `fs.watch()` on macOS can silently and permanently miss a write issued immediately after the watch is reported armed — Node's own documented, currently-unfixed behavior (nodejs/node#52601). Not a chokidar bug, and neither the "polling vs fsevents" nor "atomic-write visibility" candidates from that follow-up's brief were actually in play: chokidar 4.x (this package's version) has no `fsevents` dependency and uses neither polling nor fsevents by default, and every trigger edit in this suite already writes in place, never via atomic rename. This confirmed mechanism is fixed on the test side: `applyTriggerWithRetry` (test helper) re-applies a trigger edit if no progress signal appears within a confirm window, budgeted up to 70s total (well under the unmodified 90s inactivity deadline), since a fresh write reliably clears this specific race (measured in isolation: always lost at 0ms after arming, always caught at >=5ms, idle or under a 10-12 worker synthetic CPU load alike). `runWatchTick` and the two direct offline/online spawns in `watch-mirror-delete.test.ts`'s queue-replay test now go through it; the two delete-based trigger edits use the new `deleteRetrySafe` test helper (recreate-then-delete) instead of a bare `rmSync`, which is not safe to retry once the target is already gone. However, an interleaved matched-control measurement of the full 3-file watch integration suite under the documented load scenario still failed repeatedly on the same two tests on BOTH the fixed and unmodified arms, and inspecting one failure's raw output found evidence of a SECOND, different mechanism not fixed here: the parent test-runner process's own delayed reading of the child's stderr pipe under heavy contention, which can make an already-completed tick look like a permanent stall — not fixable by retrying the trigger edit. See `tests/helpers/watch-process.ts`'s "MEASURED RESULT AND A SECOND, DIFFERENT OPEN MECHANISM" comment and `src/commands/watch.ts`'s ready-line comment for detail. New unit tests in `tests/unit/watch-process-trigger-retry.test.ts` pin the retry/give-up semantics of the fixed mechanism directly, without a real spawn. diff --git a/packages/agent-memory-sync/src/commands/watch.ts b/packages/agent-memory-sync/src/commands/watch.ts index b8cee12..b88f173 100644 --- a/packages/agent-memory-sync/src/commands/watch.ts +++ b/packages/agent-memory-sync/src/commands/watch.ts @@ -287,11 +287,25 @@ function registerWatchCommand(program: import("commander").Command): void { // inotify-backed watcher (Linux) that scan is not instantaneous, and a // filesystem write issued before it completes can be silently missed — // chokidar has not finished wiring up inotify watch descriptors for - // every (possibly nested) watched path yet. A caller that treats this - // line as the "watch is now armed" signal (e.g. an integration test - // triggering an edit) is therefore safe on both fsevents (macOS) and - // inotify (Linux) once the line has actually printed, where a fixed - // sleep() before that point is not. + // every (possibly nested) watched path yet. This line is a large + // improvement over an unconditional sleep() before it, but is NOT a + // complete guarantee on macOS: this package's chokidar version (^4.0.3) + // depends on neither `fsevents` nor `usePolling` by default (v4 dropped + // the optional `fsevents` native dependency entirely and watches + // exclusively via Node's own fs.watch/fs.watchFile), and on macOS a + // freshly-created fs.watch() can still miss a write issued immediately + // after it returns — a currently-unfixed Node.js/libuv behavior + // (nodejs/node#52601, "Not possible to know when fs.watch has started + // on macOS"), independent of chokidar's own initial-scan/'ready' + // bookkeeping. Measured in tests/helpers/watch-process.ts's "ROOT + // CAUSE" comment (agent-tasks f876dff6): a write 0ms after the watch + // is reported armed is lost 100% of the time in isolation, on both a + // bare fs.watch() and this exact chokidar config, idle or under load; + // any real delay (>=5ms measured here) resolves it 100% of the time. + // The mitigation for that residual race lives entirely on the test + // side (retrying a stalled trigger edit rather than waiting longer), + // since Node exposes no stronger "truly armed" signal this line could + // wait for instead. watcher.on("ready", () => { writeInfo( `watching ${watchedPaths.length} path(s) under ${runConfig.rootDir} (debounce ${debounceMs}ms)`, diff --git a/packages/agent-memory-sync/tests/helpers/cli.ts b/packages/agent-memory-sync/tests/helpers/cli.ts index 9885ecc..eaf12e8 100644 --- a/packages/agent-memory-sync/tests/helpers/cli.ts +++ b/packages/agent-memory-sync/tests/helpers/cli.ts @@ -1,5 +1,5 @@ const { execFileSync, spawnSync } = require("node:child_process"); -const { existsSync, mkdirSync, readFileSync, writeFileSync } = require("node:fs"); +const { existsSync, mkdirSync, readFileSync, rmSync, writeFileSync } = require("node:fs"); const { tmpdir } = require("node:os"); const path = require("node:path"); @@ -71,6 +71,26 @@ function fileExists(filePath: string): boolean { return existsSync(filePath); } +// Recreates `filePath` with placeholder content immediately before deleting +// it, instead of a bare `rmSync`. The net effect on disk and in watch.ts's +// own pendingChanges/pendingDeletes bookkeeping is identical to a plain +// delete: only the FINAL absence matters to performPush's diff, and +// watch.ts's unlink handler unconditionally does both +// `pendingDeletes.add(filePath)` and `pendingChanges.delete(filePath)`, so an +// add-then-unlink of the SAME path collapses down to just "deleted" either +// way (src/commands/watch.ts). What this buys over a bare `rmSync`: it makes +// the edit safe to invoke more than once. A repeated `rmSync` on an +// already-deleted path either throws ENOENT or (with `{ force: true }`) is a +// silent no-op — either way it produces no fresh filesystem event, so it +// cannot help a caller recover from watch-process.ts's applyTriggerWithRetry +// re-issuing a trigger edit whose first attempt's underlying fs-event was +// lost to the arming race documented there (tests/helpers/watch-process.ts). +// Recreating first always gives the retry something real to delete again. +function deleteRetrySafe(filePath: string): void { + writeText(filePath, "(retry-safe placeholder before delete)\n"); + rmSync(filePath); +} + module.exports = { createSandbox, runCli, @@ -80,5 +100,6 @@ module.exports = { writeProjectConfig, readText, writeText, - fileExists + fileExists, + deleteRetrySafe }; diff --git a/packages/agent-memory-sync/tests/helpers/watch-process.ts b/packages/agent-memory-sync/tests/helpers/watch-process.ts index bbd9f2c..2353851 100644 --- a/packages/agent-memory-sync/tests/helpers/watch-process.ts +++ b/packages/agent-memory-sync/tests/helpers/watch-process.ts @@ -134,14 +134,112 @@ const READY_TIMEOUT_MS = 10000; // delivery failure under CPU contention, pre-existing at the merge base // under the OLD fixed whole-tick budget — no inactivity-budget size and no // additional progress signal can fix it, because the signal this task added -// never gets a chance to fire when the edit itself is never observed. This -// failure class is therefore out of this task's scope; a follow-up task to -// investigate chokidar's fs-event delivery under load will be filed by the -// orchestrator. A SIGSTOP'd child (this file's original reason for -// existing, see the module comment above) still fails reliably at this -// budget and well under this package's CI job's 10-minute timeout: no -// further progress signal is possible once the process itself is frozen, so -// inactivity accumulates exactly as it did under the old whole-tick model. +// never gets a chance to fire when the edit itself is never observed. A +// SIGSTOP'd child (this file's original reason for existing, see the module +// comment above) still fails reliably at this budget and well under this +// package's CI job's 10-minute timeout: no further progress signal is +// possible once the process itself is frozen, so inactivity accumulates +// exactly as it did under the old whole-tick model. +// +// ROOT CAUSE (follow-up task agent-tasks f876dff6, closing the item above): +// isolated outside chokidar entirely, in a standalone script with NO test +// harness, NO tsx, NO child-process spawn — just `chokidar.watch(file, +// { ignoreInitial: true, awaitWriteFinish: {...} })` (this package's exact +// options) plus a BARE `fs.watch(file)` armed at the same moment, side by +// side. Both miss a `fs.writeFileSync` issued 0ms after the watch is +// reported armed, 0/10 trials, with or without 12 `yes`-worker synthetic CPU +// load on this 12-core Mac; both catch it 100% of the time (10/10, idle AND +// under load) once the write is delayed even 5ms past arming. This is not a +// chokidar bug and not specific to this package: it is Node's own +// documented, currently-unfixed macOS behavior — a watcher created with +// `fs.watch()` does not necessarily start receiving events immediately, so a +// write issued very soon after creation can be silently and PERMANENTLY +// missed for that write, with no API to learn when the watch has actually +// gone live (nodejs/node#52601, "Not possible to know when fs.watch has +// started on macOS"; chokidar uses kqueue for files and FSEvents for +// directories on macOS, both subject to the same class of race). Once lost, +// the write's event never arrives — waiting longer never helps, matching +// exactly why raising INACTIVITY_TIMEOUT_MS (90000ms -> 150000ms) made the +// PR #102 load-scenario pass rate WORSE, not better (see above): a bigger +// budget cannot recover an event that was never going to arrive. +// waitForWatcherReady()'s own 25ms poll usually leaves enough incidental +// margin past the moment chokidar's internal fs.watch() call for a given +// path actually returns that this race rarely bites — the 30-40% figure +// above is that margin occasionally collapsing under real contention +// (competing processes' scheduling reordering the two sides closer +// together), not the race itself getting wider: the delay-sweep above found +// a clean, load-INDEPENDENT threshold (always lost at 0ms, always caught at +// >=5-25ms, idle or under the 12-worker load scenario alike). That eliminates +// the "chokidar polling vs fsevents" and "editor atomic-write visibility" +// candidates from this task's brief: chokidar 4.x (this package's version) +// depends on neither `fsevents` nor polling by default (its +// package.json has no `fsevents` dependency at all — that optional native +// module was dropped when v4 rewrote to use Node's own fs.watch/fs.watchFile +// exclusively), and every trigger edit here already writes in place via +// `fs.writeFileSync` on the SAME inode (tests/helpers/cli.ts's `writeText`), +// never an atomic rename-over-write, so neither was ever actually in play on +// this codepath. +// +// FIX: since Node exposes no "the watch is now truly live" signal to poll +// (the linked issue is open, no upstream fix available) and this package's +// own INACTIVITY_TIMEOUT_MS is explicitly out of scope, the mitigation lives +// entirely on the test side, per this task's brief: applyTriggerWithRetry() +// below applies a trigger edit, waits a short, fixed window +// (TRIGGER_ARM_CONFIRM_MS, far shorter than INACTIVITY_TIMEOUT_MS) for ANY +// new progress signal, and if none appears, re-applies the SAME edit — a +// FRESH write, not a wait, is what actually recovers here, exactly as the +// delay-sweep above demonstrates (a second write issued any real time after +// the first is always observed). runWatchTick uses it for every one-shot +// trigger edit; the two direct offline/online spawns in +// watch-mirror-delete.test.ts's queue-replay test call it explicitly for the +// same reason. A bare `fs.rmSync` retried this way is a silent no-op on its +// second attempt (nothing left to delete), so the one delete-only trigger +// edit (watch-restore.test.ts's "watch records deletions as remove entries") +// and the one delete alongside a write (watch-mirror-delete.test.ts's +// negative-control test) use cli.ts's `deleteRetrySafe` instead of a bare +// `rmSync`, which recreates the file immediately before deleting it so a +// retry always has a fresh delete to reissue — see that helper's own comment +// for why this is equivalent to a bare delete from watch.ts's and +// performPush's point of view. +// +// MEASURED RESULT AND A SECOND, DIFFERENT OPEN MECHANISM (still agent-tasks +// f876dff6): applyTriggerWithRetry measurably fixes the mechanism above — +// verified in isolation (a standalone repro with no test harness: 0/10 at +// 0ms delay, 10/10 at >=5ms, idle or under 10-12 concurrent `yes` workers) — +// but an interleaved matched-control run of this file's 3 watch integration +// test files (both WITH extra synthetic `yes` load and, matching the +// eb798875 review's actual methodology more closely, WITHOUT it — just this +// suite's own natural node:test file-level concurrency) still failed on +// BOTH arms, repeatedly landing on the SAME two tests ("watch tick queues +// locally...", "watch tick with a missing required syncPaths entry..."). +// Branch: 0/4 green across those runs; the one control-arm run in the +// series was also red. Digging into one such failure's raw output found +// something that changes the diagnosis for at least part of this residual +// class: the "stderr so far" text embedded in withTickDeadline's own +// rejection message showed only the ready line (as expected for a lost +// event), but MORE stderr — including "watch tick pushing snapshot" and +// "watch tick queued locally instead of pushing" — appeared in the test +// framework's own failure output immediately after that rejection fired. +// That is only possible if the child's pipe write reached the OS before the +// SIGKILL, and node's own 'data' event for it was simply not yet processed +// by THIS (parent, test-runner) process's event loop at the moment +// withTickDeadline's poll last checked — i.e. the tick had genuinely +// progressed (possibly even finished), and it was the PARENT's own +// stderr-pipe read, not the child's fs-event delivery, that was delayed +// past the budget. Under the documented load scenario the parent +// (node:test worker) process is itself one of many CPU-starved processes, +// so this is plausible on its own terms, independent of the arming race +// above. This is NOT something applyTriggerWithRetry can fix — retrying the +// edit does nothing for a tick that already succeeded but whose own +// completion signal the parent hasn't gotten around to reading yet — and it +// was not distinguished from the arming race in this task's original brief +// or its predecessor's measurements. Left open for a follow-up: confirm +// this second mechanism with dedicated instrumentation (e.g. logging +// wall-clock gaps between a child's own write() and this process's 'data' +// handler firing for it under the same load), and decide whether the right +// fix is observing tick completion a different way (e.g. the child's own +// exit code/state-store side effects) rather than polling piped stderr text +// at all. const INACTIVITY_TIMEOUT_MS = 90000; // Poll cadence for withTickDeadline's inactivity mode — cheap enough (a // regex match count over an in-memory string) to run this often without @@ -165,6 +263,93 @@ function countProgressSignals(text: string): number { return (text.match(PROGRESS_SIGNAL_PATTERN) || []).length; } +// How long applyTriggerWithRetry waits, after applying a trigger edit, for +// PROGRESS_SIGNAL_PATTERN's match count to increase before concluding the +// edit's filesystem event was lost to the macOS fs.watch arming race +// documented above and re-applying it. 3000ms comfortably covers every +// debounceMs value used across this suite's watch-spawning tests (300-400ms) +// plus normal performPush startup latency. +const TRIGGER_ARM_CONFIRM_MS = 3000; +// Total wall-clock budget applyTriggerWithRetry spends retrying before +// giving up and handing off to withTickDeadline's own (unmodified) 90s +// inactivity budget as the final safety net. NOT the same knob as +// INACTIVITY_TIMEOUT_MS — this bounds only the retry loop below, leaving a +// comfortable ~20s margin under it for whatever the final attempt's own +// natural tick processing needs. +// +// Revised upward from an initial 3-attempts-of-3000ms design (max ~6-9s of +// retrying) after that design measurably failed on its very first real +// matched-control run (agent-tasks f876dff6, this task): 2 of the 3 watch +// integration test files stalled the full 90000ms with zero progress signal +// EVER, meaning every one of the 3 attempts' writes was lost, not just the +// first. The isolated delay-sweep repro above (a single file, no concurrent +// test-file load) found the race resolves within single-digit milliseconds +// once ANY margin exists — but that repro did not include this suite's own +// concurrency: node:test runs multiple test FILES concurrently by default, +// so the documented load scenario is 10 `yes` workers ON TOP OF 3 +// simultaneously-running watch-spawning integration test files, each +// spawning its own tree of tsx/node/git child processes. That additional, +// self-inflicted concurrency (not present in the isolated repro) can +// apparently keep the arming race's effective window open far longer than a +// few milliseconds. Rather than assume a specific new number is "enough" +// without measuring again, this budget is set generously (70000ms — roughly +// 20-25 retry rounds at the default confirm window) and validated by the +// same matched-control re-run this comment's own history is built from; see +// this task's final report for the resulting pass rate at this setting. +const TRIGGER_RETRY_BUDGET_MS = 70000; + +// Poll cadence for applyTriggerWithRetry's confirm wait. Cheap (same regex +// match count as withTickDeadline's own poll), no measurable effect on tick +// timing at this cadence, and small relative to the default +// TRIGGER_ARM_CONFIRM_MS so a confirming signal is noticed promptly rather +// than sitting unnoticed for most of the window. +const TRIGGER_CONFIRM_POLL_INTERVAL_MS = 100; + +// Applies `triggerEdit`, then waits up to `confirmMs` (or whatever remains +// of `retryBudgetMs`, if less) for PROGRESS_SIGNAL_PATTERN's match count in +// `getStderr()` to rise above what it was right before this attempt's edit. +// If it doesn't, re-applies `triggerEdit` (a FRESH filesystem write/delete, +// not a wait — see the ROOT CAUSE / FIX comment above for why only a fresh +// edit can recover from this) and repeats until either a signal is observed +// or `retryBudgetMs` is exhausted, whichever comes first. The final attempt +// inside the budget is applied without waiting on it here at all: at that +// point withTickDeadline's own (unmodified) inactivity poll is already +// running around this whole call and remains the final, independent safety +// net regardless of what this function concludes. `confirmMs`/ +// `retryBudgetMs`/`pollIntervalMs` default to this file's calibrated +// constants (real spawns always use the defaults); they are only +// parameterized so unit tests can exercise the retry/give-up branches with +// small numbers instead of the real multi-second windows (see +// tests/unit/watch-process-trigger-retry.test.ts). +async function applyTriggerWithRetry( + getStderr: () => string, + triggerEdit: () => void | Promise, + confirmMs: number = TRIGGER_ARM_CONFIRM_MS, + retryBudgetMs: number = TRIGGER_RETRY_BUDGET_MS, + pollIntervalMs: number = TRIGGER_CONFIRM_POLL_INTERVAL_MS +): Promise { + const overallDeadline = Date.now() + retryBudgetMs; + for (;;) { + const beforeCount = countProgressSignals(getStderr()); + await triggerEdit(); + if (Date.now() >= overallDeadline) { + return; + } + const confirmDeadline = Math.min(Date.now() + confirmMs, overallDeadline); + let confirmed = false; + while (Date.now() < confirmDeadline) { + if (countProgressSignals(getStderr()) > beforeCount) { + confirmed = true; + break; + } + await new Promise((resolve) => setTimeout(resolve, pollIntervalMs)); + } + if (confirmed) { + return; + } + } +} + // How long to wait for a graceful SIGINT/SIGTERM to a watch process group to // take effect before escalating to SIGKILL — see stopWatchProcessGroup below. const GROUP_KILL_GRACE_MS = 2000; @@ -557,7 +742,7 @@ async function runWatchTick( child, async () => { await waitForWatcherReady(() => stderr); - await triggerEdit(); + await applyTriggerWithRetry(() => stderr, triggerEdit); const exitCode: number = await new Promise((resolve) => { child.on("exit", (code: number | null) => resolve(code ?? -1)); @@ -580,6 +765,7 @@ module.exports = { waitForWatcherReady, withTickDeadline, runWatchTick, + applyTriggerWithRetry, stopWatchProcessGroup, INACTIVITY_TIMEOUT_MS, ABSOLUTE_CAP_MULTIPLIER diff --git a/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts b/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts index 5da6487..5957c18 100644 --- a/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts +++ b/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts @@ -29,6 +29,7 @@ const path = require("node:path"); const { cloneRemote, createSandbox, + deleteRetrySafe, fileExists, git, initBareRemote, @@ -38,6 +39,7 @@ const { writeText } = require("../helpers/cli.ts"); const { + applyTriggerWithRetry, spawnWatch, waitForWatcherReady, withTickDeadline, @@ -147,7 +149,11 @@ test("watch tick still deletes locally-removed files and pushes local edits, wit const { exitCode, stderr } = await runWatchTick(configPath, () => { writeText(path.join(workspaceRoot, "MEMORY.md"), "base\nupdated\n"); - fs.rmSync(path.join(workspaceRoot, "logs", "mine.md")); + // deleteRetrySafe, not a bare fs.rmSync — runWatchTick retries a stalled + // trigger edit verbatim (see watch-process.ts's applyTriggerWithRetry), + // and a bare rmSync would throw ENOENT on a retry once this path is + // already gone. + deleteRetrySafe(path.join(workspaceRoot, "logs", "mine.md")); }); assert.equal(exitCode, 0, `watch exited non-zero. stderr: ${stderr}`); @@ -209,7 +215,13 @@ test("watch tick queues locally when the remote is unreachable, then replays the offlineChild, async () => { await waitForWatcherReady(() => offlineStderr); - writeText(path.join(workspaceRoot, "MEMORY.md"), "queued change\n"); + // applyTriggerWithRetry, not a bare write — see watch-process.ts's + // ROOT CAUSE / FIX comment for why a one-shot write after "ready" can + // silently and permanently miss the watch (a macOS fs.watch arming + // race, not specific to this test). + await applyTriggerWithRetry(() => offlineStderr, () => { + writeText(path.join(workspaceRoot, "MEMORY.md"), "queued change\n"); + }); return new Promise((resolve) => { offlineChild.on("exit", (code: number | null) => resolve(code ?? -1)); @@ -260,7 +272,9 @@ test("watch tick queues locally when the remote is unreachable, then replays the onlineChild, async () => { await waitForWatcherReady(() => onlineStderr); - writeText(path.join(workspaceRoot, "logs", "trigger.md"), "trigger\n"); + await applyTriggerWithRetry(() => onlineStderr, () => { + writeText(path.join(workspaceRoot, "logs", "trigger.md"), "trigger\n"); + }); return new Promise((resolve) => { onlineChild.on("exit", (code: number | null) => resolve(code ?? -1)); diff --git a/packages/agent-memory-sync/tests/integration/watch-restore.test.ts b/packages/agent-memory-sync/tests/integration/watch-restore.test.ts index 988fd46..863c52d 100644 --- a/packages/agent-memory-sync/tests/integration/watch-restore.test.ts +++ b/packages/agent-memory-sync/tests/integration/watch-restore.test.ts @@ -13,11 +13,11 @@ // matches on stderr content — every other assertion below still does not. const test = require("node:test"); const assert = require("node:assert/strict"); -const fs = require("node:fs"); const path = require("node:path"); const { cloneRemote, createSandbox, + deleteRetrySafe, fileExists, git, initBareRemote, @@ -235,7 +235,11 @@ test("watch records deletions as remove entries", async () => { runCli(["run", "default", "--config", configPath, "--mode", "push", "--output", "json"]); const { exitCode } = await runWatchTick(configPath, () => { - fs.rmSync(path.join(workspaceRoot, "logs", "2026-05-01.md")); + // deleteRetrySafe, not a bare fs.rmSync — runWatchTick retries a stalled + // trigger edit verbatim (see watch-process.ts's applyTriggerWithRetry), + // and a bare rmSync would throw ENOENT on a retry once this path is + // already gone. + deleteRetrySafe(path.join(workspaceRoot, "logs", "2026-05-01.md")); }); assert.equal(exitCode, 0); diff --git a/packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts b/packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts new file mode 100644 index 0000000..d40fe3d --- /dev/null +++ b/packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts @@ -0,0 +1,124 @@ +// Unit-level pin for applyTriggerWithRetry (tests/helpers/watch-process.ts), +// the test-side mitigation for the macOS fs.watch arming race documented in +// that file's "ROOT CAUSE" comment (agent-tasks f876dff6): a trigger edit's +// filesystem event can be silently and permanently lost if issued too soon +// after the watch is reported armed, with no larger deadline able to recover +// it, so the only working mitigation is a FRESH re-applied edit once a short +// confirm window shows no progress signal, repeated until a total retry +// budget is exhausted. Exercised here against a fake stderr feed and a +// counting triggerEdit, with small confirmMs/retryBudgetMs/pollIntervalMs +// passed explicitly — no chokidar arming, spawn, or real timing needed to +// pin the retry/give-up branches (that end-to-end evidence lives in this +// task's final report and in watch-process.ts's own comment, not in this +// automated suite). +const test = require("node:test"); +const assert = require("node:assert/strict"); +const { applyTriggerWithRetry } = require("../helpers/watch-process.ts"); + +// Matches PROGRESS_SIGNAL_PATTERN's push-start alternative +// (WATCH_TICK_PUSH_START_PATTERN in watch-process.ts) — any real +// progress-signal shape works equally; reused here for a self-contained +// fixture line. +const PUSH_START_LINE = "watch tick pushing snapshot\n"; +// Matches PROGRESS_SIGNAL_PATTERN's ready-line alternative +// (WATCH_READY_PATTERN) — used below to model the ready line that is always +// already present in getStderr() by the time applyTriggerWithRetry is +// called in real usage (waitForWatcherReady has already resolved). +const READY_LINE = "watching 1 path(s) under /tmp/fixture\n"; + +test("applyTriggerWithRetry: applies the edit once and returns without retrying when a progress signal appears within the confirm window", async () => { + let stderr = ""; + let callCount = 0; + await applyTriggerWithRetry( + () => stderr, + () => { + callCount += 1; + stderr += PUSH_START_LINE; + }, + 1000, // confirmMs + 5000, // retryBudgetMs + 10, // pollIntervalMs + ); + assert.equal( + callCount, + 1, + "a trigger edit that is immediately observed must not be retried", + ); +}); + +test("applyTriggerWithRetry: retries the edit once no progress signal appears within the confirm window, then stops once one does", async () => { + let stderr = ""; + let callCount = 0; + await applyTriggerWithRetry( + () => stderr, + () => { + callCount += 1; + // First attempt's edit is silently lost (no stderr change) — models + // the arming race. Second attempt's edit IS observed. + if (callCount >= 2) { + stderr += PUSH_START_LINE; + } + }, + 150, // confirmMs: short so the first attempt's stall is detected quickly + 5000, // retryBudgetMs: comfortably larger than one confirmMs round + 10, // pollIntervalMs + ); + assert.equal( + callCount, + 2, + "a trigger edit whose first attempt produces no signal must be re-applied exactly once before confirming", + ); +}); + +test("applyTriggerWithRetry: keeps retrying (more than once) while the retry budget lasts, and returns without throwing once it is exhausted", async () => { + let stderr = ""; + let callCount = 0; + await applyTriggerWithRetry( + () => stderr, + () => { + callCount += 1; + // Never produces a progress signal — models a genuinely stuck tick + // (not just a lost arming event), which withTickDeadline's own + // inactivity budget — unmodified by this helper — remains responsible + // for eventually failing. + }, + 30, // confirmMs + 150, // retryBudgetMs: small, deliberately allows only a handful of rounds + 5, // pollIntervalMs + ); + assert.ok( + callCount >= 2, + `must retry more than once within a budget spanning several confirm windows (got ${callCount} call(s))`, + ); +}); + +test("applyTriggerWithRetry: a pre-existing signal already in stderr before the first attempt does not by itself count as confirming that attempt", async () => { + // Guards against a regression where the confirm check treats ANY signal + // being present (count > 0) as confirmation, instead of requiring growth + // beyond the count captured fresh right before THIS attempt's own edit. + // In real usage getStderr() already contains the ready line (count=1) + // before applyTriggerWithRetry is ever called, since waitForWatcherReady + // has already resolved by then — a naive `count > 0` check would + // incorrectly "confirm" the very first attempt without it ever actually + // producing anything. + let stderr = READY_LINE; + let callCount = 0; + await applyTriggerWithRetry( + () => stderr, + () => { + callCount += 1; + // Only the SECOND attempt's edit actually adds a new signal. + if (callCount >= 2) { + stderr += PUSH_START_LINE; + } + }, + 150, // confirmMs + 5000, // retryBudgetMs + 10, // pollIntervalMs + ); + assert.equal( + callCount, + 2, + "a pre-existing signal already present in stderr must not be mistaken for confirmation of the first attempt's own edit", + ); +}); From cd1a5dd73318d64b6ce3ac50bfe243eebccd93e1 Mon Sep 17 00:00:00 2001 From: Lan Nguyen Si Date: Mon, 17 Aug 2026 05:54:31 +0200 Subject: [PATCH 2/2] agent-memory-sync: drop watch trigger-retry machinery, keep root-cause docs only (f876dff6) Review found the retry helpers added in 2cb9173 (applyTriggerWithRetry, deleteRetrySafe) introduce a deterministic regression for no measurable benefit, and that the stall symptom they targeted does not currently reproduce against the merge base. Revert tests/helpers/watch-process.ts, tests/helpers/cli.ts, tests/integration/watch-mirror-delete.test.ts and tests/integration/watch-restore.test.ts to base (47e2d605); drop tests/unit/watch-process-trigger-retry.test.ts. Keep only: the corrected ready-event comment in src/commands/watch.ts, tightened to the reviewer-verified measurement (macOS fs.watch() can permanently lose a write <1ms after arming; 0/10 at 0ms vs 10/10 at >=1ms, idle and under load; nodejs/node#52601); a compact root-cause header in tests/helpers/watch-process.ts covering that mechanism, the 2026-08-16/17 non-repro measurement, the ruled-out stderr-read-delay theory, and the exit-listener ordering constraint; and a one-line hardening (spawnWatch's child stdout is now "ignore" instead of an unread "pipe", which could otherwise back up past 64KB and look like an unexplained stall). CHANGELOG entry rewritten to match: no "fixed" claim, no behavior change beyond the stdout hardening. --- packages/agent-memory-sync/CHANGELOG.md | 2 +- .../agent-memory-sync/src/commands/watch.ts | 16 +- .../agent-memory-sync/tests/helpers/cli.ts | 25 +- .../tests/helpers/watch-process.ts | 232 +++--------------- .../integration/watch-mirror-delete.test.ts | 20 +- .../tests/integration/watch-restore.test.ts | 8 +- .../unit/watch-process-trigger-retry.test.ts | 124 ---------- 7 files changed, 51 insertions(+), 376 deletions(-) delete mode 100644 packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts diff --git a/packages/agent-memory-sync/CHANGELOG.md b/packages/agent-memory-sync/CHANGELOG.md index f966d5f..c204542 100644 --- a/packages/agent-memory-sync/CHANGELOG.md +++ b/packages/agent-memory-sync/CHANGELOG.md @@ -14,4 +14,4 @@ is dated instead. The format is loosely based on - `withTickDeadline` (test helper) gained an inactivity mode: it resets its deadline on either the ready line or the new push-start line, so a per-tick test budget bounds the gap since the last observed signal instead of the tick's total duration. A second, independent absolute cap (2.5x the inactivity budget) still bounds a tick that keeps signaling forever, failing with a distinct message. - A pre-existing failure class under this package's documented load scenario stalls before either progress signal can fire: a chokidar filesystem-event delivery issue under CPU contention, present at the merge base too, at roughly a 30-40% failure rate under load on both. No timeout size fixes this; it is out of scope for this change and tracked as a follow-up. - New unit tests in `tests/unit/watch-process-inactivity.test.ts` pin the inactivity and absolute-cap semantics directly, without a real spawn. -- Partially root-caused and partially fixed the follow-up above (agent-tasks f876dff6, status: partial — see that task's final report for full detail). Isolated outside chokidar entirely (a standalone script, no test harness), a bare `fs.watch()` on macOS can silently and permanently miss a write issued immediately after the watch is reported armed — Node's own documented, currently-unfixed behavior (nodejs/node#52601). Not a chokidar bug, and neither the "polling vs fsevents" nor "atomic-write visibility" candidates from that follow-up's brief were actually in play: chokidar 4.x (this package's version) has no `fsevents` dependency and uses neither polling nor fsevents by default, and every trigger edit in this suite already writes in place, never via atomic rename. This confirmed mechanism is fixed on the test side: `applyTriggerWithRetry` (test helper) re-applies a trigger edit if no progress signal appears within a confirm window, budgeted up to 70s total (well under the unmodified 90s inactivity deadline), since a fresh write reliably clears this specific race (measured in isolation: always lost at 0ms after arming, always caught at >=5ms, idle or under a 10-12 worker synthetic CPU load alike). `runWatchTick` and the two direct offline/online spawns in `watch-mirror-delete.test.ts`'s queue-replay test now go through it; the two delete-based trigger edits use the new `deleteRetrySafe` test helper (recreate-then-delete) instead of a bare `rmSync`, which is not safe to retry once the target is already gone. However, an interleaved matched-control measurement of the full 3-file watch integration suite under the documented load scenario still failed repeatedly on the same two tests on BOTH the fixed and unmodified arms, and inspecting one failure's raw output found evidence of a SECOND, different mechanism not fixed here: the parent test-runner process's own delayed reading of the child's stderr pipe under heavy contention, which can make an already-completed tick look like a permanent stall — not fixable by retrying the trigger edit. See `tests/helpers/watch-process.ts`'s "MEASURED RESULT AND A SECOND, DIFFERENT OPEN MECHANISM" comment and `src/commands/watch.ts`'s ready-line comment for detail. New unit tests in `tests/unit/watch-process-trigger-retry.test.ts` pin the retry/give-up semantics of the fixed mechanism directly, without a real spawn. +- Root-caused (but did not fix, see below) the follow-up above (agent-tasks f876dff6). Isolated outside chokidar entirely (a standalone script, no test harness), a bare `fs.watch()` on macOS can permanently miss a write issued <1ms after the watch is reported armed — Node's own documented, currently-unfixed behavior (nodejs/node#52601), not a chokidar bug; chokidar 4.x (this package's version) uses neither `fsevents` nor polling by default, so neither of that follow-up's original "polling vs fsevents" or "atomic-write visibility" candidates were actually in play. A second candidate mechanism — the parent test-runner process's own delayed reading of the child's stderr pipe under load — was measured and ruled out: p99 9ms / max 11ms across 600 samples under load, far too small to account for missing a 90s budget. Against this package's own documented 10-worker load scenario, the historical 30-40% stall did not reproduce: a 2026-08-16/17 measurement ran the scenario 5/5 green on the merge base, both idle and under load. No retry/workaround code was added as a result — the failure this task originally investigated is not currently reproducible, and speculative retry logic tried in an earlier iteration of this task was found on review to add a deterministic regression for no measurable benefit, so it was removed again. The one behavior change kept: `spawnWatch` (test helper) now spawns its child with stdout `'ignore'` instead of an unread `'pipe'`, since nothing reads it and an unread pipe backs up once the child writes past the OS pipe buffer (64KB), which would otherwise look exactly like an unexplained stall. See `tests/helpers/watch-process.ts`'s header comment and `src/commands/watch.ts`'s ready-line comment for the full measurement notes. diff --git a/packages/agent-memory-sync/src/commands/watch.ts b/packages/agent-memory-sync/src/commands/watch.ts index b88f173..f9ecfe5 100644 --- a/packages/agent-memory-sync/src/commands/watch.ts +++ b/packages/agent-memory-sync/src/commands/watch.ts @@ -297,15 +297,13 @@ function registerWatchCommand(program: import("commander").Command): void { // after it returns — a currently-unfixed Node.js/libuv behavior // (nodejs/node#52601, "Not possible to know when fs.watch has started // on macOS"), independent of chokidar's own initial-scan/'ready' - // bookkeeping. Measured in tests/helpers/watch-process.ts's "ROOT - // CAUSE" comment (agent-tasks f876dff6): a write 0ms after the watch - // is reported armed is lost 100% of the time in isolation, on both a - // bare fs.watch() and this exact chokidar config, idle or under load; - // any real delay (>=5ms measured here) resolves it 100% of the time. - // The mitigation for that residual race lives entirely on the test - // side (retrying a stalled trigger edit rather than waiting longer), - // since Node exposes no stronger "truly armed" signal this line could - // wait for instead. + // bookkeeping. Measured in isolation (agent-tasks f876dff6): a write + // issued 0ms after the watch is reported armed was lost 10/10 times, + // while a write issued >=1ms after was caught 10/10 times, both idle + // and under load. In practice this package's own waitForWatcherReady + // test helper (tests/helpers/watch-process.ts) polls at a 25ms + // cadence, which leaves comfortable margin above that threshold; see + // that file's header comment for the full measurement notes. watcher.on("ready", () => { writeInfo( `watching ${watchedPaths.length} path(s) under ${runConfig.rootDir} (debounce ${debounceMs}ms)`, diff --git a/packages/agent-memory-sync/tests/helpers/cli.ts b/packages/agent-memory-sync/tests/helpers/cli.ts index eaf12e8..9885ecc 100644 --- a/packages/agent-memory-sync/tests/helpers/cli.ts +++ b/packages/agent-memory-sync/tests/helpers/cli.ts @@ -1,5 +1,5 @@ const { execFileSync, spawnSync } = require("node:child_process"); -const { existsSync, mkdirSync, readFileSync, rmSync, writeFileSync } = require("node:fs"); +const { existsSync, mkdirSync, readFileSync, writeFileSync } = require("node:fs"); const { tmpdir } = require("node:os"); const path = require("node:path"); @@ -71,26 +71,6 @@ function fileExists(filePath: string): boolean { return existsSync(filePath); } -// Recreates `filePath` with placeholder content immediately before deleting -// it, instead of a bare `rmSync`. The net effect on disk and in watch.ts's -// own pendingChanges/pendingDeletes bookkeeping is identical to a plain -// delete: only the FINAL absence matters to performPush's diff, and -// watch.ts's unlink handler unconditionally does both -// `pendingDeletes.add(filePath)` and `pendingChanges.delete(filePath)`, so an -// add-then-unlink of the SAME path collapses down to just "deleted" either -// way (src/commands/watch.ts). What this buys over a bare `rmSync`: it makes -// the edit safe to invoke more than once. A repeated `rmSync` on an -// already-deleted path either throws ENOENT or (with `{ force: true }`) is a -// silent no-op — either way it produces no fresh filesystem event, so it -// cannot help a caller recover from watch-process.ts's applyTriggerWithRetry -// re-issuing a trigger edit whose first attempt's underlying fs-event was -// lost to the arming race documented there (tests/helpers/watch-process.ts). -// Recreating first always gives the retry something real to delete again. -function deleteRetrySafe(filePath: string): void { - writeText(filePath, "(retry-safe placeholder before delete)\n"); - rmSync(filePath); -} - module.exports = { createSandbox, runCli, @@ -100,6 +80,5 @@ module.exports = { writeProjectConfig, readText, writeText, - fileExists, - deleteRetrySafe + fileExists }; diff --git a/packages/agent-memory-sync/tests/helpers/watch-process.ts b/packages/agent-memory-sync/tests/helpers/watch-process.ts index 2353851..e3e55b9 100644 --- a/packages/agent-memory-sync/tests/helpers/watch-process.ts +++ b/packages/agent-memory-sync/tests/helpers/watch-process.ts @@ -24,6 +24,27 @@ const { spawn } = require("node:child_process"); const path = require("node:path"); +// ROOT CAUSE and follow-up findings (agent-tasks f876dff6): +// - Mechanism: on macOS, chokidar 4.x uses raw fs.watch() (no fsevents, no +// polling by default) and a freshly-armed fs.watch() can permanently miss +// a write issued <1ms after arming — a currently-unfixed Node.js/libuv +// behavior (nodejs/node#52601). Measured 0/10 caught at 0ms, 10/10 caught +// at >=1ms, both idle and under load. waitForWatcherReady's 25ms poll +// cadence leaves comfortable margin above that threshold. +// - Measured 2026-08-16/17: this file's documented 10-worker load scenario +// ran 5/5 green on the merge base, idle and under load; the historical +// 30-40% stall symptom did not reproduce. No retry/workaround is carried +// in this file as a result. +// - Ruled out: a parent-side delay reading the child's stderr +// pipe as a stall cause. Measured p99 9ms / max 11ms across 600 samples +// under load — cannot account for missing a 90s budget. +// - Ordering constraint for future changes to this file: any child.on( +// "exit", ...) listener MUST be registered before the first longer await +// after spawn() returns. Node does not replay a missed "exit" event to a +// listener attached after the fact (measured 0/15 caught at >=100ms +// delay), so a late listener can make an already-finished child look like +// a 90s stall. +// // Matches watch.ts's "watching N path(s) under ..." ready line. --verbose is // required for it to print at all: writeInfo (src/output.ts) is a no-op // unless verbose is set, which is why every watch invocation through this @@ -134,112 +155,14 @@ const READY_TIMEOUT_MS = 10000; // delivery failure under CPU contention, pre-existing at the merge base // under the OLD fixed whole-tick budget — no inactivity-budget size and no // additional progress signal can fix it, because the signal this task added -// never gets a chance to fire when the edit itself is never observed. A -// SIGSTOP'd child (this file's original reason for existing, see the module -// comment above) still fails reliably at this budget and well under this -// package's CI job's 10-minute timeout: no further progress signal is -// possible once the process itself is frozen, so inactivity accumulates -// exactly as it did under the old whole-tick model. -// -// ROOT CAUSE (follow-up task agent-tasks f876dff6, closing the item above): -// isolated outside chokidar entirely, in a standalone script with NO test -// harness, NO tsx, NO child-process spawn — just `chokidar.watch(file, -// { ignoreInitial: true, awaitWriteFinish: {...} })` (this package's exact -// options) plus a BARE `fs.watch(file)` armed at the same moment, side by -// side. Both miss a `fs.writeFileSync` issued 0ms after the watch is -// reported armed, 0/10 trials, with or without 12 `yes`-worker synthetic CPU -// load on this 12-core Mac; both catch it 100% of the time (10/10, idle AND -// under load) once the write is delayed even 5ms past arming. This is not a -// chokidar bug and not specific to this package: it is Node's own -// documented, currently-unfixed macOS behavior — a watcher created with -// `fs.watch()` does not necessarily start receiving events immediately, so a -// write issued very soon after creation can be silently and PERMANENTLY -// missed for that write, with no API to learn when the watch has actually -// gone live (nodejs/node#52601, "Not possible to know when fs.watch has -// started on macOS"; chokidar uses kqueue for files and FSEvents for -// directories on macOS, both subject to the same class of race). Once lost, -// the write's event never arrives — waiting longer never helps, matching -// exactly why raising INACTIVITY_TIMEOUT_MS (90000ms -> 150000ms) made the -// PR #102 load-scenario pass rate WORSE, not better (see above): a bigger -// budget cannot recover an event that was never going to arrive. -// waitForWatcherReady()'s own 25ms poll usually leaves enough incidental -// margin past the moment chokidar's internal fs.watch() call for a given -// path actually returns that this race rarely bites — the 30-40% figure -// above is that margin occasionally collapsing under real contention -// (competing processes' scheduling reordering the two sides closer -// together), not the race itself getting wider: the delay-sweep above found -// a clean, load-INDEPENDENT threshold (always lost at 0ms, always caught at -// >=5-25ms, idle or under the 12-worker load scenario alike). That eliminates -// the "chokidar polling vs fsevents" and "editor atomic-write visibility" -// candidates from this task's brief: chokidar 4.x (this package's version) -// depends on neither `fsevents` nor polling by default (its -// package.json has no `fsevents` dependency at all — that optional native -// module was dropped when v4 rewrote to use Node's own fs.watch/fs.watchFile -// exclusively), and every trigger edit here already writes in place via -// `fs.writeFileSync` on the SAME inode (tests/helpers/cli.ts's `writeText`), -// never an atomic rename-over-write, so neither was ever actually in play on -// this codepath. -// -// FIX: since Node exposes no "the watch is now truly live" signal to poll -// (the linked issue is open, no upstream fix available) and this package's -// own INACTIVITY_TIMEOUT_MS is explicitly out of scope, the mitigation lives -// entirely on the test side, per this task's brief: applyTriggerWithRetry() -// below applies a trigger edit, waits a short, fixed window -// (TRIGGER_ARM_CONFIRM_MS, far shorter than INACTIVITY_TIMEOUT_MS) for ANY -// new progress signal, and if none appears, re-applies the SAME edit — a -// FRESH write, not a wait, is what actually recovers here, exactly as the -// delay-sweep above demonstrates (a second write issued any real time after -// the first is always observed). runWatchTick uses it for every one-shot -// trigger edit; the two direct offline/online spawns in -// watch-mirror-delete.test.ts's queue-replay test call it explicitly for the -// same reason. A bare `fs.rmSync` retried this way is a silent no-op on its -// second attempt (nothing left to delete), so the one delete-only trigger -// edit (watch-restore.test.ts's "watch records deletions as remove entries") -// and the one delete alongside a write (watch-mirror-delete.test.ts's -// negative-control test) use cli.ts's `deleteRetrySafe` instead of a bare -// `rmSync`, which recreates the file immediately before deleting it so a -// retry always has a fresh delete to reissue — see that helper's own comment -// for why this is equivalent to a bare delete from watch.ts's and -// performPush's point of view. -// -// MEASURED RESULT AND A SECOND, DIFFERENT OPEN MECHANISM (still agent-tasks -// f876dff6): applyTriggerWithRetry measurably fixes the mechanism above — -// verified in isolation (a standalone repro with no test harness: 0/10 at -// 0ms delay, 10/10 at >=5ms, idle or under 10-12 concurrent `yes` workers) — -// but an interleaved matched-control run of this file's 3 watch integration -// test files (both WITH extra synthetic `yes` load and, matching the -// eb798875 review's actual methodology more closely, WITHOUT it — just this -// suite's own natural node:test file-level concurrency) still failed on -// BOTH arms, repeatedly landing on the SAME two tests ("watch tick queues -// locally...", "watch tick with a missing required syncPaths entry..."). -// Branch: 0/4 green across those runs; the one control-arm run in the -// series was also red. Digging into one such failure's raw output found -// something that changes the diagnosis for at least part of this residual -// class: the "stderr so far" text embedded in withTickDeadline's own -// rejection message showed only the ready line (as expected for a lost -// event), but MORE stderr — including "watch tick pushing snapshot" and -// "watch tick queued locally instead of pushing" — appeared in the test -// framework's own failure output immediately after that rejection fired. -// That is only possible if the child's pipe write reached the OS before the -// SIGKILL, and node's own 'data' event for it was simply not yet processed -// by THIS (parent, test-runner) process's event loop at the moment -// withTickDeadline's poll last checked — i.e. the tick had genuinely -// progressed (possibly even finished), and it was the PARENT's own -// stderr-pipe read, not the child's fs-event delivery, that was delayed -// past the budget. Under the documented load scenario the parent -// (node:test worker) process is itself one of many CPU-starved processes, -// so this is plausible on its own terms, independent of the arming race -// above. This is NOT something applyTriggerWithRetry can fix — retrying the -// edit does nothing for a tick that already succeeded but whose own -// completion signal the parent hasn't gotten around to reading yet — and it -// was not distinguished from the arming race in this task's original brief -// or its predecessor's measurements. Left open for a follow-up: confirm -// this second mechanism with dedicated instrumentation (e.g. logging -// wall-clock gaps between a child's own write() and this process's 'data' -// handler firing for it under the same load), and decide whether the right -// fix is observing tick completion a different way (e.g. the child's own -// exit code/state-store side effects) rather than polling piped stderr text -// at all. +// never gets a chance to fire when the edit itself is never observed. This +// failure class is therefore out of this task's scope; a follow-up task to +// investigate chokidar's fs-event delivery under load will be filed by the +// orchestrator. A SIGSTOP'd child (this file's original reason for +// existing, see the module comment above) still fails reliably at this +// budget and well under this package's CI job's 10-minute timeout: no +// further progress signal is possible once the process itself is frozen, so +// inactivity accumulates exactly as it did under the old whole-tick model. const INACTIVITY_TIMEOUT_MS = 90000; // Poll cadence for withTickDeadline's inactivity mode — cheap enough (a // regex match count over an in-memory string) to run this often without @@ -263,93 +186,6 @@ function countProgressSignals(text: string): number { return (text.match(PROGRESS_SIGNAL_PATTERN) || []).length; } -// How long applyTriggerWithRetry waits, after applying a trigger edit, for -// PROGRESS_SIGNAL_PATTERN's match count to increase before concluding the -// edit's filesystem event was lost to the macOS fs.watch arming race -// documented above and re-applying it. 3000ms comfortably covers every -// debounceMs value used across this suite's watch-spawning tests (300-400ms) -// plus normal performPush startup latency. -const TRIGGER_ARM_CONFIRM_MS = 3000; -// Total wall-clock budget applyTriggerWithRetry spends retrying before -// giving up and handing off to withTickDeadline's own (unmodified) 90s -// inactivity budget as the final safety net. NOT the same knob as -// INACTIVITY_TIMEOUT_MS — this bounds only the retry loop below, leaving a -// comfortable ~20s margin under it for whatever the final attempt's own -// natural tick processing needs. -// -// Revised upward from an initial 3-attempts-of-3000ms design (max ~6-9s of -// retrying) after that design measurably failed on its very first real -// matched-control run (agent-tasks f876dff6, this task): 2 of the 3 watch -// integration test files stalled the full 90000ms with zero progress signal -// EVER, meaning every one of the 3 attempts' writes was lost, not just the -// first. The isolated delay-sweep repro above (a single file, no concurrent -// test-file load) found the race resolves within single-digit milliseconds -// once ANY margin exists — but that repro did not include this suite's own -// concurrency: node:test runs multiple test FILES concurrently by default, -// so the documented load scenario is 10 `yes` workers ON TOP OF 3 -// simultaneously-running watch-spawning integration test files, each -// spawning its own tree of tsx/node/git child processes. That additional, -// self-inflicted concurrency (not present in the isolated repro) can -// apparently keep the arming race's effective window open far longer than a -// few milliseconds. Rather than assume a specific new number is "enough" -// without measuring again, this budget is set generously (70000ms — roughly -// 20-25 retry rounds at the default confirm window) and validated by the -// same matched-control re-run this comment's own history is built from; see -// this task's final report for the resulting pass rate at this setting. -const TRIGGER_RETRY_BUDGET_MS = 70000; - -// Poll cadence for applyTriggerWithRetry's confirm wait. Cheap (same regex -// match count as withTickDeadline's own poll), no measurable effect on tick -// timing at this cadence, and small relative to the default -// TRIGGER_ARM_CONFIRM_MS so a confirming signal is noticed promptly rather -// than sitting unnoticed for most of the window. -const TRIGGER_CONFIRM_POLL_INTERVAL_MS = 100; - -// Applies `triggerEdit`, then waits up to `confirmMs` (or whatever remains -// of `retryBudgetMs`, if less) for PROGRESS_SIGNAL_PATTERN's match count in -// `getStderr()` to rise above what it was right before this attempt's edit. -// If it doesn't, re-applies `triggerEdit` (a FRESH filesystem write/delete, -// not a wait — see the ROOT CAUSE / FIX comment above for why only a fresh -// edit can recover from this) and repeats until either a signal is observed -// or `retryBudgetMs` is exhausted, whichever comes first. The final attempt -// inside the budget is applied without waiting on it here at all: at that -// point withTickDeadline's own (unmodified) inactivity poll is already -// running around this whole call and remains the final, independent safety -// net regardless of what this function concludes. `confirmMs`/ -// `retryBudgetMs`/`pollIntervalMs` default to this file's calibrated -// constants (real spawns always use the defaults); they are only -// parameterized so unit tests can exercise the retry/give-up branches with -// small numbers instead of the real multi-second windows (see -// tests/unit/watch-process-trigger-retry.test.ts). -async function applyTriggerWithRetry( - getStderr: () => string, - triggerEdit: () => void | Promise, - confirmMs: number = TRIGGER_ARM_CONFIRM_MS, - retryBudgetMs: number = TRIGGER_RETRY_BUDGET_MS, - pollIntervalMs: number = TRIGGER_CONFIRM_POLL_INTERVAL_MS -): Promise { - const overallDeadline = Date.now() + retryBudgetMs; - for (;;) { - const beforeCount = countProgressSignals(getStderr()); - await triggerEdit(); - if (Date.now() >= overallDeadline) { - return; - } - const confirmDeadline = Math.min(Date.now() + confirmMs, overallDeadline); - let confirmed = false; - while (Date.now() < confirmDeadline) { - if (countProgressSignals(getStderr()) > beforeCount) { - confirmed = true; - break; - } - await new Promise((resolve) => setTimeout(resolve, pollIntervalMs)); - } - if (confirmed) { - return; - } - } -} - // How long to wait for a graceful SIGINT/SIGTERM to a watch process group to // take effect before escalating to SIGKILL — see stopWatchProcessGroup below. const GROUP_KILL_GRACE_MS = 2000; @@ -386,7 +222,12 @@ function spawnWatch(args: string[], env: NodeJS.ProcessEnv) { const child = spawn( path.resolve(process.cwd(), "node_modules", ".bin", "tsx"), ["src/main.ts", ...args], - { env, stdio: ["ignore", "pipe", "pipe"], detached: true } + // stdout is "ignore", not "pipe": nothing below ever reads child.stdout + // (only child.stderr is drained, see the "data" listener further down), + // and an unread "pipe" backs up once the child writes more than the OS + // pipe buffer (64KB) — which would block the child's own write() call + // and look exactly like an unexplained stall from the test's side. + { env, stdio: ["ignore", "ignore", "pipe"], detached: true } ); if (typeof child.pid === "number") { liveGroupPids.add(child.pid); @@ -742,7 +583,7 @@ async function runWatchTick( child, async () => { await waitForWatcherReady(() => stderr); - await applyTriggerWithRetry(() => stderr, triggerEdit); + await triggerEdit(); const exitCode: number = await new Promise((resolve) => { child.on("exit", (code: number | null) => resolve(code ?? -1)); @@ -765,7 +606,6 @@ module.exports = { waitForWatcherReady, withTickDeadline, runWatchTick, - applyTriggerWithRetry, stopWatchProcessGroup, INACTIVITY_TIMEOUT_MS, ABSOLUTE_CAP_MULTIPLIER diff --git a/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts b/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts index 5957c18..5da6487 100644 --- a/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts +++ b/packages/agent-memory-sync/tests/integration/watch-mirror-delete.test.ts @@ -29,7 +29,6 @@ const path = require("node:path"); const { cloneRemote, createSandbox, - deleteRetrySafe, fileExists, git, initBareRemote, @@ -39,7 +38,6 @@ const { writeText } = require("../helpers/cli.ts"); const { - applyTriggerWithRetry, spawnWatch, waitForWatcherReady, withTickDeadline, @@ -149,11 +147,7 @@ test("watch tick still deletes locally-removed files and pushes local edits, wit const { exitCode, stderr } = await runWatchTick(configPath, () => { writeText(path.join(workspaceRoot, "MEMORY.md"), "base\nupdated\n"); - // deleteRetrySafe, not a bare fs.rmSync — runWatchTick retries a stalled - // trigger edit verbatim (see watch-process.ts's applyTriggerWithRetry), - // and a bare rmSync would throw ENOENT on a retry once this path is - // already gone. - deleteRetrySafe(path.join(workspaceRoot, "logs", "mine.md")); + fs.rmSync(path.join(workspaceRoot, "logs", "mine.md")); }); assert.equal(exitCode, 0, `watch exited non-zero. stderr: ${stderr}`); @@ -215,13 +209,7 @@ test("watch tick queues locally when the remote is unreachable, then replays the offlineChild, async () => { await waitForWatcherReady(() => offlineStderr); - // applyTriggerWithRetry, not a bare write — see watch-process.ts's - // ROOT CAUSE / FIX comment for why a one-shot write after "ready" can - // silently and permanently miss the watch (a macOS fs.watch arming - // race, not specific to this test). - await applyTriggerWithRetry(() => offlineStderr, () => { - writeText(path.join(workspaceRoot, "MEMORY.md"), "queued change\n"); - }); + writeText(path.join(workspaceRoot, "MEMORY.md"), "queued change\n"); return new Promise((resolve) => { offlineChild.on("exit", (code: number | null) => resolve(code ?? -1)); @@ -272,9 +260,7 @@ test("watch tick queues locally when the remote is unreachable, then replays the onlineChild, async () => { await waitForWatcherReady(() => onlineStderr); - await applyTriggerWithRetry(() => onlineStderr, () => { - writeText(path.join(workspaceRoot, "logs", "trigger.md"), "trigger\n"); - }); + writeText(path.join(workspaceRoot, "logs", "trigger.md"), "trigger\n"); return new Promise((resolve) => { onlineChild.on("exit", (code: number | null) => resolve(code ?? -1)); diff --git a/packages/agent-memory-sync/tests/integration/watch-restore.test.ts b/packages/agent-memory-sync/tests/integration/watch-restore.test.ts index 863c52d..988fd46 100644 --- a/packages/agent-memory-sync/tests/integration/watch-restore.test.ts +++ b/packages/agent-memory-sync/tests/integration/watch-restore.test.ts @@ -13,11 +13,11 @@ // matches on stderr content — every other assertion below still does not. const test = require("node:test"); const assert = require("node:assert/strict"); +const fs = require("node:fs"); const path = require("node:path"); const { cloneRemote, createSandbox, - deleteRetrySafe, fileExists, git, initBareRemote, @@ -235,11 +235,7 @@ test("watch records deletions as remove entries", async () => { runCli(["run", "default", "--config", configPath, "--mode", "push", "--output", "json"]); const { exitCode } = await runWatchTick(configPath, () => { - // deleteRetrySafe, not a bare fs.rmSync — runWatchTick retries a stalled - // trigger edit verbatim (see watch-process.ts's applyTriggerWithRetry), - // and a bare rmSync would throw ENOENT on a retry once this path is - // already gone. - deleteRetrySafe(path.join(workspaceRoot, "logs", "2026-05-01.md")); + fs.rmSync(path.join(workspaceRoot, "logs", "2026-05-01.md")); }); assert.equal(exitCode, 0); diff --git a/packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts b/packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts deleted file mode 100644 index d40fe3d..0000000 --- a/packages/agent-memory-sync/tests/unit/watch-process-trigger-retry.test.ts +++ /dev/null @@ -1,124 +0,0 @@ -// Unit-level pin for applyTriggerWithRetry (tests/helpers/watch-process.ts), -// the test-side mitigation for the macOS fs.watch arming race documented in -// that file's "ROOT CAUSE" comment (agent-tasks f876dff6): a trigger edit's -// filesystem event can be silently and permanently lost if issued too soon -// after the watch is reported armed, with no larger deadline able to recover -// it, so the only working mitigation is a FRESH re-applied edit once a short -// confirm window shows no progress signal, repeated until a total retry -// budget is exhausted. Exercised here against a fake stderr feed and a -// counting triggerEdit, with small confirmMs/retryBudgetMs/pollIntervalMs -// passed explicitly — no chokidar arming, spawn, or real timing needed to -// pin the retry/give-up branches (that end-to-end evidence lives in this -// task's final report and in watch-process.ts's own comment, not in this -// automated suite). -const test = require("node:test"); -const assert = require("node:assert/strict"); -const { applyTriggerWithRetry } = require("../helpers/watch-process.ts"); - -// Matches PROGRESS_SIGNAL_PATTERN's push-start alternative -// (WATCH_TICK_PUSH_START_PATTERN in watch-process.ts) — any real -// progress-signal shape works equally; reused here for a self-contained -// fixture line. -const PUSH_START_LINE = "watch tick pushing snapshot\n"; -// Matches PROGRESS_SIGNAL_PATTERN's ready-line alternative -// (WATCH_READY_PATTERN) — used below to model the ready line that is always -// already present in getStderr() by the time applyTriggerWithRetry is -// called in real usage (waitForWatcherReady has already resolved). -const READY_LINE = "watching 1 path(s) under /tmp/fixture\n"; - -test("applyTriggerWithRetry: applies the edit once and returns without retrying when a progress signal appears within the confirm window", async () => { - let stderr = ""; - let callCount = 0; - await applyTriggerWithRetry( - () => stderr, - () => { - callCount += 1; - stderr += PUSH_START_LINE; - }, - 1000, // confirmMs - 5000, // retryBudgetMs - 10, // pollIntervalMs - ); - assert.equal( - callCount, - 1, - "a trigger edit that is immediately observed must not be retried", - ); -}); - -test("applyTriggerWithRetry: retries the edit once no progress signal appears within the confirm window, then stops once one does", async () => { - let stderr = ""; - let callCount = 0; - await applyTriggerWithRetry( - () => stderr, - () => { - callCount += 1; - // First attempt's edit is silently lost (no stderr change) — models - // the arming race. Second attempt's edit IS observed. - if (callCount >= 2) { - stderr += PUSH_START_LINE; - } - }, - 150, // confirmMs: short so the first attempt's stall is detected quickly - 5000, // retryBudgetMs: comfortably larger than one confirmMs round - 10, // pollIntervalMs - ); - assert.equal( - callCount, - 2, - "a trigger edit whose first attempt produces no signal must be re-applied exactly once before confirming", - ); -}); - -test("applyTriggerWithRetry: keeps retrying (more than once) while the retry budget lasts, and returns without throwing once it is exhausted", async () => { - let stderr = ""; - let callCount = 0; - await applyTriggerWithRetry( - () => stderr, - () => { - callCount += 1; - // Never produces a progress signal — models a genuinely stuck tick - // (not just a lost arming event), which withTickDeadline's own - // inactivity budget — unmodified by this helper — remains responsible - // for eventually failing. - }, - 30, // confirmMs - 150, // retryBudgetMs: small, deliberately allows only a handful of rounds - 5, // pollIntervalMs - ); - assert.ok( - callCount >= 2, - `must retry more than once within a budget spanning several confirm windows (got ${callCount} call(s))`, - ); -}); - -test("applyTriggerWithRetry: a pre-existing signal already in stderr before the first attempt does not by itself count as confirming that attempt", async () => { - // Guards against a regression where the confirm check treats ANY signal - // being present (count > 0) as confirmation, instead of requiring growth - // beyond the count captured fresh right before THIS attempt's own edit. - // In real usage getStderr() already contains the ready line (count=1) - // before applyTriggerWithRetry is ever called, since waitForWatcherReady - // has already resolved by then — a naive `count > 0` check would - // incorrectly "confirm" the very first attempt without it ever actually - // producing anything. - let stderr = READY_LINE; - let callCount = 0; - await applyTriggerWithRetry( - () => stderr, - () => { - callCount += 1; - // Only the SECOND attempt's edit actually adds a new signal. - if (callCount >= 2) { - stderr += PUSH_START_LINE; - } - }, - 150, // confirmMs - 5000, // retryBudgetMs - 10, // pollIntervalMs - ); - assert.equal( - callCount, - 2, - "a pre-existing signal already present in stderr must not be mistaken for confirmation of the first attempt's own edit", - ); -});