console-rs / indicatif

A command line progress reporting library for Rust
MIT License
4.22k stars 238 forks source link

Subtract with overflow when measuring line length in 0.17.4 #546

Closed foresterre closed 1 year ago

foresterre commented 1 year ago

In the report below I will describe an issue I encountered when depending on the latest indicatif release (0.17.4).

While I'm fairly certain this is an issue with indicatif, I wasn't able to create a minimal example yet (I tried, ), although this was before I further pinpointed where the issue is located.

Scroll to the bottom of this issue description to see where the issue is located. I expanded the issue description several times while writing it. Now it makes sense why I couldn't reproduce this issue in the first place.

Actual

Let's start at the beginning.

asciicast

Here, two things go wrong.

  1. Initially, a spinner is printed twice, and instead of the line being replaced, a secondary line is shown. This can be observed here: https://asciinema.org/a/589099?t=5

In this my code, I have the following, at this point:

self.pb.reset();
self.pb.set_message(format!("Rust {}", version));

Prior to this point, the message was not set (not sure if relevant).

  1. After starting a second check (happens sequentially), no more output is printed, and it seems like the progress bar hangs. This can be observed here: https://asciinema.org/a/589099?t=7.

I want to point out a few things:

  1. If you wait long enough, it will eventually print the following:

on Ubuntu:

[1]    7914 killed     cargo msrv

on Windows:

memory allocation of 34896609280 bytes failed

NB: that's 34.9 GB.

Expected

asciicast

Commands to reproduce

cargo install renders as expected indicatif version
cargo install cargo-msrv --version 0.16.0-beta.14 -f --no-default-features --locked 0.17.3
cargo install cargo-msrv --version 0.16.0-beta.14 -f --no-default-features 0.17.4

Issue @ cargo-msrv: https://github.com/foresterre/cargo-msrv/issues/706 Indicatif code in cargo-msrv: https://github.com/foresterre/cargo-msrv/blob/main/src/reporter/handler/human_progress_handler.rs

Notes

  1. While I used cargo install cargo-msrv --locked and cargo install cargo-msrv above, I double checked whether this wast most likely an issue with indicatif and not some other package, by also manually forcing the indicatif version to be either =0.17.3 and =0.17.4 in the Cargo manifest.

Investigating with Valgrind DHAT and beyond:

After running DHAT on cargo-msrv with indicatif 0.17.4, the problem can be pinpointed to indicatif-0.17.4/src/draw_target.rs:522:28.

DHAT output $ valgrind --tool=dhat cargo msrv [Meta] cargo-msrv 0.16.0-beta.14 Compatibility Check #1: Rust 1.63.0 ◓ Elapsed 0s [OK] Is compatible Compatibility Check #2: Rust 1.59.0 thread '' panicked at 'attempt to subtract with overflow', /home/foresterre/.cargo/registry/src/github.com-1ecc6299db9ec823/indicatif-0.17.4/src/draw_target.rs:522:28 note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

Turns out, I didn't even need DHAT; I should've been running in debug mode instead of release mode. Running with debug and backtrace on, clarifies this issue even further:

Backtrace cargo run -- msrv --path ..\justdbg\ Finished dev [unoptimized + debuginfo] target(s) in 0.41s Running `target\debug\cargo-msrv.exe msrv --path ..\justdbg\` [Meta] cargo-msrv 0.16.0-beta.14 Compatibility Check #1: Rust 1.63.0 ◓ Elapsed 0s [OK] Is compatible Compatibility Check #2: Rust 1.59.0 thread '' panicked at 'attempt to subtract with overflow', C:\foresterre\ws\indicatif\src\draw_target.rs:522:28 stack backtrace: 0: std::panicking::begin_panic_handler at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panicking.rs:578 1: core::panicking::panic_fmt at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\core\src\panicking.rs:67 2: core::panicking::panic at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\core\src\panicking.rs:117 3: indicatif::draw_target::DrawState::draw_to_term at C:\foresterre\ws\indicatif\src\draw_target.rs:522 4: enum2$::draw at C:\foresterre\ws\indicatif\src\draw_target.rs:328 5: indicatif::state::BarState::println at C:\foresterre\ws\indicatif\src\state.rs:160 6: indicatif::progress_bar::ProgressBar::println at C:\foresterre\ws\indicatif\src\progress_bar.rs:245 7: cargo_msrv::reporter::handler::human_progress_handler::impl$2::handle at .\src\reporter\handler\human_progress_handler.rs:91 8: cargo_msrv::impl$0::handle at .\src\bin\cargo-msrv.rs:119 9: storyteller::channel_reporter::listener::impl$1::run_handler::closure$0 > at C:\Users\foresterre\.cargo\registry\src\index.crates.io-6f17d22bba15001f\storyteller-0.8.0\src\channel_reporter\listener.rs:52 note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. thread '' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', C:\foresterre\ws\indicatif\src\progress_bar.rs:648:40 stack backtrace: 0: std::panicking::begin_panic_handler at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\std\src\panicking.rs:578 1: core::panicking::panic_fmt at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\core\src\panicking.rs:67 2: core::result::unwrap_failed at /rustc/90c541806f23a127002de5b4038be731ba1458ca/library\core\src\result.rs:1687 3: enum2$,std::sync::poison::PoisonError > > >::unwrap,std::sync:: at /rustc/90c541806f23a127002de5b4038be731ba1458ca\library\core\src\result.rs:1089 4: indicatif::progress_bar::TickerControl::run at C:\foresterre\ws\indicatif\src\progress_bar.rs:648 5: indicatif::progress_bar::impl$4::new::closure$0 at C:\foresterre\ws\indicatif\src\progress_bar.rs:624 note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace. error: process didn't exit successfully: `target\debug\cargo-msrv.exe msrv --path ..\justdbg\` (exit code: 1)

This line was last changed here: 75e8c59 (#533) as part of #533

Just to check: reverting this commit solves the issue, or alternatively, before this line, adding real_len = 1000; or a similar large enough number.

Diving deeper

I think the real cause is that console::measure_text_width(line) can be 0 for certain lines of text.

For example, if there is a ANSI color escape sequence (like the \u{1b}[1m below), console::measure_text_width will return 0, while the line is effectively "empty"; it is not enough to do just line.is_empty() in this case.

console::measure_text_width does call strip_ansi_codes.

An excerpt printing the lines: ``` Compatibility Check #2: Rust 1.59.0 [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "◑ Rust 1.63.0 Elapsed 0s" ◑ Rust 1.63.0 Elapsed 0s [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "◑ Rust 1.59.0 Elapsed 0s" ◑ Rust 1.59.0 Elapsed 0s [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "◐ Rust 1.59.0 Elapsed 0s" ◐ Rust 1.59.0 Elapsed 0s [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "◓ Rust 1.59.0 Elapsed 0s" ◓ Rust 1.59.0 Elapsed 0s [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "[\u{1b}[92mOK\u{1b}[39m] Is compatible" [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "◓ Rust 1.59.0 Elapsed 0s" [OK] Is compatible [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "\u{1b}[1m" [C:\foresterre\ws\indicatif\src\draw_target.rs:505] line.trim() = "Compatibility Check #3: Rust 1.57.0\u{1b}[0m" ```

I attempted a fix here: https://github.com/console-rs/indicatif/pull/547, which I works for cargo-msrv (but I'm not an expert in the inner workings of a terminal).