search

tokio-rs / loom

Concurrency permutation testing tool for Rust.
MIT License
2.08k stars 110 forks source link

panicked at 'called `Option::unwrap()` #331

Closed GlenDC closed 11 months ago

GlenDC commented 12 months ago

I implemented my first (unit) test using Loom:

https://github.com/plabayo/tokio-graceful/blob/41b77187f9fed59fc48074a7256e6f078477f2d4/src/trigger.rs#L223-L237

Problem is however that I get a panic when running it, even when removing most logic I still get the same panic.

This is how I run the test:

RUST_BACKTRACE=1 \
    LOOM_LOG=trace \
    LOOM_LOCATION=1 \
    LOOM_CHECKPOINT_INTERVAL=1 \
    LOOM_CHECKPOINT_FILE=target/test_loom.json \
    RUSTFLAGS="--cfg loom" \
 cargo test test_loom --release

as well as:

RUSTFLAGS="--cfg loom"  cargo test test_loom --release

It panics however. Locally I only get this meaningless error:

running 1 test
thread panicked while panicking. aborting.
error: test failed, to rerun pass `--lib`

Caused by:
  process didn't exit successfully: `/Users/glendc/code/github.com/plabayo/tokio-graceful/target/release/deps/tokio_graceful-843928df010f2f44 test_loom` (signal: 6, SIGABRT: process abort signal)

Within the CI environment where this test now also runs I do get a better error:

 running 1 test
thread 'trigger::loom_tests::test_loom_sender_trigger' panicked at 'deadlock; threads = [(Id(0), Blocked(Location(None))), (Id(1), Terminated)]', /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/loom-0.7.0/src/rt/execution.rs:216:13
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
thread 'trigger::loom_tests::test_loom_sender_trigger' panicked at 'called `Option::unwrap()` on a `None` value', /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/loom-0.7.0/src/rt/thread.rs:276:39
stack backtrace:
   0:     0x55c6a2c84071 - std::backtrace_rs::backtrace::libunwind::trace::hc5a5a7e975d8755e
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x55c6a2c84071 - std::backtrace_rs::backtrace::trace_unsynchronized::h84e5c72629d19937
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x55c6a2c84071 - std::sys_common::backtrace::_print_fmt::he3c46ed0d36f4aec
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x55c6a2c84071 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hfc5fcda08d2037a2
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x55c6a2cb006f - core::fmt::rt::Argument::fmt::hbd2b033155184b18
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/fmt/rt.rs:138:9
   5:     0x55c6a2cb006f - core::fmt::write::h3408[25](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:26)c0920a31a7
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/fmt/mod.rs:1094:21
   6:     0x55c6a2c80ed7 - std::io::Write::write_fmt::h28a7e8092125fab5
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/io/mod.rs:1714:15
   7:     0x55c6a2c83e85 - std::sys_common::backtrace::_print::hecdbb567735dad9c
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x55c6a2c83e85 - std::sys_common::backtrace::print::hfd4cba0c975574f1
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x55c6a2c85b13 - std::panicking::default_hook::{{closure}}::h4a0157e348171cd9
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:[26](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:27)9:22
  10:     0x55c6a2c85830 - std::panicking::default_hook::hf8a7bfcf739d8205
                               at /rustc/cb80ff132a0e9aa71529b7014[27](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:28)e4e6c243b58df/library/std/src/panicking.rs:[28](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:29)5:9
  11:     0x55c6a2b59842 - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h72a283dac234f22c
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/alloc/src/boxed.rs:2007:9
  12:     0x55c6a2b59842 - test::test_main::{{closure}}::h27f4c8f93c745ee8
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/test/src/lib.rs:135:21
  13:     0x55c6a2c8620e - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h2b65d785c4d54c97
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/alloc/src/boxed.rs:2007:9
  14:     0x55c6a2c8620e - std::panicking::rust_panic_with_hook::h4e348dfb616f7837
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:709:13
  15:     0x55c6a2c85f51 - std::panicking::begin_panic_handler::{{closure}}::he6cb66e2ffdddd57
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:595:13
  16:     0x55c6a2c844d6 - std::sys_common::backtrace::__rust_end_short_backtrace::h748cfc33011f2562
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:151:18
  17:     0x55c6a2c85ce2 - rust_begin_unwind
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:593:5
  18:     0x55c6a2addc13 - core::panicking::panic_fmt::he97c92a69214704e
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/panicking.rs:67:14
  19:     0x55c6a2addca3 - core::panicking::panic::h869a47101d6ef1a5
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/panicking.rs:117:5
  20:     0x55c6a2b8b63c - loom::rt::object::Ref<T>::set_action::h5c4481ea4caeae98
  21:     0x55c6a2b9b300 - scoped_tls::ScopedKey<T>::with::hdcf854c86dc9a700
  22:     0x55c6a2b87ea6 - loom::rt::arc::Arc::ref_dec::hd8e79e249df5379f
  23:     0x55c6a2afa89c - <loom::sync::arc::Arc<T> as core::ops::drop::Drop>::drop::hd53c9409cc839cf2
  24:     0x55c6a2b15193 - core::ptr::drop_in_place<loom::sync::arc::Arc<loom::rt::notify::Notify>>::h47f3cc86eeb7af8f
  25:     0x55c6a2b1567e - loom::future::block_on::h96dd0893b54469f8
  26:     0x55c6a2b02e41 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hd7f90addcc081bb6
  27:     0x55c6a2b86b84 - generator::stack::StackBox<F>::call_once::h60eaf67a40de78c8
  28:     0x55c6a2c56c8b - std::panicking::try::hc4b796f21bb6633c
  29:     0x55c6a2c569dd - generator::gen_impl::gen_init::hb39c800ae81cae69
  30:                0x0 - <unknown>
