Concurrent use of PgPool sometimes results in "reactor gone" error

[ivan]

I reliably encountered a "reactor gone" error in my unit tests which concurrently used the same PgPool. I have a minimized repro in https://github.com/ludios/sqlx-pgpool-bug-2 (main.rs).

Repro:

git clone https://github.com/ludios/sqlx-pgpool-bug-2
cd sqlx-pgpool-bug-2

This always succeeds (1 test thread):

while true; do DATABASE_URL=$(pg_tmp) RUST_BACKTRACE=1 cargo test -- --test-threads=1 || break; done

while this should fail within a minute:

while true; do DATABASE_URL=$(pg_tmp) RUST_BACKTRACE=1 cargo test -- --test-threads=2 || break; done

like so:

# while true; do DATABASE_URL=$(pg_tmp) RUST_BACKTRACE=1 cargo test -- --test-threads=2 || break; done
    Finished test [unoptimized + debuginfo] target(s) in 0.08s
     Running target/debug/deps/sqlx_pgpool_bug_2-29adf45ee5507927

running 2 tests
test tests::test_b ... ok
test tests::test_a ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

    Finished test [unoptimized + debuginfo] target(s) in 0.10s
     Running target/debug/deps/sqlx_pgpool_bug_2-29adf45ee5507927

running 2 tests
test tests::test_b ... ok
test tests::test_a ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

    Finished test [unoptimized + debuginfo] target(s) in 0.14s
     Running target/debug/deps/sqlx_pgpool_bug_2-29adf45ee5507927

running 2 tests
test tests::test_b ... ok
test tests::test_a ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out

    Finished test [unoptimized + debuginfo] target(s) in 0.14s
     Running target/debug/deps/sqlx_pgpool_bug_2-29adf45ee5507927

running 2 tests
test tests::test_b ... ok
test tests::test_a ... FAILED

failures:

