Bug: Unit test with expected panic message randomly fails because of crate-specific panic message

[urben1680]

I currently write unit tests for my Bevy project which uses the current async-task version.
My unit test looks like this:

#[test]
#[should_panic = "invalid `progress_query`: `QueryOutOfRange(2..=3)`"]

As expected, the test fails with the given message in one of the systems I wrote. However, the unit test sometimes still fails because my panic seems to cause another panic here with a different message text:

async-task/src/task.rs

Line 426 in 230b0a4

Poll::Ready(t) => Poll::Ready(t.expect("task has failed")),

---- controller::test::forward::forward_query_forward_to_too_many_ticks stdout ----
note: panic did not contain expected string
panic message: "task has failed",
expected substring: "invalid progress_query: QueryOutOfRange(2..=3)"

In my case the async_task code is called by bevy here:

https://github.com/bevyengine/bevy/blob/93a131661de507eb711264b11965fe1d4bb13f12/crates/bevy_tasks/src/task_pool.rs#L173

It only happens sometimes though, I can repeat the test multiple times (without recompiling) and this happens only sometimes. Seems to be a race condition.

This is the full console output. My project is rather large so I could not set up a minimal example of this issue yet.

Hidden output

Running unittests src\lib.rs (target\debug\deps\library-55a25fc12b677daa.exe)