thread 'trigger::loom_tests::test_loom_sender_trigger' panicked at 'panic in a function that cannot unwind', library/core/src/panicking.rs:126:5
stack backtrace:
   0:     0x55c6a2c84071 - std::backtrace_rs::backtrace::libunwind::trace::hc5a5a7e975d8755e
                               at /rustc/cb80ff132a0e9aa715[29](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:30)b701427e4e6c243b58df/library/std/src/../../backtrace/src/backtrace/libunwind.rs:93:5
   1:     0x55c6a2c84071 - std::backtrace_rs::backtrace::trace_unsynchronized::h84e5c72629d19937
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x55c6a2c84071 - std::sys_common::backtrace::_print_fmt::he3c46ed0d36f4aec
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:65:5
   3:     0x55c6a2c84071 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hfc5fcda08d2037a2
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x55c6a2cb006f - core::fmt::rt::Argument::fmt::hbd2b033155184b18
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/fmt/rt.rs:138:9
   5:     0x55c6a2cb006f - core::fmt::write::h340825c0920a31a7
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/fmt/mod.rs:1094:21
   6:     0x55c6a2c80dd7 - std::io::Write::write_fmt::h0075c984dd7bcfd8
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/io/mod.rs:1714:15
   7:     0x55c6a2c83e85 - std::sys_common::backtrace::_print::hecdbb567735dad9c
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x55c6a2c83e85 - std::sys_common::backtrace::print::hfd4cba0c975574f1
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x55c6a2c85b13 - std::panicking::default_hook::{{closure}}::h4a0157e348171cd9
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:269:22
  10:     0x55c6a2c858a4 - std::panicking::default_hook::hf8a7bfcf739d8205
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:288:9
  11:     0x55c6a2b59842 - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h72a283dac234f22c
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/alloc/src/boxed.rs:2007:9
  12:     0x55c6a2b59842 - test::test_main::{{closure}}::h27f4c8f93c745ee8
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/test/src/lib.rs:135:21
  13:     0x55c6a2c8620e - <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call::h2b65d785c4d54c97
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/alloc/src/boxed.rs:2007:9
  14:     0x55c6a2c8620e - std::panicking::rust_panic_with_hook::h4e348dfb616f7837
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:709:13
  15:     0x55c6a2c85f51 - std::panicking::begin_panic_handler::{{closure}}::he6cb66e2ffdddd57
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:595:13
  16:     0x55c6a2c844d6 - std::sys_common::backtrace::__rust_end_short_backtrace::h748cfc3[30](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:31)11f2562
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/sys_common/backtrace.rs:151:18
  17:     0x55c6a2c85ce2 - rust_begin_unwind
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/std/src/panicking.rs:593:5
  18:     0x55c6a2addc53 - core::panicking::panic_nounwind_fmt::hf0[31](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:32)76b9eea67b7f
                               at /rustc/cb80ff1[32](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:33)a0e9aa71529b701427e4e6c243b58df/library/core/src/panicking.rs:96:14
  19:     0x55c6a2addcf7 - core::panicking::panic_nounwind::h078e837899a661cc
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/panicking.rs:126:5
  20:     0x55c6a2addd93 - core::panicking::panic_cannot_unwind::h3640cea856efb54b
                               at /rustc/cb80ff132a0e9aa71529b701427e4e6c243b58df/library/core/src/panicking.rs:189:5
  21:     0x55c6a2b15698 - loom::future::block_on::h96dd0893b54469f8
  22:     0x55c6a2b02e41 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hd7f90addcc081bb6
  23:     0x55c6a2b86b84 - generator::stack::StackBox<F>::call_once::h60eaf67a40de78c8
  24:     0x55c6a2c56c8b - std::panicking::try::hc4b796f21bb66[33](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:34)c
  25:     0x55c6a2c569dd - generator::gen_impl::gen_init::hb[39](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:40)c800ae81cae69
  26:                0x0 - <unknown>
