Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Using the async-timer crate with Tokio triggers weird crashes #5975

Closed
rubenfiszel opened this issue Sep 3, 2023 · 12 comments
Closed

Using the async-timer crate with Tokio triggers weird crashes #5975

rubenfiszel opened this issue Sep 3, 2023 · 12 comments
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-runtime Module: tokio/runtime

Comments

@rubenfiszel
Copy link

rubenfiszel commented Sep 3, 2023

Version

│   │   └── tokio v1.32.0
│   │       ├── tokio-macros v2.1.0 (proc-macro)
│   │   │   ├── tokio v1.32.0 (*)
│   │   │   └── tokio-util v0.7.8
│   │   │       ├── tokio v1.32.0 (*)
│   │   ├── tokio v1.32.0 (*)
│   │   ├── tokio-util v0.7.8 (*)
│   │   ├── tokio v1.32.0 (*)
│   │   ├── tokio-stream v0.1.14
│   │   │   └── tokio v1.32.0 (*)
│   │   │   ├── tokio v1.32.0
│   │   │   │   └── tokio-macros v2.1.0 (proc-macro) (*)
├── tokio v1.32.0 (*)
├── tokio-metrics v0.1.0
│   └── tokio v1.32.0 (*)
│   │   │   │   └── tokio v1.32.0 (*)
│   │   │   │   ├── tokio v1.32.0 (*)
│   │   │   │   ├── tokio-util v0.7.8 (*)
│   │   │   │   ├── tokio v1.32.0 (*)
│   │   │   │   ├── tokio v1.32.0 (*)
│   │   │   │   └── tokio-rustls v0.24.1
│   │   │   │       └── tokio v1.32.0 (*)
│   │   │   │   ├── tokio v1.32.0 (*)
│   │   │   │   └── tokio-native-tls v0.3.1
│   │   │   │       └── tokio v1.32.0 (*)
│   │   │   ├── tokio v1.32.0 (*)
│   │   │   ├── tokio-native-tls v0.3.1 (*)
│   │   │   ├── tokio-rustls v0.24.1 (*)
│   │   │   ├── tokio-socks v0.5.1
│   │   │   │   └── tokio v1.32.0 (*)
│   │   │   ├── tokio-util v0.7.8 (*)
│   │   │   ├── tokio v1.32.0 (*)
│   │   └── tokio v1.32.0 (*)
│   │   ├── tokio v1.32.0 (*)
│   │   │   ├── tokio v1.32.0 (*)
│   │   ├── tokio v1.32.0 (*)
│   │   ├── tokio-rustls v0.24.1 (*)
│   ├── tokio v1.32.0 (*)
│   ├── tokio-tar v0.3.1
│   │   ├── tokio v1.32.0 (*)
│   │   ├── tokio-stream v0.1.14 (*)
│   ├── tokio-util v0.7.8 (*)
│   │       ├── tokio v1.32.0 (*)
│       ├── tokio v1.32.0 (*)
│   │   │   │   ├── tokio v1.32.0 (*)
│   │   │   ├── tokio v1.32.0 (*)
│   │   │   ├── tokio-rustls v0.24.1 (*)
│   │   │   ├── tokio-socks v0.5.1 (*)
│   │   │   ├── tokio-util v0.7.8 (*)
    │       ├── tokio v1.32.0 (*)
    │   ├── tokio v1.32.0 (*)
    │   └── tokio-util v0.7.8 (*)
    │   ├── tokio v1.32.0 (*)
    │   │   │   │   ├── tokio v1.32.0 (*)
    │   │   │   │   └── tokio-postgres v0.7.10
    │   │   │   │       ├── tokio v1.32.0 (*)
    │   │   │   │       ├── tokio-util v0.7.8 (*)
    │   ├── tokio v1.32.0 (*)
    │   ├── tokio-native-tls v0.3.1 (*)
    │   ├── tokio-util v0.7.8 (*)
    │   ├── tokio v1.32.0 (*)
    │   ├── tokio-native-tls v0.3.1 (*)
    │   └── tokio-postgres v0.7.10 (*)
    ├── tokio v1.32.0 (*)
    ├── tokio-postgres v0.7.10 (*)

