From 25511c1ea27d982a5baeb605c3c862b21c907e18 Mon Sep 17 00:00:00 2001 From: Brad Kollmyer Date: Thu, 3 Sep 2026 18:21:22 -0700 Subject: [PATCH 1/2] fix: do not write console logs over the interactive TUI Capture stderr logs while the TUI owns the terminal and print them after restoring cooked mode, so backend retry warnings cannot overwrite the progress popup. --- CHANGELOG.md | 6 + src/commands/tui.rs | 23 ++-- src/config/logging.rs | 249 +++++++++++++++++++++++++++++++++++++++++- 3 files changed, 269 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index fab39f71f..866f33136 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,12 @@ All notable changes to this project will be documented in this file. +## Unreleased + +### Fixed + +- do not write console logs over the interactive TUI; print them after the TUI exits + ## [0.11.4](https://github.com/rustic-rs/rustic/compare/v0.11.3...v0.11.4) - 2026-08-17 ### Added 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" + ); + } +} From f7ebf82bf55b6acad786d377d1ec4c922353fa40 Mon Sep 17 00:00:00 2001 From: Brad Kollmyer Date: Thu, 3 Sep 2026 22:10:43 -0700 Subject: [PATCH 2/2] chore: drop CHANGELOG edit; release-plz generates it --- CHANGELOG.md | 6 ------ 1 file changed, 6 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 866f33136..fab39f71f 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,12 +2,6 @@ All notable changes to this project will be documented in this file. -## Unreleased - -### Fixed - -- do not write console logs over the interactive TUI; print them after the TUI exits - ## [0.11.4](https://github.com/rustic-rs/rustic/compare/v0.11.3...v0.11.4) - 2026-08-17 ### Added