From d6d88b9de2fc766637422cc43f985c747455a1b0 Mon Sep 17 00:00:00 2001 From: Devin Foley Date: Fri, 2 Oct 2026 14:16:18 -0700 Subject: [PATCH] fix: preserve run outcomes when agent file cleanup is deferred (#14945) ## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work. > - The heartbeat service records each agent turn and releases its working files. > - A turn can save its work and finish before instruction-copy cleanup runs. > - A cleanup exception can replace that completed result with an adapter failure. > - This also loses result accounting and can prevent environment lease release. > - This pull request records a cleanup warning and keeps the original run outcome. > - The existing recovery sweep retries cleanup from the durable working-copy record. ## Linked Issues or Issue Description Related cleanup and lock work: #14866 and #14869. Related, distinct work: #14695 retains warm-process files; #12021 handles provider-process SIGTERM after a terminal result. **What happened?** An agent saved its plan, posted a comment, and requested approval. The provider completed its turn. Instruction-copy cleanup then timed out on a directory lock. Its exception escaped a `finally` block and replaced the provider result, so the completed turn showed `Run failed`. **Expected behavior** Keep the provider outcome, usage, cost, saved work, and pending approval. Record a cleanup warning and let the existing recovery sweep retry. A real provider failure must keep its original error. A failed file save must keep its failed-save receipt. **Steps to reproduce** 1. Complete a legacy adapter turn that saves work and requests approval. 2. Make instruction-copy release throw a directory-lock timeout. 3. Read the run result. Before this change, the cleanup error replaces the provider outcome. The new heartbeat tests reproduce the failure without a live provider or external service. **Paperclip version or commit** The regression reproduces on `c83df091b1a5207375eaf23466bb5c62e4e1518e`. This branch is rebased onto `cf8ad63c80`. **Deployment mode** Server-managed agent execution with persistent instruction working copies. ## What Changed - Catch instruction-copy release failures in both heartbeat teardown paths. Stop repeating a failed cleanup attempt within the same run. - Write a sanitized `instruction_cleanup` warning. A warning-write failure also preserves the run result. - Test successful, failed, and throwing providers; both teardown paths; warning-write failure; accounting; approval state; and execution-control release. - Extend the held-lock test to prove a fresh recovery worker removes the deferred copy and preserves its failed-save receipt. - Document deferred cleanup and the run-log event. ## Verification - Red proof: all five new heartbeat regression cases fail with the original release calls. - At head `20bea4f431c916d2f5db1970213aab85f5daa34c`, all 417 tests passed across heartbeat process recovery, agent directory working copies, and directory merge locks. - Full local `pnpm -r typecheck`, `pnpm build`, and `git diff --check` passed. - [GitHub CI](https://github.com/paperclipai/paperclip/actions/runs/37031119795) passed at this head. All 53 reported checks passed; the two Storybook checks were correctly skipped. This includes general and serialized tests, browser shards, runner verification, build, typecheck, and the canary dry run. - Greptile reviewed this head with 5/5, no code comments, and no unresolved review threads. The branch has no merge conflicts. - The local `pnpm test:run` attempt was stopped after it reported eight failures in unchanged suites. Four Slack/AgentMail cases selected an unrelated ancestor skills directory and failed with `ENOENT`; the two Slack cases passed with a temporary local skill-root link, which was then removed. Three company-skill cases reproduced macOS `EACCES` errors when renaming read-only cache directories. One gateway case passed when rerun alone. No full local-suite pass is claimed; the complete CI test jobs passed. ## Risks - Cleanup errors now leave recovery work pending. The durable working-copy record remains available for the existing retry sweep. - This change preserves provider failures and failed-save receipts. It does not claim that unsaved file edits were saved. - Native instruction reservation errors retain their existing behavior because they guard process ownership. - No schema, lockfile, workflow, API, or UI changes. ## Model Used OpenAI Codex, based on GPT-6, with reasoning, repository tools, and code execution. The exact backend model ID and context-window size are not exposed by this session. ## 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 - [x] All Paperclip CI gates are green - [x] Greptile is 5/5 with no open P2s, recommendations, or follow-ups - [x] I will address all Greptile and reviewer comments before requesting merge Co-authored-by: Paperclip --- doc/agent-files.md | 6 ++ doc/run-log-events.md | 7 ++ .../agent-directory-working-copies.test.ts | 10 +++ .../heartbeat-process-recovery.test.ts | 68 +++++++++++++++++++ server/src/services/heartbeat.ts | 28 +++++++- 5 files changed, 117 insertions(+), 2 deletions(-) diff --git a/doc/agent-files.md b/doc/agent-files.md index 2cfd67c668..a4154551f1 100644 --- a/doc/agent-files.md +++ b/doc/agent-files.md @@ -180,6 +180,12 @@ unavailable local copy can still contain uncollected edits; this cleanup path preserves those bytes even if local stop proof arrives later. Deferred cleanup retries after a delay so one blocked copy does not prevent other copies from being cleaned. +If releasing a run's instruction copy fails, the run records a cleanup warning +and leaves the durable copy for the recovery sweep. Cleanup does not replace the +provider's result, discard usage accounting, or prevent environment lease release. +It does not claim that unsaved agent-file changes were saved; collection failures +keep their separate failed-save receipts. A run attempts failed cleanup only once +before handing it to recovery, rather than repeating the lock wait in teardown. Re-preparing an existing run uses the same lock as cleanup and rechecks its receipt under that lock. Preparing a new run keeps its separate admission path. Missing stop proof or lost remote bytes produce a visible diagnostic, never a diff --git a/doc/run-log-events.md b/doc/run-log-events.md index dd962b0aa2..069b45144c 100644 --- a/doc/run-log-events.md +++ b/doc/run-log-events.md @@ -357,3 +357,10 @@ Successful checkpoints can include `checkpointStats`: `scannedEntries`, capture, not cumulative traffic or an atomic snapshot of background writers. They contain no file contents. The receipt remains in the instance run log; it adds no Paperclip Telemetry or OpenTelemetry export. + +If instruction-copy release throws, `instruction_cleanup` records a warning +with payload `{ "state": "deferred" }`. The existing working-copy recovery sweep +retries cleanup. This event preserves the run outcome and does not claim a file +save; `instruction_save` remains authoritative for collection. The event contains +no raw exception, host path, file contents, or lock-owner metadata. Failure to +write the warning must not replace the provider outcome or stop lease release. diff --git a/server/src/__tests__/agent-directory-working-copies.test.ts b/server/src/__tests__/agent-directory-working-copies.test.ts index 97ca234e07..32e37089a3 100644 --- a/server/src/__tests__/agent-directory-working-copies.test.ts +++ b/server/src/__tests__/agent-directory-working-copies.test.ts @@ -880,6 +880,16 @@ describe("persistent agent directories", () => { expect(await fs.readFile(path.join(blocked.localRoot, entryFile), "utf8")).toBe(initial); await expect(fs.stat(other.localRoot)).rejects.toMatchObject({ code: "ENOENT" }); }); + // A fresh recovery worker retries after the holder releases the lock. It + // cleans the pending copy without changing the failed-save receipt. + const deferred = (await copies.get(companyId, blocked.runId))!; + await db.update(agentInstructionWorkingCopies).set({ nextAttemptAt: new Date(0) }) + .where(eq(agentInstructionWorkingCopies.runId, blocked.runId)); + await agentInstructionWorkingCopyService(db).recoverCaptured(); + expect(await copies.get(companyId, blocked.runId)).toMatchObject({ state: deferred.state, + errorCode: deferred.errorCode, errorMessage: deferred.errorMessage, + candidateHash: deferred.candidateHash, receipt: { cleanupPending: false }, nextAttemptAt: null }); + await expect(fs.stat(blocked.localRoot)).rejects.toMatchObject({ code: "ENOENT" }); }); it.each(["environment", "path", "lease-run"])("rejects destruction outside the registered copy binding (%s)", async mismatch => { diff --git a/server/src/__tests__/heartbeat-process-recovery.test.ts b/server/src/__tests__/heartbeat-process-recovery.test.ts index bef526a10d..07bef2d6d8 100644 --- a/server/src/__tests__/heartbeat-process-recovery.test.ts +++ b/server/src/__tests__/heartbeat-process-recovery.test.ts @@ -1,6 +1,8 @@ import * as executionContinuation from "../services/execution-continuation.js"; import { legacyDispositionFingerprint, LEGACY_DISPOSITION_REPAIR_INSTRUCTION } from "../services/recovery/legacy-continuation.js"; import * as controllerLeases from "../services/legacy-controller-lease.js"; +import * as instructionWorkingCopies from "../services/agent-instruction-working-copies.js"; +import * as runEvents from "../services/heartbeat-run-events.js"; import { instanceSettingsService } from "../services/instance-settings.js"; import { randomUUID } from "node:crypto"; import { terminalizeLegacyExecution } from "../services/legacy-execution-recovery.js"; @@ -7147,6 +7149,72 @@ describeEmbeddedPostgres("heartbeat orphaned process recovery", () => { expect(repairWakeups).toHaveLength(0); }); + it.each([ + { providerOutcome: "succeeded", cleanupAt: "inner", warningFails: false }, + { providerOutcome: "failed", cleanupAt: "inner", warningFails: false }, + { providerOutcome: "throws", cleanupAt: "inner", warningFails: false }, + { providerOutcome: "succeeded", cleanupAt: "outer", warningFails: false }, + { providerOutcome: "succeeded", cleanupAt: "inner", warningFails: true }, + ] as const)("preserves a $providerOutcome provider outcome when instruction cleanup times out ($cleanupAt, warning failure: $warningFails)", async ({ providerOutcome, cleanupAt, warningFails }) => { + const { companyId, agentId, runId, issueId } = await seedRunFixture({ runtimeMode: "legacy", agentStatus: "idle", runStatus: "queued" }); + const interactionId = randomUUID(); + const release = vi.fn().mockRejectedValue(Object.assign(new Error("Timed out waiting for workspace restore lock at /private/agent-files.lock"), { + code: "ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT", + })); + if (cleanupAt === "outer") release.mockResolvedValueOnce(undefined); + const originalFactory = instructionWorkingCopies.agentInstructionWorkingCopyService; + const factory = vi.spyOn(instructionWorkingCopies, "agentInstructionWorkingCopyService").mockImplementation((...args) => ({ + ...originalFactory(...args), release, + })); + const originalAppend = runEvents.appendHeartbeatRunEvent; + const append = vi.spyOn(runEvents, "appendHeartbeatRunEvent").mockImplementation((db, event) => { + if (warningFails && event.eventType === "instruction_cleanup") throw new Error("Fixture warning persistence failed"); + return originalAppend(db, event); + }); + mockAdapterExecute.mockImplementationOnce((async () => { + await db.insert(issueThreadInteractions).values({ id: interactionId, companyId, issueId, sourceRunId: runId, + kind: "request_confirmation", title: "Approve the saved plan", payload: { version: 1, prompt: "Accept the plan?" } }); + await db.update(issues).set({ status: "in_review" }).where(eq(issues.id, issueId)); + await db.insert(issueComments).values({ companyId, issueId, authorAgentId: agentId, createdByRunId: runId, body: "Plan saved; awaiting approval." }); + if (providerOutcome === "throws") throw new Error("Original provider failure"); + return { exitCode: providerOutcome === "succeeded" ? 0 : 1, signal: null, timedOut: false, + errorCode: providerOutcome === "succeeded" ? null : "provider_failed", + errorMessage: providerOutcome === "succeeded" ? null : "Original provider failure", + summary: "Plan saved; awaiting approval.", provider: "test", model: "test-model", + usage: { inputTokens: 100, outputTokens: 25 }, costUsd: 0.05 }; + }) as typeof mockAdapterExecute); + const heartbeat = heartbeatService(db); + try { + await heartbeat.resumeQueuedRuns(); + await heartbeat.drainActiveRunExecutions(); + const settled = await heartbeat.getRun(runId); + expect(settled).toMatchObject({ status: providerOutcome === "succeeded" ? "succeeded" : "failed", + error: providerOutcome === "succeeded" ? null : "Original provider failure" }); + if (providerOutcome !== "throws") { + expect(settled?.resultJson?.summary).toBe("Plan saved; awaiting approval."); + expect(settled?.usageJson).toMatchObject({ inputTokens: 100, outputTokens: 25 }); + const costs = await db.select().from(costEvents).where(eq(costEvents.heartbeatRunId, runId)); + expect(costs).toHaveLength(1); + expect(costs[0]?.costCents).toBe(5); + } + expect(release).toHaveBeenCalledTimes(cleanupAt === "outer" ? 2 : 1); + expect(adapterExecutionControls.has(runId)).toBe(false); + const warnings = await db.select().from(heartbeatRunEvents).where(and(eq(heartbeatRunEvents.runId, runId), eq(heartbeatRunEvents.eventType, "instruction_cleanup"))); + expect(warnings).toHaveLength(warningFails ? 0 : 1); + if (!warningFails) expect(warnings[0]).toMatchObject({ level: "warn", payload: { state: "deferred" } }); + expect(JSON.stringify(warnings)).not.toContain("/private/"); + expect(await db.select().from(issueComments).where(eq(issueComments.issueId, issueId))).toEqual(expect.arrayContaining([ + expect.objectContaining({ body: "Plan saved; awaiting approval." }), + ])); + expect((await db.select().from(issueThreadInteractions).where(eq(issueThreadInteractions.id, interactionId)))[0]?.status).toBe("pending"); + expect((await db.select().from(issues).where(eq(issues.id, issueId)))[0]?.status).toBe("in_review"); + expect(await db.select().from(heartbeatRuns).where(eq(heartbeatRuns.retryOfRunId, runId))).toHaveLength(0); + } finally { + factory.mockRestore(); + append.mockRestore(); + } + }); + it("stops controller renewal and releases execution controls when teardown deadline cleanup throws", async () => { const { runId, issueId } = await seedRunFixture({ runtimeMode: "legacy", agentStatus: "idle", runStatus: "queued" }); mockAdapterExecute.mockImplementationOnce(async () => { diff --git a/server/src/services/heartbeat.ts b/server/src/services/heartbeat.ts index e41bd2acff..5d8e295559 100644 --- a/server/src/services/heartbeat.ts +++ b/server/src/services/heartbeat.ts @@ -20318,6 +20318,30 @@ export function heartbeatService( run = claimed; } + const instructionCleanupRun = run; + let instructionCleanupDeferred = false; + const releaseInstructionCopy = async () => { + // Cleanup is retried from the durable working-copy receipt by the + // recovery sweep. It must not replace the provider result (or prevent + // lease release), and a timeout must not be repeated in outer teardown. + if (instructionCleanupDeferred) return; + try { + await instructionCopies.release(instructionCleanupRun.companyId, instructionCleanupRun.id); + } catch (err) { + instructionCleanupDeferred = true; + logger.warn({ err, runId: instructionCleanupRun.id }, "Agent file cleanup deferred; run outcome preserved"); + await appendRunEvent(instructionCleanupRun, { + eventType: "instruction_cleanup", + stream: "system", + level: "warn", + message: "Agent file cleanup was deferred. The run outcome and file-save receipt are unchanged.", + payload: { state: "deferred" }, + }).catch((eventError) => { + logger.warn({ err: eventError, runId: instructionCleanupRun.id }, "Failed to record deferred agent file cleanup"); + }); + } + }; + if ( runOptions.nativeLeaseOwner && run.runtimeMode === "native" && @@ -25211,7 +25235,7 @@ export function heartbeatService( ); } await nativeInstructionReservation?.release(); - await instructionCopies.release(agent.companyId, run.id); + await releaseInstructionCopy(); } // Reconcile the referenced-project set against the real remote staging outcome. A referenced // project can pass authorization and clone locally at run prep, then fail to stage into the @@ -26617,7 +26641,7 @@ export function heartbeatService( message: "Instruction edits could not be recovered before environment release. No instruction save is claimed.", payload: { state: "unavailable", code: uncapturedInstructions.errorCode } }); } - await instructionCopies.release(run.companyId, run.id); + await releaseInstructionCopy(); await releaseEnvironmentLeasesForRun({ runId: run.id, companyId: run.companyId,