[Bug]: The test case curp::it read_state::read_state sometimes failed #782
Assignees
Labels
bug
Something isn't working
Comments
|
👋 Thanks for opening this issue! Reply with the following command on its own line to get help or engage:
|
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Description about the bug
As the title description, the test case
curp::it read_state::read_statefails sometimes. The log has been paste down below.Version
0.6.1 (Default)
Relevant log output
PASS [ 7.556s] curp server::raw_curp::tests::follower_will_not_start_election_when_heartbeats_are_received SIGABRT [ 1.047s] curp::it read_state::read_state --- STDOUT: curp::it read_state::read_state --- running 1 test 0.020246518s DEBUG curp::server::curp_node: 2368797937378912452 to 10032832549340216369 sync follower task start 0.020247149s DEBUG curp::server::curp_node: 2368797937378912452 to 3383425158938590665 sync follower task start 0.020811636s DEBUG curp::server::raw_curp: 10032832549340216369 becomes the leader 0.020982688s DEBUG curp::server::curp_node: 10032832549340216369 to 2368797937378912452 sync follower task start 0.021027802s DEBUG curp::server::curp_node: 10032832549340216369 to 3383425158938590665 sync follower task start 0.021459411s DEBUG curp::server::curp_node: 3383425158938590665 to 10032832549340216369 sync follower task start 0.021489868s DEBUG curp::server::curp_node: 3383425158938590665 to 2368797937378912452 sync follower task start 0.041409297s DEBUG curp_append_entries: curp::server::raw_curp: 3383425158938590665 updates to term 1 and becomes a follower 0.041408692s DEBUG curp_append_entries: curp::server::raw_curp: 2368797937378912452 updates to term 1 and becomes a follower 0.361394941s DEBUG curp_propose: curp::server::raw_curp: 10032832549340216369 gets proposal for cmd(0#8502775129477426034) 0.361697215s DEBUG curp_propose: curp::server::raw_curp: 3383425158938590665 gets proposal for cmd(0#8502775129477426034) 0.362214577s DEBUG curp::rpc::connect: client request a client id 0.362988157s DEBUG curp_propose: curp::server::raw_curp: 2368797937378912452 gets proposal for cmd(0#8502775129477426034) 0.363452834s DEBUG curp_wait_synced: curp::server::curp_node: 10032832549340216369 get wait synced request for cmd(0#8502775129477426034) 0.377538457s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#8502775129477426034) into spec pool 0.378227088s INFO curp::rpc::connect: client_id update to 3190277072616043728 0.378611207s DEBUG curp::rpc::connect: client keep alive the client id(3190277072616043728) 0.378677045s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#8502775129477426034) into spec pool 0.378776371s DEBUG curp_propose: curp::server::raw_curp: 10032832549340216369 gets new log[1] 0.379642169s DEBUG curp::server::curp_node: 10032832549340216369 send append_entries to 3383425158938590665 0.380024480s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#8502775129477426034) into spec pool 0.380528380s DEBUG curp_append_entries: curp::server::raw_curp: 3383425158938590665 received append_entries from 10032832549340216369: term(1), commit(0), prev_log_index(0), prev_log_term(0), 1 entries 0.378828845s DEBUG curp::rpc::connect: client request a client id 0.381406256s DEBUG curp::server::raw_curp::state: follower 3383425158938590665's match_index updated to 1 0.381483190s DEBUG curp::server::raw_curp: 10032832549340216369 updates commit index to 1 0.381513557s DEBUG curp::server::raw_curp: 10032832549340216369 committed log[1], last_applied updated to 1 0.381701239s INFO curp::rpc::connect: client_id update to 14212296517839440051 0.383209024s DEBUG curp::rpc::connect: client keep alive the client id(14212296517839440051) 0.393442590s DEBUG curp::server::curp_node: 10032832549340216369 send append_entries to 2368797937378912452 0.394142421s DEBUG curp_append_entries: curp::server::raw_curp: 2368797937378912452 received append_entries from 10032832549340216369: term(1), commit(1), prev_log_index(0), prev_log_term(0), 1 entries 0.394205269s DEBUG curp_append_entries: curp::server::raw_curp: 2368797937378912452 committed log[1], last_applied updated to 1 0.394621592s DEBUG curp::server::raw_curp::state: follower 2368797937378912452's match_index updated to 1 0.522230034s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8502775129477426034), entry_data: Command(TestCommand { keys: [0], exe_dur: 100ms, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) }) 0.522231980s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8502775129477426034), entry_data: Command(TestCommand { keys: [0], exe_dur: 100ms, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) }) 0.522429387s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8502775129477426034), entry_data: Command(TestCommand { keys: [0], exe_dur: 100ms, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) }) 0.623031307s DEBUG curp_append_entries: curp::server::raw_curp: 3383425158938590665 committed log[1], last_applied updated to 1 0.623342770s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8502775129477426034), entry_data: Command(TestCommand { keys: [0], exe_dur: 100ms, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) }) test panic! @info: panicked at 'internal error: entered unreachable code: expected result should be ReadState::Ids(v) where len(v) = 1, but received CommitIndex(0)', crates/curp/tests/it/read_state.rs:39:9 @stackTrace: 0: it::read_state::read_state::{closure#0} 1: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/alloc/src/boxed.rs:1999:9 2: std::panicking::rust_panic_with_hook at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:709:13 3: std::panicking::begin_panic_handler::{{closure}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:597:13 4: std::sys_common::backtrace::__rust_end_short_backtrace at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/sys_common/backtrace.rs:151:18 5: rust_begin_unwind at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:593:5 6: core::panicking::panic_fmt at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/panicking.rs:67:14 7: it::read_state::read_state::{closure#1} 8: <core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>> as core::future::future::Future>::poll 9: <tokio::runtime::park::CachedParkThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>::{closure#0} 10: <tokio::runtime::park::CachedParkThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>> 11: <tokio::runtime::context::blocking::BlockingRegionGuard>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>> 12: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>::{closure#0} 13: __covrec_47AAACAF8F76B10Eu 14: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>> 15: __covrec_43763DF24DB4D2BE 16: it::read_state::read_state 17: it::read_state::read_state::{closure#0} 18: <it::read_state::read_state::{closure#0} as core::ops::function::FnOnce<()>>::call_once 19: core::ops::function::FnOnce::call_once at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/ops/function.rs:250:5 20: test::__rust_begin_short_backtrace at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:655:18 21: test::run_test::{{closure}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:646:30 22: core::ops::function::FnOnce::call_once{{vtable.shim}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/ops/function.rs:250:5 23: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/alloc/src/boxed.rs:1985:9 24: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/panic/unwind_safe.rs:271:9 25: std::panicking::try::do_call at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:500:40 26: std::panicking::try at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:464:19 27: std::panic::catch_unwind at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panic.rs:142:14 28: test::run_test_in_process at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:678:27 29: test::run_test::run_test_inner::{{closure}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:572:39 30: test::run_test::run_test_inner::{{closure}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:599:37 31: std::sys_common::backtrace::__rust_begin_short_backtrace at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/sys_common/backtrace.rs:135:18 32: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/thread/mod.rs:529:17 33: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/panic/unwind_safe.rs:271:9 34: std::panicking::try::do_call at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:500:40 35: std::panicking::try at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:464:19 36: std::panic::catch_unwind at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panic.rs:142:14 37: std::thread::Builder::spawn_unchecked_::{{closure}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/thread/mod.rs:528:30 38: core::ops::function::FnOnce::call_once{{vtable.shim}} at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/ops/function.rs:250:5 39: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/alloc/src/boxed.rs:1985:9 40: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/alloc/src/boxed.rs:1985:9 41: std::sys::unix::thread::Thread::new::thread_start at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/sys/unix/thread.rs:108:17 42: <unknown> 43: __clone 0.833278631s DEBUG curp_test_utils::test_cmd: S0 execute cmd(TestCommand { keys: [0], exe_dur: 100ms, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) Canceling due to test failure: 3 tests still running PASS [ 1.388s] curp::it server::basic_propose PASS [ 1.345s] curp::it server::exe_exact_n_times PASS [ 2.377s] curp::it server::concurrent_cmd_order PASS [ 4.346s] curp::it server::concurrent_cmd_order_should_have_correct_revision ------------ Summary [ 17.014s] 122/340 tests run: 121 passed, 1 failed, 0 skipped SIGABRT [ 1.047s] curp::it read_state::read_state error: test run failed error: process didn't exit successfully: `/github/home/.rustup/toolchains/1.71.0-x86_64-unknown-linux-gnu/bin/cargo nextest run --manifest-path /__w/Xline/Xline/Cargo.toml --target-dir /__w/Xline/Xline/target/llvm-cov-target --all-features --workspace` (exit status: 100) Error: Process completed with exit code 1.Code of Conduct
The text was updated successfully, but these errors were encountered: