[web-shared] Mark ignored duplicate events in the observability UI - #3467
Conversation
Concurrent replays of one run share an event log, so a replay working from a stale prefix can commit a write the log already records. The runtime passes over those. The UI showed them as ordinary progress and let them move derived state. Derive the set of passed-over events from the log with `entityEventClass`, restricted to the classes a run records at most once per entity. A retried step legitimately repeats `step_started` and `step_retrying`, one per attempt, so those two are excluded and never marked. Marked events read greyed out in the sidebar event list and the events table, with a tooltip saying the event was ignored. They are also kept out of the derived step status, the queued/ran durations, and trace span geometry, where a second terminal event would otherwise stretch a step to whenever the losing replay happened to commit.
🦋 Changeset detectedLatest commit: e7c690f The changes in this PR will be included in the next version bump. This PR includes changesets to release 16 packages
Not sure what this means? Click here to learn what changesets are. Click here if you're a maintainer who wants to add another changeset to this PR |
Sim WorldSimulated world deterministic testing for races. Traces 🟠 Mint-ordered log — 6 fail of 41 total
Full trace: 🟢 Append-only log — 0 fail of 41 total
Full trace: |
An event the caller cannot identify cannot be marked: callers match on the id, so reporting a missing one tarred every other id-less event with it.
|
(AI) CI state on this branch, for anyone reading the red:
Nothing in this PR touches those paths: the diff is |
| * first so a shorter ID never sorts after a longer one on a fixture or a log | ||
| * that mixes widths. | ||
| */ | ||
| function compareLogPosition(a: Event, b: Event): number { |
There was a problem hiding this comment.
AI Review: eventId is not the authoritative order for every supported history. world-local uses the ID as a sort key only for slot-numbered runs; for legacy ULID runs, eventSortKey() returns null and events.list() deliberately orders by (createdAt, eventId). Since createdAt is captured at create() entry and the ULID is minted later, concurrent writers can produce opposite timestamp and ID orders. The runtime then consumes the backend timestamp-ordered log while this UI fold can reverse the canonical and duplicate events. Please pass an authoritative backend log-position/order key into this classifier (or otherwise preserve a guaranteed authoritative ordering contract) rather than assuming every event ID is a log position, and add a legacy-ULID test where createdAt and eventId disagree.
There was a problem hiding this comment.
(AI) Verified and fixed in 94e05bd.
You are right, and the premise checks out in the backend code: eventSortKey returns the ID only for a slot-numbered run and null otherwise, and paginatedFileSystemQuery then sorts a ULID run by (createdAt, eventId). world-vercel does no client-side sort, so it hands back the store-key order. So for a ULID log the two supported backends can genuinely disagree, and createdAt is stamped when the write arrives rather than when it commits.
I could not pass an authoritative position key in, because none of the reads that feed this UI carry one: for a ULID run the position exists only as the order the backend chose to return, and the UI receives the array already sorted by its own caller (both findDuplicateEventIds tests for caller-order independence exist because of that). So instead of assuming a contract, the classifier now establishes when it has one:
- All slot IDs: the slot is drawn at the publish, which is the linearization point, so slot order is log order in both backends and the ID settles it.
- Otherwise: the ID order must be corroborated by non-decreasing
createdAt. Where the two contradict, which occurrence the run acted on depends on which backend served it, so nothing is classified.
Added classifies a ULID log whose timestamps corroborate its ids and classifies nothing on a ULID log whose timestamps contradict its ids, both on ULID-shaped IDs (the existing helper mints slot IDs, which isSlotEventId classifies as slots, so those tests were only ever covering the slot rule).
| closedEntities.add(entity); | ||
| } | ||
|
|
||
| if (!repeatsClass) { |
There was a problem hiding this comment.
AI Review: The fold records a previously unseen class even when it first appears after the entity has already closed. For [step_created, step_completed, step_started, step_started], the runtime stops with replay divergence on the first trailing step_started; it never reaches or classifies the second one. This fold leaves the first unmarked, adds step_started to seenClasses, then falsely marks the second as an ignored duplicate. Once a closed entity encounters an unseen class, classification for that entity should become indeterminate (or the fold should stop), and that class should not be added to seenClasses. Please add this four-event sequence to the shared runtime/UI fixtures.
There was a problem hiding this comment.
(AI) Correct, fixed in 94e05bd.
Walking your sequence against the fold confirmed it: the first trailing step_started took the !repeatsClass branch and was recorded, which made the second one look like a settled repeat although the runtime had already parked on the first and exited.
I took the "stop the fold" option rather than per-entity indeterminacy, because divergence ends the run rather than that one entity: events after it were never read either, so marking a sibling's repeat past that point would have the same defect one entity over. So on a closed entity meeting an unseen class the fold breaks, and the class is never recorded.
Added the four-event sequence to the shared fixtures as repeat of a class the log has not recorded yet with ignoredIndices: []. It passes on both sides: the runtime half stops on index 2 with an unconsumed event and never calls onDuplicateEvent. The UI test classifies nothing past the point the run diverged also pins the other half of the rule, that a repeat before the divergence point is still classified.
Two gaps in the fold, both from review on #3467. The event ID is a log position only for a slot-numbered run, whose slot is drawn at the publish. A ULID-numbered run is served by one backend in (createdAt, eventId) order and by another keyed on the ID, so concurrent writers can produce opposite orders and the ID alone does not fix the position. Such a log is now classified only where its timestamps corroborate its IDs. The fold also recorded a class first seen after its entity had closed, which is the point the runtime reports divergence and exits. A later event of that class then looked like a settled repeat although the run never read it. The fold stops there instead.
karthikscale3
left a comment
karthikscale3
left a comment
There was a problem hiding this comment.
Re-reviewed at e7c690f. The latest changes address the event-order ambiguity and post-divergence classification findings with conservative fallbacks and regression coverage. No remaining code-review blockers from me.
|
Note that https://workflow-web-git-peter-duplicate-events-ui.labs.vercel.dev/?period=1h&status=completed currently fails to load due to scan limits, so couldn't re-test, but will follow up |
|
No backport to This is a feature enhancement to the observability UI: it adds a new exported API ( To override, re-run the Backport to stable workflow manually via |
2 participants
#3381 makes the runtime pass over an event that repeats a class the log already records for the same entity. Nothing about that reaches the UI: events are immutable and carry no "ignored" marker, so the observability UI showed such an event as ordinary progress and let it move derived state.
What this does
Adds
findDuplicateEventIds(events, { isCompleteHistory })to@workflow/web-shared, which derives the passed-over set from the event list usingentityEventClassfrom@workflow/world(added in #3381).The rule follows consumer lifetime rather than event type. The runtime steps over an event only when its class was already recorded for the entity and no registered callback claims it, and a callback stays registered for as long as the entity is open. So a repeat counts here only once a terminal event for the same entity (
step_terminal,wait_completed,hook_disposed) sits earlier in the log, which is the point past which no consumer remains.run_startedis the one class with no entity to close first:workflow.tsdeclines a second one outright.That means a retried step's repeated
step_started/step_retrying, a secondstep_createdon a step still in flight, and repeatedhook_receiveddeliveries are all left alone. Astep_startedafter the step's outcome is marked.The fold walks in log order, sorting on
eventId(fixed-width and monotonic within a run under both id schemes). Timestamps are not authoritative: a writer stampscreatedAton entry but takes its log position at publish time, andoccurredAtis measured on the client.Two surfaces show it:
gray-700) with a tooltip.Three derived views stop counting them:
materializeStepskeeps the outcome the run acted on. Before, astep_completedwritten by a losing replay after astep_failedflipped the materialized status.buildDurationMapmeasures "Ran for" against the terminal event the run acted on, not a later repeat.buildTracefilters them before grouping, so a span bar ends where the step ended rather than where the losing replay committed. The event lists still receive the full log, so a marked event is still listed under its entity.Incomplete histories
Which occurrence of a class came first is a property of the whole log. On a page of a paginated list or the result of a search, the earlier event can be missing, and the fold would report the surviving one instead. So
findDuplicateEventIdsrequires the caller to vouch for completeness and classifies nothing otherwise:EventListViewpasses!hasMoreEvents && !isExactSearchActive,TraceViewerpasses!hasMore. The derived-state helpers take the same flag and default it to false, so an unset caller behaves as it did before this PR. The sidebar only ever sees one entity's slice, so it takes the answer as data from the caller that holds the whole log.Wording
The tooltip says what the log shows rather than what the runtime did with it: "Written by a concurrent replay after an event of the same kind was already recorded and acted on. The run follows the earlier one." Tolerating these repeats is recent, and on a run recorded before #3381 an unclaimed repeat failed the replay rather than being passed over.
Tests
packages/world/src/test-support/duplicate-event-fixtures.tsholds nine logs and the indices no consumer claims. Both sides run them:packages/core/src/duplicate-event-fixtures.test.tsdrives them throughEventsConsumerwith consumers modeling the lifetimes instep.ts/sleep.ts/workflow.ts, andduplicate-events.test.tsruns the same fixtures through the UI classifier. A fixture whose expectation moves fails on both sides.Beyond the fixtures,
duplicate-events.test.ts,event-materialization.test.ts, andtrace-builder.test.tscover log order conflicting withcreatedAtand withoccurredAt, tied timestamps in both caller sort directions, the incomplete-history path, the preserved step outcome, the attempt count on a retried step, and the span end time.No change was needed in
packages/web: it rendersEventListViewfromweb-shared, and its flow-graph mapper already takes the first event per correlation id.