Platform

Linux rubx1 6.4.11-arch2-1 #1 SMP PREEMPT_DYNAMIC Sat, 19 Aug 2023 15:38:34 +0000 x86_64 GNU/Linux

Description

I run a high-throughtput, background workers with each worker being on spawn_blocking. From time to time (every 30mins) I get the following error:

thread 'tokio-runtime-worker' panicked at 'already borrowed: BorrowMutError', /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:1018:49
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
worker thread panicking; aborting process
[1]    457458 IOT instruction (core dumped) 
@rubenfiszel rubenfiszel added A-tokio Area: The main tokio crate C-bug Category: This is a bug. labels Sep 3, 2023
@Darksonn Darksonn added the M-runtime Module: tokio/runtime label Sep 3, 2023
@rubenfiszel
Copy link
Author

Anything I can do to help root cause this?

@Darksonn
Copy link
Contributor

Darksonn commented Sep 6, 2023

If you're able to get a backtrace, then that would definitely be helpful. A minimal reproducer would be even better.

Either way, I will look over the relevant code at some point to see if I can figure out what could cause this.

@Darksonn
Copy link
Contributor

Darksonn commented Sep 6, 2023

It would also be helpful to know whether and in which way you are using the block_in_place method.

@rubenfiszel
Copy link
Author

@Darksonn I cannot reproduce this in a deterministic way but I can reproduce it under 20mins by doing sufficient benchmarks on windmill.dev:

https://github.com/windmill-labs/windmill/tree/main/benchmarks

It is sufficient to run in the backend folder:

cargo run

And then in another CLI:

deno run --unstable -A https://raw.githubusercontent.com/windmill-labs/windmill/main/benchmarks/main.ts  -e [email protected] -p changeme --continous  --workers 1 

For a sufficiently long time. I will provide a backtrace ASAP. Windmill doesn't directly use block_in_place, but since we use many complex dependencies, maybe one of ours does.

@rubenfiszel
Copy link
Author

@Darksonn Here is a full stack trace:

     Running `target/debug/windmill`
