world-postgres: create run row, slot marker, and run_created event atomically #3656

Activity

1. samtarifflens commented on Sep 6, 2026

   

   samtarifflens

   on Sep 6, 2026

   More actions

   Deterministic reproduction and a patch (world-postgres 5.0.0-beta.40)

   We hit this in production with two API tasks on one Postgres world. A run's
   second event was written by a worker that had not yet seen the run's
   workflow_event_slots marker, so allocateEventId took the legacy branch and
   minted wevt_01M1VSBYJT…. Every later insert for that run computed its slot
   from the highest existing id, hit a ULID body where it expected a number, and
   refused the log ("Event id is not slot-numbered"). The run sat RUNNING for four
   minutes and was settled ERROR by our stall watchdog. The answer it was carrying
   was complete and correct.

   The fault is visibility, not concurrency, so it reproduces in one process.
   Widen the window with a trigger:

   CREATE FUNCTION delay_slot_marker() RETURNS trigger LANGUAGE plpgsql AS $$
   BEGIN PERFORM pg_sleep(1); RETURN NEW; END $$;
   CREATE TRIGGER delay_slot_marker BEFORE INSERT ON workflow.workflow_event_slots
     FOR EACH ROW EXECUTE FUNCTION delay_slot_marker();

   Start any workflow, and poll every 10 ms:

   SELECT r.id, (SELECT count(*) FROM workflow.workflow_event_slots s WHERE s.run_id = r.id) AS markers
   FROM workflow.workflow_runs r WHERE r.created_at > now() - interval '5 seconds';

   On beta.40 the run comes back with markers = 0 for the whole second: the
   run_created branch of createEventsStorage(...).create inserts the run row,
   then calls openEventSlots, then inserts the first event — three separate
   auto-committed statements. Any writer that reads the run in that window is
   told, correctly as far as it can see, that the run predates slots.

   Our patch, both changes in src/storage.ts:

   1. One transaction per creation path. The run_created branch and the
      resilient run_started branch each wrap the run-row insert, openEventSlots
      and the first event's insert in a single
      drizzle.transaction(..., SLOT_INSERT_TRANSACTION). onConflictDoNothing()
      and the re-read on a lost creation race are preserved; a conflict on the
      first slot now rolls the run row back instead of leaving a run with no
      run_created event. (The resilient path's comment already promised this
      transaction.)
   2. allocateEventId hardened. It reads the marker FOR SHARE, and when
      there is no marker it checks whether the run's log already holds an
      evnt_-prefixed event before deciding the run is legacy. The transaction is
      what closes the window; this survives a path we did not think of, and costs
      an extra query only on runs that really are legacy.

   With both applied, the polling loop never observes a run without its marker and
   the log stays slot-numbered end to end. That assertion is now a regression test
   for us; before the patch it fails on every run.

   Related: with two workers we also hit #3758 (a booting peer re-enqueueing runs
   a live peer is executing). We answered that by electing a single queue worker
   with a Postgres advisory lock rather than by patching, so only one process ever
   calls reenqueueActiveRuns.
2. komly commented on Sep 7, 2026

   

   komly

   on Sep 7, 2026

   Contributor

   More actions

   Another data point, with a different trigger than the two above: a process restart, not a concurrent second writer.

   Setup: eve@0.44.4 (runtime spec 6, pre-slot ids dropped per #3519) + @workflow/world-postgres@5.0.0-beta.35, one world process per agent in a single container; deploys replace the container, so no live peer — #3758 does not apply here.

   What we found in the database: three runs whose workflow_runs row existed (created 14:02, 14:19, 14:34) but with no run_created event and no workflow_event_slots row at all. Their first events were written at 14:37:35 — the second the replacement container booted — by reenqueueActiveRuns: run_started, step_created, step_started, step_completed, all with wevt_<ulid> ids because allocateEventId found no marker. Every later replay fails with Event id is not slot-numbered, and Graphile retries for 49 attempts with growing backoff. The runs were unrecoverable; we failed them with permanently_fail_jobs.

   So the window is not only a race between two writers: if the process dies between the run-row insert and the marker insert, the run stays half-created forever, and startup recovery then poisons it.

   Reproduction with the pg_sleep(1) trigger from the comment above, polling every 10 ms for a run visible without its marker, on beta.35:

   • unpatched: 79 observations in the 1 s window
   • with both creation paths wrapped in one drizzle.transaction(…, SLOT_INSERT_TRANSACTION) and allocateEventId checking the log for an existing evnt_ event before choosing the legacy id: 0 observations; final state identical (evnt_…01 run_created, marker present)

   We carry that as a pnpm patch on beta.35 until this lands. Happy to share the diff if useful.
3. VaguelySerious

   closed this as completedin #4111on Sep 11, 2026