scriptoriumadmin/fabro
1
0
Fork 0
mirror of https://github.com/fabro-sh/fabro.git synced 2026-09-07 08:27:12 +00:00
Code Issues Projects Releases Packages Wiki Activity Actions 3

Add trace() method to event enums for structured file logging

Browse source 
Every emitted event now produces a structured tracing log line so
developers can debug after the fact via ~/.arc/logs/. Each event
variant gets an appropriate log level (info/debug/warn/error) with
structured fields. Streaming noise variants (TextDelta,
ToolCallOutputDelta) are no-ops, and wrapper variants (Agent,
ExecutionEnv on PipelineEvent) delegate to the inner event's trace.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
This commit is contained in:
Bryan Helmkamp 2026-03-01 19:15:43 -05:00
parent 5ea508a5ca
commit ec70be1e0d
11 changed files with 526 additions and 0 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

2
Cargo.lock generated
View file

@ -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",
]

1
crates/arc-agent/Cargo.toml
View file

@ -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"

1
crates/arc-agent/src/docker_env.rs
View file

@ -91,6 +91,7 @@ impl DockerExecutionEnvironment {
}
fn emit(&self, event: ExecutionEnvEvent) {
event.trace();
if let Some(ref cb) = self.event_callback {
cb(event);
}

1
crates/arc-agent/src/event.rs
View file

@ -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(),

63
crates/arc-agent/src/execution_env.rs
View file

@ -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<dyn Fn(ExecutionEnvEvent) + Send + Sync>;

1
crates/arc-agent/src/local_env.rs
View file

@ -30,6 +30,7 @@ impl LocalExecutionEnvironment {
}
fn emit(&self, event: ExecutionEnvEvent) {
event.trace();
if let Some(ref cb) = self.event_callback {
cb(event);
}

1
crates/arc-agent/src/test_support.rs
View file

@ -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);
}

200
crates/arc-agent/src/types.rs
View file

@ -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,

1
crates/arc-workflows/Cargo.toml
View file

@ -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"

1
crates/arc-workflows/src/daytona_env.rs
View file

@ -70,6 +70,7 @@ impl DaytonaExecutionEnvironment {
}
fn emit(&self, event: ExecutionEnvEvent) {
event.trace();
if let Some(ref cb) = self.event_callback {
cb(event);
}

254
crates/arc-workflows/src/event.rs
View file

@ -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<dyn Fn(&PipelineEvent) + Send + Sync>;
@ -208,6 +461,7 @@ impl EventEmitter {
}
pub fn emit(&self, event: &PipelineEvent) {
event.trace();
for listener in &self.listeners {
listener(event);
}