console-rs / indicatif

A command line progress reporting library for Rust
MIT License
4.36k stars 241 forks source link

Dead lock if adding the same ProgressBar to MultiProgress more than once #503

Closed zhangkaizhao closed 1 year ago

zhangkaizhao commented 1 year ago

Build pass but dead lock while running. Tested with indicatif == 0.17.2.

use indicatif::{MultiProgress, ProgressBar, ProgressStyle};

fn main() {
    let mp = MultiProgress::new();
    let pb = ProgressBar::new(0);
    let style = ProgressStyle::with_template("{msg}").unwrap();
    pb.set_style(style);
    mp.add(pb.clone());
    mp.add(pb.clone());
    pb.set_message("Boom!");
    pb.finish();
}

Output while running:

thread 'main' panicked at 'rwlock write lock would result in deadlock', /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/sys/unix/locks/pthread_rwlock.rs:111:13
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'main' panicked at 'called `Result::unwrap()` on an `Err` value: PoisonError { .. }', /Users/kaizhao/.cargo/registry/src/mirrors.ustc.edu.cn-61ef6e0cd06fb9b8/indicatif-0.17.2/src/draw_target.rs:114:65
stack backtrace:
   0:        0x10580b682 - std::backtrace_rs::backtrace::libunwind::trace::h74d17ea919046bae
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:        0x10580b682 - std::backtrace_rs::backtrace::trace_unsynchronized::h2fc77fd5a14165ac
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:        0x10580b682 - std::sys_common::backtrace::_print_fmt::h2687aa7717781133
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/sys_common/backtrace.rs:65:5
   3:        0x10580b682 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hdc69a6f447628e71
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/sys_common/backtrace.rs:44:22
   4:        0x1058245aa - core::fmt::write::hb9e764fa47ae8444
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/fmt/mod.rs:1209:17
   5:        0x10580933c - std::io::Write::write_fmt::h8fc98987ed860a54
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/io/mod.rs:1682:15
   6:        0x10580b44a - std::sys_common::backtrace::_print::h882e8250b822b8b0
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/sys_common/backtrace.rs:47:5
   7:        0x10580b44a - std::sys_common::backtrace::print::h488fe4c0b1fb9d50
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/sys_common/backtrace.rs:34:9
   8:        0x10580cb16 - std::panicking::default_hook::{{closure}}::h5618ea3156b8b833
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:267:22
   9:        0x10580c867 - std::panicking::default_hook::h0421c26a8a92801c
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:286:9
  10:        0x10580d25d - std::panicking::rust_panic_with_hook::h57383cd32463c250
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:688:13
  11:        0x10580d013 - std::panicking::begin_panic_handler::{{closure}}::h1d1f7305cfe67fdd
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:579:13
  12:        0x10580bb18 - std::sys_common::backtrace::__rust_end_short_backtrace::hd8e12e82ff026bae
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/sys_common/backtrace.rs:137:18
  13:        0x10580ccdd - rust_begin_unwind
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:575:5
  14:        0x10582cd23 - core::panicking::panic_fmt::h7894cd1015cfee41
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/panicking.rs:65:14
  15:        0x10582cf75 - core::result::unwrap_failed::h3077b600131e58d4
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/result.rs:1791:5
  16:        0x1057c7a3c - core::result::Result<T,E>::unwrap::h3324c50c72235e7b
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/result.rs:1113:23
  17:        0x1057b5245 - indicatif::draw_target::ProgressDrawTarget::width::h10f484b78fe41f38
                               at /Users/kaizhao/.cargo/registry/src/mirrors.ustc.edu.cn-61ef6e0cd06fb9b8/indicatif-0.17.2/src/draw_target.rs:114:52
  18:        0x1057bffe9 - indicatif::state::BarState::draw::hef0a6bd659ade04e
                               at /Users/kaizhao/.cargo/registry/src/mirrors.ustc.edu.cn-61ef6e0cd06fb9b8/indicatif-0.17.2/src/state.rs:164:21
  19:        0x1057bfaa1 - indicatif::state::BarState::finish_using_style::h9e86e00fe3c32e82
                               at /Users/kaizhao/.cargo/registry/src/mirrors.ustc.edu.cn-61ef6e0cd06fb9b8/indicatif-0.17.2/src/state.rs:64:17
  20:        0x1057c0304 - <indicatif::state::BarState as core::ops::drop::Drop>::drop::h5500f1a4ff546e95
                               at /Users/kaizhao/.cargo/registry/src/mirrors.ustc.edu.cn-61ef6e0cd06fb9b8/indicatif-0.17.2/src/state.rs:195:9
  21:        0x1057aba55 - core::ptr::drop_in_place<indicatif::state::BarState>::ha76e737d2a9b1c57
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  22:        0x1057acca1 - core::ptr::drop_in_place<core::cell::UnsafeCell<indicatif::state::BarState>>::hae90256bc4473fc8
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  23:        0x1057acda1 - core::ptr::drop_in_place<std::sync::mutex::Mutex<indicatif::state::BarState>>::he96c415f95f3be34
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  24:        0x1057a26b4 - alloc::sync::Arc<T>::drop_slow::h58937141ea099b10
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1114:18
  25:        0x1057a2e14 - <alloc::sync::Arc<T> as core::ops::drop::Drop>::drop::h19ccb4630bd85572
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/alloc/src/sync.rs:1711:13
  26:        0x1057ab461 - core::ptr::drop_in_place<alloc::sync::Arc<std::sync::mutex::Mutex<indicatif::state::BarState>>>::h3fbcd49dd933d568
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  27:        0x1057ac465 - core::ptr::drop_in_place<indicatif::progress_bar::ProgressBar>::h70a0273cf2185db7
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ptr/mod.rs:490:1
  28:        0x10579e0ae - dead_lock_multiprogress_add_same_progressbar::main::hc8c00eaea5f96442
                               at /Users/kaizhao/lab/rust/indicatif/dead-lock-multiprogress-add-same-progressbar/src/main.rs:20:1
  29:        0x10579e21e - core::ops::function::FnOnce::call_once::h4f1d6e4dbc09e830
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ops/function.rs:251:5
  30:        0x10579e7d1 - std::sys_common::backtrace::__rust_begin_short_backtrace::h9302ea09b14b2009
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/sys_common/backtrace.rs:121:18
  31:        0x10579e024 - std::rt::lang_start::{{closure}}::he04aac1f5b3f6d23
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/rt.rs:166:18
  32:        0x105806834 - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h61195f273fbb2744
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/core/src/ops/function.rs:286:13
  33:        0x105806834 - std::panicking::try::do_call::h742c41daae50fa78
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:483:40
  34:        0x105806834 - std::panicking::try::h289fd06090f9252d
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:447:19
  35:        0x105806834 - std::panic::catch_unwind::h442e40ac2db064f5
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panic.rs:137:14
  36:        0x105806834 - std::rt::lang_start_internal::{{closure}}::haebd6112c3b7ec52
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/rt.rs:148:48
  37:        0x105806834 - std::panicking::try::do_call::h5621965127b9aadb
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:483:40
  38:        0x105806834 - std::panicking::try::h55c66b03bc020b32
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panicking.rs:447:19
  39:        0x105806834 - std::panic::catch_unwind::hf00d6becf2cfdae2
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/panic.rs:137:14
  40:        0x105806834 - std::rt::lang_start_internal::h9ca2efac34d80f78
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/rt.rs:148:20
  41:        0x10579dff7 - std::rt::lang_start::hd9833a935556224b
                               at /rustc/69f9c33d71c871fc16ac445211281c6e7a340943/library/std/src/rt.rs:165:17
  42:        0x10579e1e8 - _main
