Potential panic in FuturesUnordered

[gperinazzo]

EDIT(taiki-e): The regression that occurred in 0.3.18 has been fixed in 0.3.19, but the underlying problem that 0.3.18 tried to fix has not been fixed yet. This issue has been reused to track that problem as there is a detailed discussion on that problem.

---

Hey folks,

After upgrading to futures 0.3.18 from 0.3.17, we've noticed our application is panicking under high load. The panic seems to originate in src/stream/futures_unordered/ready_to_run_queue.rs:104 due to the error message inconsistent in drop:

thread 'tokio-runtime-worker' panicked at 'inconsistent in drop', /usr/local/cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/abort.rs:11:5

 stack backtrace:
    0: rust_begin_unwind
              at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:517:5
    1: std::panicking::begin_panic_fmt
              at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:460:5
    2: futures_util::stream::futures_unordered::abort::abort
    3: <futures_util::stream::futures_unordered::FuturesUnordered<Fut> as core::ops::drop::Drop>::drop
    4: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
    5: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
    6: <mysql_async::BoxFuture<T> as core::future::future::Future>::poll
    7: <mysql_async::conn::pool::futures::get_conn::GetConn as core::future::future::Future>::poll
    8: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
    9: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
   10: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
   11: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll

This panic causes a double panic that aborts the application. This seems to only happen when under high load, so it may be a race condition that only happens when there's multiple threads running futures from the FuturesUnordered. I haven't been able to create a minimal project to reproduce.

[gperinazzo]

Was able to make a minimal example. It's pretty unreliable so you may need to run it for a while. Running in debug also seems to trigger the error faster than running in release.

 use futures::stream::{FuturesUnordered, StreamExt};
 
 async fn run_loop() {
     async fn test() {
         tokio::spawn(async {
             tokio::time::sleep(std::time::Duration::from_millis(1)).await;
         })
         .await
         .unwrap();
     }
     loop {
         let mut futures = FuturesUnordered::new();
         for _ in 0..4 {
             futures.push(test());
         }
         let _ = futures.next().await;
         drop(futures);
     }
 }
 
 #[tokio::main]
 async fn main() {
     run_loop().await
 }

Here is the backtrace generated when it panics:

thread 'main' panicked at 'inconsistent in drop', /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/abort.rs:11:5
stack backtrace:
   0: rust_begin_unwind
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:517:5
   1: std::panicking::begin_panic_fmt
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:460:5
   2: futures_util::stream::futures_unordered::abort::abort
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/abort.rs:11:5
   3: futures_util::stream::futures_unordered::ready_to_run_queue::ReadyToRunQueue<Fut>::clear
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/ready_to_run_queue.rs:104:42
   4: <futures_util::stream::futures_unordered::FuturesUnordered<Fut> as core::ops::drop::Drop>::drop
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/mod.rs:580:18
   5: core::ptr::drop_in_place<futures_util::stream::futures_unordered::FuturesUnordered<core::future::from_generator::GenFuture<playground::run_loop::{{closure}}::test::{{closure}}>>>
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/ptr/mod.rs:188:1
   6: core::mem::drop
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/mem/mod.rs:898:24
   7: playground::run_loop::{{closure}}
             at ./src/main.rs:17:9
   8: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/future/mod.rs:80:19
   9: playground::main::{{closure}}
             at ./src/main.rs:23:5
  10: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/future/mod.rs:80:19
  11: tokio::park::thread::CachedParkThread::block_on::{{closure}}
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/park/thread.rs:263:54
  12: tokio::coop::with_budget::{{closure}}
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/coop.rs:106:9
  13: std::thread::local::LocalKey<T>::try_with
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/thread/local.rs:399:16
  14: std::thread::local::LocalKey<T>::with
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/thread/local.rs:375:9
  15: tokio::coop::with_budget
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/coop.rs:99:5
  16: tokio::coop::budget
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/coop.rs:76:5
  17: tokio::park::thread::CachedParkThread::block_on
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/park/thread.rs:263:31
  18: tokio::runtime::enter::Enter::block_on
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/runtime/enter.rs:151:13
  19: tokio::runtime::thread_pool::ThreadPool::block_on
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/runtime/thread_pool/mod.rs:77:9
  20: tokio::runtime::Runtime::block_on
             at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/runtime/mod.rs:463:43
  21: playground::main
             at ./src/main.rs:23:5
  22: core::ops::function::FnOnce::call_once
             at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
