From 087c9c1f1fff9179a1c99bf4f05f4b329f1b459a Mon Sep 17 00:00:00 2001 From: Eric Traut Date: Tue, 28 Apr 2026 09:24:29 -0700 Subject: [PATCH] TUI: use cumulative turn duration for worked-for separator (#19929) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Why Fixes #19814. The TUI's current `Worked for ...` timing behavior is a leftover from #9599. At that point, models could emit multiple assistant messages in one turn for preambles/commentary, but the TUI did not yet have a reliable signal that an assistant message was the final answer when it started streaming. To avoid showing an ever-growing elapsed time on each preamble separator, #9599 made the separator timer incremental by tracking elapsed time since the previous separator. That workaround is no longer the right model for the final completed-turn display. Since then, #16638 added protocol-native turn timing, including `duration_ms` on turn completion. With that cumulative duration available at the point where the TUI renders the completed-turn separator, the UI can show the actual turn duration directly instead of carrying per-separator timing state. ## What Changed - Thread `duration_ms` into `ChatWidget::on_task_complete` from both legacy `TurnCompleteEvent` handling and app-server `TurnCompleted` notifications. - Use `duration_ms` for the final `Worked for ...` separator, falling back to the status indicator timer only when the protocol duration is unavailable. - Keep mid-turn separators before later assistant text as plain visual dividers instead of clocked `Worked for ...` separators. - Remove the old incremental separator timer state and helper (`last_separator_elapsed_secs` / `worked_elapsed_from`). - Add a snapshot regression test for a turn that runs a command and then completes with a final answer, verifying the final separator uses the cumulative turn duration. ## Verification - `cargo test -p codex-tui final_worked_for_uses_cumulative_turn_duration_snapshot` - `just fix -p codex-tui` Manual repro prompt: ```text Manual timing repro. First send a short preamble/commentary sentence before using tools. Then run exactly this shell command: sleep 75; echo MANUAL_TIMING_DONE. After the command finishes, give a final answer that says "done". Do not skip the preamble. ``` After this change, the mid-turn break before the final answer should be a plain divider, and the final completed-turn separator should show `Worked for ...` using the cumulative turn duration. Before: Screenshot 2026-04-27 at 10 09 01 PM After: Screenshot 2026-04-27 at 10 09 07 PM --- codex-rs/tui/src/chatwidget.rs | 66 ++++++++----------- ...ked_for_uses_cumulative_turn_duration.snap | 12 ++++ .../tui/src/chatwidget/tests/exec_flow.rs | 58 +++++++++++++++- codex-rs/tui/src/chatwidget/tests/helpers.rs | 1 - .../tui/src/chatwidget/tests/plan_mode.rs | 26 ++++++-- .../src/chatwidget/tests/status_and_layout.rs | 14 +--- codex-rs/tui/src/history_cell.rs | 2 +- 7 files changed, 121 insertions(+), 58 deletions(-) create mode 100644 codex-rs/tui/src/chatwidget/snapshots/codex_tui__chatwidget__tests__final_worked_for_uses_cumulative_turn_duration.snap diff --git a/codex-rs/tui/src/chatwidget.rs b/codex-rs/tui/src/chatwidget.rs index 83cb972c7..6c9b57729 100644 --- a/codex-rs/tui/src/chatwidget.rs +++ b/codex-rs/tui/src/chatwidget.rs @@ -1002,13 +1002,12 @@ pub(crate) struct ChatWidget { // Whether the next streamed assistant content should be preceded by a final message separator. // // This is set whenever we insert a visible history cell that conceptually belongs to a turn. - // The separator itself is only rendered if the turn recorded "work" activity (see - // `had_work_activity`). + // The separator itself is only rendered if the turn recorded "work" activity. needs_final_message_separator: bool, // Whether the current turn performed "work" (exec commands, MCP tool calls, patch applications). // // This gates rendering of the "Worked for …" separator so purely conversational turns don't - // show an empty divider. It is reset when the separator is emitted. + // show an empty divider. had_work_activity: bool, // Whether the current turn emitted a plan update. saw_plan_update_this_turn: bool, @@ -1022,11 +1021,6 @@ pub(crate) struct ChatWidget { plan_delta_buffer: String, // True while a plan item is streaming. plan_item_active: bool, - // Status-indicator elapsed seconds captured at the last emitted final-message separator. - // - // This lets the separator show per-chunk work time (since the previous separator) rather than - // the total task-running time reported by the status indicator. - last_separator_elapsed_secs: Option, // Runtime metrics accumulated across delta snapshots for the active turn. turn_runtime_metrics: RuntimeMetricsSummary, last_rendered_width: std::cell::Cell>, @@ -2727,6 +2721,7 @@ impl ChatWidget { self.saw_copy_source_this_turn = false; self.saw_plan_update_this_turn = false; self.saw_plan_item_this_turn = false; + self.had_work_activity = false; self.latest_proposed_plan_markdown = None; self.plan_delta_buffer.clear(); self.plan_item_active = false; @@ -2752,7 +2747,12 @@ impl ChatWidget { self.request_redraw(); } - fn on_task_complete(&mut self, last_agent_message: Option, from_replay: bool) { + fn on_task_complete( + &mut self, + last_agent_message: Option, + duration_ms: Option, + from_replay: bool, + ) { self.submit_pending_steers_after_interrupt = false; // Use `last_agent_message` from the turn-complete notification as the copy // source only when no earlier item-level event (AgentMessageItem, plan @@ -2797,13 +2797,18 @@ impl ChatWidget { self.collect_runtime_metrics_delta(); let runtime_metrics = (!self.turn_runtime_metrics.is_empty()).then_some(self.turn_runtime_metrics); - let show_work_separator = self.needs_final_message_separator && self.had_work_activity; + let show_work_separator = self.had_work_activity + && (self.needs_final_message_separator || runtime_metrics.is_some()); if show_work_separator || runtime_metrics.is_some() { let elapsed_seconds = if show_work_separator { - self.bottom_pane - .status_widget() - .map(super::status_indicator_widget::StatusIndicatorWidget::elapsed_seconds) - .map(|current| self.worked_elapsed_from(current)) + duration_ms + .and_then(|duration_ms| u64::try_from(duration_ms).ok()) + .map(|duration_ms| duration_ms / 1_000) + .or_else(|| { + self.bottom_pane + .status_widget() + .map(super::status_indicator_widget::StatusIndicatorWidget::elapsed_seconds) + }) } else { None }; @@ -5034,17 +5039,10 @@ impl ChatWidget { // If the previous turn inserted non-stream history (exec output, patch status, MCP // calls), render a separator before starting the next streamed assistant message. if self.needs_final_message_separator && self.had_work_activity { - let elapsed_seconds = self - .bottom_pane - .status_widget() - .map(super::status_indicator_widget::StatusIndicatorWidget::elapsed_seconds) - .map(|current| self.worked_elapsed_from(current)); self.add_to_history(history_cell::FinalMessageSeparator::new( - elapsed_seconds, - /*runtime_metrics*/ None, + /*elapsed_seconds*/ None, /*runtime_metrics*/ None, )); self.needs_final_message_separator = false; - self.had_work_activity = false; } else if self.needs_final_message_separator { // Reset the flag even if we don't show separator (no work was done) self.needs_final_message_separator = false; @@ -5063,17 +5061,6 @@ impl ChatWidget { self.request_redraw(); } - fn worked_elapsed_from(&mut self, current_elapsed: u64) -> u64 { - let baseline = match self.last_separator_elapsed_secs { - Some(last) if current_elapsed < last => 0, - Some(last) => last, - None => 0, - }; - let elapsed = current_elapsed.saturating_sub(baseline); - self.last_separator_elapsed_secs = Some(current_elapsed); - elapsed - } - /// Finalizes an exec call while preserving the active exec cell grouping contract. /// /// Exec begin/end events usually pair through `running_commands`, but unified exec can emit an @@ -5631,7 +5618,6 @@ impl ChatWidget { last_plan_progress: None, plan_delta_buffer: String::new(), plan_item_active: false, - last_separator_elapsed_secs: None, turn_runtime_metrics: RuntimeMetricsSummary::default(), last_rendered_width: std::cell::Cell::new(None), feedback, @@ -7295,7 +7281,11 @@ impl ChatWidget { match notification.turn.status { TurnStatus::Completed => { self.last_non_retry_error = None; - self.on_task_complete(/*last_agent_message*/ None, replay_kind.is_some()) + self.on_task_complete( + /*last_agent_message*/ None, + notification.turn.duration_ms, + replay_kind.is_some(), + ) } TurnStatus::Interrupted => { self.last_non_retry_error = None; @@ -7646,9 +7636,11 @@ impl ChatWidget { } } EventMsg::TurnComplete(TurnCompleteEvent { - last_agent_message, .. + last_agent_message, + duration_ms, + .. }) => { - self.on_task_complete(last_agent_message, from_replay); + self.on_task_complete(last_agent_message, duration_ms, from_replay); } EventMsg::TokenCount(ev) => { self.set_token_info(ev.info); diff --git a/codex-rs/tui/src/chatwidget/snapshots/codex_tui__chatwidget__tests__final_worked_for_uses_cumulative_turn_duration.snap b/codex-rs/tui/src/chatwidget/snapshots/codex_tui__chatwidget__tests__final_worked_for_uses_cumulative_turn_duration.snap new file mode 100644 index 000000000..b0d5db920 --- /dev/null +++ b/codex-rs/tui/src/chatwidget/snapshots/codex_tui__chatwidget__tests__final_worked_for_uses_cumulative_turn_duration.snap @@ -0,0 +1,12 @@ +--- +source: tui/src/chatwidget/tests/exec_flow.rs +expression: combined +--- +• Ran echo preparing + └ preparing + +──────────────────────────────────────────────────────────────────────────────── + +• Final response. + +─ Worked for 2m 05s ──────────────────────────────────────────────────────────── diff --git a/codex-rs/tui/src/chatwidget/tests/exec_flow.rs b/codex-rs/tui/src/chatwidget/tests/exec_flow.rs index ec1d03f9f..d3d5de1f1 100644 --- a/codex-rs/tui/src/chatwidget/tests/exec_flow.rs +++ b/codex-rs/tui/src/chatwidget/tests/exec_flow.rs @@ -598,7 +598,9 @@ async fn unified_exec_end_after_task_complete_is_suppressed() { ); drain_insert_history(&mut rx); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); end_exec(&mut chat, begin, "", "", /*exit_code*/ 0); let cells = drain_insert_history(&mut rx); @@ -612,7 +614,9 @@ async fn unified_exec_end_after_task_complete_is_suppressed() { async fn unified_exec_interaction_after_task_complete_is_suppressed() { let (mut chat, mut rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await; chat.on_task_started(); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); chat.handle_codex_event(Event { id: "call-1".to_string(), @@ -712,6 +716,56 @@ async fn unified_exec_wait_before_streamed_agent_message_snapshot() { assert_chatwidget_snapshot!("unified_exec_wait_before_streamed_agent_message", combined); } +#[tokio::test] +async fn final_worked_for_uses_cumulative_turn_duration_snapshot() { + let (mut chat, mut rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await; + chat.handle_codex_event(Event { + id: "turn-1".into(), + msg: EventMsg::TurnStarted(TurnStartedEvent { + turn_id: "turn-1".to_string(), + started_at: None, + model_context_window: None, + collaboration_mode_kind: ModeKind::Default, + }), + }); + + let exec = begin_exec_with_source( + &mut chat, + "call-1", + "echo preparing", + ExecCommandSource::Agent, + ); + end_exec(&mut chat, exec, "preparing\n", "", /*exit_code*/ 0); + + complete_assistant_message( + &mut chat, + "msg-final", + "Final response.", + Some(MessagePhase::FinalAnswer), + ); + chat.handle_codex_event(Event { + id: "turn-1".into(), + msg: EventMsg::TurnComplete(TurnCompleteEvent { + turn_id: "turn-1".to_string(), + last_agent_message: Some("Final response.".to_string()), + completed_at: None, + duration_ms: Some(125_000), + time_to_first_token_ms: None, + }), + }); + + let cells = drain_insert_history(&mut rx); + let combined = cells + .iter() + .map(|lines| lines_to_single_string(lines)) + .collect::(); + assert!( + combined.contains("Worked for 2m 05s"), + "expected final separator to use cumulative turn duration, got:\n{combined}" + ); + assert_chatwidget_snapshot!("final_worked_for_uses_cumulative_turn_duration", combined); +} + #[tokio::test] async fn unified_exec_wait_status_header_updates_on_late_command_display() { let (mut chat, _rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await; diff --git a/codex-rs/tui/src/chatwidget/tests/helpers.rs b/codex-rs/tui/src/chatwidget/tests/helpers.rs index d68a03e8b..b9a223c88 100644 --- a/codex-rs/tui/src/chatwidget/tests/helpers.rs +++ b/codex-rs/tui/src/chatwidget/tests/helpers.rs @@ -292,7 +292,6 @@ pub(super) async fn make_chatwidget_manual( last_plan_progress: None, plan_delta_buffer: String::new(), plan_item_active: false, - last_separator_elapsed_secs: None, turn_runtime_metrics: RuntimeMetricsSummary::default(), last_rendered_width: std::cell::Cell::new(None), feedback: codex_feedback::CodexFeedback::new(), diff --git a/codex-rs/tui/src/chatwidget/tests/plan_mode.rs b/codex-rs/tui/src/chatwidget/tests/plan_mode.rs index c6e1f7376..dbe580e5c 100644 --- a/codex-rs/tui/src/chatwidget/tests/plan_mode.rs +++ b/codex-rs/tui/src/chatwidget/tests/plan_mode.rs @@ -771,7 +771,11 @@ async fn plan_implementation_popup_skips_when_messages_queued() { chat.bottom_pane.set_task_running(/*running*/ true); chat.queue_user_message("Queued message".into()); - chat.on_task_complete(Some("Plan details".to_string()), /*from_replay*/ false); + chat.on_task_complete( + Some("Plan details".to_string()), + /*duration_ms*/ None, + /*from_replay*/ false, + ); let popup = render_bottom_popup(&chat, /*width*/ 80); assert!( @@ -796,7 +800,9 @@ async fn plan_implementation_popup_skips_without_proposed_plan() { status: StepStatus::Pending, }], }); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); let popup = render_bottom_popup(&chat, /*width*/ 80); assert!( @@ -816,7 +822,9 @@ async fn plan_implementation_popup_shows_after_proposed_plan_output() { chat.on_task_started(); chat.on_plan_delta("- Step 1\n- Step 2\n".to_string()); chat.on_plan_item_completed("- Step 1\n- Step 2\n".to_string()); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); let popup = render_bottom_popup(&chat, /*width*/ 80); assert!( @@ -857,7 +865,9 @@ async fn plan_implementation_popup_skips_when_steer_follows_proposed_plan() { } complete_user_message(&mut chat, "user-1", "Please continue."); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); let popup = render_bottom_popup(&chat, /*width*/ 80); assert!( @@ -902,7 +912,9 @@ async fn plan_implementation_popup_shows_after_new_plan_follows_steer() { " .to_string(), ); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); let popup = render_bottom_popup(&chat, /*width*/ 80); assert!( @@ -929,7 +941,9 @@ async fn plan_implementation_popup_skips_when_rate_limit_prompt_pending() { }], }); chat.on_rate_limit_snapshot(Some(snapshot(/*percent*/ 92.0))); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); let popup = render_bottom_popup(&chat, /*width*/ 80); assert!( diff --git a/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs b/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs index 19890a5d3..e812e6929 100644 --- a/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs +++ b/codex-rs/tui/src/chatwidget/tests/status_and_layout.rs @@ -199,16 +199,6 @@ async fn prefetch_rate_limits_is_gated_on_chatgpt_auth_provider() { assert!(!chat.should_prefetch_rate_limits()); } -#[tokio::test] -async fn worked_elapsed_from_resets_when_timer_restarts() { - let (mut chat, _rx, _op_rx) = make_chatwidget_manual(/*model_override*/ None).await; - assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 5), 5); - assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 9), 4); - // Simulate status timer resetting (e.g., status indicator recreated for a new task). - assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 3), 3); - assert_eq!(chat.worked_elapsed_from(/*current_elapsed*/ 7), 4); -} - #[tokio::test] async fn rate_limit_warnings_emit_thresholds() { let mut state = RateLimitWarningState::default(); @@ -1933,7 +1923,9 @@ async fn runtime_metrics_websocket_timing_logs_and_final_separator_sums_totals() .expect("expected websocket timing log"); assert!(second_log.contains("TTFT: 80ms (iapi)")); - chat.on_task_complete(/*last_agent_message*/ None, /*from_replay*/ false); + chat.on_task_complete( + /*last_agent_message*/ None, /*duration_ms*/ None, /*from_replay*/ false, + ); let mut final_separator = None; while let Ok(event) = rx.try_recv() { if let AppEvent::InsertHistoryCell(cell) = event { diff --git a/codex-rs/tui/src/history_cell.rs b/codex-rs/tui/src/history_cell.rs index af77b6ecb..9d009a93f 100644 --- a/codex-rs/tui/src/history_cell.rs +++ b/codex-rs/tui/src/history_cell.rs @@ -2825,7 +2825,7 @@ pub struct FinalMessageSeparator { runtime_metrics: Option, } impl FinalMessageSeparator { - /// Creates a separator; `elapsed_seconds` typically comes from the status indicator timer. + /// Creates a separator; completed turns should pass protocol turn duration when available. pub(crate) fn new( elapsed_seconds: Option, runtime_metrics: Option,