diff --git a/src/executor/helpers/run_command_with_log_pipe.rs b/src/executor/helpers/run_command_with_log_pipe.rs index b20f06834..56f6b9dd0 100644 --- a/src/executor/helpers/run_command_with_log_pipe.rs +++ b/src/executor/helpers/run_command_with_log_pipe.rs @@ -1,6 +1,5 @@ use crate::executor::EXECUTOR_TARGET; -use crate::local_logger::rolling_buffer::ROLLING_BUFFER; -use crate::local_logger::suspend_progress_bar; +use crate::local_logger::write_command_output; use crate::prelude::*; use std::future::Future; use std::io::{Read, Write}; @@ -26,19 +25,6 @@ where F: FnOnce(std::process::Child) -> Fut, Fut: Future>, { - /// Write text to the rolling buffer if active, otherwise write raw bytes to the writer. - fn write_to_rolling_buffer_or_output(text: &str, raw_bytes: &[u8], writer: &mut impl Write) { - if let Ok(mut guard) = ROLLING_BUFFER.lock() { - if let Some(rb) = guard.as_mut() { - if rb.is_active() { - rb.push_lines(text); - return; - } - } - } - suspend_progress_bar(|| writer.write_all(raw_bytes).unwrap()); - } - fn log_tee( mut reader: impl Read, mut writer: impl Write, @@ -55,7 +41,7 @@ where if !line_buffer.is_empty() { let text = String::from_utf8_lossy(&line_buffer); trace!(target: EXECUTOR_TARGET, "{prefix}{text}"); - write_to_rolling_buffer_or_output(&text, &line_buffer, &mut writer); + write_command_output(&text, &line_buffer, &mut writer); } break; } @@ -71,7 +57,7 @@ where let to_flush = &line_buffer[..=last_newline_pos]; let text = String::from_utf8_lossy(to_flush); trace!(target: EXECUTOR_TARGET, "{prefix}{text}"); - write_to_rolling_buffer_or_output(&text, to_flush, &mut writer); + write_command_output(&text, to_flush, &mut writer); // Keep the remainder in the buffer line_buffer = line_buffer[last_newline_pos + 1..].to_vec(); diff --git a/src/executor/mod.rs b/src/executor/mod.rs index 80d31ea87..bbc69ca09 100644 --- a/src/executor/mod.rs +++ b/src/executor/mod.rs @@ -14,7 +14,6 @@ mod valgrind; mod wall_time; use crate::instruments::mongo_tracer::{MongoTracer, install_mongodb_tracer}; -use crate::local_logger::rolling_buffer::{activate_rolling_buffer, deactivate_rolling_buffer}; use crate::prelude::*; use crate::runner_mode::RunnerMode; use crate::system::SystemInfo; @@ -158,7 +157,7 @@ pub async fn run_executor( orchestrator: &Orchestrator, execution_context: &ExecutionContext, setup_cache_dir: Option<&Path>, - rolling_buffer_label: Option<&str>, + display_label: Option<&str>, ) -> Result<()> { match executor.support_level(&orchestrator.system_info) { ExecutorSupport::Unsupported => { @@ -199,12 +198,11 @@ pub async fn run_executor( None }; - if let Some(label) = rolling_buffer_label { - activate_rolling_buffer(label); - } + let display_guard = + display_label.and_then(|label| orchestrator.provider.start_command_display(label)); let run_result = executor.run(execution_context, &mongo_tracer).await; - if rolling_buffer_label.is_some() { - deactivate_rolling_buffer(); + if let Some(guard) = display_guard { + guard.finish_with(run_result.is_ok()); } run_result?; diff --git a/src/executor/orchestrator.rs b/src/executor/orchestrator.rs index ef7ad77a4..ff8a10f32 100644 --- a/src/executor/orchestrator.rs +++ b/src/executor/orchestrator.rs @@ -150,15 +150,14 @@ impl Orchestrator { let ctx = ExecutionContext::new(config, profile_folder); - let rolling_buffer_label = - (!self.config.show_full_output).then_some(part.label.as_str()); + let display_label = (!self.config.show_full_output).then_some(part.label.as_str()); run_executor( executor.as_mut(), self, &ctx, setup_cache_dir, - rolling_buffer_label, + display_label, ) .await?; diff --git a/src/local_logger/mod.rs b/src/local_logger/mod.rs index 4c09a9c2c..86c295284 100644 --- a/src/local_logger/mod.rs +++ b/src/local_logger/mod.rs @@ -3,7 +3,10 @@ pub mod rolling_buffer; use std::{ env, - sync::{Arc, Mutex}, + sync::{ + Arc, Mutex, + atomic::{AtomicBool, Ordering}, + }, time::Duration, }; @@ -37,6 +40,24 @@ static CURRENT_GROUP_NAME: LazyLock>>> = /// Flushed in `draw_frame` before each redraw. static DEFERRED_LOGS: LazyLock>> = LazyLock::new(|| Mutex::new(Vec::new())); +/// Set while a rolling buffer owns the terminal region. `LocalLogger` then +/// defers its records (see [`DEFERRED_LOGS`]) instead of printing directly, +/// as any direct stderr output would corrupt the frame. +static ROLLING_BUFFER_ACTIVE: AtomicBool = AtomicBool::new(false); + +fn set_rolling_buffer_active(active: bool) { + ROLLING_BUFFER_ACTIVE.store(active, Ordering::Relaxed); +} + +/// Write a chunk of benchmark command output to the terminal: into the rolling +/// buffer when one is active, otherwise verbatim to `writer`. +pub(crate) fn write_command_output(text: &str, raw_bytes: &[u8], writer: &mut impl Write) { + if rolling_buffer::try_push(text) { + return; + } + suspend_progress_bar(|| writer.write_all(raw_bytes).unwrap()); +} + /// A snapshot of a log record that can be stored across the rolling-buffer /// lifetime (the original `log::Record` borrows data and cannot be kept). struct DeferredLog { @@ -143,20 +164,15 @@ impl Log for LocalLogger { // When the rolling buffer is active it owns the terminal region and uses // cursor manipulation to redraw. Any direct stderr output would corrupt // the display, so we defer log records and flush them before each redraw. - { - use rolling_buffer::ROLLING_BUFFER; - if let Ok(guard) = ROLLING_BUFFER.try_lock() { - if guard.as_ref().is_some_and(|rb| rb.is_active()) { - if let Ok(mut deferred) = DEFERRED_LOGS.try_lock() { - deferred.push(DeferredLog { - level: record.level(), - message: format!("{}", record.args()), - target: record.target().to_string(), - }); - } - return; - } + if ROLLING_BUFFER_ACTIVE.load(Ordering::Relaxed) { + if let Ok(mut deferred) = DEFERRED_LOGS.try_lock() { + deferred.push(DeferredLog { + level: record.level(), + message: format!("{}", record.args()), + target: record.target().to_string(), + }); } + return; } suspend_progress_bar(|| print_record(record)); @@ -190,6 +206,15 @@ pub(crate) fn format_checkmark(label: &str, dim: bool) -> String { ) } +/// Format a failure cross with a label. +pub(crate) fn format_cross(label: &str) -> String { + format!( + " {} {}", + style(Icon::Error.to_string()).red().bold(), + label + ) +} + /// Format elapsed duration in a compact human-readable way fn format_elapsed(duration: Duration) -> String { let secs = duration.as_secs(); diff --git a/src/local_logger/rolling_buffer/mod.rs b/src/local_logger/rolling_buffer/mod.rs index a915b613d..7a709e9da 100644 --- a/src/local_logger/rolling_buffer/mod.rs +++ b/src/local_logger/rolling_buffer/mod.rs @@ -1,31 +1,35 @@ use std::collections::VecDeque; -use std::sync::Mutex; use std::sync::atomic::{AtomicBool, Ordering}; +use std::sync::{Arc, LazyLock, Mutex}; use std::time::{Duration, Instant}; use super::{ CODSPEED_U8_COLOR_CODE, IS_TTY, SPINNER, SPINNER_TICKS, TICK_INTERVAL_MS, format_checkmark, - icons::Icon, + format_cross, icons::Icon, }; use console::{Term, style}; -use std::sync::LazyLock; const INDENT: &str = " "; -/// Global shared rolling buffer, set by `activate_rolling_buffer` and -/// consumed by `log_tee` in `run_command_with_log_pipe`. -pub(crate) static ROLLING_BUFFER: LazyLock>> = - LazyLock::new(|| Mutex::new(None)); +/// Currently active rolling buffer, installed by [`RollingBufferGuard::activate`] +/// and fed through [`super::write_command_output`]. +static ACTIVE_BUFFER: LazyLock>> = LazyLock::new(|| Mutex::new(None)); -/// Stop signal for the tick thread. +/// Push command output into the active rolling buffer. /// -/// The rolling buffer manages its own background tick thread rather than using -/// `ProgressBar` because it renders a multi-line frame (title + bordered log box) -/// via direct terminal cursor manipulation. `ProgressBar` only manages a single -/// line and would conflict with the rolling buffer's cursor movements. -static TICK_STOP: AtomicBool = AtomicBool::new(false); +/// Returns `false` when no buffer is active so the caller can fall back to +/// plain output. +pub(super) fn try_push(text: &str) -> bool { + if let Ok(mut guard) = ACTIVE_BUFFER.lock() { + if let Some(rb) = guard.as_mut() { + rb.push_lines(text); + return true; + } + } + false +} -pub struct RollingBuffer { +struct RollingBuffer { lines: VecDeque, max_lines: usize, total_lines: usize, @@ -69,7 +73,7 @@ impl RollingBuffer { } } - pub fn is_active(&self) -> bool { + fn is_active(&self) -> bool { self.active } @@ -89,7 +93,7 @@ impl RollingBuffer { } } - pub fn push_lines(&mut self, text: &str) { + fn push_lines(&mut self, text: &str) { if !self.active { return; } @@ -190,10 +194,14 @@ impl RollingBuffer { frame } - /// Render the finished frame (checkmark title instead of spinner). - fn render_finished_frame(&self) -> Vec { + /// Render the finished frame (result mark title instead of spinner). + fn render_finished_frame(&self, success: bool) -> Vec { let mut frame = Vec::new(); - frame.push(format_checkmark(&self.title, false)); + frame.push(if success { + format_checkmark(&self.title, false) + } else { + format_cross(&self.title) + }); frame.push(self.render_top_delimiter()); for line in &self.lines { frame.push(self.render_content_line(line)); @@ -256,16 +264,16 @@ impl RollingBuffer { self.draw_frame(&frame); } - /// Finish the rolling display, replacing the spinner title with a checkmark - /// and leaving the last content lines visible on screen. - pub fn finish(&mut self) { + /// Finish the rolling display, replacing the spinner title with a result + /// mark and leaving the last content lines visible on screen. + fn finish(&mut self, success: bool) { if self.finished || self.rendered_count == 0 { self.finished = true; return; } self.finished = true; - let frame = self.render_finished_frame(); + let frame = self.render_finished_frame(success); self.draw_frame(&frame); self.rendered_count = 0; } @@ -274,63 +282,106 @@ impl RollingBuffer { impl Drop for RollingBuffer { fn drop(&mut self) { if !self.finished { - self.finish(); + self.finish(true); } } } -/// Activate a rolling buffer for the current executor run. +/// Scope guard for the rolling-buffer display of one executor run. /// -/// Suspends the group spinner and installs a shared rolling buffer that -/// `run_command_with_log_pipe` will automatically pick up. Starts a background -/// tick thread to keep the spinner animating. -pub fn activate_rolling_buffer(title: &str) { - if !*IS_TTY { - return; - } - let rb = RollingBuffer::new(title); - if !rb.is_active() { - return; - } - // Suspend the group spinner so it doesn't interfere with rolling output - if let Ok(mut spinner) = SPINNER.lock() { - if let Some(pb) = spinner.take() { - pb.suspend(|| eprintln!()); - pb.finish_and_clear(); +/// While alive, benchmark command output is rendered inside a live frame +/// (title + bordered log box) and `LocalLogger` records are deferred so they +/// don't corrupt it. Dropping the guard finalizes the frame, stops the tick +/// thread, and restores normal output. +pub struct RollingBufferGuard { + /// Stop signal for the tick thread. + /// + /// The guard manages its own background tick thread rather than using + /// `ProgressBar` because the frame is multi-line and drawn via direct + /// cursor manipulation; `ProgressBar` only manages a single line and would + /// conflict with the frame's cursor movements. + tick_stop: Arc, +} + +impl RollingBufferGuard { + /// Activate a rolling buffer titled `title`. + /// + /// Returns `None` when stderr is not an interactive terminal able to host + /// the frame; command output then falls through to plain display. + pub(crate) fn activate(title: &str) -> Option { + if !*IS_TTY { + return None; } - } - *ROLLING_BUFFER.lock().unwrap() = Some(rb); - - // Start a background thread that redraws periodically to animate the spinner - TICK_STOP.store(false, Ordering::Relaxed); - std::thread::spawn(|| { - while !TICK_STOP.load(Ordering::Relaxed) { - std::thread::sleep(Duration::from_millis(TICK_INTERVAL_MS)); - if TICK_STOP.load(Ordering::Relaxed) { - break; + let rb = RollingBuffer::new(title); + if !rb.is_active() { + return None; + } + + // Suspend the group spinner so it doesn't interfere with rolling output + if let Ok(mut spinner) = SPINNER.lock() { + if let Some(pb) = spinner.take() { + pb.suspend(|| eprintln!()); + pb.finish_and_clear(); + } + } + + super::set_rolling_buffer_active(true); + match ACTIVE_BUFFER.lock() { + Ok(mut slot) => *slot = Some(rb), + Err(_) => { + super::set_rolling_buffer_active(false); + return None; } - if let Ok(mut guard) = ROLLING_BUFFER.try_lock() { - if let Some(rb) = guard.as_mut() { - if rb.finished { + } + + // Background thread redrawing the title periodically to animate the spinner + let tick_stop = Arc::new(AtomicBool::new(false)); + std::thread::spawn({ + let tick_stop = Arc::clone(&tick_stop); + move || { + while !tick_stop.load(Ordering::Relaxed) { + std::thread::sleep(Duration::from_millis(TICK_INTERVAL_MS)); + if tick_stop.load(Ordering::Relaxed) { break; } - rb.redraw_title(); + if let Ok(mut guard) = ACTIVE_BUFFER.try_lock() { + if let Some(rb) = guard.as_mut() { + if rb.finished { + break; + } + rb.redraw_title(); + } + } } } - } - }); -} + }); -/// Finish and deactivate the current rolling buffer. -pub fn deactivate_rolling_buffer() { - // Stop the tick thread first - TICK_STOP.store(true, Ordering::Relaxed); + Some(Self { tick_stop }) + } - if let Ok(mut guard) = ROLLING_BUFFER.lock() { - if let Some(rb) = guard.as_mut() { - rb.finish(); + /// Finalize the frame, marking the title with a checkmark or a cross + /// according to `success`. + pub(crate) fn finish_with(self, success: bool) { + self.finalize(success); + } + + fn finalize(&self, success: bool) { + // Stop the tick thread first so it cannot redraw over the final frame + self.tick_stop.store(true, Ordering::Relaxed); + + if let Ok(mut guard) = ACTIVE_BUFFER.lock() { + if let Some(rb) = guard.as_mut() { + rb.finish(success); + } + *guard = None; } - *guard = None; + super::set_rolling_buffer_active(false); + } +} +impl Drop for RollingBufferGuard { + fn drop(&mut self) { + // Idempotent fallback for scope exits that bypass `finish_with`. + self.finalize(true); } } diff --git a/src/run_environment/local/provider.rs b/src/run_environment/local/provider.rs index 2097a30f8..bdeff96b6 100644 --- a/src/run_environment/local/provider.rs +++ b/src/run_environment/local/provider.rs @@ -3,6 +3,8 @@ use git2::Repository; use simplelog::SharedLogger; use uuid::Uuid; +use crate::local_logger::rolling_buffer::RollingBufferGuard; + use crate::api_client::{ CodSpeedAPIClient, GetOrCreateProjectRepositoryPayload, GetOrCreateProjectRepositoryVars, SessionAndRepositoryOverview, SessionAndRepositoryOverviewError, @@ -342,6 +344,10 @@ impl RunEnvironmentProvider for LocalProvider { get_local_logger() } + fn start_command_display(&self, label: &str) -> Option { + RollingBufferGuard::activate(label) + } + fn get_run_environment(&self) -> RunEnvironment { RunEnvironment::Local } diff --git a/src/run_environment/provider.rs b/src/run_environment/provider.rs index 317ac2178..ad3cf32b9 100644 --- a/src/run_environment/provider.rs +++ b/src/run_environment/provider.rs @@ -13,6 +13,7 @@ use crate::upload::{ }; use super::interfaces::{RepositoryProvider, RunEnvironment, RunEnvironmentMetadata, RunPart}; +use crate::local_logger::rolling_buffer::RollingBufferGuard; pub trait RunEnvironmentDetector { /// Detects if the runner is currently executed within this run environment. @@ -33,6 +34,16 @@ pub trait RunEnvironmentProvider { /// Returns the logger for the RunEnvironment. fn get_logger(&self) -> Box; + /// Start the live display of a benchmark command's output, titled `label`. + /// The returned guard scopes the display to the command's execution. + /// + /// This only affects the on-screen rendering: the raw output is always + /// persisted to the runner log file. Returning `None` displays the output + /// verbatim, which is what CI job logs expect. + fn start_command_display(&self, _label: &str) -> Option { + None + } + /// Returns the repository provider for this RunEnvironment fn get_repository_provider(&self) -> RepositoryProvider;