From e3465fe7a8d4dde0a7dc06610fe26e7a30e5e8f4 Mon Sep 17 00:00:00 2001 From: Tom Wiltzius Date: Tue, 7 Jul 2026 16:48:57 -0700 Subject: [PATCH] trace hook command execution --- codex-rs/hooks/src/engine/command_runner.rs | 141 ++++++++++++++------ codex-rs/hooks/src/engine/dispatcher.rs | 60 ++++++++- 2 files changed, 159 insertions(+), 42 deletions(-) diff --git a/codex-rs/hooks/src/engine/command_runner.rs b/codex-rs/hooks/src/engine/command_runner.rs index 7366d4ec511b..9f4c4e605949 100644 --- a/codex-rs/hooks/src/engine/command_runner.rs +++ b/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, } +#[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, + stdout: String, + stderr: String, + error: Option, + 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, } } diff --git a/codex-rs/hooks/src/engine/dispatcher.rs b/codex-rs/hooks/src/engine/dispatcher.rs index 50822bfc9612..ccf5c2c8e679 100644 --- a/codex-rs/hooks/src/engine/dispatcher.rs +++ b/codex-rs/hooks/src/engine/dispatcher.rs @@ -99,7 +99,7 @@ pub(crate) async fn execute_handlers( 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;