trace hook command execution (#31501)

Adds a single trace span around configured hook command execution so
slow installed hooks are visible directly in traces.

The span records low-cardinality hook metadata and command outcome
without command text, hook input, stdout, or stderr.

codex-rs/hooks/src/engine/command_runner.rs

@@ -6,9 +6,18 @@ use std::time::Instant;
 use tokio::io::AsyncWriteExt;
 use tokio::process::Command;
 use tokio::time::timeout;
+use tracing::Span;
 
 use super::CommandShell;
 use super::ConfiguredHandler;
+use super::dispatcher::hook_event_name_label;
+use super::dispatcher::hook_execution_mode_label;
+use super::dispatcher::hook_handler_type_label;
+use super::dispatcher::hook_scope_label;
+use super::dispatcher::hook_source_label;
+use super::dispatcher::scope_for_event;
+use codex_protocol::protocol::HookExecutionMode;
+use codex_protocol::protocol::HookHandlerType;
 
 #[derive(Debug)]
 pub(crate) struct CommandRunResult {
@@ -21,9 +30,26 @@ pub(crate) struct CommandRunResult {
     pub error: Option<String>,
 }
 
+#[tracing::instrument(
+    name = "codex.hooks.command",
+    level = "trace",
+    skip_all,
+    fields(
+        hook.event_name = hook_event_name_label(handler.event_name),
+        hook.handler_type = hook_handler_type_label(HookHandlerType::Command),
+        hook.execution_mode = hook_execution_mode_label(HookExecutionMode::Sync),
+        hook.scope = hook_scope_label(scope_for_event(handler.event_name)),
+        hook.source = hook_source_label(handler.source),
+        hook.display_order = handler.display_order,
+        hook.configured_order = configured_order,
+        hook.timeout_sec = handler.timeout_sec,
+        hook.command_outcome = tracing::field::Empty,
+    )
+)]
 pub(crate) async fn run_command(
     shell: &CommandShell,
     handler: &ConfiguredHandler,
+    configured_order: usize,
     input_json: &str,
     cwd: &Path,
 ) -> CommandRunResult {
@@ -41,15 +67,17 @@ pub(crate) async fn run_command(
     let mut child = match command.spawn() {
         Ok(child) => child,
         Err(err) => {
-            return CommandRunResult {
+            return finish_command_run(
                 started_at,
-                completed_at: chrono::Utc::now().timestamp(),
-                duration_ms: started.elapsed().as_millis().try_into().unwrap_or(i64::MAX),
-                exit_code: None,
-                stdout: String::new(),
-                stderr: String::new(),
-                error: Some(err.to_string()),
-            };
+                started,
+                CommandRunCompletion {
+                    exit_code: None,
+                    stdout: String::new(),
+                    stderr: String::new(),
+                    error: Some(err.to_string()),
+                    outcome: "spawn_error",
+                },
+            );
         }
     };
 
@@ -57,46 +85,79 @@ pub(crate) async fn run_command(
         && let Err(err) = stdin.write_all(input_json.as_bytes()).await
     {
         let _ = child.kill().await;
-        return CommandRunResult {
+        return finish_command_run(
             started_at,
-            completed_at: chrono::Utc::now().timestamp(),
-            duration_ms: started.elapsed().as_millis().try_into().unwrap_or(i64::MAX),
-            exit_code: None,
-            stdout: String::new(),
-            stderr: String::new(),
-            error: Some(format!("failed to write hook stdin: {err}")),
-        };
+            started,
+            CommandRunCompletion {
+                exit_code: None,
+                stdout: String::new(),
+                stderr: String::new(),
+                error: Some(format!("failed to write hook stdin: {err}")),
+                outcome: "stdin_error",
+            },
+        );
     }
 
     let timeout_duration = Duration::from_secs(handler.timeout_sec);
     match timeout(timeout_duration, child.wait_with_output()).await {
-        Ok(Ok(output)) => CommandRunResult {
+        Ok(Ok(output)) => finish_command_run(
             started_at,
-            completed_at: chrono::Utc::now().timestamp(),
-            duration_ms: started.elapsed().as_millis().try_into().unwrap_or(i64::MAX),
-            exit_code: output.status.code(),
-            stdout: String::from_utf8_lossy(&output.stdout).to_string(),
-            stderr: String::from_utf8_lossy(&output.stderr).to_string(),
-            error: None,
-        },
-        Ok(Err(err)) => CommandRunResult {
+            started,
+            CommandRunCompletion {
+                exit_code: output.status.code(),
+                stdout: String::from_utf8_lossy(&output.stdout).to_string(),
+                stderr: String::from_utf8_lossy(&output.stderr).to_string(),
+                error: None,
+                outcome: "completed",
+            },
+        ),
+        Ok(Err(err)) => finish_command_run(
             started_at,
-            completed_at: chrono::Utc::now().timestamp(),
-            duration_ms: started.elapsed().as_millis().try_into().unwrap_or(i64::MAX),
-            exit_code: None,
-            stdout: String::new(),
-            stderr: String::new(),
-            error: Some(err.to_string()),
-        },
-        Err(_) => CommandRunResult {
+            started,
+            CommandRunCompletion {
+                exit_code: None,
+                stdout: String::new(),
+                stderr: String::new(),
+                error: Some(err.to_string()),
+                outcome: "wait_error",
+            },
+        ),
+        Err(_) => finish_command_run(
             started_at,
-            completed_at: chrono::Utc::now().timestamp(),
-            duration_ms: started.elapsed().as_millis().try_into().unwrap_or(i64::MAX),
-            exit_code: None,
-            stdout: String::new(),
-            stderr: String::new(),
-            error: Some(format!("hook timed out after {}s", handler.timeout_sec)),
-        },
+            started,
+            CommandRunCompletion {
+                exit_code: None,
+                stdout: String::new(),
+                stderr: String::new(),
+                error: Some(format!("hook timed out after {}s", handler.timeout_sec)),
+                outcome: "timeout",
+            },
+        ),
+    }
+}
+
+struct CommandRunCompletion {
+    exit_code: Option<i32>,
+    stdout: String,
+    stderr: String,
+    error: Option<String>,
+    outcome: &'static str,
+}
+
+fn finish_command_run(
+    started_at: i64,
+    started: Instant,
+    completion: CommandRunCompletion,
+) -> CommandRunResult {
+    Span::current().record("hook.command_outcome", completion.outcome);
+    CommandRunResult {
+        started_at,
+        completed_at: chrono::Utc::now().timestamp(),
+        duration_ms: started.elapsed().as_millis().try_into().unwrap_or(i64::MAX),
+        exit_code: completion.exit_code,
+        stdout: completion.stdout,
+        stderr: completion.stderr,
+        error: completion.error,
     }
 }
 

codex-rs/hooks/src/engine/dispatcher.rs

@@ -99,7 +99,7 @@ pub(crate) async fn execute_handlers<T>(
         let input_json = input_json.clone();
         let turn_id = turn_id.clone();
         pending.push(async move {
-            let result = run_command(shell, &handler, &input_json, cwd).await;
+            let result = run_command(shell, &handler, configured_order, &input_json, cwd).await;
             (configured_order, parse(&handler, result, turn_id))
         });
     }
@@ -139,7 +139,7 @@ pub(crate) fn completed_summary(
     }
 }
 
-fn scope_for_event(event_name: HookEventName) -> HookScope {
+pub(crate) fn scope_for_event(event_name: HookEventName) -> HookScope {
     match event_name {
         HookEventName::SessionStart | HookEventName::SubagentStart => HookScope::Thread,
         HookEventName::PreToolUse
@@ -153,12 +153,68 @@ fn scope_for_event(event_name: HookEventName) -> HookScope {
     }
 }
 
+pub(crate) fn hook_event_name_label(event_name: HookEventName) -> &'static str {
+    match event_name {
+        HookEventName::PreToolUse => "PreToolUse",
+        HookEventName::PermissionRequest => "PermissionRequest",
+        HookEventName::PostToolUse => "PostToolUse",
+        HookEventName::PreCompact => "PreCompact",
+        HookEventName::PostCompact => "PostCompact",
+        HookEventName::SessionStart => "SessionStart",
+        HookEventName::UserPromptSubmit => "UserPromptSubmit",
+        HookEventName::SubagentStart => "SubagentStart",
+        HookEventName::SubagentStop => "SubagentStop",
+        HookEventName::Stop => "Stop",
+    }
+}
+
+pub(crate) fn hook_execution_mode_label(mode: HookExecutionMode) -> &'static str {
+    match mode {
+        HookExecutionMode::Sync => "sync",
+        HookExecutionMode::Async => "async",
+    }
+}
+
+pub(crate) fn hook_handler_type_label(handler_type: HookHandlerType) -> &'static str {
+    match handler_type {
+        HookHandlerType::Command => "command",
+        HookHandlerType::Prompt => "prompt",
+        HookHandlerType::Agent => "agent",
+    }
+}
+
+pub(crate) fn hook_scope_label(scope: HookScope) -> &'static str {
+    match scope {
+        HookScope::Thread => "thread",
+        HookScope::Turn => "turn",
+    }
+}
+
+pub(crate) fn hook_source_label(source: codex_protocol::protocol::HookSource) -> &'static str {
+    match source {
+        codex_protocol::protocol::HookSource::System => "system",
+        codex_protocol::protocol::HookSource::User => "user",
+        codex_protocol::protocol::HookSource::Project => "project",
+        codex_protocol::protocol::HookSource::Mdm => "mdm",
+        codex_protocol::protocol::HookSource::SessionFlags => "session_flags",
+        codex_protocol::protocol::HookSource::Plugin => "plugin",
+        codex_protocol::protocol::HookSource::CloudRequirements => "cloud_requirements",
+        codex_protocol::protocol::HookSource::CloudManagedConfig => "cloud_managed_config",
+        codex_protocol::protocol::HookSource::LegacyManagedConfigFile => {
+            "legacy_managed_config_file"
+        }
+        codex_protocol::protocol::HookSource::LegacyManagedConfigMdm => "legacy_managed_config_mdm",
+        codex_protocol::protocol::HookSource::Unknown => "unknown",
+    }
+}
+
 #[cfg(test)]
 mod tests {
     use codex_protocol::protocol::HookEventName;
     use codex_protocol::protocol::HookSource;
     use codex_utils_absolute_path::test_support::PathBufExt;
     use codex_utils_absolute_path::test_support::test_path_buf;
+    use pretty_assertions::assert_eq;
 
     use super::ConfiguredHandler;
     use super::select_handlers;