thread panicked while panicking. aborting.
chris-laplante commented 1 year ago

Like the documentation says, a ProgressBar is just a wrapper around an Arc, so cloning doesn't really create a new ProgressBar: https://docs.rs/indicatif/latest/indicatif/struct.ProgressBar.html. There might be a way for us the catch this at runtime and prevent the panic, but in general I'd say this isn't a bug in indicatif. Perhaps we could use better documentation here though. @djc what do you think?

djc commented 1 year ago

I'm a little unclear on why this makes us crash? It seems like it might be reasonable to, on MultiProgress::add(), do some kind of pointer equality comparison on the Arc<ProgressBar> and make adding known progress bars a second time a no-op?

In principle I agree that it is the caller's error, but if we can't make it statically impossible (which in this case isn't really possible) it would be nice if at least we make it error in a less painful and/or more obvious way.

chris-laplante commented 1 year ago

The hang occurs because MultiProgress::internalize takes the MultiState write lock:

https://github.com/console-rs/indicatif/blob/98ae38d4463937ca6819537f8d95c97667093d7f/src/multi.rs#L135-L141

but so does disconnect:

https://github.com/console-rs/indicatif/blob/98ae38d4463937ca6819537f8d95c97667093d7f/src/draw_target.rs#L178-L183

I can make this a no-op by adding drop(state); after line 138 in multi.rs. Or, I can make it panic by doing a pointer comparison like @djc suggested.

I can't think of any reason why someone would want to do this purposely, so I'm leaning towards making it panic. Any thoughts?

djc commented 1 year ago

I mean, if there are no ill effects of doing so than making it a no-op seems better than making it panic. Why crash someone's program if we don't need to?

chris-laplante commented 1 year ago

I mean, if there are no ill effects of doing so than making it a no-op seems better than making it panic. Why crash someone's program if we don't need to?

OK, that's fair. I will make the change and add some documentation for the behavior.