search

tokio-rs / tokio

A runtime for writing reliable asynchronous applications with Rust. Provides I/O, networking, scheduling, timers, ...
https://tokio.rs
MIT License
26.72k stars 2.46k forks source link

Possibly, a Race condition bug #1853

Closed Eliah-Lakhin closed 4 years ago

Eliah-Lakhin commented 4 years ago

Version

Tokio 0.2.1

Platform

Linux nuc-s 5.0.0-36-generic #39~18.04.1-Ubuntu SMP Tue Nov 12 11:09:50 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Description

The following snippet has a known issue(spawn_blocking is called when the runtime is shutting down), but it leads to the internal Tokio panic from time to time:

use tokio::task;

#[tokio::test(threaded_scheduler)]
async fn foo() {
    task::spawn(async {
        let res = task::spawn_blocking(|| {

        });
        println!("test1");
        res.await;
    });
}

Stack trace is:

thread 'tokio-runtime-worker' panicked at 'state = Snapshot { is_running: false, is_notified: true, is_released: false, is_complete: false, is_canceled: false, is_join_interested: true, has_join_waker: false, is_final_ref: false }', /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/state.rs:227:9
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/libunwind.rs:88
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.40/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:84
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:61
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1024
   5: std::io::Write::write_fmt
             at src/libstd/io/mod.rs:1412
   6: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:65
   7: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:50
   8: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:190
   9: std::panicking::default_hook
             at src/libstd/panicking.rs:207
  10: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:466
  11: std::panicking::continue_panic_fmt
             at src/libstd/panicking.rs:375
  12: std::panicking::begin_panic_fmt
             at src/libstd/panicking.rs:330
  13: tokio::task::state::State::release_task
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/state.rs:227
  14: tokio::task::harness::Harness<T,S>::drop_task
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/harness.rs:158
  15: tokio::task::raw::drop_task
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/raw.rs:167
  16: tokio::task::raw::RawTask::drop_task
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/raw.rs:119
  17: <tokio::task::Task<S> as core::ops::drop::Drop>::drop
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/mod.rs:391
  18: core::ptr::real_drop_in_place
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libcore/ptr/mod.rs:181
  19: tokio::runtime::blocking::pool::Spawner::schedule
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:233
  20: tokio::runtime::blocking::pool::spawn_blocking::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:90
  21: std::thread::local::LocalKey<T>::try_with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:262
  22: std::thread::local::LocalKey<T>::with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:239
  23: tokio::runtime::blocking::pool::spawn_blocking
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:83
  24: tokio::task::blocking::spawn_blocking
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/blocking.rs:62
  25: render::foo::{{closure}}::{{closure}}
             at lufo-sprite-constructor/tests/render.rs:6
  26: <std::future::GenFuture<T> as core::future::future::Future>::poll
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/future.rs:44
  27: tokio::task::core::Core<T>::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/core.rs:128
  28: tokio::task::harness::Harness<T,S>::poll::{{closure}}::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/harness.rs:120
  29: core::ops::function::FnOnce::call_once
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libcore/ops/function.rs:232
  30: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panic.rs:316
  31: std::panicking::try::do_call
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panicking.rs:289
  32: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:81
  33: std::panicking::try
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panicking.rs:267
  34: std::panic::catch_unwind
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panic.rs:395
  35: tokio::task::harness::Harness<T,S>::poll::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/harness.rs:101
  36: tokio::loom::std::causal_cell::CausalCell<T>::with_mut
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/loom/std/causal_cell.rs:41
  37: tokio::task::harness::Harness<T,S>::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/harness.rs:100
  38: tokio::task::raw::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/raw.rs:162
  39: tokio::task::raw::RawTask::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/raw.rs:113
  40: tokio::task::Task<S>::run
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/mod.rs:370
  41: tokio::runtime::thread_pool::worker::GenerationGuard::run_task
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:466
  42: tokio::runtime::thread_pool::worker::GenerationGuard::process_available_work
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:324
  43: tokio::runtime::thread_pool::worker::GenerationGuard::run
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:289
  44: tokio::runtime::thread_pool::worker::Worker::run::{{closure}}::{{closure}}::{{closure}}::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:175
  45: std::thread::local::LocalKey<T>::try_with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:262
  46: std::thread::local::LocalKey<T>::with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:239
  47: tokio::runtime::thread_pool::worker::Worker::run::{{closure}}::{{closure}}::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:151
  48: tokio::runtime::blocking::pool::Spawner::enter::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:191
  49: std::thread::local::LocalKey<T>::try_with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:262
  50: std::thread::local::LocalKey<T>::with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:239
  51: tokio::runtime::blocking::pool::Spawner::enter
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:176
  52: tokio::runtime::thread_pool::worker::Worker::run::{{closure}}::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:150
  53: tokio::runtime::global::with_state::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/global.rs:107
  54: std::thread::local::LocalKey<T>::try_with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:262
  55: std::thread::local::LocalKey<T>::with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:239
  56: tokio::runtime::global::with_state
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/global.rs:90
  57: tokio::runtime::global::with_thread_pool
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/global.rs:82
  58: tokio::runtime::thread_pool::worker::Worker::run::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:149
  59: tokio::runtime::thread_pool::current::set::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/current.rs:47
  60: std::thread::local::LocalKey<T>::try_with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:262
  61: std::thread::local::LocalKey<T>::with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:239
  62: tokio::runtime::thread_pool::current::set
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/current.rs:29
  63: tokio::runtime::thread_pool::worker::Worker::run
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/worker.rs:145
  64: tokio::runtime::thread_pool::Workers::spawn::{{closure}}::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/mod.rs:124
  65: <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/task.rs:30
  66: tokio::task::core::Core<T>::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/core.rs:128
  67: tokio::task::harness::Harness<T,S>::poll::{{closure}}::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/harness.rs:120
  68: core::ops::function::FnOnce::call_once
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libcore/ops/function.rs:232
  69: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panic.rs:316
  70: std::panicking::try::do_call
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panicking.rs:289
  71: __rust_maybe_catch_panic
             at src/libpanic_unwind/lib.rs:81
  72: std::panicking::try
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panicking.rs:267
  73: std::panic::catch_unwind
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/panic.rs:395
  74: tokio::task::harness::Harness<T,S>::poll::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/harness.rs:101
  75: tokio::loom::std::causal_cell::CausalCell<T>::with_mut
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/loom/std/causal_cell.rs:41
  76: tokio::task::harness::Harness<T,S>::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/harness.rs:100
  77: tokio::task::raw::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/raw.rs:162
  78: tokio::task::raw::RawTask::poll
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/raw.rs:113
  79: tokio::task::Task<S>::run
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/task/mod.rs:370
  80: tokio::runtime::blocking::pool::run_task
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:352
  81: tokio::runtime::blocking::pool::Inner::run2
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:278
  82: tokio::runtime::blocking::pool::Inner::run::{{closure}}::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:263
  83: tokio::runtime::global::with_state::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/global.rs:107
  84: std::thread::local::LocalKey<T>::try_with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:262
  85: std::thread::local::LocalKey<T>::with
             at /rustc/e87a205c2e117d9fb57f6cdeac0a7f6e95c88316/src/libstd/thread/local.rs:239
  86: tokio::runtime::global::with_state
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/global.rs:90
  87: tokio::runtime::global::with_thread_pool
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/global.rs:82
  88: tokio::runtime::thread_pool::spawner::Spawner::enter
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/thread_pool/spawner.rs:44
  89: tokio::runtime::spawner::Spawner::enter
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/spawner.rs:32
  90: tokio::runtime::blocking::pool::Inner::run::{{closure}}
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:263
  91: tokio::time::clock::Clock::enter
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/time/clock.rs:30
  92: tokio::runtime::time::variant::with_default
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/time.rs:43
  93: tokio::runtime::blocking::pool::Inner::run
             at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:262
  94: tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}
              at /home/eliah/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.1/src/runtime/blocking/pool.rs:246
