Tokio shutdown issue with async tests #1466

knutin · 2020-11-04T15:09:44Z

Hello,

I'm running into an issue with async tests when a Postgres database fairing is attached. Without the database fairing, I do not observe this problem.

Tests fail with the message below. The test itself actually runs, so I'm guessing this is caused by some drop. I can attach the full stacktrace if helpful.

thread 'tests::this_will_fail' panicked at 'Cannot drop a runtime in a context where blocking is not allowed. This happens when a runtime is dropped from within an asynchronous context.', /Users/knutin/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/blocking/shutdown.rs:49:21

Versions:

Rust: 1.47.0, stable
Rocket version: 2f98299272a2a196a3d053918ebd542e03abfc70
Rocket contrib with features = ["postgres_pool"]

Here's a repository which reproduces the problem: https://github.com/knutin/rocket-test-bug To use this repo you need a local Postgres instance. Edit Rocket.toml with your exact connection details.

The text was updated successfully, but these errors were encountered:

SergioBenitez · 2020-11-04T16:30:55Z

Can you try this with the latest version from master? Does this reproduce?

knutin · 2020-11-04T19:16:33Z

Thanks for the quick reply!

I should have been more clear. I see the issue with the latest commit from master (2f98299).

SergioBenitez · 2020-11-04T21:48:01Z

Thanks for the quick reply! I was able to reproduce this locally. This is the minimal reproducing example:

#[rocket_contrib::database("hello")]
pub struct HelloDb(rocket_contrib::databases::postgres::Client);

#[rocket::launch]
fn web() -> _ {
    rocket::ignite().attach(HelloDb::fairing())
}

Run, then kill with ctrl-c.

The issue occurs on Drop. Here's a backtrace for posterity:

Backtrace

> RUST_BACKTRACE=1 cargo run
🔧 Configured for debug.
    => address: 127.0.0.1
    => port: 8000
    => workers: 64
    => log level: normal
    => secret key: [zero]
    => limits: forms = 32KiB
    => cli colors: true
    => keep-alive: 5s
    => tls: disabled
🚀 Rocket has launched from http://127.0.0.1:8000
^CServer shutdown requested, waiting for all pending requests to finish.
thread 'main' panicked at 'Cannot drop a runtime in a context where blocking is not allowed. This happens when a runtime is dropped from within an asynchronous context.', /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/blocking/shutdown.rs:49:21
stack backtrace:
   0: std::panicking::begin_panic
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/panicking.rs:521:12
   1: tokio::runtime::blocking::shutdown::Receiver::wait
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/blocking/shutdown.rs:49:21
   2: tokio::runtime::blocking::pool::BlockingPool::shutdown
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/blocking/pool.rs:132:9
   3: <tokio::runtime::blocking::pool::BlockingPool as core::ops::drop::Drop>::drop
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/blocking/pool.rs:138:9
   4: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
   5: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
   6: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
   7: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
   8: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
   9: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  10: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  11: <alloc::vec::Vec<T> as core::ops::drop::Drop>::drop
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/vec.rs:2597:13
  12: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  13: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  14: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  15: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  16: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  17: alloc::sync::Arc<T>::drop_slow
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/sync.rs:951:18
  18: <alloc::sync::Arc<T> as core::ops::drop::Drop>::drop
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/sync.rs:1471:13
  19: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  20: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  21: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  22: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  23: core::mem::drop
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/mem/mod.rs:882:24
  24: <state::container::AnyObject as core::ops::drop::Drop>::drop
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/state-0.4.2/src/container.rs:125:13
  25: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  26: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  27: core::ptr::mut_ptr::<impl *mut T>::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mut_ptr.rs:963:18
  28: hashbrown::raw::Bucket<T>::drop
             at /cargo/registry/src/github.com-1ecc6299db9ec823/hashbrown-0.9.0/src/raw/mod.rs:334:9
  29: <hashbrown::raw::RawTable<T> as core::ops::drop::Drop>::drop
             at /cargo/registry/src/github.com-1ecc6299db9ec823/hashbrown-0.9.0/src/raw/mod.rs:1325:25
  30: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  31: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  32: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  33: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  34: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  35: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  36: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  37: alloc::sync::Arc<T>::drop_slow
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/sync.rs:951:18
  38: <alloc::sync::Arc<T> as core::ops::drop::Drop>::drop
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/alloc/src/sync.rs:1471:13
  39: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  40: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  41: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/c
