Files
PaperClipAI/server/src/services/run-cancellation.ts
T
ccc77c5b5e fix(server): record legacy controller lease-loss timings (#16359)
## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work
> - The heartbeat runner executes legacy agent runs, and a controller
lease watchdog keeps durable ownership of each run
> - The watchdog renews the lease every 10 seconds and stops the run
when a renewal does not finish within the 60-second lease
> - A staging run failed in setup with `LegacyControllerLeaseLostError`
and the `renewal_deadline` cause, after about eight minutes of
preparation and with no server restart
> - The setup failure path did not record the cause, and no evidence
showed why the renewal did not finish: a stalled database query or a
blocked event loop
> - This pull request records bounded watchdog timings with each lease
loss, on the setup failure path and on the cancellation path
> - The benefit is that the next event shows which of the two causes
stops renewal, which is the missing fact to fix the root cause

## Linked Issues or Issue Description

Refs #16084 (added the closed lease-loss cause for cancelled runs)
Refs #16355 (retries a run that a restart stopped before dispatch; a
different path)

**What happened?**
A legacy `paperclip_runner` run on staging failed with `setup_failed`
and the message "Legacy controller lease lost". The stack shows the
watchdog deadline timer (`renewal_deadline`). The run was in
`executionStage: "preparing"` for about 467 seconds. The server started
about 11 minutes before the run, so this was not a restart. The run
record and the Sentry event do not show the lease-loss cause, because
the setup failure path does not read it. Nothing shows if a renewal
query was in flight at the deadline, or if the deadline callback ran
late.

**Expected behavior**
When the watchdog loses the lease, the run records the closed cause and
the watchdog timings. This applies when the loss fails setup and when it
stops the adapter. The failure report contains only the closed cause and
bounded numbers.

**Steps to reproduce**
1. Start a legacy run with a controller lease.
2. During setup, make a lease renewal query hang for more than 60
seconds, or block the event loop past the deadline.
3. Let the watchdog abort the run.
4. Read `resultJson` on the failed run. Before this change, it has no
lease-loss evidence.

## What Changed

- `legacy-controller-lease.ts`: The watchdog tracks the last successful
renewal, the renewals in flight, the scheduled deadline, and the renewal
count. `LegacyControllerLeaseLostError` now carries `leaseLossTiming`:
`sinceRenewalMs`, `renewalPendingMs` (or `null`), `deadlineLateMs` (only
for `renewal_deadline`), and `renewalCount`. Ownership behavior does not
change.
- `run-cancellation.ts`: Add the `LegacyControllerLeaseLossTiming` type
and `readControllerLeaseLoss()`. The reader accepts only a closed cause
and non-negative finite numbers, and clamps each value to 24 hours.
- `heartbeat/run-completion.ts`: Persist
`resultJson.controllerLeaseLoss` with the cause and timings. This
applies to a lease loss that stops the adapter and to a lease loss that
fails setup (the thrown abort reason).
- `run-failure-diagnostics.ts`: Report `controllerLeaseLossCause` and
the four bounded timing fields from `controllerLeaseLoss`. A setup
failure now gets the cause label too.
- `doc/run-log-events.md`: Document the new record and how to read the
timings.
- Tests: watchdog timings for a stalled query, a blocked event loop, and
a failing query; completion records the evidence for an adapter stop and
for a setup failure; the failure report clamps values, drops unknown
keys, and drops a record without a closed cause.

## Verification

- `pnpm --filter @paperclipai/server exec vitest run
src/services/legacy-controller-lease.test.ts
src/services/heartbeat/run-completion.test.ts
src/services/__tests__/run-failure-report.test.ts
src/services/run-cancellation.test.ts`
- I could not run these tests locally. The sandbox has a 4 GB memory
limit, and `pnpm install` was stopped by the out-of-memory killer during
lockfile resolution. CI is the test run for this change.
- After deployment, a new lease loss shows
`controllerLeaseRenewalPendingMs` and `controllerLeaseDeadlineLateMs` in
the Sentry execution context. A pending time near 50 seconds or more
points at the database. A large deadline lateness points at the event
loop.

## Risks

