diff --git a/desktop/src-tauri/src/commands/agent_discovery.rs b/desktop/src-tauri/src/commands/agent_discovery.rs index d6429e0454..cbbf4ce351 100644 --- a/desktop/src-tauri/src/commands/agent_discovery.rs +++ b/desktop/src-tauri/src/commands/agent_discovery.rs @@ -236,10 +236,12 @@ pub async fn install_acp_runtime( // returns (Guard impl Drop) — so Phase 2's restart path runs outside // the guard and cannot re-enter the mutex. 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 app_clone = app.clone(); + let install_result = tokio::task::spawn_blocking(move || { + install_acp_runtime_blocking(&runtime_id_clone, &app_clone) + }) + .await + .map_err(|e| format!("install task panicked: {e}"))??; if !install_result.success { return Ok(install_result); @@ -259,12 +261,21 @@ 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 { +/// +/// 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, + 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 // run and to the subsequent discover_acp_providers call. @@ -297,6 +308,8 @@ fn install_acp_runtime_blocking(runtime_id: &str) -> Result 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(reporter.failed(steps)); } }; - 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(reporter.failed(steps)); } } } - 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(), }) } @@ -1016,8 +1010,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..903b68715a --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_capture.rs @@ -0,0 +1,319 @@ +//! 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, 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{}", + 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`. +/// +/// 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, + state: Mutex, +} + +#[derive(Default)] +struct ThrottleState { + last_emitted: Option, + pending: Option, +} + +impl Throttle { + pub(super) fn new(min_interval: Duration) -> Self { + Self { + min_interval, + state: Mutex::new(ThrottleState::default()), + } + } + + /// 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 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(); + } + } +} + +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..] +} + +/// 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 new file mode 100644 index 0000000000..8830f355df --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_capture_tests.rs @@ -0,0 +1,437 @@ +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 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_emits_the_first_line_and_holds_the_next_in_window() { + let throttle = Throttle::new(Duration::from_millis(250)); + let start = Instant::now(); + + 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 and nothing is left pending — the +/// emitted line *is* the newest, so holding it too would emit it twice. +#[test] +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_eq!( + throttle.offer("later", start + Duration::from_millis(300)), + Some("later".to_string()) + ); + + 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 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(); + throttle.offer("first", start); + + assert_eq!( + throttle.offer("held", start + Duration::from_millis(200)), + None + ); + + 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 63163ceadc..3b94f2ef8a 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,46 @@ //! `install_powershell_command`, `build_install_command`); this module owns //! only what happens once a `Command` exists. -use std::io::Read; +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. 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 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. /// /// Runtime installs pull artifacts over the network — Goose's `curl … | bash` @@ -22,10 +55,24 @@ const INSTALL_MAX_ATTEMPTS: u32 = 3; /// `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| { + // 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) + }, std::thread::sleep, ) } @@ -92,11 +139,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, @@ -104,11 +155,11 @@ 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), - }; + }); } }; - let mut child = match cmd + let child = match cmd .stdin(std::process::Stdio::null()) .stdout(std::process::Stdio::piped()) .stderr(std::process::Stdio::piped()) @@ -116,7 +167,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, @@ -124,146 +175,312 @@ fn run_install_command(step: &str, command: &str) -> InstallStepResult { stderr: format!("failed to spawn shell: {e}"), exit_code: None, hint: None, - }; + }); } }; - // Drain stdout/stderr on background threads to prevent pipe buffer deadlock. + await_install_child(step, command, child, INSTALL_TIMEOUT, observer) +} + +/// 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, + observer: Option, +) -> InstallOutcome { + // Drain stdout/stderr on background threads to prevent pipe buffer + // 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 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); + // 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), + events_tx.clone(), + observer.clone(), + ); + move || { + if let Some(pipe) = stdout_pipe { + drain_into(pipe, &capture, observer.as_ref()); + } + let _ = done.send(Settled::Drained); } - 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); + 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(Settled::Drained); } - buf }); // Save the PID before moving `child` into the wait thread so we can // 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())); }); - // 5-minute timeout for install commands. - let deadline = std::time::Instant::now() + std::time::Duration::from_secs(300); - loop { - let remaining = deadline.saturating_duration_since(std::time::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); - } - drop(rx); - let _ = wait_thread.join(); - let _ = stdout_thread.join(); - let _ = stderr_thread.join(); - return InstallStepResult { + // 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, + timeout_message(timeout), + &stdout_capture, + &stderr_capture, + ); + } + } + + match settle.status { + Some(Ok(status)) => InstallOutcome { + step: 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, + 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, + ), + } +} - match rx.recv_timeout(std::time::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(); - return InstallStepResult { - step: step.to_string(), - command: command.to_string(), - success: status.success(), - stdout: truncate_output(stdout), - stderr: truncate_output(stderr_raw), - exit_code: status.code(), - hint: None, - }; - } - Ok(Err(e)) => { - 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, - }; - } - 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 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, - }; +/// 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 } } -/// 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 { - const HEAD: usize = 512; - const TAIL: usize = 1024; - const LIMIT: usize = HEAD + TAIL; - if s.len() <= LIMIT { - return s; - } - 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..] - ) +/// Kill the install's process group, escalating on the *tree's* liveness. +/// +/// 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)); + } +} + +/// 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) }; + } +} + +/// 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) +} + +/// 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); } -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; +/// 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: &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, + }, + log_stdout: stdout.log(), + log_stderr: lead_with_reason(&reason, stderr.log()), } - index +} + +/// 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}") + } +} + +/// 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") } #[cfg(test)] @@ -410,48 +627,304 @@ mod tests { assert_eq!(cmd.get_current_dir(), Some(expected.as_path())); } - // ── output truncation ───────────────────────────────────────────────────── + // ── 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 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), + "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" + ); + 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 + /// 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(), + &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_settling_on_a_message_that_never_arrives_stops_at_the_deadline() { + let (_tx, events) = std::sync::mpsc::channel::(); + + let started = Instant::now(); + 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 {:?}", + started.elapsed() + ); + } + + /// 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)); + } - /// Output within the cap is passed through byte-for-byte — no marker, no loss. + /// 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_truncate_output_leaves_short_output_untouched() { - let short = "a".repeat(1536); + 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" + ); + } - assert_eq!(truncate_output(short.clone()), short); + /// 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`") } - /// 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. + /// 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_truncate_output_keeps_head_and_tail_with_marker() { - let input = format!( - "{}{}{}", - "H".repeat(512), - "M".repeat(4000), - "T".repeat(1024) + 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 outcome = await_install_child("cli", "install", child, Duration::from_secs(2), None); + + assert!( + 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" + ); + } - let out = truncate_output(input); + /// 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 + /// 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 outcome = await_install_child("cli", "install", child, Duration::from_secs(5), None); + let result = &outcome.step; - assert!(out.starts_with(&"H".repeat(512))); - assert!(out.ends_with(&"T".repeat(1024))); + assert!(!result.success); assert!( - out.contains("... (4000 bytes omitted) ..."), - "marker must name the omitted byte count, got: {out}" + started.elapsed() < Duration::from_secs(30), + "the drains must not block on a descendant's inherited pipe" + ); + + let pid = recorded_pid(&pidfile); + assert!( + await_death(pid), + "descendant {pid} survived the ceiling kill — the group was not signalled" ); } - /// Truncation must not split a multi-byte character. Cutting mid-codepoint - /// would panic on the slice; the boundary floor prevents it. + /// 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_truncate_output_does_not_split_multibyte_characters() { - // "é" is 2 bytes, so every candidate cut index lands mid-character. - let input = "é".repeat(4000); + 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; - let out = truncate_output(input); + assert!(!result.success); + assert!( + started.elapsed() < Duration::from_secs(30), + "a SIGTERM-ignoring descendant must not hold the ceiling open" + ); - assert!(out.contains("bytes omitted"), "input must exceed the cap"); - assert!(!out.contains('\u{fffd}'), "no replacement chars: {out}"); + 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..24bcd3456a --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report.rs @@ -0,0 +1,595 @@ +//! 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. +//! +//! [`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::{Path, PathBuf}; +use std::sync::atomic::{AtomicU64, Ordering}; +use std::sync::{Arc, Mutex, RwLock}; +use std::time::{Duration, Instant}; + +use serde::Serialize; + +use super::install_capture::{LineObserver, Throttle}; +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. +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. +/// +/// `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, Debug)] +pub(super) struct InstallOutputEvent { + pub(super) runtime_id: 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; + +/// 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 { + 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 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`. + /// + /// `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 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 { + // 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, &app_version)); + 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, Some(emit)) + } + + 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. + 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, + 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 } + } + + /// 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 { + 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) -> Option { + let live = self.live.clone()?; + Some(Arc::new(move |line: &str| live.offer(line))) + } + + /// 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.redacted_step(outcome.step) + } + + /// 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(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 + /// permission degrades the diagnostics, it does not fail the install. + fn write_record(&self, attempt: Option, outcome: &InstallOutcome) { + let Some(log) = &self.log else { + return; + }; + 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, + /// 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_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_under_guard(line); + } + // `guard` drops here, releasing the read lock after publication. + } + + /// 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(), + seq: self.seq.fetch_add(1, Ordering::Relaxed), + 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. +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. + /// + /// 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} app={app_version} os={} started={}\n", + std::env::consts::OS, + 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()); + } + } +} + +/// 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, + 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} elapsed={elapsed}\n$ {}\n", + chrono::Utc::now().to_rfc3339(), + step.step, + step.success, + 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, secrets))); + } + } + if let Some(hint) = &step.hint { + record.push_str(&format!("--- hint ---\n{}\n", redact(hint, secrets))); + } + record +} + +/// 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 +/// hard-coded key shapes would be scrubbed, so a plain `NPM_TOKEN` or +/// `ANTHROPIC_API_KEY` would land in the file in clear text. +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. +/// +/// Three kinds of variable are recognised, because they need different +/// treatment: +/// +/// * **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 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 + // output unreadable. + (value.len() >= 8 && name_marks_secret(&name)).then_some(value) + }) + .collect() +} + +/// Variables whose value is a URL that may embed a credential in its userinfo. +/// +/// npm's own `npm_config_*` aliases are here too: npm resolves them ahead of +/// the conventional names and echoes the result from `npm config list`, and +/// none of these names carries a marker [`name_marks_secret`] would catch. +/// Matching is case-insensitive because the caller uppercases the name first, +/// which is what npm's lowercase spelling needs. +const URL_CREDENTIAL_VAR_NAMES: &[&str] = &[ + "HTTP_PROXY", + "HTTPS_PROXY", + "ALL_PROXY", + "NPM_CONFIG_PROXY", + "NPM_CONFIG_HTTPS_PROXY", + "NPM_CONFIG_REGISTRY", +]; + +/// Variables whose whole value is a credential, recognised by exact name. +/// +/// These are npm's supported credential settings, whose names carry no marker +/// [`name_marks_secret`] would catch. They are listed exactly rather than +/// matched on `KEY` or `AUTH` substrings: those occur throughout an ordinary +/// environment, and scrubbing on them would delete unrelated values from the +/// whole log. +/// +/// * `NPM_CONFIG_KEY` — the PEM client key used to reach a registry. +/// * `NPM_CONFIG__AUTH` — the base64 basic-auth blob (npm's own double +/// underscore, matching the `_auth` setting). +/// * `NPM_CONFIG_OTP` — the registry one-time password. +const SECRET_VAR_NAMES: &[&str] = &["NPM_CONFIG_KEY", "NPM_CONFIG__AUTH", "NPM_CONFIG_OTP"]; + +/// 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", + "PASSWORD", + "PASSWD", + "APIKEY", + "API_KEY", + "PRIVATE_KEY", + "ACCESS_KEY", + "CREDENTIAL", + ]; + name.ends_with("_PAT") + || SECRET_NAME_MARKERS + .iter() + .any(|marker| name.contains(marker)) +} + +/// The `user:password` credential embedded in a URL, if it has one. +/// +/// 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 url_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)] +#[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 new file mode 100644 index 0000000000..c286b618b6 --- /dev/null +++ b/desktop/src-tauri/src/commands/agent_discovery/install_report_tests.rs @@ -0,0 +1,564 @@ +use super::test_support::*; +use super::*; +use crate::commands::agent_discovery::install_capture::{drain_into, Capture}; + +// ── 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")); +} + +// ── one file per run ───────────────────────────────────────────────────────── + +/// 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_app_version_and_os() { + let h = harness(); + let log = h.log_contents(); + + assert!( + log.starts_with(&format!( + "=== install run runtime=goose app={TEST_APP_VERSION} os={} started=", + std::env::consts::OS + )), + "got: {log}" + ); +} + +/// 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}" + ); +} + +// ── 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 +/// 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.start_attempt(); + 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 cannot open a session, so +/// the run degrades to no log rather than failing. +#[test] +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", TEST_APP_VERSION).is_none()); +} + +// ── live output line ───────────────────────────────────────────────────────── + +/// 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_lines_carry_their_runtime_and_a_monotonic_sequence() { + let h = harness(); + + 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"); + + // 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()), + ] + ); +} + +/// 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_a_burst_coalesces_to_the_newest_line_not_the_first() { + let h = harness(); + let observer = h.reporter.line_observer().expect("an observer"); + + 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![Some("progress".to_string()), Some("warning".to_string())], + "the second stream's line is held, not emitted immediately, and not lost" + ); +} + +/// 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().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:?}" + ); +} 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..5debae41cb 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 @@ -305,9 +305,23 @@ 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)` diff --git a/desktop/src-tauri/src/managed_agents/storage.rs b/desktop/src-tauri/src/managed_agents/storage.rs index f6f89ed898..652bb9b9ea 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,62 @@ pub(crate) fn open_log_file(path: &Path) -> Result { .map_err(|error| format!("failed to open log file {}: {error}", path.display())) } +/// 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 +/// 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. +fn open_install_log(path: &Path, truncate: bool) -> Result { + let mut options = OpenOptions::new(); + options.create(true); + if truncate { + options.write(true).truncate(true); + } else { + options.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..9943c6b3ac 100644 --- a/desktop/src-tauri/src/managed_agents/storage_tests.rs +++ b/desktop/src-tauri/src/managed_agents/storage_tests.rs @@ -698,3 +698,135 @@ 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"); +} + +/// 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_session_keeps_the_previous_run_as_dot_one() { + let dir = tempfile::tempdir().expect("temp dir"); + let path = dir.path().join("install-goose.log"); + + 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 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" + ); +} + +/// 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_session_replaces_an_existing_dot_one() { + let dir = tempfile::tempdir().expect("temp dir"); + let path = dir.path().join("install-goose.log"); + 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::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"), + "header\nfirst\nsecond\n" + ); +} + +/// 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 3d8e0ed02b..fcd8b13fc9 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, @@ -701,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..d65583e00d --- /dev/null +++ b/desktop/src/features/agents/lib/useInstallOutputLine.test.mjs @@ -0,0 +1,82 @@ +import assert from "node:assert/strict"; +import test from "node:test"; + +import { nextInstallOutputLine } from "./useInstallOutputLine.ts"; + +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", 0, "downloading"), "goose"), + { seq: 0, line: "downloading" }, + ); +}); + +test("nextInstallOutputLine: a later line replaces the current one", () => { + const current = { seq: 4, line: "downloading" }; + + assert.deepEqual( + nextInstallOutputLine(current, event("goose", 5, "unpacking"), "goose"), + { seq: 5, line: "unpacking" }, + ); +}); + +test("nextInstallOutputLine: ignores a line from another runtime", () => { + const current = { seq: 1, line: "downloading" }; + + assert.equal( + nextInstallOutputLine(current, event("codex", 2, "other work"), "goose"), + current, + ); +}); + +test("nextInstallOutputLine: ignores an out-of-order line", () => { + const current = { seq: 7, line: "retrying" }; + + assert.equal( + nextInstallOutputLine(current, event("goose", 6, "stale line"), "goose"), + current, + ); +}); + +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", 10, "step two, attempt one"), + "goose", + ), + { seq: 10, line: "step two, attempt one" }, + ); +}); + +test("nextInstallOutputLine: a first event mid-install is adopted", () => { + assert.deepEqual( + 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 new file mode 100644 index 0000000000..9f50843fc7 --- /dev/null +++ b/desktop/src/features/agents/lib/useInstallOutputLine.ts @@ -0,0 +1,108 @@ +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; + /** 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 the sequence number that produced it. */ +export type InstallOutputState = { + 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 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, + event: InstallOutputEvent, + runtimeId: string, +): InstallOutputState | null { + if (event.runtime_id !== runtimeId) return current; + 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 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 + * 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); + + // 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(() => { + 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?.(); + }; + }, [runtimeId]); + + // `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/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 ? (

({ + 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 c57525480e..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,22 +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; -}; +export type { + RawInstallRuntimeResult, + RawInstallStepResult, +} from "./installTypes"; type RawGitBashPrerequisite = { available: boolean; @@ -772,25 +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, - }; -} - function fromRawCommandAvailability( command: RawCommandAvailability, ): CommandAvailability { diff --git a/desktop/src/shared/api/types.ts b/desktop/src/shared/api/types.ts index 689c400b03..877b5b1c61 100644 --- a/desktop/src/shared/api/types.ts +++ b/desktop/src/shared/api/types.ts @@ -571,22 +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; -}; +export type { + InstallRuntimeResult, + InstallStepResult, +} from "./installTypes"; export type AcpAuthMethod = { id: string; 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 */ diff --git a/desktop/src/shared/lib/installError.test.mjs b/desktop/src/shared/lib/installError.test.mjs index c6b51186a8..181d7b802b 100644 --- a/desktop/src/shared/lib/installError.test.mjs +++ b/desktop/src/shared/lib/installError.test.mjs @@ -3,84 +3,108 @@ import test from "node:test"; import { getInstallErrorMessage } from "./installError.ts"; +/** A failed install result carrying `steps` and, optionally, a log pointer. */ +function failed(steps, logPath = null) { + return { + success: false, + steps, + restartedCount: 0, + failedRestartCount: 0, + logPath, + }; +} + test("getInstallErrorMessage: empty steps array returns fallback", () => { - 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..82bcd4a310 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, each record + * bounded far above the display truncation — 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 73b564429a..4ba5dc63ce 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. @@ -1242,6 +1245,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...", @@ -7202,6 +7207,53 @@ let personaSharePublicationCallCount = 0; // Per-page confirm_team_snapshot_import call counter for sequenced error testing. let teamSnapshotConfirmCallCount = 0; +// 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; + +/** + * 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. + * + * 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 = 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. + 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", { + runtime_id: runtimeId, + seq: installOutputSeq++, + line, + }); + } +} + async function handleInstallAcpRuntime( args: { runtimeId?: string; @@ -7209,6 +7261,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) { @@ -7265,6 +7321,7 @@ async function handleInstallAcpRuntime( ], restarted_count: 0, failed_restart_count: 0, + log_path: null, }; } @@ -11549,6 +11606,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 77d0fbcb45..2d69a4e0da 100644 --- a/desktop/tests/e2e/doctor-states.spec.ts +++ b/desktop/tests/e2e/doctor-states.spec.ts @@ -983,4 +983,91 @@ 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 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, + }); + 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 bounded output for every attempt. + 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`, + }); + + // 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, + }); + }); }); diff --git a/desktop/tests/helpers/bridge.ts b/desktop/tests/helpers/bridge.ts index ca4d62ddd6..9d4b76f8d0 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; @@ -171,35 +187,17 @@ 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?: { - 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