thread 'main' panicked at 'panicking twice to abort the program', /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/abort.rs:6:13
stack backtrace:
   0:     0x55f74103addc - std::backtrace_rs::backtrace::libunwind::trace::h3fea1eb2e0ba2ac9
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/../../backtrace/src/backtrace/libunwind.rs:90:5
   1:     0x55f74103addc - std::backtrace_rs::backtrace::trace_unsynchronized::h849d83492cbc0d59
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x55f74103addc - std::sys_common::backtrace::_print_fmt::he3179d37290f23d3
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/sys_common/backtrace.rs:67:5
   3:     0x55f74103addc - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::h140f6925cad14324
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/sys_common/backtrace.rs:46:22
   4:     0x55f74105698c - core::fmt::write::h31b9cd1bedd7ea38
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/fmt/mod.rs:1150:17
   5:     0x55f741038a65 - std::io::Write::write_fmt::h1fdf66f83f70913e
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/io/mod.rs:1667:15
   6:     0x55f74103c900 - std::sys_common::backtrace::_print::he7ac492cd19c3189
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/sys_common/backtrace.rs:49:5
   7:     0x55f74103c900 - std::sys_common::backtrace::print::hba20f8920229d8e8
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/sys_common/backtrace.rs:36:9
   8:     0x55f74103c900 - std::panicking::default_hook::{{closure}}::h714d63979ae18678
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:210:50
   9:     0x55f74103c4b7 - std::panicking::default_hook::hf1afb64e69563ca8
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:227:9
  10:     0x55f74103cfb4 - std::panicking::rust_panic_with_hook::h02231a501e274a13
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:624:17
  11:     0x55f7410242c2 - std::panicking::begin_panic::{{closure}}::h3e31aaa543823395
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:544:9
  12:     0x55f741023b79 - std::sys_common::backtrace::__rust_end_short_backtrace::h183aedad7027b78d
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/sys_common/backtrace.rs:141:18
  13:     0x55f741024203 - std::panicking::begin_panic::hab564a8571e43804
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:543:12
  14:     0x55f741023671 - <futures_util::stream::futures_unordered::abort::abort::DoublePanic as core::ops::drop::Drop>::drop::hd10fb214b1fe1391
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/abort.rs:6:13
  15:     0x55f7410236cb - core::ptr::drop_in_place<futures_util::stream::futures_unordered::abort::abort::DoublePanic>::h9d3548bc7115d38f
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/ptr/mod.rs:188:1
  16:     0x55f741023609 - futures_util::stream::futures_unordered::abort::abort::hcb1516dd393c59b8
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/abort.rs:12:1
  17:     0x55f740f417d3 - futures_util::stream::futures_unordered::ready_to_run_queue::ReadyToRunQueue<Fut>::clear::hd3e1526563b13317
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/ready_to_run_queue.rs:104:42
  18:     0x55f740f3848a - <futures_util::stream::futures_unordered::FuturesUnordered<Fut> as core::ops::drop::Drop>::drop::h1f3294c5552dfe48
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/futures-util-0.3.18/src/stream/futures_unordered/mod.rs:580:18
  19:     0x55f740f38be3 - core::ptr::drop_in_place<futures_util::stream::futures_unordered::FuturesUnordered<core::future::from_generator::GenFuture<playground::run_loop::{{closure}}::test::{{closure}}>>>::h5449b52effbf085e
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/ptr/mod.rs:188:1
  20:     0x55f740f36166 - core::mem::drop::h36e4c622fcb52977
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/mem/mod.rs:898:24
  21:     0x55f740f35448 - playground::run_loop::{{closure}}::hb1fa7de71e337272
                               at /home/guilherme/Projects/playground/src/main.rs:17:9
  22:     0x55f740f2c08b - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h5cfe28750a98defa
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/future/mod.rs:80:19
  23:     0x55f740f35a64 - playground::main::{{closure}}::h62dde6d44e9d9107
                               at /home/guilherme/Projects/playground/src/main.rs:23:5
  24:     0x55f740f2c11b - <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll::h7a8b81dafb2b7391
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/future/mod.rs:80:19
  25:     0x55f740f3cf10 - tokio::park::thread::CachedParkThread::block_on::{{closure}}::h590c4888c9fa719a
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/park/thread.rs:263:54
  26:     0x55f740f32b90 - tokio::coop::with_budget::{{closure}}::hf20cf8f2eff9aa4a
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/coop.rs:106:9
  27:     0x55f740f2b8f8 - std::thread::local::LocalKey<T>::try_with::h040973a9d010b9c9
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/thread/local.rs:399:16
  28:     0x55f740f2b77d - std::thread::local::LocalKey<T>::with::hcfe29299a13b9b13
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/thread/local.rs:375:9
  29:     0x55f740f3c966 - tokio::coop::with_budget::h5ee5df02a49d6b6a
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/coop.rs:99:5
  30:     0x55f740f3c966 - tokio::coop::budget::hab2dbd7c022946ce
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/coop.rs:76:5
  31:     0x55f740f3c966 - tokio::park::thread::CachedParkThread::block_on::h49116734c7a78377
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/park/thread.rs:263:31
  32:     0x55f740f3d066 - tokio::runtime::enter::Enter::block_on::hb139c2e42e0fbed2
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/runtime/enter.rs:151:13
  33:     0x55f740f331ab - tokio::runtime::thread_pool::ThreadPool::block_on::hb113965d8c9fe0fa
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/runtime/thread_pool/mod.rs:77:9
  34:     0x55f740f2ddab - tokio::runtime::Runtime::block_on::h8c32b678e65eab3a
                               at /home/guilherme/.cargo/registry/src/gitproxy.zycloud.tk-1ecc6299db9ec823/tokio-1.14.0/src/runtime/mod.rs:463:43
  35:     0x55f740f39b78 - playground::main::h1cd681073ddf11ba
                               at /home/guilherme/Projects/playground/src/main.rs:23:5
  36:     0x55f740f3866b - core::ops::function::FnOnce::call_once::h8b9e810d04134aad
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/ops/function.rs:227:5
  37:     0x55f740f3ff4e - std::sys_common::backtrace::__rust_begin_short_backtrace::h12a66cefae139e80
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/sys_common/backtrace.rs:125:18
  38:     0x55f740f3dfd1 - std::rt::lang_start::{{closure}}::ha6f842ca8ef64dd8
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/rt.rs:63:18
  39:     0x55f74103d5ba - core::ops::function::impls::<impl core::ops::function::FnOnce<A> for &F>::call_once::h2790017aba790142
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/core/src/ops/function.rs:259:13
  40:     0x55f74103d5ba - std::panicking::try::do_call::hd5d0fbb7d2d2d85d
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:403:40
  41:     0x55f74103d5ba - std::panicking::try::h675520ee37b0fdf7
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:367:19
  42:     0x55f74103d5ba - std::panic::catch_unwind::h803430ea0284ce79
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panic.rs:129:14
  43:     0x55f74103d5ba - std::rt::lang_start_internal::{{closure}}::h3a398a8154de3106
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/rt.rs:45:48
  44:     0x55f74103d5ba - std::panicking::try::do_call::hf60f106700df94b2
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:403:40
  45:     0x55f74103d5ba - std::panicking::try::hb2022d2bc87a9867
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panicking.rs:367:19
  46:     0x55f74103d5ba - std::panic::catch_unwind::hbf801c9d61f0c2fb
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/panic.rs:129:14
  47:     0x55f74103d5ba - std::rt::lang_start_internal::hdd488b91dc742b96
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/rt.rs:45:20
  48:     0x55f740f3dfa0 - std::rt::lang_start::h98bc61135b206bb8
                               at /rustc/59eed8a2aac0230a8b53e89d4e99d55912ba6b35/library/std/src/rt.rs:62:5
  49:     0x55f740f39c0c - main
  50:     0x7f62efa100b3 - __libc_start_main
  51:     0x55f740f2972e - _start
  52:                0x0 - <unknown>