thread 'tokio-runtime-worker' panicked at 'already borrowed: BorrowMutError', /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:1018:49
stack backtrace:
   0:     0x558a8f4fe851 - std::backtrace_rs::backtrace::libunwind::trace::he648b5c8dd376705
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x558a8f4fe851 - std::backtrace_rs::backtrace::trace_unsynchronized::h5da3e203eef39e9f
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x558a8f4fe851 - std::sys_common::backtrace::_print_fmt::h8d28d3f20588ae4c
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x558a8f4fe851 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hd9a5b0c9c6b058c0
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x558a8f53093f - core::fmt::rt::Argument::fmt::h0afc04119f252b53
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/fmt/rt.rs:138:9
   5:     0x558a8f53093f - core::fmt::write::h50b1b3e73851a6fe
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/fmt/mod.rs:1094:21
   6:     0x558a8f4fa9a7 - std::io::Write::write_fmt::h184eaf275e4484f0
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/io/mod.rs:1714:15
   7:     0x558a8f4fe665 - std::sys_common::backtrace::_print::hf58c3a5a25090e71
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x558a8f4fe665 - std::sys_common::backtrace::print::hb9cf0a7c7f077819
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x558a8f4fff83 - std::panicking::default_hook::{{closure}}::h066adb2e3f3e2c07
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:269:22
  10:     0x558a8f4ffd14 - std::panicking::default_hook::h277fa2776900ff14
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:288:9
  11:     0x558a8f500509 - std::panicking::rust_panic_with_hook::hceaf38da6d9db792
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:705:13
  12:     0x558a8f500407 - std::panicking::begin_panic_handler::{{closure}}::h2bce3ed2516af7df
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:597:13
  13:     0x558a8f4fecb6 - std::sys_common::backtrace::__rust_end_short_backtrace::h090f3faf8f98a395
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/sys_common/backtrace.rs:151:18
  14:     0x558a8f500152 - rust_begin_unwind
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:593:5
  15:     0x558a8a195513 - core::panicking::panic_fmt::h4ec8274704d163a3
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/panicking.rs:67:14
  16:     0x558a8a195aa3 - core::result::unwrap_failed::h170bc2721a6c6ff2
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/result.rs:1651:5
  17:     0x558a8f2cd9ee - core::result::Result<T,E>::expect::h2f93bd703771c833
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/result.rs:1033:23
  18:     0x558a8f2dfaf7 - core::cell::RefCell<T>::borrow_mut::hb2eef9d6f8ffa8dd
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/cell.rs:1017:9
  19:     0x558a8f23face - tokio::runtime::scheduler::multi_thread::worker::<impl tokio::runtime::scheduler::multi_thread::handle::Handle>::schedule_task::{{closure}}::h83c294ce8bd9bfe4
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:1018:41
  20:     0x558a8f23fd5e - tokio::runtime::scheduler::multi_thread::worker::with_current::{{closure}}::hf7d6b114768f685d
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:1214:35
  21:     0x558a8f2234e3 - tokio::runtime::context::scoped::Scoped<T>::with::h8512d1b081f1e0af
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/scoped.rs:53:22
  22:     0x558a8f2d74cd - tokio::runtime::context::with_scheduler::{{closure}}::hf3caaacc982fff31
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context.rs:181:26
  23:     0x558a8f2df19e - std::thread::local::LocalKey<T>::try_with::he95e41e05e56485b
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/thread/local.rs:270:16
  24:     0x558a8f2dc8eb - std::thread::local::LocalKey<T>::with::hdc4bc33b3644ac6f
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/thread/local.rs:246:9
  25:     0x558a8f2d738d - tokio::runtime::context::with_scheduler::hf002967b65eb0c67
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context.rs:181:9
  26:     0x558a8f23fc96 - tokio::runtime::scheduler::multi_thread::worker::with_current::h3166f8cd1ff045e9
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:1213:5
  27:     0x558a8f2a306c - tokio::runtime::scheduler::multi_thread::worker::<impl tokio::runtime::scheduler::multi_thread::handle::Handle>::schedule_task::h7574f8a1c9bcb565
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:1013:9
  28:     0x558a8f2cba87 - tokio::runtime::scheduler::multi_thread::worker::<impl tokio::runtime::task::Schedule for alloc::sync::Arc<tokio::runtime::scheduler::multi_thread::handle::Handle>>::schedule::he6dcafa6f0e82efe
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:1003:9
  29:     0x558a8ad39c89 - tokio::runtime::task::raw::schedule::h7ffcc816396efa81
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/raw.rs:283:5
  30:     0x558a8f266378 - tokio::runtime::task::raw::RawTask::schedule::h84d692c22e53d6c3
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/raw.rs:205:18
  31:     0x558a8f2651e7 - tokio::runtime::task::harness::<impl tokio::runtime::task::raw::RawTask>::wake_by_val::h0cc48dced357c6a0
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/harness.rs:78:17
  32:     0x558a8f245244 - tokio::runtime::task::waker::wake_by_val::h2699b807b82bef29
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/waker.rs:85:5
  33:     0x558a8df70e38 - core::task::wake::Waker::wake::h9ac465619ed84b9c
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/task/wake.rs:281:18
  34:     0x558a8df71efa - async_timer::oneshot::state::AtomicWaker::wake::hfcbfc27312d890e4
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-timer-0.7.4/src/oneshot/state.rs:101:13
  35:     0x558a8df7214a - async_timer::oneshot::state::TimerState::wake::h25b4166ff81a1097
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-timer-0.7.4/src/oneshot/state.rs:175:9
  36:     0x558a8df721d9 - async_timer::oneshot::posix::ffi::timer_handler::h5da3b95c279dca64
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/async-timer-0.7.4/src/oneshot/posix.rs:28:9
  37:     0x7f757fa3e710 - <unknown>
  38:     0x558a8f2cd9bb - core::result::Result<T,E>::expect::h2f93bd703771c833
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/result.rs:1032:16
  39:     0x558a8f2dfaf7 - core::cell::RefCell<T>::borrow_mut::hb2eef9d6f8ffa8dd
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/cell.rs:1017:9
  40:     0x558a8f23c9bd - tokio::runtime::scheduler::multi_thread::worker::Context::run_task::h7212c78147c9243c
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:572:10
  41:     0x558a8f23c497 - tokio::runtime::scheduler::multi_thread::worker::Context::run::h6869953e9a4e0e10
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:538:24
  42:     0x558a8f23bc79 - tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::{{closure}}::ha0754286d9411e3a
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:491:21
  43:     0x558a8f2230f0 - tokio::runtime::context::scoped::Scoped<T>::set::hcb1841a70ad79b39
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/scoped.rs:40:9
  44:     0x558a8f2d71db - tokio::runtime::context::set_scheduler::{{closure}}::hcc440c2631c0b95f
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context.rs:176:26
  45:     0x558a8f2df31e - std::thread::local::LocalKey<T>::try_with::hec43596ae8d2d009
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/thread/local.rs:270:16
  46:     0x558a8f2dc91b - std::thread::local::LocalKey<T>::with::he5967787a829f0b4
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/thread/local.rs:246:9
  47:     0x558a8f2d71a4 - tokio::runtime::context::set_scheduler::hf1c6bc2e7f0c1b10
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context.rs:176:9
  48:     0x558a8f23bb75 - tokio::runtime::scheduler::multi_thread::worker::run::{{closure}}::h6a9a8868330f4685
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:486:9
  49:     0x558a8f2d65d8 - tokio::runtime::context::runtime::enter_runtime::h2ae7b0bde9de7596
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/context/runtime.rs:65:16
  50:     0x558a8f23b8ec - tokio::runtime::scheduler::multi_thread::worker::run::h3fef433afe0d6cd8
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:478:5
  51:     0x558a8f23b75b - tokio::runtime::scheduler::multi_thread::worker::Launch::launch::{{closure}}::hdd9c57a586e141f8
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/scheduler/multi_thread/worker.rs:447:45
  52:     0x558a8f2e6dee - <tokio::runtime::blocking::task::BlockingTask<T> as core::future::future::Future>::poll::h1a3d9f0b40fc9404
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/blocking/task.rs:42:21
  53:     0x558a8f2d2481 - <tracing::instrument::Instrumented<T> as core::future::future::Future>::poll::h294ab7987efbc078
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-0.1.37/src/instrument.rs:272:9
  54:     0x558a8f2a9ba3 - tokio::runtime::task::core::Core<T,S>::poll::{{closure}}::h14e0d9abbbec0628
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/core.rs:334:17
  55:     0x558a8f2a91cb - tokio::loom::std::unsafe_cell::UnsafeCell<T>::with_mut::h1b2954b6e519fa95
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/loom/std/unsafe_cell.rs:16:9
  56:     0x558a8f2a91cb - tokio::runtime::task::core::Core<T,S>::poll::h81703f217ae3cad3
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/core.rs:323:13
  57:     0x558a8f22ca05 - tokio::runtime::task::harness::poll_future::{{closure}}::h509607f4b99d2064
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/harness.rs:485:19
  58:     0x558a8f2daf23 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h06093103afca1744
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/panic/unwind_safe.rs:271:9
  59:     0x558a8f2eaeac - std::panicking::try::do_call::h5b63606d97fa3ce4
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:500:40
  60:     0x558a8f2ee1fb - __rust_try
  61:     0x558a8f2e9178 - std::panicking::try::h7c94254bcc38baad
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:464:19
  62:     0x558a8f2197db - std::panic::catch_unwind::h2aa112fe0224bbd7
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panic.rs:142:14
  63:     0x558a8f22c37f - tokio::runtime::task::harness::poll_future::hdb9fb13804ec2d98
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/harness.rs:473:18
  64:     0x558a8f2256a9 - tokio::runtime::task::harness::Harness<T,S>::poll_inner::h463075745ca7189c
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/harness.rs:208:27
  65:     0x558a8f224dc7 - tokio::runtime::task::harness::Harness<T,S>::poll::hc6d22d592987bc68
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/harness.rs:153:15
  66:     0x558a8f26670d - tokio::runtime::task::raw::poll::ha6ef3a1474deb7f7
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/raw.rs:276:5
  67:     0x558a8f266347 - tokio::runtime::task::raw::RawTask::poll::h7c150cea59d0bf78
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/raw.rs:200:18
  68:     0x558a8f2d8b97 - tokio::runtime::task::UnownedTask<S>::run::h2a3762a3962271c1
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/task/mod.rs:437:9
  69:     0x558a8f31d537 - tokio::runtime::blocking::pool::Task::run::h66ced34d274c5786
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/blocking/pool.rs:159:9
  70:     0x558a8f3329e9 - tokio::runtime::blocking::pool::Inner::run::hf58289dd6407b176
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/blocking/pool.rs:513:17
  71:     0x558a8f332714 - tokio::runtime::blocking::pool::Spawner::spawn_thread::{{closure}}::h1202bb242895280d
                               at /home/rfiszel/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tokio-1.32.0/src/runtime/blocking/pool.rs:471:13
  72:     0x558a8f2cc539 - std::sys_common::backtrace::__rust_begin_short_backtrace::hb374eab4a5da5ad4
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/sys_common/backtrace.rs:135:18
  73:     0x558a8f26bd72 - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::ha450c59a618d85bc
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/thread/mod.rs:529:17
  74:     0x558a8f2db2b2 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h6f5dea67cd1d5452
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/panic/unwind_safe.rs:271:9
  75:     0x558a8f2eaadb - std::panicking::try::do_call::h1e42309cdde8dbd5
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:500:40
  76:     0x558a8f2ee1fb - __rust_try
  77:     0x558a8f2e8da1 - std::panicking::try::h63b62ca103b2e4b9
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panicking.rs:464:19
  78:     0x558a8f26bb82 - std::panic::catch_unwind::hddf78729405cba7e
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/panic.rs:142:14
  79:     0x558a8f26bb82 - std::thread::Builder::spawn_unchecked_::{{closure}}::h8b20d981d3c942e5
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/thread/mod.rs:528:30
  80:     0x558a8f333d5f - core::ops::function::FnOnce::call_once{{vtable.shim}}::hf15824939ed42274
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/core/src/ops/function.rs:250:5
  81:     0x558a8f505b05 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::hc0b1022758ecac73
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/alloc/src/boxed.rs:1993:9
  82:     0x558a8f505b05 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h0c9654ebe7ad657e
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/alloc/src/boxed.rs:1993:9
  83:     0x558a8f505b05 - std::sys::unix::thread::Thread::new::thread_start::h04c8e9c7d83d3bd5
                               at /rustc/5680fa18feaa87f3ff04063800aec256c3d4b4be/library/std/src/sys/unix/thread.rs:108:17
  84:     0x7f757fa8c9eb - <unknown>
  85:     0x7f757fb10dfc - <unknown>
  86:                0x0 - <unknown>

