search

xline-kv / Xline

A geo-distributed KV store for metadata management
https://xline.cloud
Apache License 2.0
562 stars 71 forks source link

[Bug]: The test case curp::it read_state::read_state sometimes failed #782

Open Phoenix500526 opened 2 months ago

Phoenix500526 commented 2 months ago

Description about the bug

As the title description, the test case curp::it read_state::read_state fails 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

github-actions[bot] commented 2 months ago

👋 Thanks for opening this issue!

Reply with the following command on its own line to get help or engage: