Bad error message when using IO resource after destroying runtime

[PatatasDelPapa]

Version
tokio v1.33.0

Platform
Windows 10 64-bits version 22H2

Description
Testing two async fn with #[tokio::test] I got tests failed from because of tokio itself instead of one of my conditions. (This part https://github.com/tokio-rs/tokio/blob/tokio-1.33.0/tokio/src/runtime/io/scheduled_io.rs#L214)
The error message is pretty bad and doesn't say what went wrong. Also the tests can complete or fail without any change between each call to cargo test.

The code is somewhat large to be put in a issue but I have it here --> https://github.com/PatatasDelPapa/sqlx_test/blob/b477db267cdcded3f5b268f518129c1f4aff2eb1/src/main.rs is just a single main.rs

The resume is that I have a static tokio::sync::OnceCell<sqlx::postgres::Pool<sqlx::Postgres>> that I use in each test to get a connection to the Database. It seems that the connection when it's first created is tied to the runtime that created it and because each test have different runtime it causes troubles and tokio panics (possible explanation from the discord).

I expected to see this happen:
Tests complete without issue

❯ cargo test -- --nocapture
    Finished test [unoptimized + debuginfo] target(s) in 0.33s
     Running unittests src\main.rs (target\debug\deps\sqlx_test-9ffe485cc74e9d2f.exe)

running 2 tests
test test::get_err_not_found ... ok
test test::create_ok ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.20s

Or a good error message telling me why the test fails.

Instead, this happened:
Tests fails randomly

 cargo test -- --nocapture
    Finished test [unoptimized + debuginfo] target(s) in 0.31s
     Running unittests src\main.rs (target\debug\deps\sqlx_test-9ffe485cc74e9d2f.exe)

running 2 tests
test test::create_ok ... thread 'oktest::get_err_not_found
' panicked at C:\Users\patatas\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\io\scheduled_io.rs:214:9:
assertion `left == right` failed
  left: 0
 right: 1
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
test test::get_err_not_found ... FAILED

failures:

failures:
    test::get_err_not_found

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.29s

error: test failed, to rerun pass `--bin sqlx_test`

The error message doesn't give any indication of what went wrong.

[Darksonn]

This is because each test creates a separate runtime, but they share an IO resource via a global. When the test that initialized the global exits, the other tests will fail because the IO resource stops working.

[Darksonn]

Can you run the test with RUST_BACKTRACE=1 and give me the stack trace? I can't do it myself since the sqlx stuff requires a database configuration.

[PatatasDelPapa]

Can you run the test with RUST_BACKTRACE=1 and give me the stack trace? I can't do it myself since the sqlx stuff requires a database configuration.

Sure, here it is.

❯ cargo test
    Finished test [unoptimized + debuginfo] target(s) in 0.32s
     Running unittests src\main.rs (target\debug\deps\sqlx_test-9ffe485cc74e9d2f.exe)

running 2 tests
test test::create_ok ... ok
test test::get_err_not_found ... FAILED

failures:

---- test::get_err_not_found stdout ----
thread 'test::get_err_not_found' panicked at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\io\scheduled_io.rs:214:9:
assertion `left == right` failed
  left: 0
 right: 1
