diff --git a/Cargo.lock b/Cargo.lock index 42c60ac1b..7e520798c 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -125,6 +125,7 @@ dependencies = [ "thiserror 2.0.18", "tokio", "tokio-util", + "tracing", "uuid", ] @@ -282,6 +283,7 @@ dependencies = [ "tokio", "tokio-util", "toml", + "tracing", "ulid", "uuid", ] diff --git a/crates/arc-agent/Cargo.toml b/crates/arc-agent/Cargo.toml index 0c80fbcae..9a8cbb8d4 100644 --- a/crates/arc-agent/Cargo.toml +++ b/crates/arc-agent/Cargo.toml @@ -34,6 +34,7 @@ jsonschema.workspace = true chrono.workspace = true reqwest.workspace = true tokio-util.workspace = true +tracing.workspace = true dirs = "6" glob = "0.3" shell-escape = "0.1" diff --git a/crates/arc-agent/src/docker_env.rs b/crates/arc-agent/src/docker_env.rs index 08ee0a114..b09c1830c 100644 --- a/crates/arc-agent/src/docker_env.rs +++ b/crates/arc-agent/src/docker_env.rs @@ -91,6 +91,7 @@ impl DockerExecutionEnvironment { } fn emit(&self, event: ExecutionEnvEvent) { + event.trace(); if let Some(ref cb) = self.event_callback { cb(event); } diff --git a/crates/arc-agent/src/event.rs b/crates/arc-agent/src/event.rs index fd4a73722..d6320cefe 100644 --- a/crates/arc-agent/src/event.rs +++ b/crates/arc-agent/src/event.rs @@ -15,6 +15,7 @@ impl EventEmitter { } pub fn emit(&self, session_id: String, event: AgentEvent) { + event.trace(&session_id); let wrapped = SessionEvent { event, timestamp: SystemTime::now(), diff --git a/crates/arc-agent/src/execution_env.rs b/crates/arc-agent/src/execution_env.rs index 77539bb49..4671ea80a 100644 --- a/crates/arc-agent/src/execution_env.rs +++ b/crates/arc-agent/src/execution_env.rs @@ -151,6 +151,69 @@ pub enum ExecutionEnvEvent { }, } +impl ExecutionEnvEvent { + pub fn trace(&self) { + use tracing::{debug, error, info, warn}; + match self { + Self::Initializing { env_type } => { + debug!(env_type, "Execution env initializing"); + } + Self::Ready { + env_type, + duration_ms, + } => { + info!(env_type, duration_ms, "Execution env ready"); + } + Self::InitializeFailed { + env_type, + error, + duration_ms, + } => { + error!(env_type, error, duration_ms, "Execution env init failed"); + } + Self::CleanupStarted { env_type } => { + debug!(env_type, "Execution env cleanup started"); + } + Self::CleanupCompleted { + env_type, + duration_ms, + } => { + debug!(env_type, duration_ms, "Execution env cleanup completed"); + } + Self::CleanupFailed { env_type, error } => { + warn!(env_type, error, "Execution env cleanup failed"); + } + Self::ImagePulling { image } => { + debug!(image, "Docker image pulling"); + } + Self::ImagePulled { image, duration_ms } => { + debug!(image, duration_ms, "Docker image pulled"); + } + Self::SnapshotEnsuring { name } => { + debug!(name, "Snapshot ensuring"); + } + Self::SnapshotCreating { name } => { + debug!(name, "Snapshot creating"); + } + Self::SnapshotReady { name, duration_ms } => { + info!(name, duration_ms, "Snapshot ready"); + } + Self::SnapshotFailed { name, error } => { + error!(name, error, "Snapshot failed"); + } + Self::GitCloneStarted { url, branch } => { + debug!(url, branch = branch.as_deref().unwrap_or(""), "Git clone started"); + } + Self::GitCloneCompleted { url, duration_ms } => { + debug!(url, duration_ms, "Git clone completed"); + } + Self::GitCloneFailed { url, error } => { + error!(url, error, "Git clone failed"); + } + } + } +} + /// Callback type for execution environment events. pub type ExecEnvEventCallback = Arc; diff --git a/crates/arc-agent/src/local_env.rs b/crates/arc-agent/src/local_env.rs index fc700a7b8..df61c38ff 100644 --- a/crates/arc-agent/src/local_env.rs +++ b/crates/arc-agent/src/local_env.rs @@ -30,6 +30,7 @@ impl LocalExecutionEnvironment { } fn emit(&self, event: ExecutionEnvEvent) { + event.trace(); if let Some(ref cb) = self.event_callback { cb(event); } diff --git a/crates/arc-agent/src/test_support.rs b/crates/arc-agent/src/test_support.rs index 26a54fbbe..2bcc1b128 100644 --- a/crates/arc-agent/src/test_support.rs +++ b/crates/arc-agent/src/test_support.rs @@ -49,6 +49,7 @@ impl MockExecutionEnvironment { impl MockExecutionEnvironment { fn emit(&self, event: crate::execution_env::ExecutionEnvEvent) { + event.trace(); if let Some(ref cb) = self.event_callback { cb(event); } diff --git a/crates/arc-agent/src/types.rs b/crates/arc-agent/src/types.rs index a25cb6196..ff2aaafab 100644 --- a/crates/arc-agent/src/types.rs +++ b/crates/arc-agent/src/types.rs @@ -187,6 +187,206 @@ pub enum AgentEvent { }, } +impl AgentEvent { + pub fn trace(&self, session_id: &str) { + use tracing::{debug, error, info, warn}; + match self { + Self::SessionStarted => { + info!(session_id, "Agent session started"); + } + Self::SessionEnded => { + info!(session_id, "Agent session ended"); + } + Self::UserInput { text } => { + debug!(session_id, text_len = text.len(), "User input received"); + } + Self::AssistantTextStart => { + debug!(session_id, "Assistant response started"); + } + Self::AssistantMessage { + model, + usage, + tool_call_count, + .. + } => { + info!( + session_id, + model, + input_tokens = usage.input_tokens, + output_tokens = usage.output_tokens, + tool_call_count, + "Assistant message" + ); + } + Self::TextDelta { .. } => {} + Self::ToolCallStarted { + tool_name, + tool_call_id, + .. + } => { + debug!( + session_id, + tool = tool_name.as_str(), + tool_call_id, + "Tool call started" + ); + } + Self::ToolCallOutputDelta { .. } => {} + Self::ToolCallCompleted { + tool_name, + tool_call_id, + is_error, + .. + } => { + debug!( + session_id, + tool = tool_name.as_str(), + tool_call_id, + is_error, + "Tool call completed" + ); + } + Self::Error { error } => { + error!(session_id, error, "Agent error"); + } + Self::ContextWindowWarning { + estimated_tokens, + context_window_size, + usage_percent, + } => { + warn!( + session_id, + estimated_tokens, + context_window_size, + usage_percent, + "Context window usage high" + ); + } + Self::LoopDetected => { + warn!(session_id, "Loop detected"); + } + Self::TurnLimitReached { max_turns } => { + warn!(session_id, max_turns, "Turn limit reached"); + } + Self::SkillExpanded { skill_name } => { + debug!(session_id, skill = skill_name.as_str(), "Skill expanded"); + } + Self::SteeringInjected { text } => { + debug!(session_id, text_len = text.len(), "Steering injected"); + } + Self::CompactionStarted { + estimated_tokens, + context_window_size, + } => { + info!( + session_id, + estimated_tokens, + context_window_size, + "Context compaction started" + ); + } + Self::CompactionCompleted { + original_turn_count, + preserved_turn_count, + summary_token_estimate, + tracked_file_count, + } => { + info!( + session_id, + original_turn_count, + preserved_turn_count, + summary_token_estimate, + tracked_file_count, + "Context compaction completed" + ); + } + Self::LlmRetry { + provider, + model, + attempt, + delay_secs, + error, + } => { + warn!( + session_id, + provider, + model, + attempt, + delay_secs, + error, + "LLM request failed, retrying" + ); + } + Self::SubAgentSpawned { + agent_id, + depth, + task, + } => { + debug!( + session_id, + agent_id, + depth, + task, + "Sub-agent spawned" + ); + } + Self::SubAgentCompleted { + agent_id, + depth, + success, + turns_used, + } => { + debug!( + session_id, + agent_id, + depth, + success, + turns_used, + "Sub-agent completed" + ); + } + Self::SubAgentFailed { + agent_id, + depth, + error, + } => { + warn!( + session_id, + agent_id, + depth, + error, + "Sub-agent failed" + ); + } + Self::SubAgentClosed { agent_id, depth } => { + debug!(session_id, agent_id, depth, "Sub-agent closed"); + } + Self::SubAgentEvent { event, .. } => { + event.trace(session_id); + } + Self::McpServerReady { + server_name, + tool_count, + } => { + info!( + session_id, + server = server_name.as_str(), + tool_count, + "MCP server ready" + ); + } + Self::McpServerFailed { server_name, error } => { + error!( + session_id, + server = server_name.as_str(), + error, + "MCP server failed" + ); + } + } + } +} + #[derive(Debug, Clone, Serialize, Deserialize)] pub struct SessionEvent { pub event: AgentEvent, diff --git a/crates/arc-workflows/Cargo.toml b/crates/arc-workflows/Cargo.toml index 136594a31..84676873e 100644 --- a/crates/arc-workflows/Cargo.toml +++ b/crates/arc-workflows/Cargo.toml @@ -41,6 +41,7 @@ regex.workspace = true scopeguard = "1" git2.workspace = true tokio-util.workspace = true +tracing.workspace = true [dev-dependencies] tokio = { workspace = true, features = ["test-util", "macros"] } tempfile = "3" diff --git a/crates/arc-workflows/src/daytona_env.rs b/crates/arc-workflows/src/daytona_env.rs index c952e4933..d07e9ba4b 100644 --- a/crates/arc-workflows/src/daytona_env.rs +++ b/crates/arc-workflows/src/daytona_env.rs @@ -70,6 +70,7 @@ impl DaytonaExecutionEnvironment { } fn emit(&self, event: ExecutionEnvEvent) { + event.trace(); if let Some(ref cb) = self.event_callback { cb(event); } diff --git a/crates/arc-workflows/src/event.rs b/crates/arc-workflows/src/event.rs index 8b7664cc4..7caa53bd6 100644 --- a/crates/arc-workflows/src/event.rs +++ b/crates/arc-workflows/src/event.rs @@ -173,6 +173,259 @@ pub enum PipelineEvent { }, } +impl PipelineEvent { + pub fn trace(&self) { + use tracing::{debug, error, info, warn}; + match self { + Self::PipelineStarted { name, run_id, .. } => { + info!(pipeline = name.as_str(), run_id, "Pipeline started"); + } + Self::PipelineCompleted { + duration_ms, + artifact_count, + .. + } => { + info!(duration_ms, artifact_count, "Pipeline completed"); + } + Self::PipelineFailed { + error, duration_ms, .. + } => { + error!(error, duration_ms, "Pipeline failed"); + } + Self::StageStarted { + name, + index, + handler_type, + attempt, + max_attempts, + } => { + debug!( + stage = name.as_str(), + index, + handler_type = handler_type.as_deref().unwrap_or(""), + attempt, + max_attempts, + "Stage started" + ); + } + Self::StageCompleted { + name, + index, + duration_ms, + status, + attempt, + max_attempts, + .. + } => { + debug!( + stage = name.as_str(), + index, + duration_ms, + status, + attempt, + max_attempts, + "Stage completed" + ); + } + Self::StageFailed { + name, + index, + error, + will_retry, + .. + } => { + if *will_retry { + warn!( + stage = name.as_str(), + index, + error, + will_retry, + "Stage failed" + ); + } else { + error!( + stage = name.as_str(), + index, + error, + will_retry, + "Stage failed" + ); + } + } + Self::StageRetrying { + name, + index, + attempt, + max_attempts, + delay_ms, + } => { + warn!( + stage = name.as_str(), + index, + attempt, + max_attempts, + delay_ms, + "Stage retrying" + ); + } + Self::ParallelStarted { + branch_count, + join_policy, + error_policy, + } => { + debug!( + branch_count, + join_policy, + error_policy, + "Parallel execution started" + ); + } + Self::ParallelBranchStarted { branch, index } => { + debug!(branch, index, "Parallel branch started"); + } + Self::ParallelBranchCompleted { + branch, + index, + duration_ms, + status, + } => { + debug!( + branch, + index, + duration_ms, + status, + "Parallel branch completed" + ); + } + Self::ParallelCompleted { + duration_ms, + success_count, + failure_count, + } => { + debug!( + duration_ms, + success_count, + failure_count, + "Parallel execution completed" + ); + } + Self::InterviewStarted { + stage, + question_type, + .. + } => { + debug!(stage, question_type, "Interview started"); + } + Self::InterviewCompleted { duration_ms, .. } => { + debug!(duration_ms, "Interview completed"); + } + Self::InterviewTimeout { + stage, duration_ms, .. + } => { + warn!(stage, duration_ms, "Interview timeout"); + } + Self::CheckpointSaved { node_id } => { + debug!(node_id, "Checkpoint saved"); + } + Self::GitCheckpoint { + run_id, + node_id, + status, + .. + } => { + debug!(run_id, node_id, status, "Git checkpoint"); + } + Self::EdgeSelected { + from_node, + to_node, + label, + .. + } => { + debug!( + from_node, + to_node, + label = label.as_deref().unwrap_or(""), + "Edge selected" + ); + } + Self::LoopRestart { + from_node, + to_node, + } => { + debug!(from_node, to_node, "Loop restart"); + } + Self::Prompt { stage, text } => { + debug!(stage, text_len = text.len(), "Prompt sent"); + } + Self::Agent { .. } => {} + Self::ExecutionEnv { .. } => {} + Self::ParallelEarlyTermination { + reason, + completed_count, + pending_count, + } => { + warn!( + reason, + completed_count, + pending_count, + "Parallel early termination" + ); + } + Self::SubgraphStarted { + node_id, + start_node, + } => { + debug!(node_id, start_node, "Subgraph started"); + } + Self::SubgraphCompleted { + node_id, + steps_executed, + status, + duration_ms, + } => { + debug!( + node_id, + steps_executed, + status, + duration_ms, + "Subgraph completed" + ); + } + Self::SetupStarted { command_count } => { + info!(command_count, "Setup started"); + } + Self::SetupCommandStarted { command, index } => { + debug!(command, index, "Setup command started"); + } + Self::SetupCommandCompleted { + command, + index, + exit_code, + duration_ms, + } => { + debug!( + command, + index, + exit_code, + duration_ms, + "Setup command completed" + ); + } + Self::SetupCompleted { duration_ms } => { + info!(duration_ms, "Setup completed"); + } + Self::SetupFailed { + command, + index, + exit_code, + .. + } => { + error!(command, index, exit_code, "Setup command failed"); + } + } + } +} + /// Listener callback type for pipeline events. type EventListener = Box; @@ -208,6 +461,7 @@ impl EventEmitter { } pub fn emit(&self, event: &PipelineEvent) { + event.trace(); for listener in &self.listeners { listener(event); }