driftluo commented 4 years ago

I encountered this problem, after looking at the code, it's the reason：

runtime::block_on just wait for the feature you pass in, not care about other spawned futures, when block_on finished, the runtime finished, then it can't call block_in_place on the stoping runtime. This means that you need a blocking wait completion of spawn futures, which is inconsistent with the behavior of previous versions of tokio

the source code: https://github.com/tokio-rs/tokio/blob/4261ab6627d1da5e5c70a4b88ccdfc329334716b/tokio/src/runtime/enter.rs#L99-L105

I think you should write like this:

#[tokio::test(threaded_scheduler)]
async fn foo() {
    let handle = tokio::task::spawn(async {
        let res = tokio::task::spawn_blocking(|| {

        });
        println!("test1");
        res
    });

    handle.await;
}
Eliah-Lakhin commented 4 years ago

@driftluo Thank you for your reply!

As I mentioned in my post, the code snippet has a bug for a reason. And you absolutely right, awaiting for the top task resolves this issue. However, even if the code is buggy, I think it shouldn't lead to the Tokio internal errors inconsistently. There could be something deeper inside Tokio aside from this issue, idk. Anyway, the Issue was opened by @carllerche suggestion mostly for tracking purposes: to note we possibly have something that leads to internal error.

carllerche commented 4 years ago

Thanks for the report. I have a fix pending in #1875.