Skip to content

Commit e4ae8cb

Browse files
authored
fix(run-engine,run-store,webapp): stop split-mode waits hanging on resume (#4164)
## Summary On the run-ops database split, a run that waits (`triggerAndWait`, `batchTriggerAndWait`, `wait.forToken`) could hang forever after its wait had already completed. The runner reads a resume from `/snapshots/since` exactly once: if that read returned the resume snapshot without its completed-waitpoints, the runner logged "executing without completed waitpoints", advanced its cursor, and never re-read it, so the awaiting run never continued. ## Root cause The resume snapshot and its completed-waitpoint rows were written as two separate commits. This regressed when the split replaced Prisma's atomic nested `connect` with an FK-free insert (in [#4163](#4163)), and `/snapshots/since` is served from a read replica. A fetch landing in the sub-millisecond gap between the two commits, or a multi-reader replica serving the snapshot from a different point in time than its join rows, delivered an empty resume. Because the runner consumes each snapshot once and treats an empty resume as terminal, a single stale read was fatal and produced a permanent, nondeterministic hang. ## Fixes - Commit a snapshot and its completed-waitpoint links in one transaction, restoring the atomicity the split removed. - Repair the completed-waitpoints from the owning primary when a multi-reader replica serves the snapshot without its join rows. This covers single-waitpoint resumes, which carry no `completedWaitpointOrder` and so were missed by the count-based repair. - Read the primary in the checkpoint `WAIT_FOR_BATCH` pre-check, so a batch that already resumed is not re-suspended into a stall. - Fall back to the primary when a waitpoint token misses both read replicas, so a token completed immediately after it was minted no longer returns a spurious 404. - Route batch-item creation by `batchTaskRunId`, consistent with the batch-completion count and the row's foreign key. - Reject control-plane-only relation selects on the dedicated schema with a clear error instead of an opaque Prisma failure, and stop `createDateTimeWaitpoint` bypassing residency routing through a caller transaction. Verified against the deployed split topology: a resume snapshot and its completed-waitpoints are now always delivered together, so the runner can no longer drop a resume.
1 parent de65370 commit e4ae8cb

20 files changed

Lines changed: 1295 additions & 60 deletions

apps/webapp/app/runEngine/concerns/resolveWaitpointThroughReadThrough.server.ts

Lines changed: 24 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,7 @@
11
import type { PrismaReplicaClient } from "~/db.server";
22
import {
33
$replica as defaultLegacyReplica,
4+
runOpsNewPrisma as defaultNewPrimary,
45
runOpsNewReplica as defaultNewClient,
56
runOpsSplitReadEnabled as defaultSplitReadEnabled,
67
} from "~/db.server";
@@ -9,6 +10,7 @@ import { readThroughRun } from "~/v3/runOpsMigration/readThrough.server";
910
type ResolveWaitpointDeps = {
1011
newClient?: PrismaReplicaClient;
1112
legacyReplica?: PrismaReplicaClient;
13+
newPrimary?: PrismaReplicaClient;
1214
splitEnabled?: boolean;
1315
isPastRetention?: (id: string) => boolean;
1416
};
@@ -18,12 +20,14 @@ type ResolveWaitpointDeps = {
1820
export type ResolveWaitpointReadThroughDefaults = {
1921
newClient: PrismaReplicaClient;
2022
legacyReplica: PrismaReplicaClient;
23+
newPrimary: PrismaReplicaClient;
2124
splitEnabled: boolean;
2225
};
2326

2427
const productionDefaults: ResolveWaitpointReadThroughDefaults = {
2528
newClient: defaultNewClient,
2629
legacyReplica: defaultLegacyReplica,
30+
newPrimary: defaultNewPrimary as unknown as PrismaReplicaClient,
2731
splitEnabled: defaultSplitReadEnabled,
2832
};
2933

@@ -36,18 +40,36 @@ export async function resolveWaitpointThroughReadThrough<T>(opts: {
3640
}): Promise<T | null> {
3741
const defaults = opts.defaults ?? productionDefaults;
3842

43+
const splitEnabled = opts.deps?.splitEnabled ?? defaults.splitEnabled;
44+
3945
const result = await readThroughRun({
4046
runId: opts.waitpointId,
4147
environmentId: opts.environmentId,
4248
readNew: (client) => opts.read(client),
4349
readLegacy: (replica) => opts.read(replica),
4450
deps: {
45-
splitEnabled: opts.deps?.splitEnabled ?? defaults.splitEnabled,
51+
splitEnabled,
4652
newClient: opts.deps?.newClient ?? defaults.newClient,
4753
legacyReplica: opts.deps?.legacyReplica ?? defaults.legacyReplica,
4854
isPastRetention: opts.deps?.isPastRetention,
4955
},
5056
});
5157

52-
return result.source === "new" || result.source === "legacy-replica" ? result.value : null;
58+
if (result.source === "new" || result.source === "legacy-replica") {
59+
return result.value;
60+
}
61+
// past-retention is an intentional not-found: the token is gone.
62+
if (result.source === "past-retention") {
63+
return null;
64+
}
65+
66+
// Read-your-writes fallback for a token completed immediately after mint, before it replicated:
67+
// re-read from the run-ops PRIMARY only. We deliberately never read the control-plane/legacy
68+
// primary here (that is the load the replica-only read-through exists to shed), so a legacy-resident
69+
// token that misses its replica stays a miss and the caller retries, rather than adding primary load.
70+
const fromNewPrimary = await opts.read(opts.deps?.newPrimary ?? defaults.newPrimary);
71+
if (fromNewPrimary != null) {
72+
return fromNewPrimary;
73+
}
74+
return null;
5375
}

apps/webapp/app/v3/runOpsMigration/waitpointTokenResolve.server.test.ts

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -102,6 +102,9 @@ describe("public wait-token resolution across the split boundary", () => {
102102
deps: {
103103
newClient: prisma17 as unknown as PrismaReplicaClient,
104104
legacyReplica: prisma17 as unknown as PrismaReplicaClient,
105+
// The run-ops-primary fallback is also pinned at run-ops, which does not hold this
106+
// control-plane token, so the miss stays a miss (fallback never reads the control-plane).
107+
newPrimary: prisma17 as unknown as PrismaReplicaClient,
105108
},
106109
});
107110

apps/webapp/app/v3/services/createCheckpoint.server.ts

Lines changed: 11 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -147,10 +147,14 @@ export class CreateCheckpointService extends BaseService {
147147
}
148148
case "WAIT_FOR_BATCH": {
149149
// Routed by friendlyId so a run-ops id (NEW-resident) batch is found on the owning DB;
150-
// env-scoped to the dependent attempt's run (a batch shares its dependent's env).
150+
// env-scoped to the dependent attempt's run (a batch shares its dependent's env). Read the
151+
// primary: a batch that just resumed the parent may lag the replica, and a stale resumedAt
152+
// (null) would checkpoint (suspend) an already-resumed run -> it stalls until a sweep.
151153
const batchRun = await this.runStore.findBatchTaskRunByFriendlyId(
152154
reason.batchFriendlyId,
153-
attempt.taskRun.runtimeEnvironmentId
155+
attempt.taskRun.runtimeEnvironmentId,
156+
undefined,
157+
this._prisma
154158
);
155159

156160
if (!batchRun) {
@@ -361,11 +365,13 @@ export class CreateCheckpointService extends BaseService {
361365
});
362366
await marqs?.cancelHeartbeat(attempt.taskRunId);
363367

364-
// Routed by friendlyId so a run-ops id (NEW-resident) batch is found on the owning DB;
365-
// env-scoped to the dependent attempt's run (a batch shares its dependent's env).
368+
// Routed by friendlyId; read the primary (this._prisma) so a just-resumed batch that still
369+
// lags the replica doesn't leave a stale resumedAt and suspend an already-resumed run.
366370
const batchRun = await this.runStore.findBatchTaskRunByFriendlyId(
367371
reason.batchFriendlyId,
368-
attempt.taskRun.runtimeEnvironmentId
372+
attempt.taskRun.runtimeEnvironmentId,
373+
undefined,
374+
this._prisma
369375
);
370376

371377
if (!batchRun) {
Lines changed: 65 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,65 @@
1+
// Unit red-green for the checkpoint WAIT_FOR_BATCH replica-lag fix (createCheckpoint.server.ts).
2+
// The service decides whether to suspend a run on `batchRun.resumedAt`; reading it from a lagging
3+
// replica makes a just-resumed batch look unresumed -> it suspends an already-resumed run -> stall.
4+
// The fix threads the primary (`this._prisma`) into `runStore.findBatchTaskRunByFriendlyId`. Here a
5+
// spy runStore records which client the service passed and simulates the lag (only the primary read
6+
// sees the fresh resumedAt): RED = no client -> stale null -> no early return; GREEN = primary -> kept alive.
7+
8+
import { describe, expect, it, vi } from "vitest";
9+
10+
vi.mock("~/services/logger.server", () => ({
11+
logger: { debug: vi.fn(), info: vi.fn(), log: vi.fn(), error: vi.fn(), warn: vi.fn() },
12+
}));
13+
vi.mock("~/v3/marqs/index.server", () => ({
14+
marqs: { replaceMessage: vi.fn(), cancelHeartbeat: vi.fn() },
15+
}));
16+
17+
import { CreateCheckpointService } from "~/v3/services/createCheckpoint.server";
18+
19+
describe("checkpoint WAIT_FOR_BATCH reads the primary, not a lagging replica", () => {
20+
it("threads the primary so an already-resumed batch keeps the run alive", async () => {
21+
// A freezable attempt so control reaches the WAIT_FOR_BATCH arm. This object IS the primary the
22+
// fix must thread into the batch read.
23+
const prisma = {
24+
taskRunAttempt: {
25+
findFirst: async () => ({
26+
id: "attempt_1",
27+
status: "EXECUTING",
28+
taskRunId: "run_1",
29+
taskRun: { id: "run_1", status: "EXECUTING", runtimeEnvironmentId: "env_1" },
30+
backgroundWorker: { id: "bw_1", deployment: { imageReference: "img:1" } },
31+
}),
32+
},
33+
};
34+
35+
let seenClient: unknown = "NOT_CALLED";
36+
const runStore = {
37+
findBatchTaskRunByFriendlyId: async (
38+
_friendlyId: string,
39+
_environmentId: string,
40+
_args: unknown,
41+
client?: unknown
42+
) => {
43+
seenClient = client;
44+
// Lagging replica: only a read handed the primary sees the just-committed resumedAt.
45+
return { resumedAt: client === prisma ? new Date() : null };
46+
},
47+
};
48+
49+
const service = new CreateCheckpointService(prisma as never, {} as never, runStore as never);
50+
51+
let result: unknown;
52+
try {
53+
result = await service.call({
54+
attemptFriendlyId: "attempt_1",
55+
reason: { type: "WAIT_FOR_BATCH", batchFriendlyId: "batch_1" },
56+
} as never);
57+
} catch {
58+
// Buggy path falls through the pre-check into checkpoint creation (unstubbed) and throws; the
59+
// recorded client below is what distinguishes RED from GREEN.
60+
}
61+
62+
expect(seenClient).toBe(prisma); // the fix: primary threaded into the batch read
63+
expect(result).toEqual({ success: false, keepRunAlive: true }); // early-return, run kept alive
64+
});
65+
});

apps/webapp/test/resolveWaitpointThroughReadThrough.readthrough.test.ts

Lines changed: 44 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -151,6 +151,44 @@ describe("resolveWaitpointThroughReadThrough (hetero PG14 legacy + dedicated run
151151
}
152152
);
153153

154+
// Read-your-writes: a token completed immediately after mint may not be on the replicas yet. The
155+
// replica-only read-through misses, and without a primary fallback we 404 a valid token (the
156+
// authoritative completeWaitpoint never runs). The primary fallback must find it.
157+
heteroRunOpsPostgresTest(
158+
"a NEW-resident token missing on both replicas is found on the run-ops primary (no spurious 404)",
159+
async ({ prisma17, prisma14 }) => {
160+
// A NEW-resident token lives on the run-ops DB (prisma17); its cuid id fans new-then-legacy.
161+
// Both replicas here lack it (pointed at prisma14), so only the run-ops primary can serve it.
162+
const id = generateLegacyCuid();
163+
const environmentId = generateRunOpsId();
164+
const projectId = generateRunOpsId();
165+
const seeded = await seedWaitpoint(prisma17, id, { id: environmentId, projectId });
166+
167+
const newClient = recording(prisma14);
168+
const legacyReplica = recording(prisma14);
169+
const newPrimary = recording(prisma17);
170+
171+
const result = await resolveWaitpointThroughReadThrough({
172+
waitpointId: id,
173+
environmentId,
174+
read: read(id, environmentId),
175+
deps: {
176+
splitEnabled: true,
177+
newClient: newClient.handle,
178+
legacyReplica: legacyReplica.handle,
179+
newPrimary: newPrimary.handle,
180+
},
181+
});
182+
183+
expect(result).not.toBeNull();
184+
expect(result!.id).toBe(seeded.id);
185+
// Both replicas probed and missed; the fallback read the run-ops primary (never control-plane).
186+
expect(newClient.calls.length).toBe(1);
187+
expect(legacyReplica.calls.length).toBe(1);
188+
expect(newPrimary.calls.length).toBe(1);
189+
}
190+
);
191+
154192
heteroRunOpsPostgresTest(
155193
"bare caller (no deps) resolves a NEW-resident waitpoint via the safe run-ops defaults",
156194
async ({ prisma17, prisma14 }) => {
@@ -170,6 +208,8 @@ describe("resolveWaitpointThroughReadThrough (hetero PG14 legacy + dedicated run
170208
defaults: {
171209
newClient: prisma14 as unknown as PrismaReplicaClient,
172210
legacyReplica: prisma14 as unknown as PrismaReplicaClient,
211+
// Primaries also miss the NEW-resident waitpoint, so the miss stays a miss.
212+
newPrimary: prisma14 as unknown as PrismaReplicaClient,
173213
splitEnabled: true,
174214
},
175215
});
@@ -183,6 +223,7 @@ describe("resolveWaitpointThroughReadThrough (hetero PG14 legacy + dedicated run
183223
defaults: {
184224
newClient: prisma17 as unknown as PrismaReplicaClient,
185225
legacyReplica: prisma14 as unknown as PrismaReplicaClient,
226+
newPrimary: prisma17 as unknown as PrismaReplicaClient,
186227
splitEnabled: true,
187228
},
188229
});
@@ -206,6 +247,9 @@ describe("resolveWaitpointThroughReadThrough (hetero PG14 legacy + dedicated run
206247
splitEnabled: true,
207248
newClient: recording(prisma17).handle,
208249
legacyReplica: recording(prisma14).handle,
250+
// The run-ops-primary fallback also misses this never-seeded token; inject a container client
251+
// so it does not reach for the unconnectable production singleton.
252+
newPrimary: recording(prisma17).handle,
209253
},
210254
});
211255

internal-packages/run-engine/src/engine/index.ts

Lines changed: 15 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -1655,7 +1655,6 @@ export class RunEngine {
16551655
completedAfter,
16561656
idempotencyKey,
16571657
idempotencyKeyExpiresAt,
1658-
tx,
16591658
}: {
16601659
/** The run that will block on this waitpoint. Co-locates the waitpoint with the run's DB. */
16611660
runId?: string;
@@ -1664,7 +1663,6 @@ export class RunEngine {
16641663
completedAfter: Date;
16651664
idempotencyKey?: string;
16661665
idempotencyKeyExpiresAt?: Date;
1667-
tx?: PrismaClientOrTransaction;
16681666
}) {
16691667
return this.waitpointSystem.createDateTimeWaitpoint({
16701668
runId,
@@ -1673,7 +1671,6 @@ export class RunEngine {
16731671
completedAfter,
16741672
idempotencyKey,
16751673
idempotencyKeyExpiresAt,
1676-
tx,
16771674
});
16781675
}
16791676

@@ -2097,13 +2094,24 @@ export class RunEngine {
20972094
this.readOnlyPrisma !== this.prisma;
20982095
const prisma = tx ?? (useReplica ? this.readOnlyPrisma : this.prisma);
20992096

2100-
const query = async (client: PrismaClientOrTransaction) => {
2101-
const snapshots = await getExecutionSnapshotsSince(client, runId, snapshotId, this.runStore);
2097+
const query = async (
2098+
client: PrismaClientOrTransaction,
2099+
repairClient?: PrismaClientOrTransaction
2100+
) => {
2101+
const snapshots = await getExecutionSnapshotsSince(
2102+
client,
2103+
runId,
2104+
snapshotId,
2105+
this.runStore,
2106+
repairClient
2107+
);
21022108
return snapshots.map(executionDataFromSnapshot);
21032109
};
21042110

21052111
try {
2106-
return await query(prisma);
2112+
// When reading the replica, pass the primary so a snapshot whose completed-waitpoint join rows
2113+
// have not replicated yet is repaired from the primary instead of resuming the run waitpoint-less.
2114+
return await query(prisma, useReplica ? this.prisma : undefined);
21072115
} catch (e) {
21082116
if (useReplica && e instanceof ExecutionSnapshotNotFoundError) {
21092117
// Replica lag: the runner learned this snapshot id from the writer before the
@@ -2115,7 +2123,7 @@ export class RunEngine {
21152123
if (maxMs > 0) {
21162124
await setTimeout(minMs + Math.random() * Math.max(0, maxMs - minMs));
21172125
try {
2118-
const result = await query(this.readOnlyPrisma);
2126+
const result = await query(this.readOnlyPrisma, this.prisma);
21192127
this.snapshotsSinceReplicaMissCounter.add(1, { outcome: "replica_retry" });
21202128
return result;
21212129
} catch (replicaRetryError) {

internal-packages/run-engine/src/engine/systems/executionSnapshotSystem.ts

Lines changed: 61 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -138,6 +138,30 @@ async function getSnapshotWaitpointIds(
138138
return result.map((r) => r.B);
139139
}
140140

141+
// Reads the snapshot's completed-waitpoint ids AND whether the snapshot is visible on this reader, in
142+
// one query, so a multi-reader replica can't return the ids from a different point-in-time than the
143+
// snapshot. `present=false` -> this reader lacks the snapshot; its empty id list is not authoritative.
144+
async function getSnapshotWaitpointIdsWithPresence(
145+
prisma: PrismaClientOrTransaction,
146+
snapshotId: string,
147+
runStore?: RunStore
148+
): Promise<{ present: boolean; ids: string[] }> {
149+
if (runStore) {
150+
return runStore.findSnapshotCompletedWaitpointIdsWithPresence(snapshotId, prisma);
151+
}
152+
153+
const rows = await prisma.$queryRaw<{ id: string; B: string | null }[]>`
154+
SELECT s."id", cw."B"
155+
FROM "TaskRunExecutionSnapshot" s
156+
LEFT JOIN "_completedWaitpoints" cw ON cw."A" = s."id"
157+
WHERE s."id" = ${snapshotId}
158+
`;
159+
return {
160+
present: rows.length > 0,
161+
ids: rows.filter((r) => r.B !== null).map((r) => r.B as string),
162+
};
163+
}
164+
141165
/**
142166
* Fetches waitpoints in chunks to avoid NAPI string conversion limits.
143167
* This is necessary because waitpoints can have large outputs (100KB+),
@@ -260,7 +284,10 @@ export async function getExecutionSnapshotsSince(
260284
prisma: PrismaClientOrTransaction,
261285
runId: string,
262286
sinceSnapshotId: string,
263-
runStore?: RunStore
287+
runStore?: RunStore,
288+
// The primary, for read-repair when `prisma` is a lagging read replica (see Step 3). Omit when
289+
// `prisma` is already the primary.
290+
repairClient?: PrismaClientOrTransaction
264291
): Promise<EnhancedExecutionSnapshot[]> {
265292
// Step 1: Find the createdAt of the sinceSnapshotId
266293
const sinceSnapshot = runStore
@@ -316,10 +343,41 @@ export async function getExecutionSnapshotsSince(
316343

317344
// Step 3: Get waitpoint IDs for the LATEST snapshot only (first in desc order)
318345
const latestSnapshot = snapshots[0];
319-
const waitpointIds = await getSnapshotWaitpointIds(prisma, latestSnapshot.id, runStore);
346+
let readClient = prisma;
347+
const { present, ids } = await getSnapshotWaitpointIdsWithPresence(
348+
prisma,
349+
latestSnapshot.id,
350+
runStore
351+
);
352+
let waitpointIds = ids;
353+
354+
// Read-repair (multi-reader): Step 2 saw this snapshot, but on a multi-reader replica the join read
355+
// can hit a laggier reader that does not have it yet. present=false means its empty id list is not
356+
// authoritative - re-read from the primary so the runner is not handed a waitpoint-less continue
357+
// (which it silently drops, hanging the run). Single-reader replicas never hit this (present stays true).
358+
if (repairClient && repairClient !== prisma && !present) {
359+
waitpointIds = await getSnapshotWaitpointIds(repairClient, latestSnapshot.id, runStore);
360+
readClient = repairClient;
361+
}
362+
363+
// Read-repair (batch): completedWaitpointOrder is written on the snapshot row in the same statement as the
364+
// snapshot, so it is authoritative. If it lists more waitpoints than the join read returned, the
365+
// _completedWaitpoints rows are stale on this client (a lagging read replica) - re-read them from the
366+
// primary so the runner is not handed a waitpoint-less continue, which it drops and the run hangs.
367+
// Distinct: completedWaitpointOrder can list the same id twice (a run batched under one idempotency
368+
// key) while the _completedWaitpoints join is deduped, so compare unique ids or the repair fires every
369+
// poll even against a caught-up replica.
370+
const expectedCount = new Set(latestSnapshot.completedWaitpointOrder ?? []).size;
371+
if (repairClient && repairClient !== prisma && waitpointIds.length < expectedCount) {
372+
const repaired = await getSnapshotWaitpointIds(repairClient, latestSnapshot.id, runStore);
373+
if (repaired.length > waitpointIds.length) {
374+
waitpointIds = repaired;
375+
readClient = repairClient;
376+
}
377+
}
320378

321379
// Step 4: Fetch waitpoints in chunks to avoid NAPI string conversion limits
322-
const waitpoints = await fetchWaitpointsInChunks(prisma, waitpointIds, runStore);
380+
const waitpoints = await fetchWaitpointsInChunks(readClient, waitpointIds, runStore);
323381

324382
// Step 5: Build enhanced snapshots - only latest gets waitpoints, others get empty arrays
325383
// The runner only uses completedWaitpoints from the latest snapshot anyway

0 commit comments

Comments
 (0)