Files
PaperClipAI/server/src/services/execution-projection.test.ts
T
DottaandClaude Opus 5.5 8c578668b8 fix(heartbeat): start new queued runs promptly after restart and name the wait (#19431)
## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work
> - The heartbeat queue starts queued agent turns. Restarts and deploys
happen often.
> - After a restart, new queued turns waited minutes before they
started. The task showed only "Queued", with no reason.
> - The cause is startup order. The queued-run dispatch worker registers
only after many unrelated first passes finish one after another: tool
reviews, delivery workers, the terminal workspace sweep, native restart
recovery, and residual and issue recovery.
> - The server binds its listener before this recovery, and
`/api/health` answers during it. A deployment can route traffic to the
new server for minutes before queued work starts.
> - This pull request starts queued turns that never executed as soon as
plugin workers and adapters are loaded. It also names the wait while the
server starts, recovers, or shuts down.
> - The benefit is that tasks resume quickly after a restart and show a
visible reason while they wait.

## Linked Issues or Issue Description

**What happened?**
On a hosted instance, the server restarted twice for deploys. Both
times, queued runs on idle agents started about 3.5 to 4 minutes after
the restart. Before the restart, the runs also waited about 5 minutes
while the deploy drained the old server. During the wait after the
restart, the execution presentation showed `phase: queued`, `label:
"Queued"`, `cause: null`.

**Expected behavior**
Queued work resumes automatically and quickly after a restart. While it
waits, the task shows a reason.

**Steps to reproduce**
1. Start a task drain (`POST /api/instance/task-drain`). Assign issues
to idle agents. The runs stay queued.
2. Stop the server (SIGTERM) and start it again.
3. Make any startup first pass slow (a large instance does this
naturally). Queued runs start only after every earlier startup pass
finishes.

**Paperclip version or commit**
master at 7e3caa7bac.

**Deployment mode**
Hosted Railway deployment with fleet deploy drain. Reproduced locally
with embedded PostgreSQL and an injected 20-second startup step.

## What Changed

- `heartbeat/queue.ts`: add `resumeFreshQueuedRunsAtStartup`. It starts
queued runs on agents with no run left `running` and no queued retry or
continuation (`started_at`, `retry_of_run_id`,
`process_loss_retry_count`, `continuation_attempt`). Every run still
passes the ordinary per-agent claim and dispatch gates, and scheduling
suppression (including the task drain) still applies.
- `heartbeat.ts`: expose it. Count it as a pending wake, like
`resumeQueuedRunsAfterDrain`, so drain status and upgrade readiness see
it.
- `index.ts`: run that pass at startup after plugin workers and external
adapters load. It does not wait for the unrelated startup first passes.
It skips while a drain, warm standby, or shutdown is active. Log when it
completes and when the full queued-run pass completes, with process
uptime, so a hosted restart shows both timings.
- `execution-projection.ts`: while the server is `starting`,
`recovering`, or `draining` (shutdown), a queued run shows **Waiting for
server restart** (cause `server_restarting`) with a next action. A task
drain keeps its **Waiting for maintenance** reason.
- `doc/execution-semantics.md`: describe the startup fast path and the
new presentation.
- The full queued-run pass, its position after native restart recovery,
and the drain behavior are unchanged.

## Verification

- Red, then green, local restart with a 20-second injected startup step
(embedded PostgreSQL, three process agents, runs queued under a task
drain, SIGTERM, restart):
- Before: the listener bound at 09:41:50.6. Runs started at 09:42:10.8,
20.2 s later, after the slow step ended.
- After: runs started 0.2 to 0.3 s after the listener bound, while the
slow step still ran. Each original run executed once.
- During the before run, `GET /api/issues/:id/execution` showed `Waiting
for server restart` / `server_restarting` until dispatch.
- Red, then green: `execution-projection.test.ts` restart-phase cases
failed on the old code (`label: "Queued"`, `cause: null`) and pass now.
- New `heartbeat-startup-fresh-dispatch.test.ts` (real PostgreSQL): a
fresh run starts; an agent with a `running` row from the previous
process and an agent with a queued retry stay queued; nothing starts
while a task drain is active.
- `npx vitest run` for the new test, `heartbeat-task-drain*.test.ts`,
`execution-projection*.test.ts`, `startup-recovery-timing.test.ts`,
`heartbeat/queue.test.ts`, `liveness.test.ts`: 132 passed.
- `npx tsc --noEmit -p server/tsconfig.json` passed.

## Risks

- New queued runs can start before native restart recovery finishes. The
fast path excludes any agent with a `running` row or a queued retry or
continuation, and the claim checks still enforce issue ownership,
predecessor cleanup, budgets, pauses, and concurrency. A new wakeup
during startup already starts runs at this point, so this adds no new
class of early execution.
- The drain is unchanged. It still holds new runs while the deploy waits
for in-flight runs (the Cloud wait budget is at most 5 minutes). This PR
does not change Cloud.
- The new label depends on the process-local startup phase. It shows
only on the process that is restarting.

> For core feature work, check [`ROADMAP.md`](ROADMAP.md) first and
discuss it in `#dev` before opening the PR. Feature PRs that overlap
with planned core work may need to be redirected — check the roadmap
first. See `CONTRIBUTING.md`.

## Model Used

- Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, via Claude Code with
tool use (shell, file edits, local server runs). Extended reasoning
enabled.

## 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>
2026-11-06 04:00:42 -06:00

327 lines
15 KiB
TypeScript

import { describe, expect, it } from "vitest";
import { projectExecution } from "./execution-projection.js";
import { startTaskDrain, stopTaskDrain } from "./task-admission.js";
import { resetStartupRecoveryStateForTests, setStartupRecoveryPhase } from "../startup-recovery-state.js";
type Run = Parameters<typeof projectExecution>[0];
type Coordinator = NonNullable<Parameters<typeof projectExecution>[1]>;
const now = new Date("2026-09-08T12:00:00Z");
const run = (values: Partial<Run> = {}) =>
({
status: "running",
runtimeMode: "native",
errorCode: null,
nextAction: null,
lastUsefulActionAt: now,
lastOutputAt: null,
startedAt: now,
scheduledRetryAt: null,
scheduledRetryAttempt: 1,
retryOfRunId: null,
executionControlDeadlineAt: null,
...values,
}) as Run;
const coordinator = (values: Partial<Coordinator> = {}) =>
({
phase: "observed",
attempt: 1,
failureCode: null,
failureDetail: {},
nextAttemptAt: null,
leaseExpiresAt: new Date(now.getTime() + 30_000),
controlDeadlineAt: null,
...values,
}) as Coordinator;
const project = (
r = run(),
c: Coordinator | undefined = coordinator(),
pending: { kind: string }[] = [],
) => projectExecution(r, c, pending, undefined, now);
describe("execution truth projection", () => {
it("offers Stop for every live run, including a long-silent native turn", () => {
const silentSince = new Date(now.getTime() - 35 * 60_000);
const silent = run({ lastUsefulActionAt: silentSince, startedAt: silentSince });
expect(project(silent)).toMatchObject({ phase: "working", canStop: true });
expect(project(run({ runtimeMode: "legacy" }), undefined).canStop).toBe(true);
expect(projectExecution(run({ status: "queued", startedAt: null }), undefined, [], undefined, now).canStop).toBe(true);
for (const status of ["succeeded", "cancelled", "timed_out", "failed"] as const) {
expect(project(run({ status }), undefined).canStop).toBe(false);
}
});
it("shows maintenance only for admission that has not started", () => {
startTaskDrain();
try {
expect(projectExecution(run({ status: "queued", startedAt: null }), undefined, [], undefined, now))
.toMatchObject({ phase: "queued", label: "Waiting for maintenance", cause: "task_drain" });
expect(project().phase).toBe("working");
} finally { stopTaskDrain(); }
expect(projectExecution(run({ status: "queued", startedAt: null }), undefined, [], undefined, now))
.toMatchObject({ phase: "queued", label: "Queued", cause: null });
});
it.each(["starting", "recovering", "draining"] as const)("names a server restart while it holds queued work: %s", phase => {
setStartupRecoveryPhase(phase);
try {
for (const queued of [run({ status: "queued", startedAt: null }), run({ status: "queued", startedAt: now, retryOfRunId: "prior" })]) {
const projection = projectExecution(queued, undefined, [], undefined, now);
expect(projection).toMatchObject({ phase: "queued", label: "Waiting for server restart", cause: "server_restarting" });
expect(projection.nextAction).toMatch(/starts automatically/);
}
// A live run is not relabelled; restart recovery owns its own state.
expect(project().phase).toBe("working");
} finally { resetStartupRecoveryStateForTests(); }
expect(projectExecution(run({ status: "queued", startedAt: null }), undefined, [], undefined, now))
.toMatchObject({ label: "Queued", cause: null });
});
it("keeps the maintenance hold reason while a restarted server is still recovering", () => {
setStartupRecoveryPhase("recovering");
startTaskDrain();
try {
expect(projectExecution(run({ status: "queued", startedAt: null }), undefined, [], undefined, now))
.toMatchObject({ label: "Waiting for maintenance", cause: "task_drain" });
} finally { stopTaskDrain(); resetStartupRecoveryStateForTests(); }
});
it.each(["queued", "recovering", "blocked", "recovered"] as const)("shows the exact saved workspace recovery state instead of stale repair instructions: %s", status => {
const sourceRunId = "ec036e06-90a3-4b69-81db-a8eab7dbfbac";
const source = run({ id: sourceRunId, status: "failed", errorCode: "native_continuation_requires_reconciliation" });
const action = {
status: "resolved" as const,
cause: "native_continuation_requires_reconciliation",
nextAction: "The original sandbox is retained for workspace repair.",
evidence: {
runId: sourceRunId,
automaticRecovery: { policy: "preserve_without_replay_v1", actionOutcome: "unknown", replay: "blocked" },
continuationDelivery: "invalidated",
workspaceRecovery: {
schema: "paperclip.workspace-recovery.v1", runId: sourceRunId, status,
stage: "saving_receipts", attempt: 1, requestIds: [],
...(status === "blocked" ? { message: "The saved source cannot be read safely." } : {}),
},
},
};
const projected = projectExecution(source, coordinator({ phase: "terminal_failure" }), [], action, now);
expect(projected).toMatchObject({
phase: "recovery_needed", label: "Stopped", cause: action.cause,
nextAction: status === "recovered" ? "Saved work recovered. Send a message to continue."
: status === "blocked" ? "The saved source cannot be read safely." : "Recovering saved work…",
permittedActions: ["inspect_run"], successorRunId: null,
});
expect(source.status).toBe("failed");
expect(action.evidence.automaticRecovery.replay).toBe("blocked");
expect(projectExecution(source, undefined, [], { ...action,
evidence: { ...action.evidence, workspaceRecovery: { ...action.evidence.workspaceRecovery,
runId: "5f227d75-b314-4511-bf23-9c615277e69b" } },
}, now).nextAction).toBe(action.nextAction);
});
it("keeps cleanup quarantine visible without a coordinator or recovery row", () => {
const stopped = run({ id: "stopped", status: "failed", errorCode: "native_session_cleanup_quarantined" });
expect(projectExecution(stopped, undefined, [], undefined, now)).toMatchObject({
phase: "recovery_needed", cause: "native_session_cleanup_quarantined", recoveryOwner: "board",
permittedActions: ["inspect_run", "inspect_recovery"],
});
expect(projectExecution(stopped, coordinator({ phase: "retryable_failure" }), [], undefined, now).phase).toBe("recovery_needed");
expect(projectExecution({ ...stopped, finishedAt: now }, coordinator({
phase: "terminal_failure", failureCode: "native_provider_terminal_failed",
}), [], undefined, now)).toMatchObject({ phase: "recovery_needed", recoveryOwner: "board" });
expect(projectExecution({ ...stopped, errorCode: "provider_frame_too_large" }, undefined, [], undefined, now).phase).toBe("failed");
expect(projectExecution(stopped, undefined, [], { status: "resolved", cause: "native_session_cleanup_quarantined", nextAction: "Verify prior execution",
evidence: { executionReconciliation: { providerStopped: true }, continuationRunId: "successor" } }, now))
.toMatchObject({ phase: "completed", successorRunId: "successor", cause: null });
});
it("shows subscription contention as a resource wait without failed provider attempts", () => {
expect(projectExecution(run({ runtimeMode: "legacy", status: "scheduled_retry", scheduledRetryReason: "ai_connection_busy",
scheduledRetryAttempt: 12, contextSnapshot: { failureRetriesBeforeAiConnectionWait: 0 } }), undefined, [], undefined, now))
.toMatchObject({ label: "Waiting for AI subscription", phase: "retry_scheduled", attempt: 1, recoveryOwner: null });
});
it("shows a provider usage limit wait with its reset time", () => {
const scheduledRetryAt = new Date("2026-11-05T13:47:50.375Z");
expect(projectExecution(run({ runtimeMode: "native", status: "scheduled_retry", scheduledRetryReason: "ai_connection_pool_wait",
scheduledRetryAt, scheduledRetryAttempt: 3, contextSnapshot: { wakeReason: "provider_limit_retry", failureRetriesBeforeAiConnectionWait: 0 } }),
undefined, [], undefined, now)).toMatchObject({
label: "Waiting for usage limit reset", phase: "retry_scheduled", attempt: 1, recoveryOwner: null,
nextAction: expect.stringContaining(scheduledRetryAt.toISOString()),
});
});
it("shows a workspace wait without presenting its deferral count as failed attempts", () => {
expect(projectExecution(run({ runtimeMode: "legacy", status: "scheduled_retry", scheduledRetryReason: "workspace_busy",
scheduledRetryAttempt: 12, contextSnapshot: { failureRetriesBeforeWorkspaceWait: 1 } }), undefined, [], undefined, now))
.toMatchObject({ label: "Waiting for workspace", phase: "retry_scheduled", attempt: 2, recoveryOwner: null });
});
it.each([
{ status: "resolved", previousRunId: "old", nextRunId: "next", continued: true },
{ status: "active", previousRunId: "old", nextRunId: "next", continued: false },
{ status: "resolved", previousRunId: "other", nextRunId: "next", continued: false },
{ status: "resolved", previousRunId: "old", nextRunId: "old", continued: false },
{ status: "resolved", previousRunId: "old", nextRunId: null, continued: false },
])("projects the recorded explicit successor without hiding unresolved recovery: $status/$previousRunId/$nextRunId", ({ status, previousRunId, nextRunId, continued }) => {
const source = run({ id: "old", status: "failed", errorCode: "adapter_failed" });
expect(projectExecution(source, coordinator({ phase: "terminal_failure" }), [], {
status,
cause: "native_continuation_requires_reconciliation",
nextAction: "Inspect the stopped execution.",
evidence: {
automaticRecovery: { policy: "preserve_without_replay_v1" },
explicitUserContinuation: { previousRunId, runId: nextRunId },
},
}, now)).toMatchObject(continued ? {
phase: "completed", label: "Continued in another run", successorRunId: "next",
cause: "native_continuation_requires_reconciliation", nextAction: null,
} : { phase: "recovery_needed", successorRunId: null });
expect(source.status).toBe("failed");
});
it("shows a reconciled continuation as queued until its durable delivery is recorded", () => {
const action = {
cause: "native_session_retry_exhausted",
nextAction: "Old recovery action",
status: "resolved" as const,
evidence: {
executionReconciliation: { runId: "old" },
continuationDelivery: "pending",
},
};
expect(
projectExecution(
run({ status: "failed" }),
coordinator({ phase: "terminal_failure" }),
[],
action,
now,
),
).toMatchObject({
phase: "queued",
label: "Continuation queued",
cause: null,
});
expect(
projectExecution(
run({ status: "failed" }),
coordinator({ phase: "terminal_failure" }),
[],
{
...action,
evidence: { ...action.evidence, continuationRunId: "next" },
},
now,
),
).toMatchObject({ phase: "completed", successorRunId: "next" });
expect(
projectExecution(
run({ status: "failed" }),
coordinator({ phase: "terminal_failure" }),
[],
{
...action,
evidence: { ...action.evidence, continuationDelivery: "invalidated" },
},
now,
),
).toMatchObject({ phase: "failed", label: "Continuation cancelled" });
});
it("requires current execution evidence, without treating output silence as failure", () => {
expect(project(run({ lastOutputAt: new Date(0) })).phase).toBe("working");
expect(
project(run(), coordinator({ leaseExpiresAt: new Date(0) })),
).toMatchObject({ phase: "reconnecting", label: "Confirming execution" });
expect(
project(
run({ runtimeMode: "legacy", processPid: process.pid }),
undefined,
).phase,
).toBe("working");
});
it("distinguishes provider work, finalization and timed retry", () => {
expect(
project(
run({ executionControlDeadlineAt: new Date(now.getTime() + 60_000) }),
).phase,
).toBe("finishing");
expect(
project(
run({ status: "failed" }),
coordinator({
phase: "retryable_failure",
nextAttemptAt: new Date(now.getTime() + 30_000),
attempt: 2,
}),
),
).toMatchObject({ phase: "retry_scheduled", attempt: 2, maxAttempts: 3 });
expect(
project(
run({ status: "failed" }),
coordinator({ phase: "retryable_failure", nextAttemptAt: new Date(0) }),
).phase,
).toBe("reconnecting");
});
it("includes the original legacy attempt in the displayed incident budget", () => {
expect(projectExecution(run({ runtimeMode: "legacy", status: "scheduled_retry", scheduledRetryAttempt: 1 }), undefined, [], undefined, now)).toMatchObject({ attempt: 2, maxAttempts: 3 });
});
it("shows pending interaction only after productive work has stopped", () => {
expect(
project(run(), coordinator(), [{ kind: "connection_intent" }]).phase,
).toBe("working");
expect(
project(run({ status: "succeeded" }), undefined, [
{ kind: "connection_intent" },
]).phase,
).toBe("waiting_for_access");
expect(
project(run({ status: "succeeded" }), undefined, [
{ kind: "ask_user_questions" },
]).phase,
).toBe("waiting_for_answer");
});
it("retains replacement lineage and exposes operator-owned failures for legacy runs", () => {
expect(
project(
run({ status: "failed" }),
coordinator({
phase: "terminal_failure",
failureDetail: { successorRunId: "replacement" },
}),
),
).toMatchObject({ phase: "completed", successorRunId: "replacement" });
expect(
projectExecution(
run({ runtimeMode: "legacy", status: "failed" }),
undefined,
[],
{
cause: "uncertain_external_action",
nextAction: "Reconcile the email delivery.",
},
now,
),
).toMatchObject({
phase: "recovery_needed",
recoveryOwner: "board",
nextAction: "Reconcile the email delivery.",
});
});
it("bounds recovery checking and surfaces its next action if verification never finishes", () => {
const c = coordinator({
phase: "terminal_failure",
failureCode: "native_provider_terminal_failed",
});
expect(project(run({ status: "failed", finishedAt: now }), c).label).toBe(
"Checking recovery",
);
expect(
project(
run({ status: "failed", finishedAt: new Date(now.getTime() - 60_000) }),
c,
).phase,
).toBe("recovery_needed");
expect(
project(
run({ status: "failed", finishedAt: now }),
coordinator({
...c,
failureDetail: { replacementDenied: "uncertain_provider_action" },
}),
).phase,
).toBe("recovery_needed");
});
});