Panicking when dropping `deadpool-runtime`

[Hywan]

Hello,

I'm having this error randomly when closing my app (so when it drops deadpool):

thread 'tokio-runtime-worker' (4858160) panicked at …/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/deadpool-runtime-0.1.4/src/lib.rs:77:58:
`JoinError` reason is not a panic.: JoinError::Cancelled(Id(4027))

stacktrace

stack backtrace:
   0: __rustc::rust_begin_unwind
             at /rustc/842bd5be253e17831e318fdbd9d01d716557cc75/library/std/src/panicking.rs:689:5
   1: core::panicking::panic_fmt
             at /rustc/842bd5be253e17831e318fdbd9d01d716557cc75/library/core/src/panicking.rs:80:14
   2: core::result::unwrap_failed
             at /rustc/842bd5be253e17831e318fdbd9d01d716557cc75/library/core/src/result.rs:1867:5
   3: <core::result::Result<alloc::boxed::Box<dyn core::any::Any + core::marker::Send>, tokio::runtime::task::error::JoinError>>::expect
             at …/.rustup/toolchains/nightly-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/result.rs:1185:23
   4: <tokio::runtime::task::error::JoinError>::into_panic
             at …/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/tokio-1.48.0/src/runtime/task/error.rs:95:14
   5: <deadpool_runtime::Runtime>::spawn_blocking::<<deadpool_sync::SyncWrapper<rusqlite::Connection>>::interact<<deadpool::managed::object::Object<matrix_sdk_sqlite::connection::Manager> as matrix_sdk_sqlite::utils::SqliteAsyncConnExt>::execute_batch<&str>::{closure#0}::{closure#0}, core::result::Result<(), rusqlite::error::Error>>::{closure#0}::{closure#0}, core::result::Result<core::result::Result<(), rusqlite::error::Error>, deadpool_sync::InteractError>>::{closure#0}::{closure#0}
             at …/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/deadpool-runtime-0.1.4/src/lib.rs:77:58
   6: <core::result::Result<core::result::Result<core::result::Result<(), rusqlite::error::Error>, deadpool_sync::InteractError>, tokio::runtime::task::error::JoinError>>::map_err::<deadpool_runtime::SpawnBlockingError, <deadpool_runtime::Runtime>::spawn_blocking<<deadpool_sync::SyncWrapper<rusqlite::Connection>>::interact<<deadpool::managed::object::Object<matrix_sdk_sqlite::connection::Manager> as matrix_sdk_sqlite::utils::SqliteAsyncConnExt>::execute_batch<&str>::{closure#0}::{closure#0}, core::result::Result<(), rusqlite::error::Error>>::{closure#0}::{closure#0}, core::result::Result<core::result::Result<(), rusqlite::error::Error>, deadpool_sync::InteractError>>::{closure#0}::{closure#0}>
             at …/.rustup/toolchains/nightly-aarch64-apple-darwin/lib/rustlib/src/rust/library/core/src/result.rs:968:27
   7: <deadpool_runtime::Runtime>::spawn_blocking::<<deadpool_sync::SyncWrapper<rusqlite::Connection>>::interact<<deadpool::managed::object::Object<matrix_sdk_sqlite::connection::Manager> as matrix_sdk_sqlite::utils::SqliteAsyncConnExt>::execute_batch<&str>::{closure#0}::{closure#0}, core::result::Result<(), rusqlite::error::Error>>::{closure#0}::{closure#0}, core::result::Result<core::result::Result<(), rusqlite::error::Error>, deadpool_sync::InteractError>>::{closure#0}
             at …/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/deadpool-runtime-0.1.4/src/lib.rs:77:18
   8: <deadpool_sync::SyncWrapper<rusqlite::Connection>>::interact::<<deadpool::managed::object::Object<matrix_sdk_sqlite::connection::Manager> as matrix_sdk_sqlite::utils::SqliteAsyncConnExt>::execute_batch<&str>::{closure#0}::{closure#0}, core::result::Result<(), rusqlite::error::Error>>::{closure#0}
             at …/.cargo/registry/src/index.crates.io-1949cf8c6b5b557f/deadpool-sync-0.1.4/src/lib.rs:129:14
   9: <deadpool::managed::object::Object<matrix_sdk_sqlite::connection::Manager> as matrix_sdk_sqlite::utils::SqliteAsyncConnExt>::execute_batch::<&str>::{closure#0}
             at …/matrix-sdk-sqlite/src/utils.rs:245:69

I'm willing to write a patch to fix that, just I wanted to open an issue first to track the bug.
It happens very frequently, like almost everytime.

[bikeshedder]

Thanks a lot for the issue and PR.

I had to make a breaking deadpool-runtime release and had high hopes that deadpool-sync could be made non-breaking but then realized that deadpool depends on deadpool-runtime and re-exports the SpawnBlockingError. It's quite unlucky as nobody as this re-export only exists to make the Runtime re-export sound. Nobody using the deadpool crate should be using the Runtime::spawn_blocking method. But I don't want to break any existing software so I yanked that release immediately after noticing this mistake.

I'll prepare a proper deadpool 0.13 release next. While at it I will also remove the methods from the Runtime enum so I can remove this silly re-export, too.

[bikeshedder]

After that botched release I was looking a bit deeper into this and it's a bit of a rabbit hole. How can this even happen in the first place? Quoting the docs (https://docs.rs/tokio/latest/tokio/task/index.html#cancellation):

Be aware that tasks spawned using spawn_blocking cannot be aborted because they are not async. If you call abort on a spawn_blocking task, then this will not have any effect, and the task will continue running normally. The exception is if the task has not started running yet; in that case, calling abort may prevent the task from starting.

According to the docs the only way a JoinHandle of a task spawned by spawn_blocking to return JoinError with is_cancelled() = true if you call JoinHandle::abort() before the task started executing.

But the current API doesn't even expose the JoinHandle and there is no way to abort anything started with Runtime::spawn_blocking.

I can only imagine this to happen if the runtime is in the process of being shut down. But this would also cancel the future waiting for the result of interact().

How did you manage to trigger that error? Can you maybe provide a reproduction example?

[bikeshedder]

I'm reopening this issue as I was able to merge that PR but it doesn't explain why it happens in the first place.

[bikeshedder]

After the botched release of deadpool-sync and deadpool I've just prepared deadpool-runtime 0.3.0 which makes future runtime extensions easier and non-breaking. I've updated deadpool-sync and deadpool accordingly. This is a breaking release and I want to update all the other crates at the same time. Some of them have still unreleased changes as well.

Your change is included and JoinError::Cancelled is now propagated as InteractError::Cancelled in deadpool-sync (I renamed it from Aborted to Cancelled while at it) but I still don't get how this can happen in the first place...

[bikeshedder]

@Hywan If you got any insight how that can happen to begin with it'd be awesome if I could update the doc string. As of now it states that it's merely a technical detail and "should" never happen.

[Hywan]

The reproduction of this issue is precisely why I couldn't write a test for that. The JoinHandle isn't accessible to the public API.

The way it happens on our side is the following:

• we are working on the Matrix Rust SDK, that has a deadpool with SQLite connections (custom implementation, it doesn't use deadpool-sqlite, see feat(sqlite): Replace deadpool-sqlite by our own implementation matrix-org/matrix-rust-sdk#5841 to know how we ended up doing this).
• many apps are using the Matrix Rust SDK
• when an app is closed, 90% of the time, we got this panic. It's not visible for most apps because the panic happens during the shutdown of the process, but the panics are very present. For CLI apps though, it's pretty obvious: that's how I got the backtrace for this issue.

I suspect that the OS is trying to shutdown SQLite, while a current interact is running. It could lead to an abort? But it should be an error, not an abort. Or maybe Tokio also reacts to a shutdown like this? But none of this makes sense by reading the code.

If you want to reproduce, tell me, I'll guide you how to use our debug-only CLI Matrix client, it happens every time with it.