diff --git a/.changeset/inline-claim-reclaim.md b/.changeset/inline-claim-reclaim.md new file mode 100644 index 0000000000..9d57541efc --- /dev/null +++ b/.changeset/inline-claim-reclaim.md @@ -0,0 +1,5 @@ +--- +'@workflow/core': patch +--- + +Keep a batch of inline steps together when one of its event writes loses a race, instead of discarding the batch diff --git a/.changeset/late-hook-delivery-divergence.md b/.changeset/late-hook-delivery-divergence.md new file mode 100644 index 0000000000..ab62353ca8 --- /dev/null +++ b/.changeset/late-hook-delivery-divergence.md @@ -0,0 +1,6 @@ +--- +'@workflow/core': patch +'workflow': patch +--- + +Stop failing runs with a corrupted-event-log error when a hook delivery arrives after the hook was disposed, or when a step result is still being fetched diff --git a/.changeset/local-slot-order.md b/.changeset/local-slot-order.md new file mode 100644 index 0000000000..148f7df032 --- /dev/null +++ b/.changeset/local-slot-order.md @@ -0,0 +1,5 @@ +--- +'@workflow/world-local': patch +--- + +Read a position-numbered event log in position order, so a replay sees the log the order it was written diff --git a/.changeset/precondition-restart-backoff.md b/.changeset/precondition-restart-backoff.md new file mode 100644 index 0000000000..8e739cd8f0 --- /dev/null +++ b/.changeset/precondition-restart-backoff.md @@ -0,0 +1,6 @@ +--- +'@workflow/core': patch +'workflow': patch +--- + +Space out in-process replay restarts with a randomized backoff so concurrent replays of one run stop contending in lockstep diff --git a/.changeset/slimy-weeks-act.md b/.changeset/slimy-weeks-act.md new file mode 100644 index 0000000000..a845151cc8 --- /dev/null +++ b/.changeset/slimy-weeks-act.md @@ -0,0 +1,2 @@ +--- +--- diff --git a/.changeset/slot-claims-tail-tight.md b/.changeset/slot-claims-tail-tight.md new file mode 100644 index 0000000000..346b2c92de --- /dev/null +++ b/.changeset/slot-claims-tail-tight.md @@ -0,0 +1,7 @@ +--- +'@workflow/core': patch +'@workflow/world-local': patch +'@workflow/world-postgres': patch +--- + +Take event slot claims one at a time against the event log's tail, so a replay that decided from a log missing an event is rejected instead of committing. diff --git a/.changeset/slot-duplicate-start-skip.md b/.changeset/slot-duplicate-start-skip.md new file mode 100644 index 0000000000..fc434c6abf --- /dev/null +++ b/.changeset/slot-duplicate-start-skip.md @@ -0,0 +1,6 @@ +--- +'@workflow/core': patch +'workflow': patch +--- + +Skip a step whose concurrent start another handler already wrote, instead of restarting the replay to rediscover it diff --git a/.changeset/slot-event-identity-worlds.md b/.changeset/slot-event-identity-worlds.md new file mode 100644 index 0000000000..863a2f860b --- /dev/null +++ b/.changeset/slot-event-identity-worlds.md @@ -0,0 +1,8 @@ +--- +'@workflow/world': minor +'@workflow/world-local': minor +'@workflow/world-postgres': minor +'@workflow/core': minor +--- + +Number a run's events by position in the Local and Postgres Worlds when `WORKFLOW_SLOT_IDENTITY` is set, so a reader can prove its copy of an event log is complete. diff --git a/.changeset/slot-identity-default-on.md b/.changeset/slot-identity-default-on.md new file mode 100644 index 0000000000..55e3973586 --- /dev/null +++ b/.changeset/slot-identity-default-on.md @@ -0,0 +1,8 @@ +--- +'@workflow/world': minor +'@workflow/world-vercel': minor +'@workflow/world-local': minor +'@workflow/world-postgres': minor +--- + +Number new runs' events by position by default, in every World including the Vercel one. Set `WORKFLOW_SLOT_IDENTITY=0` to keep minting ULID event ids. diff --git a/.changeset/slot-restart-budget.md b/.changeset/slot-restart-budget.md new file mode 100644 index 0000000000..6a4c52c909 --- /dev/null +++ b/.changeset/slot-restart-budget.md @@ -0,0 +1,6 @@ +--- +'@workflow/core': patch +'workflow': patch +--- + +Let a run that numbers its events by position absorb more concurrent-write rejections in one invocation, instead of falling back to a delayed re-invocation diff --git a/.changeset/slot-restart-cursor-top-up.md b/.changeset/slot-restart-cursor-top-up.md new file mode 100644 index 0000000000..18752ca81f --- /dev/null +++ b/.changeset/slot-restart-cursor-top-up.md @@ -0,0 +1,6 @@ +--- +'@workflow/core': patch +'workflow': patch +--- + +Recover faster from a concurrent write on runs that number their events by slot, by topping the event log up from its cursor instead of reloading it in full diff --git a/.changeset/tidy-moons-observe.md b/.changeset/tidy-moons-observe.md new file mode 100644 index 0000000000..9c6c5b7692 --- /dev/null +++ b/.changeset/tidy-moons-observe.md @@ -0,0 +1,5 @@ +--- +'@workflow/core': patch +--- + +Name the divergent event's pending invocations and the fenced member of an inline step batch in replay-divergence logs diff --git a/.changeset/turbo-run-started-occurred-at.md b/.changeset/turbo-run-started-occurred-at.md new file mode 100644 index 0000000000..bfbfbaf2d6 --- /dev/null +++ b/.changeset/turbo-run-started-occurred-at.md @@ -0,0 +1,5 @@ +--- +'@workflow/core': patch +--- + +Report the same workflow start time on an optimistically started run's first pass and its replays diff --git a/.github/scripts/render-event-log-race-repro-results.js b/.github/scripts/render-event-log-race-repro-results.js index bbead520b2..c0cc1aadfd 100644 --- a/.github/scripts/render-event-log-race-repro-results.js +++ b/.github/scripts/render-event-log-race-repro-results.js @@ -407,6 +407,11 @@ function renderLatestFailures(entry) { `\nShowing 20 of ${entry.failing.length + entry.truncatedFailingCount} non-completed runs.` ); } + // Deliberately not inlined here: the slices are large and this comment has a + // size limit, while the artifact has none. + console.log( + '\nThe `event-log-race-repro-results` artifact carries a window of the committed log around the divergent event, for a sample of the corruptions.' + ); console.log(''); } diff --git a/.gitignore b/.gitignore index a3f813e31a..3241f9667c 100644 --- a/.gitignore +++ b/.gitignore @@ -43,6 +43,9 @@ workbench/nextjs-*/public/.well-known/workflow workbench/sveltekit/static/.well-known/workflow +# Local e2e diagnostics dumps +e2e-diagnostics-*.json + # Event log race repro output (written to the repo root by the harness and by # scripts/event-log-race-repro-local.sh) event-log-race-repro-results.json diff --git a/docs/content/docs/v5/configuration/runtime-tuning.mdx b/docs/content/docs/v5/configuration/runtime-tuning.mdx index 1236f5e160..7feac45f69 100644 --- a/docs/content/docs/v5/configuration/runtime-tuning.mdx +++ b/docs/content/docs/v5/configuration/runtime-tuning.mdx @@ -52,9 +52,11 @@ For example, a workflow can run a 10-minute inline step even with `WORKFLOW_REPL ### `WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS` -- Default: `3` +- Default: `3`, or `12` on a run numbering its events by position (see [`WORKFLOW_SLOT_IDENTITY`](#workflow_slot_identity)) - How many times a single invocation restarts its replay 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. +- A run numbering its events by position reads only the page after its cursor instead of reloading the log, since positions are allocated in order and every event it was missing sorts above what it already has. Restarts are cheap enough there that the higher default is worth taking before a re-invocation and its delay. +- Setting this overrides both defaults. ### `WORKFLOW_PRECONDITION_MAX_REINVOCATIONS` @@ -68,6 +70,27 @@ For example, a workflow can run a 10-minute inline step even with `WORKFLOW_REPL - Delay before a re-invocation caused by a rejected event creation. - Unlike an in-process restart, which re-reads immediately, a re-invocation only happens once the in-process budget failed to catch up — so the delay gives the other writers a moment to quiesce. +### `WORKFLOW_PRECONDITION_RESTART_BACKOFF_MS` + +- Default: `15` +- Base for the randomized wait before an in-process replay restart re-derives, in milliseconds. The wait doubles with each restart the invocation has spent, up to [`WORKFLOW_PRECONDITION_RESTART_BACKOFF_MAX_MS`](#workflow_precondition_restart_backoff_max_ms), and is drawn uniformly from zero to that bound. +- The wait exists for runs with several replays in flight at once — a fan-out of steps completing together, or a burst of hooks. A rejected event creation means another replay got there first; if every loser re-derives immediately they all contend again, and none of them pulls far enough ahead to finish. Drawing each wait from the full range spreads the retries apart. +- Set to `0` to restart without waiting. + +### `WORKFLOW_PRECONDITION_RESTART_BACKOFF_MAX_MS` + +- Default: `400` +- Ceiling on the wait described above. + +### `WORKFLOW_SLOT_IDENTITY` + +- Default: enabled +- Numbers a new run's events by position instead of by ULID: `evnt_…001` is the run's first event, `evnt_…002` its second. Positions are allocated in order, so the log reads in the order it was written regardless of clock skew between writers. +- Contention becomes explicit rather than silent. Two writers proposing the same position cannot both win: the loser gets a 409 ([`SlotConflictError`](/docs/api-reference/workflow-errors/slot-conflict-error)) carrying the events it was missing, and the run replays from the top against a log that now includes them. +- Applies only to runs created while it is enabled. A run keeps the identity scheme it was created with for life, so turning the flag on or off never affects runs already in flight. +- Requires a World that supports it. A World that does not rejects the run outright rather than mis-numbering its events. +- Set `0` or `false` to disable, which numbers new runs by ULID as before. + ## Inline execution ### `WORKFLOW_V2_TIMEOUT_MS` @@ -209,6 +232,12 @@ These variables are primarily for tests, debugging, or unusual deployments. - Delay before the unconsumed-event check fires. - Minimum: `10`. +### `WORKFLOW_DEFERRED_CHECK_MAX_GRACE_MS` + +- Default: `15000` +- How long the unconsumed-event check keeps waiting while a step result or hook payload is still on its way to the workflow. An event whose consumer has not been registered yet looks exactly like an orphaned one, so the check waits rather than failing the run. +- Once this budget is spent the check reports regardless, so a delivery that never lands cannot keep a genuinely orphaned event from being detected. + ### `WORKFLOW_LOCK_POLL_INTERVAL_MS` - Default: `10` diff --git a/packages/core/e2e/event-log-race-repro.test.ts b/packages/core/e2e/event-log-race-repro.test.ts index b577df7b5c..c2895ff944 100644 --- a/packages/core/e2e/event-log-race-repro.test.ts +++ b/packages/core/e2e/event-log-race-repro.test.ts @@ -137,6 +137,31 @@ interface ReproRunResult { resumesFailed: number; stragglers?: number; }; + /** + * The committed log around the divergent event, for corruptions only. A + * divergence is a disagreement between the order the log records and the + * order a replay reconstructs, so the log's own ordering is the only + * evidence that distinguishes the candidate causes — and the run is on an + * ephemeral preview deployment, so it has to be captured while the job is + * still running rather than read back afterwards. + */ + logSlice?: LogSliceEntry[]; +} + +/** + * One committed event, projected to the fields that decide replay order: + * its position (`slot`), what it resolves (`eventType`/`correlationId`), and + * both clock domains. `occurredAt` is the client/VM moment and `createdAt` + * the persisted event time the sandbox clock is driven from; a race between a + * `sleep` and a step is decided by that clock, so the two have to be + * comparable side by side. + */ +interface LogSliceEntry { + slot: number | string; + eventType: string; + correlationId?: string; + occurredAt?: string; + createdAt?: string; } function envNumber(name: string, fallback: number) { @@ -392,6 +417,98 @@ function validateStormReturn(value: unknown): { return { stragglers }; } +/** + * Reads a terminal-failed run's error through `returnValue()`, which hydrates + * the stored payload into an Error. Returns undefined when the read itself + * fails — the outcome is already known from `errorCode`, so a missing message + * degrades the report rather than the classification. + */ +async function readFailureMessage( + run: Run +): Promise<{ name?: string; message?: string } | undefined> { + try { + await run.returnValue(); + return undefined; + } catch (err) { + if (WorkflowRunFailedError.is(err)) { + const cause = err.cause; + return { + name: cause instanceof Error ? cause.name : err.name, + message: cause instanceof Error ? cause.message : err.message, + }; + } + return undefined; + } +} + +/** + * How many events either side of the divergent one to keep. The window has to + * span a whole round of the storm — width branches, each with a step create, + * start and completion, plus the round's waits — or it can miss the very + * event whose position explains the divergence. + */ +const LOG_SLICE_RADIUS = envNumber('EVENT_LOG_RACE_REPRO_LOG_SLICE_RADIUS', 45); + +/** + * Cap on how many corruptions carry a slice. The results JSON is rendered into + * a PR comment, and a body over GitHub's limit is rejected outright, so the + * slices are a sample rather than a complete record. + */ +const LOG_SLICE_MAX_RUNS = envNumber('EVENT_LOG_RACE_REPRO_LOG_SLICE_RUNS', 6); + +let logSlicesCaptured = 0; + +/** Worlds hand timestamps back as a Date or as the stored ISO string. */ +function isoOrUndefined(value: unknown): string | undefined { + if (value instanceof Date) return value.toISOString(); + return typeof value === 'string' ? value : undefined; +} + +/** Ordinal of a slot-numbered id, or the raw id when it is a ULID. */ +function idOrdinal(id: string): number | string { + const body = id.slice(id.indexOf('_') + 1); + return /^\d+$/.test(body) ? Number(body) : id; +} + +/** + * Reads the committed log and returns the window around the divergent event + * named in `message`. Best-effort: the report is a measurement, so a failed + * read costs a slice rather than the attempt's classification. + */ +async function readLogSlice( + runId: string, + message: string | undefined +): Promise { + if (logSlicesCaptured >= LOG_SLICE_MAX_RUNS) return undefined; + try { + const world = await getWorld(); + const { data: events } = await world.events.list({ runId }); + const projected: LogSliceEntry[] = events.map((event) => ({ + slot: idOrdinal(event.eventId), + eventType: event.eventType, + correlationId: event.correlationId, + occurredAt: isoOrUndefined(event.occurredAt), + createdAt: isoOrUndefined(event.createdAt), + })); + + // The corruption message names the last divergent event; centre on it when + // it is there, and otherwise keep the tail, where a divergence that ran out + // of recovery replays ends up. + const divergent = message?.match(/evnt_[0-9A-Z]+/)?.[0]; + const at = divergent + ? projected.findIndex((entry) => entry.slot === idOrdinal(divergent)) + : -1; + const centre = at >= 0 ? at : projected.length - 1; + logSlicesCaptured += 1; + return projected.slice( + Math.max(0, centre - LOG_SLICE_RADIUS), + centre + LOG_SLICE_RADIUS + 1 + ); + } catch { + return undefined; + } +} + async function pollTerminalRun( run: Run, startedAt: number, @@ -431,14 +548,27 @@ async function pollTerminalRun( errorCode?: string; error?: { name?: string; message?: string }; }; + // `runs.get` hands back the raw serialized error payload, not an Error, so + // reading `.message` off it yields undefined and the report records the + // code with no diagnosis. Read the failure through the public + // return-value path, which hydrates it. For a corruption that message + // carries the divergent event and what the replay was waiting for, which + // is the whole reason to keep the report. + const hydrated = await readFailureMessage(run); + const outcome = classifyFailure(failure.errorCode); + const errorMessage = hydrated?.message ?? failure.error?.message; return { ...base, - outcome: classifyFailure(failure.errorCode), + outcome, status: runData.status, errorCode: failure.errorCode, - errorMessage: failure.error?.message, - errorName: failure.error?.name, + errorMessage, + errorName: hydrated?.name ?? failure.error?.name, durationMs: Date.now() - startedAt, + logSlice: + outcome === 'CORRUPTED_EVENT_LOG' + ? await readLogSlice(run.runId, errorMessage) + : undefined, }; } diff --git a/packages/core/e2e/utils.ts b/packages/core/e2e/utils.ts index 8c57ebed70..46f78b501e 100644 --- a/packages/core/e2e/utils.ts +++ b/packages/core/e2e/utils.ts @@ -659,7 +659,11 @@ async function getRunDiagnostics(tracked: TrackedRun): Promise { const elapsed = baseTime ? ((event.createdAt?.getTime?.() ?? 0) - baseTime) / 1000 : 0; - const prefix = ` +${elapsed.toFixed(1)}s`; + // The event's own id leads the line: on a run numbering its events + // by position it says where in the log the event sits, which is what + // a diagnosis of an out-of-order or gapped log needs and what the + // correlation id below cannot report. + const prefix = ` ${event.eventId} +${elapsed.toFixed(1)}s`; let detail = event.eventType; if ('eventData' in event) { const data = (event as any).eventData; diff --git a/packages/core/src/events-consumer.test.ts b/packages/core/src/events-consumer.test.ts index ecf828f728..6294803363 100644 --- a/packages/core/src/events-consumer.test.ts +++ b/packages/core/src/events-consumer.test.ts @@ -1,7 +1,15 @@ import { withResolvers } from '@workflow/utils'; import type { Event } from '@workflow/world'; -import { describe, expect, it, vi } from 'vitest'; -import { EventConsumerResult, EventsConsumer } from './events-consumer.js'; +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { + DEFERRED_CHECK_DELAY_MS, + EventConsumerResult, + EventsConsumer, +} from './events-consumer.js'; + +afterEach(() => { + vi.unstubAllEnvs(); +}); // Helper function to create mock events function createMockEvent(overrides: Partial = {}): Event { @@ -468,12 +476,63 @@ describe('EventsConsumer', () => { expect(consumer.eventIndex).toBe(1); }); - // Wait past the internal 100ms unconsumed-event setTimeout window to - // ensure the cancelled check truly does not fire. - await new Promise((resolve) => setTimeout(resolve, 150)); + // Wait past the internal unconsumed-event setTimeout window to ensure the + // cancelled check truly does not fire. + await new Promise((resolve) => + setTimeout(resolve, DEFERRED_CHECK_DELAY_MS * 1.5) + ); // The new callback consumed the event, so onUnconsumedEvent should NOT be called expect(onUnconsumedEvent).not.toHaveBeenCalled(); }); + + it('waits while a delivery is in flight, then reports once it lands', async () => { + vi.stubEnv('WORKFLOW_DEFERRED_CHECK_DELAY_MS', '10'); + const event = createMockEvent(); + const onUnconsumedEvent = vi.fn(); + let inFlight = true; + const consumer = new EventsConsumer([event], { + onUnconsumedEvent, + getPromiseQueue: () => Promise.resolve(), + isDeliveryInFlight: () => inFlight, + }); + + consumer.subscribe( + vi.fn().mockReturnValue(EventConsumerResult.NotConsumed) + ); + + // Many delay windows pass. A delivery still on its way to the workflow + // means the consumer for this event has not been registered YET — which + // is not the same thing as the event being orphaned. + await new Promise((resolve) => setTimeout(resolve, 200)); + expect(onUnconsumedEvent).not.toHaveBeenCalled(); + + inFlight = false; + await vi.waitFor(() => { + expect(onUnconsumedEvent).toHaveBeenCalledWith(event); + }); + }); + + it('reports once the grace budget runs out even if a delivery never lands', async () => { + vi.stubEnv('WORKFLOW_DEFERRED_CHECK_DELAY_MS', '10'); + vi.stubEnv('WORKFLOW_DEFERRED_CHECK_MAX_GRACE_MS', '50'); + const event = createMockEvent(); + const onUnconsumedEvent = vi.fn(); + const consumer = new EventsConsumer([event], { + onUnconsumedEvent, + getPromiseQueue: () => Promise.resolve(), + // Never clears: a delivery that is abandoned must not park the check + // forever, or a genuinely orphaned event would never be reported. + isDeliveryInFlight: () => true, + }); + + consumer.subscribe( + vi.fn().mockReturnValue(EventConsumerResult.NotConsumed) + ); + + await vi.waitFor(() => { + expect(onUnconsumedEvent).toHaveBeenCalledWith(event); + }); + }); }); }); diff --git a/packages/core/src/events-consumer.ts b/packages/core/src/events-consumer.ts index 4b7cf0742e..5db54b4169 100644 --- a/packages/core/src/events-consumer.ts +++ b/packages/core/src/events-consumer.ts @@ -26,6 +26,26 @@ const getDeferredCheckDelayMs = (): number => min: 10, }); +/** + * Upper bound on how long the unconsumed-event check keeps re-arming while a + * data delivery is still in flight (see `isDeliveryInFlight`). The delay above + * is a margin for a microtask chain; this is a margin for real async work — + * decrypting a hook payload, fetching a remote ref — that has to finish before + * the VM can resume the branch that registers the next event's consumer. + * + * Bounded rather than unbounded so a genuinely orphaned event still reports, + * and so a delivery that never lands cannot park the check forever. + */ +export const DEFERRED_CHECK_MAX_GRACE_MS = 15_000; + +/** Override: `WORKFLOW_DEFERRED_CHECK_MAX_GRACE_MS`. */ +const getDeferredCheckMaxGraceMs = (): number => + envNumber( + 'WORKFLOW_DEFERRED_CHECK_MAX_GRACE_MS', + DEFERRED_CHECK_MAX_GRACE_MS, + { integer: true, min: 0 } + ); + export enum EventConsumerResult { /** * Callback consumed the event, but should not be removed from the callbacks list @@ -65,6 +85,16 @@ export interface EventsConsumerOptions { * deserialization delays the resolve() that triggers the next subscribe(). */ getPromiseQueue: () => Promise; + /** + * Whether a data delivery (step result, hook payload) is still on its way to + * the workflow. The unconsumed-event check re-arms while this holds instead + * of reporting: an event whose consumer has not been registered yet is + * indistinguishable from an orphaned one by log inspection alone, and the + * promise-queue drain does not cover the gap between a delivery's `resolve()` + * and the VM body reaching its next `subscribe()`. Defaults to never in + * flight, which is the plain wall-clock behaviour. + */ + isDeliveryInFlight?: () => boolean; } export class EventsConsumer { @@ -74,6 +104,7 @@ export class EventsConsumer { private onConsumedEvent?: (event: Event) => void; private onUnconsumedEvent: (event: Event) => void; private getPromiseQueue: () => Promise; + private isDeliveryInFlight: () => boolean; private pendingUnconsumedCheck: Promise | null = null; private pendingUnconsumedTimeout: ReturnType | null = null; private unconsumedCheckVersion = 0; @@ -84,6 +115,7 @@ export class EventsConsumer { this.onConsumedEvent = options.onConsumedEvent; this.onUnconsumedEvent = options.onUnconsumedEvent; this.getPromiseQueue = options.getPromiseQueue; + this.isDeliveryInFlight = options.isDeliveryInFlight ?? (() => false); } /** @@ -200,32 +232,66 @@ export class EventsConsumer { // is still unconsumed after the queue drains, it's truly orphaned. if (currentEvent !== null) { const checkVersion = ++this.unconsumedCheckVersion; - this.pendingUnconsumedCheck = this.getPromiseQueue() - .then( - // Yield once after the first queue drain so promise chains resumed by - // that drain can run across the VM boundary and append any follow-up - // async work (for example: step_completed resolves -> for-await loop - // resumes -> the next hook payload starts hydrating). - () => new Promise((resolve) => setTimeout(resolve, 0)) - ) - .then(() => this.getPromiseQueue()) - .then(() => { - // Use a delayed setTimeout after the queue drains. The delay must be - // long enough for promise chains to propagate across the VM boundary - // (from resolve() in the host context through to the workflow code - // calling subscribe() in the VM context). Node.js does not guarantee - // that setTimeout(0) fires after all cross-context microtasks settle, - // so we use a small but non-zero delay. Any subscribe() call that - // arrives during this window will cancel the check via version - // invalidation + clearTimeout. - this.pendingUnconsumedTimeout = setTimeout(() => { - this.pendingUnconsumedTimeout = null; - if (this.unconsumedCheckVersion === checkVersion) { - this.pendingUnconsumedCheck = null; - this.onUnconsumedEvent(currentEvent); - } - }, getDeferredCheckDelayMs()); - }); + this.armUnconsumedCheck( + currentEvent, + checkVersion, + getDeferredCheckMaxGraceMs() + ); } } + + /** + * Wait for the promise queue to drain, then a short delay, then report + * `currentEvent` as unconsumed — unless a `subscribe()` invalidated + * `checkVersion` in the meantime, or a delivery is still in flight, in which + * case re-arm with `graceRemainingMs` reduced by the delay just spent. + */ + private armUnconsumedCheck( + currentEvent: Event, + checkVersion: number, + graceRemainingMs: number + ) { + const delay = getDeferredCheckDelayMs(); + this.pendingUnconsumedCheck = this.getPromiseQueue() + .then( + // Yield once after the first queue drain so promise chains resumed by + // that drain can run across the VM boundary and append any follow-up + // async work (for example: step_completed resolves -> for-await loop + // resumes -> the next hook payload starts hydrating). + () => new Promise((resolve) => setTimeout(resolve, 0)) + ) + .then(() => this.getPromiseQueue()) + .then(() => { + // Use a delayed setTimeout after the queue drains. The delay must be + // long enough for promise chains to propagate across the VM boundary + // (from resolve() in the host context through to the workflow code + // calling subscribe() in the VM context). Node.js does not guarantee + // that setTimeout(0) fires after all cross-context microtasks settle, + // so we use a small but non-zero delay. Any subscribe() call that + // arrives during this window will cancel the check via version + // invalidation + clearTimeout. + this.pendingUnconsumedTimeout = setTimeout(() => { + this.pendingUnconsumedTimeout = null; + if (this.unconsumedCheckVersion !== checkVersion) { + return; + } + if (graceRemainingMs > 0 && this.isDeliveryInFlight()) { + // A delivery is hydrating, or has resolved but is parked behind its + // deferral. The workflow body has not had the chance to register + // this event's consumer yet, so reporting now would reject a + // healthy run: the resulting `ReplayDivergenceError` recurs on + // every replay that is unlucky in the same way and escalates to a + // terminal `CorruptedEventLogError`. + this.armUnconsumedCheck( + currentEvent, + checkVersion, + graceRemainingMs - delay + ); + return; + } + this.pendingUnconsumedCheck = null; + this.onUnconsumedEvent(currentEvent); + }, delay); + }); + } } diff --git a/packages/core/src/log-format.test.ts b/packages/core/src/log-format.test.ts index c673893f06..3b78208744 100644 --- a/packages/core/src/log-format.test.ts +++ b/packages/core/src/log-format.test.ts @@ -113,6 +113,29 @@ describe('composeLogLine', () => { `); }); + test('renders errorMessage when the message does not already carry it', () => { + // The replay-divergence warn writes its own summary line and passes the + // error only as metadata, so this is the sole place the divergent event's + // identity appears. Dropping it leaves the log naming a symptom with no + // way to tell which event diverged. + const out = composeLogLine( + PREFIX, + 'Workflow replay diverged; queueing a recovery replay before declaring the event log corrupted', + { + errorCode: 'REPLAY_DIVERGENCE', + errorMessage: + 'Replay could not consume event: eventType=step_created, correlationId=step_00000000000000000000000025.', + divergenceCount: 1, + } + ); + expect(out).toMatchInlineSnapshot(` + "[workflow-sdk] Workflow replay diverged; queueing a recovery replay before declaring the event log corrupted + code REPLAY_DIVERGENCE + error Replay could not consume event: eventType=step_created, correlationId=step_00000000000000000000000025. + divergenceCount 1" + `); + }); + test('falls back gracefully on machine names it cannot parse', () => { const out = composeLogLine(PREFIX, 'msg', { workflowRunId: 'wrun_X', @@ -156,7 +179,8 @@ describe('composeLogLine', () => { user error · Error run wrun_01ABC · myWorkflow (./workflows/x) step step_01XYZ · add (./workflows/x) - retry 4 attempts · 3 max retries" + retry 4 attempts · 3 max retries + error Transient failure" `); }); }); diff --git a/packages/core/src/log-format.ts b/packages/core/src/log-format.ts index d63e847e3f..b3daa3263c 100644 --- a/packages/core/src/log-format.ts +++ b/packages/core/src/log-format.ts @@ -36,7 +36,7 @@ export function composeLogLine( ): string { const [framing, ...rest] = message.split('\n'); const body = rest.join('\n'); - const fields = renderStructuredFields(framing ?? '', metadata); + const fields = renderStructuredFields(message, metadata); const trimmedBody = trimStackBody(body); const lines: string[] = [`${prefix} ${framing ?? ''}`]; @@ -46,19 +46,21 @@ export function composeLogLine( } function renderStructuredFields( - framing: string, + message: string, metadata: Record | undefined ): string | null { if (!metadata || Object.keys(metadata).length === 0) return null; // Drop fields that the message already encodes. We render framings and // stacks into the message string itself in step executor / combined runtime, so - // repeating them here would be pure noise. + // repeating them here would be pure noise. The whole message counts, not just + // its first line: callers that pass `${framing}\n${stack}` put the error's + // text in the stack's leading `Name: message` line. const redundant = new Set(); redundant.add('errorStack'); if ( typeof metadata.errorMessage === 'string' && - framing.includes(metadata.errorMessage as string) + message.includes(metadata.errorMessage as string) ) { redundant.add('errorMessage'); } @@ -130,6 +132,16 @@ function renderStructuredFields( lines.push(` ${kvKey('code')} ${Ansi.dim(errorCode)}`); } + // The message only duplicates the framing when the framing was built from + // the error itself (step executor, terminal run failures), and that case is + // already marked redundant above. Everywhere else — a warn that carries an + // error alongside its own summary line — this is the only place the error's + // own text appears, so dropping it loses the diagnosis. + const errorMessage = pickString(metadata, 'errorMessage'); + if (errorMessage && !redundant.has('errorMessage')) { + lines.push(` ${kvKey('error')} ${errorMessage}`); + } + const hint = pickString(metadata, 'hint'); if (hint) { lines.push(` ${Ansi.hint(hint)}`); diff --git a/packages/core/src/logger.test.ts b/packages/core/src/logger.test.ts index 5560c9e213..78066923ca 100644 --- a/packages/core/src/logger.test.ts +++ b/packages/core/src/logger.test.ts @@ -148,6 +148,7 @@ describe('logger', () => { user error · FatalError run wrun_123 step step_456 + error boom hint: Move the call to a step function.", ], ] @@ -178,7 +179,8 @@ describe('logger', () => { user error · Error run wrun_abc step step_xyz - retry 4 attempts · 3 max retries", + retry 4 attempts · 3 max retries + error Transient failure", ], ] `); diff --git a/packages/core/src/private.ts b/packages/core/src/private.ts index a4498b3179..89b2e86a61 100644 --- a/packages/core/src/private.ts +++ b/packages/core/src/private.ts @@ -555,12 +555,25 @@ function hasParkedCommittedDelivery(ctx: WorkflowOrchestratorContext): boolean { * delivery still in flight. Empirically, replacing it with `queueMicrotask` * breaks hook/sleep `Promise.race` ordering (CorruptedEventLogError). */ +/** + * Whether some data delivery is still on its way to the workflow — the same + * two windows {@link scheduleWhenIdle} polls on, exposed for callers that need + * to test the condition without waiting on it. + * + * While this holds, the VM has not yet run the continuation that registers the + * next event's consumer, so "no consumer for this event" says nothing about + * whether the event log is well-formed. + */ +export function hasInFlightDelivery(ctx: WorkflowOrchestratorContext): boolean { + return ctx.pendingDeliveries > 0 || hasParkedCommittedDelivery(ctx); +} + export function scheduleWhenIdle( ctx: WorkflowOrchestratorContext, fn: () => void ): void { const check = () => { - if (ctx.pendingDeliveries > 0 || hasParkedCommittedDelivery(ctx)) { + if (hasInFlightDelivery(ctx)) { // A delivery is still hydrating, or is committed but parked behind its // deferral (whose resolve runs on a detached timer, not this queue). // Either way: let the queue drain, then re-check a timer tick later. diff --git a/packages/core/src/runtime.test.ts b/packages/core/src/runtime.test.ts index 750cef009f..5500f1f4ff 100644 --- a/packages/core/src/runtime.test.ts +++ b/packages/core/src/runtime.test.ts @@ -6,7 +6,10 @@ import { } from '@workflow/errors'; import { type Event, + FIRST_SLOT, SPEC_VERSION_CURRENT, + SPEC_VERSION_SLOT_IDENTITY, + slotFromId, type WorkflowRun, } from '@workflow/world'; import { ulid } from 'ulid'; @@ -19,6 +22,7 @@ import { dehydrateStepReturnValue, dehydrateWorkflowArguments, } from './serialization.js'; +import { getWorkflowMetadata } from './step/get-workflow-metadata.js'; // Capture every promise handed to `waitUntil` so tests can assert that // progress-critical sends are never registered on a detached, unconsumed @@ -1523,6 +1527,17 @@ describe('workflowEntrypoint turbo mode', () => { return undefined; }); + // Records the workflow start time the step body observes, which is the one + // the synthesized run row carries under turbo. + let turboObservedStartedAt: Date | undefined; + registerStepFunction('turboMetadataStep', async () => { + turboObservedStartedAt = getWorkflowMetadata().workflowStartedAt; + return undefined; + }); + + const oneMetadataStepWorkflow = `const s = globalThis[Symbol.for("WORKFLOW_USE_STEP")]("turboMetadataStep"); + async function workflow() { return await s(); }${xform('workflow')}`; + const oneStepWorkflow = `const s = globalThis[Symbol.for("WORKFLOW_USE_STEP")]("turboStep"); async function workflow() { return await s(); }${xform('workflow')}`; @@ -1535,12 +1550,15 @@ describe('workflowEntrypoint turbo mode', () => { return r; }${xform('workflow')}`; - async function makeRunInput(runId: string) { + async function makeRunInput( + runId: string, + specVersion = SPEC_VERSION_CURRENT + ) { return { input: await dehydrateWorkflowArguments([], runId, undefined, []), deploymentId: 'test-deployment', workflowName: 'workflow', - specVersion: SPEC_VERSION_CURRENT, + specVersion, executionContext: {}, }; } @@ -1556,8 +1574,10 @@ describe('workflowEntrypoint turbo mode', () => { attempt: number; source: string; runStartedGate?: Promise; + specVersion?: typeof SPEC_VERSION_CURRENT; }) { const { runId, attempt, source } = opts; + const specVersion = opts.specVersion ?? SPEC_VERSION_CURRENT; const order = turboOrder; const durable: Event[] = []; let seq = 0; @@ -1576,6 +1596,7 @@ describe('workflowEntrypoint turbo mode', () => { runId, workflowName: 'workflow', status: 'running', + specVersion, input: await dehydrateWorkflowArguments([], runId, undefined, []), createdAt: new Date('2024-01-01T00:00:00.000Z'), updatedAt: new Date('2024-01-01T00:00:00.000Z'), @@ -1621,7 +1642,7 @@ describe('workflowEntrypoint turbo mode', () => { }); setWorld({ - specVersion: SPEC_VERSION_CURRENT, + specVersion, createQueueHandler: vi.fn( (_p: string, handler: (m: unknown, md: unknown) => Promise) => async () => { @@ -1629,7 +1650,7 @@ describe('workflowEntrypoint turbo mode', () => { { runId, requestedAt: new Date('2024-01-01T00:00:00.000Z'), - runInput: await makeRunInput(runId), + runInput: await makeRunInput(runId, specVersion), }, { requestId: 'req_turbo', @@ -1715,6 +1736,33 @@ describe('workflowEntrypoint turbo mode', () => { ); }); + it('claims slots above the run own positions on a first delivery', async () => { + // Turbo replays against an empty snapshot, so the log the claims are + // numbered from cannot show `run_created` or the in-flight `run_started`. + // Both positions are nonetheless taken, and the mocked `run_started` + // response reports no event — the same shape as a World that skips the + // preload — so nothing but the floor seeded at turbo entry keeps the first + // batch of claims off them. + const { handlerPromise, eventsCreate } = await driveTurbo({ + runId: 'wrun_turbo_slots', + attempt: 1, + source: stepAndSleepWorkflow, + specVersion: SPEC_VERSION_SLOT_IDENTITY, + }); + + const res = await handlerPromise; + expect(res.status).toBe(204); + + const claimed = eventsCreate.mock.calls + .map((c) => (c[2] as { eventId?: unknown } | undefined)?.eventId) + .filter((id): id is string => typeof id === 'string'); + // The sleep's `wait_created` is claimed, so there is something to assert on. + expect(claimed.length).toBeGreaterThan(0); + for (const eventId of claimed) { + expect(slotFromId(eventId)).toBeGreaterThan(FIRST_SLOT + 1); + } + }); + it('does not turbo when WORKFLOW_TURBO=0 (parity with the awaited path)', async () => { process.env.WORKFLOW_TURBO = '0'; const { handlerPromise, order } = await driveTurbo({ @@ -1761,6 +1809,30 @@ describe('workflowEntrypoint turbo mode', () => { expect((redeliverRunStarted?.[2] as any)?.skipPreload).toBeUndefined(); }); + it('sends run_started the same instant it synthesizes the run from', async () => { + // Turbo starts the run against a locally synthesized run row, so the start + // time this invocation reports comes from the client clock. Backends that + // persist `occurredAt` record the run's `startedAt` from it, so sending it + // is what makes a later replay — which reads the persisted run — report the + // same `workflowStartedAt` this pass already captured into its steps. + turboObservedStartedAt = undefined; + const { handlerPromise, eventsCreate } = await driveTurbo({ + runId: 'wrun_turbo_occurred_at', + attempt: 1, + source: oneMetadataStepWorkflow, + specVersion: SPEC_VERSION_SLOT_IDENTITY, + }); + expect((await handlerPromise).status).toBe(204); + + const runStarted = eventsCreate.mock.calls.find( + (c) => (c[1] as any).eventType === 'run_started' + ); + const occurredAt = (runStarted?.[2] as { occurredAt?: Date } | undefined) + ?.occurredAt; + expect(occurredAt).toBeInstanceOf(Date); + expect(turboObservedStartedAt).toEqual(occurredAt); + }); + it('exits turbo (no forced optimistic) when the suspension creates a wait', async () => { const { handlerPromise, order } = await driveTurbo({ runId: 'wrun_turbo_wait', diff --git a/packages/core/src/runtime.ts b/packages/core/src/runtime.ts index 470e437b1b..018ca5ad7a 100644 --- a/packages/core/src/runtime.ts +++ b/packages/core/src/runtime.ts @@ -18,13 +18,17 @@ import { } from '@workflow/utils/parse-name'; import { type Event, + FIRST_SLOT, getQueueTopicPrefix, isLegacySpecVersion, + maxSlotOf, ROOT_RUN_ID_ATTRIBUTE, type RunInput, resolveQueueNamespace, SPEC_VERSION_CURRENT, SPEC_VERSION_SUPPORTS_COMPRESSION, + slotFromId, + usesSlotIdentity, type WorkflowInvokePayload, WorkflowInvokePayloadSchema, type WorkflowRun, @@ -51,10 +55,12 @@ import { getReplayDivergenceMaxRetries, isInlineOwnershipEnabled, isTurboEnabled, + preconditionRestartBackoffMs, } from './runtime/constants.js'; import { countStepStartedEvents } from './runtime/count-step-started-events.js'; import { appendUniqueEvents, + claimFenceFor, type EventCreator, eventCreateFenceFor, getQueueOverhead, @@ -714,6 +720,12 @@ export function workflowEntrypoint( let cachedEvents: Event[] | null = null; let eventsCursor: string | null = null; + // Set when a restarted replay is recovering by topping its + // cached log up from the cursor rather than reloading it + // whole. The next load verifies the result is dense before + // the replay trusts it; see the consume site below the load. + let slotTopUpPending = false; + // Inline-delta optimization: when an inline step's terminal // write returns the event-log delta since the pre-write // cursor (a supporting World only), we stash it here so the @@ -738,6 +750,19 @@ export function workflowEntrypoint( let workflowStartedAt = -1; let preloadedEvents: Event[] | undefined; let preloadedEventsCursor: string | null | undefined; + // Highest slot known to be published on a slot-numbered run, + // for the writes whose snapshot cannot show it: turbo + // backgrounds `run_started` and replays against an empty log, + // so a claim numbered from that log alone would propose a slot + // `run_started` already holds. 0 when the run is not + // slot-numbered — its ids carry no position to compare. + let knownSlotFloor = 0; + const observeSlotFloor = (eventId: string | undefined) => { + const slot = eventId ? slotFromId(eventId) : undefined; + if (slot !== undefined && slot > knownSlotFloor) { + knownSlotFloor = slot; + } + }; // Latency telemetry (TTFS) state — see runtime/step-latency.ts. // Whether this invocation's FIRST event snapshot contained @@ -901,6 +926,14 @@ export function workflowEntrypoint( // Precondition (412) recovery: how many times this invocation // has thrown away its replay and started over in-process. let preconditionRestarts = 0; + /** + * Wait the next loop iteration owes before re-deriving, set + * by `restartReplayInProcess`. Held here rather than awaited + * at the restart's call sites because the restart is decided + * from three of them, in synchronous code, while the loop head + * is the single point every restart passes through. + */ + let pendingRestartBackoffMs = 0; /** * Event ids the discarded replay held, kept until the next * load resolves so a restart can report what its reload @@ -916,7 +949,7 @@ export function workflowEntrypoint( ids: Set; restart: number; reason: string; - source: 'inline-delta' | 'full-reload'; + source: 'inline-delta' | 'full-reload' | 'slot-top-up'; } | null = null; /** * Report what a stale-snapshot restart's reload found, once @@ -995,7 +1028,9 @@ export function workflowEntrypoint( ): boolean => { if ( preconditionRestarts >= - getPreconditionMaxInProcessRestarts() + getPreconditionMaxInProcessRestarts( + usesSlotIdentity(workflowRun?.specVersion) + ) ) { return false; } @@ -1015,6 +1050,25 @@ export function workflowEntrypoint( // to merge it into; with no base log the restart has to load // the whole thing anyway. const usedDelta = Boolean(delta && cachedEvents); + // Without a delta, a slot-numbered log still heals from its + // cursor rather than from a full reload. Slot ids sort in + // write order, so every event this replay was missing is + // strictly above the cursor and one incremental page brings + // it in — and density (a dense log from slot 1 holds + // exactly `maxSlot` events) proves afterwards that it did, + // so nothing is being trusted here that is not checked. + // Neither property holds under ULID ids, which is why those + // restarts reload whole. + const topsUpFromCursor = + !usedDelta && + usesSlotIdentity(workflowRun?.specVersion) && + cachedEvents !== null && + eventsCursor !== null; + const restartSource = usedDelta + ? 'inline-delta' + : topsUpFromCursor + ? 'slot-top-up' + : 'full-reload'; // Snapshot the set being discarded while it is still in // hand; the comparison happens once the next load resolves. preconditionRestartBaseline = cachedEvents @@ -1024,7 +1078,7 @@ export function workflowEntrypoint( ), restart: preconditionRestarts, reason, - source: usedDelta ? 'inline-delta' : 'full-reload', + source: restartSource, } : null; if (usedDelta) { @@ -1032,6 +1086,18 @@ export function workflowEntrypoint( // (`pendingInlineDelta && cachedEvents`) with no // events.list round trip at all. pendingInlineDelta = delta; + } else if (topsUpFromCursor) { + // Keep the cached log and its cursor: the loop's + // incremental branch fetches the page above the cursor + // and appends it, and the density check below the load + // sends the restart to a full reload if that page did not + // close the gap. Appends land above everything already + // scanned for payload prewarming, so no rescan is needed + // unless that fallback fires. + slotTopUpPending = true; + preloadedEvents = undefined; + preloadedEventsCursor = undefined; + pendingInlineDelta = null; } else { // MUST be a full, cursor-less reload. The cursor filters // by lexicographic event id while a hole is defined by @@ -1058,12 +1124,14 @@ export function workflowEntrypoint( reason, loopIteration, preconditionRestarts, - source: usedDelta ? 'inline-delta' : 'full-reload', + source: restartSource, } ); span?.setAttributes({ 'workflow.precondition_restarts': preconditionRestarts, }); + pendingRestartBackoffMs = + preconditionRestartBackoffMs(preconditionRestarts); return true; }; @@ -1104,7 +1172,7 @@ export function workflowEntrypoint( return { reinvoked: false, error: new WorkflowRuntimeError( - `Event creation was rejected as stale after ${maxReinvocations} re-invocations of ${getPreconditionMaxInProcessRestarts()} in-process replay restarts each: this run cannot observe its own event log completely enough to make progress. Last rejection (${reason}): ${error instanceof Error ? error.message : String(error)}`, + `Event creation was rejected as stale after ${maxReinvocations} re-invocations of ${getPreconditionMaxInProcessRestarts(usesSlotIdentity(workflowRun?.specVersion))} in-process replay restarts each: this run cannot observe its own event log completely enough to make progress. Last rejection (${reason}): ${error instanceof Error ? error.message : String(error)}`, { cause: error } ), }; @@ -1441,6 +1509,16 @@ export function workflowEntrypoint( // handler, optimistic step_started, terminal run writes) so // nothing is written before the run exists. recordRunStartedCreateStart(true); + // The instant this invocation calls the run started, sent + // with the event and reused for the synthesized run row + // below. Backends that persist `occurredAt` record the + // run's `startedAt` from it, which is what keeps + // `workflowStartedAt` identical between this optimistic + // pass and every later replay that reads the persisted + // run. Without it the two disagree by the round-trip, and + // a step's captured metadata no longer matches the + // workflow's on the next replay. + const now = new Date(); const startedPromise = createEvent( runStartedEvent, // We background this purely as a write barrier and @@ -1450,7 +1528,7 @@ export function workflowEntrypoint( // run_started request the chained first step_started // waits on — shortening time-to-second-step — and the // wasted list+resolve it would otherwise compute. - { requestId, skipPreload: true } + { requestId, skipPreload: true, occurredAt: now } ); runReadyBarrier = startedPromise; // Turbo backgrounds run_started, so the non-turbo assignment @@ -1463,6 +1541,10 @@ export function workflowEntrypoint( (r) => { const limit = clampMaxEvents(r?.maxEvents); if (limit !== undefined) maxEventsLimit = limit; + // Every write of this invocation is ordered after this + // promise by `runReadyBarrier`, so the slot it reports + // is in hand before the first claim is numbered. + observeSlotFloor(r?.event?.eventId); }, () => {} ); @@ -1479,7 +1561,20 @@ export function workflowEntrypoint( // intentionally truthy here — do not change the load // branches' `if (preloadedEvents)` checks to test length. preloadedEvents = []; - const now = new Date(); + // A slot-numbered run's first two positions are the run's + // own: `run_created` from start(), then the `run_started` + // in flight above. Both are certain before any write of + // this invocation, and turbo replays against the empty + // snapshot skipped just above — so seed the floor with + // them here rather than waiting for the backgrounded + // response to report it. Waiting loses the race: a + // suspension reserves its whole batch of positions + // synchronously, so a batch that starts numbering from an + // empty log claims the two the run already holds and the + // ops holding them lose their claims. + if (usesSlotIdentity(runInput.specVersion)) { + knownSlotFloor = FIRST_SLOT + 1; + } workflowRun = { runId, status: 'running', @@ -1528,6 +1623,7 @@ export function workflowEntrypoint( } workflowRun = result.run; maxEventsLimit = clampMaxEvents(result.maxEvents); + observeSlotFloor(result.event?.eventId); // Anchors RSFS — see the declaration above. runStartedReceivedAtMs = Date.now(); @@ -1634,6 +1730,19 @@ export function workflowEntrypoint( while (true) { loopIteration++; + // A restart lost a slot to a concurrent replay of this same + // run. Pause before re-deriving so the winner gets a clear + // window to extend the log: re-deriving immediately puts + // every loser back in contention at once, and none of them + // pulls ahead. + if (pendingRestartBackoffMs > 0) { + const backoffMs = pendingRestartBackoffMs; + pendingRestartBackoffMs = 0; + await new Promise((resolve) => + setTimeout(resolve, backoffMs) + ); + } + // Replay-budget check: bail out (retry or fail) if // non-step time within this invocation has exceeded // the configured budget. Step bodies are excluded @@ -1773,6 +1882,26 @@ export function workflowEntrypoint( // the wait pass, which may swap in a freshly loaded array. cachedEvents = events; + if (slotTopUpPending) { + slotTopUpPending = false; + // A slot-numbered log is dense from slot 1, so a + // complete one holds exactly `maxSlot` events. A short + // count means the page above the cursor did not bring + // in everything the restart was missing — the only + // other reading, a permanent hole from a write that + // took a slot and then failed, is equally unrecoverable + // from here — so fall back to the authoritative load. + if (maxSlotOf(events) !== events.length) { + const loaded = await loadWorkflowRunEvents(runId); + events = loaded.events; + eventsCursor = loaded.cursor; + cachedEvents = events; + // The reload can insert events below the prefix + // already scanned for payload prewarming. + replayPayloadCache.resetScan(); + } + } + reportPreconditionRestartReload(events); // Detect concurrent completion via the event log: if @@ -1818,16 +1947,20 @@ export function workflowEntrypoint( // place by the guard's reloads, so a per-iteration // rescan for the slot high-water mark would be wasted // work on an array that never changes identity here. - const waitLog = toMutableEventLog(events, eventsCursor); + const waitLog = toMutableEventLog( + events, + eventsCursor, + knownSlotFloor + ); + const waitClaim = claimFenceFor( + waitLog, + workflowRun.specVersion + ); for (const waitEvent of waitsToComplete) { try { - await createEvent(waitEvent, { - requestId, - ...eventCreateFenceFor( - waitLog, - workflowRun.specVersion - ), - }); + await waitClaim((fence) => + createEvent(waitEvent, { requestId, ...fence }) + ); } catch (err) { if (EntityConflictError.is(err)) { runtimeLogger.info( @@ -2098,6 +2231,20 @@ export function workflowEntrypoint( // point and the inline executeStep mutates eventsCursor. preInlineWriteCursor = eventsCursor; + // One log for everything this replay writes on its way to + // a terminal event: the end-of-run drain inside + // `runWorkflow` (fire-and-forget `*_created` events, and + // the implicit disposal of the abort hooks a completing + // run leaves behind) and the `run_completed` / + // `run_failed` write below. Sharing it is what keeps the + // two from claiming the same slot — the terminal write + // numbers from a snapshot that predates the drain. + const replayWriteLog = toMutableEventLog( + events, + eventsCursor, + knownSlotFloor + ); + // Replay workflow runtimeLogger.debug('Starting workflow replay', { workflowRunId: runId, @@ -2123,7 +2270,8 @@ export function workflowEntrypoint( // `awaitRunReady()` below, so gate those writes on the // backgrounded run_started too. Undefined outside turbo. runReadyBarrier, - world.capabilities + world.capabilities, + replayWriteLog ); await payloadPrewarm; runtimeLogger.debug('Workflow replay completed', { @@ -2135,10 +2283,12 @@ export function workflowEntrypoint( // Workflow completed. Send the snapshot but do NOT // reload-and-retry the create in place: `result` was - // 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 restarts the replay in-process. + // computed by this replay, so a rejection proving the view + // was incomplete — 412 stale watermark, or 409 taken slot + // — 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 restarts the replay + // in-process. try { // Turbo: a workflow that finishes with no steps reaches // here before the backgrounded run_started; order the @@ -2153,7 +2303,7 @@ export function workflowEntrypoint( { requestId, ...eventCreateFenceFor( - toMutableEventLog(events, eventsCursor), + replayWriteLog, workflowRun.specVersion ), } @@ -2245,7 +2395,8 @@ export function workflowEntrypoint( } const suspensionLog = toMutableEventLog( cachedEvents, - eventsCursor + eventsCursor, + knownSlotFloor ); let suspensionResult: Awaited< ReturnType @@ -2262,9 +2413,10 @@ export function workflowEntrypoint( replayRecoveryReporter, }); } catch (suspensionError) { - // 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 + // A suspension create was rejected as stale (412 + // watermark, or 409 taken slot): 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 @@ -2742,10 +2894,14 @@ export function workflowEntrypoint( // (retried over the reloaded log, or exhausted into // a queue re-invocation), AND the lazy step_started // claim of its next inline step, which is fenced too - // (threaded below via - // `eventCreateFence`; on rejection the batch is - // abandoned and re-invoked for a fresh replay, so a - // stale view can never commit a step). Hooks created + // (threaded below via `claimFenceFor`; on rejection + // the batch is abandoned and re-invoked for a fresh + // replay, so a stale view can never commit a step). + // A slot-numbered run gets there differently — the + // claim merges the missed events and retries in + // place, so the same events are observed without + // discarding the batch. See claimFenceFor. + // Hooks created // by THIS suspension are inside the delta (their // `hook_created` lands before the step-terminal // write), so only their `hook_received` responses @@ -2894,10 +3050,14 @@ export function workflowEntrypoint( // whole batch so each claim draws its own event slot; // for a run fenced by the watermark instead, every claim // in the batch carries the same snapshot. - const inlineClaimLog = toMutableEventLog( - cachedEvents ?? [], - preInlineWriteCursor - ); + // + // The suspension's own log, not a second one over the + // same snapshot: its reservations are what the hook and + // wait creates just above took, and those events are not + // in `cachedEvents` yet. A fresh log would number these + // claims from the same base and hand the batch's first + // step a slot the suspension already holds. + const inlineClaimLog = suspensionLog; replayBudget.pause(); let stepResults: Awaited< @@ -2910,7 +3070,7 @@ export function workflowEntrypoint( // positional, so it has to be assigned before these // executions start racing each other, and the order // it is assigned in has to be replay-stable. - const eventCreateFence = eventCreateFenceFor( + const claimFence = claimFenceFor( inlineClaimLog, workflowRun.specVersion, { @@ -2996,7 +3156,7 @@ export function workflowEntrypoint( // see suppressOptimisticStart above. suppressOptimisticStart, runReadyBarrier, - eventCreateFence, + claimFence, ...(stepIndex === 0 && s.lazyStepInput !== undefined && latencyTracking @@ -3038,23 +3198,26 @@ export function workflowEntrypoint( stepExecutionPromises ); } catch (stepErr) { - // A stale (412) rejection of an inline step_started - // claim: the loaded view this batch was scheduled - // 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. + // An incomplete-view rejection of an inline + // step_started claim — 412 for the event-log + // watermark, 409 for a lost slot claim: the loaded + // view this batch was scheduled from is missing an + // event the backend already has, so the claim was + // fenced 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 (isStaleWriteRejection(stepErr)) { const settled = await Promise.allSettled( stepExecutionPromises ); // A sibling whose claim was accepted wrote step // events of its own, possibly after the World built - // this 412's delta — so that delta can no longer be + // the rejection's delta — so that delta can no + // longer be // assumed to complete the log, and the restart has // to reload it in full. `skipped` (the step already // existed), `gone` and `throttled` (claim rejected) @@ -3272,17 +3435,18 @@ export function workflowEntrypoint( } } } else { - // Stale-snapshot rejection of a guarded write made - // directly by the replay loop — the result-bearing - // `run_completed`, or the `wait_completed` of the wait - // pass. Both reach this one catch and the rejection - // does not say which, hence the neutral label. - // Neither may be re-posted in place: the correlation id - // and (for run_completed) the result itself came from - // this replay, and a corrected log may produce - // different ones. Don't fail the run — restart the - // replay in this invocation, and only once that budget - // is spent schedule an explicit re-invocation. + // Incomplete-view rejection of a guarded write made + // directly by the replay loop — a stale watermark (412) + // or a taken slot (409), on the result-bearing + // `run_completed` or on the `wait_completed` of the + // wait pass. Both reach this one catch and the + // rejection does not say which, hence the neutral + // label. Neither may be re-posted in place: the + // correlation id and (for run_completed) the result + // itself came from this replay, and a corrected log may + // produce different ones. Don't fail the run — restart + // the replay in this invocation, and only once that + // budget is spent schedule an explicit 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 diff --git a/packages/core/src/runtime/constants.test.ts b/packages/core/src/runtime/constants.test.ts index 208250e8e6..919c4edd14 100644 --- a/packages/core/src/runtime/constants.test.ts +++ b/packages/core/src/runtime/constants.test.ts @@ -18,6 +18,9 @@ import { MAX_REPLAY_TIMEOUT_MS, MIN_MAX_INLINE_STEPS, MIN_REPLAY_TIMEOUT_MS, + PRECONDITION_RESTART_BACKOFF_BASE_MS, + PRECONDITION_RESTART_BACKOFF_MAX_MS, + preconditionRestartBackoffMs, REPLAY_TIMEOUT_MS, } from './constants.js'; @@ -393,3 +396,60 @@ describe('getInlineOwnershipLeaseSeconds', () => { expect(getInlineOwnershipLeaseSeconds()).toBe(1); }); }); + +describe('preconditionRestartBackoffMs', () => { + const BASE_ENV = 'WORKFLOW_PRECONDITION_RESTART_BACKOFF_MS'; + const MAX_ENV = 'WORKFLOW_PRECONDITION_RESTART_BACKOFF_MAX_MS'; + + beforeEach(() => { + delete process.env[BASE_ENV]; + delete process.env[MAX_ENV]; + }); + + afterEach(() => { + delete process.env[BASE_ENV]; + delete process.env[MAX_ENV]; + }); + + it('doubles the window on each successive restart', () => { + // Draw the top of the window so the window itself is observable. + const top = () => 0.999_999; + expect(preconditionRestartBackoffMs(1, top)).toBe( + PRECONDITION_RESTART_BACKOFF_BASE_MS - 1 + ); + expect(preconditionRestartBackoffMs(2, top)).toBe( + PRECONDITION_RESTART_BACKOFF_BASE_MS * 2 - 1 + ); + expect(preconditionRestartBackoffMs(3, top)).toBe( + PRECONDITION_RESTART_BACKOFF_BASE_MS * 4 - 1 + ); + }); + + it('draws over the whole window, not a fixed delay plus noise', () => { + // Full jitter is the property that decorrelates concurrent replays; a + // floor would keep them in lockstep however long the wait. + expect(preconditionRestartBackoffMs(5, () => 0)).toBe(0); + expect(preconditionRestartBackoffMs(5, () => 0.5)).toBeLessThan( + preconditionRestartBackoffMs(5, () => 0.999_999) + ); + }); + + it('caps the window', () => { + expect(preconditionRestartBackoffMs(40, () => 0.999_999)).toBe( + PRECONDITION_RESTART_BACKOFF_MAX_MS - 1 + ); + }); + + it('is disabled by a zero base', () => { + process.env[BASE_ENV] = '0'; + expect(preconditionRestartBackoffMs(1, () => 0.999_999)).toBe(0); + expect(preconditionRestartBackoffMs(9, () => 0.999_999)).toBe(0); + }); + + it('honours overrides of both the base and the cap', () => { + process.env[BASE_ENV] = '100'; + process.env[MAX_ENV] = '150'; + expect(preconditionRestartBackoffMs(1, () => 0.999_999)).toBe(99); + expect(preconditionRestartBackoffMs(2, () => 0.999_999)).toBe(149); + }); +}); diff --git a/packages/core/src/runtime/constants.ts b/packages/core/src/runtime/constants.ts index d5fea8383b..9a42399899 100644 --- a/packages/core/src/runtime/constants.ts +++ b/packages/core/src/runtime/constants.ts @@ -397,14 +397,32 @@ export function getReplayDivergenceMaxRetries(): number { // run-level budget below then applies. export const PRECONDITION_MAX_INPROCESS_RESTARTS = 3; +// A run that numbers its events by slot recovers by topping its log up from +// its cursor, so a restart costs one incremental page instead of a full +// reload. The tight bound above is priced for the reload; spending it here +// buys a re-invocation — a queue hop plus `PRECONDITION_REINVOKE_DELAY_SECONDS` +// — in place of restarts that are orders of magnitude cheaper than the thing +// the bound was protecting against. Measured on the step-storm repro against +// world-postgres at 6-way concurrency, raising this to 12 took the six runs +// from 196–241s (two of them exceeding the harness timeout) to 119–148s with +// none timing out. +export const PRECONDITION_MAX_INPROCESS_RESTARTS_INCREMENTAL = 12; + /** * Effective in-process replay-restart budget for stale-snapshot rejections. * Override via `WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS`. + * + * @param incremental Whether a restart heals from the log's cursor rather than + * reloading it whole, which holds for runs on slot identity. */ -export function getPreconditionMaxInProcessRestarts(): number { +export function getPreconditionMaxInProcessRestarts( + incremental = false +): number { return envNumber( 'WORKFLOW_PRECONDITION_MAX_INPROCESS_RESTARTS', - PRECONDITION_MAX_INPROCESS_RESTARTS, + incremental + ? PRECONDITION_MAX_INPROCESS_RESTARTS_INCREMENTAL + : PRECONDITION_MAX_INPROCESS_RESTARTS, { integer: true } ); } @@ -447,3 +465,66 @@ export function getPreconditionReinvokeDelaySeconds(): number { { integer: true } ); } + +// Concurrent replays of one run contend for the same event slots, and a +// rejected write costs its loser a restart. With no pause the losers re-derive +// at full speed and collide again immediately, so a run under heavy fan-out can +// spend its whole invocation budget with no writer ever pulling far enough +// ahead to finish. A short randomized wait between restarts breaks the lockstep +// by spreading the retries. +export const PRECONDITION_RESTART_BACKOFF_BASE_MS = 15; + +// Ceiling on that wait. The restart is cheap (one incremental page plus a +// re-derive), so the backoff must stay well under the cost of the +// re-invocation it is competing with. +export const PRECONDITION_RESTART_BACKOFF_MAX_MS = 400; + +/** + * Effective base for the in-process restart backoff. Override via + * `WORKFLOW_PRECONDITION_RESTART_BACKOFF_MS`; `0` disables the wait entirely. + */ +export function getPreconditionRestartBackoffBaseMs(): number { + return envNumber( + 'WORKFLOW_PRECONDITION_RESTART_BACKOFF_MS', + PRECONDITION_RESTART_BACKOFF_BASE_MS, + { integer: true } + ); +} + +/** + * Effective ceiling for the in-process restart backoff. Override via + * `WORKFLOW_PRECONDITION_RESTART_BACKOFF_MAX_MS`. + */ +export function getPreconditionRestartBackoffMaxMs(): number { + return envNumber( + 'WORKFLOW_PRECONDITION_RESTART_BACKOFF_MAX_MS', + PRECONDITION_RESTART_BACKOFF_MAX_MS, + { integer: true } + ); +} + +/** + * Full-jitter backoff for the `restarts`-th in-process replay restart, in + * milliseconds. + * + * Full jitter (a uniform draw over the whole window, not a fixed delay plus + * noise) is what actually decorrelates the racers: equal-length waits would + * keep colliding replays in lockstep no matter how long they were. + * + * @param restarts 1-based count of restarts spent so far, including this one. + * @param random Injectable uniform source; defaults to `Math.random`. The delay + * never reaches the event log, so it does not affect replay determinism. + */ +export function preconditionRestartBackoffMs( + restarts: number, + random: () => number = Math.random +): number { + const base = getPreconditionRestartBackoffBaseMs(); + if (base <= 0) return 0; + const exponent = Math.max(0, restarts - 1); + const window = Math.min( + getPreconditionRestartBackoffMaxMs(), + base * 2 ** exponent + ); + return Math.floor(random() * window); +} diff --git a/packages/core/src/runtime/helpers.test.ts b/packages/core/src/runtime/helpers.test.ts index 5b81c4ee68..3ae748d1d0 100644 --- a/packages/core/src/runtime/helpers.test.ts +++ b/packages/core/src/runtime/helpers.test.ts @@ -1,4 +1,5 @@ import { + EntityConflictError, PreconditionFailedError, SlotConflictError, WorkflowWorldError, @@ -21,6 +22,7 @@ import { } from '../serialization.js'; import { appendUniqueEvents, + claimFenceFor, eventCreateFenceFor, getWorkflowQueueName, handleHealthCheckMessage, @@ -536,11 +538,12 @@ describe('slot bookkeeping', () => { const slotEvent = (slot: number) => makeEvent(slotEventId(slot)); it('reads maxSlot from the highest slot present, not the last element', () => { - // `appendUniqueEvents` appends without sorting, so a merged log's last - // element is not necessarily its newest event. + // Nothing forces a caller's array into slot order — a World is free to + // hand back a page in whatever order its index produced — so the highest + // slot is a scan, not a peek at the last element. const log = toMutableEventLog([slotEvent(3), slotEvent(1)], 'c0'); expect(log.maxSlot).toBe(3); - expect(log.reserved).toBe(0); + expect(log.nextSlot).toBe(4); }); it('reports maxSlot 0 for an empty or ULID-numbered log', () => { @@ -550,6 +553,26 @@ describe('slot bookkeeping', () => { ).toBe(0); }); + it('starts at a floor the snapshot cannot show', () => { + // Turbo replays against an empty log while its `run_started` write is still + // in flight, so the snapshot alone would number the first claim onto a slot + // that write already holds. + const log = toMutableEventLog([], null, 2); + expect(log.maxSlot).toBe(2); + expect(reserveSlot(log)).toBe(3); + }); + + it('ignores a floor the snapshot has already passed', () => { + const log = toMutableEventLog([slotEvent(5)], 'c0', 2); + expect(log.maxSlot).toBe(5); + }); + + it('keeps the floor across a merge', () => { + const log = toMutableEventLog([], null, 2); + mergeLoadedEvents(log, [slotEvent(1)]); + expect(log.maxSlot).toBe(2); + }); + it('never lowers maxSlot when an older delta is merged in', () => { const log = toMutableEventLog([slotEvent(1), slotEvent(3)], 'c0'); mergeLoadedEvents(log, [slotEvent(2)]); @@ -557,21 +580,33 @@ describe('slot bookkeeping', () => { expect(log.events).toHaveLength(3); }); - it('raises maxSlot and drops reservations when a newer delta is merged in', () => { + it('raises the reservation pointer past a newer delta', () => { const log = toMutableEventLog([slotEvent(1)], 'c0'); reserveSlot(log); reserveSlot(log); - expect(log.reserved).toBe(2); + expect(log.nextSlot).toBe(4); mergeLoadedEvents(log, [slotEvent(2), slotEvent(5)]); expect(log.maxSlot).toBe(5); - // The merged events are the authority on which slots are taken, so the - // outstanding reservations (slots 2 and 3) are void. - expect(log.reserved).toBe(0); expect(reserveSlot(log)).toBe(6); }); + it('never rewinds the reservation pointer onto an outstanding slot', () => { + // A writer that loses its slot merges the delta and reserves again while + // its siblings are still in flight on theirs. Rewinding to `maxSlot + 1` + // would hand it slot 4, which a sibling already holds. + const log = toMutableEventLog([slotEvent(1)], 'c0'); + expect(reserveSlot(log)).toBe(2); + expect(reserveSlot(log)).toBe(3); + expect(reserveSlot(log)).toBe(4); + + mergeLoadedEvents(log, [slotEvent(2)]); + + expect(log.maxSlot).toBe(2); + expect(reserveSlot(log)).toBe(5); + }); + it('deduplicates merged events by id', () => { const log = toMutableEventLog([slotEvent(1)], 'c0'); mergeLoadedEvents(log, [slotEvent(1), slotEvent(2)]); @@ -581,6 +616,33 @@ describe('slot bookkeeping', () => { ]); }); + it('restores slot order when a merge brings in a lower slot', () => { + // Arrival order is not log order: a slot is reserved when its event is + // issued and written when the issue resolves, so a lower slot can be + // learned after a higher one. The replay consumes this array positionally, + // so an event left sitting ahead of the one it followed decides races the + // wrong way. + const log = toMutableEventLog([slotEvent(1), slotEvent(4)], 'c0'); + mergeLoadedEvents(log, [slotEvent(3), slotEvent(2)]); + expect(log.events.map((e) => e.eventId)).toEqual([ + slotEventId(1), + slotEventId(2), + slotEventId(3), + slotEventId(4), + ]); + }); + + it('leaves a ULID log in the order the World returned it', () => { + // ULID ids are minted at write time, so arrival order *is* log order and + // the World's ordering is the authority. + const events = [makeUlidEvent(1_700_000_000_000)]; + const later = makeUlidEvent(1_700_000_001_000); + const earlier = makeUlidEvent(1_699_999_999_000); + const log = toMutableEventLog(events, 'c0'); + mergeLoadedEvents(log, [later, earlier]); + expect(log.events).toEqual([events[0], later, earlier]); + }); + it('hands out contiguous distinct slots for a synchronous burst', () => { // The suspension flush issues every operation synchronously and awaits // them together; without contiguous reservation they would all propose the @@ -630,7 +692,7 @@ describe('slot bookkeeping', () => { eventCreateFenceFor(log, SPEC_VERSION_SLOT_IDENTITY - 1, { extraEvents: 1, }); - expect(log.reserved).toBe(0); + expect(log.nextSlot).toBe(1); }); it('proposes no event id for a ULID-numbered run', () => { @@ -638,7 +700,144 @@ describe('slot bookkeeping', () => { const log = toMutableEventLog([], null); const fence = eventCreateFenceFor(log, SPEC_VERSION_SLOT_IDENTITY - 1); expect(fence?.eventId).toBeUndefined(); - expect(log.reserved).toBe(0); + expect(log.nextSlot).toBe(1); + }); +}); + +describe('claimFenceFor', () => { + const slotEvent = (slot: number) => makeEvent(slotEventId(slot)); + + beforeEach(() => { + eventsListMock.mockReset(); + }); + + it('claims the next free slot and passes the observed maxSlot alongside it', async () => { + const log = toMutableEventLog([slotEvent(1), slotEvent(2)], 'c0'); + const claim = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY); + const op = vi.fn(async () => 'ok'); + + await expect(claim(op)).resolves.toBe('ok'); + expect(op).toHaveBeenCalledWith({ eventId: slotEventId(3), maxSlot: 2 }); + expect(eventsListMock).not.toHaveBeenCalled(); + }); + + it('takes each claim only once the create ahead of it has committed', async () => { + // A claim fences out a concurrent writer only while it names the slot right + // after the tail the writer saw, so a second create cannot be numbered + // until the first has landed. + const log = toMutableEventLog([slotEvent(1)], 'c0'); + const claim = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY); + const claimed: (string | undefined)[] = []; + let releaseFirst!: () => void; + const firstLanded = new Promise((resolve) => { + releaseFirst = resolve; + }); + + const first = claim(async (fence) => { + claimed.push(fence?.eventId); + await firstLanded; + return 'first'; + }); + const second = claim(async (fence) => { + claimed.push(fence?.eventId); + return 'second'; + }); + + await Promise.resolve(); + expect(claimed).toEqual([slotEventId(2)]); + + releaseFirst(); + await expect(first).resolves.toBe('first'); + await expect(second).resolves.toBe('second'); + expect(claimed).toEqual([slotEventId(2), slotEventId(3)]); + }); + + it('rejects a lost claim rather than re-addressing the write', async () => { + // A 409 says this replay decided from a log missing an event. Moving the + // same write to a free slot would commit that decision anyway, so the + // rejection propagates and the run replays. + const log = toMutableEventLog([slotEvent(1)], 'c0'); + const claim = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY); + const op = vi.fn(async (fence?: { eventId?: string }) => { + throw new SlotConflictError('taken', { + eventId: fence?.eventId as string, + events: [slotEvent(2)], + cursor: 'c1', + }); + }); + + await expect(claim(op)).rejects.toBeInstanceOf(SlotConflictError); + expect(op).toHaveBeenCalledTimes(1); + expect(eventsListMock).not.toHaveBeenCalled(); + }); + + it('leaves the rest of the batch claiming into the occupied range', async () => { + // The tail stops advancing for this log while the backend's moves on, so + // the siblings behind a rejected claim propose slots the backend has + // already filled and are rejected with it. + const log = toMutableEventLog([slotEvent(1)], 'c0'); + const claim = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY); + const loser = claim(async (fence) => { + throw new SlotConflictError('taken', { + eventId: fence?.eventId as string, + }); + }); + await expect(loser).rejects.toBeInstanceOf(SlotConflictError); + + await expect(claim(async (fence) => fence?.eventId)).resolves.toBe( + slotEventId(2) + ); + }); + + it('numbers a batch in the order its claims fire, each one above the last', async () => { + // A step that publishes the `step_created` it deferred takes the two slots + // below its claim, and the next claim starts above both. + const log = toMutableEventLog([slotEvent(1)], 'c0'); + const withCreate = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY, { + extraEvents: 1, + }); + const plain = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY); + + const claimed: (string | undefined)[] = []; + const record = (fence?: { eventId?: string }) => { + claimed.push(fence?.eventId); + return Promise.resolve('ok'); + }; + await withCreate(record); + await plain(record); + + expect(claimed).toEqual([slotEventId(3), slotEventId(4)]); + }); + + it('rethrows a non-conflict error immediately, without merging', async () => { + const log = toMutableEventLog([slotEvent(1)], 'c0'); + const claim = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY); + const op = vi.fn(async () => { + throw new PreconditionFailedError('stale'); + }); + + await expect(claim(op)).rejects.toBeInstanceOf(PreconditionFailedError); + expect(op).toHaveBeenCalledTimes(1); + expect(eventsListMock).not.toHaveBeenCalled(); + }); + + it('leaves a ULID-numbered batch on one shared watermark, unserialized', async () => { + // A 412 compares time, so every member of the batch carries the same fence + // value and the batch fails as a unit — which is what the caller's + // fresh-replay path expects. + const time = 1_700_000_000_000; + const log = toMutableEventLog([makeUlidEvent(time)], 'c0'); + const claim = claimFenceFor(log, SPEC_VERSION_SLOT_IDENTITY - 1); + const op = vi.fn(async () => { + throw new PreconditionFailedError('stale'); + }); + + await expect(claim(op)).rejects.toBeInstanceOf(PreconditionFailedError); + expect(op).toHaveBeenCalledTimes(1); + expect(op).toHaveBeenCalledWith( + expect.objectContaining({ stateUpdatedAt: time }) + ); + expect(eventsListMock).not.toHaveBeenCalled(); }); }); diff --git a/packages/core/src/runtime/helpers.ts b/packages/core/src/runtime/helpers.ts index a6f1711001..9f502c3d96 100644 --- a/packages/core/src/runtime/helpers.ts +++ b/packages/core/src/runtime/helpers.ts @@ -17,6 +17,7 @@ import type { import { getQueueTopicPrefix, HealthCheckPayloadSchema, + isSlotId, maxSlotOf, resolveQueueNamespace, SPEC_VERSION_CURRENT, @@ -465,7 +466,22 @@ function recordRequestedEventCursor( } /** - * Appends events whose IDs are not already present in `target`. + * Appends events whose IDs are not already present in `target`, keeping a + * slot-numbered log in slot order. + * + * Arrival order is not log order under slot identity. A slot is reserved when + * its event is issued and written when that issue resolves, so a lower slot can + * be committed after a higher one, and a merge that only appends leaves the + * array in the order the events were *learned*, not the order they occupy. + * That difference decides races: the replay consumes this array positionally + * — the delivery barriers in `pendingDeliveryBarriers` are keyed on the index — + * so a `step_completed` sitting ahead of a `wait_completed` it actually + * follows makes the replay take the branch the log does not record, and the + * next event it reads belongs to a step it never started. + * + * Sorting by event id *is* sorting by slot: ids are zero-padded to a fixed + * width, and a slot-numbered run's log carries no ULID ids to interleave with + * them. * * Pass the IDs currently present in `target` when appending repeatedly to the * same array. The set is updated alongside `target`. @@ -489,13 +505,19 @@ 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)) { continue; } ids.add(event.eventId); + outOfOrder ||= + target.length > 0 && event.eventId < target[target.length - 1].eventId; target.push(event); } + if (outOfOrder && isSlotId(target[0].eventId)) { + target.sort((a, b) => (a.eventId < b.eventId ? -1 : 1)); + } } function assertEventPaginationProgress( @@ -676,24 +698,51 @@ export interface MutableEventLog extends LoadedEventLog { */ maxSlot: number; /** - * Slots handed out by `reserveSlot` past `maxSlot` whose events have not been - * merged back yet. Reset whenever the log is merged into, because the merged - * events are the authority on which slots are taken. + * Next slot `reserveSlot` will hand out. Only a writer holding the log's + * write chain may draw from it, and it is rewound to `maxSlot + 1` when a + * claim is rejected so the rest of the batch claims into the occupied range + * and is rejected with it. */ - reserved: number; + nextSlot: number; + /** + * Tail of the chain of creates numbered off this log, or `undefined` when + * none is in flight. + * + * Slot claims are taken one at a time. A claim only fences out a concurrent + * writer if it names the slot right after the log's committed tail: numbering + * a whole concurrent batch up front hands its later writes slots far enough + * above the tail that a foreign event landing in between clears every fence + * they carry, and the batch commits decisions taken without it. + */ + writeChain?: Promise; } -/** A `MutableEventLog` over a freshly loaded snapshot. */ +/** + * A `MutableEventLog` over a freshly loaded snapshot. + * + * `slotFloor` is a slot known to be published that the snapshot may not contain + * — the run's own `run_started`, whose write turbo backgrounds while replaying + * against an empty log. Numbering a claim from the snapshot alone would then + * propose a slot that is already taken, so every first write of a turbo + * invocation would conflict and cost the run an extra replay. + */ export function toMutableEventLog( events: Event[], - cursor: string | null + cursor: string | null, + slotFloor = 0 ): MutableEventLog { - return { events, cursor, maxSlot: maxSlotOf(events), reserved: 0 }; + const maxSlot = Math.max(maxSlotOf(events), slotFloor); + return { + events, + cursor, + maxSlot, + nextSlot: maxSlot + 1, + }; } /** * Merges loaded events into `log` in place, keeping `maxSlot` current and - * dropping outstanding reservations (the merged events supersede them). + * advancing the reservation pointer past the events merged in. */ export function mergeLoadedEvents( log: MutableEventLog, @@ -701,22 +750,20 @@ export function mergeLoadedEvents( ): void { appendUniqueEvents(log.events, events); log.maxSlot = Math.max(log.maxSlot, maxSlotOf(events)); - log.reserved = 0; + log.nextSlot = Math.max(log.nextSlot, log.maxSlot + 1); } /** - * Claims the next free slot in `log`, synchronously at the moment an event is - * issued. + * Claims the next free slot in `log`. * - * Reservations are contiguous rather than all-`maxSlot + 1` because a - * suspension flushes its operations concurrently: without them every operation - * in the flush would propose the same slot and all but one would conflict, on - * every single flush. Operations are built in deterministic replay order, so - * the slot each one draws is replay-stable too. + * Only call this while holding the log's write chain: the claim is the fence, + * and it only fences anything while it names the slot immediately after the + * tail this writer has seen. */ export function reserveSlot(log: MutableEventLog): number { - log.reserved += 1; - return log.maxSlot + log.reserved; + const slot = log.nextSlot; + log.nextSlot = slot + 1; + return slot; } /** @@ -958,18 +1005,118 @@ export function eventCreateFenceFor( options?: { extraEvents?: number } ): EventCreateFence { if (usesSlotIdentity(specVersion)) { - const maxSlot = log.maxSlot; - // The extra events sit below the one being created, matching the order a - // reader expects (a step is created before it starts) — so their slots are - // reserved first and the claim names the last of the run. - for (let i = 0; i < (options?.extraEvents ?? 0); i++) { - reserveSlot(log); - } - return { eventId: slotEventId(reserveSlot(log)), maxSlot }; + return reserveSlotFence(log, options?.extraEvents ?? 0); } return preconditionSnapshotParams(log.events, log.cursor); } +/** + * Reserves this write's slots off `log` and names the one the event itself + * takes. + * + * `extraEvents` sit below the one being created, matching the order a reader + * expects (a step is created before it starts), so their slots are reserved + * first and the claim names the last of the run — a World that writes a pair + * derives the lower id from the one it was given. + */ +function reserveSlotFence( + log: MutableEventLog, + extraEvents: number +): EventCreateFence { + const maxSlot = log.maxSlot; + for (let i = 0; i < extraEvents; i++) { + reserveSlot(log); + } + return { eventId: slotEventId(reserveSlot(log)), maxSlot }; +} + +/** + * Runs one slot-numbered create with the log's claim to itself, taking its slot + * only once every create ahead of it on the log has settled. + * + * A slot claim is an assertion about the tail: "nothing has been published + * since the view I decided from". Claims handed out up front to a concurrent + * batch can only assert that about the first of them — the rest sit above slots + * their own siblings have yet to fill, so a foreign event landing in that space + * satisfies their fences too and they commit on a view that is already missing + * it. Taking claims one at a time keeps every write's fence tight against the + * tail the writer actually saw. + * + * A rejection therefore stops the whole batch rather than only its own write: + * the log's tail stops advancing while the backend's moves on, so the claims + * behind it fall inside the occupied range and are rejected in turn. That is + * the intent — the batch was decided from a log missing an event, so none of it + * should land. + */ +async function withSerializedClaim( + log: MutableEventLog, + extraEvents: number, + op: (fence: EventCreateFence) => Promise +): Promise { + const ahead = log.writeChain; + let done!: () => void; + log.writeChain = new Promise((resolve) => { + done = resolve; + }); + if (ahead) { + await ahead; + } + try { + const fence = reserveSlotFence(log, extraEvents); + const result = await op(fence); + log.maxSlot = Math.max( + log.maxSlot, + maxSlotOf([{ eventId: fence.eventId ?? '' }]) + ); + log.nextSlot = Math.max(log.nextSlot, log.maxSlot + 1); + return result; + } catch (error) { + // The slots this attempt drew are not the writer's, and the tail is at + // least as high as the claim that lost. Rewinding onto the occupied range + // is what makes the rest of the batch fail with it. + log.nextSlot = log.maxSlot + 1; + throw error; + } finally { + done(); + } +} + +/** + * Runs one event create under whichever fence its run uses. + */ +export type FencedCreate = ( + op: (fence: EventCreateFence | undefined) => Promise +) => Promise; + +/** + * The fenced create for a claim issued from a concurrent batch — an inline + * step's `step_started`, or a suspension flush's writes. + * + * Under slot numbering this serializes the batch's claims so each one is taken + * against the tail its writer actually saw ({@link withSerializedClaim}); under + * the watermark every claim in the batch legitimately carries the same + * snapshot, so they all run concurrently off one fence. + * + * Neither scheme re-issues a rejected claim at a free number. A rejection says + * this replay decided from a log it had not fully seen, and the missing event + * can be the one that would have sent the workflow down another branch — with + * correlation ids counted in branch order, every id after that branch moves + * with it, so the re-issued write would land under an identity that now names a + * different step. The rejection propagates and the run replays over the + * corrected log ({@link isStaleWriteRejection}). + */ +export function claimFenceFor( + log: MutableEventLog, + specVersion: number | undefined, + options?: { extraEvents?: number } +): FencedCreate { + if (usesSlotIdentity(specVersion)) { + return (op) => withSerializedClaim(log, options?.extraEvents ?? 0, op); + } + const fence = eventCreateFenceFor(log, specVersion, options); + return (op) => op(fence); +} + /** * CORS headers for health check responses. * Allows the observability UI to check endpoint health from a different origin. diff --git a/packages/core/src/runtime/precondition-guard-replay.test.ts b/packages/core/src/runtime/precondition-guard-replay.test.ts index fefa5a0bcf..e9559008b9 100644 --- a/packages/core/src/runtime/precondition-guard-replay.test.ts +++ b/packages/core/src/runtime/precondition-guard-replay.test.ts @@ -10,7 +10,10 @@ * 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). + * consumes with no events.list round trip at all (first restart only). A run + * numbering its events by slot instead heals from its cursor, since slot ids + * sort in write order and density proves afterwards that the page closed the + * gap; a short count sends it back to the full reload. * 3. Restarts are bounded; once the bound is spent the runtime schedules a * delayed re-invocation instead of failing the run — and that escalation is * itself counted on the queue message, so a run that can never observe its @@ -19,11 +22,19 @@ * Modeled on wait-completion-replay.test.ts, but with real ULID event IDs so * latestEventStateUpdatedAt() actually derives snapshot times. */ -import { PreconditionFailedError, RUN_ERROR_CODES } from '@workflow/errors'; +import { + PreconditionFailedError, + RUN_ERROR_CODES, + SlotConflictError, +} from '@workflow/errors'; import { type CreateEventRequest, type Event, + FIRST_SLOT, SPEC_VERSION_CURRENT, + SPEC_VERSION_SLOT_IDENTITY, + slotFromId, + slotIdBody, type WorkflowRun, type World, } from '@workflow/world'; @@ -42,6 +53,7 @@ import { getPreconditionMaxInProcessRestarts, getPreconditionMaxReinvocations, getPreconditionReinvokeDelaySeconds, + PRECONDITION_MAX_INPROCESS_RESTARTS, } from './constants.js'; import { setWorld } from './world.js'; @@ -88,6 +100,8 @@ interface SnapshotParams { stateUpdatedAt: number | undefined; stateEventCount: number | undefined; stateCursor: string | undefined; + /** The claimed position, on a run that numbers its events by slot. */ + eventId?: string | undefined; } async function runPreconditionScenario(options: { @@ -98,6 +112,17 @@ async function runPreconditionScenario(options: { * or a payload the runtime must refuse to narrow (`malformed`). */ attachDelta?: 'complete' | 'malformed'; + /** + * Number the run's events and correlation ids by slot rather than by ULID, + * and reject with the 409 a taken slot produces instead of the 412. + */ + slotIdentity?: boolean; + /** + * Slot mode only: land a second out-of-band event ahead of the hook and hide + * it from the page above the cursor, so a restart that tops up incrementally + * ends holding a log that is short of its own highest slot. + */ + hideFirstOutsideEventFromCursor?: boolean; }) { vi.spyOn(Date, 'now').mockReturnValue(+fixedNow); @@ -112,14 +137,24 @@ async function runPreconditionScenario(options: { undefined ); + const SPEC = options.slotIdentity + ? SPEC_VERSION_SLOT_IDENTITY + : SPEC_VERSION_CURRENT; + const { globalThis: vmGlobalThis } = createContext({ seed: `${runId}:${workflowName}:${deploymentId}`, fixedTimestamp: +startedAt, }); const vmUlid = monotonicFactory(() => vmGlobalThis.Math.random()); + // Hooks keep their ULID ids in both modes; steps and waits count per kind + // once the run is on slot identity. const hookCorrelationId = `hook_${vmUlid(+startedAt)}`; - const syncStep0CorrelationId = `step_${vmUlid(+startedAt)}`; - const waitCorrelationId = `wait_${vmUlid(+startedAt)}`; + const syncStep0CorrelationId = options.slotIdentity + ? `step_${slotIdBody(FIRST_SLOT)}` + : `step_${vmUlid(+startedAt)}`; + const waitCorrelationId = options.slotIdentity + ? `wait_${slotIdBody(FIRST_SLOT)}` + : `wait_${vmUlid(+startedAt)}`; const workflowRun: WorkflowRun = { runId, @@ -127,23 +162,35 @@ async function runPreconditionScenario(options: { status: 'running', input: workflowArgs, deploymentId, - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, startedAt, createdAt: startedAt, updatedAt: startedAt, }; // Real ULID event IDs at controlled times so latestEventStateUpdatedAt() - // resolves an actual epoch-ms snapshot from the loaded log. + // resolves an actual epoch-ms snapshot from the loaded log. Under slot + // identity the id is instead the next free slot, or the one the writer + // claimed, and the log stays dense from slot 1. const hostUlid = monotonicFactory(); let eventIndex = 0; - const event = (data: CreateEventRequest, atMs?: number): Event => { + let nextSlot = FIRST_SLOT; + const event = ( + data: CreateEventRequest, + atMs?: number, + claimedEventId?: string + ): Event => { const t = atMs ?? +startedAt + ++eventIndex * 100; + let eventId = `evnt_${hostUlid(t)}`; + if (options.slotIdentity) { + eventId = claimedEventId ?? `evnt_${slotIdBody(nextSlot)}`; + nextSlot = Math.max(nextSlot, slotFromId(eventId) ?? nextSlot) + 1; + } return { ...data, - specVersion: data.specVersion ?? SPEC_VERSION_CURRENT, + specVersion: data.specVersion ?? SPEC, runId, - eventId: `evnt_${hostUlid(t)}`, + eventId, createdAt: new Date(t), } as Event; }; @@ -151,19 +198,19 @@ async function runPreconditionScenario(options: { const staleEvents: Event[] = [ event({ eventType: 'run_created', - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, eventData: { deploymentId, workflowName, input: workflowArgs }, }), - event({ eventType: 'run_started', specVersion: SPEC_VERSION_CURRENT }), + event({ eventType: 'run_started', specVersion: SPEC }), event({ eventType: 'hook_created', - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, correlationId: hookCorrelationId, eventData: { token: hookToken }, }), event({ eventType: 'step_created', - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, correlationId: syncStep0CorrelationId, eventData: { stepName: 'syncStep', @@ -176,12 +223,12 @@ async function runPreconditionScenario(options: { }), event({ eventType: 'step_started', - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, correlationId: syncStep0CorrelationId, }), event({ eventType: 'step_completed', - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, correlationId: syncStep0CorrelationId, eventData: { result: await dehydrateStepReturnValue(undefined, runId, undefined), @@ -189,7 +236,7 @@ async function runPreconditionScenario(options: { }), event({ eventType: 'wait_created', - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, correlationId: waitCorrelationId, eventData: { resumeAt: new Date(+startedAt - 1_000) }, }), @@ -199,10 +246,30 @@ async function runPreconditionScenario(options: { const staleEventsCursor = 'cursor-after-stale-events'; const OUTSIDE_EVENT_MS = +startedAt + 5_000; + // Lands ahead of the winning delivery and is withheld from the page above + // the cursor, so an incremental top-up comes back holding fewer events than + // its own highest slot names. + const hiddenOutsideEvent = options.hideFirstOutsideEventFromCursor + ? event( + { + eventType: 'hook_received', + specVersion: SPEC, + correlationId: hookCorrelationId, + eventData: { + payload: await dehydrateStepReturnValue( + { value: 'hook-poke' }, + runId, + undefined + ), + }, + }, + OUTSIDE_EVENT_MS - 1 + ) + : undefined; const hookReceivedEvent = event( { eventType: 'hook_received', - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, correlationId: hookCorrelationId, eventData: { payload: await dehydrateStepReturnValue( @@ -233,7 +300,9 @@ async function runPreconditionScenario(options: { }) => { const data = params.pagination?.cursor === staleEventsCursor - ? durableEvents.slice(staleEvents.length) + ? durableEvents + .slice(staleEvents.length) + .filter((e) => e !== hiddenOutsideEvent) : [...durableEvents]; return { data, @@ -262,6 +331,7 @@ async function runPreconditionScenario(options: { stateUpdatedAt?: number; stateEventCount?: number; stateCursor?: string; + eventId?: string; } ) => { createParams.push({ @@ -269,6 +339,7 @@ async function runPreconditionScenario(options: { stateUpdatedAt: params?.stateUpdatedAt, stateEventCount: params?.stateEventCount, stateCursor: params?.stateCursor, + eventId: params?.eventId, }); if (request.eventType === 'run_started') { @@ -278,11 +349,32 @@ async function runPreconditionScenario(options: { if (request.eventType === 'wait_completed') { // The out-of-band hook payload becomes durable just before the // wait_completed commit — this is the exact race the guard closes. + if (hiddenOutsideEvent && !durableEvents.includes(hiddenOutsideEvent)) { + durableEvents.push(hiddenOutsideEvent); + } if (!durableEvents.includes(hookReceivedEvent)) { durableEvents.push(hookReceivedEvent); } if (waitCompletedRejections < (options.rejectWaitCompletedTimes ?? 0)) { waitCompletedRejections++; + // Both rejections say the same thing — "you decided from a log you + // had not fully seen" — and differ only in how the writer found out: + // a watermark comparison, or the slot it claimed already being + // occupied by the event it was missing. + if (options.slotIdentity) { + throw new SlotConflictError( + `Event ${params?.eventId} is already taken.`, + { + eventId: params?.eventId ?? '', + events: + options.attachDelta === 'complete' + ? [hookReceivedEvent] + : undefined, + cursor: + options.attachDelta === 'complete' ? 'cursor-409' : undefined, + } + ); + } throw new PreconditionFailedError( 'Run state is stale: the client event log is missing at least one event at or before its snapshot.', options.attachDelta === undefined @@ -303,17 +395,30 @@ async function runPreconditionScenario(options: { !!request.eventData && (request.eventData as { input?: unknown }).input !== undefined; let effectiveRequest = request; + // A claim covers the whole write, so a lazy start's synthesized + // step_created takes the claimed position and the step_started the one + // after it — the two extra slots the caller reserved for exactly this. + let claimedEventId = params?.eventId; + const takeClaim = () => { + const claim = claimedEventId; + claimedEventId = undefined; + return claim; + }; if (lazyStepStart) { const lazyData = request.eventData as { stepName?: string; input?: unknown; }; - const syntheticStepCreated = event({ - eventType: 'step_created', - specVersion: SPEC_VERSION_CURRENT, - correlationId: request.correlationId, - eventData: { stepName: lazyData.stepName, input: lazyData.input }, - } as CreateEventRequest); + const syntheticStepCreated = event( + { + eventType: 'step_created', + specVersion: SPEC, + correlationId: request.correlationId, + eventData: { stepName: lazyData.stepName, input: lazyData.input }, + } as CreateEventRequest, + undefined, + takeClaim() + ); durableEvents.push(syntheticStepCreated); createdEvents.push(syntheticStepCreated); const { input: _strippedInput, ...startEventData } = lazyData; @@ -323,7 +428,7 @@ async function runPreconditionScenario(options: { } as CreateEventRequest; } - const created = event(effectiveRequest); + const created = event(effectiveRequest, undefined, takeClaim()); durableEvents.push(created); createdEvents.push(created); if (effectiveRequest.eventType === 'step_started') { @@ -343,7 +448,7 @@ async function runPreconditionScenario(options: { const queue = vi.fn().mockResolvedValue({ messageId: 'msg_step' }); const fakeWorld = { - specVersion: SPEC_VERSION_CURRENT, + specVersion: SPEC, createQueueHandler: vi.fn((_prefix, handler) => { capturedHandler = handler; return vi.fn(); @@ -1051,6 +1156,89 @@ describe('precondition guard through the real replay loop', () => { ); }); + it('heals a slot-numbered log from its cursor instead of reloading it whole', async () => { + const result = await runPreconditionScenario({ + slotIdentity: true, + rejectWaitCompletedTimes: 1, + }); + await result.handlerInvocation; + + expect(result.waitCompletedRejectionCount()).toBe(1); + // Slot ids sort in write order, so the event the snapshot was missing is + // strictly above the cursor and one incremental page brings it in. The + // full reload the ULID path needs exists only because a hole defined by + // ULID time can sort below the cursor. + expect(cursorlessLoads(result.listEvents)).toBe(0); + + const waitCreates = result.createParams.filter( + (c) => c.eventType === 'wait_completed' + ); + expect(waitCreates).toHaveLength(2); + // No watermark is sent on a run that fences by position. + expect(waitCreates[0]?.stateUpdatedAt).toBeUndefined(); + // The rejected claim sat at the position the hook had just taken; the + // restarted replay claims the one after it. + expect(slotFromId(waitCreates[1]?.eventId ?? '')).toBe( + (slotFromId(waitCreates[0]?.eventId ?? '') ?? 0) + 1 + ); + + // Replay after the restart observed the hook and took the hook branch. + expect(result.createdEvents).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + eventType: 'step_created', + eventData: expect.objectContaining({ stepName: 'drainStep' }), + }), + ]) + ); + }); + + it('falls back to the full reload when a slot top-up leaves the log short of its own highest slot', async () => { + const result = await runPreconditionScenario({ + slotIdentity: true, + rejectWaitCompletedTimes: 1, + hideFirstOutsideEventFromCursor: true, + }); + await result.handlerInvocation; + + // A slot log is dense from slot 1, so a complete one holds exactly + // `maxSlot` events. The page above the cursor withheld one, the count came + // up short, and the restart fell through to the authoritative load — the + // check is what lets the cheap path be taken in the first place. + expect(cursorlessLoads(result.listEvents)).toBe(1); + expect( + result.createParams.filter((c) => c.eventType === 'wait_completed') + ).toHaveLength(2); + expect(result.createdEvents).toEqual( + expect.arrayContaining([ + expect.objectContaining({ + eventType: 'step_created', + eventData: expect.objectContaining({ stepName: 'drainStep' }), + }), + ]) + ); + }); + + it('spends a larger in-process restart budget when restarts heal from the cursor', async () => { + // One more rejection than a reloading run is allowed to absorb. That run + // would be out of budget and re-invoked; this one keeps recovering in + // process, because each of its restarts costs one incremental page rather + // than a full reload and so is not worth a queue hop to avoid. + const rejections = PRECONDITION_MAX_INPROCESS_RESTARTS + 1; + const result = await runPreconditionScenario({ + slotIdentity: true, + rejectWaitCompletedTimes: rejections, + }); + + await expect(result.handlerInvocation).resolves.toBeUndefined(); + expect(result.waitCompletedRejectionCount()).toBe(rejections); + expect( + result.createParams.filter((c) => c.eventType === 'wait_completed') + ).toHaveLength(rejections + 1); + // Every one of them healed from the cursor. + expect(cursorlessLoads(result.listEvents)).toBe(0); + }); + it('falls back to the full reload when the 412 payload does not narrow to events', async () => { const result = await runPreconditionScenario({ rejectWaitCompletedTimes: 1, diff --git a/packages/core/src/runtime/start.test.ts b/packages/core/src/runtime/start.test.ts index 8904600556..9d96422c7c 100644 --- a/packages/core/src/runtime/start.test.ts +++ b/packages/core/src/runtime/start.test.ts @@ -2,6 +2,7 @@ import { WorkflowRuntimeError, WorkflowWorldError } from '@workflow/errors'; import { SPEC_VERSION_CURRENT, SPEC_VERSION_LEGACY, + SPEC_VERSION_MAX_SUPPORTED, SPEC_VERSION_SUPPORTS_ATTRIBUTES, SPEC_VERSION_SUPPORTS_CBOR_QUEUE_TRANSPORT, } from '@workflow/world'; @@ -136,7 +137,7 @@ describe('start', () => { } as any); await expect(start(validWorkflow, [])).rejects.toThrow( - 'requires a World with matching spec version' + 'requires a World with spec version' ); expect(mockEventsCreate).not.toHaveBeenCalled(); expect(mockQueue).not.toHaveBeenCalled(); @@ -174,7 +175,7 @@ describe('start', () => { } as any); await expect(start(validWorkflow, [])).rejects.toThrow( - 'requires a World with matching spec version' + 'requires a World with spec version' ); expect(mockEventsCreate).not.toHaveBeenCalled(); expect(mockQueue).not.toHaveBeenCalled(); @@ -186,19 +187,43 @@ describe('start', () => { }); setWorld({ - specVersion: SPEC_VERSION_CURRENT + 1, + specVersion: SPEC_VERSION_MAX_SUPPORTED + 1, getDeploymentId: vi.fn().mockResolvedValue('deploy_123'), events: { create: mockEventsCreate }, queue: mockQueue, } as any); await expect(start(validWorkflow, [])).rejects.toThrow( - 'requires a World with matching spec version' + 'requires a World with spec version' ); expect(mockEventsCreate).not.toHaveBeenCalled(); expect(mockQueue).not.toHaveBeenCalled(); }); + it('accepts a world that mints a newer version this runtime supports', async () => { + // A world opted into slot identity stamps a version above the runtime's + // current one. The runtime can read and write those runs, so the + // handshake has to pass and the run has to keep the world's version. + const validWorkflow = Object.assign(() => Promise.resolve('result'), { + workflowId: 'test-workflow', + }); + + setWorld({ + specVersion: SPEC_VERSION_MAX_SUPPORTED, + getDeploymentId: vi.fn().mockResolvedValue('deploy_123'), + events: { create: mockEventsCreate }, + queue: mockQueue, + } as any); + + await start(validWorkflow, []); + + expect(mockEventsCreate).toHaveBeenCalledWith( + expect.stringMatching(/^wrun_/), + expect.objectContaining({ specVersion: SPEC_VERSION_MAX_SUPPORTED }), + expect.anything() + ); + }); + it('should use provided specVersion when passed in options', async () => { const validWorkflow = Object.assign(() => Promise.resolve('result'), { workflowId: 'test-workflow', diff --git a/packages/core/src/runtime/step-executor.test.ts b/packages/core/src/runtime/step-executor.test.ts index 4a4ed0e9cb..a0e9e615a3 100644 --- a/packages/core/src/runtime/step-executor.test.ts +++ b/packages/core/src/runtime/step-executor.test.ts @@ -1,6 +1,7 @@ import { mkdtempSync } from 'node:fs'; import { tmpdir } from 'node:os'; import { join } from 'node:path'; +import { SlotConflictError } from '@workflow/errors'; import type { Event, World } from '@workflow/world'; import { SPEC_VERSION_CURRENT } from '@workflow/world'; import { createWorld } from '@workflow/world-local'; @@ -197,7 +198,7 @@ describe('executeStep — compute instance stamping', () => { workflowStartedAt: Date.now(), stepId, stepName, - eventCreateFence: preconditionSnapshot, + claimFence: (op) => op(preconditionSnapshot), }); const started = createSpy.mock.calls.filter( @@ -210,3 +211,153 @@ describe('executeStep — compute instance stamping', () => { expect(started[0]?.[2]).toMatchObject(preconditionSnapshot); }); }); + +// A run that numbers its events by position rejects a claim whose slot was +// taken, and the rejection carries the events that took it. When those events +// show the same step already started, the loser is in the ordinary "another +// handler owns this step" position and skips — the outcome an unfenced write +// reaches via EntityConflictError. Anything less than proof of the same call +// must propagate instead, because correlation ids are positional: a replay +// that diverged can reach the same step number naming a different call. +describe('executeStep — slot rejection carrying a duplicate start', () => { + afterEach(() => { + counter += 1; + }); + + function startedEvent(opts: { + stepId: string; + stepName: string; + input?: unknown; + }) { + return { + eventType: 'step_started', + correlationId: opts.stepId, + eventData: { + stepName: opts.stepName, + ...(opts.input !== undefined ? { input: opts.input } : {}), + }, + }; + } + + async function runAgainstRejection(opts: { + events: unknown[]; + lazyStepInput?: Uint8Array; + onBody?: () => void; + }) { + const world = makeWorld(); + const stepName = uniqueStepName(); + let bodyRuns = 0; + const { runId, stepId } = await setupRunningStep({ + world, + stepName, + onBody: () => { + bodyRuns += 1; + opts.onBody?.(); + }, + }); + + const rejection = new SlotConflictError('slot taken', { + eventId: 'evnt_00000000000000000000000007', + events: opts.events.map((build) => + typeof build === 'function' + ? (build as (ids: { stepId: string; stepName: string }) => unknown)({ + stepId, + stepName, + }) + : build + ), + }); + + const run = () => + executeStep({ + world, + workflowRunId: runId, + workflowName: 'wf', + workflowStartedAt: Date.now(), + stepId, + stepName, + lazyStepInput: opts.lazyStepInput, + // Take the awaited claim path so the rejection is translated before a + // body ever runs; the optimistic path reconciles the same way but + // would run the body first and muddy the assertion. + suppressOptimisticStart: true, + claimFence: () => Promise.reject(rejection), + }); + + return { run, bodyRuns: () => bodyRuns, stepName, stepId }; + } + + it('skips when the delta already started this step (no lazy input to compare)', async () => { + const { run, bodyRuns } = await runAgainstRejection({ + events: [ + (ids: { stepId: string; stepName: string }) => startedEvent(ids), + ], + }); + + await expect(run()).resolves.toEqual({ type: 'skipped' }); + expect(bodyRuns()).toBe(0); + }); + + it('skips when the delta started this step with byte-identical input', async () => { + const input = new Uint8Array([1, 2, 3]); + const { run, bodyRuns } = await runAgainstRejection({ + lazyStepInput: input, + events: [ + (ids: { stepId: string; stepName: string }) => + startedEvent({ ...ids, input: new Uint8Array([1, 2, 3]) }), + ], + }); + + await expect(run()).resolves.toEqual({ type: 'skipped' }); + expect(bodyRuns()).toBe(0); + }); + + it('propagates when the delta started the same slot under a different step name', async () => { + const { run } = await runAgainstRejection({ + events: [ + (ids: { stepId: string }) => + startedEvent({ ...ids, stepName: 'step//./other//someOtherStep' }), + ], + }); + + await expect(run()).rejects.toThrow(SlotConflictError); + }); + + it('propagates when the delta started this step with different input bytes', async () => { + const { run } = await runAgainstRejection({ + lazyStepInput: new Uint8Array([1, 2, 3]), + events: [ + (ids: { stepId: string; stepName: string }) => + startedEvent({ ...ids, input: new Uint8Array([1, 2, 4]) }), + ], + }); + + await expect(run()).rejects.toThrow(SlotConflictError); + }); + + it('propagates when the delta start carries a remote ref instead of inline bytes', async () => { + // A ref says nothing about the value behind it, so identity is unprovable + // and the replay restart is the only correct answer. + const { run } = await runAgainstRejection({ + lazyStepInput: new Uint8Array([1, 2, 3]), + events: [ + (ids: { stepId: string; stepName: string }) => + startedEvent({ ...ids, input: { ref: 'payload_abc' } }), + ], + }); + + await expect(run()).rejects.toThrow(SlotConflictError); + }); + + it('propagates when the delta holds no start for this step', async () => { + const { run } = await runAgainstRejection({ + events: [ + { eventType: 'step_completed', correlationId: 'step_other' }, + (ids: { stepName: string }) => + startedEvent({ ...ids, stepId: 'step_other' }), + ], + }); + + await expect(run()).rejects.toThrow(SlotConflictError); + }); +}); diff --git a/packages/core/src/runtime/step-executor.ts b/packages/core/src/runtime/step-executor.ts index 93099305a5..8d1e7f61bf 100644 --- a/packages/core/src/runtime/step-executor.ts +++ b/packages/core/src/runtime/step-executor.ts @@ -4,6 +4,7 @@ import { FatalError, RetryableError, RunExpiredError, + SlotConflictError, ThrottleError, TooEarlyError, WorkflowRuntimeError, @@ -53,6 +54,7 @@ import { getPortLazy } from './get-port-lazy.js'; import { type EventCreateFence, type EventCreator, + type FencedCreate, memoizeEncryptionKey, } from './helpers.js'; import { ReplayRecoveryReporter } from './replay-recovery-reporter.js'; @@ -86,6 +88,73 @@ function extractInlineDelta( }; } +/** + * Byte-equality for two dehydrated step inputs, used to decide whether a + * conflicting `step_started` describes the same call as ours. Only inline + * bytes can answer that: a `SerializedData` that came back as a remote ref + * carries no payload, and two refs being unequal says nothing about the + * values behind them, so anything that is not a pair of `Uint8Array`s is + * reported as "cannot tell". + */ +function sameSerializedInput( + a: SerializedData | undefined, + b: SerializedData | undefined +): boolean { + if (!(a instanceof Uint8Array) || !(b instanceof Uint8Array)) return false; + if (a.byteLength !== b.byteLength) return false; + for (let i = 0; i < a.byteLength; i++) { + if (a[i] !== b[i]) return false; + } + return true; +} + +/** + * Decide whether a slot rejection carrying a delta is a *benign duplicate*: + * the events we lost the slot to already contain a `step_started` for this + * exact step, so a concurrent handler is running (or has run) the very call + * we were about to claim. The step is then someone else's to finish and we + * can skip, exactly as we do on the `EntityConflictError` the unfenced path + * would have raised instead. + * + * The identity test is deliberately strict. Correlation ids are positional + * under slot identity, so a replay that diverged — a `Promise.race` between + * a hook and a step resolving the other way, say — can arrive at the same + * `step_N` naming a different call. Matching on the correlation id alone + * would let such a replay adopt a foreign step's completion as its own. So + * the step name must match, and on the lazy path (where we hold the input) + * the inputs must be byte-identical. Anything we cannot prove identical + * returns false and takes the replay restart, which is always correct and + * merely slower. + */ +function isBenignDuplicateStart( + events: unknown[], + stepId: string, + stepName: string, + lazyStepInput: SerializedData | undefined +): boolean { + for (const candidate of events) { + if (!candidate || typeof candidate !== 'object') continue; + const event = candidate as { + eventType?: unknown; + correlationId?: unknown; + eventData?: { stepName?: unknown; input?: unknown } | null; + }; + if (event.eventType !== 'step_started') continue; + if (event.correlationId !== stepId) continue; + if (event.eventData?.stepName !== stepName) continue; + if (lazyStepInput === undefined) return true; + if ( + sameSerializedInput( + lazyStepInput, + event.eventData?.input as SerializedData + ) + ) { + return true; + } + } + return false; +} + export interface StepExecutorParams { world: World; workflowRunId: string; @@ -141,23 +210,27 @@ export interface StepExecutorParams { */ inlineDeltaSinceCursor?: string; /** - * Concurrency fence to attach to this step's `step_started` claim: the event - * slot the claim occupies, or the caller's replay snapshot (`stateUpdatedAt`, - * epoch ms of the latest event it loaded) for a run on the older numbering. + * Runs this step's `step_started` claim under its run's concurrency fence: + * the event slot the claim occupies, or the caller's replay snapshot + * (`stateUpdatedAt`, epoch ms of the latest event it loaded) for a run on the + * older numbering. * * On the lazy inline path the claim is the step's FIRST durable write (its * `step_created` is deferred), so without a fence it would be unguarded * entirely: a replay working from a stale view could claim — and then commit — * a step scheduled without observing an out-of-band event. A fencing World * rejects such a claim with `SlotConflictError` (409) or - * `PreconditionFailedError` (412); executeStep does NOT translate either - * 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. + * `PreconditionFailedError` (412). + * + * Whether a rejection is retried in place is the caller's decision, made per + * scheme — see `claimFenceFor`. Either way executeStep does NOT translate a + * rejection that reaches it, so an unretried one propagates for the caller to + * abandon the batch and force a fresh replay. * * Undefined when the caller has no snapshot, or when the watermark guard is * disabled on a run that uses it; Worlds that fence neither way ignore it. */ - eventCreateFence?: EventCreateFence; + claimFence?: FencedCreate; /** * Suppress optimistic inline start for this step regardless of * `WORKFLOW_OPTIMISTIC_INLINE_START` / `forceOptimisticStart`: take the @@ -271,6 +344,10 @@ export async function executeStep( // put us on the Vercel branch with nothing to build a host from, making // `https://` the base URL of every step. const isVercel = Boolean(process.env.VERCEL_URL); + // Unfenced when the caller passes no fence — every World that fences + // ignores the field it does not understand, so this is the same create it + // was before either mechanism existed. + const runClaim: FencedCreate = params.claimFence ?? ((op) => op(undefined)); // Gate payload compression on the run's specVersion. const compression = (params.runSpecVersion ?? 0) >= SPEC_VERSION_SUPPORTS_COMPRESSION; @@ -491,6 +568,37 @@ export async function executeStep( }); return { type: 'skipped' }; } + if ( + SlotConflictError.is(err) && + isBenignDuplicateStart( + err.events, + stepId, + stepName, + params.lazyStepInput + ) + ) { + // We lost the slot to a writer that had already started this same + // step, so this is the ordinary "another handler owns it" outcome + // wearing a slot rejection — the same thing an unfenced write reports + // as EntityConflictError. Skip rather than restart the replay: the + // restart would re-derive this identical claim and lose again. + // + // The delta on the error is deliberately NOT merged into the log. + // Adopting events this VM never replayed would let the next claim + // fence itself against a tail it cannot account for, which is the + // one thing the fence exists to prevent. Siblings in the batch fail + // with their own rejection and the handler defers as usual. + runtimeLogger.debug('Step already started by a concurrent writer', { + stepName, + stepId, + workflowRunId, + }); + span?.setAttributes({ + ...Attribute.StepSkipped(true), + ...Attribute.StepSkipReason('completed'), + }); + return { type: 'skipped' }; + } if (TooEarlyError.is(err)) { const timeoutSeconds = Math.max(1, err.retryAfter ?? 1); runtimeLogger.debug('Step retryAfter timestamp not yet reached', { @@ -533,12 +641,14 @@ export async function executeStep( let step: Step; // Params for the `step_started` create on either path below: the ambient // compute-instance stamp plus whichever fence the claim is running under. - const startEventParams: CreateEventParams = { + const startEventParams = ( + fence: EventCreateFence | undefined + ): CreateEventParams => ({ computeInstanceId: COMPUTE_INSTANCE_ID, // Spread as a unit: the fence's fields describe one fence and must - // travel together — see StepExecutorParams.eventCreateFence. - ...params.eventCreateFence, - }; + // travel together — see StepExecutorParams.claimFence. + ...fence, + }); // `Date.now()` taken immediately before the `step_started` create is // issued (either path below) — anchors RSFS's end point. See // StepLatencyEventData.rsfs and the call sites below. @@ -578,26 +688,29 @@ export async function executeStep( // RSFS measures the run_started-to-POST stretch, and the barrier // wait IS part of that stretch under turbo. stepStartPostSentAtMs = Date.now(); - return createEvent( - { - eventType: 'step_started', - specVersion: SPEC_VERSION_CURRENT, - correlationId: stepId, - eventData: { - stepName, - workflowName, - input: params.lazyStepInput, - // Inline-ownership stamp — see StepExecutorParams.ownerMessageId. - ...(params.ownerMessageId !== undefined - ? { ownerMessageId: params.ownerMessageId } - : {}), + // Fence the claim — see StepExecutorParams.claimFence. A rejection + // the fence does not retry surfaces via reconcileOptimisticStart: + // the body result is discarded, and unless the rejection proves + // another writer already started this same step (a benign + // duplicate, skipped) it propagates to the caller. + return runClaim((fence) => + createEvent( + { + eventType: 'step_started', + specVersion: SPEC_VERSION_CURRENT, + correlationId: stepId, + eventData: { + stepName, + workflowName, + input: params.lazyStepInput, + // Inline-ownership stamp — see StepExecutorParams.ownerMessageId. + ...(params.ownerMessageId !== undefined + ? { ownerMessageId: params.ownerMessageId } + : {}), + }, }, - }, - // Fence the claim — see StepExecutorParams.eventCreateFence. A 409/412 - // rejection surfaces via reconcileOptimisticStart as a - // non-translatable error: the body result is discarded and the - // rejection propagates to the caller. - startEventParams + startEventParams(fence) + ) ); } ); @@ -638,25 +751,28 @@ export async function executeStep( ? { ownerMessageId: params.ownerMessageId } : {}; stepStartPostSentAtMs = Date.now(); - const startResult = await createEvent( - { - eventType: 'step_started', - specVersion: SPEC_VERSION_CURRENT, - correlationId: stepId, - eventData: - params.lazyStepInput !== undefined - ? { - stepName, - workflowName, - input: params.lazyStepInput, - ...ownershipStamp, - } - : { stepName, ...ownershipStamp }, - }, - // Fence the claim — see StepExecutorParams.eventCreateFence. A 409/412 - // rejection is intentionally NOT translated by startErrorToResult - // below, so it propagates to the caller for a fresh replay. - startEventParams + // Fence the claim — see StepExecutorParams.claimFence. A rejection the + // fence does not retry propagates to the caller for a fresh replay, + // except where startErrorToResult below can read the rejection's delta + // as "another writer already started this exact step" and skip. + const startResult = await runClaim((fence) => + createEvent( + { + eventType: 'step_started', + specVersion: SPEC_VERSION_CURRENT, + correlationId: stepId, + eventData: + params.lazyStepInput !== undefined + ? { + stepName, + workflowName, + input: params.lazyStepInput, + ...ownershipStamp, + } + : { stepName, ...ownershipStamp }, + }, + startEventParams(fence) + ) ); if (!startResult.step) { diff --git a/packages/core/src/runtime/suspension-handler.ts b/packages/core/src/runtime/suspension-handler.ts index 5d5b6f80af..e167d83b05 100644 --- a/packages/core/src/runtime/suspension-handler.ts +++ b/packages/core/src/runtime/suspension-handler.ts @@ -30,8 +30,8 @@ import * as Attribute from '../telemetry/semantic-conventions.js'; import { getAbortStreamIdFromToken } from '../util.js'; import { getMaxInlineSteps } from './constants.js'; import { + claimFenceFor, type EventCreator, - eventCreateFenceFor, type MutableEventLog, } from './helpers.js'; import { ReplayRecoveryReporter } from './replay-recovery-reporter.js'; @@ -278,10 +278,10 @@ export async function handleSuspension({ // replay produces. const createGuarded: EventCreator = (data, params) => eventLog - ? createEvent(data, { - ...params, - ...eventCreateFenceFor(eventLog, run.specVersion), - }) + ? claimFenceFor( + eventLog, + run.specVersion + )((fence) => createEvent(data, { ...params, ...fence })) : createEvent(data, params); // Separate queue items by type const stepItems = suspension.steps.filter( diff --git a/packages/core/src/runtime/world-compatibility.ts b/packages/core/src/runtime/world-compatibility.ts index c06c26eefb..f3de904359 100644 --- a/packages/core/src/runtime/world-compatibility.ts +++ b/packages/core/src/runtime/world-compatibility.ts @@ -1,19 +1,40 @@ import { WorkflowRuntimeError } from '@workflow/errors'; import type { World } from '@workflow/world'; -import { SPEC_VERSION_CURRENT } from '@workflow/world'; +import { + SPEC_VERSION_CURRENT, + SPEC_VERSION_MAX_SUPPORTED, +} from '@workflow/world'; type WorldSpecVersionMetadata = Pick; +/** + * Rejects a World whose protocol this runtime does not speak. + * + * A World declares the spec version it stamps on the runs it creates. Anything + * from {@link SPEC_VERSION_CURRENT} up to {@link SPEC_VERSION_MAX_SUPPORTED} is + * fine: the upper end covers a World opted into a newer identity scheme that + * this runtime already understands, and only versions this runtime has no code + * for are refused. Below the current version means the World package predates + * this runtime and cannot record what it emits. + */ export function assertWorldSupportsRuntimeProtocol( world: WorldSpecVersionMetadata ): void { - if (world.specVersion === SPEC_VERSION_CURRENT) { + if ( + world.specVersion !== undefined && + world.specVersion >= SPEC_VERSION_CURRENT && + world.specVersion <= SPEC_VERSION_MAX_SUPPORTED + ) { return; } const supportedVersion = world.specVersion ?? 'none'; + const supported = + SPEC_VERSION_CURRENT === SPEC_VERSION_MAX_SUPPORTED + ? `${SPEC_VERSION_CURRENT}` + : `${SPEC_VERSION_CURRENT} to ${SPEC_VERSION_MAX_SUPPORTED}`; throw new WorkflowRuntimeError( - `This Workflow runtime requires a World with matching spec version ${SPEC_VERSION_CURRENT}, ` + + `This Workflow runtime requires a World with spec version ${supported}, ` + `but the configured World declares spec version ${supportedVersion}. ` + 'Install a World package version compatible with the current Workflow runtime.' ); diff --git a/packages/core/src/workflow.ts b/packages/core/src/workflow.ts index 6cd57a2227..6583fd54aa 100644 --- a/packages/core/src/workflow.ts +++ b/packages/core/src/workflow.ts @@ -15,9 +15,13 @@ import { EventConsumerResult, EventsConsumer } from './events-consumer.js'; import type { QueueItem } from './global.js'; import { ENOTSUP, WorkflowSuspension } from './global.js'; import { runtimeLogger } from './logger.js'; -import type { WorkflowOrchestratorContext } from './private.js'; +import { + hasInFlightDelivery, + type WorkflowOrchestratorContext, +} from './private.js'; import { ReplayPayloadCache } from './replay-payload-cache.js'; import { getPortLazy } from './runtime/get-port-lazy.js'; +import type { MutableEventLog } from './runtime/helpers.js'; import { runIdCreatedAt } from './runtime/run-id-time.js'; import { handleSuspension } from './runtime/suspension-handler.js'; import { getWorld } from './runtime/world.js'; @@ -74,7 +78,15 @@ async function drainPendingQueueItems( * In turbo mode, gates final `*_created` writes on backgrounded * `run_started`. Undefined when `run_started` is awaited. */ - runReadyBarrier?: Promise + runReadyBarrier?: Promise, + /** + * The replay's event log, so the drain's writes claim their slots from the + * same source the terminal `run_completed` / `run_failed` write draws from. + * Without it the drain writes unfenced — the World picks the next free slot — + * and the terminal write, numbering from a snapshot taken before the drain, + * proposes the slot the drain just took and loses it. + */ + eventLog?: MutableEventLog ): Promise { if (pendingQueue.size === 0) return; // Implicitly dispose any abort hooks (system hooks) that are still alive at @@ -101,6 +113,7 @@ async function drainPendingQueueItems( world, run: workflowRun, runReadyBarrier, + eventLog, }); } catch (err) { runtimeLogger.warn( @@ -137,7 +150,13 @@ export async function runWorkflow( * Features supported by the World executing this workflow. Missing * capabilities are treated as unsupported. */ - worldCapabilities?: WorldCapabilities + worldCapabilities?: WorldCapabilities, + /** + * The caller's event log for this replay. Its only use here is the end-of-run + * drain, whose writes have to be ordered with the caller's terminal write — + * see {@link drainPendingQueueItems}. + */ + eventLog?: MutableEventLog ): Promise { return trace(`workflow.run ${workflowRun.workflowName}`, async (span) => { span?.setAttributes({ @@ -196,22 +215,34 @@ export async function runWorkflow( // by step/hook/sleep callbacks as events are processed. const promiseQueueHolder = { current: Promise.resolve() }; + // Assigned immediately below. The consumer needs to test the context's + // delivery state, and the context needs the consumer. + let workflowContext: WorkflowOrchestratorContext; + const eventsConsumer = new EventsConsumer(events, { onConsumedEvent: (event) => { updateTimestamp(+event.createdAt); }, onUnconsumedEvent: (event) => { + // Name what the replay was waiting for instead. An unconsumable event + // is almost always one whose entity this replay never issued, or + // issued under a different correlation ID; the pending invocation + // queue is the only place that distinction is visible, and without it + // the log names a symptom with no way to reach the cause. + const pending = [...workflowContext.invocationsQueue.keys()]; workflowDiscontinuation.reject( new ReplayDivergenceError( - `Replay could not consume event: eventType=${event.eventType}, correlationId=${event.correlationId}, eventId=${event.eventId}.`, + `Replay could not consume event: eventType=${event.eventType}, correlationId=${event.correlationId}, eventId=${event.eventId}. Pending invocations: ${pending.length > 0 ? pending.join(', ') : '(none)'}.`, { eventId: event.eventId } ) ); }, getPromiseQueue: () => promiseQueueHolder.current, + isDeliveryInFlight: () => + workflowContext !== undefined && hasInFlightDelivery(workflowContext), }); - const workflowContext: WorkflowOrchestratorContext = { + workflowContext = { runId: workflowRun.runId, encryptionKey, worldCapabilities, @@ -863,7 +894,8 @@ export async function runWorkflow( vmGlobalThis, workflowRun, 'completed', - runReadyBarrier + runReadyBarrier, + eventLog ); return dehydrated; @@ -880,7 +912,8 @@ export async function runWorkflow( vmGlobalThis, workflowRun, 'failed', - runReadyBarrier + runReadyBarrier, + eventLog ); throw err; diff --git a/packages/core/src/workflow/hook.test.ts b/packages/core/src/workflow/hook.test.ts index 4bda06998a..307293f571 100644 --- a/packages/core/src/workflow/hook.test.ts +++ b/packages/core/src/workflow/hook.test.ts @@ -24,7 +24,10 @@ import { createWebhook } from './create-hook.js'; import { createCreateHook } from './hook.js'; // Helper to setup context to simulate a workflow run -function setupWorkflowContext(events: Event[]): WorkflowOrchestratorContext { +function setupWorkflowContext( + events: Event[], + onUnconsumedEvent: (event: Event) => void = () => {} +): WorkflowOrchestratorContext { const context = createContext({ seed: 'test', fixedTimestamp: 1753481739458, @@ -43,7 +46,7 @@ function setupWorkflowContext(events: Event[]): WorkflowOrchestratorContext { replayPayloadCache: new ReplayPayloadCache(undefined), globalThis: context.globalThis, eventsConsumer: new EventsConsumer(events, { - onUnconsumedEvent: () => {}, + onUnconsumedEvent, getPromiseQueue: () => Promise.resolve(), }), invocationsQueue: new Map(), @@ -471,6 +474,65 @@ describe('createCreateHook', () => { expect(runtimeErrors).toHaveLength(0); }); + it('should discard a hook_received ordered after the hook_disposed', async () => { + // The world orders a delivery by when its event row commits, not by when + // the payload arrived, so a delivery that raced the disposal can land after + // it in the log. Nothing else in the run can consume that event, so the + // hook's own consumer has to swallow it — otherwise the events consumer + // reports an orphan and the replay diverges on a well-formed log. + const ops: Promise[] = []; + const onUnconsumedEvent = vi.fn(); + const ctx = setupWorkflowContext( + [ + { + eventId: 'evnt_0', + runId: 'wrun_123', + eventType: 'hook_created', + correlationId: 'hook_01K11TFZ62YS0YYFDQ3E8B9YCV', + eventData: { token: 'test-token' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_1', + runId: 'wrun_123', + eventType: 'hook_disposed', + correlationId: 'hook_01K11TFZ62YS0YYFDQ3E8B9YCV', + eventData: { token: 'test-token' }, + createdAt: new Date(), + }, + { + eventId: 'evnt_2', + runId: 'wrun_123', + eventType: 'hook_received', + correlationId: 'hook_01K11TFZ62YS0YYFDQ3E8B9YCV', + eventData: { + token: 'test-token', + payload: await dehydrateStepReturnValue( + { message: 'lost the race' }, + 'wrun_test', + undefined, + ops + ), + }, + createdAt: new Date(), + }, + ], + onUnconsumedEvent + ); + + const createHook = createCreateHook(ctx); + createHook({ token: 'test-token' }); + + // The whole log is consumed: the disposal retires the hook and the late + // delivery is dropped on the floor. + await vi.waitFor(() => { + expect(ctx.eventsConsumer.eventIndex).toBe(3); + }); + expect(onUnconsumedEvent).not.toHaveBeenCalled(); + expect(ctx.onWorkflowError).not.toHaveBeenCalled(); + expect(ctx.invocationsQueue.size).toBe(0); + }); + it('should handle multiple hook_received events with iterator', async () => { const ops: Promise[] = []; const ctx = setupWorkflowContext([ diff --git a/packages/core/src/workflow/hook.ts b/packages/core/src/workflow/hook.ts index 22d66d8c73..b69b43725e 100644 --- a/packages/core/src/workflow/hook.ts +++ b/packages/core/src/workflow/hook.ts @@ -175,8 +175,9 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { eventLogEmpty = true; if ( - (promises.length > 0 && payloadsQueue.length === 0) || - (getConflictPromises.length > 0 && !hasCreated && !hasConflict) + !hasDisposedEvent && + ((promises.length > 0 && payloadsQueue.length === 0) || + (getConflictPromises.length > 0 && !hasCreated && !hasConflict)) ) { scheduleWhenIdle(ctx, () => { ctx.onWorkflowError( @@ -192,6 +193,31 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { return EventConsumerResult.NotConsumed; } + if (hasDisposedEvent) { + // A delivery ordered AFTER this hook's own `hook_disposed`. The world + // orders a delivery by when its event row is written, not by when the + // payload arrived, so a delivery that raced the disposal — arriving + // first, committing second — lands here. Swallow it: the hook is gone, + // there is no consumer to hand the payload to, and every awaiter was + // already settled by `disposeHook`. + // + // This consumer must stay registered to do that. Retiring it on + // `hook_disposed` leaves the late delivery with no consumer at all, + // which the events consumer reports as an orphaned event — + // a `ReplayDivergenceError` that recurs on every replay of a log that + // is otherwise perfectly well-formed, escalating to a terminal + // `CorruptedEventLogError`. + webhookLogger.warn( + 'Discarding a hook delivery ordered after disposal', + { + correlationId, + eventId: event.eventId, + eventType: event.eventType, + } + ); + return EventConsumerResult.Consumed; + } + const eventToken = 'eventData' in event && event.eventData && 'token' in event.eventData ? event.eventData.token @@ -450,8 +476,10 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { ctx.invocationsQueue.delete(correlationId); // Mark that the event log confirms disposal happened hasDisposedEvent = true; - // We're done processing any more events for this hook - return EventConsumerResult.Finished; + // Stay registered as a tombstone rather than retiring: a delivery that + // raced this disposal can still be ordered after it, and nothing else + // in the run can consume it. See the `hasDisposedEvent` branch above. + return EventConsumerResult.Consumed; } // This replay installed a different consumer than the stored event needs. @@ -571,8 +599,9 @@ export function createCreateHook(ctx: WorkflowOrchestratorContext) { // Drain any pending promises that are waiting for payloads. // Without this, promises created by `await hook` or the async iterator's - // `yield await this` would hang forever since the event consumer will - // never deliver another hook_received after disposal. + // `yield await this` would hang forever: a hook_received ordered after + // the disposal is discarded rather than handed to an awaiter, so nothing + // will ever settle them. if (promises.length > 0) { promises.length = 0; scheduleWhenIdle(ctx, () => { diff --git a/packages/world-local/src/fs.ts b/packages/world-local/src/fs.ts index 70178b344c..8d2ec5d203 100644 --- a/packages/world-local/src/fs.ts +++ b/packages/world-local/src/fs.ts @@ -466,6 +466,11 @@ export async function deleteJSON(filePath: string): Promise { await withWindowsRetry(() => fs.unlink(filePath)); } catch (error) { if ((error as any).code !== 'ENOENT') throw error; + } finally { + // The cache stands in for an `fs.access` on the write path, so a path that + // no longer exists may not stay in it: a later create-if-absent write of the + // same path would be rejected as a duplicate of a file that is gone. + createdFilesCache.delete(filePath); } } @@ -579,6 +584,14 @@ interface PaginatedFileSystemQueryConfig { cursor?: string; getCreatedAt(filename: string): Date | null; getId?(item: T): string; + /** + * The time an item sorts and paginates by, when that is not its `createdAt`. + * A slot-numbered event log orders by slot — the position is the order — and + * a writer that loses a slot re-proposes above the winner while keeping the + * stamp it started with, so `createdAt` there disagrees with the log. Such an + * item reports one shared time and lets the `getId` tie-break order it. + */ + getOrderTime?: (item: NoInfer) => number; } // Cursor format: "timestamp|id" for tie-breaking interface ParsedCursor { @@ -615,6 +628,7 @@ export async function paginatedFileSystemQuery( cursor, getCreatedAt, getId, + getOrderTime = (item: T) => item.createdAt.getTime(), } = config; // Validate filePrefix (typically `${runId}-`) so request-derived prefixes @@ -718,7 +732,7 @@ export async function paginatedFileSystemQuery( // Double-check cursor filtering with actual createdAt from JSON // (in case ULID timestamp differs from stored createdAt) if (parsedCursor) { - const itemTime = item.createdAt.getTime(); + const itemTime = getOrderTime(item); const cursorTime = parsedCursor.timestamp.getTime(); if (sortOrder === 'desc') { @@ -746,8 +760,8 @@ export async function paginatedFileSystemQuery( // 5. Sort by createdAt (and by ID for tie-breaking if getId is provided) validItems.sort((a, b) => { - const aTime = a.createdAt.getTime(); - const bTime = b.createdAt.getTime(); + const aTime = getOrderTime(a); + const bTime = getOrderTime(b); const timeComparison = sortOrder === 'asc' ? aTime - bTime : bTime - aTime; // If timestamps are equal and we have getId, use ID for stable sorting @@ -768,7 +782,7 @@ export async function paginatedFileSystemQuery( const nextCursor = items.length > 0 ? createCursor( - items[items.length - 1].createdAt, + new Date(getOrderTime(items[items.length - 1])), getId?.(items[items.length - 1]) ) : null; diff --git a/packages/world-local/src/index.ts b/packages/world-local/src/index.ts index f8e2166fb7..aa77546732 100644 --- a/packages/world-local/src/index.ts +++ b/packages/world-local/src/index.ts @@ -2,7 +2,7 @@ import { promises as fs } from 'node:fs'; import { rm } from 'node:fs/promises'; import path from 'node:path'; import type { QueuePrefix, World } from '@workflow/world'; -import { reenqueueActiveRuns, SPEC_VERSION_CURRENT } from '@workflow/world'; +import { mintedSpecVersion, reenqueueActiveRuns } from '@workflow/world'; import { warnIfRunningInVercelDeployment } from './build-target-mismatch.js'; import type { Config } from './config.js'; import { config, resolveRecoverActiveRuns } from './config.js'; @@ -72,7 +72,10 @@ export function createWorld(args?: Partial): LocalWorld { ); const recoverActiveRuns = resolveRecoverActiveRuns(mergedConfig); return { - specVersion: SPEC_VERSION_CURRENT, + // What this world stamps on new runs: slot identity, unless + // WORKFLOW_SLOT_IDENTITY switches it off. Every world reads both schemes + // whatever this says. + specVersion: mintedSpecVersion(), ...queue, ...storage, ...instrumentObject('world.streams', { diff --git a/packages/world-local/src/storage/events-storage.ts b/packages/world-local/src/storage/events-storage.ts index 7efd49cb1e..33ad225bb5 100644 --- a/packages/world-local/src/storage/events-storage.ts +++ b/packages/world-local/src/storage/events-storage.ts @@ -5,11 +5,13 @@ import { HookNotFoundError, RunExpiredError, RunNotSupportedError, + SlotConflictError, TooEarlyError, WorkflowRunNotFoundError, WorkflowWorldError, } from '@workflow/errors'; import type { + CreateEventParams, Event, EventResult, Hook, @@ -33,9 +35,15 @@ import { isTerminalStepStatus, isTerminalWorkflowRunStatus, requiresNewerWorld, + SLOT_RETRY_BUDGET_MS, SPEC_VERSION_CURRENT, + SPEC_VERSION_MAX_SUPPORTED, StepSchema, + slotEventId, + slotFromId, + slotRetryDelay, ulidToDate, + usesSlotIdentity, validateAttributeChanges, validateUlidTimestamp, WaitSchema, @@ -85,6 +93,7 @@ import { } from './hooks-storage.js'; import { handleLegacyEvent } from './legacy.js'; import { withRunFileLock } from './runs-storage.js'; +import { createSlotBook, RUN_CREATED_SLOT } from './slots.js'; /** * Per-run event ceiling the Local World reports on run responses (mirrors the @@ -122,6 +131,20 @@ function getMaxEventsPerRun(): number { // but a shared filesystem), exactly matching the cross-process // semantics without spawning subprocesses. +/** + * The time an event orders and paginates by. A slot-numbered run's order is its + * slot order — the position *is* the order, the way the sort key is for the + * other backends — so every such event reports the same time and lets the + * event-id tie-break do the ordering. Ordering those by `createdAt` reads the + * log in an order no replay produced: a writer that loses a slot re-proposes + * above the winner while keeping the stamp it started with, and a caller that + * reserves slots for a whole flush commits them in whatever order the network + * returns. A ULID-numbered run keeps its wall-clock order, which its ids agree + * with anyway. + */ +const eventOrderTime = (event: { eventId: string; createdAt: Date }): number => + slotFromId(event.eventId) === undefined ? event.createdAt.getTime() : 0; + const HookTokenClaimSchema = z.object({ // The token-claim writer below has always persisted `hookId`, but // this read schema previously omitted it, which is the bug fixed @@ -259,6 +282,7 @@ async function findExistingHookCreatedEventId( event.correlationId === correlationId, limit: 1, getCreatedAt: getObjectCreatedAt('evnt'), + getOrderTime: eventOrderTime, getId: (event) => event.eventId, }); return result.data[0]?.eventId ?? null; @@ -506,6 +530,8 @@ export function createEventsStorage( const cachedPathsByRunId = new Map>(); let totalCachedEventBytes = 0; + const slots = createSlotBook(basedir, tag); + function deleteCachedEvent(eventPath: string): void { const event = eventCache.get(eventPath); if (!event) { @@ -525,6 +551,7 @@ export function createEventsStorage( for (const cachedPath of cachedPathsByRunId.get(runId) ?? []) { deleteCachedEvent(cachedPath); } + slots.forget(runId); } function clearCache(): void { @@ -532,6 +559,7 @@ export function createEventsStorage( cachedEventBytes.clear(); cachedPathsByRunId.clear(); totalCachedEventBytes = 0; + slots.clear(); } function cacheEvent( @@ -592,6 +620,65 @@ export function createEventsStorage( } } + /** + * The events a caller that just lost a slot is missing: one ascending page of + * the run's log after the cursor it wrote from, minus anything at or below the + * highest slot it already held. Because slots are dense, that second filter is + * exact — a caller cannot be missing an event whose position it can name. + * + * Returned inline with the conflict so the common case (a handful of events + * arrived out of band) costs the caller no extra round-trip. `hasMore` is + * forwarded verbatim: an overflowing delta is the caller's signal to page from + * `cursor` instead of treating this as the whole story. + */ + async function eventsAfterClaim( + runId: string, + params: CreateEventParams | undefined + ): Promise<{ events: Event[]; cursor: string | null; hasMore: boolean }> { + const page = await paginatedFileSystemQuery({ + directory: path.join(basedir, 'events'), + schema: EventSchema, + cachedItems: eventCache, + filePrefix: `${runId}-`, + sortOrder: 'asc', + ...(typeof params?.sinceCursor === 'string' + ? { cursor: params.sinceCursor } + : {}), + getCreatedAt: getObjectCreatedAt('evnt'), + getOrderTime: eventOrderTime, + getId: (event) => event.eventId, + }); + const maxSlot = params?.maxSlot ?? 0; + const resolveData = params?.resolveData ?? DEFAULT_RESOLVE_DATA_OPTION; + const missing = page.data.filter( + (event) => (slotFromId(event.eventId) ?? 0) > maxSlot + ); + return { + events: + resolveData === 'none' + ? missing.map((event) => stripEventDataRefs(event, resolveData)) + : missing, + cursor: page.cursor, + hasMore: page.hasMore, + }; + } + + /** + * The 409 a caller gets when the slot it named turns out to belong to someone + * else, carrying the events it is missing so it can merge, replay and + * re-propose at a free position. + */ + async function slotConflict( + runId: string, + eventId: string, + params: CreateEventParams | undefined + ): Promise { + return new SlotConflictError( + `Slot ${slotFromId(eventId)} of run "${runId}" is already taken`, + { eventId, ...(await eventsAfterClaim(runId, params)) } + ); + } + async function storeEvent(event: Event): Promise { const eventPath = taggedPath( basedir, @@ -643,6 +730,58 @@ export function createEventsStorage( if ('correlationId' in data && typeof data.correlationId === 'string') { assertSafeEntityId('correlationId', data.correlationId); } + if (params?.eventId !== undefined) { + assertSafeEntityId('eventId', params.eventId); + } + + // A slot-numbered create reserves its position before running the + // validation and materialization that may still reject it. Handing the + // reservation back on the way out is what keeps the log dense: an + // abandoned slot below a sibling's published one is a hole that can never + // be filled, and a log with a hole can no longer prove it is complete. + const reserved = new Set(); + let reservedRunId: string | undefined; + /** + * Undo actions for the duplicate-suppression claims a create takes before + * its event exists, newest last. Run only when the create ends without + * publishing anything: the answer to a lost position is to propose the + * same operation one position higher, and a claim left behind is what + * would reject that retry as a duplicate of a write that never landed. + */ + const abandonedClaims: Array<() => Promise> = []; + /** + * Whether any event of this create became reader-visible. Once one has, + * nothing the create claimed may be undone: the entity an event describes + * has to keep existing even if a later step of the same call fails. + */ + let eventCommitted = false; + /** + * Hands the slots of a create that never published back to the allocator, + * so an abandoned reservation below a sibling's published slot does not + * become a hole the run can never fill. + */ + async function releasingSlots( + result: Promise + ): Promise { + try { + return await result; + } catch (error) { + if (reservedRunId !== undefined) { + for (const slot of reserved) { + slots.release(reservedRunId, slot); + } + } + if (!eventCommitted) { + for (const undo of abandonedClaims.reverse()) { + // Best effort: the throw the caller sees is the one that matters, + // and a claim that outlives its create is a duplicate suppressed + // for a write that is not coming back. + await undo().catch(() => {}); + } + } + throw error; + } + } // Step lifecycle events are serialized per-step via an in-process mutex // so that the "check state, then write" sequence in step_started / @@ -653,7 +792,9 @@ export function createEventsStorage( const lockKey = tag ? `${runId}-${data.correlationId}.${tag}` : `${runId}-${data.correlationId}`; - return withInProcessLock(stepLocks, lockKey, () => createImpl()); + return releasingSlots( + withInProcessLock(stepLocks, lockKey, () => createImpl()) + ); } // `hook_created` is serialized per-(runId, hookId) so the // "claim token, write hook entity, write event" sequence runs to @@ -682,9 +823,11 @@ export function createEventsStorage( const lockKey = tag ? `${runId}-${data.correlationId}.hook.${tag}` : `${runId}-${data.correlationId}.hook`; - return withInProcessLock(hookLocks, lockKey, () => createImpl()); + return releasingSlots( + withInProcessLock(hookLocks, lockKey, () => createImpl()) + ); } - return createImpl(); + return releasingSlots(createImpl()); async function createImpl(): Promise { // Most paths use the freshly-generated candidate eventId. The @@ -719,6 +862,18 @@ export function createEventsStorage( // specVersion is always sent by the runtime, but we provide a fallback for safety const effectiveSpecVersion = data.specVersion ?? SPEC_VERSION_CURRENT; + // Whether this run numbers its events by slot. Read from what was + // persisted, never from this request or this build, so a run stays in + // the mode it was created in for life — a run whose log holds ULID ids + // must never be handed a slot id, and vice versa. `run_created` is the + // one event that decides the mode instead of reading it; the + // resilient-start path below decides it too, on the request that + // creates the run. + let slotMode = + data.eventType === 'run_created' + ? usesSlotIdentity(effectiveSpecVersion) + : await slots.usesSlots(effectiveRunId); + // Get current run state for validation (if not creating a new run) // Skip run validation for step_completed and step_retrying - they only operate // on running steps, and running steps are always allowed to modify regardless @@ -800,8 +955,14 @@ export function createEventsStorage( ); if (created) { - // We created the run — also write the run_created event. - const runCreatedEventId = `evnt_${monotonicUlid()}`; + // We created the run, so this request also decided its mode. + slotMode = usesSlotIdentity(effectiveSpecVersion); + // We created the run — also write the run_created event. Its + // slot needs no allocation: a run's own `run_created` provably + // has nothing before it. + const runCreatedEventId = slotMode + ? slotEventId(RUN_CREATED_SLOT) + : `evnt_${monotonicUlid()}`; const runCreatedEvent: Event = { eventType: 'run_created', runId: effectiveRunId, @@ -820,6 +981,7 @@ export function createEventsStorage( }, }; await storeEvent(runCreatedEvent); + slots.observe(effectiveRunId, runCreatedEventId); currentRun = createdRun; } else { // Run already exists (concurrent run_created won the @@ -836,6 +998,18 @@ export function createEventsStorage( } } + // The run entity we just read is the authority on the mode, and it can + // appear between the probe above and this read: start() issues + // `run_created` and the queue send concurrently, so the delivery's + // `run_started` can arrive while the run is still being published. A + // stale "no" there would number that one event with a ULID on an + // otherwise slot-numbered run, and a ULID names no position: the replay + // would read it wherever its timestamp happens to sort rather than where + // the writer meant it to go. + if (currentRun && data.eventType !== 'run_created') { + slotMode = usesSlotIdentity(currentRun.specVersion); + } + // run_failed on a non-existent run is rejected to match the // postgres and vercel worlds, which both surface this as a // WorkflowRunNotFoundError rather than silently persisting an @@ -857,7 +1031,7 @@ export function createEventsStorage( if (requiresNewerWorld(currentRun.specVersion)) { throw new RunNotSupportedError( currentRun.specVersion!, - SPEC_VERSION_CURRENT + SPEC_VERSION_MAX_SUPPORTED ); } @@ -873,20 +1047,109 @@ export function createEventsStorage( } } - // ============================================================ - // VALIDATION: Terminal state and event ordering checks - // ============================================================ - // Lazy step start: a step_started carrying step-creation data // (stepName + input) is allowed to arrive with no prior step_created // — it creates the step on the fly (see the materialization block // below). This mirrors the resilient run_started path. Detect it here - // so the entity-creation terminal-run guard treats it like a creation - // and the "step must exist" ordering guard doesn't reject it. + // so the second event it publishes can be numbered alongside the + // first, the entity-creation terminal-run guard treats it like a + // creation, and the "step must exist" ordering guard doesn't reject it. const createsChildEntity = isChildEntityCreationEvent(data); const lazyStepStart = createsChildEntity && data.eventType === 'step_started'; + // ============================================================ + // EVENT ID: the caller's slot claim, an allocated slot, or a ULID + // ============================================================ + // A run's own `run_created` owns the first slot — provably, since + // nothing precedes it — so it takes that position outright instead of + // allocating one, and every other event allocates above it even when it + // is the first to arrive here. Allocation is append-only (see SlotBook), + // so `run_created` cannot get the first position by asking for the lowest + // free one: a `run_started` racing it (start() issues the creation and + // the queue send in parallel) may already have moved the book past it. + const ownsFirstSlot = data.eventType === 'run_created'; + // A slot-numbered run's ids name positions in its log, so an id is + // either claimed by a caller that holds the log (and is therefore + // asserting the log is complete up to that position) or allocated here + // for a caller that has no log — a step completion reporting in, a + // cancellation from an API call. + // + // The position of the second event a lazy start publishes, when this + // one publishes two. Consumed by the materialization below; released + // again if that block turns out not to need it. + let companionSlot: number | undefined; + if (params?.eventId !== undefined) { + const claimedSlot = slotFromId(params.eventId); + if (!slotMode) { + throw new WorkflowWorldError( + `Event id "${params.eventId}" was supplied for run "${effectiveRunId}", whose events are not numbered by slot`, + { status: 400 } + ); + } + if (claimedSlot === undefined) { + throw new WorkflowWorldError( + `Event id "${params.eventId}" is not a slot id, and run "${effectiveRunId}" numbers its events by slot`, + { status: 400 } + ); + } + eventId = params.eventId; + reservedRunId = effectiveRunId; + reserved.add(claimedSlot); + slots.claim(effectiveRunId, claimedSlot); + // One request, two events: a lazy start also publishes the + // `step_created` it deferred. A claim names the *top* of the pair, + // so the second event takes the slot immediately below it — the + // caller reserved both positions and named only one, which is what + // keeps the pair from landing on a position another write in the + // same batch is already holding. + if (lazyStepStart) { + companionSlot = claimedSlot - 1; + if (companionSlot < RUN_CREATED_SLOT + 1) { + throw new WorkflowWorldError( + `Event id "${params.eventId}" leaves no slot below it in run "${effectiveRunId}" for the "step_created" published alongside it`, + { status: 400 } + ); + } + reserved.add(companionSlot); + slots.claim(effectiveRunId, companionSlot); + } + // A claim has to clear the log's tail, not merely be free: a + // position left unwritten by an abandoned reservation stays empty + // for good, and a caller numbering from a stale snapshot aims + // straight at it, landing an event below events another replay + // already consumed. Rejected before the materialization below + // creates the step, hook or wait this event will now never + // accompany. See SlotBook.highestWritten. + const tail = await slots.highestWritten(effectiveRunId); + for (const slot of companionSlot === undefined + ? [claimedSlot] + : [companionSlot, claimedSlot]) { + if (slot <= tail) { + throw await slotConflict( + effectiveRunId, + slotEventId(slot), + params + ); + } + } + } else if (slotMode) { + reservedRunId = effectiveRunId; + let slot: number; + if (ownsFirstSlot) { + slot = RUN_CREATED_SLOT; + slots.claim(effectiveRunId, slot); + } else { + slot = await slots.reserve(effectiveRunId); + } + reserved.add(slot); + eventId = slotEventId(slot); + } + + // ============================================================ + // VALIDATION: Terminal state and event ordering checks + // ============================================================ + // Run terminal state validation if (currentRun && isTerminalWorkflowRunStatus(currentRun.status)) { // Idempotent operation: run_cancelled on already cancelled run is allowed @@ -1127,13 +1390,40 @@ export function createEventsStorage( // strictly dominates all visible events of the run guarantees the // terminal event replays last. See mintRunDominantEventKey for // the dominance argument. - const dominantKey = await mintRunDominantEventKey( - basedir, - effectiveRunId, - tag - ); - eventId = dominantKey.eventId; - event = { ...event, eventId, createdAt: dominantKey.createdAt }; + // + // A key the *caller* chose is left alone. Its slot was picked from + // the caller's own log, so a concurrent event either sits below it + // (and already replays first) or takes the slot itself — in which + // case the publish below conflicts and the caller merges and + // re-proposes, which is the stronger answer. Re-numbering it here + // would also be actively wrong: the caller reserves slots for a + // whole flush of concurrent ops at once, so moving this one to + // "highest visible + 1" would steal the slot a sibling op is still + // in flight with. + if (params?.eventId === undefined) { + const dominantKey = await mintRunDominantEventKey( + basedir, + effectiveRunId, + tag, + slotMode + ); + const staleSlot = slotFromId(eventId); + const dominantSlot = slotFromId(dominantKey.eventId); + if (staleSlot !== undefined && staleSlot !== dominantSlot) { + // Only reachable when the log moved under us, which means the + // slot we held is now someone else's written event — handing it + // back leaves no hole. + reserved.delete(staleSlot); + slots.release(effectiveRunId, staleSlot); + } + if (dominantSlot !== undefined) { + reservedRunId = effectiveRunId; + reserved.add(dominantSlot); + slots.claim(effectiveRunId, dominantSlot); + } + eventId = dominantKey.eventId; + event = { ...event, eventId, createdAt: dominantKey.createdAt }; + } } // Create/update entity based on event type (event-sourced architecture) @@ -1416,6 +1706,7 @@ export function createEventsStorage( `Step "${data.correlationId}" already created` ); } + abandonedClaims.push(() => fs.unlink(stepCreatedLockPath)); const stepData = data.eventData as { stepName: string; input: any; @@ -1437,10 +1728,14 @@ export function createEventsStorage( specVersion: effectiveSpecVersion, }; const stepCompositeKey = `${effectiveRunId}-${data.correlationId}`; - await writeJSON( - taggedPath(basedir, 'steps', stepCompositeKey, tag), - step + const stepEntityPath = taggedPath( + basedir, + 'steps', + stepCompositeKey, + tag ); + await writeJSON(stepEntityPath, step); + abandonedClaims.push(() => deleteJSON(stepEntityPath)); } else if (data.eventType === 'step_started') { // step_started: Increments attempt, sets status to 'running' // Sets startedAt only on the first start (not updated on retries) @@ -1479,6 +1774,7 @@ export function createEventsStorage( `Step "${data.correlationId}" already created` ); } else { + abandonedClaims.push(() => fs.unlink(stepCreatedLockPath)); const createdStep: Step = { runId: effectiveRunId, stepId: data.correlationId, @@ -1494,24 +1790,35 @@ export function createEventsStorage( updatedAt: now, specVersion: effectiveSpecVersion, }; - await writeJSON( - taggedPath( - basedir, - 'steps', - `${effectiveRunId}-${data.correlationId}`, - tag - ), - createdStep + const lazyStepEntityPath = taggedPath( + basedir, + 'steps', + `${effectiveRunId}-${data.correlationId}`, + tag ); + await writeJSON(lazyStepEntityPath, createdStep); + abandonedClaims.push(() => deleteJSON(lazyStepEntityPath)); // Write the synthetic step_created event so replay observes it // (the client step consumer sets hasCreatedEvent only on a - // step_created event). Its eventId is a fresh monotonic ULID. + // step_created event). Its eventId is a second slot, or a fresh + // monotonic ULID — one request, two events. // Ordering vs. the step_started event row does not affect // correctness: the step_started consumer is a no-op and only // step_created flips hasCreatedEvent, so the end state is the // same whichever sorts first — this matches the resilient // run_started → run_created precedent in this file. - const stepCreatedEventId = `evnt_${monotonicUlid()}`; + let stepCreatedEventId = `evnt_${monotonicUlid()}`; + if (slotMode) { + // A claimed start numbers this event one below its own + // position, which the caller reserved for exactly this. A start + // that allocated takes the next free slot instead: nothing + // outside this world named either position. + const slot = + companionSlot ?? (await slots.reserve(effectiveRunId)); + companionSlot = undefined; + reserved.add(slot); + stepCreatedEventId = slotEventId(slot); + } const stepCreatedEvent: Event = { eventType: 'step_created', runId: effectiveRunId, @@ -1524,15 +1831,39 @@ export function createEventsStorage( input: lazyData.input, }, }; - await writeJSON( - taggedPath( - basedir, - 'events', - `${effectiveRunId}-${stepCreatedEventId}`, - tag - ), - stepCreatedEvent + const stepCreatedEventPath = taggedPath( + basedir, + 'events', + `${effectiveRunId}-${stepCreatedEventId}`, + tag ); + if (slotMode) { + // The position decides this event as much as it decides the + // start it rides with, so it is published the same way: whoever + // links the file first owns the slot. A loss here is the + // caller's to resolve — it named this position — and the undo + // list above takes the step entity and its claim back out, so + // the re-proposal one position higher starts the step lazily + // again instead of tripping its own leftovers. + const published = await writeExclusive( + stepCreatedEventPath, + JSON.stringify(stepCreatedEvent, jsonReplacer, 2) + ); + if (!published) { + throw await slotConflict( + effectiveRunId, + stepCreatedEventId, + params + ); + } + } else { + await writeJSON(stepCreatedEventPath, stepCreatedEvent); + } + // Readers can see this event from here on, so the step entity it + // describes has to keep existing even if the start it rides with + // goes on to lose its own position. + eventCommitted = true; + slots.observe(effectiveRunId, stepCreatedEventId); validatedStep = createdStep; stepCreatedLazily = true; } @@ -2137,6 +2468,7 @@ export function createEventsStorage( `Wait "${data.correlationId}" already exists` ); } + abandonedClaims.push(() => fs.unlink(waitCreatedLockPath)); const waitData = data.eventData as { resumeAt?: Date; }; @@ -2150,10 +2482,14 @@ export function createEventsStorage( updatedAt: now, specVersion: effectiveSpecVersion, }; - await writeJSON( - taggedPath(basedir, 'waits', waitCompositeKey, tag), - wait + const waitEntityPath = taggedPath( + basedir, + 'waits', + waitCompositeKey, + tag ); + await writeJSON(waitEntityPath, wait); + abandonedClaims.push(() => deleteJSON(waitEntityPath)); } else if (data.eventType === 'wait_completed') { // wait_completed: Transitions wait to 'completed', rejects duplicates. // Uses writeExclusive on a lock file to atomically prevent concurrent @@ -2215,11 +2551,17 @@ export function createEventsStorage( // race here; whoever links the file first wins, the loser // throws EntityConflictError, and the runtime's existing // concurrent-replay catch path at suspension-handler.ts:142 - // swallows it. For all other event types, eventIds are - // monotonic ULIDs (globally unique by construction) so a - // collision indicates a real bug and EntityConflictError is + // swallows it. For all other event types of a ULID-numbered run, + // eventIds are monotonic ULIDs (globally unique by construction) so + // a collision indicates a real bug and EntityConflictError is // also the right surface — same shape as step_created's // claim-file behavior. + // + // A slot-numbered run collides by design: the id names a position in + // the log, so a loser is not a bug but a writer whose log was missing + // an event. It gets a SlotConflictError carrying that event instead + // (see below), and this write is the authority that decides it — the + // allocator's book is only ever a hint. // Last-instant re-validation for `hook_received` (see the acceptance // check above). The per-hook in-process lock already serializes // resume vs. dispose within one storage instance; this second check @@ -2235,115 +2577,178 @@ export function createEventsStorage( throw new HookNotFoundError(data.correlationId); } - const compositeKey = `${effectiveRunId}-${eventId}`; - const eventPath = taggedPath(basedir, 'events', compositeKey, tag); - // Capture the serialized payload before the write's `await` so the - // cached snapshot can't observe a later mutation (see - // rememberStoredEvent). - const serializedEvent = JSON.stringify(event, jsonReplacer, 2); - - // Cross-process terminal-run guard for `hook_received`. A terminal - // transition (run_completed / run_failed / run_cancelled) in ANY - // process (1) publishes a durable `runTerminalMarkerPath` marker and - // (2) reaps the run's staged hook_received events, both BEFORE it - // writes the terminal run state or appends its terminal event (see - // the terminal-transition block earlier in this function). In-memory - // locks cannot close the shared-filesystem race this backend - // explicitly supports, and a published event file is immediately - // visible to `events.list()` in other processes — so it can never be - // "rolled back" after the fact. Instead, the event stays INVISIBLE - // to readers until a single atomic filesystem operation decides its - // fate: - // - // 1. (fast path) reject if the run is already terminal — by - // marker, or by run state for runs that predate the marker — - // so the common case never creates a file. - // 2. STAGE the event at a non-reader-visible path under `.locks`. - // 3. re-CHECK the terminal marker; reject if present. - // 4. PROMOTE the staged file into `events/` with an atomic hard - // link; reject if the staged file was reaped (`'missing'`). - // - // Correctness: the reap's `unlink` and step 4's `link` target the - // same staged file, so the filesystem serializes them — exactly one - // wins. If the link wins, the event was reader-visible before the - // reap completed, and therefore before the terminal state and - // terminal event were written: acceptance happened-before the - // termination and legitimately precedes it. If the unlink wins, - // promotion fails and the event is never visible to any reader — - // there is nothing to roll back. A resume that stages after the - // reap has passed necessarily stages after the marker was - // committed, so step 3 rejects it. Rejections before step 4 unlink - // a file no reader can see. - let eventPublished: boolean; - if (data.eventType === 'hook_received') { - // Step 1: fast path. The marker is the authoritative durable - // signal; the run-state read additionally rejects runs whose - // terminal state was written without a marker (e.g. runs that - // terminated on an older storage version). - const terminalByMarker = await isRunTerminalCommitted( - basedir, - effectiveRunId, - tag - ); - const runNow = terminalByMarker - ? null - : await readJSONWithFallback( - basedir, - 'runs', - effectiveRunId, - WorkflowRunSchema, - tag - ); - if ( - terminalByMarker || - (runNow && isTerminalWorkflowRunStatus(runNow.status)) - ) { - throw new RunExpiredError( - `Workflow run "${effectiveRunId}" is already in a terminal state` - ); - } - - const stagedPath = pendingHookEventPath( - basedir, - effectiveRunId, - eventId, - tag - ); - const staged = await writeExclusive(stagedPath, serializedEvent); - if (!staged) { - // eventId is a freshly generated ULID; its staging path can - // only be occupied by a previous crashed attempt of this very - // event, which never promoted. Surface the same conflict shape - // as a visible-path collision. - throw new EntityConflictError( - `Event "${eventId}" already exists for run "${effectiveRunId}"` + /** + * One attempt at publishing the event at the position `eventId` + * currently names: `true` when this call made it reader-visible, + * `false` when the position was already taken. What a loss means is the + * loop's decision — a position this world allocated is simply retried + * one higher, a position the caller claimed is a conflict it has to + * resolve. + */ + async function publishOnce(): Promise { + // Cross-process terminal-run guard for `hook_received`. A terminal + // transition (run_completed / run_failed / run_cancelled) in ANY + // process (1) publishes a durable `runTerminalMarkerPath` marker and + // (2) reaps the run's staged hook_received events, both BEFORE it + // writes the terminal run state or appends its terminal event (see + // the terminal-transition block earlier in this function). In-memory + // locks cannot close the shared-filesystem race this backend + // explicitly supports, and a published event file is immediately + // visible to `events.list()` in other processes — so it can never be + // "rolled back" after the fact. Instead, the event stays INVISIBLE + // to readers until a single atomic filesystem operation decides its + // fate: + // + // 1. (fast path) reject if the run is already terminal — by + // marker, or by run state for runs that predate the marker — + // so the common case never creates a file. + // 2. STAGE the event at a non-reader-visible path under `.locks`. + // 3. re-CHECK the terminal marker; reject if present. + // 4. PROMOTE the staged file into `events/` with an atomic hard + // link; reject if the staged file was reaped (`'missing'`). + // + // Correctness: the reap's `unlink` and step 4's `link` target the + // same staged file, so the filesystem serializes them — exactly one + // wins. If the link wins, the event was reader-visible before the + // reap completed, and therefore before the terminal state and + // terminal event were written: acceptance happened-before the + // termination and legitimately precedes it. If the unlink wins, + // promotion fails and the event is never visible to any reader — + // there is nothing to roll back. A resume that stages after the + // reap has passed necessarily stages after the marker was + // committed, so step 3 rejects it. Rejections before step 4 unlink + // a file no reader can see. + if (data.eventType === 'hook_received') { + // Step 1: fast path. The marker is the authoritative durable + // signal; the run-state read additionally rejects runs whose + // terminal state was written without a marker (e.g. runs that + // terminated on an older storage version). + const terminalByMarker = await isRunTerminalCommitted( + basedir, + effectiveRunId, + tag ); - } - try { - if (await isRunTerminalCommitted(basedir, effectiveRunId, tag)) { + const runNow = terminalByMarker + ? null + : await readJSONWithFallback( + basedir, + 'runs', + effectiveRunId, + WorkflowRunSchema, + tag + ); + if ( + terminalByMarker || + (runNow && isTerminalWorkflowRunStatus(runNow.status)) + ) { throw new RunExpiredError( `Workflow run "${effectiveRunId}" is already in a terminal state` ); } - const promoted = await promoteExclusive(stagedPath, eventPath); - if (promoted === 'missing') { - // A terminal transition reaped the staged file between the - // check and the link — the atomic loss of the arbitration. - throw new RunExpiredError( - `Workflow run "${effectiveRunId}" is already in a terminal state` + + const stagedPath = pendingHookEventPath( + basedir, + effectiveRunId, + eventId, + tag + ); + const staged = await writeExclusive(stagedPath, serializedEvent); + if (!staged) { + // For a ULID-numbered run the eventId is freshly generated, so + // its staging path can only be occupied by a previous crashed + // attempt of this very event, which never promoted. A + // slot-numbered run can also collide here with another instance + // that allocated the same slot from its own book. Either way the + // event is not reader-visible, so there is no delta to hand back + // and nothing for the caller to merge: surface the same conflict + // shape as a visible-path collision — or, when this world + // allocated the position itself, let the loop below re-probe and + // take the next one. + if (reallocatesSlot) { + return false; + } + throw new EntityConflictError( + `Event "${eventId}" already exists for run "${effectiveRunId}"` ); } - eventPublished = promoted === 'linked'; - } finally { - // The staged path is not reader-visible; removing it is pure - // cleanup on every outcome (already gone when reaped). - await deleteJSON(stagedPath).catch(() => {}); + try { + if (await isRunTerminalCommitted(basedir, effectiveRunId, tag)) { + throw new RunExpiredError( + `Workflow run "${effectiveRunId}" is already in a terminal state` + ); + } + const promoted = await promoteExclusive(stagedPath, eventPath); + if (promoted === 'missing') { + // A terminal transition reaped the staged file between the + // check and the link — the atomic loss of the arbitration. + throw new RunExpiredError( + `Workflow run "${effectiveRunId}" is already in a terminal state` + ); + } + return promoted === 'linked'; + } finally { + // The staged path is not reader-visible; removing it is pure + // cleanup on every outcome (already gone when reaped). + await deleteJSON(stagedPath).catch(() => {}); + } } - } else { - eventPublished = await writeExclusive(eventPath, serializedEvent); + return await writeExclusive(eventPath, serializedEvent); } - if (!eventPublished) { + // A write that allocated its own position may take the next free one + // when it loses: nothing outside this world named the slot, so which + // position the event lands on is this world's business, and the caller + // — a step reporting its completion, a hook being received — has no log + // to reconcile. A write whose position the *caller* claimed may not: + // the claim asserts a log complete up to that position, so losing it + // means that log is stale and only the caller can resolve it. + // `run_created` is excluded even though it named its own position: the + // first slot is the only position it can ever occupy, so losing it means + // the run already has a creation event, and appending a second one above + // it would be worse than the duplicate the publish is reporting. + const reallocatesSlot = + slotMode && params?.eventId === undefined && !ownsFirstSlot; + const slotDeadline = Date.now() + SLOT_RETRY_BUDGET_MS; + let compositeKey = ''; + let eventPath = ''; + let serializedEvent = ''; + let eventPublished = false; + + for (let round = 0; ; round++) { + compositeKey = `${effectiveRunId}-${eventId}`; + eventPath = taggedPath(basedir, 'events', compositeKey, tag); + // Capture the serialized payload before the write's `await` so the + // cached snapshot can't observe a later mutation (see + // rememberStoredEvent). + serializedEvent = JSON.stringify(event, jsonReplacer, 2); + eventPublished = await publishOnce(); + if (eventPublished) { + break; + } + if (reallocatesSlot && Date.now() < slotDeadline) { + // The position is someone else's — either published there or + // staged for it. Record that, top the book up from disk, and try + // again above whatever the log has reached rather than surfacing a + // conflict the caller cannot act on. Re-reading rather than + // incrementing bounds the search: every round at least one writer + // wins, so the top of the log is never further than the number of + // writers still contending for it. + const lost = slotFromId(eventId); + if (lost !== undefined) { + reserved.delete(lost); + } + slots.observe(effectiveRunId, eventId); + await slots.refresh(effectiveRunId); + await new Promise((resolve) => + setTimeout(resolve, slotRetryDelay(round)) + ); + const slot = await slots.reserve(effectiveRunId); + reservedRunId = effectiveRunId; + reserved.add(slot); + eventId = slotEventId(slot); + event = { ...event, eventId }; + continue; + } // For `hook_created`, losing the event publish means the // event was already committed at this exact (canonical) // path. The original publisher may have crashed between @@ -2364,14 +2769,54 @@ export function createEventsStorage( tag ); } + if (reallocatesSlot) { + // Out of budget: every position this writer tried was taken by + // someone else. Surfacing it as a 503 puts the whole operation + // back on the queue rather than stalling the run here. + throw new WorkflowWorldError( + `Could not place an event in run "${effectiveRunId}" within ${SLOT_RETRY_BUDGET_MS}ms of contention`, + { status: 503 } + ); + } + if (slotMode) { + // Losing a claimed slot means someone else's event occupies this + // position, so the log this event was derived from is missing at + // least that event — the whole proposed event is stale, not just + // its id. Hand back what the caller is missing so it can merge, + // replay and re-propose, and forget the run's book so the next + // allocation re-reads the log this instance evidently does not + // have. + // + // Reaching here means the slot was taken *after* the pre-check at + // the claim site, so the entity this event was going to describe + // has already been materialized. Only two storage instances + // sharing a directory can do that, since one instance's book + // hands the same slot to nobody else. + slots.forget(effectiveRunId); + throw await slotConflict(effectiveRunId, eventId, params); + } throw new EntityConflictError( `Event "${eventId}" already exists for run "${effectiveRunId}"` ); } // The event is now committed; cache it so an immediate sequential - // replay can serve it without rereading from disk. + // replay can serve it without rereading from disk. Nothing this create + // claimed may be undone from here on: readers can see the event, so the + // entity it describes has to keep existing even if a later step of this + // call fails. + eventCommitted = true; rememberStoredEvent(event, eventPath, serializedEvent); + slots.observe(effectiveRunId, eventId); + if (companionSlot !== undefined) { + // A start that carried creation data for a step that already existed + // synthesized no `step_created`, so the position below it went + // unused. Hand it back instead of leaving it outstanding for the life + // of the process, where it would block the allocator from ever + // filling that position. + reserved.delete(companionSlot); + slots.release(effectiveRunId, companionSlot); + } // Write the hook entity ONLY now that the event publish has // committed. Doing this earlier (in the `hook_created` @@ -2409,6 +2854,7 @@ export function createEventsStorage( sortOrder: 'asc', limit: 1000, getCreatedAt: getObjectCreatedAt('evnt'), + getOrderTime: eventOrderTime, getId: (e) => e.eventId, }); events = allEvents.data; @@ -2457,6 +2903,7 @@ export function createEventsStorage( sortOrder: 'asc', cursor: params.sinceCursor, getCreatedAt: getObjectCreatedAt('evnt'), + getOrderTime: eventOrderTime, getId: (e) => e.eventId, }); events = @@ -2517,6 +2964,7 @@ export function createEventsStorage( limit: params.pagination?.limit, cursor: params.pagination?.cursor, getCreatedAt: getObjectCreatedAt('evnt'), + getOrderTime: eventOrderTime, getId: (event) => event.eventId, }); @@ -2549,6 +2997,7 @@ export function createEventsStorage( limit: params.pagination?.limit, cursor: params.pagination?.cursor, getCreatedAt: getObjectCreatedAt('evnt'), + getOrderTime: eventOrderTime, getId: (event) => event.eventId, }); diff --git a/packages/world-local/src/storage/helpers.ts b/packages/world-local/src/storage/helpers.ts index d7c2cc78bb..2817fb0574 100644 --- a/packages/world-local/src/storage/helpers.ts +++ b/packages/world-local/src/storage/helpers.ts @@ -1,6 +1,7 @@ import { createHash } from 'node:crypto'; import fs from 'node:fs/promises'; import path from 'node:path'; +import { FIRST_SLOT, maxSlotOf, slotEventId } from '@workflow/world'; import { decodeTime, monotonicFactory } from 'ulid'; import { hasTag, @@ -208,6 +209,46 @@ export async function reapPendingHookEvents( } } +/** + * The event ids of `runId` that are visible in the given tag's view, read from + * the event filenames alone — no file contents, so the cost is one `readdir` + * however large the log is. + * + * A missing `events` directory means the run provably has no events yet. Any + * other failure is thrown: callers derive an event key from this scan, and a + * silently short answer would mint a key that collides with, or fails to + * dominate, an event that is actually there. + */ +export async function listRunEventIds( + basedir: string, + runId: string, + tag?: string +): Promise { + let files: string[] = []; + try { + files = await fs.readdir(path.join(basedir, 'events')); + } catch (error) { + if ((error as NodeJS.ErrnoException).code !== 'ENOENT') { + throw error; + } + } + const prefix = `${runId}-`; + const eventIds: string[] = []; + for (const file of files) { + if (!file.startsWith(prefix) || !file.endsWith('.json')) { + continue; + } + const fileId = file.slice(0, -'.json'.length); + // Mirror read visibility: untagged files are visible to every tag, + // tagged files only to their own tag. + if (!isUntagged(fileId) && !(tag && hasTag(fileId, tag))) { + continue; + } + eventIds.push(stripTag(fileId).slice(prefix.length)); + } + return eventIds; +} + /** * Mint an event key (eventId + createdAt) that sorts strictly AFTER every * reader-visible event of the run in the given tag's view. @@ -229,38 +270,35 @@ export async function reapPendingHookEvents( * >= every visible event's `createdAt`, which was stamped at that event's * `createImpl()` entry — before its publish, and thus before this call. * Equal-`createdAt` ties fall to the strictly-dominant eventId. + * + * A slot-numbered run takes the slot above the highest visible one, which + * dominates by construction, paired with the wall clock — `createdAt` needs + * only to be >= every visible one, by the same argument as above. This is + * the one allocation that deliberately does *not* fill a hole below the max: + * a lower slot would sort before the events it has to follow, and density + * matters less here than replay order, since a hole below a terminal event + * means the run already lost an event it can never write. */ export async function mintRunDominantEventKey( basedir: string, runId: string, - tag?: string + tag: string | undefined, + slotMode: boolean ): Promise<{ eventId: string; createdAt: Date }> { - let files: string[] = []; - try { - files = await fs.readdir(path.join(basedir, 'events')); - } catch (error) { - // Only ENOENT ("no events directory yet") means there is provably - // nothing visible to dominate. Any other failure would silently mint a - // wall-clock key with no dominance guarantee over an already-accepted - // hook — abort the terminal transition instead; its retry re-runs this - // scan. - if ((error as NodeJS.ErrnoException).code !== 'ENOENT') { - throw error; - } + const eventIds = await listRunEventIds(basedir, runId, tag); + if (slotMode) { + // Above every event on disk, and above the run's own first slot even when + // that event has not landed yet: only `run_created` may occupy it, and a + // terminal event is never the run's first. + return { + eventId: slotEventId( + Math.max(maxSlotOf(eventIds.map(toEventRef)), FIRST_SLOT) + 1 + ), + createdAt: new Date(), + }; } - const prefix = `${runId}-`; let maxUlid: string | null = null; - for (const file of files) { - if (!file.startsWith(prefix) || !file.endsWith('.json')) { - continue; - } - const fileId = file.slice(0, -'.json'.length); - // Mirror read visibility: untagged files are visible to every tag, - // tagged files only to their own tag. - if (!isUntagged(fileId) && !(tag && hasTag(fileId, tag))) { - continue; - } - const candidate = stripTag(fileId).slice(prefix.length); + for (const candidate of eventIds) { if (!maxUlid || candidate > maxUlid) { maxUlid = candidate; } @@ -279,6 +317,10 @@ export async function mintRunDominantEventKey( return { eventId: `evnt_${monotonicUlid(ts)}`, createdAt: new Date(ts) }; } +function toEventRef(eventId: string): { eventId: string } { + return { eventId }; +} + /** * Path of the exclusive-create claim file that reserves a hook token. */ diff --git a/packages/world-local/src/storage/slot-identity.test.ts b/packages/world-local/src/storage/slot-identity.test.ts new file mode 100644 index 0000000000..f1ee5df07b --- /dev/null +++ b/packages/world-local/src/storage/slot-identity.test.ts @@ -0,0 +1,484 @@ +import { promises as fs } from 'node:fs'; +import os from 'node:os'; +import path from 'node:path'; +import { SlotConflictError } from '@workflow/errors'; +import type { Storage } from '@workflow/world'; +import { + FIRST_SLOT, + maxSlotOf, + SPEC_VERSION_CURRENT, + SPEC_VERSION_SLOT_IDENTITY, + slotEventId, + slotFromId, +} from '@workflow/world'; +import { afterEach, beforeEach, describe, expect, it } from 'vitest'; +import { createStorage } from './index.js'; + +let testDir: string; +let storage: Storage; + +beforeEach(async () => { + testDir = await fs.mkdtemp(path.join(os.tmpdir(), 'slot-identity-')); + storage = createStorage(testDir); +}); + +afterEach(async () => { + await fs.rm(testDir, { recursive: true, force: true }); +}); + +/** Start a run whose events are numbered by slot, and return its id. */ +async function newSlotRun(): Promise { + const result = await storage.events.create(null, { + eventType: 'run_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + eventData: { + deploymentId: 'dpl_test', + workflowName: 'test-workflow', + input: new Uint8Array(), + }, + }); + if (!result.run) { + throw new Error('Expected run to be created'); + } + return result.run.runId; +} + +/** + * The slots of the run's log, in list order. The page size is explicit: the + * default would silently truncate a fan-out and make a dense log look sparse. + */ +async function slotsOf(runId: string): Promise { + const { data } = await eventsOf(runId); + return data.map((event) => slotFromId(event.eventId) ?? -1); +} + +function eventsOf(runId: string) { + return storage.events.list({ runId, pagination: { limit: 500 } }); +} + +async function createStep( + runId: string, + stepId: string, + eventId?: string +): Promise { + const result = await storage.events.create( + runId, + { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: stepId, + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + eventId === undefined ? undefined : { eventId } + ); + if (!result.event) { + throw new Error('Expected an event'); + } + return result.event.eventId; +} + +async function createWait( + runId: string, + waitId: string, + eventId?: string +): Promise { + const result = await storage.events.create( + runId, + { + eventType: 'wait_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: waitId, + eventData: { resumeAt: new Date('2030-01-01T00:00:00.000Z') }, + }, + eventId === undefined ? undefined : { eventId } + ); + if (!result.event) { + throw new Error('Expected an event'); + } + return result.event.eventId; +} + +describe('numbering', () => { + it('puts run_created in the first slot', async () => { + const runId = await newSlotRun(); + await expect(slotsOf(runId)).resolves.toEqual([FIRST_SLOT]); + }); + + it('allocates dense slots for writers that hold no log', async () => { + // A step completion reporting in, a cancellation from an API call: the + // caller has no event log, so the world numbers the event for it. + const runId = await newSlotRun(); + await createStep(runId, 'step_a'); + await createStep(runId, 'step_b'); + await expect(slotsOf(runId)).resolves.toEqual([1, 2, 3]); + }); + + it('honours a slot the caller claims', async () => { + const runId = await newSlotRun(); + const eventId = await createStep(runId, 'step_a', slotEventId(2)); + expect(eventId).toBe(slotEventId(2)); + await expect(slotsOf(runId)).resolves.toEqual([1, 2]); + }); + + it('rejects a claim on a free position below the log’s tail', async () => { + // The undercut that a "is the position free?" check cannot catch. A + // position claimed by a write that then failed is never filled, so a log + // carries holes below its tail — and a caller numbering from a snapshot + // that predates the events above one of those holes aims straight at it. + // Let it land and the event sits below events another replay has already + // consumed: the log stays internally consistent while its order silently + // changes, which is enough to flip a race between a step and a sleep from + // one replay to the next. A claim asserts a complete log, so a claim that + // does not clear the tail is a conflict, exactly as a taken one is. + const runId = await newSlotRun(); + await createStep(runId, 'step_late', slotEventId(3)); + await expect( + createStep(runId, 'step_early', slotEventId(2)) + ).rejects.toThrow(SlotConflictError); + // The hole stays a hole, and the log stays in slot order. + await expect(slotsOf(runId)).resolves.toEqual([1, 3]); + }); + + it('accepts the claim immediately above a tail with a hole below it', async () => { + // The fence rejects at-or-below, so the first position above the tail has + // to stay writable — otherwise every write following a hole would conflict + // forever and the run could never make progress again. + const runId = await newSlotRun(); + await createStep(runId, 'step_late', slotEventId(3)); + expect(await createStep(runId, 'step_next', slotEventId(4))).toBe( + slotEventId(4) + ); + await expect(slotsOf(runId)).resolves.toEqual([1, 3, 4]); + }); + + it('keeps a burst of concurrent writers dense', async () => { + // The suspension flush issues every op at once. Density is what lets a + // reader prove its log is complete, so a burst must not leave holes. + const runId = await newSlotRun(); + const ids = await Promise.all( + Array.from({ length: 20 }, (_, index) => + createStep(runId, `step_${index}`) + ) + ); + expect(new Set(ids).size).toBe(ids.length); + const slots = await slotsOf(runId); + expect([...slots].sort((a, b) => a - b)).toEqual( + Array.from({ length: ids.length + 1 }, (_, index) => FIRST_SLOT + index) + ); + }); + + it('numbers a run densely when every write it makes lands', async () => { + const runId = await newSlotRun(); + await Promise.all( + Array.from({ length: 5 }, (_, index) => + createStep(runId, `step_${index}`) + ) + ); + const { data } = await eventsOf(runId); + expect(maxSlotOf(data)).toBe(data.length); + }); + + it('leaves a rejected write’s position unused instead of recycling it', async () => { + // The rejected op's position sits below its concurrent sibling's, so handing + // it to the next writer would order that writer's event below one that + // already published. The hole costs a reader nothing it was promised; the + // inversion would cost the run. + const runId = await newSlotRun(); + const [rejected, accepted] = await Promise.allSettled([ + storage.events.create(runId, { + eventType: 'step_completed', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_never_created', + eventData: { output: new Uint8Array() }, + }), + createStep(runId, 'step_a'), + ]); + expect(rejected.status).toBe('rejected'); + expect(accepted.status).toBe('fulfilled'); + await createStep(runId, 'step_b'); + const slots = await slotsOf(runId); + expect(slots).toHaveLength(3); + expect(slots[0]).toBe(FIRST_SLOT); + // Both concurrent writers took a position, one abandoned its own, and the + // third write went above them both. + expect(slots[2]).toBe(FIRST_SLOT + 3); + expect(slots[1]).toBeGreaterThan(slots[0]); + expect(slots[1]).toBeLessThan(slots[2]); + }); +}); + +/** + * A lazy step start: a `step_started` carrying the step's creation data, which + * the world materializes into a step plus the `step_created` event the caller + * deferred — one request, two events. + */ +async function startStepLazily( + runId: string, + stepId: string, + eventId?: string +): Promise { + const result = await storage.events.create( + runId, + { + eventType: 'step_started', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: stepId, + eventData: { stepName: 'a-step', input: new Uint8Array(), attempt: 0 }, + }, + eventId === undefined ? undefined : { eventId } + ); + if (!result.event) { + throw new Error('Expected an event'); + } + return result.event.eventId; +} + +describe('a write that publishes two events', () => { + it('numbers the deferred step_created below the claim', async () => { + // The caller reserves both positions and names only the top one, so the + // pair is fixed before either lands — which is what keeps it off the slot + // the next write of the same batch is holding. + const runId = await newSlotRun(); + const startedEventId = await startStepLazily( + runId, + 'step_a', + slotEventId(3) + ); + expect(startedEventId).toBe(slotEventId(3)); + await expect(slotsOf(runId)).resolves.toEqual([1, 2, 3]); + }); + + it('allocates both positions for a start that claims neither', async () => { + const runId = await newSlotRun(); + await startStepLazily(runId, 'step_a'); + await expect(slotsOf(runId)).resolves.toEqual([1, 2, 3]); + }); + + it('keeps every claim in a burst of lazy starts', async () => { + // The suspension flush issues its lazy starts at once, each having reserved + // two positions. A second event numbered off the log as this world sees it + // would take the slot the next start in the batch claimed, and cost every + // start after the first its claim — collapsing the fan-out to one step. + const runId = await newSlotRun(); + const claims = Array.from({ length: 10 }, (_, index) => + slotEventId(FIRST_SLOT + 2 * (index + 1)) + ); + const ids = await Promise.all( + claims.map((eventId, index) => + startStepLazily(runId, `step_${index}`, eventId) + ) + ); + expect(ids).toEqual(claims); + const slots = await slotsOf(runId); + expect([...slots].sort((a, b) => a - b)).toEqual( + Array.from({ length: 2 * claims.length + 1 }, (_, i) => FIRST_SLOT + i) + ); + }); + + it('rejects a claim that leaves no room for the second event', async () => { + // The run's own run_created holds the first slot, so a claim of the second + // means the caller reserved one position for a write that publishes two. + const runId = await newSlotRun(); + await expect( + startStepLazily(runId, 'step_a', slotEventId(FIRST_SLOT + 1)) + ).rejects.toThrow(/leaves no slot below it/); + }); +}); + +describe('mode is pinned to the run', () => { + it('rejects a slot id claimed on a ULID-numbered run', async () => { + const created = await storage.events.create(null, { + eventType: 'run_created', + specVersion: SPEC_VERSION_CURRENT, + eventData: { + deploymentId: 'dpl_test', + workflowName: 'test-workflow', + input: new Uint8Array(), + }, + }); + const runId = created.run?.runId as string; + await expect(createStep(runId, 'step_a', slotEventId(2))).rejects.toThrow( + /not numbered by slot/ + ); + }); + + it('rejects a ULID id claimed on a slot-numbered run', async () => { + const runId = await newSlotRun(); + await expect( + createStep(runId, 'step_a', 'evnt_01K5Z0000000000000000000AA') + ).rejects.toThrow(/not a slot id/); + }); + + it('ignores the spec version of later requests', async () => { + // A run is in exactly one mode for life; only what was persisted decides. + const runId = await newSlotRun(); + const result = await storage.events.create(runId, { + eventType: 'step_created', + specVersion: SPEC_VERSION_CURRENT, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }); + expect(slotFromId(result.event?.eventId ?? '')).toBe(2); + }); +}); + +describe('conflict', () => { + it('reports the events the loser is missing', async () => { + const runId = await newSlotRun(); + // Out of band: something else takes the slot this caller was about to + // claim, so the caller's log is provably missing an event. + await createStep(runId, 'step_out_of_band'); + + const conflict = await storage.events + .create( + runId, + { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + { eventId: slotEventId(2), maxSlot: 1 } + ) + .catch((error: unknown) => error); + + expect(SlotConflictError.is(conflict)).toBe(true); + const slotConflict = conflict as SlotConflictError; + expect(slotConflict.status).toBe(409); + expect(slotConflict.eventId).toBe(slotEventId(2)); + expect(slotConflict.events?.map((event) => event.eventId)).toEqual([ + slotEventId(2), + ]); + }); + + it('lets the loser re-propose at the next free slot', async () => { + const runId = await newSlotRun(); + await createStep(runId, 'step_out_of_band'); + await expect(createStep(runId, 'step_a', slotEventId(2))).rejects.toThrow( + SlotConflictError + ); + // Merging the delta moves the caller's own numbering forward by one. + const eventId = await createStep(runId, 'step_a', slotEventId(3)); + expect(eventId).toBe(slotEventId(3)); + await expect(slotsOf(runId)).resolves.toEqual([1, 2, 3]); + }); + + it('excludes events the loser already holds from the delta', async () => { + const runId = await newSlotRun(); + await createStep(runId, 'step_one'); + await createStep(runId, 'step_two'); + + const conflict = await storage.events + .create( + runId, + { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + { eventId: slotEventId(2), maxSlot: 2 } + ) + .catch((error: unknown) => error); + + // Slots 1 and 2 are at or below what the caller had; only 3 is news. + expect( + (conflict as SlotConflictError).events?.map((event) => event.eventId) + ).toEqual([slotEventId(3)]); + }); + + it('conflicts when another instance takes a claimed slot', async () => { + // Two instances keep independent books, so the exclusive write — not the + // book — is what decides who owns a slot. A claim asserts a complete log, + // so its loser has to reload rather than move over. + const runId = await newSlotRun(); + const other = createStorage(testDir); + await other.events.create(runId, { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_b', + eventData: { stepName: 'b-step', input: new Uint8Array() }, + }); + await expect(createStep(runId, 'step_a', slotEventId(2))).rejects.toThrow( + SlotConflictError + ); + await expect(slotsOf(runId)).resolves.toEqual([1, 2]); + }); + + it('lets a lost claim re-propose an entity it had already materialized', async () => { + // A claim only reaches its exclusive write after the entity it describes + // exists, so a claim that loses leaves that entity behind. The caller's + // whole answer to a conflict is to merge, replay and propose the same + // operation one position higher — which it cannot do if its own leftover + // entity is what rejects the retry. + const runId = await newSlotRun(); + // Seed this instance's book, then let another instance take the position + // the book will hand out next. The claim below passes the book's + // "is it written?" check because the book has not seen that write. + await createStep(runId, 'step_seed'); + const other = createStorage(testDir); + await other.events.create(runId, { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_out_of_band', + eventData: { stepName: 'b-step', input: new Uint8Array() }, + }); + + await expect(createWait(runId, 'wait_a', slotEventId(3))).rejects.toThrow( + SlotConflictError + ); + const eventId = await createWait(runId, 'wait_a', slotEventId(4)); + expect(eventId).toBe(slotEventId(4)); + await expect(slotsOf(runId)).resolves.toEqual([1, 2, 3, 4]); + }); + + it('lets a lazy start lose the position of the event it defers', async () => { + // The deferred `step_created` is published on the same terms as the start + // itself, so it is the pair's first position that can be lost. The retry has + // to be able to start the step lazily all over again — its own claim file + // and step entity would otherwise answer for a write that never landed. + const runId = await newSlotRun(); + await createStep(runId, 'step_seed'); + const other = createStorage(testDir); + await other.events.create(runId, { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_out_of_band', + eventData: { stepName: 'b-step', input: new Uint8Array() }, + }); + + await expect( + startStepLazily(runId, 'step_a', slotEventId(4)) + ).rejects.toThrow(SlotConflictError); + const eventId = await startStepLazily(runId, 'step_a', slotEventId(5)); + expect(eventId).toBe(slotEventId(5)); + await expect(slotsOf(runId)).resolves.toEqual([1, 2, 3, 4, 5]); + }); + + it('reallocates around another instance holding the slot it picked', async () => { + // Neither writer holds a log, so neither has anything to reconcile: the + // loser takes the next free position instead of surfacing a conflict its + // caller could not act on. + const runId = await newSlotRun(); + const other = createStorage(testDir); + const outcomes = await Promise.allSettled([ + storage.events.create(runId, { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }), + other.events.create(runId, { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_b', + eventData: { stepName: 'b-step', input: new Uint8Array() }, + }), + ]); + expect(outcomes.map((outcome) => outcome.status)).toEqual([ + 'fulfilled', + 'fulfilled', + ]); + await expect(slotsOf(runId)).resolves.toEqual([1, 2, 3]); + }); +}); diff --git a/packages/world-local/src/storage/slots.test.ts b/packages/world-local/src/storage/slots.test.ts new file mode 100644 index 0000000000..318b95c204 --- /dev/null +++ b/packages/world-local/src/storage/slots.test.ts @@ -0,0 +1,288 @@ +import fs from 'node:fs/promises'; +import os from 'node:os'; +import path from 'node:path'; +import { + FIRST_SLOT, + SPEC_VERSION_CURRENT, + SPEC_VERSION_SLOT_IDENTITY, + slotEventId, +} from '@workflow/world'; +import { afterEach, beforeEach, describe, expect, it } from 'vitest'; +import { createSlotBook, RUN_CREATED_SLOT } from './slots.js'; + +let basedir: string; + +beforeEach(async () => { + basedir = await fs.mkdtemp(path.join(os.tmpdir(), 'slot-book-')); +}); + +afterEach(async () => { + await fs.rm(basedir, { recursive: true, force: true }); +}); + +const RUN_ID = 'wrun_01K0000000000000000000TEST'; + +async function writeRun(specVersion: number): Promise { + await fs.mkdir(path.join(basedir, 'runs'), { recursive: true }); + await fs.writeFile( + path.join(basedir, 'runs', `${RUN_ID}.json`), + JSON.stringify({ + runId: RUN_ID, + deploymentId: 'dpl_test', + status: 'running', + workflowName: 'test', + specVersion, + input: [], + attributes: {}, + createdAt: new Date().toISOString(), + updatedAt: new Date().toISOString(), + }) + ); +} + +async function writeEvents(...slots: number[]): Promise { + await fs.mkdir(path.join(basedir, 'events'), { recursive: true }); + for (const slot of slots) { + await fs.writeFile( + path.join(basedir, 'events', `${RUN_ID}-${slotEventId(slot)}.json`), + '{}' + ); + } +} + +describe('usesSlots', () => { + it('reads the mode off the persisted run, not the build', async () => { + await writeRun(SPEC_VERSION_SLOT_IDENTITY); + await expect(createSlotBook(basedir).usesSlots(RUN_ID)).resolves.toBe(true); + + await writeRun(SPEC_VERSION_CURRENT); + await expect(createSlotBook(basedir).usesSlots(RUN_ID)).resolves.toBe( + false + ); + }); + + it('re-reads until the run exists', async () => { + // The resilient-start path writes run_started before the run entity, so a + // cached "no" taken from the missing run would strand a slot-numbered run + // on ULID ids for the rest of the process's life. + const book = createSlotBook(basedir); + await expect(book.usesSlots(RUN_ID)).resolves.toBe(false); + await writeRun(SPEC_VERSION_SLOT_IDENTITY); + await expect(book.usesSlots(RUN_ID)).resolves.toBe(true); + }); + + it('prefers its own tagged run over the untagged one', async () => { + await writeRun(SPEC_VERSION_SLOT_IDENTITY); + await fs.rename( + path.join(basedir, 'runs', `${RUN_ID}.json`), + path.join(basedir, 'runs', `${RUN_ID}.mine.json`) + ); + await writeRun(SPEC_VERSION_CURRENT); + + await expect( + createSlotBook(basedir, 'mine').usesSlots(RUN_ID) + ).resolves.toBe(true); + await expect( + createSlotBook(basedir, 'other').usesSlots(RUN_ID) + ).resolves.toBe(false); + }); +}); + +describe('reserve', () => { + it('starts above the slot the run’s own creation event owns', async () => { + // `run_created` takes the first slot outright — nothing can precede it — so + // an allocation never hands that position out. + await expect(createSlotBook(basedir).reserve(RUN_ID)).resolves.toBe( + RUN_CREATED_SLOT + 1 + ); + }); + + it('continues above the highest slot already on disk', async () => { + await writeEvents(1, 2, 3); + await expect(createSlotBook(basedir).reserve(RUN_ID)).resolves.toBe(4); + }); + + it('leaves a hole in the persisted log unfilled', async () => { + // Allocation is append-only: the free position sits below a published event, + // and an event placed there would order before one that already happened. + await writeEvents(1, 3); + const book = createSlotBook(basedir); + await expect(book.reserve(RUN_ID)).resolves.toBe(4); + await expect(book.reserve(RUN_ID)).resolves.toBe(5); + }); + + it('stays above published events when a lower position comes free', async () => { + // The corruption this rules out: a step completion allocating late, dropping + // into a hole, and landing below the step_started it reports on. Replay reads + // the log in slot order and cannot consume that. + const book = createSlotBook(basedir); + const abandoned = await book.reserve(RUN_ID); + const published = await book.reserve(RUN_ID); + book.observe(RUN_ID, slotEventId(published)); + book.release(RUN_ID, abandoned); + await expect(book.reserve(RUN_ID)).resolves.toBeGreaterThan(published); + }); + + it('hands a synchronous burst distinct consecutive slots', async () => { + // The suspension flush issues every op concurrently; a book that only moved + // on publish would give them all the same position and fail all but one. + const book = createSlotBook(basedir); + const slots = await Promise.all( + Array.from({ length: 20 }, () => book.reserve(RUN_ID)) + ); + expect([...slots].sort((a, b) => a - b)).toEqual( + Array.from({ length: 20 }, (_, index) => RUN_CREATED_SLOT + 1 + index) + ); + }); + + it('shares one disk scan across concurrent first callers', async () => { + await writeEvents(1); + const book = createSlotBook(basedir); + const slots = await Promise.all([ + book.reserve(RUN_ID), + book.reserve(RUN_ID), + ]); + expect([...slots].sort((a, b) => a - b)).toEqual([2, 3]); + }); + + it('honours a floor above where the book has reached', async () => { + // start() publishes the run entity before its `run_created` event and issues + // the queue send in parallel, so the delivery's `run_started` can allocate + // while slot 1 is still in flight. + const book = createSlotBook(basedir); + await expect(book.reserve(RUN_ID, 5)).resolves.toBe(5); + await expect(book.reserve(RUN_ID)).resolves.toBe(6); + }); + + it('keeps runs independent', async () => { + await writeEvents(1, 2); + const book = createSlotBook(basedir); + await expect(book.reserve(RUN_ID)).resolves.toBe(3); + await expect(book.reserve('wrun_01K0000000000000000000OTHR')).resolves.toBe( + RUN_CREATED_SLOT + 1 + ); + }); +}); + +describe('release', () => { + it('does not recycle an abandoned interior slot', async () => { + // The position may already sit below a sibling that published, and no + // caller can tell from here. A hole is a position nothing ever wrote; an + // inversion is an event a replay reads before the one it followed. + const book = createSlotBook(basedir); + const [first, second] = await Promise.all([ + book.reserve(RUN_ID), + book.reserve(RUN_ID), + ]); + book.release(RUN_ID, first); + await expect(book.reserve(RUN_ID)).resolves.toBe(second + 1); + }); + + it('does not resurrect a slot that was published', async () => { + const book = createSlotBook(basedir); + const slot = await book.reserve(RUN_ID); + book.observe(RUN_ID, slotEventId(slot)); + book.release(RUN_ID, slot); + await expect(book.reserve(RUN_ID)).resolves.toBe(slot + 1); + }); +}); + +describe('highestWritten', () => { + it('reads the log to answer for a run it has never seen', async () => { + await writeEvents(1, 2); + const book = createSlotBook(basedir); + await expect(book.highestWritten(RUN_ID)).resolves.toBe(2); + }); + + it('reports the tail of a log with a hole below it', async () => { + // The case the tail exists to catch: slot 3 was claimed by a write that + // never published, so it is free — but a claim on it would land below the + // event at 4 that a replay may already have consumed. + await writeEvents(1, 2, 4); + const book = createSlotBook(basedir); + await expect(book.highestWritten(RUN_ID)).resolves.toBe(4); + }); + + it('is below the first slot for a run with no events', async () => { + const book = createSlotBook(basedir); + await expect(book.highestWritten(RUN_ID)).resolves.toBe(FIRST_SLOT - 1); + }); + + it('ignores a slot that is only reserved', async () => { + // A reservation is not a publish, so a caller claiming the slot has to be + // allowed through to the write that actually decides it. + const book = createSlotBook(basedir); + await book.reserve(RUN_ID); + await expect(book.highestWritten(RUN_ID)).resolves.toBe(FIRST_SLOT - 1); + }); +}); + +describe('claim', () => { + it('holds a slot claimed before anything allocated for the run', async () => { + // A claim is synchronous and the first allocation's log scan is not, so a + // claim that only registered against an existing book would be invisible to + // the very allocation it races — and a single-process app would hand the + // caller's own position away. + await writeEvents(1); + const book = createSlotBook(basedir); + book.claim(RUN_ID, 2); + await expect(book.reserve(RUN_ID)).resolves.toBe(3); + }); + + it('stops holding back a claim that resolved', async () => { + // Released before anything allocated for the run, so no position in this + // instance was ever handed out above it and the log — which is the authority + // on what published — reaches only slot 1. Nothing can be inverted by + // seeding the book from disk alone. + await writeEvents(1); + const book = createSlotBook(basedir); + book.claim(RUN_ID, 2); + book.release(RUN_ID, 2); + await expect(book.reserve(RUN_ID)).resolves.toBe(2); + }); + + it('keeps holding a claim across a forget', async () => { + // `forget` follows a lost publish: the book is behind another writer, but + // the claims other writes in this instance still hold are not. + await writeEvents(1); + const book = createSlotBook(basedir); + book.claim(RUN_ID, 2); + book.forget(RUN_ID); + await expect(book.reserve(RUN_ID)).resolves.toBe(3); + }); +}); + +describe('observe', () => { + it('moves allocation above a position the client claimed', async () => { + const book = createSlotBook(basedir); + await book.reserve(RUN_ID); + book.observe(RUN_ID, slotEventId(5)); + await expect(book.reserve(RUN_ID)).resolves.toBe(6); + }); + + it('ignores ULID event ids', async () => { + const book = createSlotBook(basedir); + const slot = await book.reserve(RUN_ID); + book.observe(RUN_ID, 'evnt_01K5Z0000000000000000000AA'); + await expect(book.reserve(RUN_ID)).resolves.toBe(slot + 1); + }); +}); + +describe('forget', () => { + it("re-reads the log, picking up another writer's events", async () => { + const book = createSlotBook(basedir); + await expect(book.reserve(RUN_ID)).resolves.toBe(RUN_CREATED_SLOT + 1); + await writeEvents(1, 2, 3); + book.forget(RUN_ID); + await expect(book.reserve(RUN_ID)).resolves.toBe(4); + }); + + it('clear() forgets every run', async () => { + await writeEvents(1); + const book = createSlotBook(basedir); + await expect(book.reserve(RUN_ID)).resolves.toBe(2); + await writeEvents(2, 3); + book.clear(); + await expect(book.reserve(RUN_ID)).resolves.toBe(4); + }); +}); diff --git a/packages/world-local/src/storage/slots.ts b/packages/world-local/src/storage/slots.ts new file mode 100644 index 0000000000..1b1822e704 --- /dev/null +++ b/packages/world-local/src/storage/slots.ts @@ -0,0 +1,327 @@ +/** + * Slot allocation for the Local World. + * + * A slot-numbered run names its events by position: `evnt_…001` is the first + * event of the run, `evnt_…002` the second. A replay reads the log in slot + * order, so the order slots are handed out in has to be an order some execution + * could have produced — which makes allocation strictly *append-only*: a slot is + * only ever handed out above every position this book has seen. + * + * Filling a hole is what that rules out, and it is worth naming why, because the + * alternative looks appealing (it keeps the log dense). A position left unwritten + * by an abandoned reservation sits below events that are already published. Hand + * it to the next caller and a `step_completed` lands below its own + * `step_started`; the replay reaches a completion for a step it has not started + * and diverges, and every later replay diverges the same way. A hole costs a + * reader the ability to prove its copy of the log is complete. An inversion + * costs the run. + * + * Three properties do the work: + * + * - Handing out a slot is a *synchronous* set operation, so concurrent + * callers in one process get distinct slots with no lock. The only await is + * seeding from disk, which is memoized per run. + * - An allocation picks the position above the highest one the book knows of, + * written or outstanding, and that ceiling never descends. A reservation that + * is abandoned (its create threw a validation error) leaves its position + * unused rather than being recycled below a sibling that already published. + * - The event publish is `writeExclusive`, which is the authority. The book is + * a hint: when it turns out to be stale (another process wrote the slot), + * the publish fails and the caller is told so, rather than a duplicate being + * written or a slot being skipped. + * + * The book is per storage instance, and two instances may share a data + * directory (the cross-process convergence tests rely on exactly that). Their + * books are then independent, and the loser of a collision gets a conflict it + * has to resolve by reloading — the same contract as the networked worlds. + */ + +import type { WorkflowRun } from '@workflow/world'; +import { + FIRST_SLOT, + slotFromId, + usesSlotIdentity, + WorkflowRunSchema, +} from '@workflow/world'; +import { readJSONWithFallback } from '../fs.js'; +import { listRunEventIds } from './helpers.js'; + +interface RunSlots { + /** Slots proven to be on disk. */ + written: Set; + /** Slots handed out whose publish has not resolved yet. */ + outstanding: Set; + /** + * The highest position this book has ever seen written, claimed or handed out. + * Allocation goes above it and it never descends, which is what keeps a + * released position from being recycled below events already published. + */ + ceiling: number; +} + +export interface SlotBook { + /** + * Whether `runId`'s events are numbered by slot, read from the run's + * persisted `specVersion` — never from the build, so a run stays in the mode + * it was created in for life. A run that does not exist yet is not + * slot-numbered, and that answer is not cached: the resilient-start path + * creates the run moments later, and caching "no" would strand it on ULIDs + * for the rest of this process's life. + */ + usesSlots(runId: string): Promise; + /** + * Reserves the position above every one this book knows of for `runId`, and at + * or above `minSlot`. Distinct for every concurrent caller; the publish still + * has to prove the position was actually free. + * + * `minSlot` defaults to the position above the run's first slot, which is + * reserved for its own `run_created`: that event needs no allocation, and it + * may not be on disk yet when a concurrent `run_started` allocates (start() + * issues the creation and the queue send in parallel, and the run entity is + * published before its event). + */ + reserve(runId: string, minSlot?: number): Promise; + /** + * Records that a caller claimed `slot` itself, so an allocation running + * alongside it picks a different one. Reserved and released on the same terms + * as {@link reserve}: the claim is only a hint until the publish proves it. + */ + claim(runId: string, slot: number): void; + /** + * The highest position this run has published, seeding from disk if the run + * has not been read yet, or `FIRST_SLOT - 1` for a log with no events. + * + * This is the tail a claim has to clear. "Free" is not the property a claim + * needs: allocation is append-only, so a position left unwritten by an + * abandoned reservation stays empty for good, and a caller numbering from a + * snapshot that predates the events above such a hole aims straight at it. Let + * that write land and the event sits *below* events another replay already + * consumed — the log stays internally consistent while its order silently + * changes, which is enough to flip a race between a step and a sleep from one + * replay to the next. + * + * Reading the tail before the write also lets a doomed claim be rejected + * *before* the create materializes its step, hook or wait: the entity mutation + * runs ahead of the event publish, so a claim that only fails at the publish + * leaves an entity behind with no event, and the caller's re-proposal at the + * next slot then collides with its own orphan. A tail read here is not a + * promise — the publish is still the authority, and another instance sharing + * the data directory may have written above it — but it turns the case that + * actually happens (a caller numbering from a stale log) into a clean + * conflict. + */ + highestWritten(runId: string): Promise; + /** + * Forgets a reserved or claimed slot whose publish is never going to happen, + * so nothing waits on it. The position itself is not handed out again: it may + * already sit below a sibling that published, and recycling it there would put + * a later event below an earlier one. + */ + release(runId: string, slot: number): void; + /** Records a published event id, so it is never handed out again. */ + observe(runId: string, eventId: string): void; + /** + * Merges the run's published positions from disk into the book kept for it, + * leaving the reservations other writers in this instance still hold. + * + * A writer whose publish lost its position calls this before trying again: + * the book is demonstrably behind another instance's writes, and dropping it + * wholesale ({@link SlotBook.forget}) would hand a sibling's outstanding + * position to the next caller and cost that sibling its own publish. + */ + refresh(runId: string): Promise; + /** Drops what is cached for `runId`, so the next reservation re-reads disk. */ + forget(runId: string): void; + /** Drops everything cached (the data directory was cleared out from under us). */ + clear(): void; +} + +export function createSlotBook(basedir: string, tag?: string): SlotBook { + /** runId → whether the run is slot-numbered, memoized once it exists. */ + const modes = new Map(); + const books = new Map(); + /** runId → in-flight seed scan, so concurrent first callers share one scan. */ + const seeds = new Map>(); + /** + * runId → slots claimed while the run had no book yet, so the book the next + * allocation seeds starts out holding them. A claim is synchronous and a seed + * scan is not: without this, the first allocation of a run would read the log + * from disk and hand out a position a caller in this very instance had already + * claimed — the case that makes a claim lose in a single-process app. + */ + const claims = new Map>(); + + async function readMode(runId: string): Promise { + const run = await readJSONWithFallback( + basedir, + 'runs', + runId, + WorkflowRunSchema, + tag + ); + return run ? usesSlotIdentity(run.specVersion) : false; + } + + async function seed(runId: string): Promise { + const eventIds = await listRunEventIds(basedir, runId, tag); + const written = new Set(); + for (const eventId of eventIds) { + const slot = slotFromId(eventId); + if (slot !== undefined) { + written.add(slot); + } + } + const outstanding = new Set(claims.get(runId)); + const book: RunSlots = { + written, + outstanding, + ceiling: Math.max(FIRST_SLOT - 1, ...written, ...outstanding), + }; + books.set(runId, book); + return book; + } + + /** The run's book, seeding it from disk once for all concurrent callers. */ + function open(runId: string): RunSlots | Promise { + const known = books.get(runId); + if (known) { + return known; + } + let pending = seeds.get(runId); + if (!pending) { + pending = seed(runId).finally(() => seeds.delete(runId)); + seeds.set(runId, pending); + } + return pending; + } + + /** + * Drops a claim once its publish resolved, either way: a claim left behind + * would be handed to no one and become a hole in a log seeded later. + */ + function forgetClaim(runId: string, slot: number): void { + const claimed = claims.get(runId); + if (!claimed) { + return; + } + claimed.delete(slot); + if (claimed.size === 0) { + claims.delete(runId); + } + } + + function take(book: RunSlots, minSlot: number): number { + const slot = Math.max(book.ceiling + 1, minSlot); + book.outstanding.add(slot); + book.ceiling = slot; + return slot; + } + + return { + async usesSlots(runId) { + const cached = modes.get(runId); + if (cached !== undefined) { + return cached; + } + const mode = await readMode(runId); + // `false` here can mean "run not created yet" as well as "ULID run", and + // only the run's own absence is transient — so remember the positive + // answer eagerly and re-read until the run exists. + if (mode) { + modes.set(runId, true); + } + return mode; + }, + + async reserve(runId, minSlot = RUN_CREATED_SLOT + 1) { + const opened = open(runId); + // Awaiting a book that is already in hand would yield to the microtask + // queue and let a concurrent caller take the same slot. + return take(opened instanceof Promise ? await opened : opened, minSlot); + }, + + claim(runId, slot) { + const claimed = claims.get(runId); + if (claimed) { + claimed.add(slot); + } else { + claims.set(runId, new Set([slot])); + } + const book = books.get(runId); + if (book) { + book.outstanding.add(slot); + book.ceiling = Math.max(book.ceiling, slot); + } + }, + + async highestWritten(runId) { + const book = await open(runId); + return Math.max(FIRST_SLOT - 1, ...book.written); + }, + + release(runId, slot) { + forgetClaim(runId, slot); + const book = books.get(runId); + if (!book) { + return; + } + // The ceiling stays where it is: this position may already sit below one a + // sibling published, and handing it out again would order a later event + // before an earlier one. + book.outstanding.delete(slot); + }, + + observe(runId, eventId) { + const slot = slotFromId(eventId); + if (slot === undefined) { + return; + } + forgetClaim(runId, slot); + const book = books.get(runId); + if (!book) { + // Nothing to keep consistent: the slot is on disk by the time this is + // called, so the eventual seed scan picks it up. + return; + } + book.written.add(slot); + book.outstanding.delete(slot); + book.ceiling = Math.max(book.ceiling, slot); + }, + + async refresh(runId) { + const book = books.get(runId); + if (!book) { + // Nothing cached to correct; the next reservation seeds from disk. + return; + } + for (const eventId of await listRunEventIds(basedir, runId, tag)) { + const slot = slotFromId(eventId); + if (slot !== undefined) { + book.written.add(slot); + book.outstanding.delete(slot); + book.ceiling = Math.max(book.ceiling, slot); + } + } + }, + + forget(runId) { + modes.delete(runId); + books.delete(runId); + // Claims outlive the book on purpose: they belong to writes still in + // flight, and the book a later allocation seeds has to hold them back. + }, + + clear() { + modes.clear(); + books.clear(); + claims.clear(); + }, + }; +} + +/** + * The slot a run's first event occupies. A run's own `run_created` is the only + * event that can be numbered without consulting the log, because there is + * provably nothing before it. + */ +export const RUN_CREATED_SLOT = FIRST_SLOT; diff --git a/packages/world-postgres/src/drizzle/migrations/0018_run_scoped_event_and_step_keys.sql b/packages/world-postgres/src/drizzle/migrations/0018_run_scoped_event_and_step_keys.sql new file mode 100644 index 0000000000..0764dee02d --- /dev/null +++ b/packages/world-postgres/src/drizzle/migrations/0018_run_scoped_event_and_step_keys.sql @@ -0,0 +1,13 @@ +-- Event ids and step ids are unique per run, not globally. Under slot identity +-- (spec 6) every run numbers its own log from 1, so "evnt_0...001" and +-- "step_0...001" exist once per run and the old global primary keys would make +-- the second run to reach slot 1 collide with the first. +-- +-- The run leads both keys so the existing run-scoped range scans stay a single +-- index seek; that also makes the standalone run_id indexes redundant. +ALTER TABLE "workflow"."workflow_events" DROP CONSTRAINT IF EXISTS "workflow_events_pkey";--> statement-breakpoint +ALTER TABLE "workflow"."workflow_events" ADD CONSTRAINT "workflow_events_run_id_id_pk" PRIMARY KEY("run_id","id");--> statement-breakpoint +DROP INDEX IF EXISTS "workflow"."workflow_events_run_id_index";--> statement-breakpoint +ALTER TABLE "workflow"."workflow_steps" DROP CONSTRAINT IF EXISTS "workflow_steps_pkey";--> statement-breakpoint +ALTER TABLE "workflow"."workflow_steps" ADD CONSTRAINT "workflow_steps_run_id_step_id_pk" PRIMARY KEY("run_id","step_id");--> statement-breakpoint +DROP INDEX IF EXISTS "workflow"."workflow_steps_run_id_index"; diff --git a/packages/world-postgres/src/drizzle/migrations/meta/_journal.json b/packages/world-postgres/src/drizzle/migrations/meta/_journal.json index b7fb5d8215..9dca967a5b 100644 --- a/packages/world-postgres/src/drizzle/migrations/meta/_journal.json +++ b/packages/world-postgres/src/drizzle/migrations/meta/_journal.json @@ -127,6 +127,13 @@ "when": 1785283200000, "tag": "0017_add_hook_resume_context", "breakpoints": true + }, + { + "idx": 18, + "version": "7", + "when": 1785801600000, + "tag": "0018_run_scoped_event_and_step_keys", + "breakpoints": true } ] } diff --git a/packages/world-postgres/src/drizzle/schema.ts b/packages/world-postgres/src/drizzle/schema.ts index 6ffb21abcb..df58f73eb8 100644 --- a/packages/world-postgres/src/drizzle/schema.ts +++ b/packages/world-postgres/src/drizzle/schema.ts @@ -133,7 +133,7 @@ export const runs = schema.table( export const events = schema.table( 'workflow_events', { - eventId: varchar('id').primaryKey(), + eventId: varchar('id').notNull(), eventType: varchar('type').$type().notNull(), correlationId: varchar('correlation_id'), createdAt: timestamp('created_at').defaultNow().notNull(), @@ -146,7 +146,11 @@ export const events = schema.table( Cborized & { eventData?: undefined }, 'eventData'> >, (tb) => [ - index().on(tb.runId), + // Event ids are only unique within their run: under slot identity every run + // numbers its own log from 1, so `evnt_0…001` exists once per run. The run + // leads the key so the range scans in `list` stay a single index seek, and + // it subsumes the plain `run_id` index the table used to carry. + primaryKey({ columns: [tb.runId, tb.eventId] }), index().on(tb.correlationId), // Runtime-correlated one-shot events must be unique per (run, correlation) // — without @@ -167,7 +171,7 @@ export const steps = schema.table( 'workflow_steps', { runId: varchar('run_id').notNull(), - stepId: varchar('step_id').primaryKey(), + stepId: varchar('step_id').notNull(), stepName: varchar('step_name').notNull(), status: stepStatus('status').notNull(), /** @deprecated */ @@ -203,7 +207,13 @@ export const steps = schema.table( 'output' | 'input' | 'error' > >, - (tb) => [index().on(tb.runId), index().on(tb.status)] + (tb) => [ + // A step id is a correlation id, which under slot identity is only unique + // within its run — same reasoning as `workflow_events`. Every step query in + // this world is already run-scoped, so the run leads the key. + primaryKey({ columns: [tb.runId, tb.stepId] }), + index().on(tb.status), + ] ); export const hooks = schema.table( diff --git a/packages/world-postgres/src/index.ts b/packages/world-postgres/src/index.ts index 430cea0812..926d752d3b 100644 --- a/packages/world-postgres/src/index.ts +++ b/packages/world-postgres/src/index.ts @@ -1,5 +1,5 @@ import type { Storage, World } from '@workflow/world'; -import { reenqueueActiveRuns, SPEC_VERSION_CURRENT } from '@workflow/world'; +import { mintedSpecVersion, reenqueueActiveRuns } from '@workflow/world'; import { Pool } from 'pg'; import type { PostgresWorldConfig } from './config.js'; import { createClient, type Drizzle } from './drizzle/index.js'; @@ -63,7 +63,10 @@ export function createWorld( const streamer = createStreamer(pool, drizzle); return { - specVersion: SPEC_VERSION_CURRENT, + // What this world stamps on new runs: slot identity, unless + // WORKFLOW_SLOT_IDENTITY switches it off. Every world reads both schemes + // whatever this says. + specVersion: mintedSpecVersion(), ...storage, ...streamer, ...queue, diff --git a/packages/world-postgres/src/slots.ts b/packages/world-postgres/src/slots.ts new file mode 100644 index 0000000000..6a0366a636 --- /dev/null +++ b/packages/world-postgres/src/slots.ts @@ -0,0 +1,231 @@ +/** + * Slot identity for the postgres world. + * + * A slot-numbered run names its events by position: `evnt_…001` is the first + * event of the run, `evnt_…002` the second. Contention on a position is the + * point — it is what makes a concurrent write detectable rather than silent — + * so the two things this module has to get right are that a position is written + * at most once and that a position this allocator loses is retried rather than + * abandoned as a hole. + * + * The authority for both is the events table's primary key, `(run_id, id)`: the + * INSERT either lands or raises a unique violation, and a writer that loses the + * race is retried at a position that is still free rather than abandoning the + * one it lost. The probe below is only ever a hint about where to try next. + */ + +import { WorkflowWorldError } from '@workflow/errors'; +import { + FIRST_SLOT, + SLOT_RETRY_BUDGET_MS, + slotEventId, + slotFromId, + slotRetryDelay, +} from '@workflow/world'; +import { and, desc, eq } from 'drizzle-orm'; +import { type Drizzle, Schema } from './drizzle/index.js'; + +/** + * The slot a run's own `run_created` occupies. Nothing in a run precedes its + * creation, so this one position needs no allocation, and every other event of + * the run searches above it — including the event that happens to reach storage + * first, which on the start path is routinely `run_started`. + */ +export const RUN_CREATED_SLOT = FIRST_SLOT; + +/** Postgres unique-violation code. */ +const UNIQUE_VIOLATION = '23505'; + +/** + * Whether an error says the position a write aimed at is already occupied. + * + * Drizzle wraps the pg error, so the code can sit on the error or on its cause. + * Both the name drizzle generates for the composite key and the name postgres + * gives an inline `PRIMARY KEY` are accepted, so a database whose key predates + * the run-scoped migration still classifies correctly. + */ +export function isEventKeyViolation(error: unknown): boolean { + const pg = (error as { code?: string; constraint?: string }).code + ? (error as { code?: string; constraint?: string }) + : ((error as { cause?: { code?: string; constraint?: string } }).cause ?? + {}); + return ( + pg.code === UNIQUE_VIOLATION && + (pg.constraint === 'workflow_events_run_id_id_pk' || + pg.constraint === 'workflow_events_pkey') + ); +} + +/** + * The highest event id in a run's log, or undefined when the log is empty. + * + * One backwards scan of the `(run_id, id)` primary key. Ids are fixed-width + * within a scheme, so for a slot-numbered run the highest id names the highest + * written position — and because a log holds ids of exactly one scheme, that id + * also reports which scheme the run was created with. + */ +export async function highestEventId( + drizzle: Drizzle, + runId: string +): Promise { + const [row] = await drizzle + .select({ eventId: Schema.events.eventId }) + .from(Schema.events) + .where(eq(Schema.events.runId, runId)) + .orderBy(desc(Schema.events.eventId)) + .limit(1); + return row?.eventId; +} + +/** The position an id names, or 0 for an empty log or a ULID-numbered one. */ +export function highestSlotOf(eventId: string | undefined): number { + return eventId === undefined ? 0 : (slotFromId(eventId) ?? 0); +} + +/** Whether a run's log already holds `eventId`. */ +export async function eventExists( + drizzle: Drizzle, + runId: string, + eventId: string +): Promise { + const [row] = await drizzle + .select({ eventId: Schema.events.eventId }) + .from(Schema.events) + .where( + and(eq(Schema.events.runId, runId), eq(Schema.events.eventId, eventId)) + ) + .limit(1); + return row !== undefined; +} + +/** The event ids a single create publishes. */ +export interface EventIds { + /** + * The id of the event this create returns. Taken on demand: a ULID-numbered + * write mints it inside its transaction, once the row lock that orders it is + * held. + */ + primary: () => string; + /** + * An additional event written in the same breath — the synthetic + * `step_created` of a lazy step start. + * + * A claim names the *top* of the pair, so this event takes the position + * immediately below it: the caller reserved both and named one. Numbering it + * off the log instead would hand it a position another write of the same + * concurrent batch is already holding, and cost that write its claim. + */ + extra: () => Promise; +} + +export interface PlaceEventOptions { + /** + * Position the caller named, when it holds the log and claimed one. A claim + * asserts the log is complete up to that position, so losing it is a conflict + * the caller has to resolve rather than something to retry here. + */ + claimedSlot?: number; + /** Lowest position this write may take when allocating. */ + minSlot: number; + /** + * Result of a probe the caller has already made, used for the first attempt + * instead of probing again. Later rounds always re-probe: the log has + * demonstrably moved. + */ + seedHighestEventId?: string | undefined; + /** The conflict raised when a claimed position turns out to be taken. */ + onClaimTaken: () => Promise; + /** Performs the write with the ids it should publish under. */ + write: (ids: EventIds) => Promise; +} + +/** + * Writes an event of a slot-numbered run, at the position the caller claimed or + * at the next free one. + * + * Every round re-probes rather than incrementing a local counter: each round at + * least one writer wins, so re-probing guarantees progress under any amount of + * contention. `write` must leave nothing behind when it raises a unique + * violation — the callers here either write only the event row or wrap their + * materialization in the same transaction, so a lost round rolls back whole. + */ +export async function placeEvent( + drizzle: Drizzle, + runId: string, + options: PlaceEventOptions +): Promise { + const deadline = Date.now() + SLOT_RETRY_BUDGET_MS; + for (let round = 0; ; round++) { + let cursor: number | undefined; + /** + * Positions for this attempt, consecutive from one probe. Deferred so a + * claimed write with no extra event never probes at all. + */ + const take = async (): Promise => { + if (cursor === undefined) { + const highest = + round === 0 && options.seedHighestEventId !== undefined + ? options.seedHighestEventId + : await highestEventId(drizzle, runId); + cursor = Math.max( + highestSlotOf(highest) + 1, + options.minSlot, + // The claimed position is this write's own; an extra event must not + // be handed it. + (options.claimedSlot ?? 0) + 1 + ); + } + return cursor++; + }; + + const primary = + options.claimedSlot === undefined + ? slotEventId(await take()) + : slotEventId(options.claimedSlot); + /** Positions the caller named, which are the caller's to resolve. */ + const claimed = options.claimedSlot === undefined ? [] : [primary]; + try { + return await options.write({ + primary: () => primary, + extra: async () => { + if (options.claimedSlot === undefined) { + return slotEventId(await take()); + } + const slot = options.claimedSlot - 1; + if (slot <= FIRST_SLOT) { + // The run's own `run_created` holds the first slot, so a claim of + // the second leaves nowhere for a second event to go: the caller + // reserved one position for a write that publishes two. + throw new WorkflowWorldError( + `Event id "${primary}" leaves no slot below it in run "${runId}" for the second event published alongside it`, + { status: 400 } + ); + } + const id = slotEventId(slot); + claimed.push(id); + return id; + }, + }); + } catch (error) { + if (!isEventKeyViolation(error)) { + throw error; + } + // Only a position the caller named is the caller's problem; one this + // world allocated is reallocated below without ever surfacing. + for (const id of claimed) { + if (await eventExists(drizzle, runId, id)) { + throw await options.onClaimTaken(); + } + } + if (Date.now() >= deadline) { + throw new WorkflowWorldError( + `Could not place an event in run "${runId}" within ${SLOT_RETRY_BUDGET_MS}ms of contention`, + { status: 503 } + ); + } + await new Promise((resolve) => + setTimeout(resolve, slotRetryDelay(round)) + ); + } + } +} diff --git a/packages/world-postgres/src/storage.ts b/packages/world-postgres/src/storage.ts index 140597a6a9..9a13a17abb 100644 --- a/packages/world-postgres/src/storage.ts +++ b/packages/world-postgres/src/storage.ts @@ -3,12 +3,14 @@ import { HookNotFoundError, RunExpiredError, RunNotSupportedError, + SlotConflictError, TooEarlyError, WorkflowRunNotFoundError, WorkflowWorldError, } from '@workflow/errors'; import type { AttributeChange, + CreateEventParams, Event, EventResult, ExperimentalSetAttributesResult, @@ -35,15 +37,20 @@ import { isChildEntityCreationEventType, isHookEventRequiringExistence, isLegacySpecVersion, + isSlotId, isTerminalRunEventType, isTerminalStepStatus, isTerminalWorkflowRunStatus, requiresNewerWorld, SPEC_VERSION_CURRENT, + SPEC_VERSION_MAX_SUPPORTED, StepSchema, + slotEventId, + slotFromId, stripEventDataRefs, TERMINAL_STEP_STATUSES, TERMINAL_WORKFLOW_RUN_STATUSES, + usesSlotIdentity, validateAttributeChanges, validateUlidTimestamp, WorkflowRunSchema, @@ -62,6 +69,13 @@ import { import { monotonicFactory } from 'ulid'; import { type Drizzle, Schema } from './drizzle/index.js'; import type { SerializedContent } from './drizzle/schema.js'; +import { + type EventIds, + highestEventId, + highestSlotOf, + placeEvent, + RUN_CREATED_SLOT, +} from './slots.js'; import { compact } from './util.js'; /** @@ -442,7 +456,7 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { // hook row left behind by a process / database interruption between // the hook INSERT and the events INSERT below (see the recovery // logic in the hook_created branch). - const getHookCreatedEvent = drizzle + const getCorrelatedEvent = drizzle .select({ eventId: events.eventId }) .from(events) .where( @@ -453,7 +467,7 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { ) ) .limit(1) - .prepare('events_get_hook_created_for_run_correlation'); + .prepare('events_get_correlated_event'); const getWaitForValidation = drizzle .select({ @@ -464,6 +478,64 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { .limit(1) .prepare('events_get_wait_for_validation'); + /** + * The events a caller that just lost a slot is missing: one ascending page of + * the run's log after the cursor it wrote from, minus anything at or below the + * highest slot it already held. Because slots are dense, that second filter is + * exact — a caller cannot be missing an event whose position it can name. + * + * Returned inline with the conflict so the common case (a handful of events + * arrived out of band) costs the caller no extra round-trip. `hasMore` is + * forwarded verbatim: an overflowing delta is the caller's signal to page from + * `cursor` instead of treating this as the whole story. + */ + async function eventsAfterClaim( + runId: string, + params: CreateEventParams | undefined + ): Promise<{ events: Event[]; cursor: string | null; hasMore: boolean }> { + const limit = 100; + const all = await drizzle + .select() + .from(events) + .where( + and( + eq(events.runId, runId), + map(params?.sinceCursor, (c) => gt(events.eventId, c)) + ) + ) + .orderBy(events.eventId) + .limit(limit + 1); + const page = all.slice(0, limit); + const maxSlot = params?.maxSlot ?? 0; + const resolveData = params?.resolveData ?? 'all'; + return { + events: page + .filter((v) => (slotFromId(v.eventId) ?? 0) > maxSlot) + .map((v) => { + v.eventData ||= v.eventDataJson; + return stripEventDataRefs(EventSchema.parse(compact(v)), resolveData); + }), + cursor: page.at(-1)?.eventId ?? null, + hasMore: all.length > limit, + }; + } + + /** + * The 409 a caller gets when the slot it named turns out to belong to someone + * else, carrying the events it is missing so it can merge, replay and + * re-propose at a free position. + */ + async function slotConflict( + runId: string, + eventId: string, + params: CreateEventParams | undefined + ): Promise { + return new SlotConflictError( + `Slot ${slotFromId(eventId)} of run "${runId}" is already taken`, + { eventId, ...(await eventsAfterClaim(runId, params)) } + ); + } + return { async create(runId, data, params): Promise { let eventId: string | undefined; @@ -490,6 +562,20 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { // specVersion is always sent by the runtime, but we provide a fallback for safety const effectiveSpecVersion = data.specVersion ?? SPEC_VERSION_CURRENT; + // Whether this run numbers its events by slot. Decided from what was + // persisted, never from this request or this build, so a run stays in the + // mode it was created in for life — a run whose log holds ULID ids must + // never be handed a slot id, and vice versa. `run_created` is the one + // event that decides the mode instead of reading it; the resilient-start + // path below decides it too, on the request that creates the run. + let slotMode: boolean | undefined = + data.eventType === 'run_created' + ? usesSlotIdentity(effectiveSpecVersion) + : undefined; + // The run's highest event id, when it was read before the write. Seeds the + // allocator's first attempt so a probe is never made twice. + let seedHighestEventId: string | undefined; + // Track entity created/updated for EventResult let run: WorkflowRun | undefined; let step: Step | undefined; @@ -585,7 +671,13 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { .returning(); if (inserted) { - const runCreatedEventId = `wevt_${ulid()}`; + // We created the run, so this request also decided its mode. + slotMode = usesSlotIdentity(effectiveSpecVersion); + // A run's own `run_created` provably has nothing before it, so its + // slot needs no allocation. + const runCreatedEventId = slotMode + ? slotEventId(RUN_CREATED_SLOT) + : `wevt_${ulid()}`; await drizzle.insert(events).values({ runId: effectiveRunId, eventId: runCreatedEventId, @@ -631,7 +723,7 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { if (requiresNewerWorld(currentRun.specVersion)) { throw new RunNotSupportedError( currentRun.specVersion!, - SPEC_VERSION_CURRENT + SPEC_VERSION_MAX_SUPPORTED ); } @@ -651,6 +743,107 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { throw new WorkflowRunNotFoundError(effectiveRunId); } + // The run entity is the authority on the mode, and it can appear between + // the resilient-start insert above and this point: start() issues + // `run_created` and the queue send concurrently, so a delivery's + // `run_started` can arrive while the run is still being published. A stale + // "no" would number that one event with a ULID on an otherwise + // slot-numbered run, and a ULID names no position: the replay would read + // it wherever its timestamp happens to sort rather than where the writer + // meant it to go. + if (currentRun && data.eventType !== 'run_created') { + slotMode = usesSlotIdentity(currentRun.specVersion); + } + if (slotMode === undefined) { + // step_completed and step_retrying skip the run read above. The log's + // own highest id reports the scheme, since a log holds ids of exactly + // one, and it is the probe the allocator needs anyway — so a + // slot-numbered run pays nothing extra for this query. + seedHighestEventId = await highestEventId(drizzle, effectiveRunId); + slotMode = isSlotId(seedHighestEventId ?? ''); + } + + // ============================================================ + // EVENT ID: the caller's slot claim, an allocated slot, or a ULID + // ============================================================ + // A slot-numbered run's ids name positions in its log, so an id is either + // claimed by a caller that holds the log (and is therefore asserting the + // log is complete up to that position) or allocated at write time for a + // caller that has no log — a step completion reporting in, a cancellation + // from an API call. + let claimedSlot: number | undefined; + if (params?.eventId !== undefined) { + if (!slotMode) { + throw new WorkflowWorldError( + `Event id "${params.eventId}" was supplied for run "${effectiveRunId}", whose events are not numbered by slot`, + { status: 400 } + ); + } + claimedSlot = slotFromId(params.eventId); + if (claimedSlot === undefined) { + throw new WorkflowWorldError( + `Event id "${params.eventId}" is not a slot id, and run "${effectiveRunId}" numbers its events by slot`, + { status: 400 } + ); + } + eventId = params.eventId; + // A claim has to clear the log's tail, not merely be free. A position + // claimed by a write that then failed is never filled, so a log can + // carry holes below its tail; a caller numbering from a snapshot that + // predates the events above such a hole aims straight at it, and a + // free-position check would accept the write. The event then lands + // *below* events another replay has already consumed — the log stays + // internally consistent while its order silently changes, which is + // enough to flip a race between a step and a sleep from one replay to + // the next. + // + // Checked here, before the materialization below creates the step, hook + // or wait this event would now never accompany: a caller that + // re-proposes at the next position would otherwise collide with its own + // orphan and read that as "my write already landed". + seedHighestEventId = + seedHighestEventId ?? + (await highestEventId(drizzle, effectiveRunId)) ?? + undefined; + if (claimedSlot <= highestSlotOf(seedHighestEventId)) { + throw await slotConflict(effectiveRunId, eventId, params); + } + } + + /** + * Runs one of the event writes below under this run's id discipline: in + * slot mode it places the event at the position the caller claimed or at + * the next free one, retrying a position lost to a concurrent writer; + * otherwise it mints a ULID. + */ + const publish = async ( + write: (ids: EventIds) => Promise + ): Promise => + slotMode + ? placeEvent(drizzle, effectiveRunId, { + ...(claimedSlot !== undefined ? { claimedSlot } : {}), + // A run's own `run_created` owns the first slot — provably, since + // nothing precedes it — so every other event allocates above it, + // even when that event is the first to arrive here. + minSlot: + data.eventType === 'run_created' + ? RUN_CREATED_SLOT + : RUN_CREATED_SLOT + 1, + seedHighestEventId, + onClaimTaken: () => + slotConflict(effectiveRunId, eventId as string, params), + write: (ids) => { + // Each attempt publishes under its own id, and the result and + // error messages below read it back from here. + eventId = ids.primary(); + return write(ids); + }, + }) + : write({ + primary: getEventId, + extra: async () => `wevt_${ulid()}`, + }); + // Lazy step start: a step_started carrying step-creation data // (stepName + input) may arrive with no prior step_created — it creates // the step on the fly (see the materialization block below). This @@ -676,17 +869,19 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { .limit(1); // Create the event (still record it) - const [value] = await drizzle - .insert(Schema.events) - .values({ - runId: effectiveRunId, - eventId: getEventId(), - correlationId: data.correlationId, - eventType: data.eventType, - eventData: 'eventData' in data ? data.eventData : undefined, - specVersion: effectiveSpecVersion, - }) - .returning({ createdAt: Schema.events.createdAt }); + const [value] = await publish((ids) => + drizzle + .insert(Schema.events) + .values({ + runId: effectiveRunId, + eventId: ids.primary(), + correlationId: data.correlationId, + eventType: data.eventType, + eventData: 'eventData' in data ? data.eventData : undefined, + specVersion: effectiveSpecVersion, + }) + .returning({ createdAt: Schema.events.createdAt }) + ); const result = { ...data, @@ -1192,41 +1387,51 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { // event INSERT behind that lock prevents a late step_started from being // ordered after a concurrent terminal event that already won the row. if (data.eventType === 'step_started') { - value = await drizzle.transaction(async (tx) => { - // Lazy step start: no prior step_created exists, but this - // step_started carries the step-creation data. The step INSERT is - // the ownership claim: only the caller that inserts the row gets to - // run the step body inline. - if (lazyStepStart && !validatedStep) { - const lazyData = data.eventData; - const [inserted] = await tx - .insert(Schema.steps) - .values({ - runId: effectiveRunId, - stepId: data.correlationId, - stepName: lazyData.stepName, - input: lazyData.input as SerializedContent, - status: 'pending', - attempt: 0, - specVersion: effectiveSpecVersion, - }) - .onConflictDoNothing() - .returning({ stepId: Schema.steps.stepId }); - - if (!inserted) { - throw new EntityConflictError( - `Step "${data.correlationId}" already created` - ); - } + // The whole transaction is the retry unit here: a step_started that + // loses its slot has to roll the step row and the synthetic + // step_created back with it, or the next attempt would trip its own + // orphaned step and read that as "a concurrent handler won the create". + value = await publish((ids) => + drizzle.transaction(async (tx) => { + // Lazy step start: no prior step_created exists, but this + // step_started carries the step-creation data. The step INSERT is + // the ownership claim: only the caller that inserts the row gets to + // run the step body inline. + if (lazyStepStart && !validatedStep) { + const lazyData = data.eventData; + const [inserted] = await tx + .insert(Schema.steps) + .values({ + runId: effectiveRunId, + stepId: data.correlationId, + stepName: lazyData.stepName, + input: lazyData.input as SerializedContent, + status: 'pending', + attempt: 0, + specVersion: effectiveSpecVersion, + }) + .onConflictDoNothing() + .returning({ stepId: Schema.steps.stepId }); + + if (!inserted) { + throw new EntityConflictError( + `Step "${data.correlationId}" already created` + ); + } - // Replay still needs to observe step_created before - // step_started. Because this synthetic event is in the same - // transaction as the lazy step row and step_started event, we - // cannot leave behind only one side of that materialization. - const stepCreatedEventId = `wevt_${ulid()}`; - await tx - .insert(events) - .values({ + // Replay still needs to observe a step_created at all: the + // client's step consumer sets hasCreatedEvent only on that event + // type. Which of the pair sorts first does not matter — the + // step_started consumer is a no-op — but leaving behind only one + // side of the materialization would, hence the shared + // transaction. + // + // It takes a position of its own — the one below the claim on a + // claimed write, the next free one otherwise. Losing that position + // rolls the transaction back for a retry, so the insert must not + // swallow the collision. + const stepCreatedEventId = await ids.extra(); + const insertStepCreated = tx.insert(events).values({ runId: effectiveRunId, eventId: stepCreatedEventId, correlationId: data.correlationId, @@ -1236,99 +1441,104 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { input: lazyData.input, }, specVersion: effectiveSpecVersion, - }) - .onConflictDoNothing(); - stepCreatedLazily = true; - } - - // Retried steps may be scheduled for later. Keep this check inside - // the transaction so the step_started write cannot slip past it. - if ( - validatedStep?.retryAfter && - validatedStep.retryAfter.getTime() > Date.now() - ) { - throw new TooEarlyError( - `Cannot start step "${data.correlationId}": retryAfter timestamp has not been reached yet`, - { - retryAfter: Math.ceil( - (validatedStep.retryAfter.getTime() - Date.now()) / 1000 - ), - } - ); - } + }); + await (slotMode + ? insertStepCreated + : insertStepCreated.onConflictDoNothing()); + stepCreatedLazily = true; + } - // The terminal-state guard is part of the UPDATE, not just the - // earlier validation read. That closes the race where another - // writer completes/fails the step between validation and start. - const [stepValue] = await tx - .update(Schema.steps) - .set({ - status: 'running', - attempt: sql`${Schema.steps.attempt} + 1`, - // Preserve the original first-start timestamp across retries or - // overlapping starts. - startedAt: sql`COALESCE(${Schema.steps.startedAt}, ${now.toISOString()})`, - retryAfter: null, - }) - .where( - and( - eq(Schema.steps.runId, effectiveRunId), - eq(Schema.steps.stepId, data.correlationId!), - notInArray(Schema.steps.status, terminalStepStatuses) - ) - ) - .returning(); + // Retried steps may be scheduled for later. Keep this check inside + // the transaction so the step_started write cannot slip past it. + if ( + validatedStep?.retryAfter && + validatedStep.retryAfter.getTime() > Date.now() + ) { + throw new TooEarlyError( + `Cannot start step "${data.correlationId}": retryAfter timestamp has not been reached yet`, + { + retryAfter: Math.ceil( + (validatedStep.retryAfter.getTime() - Date.now()) / 1000 + ), + } + ); + } - if (stepValue) { - step = deserializeStepError(compact(stepValue)); - } else { - const [existing] = await tx - .select({ status: Schema.steps.status }) - .from(Schema.steps) + // The terminal-state guard is part of the UPDATE, not just the + // earlier validation read. That closes the race where another + // writer completes/fails the step between validation and start. + const [stepValue] = await tx + .update(Schema.steps) + .set({ + status: 'running', + attempt: sql`${Schema.steps.attempt} + 1`, + // Preserve the original first-start timestamp across retries or + // overlapping starts. + startedAt: sql`COALESCE(${Schema.steps.startedAt}, ${now.toISOString()})`, + retryAfter: null, + }) .where( and( eq(Schema.steps.runId, effectiveRunId), - eq(Schema.steps.stepId, data.correlationId!) + eq(Schema.steps.stepId, data.correlationId!), + notInArray(Schema.steps.status, terminalStepStatuses) ) ) - .limit(1); - if (!existing) { - throw new WorkflowWorldError( - `Step "${data.correlationId}" not found` - ); + .returning(); + + if (stepValue) { + step = deserializeStepError(compact(stepValue)); + } else { + const [existing] = await tx + .select({ status: Schema.steps.status }) + .from(Schema.steps) + .where( + and( + eq(Schema.steps.runId, effectiveRunId), + eq(Schema.steps.stepId, data.correlationId!) + ) + ) + .limit(1); + if (!existing) { + throw new WorkflowWorldError( + `Step "${data.correlationId}" not found` + ); + } + if (isTerminalStepStatus(existing.status)) { + throw new EntityConflictError( + `Cannot modify step in terminal state "${existing.status}"` + ); + } } - if (isTerminalStepStatus(existing.status)) { + + // A ULID-numbered step_started takes its id only after the guarded + // step UPDATE has acquired and passed the row lock. Without a + // sequence, this is the local ordering guarantee we can provide: a + // writer blocked on the step row will not carry an older event id + // into a later insert. A slot id is exempt — it names a position in + // the log, not a time — and the caller may have claimed it already. + const stepStartedEventId = ids.primary(); + eventId = stepStartedEventId; + const [eventValue] = await tx + .insert(events) + .values({ + runId: effectiveRunId, + eventId: stepStartedEventId, + correlationId: data.correlationId, + eventType: data.eventType, + eventData: storedEventData, + specVersion: effectiveSpecVersion, + }) + .returning({ createdAt: events.createdAt }); + + if (!eventValue) { throw new EntityConflictError( - `Cannot modify step in terminal state "${existing.status}"` + `Event ${stepStartedEventId} could not be created` ); } - } - - // Allocate the step_started ULID only after the guarded step UPDATE - // has acquired and passed the row lock. Without a sequence, this is - // the local ordering guarantee we can provide: a writer blocked on - // the step row will not carry an older event id into a later insert. - const stepStartedEventId = `wevt_${ulid()}`; - eventId = stepStartedEventId; - const [eventValue] = await tx - .insert(events) - .values({ - runId: effectiveRunId, - eventId: stepStartedEventId, - correlationId: data.correlationId, - eventType: data.eventType, - eventData: storedEventData, - specVersion: effectiveSpecVersion, - }) - .returning({ createdAt: events.createdAt }); - - if (!eventValue) { - throw new EntityConflictError( - `Event ${stepStartedEventId} could not be created` - ); - } - return eventValue; - }); + return eventValue; + }) + ); } // Handle step_completed event: update step status @@ -1496,7 +1706,7 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { existingHook.runId === effectiveRunId && existingHook.hookId === data.correlationId ) { - const [existingEvent] = await getHookCreatedEvent.execute({ + const [existingEvent] = await getCorrelatedEvent.execute({ runId: effectiveRunId, correlationId: data.correlationId, eventType: 'hook_created', @@ -1531,20 +1741,21 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { token: eventData.token, conflictingRunId: existingHook.runId, }; + const [conflictValue] = await publish((ids) => + drizzle + .insert(events) + .values({ + runId: effectiveRunId, + eventId: ids.primary(), + correlationId: data.correlationId, + eventType: 'hook_conflict', + eventData: conflictEventData, + specVersion: effectiveSpecVersion, + }) + .returning({ createdAt: events.createdAt }) + ); const conflictEventId = getEventId(); - const [conflictValue] = await drizzle - .insert(events) - .values({ - runId: effectiveRunId, - eventId: conflictEventId, - correlationId: data.correlationId, - eventType: 'hook_conflict', - eventData: conflictEventData, - specVersion: effectiveSpecVersion, - }) - .returning({ createdAt: events.createdAt }); - if (!conflictValue) { throw new EntityConflictError( `Event ${conflictEventId} could not be created` @@ -1622,47 +1833,49 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { // guarded UPDATE linearizes against a concurrent terminal step // event. if (data.eventType === 'hook_received') { - value = await drizzle.transaction(async (tx) => { - const [runRow] = await tx - .select({ status: Schema.runs.status }) - .from(Schema.runs) - .where(eq(Schema.runs.runId, effectiveRunId)) - .for('update') - .limit(1); - if (!runRow) { - throw new WorkflowRunNotFoundError(effectiveRunId); - } - if (isTerminalWorkflowRunStatus(runRow.status)) { - throw new RunExpiredError( - `Workflow run "${effectiveRunId}" is already in terminal state "${runRow.status}"` - ); - } + value = await publish((ids) => + drizzle.transaction(async (tx) => { + const [runRow] = await tx + .select({ status: Schema.runs.status }) + .from(Schema.runs) + .where(eq(Schema.runs.runId, effectiveRunId)) + .for('update') + .limit(1); + if (!runRow) { + throw new WorkflowRunNotFoundError(effectiveRunId); + } + if (isTerminalWorkflowRunStatus(runRow.status)) { + throw new RunExpiredError( + `Workflow run "${effectiveRunId}" is already in terminal state "${runRow.status}"` + ); + } - // Allocate the ULID only after the row lock is acquired, - // matching step_started's ordering guarantee: a writer blocked - // on the run row must not carry an older event id into a later - // insert. - const hookReceivedEventId = `wevt_${ulid()}`; - eventId = hookReceivedEventId; - const [eventValue] = await tx - .insert(events) - .values({ - runId: effectiveRunId, - eventId: hookReceivedEventId, - correlationId: data.correlationId, - eventType: data.eventType, - eventData: storedEventData, - specVersion: effectiveSpecVersion, - }) - .returning({ createdAt: events.createdAt }); + // Take the ULID only after the row lock is acquired, matching + // step_started's ordering guarantee: a writer blocked on the run + // row must not carry an older event id into a later insert. A slot + // id names a position rather than a time, so it is exempt. + const hookReceivedEventId = ids.primary(); + eventId = hookReceivedEventId; + const [eventValue] = await tx + .insert(events) + .values({ + runId: effectiveRunId, + eventId: hookReceivedEventId, + correlationId: data.correlationId, + eventType: data.eventType, + eventData: storedEventData, + specVersion: effectiveSpecVersion, + }) + .returning({ createdAt: events.createdAt }); - if (!eventValue) { - throw new EntityConflictError( - `Event ${hookReceivedEventId} could not be created` - ); - } - return eventValue; - }); + if (!eventValue) { + throw new EntityConflictError( + `Event ${hookReceivedEventId} could not be created` + ); + } + return eventValue; + }) + ); } // Handle wait_created event: create wait entity @@ -1694,9 +1907,43 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { specVersion: waitValue.specVersion ?? undefined, }; } else { - throw new EntityConflictError( - `Wait "${data.correlationId}" already exists` - ); + // The wait row exists but this call did not write it. Which of the two + // reasons it is decides everything, and only the event log knows: + // - the `wait_created` event exists → a real duplicate, so throw and + // let the runtime's concurrent-replay catch path swallow it. + // - it does not → an orphaned row from an attempt that materialized + // the wait and then lost its event write (a crash, or a slot + // claimed by someone else). The caller re-proposing the same + // operation one position higher is exactly what has to succeed + // here, so adopt the row and complete the partial write. Mirrors + // hook_created's handling of the same window. + const [existingEvent] = await getCorrelatedEvent.execute({ + runId: effectiveRunId, + correlationId: data.correlationId, + eventType: 'wait_created', + }); + if (existingEvent) { + throw new EntityConflictError( + `Wait "${data.correlationId}" already exists` + ); + } + const [orphan] = await drizzle + .select() + .from(Schema.waits) + .where(eq(Schema.waits.waitId, waitId)) + .limit(1); + if (orphan) { + wait = { + waitId: orphan.waitId, + runId: orphan.runId, + status: orphan.status, + resumeAt: orphan.resumeAt ?? undefined, + completedAt: orphan.completedAt ?? undefined, + createdAt: orphan.createdAt, + updatedAt: orphan.updatedAt, + specVersion: orphan.specVersion ?? undefined, + }; + } } } @@ -1748,17 +1995,23 @@ export function createEventsStorage(drizzle: Drizzle): Storage['events'] { try { if (!value) { - [value] = await drizzle - .insert(events) - .values({ - runId: effectiveRunId, - eventId: getEventId(), - correlationId: data.correlationId, - eventType: data.eventType, - eventData: storedEventData, - specVersion: effectiveSpecVersion, - }) - .returning({ createdAt: events.createdAt }); + // Only the event row is retried here: the entity this event describes + // was materialized above, outside any transaction, and re-inserting + // the event at a higher position leaves the log dense and still + // consistent with that entity. + [value] = await publish((ids) => + drizzle + .insert(events) + .values({ + runId: effectiveRunId, + eventId: ids.primary(), + correlationId: data.correlationId, + eventType: data.eventType, + eventData: storedEventData, + specVersion: effectiveSpecVersion, + }) + .returning({ createdAt: events.createdAt }) + ); } } catch (err) { // Translate unique-violation on the correlated-event partial index diff --git a/packages/world-postgres/test/slot-identity.test.ts b/packages/world-postgres/test/slot-identity.test.ts new file mode 100644 index 0000000000..a6cf498651 --- /dev/null +++ b/packages/world-postgres/test/slot-identity.test.ts @@ -0,0 +1,426 @@ +import { execSync } from 'node:child_process'; +import { PostgreSqlContainer } from '@testcontainers/postgresql'; +import { SlotConflictError } from '@workflow/errors'; +import { + FIRST_SLOT, + maxSlotOf, + SPEC_VERSION_CURRENT, + SPEC_VERSION_SLOT_IDENTITY, + slotEventId, + slotFromId, +} from '@workflow/world'; +import { Pool } from 'pg'; +import { + afterAll, + beforeAll, + beforeEach, + describe, + expect, + test, +} from 'vitest'; +import { createClient } from '../src/drizzle/index.js'; +import { createEventsStorage } from '../src/storage.js'; + +describe('Slot identity (Postgres integration)', () => { + if (process.platform === 'win32') { + test.skip('skipped on Windows since it relies on a docker container', () => {}); + return; + } + + let container: Awaited>; + let pool: Pool; + let events: ReturnType; + + beforeAll(async () => { + container = await new PostgreSqlContainer('postgres:15-alpine').start(); + const dbUrl = container.getConnectionUri(); + process.env.DATABASE_URL = dbUrl; + process.env.WORKFLOW_POSTGRES_URL = dbUrl; + execSync('pnpm db:push', { + stdio: 'inherit', + cwd: process.cwd(), + env: process.env, + }); + // Contention is the point of these tests, so the pool has to be able to + // hold every writer of a burst at once. + pool = new Pool({ connectionString: dbUrl, max: 20 }); + events = createEventsStorage(createClient(pool)); + }, 120_000); + + beforeEach(async () => { + await pool.query( + 'TRUNCATE TABLE workflow.workflow_events, workflow.workflow_steps, workflow.workflow_hooks, workflow.workflow_runs RESTART IDENTITY CASCADE' + ); + }); + + afterAll(async () => { + await pool.end(); + await container.stop(); + }); + + /** Start a run whose events are numbered by slot, and return its id. */ + async function newSlotRun(): Promise { + const result = await events.create(null, { + eventType: 'run_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + eventData: { + deploymentId: 'dpl_test', + workflowName: 'test-workflow', + input: new Uint8Array(), + }, + }); + if (!result.run) { + throw new Error('Expected run to be created'); + } + return result.run.runId; + } + + function eventsOf(runId: string) { + // The page size is explicit: the default would silently truncate a fan-out + // and make a dense log look sparse. + return events.list({ runId, pagination: { limit: 500 } }); + } + + /** The slots of the run's log, in list order. */ + async function slotsOf(runId: string): Promise { + const { data } = await eventsOf(runId); + return data.map((event) => slotFromId(event.eventId) ?? -1); + } + + function ascending(slots: number[]): number[] { + return [...slots].sort((a, b) => a - b); + } + + function denseFrom(count: number): number[] { + return Array.from({ length: count }, (_, index) => FIRST_SLOT + index); + } + + async function createStep( + runId: string, + stepId: string, + eventId?: string + ): Promise { + const result = await events.create( + runId, + { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: stepId, + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + eventId === undefined ? undefined : { eventId } + ); + if (!result.event) { + throw new Error('Expected an event'); + } + return result.event.eventId; + } + + describe('numbering', () => { + test('puts run_created in the first slot', async () => { + const runId = await newSlotRun(); + await expect(slotsOf(runId)).resolves.toEqual([FIRST_SLOT]); + }); + + test('allocates dense slots for writers that hold no log', async () => { + // A step completion reporting in, a cancellation from an API call: the + // caller has no event log, so the world numbers the event for it. + const runId = await newSlotRun(); + await createStep(runId, 'step_a'); + await createStep(runId, 'step_b'); + await expect(slotsOf(runId)).resolves.toEqual(denseFrom(3)); + }); + + test('honours a slot the caller claims', async () => { + const runId = await newSlotRun(); + const eventId = await createStep(runId, 'step_a', slotEventId(2)); + expect(eventId).toBe(slotEventId(2)); + await expect(slotsOf(runId)).resolves.toEqual(denseFrom(2)); + }); + + test('numbers a ULID-mode run the way it always did', async () => { + const created = await events.create(null, { + eventType: 'run_created', + specVersion: SPEC_VERSION_CURRENT, + eventData: { + deploymentId: 'dpl_test', + workflowName: 'test-workflow', + input: new Uint8Array(), + }, + }); + const runId = created.run?.runId as string; + const eventId = await createStep(runId, 'step_a'); + expect(eventId).toMatch(/^wevt_/); + expect(slotFromId(eventId)).toBeUndefined(); + }); + + test('gives a lazy step start two consecutive slots', async () => { + // One request, two events: the step_started the caller sent and the + // step_created it deferred. Which sorts first does not matter — only + // step_created flips the client's hasCreatedEvent — but both have to + // land, and neither may leave a hole. + const runId = await newSlotRun(); + const started = await events.create(runId, { + eventType: 'step_started', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }); + expect(slotFromId(started.event?.eventId ?? '')).toBe(2); + const { data } = await eventsOf(runId); + expect( + data.map((event) => `${slotFromId(event.eventId)} ${event.eventType}`) + ).toEqual(['1 run_created', '2 step_started', '3 step_created']); + }); + + test('numbers the deferred step_created below a claimed slot', async () => { + // A claim names the top of the pair: the caller reserved both positions + // before either landed, which is what keeps the second event off the slot + // the next write of the same batch claimed. + const runId = await newSlotRun(); + const started = await events.create( + runId, + { + eventType: 'step_started', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + { eventId: slotEventId(3) } + ); + expect(started.event?.eventId).toBe(slotEventId(3)); + const { data } = await eventsOf(runId); + expect( + data.map((event) => `${slotFromId(event.eventId)} ${event.eventType}`) + ).toEqual(['1 run_created', '2 step_created', '3 step_started']); + }); + + test('keeps every claim in a burst of lazy starts', async () => { + // The suspension flush issues its lazy starts at once, each having + // reserved two positions. A second event numbered off the log as this + // world sees it would take the slot the next start in the batch claimed, + // costing every start after the first its claim. + const runId = await newSlotRun(); + const claims = Array.from({ length: 10 }, (_, index) => + slotEventId(FIRST_SLOT + 2 * (index + 1)) + ); + const started = await Promise.all( + claims.map((eventId, index) => + events.create( + runId, + { + eventType: 'step_started', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: `step_${index}`, + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + { eventId } + ) + ) + ); + expect(started.map((result) => result.event?.eventId)).toEqual(claims); + expect(ascending(await slotsOf(runId))).toEqual( + denseFrom(2 * claims.length + 1) + ); + }); + + test('rejects a claim that leaves no room for the second event', async () => { + // The run's own run_created holds the first slot, so a claim of the second + // means the caller reserved one position for a write that publishes two. + const runId = await newSlotRun(); + await expect( + events.create( + runId, + { + eventType: 'step_started', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + { eventId: slotEventId(FIRST_SLOT + 1) } + ) + ).rejects.toThrow(/leaves no slot below it/); + }); + + test('numbers events of runs it never created', async () => { + // `step_completed` and `step_retrying` deliberately skip the run read, so + // the mode comes from the log rather than from a run row in hand. + const runId = await newSlotRun(); + await createStep(runId, 'step_a'); + const completed = await events.create(runId, { + eventType: 'step_completed', + specVersion: SPEC_VERSION_CURRENT, + correlationId: 'step_a', + eventData: { output: new Uint8Array() }, + }); + expect(slotFromId(completed.event?.eventId ?? '')).toBe(3); + }); + }); + + describe('contention', () => { + // The primary key is the authority, and a writer that loses a position is + // retried at one that is still free rather than abandoning the one it lost, + // so a burst of concurrent writers still numbers itself densely. + for (const writers of [2, 8, 50]) { + test(`keeps ${writers} concurrent writers dense`, async () => { + const runId = await newSlotRun(); + const ids = await Promise.all( + Array.from({ length: writers }, (_, index) => + createStep(runId, `step_${index}`) + ) + ); + expect(new Set(ids).size).toBe(writers); + expect(ascending(await slotsOf(runId))).toEqual(denseFrom(writers + 1)); + }, 60_000); + } + + test('numbers a burst so the highest slot is the event count', async () => { + const runId = await newSlotRun(); + await Promise.all( + Array.from({ length: 5 }, (_, index) => + createStep(runId, `step_${index}`) + ) + ); + const { data } = await eventsOf(runId); + expect(maxSlotOf(data)).toBe(data.length); + }); + + test('leaves no hole behind a rejected write', async () => { + // The rejected op's slot sits below its concurrent sibling's, and a hole + // below a published event can never be filled. + const runId = await newSlotRun(); + const [rejected, accepted] = await Promise.allSettled([ + events.create(runId, { + eventType: 'step_completed', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_never_created', + eventData: { output: new Uint8Array() }, + }), + createStep(runId, 'step_a'), + ]); + expect(rejected.status).toBe('rejected'); + expect(accepted.status).toBe('fulfilled'); + await createStep(runId, 'step_b'); + expect(ascending(await slotsOf(runId))).toEqual(denseFrom(3)); + }); + }); + + describe('mode is pinned to the run', () => { + test('rejects a slot id claimed on a ULID-numbered run', async () => { + const created = await events.create(null, { + eventType: 'run_created', + specVersion: SPEC_VERSION_CURRENT, + eventData: { + deploymentId: 'dpl_test', + workflowName: 'test-workflow', + input: new Uint8Array(), + }, + }); + const runId = created.run?.runId as string; + await expect(createStep(runId, 'step_a', slotEventId(2))).rejects.toThrow( + /not numbered by slot/ + ); + }); + + test('rejects a ULID id claimed on a slot-numbered run', async () => { + const runId = await newSlotRun(); + await expect( + createStep(runId, 'step_a', 'evnt_01K5Z0000000000000000000AA') + ).rejects.toThrow(/not a slot id/); + }); + + test('ignores the spec version of later requests', async () => { + // A run is in exactly one mode for life; only what was persisted decides. + const runId = await newSlotRun(); + const result = await events.create(runId, { + eventType: 'step_created', + specVersion: SPEC_VERSION_CURRENT, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }); + expect(slotFromId(result.event?.eventId ?? '')).toBe(2); + }); + }); + + describe('conflict', () => { + test('reports the events the loser is missing', async () => { + const runId = await newSlotRun(); + // Out of band: something else takes the slot this caller was about to + // claim, so the caller's log is provably missing an event. + await createStep(runId, 'step_out_of_band'); + + const conflict = await events + .create( + runId, + { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + { eventId: slotEventId(2), maxSlot: 1 } + ) + .catch((error: unknown) => error); + + expect(SlotConflictError.is(conflict)).toBe(true); + const slotConflict = conflict as SlotConflictError; + expect(slotConflict.status).toBe(409); + expect(slotConflict.eventId).toBe(slotEventId(2)); + expect(slotConflict.events?.map((event) => event.eventId)).toEqual([ + slotEventId(2), + ]); + }); + + test('excludes events the loser already holds from the delta', async () => { + const runId = await newSlotRun(); + await createStep(runId, 'step_one'); + await createStep(runId, 'step_two'); + + const conflict = await events + .create( + runId, + { + eventType: 'step_created', + specVersion: SPEC_VERSION_SLOT_IDENTITY, + correlationId: 'step_a', + eventData: { stepName: 'a-step', input: new Uint8Array() }, + }, + { eventId: slotEventId(2), maxSlot: 2 } + ) + .catch((error: unknown) => error); + + // Slots 1 and 2 are at or below what the caller had; only 3 is news. + expect( + (conflict as SlotConflictError).events?.map((event) => event.eventId) + ).toEqual([slotEventId(3)]); + }); + + test('lets the loser re-propose at the next free slot', async () => { + const runId = await newSlotRun(); + await createStep(runId, 'step_out_of_band'); + await expect(createStep(runId, 'step_a', slotEventId(2))).rejects.toThrow( + SlotConflictError + ); + // Merging the delta moves the caller's own numbering forward by one. + const eventId = await createStep(runId, 'step_a', slotEventId(3)); + expect(eventId).toBe(slotEventId(3)); + await expect(slotsOf(runId)).resolves.toEqual(denseFrom(3)); + }); + + test('materializes nothing for a claim that is already taken', async () => { + // The re-post is what the guard protects: a step row left behind by the + // losing attempt would make the retry trip its own orphan and read that + // as "a concurrent handler won the create". + const runId = await newSlotRun(); + await createStep(runId, 'step_out_of_band'); + await expect(createStep(runId, 'step_a', slotEventId(2))).rejects.toThrow( + SlotConflictError + ); + const { rows } = await pool.query( + 'SELECT step_id FROM workflow.workflow_steps WHERE run_id = $1', + [runId] + ); + expect(rows.map((row) => row.step_id)).toEqual(['step_out_of_band']); + }); + }); +}); diff --git a/packages/world-vercel/src/events-v4.test.ts b/packages/world-vercel/src/events-v4.test.ts index b0cbb1e8b0..f788468974 100644 --- a/packages/world-vercel/src/events-v4.test.ts +++ b/packages/world-vercel/src/events-v4.test.ts @@ -1068,7 +1068,7 @@ describe('createWorkflowRunEventV4 over HTTP', () => { // A slot-numbered run names its own event ids, so the id has to reach the // wire: the backend reads it from the frame meta and inserts it // conditionally. Dropped, the backend mints a ULID instead and the run - // silently loses the density its completeness check depends on. + // silently reverts to server-assigned identity mid-log. const origin = WORKFLOW_SERVER_URL_OVERRIDE || 'https://vercel-workflow.com'; const agent = new MockAgent(); diff --git a/packages/world-vercel/src/index.ts b/packages/world-vercel/src/index.ts index 1f3fab9df3..887e0c2622 100644 --- a/packages/world-vercel/src/index.ts +++ b/packages/world-vercel/src/index.ts @@ -1,5 +1,5 @@ import type { World } from '@workflow/world'; -import { SPEC_VERSION_SUPPORTS_COMPRESSION } from '@workflow/world'; +import { mintedSpecVersion } from '@workflow/world'; import { createAnalytics } from './analytics.js'; import { createRunId, describeRun } from './create-run-id.js'; import { createGetEncryptionKeyForRun } from './encryption.js'; @@ -29,9 +29,12 @@ export function createWorld(config?: APIConfig): World { config?.projectConfig?.projectId || process.env.VERCEL_PROJECT_ID; return { - // Spec v5 adds client-side zstd/gzip payload compression. The server stores - // those payloads opaquely, and v5 remains a superset of v4 attributes. - specVersion: SPEC_VERSION_SUPPORTS_COMPRESSION, + // What this world stamps on new runs: slot identity (spec v6) unless + // WORKFLOW_SLOT_IDENTITY switches it off, in which case v5 — client-side + // zstd/gzip payload compression over a superset of the v4 attributes. + // Either way this world reads both, so the stamp only decides how the runs + // it creates from here on are numbered. + specVersion: mintedSpecVersion(), capabilities: { // workflow-server enforces the `stateUpdatedAt` optimistic-concurrency // guard: creations carrying a stale snapshot are rejected with 412 diff --git a/packages/world/src/events.ts b/packages/world/src/events.ts index 5eb628774a..b23ffaa03e 100644 --- a/packages/world/src/events.ts +++ b/packages/world/src/events.ts @@ -864,10 +864,10 @@ export interface CreateEventParams { * taken, reject the write with `SlotConflictError` (HTTP 409) instead of * minting a different id — a lost slot means the client replayed against an * event log missing at least one event, so its whole proposed event, not just - * its id, is suspect. Reject a mismatch in either direction with a 400: an id - * of this shape on a run that does not use slot identity, or an absent or - * ULID-shaped id on a run that does, would leave the log unable to prove its - * own completeness. + * its id, is suspect. Reject a mismatch in either direction with a 400: a + * ULID names a time and a slot names a position, so a log holding both sorts + * partly by one and partly by the other and no replay can read it in the order + * it was written. * * A World that ignores this field keeps minting ids itself, which is correct * only for runs that were never stamped with slot identity in the first diff --git a/packages/world/src/index.ts b/packages/world/src/index.ts index 7317b340ba..1ecae0457d 100644 --- a/packages/world/src/index.ts +++ b/packages/world/src/index.ts @@ -106,16 +106,23 @@ export { isSlotId, maxSlotOf, SLOT_ID_WIDTH, + SLOT_RETRY_BASE_MS, + SLOT_RETRY_BUDGET_MS, + SLOT_RETRY_MAX_DELAY_MS, slotEventId, slotFromId, slotIdBody, + slotRetryDelay, } from './slot-identity.js'; export type { SpecVersion } from './spec-version.js'; export { isLegacySpecVersion, + mintedSpecVersion, requiresNewerWorld, + SLOT_IDENTITY_ENV_VAR, SPEC_VERSION_CURRENT, SPEC_VERSION_LEGACY, + SPEC_VERSION_MAX_SUPPORTED, SPEC_VERSION_SLOT_IDENTITY, SPEC_VERSION_SUPPORTS_ATTRIBUTES, SPEC_VERSION_SUPPORTS_CBOR_QUEUE_TRANSPORT, diff --git a/packages/world/src/slot-identity.test.ts b/packages/world/src/slot-identity.test.ts index c99d2aa930..acdfada627 100644 --- a/packages/world/src/slot-identity.test.ts +++ b/packages/world/src/slot-identity.test.ts @@ -1,5 +1,6 @@ import { ulid } from 'ulid'; import { describe, expect, it } from 'vitest'; +import { z } from 'zod'; import { FIRST_SLOT, isSlotId, @@ -17,9 +18,9 @@ describe('slotIdBody', () => { expect(body).toHaveLength(SLOT_ID_WIDTH); expect(`evnt_${body}`).toHaveLength(`evnt_${ulid()}`.length); // Crockford base32 starts with the decimal digits, so the padded body - // parses as a ULID — this is what keeps every existing schema, sort key and - // range fence working unchanged. - expect(ulidToDate(body)).not.toBeNull(); + // satisfies the ULID syntax — this is what keeps every existing schema, + // sort key and range fence working unchanged. + expect(z.string().ulid().safeParse(body).success).toBe(true); }); it('orders lexicographically by slot at a fixed width', () => { @@ -60,6 +61,24 @@ describe('slotFromId', () => { }); }); +describe('a slot carries no timestamp', () => { + it('reports no time rather than epoch 0', () => { + // Passing the ULID syntax check is what makes a slot portable; decoding a + // *time* out of one is always a bug. Two that this guards: the sandbox + // clock is set from the events it consumes, so epoch 0 would rewind a + // replaying workflow's `Date.now()` to 1970; and world-local prefilters + // cursor pagination on the time in the filename, so epoch 0 would hide + // every slot-numbered event from an ascending page. + expect(ulidToDate(slotIdBody(FIRST_SLOT))).toBeNull(); + expect(ulidToDate(slotEventId(FIRST_SLOT))).toBeNull(); + expect(ulidToDate(slotIdBody(123_456))).toBeNull(); + }); + + it('still reads the time out of a ULID', () => { + expect(ulidToDate(ulid())?.getTime()).toBeGreaterThan(0); + }); +}); + describe('maxSlotOf', () => { it('finds the highest slot regardless of position', () => { // A log is merged from several loads and is not sorted, so the last element diff --git a/packages/world/src/slot-identity.ts b/packages/world/src/slot-identity.ts index d9ff11b65f..f5cfa50367 100644 --- a/packages/world/src/slot-identity.ts +++ b/packages/world/src/slot-identity.ts @@ -7,11 +7,21 @@ * cursor that accepted a ULID keeps accepting a slot — and because the width is * fixed, lexicographic order is numeric order. * - * Slots are dense and start at 1. Density is the whole point of the scheme: it - * makes `events.length === maxSlot` a proof that a loaded log has no holes, - * which is something a server-minted ULID log can never offer. Zero is left - * unused because the inclusive lower fence for range queries over a run's - * events is the all-zero id. + * Slots start at 1 and are handed out above every position the allocator has + * seen, never into a lower one that happens to be free. That makes contention + * explicit — two writers proposing one position cannot both win, and the loser + * is told which events it was missing — and it keeps slot order, which is the + * order a replay reads the log in, a linear extension of what actually + * happened. Filling a hole would place an event below ones that preceded it, + * and a replay reaching a `step_completed` below its own `step_started` diverges + * for good. Zero is left unused because the inclusive lower fence for + * range queries over a run's events is the all-zero id. + * + * Allocation being append-only does not make a published log gap-free, so + * `events.length === maxSlot` is not a completeness proof. A slot claimed by an + * operation that then fails for a reason of its own is never filled, and if a + * later slot has already been published the gap is permanent. Nothing may treat + * a missing slot as an event still on its way. * * A slot body decodes as a ULID *timestamp* of epoch 0 without erroring, so * nothing may read a time out of one. Use the event's own `createdAt` / @@ -67,6 +77,31 @@ export function slotEventId(slot: number): string { return `evnt_${slotIdBody(slot)}`; } +/** First backoff after losing a position; doubled each round. */ +export const SLOT_RETRY_BASE_MS = 5; + +/** Ceiling for a single backoff, so a contended run keeps making attempts. */ +export const SLOT_RETRY_MAX_DELAY_MS = 250; + +/** + * How long a writer that allocates its own position keeps looking for a free + * one before giving up. Exhausting it is a retryable failure for the caller — + * in practice a queue delivery — rather than something the run stalls on. + */ +export const SLOT_RETRY_BUDGET_MS = 30_000; + +/** + * Full jitter over an exponentially growing, capped window. Shared by every + * world that allocates positions, so contention behaves the same wherever a run + * is stored. + */ +export function slotRetryDelay(round: number): number { + return ( + Math.random() * + Math.min(SLOT_RETRY_BASE_MS * 2 ** round, SLOT_RETRY_MAX_DELAY_MS) + ); +} + /** * The highest slot named by any of `events`, or 0 when none is slot-numbered. * diff --git a/packages/world/src/spec-version.test.ts b/packages/world/src/spec-version.test.ts index 880c43180d..0125e2fb1c 100644 --- a/packages/world/src/spec-version.test.ts +++ b/packages/world/src/spec-version.test.ts @@ -1,9 +1,13 @@ import { describe, expect, it } from 'vitest'; import { isLegacySpecVersion, + mintedSpecVersion, requiresNewerWorld, + SLOT_IDENTITY_ENV_VAR, SPEC_VERSION_CURRENT, SPEC_VERSION_LEGACY, + SPEC_VERSION_MAX_SUPPORTED, + SPEC_VERSION_SLOT_IDENTITY, SPEC_VERSION_SUPPORTS_ATTRIBUTES, SPEC_VERSION_SUPPORTS_COMPRESSION, } from './spec-version.js'; @@ -13,10 +17,21 @@ describe('spec version constants', () => { expect(SPEC_VERSION_CURRENT).toBe(SPEC_VERSION_SUPPORTS_COMPRESSION); expect(SPEC_VERSION_SUPPORTS_COMPRESSION).toBe(5); }); + + it('can read a newer spec version than it mints', () => { + // Slot identity is readable by every world before any world mints it, so + // that turning it on for new runs cannot make those same worlds reject + // them. Once slots are the default the two constants coincide again. + expect(SPEC_VERSION_MAX_SUPPORTED).toBe(SPEC_VERSION_SLOT_IDENTITY); + expect(SPEC_VERSION_MAX_SUPPORTED).toBeGreaterThanOrEqual( + SPEC_VERSION_CURRENT + ); + }); }); describe('requiresNewerWorld', () => { - it('accepts runs at or below the current spec version', () => { + it('accepts runs at or below the newest readable spec version', () => { + expect(requiresNewerWorld(SPEC_VERSION_MAX_SUPPORTED)).toBe(false); expect(requiresNewerWorld(SPEC_VERSION_CURRENT)).toBe(false); expect(requiresNewerWorld(SPEC_VERSION_SUPPORTS_ATTRIBUTES)).toBe(false); expect(requiresNewerWorld(SPEC_VERSION_LEGACY)).toBe(false); @@ -24,13 +39,20 @@ describe('requiresNewerWorld', () => { expect(requiresNewerWorld(null)).toBe(false); }); - it('rejects runs newer than the current spec version', () => { + it('accepts a slot-identity run', () => { + // Gates the flag rollout: a world that rejected spec-6 would reject the + // runs it had just stamped spec-6 itself, at their first event after + // run_created. + expect(requiresNewerWorld(SPEC_VERSION_SLOT_IDENTITY)).toBe(false); + }); + + it('rejects runs newer than the newest readable spec version', () => { // This is the contract that protects older SDKs from compressed // payloads they cannot decode: a spec-5 run read by an SDK whose - // SPEC_VERSION_CURRENT is 4 fails this check up front (with - // RunNotSupportedError at the storage layer) instead of failing on - // individual compressed payloads. - expect(requiresNewerWorld(SPEC_VERSION_CURRENT + 1)).toBe(true); + // ceiling is 4 fails this check up front (with RunNotSupportedError at + // the storage layer) instead of failing on individual compressed + // payloads. + expect(requiresNewerWorld(SPEC_VERSION_MAX_SUPPORTED + 1)).toBe(true); }); it('simulates a v4 reader rejecting a compression-era run', () => { @@ -51,3 +73,32 @@ describe('isLegacySpecVersion', () => { expect(isLegacySpecVersion(5)).toBe(false); }); }); + +describe('mintedSpecVersion', () => { + it('mints slot identity by default', () => { + expect(mintedSpecVersion({})).toBe(SPEC_VERSION_SLOT_IDENTITY); + }); + + it('mints the previous version when the flag is switched off', () => { + for (const value of ['0', 'false']) { + expect(mintedSpecVersion({ [SLOT_IDENTITY_ENV_VAR]: value })).toBe( + SPEC_VERSION_CURRENT + ); + } + }); + + it('treats any other value as on', () => { + // An unset-but-present variable is the shape a shell leaves behind, and it + // must not silently switch a deployment's event identity scheme. Opting + // out takes an explicit `0`/`false`. + for (const value of ['', '1', 'true', 'yes']) { + expect(mintedSpecVersion({ [SLOT_IDENTITY_ENV_VAR]: value })).toBe( + SPEC_VERSION_SLOT_IDENTITY + ); + } + }); + + it('mints nothing a world cannot read', () => { + expect(requiresNewerWorld(mintedSpecVersion({}))).toBe(false); + }); +}); diff --git a/packages/world/src/spec-version.ts b/packages/world/src/spec-version.ts index d9be743be6..4b830fd4a8 100644 --- a/packages/world/src/spec-version.ts +++ b/packages/world/src/spec-version.ts @@ -42,20 +42,59 @@ export const SPEC_VERSION_SUPPORTS_COMPRESSION = 5 as SpecVersion; * persisted `specVersion`, never from the build. A run started under ULID * correlation ids and replayed by a slot-capable build would otherwise propose * `step_…001` where its log holds `step_01K…`, matching no existing entity. - * - * Deliberately not `SPEC_VERSION_CURRENT` yet: `requiresNewerWorld()` is what - * makes a world reject runs it cannot read, so bumping current before the - * worlds can allocate slots would have them reject their own new runs. */ export const SPEC_VERSION_SLOT_IDENTITY = 6 as SpecVersion; /** * Current spec version (event-sourced architecture with native attributes * and compressed payloads). + * + * The floor a world stamps on new runs, and a *lower* bar than the newest + * version this build can read — see {@link SPEC_VERSION_MAX_SUPPORTED}. What a + * world actually stamps comes from {@link mintedSpecVersion}; this is what it + * falls back to when slot identity is switched off. */ export const SPEC_VERSION_CURRENT = SPEC_VERSION_SUPPORTS_COMPRESSION as SpecVersion; +/** + * Newest spec version this build can read. Runs above it are rejected outright + * by {@link requiresNewerWorld} rather than misread. + * + * Distinct from {@link SPEC_VERSION_CURRENT} because a world has to be able to + * read a version before anything may mint it, and because a world that mints + * slot identity still has to read the spec-5 runs it created before the switch. + * Worlds opt into minting individually, via the `specVersion` they declare. + */ +export const SPEC_VERSION_MAX_SUPPORTED = + SPEC_VERSION_SLOT_IDENTITY as SpecVersion; + +/** + * Environment variable that opts new runs out of slot identity. + * + * Read per `createWorld()` call rather than at module load, so a test or a + * single process can create worlds in both modes. + */ +export const SLOT_IDENTITY_ENV_VAR = 'WORKFLOW_SLOT_IDENTITY'; + +/** + * The spec version a world should stamp on the runs it creates: slot identity + * unless {@link SLOT_IDENTITY_ENV_VAR} disables it, in which case + * {@link SPEC_VERSION_CURRENT}. + * + * Every world reads runs up to {@link SPEC_VERSION_MAX_SUPPORTED} whatever this + * returns, so turning the flag off in one place does not make the runs another + * process created unreadable here. + */ +export function mintedSpecVersion( + env: Record = process.env +): SpecVersion { + const value = env[SLOT_IDENTITY_ENV_VAR]; + return value === '0' || value === 'false' + ? SPEC_VERSION_CURRENT + : SPEC_VERSION_SLOT_IDENTITY; +} + /** * Check if a spec version is legacy (<= SPEC_VERSION_LEGACY or undefined). * Legacy runs require different handling - they use direct entity mutation @@ -73,7 +112,7 @@ export function isLegacySpecVersion(v: number | undefined | null): boolean { } /** - * Check if a spec version requires a newer world (> SPEC_VERSION_CURRENT). + * Check if a spec version requires a newer world (> SPEC_VERSION_MAX_SUPPORTED). * This happens when a run was created by a newer SDK version. * * @param v - The spec version number, or undefined/null for legacy runs @@ -81,7 +120,7 @@ export function isLegacySpecVersion(v: number | undefined | null): boolean { */ export function requiresNewerWorld(v: number | undefined | null): boolean { if (v === undefined || v === null) return false; - return v > SPEC_VERSION_CURRENT; + return v > SPEC_VERSION_MAX_SUPPORTED; } /** diff --git a/packages/world/src/ulid.ts b/packages/world/src/ulid.ts index 1ee1b7b47c..cc893834c3 100644 --- a/packages/world/src/ulid.ts +++ b/packages/world/src/ulid.ts @@ -1,5 +1,6 @@ import { decodeTime } from 'ulid'; import { z } from 'zod'; +import { isSlotId } from './slot-identity.js'; const UlidSchema = z.string().ulid(); @@ -36,8 +37,19 @@ export const DEFAULT_TIMESTAMP_THRESHOLD_MS = /** * Extracts a Date from a ULID string, or null if the string is not a valid ULID. + * + * Slot ids are not ULIDs even though they pass the ULID *syntax* check: their + * body is all decimal digits, which Crockford base32 accepts, and it would + * decode to a timestamp of epoch 0 instead of failing. A slot encodes a + * position, not a time, so it is reported here as having no time at all — + * callers must read the object's own `createdAt`. Silently returning 1970 + * instead would, among other things, rewind a replaying workflow's clock and + * make cursor pagination skip every slot-numbered event. */ export function ulidToDate(maybeUlid: string): Date | null { + if (isSlotId(maybeUlid)) { + return null; + } const ulid = UlidSchema.safeParse(maybeUlid); if (!ulid.success) { return null;