test(server): drain throttled follow-up in busy recovered-source execution-control test (#19403)

## 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 <noreply@anthropic.com>
This commit is contained in:
DottaandClaude Opus 5.5 authored and GitHub committed 2026-11-05 22:58:33 -06:00
1 parent 223687bbb9
commit 612da1e8e0
1 file changed
+7 -4
@@ -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<ReturnType<typeof pausedRecoveredSource>>[] = [];
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);