diff --git a/src/commands/tui.rs b/src/commands/tui.rs index 80c78c1f5..a39022d9b 100644 --- a/src/commands/tui.rs +++ b/src/commands/tui.rs @@ -15,6 +15,7 @@ pub use snapshots::Snapshots; use std::io; use std::sync::{Arc, RwLock}; +use crate::config::logging::TuiLogCapture; use anyhow::Result; use crossterm::event::{KeyEvent, KeyModifiers}; use crossterm::{ @@ -38,18 +39,26 @@ impl TuiResult for bool { } pub fn run(f: impl FnOnce(TuiProgressBars) -> Result<()>) -> Result<()> { - // setup terminal + // Keep console logs off the TUI; flush them after the terminal is restored. + let log_capture = TuiLogCapture::start(); + let terminal = init_terminal()?; let terminal = Arc::new(RwLock::new(terminal)); - // restore terminal (even when leaving through ?, early return, or panic) - defer! { - reset_terminal().unwrap(); - } + let result = { + // restore terminal (even when leaving through ?, early return, or panic) + defer! { + reset_terminal().unwrap(); + } + + let progress = TuiProgressBars { terminal }; + f(progress) + }; - let progress = TuiProgressBars { terminal }; + // Terminal is back to cooked mode; now replay captured logs and errors. + drop(log_capture); - if let Err(err) = f(progress) { + if let Err(err) = result { println!("{err:?}"); } diff --git a/src/config/logging.rs b/src/config/logging.rs index 42d14f027..41a4ef89b 100644 --- a/src/config/logging.rs +++ b/src/config/logging.rs @@ -1,4 +1,7 @@ -use std::{path::PathBuf, sync::OnceLock}; +use std::collections::VecDeque; +use std::io::Write; +use std::path::PathBuf; +use std::sync::{Mutex, MutexGuard, OnceLock, PoisonError}; use anyhow::Result; use clap::{Parser, ValueHint}; @@ -19,6 +22,103 @@ use serde_with::{DisplayFromStr, serde_as}; use crate::config::progress_options::multi_progress; +/// Maximum console log records held while the TUI owns the terminal. +const MAX_CAPTURED_CONSOLE_LOGS: usize = 256; + +struct ConsoleCaptureState { + /// Number of live [`TuiLogCapture`] guards. + depth: usize, + records: VecDeque, + dropped: usize, +} + +static CONSOLE_CAPTURE: Mutex = Mutex::new(ConsoleCaptureState { + depth: 0, + records: VecDeque::new(), + dropped: 0, +}); + +fn console_capture() -> MutexGuard<'static, ConsoleCaptureState> { + CONSOLE_CAPTURE + .lock() + .unwrap_or_else(PoisonError::into_inner) +} + +/// Divert console log output away from the terminal while the TUI is active. +/// +/// File logging is unaffected. When the last guard is dropped, captured messages +/// are printed to stderr (after the TUI should have restored the terminal). +#[derive(Debug)] +pub struct TuiLogCapture { + _private: (), +} + +impl TuiLogCapture { + /// Start capturing console logs until this guard is dropped. + #[must_use = "console logs are only captured while this guard is alive"] + pub fn start() -> Self { + let mut state = console_capture(); + if state.depth == 0 { + state.records.clear(); + state.dropped = 0; + } + state.depth = state.depth.saturating_add(1); + drop(state); + Self { _private: () } + } +} + +impl Drop for TuiLogCapture { + fn drop(&mut self) { + let captured = { + let mut state = console_capture(); + state.depth = state.depth.saturating_sub(1); + if state.depth == 0 { + Some(( + std::mem::take(&mut state.records), + std::mem::take(&mut state.dropped), + )) + } else { + None + } + }; + + if let Some((records, dropped)) = captured { + write_captured_console_logs(std::io::stderr(), records, dropped); + } + } +} + +fn write_captured_console_logs(mut writer: impl Write, records: VecDeque, dropped: usize) { + if dropped > 0 { + _ = writeln!(writer, "[{dropped} older log messages omitted]"); + } + for record in records { + _ = writeln!(writer, "{record}"); + } +} + +/// Capture `record` when a TUI session owns the terminal. +/// +/// Returns `true` if the record was captured and must not be written to the +/// console (which would overwrite the TUI). +fn capture_console_log(record: &log::Record<'_>) -> bool { + let mut state = console_capture(); + if state.depth == 0 { + return false; + } + + if state.records.len() >= MAX_CAPTURED_CONSOLE_LOGS { + _ = state.records.pop_front(); + state.dropped = state.dropped.saturating_add(1); + } + state + .records + .push_back(format!("[{}] {}", record.level(), record.args())); + drop(state); + true +} + /// Logging Config #[serde_as] #[derive(Default, Debug, Parser, Clone, Deserialize, Serialize, Merge)] @@ -123,12 +223,19 @@ impl LoggingOptions { } } -/// A wrapper around [`ConsoleAppender`] that suspends the progress bar when writing logs. +/// Console appender that coordinates with progress bars and the TUI. +/// +/// While a [`TuiLogCapture`] guard is active, records are buffered instead of +/// being written to the terminal. Otherwise the indicatif progress bar is +/// suspended for the duration of the write. #[derive(Debug)] struct PbPauseAppender(ConsoleAppender); impl log4rs::append::Append for PbPauseAppender { fn append(&self, record: &log::Record<'_>) -> Result<()> { + if capture_console_log(record) { + return Ok(()); + } multi_progress().suspend(|| self.0.append(record)) } @@ -141,3 +248,141 @@ impl log4rs::append::Append for PbPauseAppender { self.0.flush(); } } + +#[cfg(test)] +mod tests { + use super::*; + use std::sync::Mutex; + + static TEST_LOCK: Mutex<()> = Mutex::new(()); + + fn lock_tests() -> MutexGuard<'static, ()> { + TEST_LOCK.lock().unwrap_or_else(PoisonError::into_inner) + } + + fn reset_capture() { + let mut state = console_capture(); + state.depth = 0; + state.records.clear(); + state.dropped = 0; + } + + fn capture_warn(msg: &str) -> bool { + capture_console_log( + &log::Record::builder() + .args(format_args!("{msg}")) + .level(log::Level::Warn) + .target("test") + .build(), + ) + } + + fn snapshot() -> (usize, Vec, usize) { + let state = console_capture(); + ( + state.depth, + state.records.iter().cloned().collect(), + state.dropped, + ) + } + + fn drain_capture() { + let mut state = console_capture(); + state.records.clear(); + state.dropped = 0; + } + + #[test] + fn console_logs_pass_through_without_tui_capture() { + let _lock = lock_tests(); + reset_capture(); + assert!(!capture_warn("will retry Read")); + assert_eq!(snapshot(), (0, Vec::new(), 0)); + } + + #[test] + fn tui_capture_holds_console_logs_until_drop() { + let _lock = lock_tests(); + reset_capture(); + + let capture = TuiLogCapture::start(); + assert!(capture_warn("will retry Read (attempt 1)")); + assert!(capture_warn("still reading index")); + assert_eq!( + snapshot(), + ( + 1, + vec![ + "[WARN] will retry Read (attempt 1)".to_string(), + "[WARN] still reading index".to_string(), + ], + 0 + ) + ); + + drain_capture(); + drop(capture); + assert_eq!(snapshot(), (0, Vec::new(), 0)); + assert!(!capture_warn("after tui")); + } + + #[test] + fn nested_tui_capture_flushes_on_outermost_drop() { + let _lock = lock_tests(); + reset_capture(); + + let outer = TuiLogCapture::start(); + assert!(capture_warn("outer")); + { + let inner = TuiLogCapture::start(); + assert!(capture_warn("inner")); + drop(inner); + assert_eq!( + snapshot(), + ( + 1, + vec!["[WARN] outer".to_string(), "[WARN] inner".to_string()], + 0 + ) + ); + } + + drain_capture(); + drop(outer); + assert_eq!(snapshot(), (0, Vec::new(), 0)); + } + + #[test] + fn tui_capture_drops_oldest_records_when_full() { + let _lock = lock_tests(); + reset_capture(); + + let capture = TuiLogCapture::start(); + for i in 0..=MAX_CAPTURED_CONSOLE_LOGS { + assert!(capture_warn(&format!("msg {i}"))); + } + + let (depth, records, dropped) = snapshot(); + assert_eq!(depth, 1); + assert_eq!(dropped, 1); + assert_eq!(records.len(), MAX_CAPTURED_CONSOLE_LOGS); + assert_eq!(records[0], "[WARN] msg 1"); + assert_eq!( + records[MAX_CAPTURED_CONSOLE_LOGS - 1], + format!("[WARN] msg {MAX_CAPTURED_CONSOLE_LOGS}") + ); + + drain_capture(); + drop(capture); + } + + #[test] + fn captured_logs_replay_with_omission_notice() { + let mut out = Vec::new(); + write_captured_console_logs(&mut out, VecDeque::from(["[WARN] retry".to_string()]), 2); + assert_eq!( + String::from_utf8(out).unwrap(), + "[2 older log messages omitted]\n[WARN] retry\n" + ); + } +}