mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-09 16:02:36 +01:00
fix(observability): report directory-merge lock holder diagnostics (#17755)
A directory-merge lock timeout (ERR_WORKSPACE_RESTORE_LOCK_TIMEOUT) already carries allowlisted holder evidence, but server Sentry capture dropped it. - Add directoryMergeLockTimeoutDiagnosticsFor in adapter-utils: closed labels, booleans and bounded durations; no owner PID or paths. - server captureException: lock timeouts get an event-local directory_merge_lock context and error_code=workspace_restore_lock_timeout tag; default grouping and message unchanged. - run-failure-diagnostics restoreLock* fields use the shared reader (same allowlist and order). - Document the record in doc/workspace-restore-locks.md. Diagnostics only; does not change lock acquisition, timeouts or retries. Refs PAPERCLIP-BACKEND-4Q Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This commit is contained in:
1 parent
3a8f95d928
commit
33269e1fec
6 files changed
+233
-20
No files matched your search
@@ -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.
|
||||
|
||||
@@ -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();
|
||||
});
|
||||
});
|
||||
@@ -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<DirectoryMergeLockOperation, typeof OPERATIONS[number]>] 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<string, unknown>)[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;
|
||||
}
|
||||
@@ -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 }}"],
|
||||
});
|
||||
});
|
||||
});
|
||||
@@ -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 {
|
||||
|
||||
@@ -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.
|
||||
|
||||
Reference in new issue
Block a user