diff --git a/gigacode/src/main.rs b/gigacode/src/main.rs index 6710c17..f5e1775 100644 --- a/gigacode/src/main.rs +++ b/gigacode/src/main.rs @@ -11,6 +11,7 @@ fn main() { } fn run() -> Result<(), CliError> { + let started = std::time::Instant::now(); let cli = GigacodeCli::parse(); let config = CliConfig { token: cli.token, @@ -34,5 +35,18 @@ fn run() -> Result<(), CliError> { eprintln!("failed to init logging: {err}"); return Err(err); } - run_command(&command, &config) + tracing::info!( + command = ?command, + startup_ms = started.elapsed().as_millis() as u64, + "gigacode.run: command starting" + ); + let command_started = std::time::Instant::now(); + let result = run_command(&command, &config); + tracing::info!( + command = ?command, + command_ms = command_started.elapsed().as_millis() as u64, + total_ms = started.elapsed().as_millis() as u64, + "gigacode.run: command exited" + ); + result } diff --git a/server/packages/acp-http-adapter/src/app.rs b/server/packages/acp-http-adapter/src/app.rs index 556892f..cd2e074 100644 --- a/server/packages/acp-http-adapter/src/app.rs +++ b/server/packages/acp-http-adapter/src/app.rs @@ -93,6 +93,20 @@ fn map_error(err: AdapterError) -> Response { "timeout", "timed out waiting for agent response", ), + AdapterError::Exited { exit_code, stderr } => { + let detail = if let Some(stderr) = stderr { + format!( + "agent process exited before responding (exit_code: {:?}, stderr: {})", + exit_code, stderr + ) + } else { + format!( + "agent process exited before responding (exit_code: {:?})", + exit_code + ) + }; + problem(StatusCode::BAD_GATEWAY, "agent_exited", &detail) + } AdapterError::Write(write) => problem( StatusCode::BAD_GATEWAY, "write_failed", diff --git a/server/packages/acp-http-adapter/src/main.rs b/server/packages/acp-http-adapter/src/main.rs index 16b1c0f..7ca7819 100644 --- a/server/packages/acp-http-adapter/src/main.rs +++ b/server/packages/acp-http-adapter/src/main.rs @@ -32,6 +32,7 @@ async fn main() { } async fn run() -> Result<(), Box> { + let started = std::time::Instant::now(); tracing_subscriber::fmt() .with_env_filter( tracing_subscriber::EnvFilter::try_from_default_env() @@ -41,6 +42,12 @@ async fn run() -> Result<(), Box> { .init(); let cli = Cli::parse(); + tracing::info!( + host = %cli.host, + port = cli.port, + startup_ms = started.elapsed().as_millis() as u64, + "acp-http-adapter.run: starting server" + ); run_server(ServerConfig { host: cli.host, port: cli.port, diff --git a/server/packages/acp-http-adapter/src/process.rs b/server/packages/acp-http-adapter/src/process.rs index bfaac2c..74101ed 100644 --- a/server/packages/acp-http-adapter/src/process.rs +++ b/server/packages/acp-http-adapter/src/process.rs @@ -16,6 +16,7 @@ use tokio_stream::wrappers::BroadcastStream; use crate::registry::LaunchSpec; const RING_BUFFER_SIZE: usize = 1024; +const STDERR_TAIL_SIZE: usize = 16; #[derive(Debug, Error)] pub enum AdapterError { @@ -33,6 +34,11 @@ pub enum AdapterError { Serialize(serde_json::Error), #[error("failed to write subprocess stdin: {0}")] Write(std::io::Error), + #[error("agent process exited before responding")] + Exited { + exit_code: Option, + stderr: Option, + }, #[error("timeout waiting for response")] Timeout, } @@ -61,6 +67,7 @@ pub struct AdapterRuntime { shutting_down: AtomicBool, spawned_at: Instant, first_stdout: Arc, + stderr_tail: Arc>>, } impl AdapterRuntime { @@ -120,6 +127,7 @@ impl AdapterRuntime { shutting_down: AtomicBool::new(false), spawned_at: spawn_start, first_stdout: Arc::new(AtomicBool::new(false)), + stderr_tail: Arc::new(Mutex::new(VecDeque::with_capacity(STDERR_TAIL_SIZE))), }; runtime.spawn_stdout_loop(stdout); @@ -198,6 +206,16 @@ impl AdapterRuntime { "post: response channel dropped (agent process may have exited)" ); self.pending.lock().await.remove(&key); + if let Some((exit_code, stderr)) = self.try_process_exit_info().await { + tracing::error!( + method = %method, + id = %key, + exit_code = ?exit_code, + stderr = ?stderr, + "post: agent process exited before response channel completed" + ); + return Err(AdapterError::Exited { exit_code, stderr }); + } Err(AdapterError::Timeout) } Err(_) => { @@ -213,6 +231,16 @@ impl AdapterRuntime { "post: TIMEOUT waiting for agent response" ); self.pending.lock().await.remove(&key); + if let Some((exit_code, stderr)) = self.try_process_exit_info().await { + tracing::error!( + method = %method, + id = %key, + exit_code = ?exit_code, + stderr = ?stderr, + "post: agent process exited before timeout completed" + ); + return Err(AdapterError::Exited { exit_code, stderr }); + } Err(AdapterError::Timeout) } } @@ -445,6 +473,7 @@ impl AdapterRuntime { fn spawn_stderr_loop(&self, stderr: tokio::process::ChildStderr) { let spawned_at = self.spawned_at; + let stderr_tail = self.stderr_tail.clone(); tokio::spawn(async move { let mut lines = BufReader::new(stderr).lines(); @@ -452,6 +481,13 @@ impl AdapterRuntime { while let Ok(Some(line)) = lines.next_line().await { line_count += 1; + { + let mut tail = stderr_tail.lock().await; + tail.push_back(line.clone()); + while tail.len() > STDERR_TAIL_SIZE { + tail.pop_front(); + } + } tracing::info!( line_number = line_count, age_ms = spawned_at.elapsed().as_millis() as u64, @@ -560,6 +596,28 @@ impl AdapterRuntime { tracing::debug!(method = method, id = %id, "stdin: write+flush complete"); Ok(()) } + + async fn try_process_exit_info(&self) -> Option<(Option, Option)> { + let mut child = self.child.lock().await; + match child.try_wait() { + Ok(Some(status)) => { + let exit_code = status.code(); + drop(child); + let stderr = self.stderr_tail_summary().await; + Some((exit_code, stderr)) + } + Ok(None) => None, + Err(_) => None, + } + } + + async fn stderr_tail_summary(&self) -> Option { + let tail = self.stderr_tail.lock().await; + if tail.is_empty() { + return None; + } + Some(tail.iter().cloned().collect::>().join("\n")) + } } fn id_key(value: &Value) -> String { diff --git a/server/packages/agent-management/Cargo.toml b/server/packages/agent-management/Cargo.toml index 799229e..f9ad9cb 100644 --- a/server/packages/agent-management/Cargo.toml +++ b/server/packages/agent-management/Cargo.toml @@ -20,3 +20,4 @@ url.workspace = true dirs.workspace = true tempfile.workspace = true time.workspace = true +tracing.workspace = true diff --git a/server/packages/agent-management/src/agents.rs b/server/packages/agent-management/src/agents.rs index cf48d11..0796926 100644 --- a/server/packages/agent-management/src/agents.rs +++ b/server/packages/agent-management/src/agents.rs @@ -4,6 +4,7 @@ use std::fs; use std::io::{self, Read}; use std::path::{Path, PathBuf}; use std::process::{Command, Stdio}; +use std::time::Instant; use flate2::read::GzDecoder; use reqwest::blocking::Client; @@ -321,6 +322,14 @@ impl AgentManager { agent: AgentId, options: InstallOptions, ) -> Result { + let install_started = Instant::now(); + tracing::info!( + agent = agent.as_str(), + reinstall = options.reinstall, + native_version = ?options.version, + agent_process_version = ?options.agent_process_version, + "agent_manager.install: starting" + ); fs::create_dir_all(&self.install_dir)?; fs::create_dir_all(self.install_dir.join("agent_processes"))?; @@ -345,10 +354,20 @@ impl AgentManager { artifacts.push(artifact); } - Ok(InstallResult { + let result = InstallResult { artifacts, already_installed, - }) + }; + + tracing::info!( + agent = agent.as_str(), + already_installed = result.already_installed, + artifact_count = result.artifacts.len(), + total_ms = elapsed_ms(install_started), + "agent_manager.install: completed" + ); + + Ok(result) } pub fn is_installed(&self, agent: AgentId) -> bool { @@ -392,25 +411,41 @@ impl AgentManager { &self, agent: AgentId, ) -> Result { + let started = Instant::now(); if agent == AgentId::Mock { - return Ok(AgentProcessLaunchSpec { + let spec = AgentProcessLaunchSpec { program: self.agent_process_path(agent), args: Vec::new(), env: HashMap::new(), source: InstallSource::Builtin, version: Some("builtin".to_string()), - }); + }; + tracing::info!( + agent = agent.as_str(), + source = ?spec.source, + total_ms = elapsed_ms(started), + "agent_manager.resolve_agent_process: resolved builtin" + ); + return Ok(spec); } let launcher = self.agent_process_path(agent); if launcher.exists() { - return Ok(AgentProcessLaunchSpec { + let spec = AgentProcessLaunchSpec { program: launcher, args: Vec::new(), env: HashMap::new(), source: InstallSource::LocalPath, version: None, - }); + }; + tracing::info!( + agent = agent.as_str(), + source = ?spec.source, + program = %spec.program.display(), + total_ms = elapsed_ms(started), + "agent_manager.resolve_agent_process: resolved local launcher" + ); + return Ok(spec); } if let Some(bin) = agent.agent_process_binary_hint().and_then(find_in_path) { @@ -419,29 +454,47 @@ impl AgentManager { } else { Vec::new() }; - return Ok(AgentProcessLaunchSpec { + let spec = AgentProcessLaunchSpec { program: bin, args, env: HashMap::new(), source: InstallSource::LocalPath, version: None, - }); + }; + tracing::info!( + agent = agent.as_str(), + source = ?spec.source, + program = %spec.program.display(), + args = ?spec.args, + total_ms = elapsed_ms(started), + "agent_manager.resolve_agent_process: resolved PATH binary hint" + ); + return Ok(spec); } if agent == AgentId::Opencode { let native = self.resolve_binary(agent)?; - return Ok(AgentProcessLaunchSpec { + let spec = AgentProcessLaunchSpec { program: native, args: vec!["acp".to_string()], env: HashMap::new(), source: InstallSource::LocalPath, version: None, - }); + }; + tracing::info!( + agent = agent.as_str(), + source = ?spec.source, + program = %spec.program.display(), + args = ?spec.args, + total_ms = elapsed_ms(started), + "agent_manager.resolve_agent_process: resolved opencode native" + ); + return Ok(spec); } Err(AgentError::AgentProcessNotFound { agent, - hint: Some("run install to provision ACP agent process".to_string()), + hint: Some(format!("run step 3: `sandbox-agent install-agent {agent}`")), }) } @@ -454,11 +507,23 @@ impl AgentManager { agent: AgentId, options: &InstallOptions, ) -> Result, AgentError> { + let started = Instant::now(); if !options.reinstall && self.native_installed(agent) { + tracing::info!( + agent = agent.as_str(), + total_ms = elapsed_ms(started), + "agent_manager.install_native: already installed" + ); return Ok(None); } let path = self.binary_path(agent); + tracing::info!( + agent = agent.as_str(), + path = %path.display(), + version_override = ?options.version, + "agent_manager.install_native: installing" + ); match agent { AgentId::Claude => install_claude(&path, self.platform, options.version.as_deref())?, AgentId::Codex => install_codex(&path, self.platform, options.version.as_deref())?, @@ -474,12 +539,22 @@ impl AgentManager { } } - Ok(Some(InstalledArtifact { + let artifact = InstalledArtifact { kind: InstalledArtifactKind::NativeAgent, path, version: self.version(agent).ok().flatten(), source: InstallSource::Fallback, - })) + }; + + tracing::info!( + agent = agent.as_str(), + source = ?artifact.source, + version = ?artifact.version, + total_ms = elapsed_ms(started), + "agent_manager.install_native: completed" + ); + + Ok(Some(artifact)) } fn install_agent_process( @@ -487,8 +562,14 @@ impl AgentManager { agent: AgentId, options: &InstallOptions, ) -> Result, AgentError> { + let started = Instant::now(); if !options.reinstall { if self.agent_process_status(agent).is_some() { + tracing::info!( + agent = agent.as_str(), + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process: already installed" + ); return Ok(None); } } @@ -496,22 +577,104 @@ impl AgentManager { if agent == AgentId::Mock { let path = self.agent_process_path(agent); write_mock_agent_process_launcher(&path)?; - return Ok(Some(InstalledArtifact { + let artifact = InstalledArtifact { kind: InstalledArtifactKind::AgentProcess, path, version: Some("builtin".to_string()), source: InstallSource::Builtin, - })); + }; + tracing::info!( + agent = agent.as_str(), + source = ?artifact.source, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process: installed builtin launcher" + ); + return Ok(Some(artifact)); } if let Some(artifact) = self.install_agent_process_from_registry(agent, options)? { + tracing::info!( + agent = agent.as_str(), + source = ?artifact.source, + version = ?artifact.version, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process: installed from registry" + ); return Ok(Some(artifact)); } let artifact = self.install_agent_process_fallback(agent, options)?; + tracing::info!( + agent = agent.as_str(), + source = ?artifact.source, + version = ?artifact.version, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process: installed from fallback" + ); Ok(Some(artifact)) } + fn install_npm_agent_process_package( + &self, + agent: AgentId, + package: &str, + args: &[String], + env: &HashMap, + source: InstallSource, + version: Option, + ) -> Result { + let started = Instant::now(); + let root = self.agent_process_storage_dir(agent); + if root.exists() { + fs::remove_dir_all(&root)?; + } + fs::create_dir_all(&root)?; + + let npm_install_started = Instant::now(); + install_npm_package(&root, package, agent)?; + let npm_install_ms = elapsed_ms(npm_install_started); + + let bin_name = agent.agent_process_binary_hint().ok_or_else(|| { + AgentError::ExtractFailed(format!( + "missing executable hint for agent process package: {agent}" + )) + })?; + + let cmd_path = npm_bin_path(&root, bin_name); + if !cmd_path.exists() { + return Err(AgentError::ExtractFailed(format!( + "installed package missing executable: {}", + cmd_path.display() + ))); + } + + let launcher = self.agent_process_path(agent); + let write_started = Instant::now(); + write_exec_agent_process_launcher(&launcher, &cmd_path, args, env)?; + let write_ms = elapsed_ms(write_started); + let verify_started = Instant::now(); + verify_command(&launcher, &[])?; + let verify_ms = elapsed_ms(verify_started); + + tracing::info!( + agent = agent.as_str(), + package = %package, + cmd = %cmd_path.display(), + npm_install_ms = npm_install_ms, + write_ms = write_ms, + verify_ms = verify_ms, + total_ms = elapsed_ms(started), + "agent_manager.install_npm_agent_process_package: completed" + ); + + Ok(InstalledArtifact { + kind: InstalledArtifactKind::AgentProcess, + path: launcher, + version, + source, + }) + } + fn agent_process_status(&self, agent: AgentId) -> Option { if agent == AgentId::Mock { return Some(AgentProcessStatus { @@ -540,59 +703,111 @@ impl AgentManager { agent: AgentId, options: &InstallOptions, ) -> Result, AgentError> { + let started = Instant::now(); let Some(registry_id) = agent.agent_process_registry_id() else { return Ok(None); }; + tracing::info!( + agent = agent.as_str(), + registry_id = registry_id, + url = %self.registry_url, + "agent_manager.install_agent_process_from_registry: fetching registry" + ); + let fetch_started = Instant::now(); let registry = fetch_registry(&self.registry_url)?; + tracing::info!( + agent = agent.as_str(), + registry_id = registry_id, + fetch_ms = elapsed_ms(fetch_started), + "agent_manager.install_agent_process_from_registry: registry fetched" + ); let Some(entry) = registry.agents.into_iter().find(|a| a.id == registry_id) else { + tracing::info!( + agent = agent.as_str(), + registry_id = registry_id, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process_from_registry: missing entry" + ); return Ok(None); }; if let Some(npx) = entry.distribution.npx { let package = apply_npx_version_override(&npx.package, options.agent_process_version.as_deref()); - let launcher = self.agent_process_path(agent); - write_npx_agent_process_launcher(&launcher, &package, &npx.args, &npx.env)?; - verify_command(&launcher, &[])?; - return Ok(Some(InstalledArtifact { - kind: InstalledArtifactKind::AgentProcess, - path: launcher, - version: options - .agent_process_version - .clone() - .or(entry.version) - .or(extract_npx_version(&package)), - source: InstallSource::Registry, - })); + let version = options + .agent_process_version + .clone() + .or(entry.version) + .or(extract_npx_version(&package)); + let artifact = self.install_npm_agent_process_package( + agent, + &package, + &npx.args, + &npx.env, + InstallSource::Registry, + version, + )?; + tracing::info!( + agent = agent.as_str(), + package = %package, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process_from_registry: npm package installed" + ); + return Ok(Some(artifact)); } if let Some(binary) = entry.distribution.binary { let key = self.platform.registry_key(); if let Some(target) = binary.get(key) { let archive_url = Url::parse(&target.archive)?; + let download_started = Instant::now(); let payload = download_bytes(&archive_url)?; + let download_ms = elapsed_ms(download_started); let root = self.agent_process_storage_dir(agent); if root.exists() { fs::remove_dir_all(&root)?; } fs::create_dir_all(&root)?; + let unpack_started = Instant::now(); unpack_archive(&payload, &archive_url, &root)?; + let unpack_ms = elapsed_ms(unpack_started); let cmd_path = resolve_extracted_command(&root, &target.cmd)?; let launcher = self.agent_process_path(agent); + let write_started = Instant::now(); write_exec_agent_process_launcher(&launcher, &cmd_path, &target.args, &target.env)?; + let write_ms = elapsed_ms(write_started); + let verify_started = Instant::now(); verify_command(&launcher, &[])?; + let verify_ms = elapsed_ms(verify_started); - return Ok(Some(InstalledArtifact { + let artifact = InstalledArtifact { kind: InstalledArtifactKind::AgentProcess, path: launcher, version: options.agent_process_version.clone().or(entry.version), source: InstallSource::Registry, - })); + }; + tracing::info!( + agent = agent.as_str(), + archive_url = %archive_url, + download_ms = download_ms, + unpack_ms = unpack_ms, + write_ms = write_ms, + verify_ms = verify_ms, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process_from_registry: binary launcher installed" + ); + return Ok(Some(artifact)); } } + tracing::info!( + agent = agent.as_str(), + registry_id = registry_id, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process_from_registry: no compatible distribution" + ); Ok(None) } @@ -601,24 +816,44 @@ impl AgentManager { agent: AgentId, options: &InstallOptions, ) -> Result { - let launcher = self.agent_process_path(agent); - - match agent { + let started = Instant::now(); + let artifact = match agent { AgentId::Claude => { let package = fallback_npx_package( "@zed-industries/claude-agent-acp", options.agent_process_version.as_deref(), ); - write_npx_agent_process_launcher(&launcher, &package, &[], &HashMap::new())?; + self.install_npm_agent_process_package( + agent, + &package, + &[], + &HashMap::new(), + InstallSource::Fallback, + options + .agent_process_version + .clone() + .or(extract_npx_version(&package)), + )? } AgentId::Codex => { let package = fallback_npx_package( "@zed-industries/codex-acp", options.agent_process_version.as_deref(), ); - write_npx_agent_process_launcher(&launcher, &package, &[], &HashMap::new())?; + self.install_npm_agent_process_package( + agent, + &package, + &[], + &HashMap::new(), + InstallSource::Fallback, + options + .agent_process_version + .clone() + .or(extract_npx_version(&package)), + )? } AgentId::Opencode => { + let launcher = self.agent_process_path(agent); let native = self.resolve_binary(agent)?; write_exec_agent_process_launcher( &launcher, @@ -626,37 +861,82 @@ impl AgentManager { &["acp".to_string()], &HashMap::new(), )?; + verify_command(&launcher, &[])?; + InstalledArtifact { + kind: InstalledArtifactKind::AgentProcess, + path: launcher, + version: options.agent_process_version.clone(), + source: InstallSource::Fallback, + } } AgentId::Amp => { let package = fallback_npx_package("amp-acp", options.agent_process_version.as_deref()); - write_npx_agent_process_launcher(&launcher, &package, &[], &HashMap::new())?; + self.install_npm_agent_process_package( + agent, + &package, + &[], + &HashMap::new(), + InstallSource::Fallback, + options + .agent_process_version + .clone() + .or(extract_npx_version(&package)), + )? } AgentId::Pi => { let package = fallback_npx_package("pi-acp", options.agent_process_version.as_deref()); - write_npx_agent_process_launcher(&launcher, &package, &[], &HashMap::new())?; + self.install_npm_agent_process_package( + agent, + &package, + &[], + &HashMap::new(), + InstallSource::Fallback, + options + .agent_process_version + .clone() + .or(extract_npx_version(&package)), + )? } AgentId::Cursor => { let package = fallback_npx_package( "@blowmage/cursor-agent-acp", options.agent_process_version.as_deref(), ); - write_npx_agent_process_launcher(&launcher, &package, &[], &HashMap::new())?; + self.install_npm_agent_process_package( + agent, + &package, + &[], + &HashMap::new(), + InstallSource::Fallback, + options + .agent_process_version + .clone() + .or(extract_npx_version(&package)), + )? } AgentId::Mock => { + let launcher = self.agent_process_path(agent); write_mock_agent_process_launcher(&launcher)?; + InstalledArtifact { + kind: InstalledArtifactKind::AgentProcess, + path: launcher, + version: options.agent_process_version.clone(), + source: InstallSource::Fallback, + } } - } + }; - verify_command(&launcher, &[])?; + tracing::info!( + agent = agent.as_str(), + source = ?artifact.source, + version = ?artifact.version, + total_ms = elapsed_ms(started), + "agent_manager.install_agent_process_fallback: launcher installed" + ); - Ok(InstalledArtifact { - kind: InstalledArtifactKind::AgentProcess, - path: launcher, - version: options.agent_process_version.clone(), - source: InstallSource::Fallback, - }) + Ok(artifact) } } @@ -732,6 +1012,10 @@ pub enum AgentError { RegistryParse(String), #[error("command verification failed: {0}")] VerifyFailed(String), + #[error( + "npm is required to install {agent}. install npm, then run step 3: `sandbox-agent install-agent {agent}`" + )] + MissingNpm { agent: AgentId }, } fn fallback_npx_package(base: &str, version: Option<&str>) -> String { @@ -779,15 +1063,36 @@ fn split_package_version(package: &str) -> Option<(&str, &str)> { } } -fn write_npx_agent_process_launcher( - path: &Path, - package: &str, - args: &[String], - env: &HashMap, -) -> Result<(), AgentError> { - let mut command = vec!["npx".to_string(), "-y".to_string(), package.to_string()]; - command.extend(args.iter().cloned()); - write_launcher(path, &command, env) +fn install_npm_package(root: &Path, package: &str, agent: AgentId) -> Result<(), AgentError> { + let mut command = Command::new("npm"); + command + .arg("install") + .arg("--no-audit") + .arg("--no-fund") + .arg("--prefix") + .arg(root) + .arg(package) + .stdout(Stdio::null()) + .stderr(Stdio::null()); + + match command.status() { + Ok(status) if status.success() => Ok(()), + Ok(status) => Err(AgentError::VerifyFailed(format!( + "npm install failed for {agent} with status {status}. run step 3: `sandbox-agent install-agent {agent}`" + ))), + Err(err) if err.kind() == io::ErrorKind::NotFound => Err(AgentError::MissingNpm { agent }), + Err(err) => Err(AgentError::VerifyFailed(format!( + "failed to execute npm for {agent}: {err}" + ))), + } +} + +fn npm_bin_path(root: &Path, bin_name: &str) -> PathBuf { + let mut path = root.join("node_modules").join(".bin").join(bin_name); + if cfg!(windows) { + path.set_extension("cmd"); + } + path } fn write_exec_agent_process_launcher( @@ -998,6 +1303,15 @@ fn install_claude( platform: Platform, version: Option<&str>, ) -> Result<(), AgentError> { + let started = Instant::now(); + tracing::info!( + path = %path.display(), + platform = ?platform, + version_override = ?version, + "agent_manager.install_claude: starting" + ); + + let version_started = Instant::now(); let version = match version { Some(version) => version.to_string(), None => { @@ -1009,6 +1323,7 @@ fn install_claude( text.trim().to_string() } }; + let version_ms = elapsed_ms(version_started); let platform_segment = match platform { Platform::LinuxX64 => "linux-x64", @@ -1023,12 +1338,26 @@ fn install_claude( let url = Url::parse(&format!( "https://storage.googleapis.com/claude-code-dist-86c565f3-f756-42ad-8dfa-d59b1c096819/claude-code-releases/{version}/{platform_segment}/claude" ))?; + let download_started = Instant::now(); let bytes = download_bytes(&url)?; + let download_ms = elapsed_ms(download_started); + let write_started = Instant::now(); write_executable(path, &bytes)?; + tracing::info!( + version = %version, + url = %url, + bytes = bytes.len(), + version_ms = version_ms, + download_ms = download_ms, + write_ms = elapsed_ms(write_started), + total_ms = elapsed_ms(started), + "agent_manager.install_claude: completed" + ); Ok(()) } fn install_amp(path: &Path, platform: Platform, version: Option<&str>) -> Result<(), AgentError> { + let started = Instant::now(); let version = match version { Some(version) => version.to_string(), None => { @@ -1053,12 +1382,25 @@ fn install_amp(path: &Path, platform: Platform, version: Option<&str>) -> Result let url = Url::parse(&format!( "https://storage.googleapis.com/amp-public-assets-prod-0/cli/{version}/amp-{platform_segment}" ))?; + let download_started = Instant::now(); let bytes = download_bytes(&url)?; + let download_ms = elapsed_ms(download_started); + let write_started = Instant::now(); write_executable(path, &bytes)?; + tracing::info!( + version = %version, + url = %url, + bytes = bytes.len(), + download_ms = download_ms, + write_ms = elapsed_ms(write_started), + total_ms = elapsed_ms(started), + "agent_manager.install_amp: completed" + ); Ok(()) } fn install_codex(path: &Path, platform: Platform, version: Option<&str>) -> Result<(), AgentError> { + let started = Instant::now(); let target = match platform { Platform::LinuxX64 | Platform::LinuxX64Musl => "x86_64-unknown-linux-musl", Platform::LinuxArm64 => "aarch64-unknown-linux-musl", @@ -1077,11 +1419,15 @@ fn install_codex(path: &Path, platform: Platform, version: Option<&str>) -> Resu ))?, }; + let download_started = Instant::now(); let bytes = download_bytes(&url)?; + let download_ms = elapsed_ms(download_started); let temp_dir = tempfile::tempdir()?; + let unpack_started = Instant::now(); let cursor = io::Cursor::new(bytes); let mut archive = tar::Archive::new(GzDecoder::new(cursor)); archive.unpack(temp_dir.path())?; + let unpack_ms = elapsed_ms(unpack_started); let expected = if cfg!(windows) { format!("codex-{target}.exe") @@ -1091,7 +1437,17 @@ fn install_codex(path: &Path, platform: Platform, version: Option<&str>) -> Resu let binary = find_file_recursive(temp_dir.path(), &expected)? .ok_or_else(|| AgentError::ExtractFailed(format!("missing {expected}")))?; + let move_started = Instant::now(); move_executable(&binary, path)?; + tracing::info!( + url = %url, + target = target, + download_ms = download_ms, + unpack_ms = unpack_ms, + move_ms = elapsed_ms(move_started), + total_ms = elapsed_ms(started), + "agent_manager.install_codex: completed" + ); Ok(()) } @@ -1100,7 +1456,15 @@ fn install_opencode( platform: Platform, version: Option<&str>, ) -> Result<(), AgentError> { - match platform { + let started = Instant::now(); + tracing::info!( + path = %path.display(), + platform = ?platform, + version_override = ?version, + "agent_manager.install_opencode: starting" + ); + + let result = match platform { Platform::MacosArm64 => { let url = match version { Some(version) => Url::parse(&format!( @@ -1141,22 +1505,46 @@ fn install_opencode( ))?, }; + let download_started = Instant::now(); let bytes = download_bytes(&url)?; + let download_ms = elapsed_ms(download_started); let temp_dir = tempfile::tempdir()?; + let unpack_started = Instant::now(); let cursor = io::Cursor::new(bytes); let mut archive = tar::Archive::new(GzDecoder::new(cursor)); archive.unpack(temp_dir.path())?; + let unpack_ms = elapsed_ms(unpack_started); let binary = find_file_recursive(temp_dir.path(), "opencode") .or_else(|_| find_file_recursive(temp_dir.path(), "opencode.exe"))? .ok_or_else(|| AgentError::ExtractFailed("missing opencode".to_string()))?; + let move_started = Instant::now(); move_executable(&binary, path)?; + tracing::info!( + url = %url, + download_ms = download_ms, + unpack_ms = unpack_ms, + move_ms = elapsed_ms(move_started), + "agent_manager.install_opencode: tarball extraction complete" + ); Ok(()) } + }; + + if result.is_ok() { + tracing::info!( + total_ms = elapsed_ms(started), + "agent_manager.install_opencode: completed" + ); } + + result } fn install_zip_binary(path: &Path, url: &Url, binary_name: &str) -> Result<(), AgentError> { + let started = Instant::now(); + let download_started = Instant::now(); let bytes = download_bytes(url)?; + let download_ms = elapsed_ms(download_started); let reader = io::Cursor::new(bytes); let mut archive = zip::ZipArchive::new(reader).map_err(|err| AgentError::ExtractFailed(err.to_string()))?; @@ -1173,7 +1561,16 @@ fn install_zip_binary(path: &Path, url: &Url, binary_name: &str) -> Result<(), A let out_path = temp_dir.path().join(binary_name); let mut out_file = fs::File::create(&out_path)?; io::copy(&mut file, &mut out_file)?; + let move_started = Instant::now(); move_executable(&out_path, path)?; + tracing::info!( + url = %url, + binary_name = binary_name, + download_ms = download_ms, + move_ms = elapsed_ms(move_started), + total_ms = elapsed_ms(started), + "agent_manager.install_zip_binary: completed" + ); return Ok(()); } Err(AgentError::ExtractFailed(format!("missing {binary_name}"))) @@ -1231,6 +1628,10 @@ fn find_file_recursive(dir: &Path, filename: &str) -> Result, Ag Ok(None) } +fn elapsed_ms(start: Instant) -> u64 { + start.elapsed().as_millis() as u64 +} + fn parse_version_output(output: &std::process::Output) -> Option { let stdout = String::from_utf8_lossy(&output.stdout); let stderr = String::from_utf8_lossy(&output.stderr); @@ -1265,6 +1666,38 @@ mod tests { } } + fn write_fake_npm(path: &Path) { + write_exec( + path, + r#"#!/usr/bin/env sh +set -e +prefix="" +while [ "$#" -gt 0 ]; do + case "$1" in + install|--no-audit|--no-fund) + shift + ;; + --prefix) + prefix="$2" + shift 2 + ;; + *) + shift + ;; + esac +done +[ -n "$prefix" ] || exit 1 +mkdir -p "$prefix/node_modules/.bin" +for bin in claude-code-acp codex-acp amp-acp pi-acp cursor-agent-acp; do + echo '#!/usr/bin/env sh' > "$prefix/node_modules/.bin/$bin" + echo 'exit 0' >> "$prefix/node_modules/.bin/$bin" + chmod +x "$prefix/node_modules/.bin/$bin" +done +exit 0 +"#, + ); + } + fn env_lock() -> &'static Mutex<()> { static LOCK: OnceLock> = OnceLock::new(); LOCK.get_or_init(|| Mutex::new(())) @@ -1407,7 +1840,7 @@ mod tests { let bin_dir = temp_dir.path().join("bin"); fs::create_dir_all(&bin_dir).expect("create bin dir"); - write_exec(&bin_dir.join("npx"), "#!/usr/bin/env sh\nexit 0\n"); + write_fake_npm(&bin_dir.join("npm")); let original_path = std::env::var_os("PATH").unwrap_or_default(); let mut paths = vec![bin_dir.clone()]; @@ -1455,8 +1888,8 @@ mod tests { let launcher = fs::read_to_string(manager.agent_process_path(AgentId::Codex)).expect("launcher"); assert!( - launcher.contains("@example/codex-acp@9.9.9"), - "launcher should include overridden package version" + launcher.contains("node_modules/.bin/codex-acp"), + "launcher should invoke installed codex executable" ); } @@ -1474,7 +1907,7 @@ mod tests { let bin_dir = temp_dir.path().join("bin"); fs::create_dir_all(&bin_dir).expect("create bin dir"); - write_exec(&bin_dir.join("npx"), "#!/usr/bin/env sh\nexit 0\n"); + write_fake_npm(&bin_dir.join("npm")); let original_path = std::env::var_os("PATH").unwrap_or_default(); let mut paths = vec![bin_dir.clone()]; @@ -1496,6 +1929,39 @@ mod tests { assert_eq!(agent_process_artifact.source, InstallSource::Fallback); } + #[test] + fn install_returns_missing_npm_error_for_npm_backed_agents() { + let _env_lock = env_lock().lock().expect("env lock"); + + let temp_dir = tempfile::tempdir().expect("create tempdir"); + let mut manager = AgentManager::with_platform(temp_dir.path(), Platform::LinuxX64); + + write_exec( + &manager.binary_path(AgentId::Codex), + "#!/usr/bin/env sh\nexit 0\n", + ); + + let bin_dir = temp_dir.path().join("bin"); + fs::create_dir_all(&bin_dir).expect("create bin dir"); + + let original_path = std::env::var_os("PATH").unwrap_or_default(); + let combined_path = std::env::join_paths([bin_dir]).expect("join PATH"); + let _path_guard = EnvVarGuard::set("PATH", &combined_path); + + manager.registry_url = serve_registry_once(serde_json::json!({ "agents": [] })); + + let error = manager + .install(AgentId::Codex, InstallOptions::default()) + .expect_err("install should fail without npm"); + + match error { + AgentError::MissingNpm { agent } => assert_eq!(agent, AgentId::Codex), + other => panic!("expected MissingNpm, got {other:?}"), + } + + drop(original_path); + } + #[test] fn reinstall_mock_returns_agent_process_artifact() { let temp_dir = tempfile::tempdir().expect("create tempdir"); @@ -1522,7 +1988,7 @@ mod tests { } #[test] - fn install_pi_skips_native_and_writes_fallback_npx_launcher() { + fn install_pi_skips_native_and_installs_fallback_npm_launcher() { let _env_lock = env_lock().lock().expect("env lock"); let temp_dir = tempfile::tempdir().expect("create tempdir"); @@ -1530,7 +1996,7 @@ mod tests { let bin_dir = temp_dir.path().join("bin"); fs::create_dir_all(&bin_dir).expect("create bin dir"); - write_exec(&bin_dir.join("npx"), "#!/usr/bin/env sh\nexit 0\n"); + write_fake_npm(&bin_dir.join("npm")); let original_path = std::env::var_os("PATH").unwrap_or_default(); let mut paths = vec![bin_dir.clone()]; @@ -1564,8 +2030,8 @@ mod tests { let launcher = fs::read_to_string(manager.agent_process_path(AgentId::Pi)).expect("read pi launcher"); assert!( - launcher.contains("pi-acp"), - "pi launcher should reference pi-acp package" + launcher.contains("node_modules/.bin/pi-acp"), + "pi launcher should use installed pi executable" ); // resolve_agent_process should now find it. @@ -1590,7 +2056,7 @@ mod tests { } #[test] - fn install_cursor_skips_native_and_writes_fallback_npx_launcher() { + fn install_cursor_skips_native_and_installs_fallback_npm_launcher() { let _env_lock = env_lock().lock().expect("env lock"); let temp_dir = tempfile::tempdir().expect("create tempdir"); @@ -1598,7 +2064,7 @@ mod tests { let bin_dir = temp_dir.path().join("bin"); fs::create_dir_all(&bin_dir).expect("create bin dir"); - write_exec(&bin_dir.join("npx"), "#!/usr/bin/env sh\nexit 0\n"); + write_fake_npm(&bin_dir.join("npm")); let original_path = std::env::var_os("PATH").unwrap_or_default(); let mut paths = vec![bin_dir.clone()]; @@ -1630,8 +2096,8 @@ mod tests { let launcher = fs::read_to_string(manager.agent_process_path(AgentId::Cursor)) .expect("read cursor launcher"); assert!( - launcher.contains("@blowmage/cursor-agent-acp"), - "cursor launcher should reference @blowmage/cursor-agent-acp package" + launcher.contains("node_modules/.bin/cursor-agent-acp"), + "cursor launcher should use installed cursor executable" ); let spec = manager diff --git a/server/packages/sandbox-agent/src/acp_proxy_runtime.rs b/server/packages/sandbox-agent/src/acp_proxy_runtime.rs index 9e1e13c..47bc2b0 100644 --- a/server/packages/sandbox-agent/src/acp_proxy_runtime.rs +++ b/server/packages/sandbox-agent/src/acp_proxy_runtime.rs @@ -165,7 +165,7 @@ impl AcpProxyRuntime { error = %err, "acp_proxy: POST → error" ); - Err(map_adapter_error(err)) + Err(map_adapter_error(err, Some(instance.agent))) } } } @@ -277,27 +277,28 @@ impl AcpProxyRuntime { server_id: &str, agent: AgentId, ) -> Result, SandboxError> { - let start = std::time::Instant::now(); + let total_started = std::time::Instant::now(); tracing::info!( server_id = server_id, agent = agent.as_str(), "create_instance: starting" ); + let install_started = std::time::Instant::now(); self.ensure_installed(agent).await?; - let install_elapsed = start.elapsed(); tracing::info!( server_id = server_id, agent = agent.as_str(), - install_ms = install_elapsed.as_millis() as u64, + install_ms = install_started.elapsed().as_millis() as u64, "create_instance: agent installed/verified" ); + let resolve_started = std::time::Instant::now(); let manager = self.inner.agent_manager.clone(); let launch = tokio::task::spawn_blocking(move || manager.resolve_agent_process(agent)) .await .map_err(|err| SandboxError::StreamError { - message: format!("failed to resolve ACP agent process launch spec: {err}"), + message: format!("failed to resolve agent process launch spec: {err}"), })? .map_err(|err| SandboxError::StreamError { message: err.to_string(), @@ -308,10 +309,11 @@ impl AcpProxyRuntime { agent = agent.as_str(), program = ?launch.program, args = ?launch.args, - resolve_ms = start.elapsed().as_millis() as u64, + resolve_ms = resolve_started.elapsed().as_millis() as u64, "create_instance: launch spec resolved, spawning" ); + let spawn_started = std::time::Instant::now(); let runtime = AdapterRuntime::start( LaunchSpec { program: launch.program, @@ -321,12 +323,13 @@ impl AcpProxyRuntime { self.inner.request_timeout, ) .await - .map_err(map_adapter_error)?; + .map_err(|err| map_adapter_error(err, Some(agent)))?; - let total_ms = start.elapsed().as_millis() as u64; + let total_ms = total_started.elapsed().as_millis() as u64; tracing::info!( server_id = server_id, agent = agent.as_str(), + spawn_ms = spawn_started.elapsed().as_millis() as u64, total_ms = total_ms, "create_instance: ready" ); @@ -340,16 +343,27 @@ impl AcpProxyRuntime { } async fn ensure_installed(&self, agent: AgentId) -> Result<(), SandboxError> { + let started = std::time::Instant::now(); if self.inner.require_preinstall { if !self.is_ready(agent).await { return Err(SandboxError::AgentNotInstalled { agent: agent.as_str().to_string(), }); } + tracing::info!( + agent = agent.as_str(), + total_ms = started.elapsed().as_millis() as u64, + "ensure_installed: preinstall requirement satisfied" + ); return Ok(()); } if self.is_ready(agent).await { + tracing::info!( + agent = agent.as_str(), + total_ms = started.elapsed().as_millis() as u64, + "ensure_installed: already ready" + ); return Ok(()); } @@ -363,9 +377,19 @@ impl AcpProxyRuntime { let _guard = lock.lock().await; if self.is_ready(agent).await { + tracing::info!( + agent = agent.as_str(), + total_ms = started.elapsed().as_millis() as u64, + "ensure_installed: became ready while waiting for lock" + ); return Ok(()); } + tracing::info!( + agent = agent.as_str(), + "ensure_installed: installing missing artifacts" + ); + let install_started = std::time::Instant::now(); let manager = self.inner.agent_manager.clone(); tokio::task::spawn_blocking(move || manager.install(agent, InstallOptions::default())) .await @@ -378,6 +402,12 @@ impl AcpProxyRuntime { stderr: Some(err.to_string()), })?; + tracing::info!( + agent = agent.as_str(), + install_ms = install_started.elapsed().as_millis() as u64, + total_ms = started.elapsed().as_millis() as u64, + "ensure_installed: install complete" + ); Ok(()) } @@ -432,7 +462,7 @@ impl AcpDispatch for AcpProxyRuntime { } } -fn map_adapter_error(err: AdapterError) -> SandboxError { +fn map_adapter_error(err: AdapterError, agent: Option) -> SandboxError { match err { AdapterError::InvalidEnvelope => SandboxError::InvalidRequest { message: "request body must be a JSON-RPC object".to_string(), @@ -446,6 +476,29 @@ fn map_adapter_error(err: AdapterError) -> SandboxError { AdapterError::Write(error) => SandboxError::StreamError { message: format!("failed writing to agent stdin: {error}"), }, + AdapterError::Exited { exit_code, stderr } => { + if let Some(agent) = agent { + SandboxError::AgentProcessExited { + agent: agent.as_str().to_string(), + exit_code, + stderr, + } + } else { + SandboxError::StreamError { + message: if let Some(stderr) = stderr { + format!( + "agent process exited before responding (exit_code: {:?}, stderr: {})", + exit_code, stderr + ) + } else { + format!( + "agent process exited before responding (exit_code: {:?})", + exit_code + ) + }, + } + } + } AdapterError::Spawn(error) => SandboxError::StreamError { message: format!("failed to start agent process: {error}"), },