Skip to content

trace hook command execution #31501

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
wiltzius-openai merged 1 commit into from
Jul 8, 2026
Merged

trace hook command execution #31501

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
141 changes: 101 additions & 40 deletions codex-rs/hooks/src/engine/command_runner.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand All @@ -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 {
Expand All @@ -41,62 +67,97 @@ 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",
},
);
}
};

if let Some(mut stdin) = child.stdin.take()
&& 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,
}
}

Expand Down
60 changes: 58 additions & 2 deletions codex-rs/hooks/src/engine/dispatcher.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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))
});
}
Expand Down Expand Up @@ -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
Expand All @@ -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;
Expand Down
Loading