[codex-analytics] add protocol-native turn timestamps (#16638)

---
[//]: # (BEGIN SAPLING FOOTER)
Stack created with [Sapling](https://sapling-scm.com). Best reviewed
with [ReviewStack](https://reviewstack.dev/openai/codex/pull/16638).
* #16870
* #16706
* #16659
* #16641
* #16640
* __->__ #16638
This commit is contained in:
rhan-oai
2026-04-06 16:22:59 -07:00
committed by GitHub
parent e88c2cf4d7
commit 756c45ec61
58 changed files with 1134 additions and 36 deletions
+9
View File
@@ -256,6 +256,7 @@ async fn get_status_returns_not_found_without_manager() {
async fn on_event_updates_status_from_task_started() {
let status = agent_status_from_event(&EventMsg::TurnStarted(TurnStartedEvent {
turn_id: "turn-1".to_string(),
started_at: None,
model_context_window: None,
collaboration_mode_kind: ModeKind::Default,
}));
@@ -267,6 +268,8 @@ async fn on_event_updates_status_from_task_complete() {
let status = agent_status_from_event(&EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-1".to_string(),
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
}));
let expected = AgentStatus::Completed(Some("done".to_string()));
assert_eq!(status, Some(expected));
@@ -288,6 +291,8 @@ 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()),
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
}));
let expected = AgentStatus::Interrupted;
@@ -1200,6 +1205,8 @@ async fn multi_agent_v2_completion_ignores_dead_direct_parent() {
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: tester_turn.sub_id.clone(),
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
}),
)
.await;
@@ -1284,6 +1291,8 @@ async fn multi_agent_v2_completion_queues_message_for_direct_parent() {
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: tester_turn.sub_id.clone(),
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
}),
)
.await;
@@ -128,6 +128,7 @@ async fn record_initial_history_resumed_hydrates_previous_turn_settings_from_lif
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -145,6 +146,8 @@ async fn record_initial_history_resumed_hydrates_previous_turn_settings_from_lif
codex_protocol::protocol::TurnCompleteEvent {
turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
];
@@ -190,6 +193,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_com
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: first_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -209,11 +213,14 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_com
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: rolled_back_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -233,6 +240,8 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_com
codex_protocol::protocol::TurnCompleteEvent {
turn_id: rolled_back_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::ThreadRolledBack(
@@ -280,6 +289,7 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_inc
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: first_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -299,11 +309,14 @@ async fn reconstruct_history_rollback_keeps_history_and_metadata_in_sync_for_inc
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: incomplete_turn_id,
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -365,6 +378,7 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: first_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -384,11 +398,14 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: second_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -407,11 +424,14 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad
codex_protocol::protocol::TurnCompleteEvent {
turn_id: second_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: standalone_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -421,6 +441,8 @@ async fn reconstruct_history_rollback_skips_non_user_turns_for_history_and_metad
codex_protocol::protocol::TurnCompleteEvent {
turn_id: standalone_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::ThreadRolledBack(
@@ -471,6 +493,7 @@ async fn reconstruct_history_rollback_counts_inter_agent_assistant_turns() {
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: first_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -490,11 +513,14 @@ async fn reconstruct_history_rollback_counts_inter_agent_assistant_turns() {
codex_protocol::protocol::TurnCompleteEvent {
turn_id: first_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: assistant_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -506,6 +532,8 @@ async fn reconstruct_history_rollback_counts_inter_agent_assistant_turns() {
codex_protocol::protocol::TurnCompleteEvent {
turn_id: assistant_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::ThreadRolledBack(
@@ -551,6 +579,7 @@ async fn reconstruct_history_rollback_clears_history_and_metadata_when_exceeding
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: only_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -570,6 +599,8 @@ async fn reconstruct_history_rollback_clears_history_and_metadata_when_exceeding
codex_protocol::protocol::TurnCompleteEvent {
turn_id: only_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::ThreadRolledBack(
@@ -599,6 +630,7 @@ async fn record_initial_history_resumed_rollback_skips_only_user_turns() {
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: user_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -616,12 +648,15 @@ async fn record_initial_history_resumed_rollback_skips_only_user_turns() {
codex_protocol::protocol::TurnCompleteEvent {
turn_id: user_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
// Standalone task turn (no UserMessage) should not consume rollback skips.
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: standalone_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -630,6 +665,8 @@ async fn record_initial_history_resumed_rollback_skips_only_user_turns() {
codex_protocol::protocol::TurnCompleteEvent {
turn_id: standalone_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::ThreadRolledBack(
@@ -663,6 +700,7 @@ async fn record_initial_history_resumed_rollback_drops_incomplete_user_turn_comp
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: previous_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -680,11 +718,14 @@ async fn record_initial_history_resumed_rollback_drops_incomplete_user_turn_comp
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: incomplete_turn_id,
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -815,6 +856,7 @@ async fn reconstruct_history_legacy_compaction_without_replacement_history_clear
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: current_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -832,6 +874,8 @@ async fn reconstruct_history_legacy_compaction_without_replacement_history_clear
codex_protocol::protocol::TurnCompleteEvent {
turn_id: current_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
];
@@ -876,6 +920,7 @@ async fn record_initial_history_resumed_turn_context_after_compaction_reestablis
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: previous_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -898,6 +943,8 @@ async fn record_initial_history_resumed_turn_context_after_compaction_reestablis
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
];
@@ -979,6 +1026,7 @@ async fn record_initial_history_resumed_aborted_turn_without_id_clears_active_tu
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: previous_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -996,11 +1044,14 @@ async fn record_initial_history_resumed_aborted_turn_without_id_clears_active_tu
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: aborted_turn_id,
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1017,6 +1068,8 @@ async fn record_initial_history_resumed_aborted_turn_without_id_clears_active_tu
codex_protocol::protocol::TurnAbortedEvent {
turn_id: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::Compacted(CompactedItem {
@@ -1080,6 +1133,7 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: previous_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1097,11 +1151,14 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: current_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1118,6 +1175,8 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo
codex_protocol::protocol::TurnAbortedEvent {
turn_id: Some(unmatched_abort_turn_id),
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::TurnContext(current_context_item.clone()),
@@ -1125,6 +1184,8 @@ async fn record_initial_history_resumed_unmatched_abort_preserves_active_turn_fo
codex_protocol::protocol::TurnCompleteEvent {
turn_id: current_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
];
@@ -1187,6 +1248,7 @@ async fn record_initial_history_resumed_trailing_incomplete_turn_compaction_clea
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: previous_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1204,11 +1266,14 @@ async fn record_initial_history_resumed_trailing_incomplete_turn_compaction_clea
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: incomplete_turn_id,
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1258,6 +1323,7 @@ async fn record_initial_history_resumed_trailing_incomplete_turn_preserves_turn_
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: current_turn_id,
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1332,6 +1398,7 @@ async fn record_initial_history_resumed_replaced_incomplete_compacted_turn_clear
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: previous_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1349,11 +1416,14 @@ async fn record_initial_history_resumed_replaced_incomplete_compacted_turn_clear
codex_protocol::protocol::TurnCompleteEvent {
turn_id: previous_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: compacted_incomplete_turn_id,
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1375,6 +1445,7 @@ async fn record_initial_history_resumed_replaced_incomplete_compacted_turn_clear
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: replacing_turn_id,
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -53,6 +53,8 @@ async fn forward_events_cancelled_while_send_blocked_shuts_down_delegate() {
msg: EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some("turn-1".to_string()),
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
}),
})
.await
+41 -7
View File
@@ -235,13 +235,19 @@ async fn interrupting_regular_turn_waiting_on_startup_prewarm_emits_turn_aborted
.await
.expect("expected turn aborted event")
.expect("channel open");
assert!(matches!(
second.msg,
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(turn_id),
reason: TurnAbortReason::Interrupted,
}) if turn_id == tc.sub_id
));
let EventMsg::TurnAborted(TurnAbortedEvent {
turn_id,
reason,
completed_at,
duration_ms,
}) = second.msg
else {
panic!("expected turn aborted event");
};
assert_eq!(turn_id, Some(tc.sub_id.clone()));
assert_eq!(reason, TurnAbortReason::Interrupted);
assert!(completed_at.is_some());
assert!(duration_ms.is_some());
}
fn test_model_client_session() -> crate::client::ModelClientSession {
@@ -1300,6 +1306,7 @@ async fn record_initial_history_forked_hydrates_previous_turn_settings() {
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1317,6 +1324,8 @@ async fn record_initial_history_forked_hydrates_previous_turn_settings() {
codex_protocol::protocol::TurnCompleteEvent {
turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
},
)),
];
@@ -1481,6 +1490,7 @@ async fn thread_rollback_recomputes_previous_turn_settings_and_reference_context
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: first_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1499,10 +1509,13 @@ async fn thread_rollback_recomputes_previous_turn_settings_and_reference_context
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: first_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: rolled_back_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1521,6 +1534,8 @@ async fn thread_rollback_recomputes_previous_turn_settings_and_reference_context
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: rolled_back_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
])
.await;
@@ -1579,6 +1594,7 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: first_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1595,10 +1611,13 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: first_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: compact_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1610,10 +1629,13 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: compact_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: rolled_back_turn_id.clone(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1634,6 +1656,8 @@ async fn thread_rollback_restores_cleared_reference_context_item_after_compactio
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: rolled_back_turn_id,
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
])
.await;
@@ -1661,6 +1685,7 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() {
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: "turn-1".to_string(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1677,10 +1702,13 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() {
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-1".to_string(),
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: "turn-2".to_string(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1697,10 +1725,13 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() {
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-2".to_string(),
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
RolloutItem::EventMsg(EventMsg::TurnStarted(
codex_protocol::protocol::TurnStartedEvent {
turn_id: "turn-3".to_string(),
started_at: None,
model_context_window: Some(128_000),
collaboration_mode_kind: ModeKind::Default,
},
@@ -1717,6 +1748,8 @@ async fn thread_rollback_persists_marker_and_replays_cumulatively() {
RolloutItem::EventMsg(EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: "turn-3".to_string(),
last_agent_message: None,
completed_at: None,
duration_ms: None,
})),
])
.await;
@@ -4624,6 +4657,7 @@ async fn task_finish_emits_turn_item_lifecycle_for_leftover_pending_user_input()
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id,
last_agent_message: None,
..
}) if turn_id == tc.sub_id
));
}
+1
View File
@@ -74,6 +74,7 @@ pub(crate) async fn run_compact_task(
) -> CodexResult<()> {
let start_event = EventMsg::TurnStarted(TurnStartedEvent {
turn_id: turn_context.sub_id.clone(),
started_at: turn_context.turn_timing_state.started_at_unix_secs().await,
model_context_window: turn_context.model_context_window(),
collaboration_mode_kind: turn_context.collaboration_mode.mode,
});
+1
View File
@@ -40,6 +40,7 @@ pub(crate) async fn run_remote_compact_task(
) -> CodexResult<()> {
let start_event = EventMsg::TurnStarted(TurnStartedEvent {
turn_id: turn_context.sub_id.clone(),
started_at: turn_context.turn_timing_state.started_at_unix_secs().await,
model_context_window: turn_context.model_context_window(),
collaboration_mode_kind: turn_context.collaboration_mode.mode,
});
+13
View File
@@ -511,9 +511,15 @@ impl Session {
&[("token_type", "reasoning_output"), tmp_mem],
);
}
let (completed_at, duration_ms) = turn_context
.turn_timing_state
.completed_at_and_duration_ms()
.await;
let event = EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_context.sub_id.clone(),
last_agent_message,
completed_at,
duration_ms,
});
self.send_event(turn_context.as_ref(), event).await;
@@ -588,9 +594,16 @@ impl Session {
self.flush_rollout().await;
}
let (completed_at, duration_ms) = task
.turn_context
.turn_timing_state
.completed_at_and_duration_ms()
.await;
let event = EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(task.turn_context.sub_id.clone()),
reason,
completed_at,
duration_ms,
});
self.send_event(task.turn_context.as_ref(), event).await;
}
+1
View File
@@ -46,6 +46,7 @@ impl SessionTask for RegularTask {
// not wait on startup prewarm resolution.
let event = EventMsg::TurnStarted(TurnStartedEvent {
turn_id: ctx.sub_id.clone(),
started_at: ctx.turn_timing_state.started_at_unix_secs().await,
model_context_window: ctx.model_context_window(),
collaboration_mode_kind: ctx.collaboration_mode.mode,
});
+1
View File
@@ -111,6 +111,7 @@ pub(crate) async fn execute_user_shell_command(
// freshly reinjected context before the summary/replacement history is applied.
let event = EventMsg::TurnStarted(TurnStartedEvent {
turn_id: turn_context.sub_id.clone(),
started_at: turn_context.turn_timing_state.started_at_unix_secs().await,
model_context_window: turn_context.model_context_window(),
collaboration_mode_kind: turn_context.collaboration_mode.mode,
});
+2
View File
@@ -1010,6 +1010,8 @@ fn append_interrupted_boundary(history: InitialHistory, turn_id: Option<String>)
let aborted_event = RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
}));
match history {
+12
View File
@@ -164,6 +164,7 @@ fn out_of_range_truncation_drops_pre_user_active_turn_prefix() {
RolloutItem::ResponseItem(assistant_msg("a1")),
RolloutItem::EventMsg(EventMsg::TurnStarted(TurnStartedEvent {
turn_id: "turn-2".to_string(),
started_at: None,
model_context_window: None,
collaboration_mode_kind: Default::default(),
})),
@@ -320,6 +321,8 @@ fn interrupted_fork_snapshot_appends_interrupt_boundary() {
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
})),
])
.expect("serialize expected interrupted fork history"),
@@ -334,6 +337,8 @@ fn interrupted_fork_snapshot_appends_interrupt_boundary() {
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: None,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
})),
])
.expect("serialize expected interrupted empty history"),
@@ -349,6 +354,8 @@ fn interrupted_snapshot_is_not_mid_turn() {
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some("turn-1".to_string()),
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
})),
]);
@@ -485,6 +492,8 @@ async fn interrupted_fork_snapshot_does_not_synthesize_turn_id_for_legacy_histor
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: expected_turn_id,
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
}),
))
.expect("serialize interrupted abort event");
@@ -536,6 +545,7 @@ async fn interrupted_fork_snapshot_preserves_explicit_turn_id() {
InitialHistory::Forked(vec![
RolloutItem::EventMsg(EventMsg::TurnStarted(TurnStartedEvent {
turn_id: "turn-explicit".to_string(),
started_at: None,
model_context_window: None,
collaboration_mode_kind: Default::default(),
})),
@@ -594,6 +604,8 @@ async fn interrupted_fork_snapshot_preserves_explicit_turn_id() {
RolloutItem::EventMsg(EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(turn_id),
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
})) if turn_id == "turn-explicit"
)
}));
@@ -837,6 +837,8 @@ async fn multi_agent_v2_list_agents_returns_completed_status_and_last_task_messa
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: child_turn.sub_id.clone(),
last_agent_message: Some("done".to_string()),
completed_at: None,
duration_ms: None,
}),
)
.await;
@@ -1337,6 +1339,8 @@ async fn multi_agent_v2_followup_task_completion_notifies_parent_on_every_turn()
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: first_turn.sub_id.clone(),
last_agent_message: Some("first done".to_string()),
completed_at: None,
duration_ms: None,
}),
)
.await;
@@ -1363,6 +1367,8 @@ async fn multi_agent_v2_followup_task_completion_notifies_parent_on_every_turn()
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: second_turn.sub_id.clone(),
last_agent_message: Some("second done".to_string()),
completed_at: None,
duration_ms: None,
}),
)
.await;
@@ -1518,6 +1524,8 @@ async fn multi_agent_v2_interrupted_turn_does_not_notify_parent() {
EventMsg::TurnAborted(TurnAbortedEvent {
turn_id: Some(aborted_turn.sub_id.clone()),
reason: TurnAbortReason::Interrupted,
completed_at: None,
duration_ms: None,
}),
)
.await;
+24
View File
@@ -1,5 +1,7 @@
use std::time::Duration;
use std::time::Instant;
use std::time::SystemTime;
use std::time::UNIX_EPOCH;
use codex_otel::metrics::names::TURN_TTFM_DURATION_METRIC;
use codex_otel::metrics::names::TURN_TTFT_DURATION_METRIC;
@@ -45,6 +47,7 @@ pub(crate) struct TurnTimingState {
#[derive(Debug, Default)]
struct TurnTimingStateInner {
started_at: Option<Instant>,
started_at_unix_secs: Option<i64>,
first_token_at: Option<Instant>,
first_message_at: Option<Instant>,
}
@@ -53,10 +56,24 @@ impl TurnTimingState {
pub(crate) async fn mark_turn_started(&self, started_at: Instant) {
let mut state = self.state.lock().await;
state.started_at = Some(started_at);
state.started_at_unix_secs = Some(now_unix_timestamp_secs());
state.first_token_at = None;
state.first_message_at = None;
}
pub(crate) async fn started_at_unix_secs(&self) -> Option<i64> {
self.state.lock().await.started_at_unix_secs
}
pub(crate) async fn completed_at_and_duration_ms(&self) -> (Option<i64>, Option<i64>) {
let state = self.state.lock().await;
let completed_at = Some(now_unix_timestamp_secs());
let duration_ms = state
.started_at
.map(|started_at| i64::try_from(started_at.elapsed().as_millis()).unwrap_or(i64::MAX));
(completed_at, duration_ms)
}
pub(crate) async fn record_ttft_for_response_event(
&self,
event: &ResponseEvent,
@@ -77,6 +94,13 @@ impl TurnTimingState {
}
}
fn now_unix_timestamp_secs() -> i64 {
let duration = SystemTime::now()
.duration_since(UNIX_EPOCH)
.unwrap_or_default();
i64::try_from(duration.as_secs()).unwrap_or(i64::MAX)
}
impl TurnTimingStateInner {
fn record_turn_ttft(&mut self) -> Option<Duration> {
if self.first_token_at.is_some() {