[codex-analytics] add item lifecycle timing (#20514)

## Why

Tool families already disagree on what their existing `duration` fields
mean, so lifecycle latency should live on the shared item envelope
instead of being inferred from per-tool execution fields. Carrying that
envelope through app-server notifications gives downstream consumers one
reusable timing signal without pretending every tool has the same
execution semantics.

## What changed

- Adds `started_at_ms` to core `ItemStartedEvent` values and
`completed_at_ms` to core `ItemCompletedEvent` values.
- Populates those timestamps in the shared session lifecycle emitters,
so protocol-native items get timing without each producer tracking its
own clock state.
- Exposes `startedAtMs` on app-server `item/started` notifications and
`completedAtMs` on `item/completed` notifications.
- Maps the lifecycle timestamps through the app-server boundary while
leaving legacy-converted notifications nullable when no lifecycle
timestamp exists.
- Regenerates the app-server JSON schema and TypeScript fixtures for the
notification-envelope change and updates downstream fixtures that
construct those notifications directly.
- Extends the existing web-search and image-generation integration flows
to assert the new lifecycle timestamps on the native item events.

## Verification

- `cargo check -p codex-protocol -p codex-core -p
codex-app-server-protocol -p codex-app-server -p codex-tui -p codex-exec
-p codex-app-server-client`
- `cargo test -p codex-core --test all web_search_item_is_emitted`
- `cargo test -p codex-core --test all
image_generation_call_event_is_emitted`
- `cargo test -p codex-app-server-protocol`

---
[//]: # (BEGIN SAPLING FOOTER)
Stack created with [Sapling](https://sapling-scm.com). Best reviewed
with [ReviewStack](https://reviewstack.dev/openai/codex/pull/20514).
* #18748
* #18747
* #17090
* #17089
* __->__ #20514
This commit is contained in:
rhan-oai
2026-05-04 22:33:20 +00:00
committed by GitHub
parent e7e6267ab3
commit aee1fe2659
37 changed files with 332 additions and 11 deletions
@@ -69,6 +69,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id: response.turn_id,
item,
completed_at_ms: response.completed_at_ms,
})
}
EventMsg::CollabAgentSpawnBegin(begin_event) => {
@@ -87,6 +88,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
started_at_ms: begin_event.started_at_ms,
})
}
EventMsg::CollabAgentSpawnEnd(end_event) => {
@@ -125,6 +127,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
completed_at_ms: end_event.completed_at_ms,
})
}
EventMsg::CollabAgentInteractionBegin(begin_event) => {
@@ -144,6 +147,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
started_at_ms: begin_event.started_at_ms,
})
}
EventMsg::CollabAgentInteractionEnd(end_event) => {
@@ -171,6 +175,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
completed_at_ms: end_event.completed_at_ms,
})
}
EventMsg::CollabWaitingBegin(begin_event) => {
@@ -194,6 +199,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
started_at_ms: begin_event.started_at_ms,
})
}
EventMsg::CollabWaitingEnd(end_event) => {
@@ -229,6 +235,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
completed_at_ms: end_event.completed_at_ms,
})
}
EventMsg::CollabCloseBegin(begin_event) => {
@@ -247,6 +254,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
started_at_ms: begin_event.started_at_ms,
})
}
EventMsg::CollabCloseEnd(end_event) => {
@@ -279,6 +287,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
completed_at_ms: end_event.completed_at_ms,
})
}
EventMsg::CollabResumeBegin(begin_event) => {
@@ -297,6 +306,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
started_at_ms: begin_event.started_at_ms,
})
}
EventMsg::CollabResumeEnd(end_event) => {
@@ -329,6 +339,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item,
completed_at_ms: end_event.completed_at_ms,
})
}
EventMsg::AgentMessageContentDelta(event) => {
@@ -378,6 +389,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item: item_started_event.item.into(),
started_at_ms: item_started_event.started_at_ms,
})
}
EventMsg::ItemCompleted(item_completed_event) => {
@@ -385,6 +397,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item: item_completed_event.item.into(),
completed_at_ms: item_completed_event.completed_at_ms,
})
}
EventMsg::PatchApplyUpdated(event) => {
@@ -400,6 +413,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item: build_command_execution_begin_item(&exec_command_begin_event),
started_at_ms: exec_command_begin_event.started_at_ms,
})
}
EventMsg::ExecCommandOutputDelta(exec_command_output_delta_event) => {
@@ -428,6 +442,7 @@ pub fn item_event_to_server_notification(
thread_id,
turn_id,
item: build_command_execution_end_item(&exec_command_end_event),
completed_at_ms: exec_command_end_event.completed_at_ms,
})
}
_ => unreachable!("unsupported item event"),
@@ -480,6 +495,7 @@ mod tests {
fn collab_resume_begin_maps_to_item_started_resume_agent() {
let event = CollabResumeBeginEvent {
call_id: "call-1".to_string(),
started_at_ms: 123,
sender_thread_id: ThreadId::new(),
receiver_thread_id: ThreadId::new(),
receiver_agent_nickname: None,
@@ -496,6 +512,7 @@ mod tests {
ItemStartedNotification {
thread_id: "thread-1".to_string(),
turn_id: "turn-1".to_string(),
started_at_ms: event.started_at_ms,
item: ThreadItem::CollabAgentToolCall {
id: event.call_id,
tool: CollabAgentTool::ResumeAgent,
@@ -515,6 +532,7 @@ mod tests {
fn collab_resume_end_maps_to_item_completed_resume_agent() {
let event = CollabResumeEndEvent {
call_id: "call-2".to_string(),
completed_at_ms: 456,
sender_thread_id: ThreadId::new(),
receiver_thread_id: ThreadId::new(),
receiver_agent_nickname: None,
@@ -533,6 +551,7 @@ mod tests {
ItemCompletedNotification {
thread_id: "thread-2".to_string(),
turn_id: "turn-2".to_string(),
completed_at_ms: event.completed_at_ms,
item: ThreadItem::CollabAgentToolCall {
id: event.call_id,
tool: CollabAgentTool::ResumeAgent,
@@ -1356,6 +1356,7 @@ mod tests {
id: "user-item-id".to_string(),
content: Vec::new(),
}),
started_at_ms: 0,
}),
EventMsg::TurnComplete(TurnCompleteEvent {
turn_id: turn_id.to_string(),
@@ -1820,6 +1821,7 @@ mod tests {
call_id: "exec-1".into(),
process_id: Some("pid-1".into()),
turn_id: "turn-1".into(),
completed_at_ms: 0,
command: vec!["echo".into(), "hello world".into()],
cwd: test_path_buf("/tmp").abs(),
parsed_cmd: vec![ParsedCommand::Unknown {
@@ -1983,6 +1985,7 @@ mod tests {
codex_protocol::dynamic_tools::DynamicToolCallRequest {
call_id: "dyn-1".into(),
turn_id: "turn-1".into(),
started_at_ms: 0,
namespace: Some("codex_app".into()),
tool: "lookup_ticket".into(),
arguments: serde_json::json!({"id":"ABC-123"}),
@@ -1991,6 +1994,7 @@ mod tests {
EventMsg::DynamicToolCallResponse(DynamicToolCallResponseEvent {
call_id: "dyn-1".into(),
turn_id: "turn-1".into(),
completed_at_ms: 0,
namespace: Some("codex_app".into()),
tool: "lookup_ticket".into(),
arguments: serde_json::json!({"id":"ABC-123"}),
@@ -2046,6 +2050,7 @@ mod tests {
call_id: "exec-declined".into(),
process_id: Some("pid-2".into()),
turn_id: "turn-1".into(),
completed_at_ms: 0,
command: vec!["ls".into()],
cwd: test_path_buf("/tmp").abs(),
parsed_cmd: vec![ParsedCommand::Unknown { cmd: "ls".into() }],
@@ -2293,6 +2298,7 @@ mod tests {
call_id: "exec-late".into(),
process_id: Some("pid-42".into()),
turn_id: "turn-a".into(),
completed_at_ms: 0,
command: vec!["echo".into(), "done".into()],
cwd: test_path_buf("/tmp").abs(),
parsed_cmd: vec![ParsedCommand::Unknown {
@@ -2384,6 +2390,7 @@ mod tests {
call_id: "exec-unknown-turn".into(),
process_id: Some("pid-42".into()),
turn_id: "turn-missing".into(),
completed_at_ms: 0,
command: vec!["echo".into(), "done".into()],
cwd: test_path_buf("/tmp").abs(),
parsed_cmd: vec![ParsedCommand::Unknown {
@@ -2732,6 +2739,7 @@ mod tests {
}),
EventMsg::CollabResumeEnd(codex_protocol::protocol::CollabResumeEndEvent {
call_id: "resume-1".into(),
completed_at_ms: 0,
sender_thread_id: ThreadId::try_from("00000000-0000-0000-0000-000000000001")
.expect("valid sender thread id"),
receiver_thread_id: ThreadId::try_from("00000000-0000-0000-0000-000000000002")
@@ -2788,6 +2796,7 @@ mod tests {
}),
EventMsg::CollabAgentSpawnEnd(codex_protocol::protocol::CollabAgentSpawnEndEvent {
call_id: "spawn-1".into(),
completed_at_ms: 0,
sender_thread_id,
new_thread_id: Some(spawned_thread_id),
new_agent_nickname: Some("Scout".into()),
@@ -2849,6 +2858,7 @@ mod tests {
EventMsg::CollabAgentInteractionBegin(
codex_protocol::protocol::CollabAgentInteractionBeginEvent {
call_id: "send-1".into(),
started_at_ms: 0,
sender_thread_id: sender,
receiver_thread_id: receiver,
prompt: "new task".into(),
@@ -2857,6 +2867,7 @@ mod tests {
EventMsg::CollabAgentInteractionEnd(
codex_protocol::protocol::CollabAgentInteractionEndEvent {
call_id: "send-1".into(),
completed_at_ms: 0,
sender_thread_id: sender,
receiver_thread_id: receiver,
receiver_agent_nickname: None,
@@ -6928,6 +6928,9 @@ pub struct ItemStartedNotification {
pub item: ThreadItem,
pub thread_id: String,
pub turn_id: String,
/// Unix timestamp (in milliseconds) when this item lifecycle started.
#[ts(type = "number")]
pub started_at_ms: i64,
}
#[derive(Serialize, Deserialize, Debug, Clone, PartialEq, JsonSchema, TS)]
@@ -6990,6 +6993,9 @@ pub struct ItemCompletedNotification {
pub item: ThreadItem,
pub thread_id: String,
pub turn_id: String,
/// Unix timestamp (in milliseconds) when this item lifecycle completed.
#[ts(type = "number")]
pub completed_at_ms: i64,
}
#[derive(Serialize, Deserialize, Debug, Clone, PartialEq, JsonSchema, TS)]