Include start times in terminal turn events (#32263)

## What changed

- Add an optional `started_at` Unix timestamp to `TurnCompleteEvent` and
  `TurnAbortedEvent`.
- Populate the timestamp from turn timing state when a turn completes or is
  aborted.
- Preserve the timestamp when synthesizing interrupted fork history and when
  importing external sessions.

## Testing

- Verify that interrupting a turn emits a `TurnAbortedEvent` with a start
  timestamp.

GitOrigin-RevId: 75b3911b95c060e5fc1843a5e293d8fe47377186
This commit is contained in:
Owen Lin
2026-07-10 20:25:03 +00:00
committed by copyberry
parent b66c25c6a3
commit bca577d69a
20 changed files with 144 additions and 7 deletions
@@ -1760,6 +1760,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-1".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1818,6 +1819,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-1".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1920,6 +1922,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1971,6 +1974,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -2023,6 +2027,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -2086,6 +2091,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -2154,6 +2160,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -2232,6 +2239,7 @@ mod tests {
})),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-image".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -2344,6 +2352,7 @@ mod tests {
}),
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some("turn-1".into()),
started_at: None,
reason: TurnAbortReason::Replaced,
completed_at: None,
duration_ms: None,
@@ -2583,6 +2592,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3151,6 +3161,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3193,6 +3204,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-b".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3249,6 +3261,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3291,6 +3304,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-b".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3479,6 +3493,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3501,6 +3516,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3513,6 +3529,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-b".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3551,6 +3568,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3573,6 +3591,7 @@ mod tests {
}),
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some("turn-a".into()),
started_at: None,
reason: TurnAbortReason::Replaced,
completed_at: None,
duration_ms: None,
@@ -3616,6 +3635,7 @@ mod tests {
}),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-compact".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3878,6 +3898,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3943,6 +3964,7 @@ mod tests {
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3998,6 +4020,7 @@ mod tests {
RolloutItem::ResponseItem(hook_prompt),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -4079,6 +4102,7 @@ mod tests {
}),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -4244,6 +4268,7 @@ mod tests {
let complete_changes = builder.handle_rollout_item_with_changes(&RolloutItem::EventMsg(
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: Some(20),
duration_ms: Some(123),
@@ -4324,6 +4349,7 @@ mod tests {
})),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-a".into(),
started_at: None,
last_agent_message: None,
completed_at: Some(20),
duration_ms: Some(123),
@@ -2191,6 +2191,7 @@ mod tests {
fn turn_complete_event(turn_id: &str) -> TurnCompleteEvent {
TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: Some(TEST_TURN_COMPLETED_AT),
duration_ms: Some(TEST_TURN_DURATION_MS),
@@ -2201,6 +2202,7 @@ mod tests {
fn turn_aborted_event(turn_id: &str) -> TurnAbortedEvent {
TurnAbortedEvent {
turn_id: Some(turn_id.to_string()),
started_at: None,
reason: codex_protocol::protocol::TurnAbortReason::Interrupted,
completed_at: Some(TEST_TURN_COMPLETED_AT),
duration_ms: Some(TEST_TURN_DURATION_MS),
@@ -2268,6 +2268,7 @@ async fn thread_resume_token_usage_replay_can_belong_to_interrupted_turn() -> Re
"type": "event_msg",
"payload": serde_json::to_value(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(interrupted_turn_id.to_string()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -159,6 +159,7 @@ async fn mark_thread_completed(thread: &CodexThread) {
turn.as_ref(),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn.sub_id.clone(),
started_at: None,
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
@@ -178,6 +179,7 @@ async fn mark_thread_interrupted(thread: &CodexThread) {
turn.as_ref(),
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(turn.sub_id.clone()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
+4
View File
@@ -349,6 +349,7 @@ async fn on_event_updates_status_from_task_started() {
async fn on_event_updates_status_from_task_complete() {
let status = agent_status_from_event(&EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-1".to_string(),
started_at: None,
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
@@ -373,6 +374,7 @@ async fn on_event_updates_status_from_error() {
async fn on_event_updates_status_from_turn_aborted() {
let status = agent_status_from_event(&EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some("turn-1".to_string()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -2025,6 +2027,7 @@ async fn multi_agent_v2_completion_ignores_dead_direct_parent() {
tester_turn.as_ref(),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: tester_turn.sub_id.clone(),
started_at: None,
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
@@ -2112,6 +2115,7 @@ async fn multi_agent_v2_completion_queues_message_for_direct_parent() {
tester_turn.as_ref(),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: tester_turn.sub_id.clone(),
started_at: None,
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
@@ -56,6 +56,7 @@ async fn forward_events_filters_private_events_before_blocked_send_is_cancelled(
id: "full".to_string(),
msg: EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some("turn-1".to_string()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1177,6 +1177,7 @@ mod tests {
id: turn_id.to_string(),
msg: EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: last_agent_message.map(str::to_string),
completed_at: None,
duration_ms: None,
@@ -1190,6 +1191,7 @@ mod tests {
id: turn_id.to_string(),
msg: EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(turn_id.to_string()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
+1
View File
@@ -2229,6 +2229,7 @@ async fn guardian_reused_trunk_ignores_stale_prior_turn_completion() -> anyhow::
id: "stale-turn".to_string(),
msg: EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "stale-turn".to_string(),
started_at: None,
last_agent_message: Some(
"{\"risk_level\":\"high\",\"user_authorization\":\"low\",\"outcome\":\"deny\",\"rationale\":\"stale guardian rationale\"}"
.to_string(),
@@ -97,6 +97,7 @@ fn completed_user_turn_rollout(
codex_protocol::protocol::TurnCompleteEvent {
turn_id,
last_agent_message: None,
started_at: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
@@ -265,6 +266,7 @@ async fn record_initial_history_resumed_hydrates_previous_turn_settings_from_lif
codex_protocol::protocol::TurnCompleteEvent {
turn_id,
last_agent_message: None,
started_at: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
@@ -339,6 +341,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_com
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -373,6 +376,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_com
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: rolled_back_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -452,6 +456,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_inc
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -549,6 +554,7 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -579,6 +585,7 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: second_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -598,6 +605,7 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: standalone_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -675,6 +683,7 @@ async fn reconstruct_history_rollback_counts_inter_agent_assistant_turns() {
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -696,6 +705,7 @@ async fn reconstruct_history_rollback_counts_inter_agent_assistant_turns() {
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: assistant_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -768,6 +778,7 @@ async fn reconstruct_history_rollback_clears_history_and_metadata_when_exceeding
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: only_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -821,6 +832,7 @@ async fn record_initial_history_resumed_rollback_skips_only_user_turns() {
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: user_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -840,6 +852,7 @@ async fn record_initial_history_resumed_rollback_skips_only_user_turns() {
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: standalone_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -897,6 +910,7 @@ async fn record_initial_history_resumed_rollback_drops_incomplete_user_turn_comp
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1226,6 +1240,7 @@ async fn reconstruct_history_legacy_compaction_without_replacement_history_clear
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: current_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1306,6 +1321,7 @@ async fn record_initial_history_resumed_turn_context_after_compaction_reestablis
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1418,6 +1434,7 @@ async fn record_initial_history_resumed_aborted_turn_without_id_clears_active_tu
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1446,6 +1463,7 @@ async fn record_initial_history_resumed_aborted_turn_without_id_clears_active_tu
RolloutItem::EventMsg(EventMsg::TurnAborted(
codex_protocol::protocol::TurnAbortedEvent {
turn_id: None,
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1540,6 +1558,7 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1568,6 +1587,7 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo
RolloutItem::EventMsg(EventMsg::TurnAborted(
codex_protocol::protocol::TurnAbortedEvent {
turn_id: Some(unmatched_abort_turn_id),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1577,6 +1597,7 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: current_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1667,6 +1688,7 @@ async fn record_initial_history_resumed_trailing_incomplete_turn_compaction_clea
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1836,6 +1858,7 @@ async fn record_initial_history_resumed_replaced_incomplete_compacted_turn_clear
RolloutItem::EventMsg(EventMsg::TurnComplete(
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
+11
View File
@@ -486,6 +486,7 @@ async fn interrupting_regular_turn_waiting_on_startup_prewarm_emits_turn_aborted
let EventMsg::TurnAborted(TurnAbortedEvent {
turn_id,
reason,
started_at,
completed_at,
duration_ms,
}) = second.msg
@@ -494,6 +495,7 @@ async fn interrupting_regular_turn_waiting_on_startup_prewarm_emits_turn_aborted
};
assert_eq!(turn_id, Some(tc.sub_id.clone()));
assert_eq!(reason, TurnAbortReason::Interrupted);
assert!(started_at.is_some());
assert!(completed_at.is_some());
assert!(duration_ms.is_some());
}
@@ -3134,6 +3136,7 @@ async fn record_initial_history_forked_hydrates_previous_turn_settings() {
codex_protocol::protocol::TurnCompleteEvent {
turn_id,
last_agent_message: None,
started_at: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
@@ -3333,6 +3336,7 @@ async fn thread_rollback_recomputes_previous_turn_settings_and_reference_context
RolloutItem::ResponseItem(turn_one_assistant.clone()),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: first_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3362,6 +3366,7 @@ async fn thread_rollback_recomputes_previous_turn_settings_and_reference_context
RolloutItem::ResponseItem(turn_two_assistant),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: rolled_back_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3451,6 +3456,7 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio
RolloutItem::ResponseItem(assistant_message("turn 1 assistant")),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: first_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3475,6 +3481,7 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio
}),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: compact_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3507,6 +3514,7 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio
RolloutItem::ResponseItem(assistant_message("turn 2 assistant")),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: rolled_back_turn_id,
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3580,6 +3588,7 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() {
RolloutItem::ResponseItem(assistant_message("turn 1 assistant")),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-1".to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3607,6 +3616,7 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() {
RolloutItem::ResponseItem(assistant_message("turn 2 assistant")),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-2".to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -3634,6 +3644,7 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() {
RolloutItem::ResponseItem(assistant_message("turn 3 assistant")),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-3".to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
+9
View File
@@ -740,6 +740,7 @@ impl Session {
turn_context.config.memories.use_memories,
turn_had_memory_citation,
);
let started_at = turn_context.turn_timing_state.started_at_unix_secs().await;
let (completed_at, duration_ms) = turn_context
.turn_timing_state
.completed_at_and_duration_ms()
@@ -756,6 +757,7 @@ impl Session {
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(turn_context.sub_id.clone()),
reason,
started_at,
completed_at,
duration_ms,
})
@@ -769,6 +771,7 @@ impl Session {
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_context.sub_id.clone(),
last_agent_message,
started_at,
completed_at,
duration_ms,
time_to_first_token_ms,
@@ -877,6 +880,11 @@ impl Session {
}
}
let started_at = task
.turn_context
.turn_timing_state
.started_at_unix_secs()
.await;
let (completed_at, duration_ms) = task
.turn_context
.turn_timing_state
@@ -891,6 +899,7 @@ impl Session {
let event = EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(task.turn_context.sub_id.clone()),
reason,
started_at,
completed_at,
duration_ms,
});
+8
View File
@@ -1786,6 +1786,7 @@ fn truncate_before_nth_user_message(
struct SnapshotTurnState {
ends_mid_turn: bool,
active_turn_id: Option<String>,
active_turn_started_at: Option<i64>,
active_turn_start_index: Option<usize>,
}
@@ -1805,6 +1806,7 @@ fn snapshot_turn_state(history: &InitialHistory) -> SnapshotTurnState {
return SnapshotTurnState {
ends_mid_turn: false,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
};
}
@@ -1812,6 +1814,7 @@ fn snapshot_turn_state(history: &InitialHistory) -> SnapshotTurnState {
return SnapshotTurnState {
ends_mid_turn: true,
active_turn_id,
active_turn_started_at: active_turn_snapshot.and_then(|turn| turn.started_at),
active_turn_start_index: builder.active_turn_start_index(),
};
}
@@ -1823,6 +1826,7 @@ fn snapshot_turn_state(history: &InitialHistory) -> SnapshotTurnState {
return SnapshotTurnState {
ends_mid_turn: false,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
};
};
@@ -1838,6 +1842,7 @@ fn snapshot_turn_state(history: &InitialHistory) -> SnapshotTurnState {
)
}),
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
}
}
@@ -1865,6 +1870,7 @@ fn fork_history_from_snapshot(
append_interrupted_boundary(
history,
snapshot_state.active_turn_id,
snapshot_state.active_turn_started_at,
interrupted_marker,
)
} else {
@@ -1880,11 +1886,13 @@ fn fork_history_from_snapshot(
fn append_interrupted_boundary(
history: InitialHistory,
turn_id: Option<String>,
started_at: Option<i64>,
interrupted_marker: InterruptedTurnHistoryMarker,
) -> InitialHistory {
let aborted_event = RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id,
reason: TurnAbortReason::Interrupted,
started_at,
completed_at: None,
duration_ms: None,
}));
+20
View File
@@ -199,6 +199,7 @@ fn truncates_before_requested_user_message() {
&SnapshotTurnState {
ends_mid_turn: false,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
},
);
@@ -224,6 +225,7 @@ fn truncates_before_requested_user_message() {
&SnapshotTurnState {
ends_mid_turn: false,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
},
);
@@ -248,6 +250,7 @@ fn out_of_range_truncation_drops_only_unfinished_suffix_mid_turn() {
&SnapshotTurnState {
ends_mid_turn: true,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
},
);
@@ -299,6 +302,7 @@ fn out_of_range_truncation_drops_pre_user_active_turn_prefix() {
SnapshotTurnState {
ends_mid_turn: true,
active_turn_id: Some("turn-2".to_string()),
active_turn_started_at: None,
active_turn_start_index: Some(2),
},
);
@@ -340,6 +344,7 @@ async fn ignores_session_prefix_messages_when_truncating() {
&SnapshotTurnState {
ends_mid_turn: false,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
},
);
@@ -1379,6 +1384,7 @@ fn interrupted_fork_snapshot_appends_interrupt_boundary() {
append_interrupted_boundary(
committed_history,
/*turn_id*/ None,
/*started_at*/ None,
InterruptedTurnHistoryMarker::ContextualUser,
)
.get_rollout_items()
@@ -1389,6 +1395,7 @@ fn interrupted_fork_snapshot_appends_interrupt_boundary() {
RolloutItem::ResponseItem(contextual_user_interrupted_marker()),
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: None,
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1401,6 +1408,7 @@ fn interrupted_fork_snapshot_appends_interrupt_boundary() {
append_interrupted_boundary(
InitialHistory::New,
/*turn_id*/ None,
/*started_at*/ None,
InterruptedTurnHistoryMarker::ContextualUser,
)
.get_rollout_items()
@@ -1410,6 +1418,7 @@ fn interrupted_fork_snapshot_appends_interrupt_boundary() {
RolloutItem::ResponseItem(contextual_user_interrupted_marker()),
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: None,
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1429,6 +1438,7 @@ fn disabled_interrupted_fork_snapshot_appends_only_interrupt_event() {
append_interrupted_boundary(
committed_history,
/*turn_id*/ None,
/*started_at*/ None,
InterruptedTurnHistoryMarker::Disabled,
)
.get_rollout_items()
@@ -1438,6 +1448,7 @@ fn disabled_interrupted_fork_snapshot_appends_only_interrupt_event() {
RolloutItem::ResponseItem(user_msg("hello")),
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: None,
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1450,6 +1461,7 @@ fn disabled_interrupted_fork_snapshot_appends_only_interrupt_event() {
append_interrupted_boundary(
InitialHistory::New,
/*turn_id*/ None,
/*started_at*/ None,
InterruptedTurnHistoryMarker::Disabled,
)
.get_rollout_items()
@@ -1458,6 +1470,7 @@ fn disabled_interrupted_fork_snapshot_appends_only_interrupt_event() {
serde_json::to_value(vec![RolloutItem::EventMsg(EventMsg::TurnAborted(
TurnAbortedEvent {
turn_id: None,
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1475,6 +1488,7 @@ fn interrupted_snapshot_is_not_mid_turn() {
RolloutItem::ResponseItem(contextual_user_interrupted_marker()),
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some("turn-1".to_string()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1486,6 +1500,7 @@ fn interrupted_snapshot_is_not_mid_turn() {
SnapshotTurnState {
ends_mid_turn: false,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
},
);
@@ -1532,6 +1547,7 @@ fn completed_legacy_event_history_is_not_mid_turn() {
SnapshotTurnState {
ends_mid_turn: false,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
},
);
@@ -1556,6 +1572,7 @@ fn mixed_response_and_legacy_user_event_history_is_mid_turn() {
SnapshotTurnState {
ends_mid_turn: true,
active_turn_id: None,
active_turn_started_at: None,
active_turn_start_index: None,
},
);
@@ -1642,6 +1659,7 @@ async fn interrupted_fork_snapshot_does_not_synthesize_turn_id_for_legacy_histor
let interrupted_abort_json = serde_json::to_value(RolloutItem::EventMsg(
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: expected_turn_id,
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -1729,6 +1747,7 @@ async fn interrupted_fork_snapshot_preserves_explicit_turn_id() {
SnapshotTurnState {
ends_mid_turn: true,
active_turn_id: Some("turn-explicit".to_string()),
active_turn_started_at: None,
active_turn_start_index: Some(1),
},
);
@@ -1761,6 +1780,7 @@ async fn interrupted_fork_snapshot_preserves_explicit_turn_id() {
item,
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(turn_id),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -82,6 +82,7 @@ fn turn_started(turn_id: &str) -> RolloutItem {
fn turn_completed(turn_id: &str) -> RolloutItem {
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -1558,6 +1558,7 @@ async fn multi_agent_v2_list_agents_returns_completed_status_without_encrypted_s
child_turn.as_ref(),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: child_turn.sub_id.clone(),
started_at: None,
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
@@ -2007,6 +2008,7 @@ async fn multi_agent_v2_followup_task_completion_notifies_parent_on_every_turn()
first_turn.as_ref(),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: first_turn.sub_id.clone(),
started_at: None,
last_agent_message: Some("first done".to_string()),
completed_at: None,
duration_ms: None,
@@ -2048,6 +2050,7 @@ async fn multi_agent_v2_followup_task_completion_notifies_parent_on_every_turn()
second_turn.as_ref(),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: second_turn.sub_id.clone(),
started_at: None,
last_agent_message: Some("second done".to_string()),
completed_at: None,
duration_ms: None,
@@ -2210,6 +2213,7 @@ async fn multi_agent_v2_interrupted_turn_does_not_notify_parent() {
aborted_turn.as_ref(),
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(aborted_turn.sub_id.clone()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
@@ -74,6 +74,7 @@ fn resume_history(
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id,
last_agent_message: None,
started_at: None,
completed_at: None,
duration_ms: None,
time_to_first_token_ms: None,
+17 -7
View File
@@ -81,8 +81,13 @@ fn rollout_items_from_messages(messages: Vec<ConversationMessage>) -> Vec<Rollou
for message in messages {
match message.role {
MessageRole::User => {
if let Some(turn_id) = current_turn.take() {
items.push(turn_complete_item(turn_id, /*completed_at*/ None));
let started_at = message.timestamp;
if let Some((turn_id, previous_started_at)) = current_turn.take() {
items.push(turn_complete_item(
turn_id,
previous_started_at,
/*completed_at*/ None,
));
}
user_turn_count += 1;
let turn_id = format!("external-import-turn-{user_turn_count}");
@@ -90,7 +95,7 @@ fn rollout_items_from_messages(messages: Vec<ConversationMessage>) -> Vec<Rollou
TurnStartedEvent {
turn_id: turn_id.clone(),
trace_id: None,
started_at: message.timestamp,
started_at,
model_context_window: None,
collaboration_mode_kind: Default::default(),
},
@@ -104,7 +109,7 @@ fn rollout_items_from_messages(messages: Vec<ConversationMessage>) -> Vec<Rollou
response_item_bytes =
response_item_bytes.saturating_add(message_byte_count(&message));
items.push(RolloutItem::ResponseItem(response_item(message)));
current_turn = Some(turn_id);
current_turn = Some((turn_id, started_at));
}
MessageRole::Assistant => {
if current_turn.is_none() {
@@ -125,10 +130,10 @@ fn rollout_items_from_messages(messages: Vec<ConversationMessage>) -> Vec<Rollou
}
}
if let Some(turn_id) = current_turn {
if let Some((turn_id, started_at)) = current_turn {
items.push(external_session_imported_marker_item());
items.push(token_count_item(last_model_visible_tokens));
items.push(turn_complete_item(turn_id, completed_at));
items.push(turn_complete_item(turn_id, started_at, completed_at));
}
items
@@ -178,10 +183,15 @@ fn token_count_item(last_model_visible_tokens: i64) -> RolloutItem {
}))
}
fn turn_complete_item(turn_id: String, completed_at: Option<i64>) -> RolloutItem {
fn turn_complete_item(
turn_id: String,
started_at: Option<i64>,
completed_at: Option<i64>,
) -> RolloutItem {
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id,
last_agent_message: None,
started_at,
completed_at,
duration_ms: None,
time_to_first_token_ms: None,
+8
View File
@@ -1955,6 +1955,10 @@ pub struct ContextCompactedEvent;
pub struct TurnCompleteEvent {
pub turn_id: String,
pub last_agent_message: Option<String>,
/// Unix timestamp (in seconds) when the turn started.
#[serde(default, skip_serializing_if = "Option::is_none")]
#[ts(type = "number | null", optional)]
pub started_at: Option<i64>,
/// Unix timestamp (in seconds) when the turn completed.
#[serde(default, skip_serializing_if = "Option::is_none")]
#[ts(type = "number | null", optional)]
@@ -4105,6 +4109,10 @@ pub struct Chunk {
pub struct TurnAbortedEvent {
pub turn_id: Option<String>,
pub reason: TurnAbortReason,
/// Unix timestamp (in seconds) when the turn started.
#[serde(default, skip_serializing_if = "Option::is_none")]
#[ts(type = "number | null", optional)]
pub started_at: Option<i64>,
/// Unix timestamp (in seconds) when the turn was aborted.
#[serde(default, skip_serializing_if = "Option::is_none")]
#[ts(type = "number | null", optional)]
@@ -51,6 +51,7 @@ fn turn_started(turn_id: &str) -> RolloutItem {
fn turn_complete(turn_id: &str) -> RolloutItem {
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,
@@ -61,6 +62,7 @@ fn turn_complete(turn_id: &str) -> RolloutItem {
fn turn_aborted(turn_id: &str) -> RolloutItem {
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(turn_id.to_string()),
started_at: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
+1
View File
@@ -538,6 +538,7 @@ mod tests {
)),
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-1".to_string(),
started_at: None,
last_agent_message: None,
completed_at: None,
duration_ms: None,