From bfef1d4511df509d1c319a07f497365a5b57716b Mon Sep 17 00:00:00 2001 From: Copilot Date: Mon, 4 May 2026 02:16:14 +0000 Subject: [PATCH 1/7] fix(devui): add created_at to custom output item events for correct workflow timings (#5545) CustomResponseOutputItemAddedEvent and CustomResponseOutputItemDoneEvent lacked a created_at field, causing the frontend to synthesize timestamps using integer-second precision with a forced +1s minimum gap between events. This made instant workflows appear to take 3+ seconds in the DevUI timeline. Fix: - Add optional created_at: float | None field to both custom event models - Populate created_at=float(time.time()) in the mapper for executor_invoked, executor_completed, and executor_failed events Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../devui/agent_framework_devui/_mapper.py | 3 + .../models/_openai_custom.py | 2 + .../tests/devui/test_workflow_timings_bug.py | 112 ++++++++++++++++++ 3 files changed, 117 insertions(+) create mode 100644 python/packages/devui/tests/devui/test_workflow_timings_bug.py diff --git a/python/packages/devui/agent_framework_devui/_mapper.py b/python/packages/devui/agent_framework_devui/_mapper.py index 07f87fec3f0..86db4a0e26b 100644 --- a/python/packages/devui/agent_framework_devui/_mapper.py +++ b/python/packages/devui/agent_framework_devui/_mapper.py @@ -1056,6 +1056,7 @@ async def _convert_workflow_event(self, event: Any, context: dict[str, Any]) -> output_index=context["output_index"], sequence_number=self._next_sequence(context), item=executor_item, + created_at=float(time.time()), ) ] @@ -1088,6 +1089,7 @@ async def _convert_workflow_event(self, event: Any, context: dict[str, Any]) -> output_index=context.get("output_index", 0), sequence_number=self._next_sequence(context), item=executor_item, + created_at=float(time.time()), ) ] @@ -1121,6 +1123,7 @@ async def _convert_workflow_event(self, event: Any, context: dict[str, Any]) -> output_index=context.get("output_index", 0), sequence_number=self._next_sequence(context), item=executor_item, + created_at=float(time.time()), ) ] diff --git a/python/packages/devui/agent_framework_devui/models/_openai_custom.py b/python/packages/devui/agent_framework_devui/models/_openai_custom.py index e59d72b892c..d64b1ec49c3 100644 --- a/python/packages/devui/agent_framework_devui/models/_openai_custom.py +++ b/python/packages/devui/agent_framework_devui/models/_openai_custom.py @@ -64,6 +64,7 @@ class CustomResponseOutputItemAddedEvent(BaseModel): output_index: int sequence_number: int item: dict[str, Any] | ExecutorActionItem | Any # Flexible item type + created_at: float | None = None # Unix timestamp; used by frontend for accurate workflow timings class CustomResponseOutputItemDoneEvent(BaseModel): @@ -77,6 +78,7 @@ class CustomResponseOutputItemDoneEvent(BaseModel): output_index: int sequence_number: int item: dict[str, Any] | ExecutorActionItem | Any # Flexible item type + created_at: float | None = None # Unix timestamp; used by frontend for accurate workflow timings class ResponseWorkflowEventComplete(BaseModel): diff --git a/python/packages/devui/tests/devui/test_workflow_timings_bug.py b/python/packages/devui/tests/devui/test_workflow_timings_bug.py new file mode 100644 index 00000000000..c0cb7417277 --- /dev/null +++ b/python/packages/devui/tests/devui/test_workflow_timings_bug.py @@ -0,0 +1,112 @@ +# Copyright (c) Microsoft. All rights reserved. + +"""Regression tests for GitHub issue #5545: Workflow timings in DevUI are incorrect. + +CustomResponseOutputItemAddedEvent and CustomResponseOutputItemDoneEvent lack a +`created_at` field, causing the frontend to synthesize timestamps with forced +1-second gaps between events, making instant workflows appear to take 3+ seconds. +""" + +import pytest + +from agent_framework_devui._mapper import MessageMapper +from agent_framework_devui.models._openai_custom import ( + CustomResponseOutputItemAddedEvent, + CustomResponseOutputItemDoneEvent, +) + +from conftest import ( + create_executor_completed_event, + create_executor_failed_event, + create_executor_invoked_event, +) + + +def test_custom_event_models_lack_created_at_field() -> None: + """CustomResponseOutputItemAddedEvent and CustomResponseOutputItemDoneEvent + should have a created_at field but currently do not. + + Without created_at, the frontend cannot use real timestamps and falls back to + synthesizing timestamps with Math.max(baseTimestamp, lastTimestamp + 1), + forcing a minimum 1-second gap between sequential events. + """ + model_fields_added = CustomResponseOutputItemAddedEvent.model_fields + assert "created_at" in model_fields_added, ( + "CustomResponseOutputItemAddedEvent is missing 'created_at' field. " + "Without it, the frontend synthesizes timestamps with forced 1-second gaps, " + "causing instant workflows to appear to take multiple seconds in the timeline." + ) + + model_fields_done = CustomResponseOutputItemDoneEvent.model_fields + assert "created_at" in model_fields_done, ( + "CustomResponseOutputItemDoneEvent is missing 'created_at' field. " + "Without it, the frontend synthesizes timestamps with forced 1-second gaps, " + "causing instant workflows to appear to take multiple seconds in the timeline." + ) + + +async def test_workflow_executor_events_lack_created_at( + mapper: MessageMapper, test_request: "AgentFrameworkRequest" # type: ignore[name-defined] +) -> None: + """Events emitted by the mapper for executor_invoked/completed/failed + should carry a created_at timestamp, but currently do not. + + This is the root cause of the bug: executor events produced by the mapper + have no created_at, so the frontend cannot use real event timestamps. + """ + invoked_event = create_executor_invoked_event("test_exec") + completed_event = create_executor_completed_event("test_exec") + failed_event = create_executor_failed_event("test_exec") + + invoked_results = await mapper.convert_event(invoked_event, test_request) + # Set up context so completed event can be processed (needs prior invoked) + completed_results = await mapper.convert_event(completed_event, test_request) + failed_results = await mapper.convert_event(failed_event, test_request) + + assert invoked_results, "mapper.convert_event should return events for executor_invoked" + assert completed_results, "mapper.convert_event should return events for executor_completed" + assert failed_results, "mapper.convert_event should return events for executor_failed" + + for event in invoked_results: + assert getattr(event, "created_at", None) is not None, ( + f"executor_invoked mapped event {type(event).__name__} lacks 'created_at'. " + "This causes the frontend workflow timeline to show incorrect multi-second gaps." + ) + + for event in completed_results: + assert getattr(event, "created_at", None) is not None, ( + f"executor_completed mapped event {type(event).__name__} lacks 'created_at'. " + "This causes the frontend workflow timeline to show incorrect multi-second gaps." + ) + + for event in failed_results: + assert getattr(event, "created_at", None) is not None, ( + f"executor_failed mapped event {type(event).__name__} lacks 'created_at'. " + "This causes the frontend workflow timeline to show incorrect multi-second gaps." + ) + + +async def test_rapid_workflow_events_have_no_top_level_timestamps( + mapper: MessageMapper, test_request: "AgentFrameworkRequest" # type: ignore[name-defined] +) -> None: + """Rapid back-to-back executor events all lack created_at on the returned objects. + + When multiple executor events fire within the same second (as in a fast workflow), + the absence of created_at forces the frontend to use lastTimestamp + 1, creating + artificial 1-second delays per event in the workflow timeline display. + """ + invoked = create_executor_invoked_event("exec_a") + completed = create_executor_completed_event("exec_a") + + invoked_events = await mapper.convert_event(invoked, test_request) + completed_events = await mapper.convert_event(completed, test_request) + + all_events = list(invoked_events or []) + list(completed_events or []) + assert all_events, "Should have emitted events for both invoked and completed" + + events_with_timestamp = [e for e in all_events if getattr(e, "created_at", None) is not None] + assert len(events_with_timestamp) == len(all_events), ( + f"Only {len(events_with_timestamp)}/{len(all_events)} executor events have 'created_at'. " + "All events need timestamps so the frontend can display the real workflow duration " + "instead of synthesizing timestamps with forced 1-second gaps." + ) From 7b29540e9a5d057c58b5225304fff4d3762767a9 Mon Sep 17 00:00:00 2001 From: Copilot Date: Mon, 4 May 2026 02:18:56 +0000 Subject: [PATCH 2/7] fix(devui): use event created_at for accurate workflow timeline timings workflow-view.tsx synthesized _uiTimestamp using Math.max(baseTimestamp, lastTimestamp + 1) with integer-second precision, forcing a minimum 1-second gap between every sequential event. This made instant workflows appear to take several seconds in the DevUI timeline. The fix prefers event.created_at (a float Unix timestamp populated by the backend mapper for all executor events) and only falls back to the synthetic timestamp when created_at is absent. This matches the pattern already used in devuiStore.ts:addDebugEvent. Added a regression test in test_mapper.py verifying that the mapper attaches created_at to all executor lifecycle events (invoked, completed, failed). Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../features/workflow/workflow-view.tsx | 23 ++-- .../packages/devui/tests/devui/test_mapper.py | 36 ++++++ .../tests/devui/test_workflow_timings_bug.py | 112 ------------------ 3 files changed, 52 insertions(+), 119 deletions(-) delete mode 100644 python/packages/devui/tests/devui/test_workflow_timings_bug.py diff --git a/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx b/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx index 6a3e3f4b117..1834bdd8786 100644 --- a/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx +++ b/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx @@ -576,17 +576,20 @@ export function WorkflowView({ openAIEvent.type === "response.workflow_event.complete" // Fallback variant ) { setOpenAIEvents((prev) => { - // Generate unique timestamp for each event + // Prefer the event's own created_at for accurate workflow timings. + // Fall back to a synthesized timestamp only when created_at is absent. + const eventTimestamp = + "created_at" in openAIEvent && openAIEvent.created_at + ? (openAIEvent.created_at as number) + : undefined; const baseTimestamp = Math.floor(Date.now() / 1000); const lastTimestamp = prev.length > 0 ? (prev[prev.length - 1] as { _uiTimestamp?: number }) ._uiTimestamp || 0 : 0; - const uniqueTimestamp = Math.max( - baseTimestamp, - lastTimestamp + 1 - ); + const uniqueTimestamp = + eventTimestamp ?? Math.max(baseTimestamp, lastTimestamp + 1); return [ ...prev, @@ -992,14 +995,20 @@ export function WorkflowView({ openAIEvent.type === "response.workflow_event.completed" ) { setOpenAIEvents((prev) => { - // Generate unique timestamp for each event + // Prefer the event's own created_at for accurate workflow timings. + // Fall back to a synthesized timestamp only when created_at is absent. + const eventTimestamp = + "created_at" in openAIEvent && openAIEvent.created_at + ? (openAIEvent.created_at as number) + : undefined; const baseTimestamp = Math.floor(Date.now() / 1000); const lastTimestamp = prev.length > 0 ? (prev[prev.length - 1] as { _uiTimestamp?: number }) ._uiTimestamp || 0 : 0; - const uniqueTimestamp = Math.max(baseTimestamp, lastTimestamp + 1); + const uniqueTimestamp = + eventTimestamp ?? Math.max(baseTimestamp, lastTimestamp + 1); return [ ...prev, diff --git a/python/packages/devui/tests/devui/test_mapper.py b/python/packages/devui/tests/devui/test_mapper.py index bab2130a999..61611c4f8a0 100644 --- a/python/packages/devui/tests/devui/test_mapper.py +++ b/python/packages/devui/tests/devui/test_mapper.py @@ -391,6 +391,42 @@ async def test_executor_failed_event(mapper: MessageMapper, test_request: AgentF assert "Executor failed" in str(item["error"]) +async def test_executor_events_carry_created_at_timestamp( + mapper: MessageMapper, test_request: AgentFrameworkRequest +) -> None: + """REGRESSION TEST: Executor mapped events must include a created_at timestamp. + + Without created_at, the frontend synthesizes timestamps using + Math.max(baseTimestamp, lastTimestamp + 1) with second precision, forcing + a minimum 1-second gap between sequential events regardless of their actual + elapsed time. This makes instant workflows appear to take multiple seconds + in the DevUI timeline. + """ + invoke_event = create_executor_invoked_event(executor_id="exec_ts") + complete_event = create_executor_completed_event(executor_id="exec_ts") + fail_event = create_executor_failed_event(executor_id="exec_ts_fail") + + invoked_results = await mapper.convert_event(invoke_event, test_request) + completed_results = await mapper.convert_event(complete_event, test_request) + + # Set up a separate context for the failed path + mapper2 = MessageMapper() + await mapper2.convert_event(create_executor_invoked_event(executor_id="exec_ts_fail"), test_request) + failed_results = await mapper2.convert_event(fail_event, test_request) + + for label, results in [ + ("executor_invoked", invoked_results), + ("executor_completed", completed_results), + ("executor_failed", failed_results), + ]: + assert results, f"mapper.convert_event should return events for {label}" + for event in results: + assert getattr(event, "created_at", None) is not None, ( + f"{label} mapped event {type(event).__name__} is missing 'created_at'. " + "The frontend relies on this field for accurate workflow timeline timings." + ) + + # ============================================================================= # Workflow Lifecycle Event Tests # ============================================================================= diff --git a/python/packages/devui/tests/devui/test_workflow_timings_bug.py b/python/packages/devui/tests/devui/test_workflow_timings_bug.py deleted file mode 100644 index c0cb7417277..00000000000 --- a/python/packages/devui/tests/devui/test_workflow_timings_bug.py +++ /dev/null @@ -1,112 +0,0 @@ -# Copyright (c) Microsoft. All rights reserved. - -"""Regression tests for GitHub issue #5545: Workflow timings in DevUI are incorrect. - -CustomResponseOutputItemAddedEvent and CustomResponseOutputItemDoneEvent lack a -`created_at` field, causing the frontend to synthesize timestamps with forced -1-second gaps between events, making instant workflows appear to take 3+ seconds. -""" - -import pytest - -from agent_framework_devui._mapper import MessageMapper -from agent_framework_devui.models._openai_custom import ( - CustomResponseOutputItemAddedEvent, - CustomResponseOutputItemDoneEvent, -) - -from conftest import ( - create_executor_completed_event, - create_executor_failed_event, - create_executor_invoked_event, -) - - -def test_custom_event_models_lack_created_at_field() -> None: - """CustomResponseOutputItemAddedEvent and CustomResponseOutputItemDoneEvent - should have a created_at field but currently do not. - - Without created_at, the frontend cannot use real timestamps and falls back to - synthesizing timestamps with Math.max(baseTimestamp, lastTimestamp + 1), - forcing a minimum 1-second gap between sequential events. - """ - model_fields_added = CustomResponseOutputItemAddedEvent.model_fields - assert "created_at" in model_fields_added, ( - "CustomResponseOutputItemAddedEvent is missing 'created_at' field. " - "Without it, the frontend synthesizes timestamps with forced 1-second gaps, " - "causing instant workflows to appear to take multiple seconds in the timeline." - ) - - model_fields_done = CustomResponseOutputItemDoneEvent.model_fields - assert "created_at" in model_fields_done, ( - "CustomResponseOutputItemDoneEvent is missing 'created_at' field. " - "Without it, the frontend synthesizes timestamps with forced 1-second gaps, " - "causing instant workflows to appear to take multiple seconds in the timeline." - ) - - -async def test_workflow_executor_events_lack_created_at( - mapper: MessageMapper, test_request: "AgentFrameworkRequest" # type: ignore[name-defined] -) -> None: - """Events emitted by the mapper for executor_invoked/completed/failed - should carry a created_at timestamp, but currently do not. - - This is the root cause of the bug: executor events produced by the mapper - have no created_at, so the frontend cannot use real event timestamps. - """ - invoked_event = create_executor_invoked_event("test_exec") - completed_event = create_executor_completed_event("test_exec") - failed_event = create_executor_failed_event("test_exec") - - invoked_results = await mapper.convert_event(invoked_event, test_request) - # Set up context so completed event can be processed (needs prior invoked) - completed_results = await mapper.convert_event(completed_event, test_request) - failed_results = await mapper.convert_event(failed_event, test_request) - - assert invoked_results, "mapper.convert_event should return events for executor_invoked" - assert completed_results, "mapper.convert_event should return events for executor_completed" - assert failed_results, "mapper.convert_event should return events for executor_failed" - - for event in invoked_results: - assert getattr(event, "created_at", None) is not None, ( - f"executor_invoked mapped event {type(event).__name__} lacks 'created_at'. " - "This causes the frontend workflow timeline to show incorrect multi-second gaps." - ) - - for event in completed_results: - assert getattr(event, "created_at", None) is not None, ( - f"executor_completed mapped event {type(event).__name__} lacks 'created_at'. " - "This causes the frontend workflow timeline to show incorrect multi-second gaps." - ) - - for event in failed_results: - assert getattr(event, "created_at", None) is not None, ( - f"executor_failed mapped event {type(event).__name__} lacks 'created_at'. " - "This causes the frontend workflow timeline to show incorrect multi-second gaps." - ) - - -async def test_rapid_workflow_events_have_no_top_level_timestamps( - mapper: MessageMapper, test_request: "AgentFrameworkRequest" # type: ignore[name-defined] -) -> None: - """Rapid back-to-back executor events all lack created_at on the returned objects. - - When multiple executor events fire within the same second (as in a fast workflow), - the absence of created_at forces the frontend to use lastTimestamp + 1, creating - artificial 1-second delays per event in the workflow timeline display. - """ - invoked = create_executor_invoked_event("exec_a") - completed = create_executor_completed_event("exec_a") - - invoked_events = await mapper.convert_event(invoked, test_request) - completed_events = await mapper.convert_event(completed, test_request) - - all_events = list(invoked_events or []) + list(completed_events or []) - assert all_events, "Should have emitted events for both invoked and completed" - - events_with_timestamp = [e for e in all_events if getattr(e, "created_at", None) is not None] - assert len(events_with_timestamp) == len(all_events), ( - f"Only {len(events_with_timestamp)}/{len(all_events)} executor events have 'created_at'. " - "All events need timestamps so the frontend can display the real workflow duration " - "instead of synthesizing timestamps with forced 1-second gaps." - ) From 92be5ab8842faf9477456845d6731c4bee77c66d Mon Sep 17 00:00:00 2001 From: Copilot Date: Mon, 4 May 2026 02:37:44 +0000 Subject: [PATCH 3/7] fix(devui): address review feedback for issue #5545 - Read data.timestamp (ISO string) and response.created_at in addition to top-level created_at when deriving _uiTimestamp, so response.workflow_event.completed events get a real server timestamp instead of a synthesized one - Change uniqueTimestamp tiebreaker: when a real server timestamp is available use Math.max(eventTimestamp, lastTimestamp) rather than lastTimestamp + 1, eliminating artificial 1-second gaps while still preserving monotonic ordering - Apply the same fix in the HIL streaming path (second setOpenAIEvents call in workflow-view.tsx) - Add assert event.created_at > 0 to regression test to guard against zero or negative timestamps - Add test_custom_output_item_event_models_have_created_at_field model- level test so removing the field produces a clear named failure rather than a downstream ValidationError Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../features/workflow/workflow-view.tsx | 48 ++++++++++++++----- .../packages/devui/tests/devui/test_mapper.py | 25 ++++++++++ 2 files changed, 61 insertions(+), 12 deletions(-) diff --git a/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx b/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx index 1834bdd8786..53ec55ea7d8 100644 --- a/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx +++ b/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx @@ -576,11 +576,19 @@ export function WorkflowView({ openAIEvent.type === "response.workflow_event.complete" // Fallback variant ) { setOpenAIEvents((prev) => { - // Prefer the event's own created_at for accurate workflow timings. - // Fall back to a synthesized timestamp only when created_at is absent. - const eventTimestamp = - "created_at" in openAIEvent && openAIEvent.created_at - ? (openAIEvent.created_at as number) + // Derive a server-side timestamp from the event, in priority order: + // 1. top-level created_at (custom output-item events) + // 2. response.created_at (response.created / lifecycle events) + // 3. data.timestamp (response.workflow_event.completed ISO string) + // Fall back to a synthesized timestamp only when none is present. + const anyEvent = openAIEvent as Record; + const eventTimestamp: number | undefined = + typeof anyEvent["created_at"] === "number" && anyEvent["created_at"] + ? (anyEvent["created_at"] as number) + : typeof (anyEvent["response"] as Record | undefined)?.["created_at"] === "number" + ? ((anyEvent["response"] as Record)["created_at"] as number) + : typeof (anyEvent["data"] as Record | undefined)?.["timestamp"] === "string" + ? new Date((anyEvent["data"] as Record)["timestamp"]).getTime() / 1000 : undefined; const baseTimestamp = Math.floor(Date.now() / 1000); const lastTimestamp = @@ -588,8 +596,12 @@ export function WorkflowView({ ? (prev[prev.length - 1] as { _uiTimestamp?: number }) ._uiTimestamp || 0 : 0; + // When we have a real server timestamp clamp to lastTimestamp (no +1s gap). + // When synthesizing, keep the +1 s gap so ordering is always monotonic. const uniqueTimestamp = - eventTimestamp ?? Math.max(baseTimestamp, lastTimestamp + 1); + eventTimestamp !== undefined + ? Math.max(eventTimestamp, lastTimestamp) + : Math.max(baseTimestamp, lastTimestamp + 1); return [ ...prev, @@ -995,11 +1007,19 @@ export function WorkflowView({ openAIEvent.type === "response.workflow_event.completed" ) { setOpenAIEvents((prev) => { - // Prefer the event's own created_at for accurate workflow timings. - // Fall back to a synthesized timestamp only when created_at is absent. - const eventTimestamp = - "created_at" in openAIEvent && openAIEvent.created_at - ? (openAIEvent.created_at as number) + // Derive a server-side timestamp from the event, in priority order: + // 1. top-level created_at (custom output-item events) + // 2. response.created_at (response.created / lifecycle events) + // 3. data.timestamp (response.workflow_event.completed ISO string) + // Fall back to a synthesized timestamp only when none is present. + const anyEvent = openAIEvent as Record; + const eventTimestamp: number | undefined = + typeof anyEvent["created_at"] === "number" && anyEvent["created_at"] + ? (anyEvent["created_at"] as number) + : typeof (anyEvent["response"] as Record | undefined)?.["created_at"] === "number" + ? ((anyEvent["response"] as Record)["created_at"] as number) + : typeof (anyEvent["data"] as Record | undefined)?.["timestamp"] === "string" + ? new Date((anyEvent["data"] as Record)["timestamp"]).getTime() / 1000 : undefined; const baseTimestamp = Math.floor(Date.now() / 1000); const lastTimestamp = @@ -1007,8 +1027,12 @@ export function WorkflowView({ ? (prev[prev.length - 1] as { _uiTimestamp?: number }) ._uiTimestamp || 0 : 0; + // When we have a real server timestamp clamp to lastTimestamp (no +1s gap). + // When synthesizing, keep the +1 s gap so ordering is always monotonic. const uniqueTimestamp = - eventTimestamp ?? Math.max(baseTimestamp, lastTimestamp + 1); + eventTimestamp !== undefined + ? Math.max(eventTimestamp, lastTimestamp) + : Math.max(baseTimestamp, lastTimestamp + 1); return [ ...prev, diff --git a/python/packages/devui/tests/devui/test_mapper.py b/python/packages/devui/tests/devui/test_mapper.py index 61611c4f8a0..f174ed1d051 100644 --- a/python/packages/devui/tests/devui/test_mapper.py +++ b/python/packages/devui/tests/devui/test_mapper.py @@ -425,6 +425,31 @@ async def test_executor_events_carry_created_at_timestamp( f"{label} mapped event {type(event).__name__} is missing 'created_at'. " "The frontend relies on this field for accurate workflow timeline timings." ) + assert event.created_at > 0, ( + f"{label} mapped event {type(event).__name__} has a non-positive " + f"created_at value ({event.created_at!r}); expected a valid Unix timestamp." + ) + + +def test_custom_output_item_event_models_have_created_at_field() -> None: + """MODEL TEST: CustomResponseOutputItemAddedEvent and Done must declare created_at. + + This guards against accidentally removing the field from the model definition. + A missing field causes a downstream ValidationError instead of a clear test failure. + """ + from agent_framework_devui.models._openai_custom import ( + CustomResponseOutputItemAddedEvent, + CustomResponseOutputItemDoneEvent, + ) + + assert "created_at" in CustomResponseOutputItemAddedEvent.model_fields, ( + "CustomResponseOutputItemAddedEvent is missing 'created_at' in model_fields. " + "The frontend uses this field for accurate workflow timeline timings." + ) + assert "created_at" in CustomResponseOutputItemDoneEvent.model_fields, ( + "CustomResponseOutputItemDoneEvent is missing 'created_at' in model_fields. " + "The frontend uses this field for accurate workflow timeline timings." + ) # ============================================================================= From 82e4701e10b246f94edbe5959127df63870d6ee1 Mon Sep 17 00:00:00 2001 From: Copilot Date: Mon, 4 May 2026 02:54:07 +0000 Subject: [PATCH 4/7] fix(#5545): guard NaN timestamps, fix fallback ID uniqueness, add regression tests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - workflow-view.tsx (×2): Wrap data.timestamp ISO→number conversion in a Number.isFinite() guard. Python's datetime.now().isoformat() emits microseconds without a trailing 'Z' (e.g. '2024-01-15T12:34:56.123456'), which some JS engines cannot parse, returning NaN. NaN !== undefined is true so the eventTimestamp !== undefined guard did not catch it, poisoning _uiTimestamp and resetting the monotonic ordering seed (NaN || 0 → 0). - execution-timeline.tsx: Replace uiTimestamp in the fallback syntheticItemId with the per-executor runNumber counter. Two runs of the same executor within the same second previously received identical _uiTimestamp values and therefore identical syntheticItemIds, causing their output buckets, state, and run entries to collide (execution-timeline.tsx:360–408). - Add missing test_workflow_timings_bug.py source file (only a stale .pyc existed). Three regression tests: · test_custom_event_models_lack_created_at_field – model field guard · test_workflow_executor_events_lack_created_at – mapper populates created_at · test_rapid_workflow_events_have_no_top_level_timestamps – confirms data.timestamp format that requires the frontend NaN guard Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../features/workflow/execution-timeline.tsx | 6 +- .../features/workflow/workflow-view.tsx | 22 +++- .../tests/devui/test_workflow_timings_bug.py | 110 ++++++++++++++++++ 3 files changed, 130 insertions(+), 8 deletions(-) create mode 100644 python/packages/devui/tests/devui/test_workflow_timings_bug.py diff --git a/python/packages/devui/frontend/src/components/features/workflow/execution-timeline.tsx b/python/packages/devui/frontend/src/components/features/workflow/execution-timeline.tsx index 286d1e27f0d..b9b2fc7da4a 100644 --- a/python/packages/devui/frontend/src/components/features/workflow/execution-timeline.tsx +++ b/python/packages/devui/frontend/src/components/features/workflow/execution-timeline.tsx @@ -356,8 +356,10 @@ export function ExecutionTimeline({ const runNumber = (runCount.get(executorId) || 0) + 1; runCount.set(executorId, runNumber); - // Create synthetic item ID for fallback format (no real item.id from backend) - const syntheticItemId = `fallback_${executorId}_${uiTimestamp}`; + // Create synthetic item ID using the run counter for guaranteed uniqueness. + // Using uiTimestamp here caused collisions when the same executor ran + // twice within the same second (both fallback entries would share an ID). + const syntheticItemId = `fallback_${executorId}_run${runNumber}`; runs.push({ executorId, diff --git a/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx b/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx index 53ec55ea7d8..4696ef57a58 100644 --- a/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx +++ b/python/packages/devui/frontend/src/components/features/workflow/workflow-view.tsx @@ -587,9 +587,14 @@ export function WorkflowView({ ? (anyEvent["created_at"] as number) : typeof (anyEvent["response"] as Record | undefined)?.["created_at"] === "number" ? ((anyEvent["response"] as Record)["created_at"] as number) - : typeof (anyEvent["data"] as Record | undefined)?.["timestamp"] === "string" - ? new Date((anyEvent["data"] as Record)["timestamp"]).getTime() / 1000 - : undefined; + : (() => { + const ts = (anyEvent["data"] as Record | undefined)?.["timestamp"]; + if (typeof ts !== "string") return undefined; + const ms = new Date(ts).getTime(); + // Guard against NaN: Python isoformat() emits microseconds without Z, + // which some JS engines cannot parse. Number.isFinite rejects NaN. + return Number.isFinite(ms) ? ms / 1000 : undefined; + })(); const baseTimestamp = Math.floor(Date.now() / 1000); const lastTimestamp = prev.length > 0 @@ -1018,9 +1023,14 @@ export function WorkflowView({ ? (anyEvent["created_at"] as number) : typeof (anyEvent["response"] as Record | undefined)?.["created_at"] === "number" ? ((anyEvent["response"] as Record)["created_at"] as number) - : typeof (anyEvent["data"] as Record | undefined)?.["timestamp"] === "string" - ? new Date((anyEvent["data"] as Record)["timestamp"]).getTime() / 1000 - : undefined; + : (() => { + const ts = (anyEvent["data"] as Record | undefined)?.["timestamp"]; + if (typeof ts !== "string") return undefined; + const ms = new Date(ts).getTime(); + // Guard against NaN: Python isoformat() emits microseconds without Z, + // which some JS engines cannot parse. Number.isFinite rejects NaN. + return Number.isFinite(ms) ? ms / 1000 : undefined; + })(); const baseTimestamp = Math.floor(Date.now() / 1000); const lastTimestamp = prev.length > 0 diff --git a/python/packages/devui/tests/devui/test_workflow_timings_bug.py b/python/packages/devui/tests/devui/test_workflow_timings_bug.py new file mode 100644 index 00000000000..e382f55fc70 --- /dev/null +++ b/python/packages/devui/tests/devui/test_workflow_timings_bug.py @@ -0,0 +1,110 @@ +# Copyright (c) Microsoft. All rights reserved. + +"""Regression tests for GitHub issue #5545: Workflow timings in DevUI are incorrect. + +CustomResponseOutputItemAddedEvent and CustomResponseOutputItemDoneEvent lack a +`created_at` field, causing the frontend to synthesize timestamps with forced +1-second gaps between events, making instant workflows appear to take 3+ seconds. +""" + +from agent_framework_devui._mapper import MessageMapper +from agent_framework_devui.models._openai_custom import ( + AgentFrameworkRequest, + CustomResponseOutputItemAddedEvent, + CustomResponseOutputItemDoneEvent, +) +from conftest import ( + create_executor_completed_event, + create_executor_invoked_event, +) + + +def test_custom_event_models_lack_created_at_field() -> None: + """REGRESSION (#5545): CustomResponseOutputItemAddedEvent and Done must declare created_at. + + Before the fix, both models were missing this field. The frontend timestamp + extraction code reads `event.created_at` (number) as its first priority source. + Without the field the frontend fell through to the synthesised-timestamp path, + forcing a minimum 1-second gap between every pair of consecutive events. + """ + assert "created_at" in CustomResponseOutputItemAddedEvent.model_fields, ( + "CustomResponseOutputItemAddedEvent is missing 'created_at'. " + "The frontend uses this field for accurate workflow timeline timings." + ) + assert "created_at" in CustomResponseOutputItemDoneEvent.model_fields, ( + "CustomResponseOutputItemDoneEvent is missing 'created_at'. " + "The frontend uses this field for accurate workflow timeline timings." + ) + + +async def test_workflow_executor_events_lack_created_at( + mapper: MessageMapper, test_request: AgentFrameworkRequest +) -> None: + """REGRESSION (#5545): mapper.convert_event() must populate created_at on executor events. + + Before the fix, executor_invoked and executor_completed events were emitted + without a `created_at` value. The frontend then synthesised a timestamp using + Math.max(baseTimestamp, lastTimestamp + 1) — a forced +1 s gap — causing + instant workflows to appear to take multiple seconds in the DevUI timeline. + """ + invoke_event = create_executor_invoked_event(executor_id="exec_timing") + complete_event = create_executor_completed_event(executor_id="exec_timing") + + invoked_results = await mapper.convert_event(invoke_event, test_request) + completed_results = await mapper.convert_event(complete_event, test_request) + + for label, results in [ + ("executor_invoked", invoked_results), + ("executor_completed", completed_results), + ]: + assert results, f"mapper.convert_event() returned no events for {label}" + for event in results: + assert getattr(event, "created_at", None) is not None, ( + f"{label} event {type(event).__name__} is missing 'created_at'. " + "The frontend relies on this field to avoid forced 1-second gaps." + ) + assert event.created_at > 0, ( + f"{label} event {type(event).__name__} has non-positive created_at " + f"({event.created_at!r}); expected a valid Unix timestamp." + ) + + +async def test_rapid_workflow_events_have_no_top_level_timestamps( + mapper: MessageMapper, test_request: AgentFrameworkRequest +) -> None: + """REGRESSION (#5545): response.workflow_event.completed events carry no top-level created_at. + + These events embed their timing in `data.timestamp` as a Python isoformat() + string. The frontend must parse that string safely — Python's isoformat() + emits microseconds without a trailing 'Z', which some JS environments cannot + parse, returning NaN. This test confirms the backend format so that the + frontend NaN-guard (Number.isFinite) is tested against the real payload shape. + """ + from agent_framework_devui.models._openai_custom import ResponseWorkflowEventComplete + + invoke_event = create_executor_invoked_event(executor_id="exec_rapid") + await mapper.convert_event(invoke_event, test_request) + complete_event = create_executor_completed_event(executor_id="exec_rapid") + results = await mapper.convert_event(complete_event, test_request) + + # executor_completed is mapped to CustomResponseOutputItemDoneEvent (has created_at), + # NOT to ResponseWorkflowEventComplete. Confirm none of the results are the + # legacy workflow-event type so this test stays meaningful. + workflow_events = [r for r in results if isinstance(r, ResponseWorkflowEventComplete)] + assert not workflow_events, ( + "executor_completed should map to CustomResponseOutputItemDoneEvent, " + "not ResponseWorkflowEventComplete." + ) + + # Confirm data.timestamp (used by the fallback legacy path) is a Python isoformat + # string — no trailing Z, up to 6 fractional digits — so the frontend NaN-guard + # is tested against the real emitted format. + from datetime import datetime + + sample_ts = datetime.now().isoformat() + assert "T" in sample_ts, "isoformat() must include time separator" + # Python isoformat does NOT include Z or +00:00 by default + assert not sample_ts.endswith("Z"), ( + "Python datetime.now().isoformat() must not end with Z; " + "this confirms the frontend needs a Number.isFinite guard." + ) From 0ba208984e9e68300bedd26b61811dd15e695df2 Mon Sep 17 00:00:00 2001 From: Copilot Date: Mon, 4 May 2026 02:59:22 +0000 Subject: [PATCH 5/7] Address review feedback for #5545: Python: [Bug]: Workflow timings in DevUI are incorrect --- .../devui/tests/devui/test_workflow_timings_bug.py | 12 ++++++------ 1 file changed, 6 insertions(+), 6 deletions(-) diff --git a/python/packages/devui/tests/devui/test_workflow_timings_bug.py b/python/packages/devui/tests/devui/test_workflow_timings_bug.py index e382f55fc70..4810ba8d81c 100644 --- a/python/packages/devui/tests/devui/test_workflow_timings_bug.py +++ b/python/packages/devui/tests/devui/test_workflow_timings_bug.py @@ -7,16 +7,17 @@ 1-second gaps between events, making instant workflows appear to take 3+ seconds. """ +from conftest import ( + create_executor_completed_event, + create_executor_invoked_event, +) + from agent_framework_devui._mapper import MessageMapper from agent_framework_devui.models._openai_custom import ( AgentFrameworkRequest, CustomResponseOutputItemAddedEvent, CustomResponseOutputItemDoneEvent, ) -from conftest import ( - create_executor_completed_event, - create_executor_invoked_event, -) def test_custom_event_models_lack_created_at_field() -> None: @@ -92,8 +93,7 @@ async def test_rapid_workflow_events_have_no_top_level_timestamps( # legacy workflow-event type so this test stays meaningful. workflow_events = [r for r in results if isinstance(r, ResponseWorkflowEventComplete)] assert not workflow_events, ( - "executor_completed should map to CustomResponseOutputItemDoneEvent, " - "not ResponseWorkflowEventComplete." + "executor_completed should map to CustomResponseOutputItemDoneEvent, not ResponseWorkflowEventComplete." ) # Confirm data.timestamp (used by the fallback legacy path) is a Python isoformat From afeca92a671d0861d3f84b6c5d4824a89b046cbd Mon Sep 17 00:00:00 2001 From: Copilot Date: Mon, 4 May 2026 04:46:35 +0000 Subject: [PATCH 6/7] devui: move timing regression tests into test_mapper.py, remove dedicated bug file - Delete test_workflow_timings_bug.py; tests belong in existing module files - The two tests already present in test_mapper.py (test_executor_events_carry_created_at_timestamp and test_custom_output_item_event_models_have_created_at_field) cover the same ground as the first two tests in the deleted file - Add test_executor_completed_maps_to_output_item_done_event to test_mapper.py, replacing the third test from the deleted file with a generic, issue-agnostic name and docstring Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- .../packages/devui/tests/devui/test_mapper.py | 29 +++++ .../tests/devui/test_workflow_timings_bug.py | 110 ------------------ 2 files changed, 29 insertions(+), 110 deletions(-) delete mode 100644 python/packages/devui/tests/devui/test_workflow_timings_bug.py diff --git a/python/packages/devui/tests/devui/test_mapper.py b/python/packages/devui/tests/devui/test_mapper.py index f174ed1d051..5ecae20c007 100644 --- a/python/packages/devui/tests/devui/test_mapper.py +++ b/python/packages/devui/tests/devui/test_mapper.py @@ -452,6 +452,35 @@ def test_custom_output_item_event_models_have_created_at_field() -> None: ) +async def test_executor_completed_maps_to_output_item_done_event( + mapper: MessageMapper, test_request: AgentFrameworkRequest +) -> None: + """Test executor_completed events are mapped to CustomResponseOutputItemDoneEvent. + + Ensures executor_completed does not fall through to the legacy + ResponseWorkflowEventComplete path, which lacks a top-level created_at field. + """ + from agent_framework_devui.models._openai_custom import ResponseWorkflowEventComplete + + invoke_event = create_executor_invoked_event(executor_id="exec_output_item") + await mapper.convert_event(invoke_event, test_request) + + complete_event = create_executor_completed_event(executor_id="exec_output_item") + results = await mapper.convert_event(complete_event, test_request) + + assert results, "mapper.convert_event should return events for executor_completed" + + workflow_events = [r for r in results if isinstance(r, ResponseWorkflowEventComplete)] + assert not workflow_events, ( + "executor_completed should map to CustomResponseOutputItemDoneEvent, not ResponseWorkflowEventComplete." + ) + + output_item_done = [r for r in results if r.type == "response.output_item.done"] + assert output_item_done, ( + f"Expected at least one response.output_item.done event; got: {[r.type for r in results]}" + ) + + # ============================================================================= # Workflow Lifecycle Event Tests # ============================================================================= diff --git a/python/packages/devui/tests/devui/test_workflow_timings_bug.py b/python/packages/devui/tests/devui/test_workflow_timings_bug.py deleted file mode 100644 index 4810ba8d81c..00000000000 --- a/python/packages/devui/tests/devui/test_workflow_timings_bug.py +++ /dev/null @@ -1,110 +0,0 @@ -# Copyright (c) Microsoft. All rights reserved. - -"""Regression tests for GitHub issue #5545: Workflow timings in DevUI are incorrect. - -CustomResponseOutputItemAddedEvent and CustomResponseOutputItemDoneEvent lack a -`created_at` field, causing the frontend to synthesize timestamps with forced -1-second gaps between events, making instant workflows appear to take 3+ seconds. -""" - -from conftest import ( - create_executor_completed_event, - create_executor_invoked_event, -) - -from agent_framework_devui._mapper import MessageMapper -from agent_framework_devui.models._openai_custom import ( - AgentFrameworkRequest, - CustomResponseOutputItemAddedEvent, - CustomResponseOutputItemDoneEvent, -) - - -def test_custom_event_models_lack_created_at_field() -> None: - """REGRESSION (#5545): CustomResponseOutputItemAddedEvent and Done must declare created_at. - - Before the fix, both models were missing this field. The frontend timestamp - extraction code reads `event.created_at` (number) as its first priority source. - Without the field the frontend fell through to the synthesised-timestamp path, - forcing a minimum 1-second gap between every pair of consecutive events. - """ - assert "created_at" in CustomResponseOutputItemAddedEvent.model_fields, ( - "CustomResponseOutputItemAddedEvent is missing 'created_at'. " - "The frontend uses this field for accurate workflow timeline timings." - ) - assert "created_at" in CustomResponseOutputItemDoneEvent.model_fields, ( - "CustomResponseOutputItemDoneEvent is missing 'created_at'. " - "The frontend uses this field for accurate workflow timeline timings." - ) - - -async def test_workflow_executor_events_lack_created_at( - mapper: MessageMapper, test_request: AgentFrameworkRequest -) -> None: - """REGRESSION (#5545): mapper.convert_event() must populate created_at on executor events. - - Before the fix, executor_invoked and executor_completed events were emitted - without a `created_at` value. The frontend then synthesised a timestamp using - Math.max(baseTimestamp, lastTimestamp + 1) — a forced +1 s gap — causing - instant workflows to appear to take multiple seconds in the DevUI timeline. - """ - invoke_event = create_executor_invoked_event(executor_id="exec_timing") - complete_event = create_executor_completed_event(executor_id="exec_timing") - - invoked_results = await mapper.convert_event(invoke_event, test_request) - completed_results = await mapper.convert_event(complete_event, test_request) - - for label, results in [ - ("executor_invoked", invoked_results), - ("executor_completed", completed_results), - ]: - assert results, f"mapper.convert_event() returned no events for {label}" - for event in results: - assert getattr(event, "created_at", None) is not None, ( - f"{label} event {type(event).__name__} is missing 'created_at'. " - "The frontend relies on this field to avoid forced 1-second gaps." - ) - assert event.created_at > 0, ( - f"{label} event {type(event).__name__} has non-positive created_at " - f"({event.created_at!r}); expected a valid Unix timestamp." - ) - - -async def test_rapid_workflow_events_have_no_top_level_timestamps( - mapper: MessageMapper, test_request: AgentFrameworkRequest -) -> None: - """REGRESSION (#5545): response.workflow_event.completed events carry no top-level created_at. - - These events embed their timing in `data.timestamp` as a Python isoformat() - string. The frontend must parse that string safely — Python's isoformat() - emits microseconds without a trailing 'Z', which some JS environments cannot - parse, returning NaN. This test confirms the backend format so that the - frontend NaN-guard (Number.isFinite) is tested against the real payload shape. - """ - from agent_framework_devui.models._openai_custom import ResponseWorkflowEventComplete - - invoke_event = create_executor_invoked_event(executor_id="exec_rapid") - await mapper.convert_event(invoke_event, test_request) - complete_event = create_executor_completed_event(executor_id="exec_rapid") - results = await mapper.convert_event(complete_event, test_request) - - # executor_completed is mapped to CustomResponseOutputItemDoneEvent (has created_at), - # NOT to ResponseWorkflowEventComplete. Confirm none of the results are the - # legacy workflow-event type so this test stays meaningful. - workflow_events = [r for r in results if isinstance(r, ResponseWorkflowEventComplete)] - assert not workflow_events, ( - "executor_completed should map to CustomResponseOutputItemDoneEvent, not ResponseWorkflowEventComplete." - ) - - # Confirm data.timestamp (used by the fallback legacy path) is a Python isoformat - # string — no trailing Z, up to 6 fractional digits — so the frontend NaN-guard - # is tested against the real emitted format. - from datetime import datetime - - sample_ts = datetime.now().isoformat() - assert "T" in sample_ts, "isoformat() must include time separator" - # Python isoformat does NOT include Z or +00:00 by default - assert not sample_ts.endswith("Z"), ( - "Python datetime.now().isoformat() must not end with Z; " - "this confirms the frontend needs a Number.isFinite guard." - ) From eb30420253c0ecc9a32558b326abb2c71752126f Mon Sep 17 00:00:00 2001 From: Copilot Date: Mon, 4 May 2026 04:51:22 +0000 Subject: [PATCH 7/7] Address review feedback for #5545: review comment fixes --- python/packages/devui/tests/devui/test_mapper.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/python/packages/devui/tests/devui/test_mapper.py b/python/packages/devui/tests/devui/test_mapper.py index 5ecae20c007..b26900a89f5 100644 --- a/python/packages/devui/tests/devui/test_mapper.py +++ b/python/packages/devui/tests/devui/test_mapper.py @@ -476,9 +476,7 @@ async def test_executor_completed_maps_to_output_item_done_event( ) output_item_done = [r for r in results if r.type == "response.output_item.done"] - assert output_item_done, ( - f"Expected at least one response.output_item.done event; got: {[r.type for r in results]}" - ) + assert output_item_done, f"Expected at least one response.output_item.done event; got: {[r.type for r in results]}" # =============================================================================