diff --git a/.changeset/event-count-guard.md b/.changeset/event-count-guard.md new file mode 100644 index 0000000000..cc10ff8fca --- /dev/null +++ b/.changeset/event-count-guard.md @@ -0,0 +1,9 @@ +--- +'workflow': minor +'@workflow/core': minor +'@workflow/world-vercel': minor +'@workflow/world': minor +'@workflow/errors': minor +--- + +Strengthen the event-creation precondition guard: replay-context writes now also send the number of loaded events, so a snapshot that is missing an event is rejected instead of committing a divergent event log, and a rejection restarts the replay in-process (consuming the events a world may attach to the rejection) rather than re-committing the rejected payload or re-invoking over the queue. `@workflow/world-local` and `@workflow/world-postgres` do not implement the check. diff --git a/.changeset/step-delivery-ordering.md b/.changeset/step-delivery-ordering.md new file mode 100644 index 0000000000..1c3129223c --- /dev/null +++ b/.changeset/step-delivery-ordering.md @@ -0,0 +1,5 @@ +--- +'@workflow/core': patch +--- + +Deliver step results, wait completions, hook payloads and aborts in strict event-log order relative to one another, preventing replay divergence (`CORRUPTED_EVENT_LOG`) when a step completion is adjacent in the log to a `wait_completed`, `hook_received` or abort that a concurrent branch is awaiting. diff --git a/docs/content/docs/v5/api-reference/workflow-errors/precondition-failed-error.mdx b/docs/content/docs/v5/api-reference/workflow-errors/precondition-failed-error.mdx index ae60241f46..2430b94631 100644 --- a/docs/content/docs/v5/api-reference/workflow-errors/precondition-failed-error.mdx +++ b/docs/content/docs/v5/api-reference/workflow-errors/precondition-failed-error.mdx @@ -8,14 +8,16 @@ related: - /docs/api-reference/workflow-errors/entity-conflict-error --- -`PreconditionFailedError` is thrown by world implementations when an event creation is rejected because the client's event-log snapshot is stale — a newer out-of-band event (such as a received hook or a completed step) was recorded after the snapshot the client replayed from. It corresponds to HTTP 412 Precondition Failed semantics. +`PreconditionFailedError` is thrown by world implementations when an event creation is rejected because the client's event-log snapshot is stale — either a newer out-of-band event (such as a received hook or a completed step) was recorded after the snapshot the client replayed from, or the snapshot is missing an event recorded at or before it. It corresponds to HTTP 412 Precondition Failed semantics. -This only occurs when the optimistic-concurrency guard is enabled via `WORKFLOW_PRECONDITION_GUARD=1` (see [Runtime Tuning](/docs/configuration/runtime-tuning)); event creations that carry no snapshot are never rejected with this error. +This only occurs while the optimistic-concurrency guard is enabled (`WORKFLOW_PRECONDITION_GUARD`, on by default — see [Runtime Tuning](/docs/configuration/runtime-tuning)); event creations that carry no snapshot are never rejected with this error. -The Workflow runtime handles this error automatically: it reloads the event log and retries, ultimately re-enqueueing the run for a fresh replay if it cannot catch up. You will only encounter it when interacting with world storage APIs directly. +The Workflow runtime handles this error automatically: it restarts the replay in the same invocation from a corrected event log, and re-invokes the run for a fresh replay only once its in-process restart budget is spent. It never retries the rejected creation as-is, because a replay working from a corrected log derives different events. You will only encounter it when interacting with world storage APIs directly. +A world may attach the events the client was missing to the rejection as `details`, which lets the runtime restart without re-reading the event log. Doing so is optional, and the runtime falls back to a full reload when the details are absent or unusable. + ```typescript lineNumbers import { PreconditionFailedError } from "workflow/errors" declare const world: { events: { create(...args: any[]): Promise } }; // @setup @@ -40,6 +42,8 @@ definition={` interface PreconditionFailedError { /** Delay in seconds before the operation should be retried. Present when the server sends a Retry-After header. */ retryAfter?: number; + /** Optional rejection payload. A world may put the events the client was missing here, as \`{ events, cursor }\`, so the runtime can restart its replay without re-reading the event log. */ + details?: unknown; /** The error message. */ message: string; } diff --git a/docs/content/docs/v5/configuration/runtime-tuning.mdx b/docs/content/docs/v5/configuration/runtime-tuning.mdx index 932a4ac38c..639967facd 100644 --- a/docs/content/docs/v5/configuration/runtime-tuning.mdx +++ b/docs/content/docs/v5/configuration/runtime-tuning.mdx @@ -41,13 +41,19 @@ For example, a workflow can run a 10-minute inline step even with `WORKFLOW_REPL ### `WORKFLOW_PRECONDITION_GUARD` - Default: enabled -- An optimistic-concurrency guard for event creation: replay-context event creations send a `stateUpdatedAt` snapshot timestamp, and a backend that supports the guard rejects a creation with 412 ([`PreconditionFailedError`](/docs/api-reference/workflow-errors/precondition-failed-error)) when a newer out-of-band event (a received hook or a completed step) was recorded after that snapshot. -- On rejection the runtime reloads the event log and retries, falling back to a queue re-invocation with a fresh replay if it cannot catch up. +- An optimistic-concurrency guard for event creation: replay-context event creations describe the snapshot they replayed from — its latest event timestamp (`stateUpdatedAt`), the number of events it contains (`stateEventCount`), and its event-log cursor (`stateCursor`) — and a backend that supports the guard rejects a creation with 412 ([`PreconditionFailedError`](/docs/api-reference/workflow-errors/precondition-failed-error)) when a newer out-of-band event (a received hook or a completed step) was recorded after that snapshot, or when the snapshot is missing an event recorded at or before it. +- On rejection the runtime restarts the replay in the same invocation from a corrected event log, and falls back to a re-invocation with a fresh replay once the restart budget is spent. The rejected write is never retried as-is: a replay working from a corrected log derives different events, so only a fresh replay may write again. - When enabled — and the World declares that it enforces the guard (`capabilities.preconditionGuard`; the Vercel World does) — the runtime also keeps the per-step event-log delta optimization (consuming the delta returned by a step's terminal write instead of issuing an extra `events.list` per step) active while the run has an open hook. Without an enforced guard, an open hook disables it. - While a hook is open on a guard-enforcing deployment, inline steps take the await-then-run path even when optimistic inline start is enabled: the step's `step_started` claim carries the snapshot and is awaited before the body runs, so a claim the backend rejects as stale never executes user code. - Backends that do not support the guard ignore the snapshot; they must not declare the capability, so guard-dependent optimizations stay off against them even when the flag is set. - Set `0` to disable. +### `WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS` + +- Default: `3` +- Replays a single invocation restarts in-process after a rejected event creation before it falls back to a re-invocation. +- A restart reloads the event log and rebuilds the workflow from scratch, so it costs a replay but no queue round trip. A World may attach the missing events to its rejection, in which case the first restart needs no event-log request at all. + ## Inline execution ### `WORKFLOW_V2_TIMEOUT_MS` diff --git a/docs/content/worlds/v5/building-a-world.mdx b/docs/content/worlds/v5/building-a-world.mdx index 014f0479a5..ca8231ccef 100644 --- a/docs/content/worlds/v5/building-a-world.mdx +++ b/docs/content/worlds/v5/building-a-world.mdx @@ -106,6 +106,28 @@ Keep the owning Run available for at least as long as its token remains unavaila **Automatic Hook Cleanup:** When a run ends, remove its live Hooks. Make each token available unless its `tokenRetentionUntil` is still in the future. A `hook_disposed` event always makes the token available immediately. +### Optional: The Event Creation Precondition Guard + +A replay writes events derived from the event log it loaded, so a write made from an event log that no longer matches the store can commit events no correct replay would produce. To let a World fence those writes, `events.create()` params may carry a description of the snapshot the caller replayed from: + +- `stateUpdatedAt` — the timestamp encoded in the latest loaded event's ID. +- `stateEventCount` — how many events the caller loaded. Only sent together with `stateUpdatedAt`; ignore a count that arrives without one. +- `stateCursor` — the caller's event-log cursor. Advisory, and only meaningful on the reject path (see below). + +Enforcing the guard means rejecting the creation with a `PreconditionFailedError` when either holds: + +1. An event was recorded after `stateUpdatedAt` that the caller could not have loaded. +2. More events were recorded at or before `stateUpdatedAt` than `stateEventCount` — the caller's snapshot is missing one. + +Two rules make this safe: + +- **Compare at or below `stateUpdatedAt`, not strictly below.** Events routinely share a millisecond with the caller's latest event, and a strict comparison misses exactly those. +- **Every uncertainty must allow the write.** If your record of a run's events is incomplete, expired, or cannot answer the question, accept the creation. A rejection must always mean a real discrepancy, because the runtime responds to one by discarding a replay. + +A rejection may optionally carry the events the caller was missing, as `{ events, cursor }` on the error's `details`. Only include them when you can prove the set is complete — that those events fully account for the discrepancy and are not truncated. Otherwise omit them, and the runtime performs a full reload instead. + +A World that enforces the guard should declare `capabilities.preconditionGuard`, which the runtime also reads to keep event-log delta optimizations enabled. A World that ignores these params must not declare it. + ## Queue Interface The Queue interface handles asynchronous workflow execution, including queued step work: diff --git a/packages/core/src/delivery-barrier-coverage.test.ts b/packages/core/src/delivery-barrier-coverage.test.ts new file mode 100644 index 0000000000..73f9e92e60 --- /dev/null +++ b/packages/core/src/delivery-barrier-coverage.test.ts @@ -0,0 +1,510 @@ +/** + * Third companion to `step-delivery-ordering.test.ts` (the two production + * `CORRUPTED_EVENT_LOG` shapes) and `step-delivery-hop-count.test.ts` (a step + * result must not overtake the wait/hook branch the log ordered first, however + * many hops that branch needs). Both of those cover a step result deferring + * behind an earlier delivery. This file covers the three cases where the + * delivery-barrier registry did not yet reach: + * + * 1. STEP behind STEP, across drain windows. `DEFER_BEHIND.step` used to + * exclude `'step'`, on the grounds that the serial `promiseQueue` already + * orders step results. It no longer does: a step captures its outcome in + * its queue slot but resolves from a detached continuation once its + * barrier clears, and two steps agree on that ordering only while they + * defer behind the same set. + * + * 2. WAIT / HOOK behind STEP, at varying consumer hop counts — the mirror of + * `step-delivery-hop-count.test.ts`. `sleep.ts` and `hook.ts` used to read + * the registry after their queue work rather than at event-consumption + * time, by which point an earlier step had usually delivered and retired + * its barrier. They then skipped both the gate and + * `awaitEarlierDeliveries`' macrotask yield. + * + * 3. ABORT deliveries. `_setAborted` fires the signal's listeners, and a + * listener may invoke a step and draw a ULID, so an abort is as + * branch-deciding as any other delivery — but it resolved straight off its + * `promiseQueue` slot and registered no barrier. + * + * Every case asserts the same thing: the replay allocates its follow-up step + * ULIDs in the order the committed log recorded. A regression surfaces as the + * production `ReplayDivergenceError`. + */ +import { WorkflowRuntimeError } from '@workflow/errors'; +import { withResolvers } from '@workflow/utils'; +import type { Event } from '@workflow/world'; +import * as nanoid from 'nanoid'; +import { monotonicFactory } from 'ulid'; +import { describe, expect, it, vi } from 'vitest'; +import { EventsConsumer } from './events-consumer.js'; +import { WorkflowSuspension } from './global.js'; +import { + awaitEarlierDeliveries, + registerDeliveryBarrier, + type WorkflowOrchestratorContext, +} from './private.js'; +import { ReplayPayloadCache } from './replay-payload-cache.js'; +import { dehydrateStepReturnValue } from './serialization.js'; +import { createUseStep } from './step.js'; +import { createContext } from './vm/index.js'; +import { createCreateAbortController } from './workflow/abort-controller.js'; +import { createCreateHook } from './workflow/hook.js'; +import { createSleep } from './workflow/sleep.js'; + +const FIXED_TIMESTAMP = 1753481739458; + +function setupWorkflowContext(events: Event[]): WorkflowOrchestratorContext { + const context = createContext({ + seed: 'test', + fixedTimestamp: FIXED_TIMESTAMP, + }); + const ulid = monotonicFactory(() => context.globalThis.Math.random()); + const workflowStartedAt = context.globalThis.Date.now(); + const promiseQueueHolder = { current: Promise.resolve() }; + const ctxRef: { current?: WorkflowOrchestratorContext } = {}; + const ctx: WorkflowOrchestratorContext = { + runId: 'wrun_test', + encryptionKey: undefined, + replayPayloadCache: new ReplayPayloadCache(undefined), + globalThis: context.globalThis, + eventsConsumer: new EventsConsumer(events, { + onUnconsumedEvent: (event) => { + ctxRef.current?.onWorkflowError( + new WorkflowRuntimeError(`Unconsumed event: ${event.eventType}`) + ); + }, + getPromiseQueue: () => promiseQueueHolder.current, + }), + invocationsQueue: new Map(), + generateUlid: () => ulid(workflowStartedAt), + generateNanoid: nanoid.customRandom(nanoid.urlAlphabet, 21, (size) => + new Uint8Array(size).map(() => 256 * context.globalThis.Math.random()) + ), + onWorkflowError: vi.fn(), + get promiseQueue() { + return promiseQueueHolder.current; + }, + set promiseQueue(value: Promise) { + promiseQueueHolder.current = value; + }, + pendingDeliveries: 0, + pendingDeliveryBarriers: new Map(), + }; + ctxRef.current = ctx; + return ctx; +} + +/** + * The ULIDs the seeded generator hands out, in invocation order. Correlation + * IDs in the fixtures below have to match what the replayed workflow draws. + */ +function deterministicUlids(count: number): string[] { + const context = createContext({ + seed: 'test', + fixedTimestamp: FIXED_TIMESTAMP, + }); + const ulid = monotonicFactory(() => context.globalThis.Math.random()); + const workflowStartedAt = context.globalThis.Date.now(); + return Array.from({ length: count }, () => ulid(workflowStartedAt)); +} + +const ULIDS = deterministicUlids(8); + +async function replay( + ctx: WorkflowOrchestratorContext, + workflowFn: () => Promise +): Promise { + const discontinuation = withResolvers(); + ctx.onWorkflowError = discontinuation.reject; + try { + await Promise.race([workflowFn(), discontinuation.promise]); + } catch (err) { + return err; + } + return undefined; +} + +/** + * Assert the replay stopped where the committed log says it should: the + * follow-up steps allocated, in the log's order, and the run suspended waiting + * on them. A divergent replay fails here with the production error instead. + */ +function expectSuspendedWithPendingSteps( + ctx: WorkflowOrchestratorContext, + error: unknown, + expected: string[] +) { + if (!WorkflowSuspension.is(error)) { + throw new Error( + error === undefined + ? 'expected the replay to suspend, but it completed' + : error instanceof Error + ? error.message + : String(error), + { cause: error } + ); + } + expect( + [...ctx.invocationsQueue.values()].flatMap((item) => + item.type === 'step' ? [item.stepName] : [] + ) + ).toEqual(expected); +} + +const event = ( + eventId: string, + eventType: string, + correlationId: string, + eventData: Record +): Event => + ({ + eventId, + runId: 'wrun_test', + eventType, + correlationId, + eventData, + createdAt: new Date(), + }) as Event; + +// ─── 1. step behind step, across drain windows ──────────────────────────── +// +// The log is one a live run legitimately produces: +// +// evnt_3 wait_completed ← the sleep branch +// evnt_4 step_completed stepA ← stepA's worker wrote this just before… +// evnt_5 step_created stepB ← …the invocation resuming from the sleep +// wrote this; its own replay predated +// evnt_4, so it never delivered stepA +// evnt_7 step_completed stepB +// evnt_8 step_created afterA ← a later invocation delivered stepA first, +// evnt_9 step_created afterB exactly as the log orders them +// +// On replay `stepB`'s consumer does not exist until the sleep is delivered, so +// the drain stops at evnt_5 and the two step completions land in separate +// windows. stepA (deferring behind the wait) is then parked on the macrotask +// yield while stepB, which sees an empty registry, resolves on microtasks. +describe('step result delivery ordering against an earlier step result', () => { + it('delivers the earlier step_completed first when only it defers', async () => { + const resumeAt = new Date(FIXED_TIMESTAMP + 5_000); + const ops: Promise[] = []; + const [stepAResult, stepBResult] = await Promise.all([ + dehydrateStepReturnValue('a', 'wrun_test', undefined, ops), + dehydrateStepReturnValue('b', 'wrun_test', undefined, ops), + ]); + + const events: Event[] = [ + event('evnt_0', 'step_created', `step_${ULIDS[0]}`, { + stepName: 'stepA', + }), + event('evnt_1', 'wait_created', `wait_${ULIDS[1]}`, { resumeAt }), + event('evnt_2', 'step_started', `step_${ULIDS[0]}`, { + stepName: 'stepA', + }), + event('evnt_3', 'wait_completed', `wait_${ULIDS[1]}`, { resumeAt }), + event('evnt_4', 'step_completed', `step_${ULIDS[0]}`, { + stepName: 'stepA', + result: stepAResult, + }), + event('evnt_5', 'step_created', `step_${ULIDS[2]}`, { + stepName: 'stepB', + }), + event('evnt_6', 'step_started', `step_${ULIDS[2]}`, { + stepName: 'stepB', + }), + event('evnt_7', 'step_completed', `step_${ULIDS[2]}`, { + stepName: 'stepB', + result: stepBResult, + }), + event('evnt_8', 'step_created', `step_${ULIDS[3]}`, { + stepName: 'afterA', + }), + event('evnt_9', 'step_created', `step_${ULIDS[4]}`, { + stepName: 'afterB', + }), + ]; + + const ctx = setupWorkflowContext(events); + const useStep = createUseStep(ctx); + const sleep = createSleep(ctx); + + const error = await replay(ctx, async () => { + const stepA = useStep('stepA'); + const afterA = useStep('afterA'); + const stepB = useStep('stepB'); + const afterB = useStep('afterB'); + + await Promise.all([ + (async () => { + await stepA(); + await afterA(); + })(), + (async () => { + await sleep('5s'); + await stepB(); + await afterB(); + })(), + ]); + }); + + expectSuspendedWithPendingSteps(ctx, error, ['afterA', 'afterB']); + }); +}); + +// ─── 2. wait / hook behind step, at varying consumer hop counts ──────────── +// +// The mirror of `step-delivery-hop-count.test.ts`: there a step result must +// not overtake an earlier wait/hook branch; here a wait/hook must not overtake +// an earlier STEP branch. The step branch is padded with extra `await`s so hop +// count is the only variable — under a hop-count race the padded branch loses +// and the follow-up ULIDs swap. +const EXTRA_HOPS = [0, 1, 3, 8, 20, 50]; + +describe('wait completion delivery ordering against an earlier step result', () => { + for (const extraHops of EXTRA_HOPS) { + it(`keeps the recorded ULID allocation with ${extraHops} extra consumer hops`, async () => { + const resumeAt = new Date(FIXED_TIMESTAMP + 5_000); + const ops: Promise[] = []; + const stepAResult = await dehydrateStepReturnValue( + 'a', + 'wrun_test', + undefined, + ops + ); + + const events: Event[] = [ + event('evnt_0', 'step_created', `step_${ULIDS[0]}`, { + stepName: 'stepA', + }), + event('evnt_1', 'wait_created', `wait_${ULIDS[1]}`, { resumeAt }), + event('evnt_2', 'step_started', `step_${ULIDS[0]}`, { + stepName: 'stepA', + }), + event('evnt_3', 'step_completed', `step_${ULIDS[0]}`, { + stepName: 'stepA', + result: stepAResult, + }), + event('evnt_4', 'wait_completed', `wait_${ULIDS[1]}`, { resumeAt }), + event('evnt_5', 'step_created', `step_${ULIDS[2]}`, { + stepName: 'afterStep', + }), + event('evnt_6', 'step_created', `step_${ULIDS[3]}`, { + stepName: 'afterSleep', + }), + ]; + + const ctx = setupWorkflowContext(events); + const useStep = createUseStep(ctx); + const sleep = createSleep(ctx); + + const error = await replay(ctx, async () => { + const stepA = useStep('stepA'); + const afterStep = useStep('afterStep'); + const afterSleep = useStep('afterSleep'); + + await Promise.all([ + (async () => { + await stepA(); + for (let i = 0; i < extraHops; i++) { + await Promise.resolve(); + } + await afterStep(); + })(), + (async () => { + await sleep('5s'); + await afterSleep(); + })(), + ]); + }); + + expectSuspendedWithPendingSteps(ctx, error, ['afterStep', 'afterSleep']); + }); + } +}); + +describe('hook payload delivery ordering against an earlier step result', () => { + for (const extraHops of EXTRA_HOPS) { + it(`keeps the recorded ULID allocation with ${extraHops} extra consumer hops`, async () => { + const ops: Promise[] = []; + const [stepAResult, hookPayload] = await Promise.all([ + dehydrateStepReturnValue('a', 'wrun_test', undefined, ops), + dehydrateStepReturnValue({ v: 1 }, 'wrun_test', undefined, ops), + ]); + + const events: Event[] = [ + event('evnt_0', 'step_created', `step_${ULIDS[0]}`, { + stepName: 'stepA', + }), + event('evnt_1', 'hook_created', `hook_${ULIDS[1]}`, { + token: 'tok', + isWebhook: false, + }), + event('evnt_2', 'step_started', `step_${ULIDS[0]}`, { + stepName: 'stepA', + }), + event('evnt_3', 'step_completed', `step_${ULIDS[0]}`, { + stepName: 'stepA', + result: stepAResult, + }), + event('evnt_4', 'hook_received', `hook_${ULIDS[1]}`, { + token: 'tok', + payload: hookPayload, + }), + event('evnt_5', 'step_created', `step_${ULIDS[2]}`, { + stepName: 'afterStep', + }), + event('evnt_6', 'step_created', `step_${ULIDS[3]}`, { + stepName: 'afterHook', + }), + ]; + + const ctx = setupWorkflowContext(events); + const useStep = createUseStep(ctx); + const createHook = createCreateHook(ctx); + + const error = await replay(ctx, async () => { + const stepA = useStep('stepA'); + const afterStep = useStep('afterStep'); + const afterHook = useStep('afterHook'); + + await Promise.all([ + (async () => { + await stepA(); + for (let i = 0; i < extraHops; i++) { + await Promise.resolve(); + } + await afterStep(); + })(), + (async () => { + const hook = createHook<{ v: number }>({ token: 'tok' }); + await hook; + await afterHook(); + })(), + ]); + }); + + expectSuspendedWithPendingSteps(ctx, error, ['afterStep', 'afterHook']); + }); + } +}); + +// ─── 3. abort deliveries ─────────────────────────────────────────────────── +// +// evnt_4 wait_completed ← makes the step result defer +// evnt_5 step_completed stepA ← deferred behind the wait +// evnt_6 hook_received (abort) ← must NOT overtake evnt_5 +describe('abort delivery ordering against an earlier step result', () => { + it('delivers the earlier step_completed before the abort', async () => { + // The controller draws two ULIDs on construction (stream id, then hook + // correlation id), so the sleep and stepA take the next two. + const abortHookToken = `abrt_${ULIDS[0]}`; + const abortCorrelationId = `hook_${ULIDS[1]}`; + const waitCorrelationId = `wait_${ULIDS[2]}`; + const stepACorrelationId = `step_${ULIDS[3]}`; + + const resumeAt = new Date(FIXED_TIMESTAMP + 5_000); + const ops: Promise[] = []; + const [stepAResult, abortPayload] = await Promise.all([ + dehydrateStepReturnValue('a', 'wrun_test', undefined, ops), + dehydrateStepReturnValue( + { reason: 'cancelled' }, + 'wrun_test', + undefined, + ops + ), + ]); + + const events: Event[] = [ + event('evnt_0', 'hook_created', abortCorrelationId, { + token: abortHookToken, + isWebhook: false, + }), + event('evnt_1', 'wait_created', waitCorrelationId, { resumeAt }), + event('evnt_2', 'step_created', stepACorrelationId, { + stepName: 'stepA', + }), + event('evnt_3', 'step_started', stepACorrelationId, { + stepName: 'stepA', + }), + event('evnt_4', 'wait_completed', waitCorrelationId, { resumeAt }), + event('evnt_5', 'step_completed', stepACorrelationId, { + stepName: 'stepA', + result: stepAResult, + }), + event('evnt_6', 'hook_received', abortCorrelationId, { + token: abortHookToken, + payload: abortPayload, + }), + event('evnt_7', 'step_created', `step_${ULIDS[4]}`, { + stepName: 'afterStep', + }), + event('evnt_8', 'step_created', `step_${ULIDS[5]}`, { + stepName: 'afterAbort', + }), + ]; + + const ctx = setupWorkflowContext(events); + const useStep = createUseStep(ctx); + const sleep = createSleep(ctx); + const WorkflowAbortController = createCreateAbortController(ctx); + + const error = await replay(ctx, async () => { + const controller = new WorkflowAbortController(); + const stepA = useStep('stepA'); + const afterStep = useStep('afterStep'); + const afterAbort = useStep('afterAbort'); + + await Promise.all([ + sleep('5s'), + (async () => { + await stepA(); + await afterStep(); + })(), + (async () => { + await new Promise((resolveListener) => { + controller.signal.addEventListener('abort', resolveListener); + }); + await afterAbort(); + })(), + ]); + }); + + expectSuspendedWithPendingSteps(ctx, error, ['afterStep', 'afterAbort']); + }); +}); + +// ─── 4. registry scan cost ───────────────────────────────────────────────── +// +// `resolvesOnItsOwn` walks the registry recursively: an armed hook re-checks +// every earlier wait and step, an armed wait every earlier hook and step, and +// so on. Unmemoized that is T(n) = Σ T(j) — exponential — and the registry is +// not small by construction: `EventsConsumer` drains consecutively consumable +// events synchronously while barriers only retire on microtask-driven +// deliveries, so a fan-out of `Promise.race([hook, sleep(watchdog)])` branches +// accumulates one barrier per branch per kind (measured: 49 live barriers for +// 24 branches). +// +// The scan runs synchronously, before `awaitEarlierDeliveries` first awaits, +// so timing the call alone measures it. Unmemoized, 40 alternating armed +// hook/wait barriers is ~10^8 recursive calls — minutes. Memoized it is +// linear. The bound is deliberately loose; this is an order-of-magnitude +// guard, not a benchmark. +describe('delivery-barrier registry scan cost', () => { + it('stays linear in registry size for a step delivery', () => { + const ctx = { + pendingDeliveries: 0, + promiseQueue: Promise.resolve(), + pendingDeliveryBarriers: new Map(), + } as unknown as WorkflowOrchestratorContext; + + const BARRIERS = 40; + for (let index = 0; index < BARRIERS; index++) { + registerDeliveryBarrier(ctx, index, index % 2 ? 'hook' : 'wait'); + } + expect(ctx.pendingDeliveryBarriers?.size).toBe(BARRIERS); + + const startedAt = performance.now(); + // The floating promise never settles (nothing delivers these barriers); + // only the synchronous scan inside the call is under test. + void awaitEarlierDeliveries(ctx, BARRIERS, 'step'); + expect(performance.now() - startedAt).toBeLessThan(1_000); + }); +}); diff --git a/packages/core/src/private.ts b/packages/core/src/private.ts index 63bc94891f..c0294efb59 100644 --- a/packages/core/src/private.ts +++ b/packages/core/src/private.ts @@ -162,26 +162,33 @@ export interface WorkflowOrchestratorContext { pendingDeliveries: number; /** * Ordered registry of in-flight "branch-deciding" deliveries — the - * resolutions a workflow typically `Promise.race`s on: buffered hook - * payloads (`hook_received`) and wait completions (`wait_completed`). - * Keyed by the delivery's position (index) in the consumed event log. + * resolutions a workflow typically `Promise.race`s on, or awaits from + * independent concurrent branches: hook payloads (`hook_received`), wait + * completions (`wait_completed`), and step results (`step_completed` / + * `step_failed`). Keyed by the delivery's position (index) in the consumed + * event log. * - * The problem: a buffered hook payload is observed via the async hook - * iterator (`yield await this`), costing extra microtask hops, while a - * `wait_completed` resolves with fewer hops — and a reused sleep can - * resolve in an entirely earlier loop iteration. Either way, the - * resolution that the committed event log ordered first can lose a - * `Promise.race` to a faster- or already-resolved competitor, diverging - * from the log and surfacing as `CorruptedEventLogError`. + * The problem: each of these resolutions reaches workflow code after a + * different, workload-dependent number of microtask hops. A buffered hook + * payload is observed via the async hook iterator (`yield await this`), + * costing extra hops; a `wait_completed` resolves with fewer, and a reused + * sleep can resolve in an entirely earlier loop iteration; a step result is + * gated on hydration whose cost varies between replays of the SAME + * invocation — the first replay pays the full decrypt/decompress/revive, + * while later replays sharing the invocation's `ReplayPayloadCache` + * memo-hit small primitive results and resolve in one or two hops. Either + * way, the resolution that the committed event log ordered first can lose a + * `Promise.race` (or a `useStep` ULID allocation) to a faster- or + * already-resolved competitor, diverging from the log and surfacing as + * `CorruptedEventLogError`. * * The fix is a strict, deterministic delivery order anchored on * event-log position: a delivery does not resolve to the workflow until - * every earlier-in-log delivery of the OPPOSITE kind has been delivered. - * (Opposite kind only: sequential same-kind hook payloads must not block - * one another, and a wait need not wait behind a later wait.) Because the + * every relevant earlier-in-log delivery has been delivered. Because the * gate is "the earlier delivery resolved", not "won a timing race", the * outcome is independent of microtask hops, hydration/decryption time, - * and `Promise.race` argument order. + * and `Promise.race` argument order. Which earlier kinds a delivery defers + * behind is spelled out on {@link awaitEarlierDeliveries}. * * Index is used rather than the `eventId` string because `eventId` is an * opaque, world-assigned value not guaranteed to sort in creation order @@ -199,30 +206,147 @@ export interface WorkflowOrchestratorContext { } /** The kind of branch-deciding delivery a barrier represents. */ -export type DeliveryKind = 'hook' | 'wait'; +export type DeliveryKind = 'hook' | 'wait' | 'step'; interface DeliveryBarrierEntry { kind: DeliveryKind; /** Resolves once this delivery has resolved to the workflow. */ delivered: Promise; + /** + * Whether this delivery is committed to reaching the workflow without any + * further action by workflow code. True for wait completions and step + * results, which always resolve from their own chain, and for a hook payload + * that already had a waiting consumer when it was consumed. + * + * False for a BUFFERED hook payload no consumer has claimed yet: it is + * delivered by `claim()`, i.e. whenever the workflow next reads the hook — + * which may be causally *after* a later-in-log delivery. `arm()` flips it + * once a consumer takes the payload. + */ + armed: boolean; +} + +/** + * Which earlier kinds each delivery kind defers behind. Chosen so that no kind + * blocks on a peer it does not need to: + * + * - a hook defers behind earlier WAITS and STEPS — not earlier hooks, which + * are sequential same-entity payloads and must not block one another; + * - a wait defers behind earlier HOOKS and STEPS — not earlier waits, since a + * wait never needs to queue behind another wait; + * - a step defers behind earlier WAITS, HOOKS and STEPS. + * + * The step-behind-step edge is not redundant with the serial `promiseQueue`. + * The queue fixes the order in which step results are HYDRATED, but a step no + * longer resolves inside its queue slot — it captures the outcome there and + * resolves from a detached continuation once its barrier clears. Two steps + * agree on that continuation's ordering only while they defer behind the same + * set, which holds when they are consumed in the same drain window but not + * across windows: a step consumed later can miss a wait/hook barrier that an + * earlier step is still parked on, because the barrier retired in between. The + * earlier step is then waiting out the macrotask yield below while the later + * one resolves on microtasks, and overtakes it — see + * `delivery-barrier-coverage.test.ts`. Deferring behind earlier steps + * closes that window structurally: the earlier step's barrier is still + * registered precisely because it has not delivered yet. + * + * Every edge points from a later log index to a strictly earlier one, so the + * wait-for graph can never contain a cycle. + */ +const DEFER_BEHIND: Record = { + hook: ['wait', 'step'], + wait: ['hook', 'step'], + step: ['wait', 'hook', 'step'], +}; + +/** + * Whether `entry` will resolve on its own — it is armed, and every earlier + * delivery it defers behind will likewise resolve on its own. + * + * A step delivery is always self-resolving: it skips uncommitted deliveries + * (see {@link awaitEarlierDeliveries}), and the earlier steps it does defer + * behind are self-resolving by the same argument, inducting down on index. + * + * Recursion terminates because every edge points to a strictly smaller index. + * `memo` is required rather than an optimization: without it the walk is + * exponential in the number of live hook/wait barriers (each armed entry + * re-walks every earlier entry of the opposite kind, T(n) = Σ T(j)), and the + * registry is not small by construction — `EventsConsumer` drains + * consecutively consumable events synchronously while barriers only retire on + * microtask-driven deliveries, so a fan-out of `Promise.race([hook, sleep])` + * branches accumulates one barrier per branch per kind. Memoized, the walk is + * linear in registry size. The memo MUST be per-call: `armed` mutates between + * calls as buffered payloads are claimed. + */ +function resolvesOnItsOwn( + barriers: Map, + index: number, + entry: DeliveryBarrierEntry, + memo: Map +): boolean { + const cached = memo.get(index); + if (cached !== undefined) { + return cached; + } + const result = computeResolvesOnItsOwn(barriers, index, entry, memo); + memo.set(index, result); + return result; +} + +function computeResolvesOnItsOwn( + barriers: Map, + index: number, + entry: DeliveryBarrierEntry, + memo: Map +): boolean { + if (!entry.armed) { + return false; + } + if (entry.kind === 'step') { + return true; + } + const deferBehind = DEFER_BEHIND[entry.kind]; + for (const [otherIndex, other] of barriers) { + if ( + otherIndex < index && + deferBehind.includes(other.kind) && + !resolvesOnItsOwn(barriers, otherIndex, other, memo) + ) { + return false; + } + } + return true; } /** - * Awaits, in strict event-log order, every still-registered delivery whose - * index is earlier than `eventIndex` AND whose kind is in `deferBehindKinds`, - * so that this resolution is handed to the workflow only after all relevant - * earlier-in-log deliveries have been. This is what keeps a `Promise.race` - * deterministic and aligned with the committed event log, independent of - * microtask-hop counts, hydration time, or race-argument order. + * Awaits, in strict event-log order, every still-registered delivery that is + * earlier in the log than `eventIndex` and that a delivery of `kind` defers + * behind (see {@link DEFER_BEHIND}), so that this resolution is handed to the + * workflow only after all relevant earlier-in-log deliveries have been. This + * is what keeps a `Promise.race` — or the ULID a follow-up `useStep` draws on + * a concurrent branch — deterministic and aligned with the committed event + * log, independent of microtask-hop counts, hydration time, or race-argument + * order. When this delivery does have to wait, it also yields a macrotask + * afterwards so the earlier delivery's consumer can run to its own next + * suspension point first; see the comment at that `await` for why ordering the + * `resolve()` calls alone is not enough. * - * `deferBehindKinds` is the opposite kind(s): a hook defers behind earlier - * WAITS (not earlier hooks — those are sequential same-entity payloads), a - * wait defers behind earlier HOOKS. + * One asymmetry: a STEP result additionally skips any earlier delivery that + * will not resolve on its own, i.e. one blocked (directly or transitively) on + * a buffered hook payload no consumer has claimed. Such a payload is delivered + * only when the workflow next reads the hook, and reaching that read very + * commonly requires the step result itself (`await stepX()` before the read). + * Gating the step on it would stall the workflow until the barrier's idle + * safety net fires, which then releases every delivery queued behind that + * payload at once — losing exactly the race this ordering exists to protect. + * Waits and hooks keep gating on unclaimed payloads: for them, waiting for the + * claim IS the ordering guarantee (a `wait_completed` must not preempt a + * payload the log ordered first). */ export async function awaitEarlierDeliveries( ctx: WorkflowOrchestratorContext, eventIndex: number | undefined, - deferBehindKinds: readonly DeliveryKind[] + kind: DeliveryKind ): Promise { // Defensive: tolerate contexts that predate this field (test harnesses). if ( @@ -232,14 +356,40 @@ export async function awaitEarlierDeliveries( ) { return; } + const barriers = ctx.pendingDeliveryBarriers; + const deferBehind = DEFER_BEHIND[kind]; const earlier: Promise[] = []; - for (const [index, entry] of ctx.pendingDeliveryBarriers) { - if (index < eventIndex && deferBehindKinds.includes(entry.kind)) { - earlier.push(entry.delivered); + // Shared across this call only — see `resolvesOnItsOwn`. + const selfResolving = new Map(); + for (const [index, entry] of barriers) { + if (index >= eventIndex || !deferBehind.includes(entry.kind)) { + continue; + } + if ( + kind === 'step' && + !resolvesOnItsOwn(barriers, index, entry, selfResolving) + ) { + continue; } + earlier.push(entry.delivered); } if (earlier.length > 0) { await Promise.all(earlier); + // An earlier delivery being "delivered" only means its `resolve()` ran. + // The branch it woke may need an arbitrary number of further microtask + // hops before it reaches its next `useStep` call and draws a ULID — a + // `for await` over a hook, for instance, resumes the generator, settles + // the promise from `next()`, and only then runs the loop body. Resolving + // this delivery on a microtask would let it overtake that branch and + // reorder the ULID allocation anyway, turning the guarantee below into a + // hop-count race that holds only for the shortest consumers. + // + // Yielding a macrotask lets the earlier branch's entire microtask chain + // drain first, whatever its length, so log order survives regardless of + // how the workflow consumes the earlier delivery. Only deliveries that + // actually had to defer pay this, so the common single-delivery drain is + // unaffected. + await new Promise((resolve) => setTimeout(resolve, 0)); } } @@ -247,17 +397,26 @@ export async function awaitEarlierDeliveries( export interface DeliveryBarrier { /** * Mark this delivery as delivered to the workflow. Resolves its - * `delivered` promise so any later-in-log opposite-kind delivery gated on - * it (via {@link awaitEarlierDeliveries}) may proceed, and removes it from - * the registry. Idempotent. + * `delivered` promise so any later-in-log delivery gated on it (via + * {@link awaitEarlierDeliveries}) may proceed, and removes it from the + * registry. Idempotent. */ markDelivered: () => void; + /** + * Mark this delivery as committed to happening, for a barrier registered + * unarmed (a buffered hook payload) once a consumer has claimed it. From + * then on a later step result may be ordered behind it. Idempotent. + */ + arm: () => void; } /** * Register a branch-deciding delivery at its event-log index so that later - * opposite-kind deliveries can be ordered strictly after it. Returns an inert - * handle when `pendingDeliveryBarriers` is not initialized. + * deliveries can be ordered strictly after it. Returns an inert handle when + * `pendingDeliveryBarriers` is not initialized. + * + * Pass `armed: false` for a delivery whose resolution waits on workflow code + * asking for it (a buffered hook payload); call `arm()` when it does. * * To guarantee a later delivery gated on this one can never hang when this * delivery is abandoned (the workflow took a different branch or is @@ -266,16 +425,21 @@ export interface DeliveryBarrier { export function registerDeliveryBarrier( ctx: WorkflowOrchestratorContext, eventIndex: number | undefined, - kind: DeliveryKind + kind: DeliveryKind, + options: { armed?: boolean } = {} ): DeliveryBarrier { const barriers = ctx.pendingDeliveryBarriers; if (!barriers || eventIndex === undefined) { - return { markDelivered: () => {} }; + return { markDelivered: () => {}, arm: () => {} }; } let done = false; const { promise, resolve } = withResolvers(); - const entry: DeliveryBarrierEntry = { kind, delivered: promise }; + const entry: DeliveryBarrierEntry = { + kind, + delivered: promise, + armed: options.armed ?? true, + }; barriers.set(eventIndex, entry); const finish = () => { @@ -290,12 +454,18 @@ export function registerDeliveryBarrier( }; // Safety net: if this delivery is never delivered to the workflow (its - // branch was not taken / the run is suspending), resolve at idle so a - // later opposite-kind delivery gated on it cannot deadlock and the + // branch was not taken / the run is suspending, or a buffered hook payload + // is only claimed after a later delivery the workflow is still waiting on), + // resolve at idle so a later delivery gated on it cannot deadlock and the // registry cannot leak an entry per abandoned delivery. scheduleWhenIdle(ctx, finish); - return { markDelivered: finish }; + return { + markDelivered: finish, + arm: () => { + entry.armed = true; + }, + }; } /** diff --git a/packages/core/src/runtime.test.ts b/packages/core/src/runtime.test.ts index aafec00075..3f4da714d7 100644 --- a/packages/core/src/runtime.test.ts +++ b/packages/core/src/runtime.test.ts @@ -1968,7 +1968,7 @@ describe('workflowEntrypoint inline-delta gate with open hooks', () => { expect(stepCompletedParams(eventsCreate)?.sinceCursor).toBeUndefined(); }); - it('abandons the batch and re-invokes when a stale lazy claim is rejected by the guard (interleaved hook_received)', async () => { + it('restarts the replay in-process and still completes the run when a stale lazy claim is rejected by the guard (interleaved hook_received)', async () => { process.env.WORKFLOW_PRECONDITION_GUARD = '1'; // Simulates the interleaving the fence exists for: after step A's // terminal write, an out-of-band hook_received bumps the run's marker; @@ -1987,9 +1987,8 @@ describe('workflowEntrypoint inline-delta gate with open hooks', () => { }, } ); - // The handler responds normally: the rejection is mapped to an abandoned - // batch + re-invocation (a `{ timeoutSeconds: 0 }` redelivery outside - // turbo), never a run_failed. + // The handler responds normally: the rejection restarts the replay inside + // this delivery, never a run_failed. expect(res.status).toBe(204); // Step B's claim was issued from a loaded (non-empty) log, so it carried // the guard snapshot — that is what lets the backend fence it. (The very @@ -2002,9 +2001,10 @@ describe('workflowEntrypoint inline-delta gate with open hooks', () => { 'deltaGateStepB' ); expect(typeof (rejectedClaim?.[2] as any)?.stateUpdatedAt).toBe('number'); - // The fenced step never ran its body and never wrote events. - expect(deltaGateBodyRuns).toEqual([]); - expect(eventsCreate.mock.calls).not.toContainEqual( + // The fenced claim's body never ran: step B executes exactly once, on the + // restarted replay whose claim the backend accepted. + expect(deltaGateBodyRuns).toEqual(['B']); + expect(eventsCreate.mock.calls).toContainEqual( expect.arrayContaining([ expect.objectContaining({ eventType: 'step_completed', @@ -2012,13 +2012,18 @@ describe('workflowEntrypoint inline-delta gate with open hooks', () => { }), ]) ); + // The restart is in-process, so the run reaches its terminal event inside + // this same delivery — no re-invocation, and no run failure. + expect(eventsCreate.mock.calls).toContainEqual( + expect.arrayContaining([ + expect.objectContaining({ eventType: 'run_completed' }), + ]) + ); expect(eventsCreate.mock.calls).not.toContainEqual( expect.arrayContaining([ expect.objectContaining({ eventType: 'run_failed' }), ]) ); - // Outside turbo the re-invocation is a redelivery of the current message, - // not an explicit continuation enqueue. expect(queueMock).not.toHaveBeenCalled(); }); @@ -2028,10 +2033,10 @@ describe('workflowEntrypoint inline-delta gate with open hooks', () => { // Same interleaving as above, but with optimistic start enabled globally. // Without suppression, executeStep would begin step B's body immediately // (before the claim settles) and only discard the result after the 412 — - // the side effects would already have run. With an open hook and the - // guard in force, the runtime takes the await-then-run path instead, so - // the fence covers user code: the rejected claim means the body never - // begins. + // the side effects would already have run, and the restarted replay would + // run them a second time. With an open hook and the guard in force, the + // runtime takes the await-then-run path instead, so the fence covers user + // code: the body runs exactly once, after an accepted claim. const { res, eventsCreate } = await driveDeltaGate( 'wrun_delta_gate_stale_claim_optimistic', { @@ -2046,7 +2051,7 @@ describe('workflowEntrypoint inline-delta gate with open hooks', () => { } ); expect(res.status).toBe(204); - expect(deltaGateBodyRuns).toEqual([]); + expect(deltaGateBodyRuns).toEqual(['B']); expect(eventsCreate.mock.calls).not.toContainEqual( expect.arrayContaining([ expect.objectContaining({ eventType: 'run_failed' }), diff --git a/packages/core/src/runtime.ts b/packages/core/src/runtime.ts index 20094392fa..0c440ad826 100644 --- a/packages/core/src/runtime.ts +++ b/packages/core/src/runtime.ts @@ -41,6 +41,7 @@ import { ReplayPayloadCache } from './replay-payload-cache.js'; import { getMaxEventsOverride, getMaxQueueDeliveries, + getPreconditionMaxInProcessRestarts, getReplayDivergenceMaxRetries, isInlineOwnershipEnabled, isTurboEnabled, @@ -52,14 +53,14 @@ import { getWorkflowQueueName, handleHealthCheckMessage, isPreconditionGuardEnabled, + type LoadedEventLog, loadWorkflowRunEvents, - type MutableEventLog, memoizeEncryptionKey, parseHealthCheckPayload, + preconditionEventDelta, + preconditionSnapshotParams, queueMessage, - stateUpdatedAtForCreate, withHealthCheck, - withPreconditionRetry, } from './runtime/helpers.js'; import { handleReplayBudgetExhausted, @@ -531,7 +532,9 @@ export function workflowEntrypoint( // events.list round-trip. Each value is consumed exactly once // and then cleared. Null means "no delta pending — fetch // normally". See the consume site at the top of the loop and - // the produce site after inline executeStep. + // the produce sites: after inline executeStep, and in + // restartReplayInProcess when a stale-snapshot rejection + // carried the missing events with it. let pendingInlineDelta: { events: Event[]; cursor: string | null; @@ -565,7 +568,11 @@ export function workflowEntrypoint( let runStartedReceivedAtMs: number | undefined; // Wall-clock ms spent committing hook_created events before // the first step ran, accumulated across suspension passes - // and subtracted from TTFS. + // and subtracted from TTFS. Accumulators here survive an + // in-process replay restart (a stale-snapshot rejection, or + // the attribute-event restart below), so a restarted + // invocation over-counts by the abandoned pass's hook time — + // the same slight over-count either restart has always had. let preStepBlockingMs = 0; // Snapshot of the accumulator as of the suspension that // wrote the run's first attr_set (whose hook phase ran @@ -692,6 +699,83 @@ export function workflowEntrypoint( return undefined; }; + // Precondition (412) recovery: how many times this invocation + // has thrown away its replay and started over in-process. + let preconditionRestarts = 0; + /** + * Recover from a stale-snapshot rejection by restarting the + * replay inside this invocation, returning false when the + * per-invocation budget is spent (the caller then falls back + * to a fresh invocation). + * + * A 412 means the log this replay derived its events from was + * missing an event the backend had already recorded. The + * rejected write cannot simply be retried: correlation ids + * are positional ordinals of one seeded sequence, so a replay + * over the corrected log mints a different id for the same + * logical event, and re-posting this one would persist an + * event no correct replay ever produces. The whole replay has + * to be re-derived — which the loop does by discarding its + * cached log, since `runWorkflow` then builds a fresh VM, + * seed and correlation-id sequence from the reloaded events. + */ + const restartReplayInProcess = ( + reason: string, + error?: unknown + ): boolean => { + if ( + preconditionRestarts >= + getPreconditionMaxInProcessRestarts() + ) { + return false; + } + preconditionRestarts++; + // A World MAY return the events we were missing on the 412. + // Trust it only on the FIRST restart: its completeness proof + // leans on the backend's own bookkeeping, so if that + // under-counts, a "complete" delta can still leave a hole. + // Bounding it to one attempt caps that at a single wasted + // restart; every later restart does the authoritative load. + const delta = + preconditionRestarts === 1 + ? preconditionEventDelta(error) + : null; + if (delta && cachedEvents) { + // Consumed by the loop's first branch + // (`pendingInlineDelta && cachedEvents`) with no + // events.list round trip at all. + pendingInlineDelta = delta; + } else { + // MUST be a full, cursor-less reload. The cursor filters + // by lexicographic event id while a hole is defined by + // ULID *time*: an event in the same millisecond sorts + // either side of the cursor depending on its random + // component, and an event minted in an earlier + // millisecond but committed later always sorts below it. + // An incremental load therefore heals the hole only by + // luck. + cachedEvents = null; + eventsCursor = null; + preloadedEvents = undefined; + preloadedEventsCursor = undefined; + pendingInlineDelta = null; + } + runtimeLogger.warn( + 'Event creation rejected as stale; restarting replay in-process', + { + workflowRunId: runId, + reason, + loopIteration, + preconditionRestarts, + source: delta ? 'inline-delta' : 'full-reload', + } + ); + span?.setAttributes({ + 'workflow.precondition_restarts': preconditionRestarts, + }); + return true; + }; + // If incoming message has a stepId, this is a background step // execution. Execute the step, then check if all parallel steps // from the batch are done. If so, replay inline (saving a queue @@ -1323,6 +1407,15 @@ export function workflowEntrypoint( events = cachedEvents; } + // Publish the snapshot to the loop-scoped cache as soon + // as it is loaded, not just at the end of the iteration: + // a stale-snapshot rejection thrown by the wait-completion + // writes below restarts the replay, and that restart can + // only consume a World-attached event delta when there is + // a cached array to merge it into. Reassigned again after + // the wait pass, which may swap in a freshly loaded array. + cachedEvents = events; + // Detect concurrent completion via the event log: if // any other handler wrote a terminal run event, exit // before doing replay work. The run entity's status is @@ -1363,20 +1456,11 @@ export function workflowEntrypoint( })); for (const waitEvent of waitsToComplete) { - const waitLog: MutableEventLog = { - events, - cursor: eventsCursor, - }; try { - await withPreconditionRetry( - runId, - waitLog, - (stateUpdatedAt) => - world.events.create(runId, waitEvent, { - requestId, - stateUpdatedAt, - }) - ); + await world.events.create(runId, waitEvent, { + requestId, + ...preconditionSnapshotParams(events, eventsCursor), + }); } catch (err) { if (EntityConflictError.is(err)) { runtimeLogger.info( @@ -1389,9 +1473,6 @@ export function workflowEntrypoint( continue; } throw err; - } finally { - // Reloads inside the guard may have advanced the cursor. - eventsCursor = waitLog.cursor; } } @@ -1527,8 +1608,7 @@ export function workflowEntrypoint( // computed by this replay, so a stale (412) rejection must // force a *fresh replay* (which may observe the new event // and produce a different result), not re-commit the stale - // result. The catch below lets PreconditionFailedError - // propagate to the queue for re-invocation. + // result. The catch below restarts the replay in-process. try { // Turbo: a workflow that finishes with no steps reaches // here before the backgrounded run_started; order the @@ -1543,7 +1623,7 @@ export function workflowEntrypoint( }, { requestId, - stateUpdatedAt: stateUpdatedAtForCreate(events), + ...preconditionSnapshotParams(events, eventsCursor), } ); } catch (err) { @@ -1612,10 +1692,11 @@ export function workflowEntrypoint( // V2: handle suspension without queuing steps. // Each event creation inside handleSuspension carries the - // loaded snapshot's stateUpdatedAt and self-reloads on a - // stale (412) rejection via the shared event log. We - // guard per-create (rather than wrapping the whole call) - // so a retry never re-issues an already-created event. + // precondition snapshot of the loaded event log, so a + // backend holding an event this replay never saw rejects + // the write (412) instead of accepting a divergent one. + // The rejection is handled here, by restarting the + // replay — never by re-posting the same event. const suspensionStart = Date.now(); // The snapshot refresh above always sets cachedEvents // before the replay can suspend. Re-narrow it for this @@ -1628,7 +1709,7 @@ export function workflowEntrypoint( 'Invariant violation: workflow suspended before its event log was loaded' ); } - const suspensionLog: MutableEventLog = { + const suspensionLog: LoadedEventLog = { events: cachedEvents, cursor: eventsCursor, }; @@ -1646,15 +1727,24 @@ export function workflowEntrypoint( runReadyBarrier, }); } catch (suspensionError) { - // A suspension create whose stale (412) rejection - // survived the in-guard reload retries: schedule an + // A suspension create was rejected as stale: re-derive + // the replay from a corrected log in this invocation. + // Once the in-process budget is spent, fall back to an // explicit immediate re-invocation (a rethrow relies // on redelivery of a message the turbo path already // acked — the run would stall for the queue's ~300s // default visibility timeout). if (PreconditionFailedError.is(suspensionError)) { + if ( + restartReplayInProcess( + 'suspension-create', + suspensionError + ) + ) { + continue; + } runtimeLogger.warn( - 'Suspension event creation rejected as stale after reload retries; re-invoking run for a fresh replay', + 'Suspension event creation rejected as stale after in-process restarts; re-invoking run for a fresh replay', { workflowRunId: runId, loopIteration } ); return await reinvoke(0); @@ -2256,12 +2346,15 @@ export function workflowEntrypoint( // is deferred), so without a snapshot it would bypass // the guard entirely and a stale replay could claim — // and commit — a step scheduled off a view that misses - // an out-of-band event. `stateUpdatedAtForCreate` - // returns undefined when the guard env flag is off, so - // this is a no-op outside guarded deployments; Worlds - // that don't enforce the guard ignore it. - const inlineClaimStateUpdatedAt = - stateUpdatedAtForCreate(cachedEvents ?? []); + // an event it never loaded. + // `preconditionSnapshotParams` returns an empty object + // when the guard env flag is off, so this is a no-op + // outside guarded deployments; Worlds that don't + // enforce the guard ignore it. + const inlineClaimSnapshot = preconditionSnapshotParams( + cachedEvents ?? [], + preInlineWriteCursor + ); replayBudget.pause(); let stepResults: Awaited< @@ -2340,7 +2433,7 @@ export function workflowEntrypoint( // see suppressOptimisticStart above. suppressOptimisticStart, runReadyBarrier, - stateUpdatedAt: inlineClaimStateUpdatedAt, + preconditionSnapshot: inlineClaimSnapshot, ...(stepIndex === 0 && s.lazyStepInput !== undefined && latencyTracking @@ -2383,18 +2476,25 @@ export function workflowEntrypoint( } catch (stepErr) { // A stale (412) rejection of an inline step_started // claim: the loaded view this batch was scheduled - // from is behind an out-of-band event (e.g. a - // received hook), so the claim was fenced by the - // guard and no step events were written. Abandon the - // batch — any optimistic body result is discarded by - // executeStep's reconciliation — and re-invoke for a - // fresh replay that observes the new event. Wait for - // the sibling executions to settle first so no owned - // body is in flight when the ack path runs. + // from is missing an event the backend already has, + // so the claim was fenced by the guard and no step + // events were written. Abandon the batch — any + // optimistic body result is discarded by executeStep's + // reconciliation — and restart the replay so it + // observes the missing event. Wait for the sibling + // executions to settle first so no owned body is in + // flight when the restart (or the ack path) runs. if (PreconditionFailedError.is(stepErr)) { await Promise.allSettled(stepExecutionPromises); + if ( + restartReplayInProcess('inline-claim', stepErr) + ) { + // The finally below resumes the replay budget + // before the next iteration starts. + continue; + } runtimeLogger.warn( - 'Inline step claim rejected as stale; re-invoking run for a fresh replay', + 'Inline step claim rejected as stale after in-process restarts; re-invoking run for a fresh replay', { workflowRunId: runId, loopIteration } ); // The finally below resumes the replay budget @@ -2586,18 +2686,23 @@ export function workflowEntrypoint( } } else { // Stale-snapshot rejection of a result-bearing create - // (run_completed sends the snapshot but is intentionally - // NOT retried in place), or one that survived the - // in-guard reload retries. Don't fail the run — schedule - // an explicit immediate re-invocation so a fresh replay - // observes the new event. Rethrowing instead would rely - // on redelivery of the CURRENT message, which the turbo - // path has already acked — empirically the run then - // stalls for the queue's ~300s default visibility - // timeout before completing. + // (run_completed carries the snapshot and is never + // re-posted in place: the result was computed by this + // replay, and a corrected log may produce a different + // one). Don't fail the run — restart the replay in this + // invocation, and only once that budget is spent + // schedule an explicit immediate re-invocation. + // Rethrowing instead would rely on redelivery of the + // CURRENT message, which the turbo path has already + // acked — empirically the run then stalls for the + // queue's ~300s default visibility timeout before + // completing. if (PreconditionFailedError.is(err)) { + if (restartReplayInProcess('result-create', err)) { + continue; + } runtimeLogger.warn( - 'Event creation rejected as stale; re-invoking run for a fresh replay', + 'Event creation rejected as stale after in-process restarts; re-invoking run for a fresh replay', { workflowRunId: runId, loopIteration } ); return await reinvoke(0); diff --git a/packages/core/src/runtime/constants.ts b/packages/core/src/runtime/constants.ts index 619c50f890..60489e7520 100644 --- a/packages/core/src/runtime/constants.ts +++ b/packages/core/src/runtime/constants.ts @@ -388,3 +388,23 @@ export function getReplayDivergenceMaxRetries(): number { { integer: true } ); } + +// A stale-snapshot rejection (412) means the replay's event log was missing an +// event the World had already recorded, so the replay is re-derived from a +// corrected log inside the same invocation. Bounded because a persistently +// rejected write should escalate rather than spin: after this many restarts the +// run is re-invoked (a new invocation, possibly in a different region), and from +// there the queue's delivery limit applies. +export const PRECONDITION_MAX_INPROCESS_RESTARTS = 3; + +/** + * Effective in-process replay-restart budget for stale-snapshot rejections. + * Override via `WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS`. + */ +export function getPreconditionMaxInProcessRestarts(): number { + return envNumber( + 'WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS', + PRECONDITION_MAX_INPROCESS_RESTARTS, + { integer: true } + ); +} diff --git a/packages/core/src/runtime/helpers.test.ts b/packages/core/src/runtime/helpers.test.ts index c6b2927160..31659deb1c 100644 --- a/packages/core/src/runtime/helpers.test.ts +++ b/packages/core/src/runtime/helpers.test.ts @@ -11,14 +11,15 @@ import { SerializationFormat, } from '../serialization.js'; import { + appendUniqueEvents, getWorkflowQueueName, handleHealthCheckMessage, healthCheck, latestEventStateUpdatedAt, loadWorkflowRunEvents, memoizeEncryptionKey, - type MutableEventLog, - withPreconditionRetry, + preconditionEventDelta, + preconditionSnapshotParams, } from './helpers.js'; // Mock the logger to suppress output during tests @@ -503,11 +504,10 @@ describe('latestEventStateUpdatedAt', () => { }); }); -describe('withPreconditionRetry', () => { +describe('preconditionSnapshotParams', () => { let originalGuard: string | undefined; beforeEach(() => { - eventsListMock.mockReset(); originalGuard = process.env.WORKFLOW_PRECONDITION_GUARD; process.env.WORKFLOW_PRECONDITION_GUARD = '1'; }); @@ -520,132 +520,180 @@ describe('withPreconditionRetry', () => { } }); - it('passes no snapshot to op when the guard is explicitly disabled', async () => { - process.env.WORKFLOW_PRECONDITION_GUARD = '0'; - const log: MutableEventLog = { - events: [makeUlidEvent(1_700_000_000_000)], - cursor: 'c0', - }; - const op = vi.fn(async (stateUpdatedAt?: number) => { - expect(stateUpdatedAt).toBeUndefined(); - return 'ok'; + it('sends the watermark, the count and the cursor together', () => { + const time = 1_700_000_000_000; + const events = [makeUlidEvent(time - 1000), makeUlidEvent(time)]; + + expect(preconditionSnapshotParams(events, 'eid:abc')).toEqual({ + stateUpdatedAt: time, + stateEventCount: events.length, + stateCursor: 'eid:abc', }); + }); - await expect(withPreconditionRetry('wrun_test', log, op)).resolves.toBe( - 'ok' - ); - expect(op).toHaveBeenCalledTimes(1); - expect(eventsListMock).not.toHaveBeenCalled(); + it('sends the count without a cursor when the caller has none', () => { + const time = 1_700_000_000_000; + + expect(preconditionSnapshotParams([makeUlidEvent(time)], null)).toEqual({ + stateUpdatedAt: time, + stateEventCount: 1, + }); }); - it('sends a snapshot by default when the guard variable is unset (on by default)', async () => { + it('sends the snapshot by default (guard is on unless disabled)', () => { delete process.env.WORKFLOW_PRECONDITION_GUARD; const time = 1_700_000_000_000; - const log: MutableEventLog = { - events: [makeUlidEvent(time)], - cursor: 'c0', - }; - const op = vi.fn(async (stateUpdatedAt?: number) => { - expect(stateUpdatedAt).toBe(time); - return 'ok'; + + expect( + preconditionSnapshotParams([makeUlidEvent(time)], 'eid:abc') + ).toEqual({ + stateUpdatedAt: time, + stateEventCount: 1, + stateCursor: 'eid:abc', }); + }); + + it('omits every field when the guard is disabled', () => { + process.env.WORKFLOW_PRECONDITION_GUARD = '0'; + + expect( + preconditionSnapshotParams([makeUlidEvent(1_700_000_000_000)], 'eid:abc') + ).toEqual({}); + }); + + it('omits every field on an empty log', () => { + expect(preconditionSnapshotParams([], 'eid:abc')).toEqual({}); + }); + + it('omits every field when the latest event id is not a decodable ULID', () => { + // A count without a watermark would be meaningless to the backend, so the + // three fields have to fail open together. + expect( + preconditionSnapshotParams([makeEvent('evnt_not-a-ulid')], 'eid:abc') + ).toEqual({}); + }); +}); - await expect(withPreconditionRetry('wrun_test', log, op)).resolves.toBe( - 'ok' +describe('appendUniqueEvents', () => { + it('appends in order without reordering and without warning', async () => { + const { runtimeLogger } = await import('../logger.js'); + vi.mocked(runtimeLogger.warn).mockClear(); + const first = makeUlidEvent(1_700_000_000_000); + const second = makeUlidEvent(1_700_000_001_000); + const third = makeUlidEvent(1_700_000_002_000); + const target = [first]; + + appendUniqueEvents(target, [second, third]); + + expect(target.map((e) => e.eventId)).toEqual([ + first.eventId, + second.eventId, + third.eventId, + ]); + expect(runtimeLogger.warn).not.toHaveBeenCalled(); + }); + + it('re-sorts to canonical order and warns when an append lands out of order', async () => { + const { runtimeLogger } = await import('../logger.js'); + vi.mocked(runtimeLogger.warn).mockClear(); + const older = makeUlidEvent(1_700_000_000_000); + const newer = makeUlidEvent(1_700_000_002_000); + const middle = makeUlidEvent(1_700_000_001_000); + const target = [older, newer]; + + appendUniqueEvents(target, [middle]); + + expect(target.map((e) => e.eventId)).toEqual([ + older.eventId, + middle.eventId, + newer.eventId, + ]); + expect(runtimeLogger.warn).toHaveBeenCalledWith( + 'Event log merged out of order; re-sorted by eventId', + expect.objectContaining({ eventCount: 3 }) ); - expect(op).toHaveBeenCalledTimes(1); }); - it('passes the latest snapshot time to op and returns its result without reloading', async () => { + it('deduplicates by event id', () => { + const first = makeUlidEvent(1_700_000_000_000); + const second = makeUlidEvent(1_700_000_001_000); + const target = [first]; + + appendUniqueEvents(target, [first, second, second]); + + expect(target.map((e) => e.eventId)).toEqual([ + first.eventId, + second.eventId, + ]); + }); + + it('orders a same-millisecond pair by its random component', () => { + // Event ids are unprefixed 26-char ULIDs, so lexicographic id order is + // canonical backend order even inside one millisecond — which is what + // makes re-sorting safe. const time = 1_700_000_000_000; - const log: MutableEventLog = { - events: [makeUlidEvent(time)], - cursor: 'c0', - }; - const op = vi.fn(async (stateUpdatedAt?: number) => { - expect(stateUpdatedAt).toBe(time); - return 'ok'; - }); + const a = makeEvent(`evnt_${ulid(time).slice(0, 10)}AAAAAAAAAAAAAAAA`); + const b = makeEvent(`evnt_${ulid(time).slice(0, 10)}ZZZZZZZZZZZZZZZZ`); + const target = [b]; - await expect(withPreconditionRetry('wrun_test', log, op)).resolves.toBe( - 'ok' - ); - expect(op).toHaveBeenCalledTimes(1); - expect(eventsListMock).not.toHaveBeenCalled(); + appendUniqueEvents(target, [a]); + + expect(target.map((e) => e.eventId)).toEqual([a.eventId, b.eventId]); }); - it('reloads the event log and retries on a stale (412) rejection, then succeeds', async () => { - const log: MutableEventLog = { - events: [makeUlidEvent(1_700_000_000_000)], - cursor: 'c0', - }; - // Each reload returns one newer event and advances the cursor. - eventsListMock.mockResolvedValueOnce({ - data: [makeUlidEvent(1_700_000_001_000)], - cursor: 'c1', - hasMore: false, - }); - eventsListMock.mockResolvedValueOnce({ - data: [makeUlidEvent(1_700_000_002_000)], - cursor: 'c2', - hasMore: false, - }); + it('reports the maximum ULID time as the watermark after an out-of-order merge', () => { + // The direct link between the sort and the snapshot's correctness: the + // watermark is read off the tail, so an unsorted tail would understate it + // while the count still covered every loaded event. + const time = 1_700_000_002_000; + const target = [makeUlidEvent(1_700_000_000_000), makeUlidEvent(time)]; - let calls = 0; - const op = vi.fn(async () => { - calls++; - if (calls <= 2) { - throw new PreconditionFailedError('stale'); - } - return 'done'; - }); + appendUniqueEvents(target, [makeUlidEvent(1_700_000_001_000)]); - await expect(withPreconditionRetry('wrun_test', log, op)).resolves.toBe( - 'done' - ); - expect(op).toHaveBeenCalledTimes(3); - // Two reloads merged their events into the shared log and advanced cursor. - expect(log.events).toHaveLength(3); - expect(log.cursor).toBe('c2'); + expect(latestEventStateUpdatedAt(target)).toBe(time); }); +}); - it('rethrows the precondition error after exhausting reload retries', async () => { - const log: MutableEventLog = { - events: [makeUlidEvent(1_700_000_000_000)], - cursor: 'c0', - }; - eventsListMock.mockResolvedValue({ - data: [], - cursor: 'c1', - hasMore: false, - }); +describe('preconditionEventDelta', () => { + const delta = (details: unknown) => + preconditionEventDelta(new PreconditionFailedError('stale', { details })); - const op = vi.fn(async () => { - throw new PreconditionFailedError('always stale'); - }); + it('returns the decoded events and cursor a World attached to the 412', () => { + const event = makeUlidEvent(1_700_000_000_000); - await expect( - withPreconditionRetry('wrun_test', log, op) - ).rejects.toBeInstanceOf(PreconditionFailedError); - // attempts 0,1,2 — two reloads between them, then rethrow on the third. - expect(op).toHaveBeenCalledTimes(3); - expect(eventsListMock).toHaveBeenCalledTimes(2); + expect(delta({ events: [event], cursor: 'eid:next' })).toEqual({ + events: [event], + cursor: 'eid:next', + }); }); - it('rethrows non-precondition errors immediately without reloading', async () => { - const log: MutableEventLog = { - events: [makeUlidEvent(1_700_000_000_000)], - cursor: 'c0', - }; - const op = vi.fn(async () => { - throw new Error('boom'); + it('returns a null cursor when the World sent events without one', () => { + const event = makeUlidEvent(1_700_000_000_000); + + expect(delta({ events: [event] })).toEqual({ + events: [event], + cursor: null, }); + }); - await expect(withPreconditionRetry('wrun_test', log, op)).rejects.toThrow( - 'boom' + it('returns null when the World attached no details at all', () => { + expect(preconditionEventDelta(new PreconditionFailedError('stale'))).toBe( + null ); - expect(op).toHaveBeenCalledTimes(1); - expect(eventsListMock).not.toHaveBeenCalled(); + }); + + it('returns null for a non-precondition error', () => { + expect(preconditionEventDelta(new Error('boom'))).toBe(null); + }); + + it('returns null for an empty or malformed events payload', () => { + // Nothing here is repaired: a full reload is always correct, so anything + // that does not narrow cleanly falls back to it. + expect(delta({ events: [] })).toBe(null); + expect(delta({ events: 'not-an-array' })).toBe(null); + expect(delta({ events: [{ noEventId: true }] })).toBe(null); + expect(delta({ events: [null] })).toBe(null); + expect(delta('not-an-object')).toBe(null); }); }); diff --git a/packages/core/src/runtime/helpers.ts b/packages/core/src/runtime/helpers.ts index 8664548658..b95608ccba 100644 --- a/packages/core/src/runtime/helpers.ts +++ b/packages/core/src/runtime/helpers.ts @@ -458,10 +458,24 @@ function recordRequestedEventCursor( } /** - * Appends events whose IDs are not already present in `target`. + * Appends events whose IDs are not already present in `target`, keeping + * `target` sorted by event id. * * Pass the IDs currently present in `target` when appending repeatedly to the * same array. The set is updated alongside `target`. + * + * Sort order matters beyond tidiness: the runtime treats the last element as + * the newest event (it is the precondition snapshot's watermark, see + * {@link latestEventStateUpdatedAt}) and the replay consumes the log as an + * ordered sequence. Event ids are unprefixed 26-character ULIDs, so + * lexicographic id order *is* canonical backend order, including within a + * single millisecond — re-sorting reproduces exactly the order a fresh ordered + * load would return. + * + * Every append source should already be strictly above the tail (a + * cursor-delimited page, or a write-response delta). The re-sort is therefore + * defence in depth, and the warning is the point: it turns "this can't happen" + * into a signal. Cost in the normal case is one string comparison per event. */ export function appendUniqueEvents( target: Event[], @@ -473,11 +487,23 @@ export function appendUniqueEvents( } const ids = targetIds ?? new Set(target.map((event) => event.eventId)); + let outOfOrder = false; for (const event of events) { - if (!ids.has(event.eventId)) { - ids.add(event.eventId); - target.push(event); + if (ids.has(event.eventId)) { + continue; + } + ids.add(event.eventId); + const tail = target[target.length - 1]; + if (tail && event.eventId < tail.eventId) { + outOfOrder = true; } + target.push(event); + } + if (outOfOrder) { + target.sort((a, b) => (a.eventId < b.eventId ? -1 : 1)); + runtimeLogger.warn('Event log merged out of order; re-sorted by eventId', { + eventCount: target.length, + }); } } @@ -635,19 +661,11 @@ export async function loadWorkflowRunEvents( } /** - * Maximum number of times a replay-context event creation will reload the - * event log and retry after the backend rejects it as stale (412). After this - * many failed reloads the precondition error propagates so the run is - * re-invoked from the queue with a fresh replay. + * The runtime's loaded event-log snapshot: the events replayed so far and the + * cursor positioned after them. Handed to helpers that derive the precondition + * snapshot from it; they do not mutate it. */ -export const PRECONDITION_MAX_RELOAD_RETRIES = 2; - -/** - * A mutable view of the runtime's in-memory event log. `withPreconditionRetry` - * appends freshly-loaded events to `events` (in place) and advances `cursor` - * when it reloads, so the caller's loaded snapshot stays current. - */ -export interface MutableEventLog { +export interface LoadedEventLog { events: Event[]; cursor: string | null; } @@ -666,15 +684,18 @@ export function isPreconditionGuardEnabled(): boolean { /** * The `stateUpdatedAt` value to send with a replay-context event creation: the - * ULID time (epoch ms) of the latest event the runtime has loaded. Events are - * stored in ascending order, so the last one is the newest. Returns `undefined` - * when there are no events or the latest id is not a decodable ULID. + * ULID time (epoch ms) of the latest event the runtime has loaded. The log is + * kept sorted by event id (see {@link appendUniqueEvents}), so its tail *is* + * its maximum ULID time — which is what lets the count sent alongside it be + * read as "events at or below this watermark". Returns `undefined` when there + * are no events or the latest id is not a decodable ULID. * * Granularity: snapshots are epoch-milliseconds, and the backend allows an * equal-timestamp snapshot (an up-to-date client must not be rejected). Two * out-of-band events landing in the same millisecond where only the first was - * loaded therefore pass the guard undetected — the guard is best-effort by - * design, and fails open rather than livelocking. + * loaded therefore pass this half of the guard undetected — that is exactly + * the hole `stateEventCount` closes, since the count of events at or below the + * watermark differs even when the watermarks are equal. */ export function latestEventStateUpdatedAt(events: Event[]): number | undefined { const last = events[events.length - 1]; @@ -700,66 +721,85 @@ export function latestEventStateUpdatedAt(events: Event[]): number | undefined { } /** - * The `stateUpdatedAt` to attach to a replay-context event creation: - * the loaded snapshot's ULID time when the precondition guard is enabled, - * `undefined` (no guard, backend behaves as before) otherwise. + * The precondition snapshot a replay-context event creation sends, describing + * the event log the replay derived the event from. + * + * The three fields are one indivisible unit: the backend reads the count only + * relative to the watermark, and returns its inline delta only relative to the + * cursor. Passing them as a single object is what keeps them from drifting + * apart at a call site. */ -export function stateUpdatedAtForCreate(events: Event[]): number | undefined { - return isPreconditionGuardEnabled() - ? latestEventStateUpdatedAt(events) - : undefined; +export interface PreconditionSnapshotParams { + stateUpdatedAt?: number; + stateEventCount?: number; + stateCursor?: string; } /** - * Runs a replay-context event creation with the optimistic-concurrency guard. + * Build the precondition snapshot to attach to a replay-context event creation. + * + * Returns an empty object — no guard, backend behaves as before — when the + * guard is disabled or the watermark is not derivable. All three fields fail + * open together: a count without a watermark is meaningless to the backend, and + * a cursor without either would invite a delta nobody asked for. * - * `op` receives the current `stateUpdatedAt` (the ULID time of the latest - * loaded event) to pass to `world.events.create`. If the backend rejects the - * creation as stale (`PreconditionFailedError` / 412), the event log is - * reloaded to completion from the last cursor, merged into `log` in place, and - * `op` is retried with the now-newer snapshot — up to - * `PRECONDITION_MAX_RELOAD_RETRIES` times. If it still fails, the error is - * rethrown so the run falls back to a queue re-invocation. Non-precondition - * errors are rethrown immediately. + * `stateEventCount` is `events.length` because the watermark is the log's + * *maximum* ULID time, so every loaded event is at or below it. */ -export async function withPreconditionRetry( - runId: string, - log: MutableEventLog, - op: (stateUpdatedAt: number | undefined) => Promise -): Promise { - for (let attempt = 0; ; attempt++) { - try { - return await op(stateUpdatedAtForCreate(log.events)); - } catch (error) { - if ( - !PreconditionFailedError.is(error) || - attempt >= PRECONDITION_MAX_RELOAD_RETRIES - ) { - throw error; - } - runtimeLogger.info( - 'Event creation rejected as stale; reloading event log and retrying', - { - workflowRunId: runId, - attempt: attempt + 1, - maxRetries: PRECONDITION_MAX_RELOAD_RETRIES, - } - ); - const loaded = await loadWorkflowRunEvents( - runId, - log.cursor ?? undefined - ); - appendUniqueEvents(log.events, loaded.events); - // When several creates share one `log` (e.g. hook creations under - // `Promise.all` in `handleSuspension`), concurrent 412s can reload - // concurrently. The event merge above is safe — `appendUniqueEvents` - // builds its dedup set synchronously right before appending — but this - // cursor write is last-write-wins, so an interleaved older reload can - // briefly regress the cursor. The only consequence is refetching a few - // already-deduped events on a later load; correctness is unaffected. - log.cursor = loaded.cursor ?? log.cursor; +export function preconditionSnapshotParams( + events: Event[], + cursor?: string | null +): PreconditionSnapshotParams { + if (!isPreconditionGuardEnabled()) { + return {}; + } + const stateUpdatedAt = latestEventStateUpdatedAt(events); + if (stateUpdatedAt === undefined) { + return {}; + } + return { + stateUpdatedAt, + stateEventCount: events.length, + ...(cursor ? { stateCursor: cursor } : {}), + }; +} + +/** + * The events a rejecting World attached to a `PreconditionFailedError`, when it + * returned the ones the client's snapshot was missing inline. + * + * Returns `null` for anything else — no details, a World that did not implement + * this, or a payload that does not narrow cleanly. Callers fall back to + * reloading the event log, which is always correct; this is untrusted-shaped + * data on a failure path, so nothing here is repaired. + */ +export function preconditionEventDelta( + error: unknown +): { events: Event[]; cursor: string | null } | null { + if (!PreconditionFailedError.is(error)) { + return null; + } + const details = error.details; + if (typeof details !== 'object' || details === null) { + return null; + } + const { events, cursor } = details as { events?: unknown; cursor?: unknown }; + if (!Array.isArray(events) || events.length === 0) { + return null; + } + for (const event of events) { + if ( + typeof event !== 'object' || + event === null || + typeof (event as { eventId?: unknown }).eventId !== 'string' + ) { + return null; } } + return { + events: events as Event[], + cursor: typeof cursor === 'string' ? cursor : null, + }; } /** diff --git a/packages/core/src/runtime/precondition-guard-replay.test.ts b/packages/core/src/runtime/precondition-guard-replay.test.ts index 63fdfc0bed..714079853c 100644 --- a/packages/core/src/runtime/precondition-guard-replay.test.ts +++ b/packages/core/src/runtime/precondition-guard-replay.test.ts @@ -1,14 +1,18 @@ /** * Drives the real workflowEntrypoint replay loop (not just the helpers) to - * validate the stateUpdatedAt precondition guard end to end on the client: + * validate the precondition guard end to end on the client: * - * 1. A wait_completed create is rejected as stale (412) because a hook landed - * out-of-band after the snapshot. The runtime must reload the event log - * from its cursor, retry the create with the *newer* stateUpdatedAt, and - * the replay must then observe the hook branch. - * 2. A run_completed create rejected as stale must NOT be retried in place - * (the stale result must not be re-committed) — the error propagates to - * the queue handler and the run is not failed. + * 1. A create rejected as stale (412) because another writer landed an event + * after the snapshot must restart the replay *in this invocation* — never + * re-post the rejected payload. The payload's correlation ids were minted + * by the rejected replay's seeded ULID sequence, so a corrected event log + * generally implies different ids; only a fresh replay may write again. + * 2. The restart reloads the whole event log with no cursor, because a hole is + * defined by ULID time while a cursor filters lexicographically — unless + * the World attached the missing events to the 412, which the runtime + * consumes with no events.list round trip at all (first restart only). + * 3. Restarts are bounded; once the bound is spent the runtime schedules one + * immediate re-invocation instead of failing the run. * * Modeled on wait-completion-replay.test.ts, but with real ULID event IDs so * latestEventStateUpdatedAt() actually derives snapshot times. @@ -31,6 +35,7 @@ import { dehydrateWorkflowArguments, } from '../serialization.js'; import { createContext } from '../vm/index.js'; +import { getPreconditionMaxInProcessRestarts } from './constants.js'; import { setWorld } from './world.js'; vi.mock('@vercel/functions', () => ({ @@ -71,9 +76,21 @@ function buildStepEntity( }; } +interface SnapshotParams { + eventType: string; + stateUpdatedAt: number | undefined; + stateEventCount: number | undefined; + stateCursor: string | undefined; +} + async function runPreconditionScenario(options: { - /** Reject the first wait_completed create with 412 (hook landed). */ - rejectWaitCompletedOnce?: boolean; + /** How many wait_completed creates to reject with 412 (hook landed). */ + rejectWaitCompletedTimes?: number; + /** + * What a rejecting World attaches to the 412: the missing event (`complete`), + * or a payload the runtime must refuse to narrow (`malformed`). + */ + attachDelta?: 'complete' | 'malformed'; }) { vi.spyOn(Date, 'now').mockReturnValue(+fixedNow); @@ -193,10 +210,7 @@ async function runPreconditionScenario(options: { const durableEvents = [...staleEvents]; const createdEvents: Event[] = []; - const createParams: Array<{ - eventType: string; - stateUpdatedAt: number | undefined; - }> = []; + const createParams: SnapshotParams[] = []; let waitCompletedRejections = 0; let capturedHandler: | (( @@ -237,11 +251,17 @@ async function runPreconditionScenario(options: { async ( _runId: string, request: CreateEventRequest, - params?: { stateUpdatedAt?: number } + params?: { + stateUpdatedAt?: number; + stateEventCount?: number; + stateCursor?: string; + } ) => { createParams.push({ eventType: request.eventType, stateUpdatedAt: params?.stateUpdatedAt, + stateEventCount: params?.stateEventCount, + stateCursor: params?.stateCursor, }); if (request.eventType === 'run_started') { @@ -254,14 +274,18 @@ async function runPreconditionScenario(options: { if (!durableEvents.includes(hookReceivedEvent)) { durableEvents.push(hookReceivedEvent); } - if ( - options.rejectWaitCompletedOnce && - waitCompletedRejections === 0 && - (params?.stateUpdatedAt ?? 0) < OUTSIDE_EVENT_MS - ) { + if (waitCompletedRejections < (options.rejectWaitCompletedTimes ?? 0)) { waitCompletedRejections++; throw new PreconditionFailedError( - 'Run state is stale: an out-of-band event was recorded after the client snapshot.' + 'Run state is stale: the client event log is missing at least one event at or before its snapshot.', + options.attachDelta === undefined + ? undefined + : { + details: + options.attachDelta === 'complete' + ? { events: [hookReceivedEvent], cursor: 'cursor-412' } + : { events: [{ notAnEvent: true }] }, + } ); } } @@ -442,10 +466,7 @@ async function runCompletedRejectionScenario() { ]; const staleEventsCursor = 'cursor-after-stale-events'; - const createParams: Array<{ - eventType: string; - stateUpdatedAt: number | undefined; - }> = []; + const createParams: SnapshotParams[] = []; let capturedHandler: | (( message: unknown, @@ -463,11 +484,17 @@ async function runCompletedRejectionScenario() { async ( _runId: string, request: CreateEventRequest, - params?: { stateUpdatedAt?: number } + params?: { + stateUpdatedAt?: number; + stateEventCount?: number; + stateCursor?: string; + } ) => { createParams.push({ eventType: request.eventType, stateUpdatedAt: params?.stateUpdatedAt, + stateEventCount: params?.stateEventCount, + stateCursor: params?.stateCursor, }); if (request.eventType === 'run_started') { return { @@ -526,36 +553,185 @@ async function runCompletedRejectionScenario() { return { handlerInvocation, createParams, + listEvents, + staleEventCount: staleEvents.length, + staleEventsCursor, runStartedSnapshotMs: +startedAt + 200, }; } +/** + * Minimal scenario for the attribute path: a workflow that sets an attribute + * and returns. The attr_set a suspension writes is guarded like every other + * replay-origin write, so it must carry the snapshot. + */ +async function attributeSnapshotScenario() { + vi.spyOn(Date, 'now').mockReturnValue(+fixedNow); + + const runId = 'wrun_precondition_attr_set'; + const workflowName = 'workflow'; + const deploymentId = 'dpl_precondition_attr_set'; + const startedAt = new Date('2026-05-19T12:00:00.000Z'); + const workflowArgs = await dehydrateWorkflowArguments([], runId, undefined); + + const workflowRun: WorkflowRun = { + runId, + workflowName, + status: 'running', + input: workflowArgs, + deploymentId, + specVersion: SPEC_VERSION_CURRENT, + startedAt, + createdAt: startedAt, + updatedAt: startedAt, + }; + + const hostUlid = monotonicFactory(); + let eventIndex = 0; + const durableEvents: Event[] = []; + const event = (data: CreateEventRequest): Event => + ({ + ...data, + specVersion: data.specVersion ?? SPEC_VERSION_CURRENT, + runId, + eventId: `evnt_${hostUlid(+startedAt + ++eventIndex * 100)}`, + createdAt: new Date(+startedAt + eventIndex * 100), + }) as Event; + + durableEvents.push( + event({ + eventType: 'run_created', + specVersion: SPEC_VERSION_CURRENT, + eventData: { deploymentId, workflowName, input: workflowArgs }, + }), + event({ eventType: 'run_started', specVersion: SPEC_VERSION_CURRENT }) + ); + const preloadedCursor = 'cursor-after-run-started'; + + const createParams: SnapshotParams[] = []; + let capturedHandler: + | (( + message: unknown, + metadata: { queueName: string; messageId: string; attempt: number } + ) => Promise) + | undefined; + + const createEvent = vi.fn( + async ( + _runId: string, + request: CreateEventRequest, + params?: { + stateUpdatedAt?: number; + stateEventCount?: number; + stateCursor?: string; + } + ) => { + createParams.push({ + eventType: request.eventType, + stateUpdatedAt: params?.stateUpdatedAt, + stateEventCount: params?.stateEventCount, + stateCursor: params?.stateCursor, + }); + if (request.eventType === 'run_started') { + return { + run: workflowRun, + events: [...durableEvents], + cursor: preloadedCursor, + hasMore: false, + }; + } + const created = event(request); + durableEvents.push(created); + return { event: created }; + } + ); + + const fakeWorld = { + specVersion: SPEC_VERSION_CURRENT, + createQueueHandler: vi.fn((_prefix, handler) => { + capturedHandler = handler; + return vi.fn(); + }), + events: { + list: vi.fn(async () => ({ + data: [...durableEvents], + hasMore: false, + cursor: preloadedCursor, + })), + create: createEvent, + }, + queue: vi.fn().mockResolvedValue({ messageId: 'msg_step' }), + getEncryptionKeyForRun: vi.fn().mockResolvedValue(undefined), + } as unknown as World; + + setWorld(fakeWorld); + + const workflowCode = ` + const setAttributes = globalThis[Symbol.for("WORKFLOW_SET_ATTRIBUTES")]; + + async function workflow() { + await setAttributes([{ key: "tenant", value: "acme" }]); + return "done"; + } + + ${getWorkflowTransformCode(workflowName)} + `; + + const handler = workflowEntrypoint(workflowCode); + await handler(new Request('http://localhost', { method: 'POST' })); + expect(capturedHandler).toBeDefined(); + + await capturedHandler?.( + { runId }, + { + queueName: `__wkf_workflow_${workflowName}`, + messageId: 'msg_workflow', + attempt: 1, + } + ); + + return { createParams, preloadedCursor }; +} + describe('precondition guard through the real replay loop', () => { let originalGuard: string | undefined; + let originalRestartBound: string | undefined; beforeEach(() => { originalGuard = process.env.WORKFLOW_PRECONDITION_GUARD; - // The guard is opt-in; these scenarios exercise the opted-in path. + originalRestartBound = + process.env.WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS; process.env.WORKFLOW_PRECONDITION_GUARD = '1'; }); afterEach(() => { - if (originalGuard !== undefined) { - process.env.WORKFLOW_PRECONDITION_GUARD = originalGuard; - } else { - delete process.env.WORKFLOW_PRECONDITION_GUARD; + for (const [name, value] of [ + ['WORKFLOW_PRECONDITION_GUARD', originalGuard], + ['WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS', originalRestartBound], + ] as const) { + if (value !== undefined) { + process.env[name] = value; + } else { + delete process.env[name]; + } } setWorld(undefined); vi.restoreAllMocks(); }); - it('reloads and retries a 412-rejected wait_completed with the newer snapshot, then takes the hook branch', async () => { + /** Only a restart reloads with no cursor; every other load is incremental. */ + const cursorlessLoads = (listEvents: { mock: { calls: unknown[][] } }) => + listEvents.mock.calls.filter( + (call) => + !(call[0] as { pagination?: { cursor?: string } }).pagination?.cursor + ).length; + + it('restarts the replay in-process on a 412, reloading the whole log with no cursor, and then takes the hook branch', async () => { const result = await runPreconditionScenario({ - rejectWaitCompletedOnce: true, + rejectWaitCompletedTimes: 1, }); await result.handlerInvocation; - // Rejected once, then retried and accepted. expect(result.waitCompletedRejectionCount()).toBe(1); const waitCreates = result.createParams.filter( (c) => c.eventType === 'wait_completed' @@ -563,18 +739,19 @@ describe('precondition guard through the real replay loop', () => { expect(waitCreates).toHaveLength(2); // First attempt carried the stale snapshot (ULID time of wait_created)... expect(waitCreates[0]?.stateUpdatedAt).toBe(result.staleSnapshotMs); - // ...the retry carried the reloaded snapshot (ULID time of hook_received). + // ...the restarted replay carried the corrected one (ULID time of + // hook_received), with a count covering the event it had been missing. expect(waitCreates[1]?.stateUpdatedAt).toBe(result.OUTSIDE_EVENT_MS); - - // The guard reloaded from the held cursor (not a full re-list). - expect(result.listEvents.mock.calls[0]?.[0].pagination).toEqual( - expect.objectContaining({ - sortOrder: 'asc', - cursor: result.staleEventsCursor, - }) + expect(waitCreates[1]?.stateEventCount).toBe( + (waitCreates[0]?.stateEventCount ?? 0) + 1 ); - // Replay after the retry observed the hook and took the hook branch. + // The restart reloaded the full log rather than reading from the held + // cursor: an `eid:` cursor filters lexicographically, so a hole defined by + // ULID time can sort below it and survive an incremental load. + expect(cursorlessLoads(result.listEvents)).toBe(1); + + // Replay after the restart observed the hook and took the hook branch. expect(result.createdEvents).toEqual( expect.arrayContaining([ expect.objectContaining({ @@ -589,29 +766,126 @@ describe('precondition guard through the real replay loop', () => { ); }); - it('does not retry a 412-rejected run_completed in place; it schedules an immediate re-invocation and the run is not failed', async () => { + it('costs no extra queue message: the restart happens inside the same delivery', async () => { + // The whole point of restarting in-process rather than re-invoking: a 412 + // mid-replay must not add a queue round trip. Compared against the same + // scenario without the rejection, since the workflow's own suspension + // continuations also use the workflow queue. + const rejected = await runPreconditionScenario({ + rejectWaitCompletedTimes: 1, + }); + await rejected.handlerInvocation; + const baseline = await runPreconditionScenario({}); + await baseline.handlerInvocation; + + expect(rejected.waitCompletedRejectionCount()).toBe(1); + expect(baseline.waitCompletedRejectionCount()).toBe(0); + expect(rejected.queue.mock.calls).toHaveLength( + baseline.queue.mock.calls.length + ); + }); + + it('consumes the events a World attaches to the 412 with no events.list round trip', async () => { + const result = await runPreconditionScenario({ + rejectWaitCompletedTimes: 1, + attachDelta: 'complete', + }); + await result.handlerInvocation; + + expect(cursorlessLoads(result.listEvents)).toBe(0); + const waitCreates = result.createParams.filter( + (c) => c.eventType === 'wait_completed' + ); + expect(waitCreates).toHaveLength(2); + expect(waitCreates[1]?.stateUpdatedAt).toBe(result.OUTSIDE_EVENT_MS); + expect(result.createdEvents).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + eventType: 'step_created', + eventData: expect.objectContaining({ stepName: 'drainStep' }), + }), + ]) + ); + }); + + it('falls back to the full reload when the 412 payload does not narrow to events', async () => { + const result = await runPreconditionScenario({ + rejectWaitCompletedTimes: 1, + attachDelta: 'malformed', + }); + await result.handlerInvocation; + + // Untrusted-shaped data on a failure path: dropped without throwing. + expect(cursorlessLoads(result.listEvents)).toBe(1); + expect( + result.createParams.filter((c) => c.eventType === 'wait_completed') + ).toHaveLength(2); + }); + + it('trusts an attached delta only on the first restart of an invocation', async () => { + const result = await runPreconditionScenario({ + rejectWaitCompletedTimes: 2, + attachDelta: 'complete', + }); + await result.handlerInvocation; + + // The delta's completeness proof leans on the rejecting World's own index, + // so a second rejection for the same run means that proof is not to be + // trusted again — the second restart does the authoritative full reload. + expect(result.waitCompletedRejectionCount()).toBe(2); + expect(cursorlessLoads(result.listEvents)).toBe(1); + }); + + it('bounds in-process restarts, then schedules a single immediate re-invocation instead of failing the run', async () => { const result = await runCompletedRejectionScenario(); // The handler must NOT throw (the turbo path has already acked the // message, so a rethrow would strand the run until the queue's ~300s // default visibility timeout). It resolves with an immediate re-invoke - // so a fresh replay observes the new event. + // so a fresh invocation replays against a full reload. await expect(result.handlerInvocation).resolves.toEqual({ timeoutSeconds: 0, }); - // The stale result must not be re-committed: exactly one attempt, carrying - // the loaded snapshot (ULID time of run_started). + // One attempt per replay: the original plus one per in-process restart. + // The stale result is never re-posted — each attempt is a fresh replay. const runCompletedCreates = result.createParams.filter( (c) => c.eventType === 'run_completed' ); - expect(runCompletedCreates).toHaveLength(1); - expect(runCompletedCreates[0]?.stateUpdatedAt).toBe( - result.runStartedSnapshotMs + expect(runCompletedCreates).toHaveLength( + 1 + getPreconditionMaxInProcessRestarts() ); + for (const create of runCompletedCreates) { + expect(create.stateUpdatedAt).toBe(result.runStartedSnapshotMs); + expect(create.stateEventCount).toBe(result.staleEventCount); + } // And the runtime must not convert the rejection into a run failure. expect( result.createParams.filter((c) => c.eventType === 'run_failed') ).toHaveLength(0); }); + + it('honours the restart bound override', async () => { + process.env.WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS = '1'; + const result = await runCompletedRejectionScenario(); + + await expect(result.handlerInvocation).resolves.toEqual({ + timeoutSeconds: 0, + }); + expect( + result.createParams.filter((c) => c.eventType === 'run_completed') + ).toHaveLength(1 + getPreconditionMaxInProcessRestarts()); + }); + + it('guards the attr_set a suspension writes with the same snapshot as every other replay-origin write', async () => { + const result = await attributeSnapshotScenario(); + + const attrCreate = result.createParams.find( + (c) => c.eventType === 'attr_set' + ); + expect(attrCreate).toBeDefined(); + expect(attrCreate?.stateUpdatedAt).toBeTypeOf('number'); + expect(attrCreate?.stateEventCount).toBe(2); + expect(attrCreate?.stateCursor).toBe(result.preloadedCursor); + }); }); diff --git a/packages/core/src/runtime/step-executor.ts b/packages/core/src/runtime/step-executor.ts index 566f7d23d3..db7199b472 100644 --- a/packages/core/src/runtime/step-executor.ts +++ b/packages/core/src/runtime/step-executor.ts @@ -43,7 +43,10 @@ import { isOptimisticInlineStartExplicitlyDisabled, } from './constants.js'; import { getPortLazy } from './get-port-lazy.js'; -import { memoizeEncryptionKey } from './helpers.js'; +import { + memoizeEncryptionKey, + type PreconditionSnapshotParams, +} from './helpers.js'; import { computeStepLatencyEventData, type StepLatencyEventData, @@ -129,20 +132,20 @@ export interface StepExecutorParams { */ inlineDeltaSinceCursor?: string; /** - * Precondition-guard snapshot (epoch ms of the latest event the caller's - * replay loaded) to attach to this step's `step_started` claim. On the lazy - * inline path the claim is the step's FIRST durable write (its - * `step_created` is deferred), so without this the claim would bypass the - * optimistic-concurrency guard entirely: a replay working from a stale view - * could claim — and then commit — a step scheduled without observing an - * out-of-band event. A guard-enforcing World rejects a stale claim with - * `PreconditionFailedError` (412); executeStep does NOT translate that - * rejection (re-claiming in place would still commit the stale schedule), - * so it propagates for the caller to abandon the batch and force a fresh - * replay. Undefined when the guard is disabled or the caller has no - * snapshot; Worlds that don't enforce the guard ignore it. + * Precondition-guard snapshot of the event log the caller's replay loaded, to + * attach to this step's `step_started` claim. On the lazy inline path the + * claim is the step's FIRST durable write (its `step_created` is deferred), + * so without this the claim would bypass the optimistic-concurrency guard + * entirely: a replay working from a stale view could claim — and then commit + * — a step scheduled without observing an event it never loaded. A + * guard-enforcing World rejects a stale claim with `PreconditionFailedError` + * (412); executeStep does NOT translate that rejection (re-claiming in place + * would still commit the stale schedule), so it propagates for the caller to + * abandon the batch and restart its replay. Undefined when the guard is + * disabled or the caller has no snapshot; Worlds that don't enforce the guard + * ignore it. */ - stateUpdatedAt?: number; + preconditionSnapshot?: PreconditionSnapshotParams; /** * Suppress optimistic inline start for this step regardless of * `WORKFLOW_OPTIMISTIC_INLINE_START` / `forceOptimisticStart`: take the @@ -556,13 +559,11 @@ export async function executeStep( : {}), }, }, - // Guard the claim — see StepExecutorParams.stateUpdatedAt. A stale - // (412) rejection surfaces via reconcileOptimisticStart as a + // Guard the claim — see StepExecutorParams.preconditionSnapshot. A + // stale (412) rejection surfaces via reconcileOptimisticStart as a // non-translatable error: the body result is discarded and the // rejection propagates to the caller. - params.stateUpdatedAt !== undefined - ? { stateUpdatedAt: params.stateUpdatedAt } - : undefined + params.preconditionSnapshot ); } ); @@ -619,13 +620,11 @@ export async function executeStep( } : { stepName, ...ownershipStamp }, }, - // Guard the claim — see StepExecutorParams.stateUpdatedAt. A stale - // (412) rejection is intentionally NOT translated by + // Guard the claim — see StepExecutorParams.preconditionSnapshot. A + // stale (412) rejection is intentionally NOT translated by // startErrorToResult below, so it propagates to the caller for a // fresh replay. - params.stateUpdatedAt !== undefined - ? { stateUpdatedAt: params.stateUpdatedAt } - : undefined + params.preconditionSnapshot ); if (!startResult.step) { diff --git a/packages/core/src/runtime/suspension-handler.ts b/packages/core/src/runtime/suspension-handler.ts index 921986d7bd..a02c82c4bb 100644 --- a/packages/core/src/runtime/suspension-handler.ts +++ b/packages/core/src/runtime/suspension-handler.ts @@ -30,7 +30,7 @@ import { dehydrateStepArguments } from '../serialization.js'; import * as Attribute from '../telemetry/semantic-conventions.js'; import { getAbortStreamIdFromToken } from '../util.js'; import { getMaxInlineSteps } from './constants.js'; -import { type MutableEventLog, withPreconditionRetry } from './helpers.js'; +import { type LoadedEventLog, preconditionSnapshotParams } from './helpers.js'; export interface SuspensionHandlerParams { suspension: WorkflowSuspension; @@ -39,13 +39,15 @@ export interface SuspensionHandlerParams { span?: Span; requestId?: string; /** - * The runtime's loaded event log. Each event creation is sent with this - * snapshot's `stateUpdatedAt` and, if the backend rejects it as stale (412), - * the log is reloaded in place and the create is retried — see - * `withPreconditionRetry`. Guarding per-create (rather than the whole - * suspension) ensures a retry never re-issues an already-created event. + * The runtime's loaded event log. Every event creation this suspension makes + * is sent with the precondition snapshot derived from it, so a backend that + * has recorded an event the replay did not see rejects the write with a 412 + * instead of accepting a divergent event. The rejection is not retried here: + * the event's correlation id was minted by *this* replay's seeded sequence, + * so re-committing it against a corrected log would persist an event no + * correct replay produces. The caller restarts the replay instead. */ - eventLog?: MutableEventLog; + eventLog?: LoadedEventLog; /** * Turbo mode only: a promise that resolves once the backgrounded * `run_started` has landed (the run exists). When present, every world write @@ -228,9 +230,9 @@ export async function handleSuspension({ // Create an event with the optimistic-concurrency guard when the caller // supplied a loaded event log; otherwise create it directly (callers without - // a replay snapshot, e.g. tests). The guard reloads + retries on a stale - // (412) rejection, keeping `eventLog` current in place. All suspension events - // are non-run_created events on this run's `runId`. + // a replay snapshot, e.g. tests). A stale (412) rejection propagates to the + // caller, which restarts the replay from a corrected log. All suspension + // events are non-run_created events on this run's `runId`. const createGuarded = ( data: CreateEventRequest, params?: CreateEventParams @@ -238,9 +240,10 @@ export async function handleSuspension({ if (!eventLog) { return world.events.create(runId, data, params); } - return withPreconditionRetry(runId, eventLog, (stateUpdatedAt) => - world.events.create(runId, data, { ...params, stateUpdatedAt }) - ); + return world.events.create(runId, data, { + ...params, + ...preconditionSnapshotParams(eventLog.events, eventLog.cursor), + }); }; // Separate queue items by type const stepItems = suspension.steps.filter( @@ -614,8 +617,13 @@ export async function handleSuspension({ (async () => { try { await ensureRunReady(); - await world.events.create( - runId, + // Guarded like every other suspension write: an attr_set is a + // replay-derived event with a correlation id from this replay's + // seeded sequence, so it must not land on a log the replay never + // saw. Rejecting it is cheap — a run with attribute events already + // forces an in-process replay, so the restart costs the replay it + // was going to do anyway. + await createGuarded( { eventType: 'attr_set', specVersion: SPEC_VERSION_CURRENT, diff --git a/packages/core/src/set-attributes.ts b/packages/core/src/set-attributes.ts index a97c6529d8..e1d1c2cb0d 100644 --- a/packages/core/src/set-attributes.ts +++ b/packages/core/src/set-attributes.ts @@ -47,6 +47,10 @@ export async function setAttributes( } const world = await getWorldLazy(); + // Deliberately unguarded, unlike the attr_set a suspension writes: this call + // runs inside a step body, which holds no replay snapshot, so there is no + // event log to compare against and nothing a precondition could fence. It is + // a genuinely out-of-band write from the event log's point of view. await world.events.create(runId, { eventType: 'attr_set', specVersion: SPEC_VERSION_CURRENT, diff --git a/packages/core/src/step-delivery-hop-count.test.ts b/packages/core/src/step-delivery-hop-count.test.ts new file mode 100644 index 0000000000..f7ea3e09b1 --- /dev/null +++ b/packages/core/src/step-delivery-hop-count.test.ts @@ -0,0 +1,492 @@ +/** + * Companion to `step-delivery-ordering.test.ts`, which reproduces the two + * production `CORRUPTED_EVENT_LOG` shapes. Those two logs happen to be consumed + * by branches that reach their next `useStep` call in the fewest possible + * microtask hops, so they cannot distinguish two very different guarantees: + * + * a) step results are DELIVERED in event-log order relative to wait and hook + * deliveries, or + * b) a step result merely resolves a hop or two later than before, which is + * enough to lose a race against the shortest consumers and nothing more. + * + * The distinction is not academic. A branch resumed by a `wait_completed` or a + * hook payload may need any number of further hops before it draws its next + * ULID (`for await` over a hook resumes the generator, settles the promise from + * `next()`, and only then runs the loop body; workflow code is free to await + * anything in between). Under (b) a memo-warm step result overtakes such a + * branch and reorders the ULID allocation exactly as the unfixed runtime did. + * + * So each case here replays a log that a live run legitimately produced — the + * live invocation received the two events in SEPARATE deliveries, so the first + * branch ran to completion long before the second event existed — while the + * replay receives both in one drain window and must still allocate the ULIDs in + * the recorded order. The consumer is padded with a varying number of extra + * `await`s to make hop count the only variable. + */ +import { WorkflowRuntimeError } from '@workflow/errors'; +import { withResolvers } from '@workflow/utils'; +import type { Event } from '@workflow/world'; +import * as nanoid from 'nanoid'; +import { monotonicFactory } from 'ulid'; +import { describe, expect, it, vi } from 'vitest'; +import { EventsConsumer } from './events-consumer.js'; +import { WorkflowSuspension } from './global.js'; +import type { WorkflowOrchestratorContext } from './private.js'; +import { ReplayPayloadCache } from './replay-payload-cache.js'; +import { + dehydrateStepError, + dehydrateStepReturnValue, +} from './serialization.js'; +import { createUseStep } from './step.js'; +import { createContext } from './vm/index.js'; +import { createCreateHook } from './workflow/hook.js'; +import { createSleep } from './workflow/sleep.js'; + +function setupWorkflowContext( + events: Event[], + replayPayloadCache: ReplayPayloadCache = new ReplayPayloadCache(undefined) +): WorkflowOrchestratorContext { + const context = createContext({ + seed: 'test', + fixedTimestamp: 1753481739458, + }); + const ulid = monotonicFactory(() => context.globalThis.Math.random()); + const workflowStartedAt = context.globalThis.Date.now(); + const promiseQueueHolder = { current: Promise.resolve() }; + const ctxRef: { current?: WorkflowOrchestratorContext } = {}; + const ctx: WorkflowOrchestratorContext = { + runId: 'wrun_test', + encryptionKey: undefined, + replayPayloadCache, + globalThis: context.globalThis, + eventsConsumer: new EventsConsumer(events, { + onUnconsumedEvent: (event) => { + ctxRef.current?.onWorkflowError( + new WorkflowRuntimeError(`Unconsumed event: ${event.eventType}`) + ); + }, + getPromiseQueue: () => promiseQueueHolder.current, + }), + invocationsQueue: new Map(), + generateUlid: () => ulid(workflowStartedAt), + generateNanoid: nanoid.customRandom(nanoid.urlAlphabet, 21, (size) => + new Uint8Array(size).map(() => 256 * context.globalThis.Math.random()) + ), + onWorkflowError: vi.fn(), + get promiseQueue() { + return promiseQueueHolder.current; + }, + set promiseQueue(value: Promise) { + promiseQueueHolder.current = value; + }, + pendingDeliveries: 0, + pendingDeliveryBarriers: new Map(), + }; + ctxRef.current = ctx; + return ctx; +} + +const CORR_IDS = [ + '01K11TFZ62YS0YYFDQ3E8B9YCV', + '01K11TFZ62YS0YYFDQ3E8B9YCW', + '01K11TFZ62YS0YYFDQ3E8B9YCX', + '01K11TFZ62YS0YYFDQ3E8B9YCY', +]; + +async function runWithDiscontinuation( + ctx: WorkflowOrchestratorContext, + workflowFn: () => Promise +): Promise<{ result?: any; error?: any }> { + const d = withResolvers(); + ctx.onWorkflowError = d.reject; + let result: any; + let error: any; + try { + result = await Promise.race([workflowFn(), d.promise]); + } catch (err) { + error = err; + } + return { result, error }; +} + +function slowHydration() { + return (async () => { + const serialization = await import('./serialization.js'); + const original = serialization.hydrateStepReturnValue; + return vi + .spyOn(serialization, 'hydrateStepReturnValue') + .mockImplementation(async (...args) => { + await new Promise((r) => setTimeout(r, 10)); + return original(...args); + }); + })(); +} + +async function buildEventLog(): Promise { + const ops: Promise[] = []; + const [hookPayload, stepAResult] = await Promise.all([ + dehydrateStepReturnValue({ kind: 'ping' }, 'wrun_test', undefined, ops), + dehydrateStepReturnValue('ok', 'wrun_test', undefined, ops), + ]); + return [ + { + eventId: 'evnt_0', + runId: 'wrun_test', + eventType: 'hook_created', + correlationId: `hook_${CORR_IDS[0]}`, + eventData: { token: 'test-token', isWebhook: false }, + createdAt: new Date(), + }, + { + eventId: 'evnt_1', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[1]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_2', + runId: 'wrun_test', + eventType: 'step_started', + correlationId: `step_${CORR_IDS[1]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_3', + runId: 'wrun_test', + eventType: 'hook_received', + correlationId: `hook_${CORR_IDS[0]}`, + eventData: { token: 'test-token', payload: hookPayload }, + createdAt: new Date(), + }, + { + eventId: 'evnt_4', + runId: 'wrun_test', + eventType: 'step_completed', + correlationId: `step_${CORR_IDS[1]}`, + eventData: { stepName: 'stepA', result: stepAResult }, + createdAt: new Date(), + }, + { + eventId: 'evnt_5', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[2]}`, + eventData: { stepName: 'afterHook' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_6', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[3]}`, + eventData: { stepName: 'afterStep' }, + createdAt: new Date(), + }, + ]; +} + +function body(ctx: WorkflowOrchestratorContext, extraHops: number) { + const useStep = createUseStep(ctx); + const createHook = createCreateHook(ctx); + return async () => { + const stepA = useStep('stepA'); + const afterStep = useStep('afterStep'); + const afterHook = useStep('afterHook'); + const hook = createHook<{ kind: string }>({ token: 'test-token' }); + const b1 = (async () => { + await stepA(); + await afterStep(); + })(); + const b2 = (async () => { + for await (const p of hook) { + void p; + for (let i = 0; i < extraHops; i++) { + await Promise.resolve(); + } + await afterHook(); + break; + } + })(); + await Promise.all([b1, b2]); + }; +} + +function pendingStepNames(ctx: WorkflowOrchestratorContext): string[] { + return [...ctx.invocationsQueue.values()] + .filter((i) => i.type === 'step') + .map((i) => (i.type === 'step' ? i.stepName : '')); +} + +describe('step delivery ordering is independent of consumer hop count: hook payload', () => { + for (const extraHops of [0, 1, 2, 4, 8, 16]) { + it(`keeps the recorded ULID allocation with ${extraHops} extra consumer hops`, async () => { + const spy = await slowHydration(); + try { + const events = await buildEventLog(); + const cache = new ReplayPayloadCache(undefined); + const c1 = setupWorkflowContext(events, cache); + const r1 = await runWithDiscontinuation(c1, body(c1, extraHops)); + if (!WorkflowSuspension.is(r1.error)) { + throw r1.error ?? new Error('replay 1 did not suspend'); + } + const c2 = setupWorkflowContext(events, cache); + const r2 = await runWithDiscontinuation(c2, body(c2, extraHops)); + if (!WorkflowSuspension.is(r2.error)) { + throw r2.error ?? new Error('replay 2 did not suspend'); + } + expect(pendingStepNames(c2).sort()).toEqual(['afterHook', 'afterStep']); + } finally { + spy.mockRestore(); + } + }); + } +}); + +const RESUME_AT = new Date('2026-07-27T12:00:05.000Z'); + +async function buildWaitEventLog(): Promise { + const ops: Promise[] = []; + const stepAResult = await dehydrateStepReturnValue( + 'ok', + 'wrun_test', + undefined, + ops + ); + return [ + { + eventId: 'evnt_0', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_1', + runId: 'wrun_test', + eventType: 'wait_created', + correlationId: `wait_${CORR_IDS[1]}`, + eventData: { resumeAt: RESUME_AT }, + createdAt: new Date(), + }, + { + eventId: 'evnt_2', + runId: 'wrun_test', + eventType: 'step_started', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_3', + runId: 'wrun_test', + eventType: 'wait_completed', + correlationId: `wait_${CORR_IDS[1]}`, + eventData: { resumeAt: RESUME_AT }, + createdAt: new Date(), + }, + { + eventId: 'evnt_4', + runId: 'wrun_test', + eventType: 'step_completed', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA', result: stepAResult }, + createdAt: new Date(), + }, + { + eventId: 'evnt_5', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[2]}`, + eventData: { stepName: 'afterSleep' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_6', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[3]}`, + eventData: { stepName: 'afterStep' }, + createdAt: new Date(), + }, + ]; +} + +function waitBody(ctx: WorkflowOrchestratorContext, extraHops: number) { + const useStep = createUseStep(ctx); + const sleep = createSleep(ctx); + return async () => { + const stepA = useStep('stepA'); + const afterStep = useStep('afterStep'); + const afterSleep = useStep('afterSleep'); + const b1 = (async () => { + await stepA(); + await afterStep(); + })(); + const b2 = (async () => { + await sleep(RESUME_AT); + for (let i = 0; i < extraHops; i++) { + await Promise.resolve(); + } + await afterSleep(); + })(); + await Promise.all([b1, b2]); + }; +} + +describe('step delivery ordering is independent of consumer hop count: wait completion', () => { + for (const extraHops of [0, 1, 2, 4, 8, 16]) { + it(`keeps the recorded ULID allocation with ${extraHops} extra consumer hops`, async () => { + const spy = await slowHydration(); + try { + const events = await buildWaitEventLog(); + const cache = new ReplayPayloadCache(undefined); + const c1 = setupWorkflowContext(events, cache); + const r1 = await runWithDiscontinuation(c1, waitBody(c1, extraHops)); + if (!WorkflowSuspension.is(r1.error)) + throw r1.error ?? new Error('replay 1 did not suspend'); + const c2 = setupWorkflowContext(events, cache); + const r2 = await runWithDiscontinuation(c2, waitBody(c2, extraHops)); + if (!WorkflowSuspension.is(r2.error)) + throw r2.error ?? new Error('replay 2 did not suspend'); + expect(pendingStepNames(c2).sort()).toEqual([ + 'afterSleep', + 'afterStep', + ]); + } finally { + spy.mockRestore(); + } + }); + } +}); + +/** + * `step_failed` is as branch-deciding as `step_completed` — it decides whether + * a `catch` continuation runs, and therefore which ULID the follow-up + * `useStep` there draws — and it goes through the same barrier registration and + * event-consumption-time deferral capture. Covered here so a refactor cannot + * silently order rejections differently from results. + */ +async function buildFailedEventLog(): Promise { + const ops: Promise[] = []; + const stepAError = await dehydrateStepError( + new Error('stepA blew up'), + 'wrun_test', + undefined, + ops + ); + return [ + { + eventId: 'evnt_0', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_1', + runId: 'wrun_test', + eventType: 'wait_created', + correlationId: `wait_${CORR_IDS[1]}`, + eventData: { resumeAt: RESUME_AT }, + createdAt: new Date(), + }, + { + eventId: 'evnt_2', + runId: 'wrun_test', + eventType: 'step_started', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_3', + runId: 'wrun_test', + eventType: 'wait_completed', + correlationId: `wait_${CORR_IDS[1]}`, + eventData: { resumeAt: RESUME_AT }, + createdAt: new Date(), + }, + { + eventId: 'evnt_4', + runId: 'wrun_test', + eventType: 'step_failed', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA', error: stepAError }, + createdAt: new Date(), + }, + { + eventId: 'evnt_5', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[2]}`, + eventData: { stepName: 'afterSleep' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_6', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[3]}`, + eventData: { stepName: 'afterFailure' }, + createdAt: new Date(), + }, + ]; +} + +function failedBody(ctx: WorkflowOrchestratorContext, extraHops: number) { + const useStep = createUseStep(ctx); + const sleep = createSleep(ctx); + return async () => { + const stepA = useStep('stepA'); + const afterFailure = useStep('afterFailure'); + const afterSleep = useStep('afterSleep'); + const branchStep = (async () => { + try { + await stepA(); + } catch { + await afterFailure(); + } + })(); + const branchSleep = (async () => { + await sleep(RESUME_AT); + for (let i = 0; i < extraHops; i++) { + await Promise.resolve(); + } + await afterSleep(); + })(); + await Promise.all([branchStep, branchSleep]); + }; +} + +describe('step delivery ordering is independent of consumer hop count: step failure', () => { + for (const extraHops of [0, 1, 2, 4, 8, 16]) { + it(`keeps the recorded ULID allocation with ${extraHops} extra consumer hops`, async () => { + const spy = await slowHydration(); + try { + const events = await buildFailedEventLog(); + const cache = new ReplayPayloadCache(undefined); + const c1 = setupWorkflowContext(events, cache); + const r1 = await runWithDiscontinuation(c1, failedBody(c1, extraHops)); + if (!WorkflowSuspension.is(r1.error)) { + throw r1.error ?? new Error('replay 1 did not suspend'); + } + const c2 = setupWorkflowContext(events, cache); + const r2 = await runWithDiscontinuation(c2, failedBody(c2, extraHops)); + if (!WorkflowSuspension.is(r2.error)) { + throw r2.error ?? new Error('replay 2 did not suspend'); + } + expect(pendingStepNames(c2).sort()).toEqual([ + 'afterFailure', + 'afterSleep', + ]); + } finally { + spy.mockRestore(); + } + }); + } +}); diff --git a/packages/core/src/step-delivery-ordering.test.ts b/packages/core/src/step-delivery-ordering.test.ts new file mode 100644 index 0000000000..85933b7e7c --- /dev/null +++ b/packages/core/src/step-delivery-ordering.test.ts @@ -0,0 +1,602 @@ +import { WorkflowRuntimeError } from '@workflow/errors'; +import { withResolvers } from '@workflow/utils'; +import type { Event } from '@workflow/world'; +import * as nanoid from 'nanoid'; +import { monotonicFactory } from 'ulid'; +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { EventsConsumer } from './events-consumer.js'; +import { WorkflowSuspension } from './global.js'; +import type { WorkflowOrchestratorContext } from './private.js'; +import { ReplayPayloadCache } from './replay-payload-cache.js'; +import { dehydrateStepReturnValue } from './serialization.js'; +import { createUseStep } from './step.js'; +import { createContext } from './vm/index.js'; +import { createCreateHook } from './workflow/hook.js'; +import { createSleep } from './workflow/sleep.js'; + +/** + * Production incident: two o2flow runs on `@workflow/core@5.0.0-beta.36` + * (`wrun_41KYJENABV0GSF5YTE9EETV5DD` and `wrun_41KYJEE01S0GPC9RWT5MEKVCX8`) + * failed permanently with + * + * Replay divergence: step event step_created for step_X belongs to + * "countFanoutStep", but the current step consumer is + * "releaseGlobalLaunchSlot" + * + * repeated at the SAME eventId across three divergence-recovery replays, and + * then escalated to a terminal `CorruptedEventLogError`. + * + * Mechanism reproduced here: + * + * - Each `useStep(...)` invocation draws the next deterministic ULID as its + * correlation id (`step.ts`), so WHICH workflow branch resumes first decides + * which correlation id each step call gets. Replay matches events to + * consumers by exact correlation id and rejects a `step_created` whose + * recorded `stepName` differs from the consumer's (`step.ts`, the + * `eventStepName !== stepName` divergence check). + * - The runtime has a delivery-barrier system that pins branch-deciding + * delivery order to event-log position (`pendingDeliveryBarriers` in + * `private.ts`), but it only covers the kinds `'hook'` and `'wait'`. + * **Step results are not in it.** + * - `wait_completed` resolves through a detached chain with a fixed, small + * microtask-hop count (`workflow/sleep.ts`). A `step_completed` instead + * resolves inside a serial `ctx.promiseQueue` slot that first hydrates the + * payload via `ReplayPayloadCache.getStepResult(...)`. That hop count is not + * fixed: the first hydration pays async decrypt/deserialize, while a later + * replay sharing the same `ReplayPayloadCache` hits the + * `primitiveStepResults` memo for small primitive results and resolves in + * one or two hops. + * + * So when a `step_completed` sits adjacent in the log to a `wait_completed` + * (or `hook_received`) and both consumers are live, the FIRST replay of a + * queue delivery (cold cache) delivers the wait first — the ordering the live + * invocation recorded into the log — while every LATER replay in that same + * delivery (warm cache) delivers the step result first. The two branches then + * allocate each other's ULIDs and diverge, forever, at the same event. + * + * Production log shape for run 1, which the synthetic log below mirrors: + * + * …, step_completed(finalizeTaskSandbox), wait_completed, wait_completed, + * step_completed(finalizeTaskSandbox), step_created(countFanoutStep), + * step_created(releaseGlobalLaunchSlot), … + * + * This is entirely core replay machinery — no World implementation is + * involved. Worlds only supply event I/O, so the bug is not specific to the + * Vercel world. + * + * These tests assert the CORRECT behavior: both replays must agree with the + * committed log and suspend. On `main` the second replay instead throws + * `ReplayDivergenceError`, which is the reproduction. The companion fix on + * branch `pgp/fix-step-delivery-ordering` brings step results into the + * delivery-barrier system and makes these pass. + * + * Scope limit, worth knowing before treating these five cases as the whole + * guarantee: every branch here reaches its next `useStep(...)` in the fewest + * possible microtask hops after being resumed. That makes them unable to + * distinguish "step results are delivered in event-log order relative to wait + * and hook deliveries" from "a step result merely resolves a hop or two later + * than it used to", which beats the shortest consumers and nothing else. A + * revision of the companion fix that only reordered the `resolve()` calls + * passed all five while a consumer padded with one extra `await` still + * diverged. Padded consumers are covered separately by + * `step-delivery-hop-count.test.ts` on the fix branch; both files together are + * what pins the ordering guarantee. + */ + +/** + * Harness copied from `hook-sleep-interaction.test.ts`, with one addition: a + * `ReplayPayloadCache` can be passed in, so two sequential replays can share + * one cache exactly like the replay loop inside a single production queue + * delivery does (see the `ReplayPayloadCache` class docstring). + */ +function setupWorkflowContext( + events: Event[], + replayPayloadCache: ReplayPayloadCache = new ReplayPayloadCache(undefined) +): WorkflowOrchestratorContext { + const context = createContext({ + seed: 'test', + fixedTimestamp: 1753481739458, + }); + const ulid = monotonicFactory(() => context.globalThis.Math.random()); + const workflowStartedAt = context.globalThis.Date.now(); + const promiseQueueHolder = { current: Promise.resolve() }; + const ctxRef: { current?: WorkflowOrchestratorContext } = {}; + const ctx: WorkflowOrchestratorContext = { + runId: 'wrun_test', + encryptionKey: undefined, + replayPayloadCache, + globalThis: context.globalThis, + eventsConsumer: new EventsConsumer(events, { + onUnconsumedEvent: (event) => { + ctxRef.current?.onWorkflowError( + new WorkflowRuntimeError( + `Unconsumed event in event log: eventType=${event.eventType}, correlationId=${event.correlationId}, eventId=${event.eventId}. This indicates a corrupted or invalid event log.` + ) + ); + }, + getPromiseQueue: () => promiseQueueHolder.current, + }), + invocationsQueue: new Map(), + generateUlid: () => ulid(workflowStartedAt), + generateNanoid: nanoid.customRandom(nanoid.urlAlphabet, 21, (size) => + new Uint8Array(size).map(() => 256 * context.globalThis.Math.random()) + ), + onWorkflowError: vi.fn(), + get promiseQueue() { + return promiseQueueHolder.current; + }, + set promiseQueue(value: Promise) { + promiseQueueHolder.current = value; + }, + pendingDeliveries: 0, + pendingDeliveryBarriers: new Map(), + }; + ctxRef.current = ctx; + return ctx; +} + +// Deterministic correlation IDs from the ULID generator with seed 'test' +const CORR_IDS = [ + '01K11TFZ62YS0YYFDQ3E8B9YCV', + '01K11TFZ62YS0YYFDQ3E8B9YCW', + '01K11TFZ62YS0YYFDQ3E8B9YCX', + '01K11TFZ62YS0YYFDQ3E8B9YCY', +]; + +async function runWithDiscontinuation( + ctx: WorkflowOrchestratorContext, + workflowFn: () => Promise +): Promise<{ result?: any; error?: any }> { + const workflowDiscontinuation = withResolvers(); + ctx.onWorkflowError = workflowDiscontinuation.reject; + + let result: any; + let error: any; + try { + result = await Promise.race([ + workflowFn(), + workflowDiscontinuation.promise, + ]); + } catch (err) { + error = err; + } + return { result, error }; +} + +/** + * Models the cost of first-touch payload hydration (decrypt + deserialize). + * Production shares prepared bytes and memoized primitive results across the + * replays of one queue delivery, so the second replay of a small primitive + * step result never reaches this spy — which is exactly the hop-count + * asymmetry under test. + */ +function delayHydration() { + const hydrateSpy = vi.fn(); + return { + hydrateSpy, + install: async () => { + const serialization = await import('./serialization.js'); + const originalHydrate = serialization.hydrateStepReturnValue; + return vi + .spyOn(serialization, 'hydrateStepReturnValue') + .mockImplementation(async (...args) => { + hydrateSpy(); + await new Promise((r) => setTimeout(r, 10)); + return originalHydrate(...args); + }); + }, + }; +} + +describe('step result delivery ordering across replays', () => { + let spy: ReturnType | undefined; + + afterEach(() => { + spy?.mockRestore(); + spy = undefined; + }); + + describe('step_completed adjacent to wait_completed', () => { + // The wait's `resumeAt` is re-read from the `wait_created` event during + // replay (see `workflow/sleep.ts`), so any fixed date works here as long + // as `wait_created` and `wait_completed` agree. + const resumeAt = new Date('2026-07-27T12:00:05.000Z'); + + async function buildEventLog(): Promise { + const ops: Promise[] = []; + // A short string result is a memoizable primitive, so the SECOND replay + // sharing the cache resolves it from `primitiveStepResults` without + // touching hydration at all. + const stepAResult = await dehydrateStepReturnValue( + 'ok', + 'wrun_test', + undefined, + ops + ); + + return [ + { + eventId: 'evnt_0', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_1', + runId: 'wrun_test', + eventType: 'wait_created', + correlationId: `wait_${CORR_IDS[1]}`, + eventData: { resumeAt }, + createdAt: new Date(), + }, + { + eventId: 'evnt_2', + runId: 'wrun_test', + eventType: 'step_started', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + // The live invocation delivered the wait BEFORE the step result, so + // the wait branch resumed first and drew the next ULID. Everything + // after this point in the log encodes that ordering. + { + eventId: 'evnt_3', + runId: 'wrun_test', + eventType: 'wait_completed', + correlationId: `wait_${CORR_IDS[1]}`, + eventData: { resumeAt }, + createdAt: new Date(), + }, + { + eventId: 'evnt_4', + runId: 'wrun_test', + eventType: 'step_completed', + correlationId: `step_${CORR_IDS[0]}`, + eventData: { stepName: 'stepA', result: stepAResult }, + createdAt: new Date(), + }, + { + eventId: 'evnt_5', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[2]}`, + eventData: { stepName: 'afterSleep' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_6', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[3]}`, + eventData: { stepName: 'afterStep' }, + createdAt: new Date(), + }, + ]; + } + + // ULID draw order in this body: `stepA()` takes CORR_IDS[0], `sleep()` + // takes CORR_IDS[1], and then whichever branch is resumed FIRST takes + // CORR_IDS[2] while the other takes CORR_IDS[3]. + function workflowBody(ctx: WorkflowOrchestratorContext) { + const useStep = createUseStep(ctx); + const sleep = createSleep(ctx); + + return async () => { + const stepA = useStep('stepA'); + const afterStep = useStep('afterStep'); + const afterSleep = useStep('afterSleep'); + + const branchStep = (async () => { + await stepA(); + await afterStep(); + })(); + const branchSleep = (async () => { + await sleep(resumeAt); + await afterSleep(); + })(); + + await Promise.all([branchStep, branchSleep]); + }; + } + + function pendingStepNames(ctx: WorkflowOrchestratorContext): string[] { + return [...ctx.invocationsQueue.values()] + .filter((item) => item.type === 'step') + .map((item) => (item.type === 'step' ? item.stepName : '')); + } + + it('delivers the wait before the step result on the first replay, matching the log', async () => { + const hydration = delayHydration(); + spy = await hydration.install(); + const events = await buildEventLog(); + + const ctx = setupWorkflowContext(events); + const { error } = await runWithDiscontinuation(ctx, workflowBody(ctx)); + + expect(error).toBeDefined(); + if (!WorkflowSuspension.is(error)) { + throw error; + } + + // The log's ordering was reproduced: the sleep branch resumed first and + // drew CORR_IDS[2] for `afterSleep`, so both `step_created` events at + // the tail matched their consumers and the run suspends with both + // follow-up steps pending. + expect(pendingStepNames(ctx).sort()).toEqual(['afterSleep', 'afterStep']); + expect(ctx.eventsConsumer.eventIndex).toBe(events.length); + }); + + it('delivers the wait before the step result on a later replay sharing the payload cache', async () => { + const hydration = delayHydration(); + spy = await hydration.install(); + const events = await buildEventLog(); + + // One cache for both replays: production shares a single + // `ReplayPayloadCache` across every replay of one queue delivery. + const sharedCache = new ReplayPayloadCache(undefined); + + const firstCtx = setupWorkflowContext(events, sharedCache); + const first = await runWithDiscontinuation( + firstCtx, + workflowBody(firstCtx) + ); + if (!WorkflowSuspension.is(first.error)) { + throw first.error ?? new Error('expected the first replay to suspend'); + } + expect(hydration.hydrateSpy).toHaveBeenCalled(); + + // Second replay, fresh VM/context, same event log, same cache. The step + // result is now memoized as a primitive, so it resolves in a couple of + // microtask hops instead of paying hydration — while the wait's hop + // count is unchanged. + const secondCtx = setupWorkflowContext(events, sharedCache); + const { error } = await runWithDiscontinuation( + secondCtx, + workflowBody(secondCtx) + ); + + expect(error).toBeDefined(); + // FAILS on `main`: the step result now wins, `afterStep` draws + // CORR_IDS[2], and replay diverges at evnt_5 with the production error + // shape ("... belongs to \"afterSleep\", but the current step consumer + // is \"afterStep\""). + if (!WorkflowSuspension.is(error)) { + throw error; + } + expect(pendingStepNames(secondCtx).sort()).toEqual([ + 'afterSleep', + 'afterStep', + ]); + expect(secondCtx.eventsConsumer.eventIndex).toBe(events.length); + }); + }); + + describe('step_completed adjacent to hook_received', () => { + async function buildEventLog(): Promise { + const ops: Promise[] = []; + const [hookPayload, stepAResult] = await Promise.all([ + dehydrateStepReturnValue({ kind: 'ping' }, 'wrun_test', undefined, ops), + dehydrateStepReturnValue('ok', 'wrun_test', undefined, ops), + ]); + + return [ + { + eventId: 'evnt_0', + runId: 'wrun_test', + eventType: 'hook_created', + correlationId: `hook_${CORR_IDS[0]}`, + eventData: { token: 'test-token', isWebhook: false }, + createdAt: new Date(), + }, + { + eventId: 'evnt_1', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[1]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_2', + runId: 'wrun_test', + eventType: 'step_started', + correlationId: `step_${CORR_IDS[1]}`, + eventData: { stepName: 'stepA' }, + createdAt: new Date(), + }, + // The live invocation delivered the hook payload BEFORE the step + // result, so the hook branch resumed first and drew the next ULID. + { + eventId: 'evnt_3', + runId: 'wrun_test', + eventType: 'hook_received', + correlationId: `hook_${CORR_IDS[0]}`, + eventData: { token: 'test-token', payload: hookPayload }, + createdAt: new Date(), + }, + { + eventId: 'evnt_4', + runId: 'wrun_test', + eventType: 'step_completed', + correlationId: `step_${CORR_IDS[1]}`, + eventData: { stepName: 'stepA', result: stepAResult }, + createdAt: new Date(), + }, + { + eventId: 'evnt_5', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[2]}`, + eventData: { stepName: 'afterHook' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_6', + runId: 'wrun_test', + eventType: 'step_created', + correlationId: `step_${CORR_IDS[3]}`, + eventData: { stepName: 'afterStep' }, + createdAt: new Date(), + }, + ]; + } + + /** + * ULID draw order: `createHook()` takes CORR_IDS[0], `stepA()` takes + * CORR_IDS[1], then the branch resumed FIRST takes CORR_IDS[2]. + * + * Two ways of consuming the hook. Both subscribe before `hook_received` is + * consumed, so both take the same delivery path in `workflow/hook.ts` (the + * `promises.length > 0` branch; the buffered `claim()` path is not involved + * in either — entering `for await` calls `next()`, which reaches + * `yield await this` and registers the awaiter well before the events + * consumer drains the log on `process.nextTick`). What differs is how many + * microtask hops separate the payload RESOLVING from the branch calling + * `afterHook()` and thereby drawing the next ULID: + * + * - `for-await` (the idiomatic pattern, and what reproduces): resolution + * resumes the async generator at `yield await this`, the yielded value + * settles the promise returned by `next()`, and only then does the loop + * body run. Those extra hops are enough for a memo-warm `step_completed` + * — which on an unfixed runtime resolves inside its own queue slot with + * no detached chain at all — to draw CORR_IDS[2] first. + * - `await hook` (control): resolution resumes the branch's continuation + * directly, so it reaches `afterHook()` in the first microtask and stays + * ahead of the step result even on a warm cache. + * + * So the hook flavour of this bug is not about payload buffering; it is the + * same latency race as the wait flavour, and the consumer shape only sets + * how much of a head start the step result needs in order to win. + */ + function workflowBody( + ctx: WorkflowOrchestratorContext, + consume: 'for-await' | 'direct-await' + ) { + const useStep = createUseStep(ctx); + const createHook = createCreateHook(ctx); + + return async () => { + const stepA = useStep('stepA'); + const afterStep = useStep('afterStep'); + const afterHook = useStep('afterHook'); + const hook = createHook<{ kind: string }>({ token: 'test-token' }); + + const branchStep = (async () => { + await stepA(); + await afterStep(); + })(); + const branchHook = (async () => { + if (consume === 'direct-await') { + await hook; + await afterHook(); + return; + } + for await (const payload of hook) { + void payload; + await afterHook(); + break; + } + })(); + + await Promise.all([branchStep, branchHook]); + }; + } + + function pendingStepNames(ctx: WorkflowOrchestratorContext): string[] { + return [...ctx.invocationsQueue.values()] + .filter((item) => item.type === 'step') + .map((item) => (item.type === 'step' ? item.stepName : '')); + } + + it('delivers the hook payload before the step result on the first replay, matching the log', async () => { + const hydration = delayHydration(); + spy = await hydration.install(); + const events = await buildEventLog(); + + const ctx = setupWorkflowContext(events); + const { error } = await runWithDiscontinuation( + ctx, + workflowBody(ctx, 'for-await') + ); + + expect(error).toBeDefined(); + if (!WorkflowSuspension.is(error)) { + throw error; + } + expect(pendingStepNames(ctx).sort()).toEqual(['afterHook', 'afterStep']); + expect(ctx.eventsConsumer.eventIndex).toBe(events.length); + }); + + it('delivers the hook payload before the step result on a later replay sharing the payload cache', async () => { + const hydration = delayHydration(); + spy = await hydration.install(); + const events = await buildEventLog(); + const sharedCache = new ReplayPayloadCache(undefined); + + const firstCtx = setupWorkflowContext(events, sharedCache); + const first = await runWithDiscontinuation( + firstCtx, + workflowBody(firstCtx, 'for-await') + ); + if (!WorkflowSuspension.is(first.error)) { + throw first.error ?? new Error('expected the first replay to suspend'); + } + expect(hydration.hydrateSpy).toHaveBeenCalled(); + + // Hook payloads have no primitive memo, so the payload still re-hydrates + // on the second replay while the small primitive step result is served + // straight from `primitiveStepResults`. + const secondCtx = setupWorkflowContext(events, sharedCache); + const { error } = await runWithDiscontinuation( + secondCtx, + workflowBody(secondCtx, 'for-await') + ); + + expect(error).toBeDefined(); + // FAILS on `main`: the step result overtakes the hook payload, + // `afterStep` draws CORR_IDS[2], and replay diverges at evnt_5 with the + // production error shape. + if (!WorkflowSuspension.is(error)) { + throw error; + } + expect(pendingStepNames(secondCtx).sort()).toEqual([ + 'afterHook', + 'afterStep', + ]); + expect(secondCtx.eventsConsumer.eventIndex).toBe(events.length); + }); + + // Control: `await hook` keeps log order on both replays today. This is not + // a different delivery path — all three hook cases in this file take the + // same `promises.length > 0` immediate path in `workflow/hook.ts` — it is + // just a shorter consumer. Resolution resumes this branch's continuation + // directly, so it reaches `afterHook()` in the first microtask and stays + // ahead of a memo-warm step result. It is the shortest-consumer case here, + // and the fix must not regress it. + it('keeps log order across replays when the hook is awaited directly', async () => { + const hydration = delayHydration(); + spy = await hydration.install(); + const events = await buildEventLog(); + const sharedCache = new ReplayPayloadCache(undefined); + + for (const replay of [1, 2]) { + const ctx = setupWorkflowContext(events, sharedCache); + const { error } = await runWithDiscontinuation( + ctx, + workflowBody(ctx, 'direct-await') + ); + if (!WorkflowSuspension.is(error)) { + throw error ?? new Error(`expected replay ${replay} to suspend`); + } + expect(pendingStepNames(ctx).sort()).toEqual([ + 'afterHook', + 'afterStep', + ]); + expect(ctx.eventsConsumer.eventIndex).toBe(events.length); + } + }); + }); +}); diff --git a/packages/core/src/step.ts b/packages/core/src/step.ts index 1b14165b91..7801b25d6d 100644 --- a/packages/core/src/step.ts +++ b/packages/core/src/step.ts @@ -4,6 +4,8 @@ import { EventConsumerResult } from './events-consumer.js'; import { type StepInvocationQueueItem, WorkflowSuspension } from './global.js'; import { stepLogger } from './logger.js'; import { + awaitEarlierDeliveries, + registerDeliveryBarrier, scheduleWhenIdle, type WorkflowOrchestratorContext, } from './private.js'; @@ -165,6 +167,22 @@ export function createUseStep(ctx: WorkflowOrchestratorContext) { // deterministic ordering of all promise resolutions/rejections. // Hydrate the serialized thrown value from the event log so the // original type identity and custom properties are preserved. + // + // The rejection is as branch-deciding as a success: it decides + // whether a `try`/`catch` continuation runs, and therefore which + // ULIDs the follow-up `useStep` calls draw. So it is ordered by + // event-log position exactly like `step_completed` below — see there + // for why the deferral is captured here, at event-consumption time, + // and awaited off the serial queue. + const eventIndex = ctx.eventsConsumer.eventIndex; + const barrier = registerDeliveryBarrier(ctx, eventIndex, 'step'); + let rejection: unknown; + const earlierDelivered = awaitEarlierDeliveries( + ctx, + eventIndex, + 'step' + ); + ctx.pendingDeliveries++; ctx.promiseQueue = ctx.promiseQueue.then(async () => { try { const prepared = await ctx.replayPayloadCache.prepareEventPayload( @@ -172,7 +190,7 @@ export function createUseStep(ctx: WorkflowOrchestratorContext) { 'error', event.eventData.error ); - const hydrated = await hydrateStepError( + rejection = await hydrateStepError( event.eventData.error, ctx.runId, ctx.encryptionKey, @@ -180,7 +198,6 @@ export function createUseStep(ctx: WorkflowOrchestratorContext) { {}, prepared ); - reject(hydrated); } catch (hydrateErr) { // If hydration fails for any reason, fall back to a generic // FatalError so the workflow doesn't hang. This should be @@ -192,16 +209,20 @@ export function createUseStep(ctx: WorkflowOrchestratorContext) { ? hydrateErr.message : String(hydrateErr), }); - reject( - new FatalError( - `Failed to hydrate step error: ${ - hydrateErr instanceof Error - ? hydrateErr.message - : String(hydrateErr) - }` - ) + rejection = new FatalError( + `Failed to hydrate step error: ${ + hydrateErr instanceof Error + ? hydrateErr.message + : String(hydrateErr) + }` ); + } finally { + ctx.pendingDeliveries--; } + void earlierDelivered.then(() => { + barrier.markDelivered(); + reject(rejection); + }); }); return EventConsumerResult.Finished; } @@ -220,8 +241,58 @@ export function createUseStep(ctx: WorkflowOrchestratorContext) { // Prepared serialized bytes are shared across replay VMs, but final // objects are always revived here inside this ordered queue slot. // Only immutable primitive final values bypass revival entirely. + // + // Hydration cost is what makes this delivery's timing unstable + // across replays of one invocation: the first replay pays the full + // decrypt/decompress/revive, later replays memo-hit a primitive + // result in `ReplayPayloadCache` and finish in a hop or two. A + // workflow awaiting this result on one branch and a `sleep()` or + // hook payload on another would therefore allocate its follow-up + // step ULIDs in a different order on a warm replay than the + // invocation that WROTE those `step_created` events did — a + // permanent `ReplayDivergenceError`. So the result is ordered by + // event-log position through the delivery-barrier registry (see + // `ctx.pendingDeliveryBarriers`): + // - Register a 'step' barrier at this event's index so a + // LATER-in-log wait/hook delivery is handed over only after it. + // - Hydrate inside this serial queue slot (keeping async + // deserialization in event-log order) but only CAPTURE the + // outcome; then defer behind every EARLIER-in-log wait and hook + // delivery before resolving, and mark this step delivered. + // + // The deferral is captured HERE, while consuming the event, and not + // inside the queue slot. Two reasons, both load-bearing: + // - Determinism: the set of earlier deliveries is then a function of + // log position alone. Captured later it would depend on how much + // hydration the earlier deliveries had already finished — the very + // coupling this barrier exists to remove. + // - Coverage: an earlier delivery whose own hydration slot runs + // first on this serial queue has usually already resolved (and so + // deregistered its barrier) by the time a later slot starts. Read + // at slot start, its barrier would be invisible and this step + // would not defer at all. Every event in one drain window is + // consumed before any slot runs, so capturing at consumption time + // sees all of them. + // + // The deferral runs OFF the serial queue: it may wait on an earlier + // wait/hook delivery whose own resolution is driven by this queue, + // and blocking a queue slot on that would deadlock the queue (the + // same constraint sleep.ts and hook.ts document). `pendingDeliveries` + // is likewise released inside the slot, before the detached defer, so + // `scheduleWhenIdle` can still reach idle and retire the barriers + // this deferral may be waiting on. const completedEventId = event.eventId; const serializedResult = event.eventData.result; + const eventIndex = ctx.eventsConsumer.eventIndex; + const barrier = registerDeliveryBarrier(ctx, eventIndex, 'step'); + let outcome: + | { ok: true; value: Result } + | { ok: false; error: unknown }; + const earlierDelivered = awaitEarlierDeliveries( + ctx, + eventIndex, + 'step' + ); ctx.pendingDeliveries++; ctx.promiseQueue = ctx.promiseQueue.then(async () => { try { @@ -244,12 +315,20 @@ export function createUseStep(ctx: WorkflowOrchestratorContext) { ); } ); - resolve(hydratedResult as Result); + outcome = { ok: true, value: hydratedResult as Result }; } catch (error) { - reject(error); + outcome = { ok: false, error }; } finally { ctx.pendingDeliveries--; } + void earlierDelivered.then(() => { + barrier.markDelivered(); + if (outcome.ok) { + resolve(outcome.value); + } else { + reject(outcome.error); + } + }); }); return EventConsumerResult.Finished; } diff --git a/packages/core/src/workflow/abort-controller.ts b/packages/core/src/workflow/abort-controller.ts index 3dfdb2c864..4d5d9a08af 100644 --- a/packages/core/src/workflow/abort-controller.ts +++ b/packages/core/src/workflow/abort-controller.ts @@ -1,6 +1,10 @@ import { ReplayDivergenceError } from '@workflow/errors'; import { EventConsumerResult } from '../events-consumer.js'; -import type { WorkflowOrchestratorContext } from '../private.js'; +import { + awaitEarlierDeliveries, + registerDeliveryBarrier, + type WorkflowOrchestratorContext, +} from '../private.js'; import { hydrateStepReturnValue } from '../serialization.js'; import { ABORT_HOOK_TOKEN, ABORT_STREAM_NAME } from '../symbols.js'; import { getAbortStreamId } from '../util.js'; @@ -178,6 +182,32 @@ export function createCreateAbortController(ctx: WorkflowOrchestratorContext) { // dehydration, so `'reason' in payload` is false and reason // ends up undefined on replay. const rawPayload = event.eventData?.payload; + // An abort is a branch-deciding delivery: `_setAborted` fires the + // signal's listeners, and a listener is free to invoke a step and + // draw a ULID. So it registers in the delivery-barrier registry as a + // 'hook' — which is exactly what the event is — so that wait, hook + // and step deliveries order against it by event-log position rather + // than by whose hydration finished first. It is always ARMED: unlike + // a buffered user hook payload, nothing about its delivery waits on + // workflow code asking for it. + // + // Resolving straight off the queue slot was sufficient only while + // every other delivery also resolved from its slot. Step results no + // longer do (see step.ts), so an abort whose slot ran while a + // log-earlier step sat behind a barrier would overtake it — see + // `delivery-barrier-coverage.test.ts`. + // + // The deferral is captured HERE, at event-consumption time, for the + // same two reasons spelled out in step.ts: the set of earlier + // deliveries stays a function of log position alone, and barriers + // that retire before this slot runs are still seen. + const eventIndex = ctx.eventsConsumer.eventIndex; + const barrier = registerDeliveryBarrier(ctx, eventIndex, 'hook'); + const earlierDelivered = awaitEarlierDeliveries( + ctx, + eventIndex, + 'hook' + ); // Account this abort as a pending delivery, exactly like step // results (step.ts) and hook payloads (workflow/hook.ts) do. The // suspension handler dehydrates queued step arguments only once @@ -189,6 +219,11 @@ export function createCreateAbortController(ctx: WorkflowOrchestratorContext) { // (and a missing reason). Bumping the counter holds the suspension // until `_setAborted` has landed, so downstream serialization is // deterministic regardless of reason-hydration (decryption) latency. + // + // It is released inside the slot, before the detached deferral, so + // `scheduleWhenIdle` can still reach idle and retire the barriers + // that deferral may be waiting on — the same shape as the hook and + // step paths. ctx.pendingDeliveries++; ctx.promiseQueue = ctx.promiseQueue.then(async () => { let reason: unknown; @@ -223,10 +258,16 @@ export function createCreateAbortController(ctx: WorkflowOrchestratorContext) { // fallback (DOMException AbortError). } } - this.signal._setAborted(reason); } finally { ctx.pendingDeliveries--; } + // Detached, like the other deliveries: `awaitEarlierDeliveries` + // may be waiting on a delivery this very queue drives, and + // blocking a slot on that would deadlock the queue. + void earlierDelivered.then(() => { + barrier.markDelivered(); + this.signal._setAborted(reason); + }); }); ctx.invocationsQueue.delete(correlationId); diff --git a/packages/core/src/workflow/hook.ts b/packages/core/src/workflow/hook.ts index ba6b726170..e079827051 100644 --- a/packages/core/src/workflow/hook.ts +++ b/packages/core/src/workflow/hook.ts @@ -261,23 +261,52 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { if (event.eventType === 'hook_received') { // Register a 'hook' delivery barrier at this event's log index so a - // later-in-log `wait_completed` is delivered only after this hook, - // and so this hook is delivered only after every earlier-in-log - // `wait_completed` — keeping any `Promise.race` against a wait - // deterministic and aligned with the committed event log, regardless - // of microtask-hop count, hydration time, or race-argument order. + // later-in-log `wait_completed` or step result is delivered only after + // this hook, and so this hook is delivered only after every + // earlier-in-log `wait_completed` and step result — keeping any + // `Promise.race` (or concurrent-branch ULID allocation) deterministic + // and aligned with the committed event log, regardless of + // microtask-hop count, hydration time, or race-argument order. // See `ctx.pendingDeliveryBarriers`. + // + // The barrier is registered ARMED only when a consumer is already + // awaiting, so this payload is committed to reaching the workflow. A + // buffered payload is registered unarmed and armed by `claim()`: until + // a consumer takes it, a later step result must not be ordered behind + // it (see `awaitEarlierDeliveries`). const eventIndex = ctx.eventsConsumer.eventIndex; - const barrier = registerDeliveryBarrier(ctx, eventIndex, 'hook'); + const hasWaitingConsumer = promises.length > 0; + const barrier = registerDeliveryBarrier(ctx, eventIndex, 'hook', { + armed: hasWaitingConsumer, + }); - if (promises.length > 0) { + if (hasWaitingConsumer) { + // A consumer is already awaiting, so this payload's delivery is + // pinned to this log position: capture the deferral HERE, while + // consuming the event, not at the end of the hydration slot below — + // same reasoning as step.ts. An earlier step or hook whose slot runs + // first on this serial queue has usually delivered, and so + // deregistered its barrier, before this slot ends. Read then, it + // would be invisible and this payload would skip both the gate AND + // `awaitEarlierDeliveries`' macrotask yield, letting it overtake the + // branch that earlier delivery just woke. Every event in one drain + // window is consumed before any slot runs, so capturing at + // consumption time sees all of them. + // + // The BUFFERED branch below deliberately does NOT do this — see the + // comment on `claim()`. + const earlierDelivered = awaitEarlierDeliveries( + ctx, + eventIndex, + 'hook' + ); const next = promises.shift(); if (next) { - // A consumer is already awaiting. Hydrate through a promiseQueue - // slot (so async deserialization stays in event-log order), then - // defer behind earlier waits before resolving. The deferral runs - // OFF the serial queue (it may wait on an earlier wait delivery - // and blocking a queue slot on that would deadlock the queue). + // Hydrate through a promiseQueue slot (so async deserialization + // stays in event-log order), then defer behind earlier waits and + // steps before resolving. The deferral runs OFF the serial queue + // (it may wait on an earlier wait or step delivery and blocking a + // queue slot on that would deadlock the queue). ctx.pendingDeliveries++; let hydrateOutcome: | { ok: true; value: T } @@ -304,16 +333,14 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { } finally { ctx.pendingDeliveries--; } - void awaitEarlierDeliveries(ctx, eventIndex, ['wait']).then( - () => { - barrier.markDelivered(); - if (hydrateOutcome.ok) { - next.resolve(hydrateOutcome.value); - } else { - next.reject(hydrateOutcome.error); - } + void earlierDelivered.then(() => { + barrier.markDelivered(); + if (hydrateOutcome.ok) { + next.resolve(hydrateOutcome.value); + } else { + next.reject(hydrateOutcome.error); } - ); + }); }); } } else { @@ -331,9 +358,22 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { | undefined; const hydrated = withResolvers(); - const claim = (): Promise => - hydrated.promise - .then(() => awaitEarlierDeliveries(ctx, eventIndex, ['wait'])) + const claim = (): Promise => { + // A consumer has taken this payload, so its delivery no longer + // waits on workflow code: later step results may now be ordered + // behind it. + barrier.arm(); + // Unlike every other delivery, the deferral is evaluated HERE, at + // claim time, rather than when the event was consumed. A buffered + // payload's delivery genuinely happens when the workflow reads the + // hook, which may be many deliveries later; a consumption-time + // snapshot would make the claim wait on — and pay the macrotask + // yield for — barriers that were relevant to a moment this payload + // never participated in. That is not theoretical: it stalls the + // second payload in the e2e `hookWithSleepWorkflow` long enough + // for the run to suspend before delivering it. + return hydrated.promise + .then(() => awaitEarlierDeliveries(ctx, eventIndex, 'hook')) .then(() => { barrier.markDelivered(); if (outcome && !outcome.ok) { @@ -341,6 +381,7 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { } return (outcome as { ok: true; value: T }).value; }); + }; ctx.pendingDeliveries++; ctx.promiseQueue = ctx.promiseQueue.then(async () => { @@ -415,7 +456,7 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { // The payload was hydrated through a promiseQueue slot at its log // position (buffering branch above). `claim()` builds the // consumer-facing promise from that outcome, deferring behind any - // earlier-in-log wait and marking this hook delivered — so + // earlier-in-log wait or step and marking this hook delivered — so // resolution order stays anchored to the event log, not this later // claim site. return nextDelivery.claim(); diff --git a/packages/core/src/workflow/sleep.ts b/packages/core/src/workflow/sleep.ts index 1acb800d4d..c8848d0c3a 100644 --- a/packages/core/src/workflow/sleep.ts +++ b/packages/core/src/workflow/sleep.ts @@ -90,24 +90,40 @@ export function createSleep(ctx: WorkflowOrchestratorContext) { ctx.invocationsQueue.delete(correlationId); // This `wait_completed` is a branch-deciding resolution the workflow - // may `Promise.race` against a hook payload. Order it deterministically - // by event-log position (see `pendingDeliveryBarriers`): + // may `Promise.race` against a hook payload, or await on a branch + // parallel to one awaiting a step. Order it deterministically by + // event-log position (see `pendingDeliveryBarriers`): // - Register a 'wait' barrier at this event's index so a LATER-in-log - // hook payload is delivered only after this wait. - // - Before resolving, defer behind every EARLIER-in-log HOOK delivery - // so this wait does not preempt a hook the committed log ordered - // first. Then mark this wait delivered to release later hooks. + // hook payload or step result is delivered only after this wait. + // - Before resolving, defer behind every EARLIER-in-log HOOK and STEP + // delivery so this wait does not preempt one the committed log + // ordered first. Then mark this wait delivered to release the later + // deliveries gated on it. const eventIndex = ctx.eventsConsumer.eventIndex; const barrier = registerDeliveryBarrier(ctx, eventIndex, 'wait'); + // The deferral is captured HERE, while consuming the event, and not + // after the queue tail below — same reasoning as step.ts. An earlier + // step or hook whose hydration slot sits in that tail has usually + // delivered, and so deregistered its barrier, by the time the tail + // resolves. Read then, it would be invisible and this wait would skip + // both the gate AND `awaitEarlierDeliveries`' macrotask yield, letting + // it overtake the branch that earlier delivery just woke. Every event + // in one drain window is consumed before any slot runs, so capturing + // at consumption time sees all of them. + const earlierDelivered = awaitEarlierDeliveries( + ctx, + eventIndex, + 'wait' + ); // Defer + resolve in a DETACHED promise (not chained onto the serial // `promiseQueue`). `awaitEarlierDeliveries` may wait on an earlier - // hook delivery whose own resolution is itself driven by the + // hook or step delivery whose own resolution is itself driven by the // promiseQueue; blocking a queue slot on it would deadlock the serial // queue. We still anchor to the queue tail first so prior queued // hydration/ordering work runs in event-log order. const queueAtCompletion = ctx.promiseQueue; void queueAtCompletion - .then(() => awaitEarlierDeliveries(ctx, eventIndex, ['hook'])) + .then(() => earlierDelivered) .then(() => { barrier.markDelivered(); resolve(); diff --git a/packages/errors/src/index.ts b/packages/errors/src/index.ts index 3e0700053f..f5543c3a82 100644 --- a/packages/errors/src/index.ts +++ b/packages/errors/src/index.ts @@ -786,22 +786,34 @@ export class ThrottleError extends WorkflowWorldError { /** * Thrown when the backend rejects an event creation because the client's - * event-log snapshot is stale — a newer out-of-band event (e.g. a received - * hook or a completed step) was recorded after the snapshot the client - * replayed from (HTTP 412). + * event-log snapshot is stale — the log the client replayed from is missing + * an event the backend has already recorded (HTTP 412). * - * The workflow runtime handles this automatically: it reloads the event log - * and retries, ultimately re-enqueueing the run if it cannot catch up. Users - * interacting with world storage backends directly may encounter it. + * The workflow runtime handles this automatically: it restarts the replay from + * a corrected event log, ultimately re-enqueueing the run if it cannot catch + * up. Users interacting with world storage backends directly may encounter it. * * @property retryAfter - Delay in seconds before retrying. Accepted for - * forward-compatibility; the runtime currently reloads and retries - * immediately and does not read this field. + * forward-compatibility; the runtime restarts its replay immediately and + * does not read this field. + * @property details - Optional rejection detail supplied by the World. A World + * MAY attach the events the client's snapshot was missing so the client can + * correct its log without a follow-up fetch; see the `stateCursor` contract + * on `CreateEventParams`. Typed `unknown` because this package cannot depend + * on the event type — consumers narrow it themselves and must treat a + * missing or malformed value as "no detail" (a full reload is always + * correct). */ export class PreconditionFailedError extends WorkflowWorldError { - constructor(message: string, options?: { retryAfter?: number }) { + readonly details?: unknown; + + constructor( + message: string, + options?: { retryAfter?: number; details?: unknown } + ) { super(message, { status: 412, retryAfter: options?.retryAfter }); this.name = 'PreconditionFailedError'; + this.details = options?.details; } static is(value: unknown): value is PreconditionFailedError { diff --git a/packages/world-vercel/src/event-coerce.ts b/packages/world-vercel/src/event-coerce.ts new file mode 100644 index 0000000000..eb9ca34ed2 --- /dev/null +++ b/packages/world-vercel/src/event-coerce.ts @@ -0,0 +1,42 @@ +/** + * Shared event-decoding helper. + * + * Lives in its own module because both `events.ts` (which owns the public + * event functions) and `events-v4.ts` (the wire-level client, imported *by* + * `events.ts`) need it — putting it in `events.ts` would make that import + * circular. + */ + +import { type Event, EventSchema, EventTypeSchema } from '@workflow/world'; + +/** + * Run an assembled event through EventSchema so per-event-type + * z.coerce.date() (wait_created.resumeAt, wait_completed.resumeAt, + * step_retrying.retryAfter) converts the ISO strings the backing store + * returns back into Date instances — the workflow runtime calls .getTime() on + * these and would otherwise crash. safeParse: pass the event through + * unchanged if it doesn't match a known shape (legacy / mid-rollout). + * + * Used by every path that hands events to the runtime: GET/LIST frames + * (via buildEventFromV4), the POST response's `event` / preloaded `events` + * bag, and the events a rejecting backend attaches to a 412 — all of these + * can carry events read back from the backing store, where nested eventData + * dates are stored as ISO strings. + */ +export function coerceEventDates(raw: Record): Event { + const parsed = EventSchema.safeParse(raw); + if (parsed.success) return parsed.data as unknown as Event; + if (EventTypeSchema.safeParse(raw.eventType).success) { + // The raw-event fallback is for unknown/future event types. A parse + // failure on a *known* type means a schema/coercion regression that + // would otherwise only surface later as a crash deep in the runtime + // (e.g. .getTime() on a resumeAt that stayed a string) — leave a + // breadcrumb at the actual failure point. + console.debug( + `[workflow:world-vercel] v4 event ${raw.eventId} failed ` + + `EventSchema parse for known eventType '${raw.eventType}'; ` + + `passing through unparsed: ${parsed.error.message}` + ); + } + return raw as unknown as Event; +} diff --git a/packages/world-vercel/src/events-v4.test.ts b/packages/world-vercel/src/events-v4.test.ts index 24746c2a30..cb5c52942d 100644 --- a/packages/world-vercel/src/events-v4.test.ts +++ b/packages/world-vercel/src/events-v4.test.ts @@ -1,5 +1,6 @@ import { EntityConflictError, + PreconditionFailedError, RunExpiredError, ThrottleError, TooEarlyError, @@ -8,13 +9,13 @@ import { import { decode, encode } from 'cbor-x'; import { MockAgent } from 'undici'; import { afterEach, describe, expect, it, vi } from 'vitest'; +import { splitEventDataForV4 } from './events.js'; import { createWorkflowRunEventV4, getEventV4, getWorkflowRunEventsV4, throwForErrorResponse, } from './events-v4.js'; -import { splitEventDataForV4 } from './events.js'; import { encodeFrame, V4_FRAME_CONTENT_TYPE } from './frames.js'; import { WORKFLOW_SERVER_URL_OVERRIDE } from './utils.js'; @@ -271,7 +272,8 @@ describe('getWorkflowRunEventsV4 over HTTP', () => { */ describe('getEventV4 over HTTP', () => { it('returns the first frame and stops reading the rest', async () => { - const origin = 'https://vercel-workflow.com'; + const origin = + WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; const agent = new MockAgent(); agent.disableNetConnect(); @@ -507,8 +509,116 @@ describe('createWorkflowRunEventV4 over HTTP', () => { agent.assertNoPendingInterceptors(); }); + it('surfaces the events a 412 carries as decoded PreconditionFailedError details', async () => { + // A rejecting backend MAY return the events the client was missing, so the + // replay restart needs no events.list round trip. They arrive as JSON, so + // nested dates must come back as Date instances or the runtime crashes on + // .getTime() deep in the replay. + const origin = + WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; + const agent = new MockAgent(); + agent.disableNetConnect(); + + agent + .get(origin) + .intercept({ + path: '/api/v4/runs/wrun_1/events/wait_created', + method: 'POST', + }) + .reply( + 412, + JSON.stringify({ + success: false, + error: 'precondition-failed', + code: 'precondition-failed', + message: 'Run state is stale', + cursor: 'eid:evnt_missing', + events: [ + { + eventId: 'evnt_missing', + runId: 'wrun_1', + eventType: 'wait_created', + correlationId: 'wait_0', + specVersion: 5, + createdAt: '2026-06-10T00:00:00.000Z', + eventData: { resumeAt: '2026-06-10T00:00:05.000Z' }, + }, + ], + }), + { headers: { 'content-type': 'application/json' } } + ); + + const error = await createWorkflowRunEventV4( + { + runId: 'wrun_1', + eventType: 'wait_created', + specVersion: 5, + correlationId: 'wait_1', + stateUpdatedAt: 1747742400000, + stateEventCount: 3, + stateCursor: 'eid:evnt_3', + }, + { token: 'test-token', dispatcher: agent } + ).catch((err: unknown) => err); + + expect(PreconditionFailedError.is(error)).toBe(true); + const details = (error as PreconditionFailedError).details as { + events: Array<{ + eventId: string; + eventData: { resumeAt: unknown }; + }>; + cursor?: string; + }; + expect(details.cursor).toBe('eid:evnt_missing'); + expect(details.events).toHaveLength(1); + expect(details.events[0]?.eventId).toBe('evnt_missing'); + expect(details.events[0]?.eventData.resumeAt).toBeInstanceOf(Date); + agent.assertNoPendingInterceptors(); + }); + + it('ignores a 412 payload whose events do not narrow to events', async () => { + const origin = + WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; + const agent = new MockAgent(); + agent.disableNetConnect(); + + agent + .get(origin) + .intercept({ + path: '/api/v4/runs/wrun_1/events/wait_created', + method: 'POST', + }) + .reply( + 412, + JSON.stringify({ + success: false, + code: 'precondition-failed', + message: 'Run state is stale', + events: [{ noEventId: true }], + }), + { headers: { 'content-type': 'application/json' } } + ); + + const error = await createWorkflowRunEventV4( + { + runId: 'wrun_1', + eventType: 'wait_created', + specVersion: 5, + correlationId: 'wait_1', + }, + { token: 'test-token', dispatcher: agent } + ).catch((err: unknown) => err); + + expect(PreconditionFailedError.is(error)).toBe(true); + // Untrusted data on a failure path: dropped whole, so the client falls + // back to the authoritative full reload. + expect((error as PreconditionFailedError).details).toBeUndefined(); + agent.assertNoPendingInterceptors(); + }); + it('forwards stateUpdatedAt in the frame meta (precondition guard)', async () => { - const origin = 'https://vercel-workflow.com'; + const origin = + WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; const agent = new MockAgent(); agent.disableNetConnect(); @@ -559,8 +669,117 @@ describe('createWorkflowRunEventV4 over HTTP', () => { agent.assertNoPendingInterceptors(); }); + it('forwards stateEventCount and stateCursor in the frame meta', async () => { + const origin = + WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; + const agent = new MockAgent(); + agent.disableNetConnect(); + + let capturedMeta: Record | undefined; + agent + .get(origin) + .intercept({ + path: '/api/v4/runs/wrun_1/events/wait_created', + method: 'POST', + }) + .reply( + 200, + (opts: { body?: unknown }) => { + const bytes = new Uint8Array(opts.body as ArrayBufferLike); + const metaLen = new DataView( + bytes.buffer, + bytes.byteOffset, + bytes.byteLength + ).getUint32(0, false); + capturedMeta = decode(bytes.subarray(4, 4 + metaLen)) as Record< + string, + unknown + >; + return encode({ wait: { waitId: 'wait_1' } }); + }, + { + headers: { + 'x-wf-event-id': 'evnt_1', + 'x-wf-run-id': 'wrun_1', + 'x-wf-created-at': '2026-06-10T00:00:00.000Z', + }, + } + ); + + await createWorkflowRunEventV4( + { + runId: 'wrun_1', + eventType: 'wait_created', + specVersion: 5, + correlationId: 'wait_1', + stateUpdatedAt: 1747742400000, + stateEventCount: 12, + stateCursor: 'eid:evnt_1', + }, + { token: 'test-token', dispatcher: agent } + ); + + expect(capturedMeta?.stateEventCount).toBe(12); + expect(capturedMeta?.stateCursor).toBe('eid:evnt_1'); + agent.assertNoPendingInterceptors(); + }); + + it('omits stateEventCount and stateCursor from the frame meta when not set', async () => { + const origin = + WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; + const agent = new MockAgent(); + agent.disableNetConnect(); + + let capturedMeta: Record | undefined; + agent + .get(origin) + .intercept({ + path: '/api/v4/runs/wrun_1/events/wait_created', + method: 'POST', + }) + .reply( + 200, + (opts: { body?: unknown }) => { + const bytes = new Uint8Array(opts.body as ArrayBufferLike); + const metaLen = new DataView( + bytes.buffer, + bytes.byteOffset, + bytes.byteLength + ).getUint32(0, false); + capturedMeta = decode(bytes.subarray(4, 4 + metaLen)) as Record< + string, + unknown + >; + return encode({ wait: { waitId: 'wait_1' } }); + }, + { + headers: { + 'x-wf-event-id': 'evnt_1', + 'x-wf-run-id': 'wrun_1', + 'x-wf-created-at': '2026-06-10T00:00:00.000Z', + }, + } + ); + + await createWorkflowRunEventV4( + { + runId: 'wrun_1', + eventType: 'wait_created', + specVersion: 5, + correlationId: 'wait_1', + stateUpdatedAt: 1747742400000, + }, + { token: 'test-token', dispatcher: agent } + ); + + expect('stateEventCount' in (capturedMeta ?? {})).toBe(false); + expect('stateCursor' in (capturedMeta ?? {})).toBe(false); + agent.assertNoPendingInterceptors(); + }); + it('omits stateUpdatedAt from the frame meta when not set', async () => { - const origin = 'https://vercel-workflow.com'; + const origin = + WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; const agent = new MockAgent(); agent.disableNetConnect(); diff --git a/packages/world-vercel/src/events-v4.ts b/packages/world-vercel/src/events-v4.ts index e0556e092b..e022bf0e5a 100644 --- a/packages/world-vercel/src/events-v4.ts +++ b/packages/world-vercel/src/events-v4.ts @@ -21,7 +21,9 @@ * bytes — this module stays at the wire-bytes layer. */ +import type { Event } from '@workflow/world'; import { decode } from 'cbor-x'; +import { coerceEventDates } from './event-coerce.js'; import { decodeFrames, encodeFrame, V4_FRAME_CONTENT_TYPE } from './frames.js'; import { getEventsDispatcher } from './http-client.js'; import { @@ -207,6 +209,34 @@ export interface CreateEventV4Input { * without a loaded event log; older servers ignore it entirely. */ stateUpdatedAt?: number; + /** + * Number of loaded events at or below `stateUpdatedAt` (i.e. the loaded + * log's length). Sent with `stateUpdatedAt` so the backend can also reject + * a snapshot that is *missing* an event at or below its watermark — the + * corruption case a watermark alone cannot detect. Older servers ignore it. + */ + stateEventCount?: number; + /** + * The runtime's event-log cursor at snapshot time. Advisory: sent so a + * rejecting backend MAY return the missing events on the 412 body, saving a + * follow-up events.list. Distinct from `sinceCursor`, which the server acts + * on for the *accepted* path. + */ + stateCursor?: string; +} + +/** + * Shape the v4 client attaches to `PreconditionFailedError.details` when a + * rejecting server returned the missing events inline. `@workflow/errors` + * types `details` as `unknown` (it cannot depend on the event type), so + * consumers narrow structurally — this interface is the contract they narrow + * to. + */ +export interface PreconditionFailureDetails { + /** The events the client's snapshot was missing, in server order. */ + events: Event[]; + /** Cursor positioned after the returned events, when the server sent one. */ + cursor?: string; } export interface CreateEventV4Result { @@ -305,6 +335,10 @@ function buildPostFrameMeta( if (input.stateUpdatedAt !== undefined) { meta.stateUpdatedAt = input.stateUpdatedAt; } + if (input.stateEventCount !== undefined) { + meta.stateEventCount = input.stateEventCount; + } + if (input.stateCursor !== undefined) meta.stateCursor = input.stateCursor; return meta; } @@ -326,10 +360,17 @@ function errorFromV4Response( ): Error { let message = `v4 ${opName} failed: HTTP ${statusCode}`; let code: string | undefined; + let details: unknown; try { - const json = JSON.parse(errorBody) as { message?: string; code?: string }; + const json = JSON.parse(errorBody) as { + message?: string; + code?: string; + events?: unknown; + cursor?: unknown; + }; if (typeof json.message === 'string') message = json.message; if (typeof json.code === 'string') code = json.code; + if (statusCode === 412) details = decodePreconditionDetails(json); } catch { // body wasn't JSON — keep the default message, append raw text below if (errorBody) message += ` ${errorBody}`; @@ -345,9 +386,45 @@ function errorFromV4Response( code, url, mitigated: readHeader(responseHeaders, 'x-vercel-mitigated'), + ...(details !== undefined ? { details } : {}), }); } +/** + * Pick the inline event delta off a 412 body. + * + * A rejecting server MAY attach the events the client's snapshot was missing, + * so the runtime can correct its event log without a follow-up events.list. + * The *presence* of `events` is the server's completeness signal — it omits + * them entirely when it cannot prove the set accounts for the whole + * discrepancy — which also means an older or non-supporting server produces + * the same "no delta" shape as one that declined to prove it, and the client + * needs a single fallback path for both. + * + * Anything unexpected in the payload is dropped rather than repaired: this is + * untrusted-shaped data on a failure path, and the fallback (a full reload) is + * always correct. + */ +function decodePreconditionDetails(json: { + events?: unknown; + cursor?: unknown; +}): PreconditionFailureDetails | undefined { + if (!Array.isArray(json.events) || json.events.length === 0) return undefined; + const events: Event[] = []; + for (const raw of json.events) { + if (typeof raw !== 'object' || raw === null) return undefined; + const candidate = raw as Record; + if (typeof candidate.eventId !== 'string') return undefined; + // Same decoder the success-path delta uses: the JSON body carries nested + // eventData dates as ISO strings and the runtime calls .getTime() on them. + events.push(coerceEventDates(candidate)); + } + return { + events, + ...(typeof json.cursor === 'string' ? { cursor: json.cursor } : {}), + }; +} + /** * Throwing wrapper around `errorFromV4Response`. Exported for unit tests; the * request paths throw via `instrumentedFetch`'s `buildError`. diff --git a/packages/world-vercel/src/events.test.ts b/packages/world-vercel/src/events.test.ts index f78845fdaf..fe342219ff 100644 --- a/packages/world-vercel/src/events.test.ts +++ b/packages/world-vercel/src/events.test.ts @@ -115,13 +115,15 @@ describe('createWorkflowRunEvent with v1Compat', () => { }); /** - * The optimistic-concurrency precondition guard (see runtime/helpers.ts - * withPreconditionRetry): a replay-context create carries `stateUpdatedAt` - * (the ULID time of the latest event the runtime has loaded) so the backend - * can reject a stale write with 412. Locks in that the field reaches the v4 - * frame meta, and is omitted entirely when the caller has no loaded snapshot. + * The optimistic-concurrency precondition guard: a replay-context create + * describes the runtime's loaded snapshot with three params — `stateUpdatedAt` + * (the ULID time of the latest loaded event), `stateEventCount` (how many + * events that snapshot holds at or below it) and `stateCursor` (so a rejecting + * backend may return the missing events inline). Locks in that each reaches + * the v4 frame meta, and that all are omitted when the caller has no loaded + * snapshot — an unsent field disables the corresponding backend check. */ -describe('createWorkflowRunEvent stateUpdatedAt wire field', () => { +describe('createWorkflowRunEvent precondition snapshot wire fields', () => { it('includes stateUpdatedAt in the v4 frame meta when provided', async () => { const agent = mockAgent(); let capturedMeta: Record | undefined; @@ -193,6 +195,137 @@ describe('createWorkflowRunEvent stateUpdatedAt wire field', () => { expect('stateUpdatedAt' in (capturedMeta ?? {})).toBe(false); agent.assertNoPendingInterceptors(); }); + + it('includes stateEventCount and stateCursor in the v4 frame meta when provided', async () => { + const agent = mockAgent(); + let capturedMeta: Record | undefined; + + agent + .get(ORIGIN) + .intercept({ + path: '/api/v4/runs/wrun_1/events/run_started', + method: 'POST', + }) + .reply( + 200, + (opts: { body?: unknown }) => { + capturedMeta = decodePostedMeta(opts.body); + return encode({ run: { runId: 'wrun_1', status: 'running' } }); + }, + { + headers: { + 'x-wf-event-id': 'evnt_1', + 'x-wf-run-id': 'wrun_1', + 'x-wf-created-at': '2026-06-10T00:00:00.000Z', + }, + } + ); + + await createWorkflowRunEvent( + 'wrun_1', + { eventType: 'run_started', specVersion: 2 } as AnyEventRequest, + { + stateUpdatedAt: 1_700_000_000_000, + stateEventCount: 7, + stateCursor: 'eid:evnt_1', + }, + { token: 'test-token', dispatcher: agent } + ); + + expect(capturedMeta?.stateEventCount).toBe(7); + expect(capturedMeta?.stateCursor).toBe('eid:evnt_1'); + agent.assertNoPendingInterceptors(); + }); + + it('omits stateEventCount and stateCursor from the v4 frame meta when not provided', async () => { + const agent = mockAgent(); + let capturedMeta: Record | undefined; + + agent + .get(ORIGIN) + .intercept({ + path: '/api/v4/runs/wrun_1/events/run_started', + method: 'POST', + }) + .reply( + 200, + (opts: { body?: unknown }) => { + capturedMeta = decodePostedMeta(opts.body); + return encode({ run: { runId: 'wrun_1', status: 'running' } }); + }, + { + headers: { + 'x-wf-event-id': 'evnt_1', + 'x-wf-run-id': 'wrun_1', + 'x-wf-created-at': '2026-06-10T00:00:00.000Z', + }, + } + ); + + await createWorkflowRunEvent( + 'wrun_1', + { eventType: 'run_started', specVersion: 2 } as AnyEventRequest, + { stateUpdatedAt: 1_700_000_000_000 }, + { token: 'test-token', dispatcher: agent } + ); + + expect('stateEventCount' in (capturedMeta ?? {})).toBe(false); + expect('stateCursor' in (capturedMeta ?? {})).toBe(false); + agent.assertNoPendingInterceptors(); + }); + + it('never sends the snapshot on the legacy v1Compat path', async () => { + // Pre-event-sourcing runs have no event log to fence, and the legacy + // endpoint has no field for the snapshot: the params are dropped whole. + const agent = mockAgent(); + let capturedBody = ''; + + agent + .get(ORIGIN) + .intercept({ path: '/api/v1/runs/wrun_legacy/events', method: 'POST' }) + .reply( + 200, + (opts: { body?: unknown }) => { + capturedBody = + typeof opts.body === 'string' + ? opts.body + : new TextDecoder().decode(opts.body as ArrayBufferLike); + return { + eventId: 'evnt_legacy', + runId: 'wrun_legacy', + eventType: 'wait_completed', + correlationId: 'wait_1', + createdAt: '2026-06-10T00:00:00.000Z', + specVersion: 1, + eventData: { resumeAt: '2026-06-10T00:00:00.000Z' }, + }; + }, + { headers: { 'content-type': 'application/json' } } + ); + + await createWorkflowRunEvent( + 'wrun_legacy', + { + eventType: 'wait_completed', + correlationId: 'wait_1', + specVersion: 1, + eventData: { resumeAt: '2026-06-10T00:00:00.000Z' }, + } as AnyEventRequest, + { + v1Compat: true, + stateUpdatedAt: 1_700_000_000_000, + stateEventCount: 7, + stateCursor: 'eid:evnt_1', + }, + { token: 'test-token', dispatcher: agent } + ); + + expect(capturedBody).toContain('wait_completed'); + expect(capturedBody).not.toContain('stateUpdatedAt'); + expect(capturedBody).not.toContain('stateEventCount'); + expect(capturedBody).not.toContain('stateCursor'); + agent.assertNoPendingInterceptors(); + }); }); /** diff --git a/packages/world-vercel/src/events.ts b/packages/world-vercel/src/events.ts index 3e13e301c6..19d684770b 100644 --- a/packages/world-vercel/src/events.ts +++ b/packages/world-vercel/src/events.ts @@ -40,7 +40,6 @@ import { type EventDataPayloadField, type EventResult, EventSchema, - EventTypeSchema, type GetEventParams, getEventDataPayloadField, isHookEventRequiringExistence, @@ -53,6 +52,7 @@ import { type WorkflowRun, } from '@workflow/world'; import { decode } from 'cbor-x'; +import { coerceEventDates } from './event-coerce.js'; import { withEventPostRetry } from './event-retry.js'; import { createWorkflowRunEventV4, @@ -430,37 +430,6 @@ export function splitEventDataForV4(data: AnyEventRequest): SplitEventData { return { payload, meta }; } -/** - * Run an assembled event through EventSchema so per-event-type - * z.coerce.date() (wait_created.resumeAt, wait_completed.resumeAt, - * step_retrying.retryAfter) converts the ISO strings the backing store - * returns back into Date instances — the workflow runtime calls .getTime() on - * these and would otherwise crash. safeParse: pass the event through - * unchanged if it doesn't match a known shape (legacy / mid-rollout). - * - * Used by every path that hands events to the runtime: GET/LIST frames - * (via buildEventFromV4) and the POST response's `event` / preloaded - * `events` bag — all of these can carry events read back from the - * backing store, where nested eventData dates are stored as ISO strings. - */ -function coerceEventDates(raw: Record): Event { - const parsed = EventSchema.safeParse(raw); - if (parsed.success) return parsed.data as unknown as Event; - if (EventTypeSchema.safeParse(raw.eventType).success) { - // The raw-event fallback is for unknown/future event types. A parse - // failure on a *known* type means a schema/coercion regression that - // would otherwise only surface later as a crash deep in the runtime - // (e.g. .getTime() on a resumeAt that stayed a string) — leave a - // breadcrumb at the actual failure point. - console.debug( - `[workflow:world-vercel] v4 event ${raw.eventId} failed ` + - `EventSchema parse for known eventType '${raw.eventType}'; ` + - `passing through unparsed: ${parsed.error.message}` - ); - } - return raw as unknown as Event; -} - function coerceNormalizedEvent(raw: Record): Event { return coerceEventDates(normalizeEventData(raw)); } @@ -705,9 +674,17 @@ async function createWorkflowRunEventInner( specVersion: data.specVersion ?? 2, ...(data.correlationId ? { correlationId: data.correlationId } : {}), ...(params?.requestId ? { vercelId: params.requestId } : {}), + // Precondition snapshot. The three fields describe one snapshot and the + // runtime always sends them together (or not at all); each is spread + // independently only so an older server that knows one but not the + // others still gets what it understands. ...(params?.stateUpdatedAt !== undefined ? { stateUpdatedAt: params.stateUpdatedAt } : {}), + ...(params?.stateEventCount !== undefined + ? { stateEventCount: params.stateEventCount } + : {}), + ...(params?.stateCursor ? { stateCursor: params.stateCursor } : {}), occurredAt: params?.occurredAt ?? new Date(), // Opt-in inline-delta: forward the cursor the runtime held before // this write so the server can return the authoritative event-log diff --git a/packages/world-vercel/src/http-core.ts b/packages/world-vercel/src/http-core.ts index e8405c4002..7a31201024 100644 --- a/packages/world-vercel/src/http-core.ts +++ b/packages/world-vercel/src/http-core.ts @@ -158,8 +158,9 @@ export function parseRetryAfter( * * - 409 → EntityConflictError (start() dedupe, terminal-state transitions) * - 410 → RunExpiredError (runtime exits without retrying) - * - 412 → PreconditionFailedError + retryAfter (stale `stateUpdatedAt` - * snapshot — the optimistic-concurrency guard on event creation) + * - 412 → PreconditionFailedError + retryAfter + details (stale precondition + * snapshot — the optimistic-concurrency guard on event creation; `details` + * carries the events the backend returned inline, when it did) * - 425 → TooEarlyError + retryAfter (step retry pacing — see #1806 for what * happens when a 425 degrades into an untyped error) * - 429 → ThrottleError + retryAfter, EXCEPT a firewall challenge (429 + @@ -179,13 +180,17 @@ export function errorForResponse( code?: string; url?: string; mitigated?: string | null; + /** Rejection detail for a 412 — the events the backend says the client's + * snapshot was missing, when it returned them inline. Ignored for every + * other status. */ + details?: unknown; } = {} ): Error { - const { retryAfter, code, url, mitigated } = opts; + const { retryAfter, code, url, mitigated, details } = opts; if (status === 409) return new EntityConflictError(message); if (status === 410) return new RunExpiredError(message); if (status === 412) - return new PreconditionFailedError(message, { retryAfter }); + return new PreconditionFailedError(message, { retryAfter, details }); if (status === 425) return new TooEarlyError(message, { retryAfter }); if (status === 429) { // A firewall challenge can't be solved by a server-to-server client, so map diff --git a/packages/world-vercel/src/utils.ts b/packages/world-vercel/src/utils.ts index 60157de448..ef65a120ad 100644 --- a/packages/world-vercel/src/utils.ts +++ b/packages/world-vercel/src/utils.ts @@ -32,7 +32,11 @@ import { version } from './version.js'; * `main` — rewritten by external CI for branch-deployment testing. * Prefer `VERCEL_WORKFLOW_SERVER_URL` for deployment-time configuration. */ -export const WORKFLOW_SERVER_URL_OVERRIDE = ''; +// TEMPORARY — do not merge. Points CI e2e at the backend branch that indexes +// every event a create request persists, so the event-count guard is armed for +// these runs. Revert to '' before this PR leaves draft. +export const WORKFLOW_SERVER_URL_OVERRIDE = + 'https://workflow-server-git-peter-event-index-completeness.vercel.sh'; /** * HTTP methods that are safe to transparently re-issue inside the adapter. diff --git a/packages/world/src/events.ts b/packages/world/src/events.ts index 2a581f76bf..ffbebd25e9 100644 --- a/packages/world/src/events.ts +++ b/packages/world/src/events.ts @@ -722,8 +722,63 @@ export interface CreateEventParams { * timestamp must pass (anti-livelock, so an up-to-date client is never * rejected). A backend that ignores this field simply disables the guard — * the client falls open and behaves as before. + * + * A watermark alone cannot see an event *missing at or below* it, which is + * the failure that actually corrupts a replay — see {@link stateEventCount} + * for the second half of the guard. */ stateUpdatedAt?: number; + /** + * How many loaded events have a ULID time at or below {@link stateUpdatedAt}. + * Since `stateUpdatedAt` is the *maximum* ULID time in the loaded log, this + * equals the loaded array's length. Sent **only** together with + * `stateUpdatedAt`; a World must ignore a count that arrives without one. + * + * This closes the hole a watermark cannot: the watermark proves only "no + * newer event exists", while a replay corrupts its log by missing an event + * at or *below* its own frontier — a concurrent writer commits in the same + * ULID millisecond as the client's last loaded event, so the two watermarks + * compare equal and the write is accepted against a log that is one event + * short. Because correlation IDs are positional ordinals of a single seeded + * sequence, that one-event difference renames every entity after it. + * + * Backend contract (for World implementers who want to support this half): + * + * - Count **every** created event for the run, including replay-origin ones. + * Unlike the watermark, this is not restricted to out-of-band writes: the + * race being fenced is one replay against another. + * - Reject with 412 when the count of recorded events at ULID time + * `<= stateUpdatedAt` is strictly **greater** than `stateEventCount`. + * - Compare **at or below** `stateUpdatedAt`, never strictly below (the + * missing event routinely shares the client's frontier millisecond) and + * never against a total (all the creates of one suspension share one + * snapshot, so a total would reject every sibling after the first). + * - **One-sided safety is mandatory.** Anything that makes the backend's + * count incomplete, uncomputable, or expired must *allow* the write. A + * rejection has to imply a real hole, because the client responds to it by + * discarding and re-deriving its whole replay. + * + * See also the millisecond-granularity caveat on `stateUpdatedAt`: the count + * is what makes an equal-timestamp snapshot safe to accept. + */ + stateEventCount?: number; + /** + * The client's current event-log cursor (advisory). Sent alongside the other + * two snapshot fields so a World that rejects the write MAY return the + * events the client is missing on the 412 itself, saving the client a + * follow-up `events.list`. + * + * Distinct from {@link sinceCursor}: a World must **not** compute a delta for + * this on the accepted path — it exists purely to make a rejection cheaper. + * Returning events on a 412 is OPTIONAL, and the returned set must be + * provably complete (it must account for the entire discrepancy the + * rejection reported) or omitted entirely: a cursor filters by lexicographic + * event id while a hole is defined by ULID time, so a naive + * "everything after the cursor" delta can silently exclude the very event + * the client is missing. A client that receives nothing does the + * authoritative full reload, which is always correct. + */ + stateCursor?: string; /** * Timestamp for when the event occurred on the client side. Worlds that * support this can persist it separately from `createdAt`, which represents diff --git a/packages/world/src/interfaces.ts b/packages/world/src/interfaces.ts index e42ca866e0..b445028088 100644 --- a/packages/world/src/interfaces.ts +++ b/packages/world/src/interfaces.ts @@ -329,6 +329,15 @@ export interface WorldCapabilities { * ignore `stateUpdatedAt` must leave this unset so runtime optimizations * that rely on the 412 fence (see `WORKFLOW_PRECONDITION_GUARD`) are not * enabled without an actual fence behind them. + * + * A World declaring this should honour the whole snapshot the runtime sends, + * not just the watermark: `stateUpdatedAt`, `stateEventCount` (the count + * fence, which catches an event missing at or below the watermark — the case + * the watermark provably cannot see) and, optionally, `stateCursor` (return + * the missing events on the 412 to save the client a reload). See + * `CreateEventParams` for each field's contract. The runtime does not branch + * on which halves are implemented; a World that ignores the count simply + * fences less. */ preconditionGuard?: boolean; diff --git a/workbench/nextjs-turbopack/vercel.json b/workbench/nextjs-turbopack/vercel.json index aa4f892410..84a70f79c3 100644 --- a/workbench/nextjs-turbopack/vercel.json +++ b/workbench/nextjs-turbopack/vercel.json @@ -1,6 +1,12 @@ { + "build": { + "env": { + "WORKFLOW_SEQUENTIAL_REPLAYS": "1" + } + }, "env": { - "WORKFLOW_PUBLIC_MANIFEST": "1" + "WORKFLOW_PUBLIC_MANIFEST": "1", + "WORKFLOW_SEQUENTIAL_REPLAYS": "1" }, "regions": [ "iad1",