- Low risk. This change adds diagnostics. It does not change when the
watchdog stops a run, and it does not prevent the lease loss.
- The new `resultJson.controllerLeaseLoss` field is server-written.
Readers ignore unknown values. Old rows do not have it.
- The failure report gets five closed or numeric fields. It gets no
reason text, IDs, or user content.
- The event-loop test blocks the loop for about 80 ms to make the
deadline late. It uses real timers, so a very slow CI host makes the
lateness larger, not smaller.

> 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

- Anthropic Claude Opus 5.5 (`claude-opus-5-5`) in Claude Code, with
tool use (shell, file edits, Sentry and GitHub connectors). The exact
context-window size is not exposed in 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
- [ ] I have run tests locally and they pass (not possible in this
sandbox; see Verification)
- [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: Devin Foley <139239+devinfoley@users.noreply.github.com>
Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
2026-10-14 19:52:23 -07:00

131 lines
7.6 KiB
TypeScript

import type { heartbeatRuns } from "@paperclipai/db";
type Run = Pick<typeof heartbeatRuns.$inferSelect, "status" | "startedAt" | "finishedAt" | "runtimeMode" | "errorCode" | "error" | "resultJson">;
const SOURCES = ["operator", "queued_message", "shutdown", "provider", "transport", "control_plane", "controller_lease", "unknown"] as const;
export type CancellationSource = typeof SOURCES[number];
export interface RunCancellation {
source: CancellationSource;
expected: boolean;
initiator: { type: "user" | "agent" | "system" | "provider"; id?: string };
reason: string;
recordedAt: string;
}
/** Server-owned local evidence. Sentry receives only the closed labels below. */
export function readRunCancellation(result: Run["resultJson"] | undefined): RunCancellation | null {
const value = result?.cancellation;
if (!value || typeof value !== "object" || Array.isArray(value)) return null;
const entry = value as Record<string, unknown>;
const initiator = entry.initiator as Record<string, unknown> | undefined;
if (!SOURCES.includes(entry.source as CancellationSource) || typeof entry.expected !== "boolean" ||
!initiator || !["user", "agent", "system", "provider"].includes(initiator.type as string) ||
typeof entry.reason !== "string" || typeof entry.recordedAt !== "string") return null;
return { source: entry.source as CancellationSource, expected: entry.expected,
initiator: { type: initiator.type as RunCancellation["initiator"]["type"],
...(typeof initiator.id === "string" ? { id: initiator.id } : {}) },
reason: entry.reason.slice(0, 512), recordedAt: entry.recordedAt };
}
export function requestedRunCancellation(result: Run["resultJson"], reason: string): RunCancellation {
const queued = typeof result?.queuedCommentInterruptQueueId === "string";
const actorType = result?.cancelledByActorType ?? result?.interruptedByActorType;
const user = actorType === "user" || actorType === "board" || typeof result?.cancelledByUserId === "string";
const agent = actorType === "agent";
const actorId = result?.cancelledByUserId ?? result?.cancelledByAgentId ?? result?.interruptedByActorId;
const source: CancellationSource = queued ? "queued_message" : user ? "operator" : "control_plane";
return { source, expected: true, initiator: {
type: user ? "user" : agent ? "agent" : "system",
...(typeof actorId === "string" ? { id: actorId } : {}),
}, reason: reason.slice(0, 512), recordedAt: new Date().toISOString() };
}
const LEGACY_CONTROLLER_LEASE_LOSS_CAUSES = ["renewal_rejected", "renewal_deadline", "renewal_error"] as const;
export type LegacyControllerLeaseLossCause = typeof LEGACY_CONTROLLER_LEASE_LOSS_CAUSES[number];
const controllerLeaseLossReason = (cause: LegacyControllerLeaseLossCause) => `Legacy controller lease lost (${cause})`;
/** The host aborted its own adapter after losing durable run ownership. */
export function controllerLeaseLossCancellation(cause: LegacyControllerLeaseLossCause): RunCancellation {
return { source: "controller_lease", expected: false, initiator: { type: "system" },
reason: controllerLeaseLossReason(cause), recordedAt: new Date().toISOString() };
}
/** Closed cause label for diagnostics; only the server-written reason matches. */
export function readControllerLeaseLossCause(cancellation: RunCancellation): LegacyControllerLeaseLossCause | null {
if (cancellation.source !== "controller_lease") return null;
return LEGACY_CONTROLLER_LEASE_LOSS_CAUSES.find(cause => cancellation.reason === controllerLeaseLossReason(cause)) ?? null;
}
/** Watchdog timings at the moment the lease was lost, in milliseconds. */
export interface LegacyControllerLeaseLossTiming {
sinceRenewalMs: number;
renewalPendingMs: number | null;
deadlineLateMs: number | null;
renewalCount: number;
}
/** Read-side record: a `null` timing is dropped, so every present timing is a number. */
export type LegacyControllerLeaseLoss = { cause: LegacyControllerLeaseLossCause }
& Partial<Record<keyof LegacyControllerLeaseLossTiming, number>>;
const MAX_LEASE_LOSS_TIMING = 86_400_000;
const leaseLossTimingValue = (value: unknown) =>
typeof value === "number" && Number.isFinite(value) && value >= 0
? Math.min(Math.round(value), MAX_LEASE_LOSS_TIMING) : undefined;
/** Closed cause and bounded counters only; unknown keys and values are dropped. */
export function readControllerLeaseLoss(value: unknown): LegacyControllerLeaseLoss | null {
if (!value || typeof value !== "object") return null;
const record = value as Record<string, unknown>;
const cause = LEGACY_CONTROLLER_LEASE_LOSS_CAUSES.find(label => label === record.cause);
if (!cause) return null;
const loss: LegacyControllerLeaseLoss = { cause };
for (const field of ["sinceRenewalMs", "renewalPendingMs", "deadlineLateMs", "renewalCount"] as const) {
const timing = leaseLossTimingValue(record[field]);
if (timing !== undefined) loss[field] = timing;
}
return loss;
}
/** Preserve recorded stop intent when adapter completion replaces resultJson. */
export function cancellationResultJson(run: Run, status: string, patch?: Run["resultJson"], errorCode?: string | null, error?: string | null): Run["resultJson"] {
if (status !== "cancelled" && status !== "interrupted") return patch ?? run.resultJson;
const result = { ...run.resultJson, ...patch };
const previous = readRunCancellation(run.resultJson);
let cancellation = previous?.expected ? previous : readRunCancellation(patch) ?? previous;
const code = errorCode ?? run.errorCode;
if (!cancellation) {
if (code === "server_shutdown_interrupted") {
cancellation = { source: "shutdown", expected: true, initiator: { type: "system" },
reason: "Server shutdown interrupted execution", recordedAt: new Date().toISOString() };
} else if (result.cancelledByActorType || result.cancelledByUserId || result.interruptedByActorType || result.queuedCommentInterruptQueueId) {
cancellation = requestedRunCancellation(result, error ?? run.error ?? "Execution stopped");
} else {
const source = code === "duplex_channel_lost" ? "transport" : result.status === "cancelled" ? "provider" : "unknown";
const description = source === "provider" ? "Provider cancelled execution"
: source === "transport" ? "Connection to the execution provider was lost"
: "Execution stopped without a recorded cancellation request";
const detail = error ?? run.error;
cancellation = { source, expected: false, initiator: { type: source === "provider" ? "provider" : "system" },
reason: (!detail || /^cancelled\.?$/i.test(detail) ? description : `${description}: ${detail}`).slice(0, 512),
recordedAt: new Date().toISOString() };
}
}
return { ...result, cancellation };
}
/** Eligibility only; admission still verifies process/lease shutdown and gates.
* Historical ambiguous cancellations and outstanding tools stay held.
*/
export function canContinueCancelledRun(run: Run): boolean {
const cancellation = readRunCancellation(run.resultJson);
return run.status === "cancelled" && run.runtimeMode === "legacy" && Boolean(run.startedAt && run.finishedAt) &&
cancellation?.expected === false && ["provider", "transport"].includes(cancellation.source) &&
run.resultJson?.acpToolInventoryComplete === true && run.resultJson?.acpPendingToolCount === 0;
}
export function isUnexpectedRunCancellation(run: Run): boolean {
const bootstrap = run.resultJson?.executionRecovery as Record<string, unknown> | undefined;
return run.status === "cancelled" && Boolean(run.startedAt) &&
!(bootstrap?.kind === "bootstrap" && bootstrap.providerWorkStarted === false) &&
readRunCancellation(run.resultJson)?.expected !== true;
}