From 612da1e8e07a89e48c08f8bd68961485a011da0a Mon Sep 17 00:00:00 2001 From: Dotta <34892728+cryppadotta@users.noreply.github.com> Date: Thu, 5 Nov 2026 22:58:33 -0600 Subject: [PATCH] test(server): drain throttled follow-up in busy recovered-source execution-control test (#19403) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - The server runs durable execution-control workers, which include the workspace-recovery sweep > - `execution-control-work.test.ts` has a test for a Retry that commits during a busy recovered-source pass > - This test fails intermittently in PR runs that do not touch it, so it blocks unrelated PRs > - The test assumed that one `settle()` pass always ends idle, but the worker can correctly owe a throttled follow-up pass > - This pull request makes the test drive fake time through that throttle window while it waits for the sweep to finish > - The benefit is a deterministic test that still proves every source is visited and the worker becomes quiet ## Linked Issues or Issue Description **What happened?** `execution-control durable work > visits a newly committed earlier Retry during a busy recovered-source pass, then becomes quiet` failed in 2 of the last 250 failed `PR` workflow runs (jobs 127272079294 and 127206639630). Both failures were identical: `AssertionError: expected 1 to be +0` at `vi.waitFor` in `settle()` (`execution-control-work.test.ts:146`). The test took about 6s, which is the 5s `waitFor` limit plus overhead. **Expected behavior** The test passes on every run. Its result does not depend on runner speed. **Steps to reproduce** 1. Add a 300ms real-time delay in `registerExecutionControlWork` after `await duty.run()` and before `await duty.next()`. This simulates slow database I/O on a loaded runner. 2. Run `pnpm exec vitest run src/__tests__/execution-control-work.test.ts -t "busy recovered-source pass"` in `server/`. 3. The test fails 3 of 3 times with the same CI error. **Root cause** - `registerExecutionControlWork` lets a duty make one full pass per `EXECUTION_RECONCILIATION_INTERVAL_MS` (15s), measured from the start of the previous full pass. - The released recovery jobs call `worker.wake()` when they finish. If a wake arrives while the full pass is still reading its next deadline, `hasPending()` stays true. The coordinator then keeps its idle-tracked intent until the next permitted pass, up to 15s of fake time later. - `settle()` advances fake time by 15s and then waits 5s in real time for `idleWorkSnapshot().active === 0`. The full pass starts inside that 15s advance, so the follow-up is due after the window ends. The wait then expires. - On a fast machine the jobs usually finish after the deadline read, so the test passes. On a slow runner the order changes, so the test fails. - This is correct product behavior: the worker owes the follow-up pass. The defect is in the test's timing assumption. ## What Changed - In the busy recovered-source test, replace the bounded `settle()` loop with a `vi.waitFor` that advances fake time by `EXECUTION_RECONCILIATION_INTERVAL_MS` on each attempt. It waits until every source was visited and no idle-tracked work is active. - The test still calls `quiet(c)` after this, so it still asserts no further scheduling and no database calls during the next 90s. - The shared `settle()` helper is not changed, because `reschedules an earlier deadline…` asserts an exact `nextWakeAt()` after `settle()`. ## Verification - Red: with the 300ms delay injected (not committed), the test failed 3/3 times with the CI assertion. - Green: with the same injection at 300ms (3 runs) and at 1000ms (1 run), all four recovered-source Retry tests pass. - Without injection, the full `execution-control-work.test.ts` passed 5/5 times with 12 CPU-burner processes running. - `pnpm exec vitest run src/__tests__/execution-control-work.test.ts` in `server/`. ## Risks - Low risk. This is a test-only change. The test still requires every source to be visited, the worker to become idle, and then 90s of quiet. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, used through Claude Code with tool use (shell, file edits, GitHub CLI). Default context window. No extended thinking mode. ## Checklist - [x] I have included a thinking path that traces from project context to this change - [x] I have specified the model used (with version and capability details) - [x] I have checked ROADMAP.md and confirmed this PR does not duplicate planned core work - [x] I have searched GitHub for duplicate or related PRs and linked them above - [x] I have either (a) linked existing issues with `Fixes: #` / `Closes #` / `Refs #` OR (b) described the issue in-PR following the relevant issue template - [x] I have not referenced internal/instance-local Paperclip issues or links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip` URLs) - [x] My branch name describes the change (e.g. `docs/...`, `fix/...`) and contains no internal Paperclip ticket id or instance-derived details - [x] I have run tests locally and they pass - [x] I have added or updated tests where applicable - [x] I have updated relevant documentation to reflect my changes - [x] I have considered and documented any risks above - [ ] All Paperclip CI gates are green - [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge 🤖 Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 5.5 --- server/src/__tests__/execution-control-work.test.ts | 11 +++++++---- 1 file changed, 7 insertions(+), 4 deletions(-) diff --git a/server/src/__tests__/execution-control-work.test.ts b/server/src/__tests__/execution-control-work.test.ts index 9166c7f1da1..584eeafb6af 100644 --- a/server/src/__tests__/execution-control-work.test.ts +++ b/server/src/__tests__/execution-control-work.test.ts @@ -11,6 +11,7 @@ import { resolveExternalTestDatabaseUrl } from "./helpers/external-test-database import { createDeliveryWorkCoordinator } from "../services/delivery-work-coordinator.js"; import { DELIVERY_QUEUES, notifyDeliveryWork } from "../services/delivery-work-notifications.js"; import { executionControlSchedule, registerExecutionControlWork } from "../services/execution-control-work.js"; +import { EXECUTION_RECONCILIATION_INTERVAL_MS } from "../services/execution-control-deadline.js"; import { deliverExecutionStatuses } from "../services/execution-status-delivery.js"; import { terminalizeLegacyExecution } from "../services/legacy-execution-recovery.js"; import { reconcileAbandonedExecutionControl } from "../services/execution-control-reconciliation.js"; @@ -252,7 +253,7 @@ describe.skipIf(!support.supported)("execution-control durable work", () => { }); it("visits a newly committed earlier Retry during a busy recovered-source pass, then becomes quiet", async () => { - const sources = []; + const sources: Awaited>[] = []; for (let index = 0; index < 3; index++) { sources.push(await pausedRecoveredSource(`ffffffff-000${index}-4000-8000-${randomUUID().slice(-12)}`)); } @@ -272,9 +273,11 @@ describe.skipIf(!support.supported)("execution-control durable work", () => { const earlier = await pausedRecoveredSource(`00000000-0000-4000-8000-${randomUUID().slice(-12)}`); sources.push(earlier); release(); - for (let pass = 0; pass < 10 && sources.some(({ run }) => - !resume.mock.calls.some(([visited]) => visited.id === run.id)); pass++) await settle(); - expect(resume.mock.calls.map(([run]) => run.id)).toContain(earlier.run.id); + await vi.waitFor(async () => { + await vi.advanceTimersByTimeAsync(EXECUTION_RECONCILIATION_INTERVAL_MS); + expect(sources.every(({ run }) => resume.mock.calls.some(([visited]) => visited.id === run.id))).toBe(true); + expect(idleWorkSnapshot().active).toBe(0); + }, { timeout: 10_000, interval: 50 }); await quiet(c); for (const { run, retry } of sources) { expect(resume.mock.calls.map(([visited]) => visited.id)).toContain(run.id);