diff --git a/apps/staged/src-tauri/src/actions/commands.rs b/apps/staged/src-tauri/src/actions/commands.rs index 0439ce6fc..d06a26d57 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() { @@ -1201,9 +1203,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); @@ -1316,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) } @@ -1514,6 +1549,192 @@ 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 + } + + /// Collects the `action_output` payload each output event becomes, and + /// passes on the terminal status and exit code the execution reports. + #[cfg(unix)] + struct RecordOutput { + output: std::sync::Mutex>, + finished: std::sync::Mutex< + std::sync::mpsc::Sender<(builderbot_actions::ActionStatus, Option)>, + >, + } + + #[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 { + status, exit_code, .. + } => { + let _ = self.finished.lock().unwrap().send((status, exit_code)); + } + 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): 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(); + 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. + 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"); + 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, 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()); + 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() { + 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/actions/events.rs b/apps/staged/src-tauri/src/actions/events.rs index 578c420e9..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 @@ -72,7 +76,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(), @@ -103,11 +108,14 @@ impl ExecutionListener for TauriExecutionListener { execution_id, chunk, stream, + offset, .. } => { // 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( @@ -117,6 +125,7 @@ impl ExecutionListener for TauriExecutionListener { execution_id, chunk, stream, + offset, }, ); } 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/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/apps/staged/src-tauri/src/terminal_output.rs b/apps/staged/src-tauri/src/terminal_output.rs index 78183b4f7..ffc146d5d 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,54 @@ 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. + /// + /// 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 { + 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 +73,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 +105,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 +171,50 @@ 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; + }; + // 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; + }; + self.finalized_bytes -= dropped.len(); + self.dropped_lines += 1; } } } @@ -269,10 +352,103 @@ 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_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(); + 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/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..3f5a67529 --- /dev/null +++ b/apps/staged/src/lib/features/actions/outputFollower.test.ts @@ -0,0 +1,502 @@ +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(''); + + // 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(); + 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..4be31fbf7 --- /dev/null +++ b/apps/staged/src/lib/features/actions/outputFollower.ts @@ -0,0 +1,229 @@ +/** + * 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; + /** 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. */ + 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; + lastSnapshotFailed = false; + 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 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; + } + + 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; + } + 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; + 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 2fb50dd93..9d67774f0 100644 --- a/crates/builderbot-actions/src/executor.rs +++ b/crates/builderbot-actions/src/executor.rs @@ -2,20 +2,42 @@ //! //! Manages spawning shell commands with real-time output streaming, //! tracking running processes, and handling termination. +//! +//! 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. 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::models::{ActionStatus, ExecutionEvent, OutputChunk}; +use crate::finished_outputs::{FinishedOutputs, MAX_FINISHED_EXECUTIONS}; +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; + +#[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. +/// +/// 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); // ============================================================================= // PTY support (unix only) @@ -110,19 +132,59 @@ impl Default for StopOptions { } } -/// Internal state for a running action +/// 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, + /// 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 { + fn default() -> Self { + Self { + 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, + } + } +} + +/// 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: 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`. + /// + /// 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, } impl Default for ActionExecutor { @@ -131,66 +193,63 @@ 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, 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: Arc>>, - handle: Handle, + output: OutputSender, + done: mpsc::Sender, ) { thread::spawn(move || { + let _done = done; + + // 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) => 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, } } + output.send(stream_name, decoder.finish(), now_timestamp()); }); } +/// 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, deadline: Instant) -> bool { + matches!( + readers_done.recv_timeout(deadline.saturating_duration_since(Instant::now())), + 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 +272,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 +283,7 @@ impl ActionExecutor { RunningActionState { child_pid: Some(child_pid), output_buffer: output_buffer.clone(), + discard_output: false, }, ); } @@ -241,70 +301,96 @@ 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 // 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, - "stdout", - execution_id.clone(), - listener.clone(), - output_buffer.clone(), - handle.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(), - ); + 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(), - ); + spawn_stream_reader(stderr, "stderr", output.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(); 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) + let mut running = running_clone.lock().unwrap(); + if let Some(state) = running.get_mut(&exec_id) { + state.child_pid = None; + } + stopped_clone.lock().unwrap().remove(&exec_id) }; - // Move output buffer to completed actions map and remove from running + // 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); + + // 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) { - 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); + } } } @@ -549,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 completed map + // 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 { @@ -628,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; @@ -652,38 +750,71 @@ impl ActionExecutor { } } - /// Get buffered output for an execution - 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); + /// 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. + /// + /// 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(); + 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. 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 + /// 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() } - /// 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..1a81da2e6 --- /dev/null +++ b/crates/builderbot-actions/src/executor/tests.rs @@ -0,0 +1,861 @@ +//! 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 +//! 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, + /// The offset each of those events said its text starts at. + offsets: 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(); + let mut offsets = Vec::new(); + loop { + match events + .recv_timeout(WAIT) + .expect("the execution did not finish") + { + ExecutionEvent::Started { .. } => {} + ExecutionEvent::Output { chunk, offset, .. } => { + streamed.push(chunk); + offsets.push(offset); + } + ExecutionEvent::StatusChanged { + status, exit_code, .. + } => { + return Outcome { + streamed, + offsets, + 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(|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 +/// 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().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 + // 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 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()); + 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_eq!(outcome.streamed_text(), written); + 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); + } +} + +#[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 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![ + 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", + output.clone(), + reader_done, + ); + assert!(wait_for_readers(&readers_done, Instant::now() + WAIT)); + assert!(output.flush_by(Instant::now() + 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, and whole. + 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")); +} + +// ============================================================================= +// 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. + // + // 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(10), + ..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")); +} + +// ============================================================================= +// 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/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..1d198dabc 100644 --- a/crates/builderbot-actions/src/lib.rs +++ b/crates/builderbot-actions/src/lib.rs @@ -53,10 +53,16 @@ pub mod acp_provider; pub mod detector; pub mod executor; +mod finished_outputs; pub mod models; +mod output_buffer; +mod output_emitter; +mod utf8_stream; // Re-export main types for convenience 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 new file mode 100644 index 000000000..fdb33a135 --- /dev/null +++ b/crates/builderbot-actions/src/output_buffer.rs @@ -0,0 +1,497 @@ +//! 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, + /// Bytes of output text pushed so far, retained or not. + pushed_bytes: u64, + /// 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, +} + +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, + pushed_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 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) { + 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)); + 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 => { + 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']) + && self + .blocks + .front() + .is_some_and(|head| head.stream == evicted.stream); + } + } + + /// 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 + /// 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 + } +} + +/// 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() +} + +/// 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 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 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); + 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 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; + 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/output_emitter.rs b/crates/builderbot-actions/src/output_emitter.rs new file mode 100644 index 000000000..ca43a14dc --- /dev/null +++ b/crates/builderbot-actions/src/output_emitter.rs @@ -0,0 +1,469 @@ +//! 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 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}; +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() { + // 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, 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, + })); + } + } + } + // 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); + } + + /// 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 { + 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()); + } +} 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(), ""); + } +}