@Darksonn
Copy link
Contributor

Darksonn commented Sep 9, 2023

Okay, that backtrace definitely contains some clues. I'll have to look more closely later, but there's a good chance that it is enough to diagnose the issue.

@rubenfiszel
Copy link
Author

A bit off-topic but we (Windmill Labs, Inc.) rely on tokio for the stability of windmill (and we are very happy) and are very grateful for all the hard work done on tokio. What is the best way to support the project? Github sponsorhip?

@Darksonn
Copy link
Contributor

Yeah, we have GitHub sponsors set up for the Tokio org.

@rubenfiszel
Copy link
Author

Sponsored, any update on this ? :)

@Darksonn
Copy link
Contributor

I am very puzzled by this stacktrace. Frame 40 is here:

*self.core.borrow_mut() = Some(core);

Then in 39, we go inside the borrow_mut call, which then calls expect on the Result<RefMut<T>>. Frame 38 is inside the call to expect.

Then, frame 37 is <unknown> and frame 36 is inside async-timer - an entirely different crate.

I could understand if we were running the destructor of the old core when replacing it (it should be None here, but I guess a bug could make it Some). However, that assignment happens after we return from borrow_mut, but according to frame 39, that has not happened yet.

I'm not sure what to make of this.

@rubenfiszel
Copy link
Author

