cpg

`indicatif` progress as `log` messages

2023-06-04 #rust

Outputting indicatif progress messages as log entries

The indicatif Rust crate provides ergonomic progress bars, that can be controlled manually or automatically as an iterator trait.

Conflicting logging and progress

Command line tools may simultaneously perform logging to the standard output, e.g. with the log and fern crates.

This combination is problematic, given that indicatif redraws the last output line, hiding some messages; see for example this issue. This can be particularly troublesome if the progress bar hides an ERROR log message before a program exits.

Progress as log messages

The following addresses this issue, implementing an indicatif::ProgressBar that outputs log messages at a given frequency.

Having information about progress (including e.g. speed) as part of the logs is also convenient.

use std::sync::Atomic;
 
/// Progress bar that logs to the terminal with a maximum update rate.
pub fn progress_bar_log(length: usize) -> indicatif::ProgressBar {
    let term = ProgressLogger::new();
    let bar = indicatif::ProgressBar::with_draw_target(
        Some(length as u64),
        indicatif::ProgressDrawTarget::term_like(Box::new(term)),
    );
    bar.set_style(style());
    bar
}
 
/// Progress bar target that logs to the terminal.
struct ProgressLogger {
    term: indicatif::InMemoryTerm,
    update_interval_s: u64,
    last_update: atomic::AtomicU64,
}
impl indicatif::TermLike for ProgressLogger {
    fn width(&self) -> u16 {
        self.term.width()
    }
    fn move_cursor_up(&self, n: usize) -> std::io::Result<()> {
        self.term.move_cursor_up(n)
    }
    fn move_cursor_down(&self, n: usize) -> std::io::Result<()> {
        self.term.move_cursor_down(n)
    }
    fn move_cursor_right(&self, n: usize) -> std::io::Result<()> {
        self.term.move_cursor_right(n)
    }
    fn move_cursor_left(&self, n: usize) -> std::io::Result<()> {
        self.term.move_cursor_left(n)
    }
    fn write_line(&self, s: &str) -> std::io::Result<()> {
        self.term.write_line(s)
    }
    fn write_str(&self, s: &str) -> std::io::Result<()> {
        self.term.write_str(s)
    }
    fn clear_line(&self) -> std::io::Result<()> {
        self.term.clear_line()
    }
    fn flush(&self) -> std::io::Result<()> {
        let timestamp = std::time::SystemTime::now()
            .duration_since(std::time::SystemTime::UNIX_EPOCH)
            .unwrap()
            .as_secs();
        let log = self
            .last_update
            .fetch_update(
                atomic::Ordering::Relaxed,
                atomic::Ordering::Relaxed,
                |last_update| {
                    (timestamp >= self.update_interval_s + last_update)
                        .then_some(timestamp)
                },
            )
            .is_ok();
        self.term.flush()?;
        if log {
            self.log();
        }
        Ok(())
    }
}
impl Drop for ProgressLogger {
    fn drop(&mut self) {
        self.log();
    }
}
impl ProgressLogger {
    fn new() -> Self {
        Self {
            term: indicatif::InMemoryTerm::new(1, 100),
            last_update: Default::default(),
            update_interval_s: 1,
        }
    }
    fn log(&self) {
        let contents = self.term.contents();
        if !contents.is_empty() {
            log::info!("{}", contents);
        }
    }
}