diff --git a/doc/run-log-events.md b/doc/run-log-events.md index 10912e00640..d71bbe9283e 100644 --- a/doc/run-log-events.md +++ b/doc/run-log-events.md @@ -334,6 +334,14 @@ The local lifecycle event includes this evidence. Started cancellations without an expected stop are also reported to Sentry; its cancellation diagnostics contain only source, expectedness, initiator type, and the closed lease-loss cause, never initiator IDs or reason text. +A lease loss also records `resultJson.controllerLeaseLoss`, including a loss +during setup that fails the run before adapter dispatch. It holds the closed +cause and the watchdog timings in milliseconds: `sinceRenewalMs` (since the +last successful renewal), `renewalPendingMs` (age of a renewal query still in +flight, or `null`), `deadlineLateMs` (how late the deadline callback ran, for +`renewal_deadline` only), and `renewalCount`. A long `renewalPendingMs` points +at a stalled database query; a long `deadlineLateMs` points at a blocked event +loop. Failure reports carry these bounded numbers and the cause label only. Historical ambiguous cancellations stay `unknown` and do not authorize replay. Provider tool-definition validation failures use diff --git a/server/src/services/__tests__/run-failure-report.test.ts b/server/src/services/__tests__/run-failure-report.test.ts index 038f2b6fd32..6feb238bc71 100644 --- a/server/src/services/__tests__/run-failure-report.test.ts +++ b/server/src/services/__tests__/run-failure-report.test.ts @@ -939,6 +939,27 @@ describeEmbeddedPostgres("reportRunFailure", () => { cancellationSource: "controller_lease", cancellationExpected: false, controllerLeaseLossCause: "renewal_deadline" } } }); expect(JSON.stringify(mockCaptureRunFailure.mock.calls)).not.toMatch(/Legacy controller lease lost/); }); + it("reports bounded lease-loss timings for a setup failure", async () => { + await seedCompanyAndAgent(); + await reportRunFailure(db, buildRun({ status: "failed", errorCode: "setup_failed", startedAt: new Date(0), + finishedAt: new Date(1000), resultJson: { controllerLeaseLoss: { cause: "renewal_deadline", + sinceRenewalMs: 61_000.4, renewalPendingMs: 59_000, deadlineLateMs: 1e12, renewalCount: -1, note: "private-note" } } })); + expect(mockCaptureRunFailure).toHaveBeenCalledOnce(); + const execution = mockCaptureRunFailure.mock.calls[0][0].diagnostics.execution; + expect(execution).toMatchObject({ controllerLeaseLossCause: "renewal_deadline", controllerLeaseSinceRenewalMs: 61_000, + controllerLeaseRenewalPendingMs: 59_000, controllerLeaseDeadlineLateMs: 86_400_000 }); + expect(execution).not.toHaveProperty("controllerLeaseRenewalCount"); + expect(JSON.stringify(mockCaptureRunFailure.mock.calls)).not.toMatch(/private-note/); + }); + it("drops lease-loss timings without a closed cause", async () => { + await seedCompanyAndAgent(); + await reportRunFailure(db, buildRun({ status: "failed", errorCode: "setup_failed", startedAt: new Date(0), + finishedAt: new Date(1000), resultJson: { controllerLeaseLoss: { cause: "forged", sinceRenewalMs: 1 } } })); + expect(mockCaptureRunFailure).toHaveBeenCalledOnce(); + const execution = mockCaptureRunFailure.mock.calls[0][0].diagnostics.execution; + expect(execution).not.toHaveProperty("controllerLeaseLossCause"); + expect(execution).not.toHaveProperty("controllerLeaseSinceRenewalMs"); + }); it("does not report an operator's Stop as a failure", async () => { await seedCompanyAndAgent(); await reportRunFailure(db, buildRun({ status: "cancelled", startedAt: new Date(0), resultJson: { diff --git a/server/src/services/heartbeat/run-completion.test.ts b/server/src/services/heartbeat/run-completion.test.ts index beb1c545801..bb1e74005c3 100644 --- a/server/src/services/heartbeat/run-completion.test.ts +++ b/server/src/services/heartbeat/run-completion.test.ts @@ -175,6 +175,26 @@ describe.skipIf(!support.supported)("heartbeat run completion boundary", () => { cancellation: { source: "controller_lease", expected: false, reason: "Legacy controller lease lost (renewal_rejected)" } } }); }); + it("records the watchdog timings with a lease loss that stops the adapter", async () => { + const f = await fixture(); + Object.assign(f.input.adapterResult, { exitCode: null, errorCode: "cancelled", errorMessage: "Grok execution was cancelled" }); + f.controller.abort(new LegacyControllerLeaseLostError("renewal_deadline", + { sinceRenewalMs: 61_000, renewalPendingMs: 58_000, deadlineLateMs: 2, renewalCount: 41 })); + await f.completion.completeRun(f.input); + expect((await read(f.run.id)).resultJson).toMatchObject({ controllerLeaseLoss: { + cause: "renewal_deadline", sinceRenewalMs: 61_000, renewalPendingMs: 58_000, deadlineLateMs: 2, renewalCount: 41 } }); + }); + + it("records the lease-loss cause and timings when setup fails on the abort reason", async () => { + const f = await fixture(); + await f.completion.failRunSetup(f.setup(new LegacyControllerLeaseLostError("renewal_deadline", + { sinceRenewalMs: 60_004, renewalPendingMs: null, deadlineLateMs: 55_000, renewalCount: 3 }))); + expect(await read(f.run.id)).toMatchObject({ status: "failed", errorCode: "setup_failed", resultJson: { + executionRecovery: { kind: "bootstrap", providerWorkStarted: false }, + controllerLeaseLoss: { cause: "renewal_deadline", sinceRenewalMs: 60_004, renewalPendingMs: null, + deadlineLateMs: 55_000, renewalCount: 3 } } }); + }); + it("keeps a stop requested before the lease loss when the adapter throws", async () => { const f = await fixture(); const requested = requestedRunCancellation({ cancelledByActorType: "user", cancelledByUserId: "operator-1" }, "Stopped from the board"); diff --git a/server/src/services/heartbeat/run-completion.ts b/server/src/services/heartbeat/run-completion.ts index 970acf1881f..83767f3e780 100644 --- a/server/src/services/heartbeat/run-completion.ts +++ b/server/src/services/heartbeat/run-completion.ts @@ -317,11 +317,22 @@ function readNonEmptyString(value: unknown): string | null { return typeof value === "string" && value.trim().length > 0 ? value : null; } +// Keep the watchdog's closed cause and timings so the run and its failure +// report show whether renewal stalled in the database or the event loop. +function controllerLeaseLossEvidence(reason: unknown) { + return reason instanceof LegacyControllerLeaseLostError + ? { controllerLeaseLoss: { cause: reason.leaseLossCause, ...reason.leaseLossTiming } } + : {}; +} + // Attribute a stop the lease watchdog caused, whether the adapter returned // or threw. A requested stop recorded earlier still wins in cancellationResultJson. function controllerLeaseLossResultJson(signal: AbortSignal) { return signal.reason instanceof LegacyControllerLeaseLostError - ? { cancellation: controllerLeaseLossCancellation(signal.reason.leaseLossCause) } + ? { + cancellation: controllerLeaseLossCancellation(signal.reason.leaseLossCause), + ...controllerLeaseLossEvidence(signal.reason), + } : {}; } @@ -1330,6 +1341,8 @@ export function createHeartbeatRunCompletion(db: Db, dependencies: HeartbeatRunC const setupFailureResultJson = { ...setupFailureDetails, ...(connectionFailure ? { connectionFailure } : {}), + // A lease lost during setup surfaces as the thrown abort reason. + ...controllerLeaseLossEvidence(outerErr), executionRecovery: { kind: "bootstrap", providerWorkStarted: false }, }; const setupFailureWrite = await setRunStatusIfRunning(runId, "failed", { diff --git a/server/src/services/legacy-controller-lease.test.ts b/server/src/services/legacy-controller-lease.test.ts index 2280f70dd0e..354d88923f0 100644 --- a/server/src/services/legacy-controller-lease.test.ts +++ b/server/src/services/legacy-controller-lease.test.ts @@ -4,7 +4,7 @@ import { afterAll, beforeAll, describe, expect, it, vi } from "vitest"; import { agents, companies, createDb, heartbeatRuns } from "@paperclipai/db"; import { getEmbeddedPostgresTestSupport, startEmbeddedPostgresTestDatabase } from "../__tests__/helpers/embedded-postgres.js"; import { heartbeatService } from "./heartbeat.js"; -import { hasLiveLegacyController, LEGACY_CONTROLLER_RENEW_MS, legacyControllerBootId, legacyControllerClaim, LegacyControllerLeaseLostError, +import { hasLiveLegacyController, LEGACY_CONTROLLER_LEASE_MS, LEGACY_CONTROLLER_RENEW_MS, legacyControllerBootId, legacyControllerClaim, LegacyControllerLeaseLostError, renewLegacyControllerLease, revokeExpiredLegacyController, revokeExpiredLegacyControllerWithState, watchLegacyControllerLease } from "./legacy-controller-lease.js"; @@ -147,6 +147,44 @@ describe("legacy controller lease loss attribution", () => { await vi.advanceTimersByTimeAsync(LEGACY_CONTROLLER_RENEW_MS + 1); expect(controller.signal.reason).toBeInstanceOf(LegacyControllerLeaseLostError); expect(controller.signal.reason.leaseLossCause).toBe("renewal_error"); + expect(controller.signal.reason.leaseLossTiming).toMatchObject({ renewalPendingMs: null, deadlineLateMs: null, renewalCount: 0 }); } finally { watch.stop(); vi.useRealTimers(); } }); + + type WatchArgs = Parameters; + const watchedRun = (leaseMs: number) => ({ id: randomUUID(), companyId: randomUUID(), runtimeMode: "legacy", + controllerBootId: legacyControllerBootId, controllerLeaseExpiresAt: new Date(Date.now() + leaseMs) }) as WatchArgs[1]; + + it("records a renewal still in flight when a stalled query reaches the deadline", async () => { + let calls = 0; + const stallingDb = { update: () => ({ set: () => ({ where: () => ({ returning: () => { + calls += 1; + return calls <= 2 ? Promise.resolve([{ id: "run" }]) : new Promise(() => {}); + } }) }) }) } as unknown as WatchArgs[0]; + vi.useFakeTimers(); + const controller = new AbortController(); + const watch = watchLegacyControllerLease(stallingDb, watchedRun(LEGACY_CONTROLLER_LEASE_MS), controller); + try { + await vi.advanceTimersByTimeAsync(2 * LEGACY_CONTROLLER_RENEW_MS); + expect(controller.signal.aborted).toBe(false); + await vi.advanceTimersByTimeAsync(LEGACY_CONTROLLER_LEASE_MS + 1); + expect(controller.signal.reason.leaseLossCause).toBe("renewal_deadline"); + expect(controller.signal.reason.leaseLossTiming).toEqual({ sinceRenewalMs: LEGACY_CONTROLLER_LEASE_MS, + renewalPendingMs: LEGACY_CONTROLLER_LEASE_MS - LEGACY_CONTROLLER_RENEW_MS, deadlineLateMs: 0, renewalCount: 2 }); + } finally { watch.stop(); vi.useRealTimers(); } + }); + + it("records how late the deadline ran when the event loop was blocked", async () => { + const idleDb = { update: () => ({ set: () => ({ where: () => ({ returning: () => new Promise(() => {}) }) }) }) } as unknown as WatchArgs[0]; + const controller = new AbortController(); + const watch = watchLegacyControllerLease(idleDb, watchedRun(10), controller); + try { + const blockedUntil = Date.now() + 80; + while (Date.now() < blockedUntil) { /* hold the event loop past the deadline */ } + await new Promise((resolve) => setTimeout(resolve, 5)); + expect(controller.signal.reason.leaseLossCause).toBe("renewal_deadline"); + expect(controller.signal.reason.leaseLossTiming.deadlineLateMs).toBeGreaterThanOrEqual(60); + expect(controller.signal.reason.leaseLossTiming.renewalPendingMs).toBeNull(); + } finally { watch.stop(); } + }); }); diff --git a/server/src/services/legacy-controller-lease.ts b/server/src/services/legacy-controller-lease.ts index e13e2ee2308..10ee785e4ea 100644 --- a/server/src/services/legacy-controller-lease.ts +++ b/server/src/services/legacy-controller-lease.ts @@ -1,7 +1,7 @@ import { randomUUID } from "node:crypto"; import { and, eq, gt, lte, sql } from "drizzle-orm"; import { heartbeatRuns, type Db } from "@paperclipai/db"; -import type { LegacyControllerLeaseLossCause } from "./run-cancellation.js"; +import type { LegacyControllerLeaseLossCause, LegacyControllerLeaseLossTiming } from "./run-cancellation.js"; // A boot UUID has meaning across containers; a numeric PID does not. export const legacyControllerBootId = randomUUID(); @@ -12,7 +12,10 @@ type Run = typeof heartbeatRuns.$inferSelect; /** Abort reason for a lost lease, so completion can attribute the stop. */ export class LegacyControllerLeaseLostError extends Error { - constructor(readonly leaseLossCause: LegacyControllerLeaseLossCause) { + constructor( + readonly leaseLossCause: LegacyControllerLeaseLossCause, + readonly leaseLossTiming?: LegacyControllerLeaseLossTiming, + ) { super("Legacy controller lease lost"); this.name = "LegacyControllerLeaseLostError"; } @@ -97,17 +100,38 @@ export function watchLegacyControllerLease(db: Db, run: Run, controller: AbortCo } let stopped = false; let pending = false; + // Timing evidence for a loss: a renewal still in flight at the deadline + // points at the database; a late deadline callback points at the event loop. + let lastRenewedAt = Date.now(); + let renewalCount = 0; + const renewalsInFlight = new Set<{ startedAt: number }>(); + let deadlineDueAt = 0; + let deadline: ReturnType | undefined; const lost = (cause: LegacyControllerLeaseLossCause) => { - if (!stopped) controller.abort(new LegacyControllerLeaseLostError(cause)); + if (stopped || controller.signal.aborted) return; + const now = Date.now(); + const oldestRenewal = Math.min(...[...renewalsInFlight].map((renewal) => renewal.startedAt)); + controller.abort(new LegacyControllerLeaseLostError(cause, { + sinceRenewalMs: now - lastRenewedAt, + renewalPendingMs: renewalsInFlight.size > 0 ? now - oldestRenewal : null, + deadlineLateMs: cause === "renewal_deadline" ? Math.max(0, now - deadlineDueAt) : null, + renewalCount, + })); }; const deadlinePassed = () => lost("renewal_deadline"); - let deadline = setTimeout(deadlinePassed, Math.max(0, - (run.controllerLeaseExpiresAt?.getTime() ?? 0) - Date.now())); - deadline.unref(); + const armDeadline = (delayMs: number) => { + clearTimeout(deadline); + deadlineDueAt = Date.now() + delayMs; + deadline = setTimeout(deadlinePassed, delayMs); + deadline.unref(); + }; + armDeadline(Math.max(0, (run.controllerLeaseExpiresAt?.getTime() ?? 0) - Date.now())); const assertOwned = async (stage?: "dispatching") => { if (stopped) return; controller.signal.throwIfAborted(); const startedAt = Date.now(); + const renewal = { startedAt }; + renewalsInFlight.add(renewal); let onAbort!: () => void; const aborted = new Promise((_, reject) => { onAbort = () => reject(controller.signal.reason); @@ -117,6 +141,7 @@ export function watchLegacyControllerLease(db: Db, run: Run, controller: AbortCo try { renewed = await Promise.race([renewLegacyControllerLease(db, run, stage), aborted]); } finally { + renewalsInFlight.delete(renewal); controller.signal.removeEventListener("abort", onAbort); } if (stopped) return; @@ -126,9 +151,9 @@ export function watchLegacyControllerLease(db: Db, run: Run, controller: AbortCo } controller.signal.throwIfAborted(); if (!stopped) { - clearTimeout(deadline); - deadline = setTimeout(deadlinePassed, Math.max(0, LEGACY_CONTROLLER_LEASE_MS - (Date.now() - startedAt))); - deadline.unref(); + lastRenewedAt = Date.now(); + renewalCount += 1; + armDeadline(Math.max(0, LEGACY_CONTROLLER_LEASE_MS - (Date.now() - startedAt))); } }; const timer = setInterval(() => { diff --git a/server/src/services/run-cancellation.ts b/server/src/services/run-cancellation.ts index 95a37aabfb4..89932ecd4df 100644 --- a/server/src/services/run-cancellation.ts +++ b/server/src/services/run-cancellation.ts @@ -55,6 +55,36 @@ export function readControllerLeaseLossCause(cancellation: RunCancellation): Leg 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>; + +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; + 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; diff --git a/server/src/services/run-failure-diagnostics.ts b/server/src/services/run-failure-diagnostics.ts index 291a9503b77..f03bf4c2043 100644 --- a/server/src/services/run-failure-diagnostics.ts +++ b/server/src/services/run-failure-diagnostics.ts @@ -1,7 +1,7 @@ import { readWorkspaceBaseRefDiagnostic } from "./workspace-base-ref-diagnostics.js"; import { getEnvironmentAcquisitionDiagnostic } from "./environment-acquisition-diagnostics.js"; import type { heartbeatRuns } from "@paperclipai/db"; -import { readControllerLeaseLossCause, readRunCancellation } from "./run-cancellation.js"; +import { readControllerLeaseLoss, readControllerLeaseLossCause, readRunCancellation } from "./run-cancellation.js"; import { readProcessLossDiagnostic } from "./process-loss-diagnostics.js"; import { WORKSPACE_RESTORE_FAILURE_CODES } from "@paperclipai/shared"; import { redactDiagnosticText } from "@paperclipai/adapter-utils/command-redaction"; @@ -290,6 +290,14 @@ export function collectRunFailureDiagnostics(run: Run, options: RunFailureReport execution.cancellationSource = "unknown"; execution.cancellationExpected = false; } + const leaseLoss = readControllerLeaseLoss(read(result, "controllerLeaseLoss")); + if (leaseLoss) { + execution.controllerLeaseLossCause = leaseLoss.cause; + if (leaseLoss.sinceRenewalMs !== undefined) execution.controllerLeaseSinceRenewalMs = leaseLoss.sinceRenewalMs; + if (leaseLoss.renewalPendingMs !== undefined) execution.controllerLeaseRenewalPendingMs = leaseLoss.renewalPendingMs; + if (leaseLoss.deadlineLateMs !== undefined) execution.controllerLeaseDeadlineLateMs = leaseLoss.deadlineLateMs; + if (leaseLoss.renewalCount !== undefined) execution.controllerLeaseRenewalCount = leaseLoss.renewalCount; + } Object.assign(execution, scalars(result, [ "mode", "stopReason", "timeoutFired", "timeoutSource", "timeoutConfigured", "effectiveTimeoutSec", "errorFamily",