@Darksonn what is the best way to help on this ? I can add more stack trace to see if they're all similar or try to see where we use async-timer

@carllerche
Copy link
Member

Hey, thanks for the report and the backtrace. very helpful.

After looking at the stack trace, I am fairly confident that the issue is with the async-timer crate. I would recommend removing usage of it. async-timer uses signals on posix without being "signal safe". This manifests as weird bugs like this.

You can see this is the issue from the stack trace based on the fact that it goes from inside Tokio's worker and jumps to async-timer and the fact that async-timer uses signals.

Hope this helps, I will close this issue, but if you feel that I am wrong, feel free to open a new one w/ more details & link this one.

@Darksonn Darksonn changed the title bug: already borrowed: BorrowMutError from multi_thread/worker in 1.32.0 Using the async-timer crate with Tokio triggers weird crashes Sep 22, 2023
@Darksonn Darksonn closed this as not planned Won't fix, can't repro, duplicate, stale Sep 22, 2023
mikonieminen added a commit to mikonieminen/apalis that referenced this issue Apr 4, 2024
Use of `async-timer` can cause panic with
`already borrowed: BorrowMutError`. This issue is explained in a ticket
in `tokio` project, see:
tokio-rs/tokio#5975 (comment)

Only the `sleep` function in `apalis-core` uses `async-timer` and since
`apalis` only supports `tokio` and `async-std` as runtimes, we can use
`sleep` functions from these two runtimes directly and drop
`async-timer` as a dependency.
mikonieminen added a commit to mikonieminen/apalis that referenced this issue Apr 4, 2024
Use of `async-timer` can cause panic with
`already borrowed: BorrowMutError`. This issue is explained in a ticket
in `tokio` project, see:
tokio-rs/tokio#5975 (comment)