stack backtrace:
   0: std::panicking::begin_panic_handler
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library\std\src\panicking.rs:595
   1: core::panicking::panic_fmt
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library\core\src\panicking.rs:67
   2: core::panicking::assert_failed_inner
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library\core\src\panicking.rs:269
   3: core::panicking::assert_failed<usize,usize>
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\panicking.rs:229
   4: tokio::runtime::io::scheduled_io::ScheduledIo::set_readiness<tokio::runtime::io::scheduled_io::impl$1::clear_readiness::closure_env$0>
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\io\scheduled_io.rs:214
   5: tokio::runtime::io::scheduled_io::ScheduledIo::clear_readiness
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\io\scheduled_io.rs:386
   6: tokio::runtime::io::registration::Registration::clear_readiness
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\io\registration.rs:104
   7: tokio::runtime::io::registration::Registration::try_io<usize,tokio::net::tcp::stream::impl$0::try_read_buf::closure_env$0<ref_mut$<dyn$<sqlx_core::io::read_buf::ReadBuf> > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\io\registration.rs:197
   8: tokio::net::tcp::stream::TcpStream::try_read_buf<ref_mut$<dyn$<sqlx_core::io::read_buf::ReadBuf> > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\net\tcp\stream.rs:754
   9: sqlx_core::rt::rt_tokio::socket::impl$0::try_read
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\rt\rt_tokio\socket.rs:14
  10: sqlx_core::net::socket::impl$5::try_read<dyn$<sqlx_core::net::socket::Socket> >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\net\socket\mod.rs:161
  11: sqlx_core::net::socket::impl$0::poll<alloc::boxed::Box<dyn$<sqlx_core::net::socket::Socket>,alloc::alloc::Global>,bytes::bytes_mut::BytesMut>
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\net\socket\mod.rs:77
  12: sqlx_core::net::socket::buffered::impl$2::read::async_fn$0<alloc::boxed::Box<dyn$<sqlx_core::net::socket::Socket>,alloc::alloc::Global> >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\net\socket\buffered.rs:230
  13: sqlx_core::net::socket::buffered::impl$0::read_buffered::async_fn$0<alloc::boxed::Box<dyn$<sqlx_core::net::socket::Socket>,alloc::alloc::Global> >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\net\socket\buffered.rs:49
  14: sqlx_core::net::socket::buffered::impl$0::read_with::async_fn$0<alloc::boxed::Box<dyn$<sqlx_core::net::socket::Socket>,alloc::alloc::Global>,bytes::bytes::Bytes,tuple$<> >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\net\socket\buffered.rs:71
  15: sqlx_core::net::socket::buffered::impl$0::read::async_fn$0<alloc::boxed::Box<dyn$<sqlx_core::net::socket::Socket>,alloc::alloc::Global>,bytes::bytes::Bytes>
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\net\socket\buffered.rs:64
  16: sqlx_postgres::connection::stream::impl$0::recv_unchecked::async_fn$0
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-postgres-0.7.2\src\connection\stream.rs:88
  17: sqlx_postgres::connection::stream::impl$0::recv::async_fn$0
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-postgres-0.7.2\src\connection\stream.rs:102
  18: sqlx_postgres::connection::executor::impl$0::run::async_fn$0::closure$0::async_block$0
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-postgres-0.7.2\src\connection\executor.rs:276
  19: sqlx_core::ext::async_stream::impl$0::new::async_block$0<enum2$<either::Either<sqlx_postgres::query_result::PgQueryResult,sqlx_postgres::row::PgRow> >,sqlx_postgres::connection::executor::impl$0::run::async_fn$0::closure_env$0,enum2$<sqlx_postgres::connec
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\ext\async_stream.rs:28
  20: futures_util::future::future::fuse::impl$3::poll<enum2$<sqlx_core::ext::async_stream::impl$0::new::async_block_env$0<enum2$<either::Either<sqlx_postgres::query_result::PgQueryResult,sqlx_postgres::row::PgRow> >,sqlx_postgres::connection::executor::impl$0:
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\futures-util-0.3.28\src\future\future\fuse.rs:84
  21: core::future::future::impl$1::poll<alloc::boxed::Box<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,enum2$<sqlx_core::error::Error> > > > >,core::marker::Send>,alloc::alloc::Global> >
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\future\future.rs:125
  22: core::future::future::impl$0::poll<core::pin::Pin<alloc::boxed::Box<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,enum2$<sqlx_core::error::Error> > > > >,core::marker::Send>,alloc::alloc::Global> > >
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\future\future.rs:113
  23: sqlx_core::ext::async_stream::impl$1::poll_next<enum2$<either::Either<sqlx_postgres::query_result::PgQueryResult,sqlx_postgres::row::PgRow> > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\ext\async_stream.rs:51
  24: futures_core::stream::impl$1::poll_next<ref_mut$<sqlx_core::ext::async_stream::TryAsyncStream<enum2$<either::Either<sqlx_postgres::query_result::PgQueryResult,sqlx_postgres::row::PgRow> > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\futures-core-0.3.28\src\stream.rs:120
  25: futures_core::stream::impl$4::try_poll_next<core::pin::Pin<ref_mut$<sqlx_core::ext::async_stream::TryAsyncStream<enum2$<either::Either<sqlx_postgres::query_result::PgQueryResult,sqlx_postgres::row::PgRow> > > > >,enum2$<either::Either<sqlx_postgres::query
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\futures-core-0.3.28\src\stream.rs:196
  26: futures_util::stream::try_stream::TryStreamExt::try_poll_next_unpin<core::pin::Pin<ref_mut$<sqlx_core::ext::async_stream::TryAsyncStream<enum2$<either::Either<sqlx_postgres::query_result::PgQueryResult,sqlx_postgres::row::PgRow> > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\futures-util-0.3.28\src\stream\try_stream\mod.rs:1068
  27: futures_util::stream::try_stream::try_next::impl$3::poll<core::pin::Pin<ref_mut$<sqlx_core::ext::async_stream::TryAsyncStream<enum2$<either::Either<sqlx_postgres::query_result::PgQueryResult,sqlx_postgres::row::PgRow> > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\futures-util-0.3.28\src\stream\try_stream\try_next.rs:32
  28: sqlx_postgres::connection::executor::impl$1::fetch_optional::async_block$1<sqlx_core::query::Query<sqlx_postgres::database::Postgres,sqlx_postgres::arguments::PgArguments> >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-postgres-0.7.2\src\connection\executor.rs:405
  29: core::future::future::impl$1::poll<alloc::boxed::Box<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<enum2$<core::option::Option<sqlx_postgres::row::PgRow> >,enum2$<sqlx_core::error::Error> > > > >,core::marker::Send>,alloc::al
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\future\future.rs:125
  30: sqlx_core::pool::executor::impl$0::fetch_optional::async_block$0<sqlx_postgres::database::Postgres,sqlx_core::query::Query<sqlx_postgres::database::Postgres,sqlx_postgres::arguments::PgArguments> >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\pool\executor.rs:48
  31: core::future::future::impl$1::poll<alloc::boxed::Box<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<enum2$<core::option::Option<sqlx_postgres::row::PgRow> >,enum2$<sqlx_core::error::Error> > > > >,core::marker::Send>,alloc::al
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\future\future.rs:125
  32: sqlx_core::query::impl$5::fetch_optional::async_fn$0<sqlx_postgres::database::Postgres,sqlx_test::test::get_err_not_found::async_block$0::closure_env$0,sqlx_test::Task,sqlx_postgres::arguments::PgArguments,ref$<sqlx_core::pool::Pool<sqlx_postgres::databas
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\sqlx-core-0.7.2\src\query.rs:387
  33: sqlx_test::test::get_err_not_found::async_block$0
             at .\src\main.rs:101
  34: core::future::future::impl$1::poll<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > >
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\future\future.rs:125
  35: core::future::future::impl$1::poll<ref_mut$<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > > >
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\future\future.rs:125
  36: tokio::runtime::scheduler::current_thread::impl$8::block_on::closure$0::closure$0::closure$0<core::pin::Pin<ref_mut$<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:665
  37: tokio::runtime::coop::with_budget
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\coop.rs:107
  38: tokio::runtime::coop::budget
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\coop.rs:73
  39: tokio::runtime::scheduler::current_thread::impl$8::block_on::closure$0::closure$0<core::pin::Pin<ref_mut$<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:665
  40: tokio::runtime::scheduler::current_thread::Context::enter<enum2$<core::task::poll::Poll<enum2$<core::result::Result<tuple$<>,anyhow::Error> > > >,tokio::runtime::scheduler::current_thread::impl$8::block_on::closure$0::closure_env$0<core::pin::Pin<ref_mut$
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:410
  41: tokio::runtime::scheduler::current_thread::impl$8::block_on::closure$0<core::pin::Pin<ref_mut$<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:664
  42: tokio::runtime::scheduler::current_thread::impl$8::enter::closure$0<tokio::runtime::scheduler::current_thread::impl$8::block_on::closure_env$0<core::pin::Pin<ref_mut$<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::res
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:743
  43: tokio::runtime::context::scoped::Scoped<enum2$<tokio::runtime::scheduler::Context> >::set<enum2$<tokio::runtime::scheduler::Context>,tokio::runtime::scheduler::current_thread::impl$8::enter::closure_env$0<tokio::runtime::scheduler::current_thread::impl$8:
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\context\scoped.rs:40
  44: tokio::runtime::context::set_scheduler::closure$0<tuple$<alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core,alloc::alloc::Global>,enum2$<core::option::Option<enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > >,tokio::runtime::schedu
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\context.rs:176
  45: std::thread::local::LocalKey<tokio::runtime::context::Context>::try_with<tokio::runtime::context::Context,tokio::runtime::context::set_scheduler::closure_env$0<tuple$<alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core,alloc::alloc::Global>,
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\std\src\thread\local.rs:270
  46: std::thread::local::LocalKey<tokio::runtime::context::Context>::with<tokio::runtime::context::Context,tokio::runtime::context::set_scheduler::closure_env$0<tuple$<alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core,alloc::alloc::Global>,enum
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\std\src\thread\local.rs:246
  47: tokio::runtime::context::set_scheduler<tuple$<alloc::boxed::Box<tokio::runtime::scheduler::current_thread::Core,alloc::alloc::Global>,enum2$<core::option::Option<enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > >,tokio::runtime::scheduler::curren
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\context.rs:176
  48: tokio::runtime::scheduler::current_thread::CoreGuard::enter<tokio::runtime::scheduler::current_thread::impl$8::block_on::closure_env$0<core::pin::Pin<ref_mut$<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Res
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:743
  49: tokio::runtime::scheduler::current_thread::CoreGuard::block_on<core::pin::Pin<ref_mut$<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:652
  50: tokio::runtime::scheduler::current_thread::impl$0::block_on::closure$0<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:175
  51: tokio::runtime::context::runtime::enter_runtime<tokio::runtime::scheduler::current_thread::impl$0::block_on::closure_env$0<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\context\runtime.rs:65
  52: tokio::runtime::scheduler::current_thread::CurrentThread::block_on<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\scheduler\current_thread\mod.rs:167
  53: tokio::runtime::runtime::Runtime::block_on<core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,enum2$<core::result::Result<tuple$<>,anyhow::Error> > > > > > > >
             at C:\Users\pamel\.cargo\registry\src\index.crates.io-6f17d22bba15001f\tokio-1.33.0\src\runtime\runtime.rs:348
  54: sqlx_test::test::get_err_not_found
             at .\src\main.rs:115
  55: sqlx_test::test::get_err_not_found::closure$0
             at .\src\main.rs:91
  56: core::ops::function::FnOnce::call_once<sqlx_test::test::get_err_not_found::closure_env$0,tuple$<> >
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33\library\core\src\ops\function.rs:250
  57: core::ops::function::FnOnce::call_once
             at /rustc/cc66ad468955717ab92600c770da8c1601a4ff33/library\core\src\ops\function.rs:250
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.


failures:
    test::get_err_not_found

test result: FAILED. 1 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.92s

error: test failed, to rerun pass `--bin sqlx_test`