ore/src/ptr/mod.rs:175:1
  42: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  43: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  44: core::ptr::drop_in_place
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ptr/mod.rs:175:1
  45: core::pin::Pin<P>::set
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/pin.rs:649:9
  46: <hyper::server::shutdown::Graceful<I,S,F,E> as core::future::future::Future>::poll
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/hyper-0.13.9/src/server/shutdown.rs:86:13
  47: rocket::server::<impl rocket::rocket::Rocket>::listen_on::{{closure}}
             at /home/user/.cargo/git/checkouts/rocket-8bf16d9ca7e90bdc/007c4b0/core/lib/src/server.rs:383:9
  48: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/mod.rs:80:19
  49: <core::pin::Pin<P> as core::future::future::Future>::poll
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/future.rs:119:9
  50: rocket::rocket::Rocket::launch::{{closure}}
             at /home/user/.cargo/git/checkouts/rocket-8bf16d9ca7e90bdc/007c4b0/core/lib/src/rocket.rs:553:17
  51: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/mod.rs:80:19
  52: rocket_test_bug::main::{{closure}}
             at ./src/main.rs:14:5
  53: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/future/mod.rs:80:19
  54: tokio::runtime::enter::Enter::block_on::{{closure}}
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/enter.rs:160:58
  55: tokio::coop::with_budget::{{closure}}
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/coop.rs:127:9
  56: std::thread::local::LocalKey<T>::try_with
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:272:16
  57: std::thread::local::LocalKey<T>::with
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/std/src/thread/local.rs:248:9
  58: tokio::coop::with_budget
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/coop.rs:120:5
  59: tokio::coop::budget
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/coop.rs:96:5
  60: tokio::runtime::enter::Enter::block_on
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/enter.rs:160:35
  61: tokio::runtime::thread_pool::ThreadPool::block_on
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/thread_pool/mod.rs:82:9
  62: tokio::runtime::Runtime::block_on::{{closure}}
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/mod.rs:446:39
  63: tokio::runtime::context::enter
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/context.rs:72:5
  64: tokio::runtime::handle::Handle::enter
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/handle.rs:76:9
  65: tokio::runtime::Runtime::block_on
             at /home/user/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.22/src/runtime/mod.rs:441:9
  66: rocket::async_main
             at /home/user/.cargo/git/checkouts/rocket-8bf16d9ca7e90bdc/007c4b0/core/lib/src/lib.rs:181:5
  67: rocket_test_bug::main
             at ./src/main.rs:13:17
  68: core::ops::function::FnOnce::call_once
             at /home/user/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/library/core/src/ops/function.rs:227:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.

The only recent change to how fairings are handled was made in ec9b581. The commit prior to this is 491b229. The issue still occurs on this commit, however. Going even further back, we also find that the issue remains. Thus, this issue either existed for quite some time or was introduced by a change in postgres.

This issue does not occur with sqlite, which is the only database we run during tests.

SergioBenitez · 2020-11-04T22:25:53Z

Okay, here's what's happening:

Rocket stores a postgres::Client in managed state as part of the postgres connection pool.
The pool is dropped when the server is finished, which happens at the end of tests or on shutdown.
This drops Client, which internally includes a Connection, which itself contains a Runtime, and thus Runtime is dropped.
Since we're in an async context, tokio panics.

In effect, postgres is internally asynchronous but presents a synchronous API, storing a Runtime, which gets dropped while inside of Rocket's Runtime, which tokio considers illegal. In other words, postgres has not accounted for being used in an async context, and Rocket does not expect managed state to spawn their own Runtime.

This issue does not prevent starting or running an application that uses postgres, it simply inhibits a proper shutdown.

I see a few viable paths forward:

Raise an issue with postgres, where shutdown_background() can be used to resolve this issue, though this may not be tenable for postgres.
Drop support for postgres in rocket_contrib, prioritizing Tracking Issue for Asynchronous Database Pool Support #1117
Workaround managed state that starts its own runtime, perhaps by delaying their Drop until after the Rocket Runtime is dropped.

@jebrosen Would be curious if you have any thoughts here.

jebrosen · 2020-11-04T22:36:04Z

2 seems reasonable, although mildly disappointing (did you mean to link to #1117 ?). For many projects, postgres -> tokio_postgres may even be a more straightforward and less error-prone transition to make than postgres -> wrap run() calls around synchronous postgres.

As a modification of 3, or perhaps an option 4, we might be able to use spawn_blocking or thread::spawn inside impl<K, C> Drop for ConnectionPool<K, C>, similarly to how it's already done with Connection.

SergioBenitez · 2020-11-04T22:38:29Z

2 seems reasonable, although mildly disappointing (did you mean to link to #1117 ?). For many projects, postgres -> tokio_postgres may even be a more straightforward and less error-prone transition to make than postgres -> wrap run() calls around synchronous postgres.

Indeed, and agreed.

As a modification of 3, or perhaps an option 4, we might be able to use spawn_blocking or thread::spawn inside impl<K, C> Drop for ConnectionPool<K, C>, similarly to how it's already done with Connection.

If it works, I'd be happy with this as a stop-gap solution until #1117 is resolved; I think it's important that we have an ergonomic, out-of-the-box solution for postgres. As a means of testing this, we can create a fake Poolable type that contains a Runtime.

SergioBenitez · 2020-11-04T23:01:32Z

@jebrosen I'm assigning you to this. If you don't have the bandwidth, feel free to flip it right back at me.

This was already done for the connections, but the pool might also do synchronous/blocking work on Drop. Fixes rwf2#1466.

SergioBenitez added triage A bug report being investigated deficiency Something doesn't work as well as it could labels Nov 4, 2020

SergioBenitez removed the triage A bug report being investigated label Nov 4, 2020

SergioBenitez assigned jebrosen Nov 4, 2020

jebrosen added a commit to jebrosen/Rocket that referenced this issue Nov 5, 2020

Drop synchronous connection pools on a blocking task.

d38cc87

This was already done for the connections, but the pool might also do synchronous/blocking work on Drop. Fixes rwf2#1466.

jebrosen mentioned this issue Nov 5, 2020

Drop synchronous connection pools on a blocking task. #1467

Merged

SergioBenitez closed this as completed in c6298b9 Nov 5, 2020

SergioBenitez closed this as completed in #1467 Nov 5, 2020

mikolajsnioch mentioned this issue Oct 31, 2021

Using Clickhouse-rs in async context throws exceptions on shutdown suharev7/clickhouse-rs#161

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tokio shutdown issue with async tests #1466

Tokio shutdown issue with async tests #1466

knutin commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

knutin commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020 •

edited

Loading

jebrosen commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

Tokio shutdown issue with async tests #1466

Tokio shutdown issue with async tests #1466

Comments

knutin commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

knutin commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020 • edited Loading

jebrosen commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020

SergioBenitez commented Nov 4, 2020 •

edited

Loading