Only the `sleep` function in `apalis-core` uses `async-timer` and since
`apalis` only supports `tokio` and `async-std` as runtimes, we can use
`sleep` functions from these two runtimes directly and drop
`async-timer` as a dependency.
mikonieminen added a commit to mikonieminen/apalis that referenced this issue Apr 10, 2024
Use of `async-timer` can cause panic with
`already borrowed: BorrowMutError`. This issue is explained in a ticket
in `tokio` project, see:
tokio-rs/tokio#5975 (comment)

Only the `sleep` function in `apalis-core` uses `async-timer` and since
`apalis` only supports `tokio` and `async-std` as runtimes, we can use
`sleep` functions from these two runtimes directly and drop
`async-timer` as a dependency.
wsxiaoys pushed a commit to wsxiaoys/apalis that referenced this issue May 3, 2024
Use of `async-timer` can cause panic with
`already borrowed: BorrowMutError`. This issue is explained in a ticket
in `tokio` project, see:
tokio-rs/tokio#5975 (comment)

Only the `sleep` function in `apalis-core` uses `async-timer` and since
`apalis` only supports `tokio` and `async-std` as runtimes, we can use
`sleep` functions from these two runtimes directly and drop
`async-timer` as a dependency.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-tokio Area: The main tokio crate C-bug Category: This is a bug. M-runtime Module: tokio/runtime
Projects
None yet
Development

No branches or pull requests

3 participants