Skip to content

Commit 07cb9d7

Browse files
Priya RamanPaperclip-Paperclip
andcommitted
fix(server): buffer orphan sandbox cleanup in-process when the durable write fails
When a sandbox acquire provisions a remote sandbox, the lease insert rejects it, the compensating teardown fails, and every synchronous pending-cleanup write also fails, the orphan survived only in the thrown error and a log line. No durable row remained, so no sweep could find the live sandbox. The sandbox driver now keeps the orphan record in an in-process buffer when every synchronous write fails. The cleanup sweep flushes the buffer each tick, so the durable pending_cleanup row lands once the database recovers, and the same sweep tears the sandbox down. The buffer is bounded, dedups by provider lease id, and never logs the caught write exception. A process crash during the outage still loses the record, so the error log stays the last handle for that case. Co-authored-by: Paperclip <noreply@paperclip.ing>
1 parent c3ab11f commit 07cb9d7

4 files changed

Lines changed: 444 additions & 6 deletions

File tree

server/src/__tests__/environment-runtime.test.ts

Lines changed: 228 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1149,6 +1149,234 @@ describeEmbeddedPostgres("environmentRuntimeService", () => {
11491149
}
11501150
});
11511151

1152+
it("buffers the orphan in-process and a later sweep flush lands the durable row after the database recovers", async () => {
1153+
const { companyId, environment, runId } = await seedEnvironment({
1154+
driver: "sandbox",
1155+
name: "Foreign-bound Fake Sandbox Cleanup Buffer Flush",
1156+
config: { provider: "fake", image: "ubuntu:24.04", reuseLease: false },
1157+
});
1158+
const otherCompanyId = randomUUID();
1159+
await db.insert(companies).values({
1160+
id: otherCompanyId,
1161+
name: "Other Co Cleanup Buffer",
1162+
issuePrefix: "OCB",
1163+
status: "active",
1164+
createdAt: new Date(),
1165+
updatedAt: new Date(),
1166+
});
1167+
await db.insert(builtInManagedResources).values({
1168+
companyId: otherCompanyId,
1169+
bundleKey: "managed-environment",
1170+
resourceKind: "environment",
1171+
resourceKey: "managed-sandbox",
1172+
resourceId: environment.id,
1173+
stockVersion: "1",
1174+
stockHash: "hash",
1175+
});
1176+
1177+
// The remote teardown fails, so the acquire tries to record a durable
1178+
// pending-cleanup row instead.
1179+
const destroySpy = vi
1180+
.spyOn(sandboxProviderRuntime, "destroySandboxProviderLease")
1181+
.mockRejectedValue(new Error("teardown failed"));
1182+
// The database is down, so every synchronous pending-cleanup write rejects.
1183+
// The flag flips to false when the database recovers, so a later flush lands
1184+
// the durable row.
1185+
let databaseDown = true;
1186+
const realEnvironmentService = environmentsModule.environmentService;
1187+
const factorySpy = vi
1188+
.spyOn(environmentsModule, "environmentService")
1189+
.mockImplementation((database: Parameters<typeof realEnvironmentService>[0]) => {
1190+
const real = realEnvironmentService(database);
1191+
return {
1192+
...real,
1193+
insertPendingCleanupLease: (
1194+
input: Parameters<typeof real.insertPendingCleanupLease>[0],
1195+
) => {
1196+
if (databaseDown) {
1197+
return Promise.reject(new Error("pending-cleanup write failed; database down"));
1198+
}
1199+
return real.insertPendingCleanupLease(input);
1200+
},
1201+
};
1202+
});
1203+
const logSpy = vi.spyOn(logger, "error").mockImplementation(() => logger);
1204+
try {
1205+
// Set the retry backoff to zero, so the retries never slow the test.
1206+
const runtime = environmentRuntimeService(db, { pendingCleanupWriteBackoffMs: 0 });
1207+
const rejection = await runtime
1208+
.acquireRunLease({
1209+
companyId,
1210+
environment,
1211+
issueId: null,
1212+
heartbeatRunId: runId,
1213+
persistedExecutionWorkspace: null,
1214+
assertCompanyBinding: true,
1215+
})
1216+
.then(
1217+
() => {
1218+
throw new Error("acquireRunLease resolved but must reject");
1219+
},
1220+
(error: unknown) => error,
1221+
);
1222+
1223+
// The synchronous write failed on every attempt, so the acquire still
1224+
// throws the orphan-cleanup write error that keeps the original rejection.
1225+
expect(rejection).toBeInstanceOf(SandboxOrphanCleanupWriteError);
1226+
// The database was down, so no durable row exists yet.
1227+
let rows = await db
1228+
.select()
1229+
.from(environmentLeases)
1230+
.where(eq(environmentLeases.environmentId, environment.id));
1231+
expect(rows).toHaveLength(0);
1232+
// The acquire buffered the orphan in-process, so the log records the buffer.
1233+
const bufferedLog = logSpy.mock.calls.find(
1234+
([fields]) =>
1235+
(fields as { errorKind?: string } | undefined)?.errorKind ===
1236+
"sandbox_orphan_cleanup_write_failed",
1237+
);
1238+
expect(bufferedLog?.[0]).toMatchObject({ buffered: true });
1239+
1240+
// The database recovers, so the next cleanup-sweep flush lands the row.
1241+
databaseDown = false;
1242+
const flushed = await runtime.flushDeferredOrphanCleanups();
1243+
expect(flushed).toEqual({ recovered: 1, pending: 0 });
1244+
1245+
// A durable pending_cleanup row now tracks the orphan, so a sweep finds and
1246+
// releases the leaked sandbox.
1247+
rows = await db
1248+
.select()
1249+
.from(environmentLeases)
1250+
.where(eq(environmentLeases.environmentId, environment.id));
1251+
expect(rows).toHaveLength(1);
1252+
expect(rows[0]?.status).toBe("pending_cleanup");
1253+
expect(rows[0]?.cleanupStatus).toBe("failed");
1254+
expect(rows[0]?.failureReason).toBe("acquire_rejected_teardown_failed");
1255+
expect(rows[0]?.providerLeaseId).toBeTruthy();
1256+
1257+
// The buffer is empty now, so a second flush inserts nothing.
1258+
const second = await runtime.flushDeferredOrphanCleanups();
1259+
expect(second).toEqual({ recovered: 0, pending: 0 });
1260+
const rowsAfter = await db
1261+
.select()
1262+
.from(environmentLeases)
1263+
.where(eq(environmentLeases.environmentId, environment.id));
1264+
expect(rowsAfter).toHaveLength(1);
1265+
} finally {
1266+
logSpy.mockRestore();
1267+
factorySpy.mockRestore();
1268+
destroySpy.mockRestore();
1269+
}
1270+
});
1271+
1272+
it("keeps the buffered orphan when the flush write still fails, then recovers on a later flush", async () => {
1273+
const { companyId, environment, runId } = await seedEnvironment({
1274+
driver: "sandbox",
1275+
name: "Foreign-bound Fake Sandbox Cleanup Buffer Requeue",
1276+
config: { provider: "fake", image: "ubuntu:24.04", reuseLease: false },
1277+
});
1278+
const otherCompanyId = randomUUID();
1279+
await db.insert(companies).values({
1280+
id: otherCompanyId,
1281+
name: "Other Co Cleanup Requeue",
1282+
issuePrefix: "OCQ",
1283+
status: "active",
1284+
createdAt: new Date(),
1285+
updatedAt: new Date(),
1286+
});
1287+
await db.insert(builtInManagedResources).values({
1288+
companyId: otherCompanyId,
1289+
bundleKey: "managed-environment",
1290+
resourceKind: "environment",
1291+
resourceKey: "managed-sandbox",
1292+
resourceId: environment.id,
1293+
stockVersion: "1",
1294+
stockHash: "hash",
1295+
});
1296+
1297+
const destroySpy = vi
1298+
.spyOn(sandboxProviderRuntime, "destroySandboxProviderLease")
1299+
.mockRejectedValue(new Error("teardown failed"));
1300+
let databaseDown = true;
1301+
const realEnvironmentService = environmentsModule.environmentService;
1302+
const factorySpy = vi
1303+
.spyOn(environmentsModule, "environmentService")
1304+
.mockImplementation((database: Parameters<typeof realEnvironmentService>[0]) => {
1305+
const real = realEnvironmentService(database);
1306+
return {
1307+
...real,
1308+
insertPendingCleanupLease: (
1309+
input: Parameters<typeof real.insertPendingCleanupLease>[0],
1310+
) => {
1311+
if (databaseDown) {
1312+
return Promise.reject(new Error("pending-cleanup write failed; database down"));
1313+
}
1314+
return real.insertPendingCleanupLease(input);
1315+
},
1316+
};
1317+
});
1318+
const errorLogSpy = vi.spyOn(logger, "error").mockImplementation(() => logger);
1319+
const warnLogSpy = vi.spyOn(logger, "warn").mockImplementation(() => logger);
1320+
try {
1321+
const runtime = environmentRuntimeService(db, { pendingCleanupWriteBackoffMs: 0 });
1322+
await runtime
1323+
.acquireRunLease({
1324+
companyId,
1325+
environment,
1326+
issueId: null,
1327+
heartbeatRunId: runId,
1328+
persistedExecutionWorkspace: null,
1329+
assertCompanyBinding: true,
1330+
})
1331+
.then(
1332+
() => {
1333+
throw new Error("acquireRunLease resolved but must reject");
1334+
},
1335+
() => undefined,
1336+
);
1337+
1338+
// The database is still down, so the flush re-queues the orphan instead of
1339+
// losing it. The buffer keeps the record for a later tick.
1340+
const firstFlush = await runtime.flushDeferredOrphanCleanups();
1341+
expect(firstFlush).toEqual({ recovered: 0, pending: 1 });
1342+
const rowsWhileDown = await db
1343+
.select()
1344+
.from(environmentLeases)
1345+
.where(eq(environmentLeases.environmentId, environment.id));
1346+
expect(rowsWhileDown).toHaveLength(0);
1347+
// The flush logs the re-queue and never carries the caught write exception.
1348+
// The sync-retry path also warns with the same error kind, so match on the
1349+
// `requeued` field that only the flush warn carries.
1350+
const requeueLog = warnLogSpy.mock.calls.find(
1351+
([fields]) => (fields as { requeued?: boolean } | undefined)?.requeued === true,
1352+
);
1353+
expect(requeueLog).toBeDefined();
1354+
expect(requeueLog?.[0]).toMatchObject({
1355+
errorKind: "sandbox_orphan_cleanup_write_failed",
1356+
requeued: true,
1357+
});
1358+
expect(requeueLog?.[0]).not.toHaveProperty("cause");
1359+
expect(requeueLog?.[0]).not.toHaveProperty("cleanupWriteError");
1360+
1361+
// The database recovers, so the next flush lands the durable row exactly
1362+
// once from the still-buffered record.
1363+
databaseDown = false;
1364+
const secondFlush = await runtime.flushDeferredOrphanCleanups();
1365+
expect(secondFlush).toEqual({ recovered: 1, pending: 0 });
1366+
const rowsAfter = await db
1367+
.select()
1368+
.from(environmentLeases)
1369+
.where(eq(environmentLeases.environmentId, environment.id));
1370+
expect(rowsAfter).toHaveLength(1);
1371+
expect(rowsAfter[0]?.status).toBe("pending_cleanup");
1372+
} finally {
1373+
warnLogSpy.mockRestore();
1374+
errorLogSpy.mockRestore();
1375+
factorySpy.mockRestore();
1376+
destroySpy.mockRestore();
1377+
}
1378+
});
1379+
11521380
it("throws a SandboxOrphanCleanupWriteError when the plugin durable pending-cleanup write also fails", async () => {
11531381
const pluginId = randomUUID();
11541382
const { companyId, environment: baseEnvironment, runId } = await seedEnvironment();

server/src/__tests__/heartbeat-pending-cleanup-sweep.test.ts

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1307,4 +1307,40 @@ describeEmbeddedPostgres("heartbeat sweepPendingCleanupLeases", () => {
13071307
const arrayMetadata = await readMetadata(arrayLeaseId);
13081308
expect(arrayMetadata?.[ATTEMPTS_KEY]).toBe(1);
13091309
});
1310+
1311+
it("flushes the in-process orphan buffer before the read, so a freshly landed row is swept the same tick", async () => {
1312+
const { companyId, environmentId } = await seedCompanyAndEnvironment();
1313+
1314+
// The flush lands one durable orphan row, exactly as the runtime buffer does
1315+
// after the database recovers. The sweep must run this flush before it reads
1316+
// the rows, so the same tick tears the freshly-landed orphan down.
1317+
const flushDeferredOrphanCleanups = vi.fn(async () => {
1318+
await insertOrphanEphemeralLease({
1319+
companyId,
1320+
environmentId,
1321+
updatedAt: new Date(Date.now() - 60 * 60 * 1000),
1322+
});
1323+
return { recovered: 1, pending: 0 };
1324+
});
1325+
// The recorded-data teardown succeeds, so the sweep releases the lease.
1326+
const retryPendingSandboxTeardown = vi.fn(async () => {});
1327+
const runtime = {
1328+
flushDeferredOrphanCleanups,
1329+
retryPendingSandboxTeardown,
1330+
} as unknown as HeartbeatEnvironmentRuntime;
1331+
const heartbeat = heartbeatService(db, { environmentRuntime: runtime });
1332+
1333+
const result = await heartbeat.sweepPendingCleanupLeases({ backoffMs: 0 });
1334+
1335+
// The flush ran once before the read, so the row it landed is visible to the
1336+
// same sweep and tears down through the recorded-data teardown path.
1337+
expect(flushDeferredOrphanCleanups).toHaveBeenCalledTimes(1);
1338+
expect(retryPendingSandboxTeardown).toHaveBeenCalledTimes(1);
1339+
expect(result).toEqual({ swept: 1, destroyed: 1, capped: 0 });
1340+
1341+
const rows = await db.select().from(environmentLeases);
1342+
expect(rows).toHaveLength(1);
1343+
expect(rows[0]?.status).toBe("expired");
1344+
expect(rows[0]?.cleanupStatus).toBe("success");
1345+
});
13101346
});

0 commit comments

Comments
 (0)