Subtract with overflow when measuring line length in 0.17.4

[foresterre]

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.

• indicatif 0.17.4 was released as patch release, as a result, it is pulled in automatically (unless using --locked)
• I was installing cargo-msrv without --locked, and saw some strange rendering issue, which I didn't see before:

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).

2. 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:

• cargo-msrv bisects different toolchain versions against a given project.
• I created a fresh cargo new --bin project, with the println!("Hello world") replaced by dbg!("Hello world") (to limit the MSRV to something reasonable). This should compile in less than a second (cargo check 0.13s user 0.17s system 21% cpu 1.414 total for me after cargo clean).
• All necessary toolchains were preinstalled, so cargo-msrv does not hang accidentally on installing a toolchain: https://asciinema.org/a/589099?t=26. As you can see in the "Expected" section below, it should finish quickly.

3. 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

• Before, it looked like this (correct):

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: foresterre/cargo-msrv#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_termconsole::term::Term
at C:\foresterre\ws\indicatif\src\draw_target.rs:522
4: enum2$indicatif::draw_target::Drawable::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::printlnalloc::string::String
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<cargo_msrv::reporter::event::Event,enum2$<cargo_msrv::WrappingHandler> >
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$<core::result::Result<std::sync::mutex::MutexGuardindicatif::state::BarState,std::sync::poison::PoisonError<std::sync::mutex::MutexGuardindicatif::state::BarState > > >::unwrap<std::sync::mutex::MutexGuardindicatif::state::BarState,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: #547, which I works for cargo-msrv (but I'm not an expert in the inner workings of a terminal).