running 1 test
thread 'TaskPool (0)' panicked at 'invalid progress_query: QueryOutOfRange(2..=3)', src\controller\test.rs:163:25
stack backtrace:
0: std::panicking::begin_panic_handler
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\std\src\panicking.rs:556
1: core::panicking::panic_fmt
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\core\src\panicking.rs:142
2: library::controller::test::impl$3::run::closure$1<2>
at .\src\controller\test.rs:163
3: core::ops::function::impls::impl$3::call_mut<tuple$<bevy_ecs::system::system_param::Reslibrary::controller::Controller,bevy_ecs::system::commands::Commands>,library::controller::test::impl$3::run::closure_env$1<2> >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\ops\function.rs:297
4: bevy_ecs::system::function_system::impl$18::run::call_inner<tuple$<>,bevy_ecs::system::system_param::Reslibrary::controller::Controller,bevy_ecs::system::commands::Commands,ref_mut$<library::controller::test::impl$3::run::closure_env$1<2> > >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\system\function_system.rs:564
5: bevy_ecs::system::function_system::impl$18::run<tuple$<>,library::controller::test::impl$3::run::closure_env$1<2>,bevy_ecs::system::system_param::Reslibrary::controller::Controller,bevy_ecs::system::commands::Commands>
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\system\function_system.rs:567
6: bevy_ecs::system::function_system::impl$6::run_unsafe<tuple$<>,tuple$<>,tuple$<bevy_ecs::system::system_param::Reslibrary::controller::Controller,bevy_ecs::system::commands::Commands>,tuple$<>,library::controller::test::impl$3::run::closure_env$1<2> >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\system\function_system.rs:403
7: bevy_ecs::schedule::executor_parallel::impl$2::prepare_systems::async_block$0
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\schedule\executor_parallel.rs:194
8: core::future::from_generator::impl$1::poll<enum2$<bevy_ecs::schedule::executor_parallel::impl$2::prepare_systems::async_block_env$0> >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\future\mod.rs:91
9: async_executor::impl$4::spawn::async_block$0<tuple$<>,core::future::from_generator::GenFuture<enum2$<bevy_ecs::schedule::executor_parallel::impl$2::prepare_systems::async_block_env$0> > >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.1\src\lib.rs:144
10: core::future::from_generator::impl$1::poll<enum2$<async_executor::impl$4::spawn::async_block_env$0<tuple$<>,core::future::from_generator::GenFuture<enum2$<bevy_ecs::schedule::executor_parallel::impl$2::prepare_systems::async_block_env$0> > > > >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\future\mod.rs:91
11: async_task::raw::RawTask<core::future::from_generator::GenFuture<enum2$<async_executor::impl$4::spawn::async_block_env$0<tuple$<>,core::future::from_generator::GenFuture<enum2$<bevy_ecs::schedule::executor_parallel::impl$2::prepare_systems::async_block_en
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-task-4.3.0\src\raw.rs:511
12: async_task::runnable::Runnable::run
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-task-4.3.0\src\runnable.rs:309
13: async_executor::impl$4::run::async_fn$0::async_block$0<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,async_channel::Recv<tuple$<> > >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.1\src\lib.rs:235
14: core::future::from_generator::impl$1::poll<enum2$<async_executor::impl$4::run::async_fn$0::async_block_env$0<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,async_channel::Recv<tuple$<> > > > >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\future\mod.rs:91
15: futures_lite::future::impl$12::poll<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,async_channel::Recv<tuple$<> >,core::future::from_generator::GenFuture<enum2$<async_executor::impl$4::run::async_fn$0::async_block_env$0<enum2$<core::resu
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\futures-lite-1.12.0\src\future.rs:529
16: async_executor::impl$4::run::async_fn$0<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,async_channel::Recv<tuple$<> > >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.1\src\lib.rs:242
17: core::future::from_generator::impl$1::poll<enum2$<async_executor::impl$4::run::async_fn_env$0<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,async_channel::Recv<tuple$<> > > > > at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\future\mod.rs:91
18: futures_lite::future::block_on::closure$0<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,core::future::from_generator::GenFuture<enum2$<async_executor::impl$4::run::async_fn_env$0<enum2$<core::result::Result<tuple$<>,async_channel::RecvE
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\futures-lite-1.12.0\src\future.rs:89
19: std::thread::local::LocalKey<core::cell::RefCell<tuple$parking::Parker,core::task::wake::Waker > >::try_with<core::cell::RefCell<tuple$parking::Parker,core::task::wake::Waker >,futures_lite::future::block_on::closure_env$0<enum2$<core::result::Result<
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\std\src\thread\local.rs:446
20: std::thread::local::LocalKey<core::cell::RefCell<tuple$parking::Parker,core::task::wake::Waker > >::with<core::cell::RefCell<tuple$parking::Parker,core::task::wake::Waker >,futures_lite::future::block_on::closure_env$0<enum2$<core::result::Result<tupl
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\std\src\thread\local.rs:422
21: futures_lite::future::block_on<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,core::future::from_generator::GenFuture<enum2$<async_executor::impl$4::run::async_fn_env$0<enum2$<core::result::Result<tuple$<>,async_channel::RecvError> >,asy
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\futures-lite-1.12.0\src\future.rs:79
22: bevy_tasks::task_pool::impl$1::new_internal::closure$0::closure$0
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_tasks-0.8.1\src\task_pool.rs:120
note: Some details are omitted, run with RUST_BACKTRACE=full for
a verbose backtrace.
thread 'controller::test::forward::forward_query_forward_to_too_many_ticks' panicked at 'task has failed', C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-task-4.3.0\src\task.rs:426:45
stack backtrace:
0: std::panicking::begin_panic_handler
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\std\src\panicking.rs:556
1: core::panicking::panic_fmt
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\core\src\panicking.rs:142
2: core::panicking::panic_display
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\core\src\panicking.rs:72
3: core::panicking::panic_str
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\core\src\panicking.rs:56
4: core::option::expect_failed
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\core\src\option.rs:1873
5: enum2$<core::option::Option<tuple$<> > >::expect<tuple$<> >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\option.rs:738
6: async_task::task::impl$7::poll<tuple$<> >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-task-4.3.0\src\task.rs:426
7: bevy_tasks::task_pool::impl$1::scope::closure$0::async_block$0<bevy_ecs::schedule::executor_parallel::impl$1::run_systems::closure_env$0,tuple$<> >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_tasks-0.8.1\src\task_pool.rs:173
8: core::future::from_generator::impl$1::poll<enum2$<bevy_tasks::task_pool::impl$1::scope::closure$0::async_block_env$0<bevy_ecs::schedule::executor_parallel::impl$1::run_systems::closure_env$0,tuple$<> > > >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\future\mod.rs:91
9: core::future::future::impl$1::poll<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,alloc::vec::Vec<tuple$<>,alloc::alloc::Global> > > > > >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\future\future.rs:124
10: async_executor::impl$9::spawn::async_block$0<alloc::vec::Vec<tuple$<>,alloc::alloc::Global>,core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,alloc::vec::Vec<tuple$<>,alloc::alloc::Global> > > > > > >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.1\src\lib.rs:376
11: core::future::from_generator::impl$1::poll<enum2$<async_executor::impl$9::spawn::async_block_env$0<alloc::vec::Vec<tuple$<>,alloc::alloc::Global>,core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,alloc::vec::Vec<tuple$<>,alloc::alloc
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\future\mod.rs:91
12: async_task::raw::RawTask<core::future::from_generator::GenFuture<enum2$<async_executor::impl$9::spawn::async_block_env$0<alloc::vec::Vec<tuple$<>,alloc::alloc::Global>,core::pin::Pin<ref_mut$<dyn$<core::future::future::Future<assoc$<Output,alloc::vec::Vec
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-task-4.3.0\src\raw.rs:511
13: async_task::runnable::Runnable::run
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-task-4.3.0\src\runnable.rs:309
14: async_executor::Executor::try_tick
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.1\src\lib.rs:181
15: async_executor::LocalExecutor::try_tick
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\async-executor-1.4.1\src\lib.rs:405
16: bevy_tasks::task_pool::impl$1::scope::closure$0<bevy_ecs::schedule::executor_parallel::impl$1::run_systems::closure_env$0,tuple$<> >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_tasks-0.8.1\src\task_pool.rs:202
17: std::thread::local::LocalKey<async_executor::LocalExecutor>::try_with<async_executor::LocalExecutor,bevy_tasks::task_pool::impl$1::scope::closure_env$0<bevy_ecs::schedule::executor_parallel::impl$1::run_systems::closure_env$0,tuple$<> >,alloc::vec::Vec<tu
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\std\src\thread\local.rs:446
18: std::thread::local::LocalKey<async_executor::LocalExecutor>::with<async_executor::LocalExecutor,bevy_tasks::task_pool::impl$1::scope::closure_env$0<bevy_ecs::schedule::executor_parallel::impl$1::run_systems::closure_env$0,tuple$<> >,alloc::vec::Vec<tuple$
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\std\src\thread\local.rs:422
19: bevy_tasks::task_pool::TaskPool::scope<bevy_ecs::schedule::executor_parallel::impl$1::run_systems::closure_env$0,tuple$<> >
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_tasks-0.8.1\src\task_pool.rs:148
20: bevy_ecs::schedule::executor_parallel::impl$1::run_systems
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\schedule\executor_parallel.rs:126
21: bevy_ecs::schedule::stage::impl$1::run
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\schedule\stage.rs:884
22: bevy_ecs::schedule::Schedule::run_once
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\schedule\mod.rs:342
23: bevy_ecs::schedule::impl$1::run
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_ecs-0.8.1\src\schedule\mod.rs:360
24: bevy_app::app::App::update
at C:\Users\Anonymous.cargo\registry\src\github.com-1ecc6299db9ec823\bevy_app-0.8.1\src\app.rs:119
25: library::controller::test::impl$3::run::closure$4<2>
at .\src\controller\test.rs:208
26: core::iter::traits::iterator::Iterator::for_each::call::closure$0<usize,library::controller::test::impl$3::run::closure_env$4<2> >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\iter\traits\iterator.rs:828
27: core::iter::traits::iterator::Iterator::fold<core::ops::range::Range,tuple$<>,core::iter::traits::iterator::Iterator::for_each::call::closure_env$0<usize,library::controller::test::impl$3::run::closure_env$4<2> > >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\iter\traits\iterator.rs:2414
28: core::iter::traits::iterator::Iterator::for_each<core::ops::range::Range,library::controller::test::impl$3::run::closure_env$4<2> >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\iter\traits\iterator.rs:831
29: library::controller::test::impl$3::run<2>
at .\src\controller\test.rs:208
30: library::controller::test::forward::forward_query_forward_to_too_many_ticks
at .\src\controller\test\forward.rs:94
31: library::controller::test::forward::forward_query_forward_to_too_many_ticks::closure$0
at .\src\controller\test\forward.rs:93
32: core::ops::function::FnOnce::call_once<library::controller::test::forward::forward_query_forward_to_too_many_ticks::closure_env$0,tuple$<> >
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c\library\core\src\ops\function.rs:251
33: core::ops::function::FnOnce::call_once
at /rustc/57f097ea25f2c05f424fc9b9dc50dbd6d399845c/library\core\src\ops\function.rs:251
note: Some details are omitted, run with RUST_BACKTRACE=full for
a verbose backtrace.
test controller::test::forward::forward_query_forward_to_too_many_ticks - should panic ... FAILED

failures:

---- controller::test::forward::forward_query_forward_to_too_many_ticks stdout ----
note: panic did not contain expected string
panic message: "task has failed",
expected substring: "invalid progress_query: QueryOutOfRange(2..=3)"

failures:
controller::test::forward::forward_query_forward_to_too_many_ticks

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

[notgull]

At the moment, async-task doesn't handle panics beyond just propagating them up to whatever's running the task at the moment (most likely a thread in a thread pool). If you want to be able to propagate panics logically, you should file a feature request in the async-task repository.

I just realized that this is async-task. Do you want to be able to propagate panics?

[urben1680]

Yes that was my intention so I am able to align my unittests to certain panic messages no matter which thread they happen in.

Personally I fixed the issue by changing my tests to not use should_panic but instead check the error in an assert inside the test. Still this might be worth investigating to support for other users.