---- tests::test_a stdout ----
thread 'tests::test_a' panicked at 'called `Result::unwrap()` on an `Err` value: Io(Custom { kind: Other, error: "reactor gone" })', src/main.rs:39:41
stack backtrace:
   0: backtrace::backtrace::libunwind::trace
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/libunwind.rs:86
   1: backtrace::backtrace::trace_unsynchronized
             at /cargo/registry/src/github.com-1ecc6299db9ec823/backtrace-0.3.46/src/backtrace/mod.rs:66
   2: std::sys_common::backtrace::_print_fmt
             at src/libstd/sys_common/backtrace.rs:78
   3: <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt
             at src/libstd/sys_common/backtrace.rs:59
   4: core::fmt::write
             at src/libcore/fmt/mod.rs:1076
   5: std::io::Write::write_fmt
             at /rustc/5c9e5df3a097e094641f16dab501ab1c4da10e9f/src/libstd/io/mod.rs:1539
   6: std::io::impls::<impl std::io::Write for alloc::boxed::Box<W>>::write_fmt
             at src/libstd/io/impls.rs:176
   7: std::sys_common::backtrace::_print
             at src/libstd/sys_common/backtrace.rs:62
   8: std::sys_common::backtrace::print
             at src/libstd/sys_common/backtrace.rs:49
   9: std::panicking::default_hook::{{closure}}
             at src/libstd/panicking.rs:198
  10: std::panicking::default_hook
             at src/libstd/panicking.rs:214
  11: std::panicking::rust_panic_with_hook
             at src/libstd/panicking.rs:526
  12: rust_begin_unwind
             at src/libstd/panicking.rs:437
  13: core::panicking::panic_fmt
             at src/libcore/panicking.rs:85
  14: core::option::expect_none_failed
             at src/libcore/option.rs:1269
  15: core::result::Result<T,E>::unwrap
             at /home/at/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/result.rs:1005
  16: sqlx_pgpool_bug_2::tests::test_a::{{closure}}
             at src/main.rs:39
  17: <core::future::from_generator::GenFuture<T> as core::future::future::Future>::poll
             at /home/at/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/future/mod.rs:78
  18: tokio::runtime::basic_scheduler::BasicScheduler<P>::block_on::{{closure}}::{{closure}}
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/basic_scheduler.rs:131
  19: tokio::coop::with_budget::{{closure}}
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/coop.rs:127
  20: std::thread::local::LocalKey<T>::try_with
             at /home/at/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:263
  21: std::thread::local::LocalKey<T>::with
             at /home/at/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libstd/thread/local.rs:239
  22: tokio::coop::with_budget
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/coop.rs:120
  23: tokio::coop::budget
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/coop.rs:96
  24: tokio::runtime::basic_scheduler::BasicScheduler<P>::block_on::{{closure}}
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/basic_scheduler.rs:131
  25: tokio::runtime::basic_scheduler::enter::{{closure}}
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/basic_scheduler.rs:213
  26: tokio::macros::scoped_tls::ScopedKey<T>::set
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/macros/scoped_tls.rs:63
  27: tokio::runtime::basic_scheduler::enter
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/basic_scheduler.rs:213
  28: tokio::runtime::basic_scheduler::BasicScheduler<P>::block_on
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/basic_scheduler.rs:123
  29: tokio::runtime::Runtime::block_on::{{closure}}
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/mod.rs:444
  30: tokio::runtime::context::enter
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/context.rs:72
  31: tokio::runtime::handle::Handle::enter
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/handle.rs:76
  32: tokio::runtime::Runtime::block_on
             at /home/at/.cargo/registry/src/github.com-1ecc6299db9ec823/tokio-0.2.21/src/runtime/mod.rs:441
  33: sqlx_pgpool_bug_2::tests::test_a
             at src/main.rs:31
  34: sqlx_pgpool_bug_2::tests::test_a::{{closure}}
             at src/main.rs:31
  35: core::ops::function::FnOnce::call_once
             at /home/at/.rustup/toolchains/nightly-x86_64-unknown-linux-gnu/lib/rustlib/src/rust/src/libcore/ops/function.rs:233
  36: <alloc::boxed::Box<F> as core::ops::function::FnOnce<A>>::call_once
             at /rustc/5c9e5df3a097e094641f16dab501ab1c4da10e9f/src/liballoc/boxed.rs:1081
  37: <std::panic::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/5c9e5df3a097e094641f16dab501ab1c4da10e9f/src/libstd/panic.rs:318
  38: std::panicking::try::do_call
             at /rustc/5c9e5df3a097e094641f16dab501ab1c4da10e9f/src/libstd/panicking.rs:348
  39: std::panicking::try
             at /rustc/5c9e5df3a097e094641f16dab501ab1c4da10e9f/src/libstd/panicking.rs:325
  40: std::panic::catch_unwind
             at /rustc/5c9e5df3a097e094641f16dab501ab1c4da10e9f/src/libstd/panic.rs:394
  41: test::run_test_in_process
             at src/libtest/lib.rs:541
  42: test::run_test::run_test_inner::{{closure}}
             at src/libtest/lib.rs:450
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.


failures:
    tests::test_a

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out

error: test failed, to rerun pass '--bin sqlx-pgpool-bug-2'

I tested with Rust nightly (rustc 1.46.0-nightly (5c9e5df3a 2020-07-16)) on NixOS master, with pg_tmp creating a temporary PostgreSQL 12.3.

[abonander]

I don't think this is a bug on our end. #[tokio::test] spawns a different runtime for every function which only lives as long as the async fn is executing. The Pool gets attached to the runtime for whatever is the test that starts first, and then if that runtime exits while the second test is still running you're likely to get this error.

As to why it works when run on only one thread, I imagine it's because the pool isn't being used between test executions, so you don't have the runtime dying while a task is trying to use a connection that was attached to it. It's hard to say for certain, but that's likely what's happening.

As a fix, you could initialize a single global runtime instead of using #[tokio::test], and then call runtime.handle().block_on() with your async test code. This will only work if you use the threaded scheduler, however.

[ivan]

Ah, thank you very much for that explanation. I worked around it by giving each test a new PgPool, but I didn't know each test had its own tokio runtime. I will close this since that sounds correct. Thanks again!

related tokio-rs/tokio#2374