thread caused non-unwinding panic. aborting.
error: test failed, to rerun pass `--lib`

Caused by:
  process didn't exit successfully: `/home/runner/work/tokio-graceful/tokio-graceful/target/release/deps/tokio_graceful-fc2[49](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:50)14d27e9a4b1 test_loom` (signal: 6, SIGABRT: process abort signal)
Error: The process '/home/runner/.cargo/bin/cargo' failed with exit code [101](https://github.com/plabayo/tokio-graceful/actions/runs/6194982179/job/16818888474?pr=3#step:5:102)

Am I using loom incorrect? Is it not made for these purposes? Do I have a bug in my code? Does documentation need to be updated? no clue. Any help is welcome. I'm also on Tokio's discord as @glendc. Available here, but also there.

hawkw commented 11 months ago

Note that the second panic message begins with:

thread 'trigger::loom_tests::test_loom_sender_trigger' panicked at 'deadlock; threads = [(Id(0), Blocked(Location(None))), (Id(1), Terminated)]', /home/runner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/loom-0.7.0/src/rt/execution.rs:216:13

This indicates thatloom panicked due to a deadlock in the code under test: either a bug in your code, or in your test.

After this panic occurred, a double-panic occurred while unwinding. This often happens when a Drop impl does something that requires accessing the loom test execution state, but the test context has already been torn down. This is kind of an annoying rough edge when using loom --- we should probably spend some time ensuring that loom's simulated atomics and synchronization primitives behave more gracefully when used in a Drop impl during a panic. That would likely require some effort though.

GlenDC commented 11 months ago

Ok for now going to close the issue then. I haven't found the reason yet, but so far the theory from your end is that it is anyway on my end (whether in the test or actual code). So going to not botter your time more here in that case. If it does end up be a loom issue I'll re-open, but so far it doesn't seem like it is. Thanks!

hawkw commented 11 months ago

The double panic is kind of a loom issue, but it's occurring due to a panic from loom correctly detecting a deadlock in your test. So, loom found an issue in your code, and we should fix the double panic so that loom can report these errors better and make them easier to debug :)

GlenDC commented 11 months ago

Yes I did find the issue in the meanwhile. Turns out I was having a race condition that loom detected which caused me to never wake up... Gosh. Good that i start using loom for these very core primitives of my crate.