thread panicked while panicking. aborting.
Illegal instruction (core dumped)

[gperinazzo]

I've run the code above for 6 hours on 0.3.17 with no crashes so far. With the 0.3.18 version of the crate it usually crashes within the first 20 minutes.

I think it's safe to assume that the issue was introduced by the changes in 0.3.18.

[taiki-e]

Thanks for the report! Considering that 9080b83 is the only one that changed the code related to FuturesUnordered between 0.3.17 and 0.3.18 (0.3.17...0.3.18), it seems likely to be related to #2493 (cc @ibraheemdev).

[ibraheemdev]

That must mean ReadyToRunQueue is dropped outside of FuturesUnordered::drop. Any idea where?

[ibraheemdev]

Could it be

futures-rs/futures-util/src/stream/futures_unordered/task.rs

Line 46 in b48eb2e

let inner = match arc_self.ready_to_run_queue.upgrade() {

[ibraheemdev]

Hm the stack trace shows:

<futures_util::stream::futures_unordered::FuturesUnordered<Fut> as core::ops::drop::Drop>::drop

[gperinazzo]

Yes, the debug traceback makes it clear that it's panicking in the clear called inside the drop implementation.

The initial backtrace is from a release binary and does not show all calls. It's probably being inlined.

[gperinazzo]

That does make sense, another thread may be holding a reference through that Weak reference. In that case it could run clear while another thread is trying to enqueue.

[gperinazzo]

Okay, I understand the issue now: ReadyToRunQueue::clearrequires unique access to the ReadyToRunQueue. During the call to FuturesUnordered::clear or FuturesUnordered::drop you have unique access to FuturesUnordered, but not to ReadyToRunQueue.

This comment is thus wrong and you should not call ReadyToRunQueue::clear there:

// SAFETY: we just cleared all the tasks and we have &mut self

This can be prevented from being mistakenly changed again by making ReadyToRunQueue::clear require a mutable reference.

[magnet]

I've also hit this issue. Since this is a heisenbug that anyone can get through cargo update, I suggest 0.3.18 be yanked and a 0.3.19 cut with a fix. I'd be happy to provide a patch but I'm not sure if a revert #2493 would be accepted or if @ibraheemdev wants try to fix it differently.

[taiki-e]

(I've yanked futures/futures-util 0.3.18)