From 1eb28e0aab065f6a81c7a0951ac7ee3a69d35ef0 Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Tue, 28 Jul 2026 15:21:54 -0400 Subject: [PATCH 1/9] fix(desktop): raise the install ceiling to 15 minutes and keep its output MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A hard 300s wall killed installs that were working, just slowly: the Goose step downloads a ~79MB release asset and Windows Defender scans every file npm extracts, which routinely pushes a healthy install past five minutes (#2401). The ceiling is now 900s, and it stays a pure wall-clock ceiling — nothing observable distinguishes a hung installer from one silently transferring a large artifact, so silence alone never kills an install. A ceiling kill used to return empty stdout and a bare timeout string, discarding the one piece of evidence that says where the install stalled. Output now drains into a bounded head/tail sink shared with the reader rather than a String the reader returns, so the partial capture is readable at the ceiling and an installer printing megabytes costs a fixed amount of memory. The install shell is a session leader, so signalling only its PID left descendants alive holding the output pipes — the drain joins could then block past the ceiling, holding the concurrency guard that rejects the user's next install attempt. The ceiling now terminates the whole process group through the same SIGTERM/grace/SIGKILL path used for managed agent runtimes, and waits a bounded grace for the drains instead of joining unconditionally. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../commands/agent_discovery/install_exec.rs | 528 +++++++++++++++--- desktop/src-tauri/src/managed_agents/types.rs | 3 +- desktop/src/shared/lib/configNudge.ts | 2 +- 3 files changed, 444 insertions(+), 89 deletions(-) diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs index 63163ceadc..2c93b482d6 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs @@ -5,13 +5,39 @@ //! `install_powershell_command`, `build_install_command`); this module owns //! only what happens once a `Command` exists. +use std::collections::VecDeque; use std::io::Read; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; use crate::managed_agents::InstallStepResult; /// Maximum number of attempts for a transient-looking install command. const INSTALL_MAX_ATTEMPTS: u32 = 3; +/// Absolute wall-clock ceiling for a single install command. +/// +/// This is a ceiling, not an inactivity timeout: nothing observable +/// distinguishes a hung installer from one silently transferring a large +/// artifact (the Goose step downloads a ~79MB release asset with no progress +/// output, and npm at its default log level prints only at the end), so silence +/// alone never kills an install. The previous 300s wall killed +/// slow-but-working installs — Windows Defender scanning every file npm +/// extracts pushes past it routinely (#2401). +/// +/// The cost of a larger ceiling: skipping onboarding does not cancel a running +/// install and a per-runtime guard rejects a second one, so this is also the +/// longest a user who skipped a genuinely *hung* install waits before Install +/// works again in Settings. User-facing cancellation is the product-level fix. +const INSTALL_TIMEOUT: Duration = Duration::from_secs(900); + +/// How long the ceiling waits for the output drains to finish after killing the +/// install's process group. The kill closes the pipe write ends, so the drains +/// normally end within microseconds; this bound only covers a descendant that +/// escaped the group and still holds one open. Such a process must not hold the +/// install — and the concurrency guard behind it — open past the ceiling. +const DRAIN_GRACE: Duration = Duration::from_secs(2); + /// Run an install command, retrying transient failures with backoff. /// /// Runtime installs pull artifacts over the network — Goose's `curl … | bash` @@ -108,7 +134,7 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { } }; - let mut child = match cmd + let child = match cmd .stdin(std::process::Stdio::null()) .stdout(std::process::Stdio::piped()) .stderr(std::process::Stdio::piped()) @@ -128,23 +154,48 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { } }; - // Drain stdout/stderr on background threads to prevent pipe buffer deadlock. + await_install_child(step, command, child, INSTALL_TIMEOUT) +} + +/// Drain a spawned install child's output into bounded buffers and wait for it +/// to exit, killing it at `timeout`. +/// +/// Split from the spawn so the timing-sensitive half is testable without a real +/// login shell: shell startup alone can outlast a short test ceiling on a +/// loaded machine. Production always passes [`INSTALL_TIMEOUT`]. +fn await_install_child( + step: &str, + command: &str, + mut child: std::process::Child, + timeout: Duration, +) -> InstallStepResult { + // Drain stdout/stderr on background threads to prevent pipe buffer + // deadlock. Each drain feeds a bounded sink the main thread can read at any + // time, so a timeout can still surface whatever the install printed before + // it stalled. + let stdout_sink = BoundedOutput::shared(); + let stderr_sink = BoundedOutput::shared(); let stdout_pipe = child.stdout.take(); let stderr_pipe = child.stderr.take(); + let (drained_tx, drained_rx) = std::sync::mpsc::channel(); - let stdout_thread = std::thread::spawn(move || { - let mut buf = String::new(); - if let Some(mut pipe) = stdout_pipe { - let _ = pipe.read_to_string(&mut buf); + let stdout_thread = std::thread::spawn({ + let (sink, done) = (Arc::clone(&stdout_sink), drained_tx.clone()); + move || { + if let Some(pipe) = stdout_pipe { + drain_into(pipe, &sink); + } + let _ = done.send(()); } - buf }); - let stderr_thread = std::thread::spawn(move || { - let mut buf = String::new(); - if let Some(mut pipe) = stderr_pipe { - let _ = pipe.read_to_string(&mut buf); + let stderr_thread = std::thread::spawn({ + let (sink, done) = (Arc::clone(&stderr_sink), drained_tx); + move || { + if let Some(pipe) = stderr_pipe { + drain_into(pipe, &sink); + } + let _ = done.send(()); } - buf }); // Save the PID before moving `child` into the wait thread so we can @@ -157,47 +208,42 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { let _ = tx.send(status); }); - // 5-minute timeout for install commands. - let deadline = std::time::Instant::now() + std::time::Duration::from_secs(300); + let deadline = Instant::now() + timeout; loop { - let remaining = deadline.saturating_duration_since(std::time::Instant::now()); + let remaining = deadline.saturating_duration_since(Instant::now()); if remaining.is_zero() { - // Timeout: kill the child process via its PID, then join all - // threads so nothing leaks. - #[cfg(unix)] - unsafe { - libc::kill(child_pid as i32, libc::SIGTERM); - } - #[cfg(windows)] - { - let _ = crate::managed_agents::taskkill_tree(child_pid); - } + // Ceiling reached: kill the install's whole process group — the + // install shell is a session leader (`setsid` in its `pre_exec`), so + // signalling only the leader would leave descendants running and + // holding the output pipes open. + let _ = crate::managed_agents::terminate_process(child_pid); drop(rx); let _ = wait_thread.join(); - let _ = stdout_thread.join(); - let _ = stderr_thread.join(); - return InstallStepResult { - step: step.to_string(), - command: command.to_string(), - success: false, - stdout: String::new(), - stderr: "install command timed out after 5 minutes".to_string(), - exit_code: None, - hint: None, - }; + // The kill closes the pipes, so the drains normally end at once. + // Any that don't are left detached rather than holding the install + // (and the concurrency guard behind it) open past the ceiling — + // their sinks are read under the lock either way. + await_drains(&drained_rx, DRAIN_GRACE); + return failed_with_capture( + step, + command, + timeout_message(timeout), + &stdout_sink, + &stderr_sink, + ); } - match rx.recv_timeout(std::time::Duration::from_millis(200).min(remaining)) { + match rx.recv_timeout(Duration::from_millis(200).min(remaining)) { Ok(Ok(status)) => { let _ = wait_thread.join(); - let stdout = stdout_thread.join().unwrap_or_default(); - let stderr_raw = stderr_thread.join().unwrap_or_default(); + let _ = stdout_thread.join(); + let _ = stderr_thread.join(); return InstallStepResult { step: step.to_string(), command: command.to_string(), success: status.success(), - stdout: truncate_output(stdout), - stderr: truncate_output(stderr_raw), + stdout: render_sink(&stdout_sink), + stderr: render_sink(&stderr_sink), exit_code: status.code(), hint: None, }; @@ -206,15 +252,13 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { let _ = wait_thread.join(); let _ = stdout_thread.join(); let _ = stderr_thread.join(); - return InstallStepResult { - step: step.to_string(), - command: command.to_string(), - success: false, - stdout: String::new(), - stderr: format!("failed to check process status: {e}"), - exit_code: None, - hint: None, - }; + return failed_with_capture( + step, + command, + format!("failed to check process status: {e}"), + &stdout_sink, + &stderr_sink, + ); } Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { // Still running; loop and check deadline again. @@ -225,45 +269,182 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { let _ = wait_thread.join(); let _ = stdout_thread.join(); let _ = stderr_thread.join(); - return InstallStepResult { - step: step.to_string(), - command: command.to_string(), - success: false, - stdout: String::new(), - stderr: "internal error: wait thread disconnected".to_string(), - exit_code: None, - hint: None, - }; + return failed_with_capture( + step, + command, + "internal error: wait thread disconnected".to_string(), + &stdout_sink, + &stderr_sink, + ); } } } } -/// Cap output to head + tail to avoid flooding the UI with large error dumps, -/// while preserving the most useful parts of the output. -fn truncate_output(s: String) -> String { +/// Bounded capture of one output stream: the first [`BoundedOutput::HEAD`] +/// bytes, the last [`BoundedOutput::TAIL`] bytes, and the total byte count. +/// +/// Two properties matter. Output of any size costs a fixed amount of memory — +/// an installer that prints megabytes cannot grow the process. And because the +/// sink is *shared* with the draining reader instead of being returned by it, +/// whatever arrived before a stall is readable at the ceiling, which is exactly +/// when the output is most needed. +struct BoundedOutput { + head: Vec, + tail: VecDeque, + total: usize, +} + +type SharedOutput = Arc>; + +impl BoundedOutput { + /// The head keeps the command's opening context; the tail keeps the error + /// that usually trails. Everything between them is replaced by a marker + /// naming the omitted byte count. const HEAD: usize = 512; const TAIL: usize = 1024; - const LIMIT: usize = HEAD + TAIL; - if s.len() <= LIMIT { - return s; + + fn shared() -> SharedOutput { + Arc::new(Mutex::new(Self { + head: Vec::new(), + tail: VecDeque::new(), + total: 0, + })) + } + + /// Absorb one read. Chunk boundaries are irrelevant to the result: the head + /// fills first, the remainder rolls through the tail window. + fn push(&mut self, chunk: &[u8]) { + self.total += chunk.len(); + let head_room = Self::HEAD.saturating_sub(self.head.len()).min(chunk.len()); + let (head_part, tail_part) = chunk.split_at(head_room); + self.head.extend_from_slice(head_part); + self.tail.extend(tail_part); + while self.tail.len() > Self::TAIL { + self.tail.pop_front(); + } + } + + fn render(&self) -> String { + let tail: Vec = self.tail.iter().copied().collect(); + if self.total <= Self::HEAD + Self::TAIL { + // Nothing was dropped, so head followed by tail is the whole stream. + let mut whole = self.head.clone(); + whole.extend_from_slice(&tail); + return decode(&whole); + } + // Both ends are cut at arbitrary byte offsets, so trim any partial + // character rather than emitting replacement chars. The marker counts + // every dropped byte, including those trims. + let head = utf8_prefix(&self.head); + let tail = utf8_suffix(&tail); + let omitted = self.total - head.len() - tail.len(); + format!( + "{}\n... ({omitted} bytes omitted) ...\n{}", + decode(head), + decode(tail) + ) } - let head_end = floor_char_boundary(&s, HEAD); - let tail_start = floor_char_boundary(&s, s.len().saturating_sub(TAIL)); - let omitted = tail_start - head_end; - format!( - "{}\n... ({omitted} bytes omitted) ...\n{}", - &s[..head_end], - &s[tail_start..] - ) } -fn floor_char_boundary(s: &str, mut index: usize) -> usize { - index = index.min(s.len()); - while index > 0 && !s.is_char_boundary(index) { - index -= 1; +/// Read `pipe` to EOF, feeding fixed-size chunks into `sink`. Read errors end +/// the drain — a broken pipe means the child is gone and there is nothing left +/// to capture. +fn drain_into(mut pipe: impl Read, sink: &SharedOutput) { + let mut chunk = [0u8; 8192]; + loop { + match pipe.read(&mut chunk) { + Ok(0) => return, + Ok(n) => { + if let Ok(mut sink) = sink.lock() { + sink.push(&chunk[..n]); + } + } + Err(e) if e.kind() == std::io::ErrorKind::Interrupted => continue, + Err(_) => return, + } } - index +} + +/// Render a sink even if its drain thread panicked mid-write — a poisoned lock +/// must not cost the diagnostics. +fn render_sink(sink: &SharedOutput) -> String { + sink.lock().unwrap_or_else(|p| p.into_inner()).render() +} + +/// Wait up to `grace` in total for both drains to signal completion. Returns +/// early on timeout, leaving any straggler detached. +fn await_drains(done: &std::sync::mpsc::Receiver<()>, grace: Duration) { + let deadline = Instant::now() + grace; + for _ in 0..2 { + let remaining = deadline.saturating_duration_since(Instant::now()); + if done.recv_timeout(remaining).is_err() { + return; + } + } +} + +/// A failure carrying whatever the drains captured, with `reason` leading +/// stderr so the surfaced message names the failure before the install's own +/// output. +fn failed_with_capture( + step: &str, + command: &str, + reason: String, + stdout: &SharedOutput, + stderr: &SharedOutput, +) -> InstallStepResult { + let captured = render_sink(stderr); + InstallStepResult { + step: step.to_string(), + command: command.to_string(), + success: false, + stdout: render_sink(stdout), + stderr: if captured.is_empty() { + reason + } else { + format!("{reason}\n{captured}") + }, + exit_code: None, + hint: None, + } +} + +/// Name the limit that fired and its value, so a ceiling kill is +/// distinguishable from the installer's own failure. +fn timeout_message(timeout: Duration) -> String { + let secs = timeout.as_secs(); + let limit = if secs >= 60 { + format!("{}-minute", secs / 60) + } else { + format!("{secs}-second") + }; + format!("install command exceeded the {limit} ceiling and was terminated") +} + +fn decode(bytes: &[u8]) -> String { + String::from_utf8_lossy(bytes).into_owned() +} + +/// Drop a trailing partial UTF-8 sequence, keeping mid-stream invalid bytes for +/// the lossy decode to mark. +fn utf8_prefix(bytes: &[u8]) -> &[u8] { + match std::str::from_utf8(bytes) { + Ok(_) => bytes, + Err(e) if e.error_len().is_none() => &bytes[..e.valid_up_to()], + Err(_) => bytes, + } +} + +/// Drop leading UTF-8 continuation bytes — at most three can precede a +/// character start. +fn utf8_suffix(bytes: &[u8]) -> &[u8] { + let start = bytes + .iter() + .take(3) + .take_while(|b| *b & 0b1100_0000 == 0b1000_0000) + .count(); + &bytes[start..] } #[cfg(test)] @@ -410,21 +591,30 @@ mod tests { assert_eq!(cmd.get_current_dir(), Some(expected.as_path())); } - // ── output truncation ───────────────────────────────────────────────────── + // ── output capture ──────────────────────────────────────────────────────── + + /// Feed `chunks` through a sink in order and render it. + fn capture(chunks: &[&[u8]]) -> String { + let sink = BoundedOutput::shared(); + for chunk in chunks { + sink.lock().unwrap().push(chunk); + } + render_sink(&sink) + } /// Output within the cap is passed through byte-for-byte — no marker, no loss. #[test] - fn test_truncate_output_leaves_short_output_untouched() { + fn test_capture_leaves_short_output_untouched() { let short = "a".repeat(1536); - assert_eq!(truncate_output(short.clone()), short); + assert_eq!(capture(&[short.as_bytes()]), short); } /// Over the cap, both ends survive and the middle is replaced by a marker /// naming the omitted byte count — the head keeps the command's opening /// context and the tail keeps the error that usually trails. #[test] - fn test_truncate_output_keeps_head_and_tail_with_marker() { + fn test_capture_over_cap_keeps_head_and_tail_with_marker() { let input = format!( "{}{}{}", "H".repeat(512), @@ -432,7 +622,7 @@ mod tests { "T".repeat(1024) ); - let out = truncate_output(input); + let out = capture(&[input.as_bytes()]); assert!(out.starts_with(&"H".repeat(512))); assert!(out.ends_with(&"T".repeat(1024))); @@ -442,16 +632,180 @@ mod tests { ); } - /// Truncation must not split a multi-byte character. Cutting mid-codepoint - /// would panic on the slice; the boundary floor prevents it. + /// The rendered result depends only on the byte stream, not on how the + /// reads happened to split it — a real drain sees arbitrary chunk sizes. + #[test] + fn test_capture_is_independent_of_chunk_boundaries() { + let input = "x".repeat(9000); + let one_shot = capture(&[input.as_bytes()]); + + let chunked: Vec<&[u8]> = input.as_bytes().chunks(7).collect(); + + assert_eq!(capture(&chunked), one_shot); + } + + /// Truncation must not split a multi-byte character. Both cut points land + /// mid-codepoint here; the partial bytes are dropped rather than decoded + /// into replacement chars. #[test] - fn test_truncate_output_does_not_split_multibyte_characters() { + fn test_capture_does_not_split_multibyte_characters() { // "é" is 2 bytes, so every candidate cut index lands mid-character. let input = "é".repeat(4000); - let out = truncate_output(input); + let out = capture(&[input.as_bytes()]); assert!(out.contains("bytes omitted"), "input must exceed the cap"); assert!(!out.contains('\u{fffd}'), "no replacement chars: {out}"); } + + /// Memory stays flat regardless of how much the installer prints: the + /// rendered result of a 4MiB stream is no larger than that of a 6KiB one. + #[test] + fn test_capture_of_huge_output_stays_bounded() { + let chunk = vec![b'z'; 8192]; + let sink = BoundedOutput::shared(); + for _ in 0..512 { + sink.lock().unwrap().push(&chunk); + } + + let out = render_sink(&sink); + + assert!( + out.len() < 2048, + "4MiB of output must render bounded, got {} bytes", + out.len() + ); + assert!(out.contains("bytes omitted")); + } + + // ── install ceiling ─────────────────────────────────────────────────────── + + /// The ceiling is Will's ruling: 15 minutes, and the error names the limit + /// that fired so a ceiling kill is not mistaken for the installer's own + /// failure. + #[test] + fn test_ceiling_is_fifteen_minutes_and_error_names_it() { + assert_eq!(INSTALL_TIMEOUT, Duration::from_secs(900)); + assert!( + timeout_message(INSTALL_TIMEOUT).contains("15-minute"), + "got: {}", + timeout_message(INSTALL_TIMEOUT) + ); + } + + /// Spawn `script` under `sh` as a process-group leader with piped output — + /// the same shape [`run_install_command`] hands to + /// [`await_install_child`], minus the login shell whose own startup can + /// outlast a short test ceiling. + #[cfg(unix)] + fn spawn_group_leader(script: &str) -> std::process::Child { + use std::os::unix::process::CommandExt; + + let mut cmd = std::process::Command::new("/bin/sh"); + cmd.arg("-c").arg(script); + unsafe { + cmd.pre_exec(|| { + libc::setsid(); + Ok(()) + }); + } + cmd.stdin(std::process::Stdio::null()) + .stdout(std::process::Stdio::piped()) + .stderr(std::process::Stdio::piped()) + .spawn() + .expect("sh must spawn") + } + + /// A command killed by the ceiling must surface what it printed before + /// stalling — that partial output is the only evidence of where the install + /// got stuck — and must stay unretryable, since re-running a hang just + /// costs the user another ceiling. + #[cfg(unix)] + #[test] + fn test_ceiling_returns_captured_output_and_stays_unretryable() { + let child = spawn_group_leader("echo out-before-hang; echo err-before-hang >&2; sleep 60"); + + let started = Instant::now(); + let result = await_install_child("cli", "install", child, Duration::from_secs(5)); + + assert!(!result.success); + assert_eq!(result.exit_code, None, "a killed command has no exit code"); + assert!( + !install_failure_is_retryable(&result), + "a ceiling kill must not be retried" + ); + assert!( + result.stdout.contains("out-before-hang"), + "stdout captured before the stall must survive, got: {:?}", + result.stdout + ); + assert!( + result.stderr.contains("5-second ceiling"), + "stderr must name the ceiling that actually fired, got: {:?}", + result.stderr + ); + assert!( + result.stderr.contains("err-before-hang"), + "stderr captured before the stall must survive, got: {:?}", + result.stderr + ); + assert!( + started.elapsed() < Duration::from_secs(30), + "the ceiling must not wait on the hung command's own exit" + ); + } + + /// A failure whose stream captured nothing surfaces the reason alone — no + /// dangling separator from an empty capture. + #[test] + fn test_failure_with_no_captured_output_reports_only_the_reason() { + let result = failed_with_capture( + "cli", + "curl … | bash", + "boom".to_string(), + &BoundedOutput::shared(), + &BoundedOutput::shared(), + ); + + assert_eq!(result.stdout, ""); + assert_eq!(result.stderr, "boom"); + } + + /// The install shell is a process-group leader, and its descendants inherit + /// the output pipes. Killing only the leader leaves them running and the + /// drains blocked on a pipe nobody will close, so the ceiling kills the + /// whole group. + #[cfg(unix)] + #[test] + fn test_ceiling_kills_descendants_holding_the_output_pipe() { + let dir = tempfile::tempdir().expect("tempdir"); + let pidfile = dir.path().join("descendant.pid"); + let child = spawn_group_leader(&format!( + "sh -c 'echo $$ > {pid}; sleep 60' & echo leader-up; sleep 60", + pid = pidfile.display() + )); + + let started = Instant::now(); + let result = await_install_child("cli", "install", child, Duration::from_secs(5)); + + assert!(!result.success); + assert!( + started.elapsed() < Duration::from_secs(30), + "the drains must not block on a descendant's inherited pipe" + ); + + let pid: u32 = std::fs::read_to_string(&pidfile) + .expect("the descendant must have recorded its pid") + .trim() + .parse() + .expect("pid must parse"); + // Signal delivery is asynchronous; allow the group a moment to die. + for _ in 0..30 { + if !crate::managed_agents::process_is_running(pid) { + return; + } + std::thread::sleep(Duration::from_millis(100)); + } + panic!("descendant {pid} survived the ceiling kill — the group was not signalled"); + } } diff --git a/desktop/src-tauri/src/managed_agents/types.rs b/desktop/src-tauri/src/managed_agents/types.rs index 3d8e0ed02b..7528d4f384 100644 --- a/desktop/src-tauri/src/managed_agents/types.rs +++ b/desktop/src-tauri/src/managed_agents/types.rs @@ -587,7 +587,8 @@ pub struct ManagedAgentLogResponse { pub enum AcpAvailabilityStatus { Available, AdapterMissing, - /// Adapter binary is present but is from the deprecated package (< 1.0). Reinstall required. + /// Adapter binary is present but unsupported — either the deprecated + /// package or a version below the supported floor. Reinstall required. AdapterOutdated, CliMissing, NotInstalled, diff --git a/desktop/src/shared/lib/configNudge.ts b/desktop/src/shared/lib/configNudge.ts index 82ed8f306a..86c0e16c13 100644 --- a/desktop/src/shared/lib/configNudge.ts +++ b/desktop/src/shared/lib/configNudge.ts @@ -32,7 +32,7 @@ export type ConfigNudgeRequirement = * Determines which message and CTA the nudge card shows: * - "available" → tooling installed, needs login * - "adapter_missing" → CLI installed but ACP adapter missing - * - "adapter_outdated" → ACP adapter present but from deprecated package; reinstall required + * - "adapter_outdated" → ACP adapter present but unsupported/outdated; reinstall required * - "cli_missing" → ACP adapter installed but CLI missing * - "not_installed" → neither adapter nor CLI found */ From ee80856af31a0fb84070452ebd4bb92f10f10ab4 Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Tue, 28 Jul 2026 16:57:47 -0400 Subject: [PATCH 2/9] feat(desktop): write install logs and show live install output MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A failing install surfaced only its last step's stdout/stderr, truncated to 1.5KB for a toast. Everything before it — earlier retries of the same step, the prerequisite step that actually broke, the managed-Node bootstrap — was discarded, so the user got a symptom with no history behind it. The install now writes a log file: one self-contained record per attempt of per step, appended under 0o600, and the failure message ends with `Full log: `. Each record is bounded independently at 128KiB of head and tail per stream, so an early attempt that printed megabytes cannot push out the later record that explains the failure, and the run's total is bounded by steps x attempts. A record cut at the cap says so inline, so the file never implies completeness it lacks. Both bounds hang off one drain seam: each stream's drain feeds a capture holding two views of the same bytes, the UI's 512/1024 and the log's 128KiB/128KiB. Install output can echo a registry token from the environment it ran in and the file is written unattended, so records are redacted and the owner-only mode is set by the create rather than a later chmod. A runtime id that cannot be a filename yields no log rather than a sanitized one, which could collide with another runtime's. The same seam feeds the live output line the install cards now show. A 15-minute ceiling with nothing but a spinner behind it is indistinguishable from a hang; the newest line the installer printed makes the wait observable. Lines are throttled to four events a second and tagged with their attempt, so a line emitted just before a retry starts cannot sit under the spinner describing work that has already been superseded. The ceiling's own kill now escalates on the group's liveness rather than the leader's: a descendant that ignores SIGTERM outlives the install shell, and escalation keyed to the leader would leave it running with the output pipes open. Reaping the killed child and finishing the drains share one bounded grace, since a termination that failed outright must not extend the ceiling that fired or the per-runtime guard behind it. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../src-tauri/src/commands/agent_discovery.rs | 78 +-- .../agent_discovery/install_capture.rs | 249 ++++++++ .../agent_discovery/install_capture_tests.rs | 269 +++++++++ .../commands/agent_discovery/install_exec.rs | 558 +++++++++--------- .../agent_discovery/install_report.rs | 186 ++++++ .../agent_discovery/install_report_tests.rs | 255 ++++++++ .../post_install_verification.rs | 10 +- .../src-tauri/src/managed_agents/backend.rs | 2 +- .../src-tauri/src/managed_agents/storage.rs | 50 ++ .../src/managed_agents/storage_tests.rs | 97 +++ desktop/src-tauri/src/managed_agents/types.rs | 4 + .../agents/lib/useInstallOutputLine.test.mjs | 58 ++ .../agents/lib/useInstallOutputLine.ts | 87 +++ .../src/features/onboarding/ui/SetupStep.tsx | 17 +- .../settings/ui/HarnessCatalogDialog.tsx | 14 +- .../src/features/settings/ui/HarnessRow.tsx | 13 +- desktop/src/shared/api/tauri.ts | 3 + desktop/src/shared/api/types.ts | 7 + desktop/src/shared/lib/installError.test.mjs | 213 ++++--- desktop/src/shared/lib/installError.ts | 18 +- desktop/src/testing/e2eBridge.ts | 1 + desktop/tests/helpers/bridge.ts | 42 +- 22 files changed, 1810 insertions(+), 421 deletions(-) create mode 100644 desktop/src-tauri/src/commands/agent_discovery/install_capture.rs create mode 100644 desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs create mode 100644 desktop/src-tauri/src/commands/agent_discovery/install_report.rs create mode 100644 desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs create mode 100644 desktop/src/features/agents/lib/useInstallOutputLine.test.mjs create mode 100644 desktop/src/features/agents/lib/useInstallOutputLine.ts diff --git a/desktop/src-tauri/src/commands/agent_discovery.rs b/desktop/src-tauri/src/commands/agent_discovery.rs index d6429e0454..90bc79596c 100644 --- a/desktop/src-tauri/src/commands/agent_discovery.rs +++ b/desktop/src-tauri/src/commands/agent_discovery.rs @@ -4,8 +4,8 @@ use crate::{ app_state::AppState, managed_agents::{ command_availability, is_npm_global_install, AcpRuntimeCatalogEntry, - DiscoverManagedAgentPrereqsRequest, InstallRuntimeResult, ManagedAgentPrereqsInfo, - RelayAgentInfo, DEFAULT_ACP_COMMAND, + DiscoverManagedAgentPrereqsRequest, InstallRuntimeResult, InstallStepResult, + ManagedAgentPrereqsInfo, RelayAgentInfo, DEFAULT_ACP_COMMAND, }, nostr_convert, relay::query_relay, @@ -235,11 +235,13 @@ pub async fn install_acp_runtime( // active_installs guard is dropped when install_acp_runtime_blocking // returns (Guard impl Drop) — so Phase 2's restart path runs outside // the guard and cannot re-enter the mutex. + let reporter = InstallReporter::for_command(&app, &runtime_id); let runtime_id_clone = runtime_id.clone(); - let install_result = - tokio::task::spawn_blocking(move || install_acp_runtime_blocking(&runtime_id_clone)) - .await - .map_err(|e| format!("install task panicked: {e}"))??; + let install_result = tokio::task::spawn_blocking(move || { + install_acp_runtime_blocking(&runtime_id_clone, &reporter) + }) + .await + .map_err(|e| format!("install task panicked: {e}"))??; if !install_result.success { return Ok(install_result); @@ -259,12 +261,16 @@ pub async fn install_acp_runtime( steps: install_result.steps, restarted_count, failed_restart_count, + log_path: install_result.log_path, }) } /// Err(_) = infrastructure failure (panic, concurrency guard). /// Ok({success: false}) = an install step failed (stderr captured in steps). -fn install_acp_runtime_blocking(runtime_id: &str) -> Result { +fn install_acp_runtime_blocking( + runtime_id: &str, + reporter: &InstallReporter, +) -> Result { // Re-fetch the login-shell PATH so a Node.js installation that happened // after app launch (or after a previous failed install) is visible to this // run and to the subsequent discover_acp_providers call. @@ -306,16 +312,11 @@ fn install_acp_runtime_blocking(runtime_id: &str) -> Result Result Result command, Ok(None) => cmd.to_string(), Err(step) => { - steps.push(*step); - return Ok(InstallRuntimeResult { - success: false, - steps, - restarted_count: 0, - failed_restart_count: 0, - }); + reporter.record_step(&mut steps, *step); + return Ok(failed_install(steps, reporter)); } }; - let mut result = run_install_command_with_retry("adapter", &planned); + let mut result = run_install_command_with_retry("adapter", &planned, reporter); if !result.success && result.hint.is_none() && is_npm_global_install(cmd) { result.hint = npm_eacces_hint(&result.stderr, cmd); } let success = result.success; steps.push(result); if !success { - return Ok(InstallRuntimeResult { - success: false, - steps, - restarted_count: 0, - failed_restart_count: 0, - }); + return Ok(failed_install(steps, reporter)); } } } - post_install_verification::run(runtime_id, &mut steps); + post_install_verification::run(runtime_id, &mut steps, reporter); Ok(InstallRuntimeResult { success: steps.iter().all(|step| step.success), steps, restarted_count: 0, failed_restart_count: 0, + log_path: reporter.log_path(), }) } +/// A failed install, carrying the steps recorded so far and the log holding +/// their full history. Every early return in the install builds its result +/// here, so none can forget the log pointer the failure message needs. +fn failed_install( + steps: Vec, + reporter: &InstallReporter, +) -> InstallRuntimeResult { + InstallRuntimeResult { + success: false, + steps, + restarted_count: 0, + failed_restart_count: 0, + log_path: reporter.log_path(), + } +} + // ── Post-install auto-restart (Phase 2 of install_acp_runtime) ─────────────── // // After a successful adapter install, restart any local agents that: @@ -1016,8 +1019,11 @@ fn build_install_command(command: &str) -> Result } // ── install command execution ───────────────────────────────────────────────── +mod install_capture; mod install_exec; +mod install_report; use install_exec::run_install_command_with_retry; +use install_report::InstallReporter; // ── managed Node/npm runtime ────────────────────────────────────────────────── mod managed_node; diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs b/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs new file mode 100644 index 0000000000..4a212c7ee1 --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs @@ -0,0 +1,249 @@ +//! Bounded capture of an install command's output. +//! +//! One drain per stream feeds a [`Capture`], which holds two independently +//! bounded views of the same bytes: a small one sized for an error toast and a +//! large one sized for the install log file. Both are shared with the draining +//! reader rather than returned by it, so whatever arrived before a stall is +//! readable at the ceiling — exactly when the output matters most. + +use std::collections::VecDeque; +use std::io::Read; +use std::sync::{Arc, Mutex}; +use std::time::{Duration, Instant}; + +/// How much of each end a capture keeps, and how it names what was cut. +#[derive(Clone, Copy)] +struct Caps { + head: usize, + tail: usize, + marker: fn(usize) -> String, +} + +/// Sized for a UI error message: enough to identify the failure, small enough +/// to read in a toast. +const UI_CAPS: Caps = Caps { + head: 512, + tail: 1024, + marker: |omitted| format!("... ({omitted} bytes omitted) ..."), +}; + +/// Sized for the log file, where the budget is disk rather than screen. At this +/// cap a real install log is complete in practice; the marker names the cases +/// where it is not, so the file never implies completeness it does not have. +const LOG_CAPS: Caps = Caps { + head: 128 * 1024, + tail: 128 * 1024, + marker: |omitted| format!("... [{omitted} bytes omitted at cap] ..."), +}; + +/// Bounded capture of one stream: its first `head` bytes, its last `tail` +/// bytes, and the total byte count. Output of any size costs a fixed amount of +/// memory, so an installer that prints megabytes cannot grow the process. +struct BoundedOutput { + head: Vec, + tail: VecDeque, + total: usize, + caps: Caps, +} + +type SharedOutput = Arc>; + +impl BoundedOutput { + fn shared(caps: Caps) -> SharedOutput { + Arc::new(Mutex::new(Self { + head: Vec::new(), + tail: VecDeque::new(), + total: 0, + caps, + })) + } + + /// Absorb one read. Chunk boundaries are irrelevant to the result: the head + /// fills first, the remainder rolls through the tail window. + fn push(&mut self, chunk: &[u8]) { + self.total += chunk.len(); + let head_room = self + .caps + .head + .saturating_sub(self.head.len()) + .min(chunk.len()); + let (head_part, tail_part) = chunk.split_at(head_room); + self.head.extend_from_slice(head_part); + self.tail.extend(tail_part); + while self.tail.len() > self.caps.tail { + self.tail.pop_front(); + } + } + + fn render(&self) -> String { + let tail: Vec = self.tail.iter().copied().collect(); + if self.total <= self.caps.head + self.caps.tail { + // Nothing was dropped, so head followed by tail is the whole stream. + let mut whole = self.head.clone(); + whole.extend_from_slice(&tail); + return decode(&whole); + } + // Both ends are cut at arbitrary byte offsets, so trim any partial + // character rather than emitting replacement chars. The marker counts + // every dropped byte, including those trims. + let head = utf8_prefix(&self.head); + let tail = utf8_suffix(&tail); + let omitted = self.total - head.len() - tail.len(); + format!( + "{}\n{}\n{}", + decode(head), + (self.caps.marker)(omitted), + decode(tail) + ) + } +} + +/// The two bounded views of one stream, filled by a single drain. +pub(super) struct Capture { + ui: SharedOutput, + log: SharedOutput, +} + +impl Capture { + pub(super) fn new() -> Self { + Self { + ui: BoundedOutput::shared(UI_CAPS), + log: BoundedOutput::shared(LOG_CAPS), + } + } + + /// What the UI shows for this stream. + pub(super) fn ui(&self) -> String { + render(&self.ui) + } + + /// What the install log records for this stream. + pub(super) fn log(&self) -> String { + render(&self.log) + } + + fn push(&self, chunk: &[u8]) { + for sink in [&self.ui, &self.log] { + if let Ok(mut sink) = sink.lock() { + sink.push(chunk); + } + } + } +} + +/// Called with each complete line an install prints, for the live output line +/// in the UI. Shared across both drain threads of one attempt. +pub(super) type LineObserver = Arc; + +/// Render a capture even if its drain thread panicked mid-write — a poisoned +/// lock must not cost the diagnostics. +fn render(sink: &SharedOutput) -> String { + sink.lock().unwrap_or_else(|p| p.into_inner()).render() +} + +/// Read `pipe` to EOF, feeding fixed-size chunks into `capture` and each +/// complete line to `observer`. Read errors end the drain — a broken pipe means +/// the child is gone and there is nothing left to capture. +pub(super) fn drain_into(mut pipe: impl Read, capture: &Capture, observer: Option<&LineObserver>) { + let mut chunk = [0u8; 8192]; + let mut lines = LineSplitter::default(); + loop { + match pipe.read(&mut chunk) { + Ok(0) => return, + Ok(n) => { + capture.push(&chunk[..n]); + if let Some(observe) = observer { + lines.feed(&chunk[..n], |line| observe(line)); + } + } + Err(e) if e.kind() == std::io::ErrorKind::Interrupted => continue, + Err(_) => return, + } + } +} + +/// Reassembles lines from arbitrary read chunks. A partial trailing line is +/// held until its newline arrives, so an observer only ever sees complete +/// lines. The buffer is capped: a program that prints megabytes without a +/// newline must not grow it without bound. +#[derive(Default)] +struct LineSplitter { + partial: Vec, +} + +impl LineSplitter { + /// Longest line reassembled. Beyond this the excess is dropped, since the + /// consumer displays a single truncated line anyway. + const MAX_LINE: usize = 4096; + + fn feed(&mut self, chunk: &[u8], mut emit: impl FnMut(&str)) { + for byte in chunk { + if *byte == b'\n' { + let line = String::from_utf8_lossy(&self.partial).trim().to_string(); + self.partial.clear(); + if !line.is_empty() { + emit(&line); + } + } else if self.partial.len() < Self::MAX_LINE { + self.partial.push(*byte); + } + } + } +} + +/// Rate limiter for the live output line: at most one event per +/// `min_interval`. Lines arriving inside the window are dropped rather than +/// buffered — the UI shows the latest line, so a stale backlog has no value. +pub(super) struct Throttle { + min_interval: Duration, + last: Mutex>, +} + +impl Throttle { + pub(super) fn new(min_interval: Duration) -> Self { + Self { + min_interval, + last: Mutex::new(None), + } + } + + pub(super) fn allows(&self, now: Instant) -> bool { + let Ok(mut last) = self.last.lock() else { + return false; + }; + if last.is_some_and(|prev| now.duration_since(prev) < self.min_interval) { + return false; + } + *last = Some(now); + true + } +} + +fn decode(bytes: &[u8]) -> String { + String::from_utf8_lossy(bytes).into_owned() +} + +/// Drop a trailing partial UTF-8 sequence, keeping mid-stream invalid bytes for +/// the lossy decode to mark. +fn utf8_prefix(bytes: &[u8]) -> &[u8] { + match std::str::from_utf8(bytes) { + Ok(_) => bytes, + Err(e) if e.error_len().is_none() => &bytes[..e.valid_up_to()], + Err(_) => bytes, + } +} + +/// Drop leading UTF-8 continuation bytes — at most three can precede a +/// character start. +fn utf8_suffix(bytes: &[u8]) -> &[u8] { + let start = bytes + .iter() + .take(3) + .take_while(|b| *b & 0b1100_0000 == 0b1000_0000) + .count(); + &bytes[start..] +} + +#[cfg(test)] +#[path = "install_capture_tests.rs"] +mod tests; diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs new file mode 100644 index 0000000000..f9ed4b89e0 --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs @@ -0,0 +1,269 @@ +use super::*; + +/// Feed `chunks` through a capture in order. +fn capture_of(chunks: &[&[u8]]) -> Capture { + let capture = Capture::new(); + for chunk in chunks { + capture.push(chunk); + } + capture +} + +/// Render what the UI would show for a stream of `chunks`. +fn ui(chunks: &[&[u8]]) -> String { + capture_of(chunks).ui() +} + +// ── bounded capture ────────────────────────────────────────────────────────── + +/// Output within the cap is passed through byte-for-byte — no marker, no loss. +#[test] +fn test_capture_leaves_short_output_untouched() { + let short = "a".repeat(1536); + + assert_eq!(ui(&[short.as_bytes()]), short); +} + +/// Over the cap, both ends survive and the middle is replaced by a marker +/// naming the omitted byte count — the head keeps the command's opening +/// context and the tail keeps the error that usually trails. +#[test] +fn test_capture_over_cap_keeps_head_and_tail_with_marker() { + let input = format!( + "{}{}{}", + "H".repeat(512), + "M".repeat(4000), + "T".repeat(1024) + ); + + let out = ui(&[input.as_bytes()]); + + assert!(out.starts_with(&"H".repeat(512))); + assert!(out.ends_with(&"T".repeat(1024))); + assert!( + out.contains("... (4000 bytes omitted) ..."), + "marker must name the omitted byte count, got: {out}" + ); +} + +/// The rendered result depends only on the byte stream, not on how the reads +/// happened to split it — a real drain sees arbitrary chunk sizes. +#[test] +fn test_capture_is_independent_of_chunk_boundaries() { + let input = "x".repeat(9000); + let one_shot = ui(&[input.as_bytes()]); + + let chunked: Vec<&[u8]> = input.as_bytes().chunks(7).collect(); + + assert_eq!(ui(&chunked), one_shot); +} + +/// Truncation must not split a multi-byte character. Both cut points land +/// mid-codepoint here; the partial bytes are dropped rather than decoded into +/// replacement chars. +#[test] +fn test_capture_does_not_split_multibyte_characters() { + // "é" is 2 bytes, so every candidate cut index lands mid-character. + let input = "é".repeat(4000); + + let out = ui(&[input.as_bytes()]); + + assert!(out.contains("bytes omitted"), "input must exceed the cap"); + assert!(!out.contains('\u{fffd}'), "no replacement chars: {out}"); +} + +/// Memory stays flat regardless of how much the installer prints: the rendered +/// UI result of a 4MiB stream is no larger than that of a 6KiB one. +#[test] +fn test_capture_of_huge_output_stays_bounded() { + let chunk = vec![b'z'; 8192]; + + let capture = Capture::new(); + for _ in 0..512 { + capture.push(&chunk); + } + + let out = capture.ui(); + assert!( + out.len() < 2048, + "4MiB of output must render bounded, got {} bytes", + out.len() + ); + assert!(out.contains("bytes omitted")); +} + +// ── the log view is separately bounded ─────────────────────────────────────── + +/// The log view holds output the UI view had to cut. A toast is capped for +/// readability; the log file's budget is disk, and "Full log: {path}" has to +/// point at more than the toast already showed. +#[test] +fn test_log_view_keeps_output_the_ui_view_truncates() { + let input = format!("start{}end", "m".repeat(64 * 1024)); + + let capture = capture_of(&[input.as_bytes()]); + + assert!( + capture.ui().contains("bytes omitted"), + "64KiB must exceed the UI cap" + ); + assert_eq!( + capture.log(), + input, + "the same output must be complete in the log view" + ); +} + +/// Even the log view is bounded — a runaway installer cannot fill the disk — +/// and when it does cut, the record says so inline at the cap rather than +/// implying completeness. +#[test] +fn test_log_view_is_bounded_and_marks_its_cap() { + let head = "H".repeat(128 * 1024); + let middle = "M".repeat(5000); + let tail = "T".repeat(128 * 1024); + let input = format!("{head}{middle}{tail}"); + + let capture = capture_of(&[input.as_bytes()]); + + let out = capture.log(); + assert!( + out.len() < 300 * 1024, + "output past the log cap must render bounded, got {} bytes", + out.len() + ); + assert!(out.starts_with(&head), "the log head must survive intact"); + assert!(out.ends_with(&tail), "the log tail must survive intact"); + assert!( + out.contains("... [5000 bytes omitted at cap] ..."), + "a cut log record must name the cap inline, got the middle: {}", + &out[128 * 1024..(128 * 1024 + 64).min(out.len())] + ); +} + +/// The two views mark their cuts differently on purpose: the toast reads as +/// prose, the log record reads as a machine-scannable annotation. +#[test] +fn test_ui_and_log_views_use_their_own_cap_markers() { + let input = "x".repeat(300 * 1024); + + let capture = capture_of(&[input.as_bytes()]); + + assert!( + capture.ui().contains("bytes omitted) ..."), + "the UI marker reads as prose: {}", + capture.ui() + ); + assert!(capture.log().contains("bytes omitted at cap] ...")); +} + +// ── line observation ───────────────────────────────────────────────────────── + +/// Collect the lines a drain over `chunks` reports. +fn observed_lines(chunks: &[&[u8]]) -> Vec { + let seen: Arc>> = Arc::new(Mutex::new(Vec::new())); + let observer: LineObserver = { + let seen = Arc::clone(&seen); + Arc::new(move |line: &str| seen.lock().unwrap().push(line.to_string())) + }; + let bytes: Vec = chunks.concat(); + + drain_into(bytes.as_slice(), &Capture::new(), Some(&observer)); + + let observed = seen.lock().unwrap().clone(); + observed +} + +/// The observer sees complete lines, reassembled across the read boundaries +/// that split them — a live output line must never show half a word. +#[test] +fn test_observer_reassembles_lines_split_across_reads() { + let lines = observed_lines(&[b"downloa", b"ding 40%\nunpack", b"ing\n"]); + + assert_eq!(lines, vec!["downloading 40%", "unpacking"]); +} + +/// A trailing line with no newline is never reported: it may still be growing, +/// and showing a half-line as if complete is worse than showing the previous +/// one. +#[test] +fn test_observer_withholds_a_line_that_has_no_newline_yet() { + let lines = observed_lines(&[b"complete\n", b"still-writing"]); + + assert_eq!(lines, vec!["complete"]); +} + +/// Blank lines carry nothing to display; progress output is full of them. +#[test] +fn test_observer_skips_blank_lines() { + let lines = observed_lines(&[b"a\n\n \nb\n"]); + + assert_eq!(lines, vec!["a", "b"]); +} + +/// A pathological line with no newline must not grow the buffer without bound. +#[test] +fn test_observer_caps_a_pathologically_long_line() { + let huge = "x".repeat(100_000); + + let lines = observed_lines(&[huge.as_bytes(), b"\n"]); + + assert_eq!(lines.len(), 1); + assert!( + lines[0].len() <= LineSplitter::MAX_LINE, + "line must be capped, got {} bytes", + lines[0].len() + ); +} + +/// A drain with no observer still captures — the log and UI views do not +/// depend on anyone watching. +#[test] +fn test_drain_captures_without_an_observer() { + let capture = Capture::new(); + + drain_into(b"hello\n".as_slice(), &capture, None); + + assert_eq!(capture.ui(), "hello\n"); +} + +// ── throttle ───────────────────────────────────────────────────────────────── + +/// The first line always goes out, and a second inside the window is dropped +/// rather than queued: the UI wants the newest line, not a replay. +#[test] +fn test_throttle_allows_the_first_line_and_drops_the_next_in_window() { + let throttle = Throttle::new(Duration::from_millis(250)); + let start = Instant::now(); + + assert!(throttle.allows(start)); + assert!(!throttle.allows(start + Duration::from_millis(100))); +} + +/// Once the window passes, emission resumes — a long install keeps showing +/// progress. +#[test] +fn test_throttle_allows_again_after_the_window() { + let throttle = Throttle::new(Duration::from_millis(250)); + let start = Instant::now(); + + assert!(throttle.allows(start)); + + assert!(throttle.allows(start + Duration::from_millis(300))); +} + +/// The window is measured from the last *emitted* line, not the last attempt: +/// a stream of dropped lines must not extend the silence. +#[test] +fn test_throttle_window_runs_from_the_last_emission() { + let throttle = Throttle::new(Duration::from_millis(250)); + let start = Instant::now(); + assert!(throttle.allows(start)); + + assert!(!throttle.allows(start + Duration::from_millis(200))); + + assert!( + throttle.allows(start + Duration::from_millis(260)), + "a dropped line must not restart the window" + ); +} diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs index 2c93b482d6..806a4c7081 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs @@ -5,11 +5,11 @@ //! `install_powershell_command`, `build_install_command`); this module owns //! only what happens once a `Command` exists. -use std::collections::VecDeque; -use std::io::Read; -use std::sync::{Arc, Mutex}; +use std::sync::Arc; use std::time::{Duration, Instant}; +use super::install_capture::{drain_into, Capture, LineObserver}; +use super::install_report::{InstallOutcome, InstallReporter}; use crate::managed_agents::InstallStepResult; /// Maximum number of attempts for a transient-looking install command. @@ -31,12 +31,19 @@ const INSTALL_MAX_ATTEMPTS: u32 = 3; /// works again in Settings. User-facing cancellation is the product-level fix. const INSTALL_TIMEOUT: Duration = Duration::from_secs(900); -/// How long the ceiling waits for the output drains to finish after killing the -/// install's process group. The kill closes the pipe write ends, so the drains -/// normally end within microseconds; this bound only covers a descendant that -/// escaped the group and still holds one open. Such a process must not hold the -/// install — and the concurrency guard behind it — open past the ceiling. -const DRAIN_GRACE: Duration = Duration::from_secs(2); +/// How long the group gets to exit on SIGTERM before the ceiling escalates to +/// SIGKILL. +#[cfg(unix)] +const TERM_GRACE: Duration = Duration::from_secs(1); + +/// How long the ceiling waits after killing the install's process group — +/// applied separately to reaping the killed child and to the output drains +/// finishing. The kill closes the pipe write ends, so both normally complete +/// within microseconds; the bound covers the cases where they don't (a process +/// that escaped the group and still holds a pipe, or a termination that failed +/// outright). Neither may hold the install — nor the per-runtime concurrency +/// guard behind it — open past the ceiling. +const POST_KILL_GRACE: Duration = Duration::from_secs(2); /// Run an install command, retrying transient failures with backoff. /// @@ -48,10 +55,21 @@ const DRAIN_GRACE: Duration = Duration::from_secs(2); /// `INSTALL_MAX_ATTEMPTS` times. Failures with no exit code — a timeout or a /// shell that never spawned — are not retried, since re-running them just costs /// the user more time without a plausible path to success. -pub(super) fn run_install_command_with_retry(step: &str, command: &str) -> InstallStepResult { +/// +/// Every attempt is recorded through `reporter`, so the install log holds the +/// full retry history even though the UI only ever sees the last attempt. +pub(super) fn run_install_command_with_retry( + step: &str, + command: &str, + reporter: &InstallReporter, +) -> InstallStepResult { run_install_with_retry( INSTALL_MAX_ATTEMPTS, - |_attempt| run_install_command(step, command), + |attempt| { + let outcome = run_install_command(step, command, reporter.line_observer(attempt)); + reporter.record_attempt(attempt, &outcome); + outcome.step + }, std::thread::sleep, ) } @@ -118,11 +136,15 @@ fn prepare_install_command(command: &str) -> Result InstallStepResult { +fn run_install_command( + step: &str, + command: &str, + observer: Option, +) -> InstallOutcome { let mut cmd = match prepare_install_command(command) { Ok(cmd) => cmd, Err(hint) => { - return InstallStepResult { + return InstallOutcome::synthesized(InstallStepResult { step: step.to_string(), command: command.to_string(), success: false, @@ -130,7 +152,7 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { stderr: "no suitable shell found for install commands".to_string(), exit_code: None, hint: Some(hint), - }; + }); } }; @@ -142,7 +164,7 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { { Ok(child) => child, Err(e) => { - return InstallStepResult { + return InstallOutcome::synthesized(InstallStepResult { step: step.to_string(), command: command.to_string(), success: false, @@ -150,11 +172,11 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { stderr: format!("failed to spawn shell: {e}"), exit_code: None, hint: None, - }; + }); } }; - await_install_child(step, command, child, INSTALL_TIMEOUT) + await_install_child(step, command, child, INSTALL_TIMEOUT, observer) } /// Drain a spawned install child's output into bounded buffers and wait for it @@ -168,31 +190,36 @@ fn await_install_child( command: &str, mut child: std::process::Child, timeout: Duration, -) -> InstallStepResult { + observer: Option, +) -> InstallOutcome { // Drain stdout/stderr on background threads to prevent pipe buffer - // deadlock. Each drain feeds a bounded sink the main thread can read at any - // time, so a timeout can still surface whatever the install printed before - // it stalled. - let stdout_sink = BoundedOutput::shared(); - let stderr_sink = BoundedOutput::shared(); + // deadlock. Each drain feeds a bounded capture the main thread can read at + // any time, so a timeout can still surface whatever the install printed + // before it stalled. + let stdout_capture = Arc::new(Capture::new()); + let stderr_capture = Arc::new(Capture::new()); let stdout_pipe = child.stdout.take(); let stderr_pipe = child.stderr.take(); let (drained_tx, drained_rx) = std::sync::mpsc::channel(); let stdout_thread = std::thread::spawn({ - let (sink, done) = (Arc::clone(&stdout_sink), drained_tx.clone()); + let (capture, done, observer) = ( + Arc::clone(&stdout_capture), + drained_tx.clone(), + observer.clone(), + ); move || { if let Some(pipe) = stdout_pipe { - drain_into(pipe, &sink); + drain_into(pipe, &capture, observer.as_ref()); } let _ = done.send(()); } }); let stderr_thread = std::thread::spawn({ - let (sink, done) = (Arc::clone(&stderr_sink), drained_tx); + let (capture, done) = (Arc::clone(&stderr_capture), drained_tx); move || { if let Some(pipe) = stderr_pipe { - drain_into(pipe, &sink); + drain_into(pipe, &capture, observer.as_ref()); } let _ = done.send(()); } @@ -216,20 +243,23 @@ fn await_install_child( // install shell is a session leader (`setsid` in its `pre_exec`), so // signalling only the leader would leave descendants running and // holding the output pipes open. - let _ = crate::managed_agents::terminate_process(child_pid); - drop(rx); - let _ = wait_thread.join(); - // The kill closes the pipes, so the drains normally end at once. - // Any that don't are left detached rather than holding the install - // (and the concurrency guard behind it) open past the ceiling — - // their sinks are read under the lock either way. - await_drains(&drained_rx, DRAIN_GRACE); + terminate_install_group(child_pid); + // Reaping the child and finishing the drains share one bound. Both + // normally complete within microseconds of the kill, which closes + // the pipes; when they don't — a process that escaped the group + // still holding a pipe, or a termination that failed outright — + // waiting would defeat the very ceiling that fired and keep the + // per-runtime install guard behind it closed. Stragglers are + // detached instead; the sinks are read under the lock either way. + let settle_by = Instant::now() + POST_KILL_GRACE; + await_messages(&rx, 1, settle_by); + await_messages(&drained_rx, 2, settle_by); return failed_with_capture( step, command, timeout_message(timeout), - &stdout_sink, - &stderr_sink, + &stdout_capture, + &stderr_capture, ); } @@ -238,14 +268,18 @@ fn await_install_child( let _ = wait_thread.join(); let _ = stdout_thread.join(); let _ = stderr_thread.join(); - return InstallStepResult { - step: step.to_string(), - command: command.to_string(), - success: status.success(), - stdout: render_sink(&stdout_sink), - stderr: render_sink(&stderr_sink), - exit_code: status.code(), - hint: None, + return InstallOutcome { + step: InstallStepResult { + step: step.to_string(), + command: command.to_string(), + success: status.success(), + stdout: stdout_capture.ui(), + stderr: stderr_capture.ui(), + exit_code: status.code(), + hint: None, + }, + log_stdout: stdout_capture.log(), + log_stderr: stderr_capture.log(), }; } Ok(Err(e)) => { @@ -256,8 +290,8 @@ fn await_install_child( step, command, format!("failed to check process status: {e}"), - &stdout_sink, - &stderr_sink, + &stdout_capture, + &stderr_capture, ); } Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { @@ -273,110 +307,83 @@ fn await_install_child( step, command, "internal error: wait thread disconnected".to_string(), - &stdout_sink, - &stderr_sink, + &stdout_capture, + &stderr_capture, ); } } } } -/// Bounded capture of one output stream: the first [`BoundedOutput::HEAD`] -/// bytes, the last [`BoundedOutput::TAIL`] bytes, and the total byte count. +/// Kill the install's process group, escalating on the *tree's* liveness. /// -/// Two properties matter. Output of any size costs a fixed amount of memory — -/// an installer that prints megabytes cannot grow the process. And because the -/// sink is *shared* with the draining reader instead of being returned by it, -/// whatever arrived before a stall is readable at the ceiling, which is exactly -/// when the output is most needed. -struct BoundedOutput { - head: Vec, - tail: VecDeque, - total: usize, -} - -type SharedOutput = Arc>; - -impl BoundedOutput { - /// The head keeps the command's opening context; the tail keeps the error - /// that usually trails. Everything between them is replaced by a marker - /// naming the omitted byte count. - const HEAD: usize = 512; - const TAIL: usize = 1024; - - fn shared() -> SharedOutput { - Arc::new(Mutex::new(Self { - head: Vec::new(), - tail: VecDeque::new(), - total: 0, - })) - } - - /// Absorb one read. Chunk boundaries are irrelevant to the result: the head - /// fills first, the remainder rolls through the tail window. - fn push(&mut self, chunk: &[u8]) { - self.total += chunk.len(); - let head_room = Self::HEAD.saturating_sub(self.head.len()).min(chunk.len()); - let (head_part, tail_part) = chunk.split_at(head_room); - self.head.extend_from_slice(head_part); - self.tail.extend(tail_part); - while self.tail.len() > Self::TAIL { - self.tail.pop_front(); +/// The install ceiling owns this rather than reusing +/// `managed_agents::terminate_process`, which escalates to SIGKILL only while +/// the group *leader* is still running: a descendant that ignores SIGTERM +/// outlives the leader, keeps the output pipes open, and never receives the +/// group SIGKILL. The ceiling's contract is that nothing survives it, and the +/// shared helper's escalation is load-bearing for the agent stop/restore paths, +/// so the stricter rule lives here instead of changing it for them. +/// +/// Nothing is returned: every outcome — including a signal that could not be +/// delivered at all — has the same handling, the bounded waits at the call +/// site. +#[cfg(unix)] +fn terminate_install_group(pid: u32) { + signal_install_tree(pid, libc::SIGTERM); + let deadline = Instant::now() + TERM_GRACE; + while install_tree_is_alive(pid) { + if Instant::now() >= deadline { + signal_install_tree(pid, libc::SIGKILL); + return; } + std::thread::sleep(Duration::from_millis(50)); } +} - fn render(&self) -> String { - let tail: Vec = self.tail.iter().copied().collect(); - if self.total <= Self::HEAD + Self::TAIL { - // Nothing was dropped, so head followed by tail is the whole stream. - let mut whole = self.head.clone(); - whole.extend_from_slice(&tail); - return decode(&whole); - } - // Both ends are cut at arbitrary byte offsets, so trim any partial - // character rather than emitting replacement chars. The marker counts - // every dropped byte, including those trims. - let head = utf8_prefix(&self.head); - let tail = utf8_suffix(&tail); - let omitted = self.total - head.len() - tail.len(); - format!( - "{}\n... ({omitted} bytes omitted) ...\n{}", - decode(head), - decode(tail) - ) +/// Signal every process in `pid`'s group, falling back to the leader alone when +/// the group cannot be signalled — the leader may have changed groups, or macOS +/// may refuse one member — since killing the install shell beats killing +/// nothing. +#[cfg(unix)] +fn signal_install_tree(pid: u32, signal: i32) { + if unsafe { libc::kill(-(pid as i32), signal) } != 0 { + unsafe { libc::kill(pid as i32, signal) }; } } -/// Read `pipe` to EOF, feeding fixed-size chunks into `sink`. Read errors end -/// the drain — a broken pipe means the child is gone and there is nothing left -/// to capture. -fn drain_into(mut pipe: impl Read, sink: &SharedOutput) { - let mut chunk = [0u8; 8192]; - loop { - match pipe.read(&mut chunk) { - Ok(0) => return, - Ok(n) => { - if let Ok(mut sink) = sink.lock() { - sink.push(&chunk[..n]); - } - } - Err(e) if e.kind() == std::io::ErrorKind::Interrupted => continue, - Err(_) => return, - } +/// Whether anything the ceiling aimed at is still running: a member of the +/// process group, or the leader itself. +#[cfg(unix)] +fn install_tree_is_alive(pid: u32) -> bool { + signal_reaches(-(pid as i32)) || signal_reaches(pid as i32) +} + +/// `kill(target, 0)` distinguishes "nothing there" (`ESRCH`) from every other +/// outcome. Anything ambiguous — notably `EPERM` for a member we may not +/// signal — counts as alive, so an unclear answer escalates rather than +/// declaring the tree dead. +#[cfg(unix)] +fn signal_reaches(target: i32) -> bool { + if unsafe { libc::kill(target, 0) } == 0 { + return true; } + std::io::Error::last_os_error().raw_os_error() != Some(libc::ESRCH) } -/// Render a sink even if its drain thread panicked mid-write — a poisoned lock -/// must not cost the diagnostics. -fn render_sink(sink: &SharedOutput) -> String { - sink.lock().unwrap_or_else(|p| p.into_inner()).render() +/// Windows has no process groups on this path: `terminate_process` runs +/// `taskkill /T /F`, which is already tree-wide and unconditional, so there is +/// no escalation to get wrong. +#[cfg(not(unix))] +fn terminate_install_group(pid: u32) { + let _ = crate::managed_agents::terminate_process(pid); } -/// Wait up to `grace` in total for both drains to signal completion. Returns -/// early on timeout, leaving any straggler detached. -fn await_drains(done: &std::sync::mpsc::Receiver<()>, grace: Duration) { - let deadline = Instant::now() + grace; - for _ in 0..2 { +/// Wait for `count` messages on `done`, giving up at `deadline` and leaving any +/// straggler detached. Used only after the ceiling's kill, where a sender that +/// never arrives is precisely the case that must not extend the ceiling. +fn await_messages(done: &std::sync::mpsc::Receiver, count: usize, deadline: Instant) { + for _ in 0..count { let remaining = deadline.saturating_duration_since(Instant::now()); if done.recv_timeout(remaining).is_err() { return; @@ -391,22 +398,32 @@ fn failed_with_capture( step: &str, command: &str, reason: String, - stdout: &SharedOutput, - stderr: &SharedOutput, -) -> InstallStepResult { - let captured = render_sink(stderr); - InstallStepResult { - step: step.to_string(), - command: command.to_string(), - success: false, - stdout: render_sink(stdout), - stderr: if captured.is_empty() { - reason - } else { - format!("{reason}\n{captured}") + stdout: &Capture, + stderr: &Capture, +) -> InstallOutcome { + InstallOutcome { + step: InstallStepResult { + step: step.to_string(), + command: command.to_string(), + success: false, + stdout: stdout.ui(), + stderr: lead_with_reason(&reason, stderr.ui()), + exit_code: None, + hint: None, }, - exit_code: None, - hint: None, + log_stdout: stdout.log(), + log_stderr: lead_with_reason(&reason, stderr.log()), + } +} + +/// Put `reason` ahead of the install's own stderr, so the surfaced message names +/// the failure before the output. An empty capture leaves the reason alone, +/// without a dangling separator. +fn lead_with_reason(reason: &str, captured: String) -> String { + if captured.is_empty() { + reason.to_string() + } else { + format!("{reason}\n{captured}") } } @@ -422,31 +439,6 @@ fn timeout_message(timeout: Duration) -> String { format!("install command exceeded the {limit} ceiling and was terminated") } -fn decode(bytes: &[u8]) -> String { - String::from_utf8_lossy(bytes).into_owned() -} - -/// Drop a trailing partial UTF-8 sequence, keeping mid-stream invalid bytes for -/// the lossy decode to mark. -fn utf8_prefix(bytes: &[u8]) -> &[u8] { - match std::str::from_utf8(bytes) { - Ok(_) => bytes, - Err(e) if e.error_len().is_none() => &bytes[..e.valid_up_to()], - Err(_) => bytes, - } -} - -/// Drop leading UTF-8 continuation bytes — at most three can precede a -/// character start. -fn utf8_suffix(bytes: &[u8]) -> &[u8] { - let start = bytes - .iter() - .take(3) - .take_while(|b| *b & 0b1100_0000 == 0b1000_0000) - .count(); - &bytes[start..] -} - #[cfg(test)] mod tests { use super::*; @@ -591,93 +583,6 @@ mod tests { assert_eq!(cmd.get_current_dir(), Some(expected.as_path())); } - // ── output capture ──────────────────────────────────────────────────────── - - /// Feed `chunks` through a sink in order and render it. - fn capture(chunks: &[&[u8]]) -> String { - let sink = BoundedOutput::shared(); - for chunk in chunks { - sink.lock().unwrap().push(chunk); - } - render_sink(&sink) - } - - /// Output within the cap is passed through byte-for-byte — no marker, no loss. - #[test] - fn test_capture_leaves_short_output_untouched() { - let short = "a".repeat(1536); - - assert_eq!(capture(&[short.as_bytes()]), short); - } - - /// Over the cap, both ends survive and the middle is replaced by a marker - /// naming the omitted byte count — the head keeps the command's opening - /// context and the tail keeps the error that usually trails. - #[test] - fn test_capture_over_cap_keeps_head_and_tail_with_marker() { - let input = format!( - "{}{}{}", - "H".repeat(512), - "M".repeat(4000), - "T".repeat(1024) - ); - - let out = capture(&[input.as_bytes()]); - - assert!(out.starts_with(&"H".repeat(512))); - assert!(out.ends_with(&"T".repeat(1024))); - assert!( - out.contains("... (4000 bytes omitted) ..."), - "marker must name the omitted byte count, got: {out}" - ); - } - - /// The rendered result depends only on the byte stream, not on how the - /// reads happened to split it — a real drain sees arbitrary chunk sizes. - #[test] - fn test_capture_is_independent_of_chunk_boundaries() { - let input = "x".repeat(9000); - let one_shot = capture(&[input.as_bytes()]); - - let chunked: Vec<&[u8]> = input.as_bytes().chunks(7).collect(); - - assert_eq!(capture(&chunked), one_shot); - } - - /// Truncation must not split a multi-byte character. Both cut points land - /// mid-codepoint here; the partial bytes are dropped rather than decoded - /// into replacement chars. - #[test] - fn test_capture_does_not_split_multibyte_characters() { - // "é" is 2 bytes, so every candidate cut index lands mid-character. - let input = "é".repeat(4000); - - let out = capture(&[input.as_bytes()]); - - assert!(out.contains("bytes omitted"), "input must exceed the cap"); - assert!(!out.contains('\u{fffd}'), "no replacement chars: {out}"); - } - - /// Memory stays flat regardless of how much the installer prints: the - /// rendered result of a 4MiB stream is no larger than that of a 6KiB one. - #[test] - fn test_capture_of_huge_output_stays_bounded() { - let chunk = vec![b'z'; 8192]; - let sink = BoundedOutput::shared(); - for _ in 0..512 { - sink.lock().unwrap().push(&chunk); - } - - let out = render_sink(&sink); - - assert!( - out.len() < 2048, - "4MiB of output must render bounded, got {} bytes", - out.len() - ); - assert!(out.contains("bytes omitted")); - } - // ── install ceiling ─────────────────────────────────────────────────────── /// The ceiling is Will's ruling: 15 minutes, and the error names the limit @@ -726,12 +631,13 @@ mod tests { let child = spawn_group_leader("echo out-before-hang; echo err-before-hang >&2; sleep 60"); let started = Instant::now(); - let result = await_install_child("cli", "install", child, Duration::from_secs(5)); + let outcome = await_install_child("cli", "install", child, Duration::from_secs(5), None); + let result = &outcome.step; assert!(!result.success); assert_eq!(result.exit_code, None, "a killed command has no exit code"); assert!( - !install_failure_is_retryable(&result), + !install_failure_is_retryable(result), "a ceiling kill must not be retried" ); assert!( @@ -753,6 +659,11 @@ mod tests { started.elapsed() < Duration::from_secs(30), "the ceiling must not wait on the hung command's own exit" ); + assert!( + outcome.log_stderr.contains("err-before-hang"), + "the log record of a ceiling kill must carry the output too, got: {:?}", + outcome.log_stderr + ); } /// A failure whose stream captured nothing surfaces the reason alone — no @@ -763,14 +674,77 @@ mod tests { "cli", "curl … | bash", "boom".to_string(), - &BoundedOutput::shared(), - &BoundedOutput::shared(), - ); + &Capture::new(), + &Capture::new(), + ) + .step; assert_eq!(result.stdout, ""); assert_eq!(result.stderr, "boom"); } + // ── post-kill settle bound ──────────────────────────────────────────────── + + /// A sender that never arrives — the shape of a failed termination, whose + /// child is never reaped — must not extend the wait past its deadline. + #[test] + fn test_awaiting_a_message_that_never_arrives_stops_at_the_deadline() { + let (_tx, rx) = std::sync::mpsc::channel::<()>(); + + let started = Instant::now(); + await_messages(&rx, 1, started + Duration::from_millis(200)); + + assert!( + started.elapsed() < Duration::from_secs(1), + "the wait must end at its deadline, took {:?}", + started.elapsed() + ); + } + + /// The deadline is shared across the whole settle, not restarted per + /// message: two waits behind one deadline still end at that deadline. + #[test] + fn test_awaiting_several_messages_shares_one_deadline() { + let (_tx, rx) = std::sync::mpsc::channel::<()>(); + + let started = Instant::now(); + let settle_by = started + Duration::from_millis(200); + await_messages(&rx, 1, settle_by); + await_messages(&rx, 2, settle_by); + + assert!( + started.elapsed() < Duration::from_secs(1), + "a shared deadline must not compound per wait, took {:?}", + started.elapsed() + ); + } + + /// Wait up to 3s for `pid` to disappear. + #[cfg(unix)] + fn await_death(pid: u32) -> bool { + for _ in 0..30 { + if !crate::managed_agents::process_is_running(pid) { + return true; + } + std::thread::sleep(Duration::from_millis(100)); + } + false + } + + /// Read the pid a test descendant recorded for itself. + #[cfg(unix)] + fn recorded_pid(pidfile: &std::path::Path) -> u32 { + for _ in 0..50 { + if let Ok(text) = std::fs::read_to_string(pidfile) { + if let Ok(pid) = text.trim().parse() { + return pid; + } + } + std::thread::sleep(Duration::from_millis(100)); + } + panic!("the descendant never recorded its pid at {pidfile:?}"); + } + /// The install shell is a process-group leader, and its descendants inherit /// the output pipes. Killing only the leader leaves them running and the /// drains blocked on a pipe nobody will close, so the ceiling kills the @@ -786,7 +760,8 @@ mod tests { )); let started = Instant::now(); - let result = await_install_child("cli", "install", child, Duration::from_secs(5)); + let outcome = await_install_child("cli", "install", child, Duration::from_secs(5), None); + let result = &outcome.step; assert!(!result.success); assert!( @@ -794,18 +769,43 @@ mod tests { "the drains must not block on a descendant's inherited pipe" ); - let pid: u32 = std::fs::read_to_string(&pidfile) - .expect("the descendant must have recorded its pid") - .trim() - .parse() - .expect("pid must parse"); - // Signal delivery is asynchronous; allow the group a moment to die. - for _ in 0..30 { - if !crate::managed_agents::process_is_running(pid) { - return; - } - std::thread::sleep(Duration::from_millis(100)); - } - panic!("descendant {pid} survived the ceiling kill — the group was not signalled"); + let pid = recorded_pid(&pidfile); + assert!( + await_death(pid), + "descendant {pid} survived the ceiling kill — the group was not signalled" + ); + } + + /// Escalation must key off the group, not the leader: a descendant that + /// ignores SIGTERM outlives the leader, and if SIGKILL is skipped because + /// the leader is gone it keeps running with the output pipes open — past the + /// ceiling, and past the concurrency guard that blocks the next install. + #[cfg(unix)] + #[test] + fn test_ceiling_kills_sigterm_ignoring_descendant() { + let dir = tempfile::tempdir().expect("tempdir"); + let pidfile = dir.path().join("stubborn.pid"); + // An ignored disposition survives exec, so the descendant's own `sleep` + // ignores SIGTERM too — nothing in that subtree dies without SIGKILL. + let child = spawn_group_leader(&format!( + "sh -c 'trap \"\" TERM; echo $$ > {pid}; sleep 60' & echo leader-up; sleep 60", + pid = pidfile.display() + )); + + let started = Instant::now(); + let outcome = await_install_child("cli", "install", child, Duration::from_secs(5), None); + let result = &outcome.step; + + assert!(!result.success); + assert!( + started.elapsed() < Duration::from_secs(30), + "a SIGTERM-ignoring descendant must not hold the ceiling open" + ); + + let pid = recorded_pid(&pidfile); + assert!( + await_death(pid), + "SIGTERM-ignoring descendant {pid} survived — escalation followed the leader, not the group" + ); } } diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs new file mode 100644 index 0000000000..7f85ff9f5d --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -0,0 +1,186 @@ +//! Where an install's output goes: the install log file (complete history) and +//! the live output line in the UI (current progress). +//! +//! Both destinations hang off the same drain seam in +//! [`super::install_capture`], and both are best-effort: an install must never +//! fail because a log write or an event emit did. + +use std::io::Write; +use std::path::PathBuf; +use std::sync::Arc; +use std::time::{Duration, Instant}; + +use serde::Serialize; + +use super::install_capture::{LineObserver, Throttle}; +use crate::managed_agents::InstallStepResult; + +/// One install command's result: what the UI shows, and the log-scale copy of +/// the same output for the log file. +pub(super) struct InstallOutcome { + pub(super) step: InstallStepResult, + pub(super) log_stdout: String, + pub(super) log_stderr: String, +} + +impl InstallOutcome { + /// A step Buzz synthesized rather than ran — a failed prerequisite, or the + /// post-install verification. Its own message is the whole record. + pub(super) fn synthesized(step: InstallStepResult) -> Self { + Self { + log_stdout: step.stdout.clone(), + log_stderr: step.stderr.clone(), + step, + } + } +} + +/// Payload of the `acp-install-output` event. +/// +/// `attempt` lets the UI drop a line that belongs to a superseded retry: +/// without it, a line emitted just before attempt 2 starts can sit under the +/// spinner while attempt 2 runs. +#[derive(Serialize, Clone)] +pub(super) struct InstallOutputEvent { + pub(super) runtime_id: String, + pub(super) attempt: u32, + pub(super) line: String, +} + +/// Emits one live output event. Boxed rather than holding an `AppHandle` so the +/// reporter is constructible — and assertable — without a Tauri app. +type EmitEvent = Arc; + +/// At most four live-output events per second. Coalescing is by dropping, not +/// buffering: the UI shows only the newest line, so a queued backlog would +/// display stale progress. +const LIVE_LINE_INTERVAL: Duration = Duration::from_millis(250); + +pub(super) struct InstallReporter { + runtime_id: String, + log_path: Option, + emit: Option, + throttle: Arc, +} + +impl InstallReporter { + /// The reporter a real install command uses: it writes the install log and + /// emits live output events through `app`. + /// + /// A log path that cannot be resolved degrades to no log rather than failing + /// the install — a user with a broken app-data directory still needs the + /// install itself to work. + pub(super) fn for_command(app: &tauri::AppHandle, runtime_id: &str) -> Self { + let log_path = crate::managed_agents::storage::install_log_path(app, runtime_id).ok(); + let app = app.clone(); + let emit: EmitEvent = Arc::new(move |event| { + use tauri::Emitter; + let _ = app.emit("acp-install-output", event); + }); + Self::new(runtime_id, log_path, Some(emit)) + } + + pub(super) fn new( + runtime_id: &str, + log_path: Option, + emit: Option, + ) -> Self { + Self { + runtime_id: runtime_id.to_string(), + log_path, + emit, + throttle: Arc::new(Throttle::new(LIVE_LINE_INTERVAL)), + } + } + + /// The log file to point the user at, once something has been written to it. + /// `None` when this install has no log — the failure message then omits the + /// pointer rather than naming a file that does not exist. + pub(super) fn log_path(&self) -> Option { + let path = self.log_path.as_ref()?; + path.exists().then(|| path.display().to_string()) + } + + /// Observer for one attempt's drains, or `None` when nothing is listening. + pub(super) fn line_observer(&self, attempt: u32) -> Option { + let emit = Arc::clone(self.emit.as_ref()?); + let throttle = Arc::clone(&self.throttle); + let runtime_id = self.runtime_id.clone(); + Some(Arc::new(move |line: &str| { + if throttle.allows(Instant::now()) { + emit(InstallOutputEvent { + runtime_id: runtime_id.clone(), + attempt, + line: line.to_string(), + }); + } + })) + } + + /// Record one executed attempt of a step. + pub(super) fn record_attempt(&self, attempt: u32, outcome: &InstallOutcome) { + self.write_record(Some(attempt), outcome); + } + + /// Push a synthesized step onto `steps` and record it. Routing every step + /// through here is what keeps the log complete: a step that reaches the UI + /// without passing this function is invisible in the file. + pub(super) fn record_step(&self, steps: &mut Vec, step: InstallStepResult) { + self.write_record(None, &InstallOutcome::synthesized(step.clone())); + steps.push(step); + } + + /// Append one record. Best-effort by contract: a full disk or a revoked + /// permission degrades the diagnostics, it does not fail the install. + fn write_record(&self, attempt: Option, outcome: &InstallOutcome) { + let Some(path) = self.log_path.as_ref() else { + return; + }; + let record = render_record(attempt, outcome); + if let Ok(mut file) = crate::managed_agents::storage::open_install_log_file(path) { + let _ = file.write_all(record.as_bytes()); + } + } +} + +/// One self-contained record. Each is capped independently by the log-scale +/// capture that produced it, so an early attempt that printed megabytes cannot +/// push a later attempt — or the verification step that explains the failure — +/// out of the file. +fn render_record(attempt: Option, outcome: &InstallOutcome) -> String { + let step = &outcome.step; + let attempt = attempt.map_or_else(|| "-".to_string(), |n| n.to_string()); + let exit = step + .exit_code + .map_or_else(|| "none".to_string(), |code| code.to_string()); + let mut record = format!( + "=== {} step={} attempt={attempt} success={} exit={exit}\n$ {}\n", + chrono::Utc::now().to_rfc3339(), + step.step, + step.success, + redact(&step.command), + ); + for (label, text) in [ + ("stdout", &outcome.log_stdout), + ("stderr", &outcome.log_stderr), + ] { + if !text.trim().is_empty() { + record.push_str(&format!("--- {label} ---\n{}\n", redact(text))); + } + } + if let Some(hint) = &step.hint { + record.push_str(&format!("--- hint ---\n{}\n", redact(hint))); + } + record +} + +/// Scrub known secret shapes before anything reaches disk. Install output can +/// echo a registry token or a signing key from the environment it ran in, and +/// this file is written unattended. +fn redact(text: &str) -> String { + crate::managed_agents::redact_secrets_with(text, &[]) +} + +#[cfg(test)] +#[path = "install_report_tests.rs"] +mod tests; diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs new file mode 100644 index 0000000000..b6ac24ddfa --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -0,0 +1,255 @@ +use super::*; +use crate::commands::agent_discovery::install_capture::{drain_into, Capture}; +use std::sync::Mutex; + +/// A reporter writing to a temp log, with the emitted events captured. +struct Harness { + _dir: tempfile::TempDir, + log: PathBuf, + reporter: InstallReporter, + events: Arc>>, +} + +fn harness() -> Harness { + let dir = tempfile::tempdir().expect("tempdir"); + let log = dir.path().join("install-goose.log"); + let events: Arc>> = Arc::new(Mutex::new(Vec::new())); + let emit: EmitEvent = { + let events = Arc::clone(&events); + Arc::new(move |event| events.lock().unwrap().push(event)) + }; + Harness { + reporter: InstallReporter::new("goose", Some(log.clone()), Some(emit)), + _dir: dir, + log, + events, + } +} + +/// A reporter with no log file and nothing listening — the degraded shape. +fn silent_reporter() -> InstallReporter { + InstallReporter::new("goose", None, None) +} + +fn step(name: &str, success: bool, stderr: &str) -> InstallStepResult { + InstallStepResult { + step: name.to_string(), + command: "curl … | bash".to_string(), + success, + stdout: String::new(), + stderr: stderr.to_string(), + exit_code: Some(if success { 0 } else { 1 }), + hint: None, + } +} + +/// An executed attempt whose log copy differs from the UI copy — the real shape, +/// since the two views are capped differently. +fn outcome(name: &str, success: bool, log_stdout: &str) -> InstallOutcome { + InstallOutcome { + step: step(name, success, ""), + log_stdout: log_stdout.to_string(), + log_stderr: String::new(), + } +} + +impl Harness { + fn log_contents(&self) -> String { + std::fs::read_to_string(&self.log).unwrap_or_default() + } + + fn lines(&self) -> Vec { + self.events + .lock() + .unwrap() + .iter() + .map(|e| e.line.clone()) + .collect() + } +} + +// ── the log records history the UI does not keep ───────────────────────────── + +/// Every attempt is recorded, not just the one the UI surfaces. Reproducing an +/// install failure means seeing whether attempts 1 and 2 failed the same way. +#[test] +fn test_log_records_every_attempt_not_only_the_last() { + let h = harness(); + + h.reporter + .record_attempt(1, &outcome("cli", false, "attempt-one-output")); + h.reporter + .record_attempt(2, &outcome("cli", false, "attempt-two-output")); + + let log = h.log_contents(); + assert!(log.contains("attempt-one-output"), "got: {log}"); + assert!(log.contains("attempt-two-output"), "got: {log}"); + assert!( + log.contains("attempt=1") && log.contains("attempt=2"), + "got: {log}" + ); +} + +/// A first attempt that printed a huge amount must not push later records out of +/// the file. Records are capped individually by the log-scale capture that +/// produced them, so the run's total is bounded by steps × attempts × cap rather +/// than by one runaway attempt. +/// +/// The flood goes through a real [`Capture`] rather than straight into the +/// record, so this exercises the cap that actually bounds a record. +#[test] +fn test_first_attempt_overflow_does_not_erase_later_records() { + let h = harness(); + // Through the real drain, so the record is bounded by the cap that bounds a + // production record rather than by a string this test chose. + let capture = Capture::new(); + drain_into(vec![b'F'; 4 * 1024 * 1024].as_slice(), &capture, None); + + h.reporter + .record_attempt(1, &outcome("cli", false, &capture.log())); + h.reporter + .record_attempt(2, &outcome("cli", false, "second-attempt-detail")); + h.reporter.record_step( + &mut Vec::new(), + step("verify", false, "verification-detail"), + ); + + let log = h.log_contents(); + assert!( + log.contains("bytes omitted at cap"), + "the flooded record must be marked as cut" + ); + assert!( + log.contains("second-attempt-detail"), + "a later attempt must survive an earlier flood" + ); + assert!( + log.contains("verification-detail"), + "the synthesized step explaining the failure must survive too" + ); + assert!( + log.len() < 4 * 1024 * 1024, + "4MiB of first-attempt output must not reach the file, got {} bytes", + log.len() + ); +} + +/// A step Buzz synthesizes — a failed prerequisite, or post-install +/// verification — reaches the log as well as the UI. `record_step` is the only +/// path that guarantees this, which is why callers use it instead of +/// `steps.push`. +#[test] +fn test_recording_a_synthesized_step_logs_it_and_keeps_it_for_the_ui() { + let h = harness(); + let mut steps = Vec::new(); + + h.reporter + .record_step(&mut steps, step("verify", false, "still-not-usable")); + + assert_eq!(steps.len(), 1, "the UI must still receive the step"); + assert!(h.log_contents().contains("still-not-usable")); +} + +/// Secrets that an installer echoed must not land on disk. The log is written +/// unattended, so scrubbing happens at the write, not at the read. +#[test] +fn test_log_redacts_secrets_before_writing() { + let h = harness(); + let leak = "npm ERR! token nsec1qqqqqqqqqqsecretvalue failed"; + + h.reporter.record_attempt(1, &outcome("cli", false, leak)); + + let log = h.log_contents(); + assert!(!log.contains("nsec1qqqqqqqqqqsecretvalue"), "got: {log}"); + assert!(log.contains("[REDACTED]"), "got: {log}"); +} + +/// The log path is surfaced only once something is in the file — a message +/// pointing at a path that does not exist is worse than no pointer. +#[test] +fn test_log_path_is_absent_until_something_is_written() { + let h = harness(); + + assert_eq!(h.reporter.log_path(), None); + + h.reporter.record_attempt(1, &outcome("cli", true, "done")); + + assert_eq!( + h.reporter.log_path(), + Some(h.log.display().to_string()), + "a written log must be surfaced" + ); +} + +/// A reporter with no log — an unresolvable app-data directory — records +/// nothing and reports no path, but must not panic or fail the install. +#[test] +fn test_reporter_without_a_log_records_nothing_and_reports_no_path() { + let reporter = silent_reporter(); + let mut steps = Vec::new(); + + reporter.record_attempt(1, &outcome("cli", false, "output")); + reporter.record_step(&mut steps, step("verify", false, "detail")); + + assert_eq!(reporter.log_path(), None); + assert_eq!(steps.len(), 1, "the UI path is unaffected by a missing log"); +} + +/// A log path inside a directory that no longer exists fails every write. The +/// install still runs; the pointer is simply absent. +#[test] +fn test_write_failure_leaves_the_install_unaffected() { + let reporter = InstallReporter::new( + "goose", + Some(PathBuf::from("/nonexistent-dir-for-test/install-goose.log")), + None, + ); + + reporter.record_attempt(1, &outcome("cli", false, "output")); + + assert_eq!(reporter.log_path(), None); +} + +// ── live output line ───────────────────────────────────────────────────────── + +/// Lines drained during an attempt are emitted with that attempt's number, so +/// the UI can discard a line that belongs to a superseded retry. +#[test] +fn test_emitted_line_carries_its_runtime_and_attempt() { + let h = harness(); + + let observer = h.reporter.line_observer(2).expect("an observer"); + observer("downloading"); + + let events = h.events.lock().unwrap(); + assert_eq!(events.len(), 1); + assert_eq!(events[0].runtime_id, "goose"); + assert_eq!(events[0].attempt, 2); + assert_eq!(events[0].line, "downloading"); +} + +/// The throttle is per install, not per attempt or per stream: a burst across +/// two observers still coalesces, because both share one window. +#[test] +fn test_emission_is_throttled_across_attempts_and_streams() { + let h = harness(); + let first = h.reporter.line_observer(1).expect("an observer"); + let second = h.reporter.line_observer(2).expect("an observer"); + + first("one"); + first("two"); + second("three"); + + assert_eq!( + h.lines(), + vec!["one"], + "a burst inside the window must coalesce to the first line" + ); +} + +/// Nothing listening means no observer at all, so the drain skips line +/// reassembly entirely rather than doing the work and discarding it. +#[test] +fn test_no_observer_when_nothing_is_listening() { + assert!(silent_reporter().line_observer(1).is_none()); +} diff --git a/desktop/src-tauri/src/commands/agent_discovery/post_install_verification.rs b/desktop/src-tauri/src/commands/agent_discovery/post_install_verification.rs index 3155104b56..535d4c9ecb 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/post_install_verification.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/post_install_verification.rs @@ -1,13 +1,19 @@ use crate::managed_agents::{AcpAvailabilityStatus, InstallStepResult}; -pub(super) fn run(runtime_id: &str, steps: &mut Vec) { +use super::install_report::InstallReporter; + +pub(super) fn run( + runtime_id: &str, + steps: &mut Vec, + reporter: &InstallReporter, +) { // Observe PATH changes and binaries added after Buzz launched. crate::managed_agents::refresh_login_shell_path(); crate::managed_agents::clear_resolve_cache(); let availability = crate::managed_agents::discover_acp_runtime_availability(runtime_id); if let Some(failure) = failure(runtime_id, availability) { - steps.push(failure); + reporter.record_step(steps, failure); } } diff --git a/desktop/src-tauri/src/managed_agents/backend.rs b/desktop/src-tauri/src/managed_agents/backend.rs index 2a72af92d7..3f96229404 100644 --- a/desktop/src-tauri/src/managed_agents/backend.rs +++ b/desktop/src-tauri/src/managed_agents/backend.rs @@ -286,7 +286,7 @@ fn redact_secrets(s: &str) -> String { /// (would match every short token in normal log output). Entries are /// applied in decreasing length order so superstrings get scrubbed before /// substrings — protects against partial overlap leaks. -fn redact_secrets_with(s: &str, extras: &[&str]) -> String { +pub(crate) fn redact_secrets_with(s: &str, extras: &[&str]) -> String { let mut result = s.to_string(); // Extras: longest first to avoid partial-overlap leaks. We use diff --git a/desktop/src-tauri/src/managed_agents/storage.rs b/desktop/src-tauri/src/managed_agents/storage.rs index f6f89ed898..0098a153ef 100644 --- a/desktop/src-tauri/src/managed_agents/storage.rs +++ b/desktop/src-tauri/src/managed_agents/storage.rs @@ -52,6 +52,34 @@ fn managed_agents_logs_dir(app: &AppHandle) -> Result { Ok(dir) } +/// Install-log path for `runtime_id`, alongside the agent logs. +pub fn install_log_path(app: &AppHandle, runtime_id: &str) -> Result { + Ok(managed_agents_logs_dir(app)?.join(install_log_filename(runtime_id)?)) +} + +/// Filename for a runtime's install log, or an error for an id that must not +/// become one. +/// +/// The id is validated rather than trusted: ids reach this from user-defined +/// custom harnesses as well as the catalog, and a `../` or a separator in one +/// would place the log outside the logs directory. Rejecting beats sanitizing — +/// a rejected id means no log, while a rewritten one could collide with another +/// runtime's. +fn install_log_filename(runtime_id: &str) -> Result { + if runtime_id.is_empty() || !runtime_id.chars().all(is_safe_id_char) { + return Err(format!( + "unsafe runtime id for a log filename: {runtime_id}" + )); + } + Ok(format!("install-{runtime_id}.log")) +} + +/// Characters allowed in a runtime id used as a filename. Excludes `/`, `\`, +/// `:` and `.`, so no id can traverse or escape the logs directory. +fn is_safe_id_char(c: char) -> bool { + c.is_ascii_alphanumeric() || c == '-' || c == '_' +} + pub fn managed_agent_log_path(app: &AppHandle, pubkey: &str) -> Result { Ok(managed_agents_logs_dir(app)?.join(format!("{pubkey}.log"))) } @@ -632,6 +660,28 @@ pub(crate) fn open_log_file(path: &Path) -> Result { .map_err(|error| format!("failed to open log file {}: {error}", path.display())) } +/// Open an install log for appending, creating it owner-only. +/// +/// The mode is set *in the create* rather than chmod'd afterwards, so the file +/// is never briefly group/world-readable. Install output can carry registry +/// tokens and proxy credentials echoed by a failing installer, so the window +/// matters even though it is short. An existing file's mode is left as-is — +/// `OpenOptions::mode` only applies on creation, and silently re-tightening a +/// file the user relaxed is not this function's call to make. +pub(crate) fn open_install_log_file(path: &Path) -> Result { + maybe_rotate_log(path); + let mut options = OpenOptions::new(); + options.create(true).append(true); + #[cfg(unix)] + { + use std::os::unix::fs::OpenOptionsExt; + options.mode(0o600); + } + options + .open(path) + .map_err(|error| format!("failed to open log file {}: {error}", path.display())) +} + pub(crate) fn append_log_marker(path: &Path, message: &str) -> Result<(), String> { let mut file = open_log_file(path)?; writeln!(file, "{message}").map_err(|error| format!("failed to write log marker: {error}")) diff --git a/desktop/src-tauri/src/managed_agents/storage_tests.rs b/desktop/src-tauri/src/managed_agents/storage_tests.rs index 73567bb915..ab78d0f2ae 100644 --- a/desktop/src-tauri/src/managed_agents/storage_tests.rs +++ b/desktop/src-tauri/src/managed_agents/storage_tests.rs @@ -698,3 +698,100 @@ fn try_delete_agent_key_returns_result() { // team_snapshot::tests::rollback_aggregates_multiple_errors. let _: fn(&str) -> Result<(), String> = super::try_delete_agent_key; } + +// ── install logs ───────────────────────────────────────────────────────────── + +/// Install output can carry registry tokens and proxy credentials a failing +/// installer echoed, and the file is written unattended. `0o600` must come from +/// the create itself: a post-write `chmod` leaves a window where the umask +/// decides, and a crash inside it leaves the log readable to other local users. +#[cfg(unix)] +#[test] +fn install_log_is_created_owner_only_without_post_write_chmod() { + use std::os::unix::fs::PermissionsExt; + + let dir = tempfile::tempdir().expect("temp dir"); + let path = dir.path().join("install-goose.log"); + + let mut file = super::open_install_log_file(&path).expect("open install log"); + file.write_all(b"npm ERR!\n").expect("write"); + + let mode = std::fs::metadata(&path) + .expect("metadata") + .permissions() + .mode() + & 0o777; + assert_eq!(mode, 0o600, "install logs must be owner-only"); +} + +/// Reopening appends rather than truncating — a run's later records must not +/// erase its earlier ones. +#[test] +fn install_log_appends_across_opens() { + let dir = tempfile::tempdir().expect("temp dir"); + let path = dir.path().join("install-goose.log"); + + for record in ["first\n", "second\n"] { + let mut file = super::open_install_log_file(&path).expect("open install log"); + file.write_all(record.as_bytes()).expect("write"); + } + + assert_eq!( + std::fs::read_to_string(&path).expect("read back"), + "first\nsecond\n" + ); +} + +/// An oversized install log rotates to `.1` on the next open, so the file +/// cannot grow without bound across repeated install attempts. +#[test] +fn install_log_rotates_when_oversized() { + let dir = tempfile::tempdir().expect("temp dir"); + let path = dir.path().join("install-goose.log"); + std::fs::write(&path, vec![b'x'; (super::MAX_LOG_FILE_SIZE + 1) as usize]).expect("seed"); + + let mut file = super::open_install_log_file(&path).expect("open install log"); + file.write_all(b"fresh\n").expect("write"); + + assert_eq!( + std::fs::read_to_string(&path).expect("read back"), + "fresh\n", + "the live log must restart after rotation" + ); + let rotated = dir.path().join("install-goose.log.1"); + assert!(rotated.exists(), "the oversized log must be kept as .1"); +} + +/// A runtime id becomes part of a filename. Ids reach this from user-defined +/// custom harnesses as well as the catalog, so anything that could traverse or +/// escape the logs directory is rejected rather than sanitized — a rejected id +/// simply means no log, while a silently rewritten one could collide with +/// another runtime's log. +#[test] +fn install_log_filename_rejects_ids_that_would_escape_the_logs_dir() { + for id in [ + "../../etc/passwd", + "goose/../../evil", + "sub/dir", + "back\\slash", + "with.dot", + "", + ] { + assert!( + super::install_log_filename(id).is_err(), + "id {id:?} must not be accepted as a filename component" + ); + } +} + +/// Ordinary catalog and custom-harness ids are accepted — the guard must not +/// reject the ids it exists to serve. +#[test] +fn install_log_filename_accepts_ordinary_runtime_ids() { + for id in ["goose", "claude-code", "buzz_agent", "codex2"] { + assert_eq!( + super::install_log_filename(id).expect("id must be usable in a log filename"), + format!("install-{id}.log") + ); + } +} diff --git a/desktop/src-tauri/src/managed_agents/types.rs b/desktop/src-tauri/src/managed_agents/types.rs index 7528d4f384..fcd8b13fc9 100644 --- a/desktop/src-tauri/src/managed_agents/types.rs +++ b/desktop/src-tauri/src/managed_agents/types.rs @@ -702,6 +702,10 @@ pub struct InstallRuntimeResult { /// Number of agents whose stop succeeded but respawn failed. /// Mirrors `GlobalAgentConfigSaveResult.failed_restart_count`. pub failed_restart_count: u32, + /// Install log file for this run, when one was written. The UI surfaces it + /// on failure so a user can read the full retry history instead of only the + /// last step's truncated output. `None` when no log could be opened. + pub log_path: Option, } #[derive(Debug, Clone, Serialize)] diff --git a/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs b/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs new file mode 100644 index 0000000000..a45e6dd5ba --- /dev/null +++ b/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs @@ -0,0 +1,58 @@ +import assert from "node:assert/strict"; +import test from "node:test"; + +import { nextInstallOutputLine } from "./useInstallOutputLine.ts"; + +function event(runtimeId, attempt, line) { + return { runtime_id: runtimeId, attempt, line }; +} + +test("nextInstallOutputLine: adopts the first line for the watched runtime", () => { + assert.deepEqual( + nextInstallOutputLine(null, event("goose", 1, "downloading"), "goose"), + { attempt: 1, line: "downloading" }, + ); +}); + +test("nextInstallOutputLine: replaces the line within the same attempt", () => { + const current = { attempt: 1, line: "downloading" }; + + assert.deepEqual( + nextInstallOutputLine(current, event("goose", 1, "unpacking"), "goose"), + { attempt: 1, line: "unpacking" }, + ); +}); + +test("nextInstallOutputLine: ignores a line from another runtime", () => { + const current = { attempt: 1, line: "downloading" }; + + assert.equal( + nextInstallOutputLine(current, event("codex", 1, "other work"), "goose"), + current, + ); +}); + +test("nextInstallOutputLine: ignores a line from a superseded attempt", () => { + const current = { attempt: 2, line: "retrying" }; + + assert.equal( + nextInstallOutputLine(current, event("goose", 1, "stale line"), "goose"), + current, + ); +}); + +test("nextInstallOutputLine: adopts the first line of a new attempt", () => { + const current = { attempt: 1, line: "download failed" }; + + assert.deepEqual( + nextInstallOutputLine(current, event("goose", 2, "downloading"), "goose"), + { attempt: 2, line: "downloading" }, + ); +}); + +test("nextInstallOutputLine: a first event from a later attempt is adopted", () => { + assert.deepEqual( + nextInstallOutputLine(null, event("goose", 3, "downloading"), "goose"), + { attempt: 3, line: "downloading" }, + ); +}); diff --git a/desktop/src/features/agents/lib/useInstallOutputLine.ts b/desktop/src/features/agents/lib/useInstallOutputLine.ts new file mode 100644 index 0000000000..f486b6864b --- /dev/null +++ b/desktop/src/features/agents/lib/useInstallOutputLine.ts @@ -0,0 +1,87 @@ +import * as React from "react"; +import { listen } from "@tauri-apps/api/event"; + +/** Mirror of the Rust `InstallOutputEvent` payload (install_report.rs). */ +export type InstallOutputEvent = { + runtime_id: string; + attempt: number; + line: string; +}; + +/** The line being shown, and which attempt produced it. */ +export type InstallOutputState = { + attempt: number; + line: string; +}; + +/** + * Fold one event into the displayed line. + * + * Events from another runtime are ignored — every install card listens to the + * same channel. So is an event from a superseded attempt: install retries with + * backoff, and a line emitted just as attempt 2 starts would otherwise sit + * under the spinner while attempt 2 runs, showing the user the failure they + * already had instead of current progress. + */ +export function nextInstallOutputLine( + current: InstallOutputState | null, + event: InstallOutputEvent, + runtimeId: string, +): InstallOutputState | null { + if (event.runtime_id !== runtimeId) return current; + if (current && event.attempt < current.attempt) return current; + return { attempt: event.attempt, line: event.line }; +} + +/** + * The install command's most recent output line for `runtimeId`, or null when + * nothing has been printed yet. + * + * An install runs for up to 15 minutes with no other feedback than a spinner; + * this turns that wait into observable progress. The backend throttles + * emission, so this re-renders a few times a second at most. + * + * Pass `isInstalling` so the line clears when the install settles — a finished + * install must not leave its last line under a fresh Install button. + */ +export function useInstallOutputLine( + runtimeId: string, + isInstalling: boolean, +): string | null { + const [state, setState] = React.useState(null); + + React.useEffect(() => { + if (!isInstalling) { + setState(null); + return; + } + let cancelled = false; + let unlisten: (() => void) | null = null; + (async () => { + try { + const stop = await listen( + "acp-install-output", + (event) => { + if (cancelled) return; + setState((current) => + nextInstallOutputLine(current, event.payload, runtimeId), + ); + }, + ); + if (cancelled) { + stop(); + } else { + unlisten = stop; + } + } catch { + // Event system unavailable (web/e2e) — the spinner shows alone. + } + })(); + return () => { + cancelled = true; + unlisten?.(); + }; + }, [isInstalling, runtimeId]); + + return state?.line ?? null; +} diff --git a/desktop/src/features/onboarding/ui/SetupStep.tsx b/desktop/src/features/onboarding/ui/SetupStep.tsx index 843206aa70..431c9b2f51 100644 --- a/desktop/src/features/onboarding/ui/SetupStep.tsx +++ b/desktop/src/features/onboarding/ui/SetupStep.tsx @@ -8,6 +8,7 @@ import { useConnectAcpRuntimeMutation, useInstallAcpRuntimeMutation, } from "@/features/agents/hooks"; +import { useInstallOutputLine } from "@/features/agents/lib/useInstallOutputLine"; import { describeResolvedCommand } from "@/features/agents/ui/agentUi"; import type { AcpAuthMethod, AcpRuntimeCatalogEntry } from "@/shared/api/types"; import { getInstallErrorMessage } from "@/shared/lib/installError"; @@ -483,6 +484,7 @@ function RuntimeCard({ const installMutation = useInstallAcpRuntimeMutation(); const installError = installResults[runtime.id]?.error ?? null; const isInstalling = installMutation.isPending; + const installOutputLine = useInstallOutputLine(runtime.id, isInstalling); const isAvailable = runtime.availability === "available"; const isReady = runtimeIsReadyForOnboarding(runtime); @@ -499,7 +501,7 @@ function RuntimeCard({ [runtime.id]: result.success ? { error: null, success: true } : { - error: getInstallErrorMessage(result.steps), + error: getInstallErrorMessage(result), success: false, }, })); @@ -542,7 +544,18 @@ function RuntimeCard({ onInstall={handleInstall} runtime={runtime} /> - {!isAvailable && runtimeDetailText(runtime) ? ( + {isInstalling && installOutputLine ? ( + // Takes the detail text's slot rather than adding a row: the card is + // fixed-height, and during an install the live line is the more + // useful of the two. +

+ {installOutputLine} +

+ ) : !isAvailable && runtimeDetailText(runtime) ? (

{ if (!result.success) { - setInstallError(getInstallErrorMessage(result.steps)); + setInstallError(getInstallErrorMessage(result)); } }, onError: (error) => { @@ -502,6 +504,16 @@ function CatalogDetail({ entry }: { entry: AcpRuntimeCatalogEntry }) { ) : null} + {install.isPending && installOutputLine ? ( +

+ {installOutputLine} +

+ ) : null} + {installError ? (

{installError} diff --git a/desktop/src/features/settings/ui/HarnessRow.tsx b/desktop/src/features/settings/ui/HarnessRow.tsx index de6666b8c3..c0feef13cc 100644 --- a/desktop/src/features/settings/ui/HarnessRow.tsx +++ b/desktop/src/features/settings/ui/HarnessRow.tsx @@ -10,6 +10,7 @@ import { useManagedAgentsQuery, usePersonasQuery, } from "@/features/agents/hooks"; +import { useInstallOutputLine } from "@/features/agents/lib/useInstallOutputLine"; import { RuntimeIcon } from "@/features/onboarding/ui/RuntimeIcon"; import type { AcpAuthMethod, AcpRuntimeCatalogEntry } from "@/shared/api/types"; import { getInstallErrorMessage } from "@/shared/lib/installError"; @@ -324,6 +325,7 @@ export function HarnessRow({ }, [resetEpoch]); const isInstalling = installMutation.isPending; const installError = installResult?.error ?? null; + const installOutputLine = useInstallOutputLine(runtime.id, isInstalling); const del = useDeleteCustomHarnessMutation(); // Blast-radius data for the delete confirmation — only fetched while the @@ -348,7 +350,7 @@ export function HarnessRow({ } else { setInstallResult({ success: false, - error: getInstallErrorMessage(result.steps), + error: getInstallErrorMessage(result), }); } }, @@ -479,6 +481,15 @@ export function HarnessRow({

) : null} + {isInstalling && installOutputLine ? ( +

+ {installOutputLine} +

+ ) : null} {installError ? (

{ - assert.equal(getInstallErrorMessage([]), "Install failed with no output."); + assert.equal( + getInstallErrorMessage(failed([])), + "Install failed with no output.", + ); }); test("getInstallErrorMessage: failed step without hint contains step name and stderr", () => { - const message = getInstallErrorMessage([ - { - step: "adapter", - command: "npm install -g @block/buzz-acp", - success: false, - stdout: "", - stderr: "EACCES: permission denied", - exitCode: 1, - }, - ]); + const message = getInstallErrorMessage( + failed([ + { + step: "adapter", + command: "npm install -g @block/buzz-acp", + success: false, + stdout: "", + stderr: "EACCES: permission denied", + exitCode: 1, + }, + ]), + ); assert.match(message, /Step "adapter" failed:/); assert.match(message, /EACCES: permission denied/); }); test("getInstallErrorMessage: failed step without hint does not contain hint-ish text", () => { - const message = getInstallErrorMessage([ - { - step: "adapter", - command: "npm install -g @block/buzz-acp", - success: false, - stdout: "", - stderr: "EACCES: permission denied", - exitCode: 1, - }, - ]); + const message = getInstallErrorMessage( + failed([ + { + step: "adapter", + command: "npm install -g @block/buzz-acp", + success: false, + stdout: "", + stderr: "EACCES: permission denied", + exitCode: 1, + }, + ]), + ); assert.doesNotMatch(message, /npm config set prefix/); }); test("getInstallErrorMessage: failed step with hint starts with hint and still contains stderr", () => { const hint = "Fix the npm prefix ownership:\n sudo chown -R $USER $(npm config get prefix)"; - const message = getInstallErrorMessage([ - { - step: "adapter", - command: "npm install -g @block/buzz-acp", - success: false, - stdout: "", - stderr: "EACCES: permission denied, mkdir '/usr/local/lib'", - exitCode: 1, - hint, - }, - ]); + const message = getInstallErrorMessage( + failed([ + { + step: "adapter", + command: "npm install -g @block/buzz-acp", + success: false, + stdout: "", + stderr: "EACCES: permission denied, mkdir '/usr/local/lib'", + exitCode: 1, + hint, + }, + ]), + ); assert.ok(message.startsWith(hint), "message should start with hint"); assert.match(message, /EACCES: permission denied/); }); test("getInstallErrorMessage: failed step with empty stderr falls back to stdout", () => { - const message = getInstallErrorMessage([ - { - step: "node", - command: "node --version", - success: false, - stdout: "some stdout output", - stderr: "", - exitCode: 1, - }, - ]); + const message = getInstallErrorMessage( + failed([ + { + step: "node", + command: "node --version", + success: false, + stdout: "some stdout output", + stderr: "", + exitCode: 1, + }, + ]), + ); assert.match(message, /some stdout output/); }); test("getInstallErrorMessage: hint and step detail are separated by double newline for whitespace-pre-line rendering", () => { const hint = "Git Bash is required. Install it from git-scm.com."; - const message = getInstallErrorMessage([ - { - step: "shell", - command: "bash -l -c 'npm install'", - success: false, - stdout: "", - stderr: "bash: command not found", - exitCode: 127, - hint, - }, - ]); + const message = getInstallErrorMessage( + failed([ + { + step: "shell", + command: "bash -l -c 'npm install'", + success: false, + stdout: "", + stderr: "bash: command not found", + exitCode: 127, + hint, + }, + ]), + ); assert.ok( message.includes("\n\n"), "hint and step detail should be separated by a blank line", @@ -89,25 +113,72 @@ test("getInstallErrorMessage: hint and step detail are separated by double newli }); test("getInstallErrorMessage: only reports the last (failing) step when multiple steps present", () => { - const message = getInstallErrorMessage([ - { - step: "node", - command: "node --version", - success: true, - stdout: "v20.0.0", - stderr: "", - exitCode: 0, - }, - { - step: "adapter", - command: "npm install -g @agentclientprotocol/claude-code-acp", - success: false, - stdout: "", - stderr: "npm ERR! code E404", - exitCode: 1, - }, - ]); + const message = getInstallErrorMessage( + failed([ + { + step: "node", + command: "node --version", + success: true, + stdout: "v20.0.0", + stderr: "", + exitCode: 0, + }, + { + step: "adapter", + command: "npm install -g @agentclientprotocol/claude-code-acp", + success: false, + stdout: "", + stderr: "npm ERR! code E404", + exitCode: 1, + }, + ]), + ); assert.match(message, /Step "adapter" failed:/); assert.match(message, /npm ERR! code E404/); assert.doesNotMatch(message, /Step "node"/); }); + +test("getInstallErrorMessage: points at the install log when one was written", () => { + const message = getInstallErrorMessage( + failed( + [ + { + step: "cli", + command: "curl … | bash", + success: false, + stdout: "", + stderr: "download failed", + exitCode: 1, + }, + ], + "/logs/install-goose.log", + ), + ); + assert.match(message, /download failed/); + assert.ok( + message.endsWith("\n\nFull log: /logs/install-goose.log"), + `log pointer should close the message, got: ${message}`, + ); +}); + +test("getInstallErrorMessage: omits the log pointer when no log was written", () => { + const message = getInstallErrorMessage( + failed([ + { + step: "cli", + command: "curl … | bash", + success: false, + stdout: "", + stderr: "download failed", + exitCode: 1, + }, + ]), + ); + assert.doesNotMatch(message, /Full log/); +}); + +test("getInstallErrorMessage: a run with no steps at all still points at its log", () => { + const message = getInstallErrorMessage(failed([], "/logs/install-goose.log")); + assert.match(message, /Install failed with no output\./); + assert.match(message, /Full log: \/logs\/install-goose\.log/); +}); diff --git a/desktop/src/shared/lib/installError.ts b/desktop/src/shared/lib/installError.ts index bf72c4d3b2..d154714b1a 100644 --- a/desktop/src/shared/lib/installError.ts +++ b/desktop/src/shared/lib/installError.ts @@ -1,15 +1,25 @@ -import type { InstallStepResult } from "@/shared/api/types"; +import type { InstallRuntimeResult } from "@/shared/api/types"; /** * Build the user-visible error message for a failed install. * When the last step carries an actionable hint, it is shown first, * followed by the raw step failure detail. + * + * The step detail is truncated for display, so the message ends with a pointer + * to the install log — which holds every attempt of every step in full — when + * one was written. */ -export function getInstallErrorMessage(steps: InstallStepResult[]): string { +export function getInstallErrorMessage(result: InstallRuntimeResult): string { + const { steps, logPath } = result; const lastStep = steps[steps.length - 1]; if (!lastStep) { - return "Install failed with no output."; + return withLog("Install failed with no output.", logPath); } const base = `Step "${lastStep.step}" failed: ${lastStep.stderr || lastStep.stdout || "unknown error"}`; - return lastStep.hint ? `${lastStep.hint}\n\n${base}` : base; + const detail = lastStep.hint ? `${lastStep.hint}\n\n${base}` : base; + return withLog(detail, logPath); +} + +function withLog(message: string, logPath: string | null): string { + return logPath ? `${message}\n\nFull log: ${logPath}` : message; } diff --git a/desktop/src/testing/e2eBridge.ts b/desktop/src/testing/e2eBridge.ts index 4cfc553df1..ac37dcb840 100644 --- a/desktop/src/testing/e2eBridge.ts +++ b/desktop/src/testing/e2eBridge.ts @@ -7264,6 +7264,7 @@ async function handleInstallAcpRuntime( ], restarted_count: 0, failed_restart_count: 0, + log_path: null, }; } diff --git a/desktop/tests/helpers/bridge.ts b/desktop/tests/helpers/bridge.ts index ca4d62ddd6..d5eee0dae3 100644 --- a/desktop/tests/helpers/bridge.ts +++ b/desktop/tests/helpers/bridge.ts @@ -131,6 +131,22 @@ export type MockAgentMemoryListing = { fetchedAt: number; }; +/** Result returned by the `install_acp_runtime` mock command. */ +type MockInstallRuntimeResult = { + success: boolean; + steps: { + step: string; + command: string; + success: boolean; + stdout: string; + stderr: string; + exit_code: number | null; + hint?: string; + }[]; + /** Install log the failure message points at. Omitted = no log was written. */ + log_path?: string | null; +}; + type MockBridgeOptions = { /** Advertised HEAD for the first mock project without adding that branch. */ projectHeadBranch?: string; @@ -173,33 +189,11 @@ type MockBridgeOptions = { installAcpRuntimeDelayMs?: number; /** Override the result returned by the `install_acp_runtime` mock command. * Pass `{ success: false, steps: [...] }` to exercise error/Retry states. */ - installAcpRuntimeResult?: { - success: boolean; - steps: { - step: string; - command: string; - success: boolean; - stdout: string; - stderr: string; - exit_code: number | null; - hint?: string; - }[]; - }; + installAcpRuntimeResult?: MockInstallRuntimeResult; /** Sequence of results for successive `install_acp_runtime` calls. Call N * returns results[N]; when exhausted the last entry repeats. Takes precedence * over `installAcpRuntimeResult`. Use for fail-then-succeed Retry tests. */ - installAcpRuntimeResults?: Array<{ - success: boolean; - steps: { - step: string; - command: string; - success: boolean; - stdout: string; - stderr: string; - exit_code: number | null; - hint?: string; - }[]; - }>; + installAcpRuntimeResults?: MockInstallRuntimeResult[]; activePersonaIds?: string[]; /** * Listing returned by the mocked `get_agent_memory` command. Pass a single From 832098256981cc24578438762a5018d5551c815d Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Tue, 28 Jul 2026 20:08:55 -0400 Subject: [PATCH 3/9] fix(desktop): bound the install settle and key live output by install seq MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The ceiling only bounded the child's exit: the drain joins ran after it, so a descendant that outlived a normally-exited install shell held the output pipes — and the per-runtime install guard behind them — open with no bound at all. Exit and drains now fold into one resumable settle under a single deadline, and the deadline path terminates the process group on the normal-exit branch too, so the guard cannot stick either way. Live output was keyed on the per-step attempt number, which restarts at 1 for every step, so one step succeeding on attempt 2 froze the display for the rest of the install. The key is now a sequence monotonic across the whole install, paired with an unthrottled clear signal at each attempt start; the throttle retains the newest pending line and flushes it rather than dropping the first line of a new attempt. Log redaction matched only known secret prefixes, so a value with no recognisable shape survived; it now redacts by env variable name, snapshotted for the run. Install result types move to `installTypes.ts` so `tauri.ts` and `types.ts`, both already over the size cap, do not have to grow to carry them. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../src-tauri/src/commands/agent_discovery.rs | 47 +-- .../agent_discovery/install_capture.rs | 100 +++++- .../agent_discovery/install_capture_tests.rs | 202 ++++++++++- .../commands/agent_discovery/install_exec.rs | 324 ++++++++++++------ .../agent_discovery/install_report.rs | 317 +++++++++++++---- .../agent_discovery/install_report_tests.rs | 272 ++++++++++++--- .../src-tauri/src/managed_agents/storage.rs | 42 ++- .../src/managed_agents/storage_tests.rs | 73 +++- .../agents/lib/useInstallOutputLine.test.mjs | 64 ++-- .../agents/lib/useInstallOutputLine.ts | 32 +- desktop/src/shared/api/installTypes.ts | 67 ++++ desktop/src/shared/api/tauri.ts | 46 +-- desktop/src/shared/api/types.ts | 27 +- desktop/src/shared/lib/installError.ts | 4 +- desktop/src/testing/e2eBridge.ts | 41 +++ desktop/tests/e2e/doctor-states.spec.ts | 72 ++++ desktop/tests/helpers/bridge.ts | 4 + 17 files changed, 1346 insertions(+), 388 deletions(-) create mode 100644 desktop/src/shared/api/installTypes.ts diff --git a/desktop/src-tauri/src/commands/agent_discovery.rs b/desktop/src-tauri/src/commands/agent_discovery.rs index 90bc79596c..cbbf4ce351 100644 --- a/desktop/src-tauri/src/commands/agent_discovery.rs +++ b/desktop/src-tauri/src/commands/agent_discovery.rs @@ -4,8 +4,8 @@ use crate::{ app_state::AppState, managed_agents::{ command_availability, is_npm_global_install, AcpRuntimeCatalogEntry, - DiscoverManagedAgentPrereqsRequest, InstallRuntimeResult, InstallStepResult, - ManagedAgentPrereqsInfo, RelayAgentInfo, DEFAULT_ACP_COMMAND, + DiscoverManagedAgentPrereqsRequest, InstallRuntimeResult, ManagedAgentPrereqsInfo, + RelayAgentInfo, DEFAULT_ACP_COMMAND, }, nostr_convert, relay::query_relay, @@ -235,10 +235,10 @@ pub async fn install_acp_runtime( // active_installs guard is dropped when install_acp_runtime_blocking // returns (Guard impl Drop) — so Phase 2's restart path runs outside // the guard and cannot re-enter the mutex. - let reporter = InstallReporter::for_command(&app, &runtime_id); let runtime_id_clone = runtime_id.clone(); + let app_clone = app.clone(); let install_result = tokio::task::spawn_blocking(move || { - install_acp_runtime_blocking(&runtime_id_clone, &reporter) + install_acp_runtime_blocking(&runtime_id_clone, &app_clone) }) .await .map_err(|e| format!("install task panicked: {e}"))??; @@ -267,9 +267,14 @@ pub async fn install_acp_runtime( /// Err(_) = infrastructure failure (panic, concurrency guard). /// Ok({success: false}) = an install step failed (stderr captured in steps). +/// +/// The reporter is built here rather than by the caller so this run's log +/// session starts only once the concurrency guard is held and the runtime id is +/// resolved to its canonical catalog form: a rejected install must not rotate a +/// running one's log, and the log filename is derived from that id. fn install_acp_runtime_blocking( runtime_id: &str, - reporter: &InstallReporter, + app: &tauri::AppHandle, ) -> Result { // Re-fetch the login-shell PATH so a Node.js installation that happened // after app launch (or after a previous failed install) is visible to this @@ -303,6 +308,8 @@ fn install_acp_runtime_blocking( let runtime = crate::managed_agents::known_acp_runtime_exact(runtime_id) .ok_or_else(|| format!("unknown runtime: {runtime_id}"))?; + let reporter = InstallReporter::for_run(app, runtime.id); + let mut steps = Vec::new(); // Phase 1: Install CLI if missing and commands are available. @@ -312,11 +319,11 @@ fn install_acp_runtime_blocking( if let Some(cli) = runtime.underlying_cli { if crate::managed_agents::resolve_command(cli).is_none() { for cmd in runtime.cli_install_commands_for_os() { - let result = run_install_command_with_retry("cli", cmd, reporter); + let result = run_install_command_with_retry("cli", cmd, &reporter); let success = result.success; steps.push(result); if !success { - return Ok(failed_install(steps, reporter)); + return Ok(reporter.failed(steps)); } } } @@ -342,7 +349,7 @@ fn install_acp_runtime_blocking( if use_managed_npm { if let Err(step) = ensure_managed_node_runtime_blocking() { reporter.record_step(&mut steps, *step); - return Ok(failed_install(steps, reporter)); + return Ok(reporter.failed(steps)); } } @@ -356,23 +363,23 @@ fn install_acp_runtime_blocking( Ok(None) => cmd.to_string(), Err(step) => { reporter.record_step(&mut steps, *step); - return Ok(failed_install(steps, reporter)); + return Ok(reporter.failed(steps)); } }; - let mut result = run_install_command_with_retry("adapter", &planned, reporter); + let mut result = run_install_command_with_retry("adapter", &planned, &reporter); if !result.success && result.hint.is_none() && is_npm_global_install(cmd) { result.hint = npm_eacces_hint(&result.stderr, cmd); } let success = result.success; steps.push(result); if !success { - return Ok(failed_install(steps, reporter)); + return Ok(reporter.failed(steps)); } } } - post_install_verification::run(runtime_id, &mut steps, reporter); + post_install_verification::run(runtime_id, &mut steps, &reporter); Ok(InstallRuntimeResult { success: steps.iter().all(|step| step.success), @@ -383,22 +390,6 @@ fn install_acp_runtime_blocking( }) } -/// A failed install, carrying the steps recorded so far and the log holding -/// their full history. Every early return in the install builds its result -/// here, so none can forget the log pointer the failure message needs. -fn failed_install( - steps: Vec, - reporter: &InstallReporter, -) -> InstallRuntimeResult { - InstallRuntimeResult { - success: false, - steps, - restarted_count: 0, - failed_restart_count: 0, - log_path: reporter.log_path(), - } -} - // ── Post-install auto-restart (Phase 2 of install_acp_runtime) ─────────────── // // After a successful adapter install, restart any local agents that: diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs b/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs index 4a212c7ee1..903b68715a 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs @@ -84,10 +84,11 @@ impl BoundedOutput { return decode(&whole); } // Both ends are cut at arbitrary byte offsets, so trim any partial - // character rather than emitting replacement chars. The marker counts - // every dropped byte, including those trims. - let head = utf8_prefix(&self.head); - let tail = utf8_suffix(&tail); + // character rather than emitting replacement chars, then drop the + // partial *token* each cut left behind. The marker counts every dropped + // byte, including both trims. + let head = erode_head(utf8_prefix(&self.head)); + let tail = erode_tail(utf8_suffix(&tail)); let omitted = self.total - head.len() - tail.len(); format!( "{}\n{}\n{}", @@ -192,30 +193,64 @@ impl LineSplitter { } /// Rate limiter for the live output line: at most one event per -/// `min_interval`. Lines arriving inside the window are dropped rather than -/// buffered — the UI shows the latest line, so a stale backlog has no value. +/// `min_interval`. +/// +/// A line arriving inside the window is *held* rather than dropped, and the +/// newest held line replaces any older one. Dropping was wrong at two points: +/// the last line of an attempt — typically the failure that caused the retry — +/// vanished if it landed inside the window, and so did a new attempt's first +/// line when it arrived within 250ms of the previous attempt's last. pub(super) struct Throttle { min_interval: Duration, - last: Mutex>, + state: Mutex, +} + +#[derive(Default)] +struct ThrottleState { + last_emitted: Option, + pending: Option, } impl Throttle { pub(super) fn new(min_interval: Duration) -> Self { Self { min_interval, - last: Mutex::new(None), + state: Mutex::new(ThrottleState::default()), } } - pub(super) fn allows(&self, now: Instant) -> bool { - let Ok(mut last) = self.last.lock() else { - return false; + /// Offer one line. `Some` means emit it now; `None` means it is held as the + /// newest pending line, to be emitted by [`Throttle::take_pending`] or + /// replaced by a line that supersedes it. + pub(super) fn offer(&self, line: &str, now: Instant) -> Option { + let Ok(mut state) = self.state.lock() else { + return None; }; - if last.is_some_and(|prev| now.duration_since(prev) < self.min_interval) { - return false; + if state + .last_emitted + .is_some_and(|prev| now.duration_since(prev) < self.min_interval) + { + state.pending = Some(line.to_string()); + return None; + } + state.last_emitted = Some(now); + // Emitting a newer line makes the held one obsolete: the display shows + // one line, and it must be the latest. + state.pending = None; + Some(line.to_string()) + } + + /// Take the held line, if the window closed on one. + pub(super) fn take_pending(&self) -> Option { + self.state.lock().ok()?.pending.take() + } + + /// Open the window for a new attempt, so its first line is emitted + /// immediately instead of waiting out the previous attempt's window. + pub(super) fn restart(&self) { + if let Ok(mut state) = self.state.lock() { + *state = ThrottleState::default(); } - *last = Some(now); - true } } @@ -244,6 +279,41 @@ fn utf8_suffix(bytes: &[u8]) -> &[u8] { &bytes[start..] } +/// How far a cut edge looks for a token boundary. Sized past any credential +/// shape worth protecting (an `nsec1` key is 63 bytes, registry tokens are +/// shorter) and short enough that erosion costs a token rather than a chunk of +/// output. A cut inside a longer whitespace-free run is left alone: erasing +/// kilobytes of a single-token stream would cost more diagnostics than the +/// fragment could leak. +const MAX_ERODED_TOKEN: usize = 256; + +/// Drop the partial token a head cut left at its end. +/// +/// Redaction runs on the rendered text and matches whole tokens: a prefixed +/// secret up to the next whitespace, or an exact env value. A cut through the +/// middle of a secret leaves a fragment that matches neither and therefore +/// survives scrubbing, so the fragment is removed here instead — at the cut, +/// where it is still identifiable as partial. The omitted-byte marker counts +/// what this drops. +fn erode_head(bytes: &[u8]) -> &[u8] { + let window = bytes.len().saturating_sub(MAX_ERODED_TOKEN); + match bytes[window..].iter().rposition(u8::is_ascii_whitespace) { + Some(last) => &bytes[..=window + last], + None => bytes, + } +} + +/// Drop the partial token a tail cut left at its start — the direction that +/// matters most, since a fragment there has lost the `nsec1`-style prefix the +/// scrubber keys on. See [`erode_head`]. +fn erode_tail(bytes: &[u8]) -> &[u8] { + let window = MAX_ERODED_TOKEN.min(bytes.len()); + match bytes[..window].iter().position(u8::is_ascii_whitespace) { + Some(first) => &bytes[first..], + None => bytes, + } +} + #[cfg(test)] #[path = "install_capture_tests.rs"] mod tests; diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs index f9ed4b89e0..8830f355df 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs @@ -229,41 +229,209 @@ fn test_drain_captures_without_an_observer() { // ── throttle ───────────────────────────────────────────────────────────────── -/// The first line always goes out, and a second inside the window is dropped -/// rather than queued: the UI wants the newest line, not a replay. +/// The first line goes out immediately, and one arriving inside the window is +/// *held* rather than dropped: it becomes the pending line, so the newest output +/// survives the rate limit instead of vanishing. #[test] -fn test_throttle_allows_the_first_line_and_drops_the_next_in_window() { +fn test_throttle_emits_the_first_line_and_holds_the_next_in_window() { let throttle = Throttle::new(Duration::from_millis(250)); let start = Instant::now(); - assert!(throttle.allows(start)); - assert!(!throttle.allows(start + Duration::from_millis(100))); + assert_eq!(throttle.offer("first", start), Some("first".to_string())); + assert_eq!( + throttle.offer("second", start + Duration::from_millis(100)), + None + ); + assert_eq!( + throttle.take_pending(), + Some("second".to_string()), + "the line inside the window must be retained, not dropped" + ); +} + +/// A burst inside one window collapses to its newest line: the display shows a +/// single line, so an older held line has no value once a newer one exists. +#[test] +fn test_throttle_keeps_only_the_newest_held_line() { + let throttle = Throttle::new(Duration::from_millis(250)); + let start = Instant::now(); + throttle.offer("emitted", start); + + throttle.offer("held-then-superseded", start + Duration::from_millis(50)); + throttle.offer("newest", start + Duration::from_millis(100)); + + assert_eq!(throttle.take_pending(), Some("newest".to_string())); } -/// Once the window passes, emission resumes — a long install keeps showing -/// progress. +/// Once the window passes, emission resumes and nothing is left pending — the +/// emitted line *is* the newest, so holding it too would emit it twice. #[test] -fn test_throttle_allows_again_after_the_window() { +fn test_throttle_emits_again_after_the_window_and_clears_the_held_line() { let throttle = Throttle::new(Duration::from_millis(250)); let start = Instant::now(); + throttle.offer("first", start); + throttle.offer("held", start + Duration::from_millis(50)); - assert!(throttle.allows(start)); + assert_eq!( + throttle.offer("later", start + Duration::from_millis(300)), + Some("later".to_string()) + ); - assert!(throttle.allows(start + Duration::from_millis(300))); + assert_eq!( + throttle.take_pending(), + None, + "a line emitted after the window supersedes the held one" + ); } -/// The window is measured from the last *emitted* line, not the last attempt: -/// a stream of dropped lines must not extend the silence. +/// The window is measured from the last *emitted* line, not the last offer: a +/// stream of held lines must not extend the silence. #[test] fn test_throttle_window_runs_from_the_last_emission() { let throttle = Throttle::new(Duration::from_millis(250)); let start = Instant::now(); - assert!(throttle.allows(start)); + throttle.offer("first", start); - assert!(!throttle.allows(start + Duration::from_millis(200))); + assert_eq!( + throttle.offer("held", start + Duration::from_millis(200)), + None + ); - assert!( - throttle.allows(start + Duration::from_millis(260)), - "a dropped line must not restart the window" + assert_eq!( + throttle.offer("next", start + Duration::from_millis(260)), + Some("next".to_string()), + "a held line must not restart the window" + ); +} + +/// A pending line is taken once. Taking it twice would re-emit a line the +/// display already shows. +#[test] +fn test_throttle_yields_a_held_line_only_once() { + let throttle = Throttle::new(Duration::from_millis(250)); + let start = Instant::now(); + throttle.offer("first", start); + throttle.offer("held", start + Duration::from_millis(50)); + + assert_eq!(throttle.take_pending(), Some("held".to_string())); + + assert_eq!(throttle.take_pending(), None); +} + +/// Restarting opens the window immediately, which is what lets a new attempt's +/// first line go out even when it arrives inside the previous attempt's window. +/// It also discards a held line: that line belongs to the attempt that just +/// ended, and the new attempt is about to clear the display. +#[test] +fn test_throttle_restart_opens_the_window_and_discards_the_held_line() { + let throttle = Throttle::new(Duration::from_millis(250)); + let start = Instant::now(); + throttle.offer("previous attempt", start); + throttle.offer("held", start + Duration::from_millis(10)); + + throttle.restart(); + + assert_eq!(throttle.take_pending(), None); + assert_eq!( + throttle.offer("new attempt", start + Duration::from_millis(20)), + Some("new attempt".to_string()) + ); +} + +// ── cut-edge erosion ───────────────────────────────────────────────────────── + +/// A secret cut in half by the head cap must not survive as a fragment. +/// Redaction matches whole tokens — a prefixed secret up to the next whitespace +/// — so `nsec1qqq…` cut mid-value would still be scrubbed, but the *tail* of +/// that same value, having lost its prefix, would not be. Both cut edges drop +/// their partial token for that reason. +#[test] +fn test_capture_drops_the_partial_token_at_each_cut_edge() { + // Positioned so the head cap lands inside the first secret and the tail cap + // inside the second. + let head_secret = "nsec1headsecretvalue"; + let tail_secret = "nsec1tailsecretvalue"; + let input = format!( + "{} {head_secret} {} {tail_secret} {}", + "h".repeat(500), + "m".repeat(4000), + "t".repeat(1010) + ); + + let out = ui(&[input.as_bytes()]); + + assert!(out.contains("bytes omitted"), "input must exceed the cap"); + for fragment in ["nsec1head", "secretvalue"] { + assert!( + !out.contains(fragment), + "a fragment of a cut token must not survive: {out}" + ); + } +} + +/// Erosion stops at the nearest whitespace, so it costs one partial token and +/// not the surrounding output — the head's earlier lines and the tail's later +/// ones are what make a truncated capture readable. +#[test] +fn test_capture_erosion_keeps_the_complete_tokens_around_the_cut() { + let input = format!( + "opening line +{} +cut-here-head{}cut-here-tail +{} +closing line +", + "h".repeat(480), + "m".repeat(4000), + "t".repeat(980) + ); + + let out = ui(&[input.as_bytes()]); + + assert!(out.starts_with("opening line\n"), "got: {out}"); + assert!(out.ends_with("closing line\n"), "got: {out}"); +} + +/// A cut inside a whitespace-free run longer than the erosion window is left +/// intact. Erosion is bounded on purpose: erasing kilobytes of a single-token +/// stream — `npm` progress bars and base64 payloads both look like this — would +/// cost more diagnostics than a fragment of one could leak. +#[test] +fn test_capture_of_one_giant_token_keeps_its_cut_edges() { + let input = "x".repeat(4000); + + let out = ui(&[input.as_bytes()]); + + assert!(out.starts_with(&"x".repeat(512)), "got: {out}"); + assert!(out.ends_with(&"x".repeat(1024)), "got: {out}"); +} + +/// The marker's byte count stays honest across erosion: what it names as omitted +/// must equal the input minus what is actually shown, or a reader cannot trust +/// the file to say how much is missing. +#[test] +fn test_capture_marker_counts_the_bytes_erosion_dropped() { + let input = format!( + "{} {} {}", + "h".repeat(600), + "m".repeat(4000), + "t".repeat(1100) + ); + + let out = ui(&[input.as_bytes()]); + + let (head, rest) = out.split_once('\n').expect("a marker line"); + let (marker, tail) = rest.split_once('\n').expect("a marker line"); + let omitted: usize = marker + .trim_start_matches("... (") + .split_once(' ') + .expect("a byte count") + .0 + .parse() + .expect("a byte count"); + assert_eq!( + head.len() + omitted + tail.len(), + input.len(), + "shown + omitted must account for every input byte" ); } diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs index 806a4c7081..df2a6b70aa 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs @@ -66,7 +66,11 @@ pub(super) fn run_install_command_with_retry( run_install_with_retry( INSTALL_MAX_ATTEMPTS, |attempt| { - let outcome = run_install_command(step, command, reporter.line_observer(attempt)); + // Before the command spawns, so the previous attempt's last line + // stops being displayed for the whole backoff rather than until the + // new attempt happens to print something. + reporter.start_attempt(); + let outcome = run_install_command(step, command, reporter.line_observer()); reporter.record_attempt(attempt, &outcome); outcome.step }, @@ -200,28 +204,32 @@ fn await_install_child( let stderr_capture = Arc::new(Capture::new()); let stdout_pipe = child.stdout.take(); let stderr_pipe = child.stderr.take(); - let (drained_tx, drained_rx) = std::sync::mpsc::channel(); - let stdout_thread = std::thread::spawn({ + // One event stream carries every input the ceiling waits on, so the exit + // and the drains are governed by the same deadline instead of the exit + // releasing the drains from it. + let (events_tx, events) = std::sync::mpsc::channel(); + + std::thread::spawn({ let (capture, done, observer) = ( Arc::clone(&stdout_capture), - drained_tx.clone(), + events_tx.clone(), observer.clone(), ); move || { if let Some(pipe) = stdout_pipe { drain_into(pipe, &capture, observer.as_ref()); } - let _ = done.send(()); + let _ = done.send(Settled::Drained); } }); - let stderr_thread = std::thread::spawn({ - let (capture, done) = (Arc::clone(&stderr_capture), drained_tx); + std::thread::spawn({ + let (capture, done) = (Arc::clone(&stderr_capture), events_tx.clone()); move || { if let Some(pipe) = stderr_pipe { drain_into(pipe, &capture, observer.as_ref()); } - let _ = done.send(()); + let _ = done.send(Settled::Drained); } }); @@ -229,31 +237,37 @@ fn await_install_child( // kill the process on timeout. let child_pid = child.id(); - let (tx, rx) = std::sync::mpsc::channel(); - let wait_thread = std::thread::spawn(move || { - let status = child.wait(); - let _ = tx.send(status); + std::thread::spawn(move || { + let _ = events_tx.send(Settled::Exited(child.wait())); }); - let deadline = Instant::now() + timeout; - loop { - let remaining = deadline.saturating_duration_since(Instant::now()); - if remaining.is_zero() { - // Ceiling reached: kill the install's whole process group — the - // install shell is a session leader (`setsid` in its `pre_exec`), so - // signalling only the leader would leave descendants running and - // holding the output pipes open. - terminate_install_group(child_pid); - // Reaping the child and finishing the drains share one bound. Both - // normally complete within microseconds of the kill, which closes - // the pipes; when they don't — a process that escaped the group - // still holding a pipe, or a termination that failed outright — - // waiting would defeat the very ceiling that fired and keep the - // per-runtime install guard behind it closed. Stragglers are - // detached instead; the sinks are read under the lock either way. - let settle_by = Instant::now() + POST_KILL_GRACE; - await_messages(&rx, 1, settle_by); - await_messages(&drained_rx, 2, settle_by); + // No thread is ever joined. Each sends its one event before exiting, so a + // join after a complete settle would add nothing — and a join before one + // would reintroduce the unbounded wait this loop exists to prevent. + let mut settle = Settle::default(); + let ended = settle.collect(&events, Instant::now() + timeout); + if ended == Collected::Deadline { + // Ceiling reached: kill the install's whole process group — the install + // shell is a session leader (`setsid` in its `pre_exec`), so signalling + // only the leader would leave descendants running and holding the + // output pipes open. + // + // Whether the leader had already exited decides the verdict. If it had, + // only a descendant was holding a drain open: the install genuinely + // finished and its real status stands. If it had not, the install itself + // was still running and this is a timeout — the status the kill produces + // moments later describes the kill, not the install, so it is discarded. + let install_finished = settle.status.is_some(); + terminate_install_group(child_pid); + // Reaping the child and finishing the drains share one bound. Both + // normally complete within microseconds of the kill, which closes the + // pipes; when they don't — a process that escaped the group still + // holding a pipe, or a termination that failed outright — waiting would + // defeat the very ceiling that fired and keep the per-runtime install + // guard behind it closed. Stragglers are detached instead; the captures + // are read under the lock either way. + settle.collect(&events, Instant::now() + POST_KILL_GRACE); + if !install_finished { return failed_with_capture( step, command, @@ -262,56 +276,99 @@ fn await_install_child( &stderr_capture, ); } + } - match rx.recv_timeout(Duration::from_millis(200).min(remaining)) { - Ok(Ok(status)) => { - let _ = wait_thread.join(); - let _ = stdout_thread.join(); - let _ = stderr_thread.join(); - return InstallOutcome { - step: InstallStepResult { - step: step.to_string(), - command: command.to_string(), - success: status.success(), - stdout: stdout_capture.ui(), - stderr: stderr_capture.ui(), - exit_code: status.code(), - hint: None, - }, - log_stdout: stdout_capture.log(), - log_stderr: stderr_capture.log(), - }; - } - Ok(Err(e)) => { - let _ = wait_thread.join(); - let _ = stdout_thread.join(); - let _ = stderr_thread.join(); - return failed_with_capture( - step, - command, - format!("failed to check process status: {e}"), - &stdout_capture, - &stderr_capture, - ); - } - Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { - // Still running; loop and check deadline again. - continue; - } - Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => { - // wait_thread dropped sender without sending — shouldn't happen. - let _ = wait_thread.join(); - let _ = stdout_thread.join(); - let _ = stderr_thread.join(); - return failed_with_capture( - step, - command, - "internal error: wait thread disconnected".to_string(), - &stdout_capture, - &stderr_capture, - ); + match settle.status { + Some(Ok(status)) => InstallOutcome { + step: InstallStepResult { + step: step.to_string(), + command: command.to_string(), + success: status.success(), + stdout: stdout_capture.ui(), + stderr: stderr_capture.ui(), + exit_code: status.code(), + hint: None, + }, + log_stdout: stdout_capture.log(), + log_stderr: stderr_capture.log(), + }, + Some(Err(e)) => failed_with_capture( + step, + command, + format!("failed to check process status: {e}"), + &stdout_capture, + &stderr_capture, + ), + // Every sender is gone without an exit ever arriving. + None => failed_with_capture( + step, + command, + "internal error: install wait ended without a status".to_string(), + &stdout_capture, + &stderr_capture, + ), + } +} + +/// One input the ceiling waits on. +enum Settled { + Exited(std::io::Result), + Drained, +} + +/// How a bounded [`Settle::collect`] ended. +#[derive(PartialEq, Debug)] +enum Collected { + /// The child exited and both drains reached EOF. + Complete, + /// The deadline passed first. + Deadline, + /// Every sender is gone — a thread died without reporting. + Disconnected, +} + +/// What the install has settled so far: the child's exit status once it is +/// known, and how many of the two drains have reached EOF. +/// +/// Collecting is resumable, so the ceiling can fold more events into the same +/// state under a second, post-kill deadline. +#[derive(Default)] +struct Settle { + status: Option>, + drained: usize, +} + +impl Settle { + const DRAINS: usize = 2; + + fn is_complete(&self) -> bool { + self.status.is_some() && self.drained >= Self::DRAINS + } + + /// Fold events until the install has fully settled or `deadline` passes. + /// + /// The exit and the drains share one deadline deliberately: a shell can exit + /// while a descendant it left behind still holds the inherited output pipes, + /// and waiting on those drains outside the deadline would let such a + /// descendant outlast the ceiling — holding the per-runtime install guard, + /// which is the very failure the ceiling exists to prevent. + fn collect( + &mut self, + events: &std::sync::mpsc::Receiver, + deadline: Instant, + ) -> Collected { + while !self.is_complete() { + let remaining = deadline.saturating_duration_since(Instant::now()); + match events.recv_timeout(remaining) { + Ok(Settled::Exited(status)) => self.status = Some(status), + Ok(Settled::Drained) => self.drained += 1, + Err(std::sync::mpsc::RecvTimeoutError::Timeout) => return Collected::Deadline, + Err(std::sync::mpsc::RecvTimeoutError::Disconnected) => { + return Collected::Disconnected + } } } + Collected::Complete } } @@ -379,18 +436,6 @@ fn terminate_install_group(pid: u32) { let _ = crate::managed_agents::terminate_process(pid); } -/// Wait for `count` messages on `done`, giving up at `deadline` and leaving any -/// straggler detached. Used only after the ceiling's kill, where a sender that -/// never arrives is precisely the case that must not extend the ceiling. -fn await_messages(done: &std::sync::mpsc::Receiver, count: usize, deadline: Instant) { - for _ in 0..count { - let remaining = deadline.saturating_duration_since(Instant::now()); - if done.recv_timeout(remaining).is_err() { - return; - } - } -} - /// A failure carrying whatever the drains captured, with `reason` leading /// stderr so the surfaced message names the failure before the install's own /// output. @@ -688,12 +733,13 @@ mod tests { /// A sender that never arrives — the shape of a failed termination, whose /// child is never reaped — must not extend the wait past its deadline. #[test] - fn test_awaiting_a_message_that_never_arrives_stops_at_the_deadline() { - let (_tx, rx) = std::sync::mpsc::channel::<()>(); + fn test_settling_on_a_message_that_never_arrives_stops_at_the_deadline() { + let (_tx, events) = std::sync::mpsc::channel::(); let started = Instant::now(); - await_messages(&rx, 1, started + Duration::from_millis(200)); + let ended = Settle::default().collect(&events, started + Duration::from_millis(200)); + assert_eq!(ended, Collected::Deadline); assert!( started.elapsed() < Duration::from_secs(1), "the wait must end at its deadline, took {:?}", @@ -701,22 +747,96 @@ mod tests { ); } - /// The deadline is shared across the whole settle, not restarted per - /// message: two waits behind one deadline still end at that deadline. + /// An exit alone is not a settle: the drains are inputs to the same wait, so + /// a shell that exited while a descendant holds a pipe still hits the + /// deadline instead of being released from it. + #[test] + fn test_exit_without_drains_still_hits_the_deadline() { + let (tx, events) = std::sync::mpsc::channel(); + tx.send(Settled::Exited(Ok(exit_status_zero()))).unwrap(); + + let started = Instant::now(); + let mut settle = Settle::default(); + let ended = settle.collect(&events, started + Duration::from_millis(200)); + + assert_eq!( + ended, + Collected::Deadline, + "a leader exit must not complete the settle while a drain is outstanding" + ); + assert!(settle.status.is_some(), "the exit status must be retained"); + assert!(started.elapsed() < Duration::from_secs(1)); + } + + /// The settle completes only when the exit and both drains have arrived, and + /// it is resumable: state folded under the first deadline carries into the + /// post-kill one. + #[test] + fn test_settle_completes_on_exit_plus_both_drains_and_resumes() { + let (tx, events) = std::sync::mpsc::channel(); + tx.send(Settled::Drained).unwrap(); + + let mut settle = Settle::default(); + assert_eq!( + settle.collect(&events, Instant::now() + Duration::from_millis(50)), + Collected::Deadline + ); + + tx.send(Settled::Exited(Ok(exit_status_zero()))).unwrap(); + tx.send(Settled::Drained).unwrap(); + + assert_eq!( + settle.collect(&events, Instant::now() + Duration::from_secs(5)), + Collected::Complete, + "the second collect must build on the first's state, not restart it" + ); + } + + /// Exit status of a trivially successful command, for driving `Settle` + /// without a real install. + fn exit_status_zero() -> std::process::ExitStatus { + std::process::Command::new("true") + .status() + .expect("run `true`") + } + + /// A shell can exit while a descendant it left behind still holds the + /// inherited output pipes. If the exit released the drains from the + /// deadline, that descendant would hold the install — and the per-runtime + /// concurrency guard behind it — open indefinitely, which is exactly the + /// failure the ceiling exists to prevent. The leader here exits in + /// milliseconds; only the descendant outlives the ceiling. + #[cfg(unix)] #[test] - fn test_awaiting_several_messages_shares_one_deadline() { - let (_tx, rx) = std::sync::mpsc::channel::<()>(); + fn test_promptly_exited_leader_with_a_pipe_holding_descendant_still_obeys_the_ceiling() { + let dir = tempfile::tempdir().expect("tempdir"); + let pidfile = dir.path().join("lingering.pid"); + let child = spawn_group_leader(&format!( + "sh -c 'echo $$ > {pid}; sleep 120' & exit 3", + pid = pidfile.display() + )); let started = Instant::now(); - let settle_by = started + Duration::from_millis(200); - await_messages(&rx, 1, settle_by); - await_messages(&rx, 2, settle_by); + let outcome = await_install_child("cli", "install", child, Duration::from_secs(2), None); assert!( - started.elapsed() < Duration::from_secs(1), - "a shared deadline must not compound per wait, took {:?}", + started.elapsed() < Duration::from_secs(30), + "a descendant holding the pipe must not outlast the ceiling, took {:?}", started.elapsed() ); + assert_eq!( + outcome.step.exit_code, + Some(3), + "the leader's real status outranks the ceiling's verdict once it is known" + ); + // The deadline must still reach the kill on this path: a leader exit that + // skipped termination would leave the descendant running with the pipes + // open, which is the defect itself rather than a detail of it. + let pid = recorded_pid(&pidfile); + assert!( + await_death(pid), + "descendant {pid} survived — a leader exit must not skip the ceiling's kill" + ); } /// Wait up to 3s for `pid` to disappear. diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs index 7f85ff9f5d..1004d0db87 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -4,16 +4,26 @@ //! Both destinations hang off the same drain seam in //! [`super::install_capture`], and both are best-effort: an install must never //! fail because a log write or an event emit did. +//! +//! [`InstallReporter`] owns two explicit lifecycles, because both the log and +//! the live line are meaningless without a notion of "this run": +//! +//! * a **log session**, started once per run, which keeps the previous run's +//! file as `.1` and writes this run's header; and +//! * a **live-event sequence**, monotonic across the whole install, which is +//! what lets the UI drop a superseded line. A per-command retry number +//! cannot do that job — it restarts at 1 for every step. use std::io::Write; -use std::path::PathBuf; -use std::sync::Arc; +use std::path::{Path, PathBuf}; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex}; use std::time::{Duration, Instant}; use serde::Serialize; use super::install_capture::{LineObserver, Throttle}; -use crate::managed_agents::InstallStepResult; +use crate::managed_agents::{InstallRuntimeResult, InstallStepResult}; /// One install command's result: what the UI shows, and the log-scale copy of /// the same output for the log file. @@ -37,88 +47,134 @@ impl InstallOutcome { /// Payload of the `acp-install-output` event. /// -/// `attempt` lets the UI drop a line that belongs to a superseded retry: -/// without it, a line emitted just before attempt 2 starts can sit under the -/// spinner while attempt 2 runs. +/// `seq` is monotonic across the entire install, so the UI can drop a line a +/// later step or attempt has already superseded. The retry number cannot serve +/// as that key: it restarts at 1 for every step, so a step that succeeded on +/// attempt 2 would make the next step's attempt-1 output look stale and freeze +/// the display. +/// +/// `line: None` is the *start signal*: an attempt is beginning and the displayed +/// line must clear now. It is emitted unthrottled, because the point is that +/// stale output stops being shown before the new work prints anything. #[derive(Serialize, Clone)] pub(super) struct InstallOutputEvent { pub(super) runtime_id: String, - pub(super) attempt: u32, - pub(super) line: String, + pub(super) seq: u64, + pub(super) line: Option, } /// Emits one live output event. Boxed rather than holding an `AppHandle` so the /// reporter is constructible — and assertable — without a Tauri app. type EmitEvent = Arc; -/// At most four live-output events per second. Coalescing is by dropping, not -/// buffering: the UI shows only the newest line, so a queued backlog would -/// display stale progress. +/// Literal secret values scrubbed out of everything this module publishes, in +/// addition to the shapes [`crate::managed_agents::redact_secrets_with`] +/// recognises on its own. +type Secrets = Arc>; + +/// At most four live-output events per second. Coalescing *holds* the newest +/// line rather than dropping it: a burst that ends just before the window +/// closes would otherwise leave the display showing a line the install had +/// already moved past. const LIVE_LINE_INTERVAL: Duration = Duration::from_millis(250); pub(super) struct InstallReporter { - runtime_id: String, - log_path: Option, - emit: Option, - throttle: Arc, + log: Option, + /// `None` when nothing is listening, which is also what makes + /// [`InstallReporter::line_observer`] `None` — the drain then skips line + /// reassembly entirely instead of doing it for no one. + live: Option, + secrets: Secrets, } impl InstallReporter { - /// The reporter a real install command uses: it writes the install log and - /// emits live output events through `app`. + /// The reporter a real install run uses: it starts this run's log session + /// and emits live output events through `app`. + /// + /// `runtime_id` must already be the canonical id from the runtime catalog — + /// the log path is built from it, so resolving it first is what keeps a raw + /// command argument out of a filename. /// - /// A log path that cannot be resolved degrades to no log rather than failing - /// the install — a user with a broken app-data directory still needs the - /// install itself to work. - pub(super) fn for_command(app: &tauri::AppHandle, runtime_id: &str) -> Self { - let log_path = crate::managed_agents::storage::install_log_path(app, runtime_id).ok(); + /// A log that cannot be resolved or opened degrades to no log rather than + /// failing the install: a user with a broken app-data directory still needs + /// the install itself to work. + pub(super) fn for_run(app: &tauri::AppHandle, runtime_id: &str) -> Self { + let log = crate::managed_agents::storage::install_log_path(app, runtime_id) + .ok() + .and_then(|path| InstallLog::start(&path, runtime_id)); let app = app.clone(); let emit: EmitEvent = Arc::new(move |event| { use tauri::Emitter; let _ = app.emit("acp-install-output", event); }); - Self::new(runtime_id, log_path, Some(emit)) + Self::new(runtime_id, log, Some(emit)) } - pub(super) fn new( - runtime_id: &str, - log_path: Option, - emit: Option, - ) -> Self { - Self { - runtime_id: runtime_id.to_string(), - log_path, + fn new(runtime_id: &str, log: Option, emit: Option) -> Self { + // Snapshot the environment's secrets once, at construction: the install + // inherits this environment, so anything it echoes came from here. + let secrets: Secrets = Arc::new(env_secret_values()); + let live = emit.map(|emit| Live { + runtime_id: Arc::from(runtime_id), emit, throttle: Arc::new(Throttle::new(LIVE_LINE_INTERVAL)), - } + seq: Arc::new(AtomicU64::new(0)), + secrets: Arc::clone(&secrets), + }); + Self { log, live, secrets } } - /// The log file to point the user at, once something has been written to it. - /// `None` when this install has no log — the failure message then omits the - /// pointer rather than naming a file that does not exist. + /// The log file to point the user at, or `None` when this run has no log — + /// the failure message then omits the pointer rather than naming a file + /// that does not exist. pub(super) fn log_path(&self) -> Option { - let path = self.log_path.as_ref()?; - path.exists().then(|| path.display().to_string()) + Some(self.log.as_ref()?.path.display().to_string()) + } + + /// A failed install carrying the steps recorded so far and the log holding + /// their full history. Every early return in the install shapes its result + /// here, so none can forget the log pointer the failure message needs. + pub(super) fn failed(&self, steps: Vec) -> InstallRuntimeResult { + InstallRuntimeResult { + success: false, + steps, + restarted_count: 0, + failed_restart_count: 0, + log_path: self.log_path(), + } + } + + /// Mark the start of one executed attempt: clear whatever line the previous + /// attempt left on screen, and start this attempt's clock. + /// + /// The clear is emitted unthrottled and reopens the rate window, so the new + /// attempt's first line cannot be swallowed by the previous attempt's. + /// Without this signal the prior attempt's last line — typically the failure + /// that caused the retry — sits under the spinner through the backoff and + /// through a silent next attempt. + pub(super) fn start_attempt(&self) { + if let Some(log) = &self.log { + log.mark_attempt_start(); + } + if let Some(live) = &self.live { + live.throttle.restart(); + live.publish(None); + } } /// Observer for one attempt's drains, or `None` when nothing is listening. - pub(super) fn line_observer(&self, attempt: u32) -> Option { - let emit = Arc::clone(self.emit.as_ref()?); - let throttle = Arc::clone(&self.throttle); - let runtime_id = self.runtime_id.clone(); - Some(Arc::new(move |line: &str| { - if throttle.allows(Instant::now()) { - emit(InstallOutputEvent { - runtime_id: runtime_id.clone(), - attempt, - line: line.to_string(), - }); - } - })) + pub(super) fn line_observer(&self) -> Option { + let live = self.live.clone()?; + Some(Arc::new(move |line: &str| live.offer(line))) } /// Record one executed attempt of a step. pub(super) fn record_attempt(&self, attempt: u32, outcome: &InstallOutcome) { + // The drains are finished, so a line the throttle is still holding is + // this attempt's last and nothing is coming to replace it. + if let Some(live) = &self.live { + live.flush_pending(); + } self.write_record(Some(attempt), outcome); } @@ -133,11 +189,98 @@ impl InstallReporter { /// Append one record. Best-effort by contract: a full disk or a revoked /// permission degrades the diagnostics, it does not fail the install. fn write_record(&self, attempt: Option, outcome: &InstallOutcome) { - let Some(path) = self.log_path.as_ref() else { + let Some(log) = &self.log else { return; }; - let record = render_record(attempt, outcome); - if let Ok(mut file) = crate::managed_agents::storage::open_install_log_file(path) { + log.append(&render_record( + attempt, + log.take_attempt_elapsed(), + outcome, + &self.secrets, + )); + } +} + +/// The shared half of the reporter — everything a drain thread's observer needs, +/// owned rather than borrowed so an observer can outlive the call that made it. +#[derive(Clone)] +struct Live { + runtime_id: Arc, + emit: EmitEvent, + throttle: Arc, + seq: Arc, + secrets: Secrets, +} + +impl Live { + /// Offer one drained line to the rate limiter, emitting it if the window is + /// open and holding it as the newest pending line if not. + fn offer(&self, line: &str) { + if let Some(line) = self.throttle.offer(line, Instant::now()) { + self.publish(Some(line)); + } + } + + fn flush_pending(&self) { + if let Some(line) = self.throttle.take_pending() { + self.publish(Some(line)); + } + } + + /// Emit `line` now, bypassing the rate window. `None` clears the display. + fn publish(&self, line: Option) { + (self.emit)(InstallOutputEvent { + runtime_id: self.runtime_id.to_string(), + seq: self.seq.fetch_add(1, Ordering::Relaxed), + line: line.map(|line| redact(&line, &self.secrets)), + }); + } +} + +/// This run's log file: one session, opened once, appended to per record. +struct InstallLog { + path: PathBuf, + /// When the attempt currently running started, so its record can name its + /// own duration. A 15-minute ceiling is only diagnosable if the file says + /// how long each attempt actually took. + attempt_start: Mutex>, +} + +impl InstallLog { + /// Start this run's session, or `None` if the file cannot be opened. + /// + /// Rotation happens here, once per run, rather than per record: a run either + /// gets its own file or it gets no log at all, so two runs are never + /// interleaved in one file. + fn start(path: &Path, runtime_id: &str) -> Option { + let mut file = crate::managed_agents::storage::start_install_log_session(path).ok()?; + let _ = file.write_all( + format!( + "=== install run runtime={runtime_id} started={}\n", + chrono::Utc::now().to_rfc3339() + ) + .as_bytes(), + ); + Some(Self { + path: path.to_path_buf(), + attempt_start: Mutex::new(None), + }) + } + + fn mark_attempt_start(&self) { + if let Ok(mut start) = self.attempt_start.lock() { + *start = Some(Instant::now()); + } + } + + /// How long the attempt being recorded ran, consumed so a later record + /// cannot reuse it. `None` for a synthesized step, which never ran. + fn take_attempt_elapsed(&self) -> Option { + Some(self.attempt_start.lock().ok()?.take()?.elapsed()) + } + + fn append(&self, record: &str) { + if let Ok(mut file) = crate::managed_agents::storage::open_install_log_file(&self.path) { let _ = file.write_all(record.as_bytes()); } } @@ -147,38 +290,86 @@ impl InstallReporter { /// capture that produced it, so an early attempt that printed megabytes cannot /// push a later attempt — or the verification step that explains the failure — /// out of the file. -fn render_record(attempt: Option, outcome: &InstallOutcome) -> String { +fn render_record( + attempt: Option, + elapsed: Option, + outcome: &InstallOutcome, + secrets: &Secrets, +) -> String { let step = &outcome.step; let attempt = attempt.map_or_else(|| "-".to_string(), |n| n.to_string()); let exit = step .exit_code .map_or_else(|| "none".to_string(), |code| code.to_string()); + let elapsed = elapsed.map_or_else( + || "-".to_string(), + |elapsed| format!("{:.1}s", elapsed.as_secs_f64()), + ); let mut record = format!( - "=== {} step={} attempt={attempt} success={} exit={exit}\n$ {}\n", + "=== {} step={} attempt={attempt} success={} exit={exit} elapsed={elapsed}\n$ {}\n", chrono::Utc::now().to_rfc3339(), step.step, step.success, - redact(&step.command), + redact(&step.command, secrets), ); for (label, text) in [ ("stdout", &outcome.log_stdout), ("stderr", &outcome.log_stderr), ] { if !text.trim().is_empty() { - record.push_str(&format!("--- {label} ---\n{}\n", redact(text))); + record.push_str(&format!("--- {label} ---\n{}\n", redact(text, secrets))); } } if let Some(hint) = &step.hint { - record.push_str(&format!("--- hint ---\n{}\n", redact(hint))); + record.push_str(&format!("--- hint ---\n{}\n", redact(hint, secrets))); } record } -/// Scrub known secret shapes before anything reaches disk. Install output can -/// echo a registry token or a signing key from the environment it ran in, and -/// this file is written unattended. -fn redact(text: &str) -> String { - crate::managed_agents::redact_secrets_with(text, &[]) +/// Scrub secrets before anything reaches disk or the UI. The log is written +/// unattended and the live line is rendered verbatim, so scrubbing happens at +/// the write, not at the read. +fn redact(text: &str, secrets: &Secrets) -> String { + let extras: Vec<&str> = secrets.iter().map(String::as_str).collect(); + crate::managed_agents::redact_secrets_with(text, &extras) +} + +/// Values of environment variables whose *name* marks them as secret. +/// +/// An install inherits Buzz's environment and installers echo it back — npm +/// prints the resolved registry config on an auth failure, and a shell that +/// traces its commands prints every expansion. Without this, only the two +/// hard-coded key shapes would be scrubbed, so a plain `NPM_TOKEN` or +/// `ANTHROPIC_API_KEY` would land in the file in clear text. +/// +/// Keyed on the name because a secret's *value* has no reliable shape. Two +/// filters keep ordinary output readable: a value under 8 bytes is skipped +/// (more likely a flag like `true` or a version than a credential), and the +/// markers avoid substrings that occur in non-secret names — `AUTH` is left out +/// because it matches `GIT_AUTHOR_NAME`, whose value is a person's name. +fn env_secret_values() -> Vec { + const SECRET_NAME_MARKERS: &[&str] = &[ + "TOKEN", + "SECRET", + "PASSWORD", + "PASSWD", + "APIKEY", + "API_KEY", + "PRIVATE_KEY", + "ACCESS_KEY", + "CREDENTIAL", + ]; + std::env::vars() + .filter(|(name, value)| { + value.len() >= 8 && { + let name = name.to_ascii_uppercase(); + SECRET_NAME_MARKERS + .iter() + .any(|marker| name.contains(marker)) + } + }) + .map(|(_, value)| value) + .collect() } #[cfg(test)] diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs index b6ac24ddfa..354d57411d 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -2,7 +2,8 @@ use super::*; use crate::commands::agent_discovery::install_capture::{drain_into, Capture}; use std::sync::Mutex; -/// A reporter writing to a temp log, with the emitted events captured. +/// A reporter with a started log session in a temp dir, and the emitted events +/// captured. struct Harness { _dir: tempfile::TempDir, log: PathBuf, @@ -11,7 +12,13 @@ struct Harness { } fn harness() -> Harness { - let dir = tempfile::tempdir().expect("tempdir"); + harness_at(None) +} + +/// A harness whose log lives in `dir`, or in a fresh temp dir when `dir` is +/// `None`. Passing a directory lets a test seed a previous run's file first. +fn harness_at(dir: Option) -> Harness { + let dir = dir.unwrap_or_else(|| tempfile::tempdir().expect("tempdir")); let log = dir.path().join("install-goose.log"); let events: Arc>> = Arc::new(Mutex::new(Vec::new())); let emit: EmitEvent = { @@ -19,7 +26,7 @@ fn harness() -> Harness { Arc::new(move |event| events.lock().unwrap().push(event)) }; Harness { - reporter: InstallReporter::new("goose", Some(log.clone()), Some(emit)), + reporter: InstallReporter::new("goose", InstallLog::start(&log, "goose"), Some(emit)), _dir: dir, log, events, @@ -58,7 +65,8 @@ impl Harness { std::fs::read_to_string(&self.log).unwrap_or_default() } - fn lines(&self) -> Vec { + /// The emitted lines in order, with a clear signal rendered as `None`. + fn lines(&self) -> Vec> { self.events .lock() .unwrap() @@ -66,6 +74,10 @@ impl Harness { .map(|e| e.line.clone()) .collect() } + + fn events(&self) -> Vec { + self.events.lock().unwrap().clone() + } } // ── the log records history the UI does not keep ───────────────────────────── @@ -150,6 +162,78 @@ fn test_recording_a_synthesized_step_logs_it_and_keeps_it_for_the_ui() { assert!(h.log_contents().contains("still-not-usable")); } +// ── one file per run ───────────────────────────────────────────────────────── + +/// A run opens with a header naming the runtime, so a file holding one run of +/// several steps is identifiable as that run rather than a stream of records. +#[test] +fn test_a_run_opens_with_a_header_naming_the_runtime() { + let h = harness(); + + assert!( + h.log_contents() + .starts_with("=== install run runtime=goose "), + "got: {}", + h.log_contents() + ); +} + +/// A new run does not append to the previous run's file: it starts a fresh one +/// and keeps the previous as `.1`. Reading a log has to mean reading one run — +/// records accumulated across runs are indistinguishable from retries within +/// one. +#[test] +fn test_a_new_run_starts_a_fresh_file_and_keeps_the_previous_as_dot_one() { + let first = harness(); + first + .reporter + .record_attempt(1, &outcome("cli", false, "previous-run-output")); + let previous = first.log.clone(); + let dir = first._dir; + drop(first.reporter); + + let second = harness_at(Some(dir)); + second + .reporter + .record_attempt(1, &outcome("cli", false, "current-run-output")); + + let log = second.log_contents(); + assert!(log.contains("current-run-output"), "got: {log}"); + assert!( + !log.contains("previous-run-output"), + "the new run's file must not carry the previous run's records: {log}" + ); + let rotated = std::fs::read_to_string(previous.with_extension("log.1")).expect("read .1"); + assert!( + rotated.contains("previous-run-output"), + "the previous run must remain readable as .1: {rotated}" + ); +} + +/// Each executed attempt records how long it ran. A 15-minute ceiling is only +/// diagnosable if the file says which attempt consumed the time. +#[test] +fn test_an_executed_attempt_records_its_own_duration() { + let h = harness(); + + h.reporter.start_attempt(); + h.reporter.record_attempt(1, &outcome("cli", true, "done")); + h.reporter + .record_step(&mut Vec::new(), step("verify", true, "")); + + let log = h.log_contents(); + assert!( + log.contains("attempt=1") && log.contains("elapsed=0."), + "an executed attempt must carry its duration: {log}" + ); + assert!( + log.contains("attempt=- ") && log.contains("elapsed=-"), + "a synthesized step never ran, so it has no duration: {log}" + ); +} + +// ── redaction ──────────────────────────────────────────────────────────────── + /// Secrets that an installer echoed must not land on disk. The log is written /// unattended, so scrubbing happens at the write, not at the read. #[test] @@ -164,21 +248,54 @@ fn test_log_redacts_secrets_before_writing() { assert!(log.contains("[REDACTED]"), "got: {log}"); } -/// The log path is surfaced only once something is in the file — a message -/// pointing at a path that does not exist is worse than no pointer. +/// The environment's own secrets are scrubbed too, by *name* rather than shape. +/// An install inherits Buzz's environment and installers echo it back — npm +/// prints its resolved config on an auth failure — and a token with no +/// recognizable prefix would otherwise reach the file verbatim. #[test] -fn test_log_path_is_absent_until_something_is_written() { +fn test_log_redacts_an_environment_secret_with_no_recognizable_prefix() { + let secret = "0e8f31c5a4b7d296e5f1a"; + // Set before the reporter is built: the snapshot is taken at construction. + std::env::set_var("BUZZ_TEST_REGISTRY_TOKEN", secret); let h = harness(); + std::env::remove_var("BUZZ_TEST_REGISTRY_TOKEN"); - assert_eq!(h.reporter.log_path(), None); + h.reporter.record_attempt( + 1, + &outcome("cli", false, &format!("npm ERR! _authToken={secret}")), + ); - h.reporter.record_attempt(1, &outcome("cli", true, "done")); + let log = h.log_contents(); + assert!(!log.contains(secret), "got: {log}"); + assert!(log.contains("[REDACTED]"), "got: {log}"); +} - assert_eq!( - h.reporter.log_path(), - Some(h.log.display().to_string()), - "a written log must be surfaced" - ); +/// A live line carries the same scrubbing as the log record. The line is +/// rendered verbatim in the UI, so a leak there is as visible as one on disk. +#[test] +fn test_a_live_line_is_redacted_before_it_is_emitted() { + let h = harness(); + + let observer = h.reporter.line_observer().expect("an observer"); + observer("fetching with token nsec1qqqqqqqqqqleaked"); + + let lines = h.lines(); + assert_eq!(lines.len(), 1); + let line = lines[0].clone().expect("a line, not a clear signal"); + assert!(!line.contains("nsec1qqqqqqqqqqleaked"), "got: {line}"); + assert!(line.contains("[REDACTED]"), "got: {line}"); +} + +// ── the log pointer ────────────────────────────────────────────────────────── + +/// The path is available as soon as the run's session opens, because the file +/// exists from that moment — the header is already in it. A failure before any +/// step ran still points the user at a real file. +#[test] +fn test_log_path_is_available_from_the_start_of_the_run() { + let h = harness(); + + assert_eq!(h.reporter.log_path(), Some(h.log.display().to_string())); } /// A reporter with no log — an unresolvable app-data directory — records @@ -188,6 +305,7 @@ fn test_reporter_without_a_log_records_nothing_and_reports_no_path() { let reporter = silent_reporter(); let mut steps = Vec::new(); + reporter.start_attempt(); reporter.record_attempt(1, &outcome("cli", false, "output")); reporter.record_step(&mut steps, step("verify", false, "detail")); @@ -195,55 +313,119 @@ fn test_reporter_without_a_log_records_nothing_and_reports_no_path() { assert_eq!(steps.len(), 1, "the UI path is unaffected by a missing log"); } -/// A log path inside a directory that no longer exists fails every write. The -/// install still runs; the pointer is simply absent. +/// A log path inside a directory that no longer exists cannot open a session, so +/// the run degrades to no log rather than failing. #[test] -fn test_write_failure_leaves_the_install_unaffected() { - let reporter = InstallReporter::new( - "goose", - Some(PathBuf::from("/nonexistent-dir-for-test/install-goose.log")), - None, - ); +fn test_an_unopenable_log_degrades_to_no_log() { + let path = PathBuf::from("/nonexistent-dir-for-test/install-goose.log"); - reporter.record_attempt(1, &outcome("cli", false, "output")); - - assert_eq!(reporter.log_path(), None); + assert!(InstallLog::start(&path, "goose").is_none()); } // ── live output line ───────────────────────────────────────────────────────── -/// Lines drained during an attempt are emitted with that attempt's number, so -/// the UI can discard a line that belongs to a superseded retry. +/// Lines carry an install-wide monotonic sequence number, so the UI can order +/// them across steps and attempts — which a per-step retry number cannot do. #[test] -fn test_emitted_line_carries_its_runtime_and_attempt() { +fn test_emitted_lines_carry_their_runtime_and_a_monotonic_sequence() { let h = harness(); - let observer = h.reporter.line_observer(2).expect("an observer"); + let observer = h.reporter.line_observer().expect("an observer"); observer("downloading"); + h.reporter.start_attempt(); + + let events = h.events(); + assert_eq!(events.len(), 2); + assert!(events.iter().all(|e| e.runtime_id == "goose")); + assert_eq!(events[0].line.as_deref(), Some("downloading")); + assert_eq!(events[0].seq, 0); + assert_eq!( + events[1].seq, 1, + "the clear signal takes the next sequence number, so it cannot be \ + mistaken for a stale event" + ); +} + +/// Starting an attempt clears the display first: the previous attempt's last +/// line is typically the failure that caused the retry, and leaving it under the +/// spinner through the backoff shows the user the past as if it were current. +#[test] +fn test_starting_an_attempt_clears_the_displayed_line() { + let h = harness(); + let observer = h.reporter.line_observer().expect("an observer"); + observer("download failed"); + + h.reporter.start_attempt(); + + assert_eq!( + h.lines(), + vec![Some("download failed".to_string()), None], + "the attempt boundary must emit a clear" + ); +} + +/// The clear is not rate-limited, and it reopens the window: a new attempt's +/// first line goes out immediately even if it arrives inside the previous +/// attempt's window. This is the case the throttle used to swallow entirely. +#[test] +fn test_a_new_attempts_first_line_is_emitted_even_inside_the_previous_window() { + let h = harness(); + let observer = h.reporter.line_observer().expect("an observer"); + observer("attempt one failed"); - let events = h.events.lock().unwrap(); - assert_eq!(events.len(), 1); - assert_eq!(events[0].runtime_id, "goose"); - assert_eq!(events[0].attempt, 2); - assert_eq!(events[0].line, "downloading"); + // No wait: the previous line was emitted microseconds ago, so this is well + // inside the 250ms window. + h.reporter.start_attempt(); + observer("attempt two starting"); + + assert_eq!( + h.lines(), + vec![ + Some("attempt one failed".to_string()), + None, + Some("attempt two starting".to_string()), + ] + ); } -/// The throttle is per install, not per attempt or per stream: a burst across -/// two observers still coalesces, because both share one window. +/// A burst inside the window coalesces to one event, and the line it emits is +/// the *newest* — the display shows current progress, not the line that happened +/// to arrive when the window opened. #[test] -fn test_emission_is_throttled_across_attempts_and_streams() { +fn test_a_burst_coalesces_to_the_newest_line_not_the_first() { let h = harness(); - let first = h.reporter.line_observer(1).expect("an observer"); - let second = h.reporter.line_observer(2).expect("an observer"); + let observer = h.reporter.line_observer().expect("an observer"); - first("one"); - first("two"); - second("three"); + observer("one"); + observer("two"); + observer("three"); + // Ends the attempt, which is when a held line is known to be the last. + h.reporter.record_attempt(1, &outcome("cli", true, "done")); + + assert_eq!( + h.lines(), + vec![Some("one".to_string()), Some("three".to_string())], + "the held line must be the newest, and it must not be lost" + ); +} + +/// The throttle is per install, not per stream: stdout and stderr of one attempt +/// share one window, so an install printing on both does not double the event +/// rate. +#[test] +fn test_both_streams_of_one_attempt_share_the_rate_window() { + let h = harness(); + let stdout = h.reporter.line_observer().expect("an observer"); + let stderr = h.reporter.line_observer().expect("an observer"); + + stdout("progress"); + stderr("warning"); + h.reporter.record_attempt(1, &outcome("cli", true, "done")); assert_eq!( h.lines(), - vec!["one"], - "a burst inside the window must coalesce to the first line" + vec![Some("progress".to_string()), Some("warning".to_string())], + "the second stream's line is held, not emitted immediately, and not lost" ); } @@ -251,5 +433,5 @@ fn test_emission_is_throttled_across_attempts_and_streams() { /// reassembly entirely rather than doing the work and discarding it. #[test] fn test_no_observer_when_nothing_is_listening() { - assert!(silent_reporter().line_observer(1).is_none()); + assert!(silent_reporter().line_observer().is_none()); } diff --git a/desktop/src-tauri/src/managed_agents/storage.rs b/desktop/src-tauri/src/managed_agents/storage.rs index 0098a153ef..652bb9b9ea 100644 --- a/desktop/src-tauri/src/managed_agents/storage.rs +++ b/desktop/src-tauri/src/managed_agents/storage.rs @@ -660,7 +660,37 @@ pub(crate) fn open_log_file(path: &Path) -> Result { .map_err(|error| format!("failed to open log file {}: {error}", path.display())) } -/// Open an install log for appending, creating it owner-only. +/// Start a new install-log session at `path`: keep the previous run as +/// `.1` and return a freshly created, empty current file. +/// +/// Rotating per *run* rather than by size is what bounds this file. A run +/// writes one record per executed attempt, each capped by the log-scale +/// capture, so one run's file is bounded by steps × attempts × cap and the +/// history on disk is bounded at two runs. Size-triggered rotation could not +/// promise either: it never replaced an existing `.1`, and on Windows — +/// where rename does not replace its destination — it stopped working +/// altogether once `.1` existed, leaving the current file to grow. +/// +/// The old `.1` is therefore *removed* before the rename rather than renamed +/// over. Every step is best-effort: a rotation that fails must not cost the +/// user the install, so the session continues with a truncated current file. +pub(crate) fn start_install_log_session(path: &Path) -> Result { + if path.exists() { + let mut previous = path.as_os_str().to_owned(); + previous.push(".1"); + let previous = PathBuf::from(previous); + let _ = fs::remove_file(&previous); + let _ = fs::rename(path, &previous); + } + open_install_log(path, /* truncate */ true) +} + +/// Open an install log for appending one more record to the current session. +pub(crate) fn open_install_log_file(path: &Path) -> Result { + open_install_log(path, /* truncate */ false) +} + +/// Open an install log owner-only. /// /// The mode is set *in the create* rather than chmod'd afterwards, so the file /// is never briefly group/world-readable. Install output can carry registry @@ -668,10 +698,14 @@ pub(crate) fn open_log_file(path: &Path) -> Result { /// matters even though it is short. An existing file's mode is left as-is — /// `OpenOptions::mode` only applies on creation, and silently re-tightening a /// file the user relaxed is not this function's call to make. -pub(crate) fn open_install_log_file(path: &Path) -> Result { - maybe_rotate_log(path); +fn open_install_log(path: &Path, truncate: bool) -> Result { let mut options = OpenOptions::new(); - options.create(true).append(true); + options.create(true); + if truncate { + options.write(true).truncate(true); + } else { + options.append(true); + } #[cfg(unix)] { use std::os::unix::fs::OpenOptionsExt; diff --git a/desktop/src-tauri/src/managed_agents/storage_tests.rs b/desktop/src-tauri/src/managed_agents/storage_tests.rs index ab78d0f2ae..9943c6b3ac 100644 --- a/desktop/src-tauri/src/managed_agents/storage_tests.rs +++ b/desktop/src-tauri/src/managed_agents/storage_tests.rs @@ -724,42 +724,77 @@ fn install_log_is_created_owner_only_without_post_write_chmod() { assert_eq!(mode, 0o600, "install logs must be owner-only"); } -/// Reopening appends rather than truncating — a run's later records must not -/// erase its earlier ones. +/// A run starts a new current file and keeps the previous run as `.1`, so the +/// two runs are never mixed and the history on disk stays bounded at two. #[test] -fn install_log_appends_across_opens() { +fn install_log_session_keeps_the_previous_run_as_dot_one() { let dir = tempfile::tempdir().expect("temp dir"); let path = dir.path().join("install-goose.log"); - for record in ["first\n", "second\n"] { - let mut file = super::open_install_log_file(&path).expect("open install log"); - file.write_all(record.as_bytes()).expect("write"); - } + let mut first = super::start_install_log_session(&path).expect("first session"); + first.write_all(b"run-one\n").expect("write"); + let mut second = super::start_install_log_session(&path).expect("second session"); + second.write_all(b"run-two\n").expect("write"); assert_eq!( - std::fs::read_to_string(&path).expect("read back"), - "first\nsecond\n" + std::fs::read_to_string(&path).expect("read current"), + "run-two\n", + "the current file must hold only the newest run" + ); + assert_eq!( + std::fs::read_to_string(dir.path().join("install-goose.log.1")).expect("read .1"), + "run-one\n", + "the previous run must be preserved as .1" ); } -/// An oversized install log rotates to `.1` on the next open, so the file -/// cannot grow without bound across repeated install attempts. +/// The third run must still rotate when `.1` already exists. Windows `rename` +/// does not replace its destination, so a rename-only rotation silently stops +/// working here and leaves the current file to grow across every later run — +/// the old `.1` is removed first precisely so this cannot happen. Runs on the +/// Windows target too: this is the path that fails there. #[test] -fn install_log_rotates_when_oversized() { +fn install_log_session_replaces_an_existing_dot_one() { let dir = tempfile::tempdir().expect("temp dir"); let path = dir.path().join("install-goose.log"); - std::fs::write(&path, vec![b'x'; (super::MAX_LOG_FILE_SIZE + 1) as usize]).expect("seed"); + let rotated = dir.path().join("install-goose.log.1"); + // Seed the state a rename-only rotation cannot get out of: both files exist. + std::fs::write(&path, b"previous-run\n").expect("seed current"); + std::fs::write(&rotated, b"ancient-run\n").expect("seed .1"); - let mut file = super::open_install_log_file(&path).expect("open install log"); - file.write_all(b"fresh\n").expect("write"); + let mut file = super::start_install_log_session(&path).expect("session"); + file.write_all(b"fresh-run\n").expect("write"); + + assert_eq!( + std::fs::read_to_string(&path).expect("read current"), + "fresh-run\n", + "the current file must restart even when .1 was already present" + ); + assert_eq!( + std::fs::read_to_string(&rotated).expect("read .1"), + "previous-run\n", + ".1 must be replaced by the run that just ended, not kept" + ); +} + +/// Records written after the session starts append to it — a run's later +/// records must not erase its earlier ones. +#[test] +fn install_log_appends_within_a_session() { + let dir = tempfile::tempdir().expect("temp dir"); + let path = dir.path().join("install-goose.log"); + + let mut session = super::start_install_log_session(&path).expect("session"); + session.write_all(b"header\n").expect("write"); + for record in ["first\n", "second\n"] { + let mut file = super::open_install_log_file(&path).expect("open install log"); + file.write_all(record.as_bytes()).expect("write"); + } assert_eq!( std::fs::read_to_string(&path).expect("read back"), - "fresh\n", - "the live log must restart after rotation" + "header\nfirst\nsecond\n" ); - let rotated = dir.path().join("install-goose.log.1"); - assert!(rotated.exists(), "the oversized log must be kept as .1"); } /// A runtime id becomes part of a filename. Ids reach this from user-defined diff --git a/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs b/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs index a45e6dd5ba..d65583e00d 100644 --- a/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs +++ b/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs @@ -3,56 +3,80 @@ import test from "node:test"; import { nextInstallOutputLine } from "./useInstallOutputLine.ts"; -function event(runtimeId, attempt, line) { - return { runtime_id: runtimeId, attempt, line }; +function event(runtimeId, seq, line) { + return { runtime_id: runtimeId, seq, line }; } test("nextInstallOutputLine: adopts the first line for the watched runtime", () => { assert.deepEqual( - nextInstallOutputLine(null, event("goose", 1, "downloading"), "goose"), - { attempt: 1, line: "downloading" }, + nextInstallOutputLine(null, event("goose", 0, "downloading"), "goose"), + { seq: 0, line: "downloading" }, ); }); -test("nextInstallOutputLine: replaces the line within the same attempt", () => { - const current = { attempt: 1, line: "downloading" }; +test("nextInstallOutputLine: a later line replaces the current one", () => { + const current = { seq: 4, line: "downloading" }; assert.deepEqual( - nextInstallOutputLine(current, event("goose", 1, "unpacking"), "goose"), - { attempt: 1, line: "unpacking" }, + nextInstallOutputLine(current, event("goose", 5, "unpacking"), "goose"), + { seq: 5, line: "unpacking" }, ); }); test("nextInstallOutputLine: ignores a line from another runtime", () => { - const current = { attempt: 1, line: "downloading" }; + const current = { seq: 1, line: "downloading" }; assert.equal( - nextInstallOutputLine(current, event("codex", 1, "other work"), "goose"), + nextInstallOutputLine(current, event("codex", 2, "other work"), "goose"), current, ); }); -test("nextInstallOutputLine: ignores a line from a superseded attempt", () => { - const current = { attempt: 2, line: "retrying" }; +test("nextInstallOutputLine: ignores an out-of-order line", () => { + const current = { seq: 7, line: "retrying" }; assert.equal( - nextInstallOutputLine(current, event("goose", 1, "stale line"), "goose"), + nextInstallOutputLine(current, event("goose", 6, "stale line"), "goose"), current, ); }); -test("nextInstallOutputLine: adopts the first line of a new attempt", () => { - const current = { attempt: 1, line: "download failed" }; +test("nextInstallOutputLine: ignores a replay of the current sequence number", () => { + const current = { seq: 7, line: "retrying" }; + + assert.equal( + nextInstallOutputLine(current, event("goose", 7, "duplicate"), "goose"), + current, + ); +}); + +test("nextInstallOutputLine: a null line clears the display", () => { + const current = { seq: 3, line: "download failed" }; + + assert.deepEqual( + nextInstallOutputLine(current, event("goose", 4, null), "goose"), + { seq: 4, line: null }, + ); +}); + +test("nextInstallOutputLine: a later step's first line is adopted after a higher attempt", () => { + // The seq is install-wide: step 2 attempt 1 always follows step 1 attempt 2, + // which is exactly what an attempt-keyed comparison got wrong. + const current = { seq: 9, line: "step one, attempt two" }; assert.deepEqual( - nextInstallOutputLine(current, event("goose", 2, "downloading"), "goose"), - { attempt: 2, line: "downloading" }, + nextInstallOutputLine( + current, + event("goose", 10, "step two, attempt one"), + "goose", + ), + { seq: 10, line: "step two, attempt one" }, ); }); -test("nextInstallOutputLine: a first event from a later attempt is adopted", () => { +test("nextInstallOutputLine: a first event mid-install is adopted", () => { assert.deepEqual( - nextInstallOutputLine(null, event("goose", 3, "downloading"), "goose"), - { attempt: 3, line: "downloading" }, + nextInstallOutputLine(null, event("goose", 42, "downloading"), "goose"), + { seq: 42, line: "downloading" }, ); }); diff --git a/desktop/src/features/agents/lib/useInstallOutputLine.ts b/desktop/src/features/agents/lib/useInstallOutputLine.ts index f486b6864b..cc251f8f25 100644 --- a/desktop/src/features/agents/lib/useInstallOutputLine.ts +++ b/desktop/src/features/agents/lib/useInstallOutputLine.ts @@ -4,24 +4,31 @@ import { listen } from "@tauri-apps/api/event"; /** Mirror of the Rust `InstallOutputEvent` payload (install_report.rs). */ export type InstallOutputEvent = { runtime_id: string; - attempt: number; - line: string; + /** Monotonic across the whole install, not per step or per attempt. */ + seq: number; + /** Null is the start signal: clear the displayed line now. */ + line: string | null; }; -/** The line being shown, and which attempt produced it. */ +/** The line being shown, and the sequence number that produced it. */ export type InstallOutputState = { - attempt: number; - line: string; + seq: number; + line: string | null; }; /** * Fold one event into the displayed line. * * Events from another runtime are ignored — every install card listens to the - * same channel. So is an event from a superseded attempt: install retries with - * backoff, and a line emitted just as attempt 2 starts would otherwise sit - * under the spinner while attempt 2 runs, showing the user the failure they - * already had instead of current progress. + * same channel. So is an out-of-order event: emission is monotonic in `seq`, so + * a lower one has already been superseded. That matters at a retry boundary, + * where a line emitted just as the next attempt starts would otherwise sit + * under the spinner showing the failure the user already had. + * + * The ordering key is the install-wide `seq` rather than the attempt number, + * which restarts at 1 for every step: keyed on attempt, a step that succeeded on + * attempt 2 would make the next step's attempt-1 output look stale and freeze + * the display for the rest of the install. */ export function nextInstallOutputLine( current: InstallOutputState | null, @@ -29,13 +36,14 @@ export function nextInstallOutputLine( runtimeId: string, ): InstallOutputState | null { if (event.runtime_id !== runtimeId) return current; - if (current && event.attempt < current.attempt) return current; - return { attempt: event.attempt, line: event.line }; + if (current && event.seq <= current.seq) return current; + return { seq: event.seq, line: event.line }; } /** * The install command's most recent output line for `runtimeId`, or null when - * nothing has been printed yet. + * nothing is being shown — either nothing has printed yet, or the backend + * cleared the line because a new attempt is starting. * * An install runs for up to 15 minutes with no other feedback than a spinner; * this turns that wait into observable progress. The backend throttles diff --git a/desktop/src/shared/api/installTypes.ts b/desktop/src/shared/api/installTypes.ts new file mode 100644 index 0000000000..34d968b77d --- /dev/null +++ b/desktop/src/shared/api/installTypes.ts @@ -0,0 +1,67 @@ +/** + * Result of an ACP runtime install, in both the shape Rust sends and the shape + * the UI consumes. + */ + +export type RawInstallStepResult = { + step: string; + command: string; + success: boolean; + stdout: string; + stderr: string; + exit_code: number | null; + hint?: string; +}; + +export type RawInstallRuntimeResult = { + success: boolean; + steps: RawInstallStepResult[]; + restarted_count: number; + failed_restart_count: number; + /** Absent for a run with no log file — Rust serializes `None` as null. */ + log_path?: string | null; +}; + +export type InstallStepResult = { + step: string; + command: string; + success: boolean; + stdout: string; + stderr: string; + exitCode: number | null; + hint?: string; +}; + +export type InstallRuntimeResult = { + success: boolean; + steps: InstallStepResult[]; + restartedCount: number; + failedRestartCount: number; + /** + * Install log file for this run, when one was written. `steps` carries only + * the last attempt of each step; the log holds every attempt, each record + * bounded far above the display truncation. Null when no log could be + * written — nothing then points at a file that does not exist. + */ + logPath: string | null; +}; + +export function fromRawInstallRuntimeResult( + raw: RawInstallRuntimeResult, +): InstallRuntimeResult { + return { + success: raw.success, + steps: raw.steps.map((step) => ({ + step: step.step, + command: step.command, + success: step.success, + stdout: step.stdout, + stderr: step.stderr, + exitCode: step.exit_code, + hint: step.hint, + })), + restartedCount: raw.restarted_count, + failedRestartCount: raw.failed_restart_count, + logPath: raw.log_path ?? null, + }; +} diff --git a/desktop/src/shared/api/tauri.ts b/desktop/src/shared/api/tauri.ts index 38f4ec45bc..69e2e455ec 100644 --- a/desktop/src/shared/api/tauri.ts +++ b/desktop/src/shared/api/tauri.ts @@ -3,6 +3,10 @@ import { activateRateLimit, parseRateLimitHint, } from "@/shared/api/relayRateLimitGate"; +import { + fromRawInstallRuntimeResult, + type RawInstallRuntimeResult, +} from "@/shared/api/installTypes"; import type { AddChannelMembersInput, AddChannelMembersResult, @@ -202,24 +206,10 @@ export type RawAcpRuntimeCatalogEntry = { definition_env?: Record; }; -export type RawInstallStepResult = { - step: string; - command: string; - success: boolean; - stdout: string; - stderr: string; - exit_code: number | null; - hint?: string; -}; - -export type RawInstallRuntimeResult = { - success: boolean; - steps: RawInstallStepResult[]; - restarted_count: number; - failed_restart_count: number; - /** Absent for a run with no log file — Rust serializes `None` as null. */ - log_path?: string | null; -}; +export type { + RawInstallRuntimeResult, + RawInstallStepResult, +} from "./installTypes"; type RawGitBashPrerequisite = { available: boolean; @@ -774,26 +764,6 @@ export function fromRawAcpRuntimeCatalogEntry( }; } -function fromRawInstallRuntimeResult( - raw: RawInstallRuntimeResult, -): InstallRuntimeResult { - return { - success: raw.success, - steps: raw.steps.map((step) => ({ - step: step.step, - command: step.command, - success: step.success, - stdout: step.stdout, - stderr: step.stderr, - exitCode: step.exit_code, - hint: step.hint, - })), - restartedCount: raw.restarted_count, - failedRestartCount: raw.failed_restart_count, - logPath: raw.log_path ?? null, - }; -} - function fromRawCommandAvailability( command: RawCommandAvailability, ): CommandAvailability { diff --git a/desktop/src/shared/api/types.ts b/desktop/src/shared/api/types.ts index d014a61a39..877b5b1c61 100644 --- a/desktop/src/shared/api/types.ts +++ b/desktop/src/shared/api/types.ts @@ -571,29 +571,10 @@ export type AcpRuntime = AcpRuntimeCatalogEntry & { binaryPath: string; }; -export type InstallStepResult = { - step: string; - command: string; - success: boolean; - stdout: string; - stderr: string; - exitCode: number | null; - hint?: string; -}; - -export type InstallRuntimeResult = { - success: boolean; - steps: InstallStepResult[]; - restartedCount: number; - failedRestartCount: number; - /** - * Install log file for this run, when one was written. `steps` carries only - * the last attempt of each step, truncated for display; the log holds every - * attempt in full. Null when no log could be written — nothing then points at - * a file that does not exist. - */ - logPath: string | null; -}; +export type { + InstallRuntimeResult, + InstallStepResult, +} from "./installTypes"; export type AcpAuthMethod = { id: string; diff --git a/desktop/src/shared/lib/installError.ts b/desktop/src/shared/lib/installError.ts index d154714b1a..82bcd4a310 100644 --- a/desktop/src/shared/lib/installError.ts +++ b/desktop/src/shared/lib/installError.ts @@ -6,8 +6,8 @@ import type { InstallRuntimeResult } from "@/shared/api/types"; * followed by the raw step failure detail. * * The step detail is truncated for display, so the message ends with a pointer - * to the install log — which holds every attempt of every step in full — when - * one was written. + * to the install log — which holds every attempt of every step, each record + * bounded far above the display truncation — when one was written. */ export function getInstallErrorMessage(result: InstallRuntimeResult): string { const { steps, logPath } = result; diff --git a/desktop/src/testing/e2eBridge.ts b/desktop/src/testing/e2eBridge.ts index ac37dcb840..eba900e16a 100644 --- a/desktop/src/testing/e2eBridge.ts +++ b/desktop/src/testing/e2eBridge.ts @@ -1,4 +1,5 @@ import { bytesToHex, hexToBytes } from "@noble/hashes/utils.js"; +import { emit } from "@tauri-apps/api/event"; import { mockIPC, mockWindows } from "@tauri-apps/api/mocks"; import { decode } from "nostr-tools/nip19"; import { finalizeEvent, getPublicKey } from "nostr-tools/pure"; @@ -203,6 +204,8 @@ type E2eConfig = { acpRuntimesCatalogAfterConnect?: RawAcpRuntimeCatalogEntry[]; activePersonaIds?: string[]; installAcpRuntimeDelayMs?: number; + /** Live output lines the mocked install emits before it settles. */ + installAcpRuntimeOutputLines?: string[]; installAcpRuntimeResult?: RawInstallRuntimeResult; /** Sequence of results for successive `install_acp_runtime` calls. * Call N returns results[N]; when exhausted the last entry repeats. @@ -7201,6 +7204,40 @@ let personaSharePublicationCallCount = 0; // Per-page confirm_team_snapshot_import call counter for sequenced error testing. let teamSnapshotConfirmCallCount = 0; +// Install-wide live-output sequence, mirroring the backend's monotonic counter. +let installOutputSeq = 0; + +/** + * Replay the live output the Rust reporter emits while an install runs: a clear + * signal, then one line per entry. `seq` is install-wide and monotonic, matching + * the backend contract the UI's ordering depends on. + * + * Emissions are spaced so the sequence is observable rather than collapsing into + * one frame: the first gap lets the clicked row mount its listener, and each + * later gap lets React commit that line before the next replaces it. + */ +const INSTALL_OUTPUT_REPLAY_GAP_MS = 120; + +async function replayInstallOutput( + runtimeId: string, + lines: string[], +): Promise { + // The leading null is the clear signal the backend sends when an attempt + // starts, so this replays a whole attempt rather than only its output. + for (const line of [null, ...lines]) { + await new Promise((resolve) => + window.setTimeout(resolve, INSTALL_OUTPUT_REPLAY_GAP_MS), + ); + // `emit` reaches listeners registered through the real `listen` API, which + // is what the UI hook uses; mockIPC's shouldMockEvents wires the two. + await emit("acp-install-output", { + runtime_id: runtimeId, + seq: installOutputSeq++, + line, + }); + } +} + async function handleInstallAcpRuntime( args: { runtimeId?: string; @@ -7208,6 +7245,10 @@ async function handleInstallAcpRuntime( config: E2eConfig | undefined, ): Promise { const runtimeId = args.runtimeId ?? ""; + const outputLines = config?.mock?.installAcpRuntimeOutputLines; + if (outputLines && outputLines.length > 0) { + await replayInstallOutput(runtimeId, outputLines); + } const perRuntime = config?.mock?.installAcpRuntimeByRuntime?.[runtimeId]; if (perRuntime) { diff --git a/desktop/tests/e2e/doctor-states.spec.ts b/desktop/tests/e2e/doctor-states.spec.ts index 77d0fbcb45..e4ff35ebfd 100644 --- a/desktop/tests/e2e/doctor-states.spec.ts +++ b/desktop/tests/e2e/doctor-states.spec.ts @@ -983,4 +983,76 @@ test.describe("Doctor panel state screenshots", () => { path: `${SHOTS}/08-concurrent-installs-and-stale-clear.png`, }); }); + /** + * 09 — install observability: the live output line appears while the install + * runs and disappears when it settles, and the failure message points at the + * install log rather than only the truncated last step. + */ + test("09-install-output-line-and-log-pointer", async ({ page }) => { + await installMockBridge(page, { + acpRuntimesCatalog: [ + GOOSE_AVAILABLE, + CLAUDE_AVAILABLE_LOGGED_IN, + { + ...CODEX_NOT_INSTALLED, + can_auto_install: true, + node_required: false, + }, + BUZZ_AGENT_AVAILABLE, + ], + installAcpRuntimeDelayMs: 500, + installAcpRuntimeOutputLines: [ + "npm http fetch GET 200 @zed-industries/codex-acp", + "npm warn deprecated a transitive dependency", + ], + installAcpRuntimeResult: { + success: false, + steps: [ + { + step: "adapter", + command: "npm install -g @zed-industries/codex-acp", + success: false, + stdout: "", + stderr: "npm ERR! code E404", + exit_code: 1, + }, + ], + log_path: "/tmp/buzz-install-codex.log", + }, + }); + + await page.goto("/", { waitUntil: "domcontentloaded" }); + await openSettings(page, "agents"); + + const row = page.getByTestId("doctor-runtime-codex"); + await expect(row).toBeVisible({ timeout: 10_000 }); + + const installButton = page.getByTestId("doctor-runtime-install-codex"); + await expect(installButton).toBeEnabled(); + await installButton.click(); + + // The line shows what the install is doing right now, and each new line + // replaces the previous one rather than accumulating. + const outputLine = page.getByTestId("doctor-runtime-install-output-codex"); + await expect(outputLine).toContainText("npm warn deprecated", { + timeout: 5_000, + }); + await expect(outputLine).not.toContainText("npm http fetch"); + + // Settled: the line clears, so a finished install leaves no stale output + // under a fresh Install button. + const installError = page.getByTestId("doctor-runtime-install-error-codex"); + await expect(installError).toBeVisible({ timeout: 5_000 }); + await expect(outputLine).toHaveCount(0); + + // The failure points at the log holding every attempt in full. + await expect(installError).toContainText("npm ERR! code E404"); + await expect(installError).toContainText("/tmp/buzz-install-codex.log"); + + await row.scrollIntoViewIfNeeded(); + await waitForAnimations(page); + await row.screenshot({ + path: `${SHOTS}/09-install-output-line-and-log-pointer.png`, + }); + }); }); diff --git a/desktop/tests/helpers/bridge.ts b/desktop/tests/helpers/bridge.ts index d5eee0dae3..9d4b76f8d0 100644 --- a/desktop/tests/helpers/bridge.ts +++ b/desktop/tests/helpers/bridge.ts @@ -187,6 +187,10 @@ type MockBridgeOptions = { connectAcpRuntimeDelayMs?: number; connectAcpRuntimeError?: string; installAcpRuntimeDelayMs?: number; + /** Live output lines the mocked install emits before it settles, in order. + * Each arrives as an `acp-install-output` event, preceded by the clear + * signal the backend sends at the start of an attempt. */ + installAcpRuntimeOutputLines?: string[]; /** Override the result returned by the `install_acp_runtime` mock command. * Pass `{ success: false, steps: [...] }` to exercise error/Retry states. */ installAcpRuntimeResult?: MockInstallRuntimeResult; From 1ad4811c3d8699caa0c3a7b92ec43a1fbfd43abf Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Tue, 28 Jul 2026 21:13:49 -0400 Subject: [PATCH 4/9] fix(desktop): mount the install output listener before the install starts The live-output subscription was created only once React had committed the pending install state, but the install command is invoked from the click handler: the backend emits the attempt-start clear and can emit its first line inside that window, and nothing replays them. A fast command's entire output could therefore never appear. The listener is now mounted for the runtime's whole lifetime; the run boundary resets the ordering key when the install settles, and the line is rendered only while installing, so a straggler from a finished drain cannot show up under a fresh Install button. The E2E seam was hiding this: it delayed every event, with the first gap existing specifically to let the clicked row mount its listener. The clear and the first line now emit synchronously with the invocation, and the spec asserts the first line is observed, so it pins production ordering instead of accommodating it. The bridge's sequence also restarts per install, matching the backend's per-run counter, and a second install asserts the display accepts a restarted sequence. The install log header now names the app version and OS: a Windows install failure and a macOS one on the same runtime are different bugs, and a stale version explains a failure that no longer reproduces. The version is read from the app's own package info rather than the frontend plugin, so it cannot be mocked out from under the log. The bridge gains the `plugin:app|version` stub it was missing, which also removes an unhandled page error on every Settings render. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../agent_discovery/install_report.rs | 16 ++++++-- .../agent_discovery/install_report_tests.rs | 29 +++++++++----- .../agents/lib/useInstallOutputLine.ts | 29 ++++++++++---- desktop/src/testing/e2eBridge.ts | 38 ++++++++++++++----- desktop/tests/e2e/doctor-states.spec.ts | 21 ++++++++-- 5 files changed, 101 insertions(+), 32 deletions(-) diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs index 1004d0db87..c0c212269c 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -99,9 +99,13 @@ impl InstallReporter { /// failing the install: a user with a broken app-data directory still needs /// the install itself to work. pub(super) fn for_run(app: &tauri::AppHandle, runtime_id: &str) -> Self { + // Read from the app's own package info rather than the frontend's + // `getVersion` plugin call: the header is written on the Rust side, and + // this cannot fail or be mocked out from under the log. + let app_version = app.package_info().version.to_string(); let log = crate::managed_agents::storage::install_log_path(app, runtime_id) .ok() - .and_then(|path| InstallLog::start(&path, runtime_id)); + .and_then(|path| InstallLog::start(&path, runtime_id, &app_version)); let app = app.clone(); let emit: EmitEvent = Arc::new(move |event| { use tauri::Emitter; @@ -252,11 +256,17 @@ impl InstallLog { /// Rotation happens here, once per run, rather than per record: a run either /// gets its own file or it gets no log at all, so two runs are never /// interleaved in one file. - fn start(path: &Path, runtime_id: &str) -> Option { + /// + /// The header identifies the environment the run happened in, not just the + /// run: a Windows install failure and a macOS one on the same runtime are + /// different bugs, and a stale app version explains a failure that no longer + /// reproduces. + fn start(path: &Path, runtime_id: &str, app_version: &str) -> Option { let mut file = crate::managed_agents::storage::start_install_log_session(path).ok()?; let _ = file.write_all( format!( - "=== install run runtime={runtime_id} started={}\n", + "=== install run runtime={runtime_id} app={app_version} os={} started={}\n", + std::env::consts::OS, chrono::Utc::now().to_rfc3339() ) .as_bytes(), diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs index 354d57411d..fc8b793a1d 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -2,6 +2,9 @@ use super::*; use crate::commands::agent_discovery::install_capture::{drain_into, Capture}; use std::sync::Mutex; +/// Stands in for the real `app.package_info().version`, which needs a Tauri app. +const TEST_APP_VERSION: &str = "9.9.9"; + /// A reporter with a started log session in a temp dir, and the emitted events /// captured. struct Harness { @@ -26,7 +29,11 @@ fn harness_at(dir: Option) -> Harness { Arc::new(move |event| events.lock().unwrap().push(event)) }; Harness { - reporter: InstallReporter::new("goose", InstallLog::start(&log, "goose"), Some(emit)), + reporter: InstallReporter::new( + "goose", + InstallLog::start(&log, "goose", TEST_APP_VERSION), + Some(emit), + ), _dir: dir, log, events, @@ -164,17 +171,21 @@ fn test_recording_a_synthesized_step_logs_it_and_keeps_it_for_the_ui() { // ── one file per run ───────────────────────────────────────────────────────── -/// A run opens with a header naming the runtime, so a file holding one run of -/// several steps is identifiable as that run rather than a stream of records. +/// A run opens with a header naming the runtime and the environment the run +/// happened in, so a file holding one run of several steps is identifiable as +/// that run rather than a stream of records — and a failure report says which +/// app version and OS produced it without a second round trip to the user. #[test] -fn test_a_run_opens_with_a_header_naming_the_runtime() { +fn test_a_run_opens_with_a_header_naming_the_runtime_app_version_and_os() { let h = harness(); + let log = h.log_contents(); assert!( - h.log_contents() - .starts_with("=== install run runtime=goose "), - "got: {}", - h.log_contents() + log.starts_with(&format!( + "=== install run runtime=goose app={TEST_APP_VERSION} os={} started=", + std::env::consts::OS + )), + "got: {log}" ); } @@ -319,7 +330,7 @@ fn test_reporter_without_a_log_records_nothing_and_reports_no_path() { fn test_an_unopenable_log_degrades_to_no_log() { let path = PathBuf::from("/nonexistent-dir-for-test/install-goose.log"); - assert!(InstallLog::start(&path, "goose").is_none()); + assert!(InstallLog::start(&path, "goose", TEST_APP_VERSION).is_none()); } // ── live output line ───────────────────────────────────────────────────────── diff --git a/desktop/src/features/agents/lib/useInstallOutputLine.ts b/desktop/src/features/agents/lib/useInstallOutputLine.ts index cc251f8f25..9f50843fc7 100644 --- a/desktop/src/features/agents/lib/useInstallOutputLine.ts +++ b/desktop/src/features/agents/lib/useInstallOutputLine.ts @@ -42,8 +42,8 @@ export function nextInstallOutputLine( /** * The install command's most recent output line for `runtimeId`, or null when - * nothing is being shown — either nothing has printed yet, or the backend - * cleared the line because a new attempt is starting. + * nothing is being shown — the install is not running, nothing has printed yet, + * or the backend cleared the line because a new attempt is starting. * * An install runs for up to 15 minutes with no other feedback than a spinner; * this turns that wait into observable progress. The backend throttles @@ -58,11 +58,13 @@ export function useInstallOutputLine( ): string | null { const [state, setState] = React.useState(null); + // Subscribed for this runtime's whole lifetime, not just while installing. + // The install command is invoked from the click handler, so the backend can + // emit the attempt-start clear and the first line before React commits + // `isInstalling` — and there is no replay, so a subscription that waited for + // that commit would lose those events permanently. A fast command's entire + // output is exactly what fits in that window. React.useEffect(() => { - if (!isInstalling) { - setState(null); - return; - } let cancelled = false; let unlisten: (() => void) | null = null; (async () => { @@ -89,7 +91,18 @@ export function useInstallOutputLine( cancelled = true; unlisten?.(); }; - }, [isInstalling, runtimeId]); + }, [runtimeId]); - return state?.line ?? null; + // `seq` is monotonic within one install and restarts at 0 for the next, so + // state must not outlive the run that produced it: a retained higher `seq` + // would make every event of the following install look superseded. Settling + // is the run boundary, so it is where the ordering key resets. + React.useEffect(() => { + if (!isInstalling) setState(null); + }, [isInstalling]); + + // Events that arrive after the install settles — a drain flushing its last + // line — must not reappear under a fresh Install button, so the line is + // reported only while the install is running. + return (isInstalling ? state?.line : null) ?? null; } diff --git a/desktop/src/testing/e2eBridge.ts b/desktop/src/testing/e2eBridge.ts index eba900e16a..ca6cd22efb 100644 --- a/desktop/src/testing/e2eBridge.ts +++ b/desktop/src/testing/e2eBridge.ts @@ -1243,6 +1243,8 @@ const REACTION_TARGET_CONTENT = "React to me with a custom emoji"; // REACTION_TARGET_EVENT_ID. const SYSTEM_REACTION_TARGET_EVENT_ID = "e".repeat(64); const E2E_IDENTITY_OVERRIDE_STORAGE_KEY = "buzz:e2e-identity-override.v1"; +/** Stands in for `tauri.conf.json`'s version, which no mock IPC call can read. */ +const MOCK_APP_VERSION = "0.0.0-e2e"; const DEFAULT_MOCK_IDENTITY = { pubkey: "deadbeef".repeat(8), display_name: "npub1mock...", @@ -7204,7 +7206,10 @@ let personaSharePublicationCallCount = 0; // Per-page confirm_team_snapshot_import call counter for sequenced error testing. let teamSnapshotConfirmCallCount = 0; -// Install-wide live-output sequence, mirroring the backend's monotonic counter. +// Live-output sequence for the install currently being replayed. The backend +// counter is per run (`InstallReporter::for_run` starts a fresh one), so this +// restarts too — a bridge that stayed monotonic across installs would hide a UI +// that carried a stale sequence number into the next run and rejected all of it. let installOutputSeq = 0; /** @@ -7212,22 +7217,32 @@ let installOutputSeq = 0; * signal, then one line per entry. `seq` is install-wide and monotonic, matching * the backend contract the UI's ordering depends on. * - * Emissions are spaced so the sequence is observable rather than collapsing into - * one frame: the first gap lets the clicked row mount its listener, and each - * later gap lets React commit that line before the next replaces it. + * The clear and the first line emit synchronously with the install invocation, + * exactly as the backend does — the command is invoked from the click handler, + * so those events land before React has committed the pending install state. + * Delaying them would let a listener that mounts on that state still catch them, + * hiding the very race the UI has to survive. + * + * Later lines are spaced so each is observable rather than collapsing into one + * frame with the next. */ -const INSTALL_OUTPUT_REPLAY_GAP_MS = 120; +const INSTALL_OUTPUT_REPLAY_GAP_MS = 1000; async function replayInstallOutput( runtimeId: string, lines: string[], ): Promise { + installOutputSeq = 0; // The leading null is the clear signal the backend sends when an attempt // starts, so this replays a whole attempt rather than only its output. - for (const line of [null, ...lines]) { - await new Promise((resolve) => - window.setTimeout(resolve, INSTALL_OUTPUT_REPLAY_GAP_MS), - ); + const events: (string | null)[] = [null, ...lines]; + for (const [index, line] of events.entries()) { + // Index 0 and 1 are the clear and the first line: no gap before either. + if (index > 1) { + await new Promise((resolve) => + window.setTimeout(resolve, INSTALL_OUTPUT_REPLAY_GAP_MS), + ); + } // `emit` reaches listeners registered through the real `listen` API, which // is what the UI hook uses; mockIPC's shouldMockEvents wires the two. await emit("acp-install-output", { @@ -11563,6 +11578,11 @@ export function maybeInstallE2eTauriMocks() { return null; case "plugin:window|is_fullscreen": return false; + // Settings reads the app version through the app plugin. Without this the + // bridge throws an unhandled page error on every Settings render, which + // shows up as noise in unrelated specs. + case "plugin:app|version": + return MOCK_APP_VERSION; case "merge_save_subscription_kinds": { // Mirrors `merge_owner_p_kinds`: union `kind` into the owner_p row's // kinds, creating the row if it doesn't exist yet. diff --git a/desktop/tests/e2e/doctor-states.spec.ts b/desktop/tests/e2e/doctor-states.spec.ts index e4ff35ebfd..2d69a4e0da 100644 --- a/desktop/tests/e2e/doctor-states.spec.ts +++ b/desktop/tests/e2e/doctor-states.spec.ts @@ -1031,9 +1031,16 @@ test.describe("Doctor panel state screenshots", () => { await expect(installButton).toBeEnabled(); await installButton.click(); - // The line shows what the install is doing right now, and each new line - // replaces the previous one rather than accumulating. + // The bridge emits the attempt-start clear and the first line synchronously + // with the install invocation — before React commits the pending state — so + // observing this line proves the listener was already mounted at the click. + // A subscription that waited for the install state would have missed both. const outputLine = page.getByTestId("doctor-runtime-install-output-codex"); + await expect(outputLine).toContainText("npm http fetch", { + timeout: 5_000, + }); + + // Each new line replaces the previous one rather than accumulating. await expect(outputLine).toContainText("npm warn deprecated", { timeout: 5_000, }); @@ -1045,7 +1052,7 @@ test.describe("Doctor panel state screenshots", () => { await expect(installError).toBeVisible({ timeout: 5_000 }); await expect(outputLine).toHaveCount(0); - // The failure points at the log holding every attempt in full. + // The failure points at the log holding bounded output for every attempt. await expect(installError).toContainText("npm ERR! code E404"); await expect(installError).toContainText("/tmp/buzz-install-codex.log"); @@ -1054,5 +1061,13 @@ test.describe("Doctor panel state screenshots", () => { await row.screenshot({ path: `${SHOTS}/09-install-output-line-and-log-pointer.png`, }); + + // A second install shows its own output. The backend sequence restarts per + // run, so a display that kept the previous run's sequence number would + // reject every event of this one and show nothing at all. + await installButton.click(); + await expect(outputLine).toContainText("npm http fetch", { + timeout: 5_000, + }); }); }); From 79593af8cb955db5cf0008553a46047c4c172340 Mon Sep 17 00:00:00 2001 From: Will Pfleger Date: Wed, 29 Jul 2026 13:50:44 -0400 Subject: [PATCH 5/9] fix(desktop): serialize drain publication against reporter deactivation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A drain thread holds an owned clone of `Live` and can call `offer` after `InstallReporter` is dropped (the run boundary). An atomic flag check before emit is insufficient: a thread admitted while active can pause between the check and the emit, and `Drop` can complete in that window — letting the late publication land in the permanent listener's React state with run 1's high `seq`, causing run 2's restarted `seq=0` events to be rejected by the `event.seq <= current.seq` guard and displaying run 1's stale output. Fix: replace `Arc` with `Arc>` in `Live`. Drain threads hold a **shared read guard** from the admission check through the `(self.emit)(...)` call, making the check-then-emit pair atomic with respect to shutdown. `InstallReporter::drop` takes the **exclusive write guard** and stores `false`; this blocks until every in-flight publication has released its read guard, then prevents any new admission. Deactivation is bounded: the write lock holds only for the flag store, so it can block at most for the duration of one emit call (microseconds to low milliseconds for the Tauri IPC broadcast). No deadlock is possible: `(self.emit)` in production is `app.emit("acp-install-output", event)` — fire-and-forget Tauri IPC that does not call back into `Live`. In tests it is a Vec push. The declaration order in `install_acp_runtime_blocking` is load- bearing: `reporter` is declared after `_guard` (line 311 vs line 306), so Rust drops it first (reverse-declaration order), ensuring the exclusive write completes before the per-runtime concurrency guard releases and a new install for the same runtime can begin. Three pin tests: - `test_a_detached_observer_cannot_emit_after_the_reporter_is_dropped`: sequential drain-after-drop is a no-op. Fails when the lifecycle guard is removed from offer. - `test_deactivation_blocks_until_in_flight_publication_completes`: white-box concurrency pin — acquires a read guard, asserts `try_write()` fails while the guard is held, releases the guard, then completes deactivation. Fails to compile on the old atomic shape (`dc6421ac4`) because the `lifecycle` field does not exist. - `test_run2_output_replaces_stale_run1_state_through_shared_consumer`: one shared event sink for both runs; consumer resets to null at run-1 settlement (modeling the frontend `isInstalling` reset); verifies run 2's output wins through the shared reducer. Fails when the lifecycle guard is removed from offer (late drain emits with high seq, poisons the null-reset consumer before run 2 can emit seq=0). Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../agent_discovery/install_report.rs | 81 +++++- .../agent_discovery/install_report_tests.rs | 255 ++++++++++++++++++ 2 files changed, 331 insertions(+), 5 deletions(-) diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs index c0c212269c..3e52f1cb3d 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -17,7 +17,7 @@ use std::io::Write; use std::path::{Path, PathBuf}; use std::sync::atomic::{AtomicU64, Ordering}; -use std::sync::{Arc, Mutex}; +use std::sync::{Arc, Mutex, RwLock}; use std::time::{Duration, Instant}; use serde::Serialize; @@ -56,7 +56,7 @@ impl InstallOutcome { /// `line: None` is the *start signal*: an attempt is beginning and the displayed /// line must clear now. It is emitted unthrottled, because the point is that /// stale output stops being shown before the new work prints anything. -#[derive(Serialize, Clone)] +#[derive(Serialize, Clone, Debug)] pub(super) struct InstallOutputEvent { pub(super) runtime_id: String, pub(super) seq: u64, @@ -87,6 +87,30 @@ pub(super) struct InstallReporter { secrets: Secrets, } +impl Drop for InstallReporter { + /// Serialise deactivation against in-flight publications: take the + /// exclusive lifecycle write lock, mark the run as inactive, and return — + /// all before the per-runtime concurrency guard releases. + /// + /// Every drain thread holds the shared read guard from its admission check + /// through its `(self.emit)(...)` call, so the write lock here blocks until + /// every in-flight publication has finished. After this returns, `active` + /// is `false` under an exclusive write, and any thread that attempts a new + /// `offer` will read `false` under a read lock and return without emitting. + /// + /// The ordering guarantee: `reporter` is declared after `_guard` in + /// `install_acp_runtime_blocking` (line 311 vs line 306), so Rust drops + /// `reporter` first in reverse-declaration order — deactivation completes + /// before the runtime guard releases and a new install can start. + fn drop(&mut self) { + if let Some(live) = &self.live { + if let Ok(mut active) = live.lifecycle.write() { + *active = false; + } + } + } +} + impl InstallReporter { /// The reporter a real install run uses: it starts this run's log session /// and emits live output events through `app`. @@ -123,6 +147,7 @@ impl InstallReporter { emit, throttle: Arc::new(Throttle::new(LIVE_LINE_INTERVAL)), seq: Arc::new(AtomicU64::new(0)), + lifecycle: Arc::new(RwLock::new(true)), secrets: Arc::clone(&secrets), }); Self { log, live, secrets } @@ -213,25 +238,61 @@ struct Live { emit: EmitEvent, throttle: Arc, seq: Arc, + /// Lifecycle lock: `true` while the run is active, `false` once + /// `InstallReporter` has been dropped. + /// + /// Drain threads hold a **shared read guard** from the admission check + /// through the `(self.emit)(...)` call, making the admit-and-publish pair + /// atomic with respect to deactivation. `InstallReporter::drop` takes the + /// **exclusive write guard** and sets the value to `false`; this blocks + /// until every in-flight publication finishes, then prevents any new + /// publications from starting. The write lock is held only for the flag + /// store and is released before the per-runtime concurrency guard drops, + /// so its duration is bounded by the time a single `emit` call takes — + /// microseconds to low milliseconds for the Tauri IPC broadcast. + lifecycle: Arc>, secrets: Secrets, } impl Live { /// Offer one drained line to the rate limiter, emitting it if the window is /// open and holding it as the newest pending line if not. + /// + /// The read guard is held from the admission check through the emit call so + /// that `InstallReporter::drop`'s write lock must wait for any in-flight + /// publication to complete before deactivating. This makes the + /// check-then-emit pair atomic with respect to shutdown. fn offer(&self, line: &str) { + let Ok(guard) = self.lifecycle.read() else { + return; + }; + if !*guard { + return; + } if let Some(line) = self.throttle.offer(line, Instant::now()) { - self.publish(Some(line)); + self.publish_under_guard(line); } + // `guard` drops here, releasing the read lock after publication. } fn flush_pending(&self) { + let Ok(guard) = self.lifecycle.read() else { + return; + }; + if !*guard { + return; + } if let Some(line) = self.throttle.take_pending() { - self.publish(Some(line)); + self.publish_under_guard(line); } + // `guard` drops here, releasing the read lock after publication. } - /// Emit `line` now, bypassing the rate window. `None` clears the display. + /// Emit `line` now, bypassing the rate window and the lifecycle lock. + /// + /// Only called from `InstallReporter` methods that run on the reporter + /// itself (never from detached drain threads), so no lifecycle guard is + /// needed — the reporter is alive by definition when its own methods run. fn publish(&self, line: Option) { (self.emit)(InstallOutputEvent { runtime_id: self.runtime_id.to_string(), @@ -239,6 +300,16 @@ impl Live { line: line.map(|line| redact(&line, &self.secrets)), }); } + + /// Publish `line` while already holding a read guard on `lifecycle`. The + /// caller is responsible for checking `active` before calling this. + fn publish_under_guard(&self, line: String) { + (self.emit)(InstallOutputEvent { + runtime_id: self.runtime_id.to_string(), + seq: self.seq.fetch_add(1, Ordering::Relaxed), + line: Some(redact(&line, &self.secrets)), + }); + } } /// This run's log file: one session, opened once, appended to per record. diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs index fc8b793a1d..e136cc2e05 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -446,3 +446,258 @@ fn test_both_streams_of_one_attempt_share_the_rate_window() { fn test_no_observer_when_nothing_is_listening() { assert!(silent_reporter().line_observer().is_none()); } + +// ── late-drain deactivation ────────────────────────────────────────────────── + +/// After the reporter is dropped (run settled), a drain thread that still holds +/// a cloned observer must not be able to emit. The lifecycle lock is shared by +/// reference with every `line_observer` clone, so taking the exclusive write +/// lock in `Drop` — which waits out any in-flight read guards — ensures no +/// late event can reach the listener. +/// +/// The test resets the throttle via `start_attempt` before the late emit, so +/// the late line would be emitted unconditionally without the lifecycle lock. +#[test] +fn test_a_detached_observer_cannot_emit_after_the_reporter_is_dropped() { + let h = harness(); + + // Simulate a drain thread: `line_observer` clones `Live` (owned, not + // borrowed), so the closure outlives the reporter. + let observer = h.reporter.line_observer().expect("an observer"); + observer("before-settle"); + + assert_eq!( + h.lines(), + vec![Some("before-settle".to_string())], + "a live observer must emit before the reporter drops" + ); + + // Open a fresh throttle window so the next offer would emit immediately — + // simulating the drain arriving after the 250ms rate window closed. + h.reporter.start_attempt(); + let events = Arc::clone(&h.events); + + // Drop the reporter — takes the exclusive lifecycle write lock, waits for + // any in-flight publications, then deactivates. + drop(h); + + // A late offer after drop must be blocked by the deactivated lifecycle. + observer("late-drain-after-settle"); + + let lines: Vec> = events + .lock() + .unwrap() + .iter() + .map(|e| e.line.clone()) + .collect(); + assert_eq!( + lines, + // before-settle + the clear from start_attempt, no late line + vec![Some("before-settle".to_string()), None], + "a detached observer must not emit after the reporter is dropped" + ); +} + +/// Deterministic concurrency pin: proves that reporter deactivation cannot +/// complete while a drain thread is in-flight between admission and publication. +/// +/// The lifecycle `RwLock` enforces this: drain threads hold a shared read guard +/// for the entire (check → emit) span, so `InstallReporter::drop`'s write lock +/// blocks until every admitted publication finishes. +/// +/// **How this test fails on the old atomic shape** (`dc6421ac4`): on that shape, +/// `offer` loads `active` once as a plain atomic read and then calls `publish` +/// independently. There is no shared lock, so `drop` (an atomic store) can +/// complete while the thread is between the load and the emit — the test +/// exposes this by asserting the write lock CANNOT be acquired while a reader +/// holds a read guard. On the atomic shape the `lifecycle` field does not exist, +/// so the entire serialisation contract is absent and the pin fails. +#[test] +fn test_deactivation_blocks_until_in_flight_publication_completes() { + // Build a reporter and grab a Live clone that represents a drain thread. + let h = harness(); + let live_clone = { + // Extract the `Live` from a `line_observer` closure by temporarily + // building a second observer and using the lifecycle Arc directly. + h.reporter.line_observer().expect("observer"); + // Clone the inner lifecycle from the reporter's `Live` via a + // white-box path: the test module is a child of install_report and + // can access private fields. + h.reporter + .live + .as_ref() + .expect("live exists") + .lifecycle + .clone() + }; + + // Phase 1: acquire the shared read guard (admission). + let guard = live_clone.read().expect("lifecycle read"); + assert!(*guard, "lifecycle must be active at admission"); + + // Phase 2: while the read guard is held, a write lock must be blocked. + // This is the core serialisation invariant: `Drop` cannot complete until + // every admitted reader releases its guard. + assert!( + live_clone.try_write().is_err(), + "a write lock must not be acquirable while a read guard is held — \ + Drop must block while a publication is in-flight" + ); + + // Phase 3: release the read guard (publication completed). + drop(guard); + + // Phase 4: write lock is now available, and Drop can set active=false. + let mut write = live_clone.write().expect("lifecycle write"); + *write = false; + drop(write); + + // Phase 5: a new reader after deactivation sees active=false and returns. + let guard2 = live_clone.read().expect("lifecycle read"); + assert!( + !*guard2, + "lifecycle must be inactive after deactivation — new admissions rejected" + ); +} + +/// Shared-consumer assertion: drive a potential late run-1 event AND run-2's +/// events through the same `nextInstallOutputLine`-equivalent reducer and assert +/// that run 2's output replaces — not revives — any stale run-1 state. +/// +/// The frontend reduces events into a single consumer that resets to `null` +/// when `isInstalling` goes false (i.e., when the run settles). This test +/// models that reset and verifies the full cross-run contract: +/// +/// 1. Run 1 emits normally; the late drain is silenced by the lifecycle lock +/// (no event with a high run-1 `seq` ever reaches the shared sink). +/// 2. At run-1 settlement the consumer resets to `null`, exactly as the +/// frontend hook does when `isInstalling` becomes false. +/// 3. Run 2 starts, emits its `seq=0` clear and first line. With a null-state +/// consumer the reducer accepts both immediately — even if a late run-1 +/// event HAD arrived (it didn't), the reset would have cleared its seq. +/// +/// **Why this test fails on the old atomic shape**: without the lifecycle lock, +/// `obs1("late-run-one-drain")` emits a high-seq run-1 event into the shared +/// sink. That event arrives AFTER the consumer reset (its seq is accepted from +/// a null state), leaving `{ seq: N, line: "late-run-one-drain" }` in the +/// consumer. Run 2 then emits `seq=0` and `seq=1`, both ≤ N, so they are +/// rejected and the final state stays on run 1's output. +#[test] +fn test_run2_output_replaces_stale_run1_state_through_shared_consumer() { + // One shared event sink for all events from both runs, simulating the + // permanent frontend listener that receives all `acp-install-output` events. + let all_events: Arc>> = Arc::new(Mutex::new(Vec::new())); + // Track where run 1 settles so the consumer reset can be applied at the + // correct boundary in the fold below. + let run1_settle_len: Arc> = Arc::new(Mutex::new(0)); + let runtime_id = "goose"; + + // ── Run 1 ────────────────────────────────────────────────────────────── + let dir1 = tempfile::tempdir().expect("tempdir"); + let log1 = dir1.path().join("install-goose.log"); + let emit1: EmitEvent = { + let sink = Arc::clone(&all_events); + Arc::new(move |event| sink.lock().unwrap().push(event)) + }; + let reporter1 = InstallReporter::new( + runtime_id, + InstallLog::start(&log1, runtime_id, "1.0.0"), + Some(emit1), + ); + + reporter1.start_attempt(); + let obs1 = reporter1.line_observer().expect("observer"); + obs1("run-one-output"); + reporter1.record_attempt(1, &outcome("cli", true, "done")); + + // Drop reporter1 — deactivates obs1 via the exclusive lifecycle write lock, + // which blocks until any in-flight read guard (publication) has released. + drop(reporter1); + + // Record the sink length at settlement — this is the point where the + // frontend resets its consumer state to null (isInstalling = false). + *run1_settle_len.lock().unwrap() = all_events.lock().unwrap().len(); + + // A late drain from run 1 arrives after settlement. With the lifecycle + // lock this is silenced. Without the lock (old atomic shape) it would + // reach the sink with a high seq, poisoning the null-reset consumer before + // run 2 can emit its restarted seq=0. + // Reset the throttle so the offer would emit unconditionally if the lock + // were absent — this makes the mutation meaningful. + { + // We need a fresh throttle window. Simulate by directly restarting + // via a new reporter to touch the shared Live (not possible after drop), + // so instead just call offer — the throttle holds the last emit time + // from flush_pending, which was microseconds ago. Give the window time + // to expire so the offer fires immediately on the old atomic shape. + std::thread::sleep(Duration::from_millis(300)); + } + obs1("late-run-one-drain"); + + // ── Run 2 ────────────────────────────────────────────────────────────── + let dir2 = tempfile::tempdir().expect("tempdir"); + let log2 = dir2.path().join("install-goose.log"); + let emit2: EmitEvent = { + let sink = Arc::clone(&all_events); + Arc::new(move |event| sink.lock().unwrap().push(event)) + }; + let reporter2 = InstallReporter::new( + runtime_id, + InstallLog::start(&log2, runtime_id, "1.0.0"), + Some(emit2), + ); + + reporter2.start_attempt(); + let obs2 = reporter2.line_observer().expect("observer"); + obs2("run-two-first-line"); + reporter2.record_attempt(1, &outcome("cli", true, "done")); + + // ── Shared-consumer fold ──────────────────────────────────────────────── + // Fold all emitted events through the nextInstallOutputLine reducer logic. + // At the run-1 settlement boundary, reset consumer to null — exactly as + // the frontend hook does when isInstalling becomes false. + struct State { + seq: u64, + line: Option, + } + let settle_at = *run1_settle_len.lock().unwrap(); + let events = all_events.lock().unwrap().clone(); + let mut consumer: Option = None; + for (i, event) in events.iter().enumerate() { + // Simulate frontend reset at run-1 settlement boundary. + if i == settle_at { + consumer = None; + } + if event.runtime_id != runtime_id { + continue; + } + if let Some(ref c) = consumer { + if event.seq <= c.seq { + continue; // reject stale / out-of-order + } + } + consumer = Some(State { + seq: event.seq, + line: event.line.clone(), + }); + } + + // The final consumer state must be run 2's first line. + // + // With the lifecycle lock: obs1("late-run-one-drain") emits nothing, + // so after the null reset only run-2 events arrive — run 2 wins cleanly. + // + // Without the lifecycle lock (old atomic shape): obs1 emits the late line + // with a high seq into the already-reset (null) consumer, consumer becomes + // { seq: N, line: "late-run-one-drain" }. Run 2's seq=0/1 are both ≤ N + // and are rejected, leaving the final state on run 1's stale output. + let final_line = consumer + .as_ref() + .and_then(|s| s.line.as_deref()) + .unwrap_or(""); + assert_eq!( + final_line, "run-two-first-line", + "run 2 must replace — not revive — stale run-1 state through the shared consumer; \ + got: {final_line:?}" + ); +} From bc6710bb59109b6eef001fcb28df009deb234e0f Mon Sep 17 00:00:00 2001 From: npub1mn7jgtj4w2pd0g0zeuhxsa6jy6p0rewxz4kujt98my82ahfmp72sxjexk7 Date: Thu, 30 Jul 2026 11:20:36 -0400 Subject: [PATCH 6/9] fix(desktop): redact proxy and PAT credentials from all install surfaces MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit An install inherits Buzz's environment and installers echo it back, but the secret filter missed two credentials that are routinely present: proxy URLs carrying `user:password` userinfo, and personal access tokens under `GITHUB_PAT`/`GH_PAT`. Neither matched a name marker nor a value prefix, so an installer that printed one wrote it verbatim to the install log and the live output line. For proxies only the userinfo is treated as secret, not the whole value. An install that fails behind a proxy is diagnosable only if the record still says which proxy it went through, and the host and port are not the credential — redacting the entire value would destroy that while protecting nothing more. A bare username with no password is likewise not a credential, and scrubbing it would erase every occurrence of a common word from the log. PAT variables match `_PAT` as a suffix rather than a substring: `contains("_PAT")` would match every `*_PATH` variable and scrub directory names out of the whole file. The name-based and shape-based paths do not overlap. A token in our own environment under a PAT-ish name is caught by name whatever its shape; the GitHub value prefixes added to `redact_secrets_with` catch a token that reaches output from outside the environment — embedded in a git remote URL an installer echoes — which no name-based rule can see. That list lives in the shared scrubber so the next caller cannot silently miss GitHub tokens. The third surface was the step returned to the frontend: `InstallStepResult.stdout/stderr` came straight from the capture with no scrubbing, and `getInstallErrorMessage` renders it on failure. Scrubbing happens in the two reporter funnels every step already passes through, which covers the ordinary exit, the status-check failure and the timeout path together rather than at each construction site. Secret classification is split into a pure function so the proxy and PAT rules are assertable without exporting a live `HTTPS_PROXY` into the test process, where every HTTP client the suite builds would read it. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../commands/agent_discovery/install_exec.rs | 3 +- .../agent_discovery/install_report.rs | 135 +++++++++-- .../agent_discovery/install_report_tests.rs | 221 ++++++++++++++++-- .../src-tauri/src/managed_agents/backend.rs | 43 +++- 4 files changed, 355 insertions(+), 47 deletions(-) diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs index df2a6b70aa..3b94f2ef8a 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_exec.rs @@ -71,8 +71,7 @@ pub(super) fn run_install_command_with_retry( // new attempt happens to print something. reporter.start_attempt(); let outcome = run_install_command(step, command, reporter.line_observer()); - reporter.record_attempt(attempt, &outcome); - outcome.step + reporter.record_attempt(attempt, outcome) }, std::thread::sleep, ) diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs index 3e52f1cb3d..e364ba5062 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -141,7 +141,20 @@ impl InstallReporter { fn new(runtime_id: &str, log: Option, emit: Option) -> Self { // Snapshot the environment's secrets once, at construction: the install // inherits this environment, so anything it echoes came from here. - let secrets: Secrets = Arc::new(env_secret_values()); + Self::with_secrets(runtime_id, log, emit, env_secret_values()) + } + + /// The reporter over an explicit secret set, which is what makes the + /// scrubbing assertable: a test can name a proxy credential without + /// exporting a real `HTTPS_PROXY` into the process every HTTP client in the + /// suite would then read. + fn with_secrets( + runtime_id: &str, + log: Option, + emit: Option, + secrets: Vec, + ) -> Self { + let secrets: Secrets = Arc::new(secrets); let live = emit.map(|emit| Live { runtime_id: Arc::from(runtime_id), emit, @@ -197,14 +210,25 @@ impl InstallReporter { Some(Arc::new(move |line: &str| live.offer(line))) } - /// Record one executed attempt of a step. - pub(super) fn record_attempt(&self, attempt: u32, outcome: &InstallOutcome) { + /// Record one executed attempt of a step, returning the step with secrets + /// scrubbed out of the output the UI will render. + /// + /// The scrub happens here rather than at the construction sites because + /// every executed step reaches the caller through this function — the + /// timeout path, the status-check failure, and the ordinary exit all build + /// their `InstallStepResult` straight from the captures. + pub(super) fn record_attempt( + &self, + attempt: u32, + outcome: InstallOutcome, + ) -> InstallStepResult { // The drains are finished, so a line the throttle is still holding is // this attempt's last and nothing is coming to replace it. if let Some(live) = &self.live { live.flush_pending(); } - self.write_record(Some(attempt), outcome); + self.write_record(Some(attempt), &outcome); + self.redacted_step(outcome.step) } /// Push a synthesized step onto `steps` and record it. Routing every step @@ -212,7 +236,19 @@ impl InstallReporter { /// without passing this function is invisible in the file. pub(super) fn record_step(&self, steps: &mut Vec, step: InstallStepResult) { self.write_record(None, &InstallOutcome::synthesized(step.clone())); - steps.push(step); + steps.push(self.redacted_step(step)); + } + + /// Scrub the frontend-visible fields of a step. The failure message the UI + /// builds renders `stderr`/`stdout` and the hint verbatim, so they need the + /// same scrubbing as the log record and the live line — the log is not the + /// only place an install's output is read. + fn redacted_step(&self, mut step: InstallStepResult) -> InstallStepResult { + step.command = redact(&step.command, &self.secrets); + step.stdout = redact(&step.stdout, &self.secrets); + step.stderr = redact(&step.stderr, &self.secrets); + step.hint = step.hint.map(|hint| redact(&hint, &self.secrets)); + step } /// Append one record. Best-effort by contract: a full disk or a revoked @@ -419,16 +455,55 @@ fn redact(text: &str, secrets: &Secrets) -> String { /// /// An install inherits Buzz's environment and installers echo it back — npm /// prints the resolved registry config on an auth failure, and a shell that -/// traces its commands prints every expansion. Without this, only the two +/// traces its commands prints every expansion. Without this, only the /// hard-coded key shapes would be scrubbed, so a plain `NPM_TOKEN` or /// `ANTHROPIC_API_KEY` would land in the file in clear text. -/// -/// Keyed on the name because a secret's *value* has no reliable shape. Two -/// filters keep ordinary output readable: a value under 8 bytes is skipped -/// (more likely a flag like `true` or a version than a credential), and the -/// markers avoid substrings that occur in non-secret names — `AUTH` is left out -/// because it matches `GIT_AUTHOR_NAME`, whose value is a person's name. fn env_secret_values() -> Vec { + secret_values_from(std::env::vars()) +} + +/// The secret-bearing part of each variable that carries one. +/// +/// Split from [`env_secret_values`] so the classification is assertable without +/// mutating the process environment — setting a real `HTTPS_PROXY` in a test +/// would be read by every HTTP client the rest of the suite builds. +/// +/// Two kinds of variable are recognised, because they need opposite treatment: +/// +/// * **name-marked secrets**, whose whole value is the credential; and +/// * **proxy URLs**, where only the userinfo is the credential. +fn secret_values_from(vars: impl IntoIterator) -> Vec { + vars.into_iter() + .filter_map(|(name, value)| { + let name = name.to_ascii_uppercase(); + if PROXY_VAR_NAMES.contains(&name.as_str()) { + // Only the userinfo, so the proxy itself stays named in the + // record: an install that fails behind a proxy is diagnosable + // only if the log still says which proxy it went through, and + // the host and port are not the secret. Redacting the whole + // value would erase that while protecting nothing more. + return proxy_userinfo(&value).map(str::to_string); + } + // A value under 8 bytes is more likely a flag like `true` or a + // version than a credential, and scrubbing those makes ordinary + // output unreadable. + (value.len() >= 8 && name_marks_secret(&name)).then_some(value) + }) + .collect() +} + +/// Proxy variables whose value embeds a credential in its userinfo. +const PROXY_VAR_NAMES: &[&str] = &["HTTP_PROXY", "HTTPS_PROXY", "ALL_PROXY"]; + +/// Whether an environment variable's name marks its value as a credential. +/// +/// Keyed on the name because a secret's *value* has no reliable shape. The +/// markers avoid substrings that occur in non-secret names: `AUTH` is left out +/// because it matches `GIT_AUTHOR_NAME`, whose value is a person's name, and +/// personal access tokens match on `_PAT` as a *suffix* rather than a substring +/// — `contains("_PAT")` would match every `*_PATH` variable on the system and +/// scrub directory names out of the whole log. +fn name_marks_secret(name: &str) -> bool { const SECRET_NAME_MARKERS: &[&str] = &[ "TOKEN", "SECRET", @@ -440,17 +515,31 @@ fn env_secret_values() -> Vec { "ACCESS_KEY", "CREDENTIAL", ]; - std::env::vars() - .filter(|(name, value)| { - value.len() >= 8 && { - let name = name.to_ascii_uppercase(); - SECRET_NAME_MARKERS - .iter() - .any(|marker| name.contains(marker)) - } - }) - .map(|(_, value)| value) - .collect() + name.ends_with("_PAT") + || SECRET_NAME_MARKERS + .iter() + .any(|marker| name.contains(marker)) +} + +/// The `user:password` credential embedded in a proxy URL, if it has one. +/// +/// Parsed rather than pattern-matched so a proxy URL with no credential — +/// the common case — contributes nothing to scrub. The last `@` in the +/// authority separates userinfo from host, so a password containing an +/// encoded `@` still splits correctly. +/// +/// A bare username with no password is not treated as a credential: it is not +/// secret on its own, and scrubbing it would erase every occurrence of a word +/// like `user` from the whole record. +fn proxy_userinfo(value: &str) -> Option<&str> { + let authority = value + .split_once("://")? + .1 + .split(['/', '?', '#']) + .next() + .unwrap_or_default(); + let userinfo = authority.rsplit_once('@')?.0; + userinfo.contains(':').then_some(userinfo) } #[cfg(test)] diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs index e136cc2e05..e160a902e8 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -21,6 +21,16 @@ fn harness() -> Harness { /// A harness whose log lives in `dir`, or in a fresh temp dir when `dir` is /// `None`. Passing a directory lets a test seed a previous run's file first. fn harness_at(dir: Option) -> Harness { + harness_inner(dir, None) +} + +/// A harness whose reporter scrubs exactly `secrets`, so a proxy or PAT +/// credential can be asserted without exporting it into the process. +fn harness_with_secrets(secrets: Vec) -> Harness { + harness_inner(None, Some(secrets)) +} + +fn harness_inner(dir: Option, secrets: Option>) -> Harness { let dir = dir.unwrap_or_else(|| tempfile::tempdir().expect("tempdir")); let log = dir.path().join("install-goose.log"); let events: Arc>> = Arc::new(Mutex::new(Vec::new())); @@ -28,12 +38,12 @@ fn harness_at(dir: Option) -> Harness { let events = Arc::clone(&events); Arc::new(move |event| events.lock().unwrap().push(event)) }; + let started = InstallLog::start(&log, "goose", TEST_APP_VERSION); Harness { - reporter: InstallReporter::new( - "goose", - InstallLog::start(&log, "goose", TEST_APP_VERSION), - Some(emit), - ), + reporter: match secrets { + Some(secrets) => InstallReporter::with_secrets("goose", started, Some(emit), secrets), + None => InstallReporter::new("goose", started, Some(emit)), + }, _dir: dir, log, events, @@ -96,9 +106,9 @@ fn test_log_records_every_attempt_not_only_the_last() { let h = harness(); h.reporter - .record_attempt(1, &outcome("cli", false, "attempt-one-output")); + .record_attempt(1, outcome("cli", false, "attempt-one-output")); h.reporter - .record_attempt(2, &outcome("cli", false, "attempt-two-output")); + .record_attempt(2, outcome("cli", false, "attempt-two-output")); let log = h.log_contents(); assert!(log.contains("attempt-one-output"), "got: {log}"); @@ -125,9 +135,9 @@ fn test_first_attempt_overflow_does_not_erase_later_records() { drain_into(vec![b'F'; 4 * 1024 * 1024].as_slice(), &capture, None); h.reporter - .record_attempt(1, &outcome("cli", false, &capture.log())); + .record_attempt(1, outcome("cli", false, &capture.log())); h.reporter - .record_attempt(2, &outcome("cli", false, "second-attempt-detail")); + .record_attempt(2, outcome("cli", false, "second-attempt-detail")); h.reporter.record_step( &mut Vec::new(), step("verify", false, "verification-detail"), @@ -198,7 +208,7 @@ fn test_a_new_run_starts_a_fresh_file_and_keeps_the_previous_as_dot_one() { let first = harness(); first .reporter - .record_attempt(1, &outcome("cli", false, "previous-run-output")); + .record_attempt(1, outcome("cli", false, "previous-run-output")); let previous = first.log.clone(); let dir = first._dir; drop(first.reporter); @@ -206,7 +216,7 @@ fn test_a_new_run_starts_a_fresh_file_and_keeps_the_previous_as_dot_one() { let second = harness_at(Some(dir)); second .reporter - .record_attempt(1, &outcome("cli", false, "current-run-output")); + .record_attempt(1, outcome("cli", false, "current-run-output")); let log = second.log_contents(); assert!(log.contains("current-run-output"), "got: {log}"); @@ -228,7 +238,7 @@ fn test_an_executed_attempt_records_its_own_duration() { let h = harness(); h.reporter.start_attempt(); - h.reporter.record_attempt(1, &outcome("cli", true, "done")); + h.reporter.record_attempt(1, outcome("cli", true, "done")); h.reporter .record_step(&mut Vec::new(), step("verify", true, "")); @@ -252,7 +262,7 @@ fn test_log_redacts_secrets_before_writing() { let h = harness(); let leak = "npm ERR! token nsec1qqqqqqqqqqsecretvalue failed"; - h.reporter.record_attempt(1, &outcome("cli", false, leak)); + h.reporter.record_attempt(1, outcome("cli", false, leak)); let log = h.log_contents(); assert!(!log.contains("nsec1qqqqqqqqqqsecretvalue"), "got: {log}"); @@ -273,7 +283,7 @@ fn test_log_redacts_an_environment_secret_with_no_recognizable_prefix() { h.reporter.record_attempt( 1, - &outcome("cli", false, &format!("npm ERR! _authToken={secret}")), + outcome("cli", false, &format!("npm ERR! _authToken={secret}")), ); let log = h.log_contents(); @@ -297,6 +307,179 @@ fn test_a_live_line_is_redacted_before_it_is_emitted() { assert!(line.contains("[REDACTED]"), "got: {line}"); } +// ── proxy and PAT credentials ──────────────────────────────────────────────── + +/// A proxy URL's password is a credential, but the proxy itself is diagnostic +/// information: an install that fails behind a proxy is only debuggable if the +/// record still says which proxy it went through. So the userinfo is scrubbed +/// and the host is kept. +#[test] +fn test_proxy_userinfo_is_secret_but_the_proxy_host_is_not() { + let secrets = secret_values_from([( + "HTTPS_PROXY".to_string(), + "http://corpuser:hunter2pass@proxy.example:8080".to_string(), + )]); + + assert_eq!(secrets, vec!["corpuser:hunter2pass"]); +} + +/// A proxy with no credential contributes nothing — scrubbing a bare host would +/// erase the proxy's name from every record while protecting nothing. A bare +/// username is not a credential either, and scrubbing it would delete every +/// occurrence of that word from the log. +#[test] +fn test_a_proxy_without_credentials_contributes_no_secret() { + let secrets = secret_values_from([ + ( + "HTTP_PROXY".to_string(), + "http://proxy.example:8080".to_string(), + ), + ( + "ALL_PROXY".to_string(), + "socks5://10.0.0.1:1080".to_string(), + ), + ( + "HTTPS_PROXY".to_string(), + "http://user@proxy.example:8080".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// `*_PATH` variables must not be mistaken for personal access tokens. A +/// `contains("_PAT")` rule would match `PATH` itself and scrub every directory +/// name out of the log, which is why the rule matches `_PAT` as a suffix. +#[test] +fn test_a_path_variable_is_not_treated_as_a_personal_access_token() { + let secrets = secret_values_from([ + ("PATH".to_string(), "/usr/local/bin:/usr/bin".to_string()), + ("GOPATH".to_string(), "/home/user/go".to_string()), + ( + "CARGO_HOME_PATH".to_string(), + "/home/user/.cargo".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// Variables named as personal access tokens are secret by name, whatever shape +/// their value has. +#[test] +fn test_pat_named_variables_are_secret() { + let secrets = secret_values_from([ + ( + "GITHUB_PAT".to_string(), + "ghp_abcdefghij0123456789".to_string(), + ), + ( + "GH_PAT".to_string(), + "github_pat_abcdefghij0123".to_string(), + ), + ]); + + assert_eq!(secrets.len(), 2, "got: {secrets:?}"); +} + +/// The whole point of the widening: a proxy password and a PAT that the +/// installer echoed reach neither the log nor the live line. +/// +/// Both are checked through the real reporter rather than the classifier, so +/// this covers the wiring — a classifier that recognises a secret the reporter +/// never consults would still leak. +#[test] +fn test_proxy_and_pat_credentials_are_redacted_from_the_log_and_the_live_line() { + let proxy_password = "hunter2pass"; + let pat = "ghp_abcdefghij0123456789"; + // The classifier's own tests cover recognising these under their real + // variable names; injecting the resulting secrets here keeps a live + // `HTTPS_PROXY` out of the process the rest of the suite shares. + let h = harness_with_secrets(vec![format!("corpuser:{proxy_password}"), pat.to_string()]); + + h.reporter.record_attempt( + 1, + outcome( + "cli", + false, + &format!( + "npm ERR! proxy=http://corpuser:{proxy_password}@proxy.example authToken={pat}" + ), + ), + ); + let observer = h.reporter.line_observer().expect("an observer"); + observer(&format!("cloning https://{pat}@github.com/org/repo")); + + let log = h.log_contents(); + assert!( + !log.contains(proxy_password), + "log leaked the proxy password: {log}" + ); + assert!(!log.contains(pat), "log leaked the PAT: {log}"); + assert!( + log.contains("proxy.example"), + "the proxy host is diagnostic and must survive: {log}" + ); + + let line = h.lines().into_iter().flatten().next().expect("a live line"); + assert!(!line.contains(pat), "live line leaked the PAT: {line}"); + assert!(line.contains("[REDACTED]"), "got: {line}"); +} + +/// The third surface: the step returned to the frontend. `getInstallErrorMessage` +/// renders the failing step's stderr verbatim, so a secret that the log and the +/// live line both scrub would still reach the user through the error dialog. +#[test] +fn test_a_returned_step_is_redacted_before_the_frontend_renders_it() { + let pat = "ghp_abcdefghij0123456789"; + let h = harness_with_secrets(vec![pat.to_string()]); + + let returned = h.reporter.record_attempt( + 1, + InstallOutcome { + step: InstallStepResult { + stdout: format!("configuring remote with {pat}"), + stderr: format!("fatal: authentication failed for token {pat}"), + hint: Some(format!("check that {pat} has the repo scope")), + ..step("cli", false, "") + }, + log_stdout: String::new(), + log_stderr: String::new(), + }, + ); + + assert!(!returned.stdout.contains(pat), "got: {}", returned.stdout); + assert!(!returned.stderr.contains(pat), "got: {}", returned.stderr); + let hint = returned.hint.expect("a hint"); + assert!(!hint.contains(pat), "got: {hint}"); +} + +/// A synthesized step reaches the frontend through the other funnel, and needs +/// the same scrubbing — the managed-node prerequisite failures are built this +/// way and carry whatever the underlying command printed. +#[test] +fn test_a_synthesized_step_is_redacted_before_it_reaches_the_caller() { + let pat = "ghp_abcdefghij0123456789"; + let h = harness_with_secrets(vec![pat.to_string()]); + let mut steps = Vec::new(); + + h.reporter.record_step( + &mut steps, + InstallStepResult { + stderr: format!("npm ERR! 401 with {pat}"), + ..step("adapter", false, "") + }, + ); + + assert_eq!(steps.len(), 1); + assert!(!steps[0].stderr.contains(pat), "got: {}", steps[0].stderr); + assert!( + steps[0].stderr.contains("[REDACTED]"), + "got: {}", + steps[0].stderr + ); +} + // ── the log pointer ────────────────────────────────────────────────────────── /// The path is available as soon as the run's session opens, because the file @@ -317,7 +500,7 @@ fn test_reporter_without_a_log_records_nothing_and_reports_no_path() { let mut steps = Vec::new(); reporter.start_attempt(); - reporter.record_attempt(1, &outcome("cli", false, "output")); + reporter.record_attempt(1, outcome("cli", false, "output")); reporter.record_step(&mut steps, step("verify", false, "detail")); assert_eq!(reporter.log_path(), None); @@ -411,7 +594,7 @@ fn test_a_burst_coalesces_to_the_newest_line_not_the_first() { observer("two"); observer("three"); // Ends the attempt, which is when a held line is known to be the last. - h.reporter.record_attempt(1, &outcome("cli", true, "done")); + h.reporter.record_attempt(1, outcome("cli", true, "done")); assert_eq!( h.lines(), @@ -431,7 +614,7 @@ fn test_both_streams_of_one_attempt_share_the_rate_window() { stdout("progress"); stderr("warning"); - h.reporter.record_attempt(1, &outcome("cli", true, "done")); + h.reporter.record_attempt(1, outcome("cli", true, "done")); assert_eq!( h.lines(), @@ -608,7 +791,7 @@ fn test_run2_output_replaces_stale_run1_state_through_shared_consumer() { reporter1.start_attempt(); let obs1 = reporter1.line_observer().expect("observer"); obs1("run-one-output"); - reporter1.record_attempt(1, &outcome("cli", true, "done")); + reporter1.record_attempt(1, outcome("cli", true, "done")); // Drop reporter1 — deactivates obs1 via the exclusive lifecycle write lock, // which blocks until any in-flight read guard (publication) has released. @@ -650,7 +833,7 @@ fn test_run2_output_replaces_stale_run1_state_through_shared_consumer() { reporter2.start_attempt(); let obs2 = reporter2.line_observer().expect("observer"); obs2("run-two-first-line"); - reporter2.record_attempt(1, &outcome("cli", true, "done")); + reporter2.record_attempt(1, outcome("cli", true, "done")); // ── Shared-consumer fold ──────────────────────────────────────────────── // Fold all emitted events through the nextInstallOutputLine reducer logic. diff --git a/desktop/src-tauri/src/managed_agents/backend.rs b/desktop/src-tauri/src/managed_agents/backend.rs index 3f96229404..5debae41cb 100644 --- a/desktop/src-tauri/src/managed_agents/backend.rs +++ b/desktop/src-tauri/src/managed_agents/backend.rs @@ -305,9 +305,23 @@ pub(crate) fn redact_secrets_with(s: &str, extras: &[&str]) -> String { // Then prefix-based scrubbing. This loop *can* re-scan because each // replacement shortens the buffer past the matched prefix — the - // replacement marker `[REDACTED]` does not contain `nsec1` or - // `sprt_tok_`, so progress is guaranteed. - for prefix in &["nsec1", "sprt_tok_"] { + // replacement marker `[REDACTED]` contains none of these prefixes, so + // progress is guaranteed. Any prefix added here must preserve that. + // + // GitHub tokens are recognised by shape as well as by variable name: a + // token reaches output from outside our environment too — embedded in a + // git remote URL an installer echoes, say — where no name-based rule can + // see it. + for prefix in &[ + "nsec1", + "sprt_tok_", + "ghp_", + "gho_", + "ghu_", + "ghs_", + "ghr_", + "github_pat_", + ] { while let Some(pos) = result.find(prefix) { let end = result[pos..] .find(|c: char| c.is_whitespace() || c == '"' || c == '\'') @@ -563,6 +577,29 @@ mod tests { assert!(r.contains("42")); } + /// GitHub tokens are recognised by shape, so one that never passed through + /// our environment — embedded in a remote URL an installer echoes — is + /// still scrubbed. The scan runs to the next whitespace or quote, so the + /// rest of the URL goes with it; over-redaction is the safe direction. + #[test] + fn redact_secrets_with_scrubs_github_token_prefixes() { + for token in [ + "ghp_abcdefghij0123456789", + "gho_abcdefghij0123456789", + "ghu_abcdefghij0123456789", + "ghs_abcdefghij0123456789", + "ghr_abcdefghij0123456789", + "github_pat_abcdefghij0123456789", + ] { + let r = + redact_secrets_with(&format!("cloning https://{token}@github.com/o/r now"), &[]); + assert!(!r.contains(token), "leaked {token}: {r}"); + assert!(r.contains("[REDACTED]"), "got: {r}"); + assert!(r.contains("cloning"), "scan must stop at whitespace: {r}"); + assert!(r.ends_with(" now"), "scan must stop at whitespace: {r}"); + } + } + #[test] fn redact_secrets_with_extras_terminates_when_value_substring_of_marker() { // Regression: an earlier impl used `while let Some(pos) = find(value)` From b2147dc4e750cb776dac60665b5dca1c563690f8 Mon Sep 17 00:00:00 2001 From: npub1mn7jgtj4w2pd0g0zeuhxsa6jy6p0rewxz4kujt98my82ahfmp72sxjexk7 Date: Thu, 30 Jul 2026 13:09:38 -0400 Subject: [PATCH 7/9] fix(desktop): redact credentials from npm proxy alias variables npm resolves NPM_CONFIG_PROXY and NPM_CONFIG_HTTPS_PROXY ahead of the conventional proxy variables and echoes the resolved value back, but neither name carries a marker the name-based classifier recognises, so a credential set only under an alias never entered the scrub list and could reach the log, the live output line and the returned UI step. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../agent_discovery/install_report.rs | 14 ++- .../agent_discovery/install_report_tests.rs | 96 +++++++++++++++++++ 2 files changed, 109 insertions(+), 1 deletion(-) diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs index e364ba5062..9fb96c55d2 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -493,7 +493,19 @@ fn secret_values_from(vars: impl IntoIterator) -> Vec Date: Thu, 30 Jul 2026 14:07:27 -0400 Subject: [PATCH 8/9] fix(desktop): redact npm's registry credential settings MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit npm accepts every setting as an npm_config_* environment variable and echoes its resolved config on an auth failure, so a client key, a basic-auth blob, a one-time password or a credentialed registry URL could reach the install log, the live output line and the returned UI step. None of those names carries a marker the name-based classifier recognises. The credentials are listed by exact name rather than matched on KEY or AUTH substrings: both occur throughout an ordinary environment on values that are paths and people's names, and scrubbing on them would delete unrelated text from every record. The registry follows the proxy policy instead — which registry an install talked to is what a 401 has to be read against — so only its userinfo is secret, which is why the URL list is no longer proxy-specific. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../agent_discovery/install_report.rs | 66 +++++--- .../agent_discovery/install_report_tests.rs | 155 ++++++++++++++++++ 2 files changed, 202 insertions(+), 19 deletions(-) diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs index 9fb96c55d2..949d5bb5aa 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -468,21 +468,34 @@ fn env_secret_values() -> Vec { /// mutating the process environment — setting a real `HTTPS_PROXY` in a test /// would be read by every HTTP client the rest of the suite builds. /// -/// Two kinds of variable are recognised, because they need opposite treatment: +/// Three kinds of variable are recognised, because they need different +/// treatment: /// -/// * **name-marked secrets**, whose whole value is the credential; and -/// * **proxy URLs**, where only the userinfo is the credential. +/// * **URL-valued variables**, where only the userinfo is the credential; +/// * **exactly named credentials**, whose whole value is the secret; and +/// * **name-marked secrets**, matched by a marker substring. fn secret_values_from(vars: impl IntoIterator) -> Vec { vars.into_iter() .filter_map(|(name, value)| { let name = name.to_ascii_uppercase(); - if PROXY_VAR_NAMES.contains(&name.as_str()) { - // Only the userinfo, so the proxy itself stays named in the - // record: an install that fails behind a proxy is diagnosable - // only if the log still says which proxy it went through, and - // the host and port are not the secret. Redacting the whole - // value would erase that while protecting nothing more. - return proxy_userinfo(&value).map(str::to_string); + if URL_CREDENTIAL_VAR_NAMES.contains(&name.as_str()) { + // Only the userinfo, so the endpoint itself stays named in the + // record: an install that fails against a proxy or a private + // registry is diagnosable only if the log still says which one + // it went through, and the host and port are not the secret. + // Redacting the whole value would erase that while protecting + // nothing more. + return url_userinfo(&value).map(str::to_string); + } + if SECRET_VAR_NAMES.contains(&name.as_str()) { + // Deliberately not subject to the 8-byte floor below: an exact + // name is a fact, not the guess the marker rule makes, so there + // is nothing for a floor to protect against. npm's one-time + // password is six digits and is a credential at that length — + // short, but still above the four-byte minimum + // [`crate::managed_agents::redact_secrets_with`] applies, so it + // survives to be scrubbed. + return (!value.is_empty()).then_some(value); } // A value under 8 bytes is more likely a flag like `true` or a // version than a credential, and scrubbing those makes ordinary @@ -492,21 +505,36 @@ fn secret_values_from(vars: impl IntoIterator) -> Vec bool { .any(|marker| name.contains(marker)) } -/// The `user:password` credential embedded in a proxy URL, if it has one. +/// The `user:password` credential embedded in a URL, if it has one. /// -/// Parsed rather than pattern-matched so a proxy URL with no credential — -/// the common case — contributes nothing to scrub. The last `@` in the +/// Parsed rather than pattern-matched so a URL with no credential — the common +/// case — contributes nothing to scrub. The last `@` in the /// authority separates userinfo from host, so a password containing an /// encoded `@` still splits correctly. /// /// A bare username with no password is not treated as a credential: it is not /// secret on its own, and scrubbing it would erase every occurrence of a word /// like `user` from the whole record. -fn proxy_userinfo(value: &str) -> Option<&str> { +fn url_userinfo(value: &str) -> Option<&str> { let authority = value .split_once("://")? .1 diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs index f5735d99aa..60fd810776 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -443,6 +443,161 @@ fn test_an_npm_alias_credential_is_redacted_from_the_log_and_the_returned_step() ); } +// ── npm's own credential settings ──────────────────────────────────────────── + +/// npm accepts every one of its settings as an `npm_config_*` variable, so a +/// registry client key, a basic-auth blob or a one-time password can arrive +/// under a name that carries no marker. Their whole value is the credential — +/// unlike a proxy, none of it is diagnostic — and npm spells them in lowercase. +#[test] +fn test_npm_credential_configs_are_secret_in_either_case() { + let secrets = secret_values_from([ + ( + "npm_config_key".to_string(), + "-----BEGIN PRIVATE KEY-----lowerkey".to_string(), + ), + ( + "NPM_CONFIG_KEY".to_string(), + "-----BEGIN PRIVATE KEY-----upperkey".to_string(), + ), + ("npm_config__auth".to_string(), "bG93ZXJhdXRo".to_string()), + ("NPM_CONFIG__AUTH".to_string(), "dXBwZXJhdXRo".to_string()), + ("npm_config_otp".to_string(), "618243".to_string()), + ("NPM_CONFIG_OTP".to_string(), "907154".to_string()), + ]); + + assert_eq!( + secrets, + vec![ + "-----BEGIN PRIVATE KEY-----lowerkey", + "-----BEGIN PRIVATE KEY-----upperkey", + "bG93ZXJhdXRo", + "dXBwZXJhdXRo", + "618243", + "907154", + ] + ); +} + +/// An unset-but-exported credential is empty, and an empty needle would match +/// everywhere. The name being exact does not make a blank value a secret. +#[test] +fn test_an_empty_npm_credential_config_contributes_no_secret() { + let secrets = secret_values_from([ + ("NPM_CONFIG_KEY".to_string(), String::new()), + ("npm_config_otp".to_string(), String::new()), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// A private registry's URL follows the proxy policy rather than the whole-value +/// one: which registry an install talked to is exactly what a 401 or an ETIMEDOUT +/// has to be read against, so only the userinfo is the secret. +#[test] +fn test_npm_registry_userinfo_is_secret_but_the_registry_host_is_not() { + let secrets = secret_values_from([( + "npm_config_registry".to_string(), + "https://builder:hunter2pass@registry.example/api/npm/".to_string(), + )]); + + assert_eq!(secrets, vec!["builder:hunter2pass"]); +} + +/// The public registry — and any private one reached with a token header rather +/// than URL credentials — contributes nothing, so the registry stays named in +/// the record. +#[test] +fn test_an_npm_registry_without_credentials_contributes_no_secret() { + let secrets = secret_values_from([ + ( + "npm_config_registry".to_string(), + "https://registry.npmjs.org/".to_string(), + ), + ( + "NPM_CONFIG_REGISTRY".to_string(), + "https://builder@registry.example/api/npm/".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// The credential settings are matched by exact name, never by a `KEY` or +/// `AUTH` substring. Those occur throughout an ordinary environment on values +/// that are paths, agent sockets and people's names, and scrubbing them would +/// delete unrelated text from every record. +#[test] +fn test_key_and_auth_inside_a_variable_name_do_not_make_it_secret() { + let secrets = secret_values_from([ + ( + "SSH_AUTH_SOCK".to_string(), + "/tmp/ssh-agent.socket".to_string(), + ), + ("GIT_AUTHOR_NAME".to_string(), "Ada Lovelace".to_string()), + ( + "KEYCHAIN".to_string(), + "/Users/dev/Library/login.keychain".to_string(), + ), + ( + "NPM_CONFIG_KEYFILE".to_string(), + "/Users/dev/.npm/client.pem".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// The wiring, not just the classification: npm prints its resolved config on an +/// auth failure, so each of these has to be gone from the log and from the step +/// the frontend renders. The one-time password is the interesting one — at six +/// digits it is far shorter than any other secret here, and a value under four +/// bytes is dropped by the shared redactor rather than scrubbed. +#[test] +fn test_npm_credential_configs_are_redacted_from_the_log_and_the_returned_step() { + let client_key = "-----BEGIN PRIVATE KEY-----MIIEvQIBADAN"; + let auth = "YnVpbGRlcjpodW50ZXIycGFzcw=="; + let otp = "618243"; + let registry_password = "hunter2pass"; + let h = harness_with_secrets(secret_values_from([ + ("npm_config_key".to_string(), client_key.to_string()), + ("npm_config__auth".to_string(), auth.to_string()), + ("npm_config_otp".to_string(), otp.to_string()), + ( + "npm_config_registry".to_string(), + format!("https://builder:{registry_password}@registry.example/api/npm/"), + ), + ])); + + let returned = h.reporter.record_attempt( + 1, + InstallOutcome { + step: InstallStepResult { + stderr: format!("npm ERR! 401 otp={otp} _auth={auth}"), + ..step("cli", false, "") + }, + log_stdout: format!("npm config: key = {client_key}"), + log_stderr: format!( + "npm config: registry = https://builder:{registry_password}@registry.example/api/npm/" + ), + }, + ); + + let log = h.log_contents(); + for secret in [client_key, auth, otp, registry_password] { + assert!(!log.contains(secret), "log leaked {secret}: {log}"); + } + assert!( + log.contains("registry.example"), + "the registry host is diagnostic and must survive: {log}" + ); + assert!( + !returned.stderr.contains(otp) && !returned.stderr.contains(auth), + "the returned step leaked a credential: {}", + returned.stderr + ); +} + /// `*_PATH` variables must not be mistaken for personal access tokens. A /// `contains("_PAT")` rule would match `PATH` itself and scrub every directory /// name out of the log, which is why the rule matches `_PAT` as a suffix. From 1ecf0edb9e3d85b895a5ff02450ef9c84c3078e3 Mon Sep 17 00:00:00 2001 From: npub1mn7jgtj4w2pd0g0zeuhxsa6jy6p0rewxz4kujt98my82ahfmp72sxjexk7 Date: Thu, 30 Jul 2026 14:25:23 -0400 Subject: [PATCH 9/9] refactor(desktop): split the install-report tests by concern The redaction cases grew the single test file past the desktop 1000-line ratchet, which is a hard cap for a file that does not exist on main. They are a self-contained concern, so they move to their own module alongside the shared harness, following the split migration.rs already uses. No test changes: 37 before, 37 after. Co-authored-by: Will Pfleger Signed-off-by: Will Pfleger --- .../agent_discovery/install_report.rs | 8 + .../install_report_redaction_tests.rs | 480 +++++++++++++++ .../install_report_test_support.rs | 106 ++++ .../agent_discovery/install_report_tests.rs | 575 +----------------- 4 files changed, 595 insertions(+), 574 deletions(-) create mode 100644 desktop/src-tauri/src/commands/agent_discovery/install_report_redaction_tests.rs create mode 100644 desktop/src-tauri/src/commands/agent_discovery/install_report_test_support.rs diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs index 949d5bb5aa..24bcd3456a 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -582,6 +582,14 @@ fn url_userinfo(value: &str) -> Option<&str> { userinfo.contains(':').then_some(userinfo) } +#[cfg(test)] +#[path = "install_report_test_support.rs"] +mod test_support; + #[cfg(test)] #[path = "install_report_tests.rs"] mod tests; + +#[cfg(test)] +#[path = "install_report_redaction_tests.rs"] +mod redaction_tests; diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_redaction_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_redaction_tests.rs new file mode 100644 index 0000000000..ce97559616 --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_redaction_tests.rs @@ -0,0 +1,480 @@ +use super::test_support::*; +use super::*; + +// ── redaction ──────────────────────────────────────────────────────────────── + +/// Secrets that an installer echoed must not land on disk. The log is written +/// unattended, so scrubbing happens at the write, not at the read. +#[test] +fn test_log_redacts_secrets_before_writing() { + let h = harness(); + let leak = "npm ERR! token nsec1qqqqqqqqqqsecretvalue failed"; + + h.reporter.record_attempt(1, outcome("cli", false, leak)); + + let log = h.log_contents(); + assert!(!log.contains("nsec1qqqqqqqqqqsecretvalue"), "got: {log}"); + assert!(log.contains("[REDACTED]"), "got: {log}"); +} + +/// The environment's own secrets are scrubbed too, by *name* rather than shape. +/// An install inherits Buzz's environment and installers echo it back — npm +/// prints its resolved config on an auth failure — and a token with no +/// recognizable prefix would otherwise reach the file verbatim. +#[test] +fn test_log_redacts_an_environment_secret_with_no_recognizable_prefix() { + let secret = "0e8f31c5a4b7d296e5f1a"; + // Set before the reporter is built: the snapshot is taken at construction. + std::env::set_var("BUZZ_TEST_REGISTRY_TOKEN", secret); + let h = harness(); + std::env::remove_var("BUZZ_TEST_REGISTRY_TOKEN"); + + h.reporter.record_attempt( + 1, + outcome("cli", false, &format!("npm ERR! _authToken={secret}")), + ); + + let log = h.log_contents(); + assert!(!log.contains(secret), "got: {log}"); + assert!(log.contains("[REDACTED]"), "got: {log}"); +} + +/// A live line carries the same scrubbing as the log record. The line is +/// rendered verbatim in the UI, so a leak there is as visible as one on disk. +#[test] +fn test_a_live_line_is_redacted_before_it_is_emitted() { + let h = harness(); + + let observer = h.reporter.line_observer().expect("an observer"); + observer("fetching with token nsec1qqqqqqqqqqleaked"); + + let lines = h.lines(); + assert_eq!(lines.len(), 1); + let line = lines[0].clone().expect("a line, not a clear signal"); + assert!(!line.contains("nsec1qqqqqqqqqqleaked"), "got: {line}"); + assert!(line.contains("[REDACTED]"), "got: {line}"); +} + +// ── proxy and PAT credentials ──────────────────────────────────────────────── + +/// A proxy URL's password is a credential, but the proxy itself is diagnostic +/// information: an install that fails behind a proxy is only debuggable if the +/// record still says which proxy it went through. So the userinfo is scrubbed +/// and the host is kept. +#[test] +fn test_proxy_userinfo_is_secret_but_the_proxy_host_is_not() { + let secrets = secret_values_from([( + "HTTPS_PROXY".to_string(), + "http://corpuser:hunter2pass@proxy.example:8080".to_string(), + )]); + + assert_eq!(secrets, vec!["corpuser:hunter2pass"]); +} + +/// A proxy with no credential contributes nothing — scrubbing a bare host would +/// erase the proxy's name from every record while protecting nothing. A bare +/// username is not a credential either, and scrubbing it would delete every +/// occurrence of that word from the log. +#[test] +fn test_a_proxy_without_credentials_contributes_no_secret() { + let secrets = secret_values_from([ + ( + "HTTP_PROXY".to_string(), + "http://proxy.example:8080".to_string(), + ), + ( + "ALL_PROXY".to_string(), + "socks5://10.0.0.1:1080".to_string(), + ), + ( + "HTTPS_PROXY".to_string(), + "http://user@proxy.example:8080".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// npm reads its own `npm_config_*` aliases in preference to the conventional +/// proxy variables and prints the resolved value back, so a credential set only +/// under an alias would otherwise never enter the scrub list. npm spells them +/// in lowercase, so both cases have to classify. +#[test] +fn test_npm_proxy_aliases_are_classified_in_either_case() { + let secrets = secret_values_from([ + ( + "npm_config_proxy".to_string(), + "http://corpuser:lowerplain@proxy.example:8080".to_string(), + ), + ( + "NPM_CONFIG_PROXY".to_string(), + "http://corpuser:upperplain@proxy.example:8080".to_string(), + ), + ( + "npm_config_https_proxy".to_string(), + "http://corpuser:lowertls@proxy.example:8080".to_string(), + ), + ( + "NPM_CONFIG_HTTPS_PROXY".to_string(), + "http://corpuser:uppertls@proxy.example:8080".to_string(), + ), + ]); + + assert_eq!( + secrets, + vec![ + "corpuser:lowerplain", + "corpuser:upperplain", + "corpuser:lowertls", + "corpuser:uppertls", + ] + ); +} + +/// The alias carries the same userinfo-only policy as the conventional names: +/// a credential-less alias contributes nothing, so the proxy stays named in the +/// record. +#[test] +fn test_an_npm_proxy_alias_without_credentials_contributes_no_secret() { + let secrets = secret_values_from([ + ( + "npm_config_proxy".to_string(), + "http://proxy.example:8080".to_string(), + ), + ( + "NPM_CONFIG_HTTPS_PROXY".to_string(), + "http://user@proxy.example:8080".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// The classifier and the reporter have to agree: an alias credential that +/// classifies but never reaches the scrub list still leaks. This drives the +/// reporter with exactly what the classifier produced for an alias, and asserts +/// the log and the returned step both come back clean. +#[test] +fn test_an_npm_alias_credential_is_redacted_from_the_log_and_the_returned_step() { + let password = "hunter2pass"; + let h = harness_with_secrets(secret_values_from([( + "npm_config_proxy".to_string(), + format!("http://corpuser:{password}@proxy.example:8080"), + )])); + + let returned = h.reporter.record_attempt( + 1, + InstallOutcome { + step: InstallStepResult { + stderr: format!( + "npm ERR! proxy=http://corpuser:{password}@proxy.example:8080 tunneling failed" + ), + ..step("cli", false, "") + }, + log_stdout: String::new(), + log_stderr: format!( + "npm config: proxy = http://corpuser:{password}@proxy.example:8080" + ), + }, + ); + + let log = h.log_contents(); + assert!(!log.contains(password), "log leaked the password: {log}"); + assert!( + log.contains("proxy.example"), + "the proxy host is diagnostic and must survive: {log}" + ); + assert!( + !returned.stderr.contains(password), + "the returned step leaked the password: {}", + returned.stderr + ); +} + +// ── npm's own credential settings ──────────────────────────────────────────── + +/// npm accepts every one of its settings as an `npm_config_*` variable, so a +/// registry client key, a basic-auth blob or a one-time password can arrive +/// under a name that carries no marker. Their whole value is the credential — +/// unlike a proxy, none of it is diagnostic — and npm spells them in lowercase. +#[test] +fn test_npm_credential_configs_are_secret_in_either_case() { + let secrets = secret_values_from([ + ( + "npm_config_key".to_string(), + "-----BEGIN PRIVATE KEY-----lowerkey".to_string(), + ), + ( + "NPM_CONFIG_KEY".to_string(), + "-----BEGIN PRIVATE KEY-----upperkey".to_string(), + ), + ("npm_config__auth".to_string(), "bG93ZXJhdXRo".to_string()), + ("NPM_CONFIG__AUTH".to_string(), "dXBwZXJhdXRo".to_string()), + ("npm_config_otp".to_string(), "618243".to_string()), + ("NPM_CONFIG_OTP".to_string(), "907154".to_string()), + ]); + + assert_eq!( + secrets, + vec![ + "-----BEGIN PRIVATE KEY-----lowerkey", + "-----BEGIN PRIVATE KEY-----upperkey", + "bG93ZXJhdXRo", + "dXBwZXJhdXRo", + "618243", + "907154", + ] + ); +} + +/// An unset-but-exported credential is empty, and an empty needle would match +/// everywhere. The name being exact does not make a blank value a secret. +#[test] +fn test_an_empty_npm_credential_config_contributes_no_secret() { + let secrets = secret_values_from([ + ("NPM_CONFIG_KEY".to_string(), String::new()), + ("npm_config_otp".to_string(), String::new()), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// A private registry's URL follows the proxy policy rather than the whole-value +/// one: which registry an install talked to is exactly what a 401 or an ETIMEDOUT +/// has to be read against, so only the userinfo is the secret. +#[test] +fn test_npm_registry_userinfo_is_secret_but_the_registry_host_is_not() { + let secrets = secret_values_from([( + "npm_config_registry".to_string(), + "https://builder:hunter2pass@registry.example/api/npm/".to_string(), + )]); + + assert_eq!(secrets, vec!["builder:hunter2pass"]); +} + +/// The public registry — and any private one reached with a token header rather +/// than URL credentials — contributes nothing, so the registry stays named in +/// the record. +#[test] +fn test_an_npm_registry_without_credentials_contributes_no_secret() { + let secrets = secret_values_from([ + ( + "npm_config_registry".to_string(), + "https://registry.npmjs.org/".to_string(), + ), + ( + "NPM_CONFIG_REGISTRY".to_string(), + "https://builder@registry.example/api/npm/".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// The credential settings are matched by exact name, never by a `KEY` or +/// `AUTH` substring. Those occur throughout an ordinary environment on values +/// that are paths, agent sockets and people's names, and scrubbing them would +/// delete unrelated text from every record. +#[test] +fn test_key_and_auth_inside_a_variable_name_do_not_make_it_secret() { + let secrets = secret_values_from([ + ( + "SSH_AUTH_SOCK".to_string(), + "/tmp/ssh-agent.socket".to_string(), + ), + ("GIT_AUTHOR_NAME".to_string(), "Ada Lovelace".to_string()), + ( + "KEYCHAIN".to_string(), + "/Users/dev/Library/login.keychain".to_string(), + ), + ( + "NPM_CONFIG_KEYFILE".to_string(), + "/Users/dev/.npm/client.pem".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// The wiring, not just the classification: npm prints its resolved config on an +/// auth failure, so each of these has to be gone from the log and from the step +/// the frontend renders. The one-time password is the interesting one — at six +/// digits it is far shorter than any other secret here, and a value under four +/// bytes is dropped by the shared redactor rather than scrubbed. +#[test] +fn test_npm_credential_configs_are_redacted_from_the_log_and_the_returned_step() { + let client_key = "-----BEGIN PRIVATE KEY-----MIIEvQIBADAN"; + let auth = "YnVpbGRlcjpodW50ZXIycGFzcw=="; + let otp = "618243"; + let registry_password = "hunter2pass"; + let h = harness_with_secrets(secret_values_from([ + ("npm_config_key".to_string(), client_key.to_string()), + ("npm_config__auth".to_string(), auth.to_string()), + ("npm_config_otp".to_string(), otp.to_string()), + ( + "npm_config_registry".to_string(), + format!("https://builder:{registry_password}@registry.example/api/npm/"), + ), + ])); + + let returned = h.reporter.record_attempt( + 1, + InstallOutcome { + step: InstallStepResult { + stderr: format!("npm ERR! 401 otp={otp} _auth={auth}"), + ..step("cli", false, "") + }, + log_stdout: format!("npm config: key = {client_key}"), + log_stderr: format!( + "npm config: registry = https://builder:{registry_password}@registry.example/api/npm/" + ), + }, + ); + + let log = h.log_contents(); + for secret in [client_key, auth, otp, registry_password] { + assert!(!log.contains(secret), "log leaked {secret}: {log}"); + } + assert!( + log.contains("registry.example"), + "the registry host is diagnostic and must survive: {log}" + ); + assert!( + !returned.stderr.contains(otp) && !returned.stderr.contains(auth), + "the returned step leaked a credential: {}", + returned.stderr + ); +} + +/// `*_PATH` variables must not be mistaken for personal access tokens. A +/// `contains("_PAT")` rule would match `PATH` itself and scrub every directory +/// name out of the log, which is why the rule matches `_PAT` as a suffix. +#[test] +fn test_a_path_variable_is_not_treated_as_a_personal_access_token() { + let secrets = secret_values_from([ + ("PATH".to_string(), "/usr/local/bin:/usr/bin".to_string()), + ("GOPATH".to_string(), "/home/user/go".to_string()), + ( + "CARGO_HOME_PATH".to_string(), + "/home/user/.cargo".to_string(), + ), + ]); + + assert!(secrets.is_empty(), "got: {secrets:?}"); +} + +/// Variables named as personal access tokens are secret by name, whatever shape +/// their value has. +#[test] +fn test_pat_named_variables_are_secret() { + let secrets = secret_values_from([ + ( + "GITHUB_PAT".to_string(), + "ghp_abcdefghij0123456789".to_string(), + ), + ( + "GH_PAT".to_string(), + "github_pat_abcdefghij0123".to_string(), + ), + ]); + + assert_eq!(secrets.len(), 2, "got: {secrets:?}"); +} + +/// The whole point of the widening: a proxy password and a PAT that the +/// installer echoed reach neither the log nor the live line. +/// +/// Both are checked through the real reporter rather than the classifier, so +/// this covers the wiring — a classifier that recognises a secret the reporter +/// never consults would still leak. +#[test] +fn test_proxy_and_pat_credentials_are_redacted_from_the_log_and_the_live_line() { + let proxy_password = "hunter2pass"; + let pat = "ghp_abcdefghij0123456789"; + // The classifier's own tests cover recognising these under their real + // variable names; injecting the resulting secrets here keeps a live + // `HTTPS_PROXY` out of the process the rest of the suite shares. + let h = harness_with_secrets(vec![format!("corpuser:{proxy_password}"), pat.to_string()]); + + h.reporter.record_attempt( + 1, + outcome( + "cli", + false, + &format!( + "npm ERR! proxy=http://corpuser:{proxy_password}@proxy.example authToken={pat}" + ), + ), + ); + let observer = h.reporter.line_observer().expect("an observer"); + observer(&format!("cloning https://{pat}@github.com/org/repo")); + + let log = h.log_contents(); + assert!( + !log.contains(proxy_password), + "log leaked the proxy password: {log}" + ); + assert!(!log.contains(pat), "log leaked the PAT: {log}"); + assert!( + log.contains("proxy.example"), + "the proxy host is diagnostic and must survive: {log}" + ); + + let line = h.lines().into_iter().flatten().next().expect("a live line"); + assert!(!line.contains(pat), "live line leaked the PAT: {line}"); + assert!(line.contains("[REDACTED]"), "got: {line}"); +} + +/// The third surface: the step returned to the frontend. `getInstallErrorMessage` +/// renders the failing step's stderr verbatim, so a secret that the log and the +/// live line both scrub would still reach the user through the error dialog. +#[test] +fn test_a_returned_step_is_redacted_before_the_frontend_renders_it() { + let pat = "ghp_abcdefghij0123456789"; + let h = harness_with_secrets(vec![pat.to_string()]); + + let returned = h.reporter.record_attempt( + 1, + InstallOutcome { + step: InstallStepResult { + stdout: format!("configuring remote with {pat}"), + stderr: format!("fatal: authentication failed for token {pat}"), + hint: Some(format!("check that {pat} has the repo scope")), + ..step("cli", false, "") + }, + log_stdout: String::new(), + log_stderr: String::new(), + }, + ); + + assert!(!returned.stdout.contains(pat), "got: {}", returned.stdout); + assert!(!returned.stderr.contains(pat), "got: {}", returned.stderr); + let hint = returned.hint.expect("a hint"); + assert!(!hint.contains(pat), "got: {hint}"); +} + +/// A synthesized step reaches the frontend through the other funnel, and needs +/// the same scrubbing — the managed-node prerequisite failures are built this +/// way and carry whatever the underlying command printed. +#[test] +fn test_a_synthesized_step_is_redacted_before_it_reaches_the_caller() { + let pat = "ghp_abcdefghij0123456789"; + let h = harness_with_secrets(vec![pat.to_string()]); + let mut steps = Vec::new(); + + h.reporter.record_step( + &mut steps, + InstallStepResult { + stderr: format!("npm ERR! 401 with {pat}"), + ..step("adapter", false, "") + }, + ); + + assert_eq!(steps.len(), 1); + assert!(!steps[0].stderr.contains(pat), "got: {}", steps[0].stderr); + assert!( + steps[0].stderr.contains("[REDACTED]"), + "got: {}", + steps[0].stderr + ); +} diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_test_support.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_test_support.rs new file mode 100644 index 0000000000..17b2789560 --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_test_support.rs @@ -0,0 +1,106 @@ +//! Shared harness for the install-report test modules. +//! +//! The tests are split by concern — redaction in +//! [`super::install_report_redaction_tests`], everything else in +//! [`super::install_report_tests`] — and both drive the reporter through the +//! same harness, so it lives here rather than in either of them. + +use super::*; +use std::sync::Mutex; + +/// Stands in for the real `app.package_info().version`, which needs a Tauri app. +pub(crate) const TEST_APP_VERSION: &str = "9.9.9"; + +/// A reporter with a started log session in a temp dir, and the emitted events +/// captured. +pub(crate) struct Harness { + /// Kept alive so the log outlives the harness; a test that reuses the + /// directory for a second run takes it. + pub(crate) _dir: tempfile::TempDir, + pub(crate) log: PathBuf, + pub(crate) reporter: InstallReporter, + pub(crate) events: Arc>>, +} + +pub(crate) fn harness() -> Harness { + harness_at(None) +} + +/// A harness whose log lives in `dir`, or in a fresh temp dir when `dir` is +/// `None`. Passing a directory lets a test seed a previous run's file first. +pub(crate) fn harness_at(dir: Option) -> Harness { + harness_inner(dir, None) +} + +/// A harness whose reporter scrubs exactly `secrets`, so a proxy or PAT +/// credential can be asserted without exporting it into the process. +pub(crate) fn harness_with_secrets(secrets: Vec) -> Harness { + harness_inner(None, Some(secrets)) +} + +fn harness_inner(dir: Option, secrets: Option>) -> Harness { + let dir = dir.unwrap_or_else(|| tempfile::tempdir().expect("tempdir")); + let log = dir.path().join("install-goose.log"); + let events: Arc>> = Arc::new(Mutex::new(Vec::new())); + let emit: EmitEvent = { + let events = Arc::clone(&events); + Arc::new(move |event| events.lock().unwrap().push(event)) + }; + let started = InstallLog::start(&log, "goose", TEST_APP_VERSION); + Harness { + reporter: match secrets { + Some(secrets) => InstallReporter::with_secrets("goose", started, Some(emit), secrets), + None => InstallReporter::new("goose", started, Some(emit)), + }, + _dir: dir, + log, + events, + } +} + +/// A reporter with no log file and nothing listening — the degraded shape. +pub(crate) fn silent_reporter() -> InstallReporter { + InstallReporter::new("goose", None, None) +} + +pub(crate) fn step(name: &str, success: bool, stderr: &str) -> InstallStepResult { + InstallStepResult { + step: name.to_string(), + command: "curl … | bash".to_string(), + success, + stdout: String::new(), + stderr: stderr.to_string(), + exit_code: Some(if success { 0 } else { 1 }), + hint: None, + } +} + +/// An executed attempt whose log copy differs from the UI copy — the real shape, +/// since the two views are capped differently. +pub(crate) fn outcome(name: &str, success: bool, log_stdout: &str) -> InstallOutcome { + InstallOutcome { + step: step(name, success, ""), + log_stdout: log_stdout.to_string(), + log_stderr: String::new(), + } +} + +impl Harness { + pub(crate) fn log_contents(&self) -> String { + std::fs::read_to_string(&self.log).unwrap_or_default() + } + + /// The emitted lines in order, with a clear signal rendered as `None`. + pub(crate) fn lines(&self) -> Vec> { + self.events + .lock() + .unwrap() + .iter() + .map(|e| e.line.clone()) + .collect() + } + + pub(crate) fn events(&self) -> Vec { + self.events.lock().unwrap().clone() + } +} diff --git a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs index 60fd810776..c286b618b6 100644 --- a/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -1,101 +1,6 @@ +use super::test_support::*; use super::*; use crate::commands::agent_discovery::install_capture::{drain_into, Capture}; -use std::sync::Mutex; - -/// Stands in for the real `app.package_info().version`, which needs a Tauri app. -const TEST_APP_VERSION: &str = "9.9.9"; - -/// A reporter with a started log session in a temp dir, and the emitted events -/// captured. -struct Harness { - _dir: tempfile::TempDir, - log: PathBuf, - reporter: InstallReporter, - events: Arc>>, -} - -fn harness() -> Harness { - harness_at(None) -} - -/// A harness whose log lives in `dir`, or in a fresh temp dir when `dir` is -/// `None`. Passing a directory lets a test seed a previous run's file first. -fn harness_at(dir: Option) -> Harness { - harness_inner(dir, None) -} - -/// A harness whose reporter scrubs exactly `secrets`, so a proxy or PAT -/// credential can be asserted without exporting it into the process. -fn harness_with_secrets(secrets: Vec) -> Harness { - harness_inner(None, Some(secrets)) -} - -fn harness_inner(dir: Option, secrets: Option>) -> Harness { - let dir = dir.unwrap_or_else(|| tempfile::tempdir().expect("tempdir")); - let log = dir.path().join("install-goose.log"); - let events: Arc>> = Arc::new(Mutex::new(Vec::new())); - let emit: EmitEvent = { - let events = Arc::clone(&events); - Arc::new(move |event| events.lock().unwrap().push(event)) - }; - let started = InstallLog::start(&log, "goose", TEST_APP_VERSION); - Harness { - reporter: match secrets { - Some(secrets) => InstallReporter::with_secrets("goose", started, Some(emit), secrets), - None => InstallReporter::new("goose", started, Some(emit)), - }, - _dir: dir, - log, - events, - } -} - -/// A reporter with no log file and nothing listening — the degraded shape. -fn silent_reporter() -> InstallReporter { - InstallReporter::new("goose", None, None) -} - -fn step(name: &str, success: bool, stderr: &str) -> InstallStepResult { - InstallStepResult { - step: name.to_string(), - command: "curl … | bash".to_string(), - success, - stdout: String::new(), - stderr: stderr.to_string(), - exit_code: Some(if success { 0 } else { 1 }), - hint: None, - } -} - -/// An executed attempt whose log copy differs from the UI copy — the real shape, -/// since the two views are capped differently. -fn outcome(name: &str, success: bool, log_stdout: &str) -> InstallOutcome { - InstallOutcome { - step: step(name, success, ""), - log_stdout: log_stdout.to_string(), - log_stderr: String::new(), - } -} - -impl Harness { - fn log_contents(&self) -> String { - std::fs::read_to_string(&self.log).unwrap_or_default() - } - - /// The emitted lines in order, with a clear signal rendered as `None`. - fn lines(&self) -> Vec> { - self.events - .lock() - .unwrap() - .iter() - .map(|e| e.line.clone()) - .collect() - } - - fn events(&self) -> Vec { - self.events.lock().unwrap().clone() - } -} // ── the log records history the UI does not keep ───────────────────────────── @@ -253,484 +158,6 @@ fn test_an_executed_attempt_records_its_own_duration() { ); } -// ── redaction ──────────────────────────────────────────────────────────────── - -/// Secrets that an installer echoed must not land on disk. The log is written -/// unattended, so scrubbing happens at the write, not at the read. -#[test] -fn test_log_redacts_secrets_before_writing() { - let h = harness(); - let leak = "npm ERR! token nsec1qqqqqqqqqqsecretvalue failed"; - - h.reporter.record_attempt(1, outcome("cli", false, leak)); - - let log = h.log_contents(); - assert!(!log.contains("nsec1qqqqqqqqqqsecretvalue"), "got: {log}"); - assert!(log.contains("[REDACTED]"), "got: {log}"); -} - -/// The environment's own secrets are scrubbed too, by *name* rather than shape. -/// An install inherits Buzz's environment and installers echo it back — npm -/// prints its resolved config on an auth failure — and a token with no -/// recognizable prefix would otherwise reach the file verbatim. -#[test] -fn test_log_redacts_an_environment_secret_with_no_recognizable_prefix() { - let secret = "0e8f31c5a4b7d296e5f1a"; - // Set before the reporter is built: the snapshot is taken at construction. - std::env::set_var("BUZZ_TEST_REGISTRY_TOKEN", secret); - let h = harness(); - std::env::remove_var("BUZZ_TEST_REGISTRY_TOKEN"); - - h.reporter.record_attempt( - 1, - outcome("cli", false, &format!("npm ERR! _authToken={secret}")), - ); - - let log = h.log_contents(); - assert!(!log.contains(secret), "got: {log}"); - assert!(log.contains("[REDACTED]"), "got: {log}"); -} - -/// A live line carries the same scrubbing as the log record. The line is -/// rendered verbatim in the UI, so a leak there is as visible as one on disk. -#[test] -fn test_a_live_line_is_redacted_before_it_is_emitted() { - let h = harness(); - - let observer = h.reporter.line_observer().expect("an observer"); - observer("fetching with token nsec1qqqqqqqqqqleaked"); - - let lines = h.lines(); - assert_eq!(lines.len(), 1); - let line = lines[0].clone().expect("a line, not a clear signal"); - assert!(!line.contains("nsec1qqqqqqqqqqleaked"), "got: {line}"); - assert!(line.contains("[REDACTED]"), "got: {line}"); -} - -// ── proxy and PAT credentials ──────────────────────────────────────────────── - -/// A proxy URL's password is a credential, but the proxy itself is diagnostic -/// information: an install that fails behind a proxy is only debuggable if the -/// record still says which proxy it went through. So the userinfo is scrubbed -/// and the host is kept. -#[test] -fn test_proxy_userinfo_is_secret_but_the_proxy_host_is_not() { - let secrets = secret_values_from([( - "HTTPS_PROXY".to_string(), - "http://corpuser:hunter2pass@proxy.example:8080".to_string(), - )]); - - assert_eq!(secrets, vec!["corpuser:hunter2pass"]); -} - -/// A proxy with no credential contributes nothing — scrubbing a bare host would -/// erase the proxy's name from every record while protecting nothing. A bare -/// username is not a credential either, and scrubbing it would delete every -/// occurrence of that word from the log. -#[test] -fn test_a_proxy_without_credentials_contributes_no_secret() { - let secrets = secret_values_from([ - ( - "HTTP_PROXY".to_string(), - "http://proxy.example:8080".to_string(), - ), - ( - "ALL_PROXY".to_string(), - "socks5://10.0.0.1:1080".to_string(), - ), - ( - "HTTPS_PROXY".to_string(), - "http://user@proxy.example:8080".to_string(), - ), - ]); - - assert!(secrets.is_empty(), "got: {secrets:?}"); -} - -/// npm reads its own `npm_config_*` aliases in preference to the conventional -/// proxy variables and prints the resolved value back, so a credential set only -/// under an alias would otherwise never enter the scrub list. npm spells them -/// in lowercase, so both cases have to classify. -#[test] -fn test_npm_proxy_aliases_are_classified_in_either_case() { - let secrets = secret_values_from([ - ( - "npm_config_proxy".to_string(), - "http://corpuser:lowerplain@proxy.example:8080".to_string(), - ), - ( - "NPM_CONFIG_PROXY".to_string(), - "http://corpuser:upperplain@proxy.example:8080".to_string(), - ), - ( - "npm_config_https_proxy".to_string(), - "http://corpuser:lowertls@proxy.example:8080".to_string(), - ), - ( - "NPM_CONFIG_HTTPS_PROXY".to_string(), - "http://corpuser:uppertls@proxy.example:8080".to_string(), - ), - ]); - - assert_eq!( - secrets, - vec![ - "corpuser:lowerplain", - "corpuser:upperplain", - "corpuser:lowertls", - "corpuser:uppertls", - ] - ); -} - -/// The alias carries the same userinfo-only policy as the conventional names: -/// a credential-less alias contributes nothing, so the proxy stays named in the -/// record. -#[test] -fn test_an_npm_proxy_alias_without_credentials_contributes_no_secret() { - let secrets = secret_values_from([ - ( - "npm_config_proxy".to_string(), - "http://proxy.example:8080".to_string(), - ), - ( - "NPM_CONFIG_HTTPS_PROXY".to_string(), - "http://user@proxy.example:8080".to_string(), - ), - ]); - - assert!(secrets.is_empty(), "got: {secrets:?}"); -} - -/// The classifier and the reporter have to agree: an alias credential that -/// classifies but never reaches the scrub list still leaks. This drives the -/// reporter with exactly what the classifier produced for an alias, and asserts -/// the log and the returned step both come back clean. -#[test] -fn test_an_npm_alias_credential_is_redacted_from_the_log_and_the_returned_step() { - let password = "hunter2pass"; - let h = harness_with_secrets(secret_values_from([( - "npm_config_proxy".to_string(), - format!("http://corpuser:{password}@proxy.example:8080"), - )])); - - let returned = h.reporter.record_attempt( - 1, - InstallOutcome { - step: InstallStepResult { - stderr: format!( - "npm ERR! proxy=http://corpuser:{password}@proxy.example:8080 tunneling failed" - ), - ..step("cli", false, "") - }, - log_stdout: String::new(), - log_stderr: format!( - "npm config: proxy = http://corpuser:{password}@proxy.example:8080" - ), - }, - ); - - let log = h.log_contents(); - assert!(!log.contains(password), "log leaked the password: {log}"); - assert!( - log.contains("proxy.example"), - "the proxy host is diagnostic and must survive: {log}" - ); - assert!( - !returned.stderr.contains(password), - "the returned step leaked the password: {}", - returned.stderr - ); -} - -// ── npm's own credential settings ──────────────────────────────────────────── - -/// npm accepts every one of its settings as an `npm_config_*` variable, so a -/// registry client key, a basic-auth blob or a one-time password can arrive -/// under a name that carries no marker. Their whole value is the credential — -/// unlike a proxy, none of it is diagnostic — and npm spells them in lowercase. -#[test] -fn test_npm_credential_configs_are_secret_in_either_case() { - let secrets = secret_values_from([ - ( - "npm_config_key".to_string(), - "-----BEGIN PRIVATE KEY-----lowerkey".to_string(), - ), - ( - "NPM_CONFIG_KEY".to_string(), - "-----BEGIN PRIVATE KEY-----upperkey".to_string(), - ), - ("npm_config__auth".to_string(), "bG93ZXJhdXRo".to_string()), - ("NPM_CONFIG__AUTH".to_string(), "dXBwZXJhdXRo".to_string()), - ("npm_config_otp".to_string(), "618243".to_string()), - ("NPM_CONFIG_OTP".to_string(), "907154".to_string()), - ]); - - assert_eq!( - secrets, - vec![ - "-----BEGIN PRIVATE KEY-----lowerkey", - "-----BEGIN PRIVATE KEY-----upperkey", - "bG93ZXJhdXRo", - "dXBwZXJhdXRo", - "618243", - "907154", - ] - ); -} - -/// An unset-but-exported credential is empty, and an empty needle would match -/// everywhere. The name being exact does not make a blank value a secret. -#[test] -fn test_an_empty_npm_credential_config_contributes_no_secret() { - let secrets = secret_values_from([ - ("NPM_CONFIG_KEY".to_string(), String::new()), - ("npm_config_otp".to_string(), String::new()), - ]); - - assert!(secrets.is_empty(), "got: {secrets:?}"); -} - -/// A private registry's URL follows the proxy policy rather than the whole-value -/// one: which registry an install talked to is exactly what a 401 or an ETIMEDOUT -/// has to be read against, so only the userinfo is the secret. -#[test] -fn test_npm_registry_userinfo_is_secret_but_the_registry_host_is_not() { - let secrets = secret_values_from([( - "npm_config_registry".to_string(), - "https://builder:hunter2pass@registry.example/api/npm/".to_string(), - )]); - - assert_eq!(secrets, vec!["builder:hunter2pass"]); -} - -/// The public registry — and any private one reached with a token header rather -/// than URL credentials — contributes nothing, so the registry stays named in -/// the record. -#[test] -fn test_an_npm_registry_without_credentials_contributes_no_secret() { - let secrets = secret_values_from([ - ( - "npm_config_registry".to_string(), - "https://registry.npmjs.org/".to_string(), - ), - ( - "NPM_CONFIG_REGISTRY".to_string(), - "https://builder@registry.example/api/npm/".to_string(), - ), - ]); - - assert!(secrets.is_empty(), "got: {secrets:?}"); -} - -/// The credential settings are matched by exact name, never by a `KEY` or -/// `AUTH` substring. Those occur throughout an ordinary environment on values -/// that are paths, agent sockets and people's names, and scrubbing them would -/// delete unrelated text from every record. -#[test] -fn test_key_and_auth_inside_a_variable_name_do_not_make_it_secret() { - let secrets = secret_values_from([ - ( - "SSH_AUTH_SOCK".to_string(), - "/tmp/ssh-agent.socket".to_string(), - ), - ("GIT_AUTHOR_NAME".to_string(), "Ada Lovelace".to_string()), - ( - "KEYCHAIN".to_string(), - "/Users/dev/Library/login.keychain".to_string(), - ), - ( - "NPM_CONFIG_KEYFILE".to_string(), - "/Users/dev/.npm/client.pem".to_string(), - ), - ]); - - assert!(secrets.is_empty(), "got: {secrets:?}"); -} - -/// The wiring, not just the classification: npm prints its resolved config on an -/// auth failure, so each of these has to be gone from the log and from the step -/// the frontend renders. The one-time password is the interesting one — at six -/// digits it is far shorter than any other secret here, and a value under four -/// bytes is dropped by the shared redactor rather than scrubbed. -#[test] -fn test_npm_credential_configs_are_redacted_from_the_log_and_the_returned_step() { - let client_key = "-----BEGIN PRIVATE KEY-----MIIEvQIBADAN"; - let auth = "YnVpbGRlcjpodW50ZXIycGFzcw=="; - let otp = "618243"; - let registry_password = "hunter2pass"; - let h = harness_with_secrets(secret_values_from([ - ("npm_config_key".to_string(), client_key.to_string()), - ("npm_config__auth".to_string(), auth.to_string()), - ("npm_config_otp".to_string(), otp.to_string()), - ( - "npm_config_registry".to_string(), - format!("https://builder:{registry_password}@registry.example/api/npm/"), - ), - ])); - - let returned = h.reporter.record_attempt( - 1, - InstallOutcome { - step: InstallStepResult { - stderr: format!("npm ERR! 401 otp={otp} _auth={auth}"), - ..step("cli", false, "") - }, - log_stdout: format!("npm config: key = {client_key}"), - log_stderr: format!( - "npm config: registry = https://builder:{registry_password}@registry.example/api/npm/" - ), - }, - ); - - let log = h.log_contents(); - for secret in [client_key, auth, otp, registry_password] { - assert!(!log.contains(secret), "log leaked {secret}: {log}"); - } - assert!( - log.contains("registry.example"), - "the registry host is diagnostic and must survive: {log}" - ); - assert!( - !returned.stderr.contains(otp) && !returned.stderr.contains(auth), - "the returned step leaked a credential: {}", - returned.stderr - ); -} - -/// `*_PATH` variables must not be mistaken for personal access tokens. A -/// `contains("_PAT")` rule would match `PATH` itself and scrub every directory -/// name out of the log, which is why the rule matches `_PAT` as a suffix. -#[test] -fn test_a_path_variable_is_not_treated_as_a_personal_access_token() { - let secrets = secret_values_from([ - ("PATH".to_string(), "/usr/local/bin:/usr/bin".to_string()), - ("GOPATH".to_string(), "/home/user/go".to_string()), - ( - "CARGO_HOME_PATH".to_string(), - "/home/user/.cargo".to_string(), - ), - ]); - - assert!(secrets.is_empty(), "got: {secrets:?}"); -} - -/// Variables named as personal access tokens are secret by name, whatever shape -/// their value has. -#[test] -fn test_pat_named_variables_are_secret() { - let secrets = secret_values_from([ - ( - "GITHUB_PAT".to_string(), - "ghp_abcdefghij0123456789".to_string(), - ), - ( - "GH_PAT".to_string(), - "github_pat_abcdefghij0123".to_string(), - ), - ]); - - assert_eq!(secrets.len(), 2, "got: {secrets:?}"); -} - -/// The whole point of the widening: a proxy password and a PAT that the -/// installer echoed reach neither the log nor the live line. -/// -/// Both are checked through the real reporter rather than the classifier, so -/// this covers the wiring — a classifier that recognises a secret the reporter -/// never consults would still leak. -#[test] -fn test_proxy_and_pat_credentials_are_redacted_from_the_log_and_the_live_line() { - let proxy_password = "hunter2pass"; - let pat = "ghp_abcdefghij0123456789"; - // The classifier's own tests cover recognising these under their real - // variable names; injecting the resulting secrets here keeps a live - // `HTTPS_PROXY` out of the process the rest of the suite shares. - let h = harness_with_secrets(vec![format!("corpuser:{proxy_password}"), pat.to_string()]); - - h.reporter.record_attempt( - 1, - outcome( - "cli", - false, - &format!( - "npm ERR! proxy=http://corpuser:{proxy_password}@proxy.example authToken={pat}" - ), - ), - ); - let observer = h.reporter.line_observer().expect("an observer"); - observer(&format!("cloning https://{pat}@github.com/org/repo")); - - let log = h.log_contents(); - assert!( - !log.contains(proxy_password), - "log leaked the proxy password: {log}" - ); - assert!(!log.contains(pat), "log leaked the PAT: {log}"); - assert!( - log.contains("proxy.example"), - "the proxy host is diagnostic and must survive: {log}" - ); - - let line = h.lines().into_iter().flatten().next().expect("a live line"); - assert!(!line.contains(pat), "live line leaked the PAT: {line}"); - assert!(line.contains("[REDACTED]"), "got: {line}"); -} - -/// The third surface: the step returned to the frontend. `getInstallErrorMessage` -/// renders the failing step's stderr verbatim, so a secret that the log and the -/// live line both scrub would still reach the user through the error dialog. -#[test] -fn test_a_returned_step_is_redacted_before_the_frontend_renders_it() { - let pat = "ghp_abcdefghij0123456789"; - let h = harness_with_secrets(vec![pat.to_string()]); - - let returned = h.reporter.record_attempt( - 1, - InstallOutcome { - step: InstallStepResult { - stdout: format!("configuring remote with {pat}"), - stderr: format!("fatal: authentication failed for token {pat}"), - hint: Some(format!("check that {pat} has the repo scope")), - ..step("cli", false, "") - }, - log_stdout: String::new(), - log_stderr: String::new(), - }, - ); - - assert!(!returned.stdout.contains(pat), "got: {}", returned.stdout); - assert!(!returned.stderr.contains(pat), "got: {}", returned.stderr); - let hint = returned.hint.expect("a hint"); - assert!(!hint.contains(pat), "got: {hint}"); -} - -/// A synthesized step reaches the frontend through the other funnel, and needs -/// the same scrubbing — the managed-node prerequisite failures are built this -/// way and carry whatever the underlying command printed. -#[test] -fn test_a_synthesized_step_is_redacted_before_it_reaches_the_caller() { - let pat = "ghp_abcdefghij0123456789"; - let h = harness_with_secrets(vec![pat.to_string()]); - let mut steps = Vec::new(); - - h.reporter.record_step( - &mut steps, - InstallStepResult { - stderr: format!("npm ERR! 401 with {pat}"), - ..step("adapter", false, "") - }, - ); - - assert_eq!(steps.len(), 1); - assert!(!steps[0].stderr.contains(pat), "got: {}", steps[0].stderr); - assert!( - steps[0].stderr.contains("[REDACTED]"), - "got: {}", - steps[0].stderr - ); -} - // ── the log pointer ────────────────────────────────────────────────────────── /// The path is available as soon as the run's session opens, because the file