diff --git a/doc/workspace-restore-locks.md b/doc/workspace-restore-locks.md index 0f09b78b443..ae5cd85b215 100644 --- a/doc/workspace-restore-locks.md +++ b/doc/workspace-restore-locks.md @@ -22,6 +22,21 @@ bounded timeout diagnostics. Missing, stale, or incorrect metadata cannot grant or retain ownership. PID reuse, PID namespaces, and wall-clock changes do not decide whether a writer owns the lock. +A timeout error (`ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT`) carries that holder +evidence. `directoryMergeLockTimeoutDiagnosticsFor` reduces it to the closed +agent-directory operation label, the owner state (`alive`, `dead`, `unknown`, +`missing`, or `invalid`), whether this process knows of a local holder, whether +the owner is this process or predates it, the owner's age, and the contender's +wait in milliseconds (each capped at seven days). Unknown labels and invalid +values are omitted. The record never includes the owner's PID or file paths. +Run-failure reports use it for their `restoreLock*` fields. When the server +reports an uncaught timeout to Sentry, the event gets this record as an +event-local `directory_merge_lock` context and an +`error_code=workspace_restore_lock_timeout` tag. The error message, which names +the lock file, and default grouping are unchanged. An owner much older than the +contender's wait points to a stuck holder; a recent owner points to contention. +Reporting does not change acquisition, timeouts, or retries. + An unchanged returned snapshot still acquires the target writer lock and runs both authorization/publication hooks. If every returned path, type, file hash, file mode and symlink target matches the baseline, there is no incoming delta. diff --git a/packages/adapter-utils/src/directory-merge-lock-diagnostics.test.ts b/packages/adapter-utils/src/directory-merge-lock-diagnostics.test.ts new file mode 100644 index 00000000000..0891a338b05 --- /dev/null +++ b/packages/adapter-utils/src/directory-merge-lock-diagnostics.test.ts @@ -0,0 +1,47 @@ +import { mkdir, mkdtemp, rm } from "node:fs/promises"; +import os from "node:os"; +import path from "node:path"; +import { afterEach, describe, expect, it, vi } from "vitest"; + +import { directoryMergeLockTimeoutDiagnosticsFor } from "./directory-merge-lock-diagnostics.js"; +import { withDirectoryMergeLock, WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE } from "./workspace-restore-merge.js"; + +describe("directoryMergeLockTimeoutDiagnosticsFor", () => { + const cleanupDirs: string[] = []; + + afterEach(async () => { + vi.unstubAllEnvs(); + while (cleanupDirs.length > 0) await rm(cleanupDirs.pop()!, { recursive: true, force: true }); + }); + + it("reduces a real lock timeout to allowlisted holder diagnostics without its path or process id", async () => { + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-lock-report-")); + cleanupDirs.push(rootDir); + vi.stubEnv("PAPERCLIP_HOME", path.join(rootDir, "home")); + vi.stubEnv("PAPERCLIP_INSTANCE_ID", "test-instance"); + const targetDir = path.join(rootDir, "target"); + await mkdir(targetDir); + const contender = vi.fn(); + let caught: unknown; + await withDirectoryMergeLock(targetDir, async () => { + caught = await withDirectoryMergeLock(targetDir, contender, process.env, "agent_directory_collect", 0).catch((error: unknown) => error); + }); + expect(contender).not.toHaveBeenCalled(); + const diagnostics = directoryMergeLockTimeoutDiagnosticsFor(caught); + expect(diagnostics).toEqual({ + operation: "agent_directory_collect", ownerState: "alive", knownLocalHolder: true, + ownerSameProcess: true, ownerPredatesProcess: false, ownerAgeMs: expect.any(Number), waitMs: expect.any(Number), + }); + expect(JSON.stringify(diagnostics)).not.toContain(rootDir); + expect(JSON.stringify(diagnostics)).not.toContain(String(process.pid)); + }); + + it("omits invalid values and ignores other errors", () => { + expect(directoryMergeLockTimeoutDiagnosticsFor(Object.assign(new Error("Timed out waiting for workspace restore lock at /private"), { + code: WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE, + workspaceRestoreLock: { operation: "/private/path", ownerState: "reclaimed", ownerSameProcess: "yes", ownerAgeMs: -1, waitMs: 1.5, pid: 4242 }, + }))).toEqual({}); + expect(directoryMergeLockTimeoutDiagnosticsFor(new Error("Timed out waiting for workspace restore lock at /private"))).toBeNull(); + expect(directoryMergeLockTimeoutDiagnosticsFor(null)).toBeNull(); + }); +}); diff --git a/packages/adapter-utils/src/directory-merge-lock-diagnostics.ts b/packages/adapter-utils/src/directory-merge-lock-diagnostics.ts new file mode 100644 index 00000000000..5e9d7760660 --- /dev/null +++ b/packages/adapter-utils/src/directory-merge-lock-diagnostics.ts @@ -0,0 +1,64 @@ +import { WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE, type DirectoryMergeLockOperation } from "./workspace-restore-merge.js"; + +const OPERATIONS = [ + "agent_directory_prepare", + "agent_directory_release", + "agent_directory_collect", + "agent_directory_checkpoint", + "agent_directory_handoff", +] as const satisfies readonly DirectoryMergeLockOperation[]; +// Fails to compile when the lock module adds an operation this list omits. +const OPERATIONS_COMPLETE: [Exclude] extends [never] ? true : false = true; +void OPERATIONS_COMPLETE; +const OWNER_STATES = ["alive", "dead", "unknown", "missing", "invalid"] as const; +const MAX_DURATION_MS = 7 * 24 * 60 * 60 * 1000; + +/** + * Holder evidence a directory-merge lock timeout carries, reduced to closed + * labels, booleans and bounded durations. It never includes the lock path, + * the owner's process id, or any error message. + */ +export interface DirectoryMergeLockTimeoutDiagnostics { + operation?: DirectoryMergeLockOperation; + ownerState?: typeof OWNER_STATES[number]; + knownLocalHolder?: boolean; + ownerSameProcess?: boolean; + ownerPredatesProcess?: boolean; + ownerAgeMs?: number; + waitMs?: number; +} + +function read(value: unknown, key: string): unknown { + if (!value || typeof value !== "object") return undefined; + try { + return (value as Record)[key]; + } catch { + return undefined; + } +} + +/** + * Returns the allowlisted holder diagnostics when `error` itself is a + * directory-merge lock timeout, otherwise `null`. Invalid or unknown values + * are omitted rather than copied. + */ +export function directoryMergeLockTimeoutDiagnosticsFor(error: unknown): DirectoryMergeLockTimeoutDiagnostics | null { + if (read(error, "code") !== WORKSPACE_RESTORE_LOCK_TIMEOUT_CODE) return null; + const lock = read(error, "workspaceRestoreLock"); + const diagnostics: DirectoryMergeLockTimeoutDiagnostics = {}; + const operation = read(lock, "operation"); + const operationLabel = OPERATIONS.find((value) => value === operation); + if (operationLabel) diagnostics.operation = operationLabel; + const ownerState = read(lock, "ownerState"); + const ownerStateLabel = OWNER_STATES.find((value) => value === ownerState); + if (ownerStateLabel) diagnostics.ownerState = ownerStateLabel; + for (const field of ["knownLocalHolder", "ownerSameProcess", "ownerPredatesProcess"] as const) { + const value = read(lock, field); + if (typeof value === "boolean") diagnostics[field] = value; + } + for (const field of ["ownerAgeMs", "waitMs"] as const) { + const value = read(lock, field); + if (typeof value === "number" && Number.isSafeInteger(value) && value >= 0 && value <= MAX_DURATION_MS) diagnostics[field] = value; + } + return diagnostics; +} diff --git a/server/src/__tests__/sentry-directory-merge-lock.test.ts b/server/src/__tests__/sentry-directory-merge-lock.test.ts new file mode 100644 index 00000000000..12c390ab4c9 --- /dev/null +++ b/server/src/__tests__/sentry-directory-merge-lock.test.ts @@ -0,0 +1,93 @@ +import { mkdir, mkdtemp, rm } from "node:fs/promises"; +import os from "node:os"; +import path from "node:path"; +import { afterEach, describe, expect, it, vi } from "vitest"; +import { withDirectoryMergeLock } from "@paperclipai/adapter-utils/workspace-restore-merge"; + +// `@sentry/node` is an optional peer and is not installed for this suite. +// Mock it and the exact-version gate so the opt-in capture path runs. +function mockSentryPackage() { + const captureException = vi.fn(() => "event-id"); + vi.doMock("@sentry/node", () => ({ + getClient: () => ({ on: vi.fn() }), + init: vi.fn(), + captureException, + close: vi.fn(async () => true), + httpIntegration: vi.fn((options: unknown) => ({ name: "Http", ...(options as object) })), + onUnhandledRejectionIntegration: vi.fn((options: unknown) => ({ name: "OnUnhandledRejection", ...(options as object) })), + })); + vi.doMock("../peer-version-check.js", () => ({ checkExactPeerVersions: () => ({ ok: true }) })); + return { captureException }; +} + +async function importFreshSentry() { + vi.resetModules(); + return await import("../sentry.js"); +} + +describe("Sentry directory-merge lock timeout context", () => { + const cleanupDirs: string[] = []; + + afterEach(async () => { + vi.unstubAllEnvs(); + vi.doUnmock("@sentry/node"); + vi.doUnmock("../peer-version-check.js"); + vi.resetModules(); + while (cleanupDirs.length > 0) await rm(cleanupDirs.pop()!, { recursive: true, force: true }); + }); + + it("adds allowlisted holder diagnostics to a real lock timeout event only", async () => { + vi.stubEnv("SENTRY_DSN", ""); + vi.stubEnv("SENTRY_DSN_FRONTEND", ""); + vi.stubEnv("SENTRY_DSN_BACKEND", "https://fixture@example.com/1"); + const sdk = mockSentryPackage(); + const { captureException, sentryReady } = await importFreshSentry(); + await sentryReady; + + const rootDir = await mkdtemp(path.join(os.tmpdir(), "paperclip-sentry-lock-")); + cleanupDirs.push(rootDir); + vi.stubEnv("PAPERCLIP_HOME", path.join(rootDir, "home")); + vi.stubEnv("PAPERCLIP_INSTANCE_ID", "test-instance"); + const targetDir = path.join(rootDir, "target"); + await mkdir(targetDir); + let timeout: unknown; + await withDirectoryMergeLock(targetDir, async () => { + timeout = await withDirectoryMergeLock(targetDir, vi.fn(), process.env, "agent_directory_release", 0).catch((error: unknown) => error); + }); + + captureException(timeout); + const unrelated = new Error("unrelated"); + captureException(unrelated); + + expect(sdk.captureException.mock.calls[0]).toEqual([ + timeout, + { tags: { error_code: "workspace_restore_lock_timeout" }, fingerprint: ["{{ default }}"], contexts: { + directory_merge_lock: { operation: "agent_directory_release", ownerState: "alive", knownLocalHolder: true, + ownerSameProcess: true, ownerPredatesProcess: false, ownerAgeMs: expect.any(Number), waitMs: expect.any(Number) }, + } }, + ]); + const context = JSON.stringify((sdk.captureException.mock.calls[0] as unknown[])[1]); + expect(context).not.toContain(rootDir); + expect(context).not.toContain(String(process.pid)); + expect(sdk.captureException.mock.calls[1]).toEqual([unrelated]); + }); + + it("keeps run reference tags on a lock timeout event", async () => { + vi.stubEnv("SENTRY_DSN", ""); + vi.stubEnv("SENTRY_DSN_FRONTEND", ""); + vi.stubEnv("SENTRY_DSN_BACKEND", "https://fixture@example.com/1"); + const sdk = mockSentryPackage(); + const { captureException, sentryReady } = await importFreshSentry(); + await sentryReady; + const error = Object.assign(new Error("Timed out waiting for workspace restore lock at /private/lock"), { + code: "ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT", + workspaceRestoreLock: { ownerState: "dead", waitMs: 30_001, pid: 4242 }, + }); + captureException(error, { runId: "11111111-1111-4111-8111-111111111111" }); + expect(sdk.captureException).toHaveBeenCalledWith(error, { + tags: { run_id: "11111111-1111-4111-8111-111111111111", error_code: "workspace_restore_lock_timeout" }, + contexts: { directory_merge_lock: { ownerState: "dead", waitMs: 30_001 } }, + fingerprint: ["{{ default }}"], + }); + }); +}); diff --git a/server/src/sentry.ts b/server/src/sentry.ts index abc577a8d09..6ab1ad469f0 100644 --- a/server/src/sentry.ts +++ b/server/src/sentry.ts @@ -76,6 +76,7 @@ import { AdapterStopTimeoutError } from "./services/adapter-stop-timeout.js"; import { CloudPortfolioError } from "./services/cloud-portfolio-error.js"; import { SecretSensitiveRequestError } from "./middleware/secret-sensitive-request-error.js"; import { storageFailureDiagnosticsFor } from "./storage/failure-diagnostics.js"; +import { directoryMergeLockTimeoutDiagnosticsFor } from "@paperclipai/adapter-utils/directory-merge-lock-diagnostics"; import type { RunFailureDiagnostics } from "./services/run-failure-diagnostics.js"; import { readBuildCommit } from "./build-commit.js"; import { checkExactPeerVersions } from "./peer-version-check.js"; @@ -135,6 +136,7 @@ export function captureException(error: unknown, reference?: SentryRunReference) ...(reference.agentId ? { agent_id: reference.agentId } : {}), } : {}; const storageFailure = storageFailureDiagnosticsFor(error); + const lockTimeout = directoryMergeLockTimeoutDiagnosticsFor(error); if (error instanceof AdapterStopTimeoutError) { // Event-local, fixed-shape context: no ambient scope or raw error fields. const exception = new Error(error.message); @@ -177,6 +179,14 @@ export function captureException(error: unknown, reference?: SentryRunReference) contexts: { storage_failure: { ...storageFailure } }, fingerprint: ["{{ default }}"], }); + } else if (lockTimeout) { + // Holder evidence distinguishes contention from a stuck owner. The + // allowlisted record omits the owner's process id. + sentryHandle.captureException(error, { + tags: { ...tags, error_code: "workspace_restore_lock_timeout" }, + contexts: { directory_merge_lock: { ...lockTimeout } }, + fingerprint: ["{{ default }}"], + }); } else if (reference) { sentryHandle.captureException(error, { tags, contexts: {}, fingerprint: ["{{ default }}"] }); } else { diff --git a/server/src/services/run-failure-diagnostics.ts b/server/src/services/run-failure-diagnostics.ts index 899c68afc71..b1acdb40b2f 100644 --- a/server/src/services/run-failure-diagnostics.ts +++ b/server/src/services/run-failure-diagnostics.ts @@ -6,6 +6,7 @@ import { readProcessLossDiagnostic } from "./process-loss-diagnostics.js"; import { readReviewedChatBindingDenialReason } from "./reviewed-chat-binding-diagnostics.js"; import { WORKSPACE_RESTORE_FAILURE_CODES } from "@paperclipai/shared"; import { redactDiagnosticText } from "@paperclipai/adapter-utils/command-redaction"; +import { directoryMergeLockTimeoutDiagnosticsFor } from "@paperclipai/adapter-utils/directory-merge-lock-diagnostics"; import { sanitizeWorkspaceRestoreDiagnostic } from "@paperclipai/adapter-utils/workspace-restore-diagnostics"; import { ACP_PROCESS_TERMINAL_SIGNALS, @@ -415,26 +416,9 @@ export function collectRunFailureDiagnostics(run: Run, options: RunFailureReport execution.environmentAcquisitionBudgetMs = acquisition.budgetMs; if (acquisition.providerState) execution.environmentAcquisitionProviderState = acquisition.providerState; } - if (execution.restoreLockOwnerState === undefined && read(error, "code") === "ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT") { - const lock = read(error, "workspaceRestoreLock"); - const operation = read(lock, "operation"); - if (["agent_directory_prepare", "agent_directory_release", "agent_directory_collect", "agent_directory_checkpoint", "agent_directory_handoff"].some(value => value === operation)) { - execution.restoreLockOperation = operation as string; - } - const ownerState = read(lock, "ownerState"); - if (["alive", "dead", "unknown", "missing", "invalid"].some(value => value === ownerState)) { - execution.restoreLockOwnerState = ownerState as string; - } - for (const field of ["knownLocalHolder", "ownerSameProcess", "ownerPredatesProcess"]) { - const value = read(lock, field); - if (typeof value === "boolean") execution[`restoreLock${field[0]!.toUpperCase()}${field.slice(1)}`] = value; - } - for (const field of ["ownerAgeMs", "waitMs"]) { - const value = read(lock, field); - if (typeof value === "number" && Number.isSafeInteger(value) && value >= 0 && value <= 7 * 24 * 60 * 60 * 1000) { - execution[`restoreLock${field[0]!.toUpperCase()}${field.slice(1)}`] = value; - } - } + const lock = execution.restoreLockOwnerState === undefined ? directoryMergeLockTimeoutDiagnosticsFor(error) : null; + for (const [field, value] of Object.entries(lock ?? {})) { + execution[`restoreLock${field[0]!.toUpperCase()}${field.slice(1)}`] = value; } // A bare socket error ("aborted", ECONNRESET) cannot say which storage // read it interrupted; the provider's fixed-shape record can.