From cb75cc2e248c81284361bb70a7d230cacf375a87 Mon Sep 17 00:00:00 2001 From: Matt Toohey Date: Fri, 13 Nov 2026 12:55:12 +1100 Subject: [PATCH 1/4] fix(actions): bound and evict buffered action output The executor kept every read of an action's output for the life of the app: an unbounded Vec of per-read chunks while the action ran, cloned in full at exit, then retained until the frontend cleared it. This implements items 1, 2 and 3 (backend half) of the recommended fix in the action output leak note, and the two side effects its root-cause sections call out for this code. Move at exit (item 1) - The completion thread moves the execution's shared buffer into the finished set instead of cloning it, so the running and the finished log are the same allocation. - It then waits up to 2 s for the reader threads before it reports the terminal status. Output written just before exit is now in the finished log and is streamed before the status. The wait is bounded because a background process can keep the pipes open; what such a process writes later still reaches the same buffer. Cap by bytes (item 2) - New OutputBuffer keeps the most recent 4 MiB as a ring of blocks. Adjacent reads of one stream are coalesced into blocks of up to 64 KiB. - OutputChunk is unchanged. Once output has been dropped, the snapshot starts with a synthetic chunk on the stderr stream that says how much, and the retained text starts on a line boundary. - Streaming to the listener is not capped. Evict finished buffers (item 3, backend only) - Only the 8 most recently finished executions keep their output. - New ActionExecutor::discard_output drops an execution's output: at exit if it is still running, at once if it has finished. Branch teardown (delete branch, remove project repo, delete project) calls it through stop_and_discard_actions_for_branches. Moving a branch and transferring a project keep the output. - Clearing from the frontend when a pill is dropped is a later commit. Side effects - Reads are decoded by a streaming UTF-8 decoder, so a character split across two reads is no longer turned into replacement characters. - The tail lost after the exit snapshot is fixed by the reader wait. Tests - Unit tests for the decoder, the buffer and the finished set, and executor tests for all three items that run real /bin/sh scripts. - A Tauri test that teardown discards a deleted branch's output and a move keeps it. Follow-up, not caused by this change: children killed at birth - On a loaded macOS machine (load average 40 to 50, four copies of the test binary at once) a freshly spawned child is now and then killed with SIGKILL (wait status 9) about a millisecond after spawn, before it runs any of its script. The executor reports it as failed with no exit code and no output. - The executor at the parent commit does the same. Interleaved runs of the same spawn mix, 44 runs of each binary: 10 of 1012 child exits killed before this change, 4 of 968 with it. - It did not reproduce with --test-threads=1, with only some of the tests selected, or in standalone spawners outside the test binary. There was no memory pressure. The cause is unknown. - The new executor tests start a script again, at most 5 times, when its child dies that way. Their assertions are unchanged. Under the same stress 48 of 48 runs of them passed. Signed-off-by: Matt Toohey Co-Authored-By: Claude Fable 5.2 --- apps/staged/src-tauri/src/actions/commands.rs | 75 +++ apps/staged/src-tauri/src/branch_teardown.rs | 5 +- crates/builderbot-actions/src/executor.rs | 213 +++++-- .../builderbot-actions/src/executor/tests.rs | 577 ++++++++++++++++++ .../src/finished_outputs.rs | 104 ++++ crates/builderbot-actions/src/lib.rs | 3 + .../builderbot-actions/src/output_buffer.rs | 366 +++++++++++ crates/builderbot-actions/src/utf8_stream.rs | 115 ++++ 8 files changed, 1400 insertions(+), 58 deletions(-) create mode 100644 crates/builderbot-actions/src/executor/tests.rs create mode 100644 crates/builderbot-actions/src/finished_outputs.rs create mode 100644 crates/builderbot-actions/src/output_buffer.rs create mode 100644 crates/builderbot-actions/src/utf8_stream.rs diff --git a/apps/staged/src-tauri/src/actions/commands.rs b/apps/staged/src-tauri/src/actions/commands.rs index 0439ce6fc..dfbf7dc0a 100644 --- a/apps/staged/src-tauri/src/actions/commands.rs +++ b/apps/staged/src-tauri/src/actions/commands.rs @@ -1201,9 +1201,34 @@ pub fn stop_actions_for_branches( executor: &ActionExecutor, registry: &ActionRegistry, branch_ids: &[&str], +) { + stop_branch_actions(executor, registry, branch_ids, false); +} + +/// Stop all running actions for branches that are being deleted +/// (best-effort), and give up their output: once the branch is gone nothing +/// can show it, so it should not be retained when the actions exit. +pub fn stop_and_discard_actions_for_branches( + executor: &ActionExecutor, + registry: &ActionRegistry, + branch_ids: &[&str], +) { + stop_branch_actions(executor, registry, branch_ids, true); +} + +fn stop_branch_actions( + executor: &ActionExecutor, + registry: &ActionRegistry, + branch_ids: &[&str], + discard_output: bool, ) { for branch_id in branch_ids { for info in registry.get_running_for_branch(branch_id) { + if discard_output { + // Covers an action that exits before the stop below reaches + // it, too: its retained output is freed here. + executor.discard_output(&info.execution_id); + } if executor.is_running(&info.execution_id) { if let Err(e) = executor.stop(&info.execution_id) { log::warn!("Failed to stop action {}: {e}", info.execution_id); @@ -1514,6 +1539,56 @@ mod tests { ); } + #[cfg(unix)] + struct IgnoreEvents; + + #[cfg(unix)] + #[async_trait::async_trait] + impl builderbot_actions::ExecutionListener for IgnoreEvents { + async fn on_event(&self, _event: builderbot_actions::ExecutionEvent) {} + } + + /// Start an action that prints and then waits to be stopped, registered + /// as running on `branch_id`. + #[cfg(unix)] + async fn start_branch_action( + executor: &ActionExecutor, + registry: &ActionRegistry, + branch_id: &str, + ) -> String { + let execution_id = executor + .execute_remote( + std::path::PathBuf::from("/bin/sh"), + vec!["-c".to_string(), "printf out; sleep 600".to_string()], + Arc::new(IgnoreEvents), + ) + .await + .unwrap(); + register(registry, &execution_id, branch_id, "run"); + execution_id + } + + #[cfg(unix)] + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn stopping_a_branch_for_deletion_discards_its_action_output() { + let executor = ActionExecutor::new(); + let registry = ActionRegistry::new(); + let deleted = start_branch_action(&executor, ®istry, "deleted-branch").await; + let moved = start_branch_action(&executor, ®istry, "moved-branch").await; + + stop_and_discard_actions_for_branches(&executor, ®istry, &["deleted-branch"]); + stop_actions_for_branches(&executor, ®istry, &["moved-branch"]); + assert!(executor.wait_for_executions( + &[deleted.clone(), moved.clone()], + std::time::Duration::from_secs(60) + )); + + // A deleted branch's output is gone the moment its action exits. A + // branch that lives on keeps it, so its card can still show it. + assert!(executor.get_buffered_output(&deleted).is_none()); + assert!(executor.get_buffered_output(&moved).is_some()); + } + #[test] fn snapshot_running_actions_drops_dead_executions_and_joins_phases() { let registry = ActionRegistry::new(); diff --git a/apps/staged/src-tauri/src/branch_teardown.rs b/apps/staged/src-tauri/src/branch_teardown.rs index f67838af3..7765ff7f7 100644 --- a/apps/staged/src-tauri/src/branch_teardown.rs +++ b/apps/staged/src-tauri/src/branch_teardown.rs @@ -38,10 +38,11 @@ pub(crate) struct TeardownServices { } impl TeardownServices { - /// Stop the actions and sessions running on `branches`. + /// Stop the actions and sessions running on `branches`. The branches are + /// about to be deleted, so the actions' output is given up as well. async fn stop_work(&self, branches: &[store::Branch]) -> Result<(), String> { let branch_ids: Vec<&str> = branches.iter().map(|b| b.id.as_str()).collect(); - crate::actions::commands::stop_actions_for_branches( + crate::actions::commands::stop_and_discard_actions_for_branches( &self.action_executor, &self.action_registry, &branch_ids, diff --git a/crates/builderbot-actions/src/executor.rs b/crates/builderbot-actions/src/executor.rs index 2fb50dd93..2917d11b9 100644 --- a/crates/builderbot-actions/src/executor.rs +++ b/crates/builderbot-actions/src/executor.rs @@ -2,20 +2,37 @@ //! //! Manages spawning shell commands with real-time output streaming, //! tracking running processes, and handling termination. +//! +//! Output is also buffered so a viewer can catch up on it. That buffer is +//! bounded: each execution keeps only its most recent output, and only the +//! last few finished executions keep theirs. use anyhow::{Context, Result}; use async_trait::async_trait; use std::collections::{HashMap, HashSet}; +use std::convert::Infallible; use std::io::{Read, Write}; use std::path::PathBuf; use std::process::{Child, Command, Stdio}; -use std::sync::{Arc, Mutex}; +use std::sync::{mpsc, Arc, Mutex}; use std::thread; use std::time::{Duration, Instant}; use tokio::runtime::Handle; use tokio::sync::oneshot; +use crate::finished_outputs::{FinishedOutputs, MAX_FINISHED_EXECUTIONS}; use crate::models::{ActionStatus, ExecutionEvent, OutputChunk}; +use crate::output_buffer::{OutputBuffer, SharedOutputBuffer, MAX_OUTPUT_BYTES}; +use crate::utf8_stream::Utf8StreamDecoder; + +#[cfg(all(test, unix))] +mod tests; + +/// How long completion waits, once the process has exited, for the reader +/// threads to reach the end of its output. Only what the kernel still holds +/// is left to read by then, so this elapses only when something that outlived +/// the process keeps the output open. +const READER_DRAIN_TIMEOUT: Duration = Duration::from_secs(2); // ============================================================================= // PTY support (unix only) @@ -110,19 +127,45 @@ impl Default for StopOptions { } } +/// Bounds on what the executor retains and how long it waits. Fixed in +/// production; the tests shrink them. +#[derive(Clone, Copy)] +struct Limits { + /// Most recent output kept per execution, in bytes. + max_output_bytes: usize, + /// How many finished executions keep their output. + max_finished: usize, + reader_drain_timeout: Duration, +} + +impl Default for Limits { + fn default() -> Self { + Self { + max_output_bytes: MAX_OUTPUT_BYTES, + max_finished: MAX_FINISHED_EXECUTIONS, + reader_drain_timeout: READER_DRAIN_TIMEOUT, + } + } +} + /// Internal state for a running action struct RunningActionState { child_pid: Option, - output_buffer: Arc>>, + output_buffer: SharedOutputBuffer, + /// Set by `discard_output`: free the output at exit instead of retaining it. + discard_output: bool, } /// Manages action execution with real-time output streaming pub struct ActionExecutor { running: Arc>>, - completed: Arc>>>, + /// Output of the most recently finished executions. Locked after + /// `running` wherever both are held. + finished: Arc>, /// Tracks execution IDs that have been explicitly stopped by the user. /// The completion thread checks this to emit `Stopped` instead of `Failed`. stopped: Arc>>, + limits: Limits, } impl Default for ActionExecutor { @@ -133,64 +176,81 @@ impl Default for ActionExecutor { /// Spawn a thread that reads from `stream` and emits output events via `listener`. /// -/// Each chunk is also appended to `buffer` for later retrieval. +/// Each chunk is also appended to `buffer` for later retrieval. `done` is +/// dropped when the thread reaches the end of the stream, which is how the +/// completion thread learns that all of the output has been delivered. fn spawn_stream_reader( mut stream: impl Read + Send + 'static, stream_name: &'static str, exec_id: String, listener: Arc, - buffer: Arc>>, + buffer: SharedOutputBuffer, handle: Handle, + done: mpsc::Sender, ) { thread::spawn(move || { + let _done = done; + + let deliver = |chunk: String| { + if chunk.is_empty() { + return; + } + let timestamp = now_timestamp(); + + // Store in buffer + buffer.lock().unwrap().push(stream_name, &chunk, timestamp); + + // Emit event + handle.block_on(listener.on_event(ExecutionEvent::Output { + execution_id: exec_id.clone(), + chunk, + stream: stream_name.to_string(), + timestamp, + })); + }; + + // A read can end part-way through a multi-byte character, so the + // decoder carries the unfinished bytes over to the next read. + let mut decoder = Utf8StreamDecoder::default(); let mut buf = [0u8; 1024]; loop { match stream.read(&mut buf) { Ok(0) => break, // EOF - Ok(n) => { - let chunk = String::from_utf8_lossy(&buf[..n]).to_string(); - let timestamp = now_timestamp(); - - // Store in buffer - { - let mut b = buffer.lock().unwrap(); - b.push(OutputChunk { - chunk: chunk.clone(), - stream: stream_name.to_string(), - timestamp, - }); - } - - // Emit event - let listener = listener.clone(); - let exec_id = exec_id.clone(); - handle.block_on(async move { - listener - .on_event(ExecutionEvent::Output { - execution_id: exec_id, - chunk, - stream: stream_name.to_string(), - timestamp, - }) - .await; - }); - } + Ok(n) => deliver(decoder.decode(&buf[..n])), // PTY master returns EIO (not EOF) when the slave side is // closed, which is the normal shutdown path. Treat all read // errors as end-of-stream. Err(_) => break, } } + deliver(decoder.finish()); }); } +/// Wait up to `timeout` for every reader thread to reach the end of its +/// stream. Returns whether they all did. +/// +/// Nothing is ever sent on the channel. Each reader holds a sender and drops +/// it when it ends, so the channel disconnects once the last one is done. +fn wait_for_readers(readers_done: &mpsc::Receiver, timeout: Duration) -> bool { + matches!( + readers_done.recv_timeout(timeout), + Err(mpsc::RecvTimeoutError::Disconnected) + ) +} + impl ActionExecutor { /// Create a new action executor pub fn new() -> Self { + Self::with_limits(Limits::default()) + } + + fn with_limits(limits: Limits) -> Self { Self { running: Arc::new(Mutex::new(HashMap::new())), - completed: Arc::new(Mutex::new(HashMap::new())), + finished: Arc::new(Mutex::new(FinishedOutputs::new(limits.max_finished))), stopped: Arc::new(Mutex::new(HashSet::new())), + limits, } } @@ -213,7 +273,7 @@ impl ActionExecutor { let child_pid = child.id(); // Create output buffer - let output_buffer = Arc::new(Mutex::new(Vec::new())); + let output_buffer = OutputBuffer::shared(self.limits.max_output_bytes); let started_at = now_timestamp(); // Record the running action @@ -224,6 +284,7 @@ impl ActionExecutor { RunningActionState { child_pid: Some(child_pid), output_buffer: output_buffer.clone(), + discard_output: false, }, ); } @@ -247,6 +308,7 @@ impl ActionExecutor { // single output stream — the PTY merges stdout and stderr, matching // real terminal behavior. Otherwise (remote execution), we read from // the child's piped stdout and stderr separately. + let (reader_done, readers_done) = mpsc::channel::(); if let Some(pty_master) = pty_reader { spawn_stream_reader( pty_master, @@ -255,6 +317,7 @@ impl ActionExecutor { listener.clone(), output_buffer.clone(), handle.clone(), + reader_done.clone(), ); } else { if let Some(stdout) = child.stdout.take() { @@ -265,6 +328,7 @@ impl ActionExecutor { listener.clone(), output_buffer.clone(), handle.clone(), + reader_done.clone(), ); } @@ -276,16 +340,21 @@ impl ActionExecutor { listener.clone(), output_buffer.clone(), handle.clone(), + reader_done.clone(), ); } } + // Only the readers hold a sender from here on. + drop(reader_done); + // Spawn thread to wait for completion let exec_id = execution_id.clone(); let running_clone = self.running.clone(); - let completed_clone = self.completed.clone(); + let finished_clone = self.finished.clone(); let stopped_clone = self.stopped.clone(); let action_started_at = started_at; + let reader_drain_timeout = self.limits.reader_drain_timeout; thread::spawn(move || { let exit_status = child.wait(); @@ -298,16 +367,27 @@ impl ActionExecutor { stopped.remove(&exec_id) }; - // Move output buffer to completed actions map and remove from running + // Remove from running and hand the output buffer to the finished + // set. The buffer itself moves: nothing is copied, and the readers + // keep appending to the same one. { let mut running = running_clone.lock().unwrap(); if let Some(state) = running.remove(&exec_id) { - let output = state.output_buffer.lock().unwrap().clone(); - let mut completed = completed_clone.lock().unwrap(); - completed.insert(exec_id.clone(), output); + if !state.discard_output { + let mut finished = finished_clone.lock().unwrap(); + finished.insert(exec_id.clone(), state.output_buffer); + } } } + // The process has exited, but the readers may not have delivered + // the last of its output yet. Wait for them, so that the terminal + // status follows all of the output and the finished log is whole. + // The wait is bounded because a process that outlives the action + // can hold the output open indefinitely; whatever it writes later + // still lands in the same buffer. + wait_for_readers(&readers_done, reader_drain_timeout); + let success = exit_status.as_ref().map(|s| s.success()).unwrap_or(false); // Determine the correct status: @@ -566,7 +646,7 @@ impl ActionExecutor { } // Read the PID but do NOT remove from the running map. The completion - // thread needs the entry to move the output buffer to the completed map + // thread needs the entry to move the output buffer to the finished set // and to emit the proper StatusChanged event. let pid = { let running = self.running.lock().unwrap(); @@ -652,19 +732,24 @@ impl ActionExecutor { } } - /// Get buffered output for an execution + /// Get buffered output for an execution. + /// + /// Only the most recent output is kept. Once earlier output has been + /// dropped, the first chunk is a notice saying how much. Returns `None` + /// for an unknown execution, and for a finished one whose output has been + /// cleared or evicted. pub fn get_buffered_output(&self, execution_id: &str) -> Option> { - // First check running actions - let running = self.running.lock().unwrap(); - if let Some(state) = running.get(execution_id) { - let buffer = state.output_buffer.lock().unwrap(); - return Some(buffer.clone()); - } - drop(running); + // First check running actions, then finished ones + let buffer = { + let running = self.running.lock().unwrap(); + match running.get(execution_id) { + Some(state) => Some(state.output_buffer.clone()), + None => self.finished.lock().unwrap().get(execution_id), + } + }; - // If not running, check completed actions - let completed = self.completed.lock().unwrap(); - completed.get(execution_id).cloned() + // Copy the output with only the buffer itself locked. + buffer.map(|buffer| buffer.lock().unwrap().snapshot()) } /// Check if an action is currently running @@ -679,11 +764,27 @@ impl ActionExecutor { running.keys().cloned().collect() } - /// Clear buffered output for a completed execution - /// This removes the output from the completed actions map + /// Clear buffered output for a finished execution. Returns whether any + /// was retained. A running execution is left alone. pub fn clear_execution(&self, execution_id: &str) -> bool { - let mut completed = self.completed.lock().unwrap(); - completed.remove(execution_id).is_some() + self.finished.lock().unwrap().remove(execution_id) + } + + /// Give up an execution's output, whether or not it has finished. + /// + /// A finished execution's output is freed now. A running execution keeps + /// buffering for whoever is watching it, and its output is freed when it + /// exits instead of being retained. Returns whether the execution was + /// running or retained. + pub fn discard_output(&self, execution_id: &str) -> bool { + // Hold `running` across both checks so that an execution cannot + // finish, and be retained, in between them. + let mut running = self.running.lock().unwrap(); + if let Some(state) = running.get_mut(execution_id) { + state.discard_output = true; + return true; + } + self.finished.lock().unwrap().remove(execution_id) } } diff --git a/crates/builderbot-actions/src/executor/tests.rs b/crates/builderbot-actions/src/executor/tests.rs new file mode 100644 index 000000000..40f391b42 --- /dev/null +++ b/crates/builderbot-actions/src/executor/tests.rs @@ -0,0 +1,577 @@ +//! Tests for how the executor buffers, bounds and retains output. +//! +//! Most of them run a short `/bin/sh` script through `execute_remote`, which +//! spawns the program directly on pipes: unlike the local path it does not +//! load the user's shell profile, so the output is exactly what the script +//! writes. +//! +//! On a busy macOS machine a child is now and then killed with `SIGKILL` +//! right after it is spawned, before it runs any of its script. The executor +//! before these changes shows the same under the same load, so it is not +//! something these tests are about. They start their scripts through +//! [`finish`] and [`run_sh_until_output`], which run a script again when that +//! happens instead of failing on it. + +use std::future::Future; +use std::path::PathBuf; +use std::sync::mpsc::{Receiver, Sender}; + +use super::*; + +/// Upper bound on any single wait. Generous, so a loaded machine does not +/// fail a test; a healthy run takes milliseconds. +const WAIT: Duration = Duration::from_secs(60); + +/// How many times a script is started before a test gives up on a child that +/// keeps being killed at birth. One retry is already rare. +const SPAWN_ATTEMPTS: usize = 5; + +/// Forwards every execution event to the test. +struct Recorder { + events: Sender, + /// How long handling one output event takes. The executor calls its + /// listener synchronously, so this is how far behind a reader falls. + output_delay: Duration, +} + +#[async_trait] +impl ExecutionListener for Recorder { + async fn on_event(&self, event: ExecutionEvent) { + if matches!(event, ExecutionEvent::Output { .. }) { + thread::sleep(self.output_delay); + } + let _ = self.events.send(event); + } +} + +fn recorder() -> (Arc, Receiver) { + slow_recorder(Duration::ZERO) +} + +fn slow_recorder(output_delay: Duration) -> (Arc, Receiver) { + let (events, receiver) = mpsc::channel(); + ( + Arc::new(Recorder { + events, + output_delay, + }), + receiver, + ) +} + +/// What an execution reported up to and including its terminal status. +struct Outcome { + /// The text of every output event, in order. + streamed: Vec, + status: ActionStatus, + exit_code: Option, +} + +impl Outcome { + fn streamed_text(&self) -> String { + self.streamed.concat() + } + + /// Whether the child died from a signal without writing anything: the + /// kill described in the module docs. No script here ends that way. + fn killed_at_birth(&self) -> bool { + self.status == ActionStatus::Failed && self.exit_code.is_none() && self.streamed.is_empty() + } + + /// Fail with the exit code and the end of the output, which is where a + /// shell says what went wrong, unless the execution exited cleanly. + fn assert_completed(&self) { + let text = self.streamed_text(); + let tail: String = text + .chars() + .skip(text.chars().count().saturating_sub(400)) + .collect(); + assert!( + self.status == ActionStatus::Completed && self.exit_code == Some(0), + "expected a clean exit, got {:?} with exit code {:?}; output ends: {tail:?}", + self.status, + self.exit_code, + ); + } +} + +fn wait_for_finish(events: &Receiver) -> Outcome { + let mut streamed = Vec::new(); + loop { + match events + .recv_timeout(WAIT) + .expect("the execution did not finish") + { + ExecutionEvent::Started { .. } => {} + ExecutionEvent::Output { chunk, .. } => streamed.push(chunk), + ExecutionEvent::StatusChanged { + status, exit_code, .. + } => { + return Outcome { + streamed, + status, + exit_code, + } + } + } + } +} + +fn wait_until(what: &str, mut condition: impl FnMut() -> bool) { + let deadline = Instant::now() + WAIT; + while !condition() { + assert!(Instant::now() < deadline, "timed out waiting for {what}"); + thread::sleep(Duration::from_millis(10)); + } +} + +/// Limits for tests that are not about the drain timeout: a slow machine must +/// never cut the wait for the readers short. +fn patient_limits() -> Limits { + Limits { + reader_drain_timeout: WAIT, + ..Limits::default() + } +} + +async fn run_sh(executor: &ActionExecutor, script: &str) -> (String, Receiver) { + run_sh_with(executor, script, recorder()).await +} + +async fn run_sh_with( + executor: &ActionExecutor, + script: &str, + (listener, events): (Arc, Receiver), +) -> (String, Receiver) { + let execution_id = executor + .execute_remote( + PathBuf::from("/bin/sh"), + vec!["-c".to_string(), script.to_string()], + listener, + ) + .await + .expect("failed to spawn /bin/sh"); + (execution_id, events) +} + +/// An execution that ran to its terminal status. +struct Finished { + id: String, + /// Whatever the execution reports after its terminal status. + events: Receiver, + outcome: Outcome, +} + +/// Run what `start` starts to its terminal status. +/// +/// An attempt whose child was killed at birth is started again. Its empty +/// log is cleared first, so it does not count as a finished execution. +async fn finish(executor: &ActionExecutor, start: F) -> Finished +where + F: Fn() -> Fut, + Fut: Future)>, +{ + for _ in 0..SPAWN_ATTEMPTS { + let (id, events) = start().await; + let outcome = wait_for_finish(&events); + if !outcome.killed_at_birth() { + return Finished { + id, + events, + outcome, + }; + } + executor.clear_execution(&id); + } + panic!("the child was killed before running {SPAWN_ATTEMPTS} times in a row"); +} + +/// Run a script to its terminal status. +async fn run_sh_to_finish(executor: &ActionExecutor, script: &str) -> Finished { + finish(executor, || run_sh(executor, script)).await +} + +/// Start a script that then blocks on a [`Gate`], and wait until its +/// buffered output is exactly `first`. +/// +/// Like [`finish`], starts the script again if its child is killed at birth. +async fn run_sh_until_output( + executor: &ActionExecutor, + script: &str, + first: &str, +) -> (String, Receiver) { + for _ in 0..SPAWN_ATTEMPTS { + let (id, events) = run_sh(executor, script).await; + let deadline = Instant::now() + WAIT; + while executor.is_running(&id) { + if buffered_text(executor, &id).as_deref() == Some(first) { + return (id, events); + } + assert!(Instant::now() < deadline, "timed out waiting for {first:?}"); + thread::sleep(Duration::from_millis(10)); + } + // The gate is still closed, so the script cannot have got this far. + let outcome = wait_for_finish(&events); + assert!( + outcome.killed_at_birth(), + "the script exited at its gate: {:?} with exit code {:?}", + outcome.status, + outcome.exit_code, + ); + executor.clear_execution(&id); + } + panic!("the child was killed before running {SPAWN_ATTEMPTS} times in a row"); +} + +fn buffered_text(executor: &ActionExecutor, execution_id: &str) -> Option { + executor + .get_buffered_output(execution_id) + .map(|chunks| chunks.iter().map(|c| c.chunk.as_str()).collect()) +} + +/// A file a script waits on, so a test can hold an action open and release +/// it. Dropping the gate releases it too, so a failed test leaves no script +/// behind. +struct Gate(PathBuf); + +impl Gate { + fn closed() -> Self { + let path = std::env::temp_dir().join(format!( + "builderbot-actions-test-gate-{}", + uuid::Uuid::new_v4() + )); + std::fs::write(&path, b"").expect("failed to create the gate file"); + Self(path) + } + + /// Shell that blocks until the gate opens. + fn wait(&self) -> String { + format!("while [ -e '{}' ]; do sleep 0.05; done", self.0.display()) + } + + fn open(&self) { + let _ = std::fs::remove_file(&self.0); + } +} + +impl Drop for Gate { + fn drop(&mut self) { + self.open(); + } +} + +/// A stream that returns the given reads one at a time, then ends. +struct ScriptedReads(std::vec::IntoIter>); + +impl Read for ScriptedReads { + fn read(&mut self, buf: &mut [u8]) -> std::io::Result { + let Some(next) = self.0.next() else { + return Ok(0); + }; + buf[..next.len()].copy_from_slice(&next); + Ok(next.len()) + } +} + +// ============================================================================= +// Item 1: the buffer moves at exit, after the readers finish +// ============================================================================= + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn output_written_just_before_exit_is_in_the_finished_log() { + let executor = ActionExecutor::with_limits(patient_limits()); + // The output fits in the pipe, so the shell exits at once. The listener + // is slow, so most of the output is still unread when it does. + let Finished { + id, + events, + outcome, + } = finish(&executor, || { + run_sh_with( + &executor, + "head -c 8000 /dev/zero | tr '\\0' x; printf END", + slow_recorder(Duration::from_millis(20)), + ) + }) + .await; + + outcome.assert_completed(); + let streamed = outcome.streamed_text(); + assert_eq!(streamed.len(), 8_003); + assert!(streamed.ends_with("xEND")); + // The finished log is whole the moment the terminal status arrives, and + // no output event follows that status. + assert_eq!(buffered_text(&executor, &id).as_deref(), Some(&*streamed)); + assert!(events.try_recv().is_err()); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn finishing_moves_the_buffer_instead_of_copying_it() { + let executor = ActionExecutor::with_limits(patient_limits()); + let gate = Gate::closed(); + let (id, events) = run_sh_until_output( + &executor, + &format!("printf start; {}; printf end", gate.wait()), + "start", + ) + .await; + let live_buffer = { + let running = executor.running.lock().unwrap(); + running.get(&id).unwrap().output_buffer.clone() + }; + + gate.open(); + wait_for_finish(&events); + + assert!(!executor.is_running(&id)); + let finished_buffer = executor.finished.lock().unwrap().get(&id).unwrap(); + assert!(Arc::ptr_eq(&live_buffer, &finished_buffer)); + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("startend")); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn a_process_that_outlives_the_action_does_not_block_completion() { + let executor = ActionExecutor::with_limits(Limits { + reader_drain_timeout: Duration::from_millis(200), + ..Limits::default() + }); + let gate = Gate::closed(); + // The background job inherits the pipes and keeps them open after the + // shell exits, so the readers cannot reach the end of the output. + let Finished { id, outcome, .. } = run_sh_to_finish( + &executor, + &format!("printf first; ({}; printf late) &", gate.wait()), + ) + .await; + + // Completion gave up on the readers instead of waiting for the gate. + outcome.assert_completed(); + wait_until("the output written before exit", || { + buffered_text(&executor, &id).as_deref() == Some("first") + }); + + // What the survivor writes afterwards still reaches the finished log. + gate.open(); + wait_until("the late output", || { + buffered_text(&executor, &id).as_deref() == Some("firstlate") + }); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn local_execution_keeps_its_last_output() { + let executor = ActionExecutor::with_limits(patient_limits()); + // The local path runs the user's login shell on a PTY, whose profile may + // print as well, so only look for the action's own line. + let Finished { id, outcome, .. } = finish(&executor, || async { + let (listener, events) = recorder(); + let id = executor + .execute( + "printf 'tail-%s\\n' marker".to_string(), + std::env::temp_dir().to_string_lossy().to_string(), + listener, + ) + .await + .expect("failed to spawn the login shell"); + (id, events) + }) + .await; + + outcome.assert_completed(); + assert!(outcome.streamed_text().contains("tail-marker")); + assert_eq!(buffered_text(&executor, &id), Some(outcome.streamed_text())); +} + +// ============================================================================= +// Item 2: the buffer is capped and coalesced +// ============================================================================= + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn buffered_output_is_capped_to_the_most_recent_bytes() { + let max_output_bytes = 16 * 1024; + let executor = ActionExecutor::with_limits(Limits { + max_output_bytes, + ..patient_limits() + }); + let Finished { id, outcome, .. } = run_sh_to_finish(&executor, "seq 1 20000").await; + + // Streaming is not capped: every line was delivered as it was written. + let written: String = (1..=20_000).map(|n| format!("{n}\n")).collect(); + assert_eq!(outcome.streamed_text(), written); + + let chunks = executor.get_buffered_output(&id).unwrap(); + let (notice, retained) = chunks.split_first().unwrap(); + let retained: String = retained.iter().map(|c| c.chunk.as_str()).collect(); + // The buffer holds the end of the output, on a line boundary, within the + // cap... + assert!(retained.len() <= max_output_bytes); + assert!(retained.len() > max_output_bytes / 2); + assert!(written.ends_with(&retained)); + let first_line: u32 = retained.lines().next().unwrap().parse().unwrap(); + assert!(written.contains(&format!("\n{first_line}\n"))); + // ...and says up front that the rest is gone. + assert_eq!(notice.stream, "stderr"); + assert!( + notice.chunk.starts_with("[earlier output truncated: ") + && notice.chunk.ends_with(" KB dropped]\n"), + "unexpected notice {:?}", + notice.chunk + ); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn reads_of_one_stream_are_coalesced() { + let executor = ActionExecutor::with_limits(patient_limits()); + let written: String = (1..=3_000).map(|n| format!("{n}\n")).collect(); + + for (script, stream) in [("seq 1 3000", "stdout"), ("seq 1 3000 >&2", "stderr")] { + let Finished { id, outcome, .. } = run_sh_to_finish(&executor, script).await; + + // Many reads were streamed, and they are buffered as a single block. + assert!( + outcome.streamed.len() > 10, + "{} reads", + outcome.streamed.len() + ); + let chunks = executor.get_buffered_output(&id).unwrap(); + assert_eq!(chunks.len(), 1); + assert_eq!(chunks[0].stream, stream); + assert_eq!(chunks[0].chunk, written); + } +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn a_character_split_across_reads_is_decoded_whole() { + let (listener, events) = recorder(); + let buffer = OutputBuffer::shared(MAX_OUTPUT_BYTES); + let (reader_done, readers_done) = mpsc::channel(); + // "café €" with both multi-byte characters cut by a read boundary. + let reads = vec![ + b"caf\xc3".to_vec(), + b"\xa9 \xe2".to_vec(), + b"\x82".to_vec(), + b"\xac".to_vec(), + ]; + + spawn_stream_reader( + ScriptedReads(reads.into_iter()), + "stdout", + "exec".to_string(), + listener, + buffer.clone(), + Handle::current(), + reader_done, + ); + assert!(wait_for_readers(&readers_done, WAIT)); + + let streamed: Vec = events + .try_iter() + .map(|event| match event { + ExecutionEvent::Output { chunk, .. } => chunk, + other => panic!("unexpected event {other:?}"), + }) + .collect(); + // Each character is delivered once, with the read that completes it. + assert_eq!(streamed, vec!["caf", "é ", "€"]); + let chunks = buffer.lock().unwrap().snapshot(); + assert_eq!(chunks.len(), 1); + assert_eq!(chunks[0].chunk, "café €"); +} + +// ============================================================================= +// Item 3: finished buffers are evicted +// ============================================================================= + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn only_the_most_recently_finished_executions_keep_their_output() { + let executor = ActionExecutor::with_limits(Limits { + max_finished: 2, + ..patient_limits() + }); + + let mut ids = Vec::new(); + for word in ["one", "two", "three"] { + ids.push( + run_sh_to_finish(&executor, &format!("printf {word}")) + .await + .id, + ); + } + + assert_eq!(buffered_text(&executor, &ids[0]), None); + assert_eq!(buffered_text(&executor, &ids[1]).as_deref(), Some("two")); + assert_eq!(buffered_text(&executor, &ids[2]).as_deref(), Some("three")); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn the_default_limit_keeps_a_handful_of_finished_executions() { + let executor = ActionExecutor::with_limits(patient_limits()); + + let mut ids = Vec::new(); + for n in 0..MAX_FINISHED_EXECUTIONS + 2 { + ids.push(run_sh_to_finish(&executor, &format!("printf {n}")).await.id); + } + + let retained = ids + .iter() + .filter(|id| executor.get_buffered_output(id).is_some()) + .count(); + assert_eq!(retained, MAX_FINISHED_EXECUTIONS); + assert_eq!(buffered_text(&executor, &ids[0]), None); + assert_eq!(buffered_text(&executor, &ids[1]), None); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn clear_execution_frees_a_finished_execution_only() { + let executor = ActionExecutor::with_limits(patient_limits()); + let gate = Gate::closed(); + let (id, events) = + run_sh_until_output(&executor, &format!("printf out; {}", gate.wait()), "out").await; + + // Running: nothing is cleared. + assert!(!executor.clear_execution(&id)); + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("out")); + + gate.open(); + wait_for_finish(&events); + + // Finished: cleared once. + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("out")); + assert!(executor.clear_execution(&id)); + assert_eq!(buffered_text(&executor, &id), None); + assert!(!executor.clear_execution(&id)); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn discarding_a_running_execution_frees_its_output_at_exit() { + let executor = ActionExecutor::with_limits(patient_limits()); + let gate = Gate::closed(); + let (id, events) = run_sh_until_output( + &executor, + &format!("printf start; {}; printf end", gate.wait()), + "start", + ) + .await; + + assert!(executor.discard_output(&id)); + // Still readable while it runs, and still streamed to its listener. + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("start")); + gate.open(); + let outcome = wait_for_finish(&events); + assert_eq!(outcome.streamed_text(), "startend"); + + // Never retained once it has exited. + assert_eq!(buffered_text(&executor, &id), None); + assert!(executor.finished.lock().unwrap().get(&id).is_none()); + assert!(!executor.discard_output(&id)); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn discarding_a_finished_execution_frees_its_output_now() { + let executor = ActionExecutor::with_limits(patient_limits()); + let Finished { id, .. } = run_sh_to_finish(&executor, "printf out").await; + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("out")); + + assert!(executor.discard_output(&id)); + assert_eq!(buffered_text(&executor, &id), None); + assert!(!executor.discard_output("no-such-execution")); +} diff --git a/crates/builderbot-actions/src/finished_outputs.rs b/crates/builderbot-actions/src/finished_outputs.rs new file mode 100644 index 000000000..f82679ecb --- /dev/null +++ b/crates/builderbot-actions/src/finished_outputs.rs @@ -0,0 +1,104 @@ +//! Output of executions that have ended. +//! +//! A viewer can still ask for an execution's output shortly after it ends, so +//! the executor cannot drop the buffer at exit. It keeps the buffers of the +//! last few executions instead, which bounds what finished work costs however +//! long the process lives. + +use std::collections::VecDeque; + +use crate::output_buffer::SharedOutputBuffer; + +/// How many finished executions keep their output. +pub(crate) const MAX_FINISHED_EXECUTIONS: usize = 8; + +/// The output buffers of the most recently finished executions. +pub(crate) struct FinishedOutputs { + /// Oldest first. + entries: VecDeque<(String, SharedOutputBuffer)>, + max_entries: usize, +} + +impl FinishedOutputs { + pub(crate) fn new(max_entries: usize) -> Self { + Self { + entries: VecDeque::new(), + max_entries, + } + } + + /// Retain the output of an execution that has just ended, evicting the + /// longest-finished ones beyond the limit. + pub(crate) fn insert(&mut self, execution_id: String, output: SharedOutputBuffer) { + self.entries.push_back((execution_id, output)); + while self.entries.len() > self.max_entries { + self.entries.pop_front(); + } + } + + pub(crate) fn get(&self, execution_id: &str) -> Option { + self.entries + .iter() + .find(|(id, _)| id == execution_id) + .map(|(_, output)| output.clone()) + } + + /// Stop retaining an execution's output. Returns whether it was retained. + pub(crate) fn remove(&mut self, execution_id: &str) -> bool { + let before = self.entries.len(); + self.entries.retain(|(id, _)| id != execution_id); + self.entries.len() != before + } +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::output_buffer::OutputBuffer; + + fn insert(finished: &mut FinishedOutputs, id: &str) { + finished.insert(id.to_string(), OutputBuffer::shared(1024)); + } + + #[test] + fn the_longest_finished_execution_is_evicted_first() { + let mut finished = FinishedOutputs::new(2); + insert(&mut finished, "a"); + insert(&mut finished, "b"); + assert!(finished.get("a").is_some()); + + insert(&mut finished, "c"); + assert!(finished.get("a").is_none()); + assert!(finished.get("b").is_some()); + assert!(finished.get("c").is_some()); + } + + #[test] + fn remove_reports_whether_the_execution_was_retained() { + let mut finished = FinishedOutputs::new(2); + insert(&mut finished, "a"); + + assert!(finished.remove("a")); + assert!(finished.get("a").is_none()); + assert!(!finished.remove("a")); + } + + #[test] + fn removing_one_execution_frees_its_slot() { + let mut finished = FinishedOutputs::new(2); + insert(&mut finished, "a"); + insert(&mut finished, "b"); + finished.remove("a"); + insert(&mut finished, "c"); + + assert!(finished.get("b").is_some()); + assert!(finished.get("c").is_some()); + } + + #[test] + fn a_limit_of_zero_retains_nothing() { + let mut finished = FinishedOutputs::new(0); + insert(&mut finished, "a"); + assert!(finished.get("a").is_none()); + } +} diff --git a/crates/builderbot-actions/src/lib.rs b/crates/builderbot-actions/src/lib.rs index b1a6389ba..3067cb54b 100644 --- a/crates/builderbot-actions/src/lib.rs +++ b/crates/builderbot-actions/src/lib.rs @@ -53,7 +53,10 @@ pub mod acp_provider; pub mod detector; pub mod executor; +mod finished_outputs; pub mod models; +mod output_buffer; +mod utf8_stream; // Re-export main types for convenience pub use acp_provider::AcpAiProvider; diff --git a/crates/builderbot-actions/src/output_buffer.rs b/crates/builderbot-actions/src/output_buffer.rs new file mode 100644 index 000000000..4d5b838e8 --- /dev/null +++ b/crates/builderbot-actions/src/output_buffer.rs @@ -0,0 +1,366 @@ +//! Bounded storage for one execution's output. +//! +//! The executor keeps recent output so that a viewer opened part-way through a +//! run, or just after it, can show what it missed. Output is unbounded and a +//! progress bar redraws constantly, so the buffer keeps only the most recent +//! bytes and merges the small reads it is fed into larger blocks. + +use std::collections::VecDeque; +use std::sync::{Arc, Mutex}; + +use crate::models::OutputChunk; + +/// Most recent output kept per execution, in bytes. +pub(crate) const MAX_OUTPUT_BYTES: usize = 4 * 1024 * 1024; + +/// Adjacent reads of one stream are merged into blocks of up to this size. +const MAX_BLOCK_BYTES: usize = 64 * 1024; + +/// What a block costs beyond its text. Counting it keeps the bound honest when +/// two streams alternate and every block is tiny. +const BLOCK_OVERHEAD_BYTES: usize = std::mem::size_of::(); + +/// Stream the truncation notice is reported on, so that viewers which tell the +/// streams apart set it off from the command's own output. +const NOTICE_STREAM: &str = "stderr"; + +/// An output buffer shared between the reader threads that fill it and the +/// executor that hands it out. +pub(crate) type SharedOutputBuffer = Arc>; + +/// The most recent output of one execution. +pub(crate) struct OutputBuffer { + /// Oldest first. Each block is consecutive output of a single stream. + blocks: VecDeque, + /// Size of `blocks`: their text plus the per-block overhead. + retained_bytes: usize, + /// Bytes of output text evicted from the front so far. + dropped_bytes: u64, + /// Whether the oldest retained block starts part-way through a line, + /// because the block evicted before it did not end on a line break. + head_is_partial_line: bool, + max_bytes: usize, + block_bytes: usize, +} + +impl OutputBuffer { + /// A buffer that retains about `max_bytes` of the most recent output. The + /// newest block always stays, so the bound is never below one block. + pub(crate) fn new(max_bytes: usize) -> Self { + Self { + blocks: VecDeque::new(), + retained_bytes: 0, + dropped_bytes: 0, + head_is_partial_line: false, + max_bytes, + block_bytes: MAX_BLOCK_BYTES.min(max_bytes / 4).max(1), + } + } + + pub(crate) fn shared(max_bytes: usize) -> SharedOutputBuffer { + Arc::new(Mutex::new(Self::new(max_bytes))) + } + + /// Append one read of `stream`, evicting the oldest output once the buffer + /// is over its bound. `timestamp` is kept only for the first read of a + /// block. + pub(crate) fn push(&mut self, stream: &str, text: &str, timestamp: i64) { + if text.is_empty() { + return; + } + + let block_bytes = self.block_bytes; + let merged = match self.blocks.back_mut() { + Some(last) if last.stream == stream && last.chunk.len() + text.len() <= block_bytes => { + last.chunk.push_str(text); + true + } + Some(last) => { + // This block is finished: release the slack its growth left. + last.chunk.shrink_to_fit(); + false + } + None => false, + }; + if merged { + self.retained_bytes += text.len(); + } else { + let block = OutputChunk { + chunk: text.to_string(), + stream: stream.to_string(), + timestamp, + }; + self.retained_bytes += block_cost(&block); + self.blocks.push_back(block); + } + + while self.retained_bytes > self.max_bytes && self.blocks.len() > 1 { + let Some(evicted) = self.blocks.pop_front() else { + break; + }; + self.retained_bytes -= block_cost(&evicted); + self.dropped_bytes += evicted.chunk.len() as u64; + self.head_is_partial_line = !evicted.chunk.ends_with(['\n', '\r']); + } + } + + /// The retained output, oldest first. + /// + /// Once earlier output has been dropped, the first chunk is a synthetic + /// notice saying how much, and the output after it starts on a whole line. + pub(crate) fn snapshot(&self) -> Vec { + if self.dropped_bytes == 0 { + return self.blocks.iter().cloned().collect(); + } + + let head = self.blocks.front(); + let skipped = match head { + Some(head) if self.head_is_partial_line => partial_line_len(&head.chunk), + _ => 0, + }; + + let mut chunks = Vec::with_capacity(self.blocks.len() + 1); + chunks.push(OutputChunk { + chunk: truncation_notice(self.dropped_bytes + skipped as u64), + stream: NOTICE_STREAM.to_string(), + timestamp: head.map_or(0, |head| head.timestamp), + }); + for (index, block) in self.blocks.iter().enumerate() { + if index > 0 || skipped == 0 { + chunks.push(block.clone()); + } else if skipped < block.chunk.len() { + chunks.push(OutputChunk { + chunk: block.chunk[skipped..].to_string(), + stream: block.stream.clone(), + timestamp: block.timestamp, + }); + } + } + chunks + } +} + +fn block_cost(block: &OutputChunk) -> usize { + BLOCK_OVERHEAD_BYTES + block.stream.len() + block.chunk.len() +} + +/// Length of the remainder of a line that `text` starts in the middle of, +/// including its line break. Zero when `text` holds no line break, in which +/// case there is no later line to start from. +fn partial_line_len(text: &str) -> usize { + match text.find(['\n', '\r']) { + Some(at) if text[at..].starts_with("\r\n") => at + 2, + Some(at) => at + 1, + None => 0, + } +} + +fn truncation_notice(dropped_bytes: u64) -> String { + format!( + "[earlier output truncated: {} dropped]\n", + format_bytes(dropped_bytes) + ) +} + +fn format_bytes(bytes: u64) -> String { + const KB: f64 = 1024.0; + let bytes_f = bytes as f64; + if bytes_f < KB { + format!("{bytes} B") + } else if bytes_f < KB * KB { + format!("{:.1} KB", bytes_f / KB) + } else if bytes_f < KB * KB * KB { + format!("{:.1} MB", bytes_f / (KB * KB)) + } else { + format!("{:.1} GB", bytes_f / (KB * KB * KB)) + } +} + +#[cfg(test)] +mod tests { + use super::*; + + fn text_of(chunks: &[OutputChunk]) -> String { + chunks.iter().map(|c| c.chunk.as_str()).collect() + } + + #[test] + fn adjacent_reads_of_one_stream_merge_into_one_block() { + let mut buffer = OutputBuffer::new(MAX_OUTPUT_BYTES); + buffer.push("stdout", "one ", 10); + buffer.push("stdout", "two ", 20); + buffer.push("stdout", "three", 30); + + let chunks = buffer.snapshot(); + assert_eq!(chunks.len(), 1); + assert_eq!(chunks[0].chunk, "one two three"); + assert_eq!(chunks[0].stream, "stdout"); + // The block carries the time of its first read. + assert_eq!(chunks[0].timestamp, 10); + } + + #[test] + fn a_change_of_stream_starts_a_new_block() { + let mut buffer = OutputBuffer::new(MAX_OUTPUT_BYTES); + buffer.push("stdout", "out1", 1); + buffer.push("stderr", "err", 2); + buffer.push("stdout", "out2", 3); + buffer.push("stdout", "out3", 4); + + let chunks = buffer.snapshot(); + let seen: Vec<(&str, &str)> = chunks + .iter() + .map(|c| (c.stream.as_str(), c.chunk.as_str())) + .collect(); + assert_eq!( + seen, + vec![ + ("stdout", "out1"), + ("stderr", "err"), + ("stdout", "out2out3") + ] + ); + } + + #[test] + fn blocks_stop_growing_at_the_block_size() { + let mut buffer = OutputBuffer::new(MAX_OUTPUT_BYTES); + let read = "x".repeat(1024); + for _ in 0..200 { + buffer.push("stdout", &read, 0); + } + + let chunks = buffer.snapshot(); + assert_eq!(text_of(&chunks).len(), 200 * 1024); + assert_eq!(chunks.len(), 200 * 1024 / MAX_BLOCK_BYTES + 1); + assert!(chunks.iter().all(|c| c.chunk.len() <= MAX_BLOCK_BYTES)); + } + + #[test] + fn empty_reads_are_ignored() { + let mut buffer = OutputBuffer::new(MAX_OUTPUT_BYTES); + buffer.push("stdout", "", 0); + assert!(buffer.snapshot().is_empty()); + } + + #[test] + fn only_the_most_recent_output_is_retained() { + let max_bytes = 8 * 1024; + let mut buffer = OutputBuffer::new(max_bytes); + let mut written = String::new(); + for line in 0..5_000 { + let text = format!("line {line}\n"); + buffer.push("stdout", &text, line); + written.push_str(&text); + assert!(buffer.retained_bytes <= max_bytes); + } + + let chunks = buffer.snapshot(); + let retained = text_of(&chunks[1..]); + assert!(retained.len() <= max_bytes); + // Nearly the whole budget is used, and what is kept is the end. + assert!(retained.len() > max_bytes / 2); + assert!(written.ends_with(&retained)); + assert!(retained.ends_with("line 4999\n")); + } + + #[test] + fn dropped_output_is_reported_in_a_leading_notice() { + let mut buffer = OutputBuffer::new(4 * 1024); + let line = format!("{}\n", "y".repeat(99)); + for _ in 0..1_000 { + buffer.push("stdout", &line, 7); + } + + let chunks = buffer.snapshot(); + let retained = text_of(&chunks[1..]); + let dropped = 1_000 * line.len() - retained.len(); + assert_eq!(chunks[0].stream, NOTICE_STREAM); + assert_eq!(chunks[0].chunk, truncation_notice(dropped as u64)); + assert!(chunks[0].chunk.ends_with('\n')); + } + + #[test] + fn no_notice_while_nothing_has_been_dropped() { + let mut buffer = OutputBuffer::new(4 * 1024); + buffer.push("stdout", "short\n", 0); + assert_eq!(text_of(&buffer.snapshot()), "short\n"); + } + + #[test] + fn retained_output_starts_on_a_whole_line() { + // Reads that end mid-line, as a full pipe produces them. + let mut buffer = OutputBuffer::new(2 * 1024); + let mut written = String::new(); + for line in 0..2_000 { + written.push_str(&format!("line {line}\n")); + } + for read in written.as_bytes().chunks(100) { + buffer.push("stdout", std::str::from_utf8(read).unwrap(), 0); + } + + let chunks = buffer.snapshot(); + let retained = text_of(&chunks[1..]); + assert!(retained.starts_with("line ")); + assert!(written.ends_with(&retained)); + // The cut-off line counts as dropped. + let dropped = (written.len() - retained.len()) as u64; + assert_eq!(chunks[0].chunk, truncation_notice(dropped)); + } + + #[test] + fn a_whole_line_at_the_cut_is_kept() { + // Reads that are whole lines, as a terminal produces them. + let mut buffer = OutputBuffer::new(2 * 1024); + let mut written = String::new(); + for line in 0..2_000 { + let text = format!("line {line}\n"); + buffer.push("stdout", &text, 0); + written.push_str(&text); + } + + let chunks = buffer.snapshot(); + let retained = text_of(&chunks[1..]); + let dropped = (written.len() - retained.len()) as u64; + // Nothing beyond the evicted blocks is skipped. + assert_eq!(dropped, buffer.dropped_bytes); + assert!(retained.starts_with("line ")); + } + + #[test] + fn carriage_return_redraws_are_capped_too() { + let max_bytes = 4 * 1024; + let mut buffer = OutputBuffer::new(max_bytes); + for frame in 0..10_000 { + buffer.push("stdout", &format!("\rprogress {frame}"), 0); + } + + let chunks = buffer.snapshot(); + let retained = text_of(&chunks[1..]); + assert!(retained.len() <= max_bytes); + assert!(retained.starts_with("progress ")); + assert!(retained.ends_with("\rprogress 9999")); + } + + #[test] + fn alternating_streams_stay_within_the_bound() { + let max_bytes = 4 * 1024; + let mut buffer = OutputBuffer::new(max_bytes); + for i in 0..10_000 { + let stream = if i % 2 == 0 { "stdout" } else { "stderr" }; + buffer.push(stream, "x", 0); + assert!(buffer.retained_bytes <= max_bytes); + } + // Every block is one byte, so the overhead dominates the budget. + assert!(buffer.blocks.len() < max_bytes / BLOCK_OVERHEAD_BYTES); + } + + #[test] + fn sizes_are_formatted_in_readable_units() { + assert_eq!(format_bytes(0), "0 B"); + assert_eq!(format_bytes(1023), "1023 B"); + assert_eq!(format_bytes(1536), "1.5 KB"); + assert_eq!(format_bytes(124 * 1024 * 1024), "124.0 MB"); + assert_eq!(format_bytes(3 * 1024 * 1024 * 1024), "3.0 GB"); + } +} diff --git a/crates/builderbot-actions/src/utf8_stream.rs b/crates/builderbot-actions/src/utf8_stream.rs new file mode 100644 index 000000000..173eb0f8f --- /dev/null +++ b/crates/builderbot-actions/src/utf8_stream.rs @@ -0,0 +1,115 @@ +//! UTF-8 decoding for a byte stream that arrives in arbitrary pieces. + +/// Decodes a byte stream to text one read at a time. +/// +/// A read can end part-way through a multi-byte character. Decoding each read +/// on its own turns both halves into replacement characters, so the unfinished +/// tail of one read is held back and decoded together with the next. +#[derive(Default)] +pub(crate) struct Utf8StreamDecoder { + /// The start of a character whose remaining bytes have not arrived yet. + /// At most three bytes. + pending: Vec, +} + +impl Utf8StreamDecoder { + /// Decode the next read. Invalid bytes become U+FFFD, as with + /// `String::from_utf8_lossy`. The result is empty when the read only + /// continued a character that is still incomplete. + pub(crate) fn decode(&mut self, bytes: &[u8]) -> String { + let joined; + let mut input = if self.pending.is_empty() { + bytes + } else { + self.pending.extend_from_slice(bytes); + joined = std::mem::take(&mut self.pending); + joined.as_slice() + }; + + let mut text = String::with_capacity(input.len()); + loop { + let error = match std::str::from_utf8(input) { + Ok(valid) => { + text.push_str(valid); + break; + } + Err(error) => error, + }; + let (valid, rest) = input.split_at(error.valid_up_to()); + text.push_str(&String::from_utf8_lossy(valid)); + match error.error_len() { + // Bytes that can never start or continue a character. + Some(invalid_len) => { + text.push(char::REPLACEMENT_CHARACTER); + input = &rest[invalid_len..]; + } + // The input ended inside a character: wait for the rest. + None => { + self.pending = rest.to_vec(); + break; + } + } + } + text + } + + /// Call at end of stream. A character that never completed becomes one + /// U+FFFD; otherwise the result is empty. + pub(crate) fn finish(&mut self) -> String { + if self.pending.is_empty() { + return String::new(); + } + self.pending.clear(); + char::REPLACEMENT_CHARACTER.to_string() + } +} + +#[cfg(test)] +mod tests { + use super::*; + + /// Decode `bytes` split at every possible position and check that the + /// result always matches decoding it in one piece. + fn assert_split_invariant(bytes: &[u8]) { + let expected = String::from_utf8_lossy(bytes).to_string(); + for split in 0..=bytes.len() { + let mut decoder = Utf8StreamDecoder::default(); + let mut text = decoder.decode(&bytes[..split]); + text.push_str(&decoder.decode(&bytes[split..])); + text.push_str(&decoder.finish()); + assert_eq!(text, expected, "split at byte {split}"); + } + } + + #[test] + fn characters_split_across_reads_decode_whole() { + // Two, three and four byte characters. + assert_split_invariant("aé€😀z".as_bytes()); + } + + #[test] + fn a_character_fed_one_byte_at_a_time_decodes_whole() { + let mut decoder = Utf8StreamDecoder::default(); + let mut text = String::new(); + for byte in "😀".as_bytes() { + text.push_str(&decoder.decode(std::slice::from_ref(byte))); + } + assert_eq!(text, "😀"); + assert_eq!(decoder.finish(), ""); + } + + #[test] + fn invalid_bytes_match_lossy_decoding_at_any_split() { + // A stray continuation byte, an overlong lead byte, and a three-byte + // character cut short by ASCII. + assert_split_invariant(b"ok\x80mid\xc0\xafx\xe2\x82yz"); + } + + #[test] + fn a_character_cut_off_by_end_of_stream_becomes_one_replacement() { + let mut decoder = Utf8StreamDecoder::default(); + assert_eq!(decoder.decode(b"tail\xe2\x82"), "tail"); + assert_eq!(decoder.finish(), "\u{fffd}"); + assert_eq!(decoder.finish(), ""); + } +} From bd03eba584655ef5bd03ec2f10d92a7fe9ada6e9 Mon Sep 17 00:00:00 2001 From: Matt Toohey Date: Fri, 13 Nov 2026 13:38:15 +1100 Subject: [PATCH 2/4] perf(actions): batch action output and skip work nobody consumes Every read of an action's output, about 1 KB, cost one listener call, one event to every client and a line-buffer append, whether or not anything consumed it. This implements item 4 of the recommended fix in the action output leak note, all three parts, and closes the hole in root cause section 3: a registry entry recreated by output that arrives after `unregister`. Batch the output (item 4, part 1) - New output_emitter module. The reader threads queue their reads for one emitter thread per execution. It merges them and delivers a batch once it is 50 ms old or 64 KiB large, one event per run of a stream. - A batch is appended to the buffer and then handed to the listener, as each read was. Output waiting in a batch is in neither, so the buffer and the events stay in step for a viewer that reads one and then follows the other. - Completion waits for the readers, then has the emitter deliver what it holds, then reports the terminal status. The tail still precedes the status. The flush has its own 2 s bound, so what was read is delivered before the status even when the readers used up theirs. - The queue holds 64 reads. A slow listener blocks the readers, as it did when each read was delivered directly, so no queue builds up. - ExecutionEvent and the `action_output` payload are unchanged. A chunk is larger, and a size-triggered batch can exceed 64 KiB by one read. - OutputBuffer::push splits text larger than a block into several blocks. Its bound assumed pushes no larger than a block, which batches are not. Skip the web serialization (item 4, part 2) - emit_to_all serializes for the WebSocket channel only while a client is subscribed. This applies to every event, not just action output. - It also passes the payload to Tauri by reference instead of cloning it. Gate and cap the registry buffer (item 4, part 3) - Only Run actions have a detection buffer. `register` creates it when the action starts, before any output can arrive. Creating it in `wire_run_detection`, which runs after `execute` returns, would lose the output written in between. `wire_run_detection` still asks for the buffer, which covers any other execution it is ever called for. - Output of build, test, check, format, prerun and clean-up actions is no longer normalized or stored there. - The buffer keeps the most recent 20,000 lines and 2 MiB of text. An unterminated line stops growing at 2 MiB. - Lines are numbered from the start of the output, so the regex matcher keeps its place once old lines are dropped. It now copies only the new lines on each poll instead of the whole buffer, and the autodetect poller copies only the last 200. - Limit: a line is missed by the regex matcher if more than the cap is written after it within one 2 s poll. Before, nothing was dropped and the buffer grew without bound. Entries recreated after unregister (root cause section 3) - `append_output_chunk` no longer creates a buffer, so late output from a process that outlived its action is dropped. - The run phase, the output buffer and the detector's cancel sender are now stored only for a registered execution, under the lock that `unregister` holds. Wiring detection for an action that has already ended stored all three for good before, and left its detector task polling. That is the same hole reached another way, so it is closed here too. A cancel sender that is not stored is dropped, which stops the task. Tests - Emitter unit tests: merging, stream order, the interval, the size limit, buffer-before-listener order, flush deadlines, shutdown. - Executor tests on real /bin/sh scripts: one event for many reads, size-triggered batches, delivery while the action runs, and a pending batch delivered before the status when the readers time out. - Registry, run detector and terminal output tests for the gating, the cap, line numbering and the unregister hole. - web_server tests that count serializations with and without a connected client. Not changed - The frontend. The modal still fetches the buffer before it registers its listener, which is item 5. Signed-off-by: Matt Toohey Co-Authored-By: Claude Fable 5.2 --- apps/staged/src-tauri/src/actions/commands.rs | 6 +- apps/staged/src-tauri/src/actions/events.rs | 9 +- apps/staged/src-tauri/src/actions/registry.rs | 329 ++++++++++++--- .../src-tauri/src/actions/run_detector.rs | 142 ++++++- apps/staged/src-tauri/src/terminal_output.rs | 184 +++++++- apps/staged/src-tauri/src/web_server.rs | 109 ++++- crates/builderbot-actions/src/executor.rs | 124 +++--- .../builderbot-actions/src/executor/tests.rs | 150 ++++++- crates/builderbot-actions/src/lib.rs | 1 + .../builderbot-actions/src/output_buffer.rs | 65 ++- .../builderbot-actions/src/output_emitter.rs | 396 ++++++++++++++++++ 11 files changed, 1326 insertions(+), 189 deletions(-) create mode 100644 crates/builderbot-actions/src/output_emitter.rs diff --git a/apps/staged/src-tauri/src/actions/commands.rs b/apps/staged/src-tauri/src/actions/commands.rs index dfbf7dc0a..075c1f385 100644 --- a/apps/staged/src-tauri/src/actions/commands.rs +++ b/apps/staged/src-tauri/src/actions/commands.rs @@ -752,8 +752,10 @@ fn wire_run_detection( working_dir: String, provider_id: Option, ) { - // Ensure the output buffer for this execution_id exists so the - // regex matcher can obtain a reference to it. + // A Run action has had its output buffer since it started, so that no + // output is missed before this point. Make sure of it for whatever else + // is wired up here. Nothing below is stored if the action has already + // ended: the registry only holds state for running executions. registry.register_output_buffer(&execution_id); match action.run_detection_mode.clone() { diff --git a/apps/staged/src-tauri/src/actions/events.rs b/apps/staged/src-tauri/src/actions/events.rs index 578c420e9..418f7facc 100644 --- a/apps/staged/src-tauri/src/actions/events.rs +++ b/apps/staged/src-tauri/src/actions/events.rs @@ -72,7 +72,8 @@ impl ExecutionListener for TauriExecutionListener { execution_id, started_at, } => { - // Register the running action + // Register the running action. For a Run action this also + // creates the buffer Run detection reads, ahead of any output. self.registry.register( execution_id.clone(), self.branch_id.clone(), @@ -106,8 +107,10 @@ impl ExecutionListener for TauriExecutionListener { .. } => { // Feed normalized terminal output into the shared buffer for - // regex matching and autodetect prompts. The frontend still - // receives the original chunk for live display. + // regex matching and autodetect prompts. Only executions Run + // detection reads have one; for the rest this does nothing. + // The frontend still receives the original chunk for live + // display. self.registry.append_output_chunk(&execution_id, &chunk); crate::web_server::emit_to_all( diff --git a/apps/staged/src-tauri/src/actions/registry.rs b/apps/staged/src-tauri/src/actions/registry.rs index 1100fbb8f..433cdf261 100644 --- a/apps/staged/src-tauri/src/actions/registry.rs +++ b/apps/staged/src-tauri/src/actions/registry.rs @@ -3,7 +3,15 @@ //! This registry maintains a mapping of execution IDs to their associated //! branch and action information, allowing the UI to restore state when //! components remount. +//! +//! Alongside each running action it keeps what Run detection needs: the run +//! phase, the detector's cancellation handle and, for Run actions only, a +//! normalized copy of the recent output. All of that exists only while the +//! execution is registered. Whatever arrives for an execution that has been +//! unregistered, or never was registered, is dropped rather than stored, +//! because nothing would ever remove it again. +use builderbot_actions::ActionType; use serde::{Deserialize, Serialize}; use std::collections::HashMap; use std::sync::{Arc, Mutex}; @@ -33,7 +41,19 @@ pub enum RunPhase { NoDetection, } +/// How many recent lines of a Run action's output are kept for detection. +pub(super) const DETECTION_MAX_LINES: usize = 20_000; + +/// How much text those lines may hold. The regex matcher reads the buffer +/// every two seconds and the autodetect poller reads its last 200 lines, so +/// this only has to cover what a service prints between two reads. +const DETECTION_MAX_BYTES: usize = 2 * 1024 * 1024; + /// Registry for tracking running actions +/// +/// `running` says which executions are live. It is locked before any of the +/// other maps wherever both are held, and they gain an entry only while it +/// is held and has the execution, so `unregister` leaves nothing behind. pub struct ActionRegistry { running: Mutex>, run_phases: Mutex>, @@ -59,7 +79,12 @@ impl ActionRegistry { } } - /// Register a new running action + /// Register a new running action. + /// + /// A Run action also gets the output buffer Run detection reads. It is + /// created here, before the action can have produced any output, so that + /// detection sees the output from its first line even though the detector + /// itself is wired up only once the action has started. pub fn register( &self, execution_id: String, @@ -69,6 +94,7 @@ impl ActionRegistry { action_type: String, started_at: i64, ) { + let detects_run = action_type == ActionType::Run.as_str(); let info = RunningActionInfo { execution_id: execution_id.clone(), branch_id, @@ -79,27 +105,33 @@ impl ActionRegistry { }; let mut running = self.running.lock().unwrap(); + if detects_run { + let mut buffers = self.output_buffers.lock().unwrap(); + buffers + .entry(execution_id.clone()) + .or_insert_with(new_detection_buffer); + } running.insert(execution_id, info); } /// Unregister a completed action and clean up associated state. pub fn unregister(&self, execution_id: &str) { - { - let mut running = self.running.lock().unwrap(); - running.remove(execution_id); - } - { - let mut phases = self.run_phases.lock().unwrap(); - phases.remove(execution_id); - } - { - let mut buffers = self.output_buffers.lock().unwrap(); - buffers.remove(execution_id); - } - { - // Dropping the sender signals the background task to stop. - let mut senders = self.cancel_senders.lock().unwrap(); - senders.remove(execution_id); + // Held throughout, so that nothing can add state for this execution + // between its removal from `running` and the removals below. + let mut running = self.running.lock().unwrap(); + running.remove(execution_id); + self.run_phases.lock().unwrap().remove(execution_id); + self.output_buffers.lock().unwrap().remove(execution_id); + // Dropping the sender signals the background task to stop. + self.cancel_senders.lock().unwrap().remove(execution_id); + } + + /// Run `store` if the execution is registered, with `running` held so + /// that it cannot be unregistered meanwhile. + fn while_registered(&self, execution_id: &str, store: impl FnOnce()) { + let running = self.running.lock().unwrap(); + if running.contains_key(execution_id) { + store(); } } @@ -121,10 +153,13 @@ impl ActionRegistry { // ----- RunPhase tracking ----- - /// Set the run phase for an execution. + /// Set the run phase for an execution. Ignored once the execution has + /// ended. pub fn set_run_phase(&self, execution_id: &str, phase: RunPhase) { - let mut phases = self.run_phases.lock().unwrap(); - phases.insert(execution_id.to_string(), phase); + self.while_registered(execution_id, || { + let mut phases = self.run_phases.lock().unwrap(); + phases.insert(execution_id.to_string(), phase); + }); } /// Get the current run phase for an execution. @@ -135,75 +170,269 @@ impl ActionRegistry { // ----- Output buffer management ----- - /// Create (or retrieve) a shared output buffer for an execution and return - /// a reference to it. - pub(crate) fn register_output_buffer( - &self, - execution_id: &str, - ) -> Arc> { - let mut buffers = self.output_buffers.lock().unwrap(); - buffers - .entry(execution_id.to_string()) - .or_insert_with(|| Arc::new(Mutex::new(TerminalOutputProcessor::default()))) - .clone() + /// Make sure a running execution has an output buffer for Run detection + /// to read. Run actions have had one since they were registered; this + /// covers any other execution a detector is attached to. Does nothing + /// once the execution has ended. + pub(crate) fn register_output_buffer(&self, execution_id: &str) { + self.while_registered(execution_id, || { + let mut buffers = self.output_buffers.lock().unwrap(); + buffers + .entry(execution_id.to_string()) + .or_insert_with(new_detection_buffer); + }); } - /// Append a raw output chunk to the normalized buffer for the given execution. - /// Creates the buffer lazily if it does not yet exist. + /// Append a raw output chunk to the normalized buffer for the given + /// execution, if it has one. + /// + /// Only executions Run detection reads have a buffer. Output of any + /// other action is not kept here, and neither is output that arrives + /// after the execution was unregistered: a process that outlives its + /// action can keep writing indefinitely. pub(crate) fn append_output_chunk(&self, execution_id: &str, chunk: &str) { - let buf = self.register_output_buffer(execution_id); - let mut buf = buf.lock().unwrap(); - buf.process_chunk(chunk); + if let Some(buf) = self.output_buffer(execution_id) { + buf.lock().unwrap().process_chunk(chunk); + } } - /// Get a snapshot of all output lines for an execution. - pub(crate) fn get_output_lines(&self, execution_id: &str) -> Option> { - let buf = { - let buffers = self.output_buffers.lock().unwrap(); - buffers.get(execution_id).cloned() - }; - buf.map(|b| { - let b = b.lock().unwrap(); - b.snapshot_lines() + /// The output lines numbered `from` and up, with the number of lines + /// there have been so far. Lines are numbered from the start of the + /// output, and those no longer retained are left out. `None` if the + /// execution has no output buffer. + pub(crate) fn get_output_lines_from( + &self, + execution_id: &str, + from: usize, + ) -> Option<(usize, Vec)> { + self.output_buffer(execution_id).map(|buf| { + let buf = buf.lock().unwrap(); + (buf.line_count(), buf.lines_from(from)) }) } + /// The last `count` output lines for an execution. `None` if it has no + /// output buffer. + pub(crate) fn get_last_output_lines( + &self, + execution_id: &str, + count: usize, + ) -> Option> { + self.output_buffer(execution_id) + .map(|buf| buf.lock().unwrap().last_lines(count)) + } + + fn output_buffer(&self, execution_id: &str) -> Option>> { + let buffers = self.output_buffers.lock().unwrap(); + buffers.get(execution_id).cloned() + } + // ----- Cancellation sender management ----- /// Store a cancellation sender for a regex matcher / detector task. + /// + /// If the execution has already ended the sender is dropped instead, + /// which stops the task just as `unregister` would have. pub fn store_cancel_sender(&self, execution_id: &str, sender: watch::Sender) { - let mut senders = self.cancel_senders.lock().unwrap(); - senders.insert(execution_id.to_string(), sender); + self.while_registered(execution_id, || { + let mut senders = self.cancel_senders.lock().unwrap(); + senders.insert(execution_id.to_string(), sender); + }); } } +fn new_detection_buffer() -> Arc> { + Arc::new(Mutex::new(TerminalOutputProcessor::keeping_recent( + DETECTION_MAX_LINES, + DETECTION_MAX_BYTES, + ))) +} + #[cfg(test)] mod tests { use super::*; + fn register(registry: &ActionRegistry, execution_id: &str, action_type: ActionType) { + registry.register( + execution_id.to_string(), + "branch".to_string(), + format!("action-{execution_id}"), + format!("Action {execution_id}"), + action_type.as_str().to_string(), + 0, + ); + } + + fn output_lines(registry: &ActionRegistry, execution_id: &str) -> Option> { + registry + .get_output_lines_from(execution_id, 0) + .map(|(_, lines)| lines) + } + + /// How many entries the registry holds beyond the running actions. + fn side_entries(registry: &ActionRegistry) -> usize { + registry.run_phases.lock().unwrap().len() + + registry.output_buffers.lock().unwrap().len() + + registry.cancel_senders.lock().unwrap().len() + } + #[test] fn output_buffer_renders_progress_across_chunks() { let registry = ActionRegistry::new(); + register(®istry, "run", ActionType::Run); registry.append_output_chunk("run", "10%\r"); - assert_eq!(registry.get_output_lines("run").unwrap(), vec!["10%"]); + assert_eq!(output_lines(®istry, "run").unwrap(), vec!["10%"]); registry.append_output_chunk("run", "20%\r"); registry.append_output_chunk("run", "done\n"); - assert_eq!(registry.get_output_lines("run").unwrap(), vec!["done"]); + assert_eq!(output_lines(®istry, "run").unwrap(), vec!["done"]); } #[test] fn output_buffer_handles_crlf_split_across_chunks() { let registry = ActionRegistry::new(); + register(®istry, "run", ActionType::Run); registry.append_output_chunk("run", "hello\r"); registry.append_output_chunk("run", "\nworld\n"); assert_eq!( - registry.get_output_lines("run").unwrap(), + output_lines(®istry, "run").unwrap(), vec!["hello", "world"] ); } + + #[test] + fn a_run_action_is_buffered_from_its_first_output() { + let registry = ActionRegistry::new(); + register(®istry, "run", ActionType::Run); + + // Output that arrives before the detector is wired up is kept, and + // wiring it up keeps what is already there. + registry.append_output_chunk("run", "Listening on :3000\n"); + registry.register_output_buffer("run"); + registry.append_output_chunk("run", "ready\n"); + + assert_eq!( + output_lines(®istry, "run").unwrap(), + vec!["Listening on :3000", "ready"] + ); + assert_eq!( + registry.get_last_output_lines("run", 1).unwrap(), + vec!["ready"] + ); + } + + #[test] + fn only_executions_run_detection_reads_are_buffered() { + let registry = ActionRegistry::new(); + for action_type in [ + ActionType::Build, + ActionType::Test, + ActionType::Format, + ActionType::Check, + ActionType::Prerun, + ActionType::CleanUp, + ] { + let execution_id = action_type.as_str(); + register(®istry, execution_id, action_type); + registry.append_output_chunk(execution_id, "output nothing reads\n"); + assert_eq!(output_lines(®istry, execution_id), None); + assert_eq!(registry.get_last_output_lines(execution_id, 200), None); + } + assert_eq!(side_entries(®istry), 0); + + // A detector attached to one of them gets a buffer from then on. + registry.register_output_buffer("build"); + registry.append_output_chunk("build", "now read\n"); + assert_eq!(output_lines(®istry, "build").unwrap(), vec!["now read"]); + assert_eq!(side_entries(®istry), 1); + } + + #[test] + fn output_after_unregister_does_not_bring_the_entry_back() { + let registry = ActionRegistry::new(); + register(®istry, "run", ActionType::Run); + registry.append_output_chunk("run", "before\n"); + assert_eq!(side_entries(®istry), 1); + + registry.unregister("run"); + assert_eq!(side_entries(®istry), 0); + + // A process that outlived the action is still writing. + registry.append_output_chunk("run", "after\n"); + assert_eq!(output_lines(®istry, "run"), None); + assert_eq!(side_entries(®istry), 0); + } + + #[test] + fn nothing_is_stored_for_an_execution_that_is_not_running() { + let registry = ActionRegistry::new(); + register(®istry, "ended", ActionType::Run); + registry.unregister("ended"); + + for execution_id in ["ended", "never-started"] { + // Everything Run detection stores when it is wired up, late. + registry.register_output_buffer(execution_id); + registry.append_output_chunk(execution_id, "output\n"); + registry.set_run_phase(execution_id, RunPhase::Building); + let (cancel_tx, cancel_rx) = watch::channel(false); + registry.store_cancel_sender(execution_id, cancel_tx); + + assert_eq!(output_lines(®istry, execution_id), None); + assert!(registry.get_run_phase(execution_id).is_none()); + // The sender was dropped, which is what stops a detector task. + assert!(cancel_rx.has_changed().is_err()); + } + assert_eq!(side_entries(®istry), 0); + } + + #[test] + fn a_running_execution_keeps_its_detection_state_until_it_ends() { + let registry = ActionRegistry::new(); + register(®istry, "run", ActionType::Run); + registry.set_run_phase("run", RunPhase::Building); + let (cancel_tx, cancel_rx) = watch::channel(false); + registry.store_cancel_sender("run", cancel_tx); + + assert!(matches!( + registry.get_run_phase("run"), + Some(RunPhase::Building) + )); + assert!(cancel_rx.has_changed().is_ok()); + assert_eq!(side_entries(®istry), 3); + + registry.unregister("run"); + assert!(registry.get_run_phase("run").is_none()); + assert!(cancel_rx.has_changed().is_err()); + assert_eq!(side_entries(®istry), 0); + } + + #[test] + fn the_detection_buffer_keeps_only_recent_lines() { + let registry = ActionRegistry::new(); + register(®istry, "run", ActionType::Run); + + let written = DETECTION_MAX_LINES + 500; + let chunk: String = (0..written).map(|line| format!("line {line}\n")).collect(); + registry.append_output_chunk("run", &chunk); + + let (count, lines) = registry.get_output_lines_from("run", 0).unwrap(); + assert_eq!(count, written); + assert_eq!(lines.len(), DETECTION_MAX_LINES); + assert_eq!(lines[0], "line 500"); + // Line numbers still address the lines that remain. + let (_, last) = registry.get_output_lines_from("run", written - 1).unwrap(); + assert_eq!(last, vec![format!("line {}", written - 1)]); + + // Long lines are bounded by their size instead. + let long = format!("{}\n", "x".repeat(DETECTION_MAX_BYTES / 4)); + for _ in 0..8 { + registry.append_output_chunk("run", &long); + } + let (_, lines) = registry.get_output_lines_from("run", 0).unwrap(); + assert_eq!(lines.len(), 4); + } } diff --git a/apps/staged/src-tauri/src/actions/run_detector.rs b/apps/staged/src-tauri/src/actions/run_detector.rs index f5ebd8121..74553347a 100644 --- a/apps/staged/src-tauri/src/actions/run_detector.rs +++ b/apps/staged/src-tauri/src/actions/run_detector.rs @@ -1,7 +1,8 @@ //! Run detection: regex matching and AI-powered autodetection. //! //! * `spawn_regex_matcher` — polls the output buffer every 2 seconds and applies -//! a compiled regex to detect when the service is running. +//! a compiled regex to detect when the service is running. The buffer keeps +//! only recent lines, so the matcher follows it by line number. //! * `spawn_autodetect_poller` — uses an AI model on a backoff schedule to //! derive a regex pattern from terminal output, then hands off to the regex //! matcher once a valid pattern is found. @@ -90,20 +91,10 @@ pub fn spawn_regex_matcher( } } - // Read new lines since last check. Re-check the previous line too: - // it may have been an in-progress line that gained more text since - // the last poll. - let new_lines: Vec = { - let Some(lines) = registry.get_output_lines(&execution_id) else { - continue; - }; - let start_index = last_checked_index.saturating_sub(1); - if lines.len() <= start_index { - continue; - } - let new_lines = lines[start_index..].to_vec(); - last_checked_index = lines.len(); - new_lines + let Some(new_lines) = + unchecked_lines(®istry, &execution_id, &mut last_checked_index) + else { + continue; }; // Apply regex to each normalized plain-text line. @@ -135,6 +126,29 @@ pub fn spawn_regex_matcher( }); } +/// The output lines to match since the last check, or `None` if there are +/// none. `last_checked_index` is the number of lines seen by the last check +/// and is advanced past the lines returned. +/// +/// The line before the new ones is returned again: it may have been an +/// in-progress line that gained more text since the last poll. Lines are +/// addressed by their number in the whole output, so this keeps working once +/// the buffer has dropped its oldest lines; lines dropped before they were +/// ever checked are skipped. +fn unchecked_lines( + registry: &ActionRegistry, + execution_id: &str, + last_checked_index: &mut usize, +) -> Option> { + let start_index = last_checked_index.saturating_sub(1); + let (line_count, new_lines) = registry.get_output_lines_from(execution_id, start_index)?; + if line_count <= start_index { + return None; + } + *last_checked_index = line_count; + Some(new_lines) +} + // ============================================================================= // AI autodetect poller (Phase 3) // ============================================================================= @@ -211,15 +225,10 @@ pub fn spawn_autodetect_poller( } // ---- Read the last ~200 lines of output ---- - let lines = match registry.get_output_lines(&execution_id) { + let tail = match registry.get_last_output_lines(&execution_id, 200) { Some(l) => l, None => continue, // buffer not yet created }; - let tail: Vec<&String> = if lines.len() > 200 { - lines[lines.len() - 200..].iter().collect() - } else { - lines.iter().collect() - }; if tail.is_empty() { continue; } @@ -445,3 +454,94 @@ If still building, set regex and has_endpoint_capture to null/false."#, ); }); } + +#[cfg(test)] +mod tests { + use super::super::registry::DETECTION_MAX_LINES; + use super::*; + use builderbot_actions::ActionType; + + fn registry_with(execution_id: &str, action_type: ActionType) -> ActionRegistry { + let registry = ActionRegistry::new(); + registry.register( + execution_id.to_string(), + "branch".to_string(), + "action".to_string(), + "Action".to_string(), + action_type.as_str().to_string(), + 0, + ); + registry + } + + #[test] + fn the_matcher_reads_new_lines_and_rereads_the_one_before_them() { + let registry = registry_with("run", ActionType::Run); + let mut checked = 0; + + // Nothing written yet. + assert_eq!(unchecked_lines(®istry, "run", &mut checked), None); + + registry.append_output_chunk("run", "building\nListe"); + assert_eq!( + unchecked_lines(®istry, "run", &mut checked).unwrap(), + vec!["building", "Liste"] + ); + + // The in-progress line is read again once it is whole. + registry.append_output_chunk("run", "ning on :3000\nnext\n"); + assert_eq!( + unchecked_lines(®istry, "run", &mut checked).unwrap(), + vec!["Listening on :3000", "next"] + ); + assert_eq!( + unchecked_lines(®istry, "run", &mut checked).unwrap(), + vec!["next"] + ); + assert_eq!(checked, 3); + } + + #[test] + fn the_matcher_keeps_reading_once_the_buffer_has_dropped_lines() { + let registry = registry_with("run", ActionType::Run); + let mut checked = 0; + + registry.append_output_chunk("run", "first\n"); + assert_eq!( + unchecked_lines(®istry, "run", &mut checked).unwrap(), + vec!["first"] + ); + + // More than the buffer holds arrives between two polls: the matcher + // gets what is retained, oldest first, up to the newest line. + let flood = DETECTION_MAX_LINES + 10; + let chunk: String = (0..flood).map(|line| format!("noise {line}\n")).collect(); + registry.append_output_chunk("run", &chunk); + let lines = unchecked_lines(®istry, "run", &mut checked).unwrap(); + assert_eq!(lines.len(), DETECTION_MAX_LINES); + assert_eq!(lines[0], "noise 10"); + assert_eq!(lines.last().unwrap(), &format!("noise {}", flood - 1)); + assert_eq!(checked, flood + 1); + + // And it still sees what is written after that. + registry.append_output_chunk("run", "Listening on :3000\n"); + assert_eq!( + unchecked_lines(®istry, "run", &mut checked).unwrap(), + vec![ + format!("noise {}", flood - 1), + "Listening on :3000".to_string() + ] + ); + } + + #[test] + fn an_execution_without_a_detection_buffer_has_no_lines_to_match() { + let registry = registry_with("build", ActionType::Build); + registry.append_output_chunk("build", "Listening on :3000\n"); + + let mut checked = 0; + assert_eq!(unchecked_lines(®istry, "build", &mut checked), None); + assert_eq!(unchecked_lines(®istry, "ended", &mut checked), None); + assert_eq!(checked, 0); + } +} diff --git a/apps/staged/src-tauri/src/terminal_output.rs b/apps/staged/src-tauri/src/terminal_output.rs index 78183b4f7..cf8f5c63e 100644 --- a/apps/staged/src-tauri/src/terminal_output.rs +++ b/apps/staged/src-tauri/src/terminal_output.rs @@ -5,6 +5,8 @@ //! action output viewer does, and strips ANSI/control sequences before text is //! used for AI prompts or regex matching. +use std::collections::VecDeque; + #[derive(Debug, Clone, Copy, Default, PartialEq, Eq)] enum EscapeState { #[default] @@ -15,16 +17,50 @@ enum EscapeState { OscEsc, } +/// How much a processor fed by a long-running command retains. +#[derive(Debug, Clone, Copy)] +struct RecentLines { + max_lines: usize, + /// Bound on the text of the finalized lines, and separately on the text + /// of the in-progress line. + max_bytes: usize, +} + /// Incrementally renders terminal text into plain lines. +/// +/// Lines are numbered from zero in the order they were written. A processor +/// built with [`TerminalOutputProcessor::keeping_recent`] drops its oldest +/// lines once it is over its bound, and the numbers of the lines that remain +/// do not change. #[derive(Debug, Default)] pub(crate) struct TerminalOutputProcessor { - finalized_lines: Vec, + /// Oldest first. The first one is line number `dropped_lines`. + finalized_lines: VecDeque, + /// Bytes of text in `finalized_lines`. + finalized_bytes: usize, + /// How many finalized lines have been dropped from the front. + dropped_lines: usize, current_text: String, pending_cr: bool, escape_state: EscapeState, + /// `None` retains every line. + recent: Option, } impl TerminalOutputProcessor { + /// A processor that retains only its most recent lines: at most + /// `max_lines` finalized lines holding at most `max_bytes` of text. The + /// in-progress line stops growing at `max_bytes` too, until it ends. + pub(crate) fn keeping_recent(max_lines: usize, max_bytes: usize) -> Self { + Self { + recent: Some(RecentLines { + max_lines, + max_bytes, + }), + ..Self::default() + } + } + pub(crate) fn process_chunk(&mut self, raw: &str) { for ch in raw.chars() { if let Some(clean) = self.consume_escape_or_control(ch) { @@ -33,15 +69,30 @@ impl TerminalOutputProcessor { } } - /// Return finalized lines plus the visible in-progress line. Even when a - /// trailing `\r` is unresolved, live snapshots expose the current text so - /// readiness detection matches the frontend incremental output view. - pub(crate) fn snapshot_lines(&self) -> Vec { - let mut lines = self.finalized_lines.clone(); - if !self.current_text.is_empty() { - lines.push(self.current_text.clone()); - } - lines + /// How many lines there have been so far: every finalized line, retained + /// or not, plus the in-progress line if it is visible. + pub(crate) fn line_count(&self) -> usize { + self.dropped_lines + self.finalized_lines.len() + usize::from(!self.current_text.is_empty()) + } + + /// The lines numbered `from` and up: finalized lines, then the visible + /// in-progress line. Even when a trailing `\r` is unresolved, live + /// snapshots expose the current text so readiness detection matches the + /// frontend incremental output view. Lines that are no longer retained + /// are left out. + pub(crate) fn lines_from(&self, from: usize) -> Vec { + let skip = from.saturating_sub(self.dropped_lines); + self.finalized_lines + .iter() + .chain((!self.current_text.is_empty()).then_some(&self.current_text)) + .skip(skip) + .cloned() + .collect() + } + + /// The last `count` lines, as [`Self::lines_from`] lists them. + pub(crate) fn last_lines(&self, count: usize) -> Vec { + self.lines_from(self.line_count().saturating_sub(count)) } fn finish(mut self) -> Vec { @@ -50,7 +101,7 @@ impl TerminalOutputProcessor { self.pending_cr = false; } - let mut lines = self.finalized_lines; + let mut lines = Vec::from(self.finalized_lines); if !self.current_text.is_empty() { lines.push(self.current_text); } @@ -116,22 +167,46 @@ impl TerminalOutputProcessor { if self.pending_cr { self.pending_cr = false; if ch == '\n' { - self.finalized_lines - .push(std::mem::take(&mut self.current_text)); + self.finalize_current_line(); return; } self.current_text.clear(); } match ch { - '\n' => { - self.finalized_lines - .push(std::mem::take(&mut self.current_text)); - } + '\n' => self.finalize_current_line(), '\r' => { self.pending_cr = true; } - c => self.current_text.push(c), + c => { + // A line with no end in sight must not grow without bound + // either: past the bound, the rest of it is dropped. + let full = self + .recent + .is_some_and(|recent| self.current_text.len() >= recent.max_bytes); + if !full { + self.current_text.push(c); + } + } + } + } + + fn finalize_current_line(&mut self) { + let line = std::mem::take(&mut self.current_text); + self.finalized_bytes += line.len(); + self.finalized_lines.push_back(line); + + let Some(recent) = self.recent else { + return; + }; + while self.finalized_lines.len() > recent.max_lines + || self.finalized_bytes > recent.max_bytes + { + let Some(dropped) = self.finalized_lines.pop_front() else { + break; + }; + self.finalized_bytes -= dropped.len(); + self.dropped_lines += 1; } } } @@ -269,10 +344,79 @@ mod tests { fn snapshot_includes_unresolved_carriage_return_line() { let mut processor = TerminalOutputProcessor::default(); processor.process_chunk("10%\r"); - assert_eq!(processor.snapshot_lines(), vec!["10%".to_string()]); + assert_eq!(processor.lines_from(0), vec!["10%".to_string()]); processor.process_chunk("done"); - assert_eq!(processor.snapshot_lines(), vec!["done".to_string()]); + assert_eq!(processor.lines_from(0), vec!["done".to_string()]); + } + + #[test] + fn lines_are_numbered_from_the_start_of_the_output() { + let mut processor = TerminalOutputProcessor::default(); + processor.process_chunk("zero\none\ntwo\nthr"); + + assert_eq!(processor.line_count(), 4); + assert_eq!(processor.lines_from(2), vec!["two", "thr"]); + assert_eq!(processor.lines_from(4), Vec::::new()); + assert_eq!(processor.lines_from(9), Vec::::new()); + assert_eq!(processor.last_lines(2), vec!["two", "thr"]); + assert_eq!(processor.last_lines(9), processor.lines_from(0)); + + // An in-progress line that is cleared stops counting. + processor.process_chunk("\rx\r"); + processor.process_chunk("\r"); + assert_eq!(processor.line_count(), 3); + assert_eq!(processor.lines_from(2), vec!["two"]); + } + + #[test] + fn a_processor_keeping_recent_lines_drops_the_oldest() { + let mut processor = TerminalOutputProcessor::keeping_recent(3, usize::MAX); + for line in 0..10 { + processor.process_chunk(&format!("line {line}\n")); + } + processor.process_chunk("partial"); + + assert_eq!( + processor.lines_from(0), + vec!["line 7", "line 8", "line 9", "partial"] + ); + // The lines that remain keep their numbers. + assert_eq!(processor.line_count(), 11); + assert_eq!(processor.lines_from(9), vec!["line 9", "partial"]); + // Asking for a dropped line starts at the oldest one retained. + assert_eq!(processor.lines_from(2), processor.lines_from(0)); + assert_eq!(processor.last_lines(2), vec!["line 9", "partial"]); + } + + #[test] + fn a_processor_keeping_recent_lines_is_bounded_in_bytes() { + let max_bytes = 100; + let mut processor = TerminalOutputProcessor::keeping_recent(usize::MAX, max_bytes); + for line in 0..1_000 { + processor.process_chunk(&format!("line {line:04}\n")); + assert!(processor.finalized_bytes <= max_bytes); + } + assert_eq!(processor.lines_from(0).len(), max_bytes / "line 0000".len()); + assert_eq!(processor.lines_from(0).last().unwrap(), "line 0999"); + assert_eq!(processor.line_count(), 1_000); + + // A line that never ends stops growing, and the next line is whole. + processor.process_chunk(&"x".repeat(10 * max_bytes)); + assert_eq!(processor.current_text.len(), max_bytes); + processor.process_chunk("\nnext\n"); + assert_eq!(processor.lines_from(0), vec!["next"]); + assert_eq!(processor.line_count(), 1_002); + } + + #[test] + fn a_default_processor_keeps_every_line() { + let mut processor = TerminalOutputProcessor::default(); + for line in 0..30_000 { + processor.process_chunk(&format!("{line}\n")); + } + assert_eq!(processor.lines_from(0).len(), 30_000); + assert_eq!(processor.dropped_lines, 0); } #[test] diff --git a/apps/staged/src-tauri/src/web_server.rs b/apps/staged/src-tauri/src/web_server.rs index adc4a023e..75ebe88c1 100644 --- a/apps/staged/src-tauri/src/web_server.rs +++ b/apps/staged/src-tauri/src/web_server.rs @@ -129,15 +129,34 @@ pub fn emit_to_all( payload: S, ) { use tauri::{Emitter, Manager}; - let _ = app_handle.emit(event_name, payload.clone()); + let _ = app_handle.emit(event_name, &payload); if let Some(tx) = app_handle.try_state::>() { - if let Ok(json) = serialize_web_event(event_name, payload) { - let _ = tx.send(WebEvent { - event_name: event_name.to_string(), - payload: json, - }); - } + broadcast_web_event(&tx, event_name, &payload); + } +} + +/// Send an event to the browser clients connected over WebSocket. Returns +/// whether there was anyone to send it to. +/// +/// With no client connected the payload is not serialized at all. Most +/// installs never have one, and events such as action output are frequent. +/// A client that connects a moment later misses the event either way: the +/// channel only delivers what is sent after a client subscribes. +fn broadcast_web_event( + tx: &broadcast::Sender, + event_name: &str, + payload: &S, +) -> bool { + if tx.receiver_count() == 0 { + return false; + } + if let Ok(json) = serialize_web_event(event_name, payload) { + let _ = tx.send(WebEvent { + event_name: event_name.to_string(), + payload: json, + }); } + true } // ============================================================================= @@ -4476,8 +4495,8 @@ mod blocking_guard_tests; #[cfg(test)] mod tests { use super::{ - control_create_image_args, event_gap_payload, normalize_ws_client_id, web_caller_rejection, - web_client_id, DispatchCaller, + broadcast_web_event, control_create_image_args, emit_to_all, event_gap_payload, + normalize_ws_client_id, web_caller_rejection, web_client_id, DispatchCaller, WebEvent, }; use serde_json::{json, Value}; use std::collections::{BTreeMap, BTreeSet}; @@ -4759,6 +4778,78 @@ mod tests { assert!(web_client_id(&json!({ "clientId": 7 })).is_err()); } + /// A payload that counts how many times it is serialized. + #[derive(Clone)] + struct CountedPayload<'a>(&'a std::sync::atomic::AtomicUsize); + + impl serde::Serialize for CountedPayload<'_> { + fn serialize(&self, serializer: S) -> Result { + self.0.fetch_add(1, std::sync::atomic::Ordering::SeqCst); + serializer.serialize_str("payload") + } + } + + #[test] + fn web_events_are_serialized_only_while_a_client_is_connected() { + use std::sync::atomic::{AtomicUsize, Ordering}; + let serialized = AtomicUsize::new(0); + let payload = CountedPayload(&serialized); + let (tx, _) = tokio::sync::broadcast::channel::(4); + + // Nobody connected: nothing is serialized and nothing is queued. + assert!(!broadcast_web_event(&tx, "action_output", &payload)); + assert_eq!(serialized.load(Ordering::SeqCst), 0); + assert!(tx.is_empty()); + + // A connected client gets the events sent from then on. + let mut client = tx.subscribe(); + assert!(broadcast_web_event(&tx, "action_output", &payload)); + assert_eq!(serialized.load(Ordering::SeqCst), 1); + let event = client.try_recv().unwrap(); + assert_eq!(event.event_name, "action_output"); + assert_eq!( + serde_json::from_str::(&event.payload).unwrap(), + json!({ "event": "action_output", "payload": "payload" }) + ); + assert!(client.try_recv().is_err()); + + // Once it disconnects, events are skipped again. + drop(client); + assert!(!broadcast_web_event(&tx, "action_output", &payload)); + assert_eq!(serialized.load(Ordering::SeqCst), 1); + } + + #[test] + fn emit_to_all_reaches_the_window_and_only_connected_web_clients() { + use std::sync::atomic::{AtomicUsize, Ordering}; + use tauri::{Listener, Manager}; + + let app = tauri::test::mock_builder() + .build(tauri::test::mock_context(tauri::test::noop_assets())) + .expect("failed to build mock app"); + let (tx, _) = tokio::sync::broadcast::channel::(4); + app.manage(tx.clone()); + let (heard_tx, heard) = std::sync::mpsc::channel(); + app.listen("action_output", move |event| { + let _ = heard_tx.send(event.payload().to_string()); + }); + let serialized = AtomicUsize::new(0); + let payload = CountedPayload(&serialized); + + // No web client: the Tauri side still gets the event. + emit_to_all(app.handle(), "action_output", payload.clone()); + assert_eq!(heard.try_recv().unwrap(), "\"payload\""); + let for_tauri_alone = serialized.swap(0, Ordering::SeqCst); + + // A web client costs exactly one more serialization, and gets it. + let mut client = tx.subscribe(); + emit_to_all(app.handle(), "action_output", payload.clone()); + assert_eq!(heard.try_recv().unwrap(), "\"payload\""); + assert_eq!(serialized.load(Ordering::SeqCst), for_tauri_alone + 1); + assert_eq!(client.try_recv().unwrap().event_name, "action_output"); + assert!(client.try_recv().is_err()); + } + #[test] fn event_gap_payload_requests_full_client_recovery() { assert_eq!( diff --git a/crates/builderbot-actions/src/executor.rs b/crates/builderbot-actions/src/executor.rs index 2917d11b9..173c82119 100644 --- a/crates/builderbot-actions/src/executor.rs +++ b/crates/builderbot-actions/src/executor.rs @@ -3,7 +3,8 @@ //! Manages spawning shell commands with real-time output streaming, //! tracking running processes, and handling termination. //! -//! Output is also buffered so a viewer can catch up on it. That buffer is +//! Output is delivered to the listener in batches rather than read by read, +//! and is also buffered so a viewer can catch up on it. That buffer is //! bounded: each execution keeps only its most recent output, and only the //! last few finished executions keep theirs. @@ -23,6 +24,7 @@ use tokio::sync::oneshot; use crate::finished_outputs::{FinishedOutputs, MAX_FINISHED_EXECUTIONS}; use crate::models::{ActionStatus, ExecutionEvent, OutputChunk}; use crate::output_buffer::{OutputBuffer, SharedOutputBuffer, MAX_OUTPUT_BYTES}; +use crate::output_emitter::{self, OutputSender, EMIT_INTERVAL, EMIT_MAX_BYTES}; use crate::utf8_stream::Utf8StreamDecoder; #[cfg(all(test, unix))] @@ -32,6 +34,9 @@ mod tests; /// threads to reach the end of its output. Only what the kernel still holds /// is left to read by then, so this elapses only when something that outlived /// the process keeps the output open. +/// +/// Completion then waits as long again, at most, for the listener to be given +/// what was read. That elapses only when the listener is far behind. const READER_DRAIN_TIMEOUT: Duration = Duration::from_secs(2); // ============================================================================= @@ -136,6 +141,11 @@ struct Limits { /// How many finished executions keep their output. max_finished: usize, reader_drain_timeout: Duration, + /// How long output waits to be merged with what follows it before the + /// listener is given it. + emit_interval: Duration, + /// Size at which a batch of output is delivered without waiting. + emit_max_bytes: usize, } impl Default for Limits { @@ -144,6 +154,8 @@ impl Default for Limits { max_output_bytes: MAX_OUTPUT_BYTES, max_finished: MAX_FINISHED_EXECUTIONS, reader_drain_timeout: READER_DRAIN_TIMEOUT, + emit_interval: EMIT_INTERVAL, + emit_max_bytes: EMIT_MAX_BYTES, } } } @@ -174,41 +186,21 @@ impl Default for ActionExecutor { } } -/// Spawn a thread that reads from `stream` and emits output events via `listener`. +/// Spawn a thread that reads from `stream` and queues what it reads on +/// `output`, which buffers it and delivers it to the listener in batches. /// -/// Each chunk is also appended to `buffer` for later retrieval. `done` is -/// dropped when the thread reaches the end of the stream, which is how the -/// completion thread learns that all of the output has been delivered. +/// `done` is dropped when the thread reaches the end of the stream, after its +/// last read has been queued, which is how the completion thread learns that +/// all of the output is on its way. fn spawn_stream_reader( mut stream: impl Read + Send + 'static, stream_name: &'static str, - exec_id: String, - listener: Arc, - buffer: SharedOutputBuffer, - handle: Handle, + output: OutputSender, done: mpsc::Sender, ) { thread::spawn(move || { let _done = done; - let deliver = |chunk: String| { - if chunk.is_empty() { - return; - } - let timestamp = now_timestamp(); - - // Store in buffer - buffer.lock().unwrap().push(stream_name, &chunk, timestamp); - - // Emit event - handle.block_on(listener.on_event(ExecutionEvent::Output { - execution_id: exec_id.clone(), - chunk, - stream: stream_name.to_string(), - timestamp, - })); - }; - // A read can end part-way through a multi-byte character, so the // decoder carries the unfinished bytes over to the next read. let mut decoder = Utf8StreamDecoder::default(); @@ -216,25 +208,25 @@ fn spawn_stream_reader( loop { match stream.read(&mut buf) { Ok(0) => break, // EOF - Ok(n) => deliver(decoder.decode(&buf[..n])), + Ok(n) => output.send(stream_name, decoder.decode(&buf[..n]), now_timestamp()), // PTY master returns EIO (not EOF) when the slave side is // closed, which is the normal shutdown path. Treat all read // errors as end-of-stream. Err(_) => break, } } - deliver(decoder.finish()); + output.send(stream_name, decoder.finish(), now_timestamp()); }); } -/// Wait up to `timeout` for every reader thread to reach the end of its +/// Wait until `deadline` for every reader thread to reach the end of its /// stream. Returns whether they all did. /// /// Nothing is ever sent on the channel. Each reader holds a sender and drops /// it when it ends, so the channel disconnects once the last one is done. -fn wait_for_readers(readers_done: &mpsc::Receiver, timeout: Duration) -> bool { +fn wait_for_readers(readers_done: &mpsc::Receiver, deadline: Instant) -> bool { matches!( - readers_done.recv_timeout(timeout), + readers_done.recv_timeout(deadline.saturating_duration_since(Instant::now())), Err(mpsc::RecvTimeoutError::Disconnected) ) } @@ -302,6 +294,17 @@ impl ActionExecutor { // command handler), so `Handle::current()` is guaranteed to succeed. let handle = Handle::current(); + // Everything read from the process goes through one emitter, which + // appends it to the buffer and hands it to the listener in batches. + let output = output_emitter::spawn( + execution_id.clone(), + listener.clone(), + output_buffer.clone(), + handle.clone(), + self.limits.emit_interval, + self.limits.emit_max_bytes, + ); + // Spawn threads to read output. // // When a PTY reader is provided (local execution), we use it as the @@ -310,38 +313,14 @@ impl ActionExecutor { // the child's piped stdout and stderr separately. let (reader_done, readers_done) = mpsc::channel::(); if let Some(pty_master) = pty_reader { - spawn_stream_reader( - pty_master, - "stdout", - execution_id.clone(), - listener.clone(), - output_buffer.clone(), - handle.clone(), - reader_done.clone(), - ); + spawn_stream_reader(pty_master, "stdout", output.clone(), reader_done.clone()); } else { if let Some(stdout) = child.stdout.take() { - spawn_stream_reader( - stdout, - "stdout", - execution_id.clone(), - listener.clone(), - output_buffer.clone(), - handle.clone(), - reader_done.clone(), - ); + spawn_stream_reader(stdout, "stdout", output.clone(), reader_done.clone()); } if let Some(stderr) = child.stderr.take() { - spawn_stream_reader( - stderr, - "stderr", - execution_id.clone(), - listener.clone(), - output_buffer.clone(), - handle.clone(), - reader_done.clone(), - ); + spawn_stream_reader(stderr, "stderr", output.clone(), reader_done.clone()); } } @@ -368,8 +347,8 @@ impl ActionExecutor { }; // Remove from running and hand the output buffer to the finished - // set. The buffer itself moves: nothing is copied, and the readers - // keep appending to the same one. + // set. The buffer itself moves: nothing is copied, and the emitter + // keeps appending to the same one. { let mut running = running_clone.lock().unwrap(); if let Some(state) = running.remove(&exec_id) { @@ -380,13 +359,22 @@ impl ActionExecutor { } } - // The process has exited, but the readers may not have delivered - // the last of its output yet. Wait for them, so that the terminal - // status follows all of the output and the finished log is whole. - // The wait is bounded because a process that outlives the action - // can hold the output open indefinitely; whatever it writes later - // still lands in the same buffer. - wait_for_readers(&readers_done, reader_drain_timeout); + // The process has exited, but the last of its output may still be + // unread, or read and waiting in a batch. Wait for the readers, + // then have the emitter deliver what it holds, so that the + // terminal status follows all of the output and the finished log + // is whole. + // + // The wait for the readers is bounded because a process that + // outlives the action can hold the output open indefinitely; + // whatever it writes later still lands in the same buffer and is + // still delivered. The flush has a bound of its own, so that what + // was read is delivered ahead of the status even when the readers + // used theirs up. + wait_for_readers(&readers_done, Instant::now() + reader_drain_timeout); + output.flush_by(Instant::now() + reader_drain_timeout); + // The readers keep the emitter alive for as long as they run. + drop(output); let success = exit_status.as_ref().map(|s| s.success()).unwrap_or(false); diff --git a/crates/builderbot-actions/src/executor/tests.rs b/crates/builderbot-actions/src/executor/tests.rs index 40f391b42..90f69de82 100644 --- a/crates/builderbot-actions/src/executor/tests.rs +++ b/crates/builderbot-actions/src/executor/tests.rs @@ -1,4 +1,4 @@ -//! Tests for how the executor buffers, bounds and retains output. +//! Tests for how the executor buffers, bounds, retains and delivers output. //! //! Most of them run a short `/bin/sh` script through `execute_remote`, which //! spawns the program directly on pipes: unlike the local path it does not @@ -427,11 +427,7 @@ async fn reads_of_one_stream_are_coalesced() { let Finished { id, outcome, .. } = run_sh_to_finish(&executor, script).await; // Many reads were streamed, and they are buffered as a single block. - assert!( - outcome.streamed.len() > 10, - "{} reads", - outcome.streamed.len() - ); + assert_eq!(outcome.streamed_text(), written); let chunks = executor.get_buffered_output(&id).unwrap(); assert_eq!(chunks.len(), 1); assert_eq!(chunks[0].stream, stream); @@ -443,6 +439,14 @@ async fn reads_of_one_stream_are_coalesced() { async fn a_character_split_across_reads_is_decoded_whole() { let (listener, events) = recorder(); let buffer = OutputBuffer::shared(MAX_OUTPUT_BYTES); + let output = output_emitter::spawn( + "exec".to_string(), + listener, + buffer.clone(), + Handle::current(), + WAIT, + EMIT_MAX_BYTES, + ); let (reader_done, readers_done) = mpsc::channel(); // "café €" with both multi-byte characters cut by a read boundary. let reads = vec![ @@ -455,13 +459,11 @@ async fn a_character_split_across_reads_is_decoded_whole() { spawn_stream_reader( ScriptedReads(reads.into_iter()), "stdout", - "exec".to_string(), - listener, - buffer.clone(), - Handle::current(), + output.clone(), reader_done, ); - assert!(wait_for_readers(&readers_done, WAIT)); + assert!(wait_for_readers(&readers_done, Instant::now() + WAIT)); + assert!(output.flush_by(Instant::now() + WAIT)); let streamed: Vec = events .try_iter() @@ -470,8 +472,8 @@ async fn a_character_split_across_reads_is_decoded_whole() { other => panic!("unexpected event {other:?}"), }) .collect(); - // Each character is delivered once, with the read that completes it. - assert_eq!(streamed, vec!["caf", "é ", "€"]); + // Each character is delivered once, and whole. + assert_eq!(streamed, vec!["café €"]); let chunks = buffer.lock().unwrap().snapshot(); assert_eq!(chunks.len(), 1); assert_eq!(chunks[0].chunk, "café €"); @@ -575,3 +577,125 @@ async fn discarding_a_finished_execution_frees_its_output_now() { assert_eq!(buffered_text(&executor, &id), None); assert!(!executor.discard_output("no-such-execution")); } + +// ============================================================================= +// Item 4: output is delivered to the listener in batches +// ============================================================================= + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn output_is_delivered_in_batches_instead_of_read_by_read() { + // The interval never elapses in this test, and the output is smaller than + // a batch may be, so nothing delivers it before the execution ends. + let executor = ActionExecutor::with_limits(Limits { + emit_interval: WAIT, + ..patient_limits() + }); + let started = Instant::now(); + let Finished { + events, outcome, .. + } = run_sh_to_finish(&executor, "seq 1 3000").await; + + outcome.assert_completed(); + // Dozens of reads reach the listener as one event. It arrives ahead of + // the terminal status, which does not wait out the interval for it, and + // nothing follows that status. + let written: String = (1..=3_000).map(|n| format!("{n}\n")).collect(); + assert_eq!(outcome.streamed, vec![written]); + assert!(started.elapsed() < WAIT); + assert!(events.try_recv().is_err()); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn a_full_batch_is_delivered_without_waiting_for_the_interval() { + let emit_max_bytes = 4096; + let executor = ActionExecutor::with_limits(Limits { + emit_interval: WAIT, + emit_max_bytes, + ..patient_limits() + }); + let Finished { outcome, .. } = run_sh_to_finish(&executor, "seq 1 20000").await; + + outcome.assert_completed(); + let written: String = (1..=20_000).map(|n| format!("{n}\n")).collect(); + assert_eq!(outcome.streamed_text(), written); + // Every batch but the last went out on reaching the size, so it is at + // least that large and overshoots by less than the one read that filled + // it. + let (last, full) = outcome.streamed.split_last().unwrap(); + let largest_read = 1024; + assert!(full.len() >= 20, "{} batches", full.len()); + for batch in full { + assert!( + (emit_max_bytes..emit_max_bytes + largest_read).contains(&batch.len()), + "a batch of {} bytes", + batch.len() + ); + } + assert!(last.len() < emit_max_bytes + largest_read); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn output_reaches_the_listener_while_the_action_is_still_running() { + // The production interval and batch size. + let executor = ActionExecutor::with_limits(patient_limits()); + let gate = Gate::closed(); + let (id, events) = run_sh_until_output( + &executor, + &format!("printf start; {}; printf end", gate.wait()), + "start", + ) + .await; + + // The script is waiting at its gate and the batch is far from full: the + // interval alone delivers it. + let first = loop { + match events.recv_timeout(WAIT).expect("no output was delivered") { + ExecutionEvent::Started { .. } => {} + ExecutionEvent::Output { chunk, .. } => break chunk, + other => panic!("unexpected event {other:?}"), + } + }; + assert_eq!(first, "start"); + assert!(executor.is_running(&id)); + + gate.open(); + let outcome = wait_for_finish(&events); + outcome.assert_completed(); + assert_eq!(outcome.streamed, vec!["end"]); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn a_batch_still_pending_at_exit_is_delivered_before_the_status() { + // The interval never elapses, so "first" is still waiting in its batch + // when the shell exits. The readers then time out, because the background + // job holds the pipes open. + let executor = ActionExecutor::with_limits(Limits { + emit_interval: WAIT, + reader_drain_timeout: Duration::from_secs(2), + ..Limits::default() + }); + let gate = Gate::closed(); + let Finished { + id, + events, + outcome, + } = run_sh_to_finish( + &executor, + &format!("printf first; ({}; printf late) &", gate.wait()), + ) + .await; + + // What had been read went out ahead of the terminal status all the same, + // and is in the finished log. + outcome.assert_completed(); + assert_eq!(outcome.streamed, vec!["first"]); + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("first")); + + // What the survivor writes afterwards is still delivered, after it. + gate.open(); + match events.recv_timeout(WAIT).expect("no late output") { + ExecutionEvent::Output { chunk, .. } => assert_eq!(chunk, "late"), + other => panic!("unexpected event {other:?}"), + } + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("firstlate")); +} diff --git a/crates/builderbot-actions/src/lib.rs b/crates/builderbot-actions/src/lib.rs index 3067cb54b..ad966145c 100644 --- a/crates/builderbot-actions/src/lib.rs +++ b/crates/builderbot-actions/src/lib.rs @@ -56,6 +56,7 @@ pub mod executor; mod finished_outputs; pub mod models; mod output_buffer; +mod output_emitter; mod utf8_stream; // Re-export main types for convenience diff --git a/crates/builderbot-actions/src/output_buffer.rs b/crates/builderbot-actions/src/output_buffer.rs index 4d5b838e8..c2e678b9a 100644 --- a/crates/builderbot-actions/src/output_buffer.rs +++ b/crates/builderbot-actions/src/output_buffer.rs @@ -61,14 +61,25 @@ impl OutputBuffer { Arc::new(Mutex::new(Self::new(max_bytes))) } - /// Append one read of `stream`, evicting the oldest output once the buffer + /// Append output of `stream`, evicting the oldest output once the buffer /// is over its bound. `timestamp` is kept only for the first read of a /// block. + /// + /// Output arrives in batches that can be larger than a block. Such a + /// batch is stored as several blocks, so that the bound holds whatever + /// size the buffer is fed in. pub(crate) fn push(&mut self, stream: &str, text: &str, timestamp: i64) { - if text.is_empty() { - return; + let mut rest = text; + while !rest.is_empty() { + let (piece, after) = rest.split_at(piece_len(rest, self.block_bytes)); + self.push_piece(stream, piece, timestamp); + rest = after; } + } + /// Append text that is no larger than a block, unless it is a single + /// character that is. + fn push_piece(&mut self, stream: &str, text: &str, timestamp: i64) { let block_bytes = self.block_bytes; let merged = match self.blocks.back_mut() { Some(last) if last.stream == stream && last.chunk.len() + text.len() <= block_bytes => { @@ -140,6 +151,18 @@ impl OutputBuffer { } } +/// How much of `text` goes into one block: all of it if it fits, otherwise +/// as many whole characters as do, and always at least one. +fn piece_len(text: &str, block_bytes: usize) -> usize { + if text.len() <= block_bytes { + return text.len(); + } + match text.floor_char_boundary(block_bytes) { + 0 => text.chars().next().map_or(0, char::len_utf8), + fits => fits, + } +} + fn block_cost(block: &OutputChunk) -> usize { BLOCK_OVERHEAD_BYTES + block.stream.len() + block.chunk.len() } @@ -236,6 +259,42 @@ mod tests { assert!(chunks.iter().all(|c| c.chunk.len() <= MAX_BLOCK_BYTES)); } + #[test] + fn a_batch_larger_than_a_block_is_stored_as_several() { + let max_bytes = 8 * 1024; + let mut buffer = OutputBuffer::new(max_bytes); + let block_bytes = buffer.block_bytes; + // Two-byte characters at odd offsets, so that a block boundary falls + // inside one. + let written: String = (0..20_000).map(|n| format!("é{n}\n")).collect(); + assert!(written.len() > 10 * max_bytes); + + buffer.push("stdout", &written, 7); + + assert!(buffer.retained_bytes <= max_bytes); + assert!(buffer.blocks.len() > 1); + assert!(buffer.blocks.iter().all(|b| b.chunk.len() <= block_bytes)); + assert!(buffer.blocks.iter().all(|b| b.timestamp == 7)); + // Whole characters only, and nothing lost at the block boundaries. + let retained: String = buffer.blocks.iter().map(|b| b.chunk.as_str()).collect(); + assert!(written.ends_with(&retained)); + assert_eq!( + buffer.dropped_bytes as usize + retained.len(), + written.len() + ); + } + + #[test] + fn a_character_larger_than_a_block_is_kept_whole() { + // The smallest buffer has one-byte blocks. + let mut buffer = OutputBuffer::new(1); + buffer.push("stdout", "a€b", 0); + + let blocks: Vec<&str> = buffer.blocks.iter().map(|b| b.chunk.as_str()).collect(); + assert_eq!(blocks, vec!["b"]); + assert_eq!(buffer.dropped_bytes, 4); + } + #[test] fn empty_reads_are_ignored() { let mut buffer = OutputBuffer::new(MAX_OUTPUT_BYTES); diff --git a/crates/builderbot-actions/src/output_emitter.rs b/crates/builderbot-actions/src/output_emitter.rs new file mode 100644 index 000000000..8f8eb229c --- /dev/null +++ b/crates/builderbot-actions/src/output_emitter.rs @@ -0,0 +1,396 @@ +//! Batched delivery of one execution's output. +//! +//! A process writes in small pieces, and a progress bar redraws many times a +//! second. Handing every read to the listener costs it an event each, whether +//! or not anyone is watching. Instead the reader threads queue their reads for +//! one emitter thread per execution, which merges them and delivers a batch +//! once it is [`EMIT_INTERVAL`] old or [`EMIT_MAX_BYTES`] large. +//! +//! A batch reaches the execution's buffer and then its listener, in that +//! order, so the buffer never holds output the listener has yet to be told +//! about. A viewer that reads the buffer and then follows the events sees no +//! batch twice. + +use std::convert::Infallible; +use std::sync::mpsc::{self, RecvTimeoutError, TrySendError}; +use std::sync::Arc; +use std::thread; +use std::time::{Duration, Instant}; + +use tokio::runtime::Handle; + +use crate::executor::ExecutionListener; +use crate::models::ExecutionEvent; +use crate::output_buffer::SharedOutputBuffer; + +/// How long output waits to be merged with what follows it. +pub(crate) const EMIT_INTERVAL: Duration = Duration::from_millis(50); + +/// A batch this large is delivered without waiting out the interval. +pub(crate) const EMIT_MAX_BYTES: usize = 64 * 1024; + +/// How many reads may be queued for the emitter before a reader blocks. The +/// listener is called synchronously, so this is what stops a slow listener +/// from building an unbounded queue: the reader stops reading, and the +/// process blocks on its output, as it did when each read was delivered +/// directly. +const QUEUED_READS: usize = 64; + +/// How often a flush that found the queue full tries again. +const FLUSH_RETRY_INTERVAL: Duration = Duration::from_millis(1); + +enum Message { + Output { + stream: &'static str, + text: String, + timestamp: i64, + }, + /// Deliver what is pending now, then drop the sender. + Flush(mpsc::Sender), +} + +/// Where the reader threads queue an execution's output. The emitter thread +/// ends once every clone has been dropped and the queue is empty. +#[derive(Clone)] +pub(crate) struct OutputSender(mpsc::SyncSender); + +impl OutputSender { + /// Queue one read of `stream`. Blocks while the emitter is behind. + pub(crate) fn send(&self, stream: &'static str, text: String, timestamp: i64) { + if text.is_empty() { + return; + } + // Fails only if the emitter thread is gone, which leaves nowhere to + // deliver to. + let _ = self.0.send(Message::Output { + stream, + text, + timestamp, + }); + } + + /// Deliver everything queued so far without waiting out the interval. + /// Returns whether the listener had it all by `deadline`. + /// + /// Unlike a read, the request does not wait indefinitely for room in the + /// queue: a caller with a deadline must not be held up by a listener that + /// has fallen behind. + pub(crate) fn flush_by(&self, deadline: Instant) -> bool { + let (delivered, wait) = mpsc::channel::(); + let mut request = Message::Flush(delivered); + loop { + match self.0.try_send(request) { + Ok(()) => break, + // The emitter thread has ended, with nothing left to deliver. + Err(TrySendError::Disconnected(_)) => return true, + Err(TrySendError::Full(unsent)) => { + if Instant::now() >= deadline { + return false; + } + request = unsent; + thread::sleep(FLUSH_RETRY_INTERVAL); + } + } + } + // Nothing is ever sent: the emitter drops its end once it is done. + matches!( + wait.recv_timeout(deadline.saturating_duration_since(Instant::now())), + Err(RecvTimeoutError::Disconnected) + ) + } +} + +/// Consecutive output of one stream, waiting to be delivered. +struct Segment { + stream: &'static str, + text: String, + /// When the first read in the segment arrived. + timestamp: i64, +} + +/// Start the emitter thread for one execution and return the queue that +/// feeds it. +pub(crate) fn spawn( + execution_id: String, + listener: Arc, + buffer: SharedOutputBuffer, + handle: Handle, + interval: Duration, + max_bytes: usize, +) -> OutputSender { + let (sender, receiver) = mpsc::sync_channel(QUEUED_READS); + + thread::spawn(move || { + let mut pending: Vec = Vec::new(); + let mut pending_bytes = 0; + // When the oldest pending read is due. Set while anything is pending. + let mut due: Option = None; + + loop { + let message = match due { + Some(due) => receiver.recv_timeout(due.saturating_duration_since(Instant::now())), + None => receiver.recv().map_err(|_| RecvTimeoutError::Disconnected), + }; + + let mut flush_requested = None; + let mut disconnected = false; + let deliver_now = match message { + Ok(Message::Output { + stream, + text, + timestamp, + }) => { + pending_bytes += text.len(); + match pending.last_mut() { + Some(last) if last.stream == stream => last.text.push_str(&text), + _ => pending.push(Segment { + stream, + text, + timestamp, + }), + } + let due = *due.get_or_insert_with(|| Instant::now() + interval); + // The queue can stay non-empty past the due time, so the + // timeout alone would not bound how long a batch waits. + pending_bytes >= max_bytes || Instant::now() >= due + } + Ok(Message::Flush(delivered)) => { + flush_requested = Some(delivered); + true + } + Err(RecvTimeoutError::Timeout) => true, + Err(RecvTimeoutError::Disconnected) => { + disconnected = true; + true + } + }; + + if deliver_now { + due = None; + pending_bytes = 0; + let batch = std::mem::take(&mut pending); + if !batch.is_empty() { + { + let mut buffer = buffer.lock().unwrap(); + for segment in &batch { + buffer.push(segment.stream, &segment.text, segment.timestamp); + } + } + for segment in batch { + handle.block_on(listener.on_event(ExecutionEvent::Output { + execution_id: execution_id.clone(), + chunk: segment.text, + stream: segment.stream.to_string(), + timestamp: segment.timestamp, + })); + } + } + } + // Only now is whoever asked for the flush told that it is done. + drop(flush_requested); + + if disconnected { + break; + } + } + }); + + OutputSender(sender) +} + +#[cfg(test)] +mod tests { + use super::*; + use crate::output_buffer::OutputBuffer; + use async_trait::async_trait; + + /// Upper bound on any single wait. Generous, so a loaded machine does not + /// fail a test; a healthy run takes milliseconds. + const WAIT: Duration = Duration::from_secs(60); + + /// Forwards the stream and text of every output event to the test. + struct Recorder { + events: mpsc::Sender<(String, String)>, + /// Held while an event is handled, so a test can stall the emitter. + stall: Arc>, + } + + #[async_trait] + impl ExecutionListener for Recorder { + async fn on_event(&self, event: ExecutionEvent) { + let _stalled = self.stall.lock().unwrap(); + if let ExecutionEvent::Output { chunk, stream, .. } = event { + let _ = self.events.send((stream, chunk)); + } + } + } + + struct Fixture { + output: OutputSender, + events: mpsc::Receiver<(String, String)>, + buffer: SharedOutputBuffer, + stall: Arc>, + } + + fn emitter(interval: Duration, max_bytes: usize) -> Fixture { + let (events_tx, events) = mpsc::channel(); + let stall = Arc::new(std::sync::Mutex::new(())); + let buffer = OutputBuffer::shared(1024 * 1024); + let output = spawn( + "exec".to_string(), + Arc::new(Recorder { + events: events_tx, + stall: stall.clone(), + }), + buffer.clone(), + Handle::current(), + interval, + max_bytes, + ); + Fixture { + output, + events, + buffer, + stall, + } + } + + fn flush(output: &OutputSender) { + assert!(output.flush_by(Instant::now() + WAIT)); + } + + fn owned(events: &[(&str, &str)]) -> Vec<(String, String)> { + events + .iter() + .map(|(stream, text)| (stream.to_string(), text.to_string())) + .collect() + } + + fn buffered(buffer: &SharedOutputBuffer) -> Vec<(String, String)> { + let chunks = buffer.lock().unwrap().snapshot(); + chunks.into_iter().map(|c| (c.stream, c.chunk)).collect() + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn reads_are_merged_into_one_event_per_run_of_a_stream() { + // The interval never elapses here: only the flush delivers. + let Fixture { + output, + events, + buffer, + .. + } = emitter(WAIT, usize::MAX); + + for (stream, text) in [ + ("stdout", "a"), + ("stdout", "b"), + ("stderr", "c"), + ("stdout", "d"), + ("stdout", ""), + ("stdout", "e"), + ] { + output.send(stream, text.to_string(), 0); + } + assert!(events.try_recv().is_err()); + flush(&output); + + // The streams keep the order they were read in. + let expected = owned(&[("stdout", "ab"), ("stderr", "c"), ("stdout", "de")]); + assert_eq!(events.try_iter().collect::>(), expected); + assert_eq!(buffered(&buffer), expected); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn a_batch_is_delivered_once_the_interval_has_passed() { + let Fixture { output, events, .. } = emitter(Duration::from_millis(20), usize::MAX); + + output.send("stdout", "one".to_string(), 0); + // No flush and no further output: the interval alone delivers it. + assert_eq!( + events.recv_timeout(WAIT).unwrap(), + ("stdout".to_string(), "one".to_string()) + ); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn a_batch_that_reaches_the_size_limit_is_delivered_at_once() { + let Fixture { output, events, .. } = emitter(WAIT, 10); + + output.send("stdout", "12345".to_string(), 0); + output.send("stdout", "6789".to_string(), 0); + output.send("stdout", "0".to_string(), 0); + assert_eq!(events.recv_timeout(WAIT).unwrap().1, "1234567890"); + + // The next batch starts empty. + output.send("stdout", "rest".to_string(), 0); + flush(&output); + assert_eq!(events.try_iter().collect::>().len(), 1); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn the_buffer_never_runs_ahead_of_the_listener() { + let Fixture { + output, + events, + buffer, + .. + } = emitter(WAIT, usize::MAX); + + output.send("stdout", "first".to_string(), 0); + flush(&output); + assert_eq!(events.try_iter().count(), 1); + + // Queued but not yet delivered: a viewer that reads the buffer now and + // then follows the events must not get "second" from both. + output.send("stdout", "second".to_string(), 0); + assert_eq!(buffered(&buffer), owned(&[("stdout", "first")])); + + flush(&output); + assert_eq!(buffered(&buffer), owned(&[("stdout", "firstsecond")])); + assert_eq!(events.try_iter().count(), 1); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn a_flush_gives_up_at_its_deadline() { + let Fixture { + output, + events, + stall, + .. + } = emitter(WAIT, usize::MAX); + let soon = || Instant::now() + Duration::from_millis(50); + + // The listener is busy with the batch being flushed. + let stalled = stall.lock().unwrap(); + output.send("stdout", "one".to_string(), 0); + assert!(!output.flush_by(soon())); + + // The queue fills up behind it, so a flush cannot even be requested. + for _ in 0..QUEUED_READS { + output.send("stdout", "x".to_string(), 0); + } + assert!(!output.flush_by(soon())); + + // Nothing was lost to either: it is all delivered once the listener + // catches up. + drop(stalled); + flush(&output); + let delivered: Vec = events.try_iter().map(|(_, text)| text).collect(); + assert_eq!(delivered, vec!["one".to_string(), "x".repeat(QUEUED_READS)]); + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn pending_output_is_delivered_when_the_last_sender_goes() { + let Fixture { output, events, .. } = emitter(WAIT, usize::MAX); + + output.send("stderr", "tail".to_string(), 0); + drop(output); + + assert_eq!( + events.recv_timeout(WAIT).unwrap(), + ("stderr".to_string(), "tail".to_string()) + ); + // The emitter thread has ended, and its listener with it. + assert!(events.recv_timeout(WAIT).is_err()); + } +} From 21f8e6fe85c5560fb3a262269370594f179c8470 Mon Sep 17 00:00:00 2001 From: Matt Toohey Date: Fri, 13 Nov 2026 14:41:55 +1100 Subject: [PATCH 3/4] fix(actions): join buffered and live output exactly, and bound the view Requested: item 5 of the action-output leak note's recommended fix (make get_action_output_buffer asynchronous and tail-only, register the listener before fetching the snapshot, cap displayed lines, stop copying the line array each frame, release lines and the render cache on close), the frontend half of item 3 (clear a finished execution when its pill is dropped, unless the modal is showing it), and what root cause section 4 lists for the open view. Builds on cb75cc2e and bd03eba5, which bounded, batched and evicted the output in the backend. NEEDS HUMAN REVIEW: backend shape changes The constraint was no missing or duplicated chunk where the snapshot meets the live events. That cannot be met from the existing shapes: the snapshot and the events travel on separate channels, so an event can land on either side of a snapshot that already holds its text, and matching on content is ambiguous for output that repeats itself (a progress bar). The smallest change that makes the join exact is one byte offset on each side: - builderbot_actions::ExecutionEvent::Output gains `offset: u64`, the bytes of output delivered before the chunk. - The `action_output` event payload gains `offset`. - `get_action_output_buffer` now returns `{ chunks, endOffset }`, the new builderbot_actions::BufferedOutput, instead of a bare chunk array. `OutputExecutor::get_buffered_output` returns the same type. - `get_action_output_buffer` is now an async command, so it no longer serialises up to 4 MiB on the main thread. Its arguments are unchanged. Both additions are additive for a reader of the events. The return shape is not: a web client still running a cached older shell would fail to load output until it reloads. "Tail-only" adds no parameter: the tail is the 4 MiB ring cb75cc2e introduced, which the command already returned. The offset is counted in OutputBuffer under the lock that appends a batch, and a batch is appended whole before it is emitted, so a snapshot always ends on the boundary between two events. Frontend - outputFollower (new) joins the two sources. It shows a snapshot, skips events that end at or before the snapshot's end, shows the event that starts exactly there, and takes a new snapshot on any gap or overlap instead of showing output with a hole in it. Events that arrive while a snapshot is in flight are held, up to 4 Mi characters. - ActionOutputModal registers its output listener first and reads the buffer from the listener's onEstablished, which also fires after a reconnect or an event gap. The old order lost what was written before the listener went live. - createIncrementalProcessor keeps a bounded tail: 5,000 lines, 4 Mi characters, 64 Ki characters per line. It updates one array in place and replaces a line object only when its text changes. The modal shows a count of the earlier lines it dropped. - The modal publishes that same array once per frame through a keyed each, so a frame costs the lines that changed, not the lines shown. - The render cache is gone rather than bounded. With the keyed list a line is rendered once per line object, so there was nothing left for a cache to save. - The modal releases its lines once the dialog has finished closing (onOpenChangeComplete), so the instance a branch card keeps mounted holds nothing between uses. It shows "Output is no longer available." for an execution whose output was cleared or evicted. - ActionRunner clears a finished execution in the backend when its pill is dropped. If the output modal is showing that execution, the clear waits until the modal closes or moves to another execution. Tests - Crate: offsets in the buffer and emitter, and events against the snapshot under eviction. - Tauri: the command's JSON shape and its agreement with the events. - Frontend: the follower (boundary cases and a randomised delivery and loss simulation), the processor (parity with processChunksToLines, limits, object identity), the runner's clearing, and the modal under the real dialog primitive. Checks run: cargo fmt --check and clippy for the crate and the Tauri app, cargo test -p builderbot-actions, the Tauri actions and web dispatch tests, prettier, svelte-check and tsc, and vitest for the actions feature, BranchCard and projectRunActions. Not run, because of machine load and disk: the full Tauri and frontend suites, and `just ci`. Not exercised in a real webview: the release after the close animation. Known limits: the Save log button saves the lines the modal holds, not the whole run. A reader scrolled up at the line cap sees the content shift as lines are dropped. Clearing on pill drop is per runner, so another window that opens the same finished execution afterwards sees "Output is no longer available." Signed-off-by: Matt Toohey Co-Authored-By: Claude Fable 5.2 --- apps/staged/src-tauri/src/actions/commands.rs | 135 +++- apps/staged/src-tauri/src/actions/events.rs | 6 + .../ActionOutputModal.component.test.ts | 612 ++++++++++++++++++ .../features/actions/ActionOutputModal.svelte | 276 +++++--- .../features/actions/actionRunner.svelte.ts | 76 ++- .../lib/features/actions/actionRunner.test.ts | 210 +++++- .../src/lib/features/actions/actions.ts | 44 +- .../features/actions/outputFollower.test.ts | 458 +++++++++++++ .../lib/features/actions/outputFollower.ts | 217 +++++++ .../features/actions/processOutput.test.ts | 276 +++++++- .../src/lib/features/actions/processOutput.ts | 248 +++++-- crates/builderbot-actions/src/executor.rs | 20 +- .../builderbot-actions/src/executor/tests.rs | 46 +- crates/builderbot-actions/src/lib.rs | 4 +- crates/builderbot-actions/src/models.rs | 20 + .../builderbot-actions/src/output_buffer.rs | 40 ++ .../builderbot-actions/src/output_emitter.rs | 81 ++- 17 files changed, 2543 insertions(+), 226 deletions(-) create mode 100644 apps/staged/src/lib/features/actions/ActionOutputModal.component.test.ts create mode 100644 apps/staged/src/lib/features/actions/outputFollower.test.ts create mode 100644 apps/staged/src/lib/features/actions/outputFollower.ts diff --git a/apps/staged/src-tauri/src/actions/commands.rs b/apps/staged/src-tauri/src/actions/commands.rs index 075c1f385..c9ae35853 100644 --- a/apps/staged/src-tauri/src/actions/commands.rs +++ b/apps/staged/src-tauri/src/actions/commands.rs @@ -1343,16 +1343,24 @@ pub fn get_all_running_actions( pub(crate) fn get_action_output_buffer_impl( execution_id: String, executor: &ActionExecutor, -) -> Result>, String> { +) -> Result, String> { Ok(executor.get_buffered_output(&execution_id)) } -/// Get buffered output for an action execution +/// Get the buffered output of an action execution: the most recent output the +/// executor retains, and the offset it ends at. +/// +/// A viewer that is already listening for `action_output` uses that offset to +/// join the two without a gap or a repeat: events whose `offset` is below it +/// are in the returned chunks, and the next one starts exactly at it. +/// +/// Asynchronous so that copying and serializing the buffer, which can be +/// several megabytes, happens off the main thread. #[tauri::command] -pub fn get_action_output_buffer( +pub async fn get_action_output_buffer( execution_id: String, executor: State<'_, Arc>, -) -> Result>, String> { +) -> Result, String> { get_action_output_buffer_impl(execution_id, &executor) } @@ -1570,6 +1578,125 @@ mod tests { execution_id } + /// Collects the `action_output` payload each output event becomes, and + /// says when the execution has reported its terminal status. + #[cfg(unix)] + struct RecordOutput { + output: std::sync::Mutex>, + finished: std::sync::Mutex>, + } + + #[cfg(unix)] + #[async_trait::async_trait] + impl builderbot_actions::ExecutionListener for RecordOutput { + async fn on_event(&self, event: builderbot_actions::ExecutionEvent) { + match event { + builderbot_actions::ExecutionEvent::Output { + execution_id, + chunk, + stream, + offset, + .. + } => self + .output + .lock() + .unwrap() + .push(crate::actions::events::ActionOutputEvent { + execution_id, + chunk, + stream, + offset, + }), + builderbot_actions::ExecutionEvent::StatusChanged { .. } => { + let _ = self.finished.lock().unwrap().send(()); + } + builderbot_actions::ExecutionEvent::Started { .. } => {} + } + } + } + + #[cfg(unix)] + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn the_output_buffer_ends_where_the_output_events_do() { + let executor = ActionExecutor::new(); + + // A freshly spawned child is occasionally killed before it runs (see + // the executor's tests), so start again if nothing was written. + let mut attempt = None; + for _ in 0..5 { + let (finished_tx, finished) = std::sync::mpsc::channel(); + let listener = Arc::new(RecordOutput { + output: Default::default(), + finished: std::sync::Mutex::new(finished_tx), + }); + let execution_id = executor + .execute_remote( + std::path::PathBuf::from("/bin/sh"), + vec![ + "-c".to_string(), + "printf 'héllo\\n'; printf 'err\\n' >&2".to_string(), + ], + listener.clone(), + ) + .await + .unwrap(); + // The terminal status follows all of the output. + finished + .recv_timeout(std::time::Duration::from_secs(60)) + .expect("the execution did not finish"); + let output = get_action_output_buffer_impl(execution_id.clone(), &executor) + .unwrap() + .expect("a finished execution keeps its output"); + if output.end_offset > 0 { + attempt = Some((execution_id, listener, output)); + break; + } + } + let (execution_id, listener, output) = attempt.expect("the script never ran"); + + let text: String = output.chunks.iter().map(|c| c.chunk.as_str()).collect(); + assert_eq!(text.len(), "héllo\nerr\n".len()); + assert_eq!(output.end_offset, text.len() as u64); + + // The payload a viewer gets: the chunks, and the offset they end at. + let json = serde_json::to_value(&output).unwrap(); + assert_eq!(json["endOffset"], serde_json::json!(text.len())); + assert_eq!( + json["chunks"].as_array().unwrap().len(), + output.chunks.len() + ); + assert!(json["chunks"][0]["chunk"].is_string()); + assert!(json["chunks"][0]["stream"].is_string()); + + // Each event says where its chunk starts, in the same bytes, and the + // last one ends where the buffer does. + let events = listener.output.lock().unwrap().clone(); + let mut expected = 0; + for event in &events { + assert_eq!(event.execution_id, execution_id); + assert_eq!(event.offset, expected); + expected += event.chunk.len() as u64; + assert_eq!( + serde_json::to_value(event).unwrap()["offset"], + serde_json::json!(event.offset) + ); + } + assert_eq!(expected, output.end_offset); + + // An execution that is unknown, or whose output is gone, has none. + assert!(clear_action_execution_impl(execution_id.clone(), &executor).unwrap()); + assert!(get_action_output_buffer_impl(execution_id, &executor) + .unwrap() + .is_none()); + assert_eq!( + serde_json::to_value( + get_action_output_buffer_impl("unknown".to_string(), &executor).unwrap() + ) + .unwrap(), + serde_json::Value::Null + ); + } + #[cfg(unix)] #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn stopping_a_branch_for_deletion_discards_its_action_output() { diff --git a/apps/staged/src-tauri/src/actions/events.rs b/apps/staged/src-tauri/src/actions/events.rs index 418f7facc..5e941f7bb 100644 --- a/apps/staged/src-tauri/src/actions/events.rs +++ b/apps/staged/src-tauri/src/actions/events.rs @@ -17,6 +17,10 @@ pub struct ActionOutputEvent { pub execution_id: String, pub chunk: String, pub stream: String, // "stdout" or "stderr" + /// Where `chunk` starts in the execution's output, in bytes. A viewer + /// compares it with the `endOffset` of `get_action_output_buffer` to tell + /// output it already has from output that follows it. + pub offset: u64, } /// Event emitted when action status changes @@ -104,6 +108,7 @@ impl ExecutionListener for TauriExecutionListener { execution_id, chunk, stream, + offset, .. } => { // Feed normalized terminal output into the shared buffer for @@ -120,6 +125,7 @@ impl ExecutionListener for TauriExecutionListener { execution_id, chunk, stream, + offset, }, ); } diff --git a/apps/staged/src/lib/features/actions/ActionOutputModal.component.test.ts b/apps/staged/src/lib/features/actions/ActionOutputModal.component.test.ts new file mode 100644 index 000000000..6c0815405 --- /dev/null +++ b/apps/staged/src/lib/features/actions/ActionOutputModal.component.test.ts @@ -0,0 +1,612 @@ +import { flushSync, mount, tick, unmount } from 'svelte'; +import { afterEach, beforeAll, beforeEach, describe, expect, it, vi } from 'vitest'; +import type { ListenOptions } from '$lib/transport'; +import type { ActionOutputEvent, ActionStatusEvent, BufferedOutput } from './actions'; + +// The modal under the real dialog primitive, with the backend replaced by a +// fake the tests drive: a buffer snapshot that lands when the test says, and +// output and status listeners the test can fire. What is covered here is the +// wiring around outputFollower and processOutput, which have their own +// tests: the order the modal subscribes and fetches in, what it renders at +// the join, how much of the list a live update touches, and what it lets go +// of when it closes. + +const backend = vi.hoisted(() => { + interface Listener { + callback: (event: T) => void; + opts?: ListenOptions; + live: boolean; + } + interface Fetch { + executionId: string; + land: (snapshot: BufferedOutput | null) => void; + fail: (error: unknown) => void; + } + return { + /** Every backend call the modal made, in order. */ + calls: [] as string[], + outputListeners: [] as Listener[], + statusListeners: [] as Listener[], + fetches: [] as Fetch[], + sanitized: [] as string[], + processors: [] as { lines: unknown[] }[], + createNote: vi.fn(async () => {}), + clearActionExecution: vi.fn(async () => true), + stopBranchAction: vi.fn(async () => {}), + }; +}); + +vi.mock('./actions', () => { + function listen( + name: string, + listeners: { callback: (event: T) => void; opts?: ListenOptions; live: boolean }[] + ) { + return (callback: (event: T) => void, opts?: ListenOptions) => { + backend.calls.push(`listen:${name}`); + const listener = { callback, opts, live: true }; + listeners.push(listener); + return () => { + backend.calls.push(`unlisten:${name}`); + listener.live = false; + }; + }; + } + return { + getActionOutputBuffer: (executionId: string) => { + backend.calls.push(`fetch:${executionId}`); + return new Promise((land, fail) => { + backend.fetches.push({ executionId, land, fail }); + }); + }, + listenToActionOutput: listen('output', backend.outputListeners), + listenToActionStatus: listen('status', backend.statusListeners), + stopBranchAction: backend.stopBranchAction, + clearActionExecution: backend.clearActionExecution, + }; +}); +vi.mock('../../commands', () => ({ createNote: backend.createNote })); +// The real sanitizer and line processor, with a record of what each was +// asked for: the lines rendered to HTML, and the processors made to hold +// lines. +vi.mock('../../shared/sanitize', async (importOriginal) => { + const actual = await importOriginal(); + return { + sanitize: (dirty: string) => { + backend.sanitized.push(dirty); + return actual.sanitize(dirty); + }, + }; +}); +vi.mock('./processOutput', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + createIncrementalProcessor: (...args: Parameters) => { + const processor = actual.createIncrementalProcessor(...args); + backend.processors.push(processor); + return processor; + }, + }; +}); + +import ActionOutputModal from './ActionOutputModal.svelte'; +import { OUTPUT_LINE_LIMITS } from './processOutput'; +import { reactiveProps } from '../sessions/testStubs/reactiveProps.svelte'; + +const encoder = new TextEncoder(); + +/** A fake execution's output, as the backend's buffer and events present it. */ +function execution(executionId: string) { + const chunks: { chunk: string; stream: 'stdout' | 'stderr'; offset: number }[] = []; + let end = 0; + return { + /** Write `chunk`. Returns the event the backend emits for it. */ + write(chunk: string, stream: 'stdout' | 'stderr' = 'stdout'): ActionOutputEvent { + const event = { executionId, chunk, stream, offset: end }; + chunks.push({ chunk, stream, offset: end }); + end += encoder.encode(chunk).length; + return event; + }, + /** The buffer as it now stands. */ + snapshot(): BufferedOutput { + return { + chunks: chunks.map(({ chunk, stream }) => ({ chunk, stream, timestamp: 0 })), + endOffset: end, + }; + }, + }; +} + +type Props = { + open: boolean; + executionId: string; + branchId?: string; + actionName: string; + onClose: () => void; +}; + +let component: ReturnType | null = null; +let props: Props; + +/** Let promise callbacks, the dialog's frames and the re-render all land. */ +async function settle() { + // The dialog mounts and unmounts, and the modal publishes live output, on + // animation frames. + await new Promise((resolve) => requestAnimationFrame(resolve)); + for (let i = 0; i < 3; i++) { + await new Promise((resolve) => setTimeout(resolve, 0)); + await tick(); + flushSync(); + } +} + +async function mountModal(initial: Partial = {}) { + props = reactiveProps({ + open: true, + executionId: 'execution-1', + branchId: 'branch-1', + actionName: 'Test', + onClose: vi.fn(), + ...initial, + }); + const target = document.createElement('div'); + document.body.appendChild(target); + component = mount(ActionOutputModal, { target, props }); + await settle(); +} + +const liveOutputListeners = () => backend.outputListeners.filter((l) => l.live); +const liveStatusListeners = () => backend.statusListeners.filter((l) => l.live); + +/** Tell the modal its output listener is live (or live again). */ +function establish() { + for (const listener of liveOutputListeners()) listener.opts?.onEstablished?.(); +} + +function emit(event: ActionOutputEvent) { + for (const listener of liveOutputListeners()) listener.callback(event); +} + +/** Land the oldest snapshot still in flight. */ +async function land(snapshot: BufferedOutput | null) { + const fetch = backend.fetches.shift(); + if (!fetch) throw new Error('no snapshot is in flight'); + fetch.land(snapshot); + await settle(); +} + +const rows = () => [...document.querySelectorAll('.output-line:not(.dropped-lines)')]; +const rowTexts = () => rows().map((row) => row.textContent?.trim()); +const centerState = () => document.querySelector('.center-state')?.textContent?.trim() ?? null; +const droppedNotice = () => document.querySelector('.dropped-lines')?.textContent?.trim() ?? null; + +beforeAll(() => { + // jsdom lacks the layout APIs the dialog's viewport tracking uses. + window.matchMedia = ((query: string) => ({ + matches: false, + media: query, + addEventListener: () => {}, + removeEventListener: () => {}, + })) as unknown as typeof window.matchMedia; +}); + +beforeEach(() => { + backend.calls.length = 0; + backend.outputListeners.length = 0; + backend.statusListeners.length = 0; + backend.fetches.length = 0; + backend.sanitized.length = 0; + backend.processors.length = 0; + backend.createNote.mockClear(); + vi.spyOn(console, 'error').mockImplementation(() => {}); +}); + +afterEach(async () => { + if (component) unmount(component); + component = null; + await settle(); + document.body.innerHTML = ''; + vi.restoreAllMocks(); +}); + +describe('opening', () => { + it('listens for output before it reads the buffer', async () => { + await mountModal(); + + // Nothing is read until the listener says it is live: output written in + // between would be in neither the snapshot nor an event. + expect(backend.calls).toEqual(['listen:output', 'listen:status']); + expect(centerState()).toBe('Loading output…'); + + establish(); + expect(backend.calls).toEqual(['listen:output', 'listen:status', 'fetch:execution-1']); + }); + + it('still shows the buffer when the listener cannot be registered', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + + liveOutputListeners()[0].opts?.onRegistrationFailed?.(new Error('no event channel')); + await land(run.snapshot()); + + expect(rowTexts()).toEqual(['one']); + }); + + it('shows each chunk once when events land on both sides of the snapshot', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + establish(); + + // Written while the snapshot is in flight. The snapshot is taken after + // the first of these and before the second, and both events reach the + // modal ahead of it. + const inSnapshot = run.write('two\n'); + const snapshot = run.snapshot(); + const afterSnapshot = run.write('three\n'); + emit(inSnapshot); + emit(afterSnapshot); + await land(snapshot); + expect(rowTexts()).toEqual(['one', 'two', 'three']); + + // An event the snapshot already held, delivered late. + emit(inSnapshot); + emit(run.write('four\n')); + await settle(); + expect(rowTexts()).toEqual(['one', 'two', 'three', 'four']); + }); + + it('joins a progress bar that repeats itself without dropping or doubling a tick', async () => { + // Identical chunks: nothing in their text says which the snapshot holds. + const run = execution('execution-1'); + const ticks = [run.write('.'), run.write('.'), run.write('.')]; + await mountModal(); + establish(); + const snapshot = run.snapshot(); + ticks.push(run.write('.'), run.write('.')); + for (const tick of ticks) emit(tick); + await land(snapshot); + + expect(rowTexts()).toEqual(['.....']); + }); + + it('ignores the output of other executions', async () => { + const run = execution('execution-1'); + const other = execution('execution-2'); + await mountModal(); + establish(); + await land(run.snapshot()); + + emit(other.write('not mine\n')); + emit(run.write('mine\n')); + await settle(); + + expect(rowTexts()).toEqual(['mine']); + }); + + it('says so when a running action has written nothing yet', async () => { + await mountModal(); + establish(); + await land(execution('execution-1').snapshot()); + + expect(centerState()).toBe('No output yet…'); + }); + + it('says so when the output has been cleared or evicted', async () => { + await mountModal(); + establish(); + await land(null); + + expect(centerState()).toBe('Output is no longer available.'); + expect(rows()).toHaveLength(0); + }); + + it('shows the failure when the buffer cannot be read', async () => { + await mountModal(); + establish(); + backend.fetches.shift()!.fail(new Error('IPC unavailable')); + await settle(); + + expect(centerState()).toBe('IPC unavailable'); + }); + + it('reads nothing and listens to nothing while closed', async () => { + await mountModal({ open: false, executionId: '' }); + + expect(backend.calls).toEqual([]); + expect(document.querySelector('.output-line')).toBeNull(); + }); +}); + +describe('following live output', () => { + it('renders only the lines that changed', async () => { + const run = execution('execution-1'); + run.write('one\ntwo\nthr'); + await mountModal(); + establish(); + await land(run.snapshot()); + expect(rowTexts()).toEqual(['one', 'two', 'thr']); + expect(backend.sanitized).toEqual(['one', 'two', 'thr']); + const before = rows(); + + backend.sanitized.length = 0; + emit(run.write('ee\nfour\n')); + await settle(); + + expect(rowTexts()).toEqual(['one', 'two', 'three', 'four']); + // The finished lines were neither rendered to HTML again nor replaced in + // the document; the unfinished one was updated where it stood. + expect([...backend.sanitized].sort()).toEqual(['four', 'three']); + const after = rows(); + expect(after.slice(0, 3).every((row, i) => row === before[i])).toBe(true); + }); + + it('does not render a line again when it finishes as it stood', async () => { + const run = execution('execution-1'); + run.write('building'); + await mountModal(); + establish(); + await land(run.snapshot()); + backend.sanitized.length = 0; + + emit(run.write('\n')); + emit(run.write('done')); + await settle(); + + expect(rowTexts()).toEqual(['building', 'done']); + expect(backend.sanitized).toEqual(['done']); + }); + + it('keeps one processor and one line array for the whole of a run', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + const processor = backend.processors.at(-1)!; + const lines = processor.lines; + + for (let i = 0; i < 50; i++) { + emit(run.write(`line ${i}\n`)); + if (i % 10 === 0) await settle(); + } + await settle(); + + expect(rows()).toHaveLength(51); + // Live output is added to the array the snapshot filled: no update + // copies the lines or starts a new holder for them. + expect(backend.processors.at(-1)).toBe(processor); + expect(processor.lines).toBe(lines); + expect(lines).toHaveLength(51); + }); + + it('overwrites a line on a carriage return', async () => { + const run = execution('execution-1'); + run.write('10%'); + await mountModal(); + establish(); + await land(run.snapshot()); + + emit(run.write('\r50%')); + emit(run.write('\r100%\n')); + await settle(); + + expect(rowTexts()).toEqual(['100%']); + }); + + it('marks stderr lines', async () => { + const run = execution('execution-1'); + run.write('out\n'); + run.write('err\n', 'stderr'); + await mountModal(); + establish(); + await land(run.snapshot()); + + expect(rows().map((row) => row.classList.contains('stderr'))).toEqual([false, true]); + }); + + it('keeps the output inert', async () => { + const run = execution('execution-1'); + run.write(' \u001b[31mred\u001b[0m\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + + expect(rows()[0].querySelector('img')).toBeNull(); + expect(rowTexts()).toEqual([' red']); + }); + + it('reads the buffer again when the listener is re-established', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + + // A reconnect: these were written while nothing was listening. + run.write('two\n'); + run.write('three\n'); + establish(); + expect(backend.fetches).toHaveLength(1); + await land(run.snapshot()); + + expect(rowTexts()).toEqual(['one', 'two', 'three']); + }); + + it('reads the buffer again when an event shows that one was lost', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + + run.write('two\n'); + emit(run.write('three\n')); + await settle(); + // Not shown with a hole in it. + expect(rowTexts()).toEqual(['one']); + await land(run.snapshot()); + + expect(rowTexts()).toEqual(['one', 'two', 'three']); + }); + + it('keeps what is on show when a later read of the buffer fails', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + + establish(); + backend.fetches.shift()!.fail(new Error('IPC unavailable')); + await settle(); + + expect(rowTexts()).toEqual(['one']); + expect(centerState()).toBeNull(); + }); +}); + +describe('the line limit', () => { + it('shows the most recent lines and counts the rest', async () => { + const run = execution('execution-1'); + const total = OUTPUT_LINE_LIMITS.maxLines + 3; + let text = ''; + for (let i = 0; i < total; i++) text += `line ${i}\n`; + run.write(text); + await mountModal(); + establish(); + await land(run.snapshot()); + + expect(rows()).toHaveLength(OUTPUT_LINE_LIMITS.maxLines); + expect(rows()[0].textContent?.trim()).toBe('line 3'); + expect(rows().at(-1)?.textContent?.trim()).toBe(`line ${total - 1}`); + expect(droppedNotice()).toBe('3 earlier lines not shown'); + // The lines that were dropped were never rendered to HTML. + expect(backend.sanitized).toHaveLength(OUTPUT_LINE_LIMITS.maxLines); + + backend.sanitized.length = 0; + emit(run.write('one more\n')); + await settle(); + // Dropping a line from the front renders none of the others again. + expect(backend.sanitized).toEqual(['one more']); + expect(rows()).toHaveLength(OUTPUT_LINE_LIMITS.maxLines); + expect(rows()[0].textContent?.trim()).toBe('line 4'); + expect(rows().at(-1)?.textContent?.trim()).toBe('one more'); + expect(droppedNotice()).toBe('4 earlier lines not shown'); + }); + + it('shows no count while nothing has been dropped', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + + expect(droppedNotice()).toBeNull(); + }); +}); + +describe('closing', () => { + it('stops listening and lets go of the lines once the dialog has gone', async () => { + const run = execution('execution-1'); + run.write('one\ntwo\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + const held = backend.processors.at(-1)!; + expect(held.lines).toHaveLength(2); + + props.open = false; + await settle(); + await vi.waitFor(() => expect(document.querySelector('.modal-content')).toBeNull()); + await settle(); + + expect(liveOutputListeners()).toHaveLength(0); + expect(liveStatusListeners()).toHaveLength(0); + // The component, still mounted as it is on a branch card, has swapped + // the processor that held the lines for an empty one. + const now = backend.processors.at(-1)!; + expect(now).not.toBe(held); + expect(now.lines).toHaveLength(0); + }); + + it('shows nothing of the last execution when it is opened on another', async () => { + const first = execution('execution-1'); + first.write('from the first\n'); + await mountModal(); + establish(); + await land(first.snapshot()); + + props.open = false; + await settle(); + await vi.waitFor(() => expect(document.querySelector('.modal-content')).toBeNull()); + props.executionId = 'execution-2'; + props.open = true; + await settle(); + + expect(centerState()).toBe('Loading output…'); + expect(rows()).toHaveLength(0); + const second = execution('execution-2'); + second.write('from the second\n'); + establish(); + expect(backend.fetches.map((f) => f.executionId)).toEqual(['execution-2']); + await land(second.snapshot()); + expect(rowTexts()).toEqual(['from the second']); + }); + + it('ignores a snapshot and events that arrive after it closed', async () => { + const run = execution('execution-1'); + run.write('one\n'); + await mountModal(); + establish(); + const stale = backend.fetches.shift()!; + const listener = liveOutputListeners()[0]; + + props.open = false; + await settle(); + stale.land(run.snapshot()); + listener.callback(run.write('two\n')); + await settle(); + + expect(backend.processors.every((processor) => processor.lines.length === 0)).toBe(true); + }); + + it('follows the new execution when Run again swaps it while open', async () => { + const first = execution('execution-1'); + first.write('first run\n'); + await mountModal(); + establish(); + await land(first.snapshot()); + + props.executionId = 'execution-2'; + await settle(); + expect(liveOutputListeners()).toHaveLength(1); + expect(centerState()).toBe('Loading output…'); + + const second = execution('execution-2'); + establish(); + await land(second.snapshot()); + emit(first.write('late, from the first\n')); + emit(second.write('second run\n')); + await settle(); + + expect(rowTexts()).toEqual(['second run']); + }); + + it('saves the lines it holds as a note', async () => { + const run = execution('execution-1'); + run.write('one\ntwo\n'); + await mountModal(); + establish(); + await land(run.snapshot()); + + const save = [...document.querySelectorAll('button')].find((button) => + button.textContent?.includes('Save log') + )!; + save.click(); + await settle(); + + expect(backend.createNote).toHaveBeenCalledWith('branch-1', 'Test log', '```\none\ntwo\n```'); + }); +}); diff --git a/apps/staged/src/lib/features/actions/ActionOutputModal.svelte b/apps/staged/src/lib/features/actions/ActionOutputModal.svelte index 262a11dda..46e219de9 100644 --- a/apps/staged/src/lib/features/actions/ActionOutputModal.svelte +++ b/apps/staged/src/lib/features/actions/ActionOutputModal.svelte @@ -9,10 +9,16 @@ - Real-time output streaming with ANSI color rendering - Status badge (Running/Completed/Failed/Stopped) - Stop button when running - - Automatically fetches buffered output on mount + - Shows the output buffered so far, then follows the live output from + exactly where that ends (see outputFollower) - Auto-scrolls to follow new output - Distinguishes stdout (normal) from stderr (dimmed) + What it holds is bounded: the most recent lines only (see + OUTPUT_LINE_LIMITS), with a count of the earlier ones. It holds nothing + while closed, so the instance a branch card keeps mounted costs nothing + between uses. + Props: executionId — the execution to display output for branchId — the branch saved notes attach to; omit for repo-scoped @@ -21,7 +27,7 @@ onClose — callback to close this modal --> - !v && onClose()}> + !v && onClose()} + onOpenChangeComplete={handleOpenChangeComplete} +> {error} - {:else if displayLines.length === 0} + {:else if unavailable} +
+ Output is no longer available. +
+ {:else if view.lines.length === 0}
No output yet…
{:else}
- {#each displayLines as line} + {#if view.droppedLines > 0} +
+ {droppedLinesLabel(view.droppedLines)} +
+ {/if} + {#each view.lines as line (line.id)}
{@html renderLine(line)}
@@ -659,6 +739,10 @@ color: #9ca3af; } + .output-line.dropped-lines { + font-style: italic; + } + /* The mobile layout (MOBILE_LAYOUT_QUERY, viewport.svelte.ts). Rows span the full-screen dialog and clear its insets (`--dialog-safe-*`, see dialog-content), the header the top one too. */ diff --git a/apps/staged/src/lib/features/actions/actionRunner.svelte.ts b/apps/staged/src/lib/features/actions/actionRunner.svelte.ts index fb4a9eadc..bbf801474 100644 --- a/apps/staged/src/lib/features/actions/actionRunner.svelte.ts +++ b/apps/staged/src/lib/features/actions/actionRunner.svelte.ts @@ -6,11 +6,14 @@ * Owns the configured action list, the live running-execution set (hydrated * via get_running_branch_actions or an injected bulk loader, updated by * action_status and action:run-phase-changed events), stop/fade-out - * bookkeeping, and the output modal state. The execution pipeline treats its - * routing id as an opaque string, so the runner is parameterized by a scope id - * — a branch id, or the synthetic repo scope id from repoActionScopeId() — - * plus loadActions/run callbacks, letting branch cards and repo cards share - * one implementation. + * bookkeeping, and the output modal state. It also frees a finished + * execution's buffered output in the backend once nothing here can show it + * any more: when its pill or pinned-button state goes, or, if the output + * modal is showing it then, when the modal moves on. The execution pipeline + * treats its routing id as an opaque string, so the runner is parameterized + * by a scope id — a branch id, or the synthetic repo scope id from + * repoActionScopeId() — plus loadActions/run callbacks, letting branch cards + * and repo cards share one implementation. */ import { toast } from 'svelte-sonner'; @@ -90,6 +93,12 @@ export class ActionRunner { outputModal = $state(null); + /** + * Finished executions that have left `runningActions` while the output + * modal was showing them. Their output is freed when the modal lets go. + */ + private outputHeldForModal = new Set(); + groupedActions = $derived(groupActionsByType(this.actions)); pinnedActions = $derived(getPinnedActions(this.actions)); pinnedActionIds = $derived(new Set(this.pinnedActions.map((a) => a.id))); @@ -195,9 +204,15 @@ export class ActionRunner { // Remove after animation completes (or immediately for pinned) setTimeout( () => { + const tracked = this.runningActions.some( + (a) => a.executionId === payload.executionId + ); this.runningActions = this.runningActions.filter( (a) => a.executionId !== payload.executionId ); + // The pill was the way to this execution's output. A re-run + // may already have dropped it, and freed the output with it. + if (tracked) this.releaseOutput(payload.executionId); }, isPinnedAction ? 0 : 300 ); // Match CSS transition duration for secondary @@ -278,17 +293,48 @@ export class ActionRunner { } } + /** + * Free the output the backend has buffered for a finished execution that + * this runner no longer lists. The backend keeps it until told otherwise + * (or until enough later executions have finished), and once the execution + * is off the list nothing here can open it again. + * + * The one exception is the output modal: while it is showing the + * execution it may still need the buffer, to recover from lost events, so + * the output is freed when the modal closes or moves to another execution. + */ + private releaseOutput(executionId: string): void { + if (this.outputModal?.executionId === executionId) { + this.outputHeldForModal.add(executionId); + return; + } + clearActionExecution(executionId).catch(() => {}); + } + + /** + * Point the output modal at an execution, or close it, and free the output + * that was being kept only because the modal was showing it. + */ + private setOutputModal(next: ActionOutputModalState | null): void { + this.outputModal = next; + for (const held of [...this.outputHeldForModal]) { + if (held === next?.executionId) continue; + this.outputHeldForModal.delete(held); + clearActionExecution(held).catch(() => {}); + } + } + /** Drop terminal executions of an action and clear their output buffers. */ private clearStaleExecutions(actionId: string): void { const staleExecutions = this.runningActions.filter( (a) => a.actionId === actionId && a.status !== 'running' ); - for (const stale of staleExecutions) { - clearActionExecution(stale.executionId).catch(() => {}); - } this.runningActions = this.runningActions.filter( (a) => !(a.actionId === actionId && a.status !== 'running') ); + for (const stale of staleExecutions) { + this.releaseOutput(stale.executionId); + } } /** @@ -308,24 +354,24 @@ export class ActionRunner { ); if (existingExecution) { - this.outputModal = { + this.setOutputModal({ executionId: existingExecution.executionId, actionId: action.id, actionName: action.name, isStopping: this.stoppingExecutions.has(existingExecution.executionId), - }; + }); return; } try { const executionId = await this.run(action.id); if (keepModal) { - this.outputModal = { + this.setOutputModal({ executionId, actionId: action.id, actionName: action.name, isStopping: false, - }; + }); } } catch (e) { console.error('Failed to run action:', e); @@ -357,12 +403,12 @@ export class ActionRunner { } showOutput(execution: RunningAction): void { - this.outputModal = { + this.setOutputModal({ executionId: execution.executionId, actionId: execution.actionId, actionName: execution.actionName, isStopping: this.stoppingExecutions.has(execution.executionId), - }; + }); } /** Re-run the output modal's action, keeping the modal open on the new execution. */ @@ -373,6 +419,6 @@ export class ActionRunner { } closeOutputModal(): void { - this.outputModal = null; + this.setOutputModal(null); } } diff --git a/apps/staged/src/lib/features/actions/actionRunner.test.ts b/apps/staged/src/lib/features/actions/actionRunner.test.ts index 9c733d726..ab00a6a11 100644 --- a/apps/staged/src/lib/features/actions/actionRunner.test.ts +++ b/apps/staged/src/lib/features/actions/actionRunner.test.ts @@ -3,6 +3,9 @@ import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; describe('ActionRunner', () => { let getRunningBranchActions: ReturnType; let getRunPhase: ReturnType; + let clearActionExecution: ReturnType; + /** The runner's action_status handler, once it has subscribed. */ + let emitStatus: (payload: Record) => void; beforeEach(() => { vi.resetModules(); @@ -13,21 +16,29 @@ describe('ActionRunner', () => { getRunningBranchActions = vi.fn(); getRunPhase = vi.fn(); + clearActionExecution = vi.fn().mockResolvedValue(true); + emitStatus = () => { + throw new Error('the runner has not subscribed'); + }; vi.doMock('./actions', () => ({ ACTION_TYPES: ['run', 'prerun', 'build', 'test', 'format', 'check', 'cleanUp'], getRunningBranchActions, getRunPhase, stopBranchAction: vi.fn(), - clearActionExecution: vi.fn(), + clearActionExecution, })); vi.doMock('../../services/branchEventService', () => ({ - onBranchActionStatus: vi.fn(() => () => {}), + onBranchActionStatus: vi.fn((_scopeId: string, handler: typeof emitStatus) => { + emitStatus = handler; + return () => {}; + }), onBranchRunPhaseChanged: vi.fn(() => () => {}), })); vi.doMock('svelte-sonner', () => ({ toast: { error: vi.fn() } })); }); afterEach(() => { + vi.useRealTimers(); vi.unstubAllGlobals(); vi.doUnmock('./actions'); vi.doUnmock('../../services/branchEventService'); @@ -197,4 +208,199 @@ describe('ActionRunner', () => { isStopping: false, }); }); + + describe('buffered output of finished executions', () => { + /** How long a finished pill stays, fade included. */ + const COMPLETED_PILL_MS = 2000 + 300; + const FAILED_PILL_MS = 3000 + 300; + + function status(executionId: string, value: string, actionId = `action-${executionId}`) { + return { + executionId, + branchId: 'repo:block/goose', + actionId, + actionName: executionId, + actionType: 'test', + status: value, + exitCode: value === 'completed' ? 0 : value === 'failed' ? 1 : undefined, + startedAt: 1, + completedAt: value === 'running' ? undefined : 2, + }; + } + + /** A subscribed runner that has seen `executionId` start. */ + async function runnerWithRunning(executionId: string, opts: Record = {}) { + vi.useFakeTimers(); + const runner = await newRunner(opts); + runner.subscribe(); + emitStatus(status(executionId, 'running')); + return runner; + } + + it('frees the output when the pill is dropped, and not before', async () => { + const runner = await runnerWithRunning('execution-1'); + + emitStatus(status('execution-1', 'completed')); + vi.advanceTimersByTime(COMPLETED_PILL_MS - 1); + // The pill is still there to be clicked, so the output must be too. + expect(runner.runningActions).toHaveLength(1); + expect(clearActionExecution).not.toHaveBeenCalled(); + + vi.advanceTimersByTime(1); + expect(runner.runningActions).toHaveLength(0); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + expect(clearActionExecution).toHaveBeenCalledWith('execution-1'); + }); + + it('frees the output of failed and stopped executions on their longer schedule', async () => { + const runner = await runnerWithRunning('execution-failed'); + emitStatus(status('execution-stopped', 'running')); + + emitStatus(status('execution-failed', 'failed')); + emitStatus(status('execution-stopped', 'stopped')); + vi.advanceTimersByTime(FAILED_PILL_MS - 1); + expect(clearActionExecution).not.toHaveBeenCalled(); + + vi.advanceTimersByTime(1); + expect(runner.runningActions).toHaveLength(0); + expect(clearActionExecution.mock.calls.map(([id]) => id).sort()).toEqual([ + 'execution-failed', + 'execution-stopped', + ]); + }); + + it('leaves the output of a running execution alone', async () => { + const runner = await runnerWithRunning('execution-1'); + runner.showOutput(runner.runningActions[0]); + runner.closeOutputModal(); + vi.advanceTimersByTime(60_000); + + expect(runner.runningActions).toHaveLength(1); + expect(clearActionExecution).not.toHaveBeenCalled(); + }); + + it('ignores the end of an execution it never listed', async () => { + await runnerWithRunning('execution-1'); + emitStatus(status('execution-unknown', 'completed')); + vi.advanceTimersByTime(60_000); + + expect(clearActionExecution).not.toHaveBeenCalled(); + }); + + it('keeps the output while the modal is showing it, and frees it on close', async () => { + const runner = await runnerWithRunning('execution-1'); + runner.showOutput(runner.runningActions[0]); + + emitStatus(status('execution-1', 'completed')); + vi.advanceTimersByTime(COMPLETED_PILL_MS + 60_000); + // The pill has gone, but the modal is still on this execution. + expect(runner.runningActions).toHaveLength(0); + expect(clearActionExecution).not.toHaveBeenCalled(); + + runner.closeOutputModal(); + expect(runner.outputModal).toBeNull(); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + expect(clearActionExecution).toHaveBeenCalledWith('execution-1'); + }); + + it("keeps the output when the modal opens in the pill's last moments", async () => { + const runner = await runnerWithRunning('execution-1'); + + emitStatus(status('execution-1', 'completed')); + vi.advanceTimersByTime(COMPLETED_PILL_MS - 1); + runner.showOutput(runner.runningActions[0]); + vi.advanceTimersByTime(1); + + expect(runner.runningActions).toHaveLength(0); + expect(clearActionExecution).not.toHaveBeenCalled(); + runner.closeOutputModal(); + expect(clearActionExecution).toHaveBeenCalledWith('execution-1'); + }); + + it('frees the output when the modal moves on to another execution', async () => { + const runner = await runnerWithRunning('execution-1'); + emitStatus(status('execution-2', 'running')); + runner.showOutput(runner.runningActions[0]); + + emitStatus(status('execution-1', 'completed')); + vi.advanceTimersByTime(COMPLETED_PILL_MS); + expect(clearActionExecution).not.toHaveBeenCalled(); + + runner.showOutput(runner.runningActions[0]); + expect(runner.outputModal?.executionId).toBe('execution-2'); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + expect(clearActionExecution).toHaveBeenCalledWith('execution-1'); + + // Closing the modal on the other, running, execution frees nothing more. + runner.closeOutputModal(); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + }); + + it('does not free the output again when the modal is closed a second time', async () => { + const runner = await runnerWithRunning('execution-1'); + runner.showOutput(runner.runningActions[0]); + emitStatus(status('execution-1', 'completed')); + vi.advanceTimersByTime(COMPLETED_PILL_MS); + + runner.closeOutputModal(); + runner.closeOutputModal(); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + }); + + it('frees a finished run once when its action is run again before the pill goes', async () => { + const action = { id: 'action-1', name: 'Test' }; + const run = vi.fn().mockResolvedValue('execution-2'); + const runner = await runnerWithRunning('execution-1', { run }); + emitStatus(status('execution-1', 'completed', 'action-1')); + // The first run started under its own action id; give it this one. + runner.runningActions[0].actionId = 'action-1'; + + await runner.runAction(action as never); + expect(runner.runningActions).toHaveLength(0); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + expect(clearActionExecution).toHaveBeenCalledWith('execution-1'); + + // The first run's pill timers still fire, with nothing left to do. + vi.advanceTimersByTime(FAILED_PILL_MS); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + }); + + it('keeps a finished run the modal is showing until Run Again has replaced it', async () => { + const action = { id: 'action-1', name: 'Test' }; + let started: (executionId: string) => void = () => {}; + const run = vi.fn(() => new Promise((resolve) => void (started = resolve))); + const runner = await runnerWithRunning('execution-1', { + loadActions: async () => [action], + run, + }); + await runner.loadActions(); + runner.runningActions[0].actionId = 'action-1'; + runner.showOutput(runner.runningActions[0]); + emitStatus(status('execution-1', 'failed', 'action-1')); + + // Run Again drops the finished run from the list while the modal is + // still showing its output, which is kept until the new run is up. + const rerun = runner.runAgain(); + expect(runner.runningActions).toHaveLength(0); + expect(clearActionExecution).not.toHaveBeenCalled(); + + started('execution-2'); + await rerun; + expect(runner.outputModal?.executionId).toBe('execution-2'); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + expect(clearActionExecution).toHaveBeenCalledWith('execution-1'); + }); + + it('survives a clear that fails', async () => { + clearActionExecution.mockRejectedValue(new Error('IPC unavailable')); + const runner = await runnerWithRunning('execution-1'); + + emitStatus(status('execution-1', 'completed')); + vi.advanceTimersByTime(COMPLETED_PILL_MS); + await vi.runAllTimersAsync(); + + expect(runner.runningActions).toHaveLength(0); + expect(clearActionExecution).toHaveBeenCalledTimes(1); + }); + }); }); diff --git a/apps/staged/src/lib/features/actions/actions.ts b/apps/staged/src/lib/features/actions/actions.ts index e4ff593a5..0f5376d5e 100644 --- a/apps/staged/src/lib/features/actions/actions.ts +++ b/apps/staged/src/lib/features/actions/actions.ts @@ -6,7 +6,7 @@ * that can be run in branch worktrees with real-time output streaming. */ -import { invokeCommand, listenToEvent, type UnlistenFn } from '../../transport'; +import { invokeCommand, listenToEvent, type ListenOptions, type UnlistenFn } from '../../transport'; /** Action types available for project actions, in the order shown in the UI. */ export const ACTION_TYPES = [ @@ -70,11 +70,30 @@ export interface OutputChunk { timestamp: number; } +/** + * The output an execution has buffered: the most recent of it, and where it + * ends in the execution's whole output, in bytes of UTF-8. + */ +export interface BufferedOutput { + /** + * Oldest first. Once the backend has dropped earlier output, the first + * chunk is its notice saying how much. + */ + chunks: OutputChunk[]; + /** + * Compared with `ActionOutputEvent.offset`: an event that starts before + * this is already in `chunks`, and the next one starts exactly here. + */ + endOffset: number; +} + /** Event payload for action output. */ export interface ActionOutputEvent { executionId: string; chunk: string; stream: 'stdout' | 'stderr'; + /** Where `chunk` starts in the execution's output, in bytes of UTF-8. */ + offset: number; } /** Event payload for action status changes. */ @@ -199,11 +218,15 @@ export function getRunningBranchActions(branchId: string): Promise { - return invokeCommand('get_action_output_buffer', { executionId }); +export function getActionOutputBuffer(executionId: string): Promise { + return invokeCommand('get_action_output_buffer', { executionId }); } /** @@ -225,9 +248,16 @@ export function runPrerunActions(branchId: string, provider?: string): Promise void): UnlistenFn { - return listenToEvent('action_output', callback); +export function listenToActionOutput( + callback: (event: ActionOutputEvent) => void, + opts?: ListenOptions +): UnlistenFn { + return listenToEvent('action_output', callback, opts); } /** diff --git a/apps/staged/src/lib/features/actions/outputFollower.test.ts b/apps/staged/src/lib/features/actions/outputFollower.test.ts new file mode 100644 index 000000000..0cb6448b4 --- /dev/null +++ b/apps/staged/src/lib/features/actions/outputFollower.test.ts @@ -0,0 +1,458 @@ +import { describe, expect, it, vi } from 'vitest'; +import type { BufferedOutput, OutputChunk } from './actions'; +import { + MAX_HELD_CHARS, + createOutputFollower, + utf8Length, + type OutputEvent, + type OutputFollower, +} from './outputFollower'; + +/** Let pending promise callbacks run. */ +async function settle(): Promise { + for (let i = 0; i < 5; i++) await Promise.resolve(); +} + +function stdout(text: string): OutputChunk { + return { chunk: text, stream: 'stdout', timestamp: 0 }; +} + +/** + * A stand-in for the backend's buffer and event stream, with the properties + * the follower relies on: output is appended to the buffer before it is + * emitted, every event says where its chunk starts, and a snapshot says where + * it ends. + */ +function backend() { + let text = ''; + let bytes = 0; + return { + get text() { + return text; + }, + /** Append `chunk` to the buffer and return the event that announces it. */ + write(chunk: string): OutputEvent { + const event: OutputEvent = { chunk, stream: 'stdout', offset: bytes }; + text += chunk; + bytes += utf8Length(chunk); + return event; + }, + snapshot(): BufferedOutput { + return { chunks: text ? [stdout(text)] : [], endOffset: bytes }; + }, + }; +} + +/** A follower whose snapshots land when the test says, and what it has shown. */ +function harness() { + const pending: { + resolve: (snapshot: BufferedOutput | null) => void; + reject: (error: unknown) => void; + }[] = []; + const view = { + text: '', + /** How many snapshots replaced the view. */ + snapshots: 0, + /** How many live chunks were appended. */ + appended: 0, + unavailable: 0, + errors: [] as unknown[], + }; + const follower: OutputFollower = createOutputFollower({ + fetchSnapshot: () => new Promise((resolve, reject) => void pending.push({ resolve, reject })), + onSnapshot: (chunks) => { + view.text = chunks.map((c) => c.chunk).join(''); + view.snapshots++; + }, + onOutput: (output) => { + view.text += output.chunk; + view.appended++; + }, + onUnavailable: () => void view.unavailable++, + onError: (error) => void view.errors.push(error), + }); + return { + follower, + view, + /** Snapshots requested and not yet landed. */ + get inFlight() { + return pending.length; + }, + /** Land the oldest snapshot in flight. */ + async land(snapshot: BufferedOutput | null) { + pending.shift()!.resolve(snapshot); + await settle(); + }, + async fail(error: unknown) { + pending.shift()!.reject(error); + await settle(); + }, + }; +} + +describe('utf8Length', () => { + it('counts bytes the way the backend does', () => { + const encoder = new TextEncoder(); + for (const text of [ + '', + 'plain ascii\r\n', + 'café', + '€ three bytes', + '😀 four bytes, two units', + 'mixed: aé€😀\u{10FFFF}߿ࠀ￿', + '\x1b[32m✓\x1b[0m done', + ]) { + expect(utf8Length(text), JSON.stringify(text)).toBe(encoder.encode(text).length); + } + }); + + it('counts an unpaired surrogate as the replacement character it encodes to', () => { + expect(utf8Length('a\ud800b')).toBe(new TextEncoder().encode('a\ud800b').length); + expect(utf8Length('\udc00')).toBe(3); + expect(utf8Length('\ud83d')).toBe(3); + }); +}); + +describe('createOutputFollower', () => { + it('shows the snapshot, then the events that continue it', async () => { + const be = backend(); + const { follower, view, land } = harness(); + be.write('one\n'); + + follower.sync(); + await land(be.snapshot()); + expect(view.text).toBe('one\n'); + + follower.handleEvent(be.write('two\n')); + follower.handleEvent(be.write('thrée\n')); + follower.handleEvent(be.write('four\n')); + expect(view.text).toBe('one\ntwo\nthrée\nfour\n'); + expect(view).toMatchObject({ snapshots: 1, appended: 3 }); + }); + + it('skips events the snapshot already holds, whichever side of it they arrive on', async () => { + const be = backend(); + const { follower, view, land } = harness(); + be.write('before the listener\n'); + + follower.sync(); + // Both of these are written before the snapshot is taken, so it holds + // them. One is delivered ahead of it... + const early = be.write('early\n'); + follower.handleEvent(early); + // ...and the other only after it has landed. + const late = be.write('late\n'); + const snapshot = be.snapshot(); + + // Written after the snapshot was taken, delivered before it lands. + const after = be.write('after\n'); + follower.handleEvent(after); + + await land(snapshot); + expect(view.text).toBe('before the listener\nearly\nlate\nafter\n'); + + follower.handleEvent(late); + follower.handleEvent(be.write('live\n')); + expect(view.text).toBe(be.text); + expect(view).toMatchObject({ snapshots: 1, appended: 2 }); + }); + + it('does not repeat or lose identical chunks at the boundary', async () => { + // A progress bar redraws the same text over and over, so the text alone + // cannot say which redraws the snapshot holds. The offsets do. + const be = backend(); + const { follower, view, land } = harness(); + const frame = '\rdownloading 50%'; + + follower.sync(); + const first = be.write(frame); + const second = be.write(frame); + const snapshot = be.snapshot(); + const third = be.write(frame); + const fourth = be.write(frame); + for (const event of [first, second, third]) follower.handleEvent(event); + + await land(snapshot); + follower.handleEvent(fourth); + + expect(view.text).toBe(frame.repeat(4)); + expect(view).toMatchObject({ snapshots: 1, appended: 2 }); + }); + + it('ignores events until it is asked to sync', async () => { + const be = backend(); + const { follower, view, land, inFlight } = harness(); + + follower.handleEvent(be.write('too early\n')); + expect(view.text).toBe(''); + expect(inFlight).toBe(0); + + follower.sync(); + await land(be.snapshot()); + expect(view.text).toBe('too early\n'); + }); + + it('takes a new snapshot when an event does not continue what is shown', async () => { + const be = backend(); + const h = harness(); + h.follower.sync(); + await h.land(be.snapshot()); + h.follower.handleEvent(be.write('one\n')); + + // Two events never arrive. + be.write('lost\n'); + be.write('also lost\n'); + h.follower.handleEvent(be.write('four\n')); + // Nothing is shown out of place meanwhile. + expect(h.view.text).toBe('one\n'); + expect(h.inFlight).toBe(1); + + // More arrives while the snapshot is on its way. + const snapshot = be.snapshot(); + h.follower.handleEvent(be.write('five\n')); + await h.land(snapshot); + + expect(h.view.text).toBe('one\nlost\nalso lost\nfour\nfive\n'); + expect(h.view).toMatchObject({ snapshots: 2, appended: 2 }); + + h.follower.handleEvent(be.write('six\n')); + expect(h.view.text).toBe(be.text); + expect(h.inFlight).toBe(0); + }); + + it('takes a new snapshot when an event overlaps the end of what is shown', async () => { + const h = harness(); + h.follower.sync(); + await h.land({ chunks: [stdout('abcd')], endOffset: 4 }); + + // The backend never emits this; whatever did, the view must not guess. + h.follower.handleEvent({ chunk: 'cdef', stream: 'stdout', offset: 2 }); + expect(h.view.text).toBe('abcd'); + expect(h.inFlight).toBe(1); + + await h.land({ chunks: [stdout('abcdef')], endOffset: 6 }); + expect(h.view.text).toBe('abcdef'); + }); + + it('retakes a snapshot that a second sync may have outdated', async () => { + const be = backend(); + const h = harness(); + be.write('one\n'); + + h.follower.sync(); + const stale = be.snapshot(); + // The stream reconnects: output written while it was down is in no event. + be.write('written while disconnected\n'); + h.follower.sync(); + expect(h.inFlight).toBe(1); + + await h.land(stale); + // The first snapshot is not shown; a second is on its way instead. + expect(h.view.snapshots).toBe(0); + expect(h.inFlight).toBe(1); + + await h.land(be.snapshot()); + expect(h.view.text).toBe('one\nwritten while disconnected\n'); + expect(h.view.snapshots).toBe(1); + }); + + it('leaves the view alone when a later snapshot holds nothing new', async () => { + const be = backend(); + const h = harness(); + h.follower.sync(); + await h.land(be.snapshot()); + h.follower.handleEvent(be.write('one\n')); + h.follower.handleEvent(be.write('two\n')); + + // A reconnect during which nothing was written. + h.follower.sync(); + await h.land(be.snapshot()); + + expect(h.view).toMatchObject({ text: 'one\ntwo\n', snapshots: 1, appended: 2 }); + h.follower.handleEvent(be.write('three\n')); + expect(h.view.text).toBe(be.text); + }); + + it('reports output that is no longer available, once, and stops following', async () => { + const h = harness(); + h.follower.sync(); + h.follower.handleEvent({ chunk: 'stray', stream: 'stdout', offset: 0 }); + await h.land(null); + + expect(h.view).toMatchObject({ text: '', unavailable: 1, snapshots: 0 }); + + h.follower.handleEvent({ chunk: 'stray', stream: 'stdout', offset: 5 }); + h.follower.sync(); + expect(h.inFlight).toBe(0); + expect(h.view.text).toBe(''); + }); + + it('keeps what is shown when the output is cleared afterwards', async () => { + const be = backend(); + const h = harness(); + be.write('all of it\n'); + h.follower.sync(); + await h.land(be.snapshot()); + + // A reconnect after the finished execution's buffer was cleared. + h.follower.sync(); + await h.land(null); + + expect(h.view).toMatchObject({ text: 'all of it\n', unavailable: 0 }); + }); + + it('reports a snapshot that fails, and recovers on the next sync', async () => { + const be = backend(); + const h = harness(); + be.write('one\n'); + + h.follower.sync(); + h.follower.handleEvent(be.write('two\n')); + await h.fail(new Error('IPC unavailable')); + expect(h.view.errors).toHaveLength(1); + expect(h.view.text).toBe(''); + + // Events have nothing to continue until a snapshot is shown. + h.follower.handleEvent(be.write('three\n')); + expect(h.view.text).toBe(''); + expect(h.inFlight).toBe(0); + + h.follower.sync(); + await h.land(be.snapshot()); + expect(h.view.text).toBe('one\ntwo\nthree\n'); + }); + + it('retries after a failed resync when the next event does not fit', async () => { + const be = backend(); + const h = harness(); + h.follower.sync(); + await h.land(be.snapshot()); + h.follower.handleEvent(be.write('one\n')); + + be.write('lost\n'); + h.follower.handleEvent(be.write('three\n')); + await h.fail(new Error('IPC unavailable')); + expect(h.view).toMatchObject({ text: 'one\n' }); + expect(h.view.errors).toHaveLength(1); + + h.follower.handleEvent(be.write('four\n')); + await h.land(be.snapshot()); + expect(h.view.text).toBe('one\nlost\nthree\nfour\n'); + }); + + it('gives up on held events past the limit and takes a newer snapshot', async () => { + const be = backend(); + const h = harness(); + h.follower.sync(); + const stale = be.snapshot(); + + const big = 'x'.repeat(MAX_HELD_CHARS / 4); + for (let n = 0; n < 5; n++) h.follower.handleEvent(be.write(big)); + h.follower.handleEvent(be.write('tail\n')); + + await h.land(stale); + // The dropped events followed that snapshot, so it is not shown. + expect(h.view.snapshots).toBe(0); + expect(h.inFlight).toBe(1); + + await h.land(be.snapshot()); + expect(h.view.text.length).toBe(be.text.length); + expect(h.view.text.endsWith('tail\n')).toBe(true); + expect(h.view).toMatchObject({ snapshots: 1, appended: 0 }); + }); + + it('does nothing once stopped', async () => { + const be = backend(); + const h = harness(); + h.follower.sync(); + await h.land(be.snapshot()); + h.follower.handleEvent(be.write('one\n')); + + h.follower.sync(); + h.follower.stop(); + be.write('two\n'); + await h.land(be.snapshot()); + h.follower.handleEvent(be.write('three\n')); + h.follower.sync(); + + expect(h.view).toMatchObject({ text: 'one\n', snapshots: 1, appended: 1 }); + expect(h.inFlight).toBe(0); + }); + + it('shows exactly the output written, whatever order things arrive in', async () => { + // A fixed pseudo-random sequence, so a failure reproduces. + let seed = 0x51ed27; + const random = (below: number) => { + seed = (seed * 1103515245 + 12345) & 0x7fffffff; + return seed % below; + }; + const pieces = ['.', '\rframe', 'line\n', 'é', '€uro\n', '😀', '\r\n', 'same', 'same']; + + for (let round = 0; round < 400; round++) { + const be = backend(); + const fetchSnapshot = vi.fn<() => Promise>(); + let shown = ''; + const follower = createOutputFollower({ + fetchSnapshot, + onSnapshot: (chunks) => void (shown = chunks.map((c) => c.chunk).join('')), + onOutput: (output) => void (shown += output.chunk), + onUnavailable: () => { + throw new Error('unexpected: unavailable'); + }, + onError: (error) => { + throw error; + }, + }); + // Snapshots are taken when requested and land some steps later. + const landing: { at: number; land: () => void }[] = []; + let step = 0; + fetchSnapshot.mockImplementation(() => { + const snapshot = be.snapshot(); + return new Promise((resolve) => { + landing.push({ at: step + random(4), land: () => resolve(snapshot) }); + }); + }); + + /** Events emitted but not yet delivered, in order. */ + let inTransit: OutputEvent[] = []; + let listening = false; + const steps = 20 + random(40); + const listenAt = random(10); + for (step = 0; step < steps; step++) { + // The backend writes; what it writes before the listener is live + // reaches nobody. + for (let n = random(3); n > 0; n--) { + const event = be.write(pieces[random(pieces.length)]); + if (listening) inTransit.push(event); + } + if (!listening && step >= listenAt) { + listening = true; + follower.sync(); + } + // Now and then the stream drops what is in transit, and says so. + if (listening && random(12) === 0) { + inTransit = []; + follower.sync(); + } + // Some of what is in transit is delivered, in order. + for (let n = random(inTransit.length + 1); n > 0; n--) { + follower.handleEvent(inTransit.shift()!); + } + for (const due of landing.filter((l) => l.at <= step)) { + landing.splice(landing.indexOf(due), 1); + due.land(); + } + await settle(); + } + // Everything in flight arrives. + for (let guard = 0; landing.length > 0 || inTransit.length > 0; guard++) { + if (guard > 100) throw new Error('did not settle'); + for (const event of inTransit.splice(0)) follower.handleEvent(event); + for (const due of landing.splice(0)) due.land(); + await settle(); + } + + expect(shown, `round ${round}`).toBe(be.text); + } + }); +}); diff --git a/apps/staged/src/lib/features/actions/outputFollower.ts b/apps/staged/src/lib/features/actions/outputFollower.ts new file mode 100644 index 000000000..1bdb2e206 --- /dev/null +++ b/apps/staged/src/lib/features/actions/outputFollower.ts @@ -0,0 +1,217 @@ +/** + * Joins an execution's buffered output to its live output. + * + * A view of an action's output has two sources: `get_action_output_buffer`, + * a snapshot of what the backend has retained, and `action_output` events, + * which carry what is written from then on. Neither says by itself where the + * other stops, and the two travel separately, so an event can arrive on + * either side of a snapshot that already holds its text. + * + * Both are positioned in the same stream of bytes. An event says where its + * chunk starts (`offset`); a snapshot says where it ends (`endOffset`). The + * backend appends a batch of output to its buffer before it emits it, and + * appends it whole, so a snapshot always ends on the boundary between two + * events. The follower shows a snapshot and then exactly the events that + * continue it: + * + * - an event that ends at or before the end of what is shown is already + * there, and is skipped; + * - an event that starts where what is shown ends is shown; + * - anything else means output was missed (a dropped event, a reconnect), + * and the follower takes a new snapshot rather than show output with a + * hole in it. + * + * The caller starts listening first and calls `sync()` once the listener is + * live, and again whenever the event stream says it may have dropped + * something. Output written before the listener went live is then in the + * snapshot, and output written after it arrives as events. + */ + +import type { ActionOutputEvent, BufferedOutput, OutputChunk } from './actions'; + +/** Output text and the stream it was written to. */ +export type OutputText = Pick; + +/** What the follower needs of an `action_output` event. */ +export type OutputEvent = Pick; + +export interface OutputFollowerOptions { + /** Take a snapshot of the buffered output. Null when there is none. */ + fetchSnapshot: () => Promise; + /** Show `chunks` in place of everything shown so far. */ + onSnapshot: (chunks: OutputChunk[]) => void; + /** Show `output` after everything shown so far. */ + onOutput: (output: OutputText) => void; + /** + * There is no output to show: the first snapshot found none buffered, + * because the execution is unknown or its output has been cleared. + */ + onUnavailable: () => void; + /** A snapshot could not be taken. What is shown, if anything, stays. */ + onError: (error: unknown) => void; +} + +export interface OutputFollower { + /** + * Take a snapshot and continue from it. Call once the event listener is + * live, and again whenever events may have been lost. + */ + sync(): void; + /** Feed an `action_output` event of the execution being followed. */ + handleEvent(event: OutputEvent): void; + /** Stop: nothing is shown or fetched after this. */ + stop(): void; +} + +/** + * Most text held back while a snapshot is in flight. Past this the held + * events are dropped and another snapshot is taken instead, which is both + * smaller (the backend retains 4 MiB) and certain to include them. + */ +export const MAX_HELD_CHARS = 4 * 1024 * 1024; + +/** The number of bytes `text` takes as UTF-8, which is what offsets count. */ +export function utf8Length(text: string): number { + // One byte per UTF-16 unit, plus what the wider characters add. + let bytes = text.length; + for (let i = 0; i < text.length; i++) { + const code = text.charCodeAt(i); + if (code < 0x80) continue; + if (code < 0x800) { + bytes += 1; + } else if (code >= 0xd800 && code <= 0xdbff && isLowSurrogate(text.charCodeAt(i + 1))) { + // A surrogate pair: two units, four bytes. + bytes += 2; + i++; + } else { + bytes += 2; + } + } + return bytes; +} + +function isLowSurrogate(code: number): boolean { + return code >= 0xdc00 && code <= 0xdfff; +} + +export function createOutputFollower(opts: OutputFollowerOptions): OutputFollower { + /** + * Where what is shown ends, and so where the next chunk to show must + * start. Null until a snapshot has been shown. + */ + let shownEnd: number | null = null; + let fetching = false; + /** Another snapshot is wanted once the one in flight has landed. */ + let fetchAgain = false; + /** Events that arrived while a snapshot was in flight, in order. */ + let held: OutputEvent[] = []; + let heldChars = 0; + /** The output is gone from the backend: there is nothing left to follow. */ + let detached = false; + let stopped = false; + + function dropHeld(): void { + held = []; + heldChars = 0; + } + + function hold(event: OutputEvent): void { + held.push(event); + heldChars += event.chunk.length; + if (heldChars > MAX_HELD_CHARS) { + // Some of these may follow the snapshot in flight, so it cannot be + // trusted to cover them. A later one will. + dropHeld(); + fetchAgain = true; + } + } + + function sync(): void { + if (stopped || detached) return; + if (fetching) { + // The snapshot in flight may have been taken before whatever prompted + // this call. + fetchAgain = true; + return; + } + fetching = true; + void takeSnapshot(); + } + + async function takeSnapshot(): Promise { + let snapshot: BufferedOutput | null = null; + let failure: { error: unknown } | null = null; + try { + snapshot = await opts.fetchSnapshot(); + } catch (error) { + failure = { error }; + } + if (stopped) return; + fetching = false; + + if (fetchAgain) { + // Not shown: it may predate lost output, and its successor replaces it. + // The held events stay; those the next snapshot covers are skipped. + fetchAgain = false; + sync(); + return; + } + + if (failure) { + // Without a snapshot the held events have nothing to continue. The + // next sync, or the next event that does not fit, tries again. + dropHeld(); + opts.onError(failure.error); + return; + } + + if (snapshot === null) { + dropHeld(); + detached = true; + if (shownEnd === null) opts.onUnavailable(); + return; + } + + // A snapshot that ends where the view already does holds nothing new, so + // the view is left as it is instead of being rebuilt. + if (shownEnd === null || snapshot.endOffset > shownEnd) { + opts.onSnapshot(snapshot.chunks); + shownEnd = snapshot.endOffset; + } + + const events = held; + dropHeld(); + for (const event of events) handleEvent(event); + } + + function handleEvent(event: OutputEvent): void { + if (stopped || detached) return; + if (fetching) { + hold(event); + return; + } + // Nothing shown and no snapshot on its way: the event has nothing to + // continue, and the snapshot that is eventually taken will hold it. + if (shownEnd === null) return; + + const end = event.offset + utf8Length(event.chunk); + if (end <= shownEnd) return; + if (event.offset !== shownEnd) { + // Output between what is shown and this event never arrived. The + // snapshot will hold it, and this event too. + sync(); + return; + } + opts.onOutput(event); + shownEnd = end; + } + + return { + sync, + handleEvent, + stop() { + stopped = true; + dropHeld(); + }, + }; +} diff --git a/apps/staged/src/lib/features/actions/processOutput.test.ts b/apps/staged/src/lib/features/actions/processOutput.test.ts index 809342ea7..e21f66958 100644 --- a/apps/staged/src/lib/features/actions/processOutput.test.ts +++ b/apps/staged/src/lib/features/actions/processOutput.test.ts @@ -1,5 +1,11 @@ import { describe, it, expect } from 'vitest'; -import { processChunksToLines, createIncrementalProcessor } from './processOutput'; +import { + LINE_CUT_MARK, + OUTPUT_LINE_LIMITS, + createIncrementalProcessor, + processChunksToLines, + type LineLimits, +} from './processOutput'; import type { OutputChunk } from './actions'; /** Helper to build an OutputChunk. */ @@ -121,20 +127,25 @@ describe('processChunksToLines', () => { // --------------------------------------------------------------------------- describe('createIncrementalProcessor', () => { - /** Helper: feed chunks one-at-a-time and return the final snapshot. */ + /** Helper: feed chunks one-at-a-time and return the final lines. */ function feedOneByOne(chunks: OutputChunk[]): string[] { const proc = createIncrementalProcessor(); - let result: ReturnType = []; for (const c of chunks) { - result = proc.process([c]); + proc.process([c]); } - return result.map((l) => l.text); + return proc.lines.map((l) => l.text); } /** Helper: feed all chunks at once. */ function feedAll(chunks: OutputChunk[]): string[] { const proc = createIncrementalProcessor(); - return proc.process(chunks).map((l) => l.text); + proc.process(chunks); + return proc.lines.map((l) => l.text); + } + + /** Limits that only the named ones can reach. */ + function limits(overrides: Partial): LineLimits { + return { maxLines: 1_000_000, maxChars: 1_000_000_000, maxLineChars: 1_000_000, ...overrides }; } // --------------------------------------------------------------------------- @@ -159,9 +170,43 @@ describe('createIncrementalProcessor', () => { it('matches batch output for interleaved stdout/stderr', () => { const chunks = [chunk('out\n', 'stdout'), chunk('err\n', 'stderr')]; const proc = createIncrementalProcessor(); - let result = proc.process([chunks[0]]); - result = proc.process([chunks[1]]); - expect(result.map((l) => l.stream)).toEqual(['stdout', 'stderr']); + proc.process([chunks[0]]); + proc.process([chunks[1]]); + expect(proc.lines.map((l) => l.stream)).toEqual(['stdout', 'stderr']); + }); + + it('matches batch output however the output is cut into chunks and calls', () => { + // A fixed pseudo-random sequence, so a failure reproduces. + let seed = 0x2f6e2b1; + const random = (below: number) => { + seed = (seed * 1103515245 + 12345) & 0x7fffffff; + return seed % below; + }; + const pieces = ['a', 'bc', '\n', '\r', '\r\n', '\n\n', '\r\r', 'x\ry', ' 50%', '\rdone', '']; + + for (let round = 0; round < 300; round++) { + const chunks: OutputChunk[] = []; + for (let n = random(12); n >= 0; n--) { + let text = ''; + for (let m = random(5); m >= 0; m--) text += pieces[random(pieces.length)]; + chunks.push(chunk(text, random(4) === 0 ? 'stderr' : 'stdout')); + } + + // The batch function resolves a trailing \r as an overwrite; the + // incremental one keeps the line until more output decides, so the + // comparison ends on a line break. + chunks.push(chunk('\n')); + const expected = processChunksToLines(chunks); + + const proc = createIncrementalProcessor(); + for (let at = 0; at < chunks.length;) { + const take = 1 + random(3); + proc.process(chunks.slice(at, at + take)); + at += take; + } + const actual = proc.lines.map(({ text, stream }) => ({ text, stream })); + expect(actual, JSON.stringify(chunks)).toEqual(expected); + } }); // --------------------------------------------------------------------------- @@ -171,16 +216,16 @@ describe('createIncrementalProcessor', () => { it('accumulates lines across multiple process() calls', () => { const proc = createIncrementalProcessor(); proc.process([chunk('line1\n')]); - const result = proc.process([chunk('line2\n')]); - expect(result.map((l) => l.text)).toEqual(['line1', 'line2']); + proc.process([chunk('line2\n')]); + expect(proc.lines.map((l) => l.text)).toEqual(['line1', 'line2']); }); it('shows in-progress line until finalized', () => { const proc = createIncrementalProcessor(); - let result = proc.process([chunk('partial')]); - expect(result.map((l) => l.text)).toEqual(['partial']); - result = proc.process([chunk(' more\n')]); - expect(result.map((l) => l.text)).toEqual(['partial more']); + proc.process([chunk('partial')]); + expect(proc.lines.map((l) => l.text)).toEqual(['partial']); + proc.process([chunk(' more\n')]); + expect(proc.lines.map((l) => l.text)).toEqual(['partial more']); }); // --------------------------------------------------------------------------- @@ -190,28 +235,22 @@ describe('createIncrementalProcessor', () => { it('preserves line text when \\r\\n is split across calls', () => { const proc = createIncrementalProcessor(); // First call ends with \r — we don't yet know if it's bare \r or \r\n - let result = proc.process([chunk('hello\r')]); + proc.process([chunk('hello\r')]); // The text should still be visible (not discarded) - expect(result.map((l) => l.text)).toEqual(['hello']); + expect(proc.lines.map((l) => l.text)).toEqual(['hello']); // Second call starts with \n — confirms it was \r\n, line should be finalized - result = proc.process([chunk('\nworld\n')]); - expect(result.map((l) => l.text)).toEqual(['hello', 'world']); + proc.process([chunk('\nworld\n')]); + expect(proc.lines.map((l) => l.text)).toEqual(['hello', 'world']); }); it('bare \\r across calls correctly overwrites when followed by non-\\n', () => { - const proc = createIncrementalProcessor(); - proc.process([chunk('old text\r')]); - const result = proc.process([chunk('new text\n')]); - expect(result.map((l) => l.text)).toEqual(['new text']); + expect(feedOneByOne([chunk('old text\r'), chunk('new text\n')])).toEqual(['new text']); }); it('multiple trailing \\r across calls resolve correctly', () => { - const proc = createIncrementalProcessor(); - proc.process([chunk('10%\r')]); - proc.process([chunk('20%\r')]); - proc.process([chunk('30%\r')]); - const result = proc.process([chunk('done\n')]); - expect(result.map((l) => l.text)).toEqual(['done']); + expect(feedOneByOne([chunk('10%\r'), chunk('20%\r'), chunk('30%\r'), chunk('done\n')])).toEqual( + ['done'] + ); }); // --------------------------------------------------------------------------- @@ -219,8 +258,183 @@ describe('createIncrementalProcessor', () => { // --------------------------------------------------------------------------- it('handles multiple chunks in a single process() call', () => { + expect(feedAll([chunk('hello\n'), chunk('world\n')])).toEqual(['hello', 'world']); + }); + + // --------------------------------------------------------------------------- + // Lines are updated in place, not copied + // --------------------------------------------------------------------------- + + it('hands out one array and updates it in place', () => { + const proc = createIncrementalProcessor(); + const lines = proc.lines; + proc.process([chunk('one\n')]); + proc.process([chunk('two\nthree')]); + + expect(proc.lines).toBe(lines); + expect(lines.map((l) => l.text)).toEqual(['one', 'two', 'three']); + }); + + it('leaves the objects of finished lines alone', () => { + const proc = createIncrementalProcessor(); + proc.process([chunk('one\ntwo\n')]); + const [one, two] = proc.lines; + + proc.process([chunk('three\nfour')]); + proc.process([chunk(' more\n')]); + + expect(proc.lines[0]).toBe(one); + expect(proc.lines[1]).toBe(two); + expect(one).toEqual({ id: 0, text: 'one', stream: 'stdout' }); + }); + + it('replaces the unfinished line when its text changes, and only then', () => { + const proc = createIncrementalProcessor(); + proc.process([chunk('done\n10%')]); + const first = proc.lines[1]; + + // Output that does not change the line leaves its object alone... + proc.process([chunk('')]); + proc.process([]); + expect(proc.lines[1]).toBe(first); + + // ...a redraw replaces it, so a renderer sees that it changed... + proc.process([chunk('\r20%')]); + const second = proc.lines[1]; + expect(second).not.toBe(first); + expect(second).toEqual({ id: first.id, text: '20%', stream: 'stdout' }); + + // ...and a line that ends as it stood stays the object that was on show. + proc.process([chunk('\nnext')]); + expect(proc.lines[1]).toBe(second); + expect(proc.lines.map((l) => l.text)).toEqual(['done', '20%', 'next']); + }); + + it('numbers lines in order and keeps a line its number once it is finished', () => { + const proc = createIncrementalProcessor(); + proc.process([chunk('a\nb\nc')]); + expect(proc.lines.map((l) => l.id)).toEqual([0, 1, 2]); + + proc.process([chunk('!\rC\nd\n')]); + expect(proc.lines.map((l) => [l.id, l.text])).toEqual([ + [0, 'a'], + [1, 'b'], + [2, 'C'], + [3, 'd'], + ]); + }); + + it('keeps a line on show while a trailing \\r is undecided', () => { + const proc = createIncrementalProcessor(); + proc.process([chunk('a\nwork')]); + proc.process([chunk('\r')]); + // Still on show: the \r may yet be half of a \r\n. + expect(proc.lines.map((l) => l.text)).toEqual(['a', 'work']); + proc.process([chunk('\n')]); + expect(proc.lines.map((l) => l.text)).toEqual(['a', 'work']); + expect(proc.lines.map((l) => l.id)).toEqual([0, 1]); + }); + + it('takes the unfinished line away once an overwrite has emptied it', () => { + const proc = createIncrementalProcessor(); + proc.process([chunk('a\nwork\r')]); + expect(proc.lines.map((l) => l.text)).toEqual(['a', 'work']); + // A second \r settles the first as an overwrite, with nothing written yet. + proc.process([chunk('\r')]); + expect(proc.lines.map((l) => l.text)).toEqual(['a']); + proc.process([chunk('again')]); + expect(proc.lines.map((l) => [l.id, l.text])).toEqual([ + [0, 'a'], + [1, 'again'], + ]); + }); + + // --------------------------------------------------------------------------- + // Limits + // --------------------------------------------------------------------------- + + it('keeps only the most recent lines and counts the rest', () => { + const proc = createIncrementalProcessor(limits({ maxLines: 3 })); + for (let n = 0; n < 10; n++) { + proc.process([chunk(`line ${n}\n`)]); + expect(proc.lines.length).toBeLessThanOrEqual(3); + } + + expect(proc.lines.map((l) => l.text)).toEqual(['line 7', 'line 8', 'line 9']); + // Lines keep the numbers they had, so a keyed list sees three removals + // and three additions, not ten changed rows. + expect(proc.lines.map((l) => l.id)).toEqual([7, 8, 9]); + expect(proc.droppedLines).toBe(7); + }); + + it('counts the unfinished line towards the limit', () => { + const proc = createIncrementalProcessor(limits({ maxLines: 3 })); + proc.process([chunk('a\nb\nc\nd')]); + expect(proc.lines.map((l) => l.text)).toEqual(['b', 'c', 'd']); + expect(proc.droppedLines).toBe(1); + + // A redraw of the unfinished line drops nothing more. + proc.process([chunk('\rD')]); + expect(proc.lines.map((l) => l.text)).toEqual(['b', 'c', 'D']); + expect(proc.droppedLines).toBe(1); + }); + + it('trims a large snapshot as it goes, to the same result', () => { + const proc = createIncrementalProcessor(limits({ maxLines: 100 })); + const snapshot = Array.from({ length: 12_345 }, (_, n) => `line ${n}\n`).join(''); + proc.process([chunk(snapshot.slice(0, 40_000)), chunk(snapshot.slice(40_000))]); + + expect(proc.lines.length).toBe(100); + expect(proc.lines[0]).toMatchObject({ id: 12_245, text: 'line 12245' }); + expect(proc.lines[99]).toMatchObject({ id: 12_344, text: 'line 12344' }); + expect(proc.droppedLines).toBe(12_245); + }); + + it('keeps the total text within the character limit', () => { + const proc = createIncrementalProcessor(limits({ maxChars: 25 })); + proc.process([chunk('aaaaaaaaaa\nbbbbbbbbbb\ncccccccccc\n')]); + // Thirty characters of lines: the oldest goes. + expect(proc.lines.map((l) => l.text)).toEqual(['bbbbbbbbbb', 'cccccccccc']); + expect(proc.droppedLines).toBe(1); + + // The unfinished line counts too. + proc.process([chunk('dddddddd')]); + expect(proc.lines.map((l) => l.text)).toEqual(['cccccccccc', 'dddddddd']); + expect(proc.droppedLines).toBe(2); + }); + + it('cuts a line that grows past the line limit, and says so', () => { + const proc = createIncrementalProcessor(limits({ maxLineChars: 10 })); + proc.process([chunk('0123456')]); + proc.process([chunk('789abcdef')]); + proc.process([chunk('more of the same line')]); + expect(proc.lines.map((l) => l.text)).toEqual(['0123456789' + LINE_CUT_MARK]); + + // The next line starts afresh, and so does a redraw of the cut one. + proc.process([chunk('\nshort\n0123456789abc\rredrawn')]); + expect(proc.lines.map((l) => l.text)).toEqual([ + '0123456789' + LINE_CUT_MARK, + 'short', + 'redrawn', + ]); + }); + + it('does not cut a line in the middle of a surrogate pair', () => { + const proc = createIncrementalProcessor(limits({ maxLineChars: 4 })); + proc.process([chunk('abc😀def\n')]); + expect(proc.lines[0].text).toBe('abc' + LINE_CUT_MARK); + }); + + it('holds a bounded amount however long the output runs', () => { const proc = createIncrementalProcessor(); - const result = proc.process([chunk('hello\n'), chunk('world\n')]); - expect(result.map((l) => l.text)).toEqual(['hello', 'world']); + const batch = Array.from({ length: 500 }, (_, n) => `${'x'.repeat(100)} ${n}\n`).join(''); + for (let n = 0; n < 40; n++) proc.process([chunk(batch)]); + // One line with no break at all, far longer than a line may be. + for (let n = 0; n < 40; n++) proc.process([chunk('y'.repeat(10_000))]); + + expect(proc.lines.length).toBe(OUTPUT_LINE_LIMITS.maxLines); + expect(proc.droppedLines).toBe(40 * 500 + 1 - OUTPUT_LINE_LIMITS.maxLines); + const last = proc.lines[proc.lines.length - 1]; + expect(last.text.length).toBe(OUTPUT_LINE_LIMITS.maxLineChars + LINE_CUT_MARK.length); }); }); diff --git a/apps/staged/src/lib/features/actions/processOutput.ts b/apps/staged/src/lib/features/actions/processOutput.ts index a16fa0d1c..d917cd090 100644 --- a/apps/staged/src/lib/features/actions/processOutput.ts +++ b/apps/staged/src/lib/features/actions/processOutput.ts @@ -97,77 +97,211 @@ export function processChunksToLines(chunks: OutputChunk[]): TerminalLine[] { return lines; } +/** A line as the output view holds it. */ +export interface OutputLine extends TerminalLine { + /** + * The line's position in the output the processor has been fed, counting + * the lines it no longer holds. A line keeps its id from the moment it + * starts until it is dropped, so the id can key a rendered list. + */ + id: number; +} + +/** How much output a processor keeps. */ +export interface LineLimits { + /** Most lines kept. The oldest go first. */ + maxLines: number; + /** Most characters kept across all lines. The oldest lines go first. */ + maxChars: number; + /** Longest a single line may grow. What follows on that line is cut. */ + maxLineChars: number; +} + +/** + * The view's limits. The backend retains at most 4 MiB of an execution's + * output, which is never more than this many characters, so a snapshot loses + * lines only to the line count. + */ +export const OUTPUT_LINE_LIMITS: LineLimits = { + maxLines: 5_000, + maxChars: 4 * 1024 * 1024, + maxLineChars: 64 * 1024, +}; + +/** Ends a line that was cut at `maxLineChars`. */ +export const LINE_CUT_MARK = ' … [line cut]'; + +const LF = 10; +const CR = 13; + +export interface LineProcessor { + /** + * The lines kept, oldest first, ending with the line still being written + * if there is one. This is the same array on every read: `process` updates + * it in place rather than building a new one, so the cost of an update does + * not grow with the output already shown. A line object is replaced, never + * changed, when its text changes, and is otherwise left alone: a renderer + * that compares line objects re-renders exactly the lines that changed. + */ + readonly lines: OutputLine[]; + /** How many lines have been dropped from the front to stay within the limits. */ + readonly droppedLines: number; + /** Feed the output that follows what has been fed so far. */ + process(chunks: Iterable>): void; +} + /** * Incremental line processor that maintains state across calls. * * Unlike `processChunksToLines` (which reprocesses every chunk from scratch), - * this only processes *new* chunks each time `process()` is called, appending - * to an internal list of finalized lines. This turns the per-update cost from - * O(total-characters) to O(new-characters). + * this only processes *new* chunks each time `process()` is called, and it + * keeps a bounded tail of the result: the cost of a call is O(new characters) + * and what it holds never exceeds `limits`, however long the output runs. */ -export function createIncrementalProcessor() { - const finalizedLines: TerminalLine[] = []; +export function createIncrementalProcessor(limits: LineLimits = OUTPUT_LINE_LIMITS): LineProcessor { + const maxLines = Math.max(1, limits.maxLines); + const lines: OutputLine[] = []; + /** Characters in the finished lines in `lines`. */ + let finishedChars = 0; + let droppedLines = 0; + /** The id of the line being written, and of the next line to be finished. */ + let nextId = 0; let currentText = ''; let currentStream: 'stdout' | 'stderr' = 'stdout'; let pendingCR = false; + /** The line being written reached `maxLineChars`; the rest of it is skipped. */ + let cut = false; + /** The line being written, as last put at the end of `lines`. */ + let unfinished: OutputLine | null = null; - return { - /** - * Feed new chunks and return the full (finalized + in-progress) line list. - */ - process(chunks: OutputChunk[]): TerminalLine[] { - for (const chunk of chunks) { - const raw = chunk.chunk; - const stream = chunk.stream; - - for (let i = 0; i < raw.length; i++) { - const ch = raw[i]; - - if (pendingCR) { - pendingCR = false; - if (ch === '\n') { - finalizedLines.push({ text: currentText, stream: currentStream }); - currentText = ''; - currentStream = stream; - continue; - } else { - currentText = ''; - currentStream = stream; - } - } - - if (ch === '\n') { - finalizedLines.push({ text: currentText, stream: currentStream }); - currentText = ''; - currentStream = stream; - } else if (ch === '\r') { - if (i + 1 < raw.length && raw[i + 1] === '\n') { - finalizedLines.push({ text: currentText, stream: currentStream }); - currentText = ''; - currentStream = stream; - i++; - } else if (i + 1 < raw.length) { - currentText = ''; - currentStream = stream; - } else { - pendingCR = true; - } - } else { - currentText += ch; - currentStream = stream; - } - } + function startLine(stream: 'stdout' | 'stderr'): void { + currentText = ''; + currentStream = stream; + cut = false; + } + + function append(text: string, stream: 'stdout' | 'stderr'): void { + currentStream = stream; + if (cut) return; + let room = limits.maxLineChars - currentText.length; + if (text.length <= room) { + currentText += text; + return; + } + // Do not leave half of a surrogate pair at the cut. + const last = room > 0 ? text.charCodeAt(room - 1) : 0; + if (last >= 0xd800 && last <= 0xdbff) room--; + currentText += text.slice(0, Math.max(0, room)) + LINE_CUT_MARK; + cut = true; + } + + /** + * Drop lines from the front until the finished lines, plus the unfinished + * one described by the arguments, are within the limits. + */ + function trim(unfinishedLines: number, unfinishedChars: number): void { + let drop = Math.max(0, lines.length + unfinishedLines - maxLines); + let freed = 0; + for (let i = 0; i < drop; i++) freed += lines[i].text.length; + while (drop < lines.length && finishedChars - freed + unfinishedChars > limits.maxChars) { + freed += lines[drop].text.length; + drop++; + } + if (drop === 0) return; + lines.splice(0, drop); + finishedChars -= freed; + droppedLines += drop; + } + + function finishLine(nextStream: 'stdout' | 'stderr'): void { + // A line that was already on show unfinished, and ends as it stood, stays + // the same object, so it is not rendered again. + const shown = unfinished; + const line = + shown && shown.id === nextId && shown.text === currentText && shown.stream === currentStream + ? shown + : { id: nextId, text: currentText, stream: currentStream }; + nextId++; + lines.push(line); + finishedChars += line.text.length; + startLine(nextStream); + // A large snapshot arrives in one call. Trimming as it goes keeps what + // is held in the meantime to twice the limit, not the whole snapshot. + if (lines.length >= 2 * maxLines) trim(0, 0); + } + + function feed(raw: string, stream: 'stdout' | 'stderr'): void { + const length = raw.length; + if (length === 0) return; + + let i = 0; + if (pendingCR) { + pendingCR = false; + if (raw.charCodeAt(0) === LF) { + // \r\n split across chunks — treat as a single newline + finishLine(stream); + i = 1; + } else { + // The previous \r was a bare carriage return — reset the line + startLine(stream); } + } - if (pendingCR) { - // Don't discard — just return what we have; the bare CR will resolve - // on the next call when more data arrives (or on final snapshot). + // Text between line breaks is taken a run at a time, not a character + // at a time. + let runStart = i; + for (; i < length; i++) { + const code = raw.charCodeAt(i); + if (code !== LF && code !== CR) continue; + + if (i > runStart) append(raw.slice(runStart, i), stream); + if (code === LF) { + finishLine(stream); + } else if (i + 1 >= length) { + // \r at the very end of the chunk — defer decision until next chunk + pendingCR = true; + } else if (raw.charCodeAt(i + 1) === LF) { + // \r\n within the same chunk + finishLine(stream); + i++; // skip the \n + } else { + // Bare \r with more data in this chunk: reset cursor (overwrite) + startLine(stream); } + runStart = i + 1; + } + if (length > runStart) append(raw.slice(runStart), stream); + } - if (currentText.length > 0) { - return [...finalizedLines, { text: currentText, stream: currentStream }]; + return { + lines, + get droppedLines() { + return droppedLines; + }, + process(chunks) { + // The unfinished line comes off the end while output is fed, and goes + // back on, as it then stands, afterwards. + if (unfinished) lines.pop(); + + for (const chunk of chunks) feed(chunk.chunk, chunk.stream); + + // A pending \r is not resolved here: the line stays on show until the + // next chunk says whether it was the start of a \r\n or an overwrite. + const hasUnfinished = currentText.length > 0; + trim(hasUnfinished ? 1 : 0, currentText.length); + if (!hasUnfinished) { + unfinished = null; + return; + } + if ( + !unfinished || + unfinished.id !== nextId || + unfinished.text !== currentText || + unfinished.stream !== currentStream + ) { + unfinished = { id: nextId, text: currentText, stream: currentStream }; } - return [...finalizedLines]; + lines.push(unfinished); }, }; } diff --git a/crates/builderbot-actions/src/executor.rs b/crates/builderbot-actions/src/executor.rs index 173c82119..bd352f4c7 100644 --- a/crates/builderbot-actions/src/executor.rs +++ b/crates/builderbot-actions/src/executor.rs @@ -22,7 +22,7 @@ use tokio::runtime::Handle; use tokio::sync::oneshot; use crate::finished_outputs::{FinishedOutputs, MAX_FINISHED_EXECUTIONS}; -use crate::models::{ActionStatus, ExecutionEvent, OutputChunk}; +use crate::models::{ActionStatus, BufferedOutput, ExecutionEvent}; use crate::output_buffer::{OutputBuffer, SharedOutputBuffer, MAX_OUTPUT_BYTES}; use crate::output_emitter::{self, OutputSender, EMIT_INTERVAL, EMIT_MAX_BYTES}; use crate::utf8_stream::Utf8StreamDecoder; @@ -720,13 +720,16 @@ impl ActionExecutor { } } - /// Get buffered output for an execution. + /// Get buffered output for an execution, and the offset it ends at. /// /// Only the most recent output is kept. Once earlier output has been /// dropped, the first chunk is a notice saying how much. Returns `None` /// for an unknown execution, and for a finished one whose output has been /// cleared or evicted. - pub fn get_buffered_output(&self, execution_id: &str) -> Option> { + /// + /// The end offset lines the snapshot up with the `Output` events: every + /// event that starts before it is in the snapshot, and no other is. + pub fn get_buffered_output(&self, execution_id: &str) -> Option { // First check running actions, then finished ones let buffer = { let running = self.running.lock().unwrap(); @@ -736,8 +739,15 @@ impl ActionExecutor { } }; - // Copy the output with only the buffer itself locked. - buffer.map(|buffer| buffer.lock().unwrap().snapshot()) + // Copy the output with only the buffer itself locked. The offset is + // read under the same lock, so it is the end of exactly this copy. + buffer.map(|buffer| { + let buffer = buffer.lock().unwrap(); + BufferedOutput { + chunks: buffer.snapshot(), + end_offset: buffer.end_offset(), + } + }) } /// Check if an action is currently running diff --git a/crates/builderbot-actions/src/executor/tests.rs b/crates/builderbot-actions/src/executor/tests.rs index 90f69de82..90494a668 100644 --- a/crates/builderbot-actions/src/executor/tests.rs +++ b/crates/builderbot-actions/src/executor/tests.rs @@ -63,6 +63,8 @@ fn slow_recorder(output_delay: Duration) -> (Arc, Receive struct Outcome { /// The text of every output event, in order. streamed: Vec, + /// The offset each of those events said its text starts at. + offsets: Vec, status: ActionStatus, exit_code: Option, } @@ -97,18 +99,23 @@ impl Outcome { fn wait_for_finish(events: &Receiver) -> Outcome { let mut streamed = Vec::new(); + let mut offsets = Vec::new(); loop { match events .recv_timeout(WAIT) .expect("the execution did not finish") { ExecutionEvent::Started { .. } => {} - ExecutionEvent::Output { chunk, .. } => streamed.push(chunk), + ExecutionEvent::Output { chunk, offset, .. } => { + streamed.push(chunk); + offsets.push(offset); + } ExecutionEvent::StatusChanged { status, exit_code, .. } => { return Outcome { streamed, + offsets, status, exit_code, } @@ -226,7 +233,7 @@ async fn run_sh_until_output( fn buffered_text(executor: &ActionExecutor, execution_id: &str) -> Option { executor .get_buffered_output(execution_id) - .map(|chunks| chunks.iter().map(|c| c.chunk.as_str()).collect()) + .map(|output| output.chunks.iter().map(|c| c.chunk.as_str()).collect()) } /// A file a script waits on, so a test can hold an action open and release @@ -398,7 +405,7 @@ async fn buffered_output_is_capped_to_the_most_recent_bytes() { let written: String = (1..=20_000).map(|n| format!("{n}\n")).collect(); assert_eq!(outcome.streamed_text(), written); - let chunks = executor.get_buffered_output(&id).unwrap(); + let chunks = executor.get_buffered_output(&id).unwrap().chunks; let (notice, retained) = chunks.split_first().unwrap(); let retained: String = retained.iter().map(|c| c.chunk.as_str()).collect(); // The buffer holds the end of the output, on a line boundary, within the @@ -418,6 +425,37 @@ async fn buffered_output_is_capped_to_the_most_recent_bytes() { ); } +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn events_and_the_snapshot_share_one_set_of_offsets() { + // A small cap, so most of the output is gone from the buffer by the end, + // and small batches, so there are many events. + let executor = ActionExecutor::with_limits(Limits { + max_output_bytes: 16 * 1024, + emit_max_bytes: 1024, + ..patient_limits() + }); + let Finished { id, outcome, .. } = run_sh_to_finish(&executor, "seq 1 20000").await; + assert!(outcome.streamed.len() > 10); + + // Each event starts where the one before it ended, counting from the + // start of the output. + let mut expected = 0; + for (chunk, offset) in outcome.streamed.iter().zip(&outcome.offsets) { + assert_eq!(*offset, expected); + expected += chunk.len() as u64; + } + + // The snapshot ends where the last event did, although it no longer holds + // the start of the output. A viewer that takes it now has nothing left to + // apply; one that took it earlier would apply the events from its end on. + let output = executor.get_buffered_output(&id).unwrap(); + assert!(output.chunks[0] + .chunk + .starts_with("[earlier output truncated: ")); + assert_eq!(output.end_offset, expected); + assert_eq!(output.end_offset, outcome.streamed_text().len() as u64); +} + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn reads_of_one_stream_are_coalesced() { let executor = ActionExecutor::with_limits(patient_limits()); @@ -428,7 +466,7 @@ async fn reads_of_one_stream_are_coalesced() { // Many reads were streamed, and they are buffered as a single block. assert_eq!(outcome.streamed_text(), written); - let chunks = executor.get_buffered_output(&id).unwrap(); + let chunks = executor.get_buffered_output(&id).unwrap().chunks; assert_eq!(chunks.len(), 1); assert_eq!(chunks[0].stream, stream); assert_eq!(chunks[0].chunk, written); diff --git a/crates/builderbot-actions/src/lib.rs b/crates/builderbot-actions/src/lib.rs index ad966145c..1d198dabc 100644 --- a/crates/builderbot-actions/src/lib.rs +++ b/crates/builderbot-actions/src/lib.rs @@ -63,4 +63,6 @@ mod utf8_stream; pub use acp_provider::AcpAiProvider; pub use detector::{ActionDetector, AiProvider, FileExplorationMode, SuggestedAction}; pub use executor::{ActionExecutor, ExecutionListener, StopOptions}; -pub use models::{ActionStatus, ActionType, ExecutionEvent, OutputChunk, RunDetectionMode}; +pub use models::{ + ActionStatus, ActionType, BufferedOutput, ExecutionEvent, OutputChunk, RunDetectionMode, +}; diff --git a/crates/builderbot-actions/src/models.rs b/crates/builderbot-actions/src/models.rs index 6fcba12d1..8b5a7afab 100644 --- a/crates/builderbot-actions/src/models.rs +++ b/crates/builderbot-actions/src/models.rs @@ -61,6 +61,22 @@ pub struct OutputChunk { pub timestamp: i64, } +/// The output an execution has buffered, and where it ends. +/// +/// Output is also delivered live, as [`ExecutionEvent::Output`]. `end_offset` +/// is what joins the two: an event whose `offset` is below it is already in +/// `chunks`, and the first one that is not starts exactly at it. +#[derive(Debug, Clone, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub struct BufferedOutput { + /// The retained output, oldest first. Once earlier output has been + /// dropped, the first chunk is a notice saying how much. + pub chunks: Vec, + /// Bytes of output the execution had produced when `chunks` was taken, + /// counting what is no longer retained. + pub end_offset: u64, +} + /// How a "run" action detects whether the process is running and/or its endpoint. #[derive(Debug, Clone, Serialize, Deserialize)] #[serde(tag = "type", rename_all = "camelCase")] @@ -85,6 +101,10 @@ pub enum ExecutionEvent { chunk: String, stream: String, // "stdout" or "stderr" timestamp: i64, + /// Where `chunk` starts in the execution's output: the number of + /// bytes of output delivered before it. Each event starts where the + /// one before it ended. + offset: u64, }, /// Action status changed StatusChanged { diff --git a/crates/builderbot-actions/src/output_buffer.rs b/crates/builderbot-actions/src/output_buffer.rs index c2e678b9a..fe23656cb 100644 --- a/crates/builderbot-actions/src/output_buffer.rs +++ b/crates/builderbot-actions/src/output_buffer.rs @@ -36,6 +36,8 @@ pub(crate) struct OutputBuffer { retained_bytes: usize, /// Bytes of output text evicted from the front so far. dropped_bytes: u64, + /// Bytes of output text pushed so far, retained or not. + pushed_bytes: u64, /// Whether the oldest retained block starts part-way through a line, /// because the block evicted before it did not end on a line break. head_is_partial_line: bool, @@ -51,6 +53,7 @@ impl OutputBuffer { blocks: VecDeque::new(), retained_bytes: 0, dropped_bytes: 0, + pushed_bytes: 0, head_is_partial_line: false, max_bytes, block_bytes: MAX_BLOCK_BYTES.min(max_bytes / 4).max(1), @@ -69,6 +72,7 @@ impl OutputBuffer { /// batch is stored as several blocks, so that the bound holds whatever /// size the buffer is fed in. pub(crate) fn push(&mut self, stream: &str, text: &str, timestamp: i64) { + self.pushed_bytes += text.len() as u64; let mut rest = text; while !rest.is_empty() { let (piece, after) = rest.split_at(piece_len(rest, self.block_bytes)); @@ -115,6 +119,12 @@ impl OutputBuffer { } } + /// Where the output pushed so far ends: its length in bytes, counting + /// what has been evicted. The next push starts here. + pub(crate) fn end_offset(&self) -> u64 { + self.pushed_bytes + } + /// The retained output, oldest first. /// /// Once earlier output has been dropped, the first chunk is a synthetic @@ -295,6 +305,36 @@ mod tests { assert_eq!(buffer.dropped_bytes, 4); } + #[test] + fn the_end_offset_counts_everything_pushed() { + let mut buffer = OutputBuffer::new(MAX_OUTPUT_BYTES); + assert_eq!(buffer.end_offset(), 0); + + buffer.push("stdout", "one", 0); + assert_eq!(buffer.end_offset(), 3); + // Bytes, not characters, and whichever stream they were written to. + buffer.push("stderr", "café €", 0); + assert_eq!(buffer.end_offset(), 3 + 9); + buffer.push("stdout", "", 0); + assert_eq!(buffer.end_offset(), 12); + } + + #[test] + fn the_end_offset_keeps_counting_evicted_output() { + let max_bytes = 4 * 1024; + let mut buffer = OutputBuffer::new(max_bytes); + let line = format!("{}\n", "z".repeat(99)); + for _ in 0..1_000 { + buffer.push("stdout", &line, 0); + } + + assert!(buffer.dropped_bytes > 0); + assert_eq!(buffer.end_offset(), 1_000 * line.len() as u64); + // What is retained is the output just before the end offset. + let retained: usize = buffer.blocks.iter().map(|b| b.chunk.len()).sum(); + assert_eq!(buffer.end_offset(), buffer.dropped_bytes + retained as u64); + } + #[test] fn empty_reads_are_ignored() { let mut buffer = OutputBuffer::new(MAX_OUTPUT_BYTES); diff --git a/crates/builderbot-actions/src/output_emitter.rs b/crates/builderbot-actions/src/output_emitter.rs index 8f8eb229c..ca43a14dc 100644 --- a/crates/builderbot-actions/src/output_emitter.rs +++ b/crates/builderbot-actions/src/output_emitter.rs @@ -7,9 +7,12 @@ //! once it is [`EMIT_INTERVAL`] old or [`EMIT_MAX_BYTES`] large. //! //! A batch reaches the execution's buffer and then its listener, in that -//! order, so the buffer never holds output the listener has yet to be told -//! about. A viewer that reads the buffer and then follows the events sees no -//! batch twice. +//! order, so the listener is never told about output the buffer does not +//! hold yet. Each event carries the offset its output starts at in the +//! buffer, and a batch is appended whole, so a snapshot of the buffer always +//! ends where one event ends and the next begins. A viewer that starts +//! following the events and then takes a snapshot can tell exactly which +//! events the snapshot already holds: those that start before its end. use std::convert::Infallible; use std::sync::mpsc::{self, RecvTimeoutError, TrySendError}; @@ -170,18 +173,23 @@ pub(crate) fn spawn( pending_bytes = 0; let batch = std::mem::take(&mut pending); if !batch.is_empty() { + // Where each segment starts in the buffer, read under the + // lock that appends it. + let mut offsets = Vec::with_capacity(batch.len()); { let mut buffer = buffer.lock().unwrap(); for segment in &batch { + offsets.push(buffer.end_offset()); buffer.push(segment.stream, &segment.text, segment.timestamp); } } - for segment in batch { + for (segment, offset) in batch.into_iter().zip(offsets) { handle.block_on(listener.on_event(ExecutionEvent::Output { execution_id: execution_id.clone(), chunk: segment.text, stream: segment.stream.to_string(), timestamp: segment.timestamp, + offset, })); } } @@ -350,6 +358,71 @@ mod tests { assert_eq!(events.try_iter().count(), 1); } + /// Forwards, for every output event, where it starts, its text, and where + /// the buffer ended when the listener was handed it. + struct OffsetRecorder { + events: mpsc::Sender<(u64, String, u64)>, + buffer: SharedOutputBuffer, + } + + #[async_trait] + impl ExecutionListener for OffsetRecorder { + async fn on_event(&self, event: ExecutionEvent) { + if let ExecutionEvent::Output { chunk, offset, .. } = event { + let buffer_end = self.buffer.lock().unwrap().end_offset(); + let _ = self.events.send((offset, chunk, buffer_end)); + } + } + } + + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] + async fn each_event_starts_where_the_one_before_it_ended() { + let (events_tx, events) = mpsc::channel(); + // A buffer far smaller than the output: what it has evicted still + // counts towards the offsets. + let buffer = OutputBuffer::shared(8); + let output = spawn( + "exec".to_string(), + Arc::new(OffsetRecorder { + events: events_tx, + buffer: buffer.clone(), + }), + buffer.clone(), + Handle::current(), + WAIT, + usize::MAX, + ); + + output.send("stdout", "one".to_string(), 0); + flush(&output); + // One batch, two events. + output.send("stdout", "twö".to_string(), 0); + output.send("stderr", "three".to_string(), 0); + flush(&output); + output.send("stdout", "four".to_string(), 0); + flush(&output); + + let seen: Vec<(u64, String, u64)> = events.try_iter().collect(); + let starts: Vec<(u64, &str)> = seen + .iter() + .map(|(offset, text, _)| (*offset, text.as_str())) + .collect(); + // Offsets are in bytes: "twö" is four of them. + assert_eq!( + starts, + vec![(0, "one"), (3, "twö"), (7, "three"), (12, "four")] + ); + + // A batch is in the buffer, whole, before any of it is delivered. So + // the buffer always ends on the boundary between two events, at or + // after the end of the one being delivered: a snapshot taken at any + // point holds whole events, and exactly those that start before its + // end. + let buffer_ends: Vec = seen.iter().map(|(_, _, end)| *end).collect(); + assert_eq!(buffer_ends, vec![3, 12, 12, 16]); + assert_eq!(buffer.lock().unwrap().end_offset(), 16); + } + #[tokio::test(flavor = "multi_thread", worker_threads = 2)] async fn a_flush_gives_up_at_its_deadline() { let Fixture { From 5b7b14d679c53110139c509db91946fdec9e03d5 Mon Sep 17 00:00:00 2001 From: Matt Toohey Date: Fri, 13 Nov 2026 15:40:06 +1100 Subject: [PATCH 4/4] fix(actions): close the exit window and other review findings Requested: apply the review of 21f8e6fe as one commit. Fix every warning and suggestion except the one on branch teardown, make sure a Stop between an action's exit and its terminal status cannot leave its id in `stopped` for good, and give each behavioural fix a test that fails without it. No backend model type, event payload or command signature is added or changed. Left out: output of a finished action on a deleted branch - Teardown still discards output only for executions the registry lists as running (stop_branch_actions, commands.rs). An action that finished with no card mounted keeps its output, up to 4 MiB, until eight later executions finish. - Closing that needs the executor to know which branch a finished execution belonged to. That is a new backend field, so it is left for a human decision. An execution is running until its terminal status is due (warning) - The completion thread took the execution out of `running` when the process exited, then waited up to 4 s for the readers and the flush. In that window the liveness queries left it out, so a card that hydrated then never showed it. - The entry now stays in `running` until the flush is done, and moves to the finished set just before the status is reported. `is_running`, `get_running_ids` and `wait_for_executions` count it as running until then. In the usual case the window is still microseconds. - App quit uses `wait_for_executions`, so it can wait for that delivery too. It is bounded by the quit's own budget, as before. Stop in that window, and Stop of anything without a process - The completion thread clears the execution's pid and consumes its `stopped` mark at exit, under the `running` lock. Stop now adds the mark under that same lock, and only when there is a pid to signal. - A Stop in the window therefore does nothing: no signal to a pid that may be reused, no mark, and the action reports the status it earned. - The same rule ends an older leak: stopping a finished or unknown execution used to leave its id in `stopped` for good. Partial-line flag across streams (output_buffer.rs) - The buffer skipped the first line of the oldest retained block whenever the evicted block did not end on a line break. With separate stdout and stderr pipes that dropped a whole stderr line after a cut in stdout. The flag is now set only when both blocks are one stream. Newest detection line always stays (terminal_output.rs) - A line that a multi-byte character took a few bytes past the byte bound evicted itself when it ended, so the matcher never saw it. The newest finalized line now stays whatever its size, as the newest block does in OutputBuffer. Retry after a failed first snapshot (outputFollower.ts) - After the first snapshot failed nothing asked again until a reconnect, so the modal stayed on its load error while the action kept writing. The next output event now takes the snapshot again. Test-only changes - commands.rs: the buffer and events test retried whenever the buffer was empty, which is also what lost output looks like. It now records the status and exit code, retries only on failed with no exit code and no output, and asserts a clean exit. - executor/tests.rs: the pending-batch test has to meet its drain timeout, not outlast it. The timeout is 10 s instead of 2 s, so a starved machine still reads and delivers in time. Tests that fail without the fix - Executor: running until the status is due, and Stop after the process has exited. With the old exit sequence both fail. With only Stop's marking reverted the Stop test fails on the leftover mark. - OutputBuffer: a line of another stream at the cut is kept whole. - Terminal output: a line a wide character took past the bound is kept. - Follower: two tests for the retry on the next event. - Each was run against the reverted fix and failed. A further executor test, that a real Stop still reports Stopped and clears its mark, is a guard and passes either way. Checks run, one at a time, on this tree - Disk before starting: 54 GiB free. Load average 13 to 68 throughout, from other sessions. - Crates workspace: cargo fmt --all --check, cargo clippy --workspace -- -D warnings, cargo test --workspace. All pass: 694 tests, 9 ignored, plus 1 doc test. - Tauri app: just app staged ci-rust-lint (fmt check, clippy) and ci-rust-test (cargo test --workspace --lib --bins --tests). All pass: 2112 app tests with 2 ignored, including all 136 project_transfer tests, 106 stagedctl tests, the help-pin test, and both bin targets, which hold no tests. - Frontend: prettier --check, svelte-check and tsc (0 errors, 0 warnings), and the full vitest suite. - Limits used to hold the load down: RUST_TEST_THREADS=4 for the Rust tests and --maxWorkers=3 for vitest. One failure, not repeated - The first full vitest run had 1 failure in 3590 tests: a 5 s timeout in MarkdownWysiwygEditor.component.test.ts, "loads embedded images from the media server", at a load average of 68. - It passed alone 3 times and in 2 further full runs on this tree. - On the merge base 4cc7a044 it passes alone and in the full suite, 3521 of 3521. This branch changes nothing under features/notes. Not run - `just ci` as one command. Its crates and Staged parts are the checks above. The Differ and Penpal apps, which this branch does not touch, were not checked. - Nothing was exercised in a running app. Signed-off-by: Matt Toohey Co-Authored-By: Claude Fable 5.2 --- apps/staged/src-tauri/src/actions/commands.rs | 35 +++-- apps/staged/src-tauri/src/terminal_output.rs | 36 ++++- .../features/actions/outputFollower.test.ts | 50 ++++++- .../lib/features/actions/outputFollower.ts | 20 ++- crates/builderbot-actions/src/executor.rs | 90 +++++++++---- .../builderbot-actions/src/executor/tests.rs | 124 +++++++++++++++++- .../builderbot-actions/src/output_buffer.rs | 38 +++++- 7 files changed, 342 insertions(+), 51 deletions(-) diff --git a/apps/staged/src-tauri/src/actions/commands.rs b/apps/staged/src-tauri/src/actions/commands.rs index c9ae35853..d06a26d57 100644 --- a/apps/staged/src-tauri/src/actions/commands.rs +++ b/apps/staged/src-tauri/src/actions/commands.rs @@ -1579,11 +1579,13 @@ mod tests { } /// Collects the `action_output` payload each output event becomes, and - /// says when the execution has reported its terminal status. + /// passes on the terminal status and exit code the execution reports. #[cfg(unix)] struct RecordOutput { output: std::sync::Mutex>, - finished: std::sync::Mutex>, + finished: std::sync::Mutex< + std::sync::mpsc::Sender<(builderbot_actions::ActionStatus, Option)>, + >, } #[cfg(unix)] @@ -1607,8 +1609,10 @@ mod tests { stream, offset, }), - builderbot_actions::ExecutionEvent::StatusChanged { .. } => { - let _ = self.finished.lock().unwrap().send(()); + builderbot_actions::ExecutionEvent::StatusChanged { + status, exit_code, .. + } => { + let _ = self.finished.lock().unwrap().send((status, exit_code)); } builderbot_actions::ExecutionEvent::Started { .. } => {} } @@ -1621,7 +1625,10 @@ mod tests { let executor = ActionExecutor::new(); // A freshly spawned child is occasionally killed before it runs (see - // the executor's tests), so start again if nothing was written. + // the executor's tests): it fails without an exit code, having + // written nothing. Start again on exactly that. A script that ran and + // whose output is missing is what this test is here to catch, so it + // must not be retried away. let mut attempt = None; for _ in 0..5 { let (finished_tx, finished) = std::sync::mpsc::channel(); @@ -1641,18 +1648,28 @@ mod tests { .await .unwrap(); // The terminal status follows all of the output. - finished + let (status, exit_code) = finished .recv_timeout(std::time::Duration::from_secs(60)) .expect("the execution did not finish"); let output = get_action_output_buffer_impl(execution_id.clone(), &executor) .unwrap() .expect("a finished execution keeps its output"); - if output.end_offset > 0 { - attempt = Some((execution_id, listener, output)); + let killed_at_birth = status == builderbot_actions::ActionStatus::Failed + && exit_code.is_none() + && output.end_offset == 0 + && listener.output.lock().unwrap().is_empty(); + if !killed_at_birth { + attempt = Some((execution_id, listener, output, status, exit_code)); break; } } - let (execution_id, listener, output) = attempt.expect("the script never ran"); + let (execution_id, listener, output, status, exit_code) = + attempt.expect("the child was killed before running 5 times in a row"); + assert_eq!( + (status, exit_code), + (builderbot_actions::ActionStatus::Completed, Some(0)), + "the script did not exit cleanly" + ); let text: String = output.chunks.iter().map(|c| c.chunk.as_str()).collect(); assert_eq!(text.len(), "héllo\nerr\n".len()); diff --git a/apps/staged/src-tauri/src/terminal_output.rs b/apps/staged/src-tauri/src/terminal_output.rs index cf8f5c63e..ffc146d5d 100644 --- a/apps/staged/src-tauri/src/terminal_output.rs +++ b/apps/staged/src-tauri/src/terminal_output.rs @@ -51,6 +51,10 @@ impl TerminalOutputProcessor { /// A processor that retains only its most recent lines: at most /// `max_lines` finalized lines holding at most `max_bytes` of text. The /// in-progress line stops growing at `max_bytes` too, until it ends. + /// + /// The newest finalized line always stays, so neither bound is ever + /// below one line. A line can end a few bytes over `max_bytes`, when the + /// character that took it there is wider than a byte. pub(crate) fn keeping_recent(max_lines: usize, max_bytes: usize) -> Self { Self { recent: Some(RecentLines { @@ -199,8 +203,12 @@ impl TerminalOutputProcessor { let Some(recent) = self.recent else { return; }; - while self.finalized_lines.len() > recent.max_lines - || self.finalized_bytes > recent.max_bytes + // The line just finalized stays whatever its size. It can be over + // the byte bound by itself, by part of a multi-byte character, and + // would otherwise evict itself before anything had read it. + while self.finalized_lines.len() > 1 + && (self.finalized_lines.len() > recent.max_lines + || self.finalized_bytes > recent.max_bytes) { let Some(dropped) = self.finalized_lines.pop_front() else { break; @@ -409,6 +417,30 @@ mod tests { assert_eq!(processor.line_count(), 1_002); } + #[test] + fn a_line_a_wide_character_took_past_the_byte_bound_is_kept() { + let max_bytes = 100; + let mut processor = TerminalOutputProcessor::keeping_recent(usize::MAX, max_bytes); + processor.process_chunk("first\n"); + // One byte short of the bound, then a three-byte character: the line + // stops growing two bytes over it. + let long = format!("{}€", "x".repeat(max_bytes - 1)); + processor.process_chunk(&long); + processor.process_chunk("more of the same line\n"); + assert_eq!(long.len(), max_bytes + 2); + + // It is over the bound by itself, and is still there, under its own + // number, for whoever reads the lines next. + assert_eq!(processor.lines_from(0), vec![long.clone()]); + assert_eq!(processor.line_count(), 2); + assert_eq!(processor.lines_from(1), vec![long]); + + // It makes way for the next line, as a line of exactly the bound does. + processor.process_chunk("next\n"); + assert_eq!(processor.lines_from(0), vec!["next"]); + assert_eq!(processor.line_count(), 3); + } + #[test] fn a_default_processor_keeps_every_line() { let mut processor = TerminalOutputProcessor::default(); diff --git a/apps/staged/src/lib/features/actions/outputFollower.test.ts b/apps/staged/src/lib/features/actions/outputFollower.test.ts index 0cb6448b4..3f5a67529 100644 --- a/apps/staged/src/lib/features/actions/outputFollower.test.ts +++ b/apps/staged/src/lib/features/actions/outputFollower.test.ts @@ -312,16 +312,60 @@ describe('createOutputFollower', () => { expect(h.view.errors).toHaveLength(1); expect(h.view.text).toBe(''); - // Events have nothing to continue until a snapshot is shown. - h.follower.handleEvent(be.write('three\n')); - expect(h.view.text).toBe(''); + // Nothing else asks for one in the meantime. expect(h.inFlight).toBe(0); + be.write('three\n'); h.follower.sync(); await h.land(be.snapshot()); expect(h.view.text).toBe('one\ntwo\nthree\n'); }); + it('retries a failed first snapshot on the next event', async () => { + const be = backend(); + const h = harness(); + be.write('one\n'); + + h.follower.sync(); + await h.fail(new Error('IPC unavailable')); + expect(h.view.errors).toHaveLength(1); + expect(h.inFlight).toBe(0); + + // Nothing is shown for the event to continue, and nobody is going to + // call sync again: the event itself asks for the snapshot. + h.follower.handleEvent(be.write('two\n')); + expect(h.inFlight).toBe(1); + // While that one is in flight, later events are held, not more requests. + h.follower.handleEvent(be.write('three\n')); + expect(h.inFlight).toBe(1); + + await h.land(be.snapshot()); + expect(h.view).toMatchObject({ text: 'one\ntwo\nthree\n', snapshots: 1, appended: 0 }); + expect(h.view.errors).toHaveLength(1); + + // From here on it follows as if the first snapshot had worked. + h.follower.handleEvent(be.write('four\n')); + expect(h.view).toMatchObject({ text: 'one\ntwo\nthree\nfour\n', appended: 1 }); + expect(h.inFlight).toBe(0); + }); + + it('keeps retrying on events for as long as the first snapshot fails', async () => { + const be = backend(); + const h = harness(); + h.follower.sync(); + await h.fail(new Error('IPC unavailable')); + + h.follower.handleEvent(be.write('one\n')); + await h.fail(new Error('IPC still unavailable')); + expect(h.view.errors).toHaveLength(2); + expect(h.inFlight).toBe(0); + + h.follower.handleEvent(be.write('two\n')); + expect(h.inFlight).toBe(1); + await h.land(be.snapshot()); + expect(h.view.text).toBe('one\ntwo\n'); + }); + it('retries after a failed resync when the next event does not fit', async () => { const be = backend(); const h = harness(); diff --git a/apps/staged/src/lib/features/actions/outputFollower.ts b/apps/staged/src/lib/features/actions/outputFollower.ts index 1bdb2e206..4be31fbf7 100644 --- a/apps/staged/src/lib/features/actions/outputFollower.ts +++ b/apps/staged/src/lib/features/actions/outputFollower.ts @@ -101,6 +101,8 @@ export function createOutputFollower(opts: OutputFollowerOptions): OutputFollowe */ let shownEnd: number | null = null; let fetching = false; + /** The last snapshot asked for could not be taken, and none has been since. */ + let lastSnapshotFailed = false; /** Another snapshot is wanted once the one in flight has landed. */ let fetchAgain = false; /** Events that arrived while a snapshot was in flight, in order. */ @@ -135,6 +137,7 @@ export function createOutputFollower(opts: OutputFollowerOptions): OutputFollowe return; } fetching = true; + lastSnapshotFailed = false; void takeSnapshot(); } @@ -159,8 +162,10 @@ export function createOutputFollower(opts: OutputFollowerOptions): OutputFollowe if (failure) { // Without a snapshot the held events have nothing to continue. The - // next sync, or the next event that does not fit, tries again. + // next sync tries again, and so does the next event that has nothing + // to continue or does not fit what is shown. dropHeld(); + lastSnapshotFailed = true; opts.onError(failure.error); return; } @@ -190,9 +195,16 @@ export function createOutputFollower(opts: OutputFollowerOptions): OutputFollowe hold(event); return; } - // Nothing shown and no snapshot on its way: the event has nothing to - // continue, and the snapshot that is eventually taken will hold it. - if (shownEnd === null) return; + if (shownEnd === null) { + // Nothing shown and no snapshot on its way: the event has nothing to + // continue, and the snapshot that is eventually taken will hold it. + // + // If a snapshot was asked for and failed, nobody else is going to ask + // again while the connection stays up, so the event is the cue to. It + // is in the buffer already, so the snapshot holds it. + if (lastSnapshotFailed) sync(); + return; + } const end = event.offset + utf8Length(event.chunk); if (end <= shownEnd) return; diff --git a/crates/builderbot-actions/src/executor.rs b/crates/builderbot-actions/src/executor.rs index bd352f4c7..9d67774f0 100644 --- a/crates/builderbot-actions/src/executor.rs +++ b/crates/builderbot-actions/src/executor.rs @@ -160,8 +160,11 @@ impl Default for Limits { } } -/// Internal state for a running action +/// Internal state for an execution that has not reported its terminal status struct RunningActionState { + /// The process to signal. `None` once it has exited: its pid can be + /// reused from then on, and there is nothing left to stop. The execution + /// stays listed until its last output has been delivered. child_pid: Option, output_buffer: SharedOutputBuffer, /// Set by `discard_output`: free the output at exit instead of retaining it. @@ -176,6 +179,10 @@ pub struct ActionExecutor { finished: Arc>, /// Tracks execution IDs that have been explicitly stopped by the user. /// The completion thread checks this to emit `Stopped` instead of `Failed`. + /// + /// An id is added only while its process is alive, and is taken out when + /// that process exits, so nothing stays here. Both happen under `running`, + /// which is locked first wherever both are held. stopped: Arc>>, limits: Limits, } @@ -340,24 +347,22 @@ impl ActionExecutor { let exit_code = exit_status.as_ref().ok().and_then(|s| s.code()); let completed_at = now_timestamp(); - // Check whether this execution was explicitly stopped by the user + // Record that the process is gone, and check whether the user + // stopped it. Both under `running`, the lock a stop holds while + // it decides whether there is a process to stop: a stop that + // comes later finds none, and so leaves no mark that nothing + // would ever clear. + // + // The execution stays in `running` until its terminal status is + // due. Until then it is still running to anything that asks, as + // it is to every viewer that has not been told otherwise. let was_stopped = { - let mut stopped = stopped_clone.lock().unwrap(); - stopped.remove(&exec_id) - }; - - // Remove from running and hand the output buffer to the finished - // set. The buffer itself moves: nothing is copied, and the emitter - // keeps appending to the same one. - { let mut running = running_clone.lock().unwrap(); - if let Some(state) = running.remove(&exec_id) { - if !state.discard_output { - let mut finished = finished_clone.lock().unwrap(); - finished.insert(exec_id.clone(), state.output_buffer); - } + if let Some(state) = running.get_mut(&exec_id) { + state.child_pid = None; } - } + stopped_clone.lock().unwrap().remove(&exec_id) + }; // The process has exited, but the last of its output may still be // unread, or read and waiting in a batch. Wait for the readers, @@ -376,6 +381,19 @@ impl ActionExecutor { // The readers keep the emitter alive for as long as they run. drop(output); + // Remove from running and hand the output buffer to the finished + // set. The buffer itself moves: nothing is copied, and the emitter + // keeps appending to the same one. + { + let mut running = running_clone.lock().unwrap(); + if let Some(state) = running.remove(&exec_id) { + if !state.discard_output { + let mut finished = finished_clone.lock().unwrap(); + finished.insert(exec_id.clone(), state.output_buffer); + } + } + } + let success = exit_status.as_ref().map(|s| s.success()).unwrap_or(false); // Determine the correct status: @@ -617,28 +635,37 @@ impl ActionExecutor { /// Stop a running action by execution ID. /// - /// Marks the execution as stopped and sends SIGTERM to the entire process - /// group. The completion thread will see the stopped flag and emit a - /// `Stopped` status event once the process actually exits. + /// Marks the execution as stopped and hangs up its process group. The + /// completion thread will see the stopped flag and emit a `Stopped` status + /// event once the process actually exits. + /// + /// Does nothing for an execution whose process has already exited, or + /// that is unknown: it ends, or ended, with the status it earned. pub fn stop(&self, execution_id: &str) -> Result<()> { self.stop_with_options(execution_id, StopOptions::default()) } /// Stop a running action with configurable shutdown timing. pub fn stop_with_options(&self, execution_id: &str, options: StopOptions) -> Result<()> { - // Mark as stopped BEFORE sending the signal so the completion thread - // knows this was an intentional stop (not a crash/failure). - { - let mut stopped = self.stopped.lock().unwrap(); - stopped.insert(execution_id.to_string()); - } - // Read the PID but do NOT remove from the running map. The completion // thread needs the entry to move the output buffer to the finished set // and to emit the proper StatusChanged event. + // + // Mark as stopped BEFORE sending the signal so the completion thread + // knows this was an intentional stop (not a crash/failure), and only + // when there is a process to signal. The completion thread clears the + // mark when the process exits, under this same lock, so a mark made + // any later would never be cleared: not for an execution that is + // waiting to deliver the last of its output, and not for one that has + // finished. let pid = { let running = self.running.lock().unwrap(); - running.get(execution_id).and_then(|state| state.child_pid) + let pid = running.get(execution_id).and_then(|state| state.child_pid); + if pid.is_some() { + let mut stopped = self.stopped.lock().unwrap(); + stopped.insert(execution_id.to_string()); + } + pid }; if let Some(pid) = pid { @@ -696,6 +723,9 @@ impl ActionExecutor { /// Wait until all listed executions are no longer running, or until the timeout elapses. /// + /// An execution is running until its terminal status is due, which is + /// once its process has exited and its last output has been delivered. + /// /// Returns `true` if every execution completed before the timeout. pub fn wait_for_executions(&self, execution_ids: &[String], timeout: Duration) -> bool { let deadline = Instant::now() + timeout; @@ -750,13 +780,15 @@ impl ActionExecutor { }) } - /// Check if an action is currently running + /// Check if an action is currently running: started, and its terminal + /// status not yet due. That covers the moment after its process exits in + /// which the last of its output is still being delivered. pub fn is_running(&self, execution_id: &str) -> bool { let running = self.running.lock().unwrap(); running.contains_key(execution_id) } - /// Get all running execution IDs + /// Get all running execution IDs, as [`Self::is_running`] counts them pub fn get_running_ids(&self) -> Vec { let running = self.running.lock().unwrap(); running.keys().cloned().collect() diff --git a/crates/builderbot-actions/src/executor/tests.rs b/crates/builderbot-actions/src/executor/tests.rs index 90494a668..1a81da2e6 100644 --- a/crates/builderbot-actions/src/executor/tests.rs +++ b/crates/builderbot-actions/src/executor/tests.rs @@ -707,9 +707,14 @@ async fn a_batch_still_pending_at_exit_is_delivered_before_the_status() { // The interval never elapses, so "first" is still waiting in its batch // when the shell exits. The readers then time out, because the background // job holds the pipes open. + // + // This test has to meet the timeout, not just outlast it: "first" must be + // read before the wait for the readers gives up, and delivered before the + // flush does. The wait always runs its full length here, so the timeout + // is test time; it is long enough that a starved machine still makes it. let executor = ActionExecutor::with_limits(Limits { emit_interval: WAIT, - reader_drain_timeout: Duration::from_secs(2), + reader_drain_timeout: Duration::from_secs(10), ..Limits::default() }); let gate = Gate::closed(); @@ -737,3 +742,120 @@ async fn a_batch_still_pending_at_exit_is_delivered_before_the_status() { } assert_eq!(buffered_text(&executor, &id).as_deref(), Some("firstlate")); } + +// ============================================================================= +// Between the process exiting and its terminal status +// ============================================================================= + +/// Start a script whose shell prints "first" and exits at once, leaving a +/// background job that holds the output open until `gate` opens and then +/// prints "late". +/// +/// Returns once the executor has noticed the shell's exit. The execution is +/// then waiting for the rest of its output, and cannot report its terminal +/// status before the gate opens: the executor must be one whose wait for the +/// readers does not run out. +async fn run_sh_until_exited_with_output_open( + executor: &ActionExecutor, + gate: &Gate, +) -> (String, Receiver) { + let script = format!("printf first; ({}; printf late) &", gate.wait()); + let (id, events) = run_sh_until_output(executor, &script, "first").await; + wait_until("the shell's exit to be noticed", || { + let running = executor.running.lock().unwrap(); + running + .get(&id) + .is_none_or(|state| state.child_pid.is_none()) + }); + (id, events) +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn an_execution_is_running_until_its_terminal_status_is_due() { + let executor = ActionExecutor::with_limits(patient_limits()); + let gate = Gate::closed(); + let (id, events) = run_sh_until_exited_with_output_open(&executor, &gate).await; + + // The shell has exited, but nobody has been told so. Whoever asks now is + // still shown the execution, and will get its terminal status. + assert!(executor.is_running(&id)); + assert_eq!(executor.get_running_ids(), vec![id.clone()]); + assert!(!executor.wait_for_executions(std::slice::from_ref(&id), Duration::from_millis(50))); + // Its output is read as a running execution's is, and is not yet + // retained as a finished one's. + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("first")); + assert!(executor.finished.lock().unwrap().get(&id).is_none()); + assert!(!executor.clear_execution(&id)); + + gate.open(); + let outcome = wait_for_finish(&events); + + // The status follows the last of the output, and by the time it is + // reported the execution is finished to everything that asks. + outcome.assert_completed(); + assert_eq!(outcome.streamed_text(), "firstlate"); + assert!(!executor.is_running(&id)); + assert!(executor.get_running_ids().is_empty()); + assert!(executor.wait_for_executions(std::slice::from_ref(&id), Duration::ZERO)); + assert_eq!(buffered_text(&executor, &id).as_deref(), Some("firstlate")); + assert!(executor.finished.lock().unwrap().get(&id).is_some()); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn a_stop_after_the_process_has_exited_leaves_nothing_behind() { + let executor = ActionExecutor::with_limits(patient_limits()); + let gate = Gate::closed(); + let (id, events) = run_sh_until_exited_with_output_open(&executor, &gate).await; + + // The execution still shows as running, so it can still be stopped, but + // there is no process left to stop. The mark a stop leaves is cleared + // when the process exits, which has already happened, so none is left. + assert!(executor.is_running(&id)); + executor.stop(&id).unwrap(); + assert!(executor.stopped.lock().unwrap().is_empty()); + + gate.open(); + let outcome = wait_for_finish(&events); + + // It reports how it really ended. The job that outlived the shell was not + // signalled either: it ran on and wrote its line. + outcome.assert_completed(); + assert_eq!(outcome.streamed_text(), "firstlate"); + assert!(executor.stopped.lock().unwrap().is_empty()); + + // Nor does stopping a finished execution, or one that never was, leave a + // mark. + executor.stop(&id).unwrap(); + executor.stop("no-such-execution").unwrap(); + assert!(executor.stopped.lock().unwrap().is_empty()); +} + +#[tokio::test(flavor = "multi_thread", worker_threads = 2)] +async fn a_stopped_execution_reports_stopped_and_clears_its_mark() { + let executor = ActionExecutor::with_limits(patient_limits()); + let gate = Gate::closed(); + let (id, events) = run_sh_until_output( + &executor, + &format!("printf start; {}; printf end", gate.wait()), + "start", + ) + .await; + + // No escalation to SIGKILL: the hangup ends a plain `sh`, and a timer + // must not outlive the test holding a pid that may be reused. + executor + .stop_with_options( + &id, + StopOptions { + force_kill_after: None, + }, + ) + .unwrap(); + let outcome = wait_for_finish(&events); + + assert_eq!(outcome.status, ActionStatus::Stopped); + assert_eq!(outcome.exit_code, None); + assert_eq!(outcome.streamed_text(), "start"); + assert!(executor.stopped.lock().unwrap().is_empty()); + assert!(!executor.is_running(&id)); +} diff --git a/crates/builderbot-actions/src/output_buffer.rs b/crates/builderbot-actions/src/output_buffer.rs index fe23656cb..fdb33a135 100644 --- a/crates/builderbot-actions/src/output_buffer.rs +++ b/crates/builderbot-actions/src/output_buffer.rs @@ -38,8 +38,11 @@ pub(crate) struct OutputBuffer { dropped_bytes: u64, /// Bytes of output text pushed so far, retained or not. pushed_bytes: u64, - /// Whether the oldest retained block starts part-way through a line, - /// because the block evicted before it did not end on a line break. + /// Whether the oldest retained block starts part-way through a line: + /// the block evicted before it was output of the same stream and did not + /// end on a line break. A block of another stream is the start of a + /// separate write, so where the evicted one stopped says nothing about + /// it. head_is_partial_line: bool, max_bytes: usize, block_bytes: usize, @@ -115,7 +118,11 @@ impl OutputBuffer { }; self.retained_bytes -= block_cost(&evicted); self.dropped_bytes += evicted.chunk.len() as u64; - self.head_is_partial_line = !evicted.chunk.ends_with(['\n', '\r']); + self.head_is_partial_line = !evicted.chunk.ends_with(['\n', '\r']) + && self + .blocks + .front() + .is_some_and(|head| head.stream == evicted.stream); } } @@ -426,6 +433,31 @@ mod tests { assert!(retained.starts_with("line ")); } + #[test] + fn a_line_of_another_stream_at_the_cut_is_kept_whole() { + // Separate pipes, as a remote action has: stdout is cut off mid-line + // by a full pipe, and stderr then writes whole lines of its own. + let max_bytes = 2 * 1024; + let mut buffer = OutputBuffer::new(max_bytes); + let block_bytes = buffer.block_bytes; + buffer.push("stdout", &"o".repeat(block_bytes), 0); + let mut written = String::new(); + for line in 0..5 { + let text = format!("error {line} {}\n", "e".repeat(block_bytes / 2)); + buffer.push("stderr", &text, 0); + written.push_str(&text); + } + // Only the stdout block has gone, and it did not end on a line break. + assert_eq!(buffer.dropped_bytes, block_bytes as u64); + + let chunks = buffer.snapshot(); + // The stderr line that now comes first was written whole, so all of + // it is shown, and the notice counts the stdout block alone. + assert_eq!(chunks[0].chunk, truncation_notice(block_bytes as u64)); + assert_eq!(text_of(&chunks[1..]), written); + assert!(chunks[1..].iter().all(|c| c.stream == "stderr")); + } + #[test] fn carriage_return_redraws_are_capped_too() { let max_bytes = 4 * 1024;