From b08502361899221c811d9b0d8f414b619c74fe82 Mon Sep 17 00:00:00 2001 From: Peter Wielander Date: Fri, 22 May 2026 17:03:49 +0200 Subject: [PATCH] [web-shared] Fix "Queued for" duration for retried steps Steps that retry emit multiple `step_started` events with the same `correlationId`. `buildDurationMap` overwrote `info.queued` on each one, so the displayed value ended up as time from `step_created` to the *last* `step_started`. Anchor on the first start instead, and process events chronologically inside the helper so its output no longer depends on the caller's sort direction. Co-Authored-By: Claude Opus 4.7 (1M context) --- .../queued-for-uses-first-step-started.md | 5 ++ .../src/components/event-list-view.tsx | 42 ++++++---- .../test/event-list-duration.test.ts | 77 +++++++++++++++++++ 3 files changed, 111 insertions(+), 13 deletions(-) create mode 100644 .changeset/queued-for-uses-first-step-started.md create mode 100644 packages/web-shared/test/event-list-duration.test.ts diff --git a/.changeset/queued-for-uses-first-step-started.md b/.changeset/queued-for-uses-first-step-started.md new file mode 100644 index 0000000000..d469643bf3 --- /dev/null +++ b/.changeset/queued-for-uses-first-step-started.md @@ -0,0 +1,5 @@ +--- +"@workflow/web-shared": patch +--- + +Fix the "Queued for" duration shown in the events list for retried steps. It now measures from `step_created` to the first `step_started` instead of the last, so the displayed value reflects actual queue time rather than queue time plus all retry waits. diff --git a/packages/web-shared/src/components/event-list-view.tsx b/packages/web-shared/src/components/event-list-view.tsx index 5415f94778..db83be83f5 100644 --- a/packages/web-shared/src/components/event-list-view.tsx +++ b/packages/web-shared/src/components/event-list-view.tsx @@ -142,7 +142,7 @@ function buildNameMaps( return { correlationNameMap, workflowName }; } -interface DurationInfo { +export interface DurationInfo { /** Time from created → started (ms) */ queued?: number; /** Time from started → completed/failed/cancelled (ms) */ @@ -154,19 +154,30 @@ interface DurationInfo { * created ↔ started (queued) and started ↔ completed/failed/cancelled (ran). * Also computes run-level durations under the key '__run__'. */ -function buildDurationMap(events: Event[]): Map { +export function buildDurationMap(events: Event[]): Map { + // Process events in chronological order so the result doesn't depend on + // the caller's sort direction. Retried steps emit multiple `step_started` + // events for the same correlationId; the queued duration must be measured + // against the first one, not the last. + const chronological = [...events].sort( + (a, b) => new Date(a.createdAt).getTime() - new Date(b.createdAt).getTime() + ); + const createdTimes = new Map(); + const firstStartedTimes = new Map(); const startedTimes = new Map(); const durations = new Map(); - for (const event of events) { + for (const event of chronological) { const ts = new Date(event.createdAt).getTime(); const key = event.correlationId ?? '__run__'; const type: string = event.eventType; // Track created times (first event for each correlation) if (type === 'step_created' || type === 'run_created') { - createdTimes.set(key, ts); + if (!createdTimes.has(key)) { + createdTimes.set(key, ts); + } } // Track started times & compute queued duration @@ -176,16 +187,21 @@ function buildDurationMap(events: Event[]): Map { type === 'workflow_started' ) { startedTimes.set(key, ts); - // If no explicit created event was seen, use the started time as created - if (!createdTimes.has(key)) { - createdTimes.set(key, ts); - } - const createdAt = createdTimes.get(key); - const info = durations.get(key) ?? {}; - if (createdAt !== undefined) { - info.queued = ts - createdAt; + // The queued duration is anchored on the first start event only — + // subsequent step_started events come from retries. + if (!firstStartedTimes.has(key)) { + firstStartedTimes.set(key, ts); + // If no explicit created event was seen, use the started time as created + if (!createdTimes.has(key)) { + createdTimes.set(key, ts); + } + const createdAt = createdTimes.get(key); + const info = durations.get(key) ?? {}; + if (createdAt !== undefined) { + info.queued = ts - createdAt; + } + durations.set(key, info); } - durations.set(key, info); } // Compute ran duration on terminal events diff --git a/packages/web-shared/test/event-list-duration.test.ts b/packages/web-shared/test/event-list-duration.test.ts new file mode 100644 index 0000000000..d791f3f4ee --- /dev/null +++ b/packages/web-shared/test/event-list-duration.test.ts @@ -0,0 +1,77 @@ +import type { Event } from '@workflow/world'; +import { describe, expect, it } from 'vitest'; +import { buildDurationMap } from '../src/components/event-list-view.js'; + +/** + * Regression tests for the "Queued for" duration shown in the Events tab. + * + * A retried step emits multiple `step_started` events for the same + * correlationId. The queued duration must be anchored on the FIRST + * `step_started` (time from `step_created` to first attempt), not the last, + * so the displayed value reflects how long the step waited before any work + * began. + */ + +function ev( + eventType: string, + correlationId: string | null, + createdAt: string +): Event { + // Only the fields buildDurationMap reads are required; the rest of Event + // is opaque to it. + return { + eventType, + correlationId, + createdAt, + } as unknown as Event; +} + +describe('buildDurationMap → queued duration', () => { + it('uses the first step_started, not the last, for steps with retries', () => { + const events: Event[] = [ + ev('step_created', 'step-1', '2026-01-01T00:00:00.000Z'), + ev('step_started', 'step-1', '2026-01-01T00:00:01.000Z'), + ev('step_failed', 'step-1', '2026-01-01T00:00:02.000Z'), + ev('step_retrying', 'step-1', '2026-01-01T00:00:03.000Z'), + ev('step_started', 'step-1', '2026-01-01T00:00:10.000Z'), + ev('step_completed', 'step-1', '2026-01-01T00:00:11.000Z'), + ]; + + const map = buildDurationMap(events); + // 1s between step_created and the first step_started. + expect(map.get('step-1')?.queued).toBe(1000); + }); + + it('handles events in descending order (newest first)', () => { + const ascending: Event[] = [ + ev('step_created', 'step-1', '2026-01-01T00:00:00.000Z'), + ev('step_started', 'step-1', '2026-01-01T00:00:01.000Z'), + ev('step_failed', 'step-1', '2026-01-01T00:00:02.000Z'), + ev('step_started', 'step-1', '2026-01-01T00:00:10.000Z'), + ev('step_completed', 'step-1', '2026-01-01T00:00:11.000Z'), + ]; + const descending = [...ascending].reverse(); + + expect(buildDurationMap(ascending).get('step-1')?.queued).toBe(1000); + expect(buildDurationMap(descending).get('step-1')?.queued).toBe(1000); + }); + + it('still works for a step with a single start (no retry)', () => { + const events: Event[] = [ + ev('step_created', 'step-2', '2026-01-01T00:00:00.000Z'), + ev('step_started', 'step-2', '2026-01-01T00:00:00.500Z'), + ev('step_completed', 'step-2', '2026-01-01T00:00:02.000Z'), + ]; + + expect(buildDurationMap(events).get('step-2')?.queued).toBe(500); + }); + + it('falls back to the started time when no created event is seen', () => { + const events: Event[] = [ + ev('step_started', 'step-3', '2026-01-01T00:00:05.000Z'), + ev('step_completed', 'step-3', '2026-01-01T00:00:06.000Z'), + ]; + + expect(buildDurationMap(events).get('step-3')?.queued).toBe(0); + }); +});