Expose tool dispatch and timing observations to extensions (#47662)

## Why

Tool lifecycle observers need visibility into calls rejected before execution starts and timing that remains available on cancellation, independently of tracing settings.

## What changed

- Add `on_tool_dispatch` and `on_tool_timing` callbacks to `ToolLifecycleContributor`, with thread, turn, and call IDs for correlation.
- Report direct calls before readiness, dispatch waiting, and hooks. Report handler duration when dispatch completes or is dropped, excluding readiness and gate waiting and returning zero if the call never passes the gate.
- Expose code-mode host durations as a separate `HostOperation` timing boundary. Exclude nested code-mode calls from dispatch and handler timing observations to avoid double counting.

## Testing

Add tests for callback ordering on completed and rejected calls, timing on cancellation, zero handler duration before gate admission without tracing, and code-mode host timing without nested dispatch or handler timing observations.

GitOrigin-RevId: 97998b5094564c13cb2cfad089bb0a9d6615eb5c

codex-rs/core/src/tools/code_mode/execute_handler.rs

@@ -214,8 +214,7 @@ impl CodeModeExecuteHandler {
         } = invocation;
 
         let mut telemetry = CodeModeToolCallGuard::new(
-            session.services.analytics_events_client.clone(),
-            session.thread_id.to_string(),
+            &session,
             turn.sub_id.clone(),
             turn.turn_metadata_state.clone(),
             call_id.clone(),

codex-rs/core/src/tools/code_mode/telemetry.rs

@@ -20,12 +20,12 @@ pub(super) struct CodeModeToolCallGuard {
     started_at_ms: u64,
     status: CodeModeToolCallStatus,
     handler_span: Span,
+    extensions: Arc<codex_extension_api::ExtensionRegistry<crate::config::Config>>,
 }
 
 impl CodeModeToolCallGuard {
     pub(super) fn new(
-        analytics: AnalyticsEventsClient,
-        thread_id: String,
+        session: &crate::session::session::Session,
         turn_id: String,
         turn_metadata: Arc<dyn TurnAnalyticsMetadata>,
         call_id: String,
@@ -33,8 +33,8 @@ impl CodeModeToolCallGuard {
         handler_span: Span,
     ) -> Self {
         Self {
-            analytics,
-            thread_id,
+            analytics: session.services.analytics_events_client.clone(),
+            thread_id: session.thread_id.to_string(),
             turn_id,
             turn_metadata,
             call_id,
@@ -43,6 +43,7 @@ impl CodeModeToolCallGuard {
             started_at_ms: codex_analytics::now_unix_millis(),
             status: CodeModeToolCallStatus::Interrupted,
             handler_span,
+            extensions: Arc::clone(&session.services.extensions),
         }
     }
 
@@ -58,6 +59,15 @@ impl CodeModeToolCallGuard {
     }
 
     pub(super) fn record_code_mode_host_duration(&self, duration: Duration) {
+        for observer in self.extensions.tool_lifecycle_contributors() {
+            observer.on_tool_timing(codex_extension_api::ToolTimingInput {
+                thread_id: &self.thread_id,
+                turn_id: &self.turn_id,
+                call_id: &self.call_id,
+                boundary: codex_extension_api::ToolTimingBoundary::HostOperation,
+                duration,
+            });
+        }
         let Ok(code_mode_host_duration_ns) = u64::try_from(duration.as_nanos()) else {
             return;
         };

codex-rs/core/src/tools/code_mode/wait_handler.rs

@@ -105,8 +105,7 @@ impl CodeModeWaitHandler {
         } = invocation;
 
         let mut telemetry = CodeModeToolCallGuard::new(
-            session.services.analytics_events_client.clone(),
-            session.thread_id.to_string(),
+            &session,
             turn.sub_id.clone(),
             turn.turn_metadata_state.clone(),
             call_id.clone(),

codex-rs/core/src/tools/parallel.rs

@@ -38,6 +38,7 @@ struct ToolCallTimingGuard {
     turn_id: String,
     call_id: String,
     tool_name: codex_tools::ToolName,
+    extensions: Arc<codex_extension_api::ExtensionRegistry<crate::config::Config>>,
 }
 
 #[derive(Clone)]
@@ -143,14 +144,24 @@ impl ToolCallRuntime {
         let lock = Arc::clone(&self.parallel_execution);
         let invocation_cancellation_token = cancellation_token.clone();
         let started = Instant::now();
-        let tool_call_timing_guard = ToolCallTimingGuard::capture(
+        let mut tool_call_timing_guard = ToolCallTimingGuard::capture(
             started,
             &session.thread_id,
             &turn.sub_id,
             &call,
             &source,
-            turn.config.code_mode.experimental_show_cell_overhead,
+            Arc::clone(&session.services.extensions),
         );
+        if let Some(guard) = tool_call_timing_guard.as_mut() {
+            for observer in session.services.extensions.tool_lifecycle_contributors() {
+                observer.on_tool_dispatch(codex_extension_api::ToolDispatchInput {
+                    thread_id: &guard.conversation_id,
+                    turn_id: &guard.turn_id,
+                    call_id: &guard.call_id,
+                    tool_name: &guard.tool_name,
+                });
+            }
+        }
         let execution_started_at = tool_call_timing_guard
             .as_ref()
             .map(|timing| Arc::clone(&timing.execution_started_at));
@@ -340,7 +351,7 @@ impl ToolCallTimingGuard {
         turn_id: &str,
         call: &ToolCall,
         source: &ToolCallSource,
-        experimental_show_cell_overhead: bool,
+        extensions: Arc<codex_extension_api::ExtensionRegistry<crate::config::Config>>,
     ) -> Option<Self> {
         // Code-mode calls are nested within a direct code-mode tool call whose
         // timing already includes them. Suppress nested guards so consumers do
@@ -348,8 +359,7 @@ impl ToolCallTimingGuard {
         if !matches!(
             source,
             ToolCallSource::Direct | ToolCallSource::DirectPlaintextMessage
-        ) || (!experimental_show_cell_overhead && !tracing::enabled!(tracing::Level::INFO))
-        {
+        ) {
             return None;
         }
 
@@ -360,6 +370,7 @@ impl ToolCallTimingGuard {
             turn_id: turn_id.to_string(),
             call_id: call.call_id.clone(),
             tool_name: call.tool_name.clone(),
+            extensions,
         })
     }
 
@@ -375,6 +386,17 @@ impl ToolCallTimingGuard {
             .get()
             .copied()
             .filter(|execution_started_at| *execution_started_at <= completed_at);
+        for observer in self.extensions.tool_lifecycle_contributors() {
+            observer.on_tool_timing(codex_extension_api::ToolTimingInput {
+                thread_id: &self.conversation_id,
+                turn_id: &self.turn_id,
+                call_id: &self.call_id,
+                boundary: codex_extension_api::ToolTimingBoundary::Handler,
+                duration: execution_started_at
+                    .map(|start| completed_at.duration_since(start))
+                    .unwrap_or_default(),
+            });
+        }
         let duration_ms = |duration: std::time::Duration| u64::try_from(duration.as_millis()).ok();
         let total_duration_ms = duration_ms(completed_at.duration_since(started_at));
         let dispatch_duration_ms = execution_started_at.map_or_else(
@@ -470,7 +492,7 @@ mod tests {
                 "turn-id",
                 &call,
                 &ToolCallSource::Direct,
-                /*experimental_show_cell_overhead*/ false,
+                codex_extension_api::empty_extension_registry(),
             );
             assert!(
                 direct_guard.is_some(),
@@ -487,7 +509,7 @@ mod tests {
                     cell_id: "cell-1".to_string(),
                     runtime_tool_call_id: "runtime-call-1".to_string(),
                 },
-                /*experimental_show_cell_overhead*/ false,
+                codex_extension_api::empty_extension_registry(),
             );
             assert!(
                 code_mode_guard.is_none(),
@@ -514,7 +536,7 @@ mod tests {
                 "turn-id",
                 &call,
                 &ToolCallSource::Direct,
-                /*experimental_show_cell_overhead*/ true,
+                codex_extension_api::empty_extension_registry(),
             )
             .expect("model-visible timing must not depend on INFO logging");
             timing
@@ -785,3 +807,7 @@ mod tests {
         Ok(())
     }
 }
+
+#[cfg(test)]
+#[path = "parallel_observation_tests.rs"]
+mod observation_tests;

codex-rs/core/src/tools/parallel_observation_tests.rs

@@ -0,0 +1,46 @@
+//! Outer tool timing observations work without enabling textual tracing.
+use super::*;
+use codex_extension_api::ToolLifecycleContributor;
+use codex_extension_api::ToolTimingInput;
+use pretty_assertions::assert_eq;
+use std::sync::Mutex;
+use std::time::Duration;
+
+#[derive(Default)]
+struct Observer(Mutex<Vec<(String, Duration)>>);
+impl ToolLifecycleContributor for Observer {
+    fn on_tool_timing(&self, input: ToolTimingInput<'_>) {
+        self.0
+            .lock()
+            .unwrap()
+            .push((input.call_id.to_string(), input.duration));
+    }
+}
+#[test]
+fn cancelled_dispatch_reports_zero_handler_work_even_without_tracing() {
+    let observer = Arc::new(Observer::default());
+    let call = ToolCall {
+        tool_name: codex_tools::ToolName::plain("tool"),
+        call_id: "call".into(),
+        payload: ToolPayload::Function {
+            arguments: "{}".into(),
+        },
+        encrypted_function_args: None,
+    };
+    let mut extensions = codex_extension_api::ExtensionRegistryBuilder::new();
+    extensions.tool_lifecycle_contributor(observer.clone());
+    let guard = ToolCallTimingGuard::capture(
+        Instant::now(),
+        &"thread",
+        "turn",
+        &call,
+        &ToolCallSource::Direct,
+        Arc::new(extensions.build()),
+    )
+    .unwrap();
+    drop(guard);
+    assert_eq!(
+        *observer.0.lock().unwrap(),
+        vec![("call".into(), Duration::ZERO)]
+    );
+}

codex-rs/core/tests/suite/tool_lifecycle.rs

@@ -51,6 +51,9 @@ use wiremock::Request;
 use wiremock::ResponseTemplate;
 use wiremock::matchers::body_partial_json;
 
+#[path = "tool_observation_tests.rs"]
+mod observations;
+
 #[path = "command_lifecycle_tests.rs"]
 mod command_lifecycle;
 

codex-rs/core/tests/suite/tool_observation_tests.rs

@@ -0,0 +1,220 @@
+//! Observe real dispatch, completion, cancellation, and nested code-mode execution.
+use super::*;
+use codex_extension_api::ToolDispatchInput;
+use codex_extension_api::ToolFinishInput;
+use codex_extension_api::ToolTimingBoundary;
+use codex_extension_api::ToolTimingInput;
+use codex_protocol::protocol::Op;
+use pretty_assertions::assert_eq;
+use test_case::test_case;
+
+#[derive(Default)]
+struct Observations {
+    events: Mutex<Vec<(String, &'static str)>>,
+    pause: bool,
+    started: Notify,
+    timed: Notify,
+}
+
+impl ToolLifecycleContributor for Observations {
+    fn on_tool_dispatch(&self, input: ToolDispatchInput<'_>) {
+        self.events
+            .lock()
+            .expect("observation lock should not be poisoned")
+            .push((input.call_id.into(), "dispatch"));
+    }
+
+    fn on_tool_start<'a>(&'a self, input: ToolStartInput<'a>) -> ToolLifecycleFuture<'a> {
+        Box::pin(async move {
+            self.events
+                .lock()
+                .expect("observation lock should not be poisoned")
+                .push((input.call_id.into(), "start"));
+            self.started.notify_one();
+            if self.pause {
+                std::future::pending::<()>().await;
+            }
+        })
+    }
+
+    fn on_tool_finish<'a>(&'a self, input: ToolFinishInput<'a>) -> ToolLifecycleFuture<'a> {
+        Box::pin(async move {
+            self.events
+                .lock()
+                .expect("observation lock should not be poisoned")
+                .push((input.call_id.into(), "finish"));
+        })
+    }
+
+    fn on_tool_timing(&self, input: ToolTimingInput<'_>) {
+        let boundary = match input.boundary {
+            ToolTimingBoundary::Handler => "handler",
+            ToolTimingBoundary::HostOperation => "host",
+        };
+        self.events
+            .lock()
+            .expect("observation lock should not be poisoned")
+            .push((input.call_id.into(), boundary));
+        self.timed.notify_one();
+    }
+}
+
+#[test_case("update_plan", &["dispatch", "start", "finish", "handler"]; "completed")]
+#[test_case("missing_tool", &["dispatch", "handler"]; "rejected_before_start")]
+#[tokio::test(flavor = "multi_thread", worker_threads = 2)]
+async fn dispatch_and_timing_surround_tool_execution(
+    tool_name: &str,
+    expected: &[&str],
+) -> Result<()> {
+    let server = responses::start_mock_server().await;
+    let requests = responses::mount_sse_sequence(
+        &server,
+        vec![
+            responses::sse(vec![
+                responses::ev_function_call("plan", tool_name, &json!({"plan": []}).to_string()),
+                responses::ev_completed("first"),
+            ]),
+            responses::sse(vec![
+                responses::ev_assistant_message("answer", "done"),
+                responses::ev_completed("last"),
+            ]),
+        ],
+    )
+    .await;
+    let observations = Arc::new(Observations::default());
+    let mut extensions = ExtensionRegistryBuilder::<Config>::new();
+    extensions.tool_lifecycle_contributor(observations.clone());
+    let test = test_codex()
+        .with_extensions(Arc::new(extensions.build()))
+        .with_config(|config| config.update_plan_enabled = true)
+        .build_with_auto_env(&server)
+        .await?;
+    test.submit_text_turn("update the plan").await?;
+    assert_eq!(requests.requests().len(), 2);
+    assert_eq!(
+        *observations
+            .events
+            .lock()
+            .expect("observation lock should not be poisoned"),
+        expected
+            .iter()
+            .map(|event| ("plan".into(), *event))
+            .collect::<Vec<_>>()
+    );
+    Ok(())
+}
+
+#[tokio::test(flavor = "multi_thread", worker_threads = 2)]
+async fn cancelled_tool_still_reports_handler_timing() -> Result<()> {
+    let server = responses::start_mock_server().await;
+    let requests = responses::mount_sse_once(
+        &server,
+        responses::sse(vec![
+            responses::ev_function_call("plan", "update_plan", &json!({"plan": []}).to_string()),
+            responses::ev_completed("first"),
+        ]),
+    )
+    .await;
+    let observations = Arc::new(Observations {
+        pause: true,
+        ..Default::default()
+    });
+    let mut extensions = ExtensionRegistryBuilder::<Config>::new();
+    extensions.tool_lifecycle_contributor(observations.clone());
+    let test = test_codex()
+        .with_extensions(Arc::new(extensions.build()))
+        .with_config(|config| config.update_plan_enabled = true)
+        .build_with_auto_env(&server)
+        .await?;
+    test.codex
+        .start_or_steer_turn(TurnInputRequest::user_input(vec![UserInput::Text {
+            text: "update the plan".into(),
+            text_elements: vec![],
+        }]))
+        .await?;
+    timeout(Duration::from_secs(10), observations.started.notified()).await?;
+    test.codex.submit(Op::Interrupt).await?;
+    timeout(Duration::from_secs(10), observations.timed.notified()).await?;
+    assert_eq!(requests.requests().len(), 1);
+    assert_eq!(
+        *observations
+            .events
+            .lock()
+            .expect("observation lock should not be poisoned"),
+        vec![
+            ("plan".into(), "dispatch"),
+            ("plan".into(), "start"),
+            ("plan".into(), "finish"),
+            ("plan".into(), "handler"),
+        ]
+    );
+    Ok(())
+}
+
+#[tokio::test(flavor = "multi_thread", worker_threads = 2)]
+async fn code_mode_reports_host_timing_without_nested_dispatch_timing() -> Result<()> {
+    let server = responses::start_mock_server().await;
+    let requests = responses::mount_sse_sequence(
+        &server,
+        vec![
+            responses::sse(vec![
+                responses::ev_custom_tool_call(
+                    "exec",
+                    "exec",
+                    "text(await tools.test_sync_tool({sleep_after_ms: 1}));",
+                ),
+                responses::ev_completed("first"),
+            ]),
+            responses::sse(vec![
+                responses::ev_assistant_message("answer", "done"),
+                responses::ev_completed("last"),
+            ]),
+        ],
+    )
+    .await;
+    let observations = Arc::new(Observations::default());
+    let mut extensions = ExtensionRegistryBuilder::<Config>::new();
+    extensions.tool_lifecycle_contributor(observations.clone());
+    let test = test_codex()
+        .with_extensions(Arc::new(extensions.build()))
+        .with_model("test-gpt-5.1-codex")
+        .with_config(|config| {
+            config
+                .features
+                .enable(Feature::CodeMode)
+                .expect("code mode should be enabled");
+        })
+        .build_with_auto_env(&server)
+        .await?;
+    test.submit_text_turn("run the nested tool").await?;
+    let requests = requests.requests();
+    assert_eq!(requests.len(), 2);
+    let events = observations
+        .events
+        .lock()
+        .expect("observation lock should not be poisoned");
+    let outer = events
+        .iter()
+        .filter(|(id, _)| id == "exec")
+        .cloned()
+        .collect::<Vec<_>>();
+    assert_eq!(
+        outer,
+        vec![
+            ("exec".into(), "dispatch"),
+            ("exec".into(), "start"),
+            ("exec".into(), "host"),
+            ("exec".into(), "finish"),
+            ("exec".into(), "handler"),
+        ],
+        "tool output: {:?}",
+        requests[1].custom_tool_call_output("exec")
+    );
+    let nested = events
+        .iter()
+        .filter(|(id, _)| id != "exec")
+        .map(|(_, event)| *event)
+        .collect::<Vec<_>>();
+    assert_eq!(nested, vec!["start", "finish"]);
+    Ok(())
+}

codex-rs/ext/extension-api/src/contributors.rs

@@ -50,6 +50,8 @@ pub use tool_lifecycle::ToolCallOutcome;
 pub use tool_lifecycle::ToolFinishInput;
 pub use tool_lifecycle::ToolLifecycleFuture;
 pub use tool_lifecycle::ToolStartInput;
+pub use tool_lifecycle::ToolTimingBoundary;
+pub use tool_lifecycle::ToolTimingInput;
 pub use turn_input::TurnInputContext;
 pub use turn_input::TurnInputEnvironment;
 pub use turn_lifecycle::TurnAbortInput;
@@ -349,6 +351,10 @@ pub trait ToolContributor: Send + Sync {
 /// rewriting the invocation. Use `ToolContributor` for owning a tool implementation
 /// and hooks for policy that changes tool payloads.
 pub trait ToolLifecycleContributor: Send + Sync {
+    /// Observe direct calls before readiness, dispatch waiting, and hooks, including blocked calls.
+    /// Excludes nested code-mode calls. Observers must return promptly.
+    fn on_tool_dispatch(&self, _input: ToolDispatchInput<'_>) {}
+
     /// Called after pre-tool hooks finalize an invocation and before execution.
     ///
     /// Calls blocked by hooks, or whose hook-provided input cannot be applied,
@@ -377,6 +383,10 @@ pub trait ToolLifecycleContributor: Send + Sync {
     fn on_tool_finish<'a>(&'a self, _input: ToolFinishInput<'a>) -> ToolLifecycleFuture<'a> {
         Box::pin(std::future::ready(()))
     }
+
+    /// Observe handler or remote host duration as defined by `ToolTimingBoundary`.
+    /// Handler timing includes cancellation. Observers must return promptly.
+    fn on_tool_timing(&self, _input: ToolTimingInput<'_>) {}
 }
 
 /// Owns the complete approval decision, including whether to consult a reviewer.
@@ -404,3 +414,5 @@ pub trait TurnItemContributor: Send + Sync {
         item: &'a mut TurnItem,
     ) -> ExtensionFuture<'a, Result<(), String>>;
 }
+
+pub use tool_lifecycle::ToolDispatchInput;

codex-rs/ext/extension-api/src/contributors/tool_lifecycle.rs

@@ -211,3 +211,45 @@ pub struct ToolFinishInput<'a> {
     /// Host-observed result of the tool call.
     pub outcome: ToolCallOutcome,
 }
+
+/// The execution interval represented by a tool timing observation.
+#[derive(Clone, Copy, Debug)]
+pub enum ToolTimingBoundary {
+    /// Elapsed time from admission through the parallel-execution gate until the
+    /// outer dispatch completes or is dropped. Includes routing, hooks, policy
+    /// checks, and result processing; excludes runtime readiness and gate waiting.
+    /// Zero if dispatch never passed the gate.
+    Handler,
+    /// Duration reported by the code-mode host for its exec or wait operation.
+    /// Measures the remote operation rather than the enclosing local dispatch.
+    HostOperation,
+}
+
+/// A measured tool interval. Handler observations also cover cancellation;
+/// host-operation observations are available only when the host reports a duration.
+/// Observers must not block.
+pub struct ToolTimingInput<'a> {
+    /// Thread that owns the tool call.
+    pub thread_id: &'a str,
+    /// Current turn submission id.
+    pub turn_id: &'a str,
+    /// Model-visible tool call id used to correlate dispatch and timing observations.
+    pub call_id: &'a str,
+    /// Execution interval measured by this observation.
+    pub boundary: ToolTimingBoundary,
+    /// Elapsed time within the specified boundary.
+    pub duration: std::time::Duration,
+}
+
+/// A direct call entering dispatch, before readiness, hooks, or policy checks.
+/// Observers must return promptly and cannot affect tool execution.
+pub struct ToolDispatchInput<'a> {
+    /// Thread that owns the tool call.
+    pub thread_id: &'a str,
+    /// Current turn submission id.
+    pub turn_id: &'a str,
+    /// Model-visible tool call id used to correlate dispatch and timing observations.
+    pub call_id: &'a str,
+    /// Tool name supplied to dispatch, before pre-tool hooks run.
+    pub tool_name: &'a ToolName,
+}

codex-rs/ext/extension-api/src/lib.rs

@@ -82,6 +82,8 @@ pub use contributors::ToolFinishInput;
 pub use contributors::ToolLifecycleContributor;
 pub use contributors::ToolLifecycleFuture;
 pub use contributors::ToolStartInput;
+pub use contributors::ToolTimingBoundary;
+pub use contributors::ToolTimingInput;
 pub use contributors::TurnAbortInput;
 pub use contributors::TurnContextContributionInput;
 pub use contributors::TurnErrorInput;
@@ -106,3 +108,5 @@ pub use user_instructions::LoadInstructionsFuture;
 pub use user_instructions::LoadedUserInstructions;
 pub use user_instructions::ThreadInstructionsProvider;
 pub use user_instructions::UserInstructionsProvider;
+
+pub use contributors::ToolDispatchInput;