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 server::shutdown_rpc_should_shutdown_the_cluster failed #774

Closed Phoenix500526 closed 2 months ago

Phoenix500526 commented 2 months ago

Description about the bug

The test case curp::it server::shutdown_rpc_should_shutdown_the_cluster failed sometimes. The output log has been pasted below.

FYI: https://github.com/xline-kv/Xline/actions/runs/8626722031/job/23645355082?pr=772

Version

0.6.1 (Default)

Relevant log output

SIGABRT [   8.488s] curp::it server::shutdown_rpc_should_shutdown_the_cluster

--- STDOUT:              curp::it server::shutdown_rpc_should_shutdown_the_cluster ---

running 1 test
   0.049279817s DEBUG curp::server::curp_node: 8280384654968381684 to 13740163161196736920 sync follower task start
   0.049290450s DEBUG curp::server::curp_node: 8280384654968381684 to 11072999871023124112 sync follower task start
   0.090303489s DEBUG curp::server::raw_curp: 11072999871023124112 becomes the leader
   0.090505576s DEBUG curp::server::curp_node: 11072999871023124112 to 8280384654968381684 sync follower task start
   0.090521933s DEBUG curp::server::curp_node: 11072999871023124112 to 13740163161196736920 sync follower task start
   0.093805270s DEBUG curp_append_entries: curp::server::raw_curp: 8280384654968381684 updates to term 1 and becomes a follower
   0.143433580s  WARN curp::server::curp_node: ae to 13740163161196736920 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
   0.159462727s DEBUG curp::server::curp_node: 13740163161196736920 to 8280384654968381684 sync follower task start
   0.159521547s DEBUG curp::server::curp_node: 13740163161196736920 to 11072999871023124112 sync follower task start
   0.393044405s DEBUG curp_append_entries: curp::server::raw_curp: 13740163161196736920 updates to term 1 and becomes a follower
   0.465063805s DEBUG curp::rpc::connect: client request a client id
   0.466749142s DEBUG curp_propose: curp::server::raw_curp: 13740163161196736920 gets proposal for cmd(0#8342557537241818130)
   0.466812601s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#8342557537241818130) into spec pool
   0.466916334s DEBUG curp_propose: curp::server::raw_curp: 8280384654968381684 gets proposal for cmd(0#8342557537241818130)
   0.466969925s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#8342557537241818130) into spec pool
   0.468018981s DEBUG curp_wait_synced: curp::server::curp_node: 11072999871023124112 get wait synced request for cmd(0#8342557537241818130)
   0.468306247s DEBUG curp_propose: curp::server::raw_curp: 11072999871023124112 gets proposal for cmd(0#8342557537241818130)
   0.468371419s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#8342557537241818130) into spec pool
   0.468463912s DEBUG curp_propose: curp::server::raw_curp: 11072999871023124112 gets new log[1]
   0.468660339s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8342557537241818130), entry_data: Command(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) })
   0.468943380s  INFO curp::rpc::connect: client_id update to 15319437023339269808
   0.469364453s DEBUG curp::rpc::connect: client keep alive the client id(15319437023339269808)
   0.469504929s DEBUG curp_test_utils::test_cmd: S0 execute cmd(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) })
   0.469590439s DEBUG curp::server::cmd_worker: 11072999871023124112 cmd(0#8342557537241818130) is speculatively executed, exe status: true
   0.469875177s DEBUG curp::rpc::connect: client request a client id
   0.470349574s DEBUG curp::client::unary: fast round for cmd(0#8342557537241818130) succeed
   0.470616926s DEBUG curp_shutdown: curp::server::raw_curp: 11072999871023124112 gets new log[2]
   0.471426087s  INFO curp::rpc::connect: client_id update to 374129606305631114
   0.471566960s DEBUG curp_propose: curp::server::raw_curp: 13740163161196736920 gets proposal for cmd(15319437023339269808#11332082429541464495)
   0.471573289s DEBUG curp_propose: curp::server::raw_curp: 8280384654968381684 gets proposal for cmd(15319437023339269808#11332082429541464495)
   0.471641179s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#11332082429541464495) into spec pool
   0.471679697s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#11332082429541464495) into spec pool
   0.472289350s DEBUG curp::rpc::connect: client keep alive the client id(374129606305631114)
   0.472342766s DEBUG curp_wait_synced: curp::server::curp_node: 11072999871023124112 get wait synced request for cmd(15319437023339269808#11332082429541464495)
   0.472354628s DEBUG curp_propose: curp::server::raw_curp: 11072999871023124112 gets proposal for cmd(15319437023339269808#11332082429541464495)
   0.472397708s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#11332082429541464495) into spec pool
   0.472458371s DEBUG curp_propose: curp::server::raw_curp: 11072999871023124112 gets new log[3]
   0.472614283s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(15319437023339269808, 11332082429541464495), entry_data: Command(TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) }) })
   0.473642186s DEBUG curp_test_utils::test_cmd: S0 execute cmd(TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) })
   0.473685047s DEBUG curp::server::cmd_worker: 11072999871023124112 cmd(15319437023339269808#11332082429541464495) is speculatively executed, exe status: true
   0.473701006s DEBUG curp::server::curp_node: 11072999871023124112 send append_entries to 13740163161196736920
   0.473701052s DEBUG curp::server::curp_node: 11072999871023124112 send append_entries to 8280384654968381684
   0.474361831s DEBUG curp::client::unary: fast round for cmd(15319437023339269808#11332082429541464495) succeed
   0.474520453s DEBUG curp_append_entries: curp::server::raw_curp: 8280384654968381684 received append_entries from 11072999871023124112: term(1), commit(0), prev_log_index(0), prev_log_term(0), 3 entries
   0.474585154s DEBUG curp_append_entries: curp::server::raw_curp: 13740163161196736920 received append_entries from 11072999871023124112: term(1), commit(0), prev_log_index(0), prev_log_term(0), 3 entries
   0.475749663s DEBUG curp_propose: curp::server::raw_curp: 13740163161196736920 gets proposal for cmd(15319437023339269808#12127689148376051421)
   0.475763839s DEBUG curp::server::raw_curp::state: follower 8280384654968381684's match_index updated to 3
   0.475837463s DEBUG curp::server::raw_curp::state: follower 13740163161196736920's match_index updated to 3
   0.475828169s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#12127689148376051421) into spec pool
   0.475872733s DEBUG curp::server::raw_curp: 11072999871023124112 updates commit index to 3
   0.475948754s DEBUG curp::server::raw_curp: 11072999871023124112 committed log[1], last_applied updated to 1
   0.475974122s DEBUG curp::server::raw_curp: 11072999871023124112 committed log[2], last_applied updated to 2
   0.475986505s DEBUG curp::server::raw_curp: 11072999871023124112 committed log[3], last_applied updated to 3
   0.476057067s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8342557537241818130), entry_data: Command(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) })
   0.476117760s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 2, propose_id: ProposeId(0, 6931548765640390236), entry_data: Shutdown })
   0.476165409s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(15319437023339269808, 11332082429541464495), entry_data: Command(TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) }) })
   0.476160326s DEBUG curp_wait_synced: curp::server::curp_node: 11072999871023124112 get wait synced request for cmd(15319437023339269808#12127689148376051421)
   0.476326246s DEBUG curp_propose: curp::server::raw_curp: 11072999871023124112 gets proposal for cmd(15319437023339269808#12127689148376051421)
   0.476366040s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#12127689148376051421) into spec pool
   0.476466522s DEBUG curp_propose: curp::server::raw_curp: 11072999871023124112 gets new log[4]
   0.476525178s DEBUG curp_propose: curp::server::raw_curp: 8280384654968381684 gets proposal for cmd(15319437023339269808#12127689148376051421)
   0.476608523s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#12127689148376051421) into spec pool
   0.476634415s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(15319437023339269808, 12127689148376051421), entry_data: Command(TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) }) })
   0.477970637s DEBUG curp_test_utils::test_cmd: cmd Put(1)-TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) } revision is 2
   0.477986450s DEBUG curp_test_utils::test_cmd: cmd Put(0)-TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) } revision is 1
   0.478061577s DEBUG curp_test_utils::test_cmd: S0 after sync cmd(Put(1) - TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) }), index: 3
   0.478092398s DEBUG curp::server::spec_pool: cmd(0#8342557537241818130) is removed from spec pool
   0.478117084s DEBUG curp::server::cmd_worker: 11072999871023124112 cmd(0#8342557537241818130) after sync is called
   0.478125326s DEBUG curp::server::spec_pool: cmd(15319437023339269808#11332082429541464495) is removed from spec pool
   0.478140655s DEBUG curp::server::cmd_worker: 11072999871023124112 cmd(15319437023339269808#11332082429541464495) after sync is called
   0.478372181s DEBUG curp::server::curp_node: 11072999871023124112 send append_entries to 8280384654968381684
   0.478382490s DEBUG curp::server::curp_node: 11072999871023124112 send append_entries to 13740163161196736920
   0.479174990s DEBUG curp_append_entries: curp::server::raw_curp: 13740163161196736920 received append_entries from 11072999871023124112: term(1), commit(3), prev_log_index(3), prev_log_term(1), 1 entries
   0.479215412s DEBUG curp_append_entries: curp::server::raw_curp: 8280384654968381684 received append_entries from 11072999871023124112: term(1), commit(3), prev_log_index(3), prev_log_term(1), 1 entries
   0.479287767s DEBUG curp_append_entries: curp::server::raw_curp: 8280384654968381684 committed log[1], last_applied updated to 1
   0.479285907s DEBUG curp_append_entries: curp::server::raw_curp: 13740163161196736920 committed log[1], last_applied updated to 1
   0.479344242s DEBUG curp_append_entries: curp::server::raw_curp: 8280384654968381684 committed log[2], last_applied updated to 2
   0.479383917s DEBUG curp_append_entries: curp::server::raw_curp: 8280384654968381684 committed log[3], last_applied updated to 3
   0.479395432s DEBUG curp_append_entries: curp::server::raw_curp: 13740163161196736920 committed log[2], last_applied updated to 2
   0.479442249s DEBUG curp_append_entries: curp::server::raw_curp: 13740163161196736920 committed log[3], last_applied updated to 3
   0.479498494s DEBUG curp_test_utils::test_cmd: S0 execute cmd(TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) })
   0.479551884s DEBUG curp::server::cmd_worker: 11072999871023124112 cmd(15319437023339269808#12127689148376051421) is speculatively executed, exe status: true
   0.479765229s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8342557537241818130), entry_data: Command(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) })
   0.479908680s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 1, propose_id: ProposeId(0, 8342557537241818130), entry_data: Command(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }) })
   0.480796755s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 2, propose_id: ProposeId(0, 6931548765640390236), entry_data: Shutdown })
   0.480850856s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(15319437023339269808, 11332082429541464495), entry_data: Command(TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) }) })
   0.480915551s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 2, propose_id: ProposeId(0, 6931548765640390236), entry_data: Shutdown })
   0.480976194s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 3, propose_id: ProposeId(15319437023339269808, 11332082429541464495), entry_data: Command(TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) }) })
   0.481300039s DEBUG curp::server::raw_curp::state: follower 8280384654968381684's match_index updated to 4
   0.481300046s DEBUG curp::server::raw_curp::state: follower 13740163161196736920's match_index updated to 4
   0.481394853s DEBUG curp::server::raw_curp: 11072999871023124112 updates commit index to 4
   0.481422034s DEBUG curp::server::raw_curp: 11072999871023124112 committed log[4], last_applied updated to 4
   0.481459066s DEBUG curp_propose: curp::server::raw_curp: 8280384654968381684 gets proposal for cmd(374129606305631114#7237228746428657376)
   0.481479591s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(15319437023339269808, 12127689148376051421), entry_data: Command(TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) }) })
   0.481538695s DEBUG curp_propose: curp::server::spec_pool: insert cmd(374129606305631114#7237228746428657376) into spec pool
   0.481739686s DEBUG curp_test_utils::test_cmd: S2 execute cmd(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) })
   0.481743988s DEBUG curp::client::unary: fast round for cmd(15319437023339269808#12127689148376051421) succeed
   0.481798005s DEBUG curp::server::cmd_worker: 8280384654968381684 cmd(0#8342557537241818130) is speculatively executed, exe status: true
   0.481970808s DEBUG curp_test_utils::test_cmd: S1 execute cmd(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) })
   0.482022594s DEBUG curp::server::cmd_worker: 13740163161196736920 cmd(0#8342557537241818130) is speculatively executed, exe status: true
   0.482648444s  WARN curp::client::unary: propose cmd(374129606305631114#7237228746428657376) to server(11072999871023124112) error: ShuttingDown(())
   0.482726673s DEBUG curp_propose: curp::server::raw_curp: 13740163161196736920 gets proposal for cmd(374129606305631114#7237228746428657376)
   0.482795322s DEBUG curp_propose: curp::server::spec_pool: insert cmd(374129606305631114#7237228746428657376) into spec pool
   0.482941331s DEBUG curp_test_utils::test_cmd: cmd Put(0)-TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) } revision is 1
   0.483053380s DEBUG curp_test_utils::test_cmd: S1 after sync cmd(Put(0) - TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }), index: 1
   0.483096381s DEBUG curp::server::spec_pool: cmd(0#8342557537241818130) is removed from spec pool
   0.483117189s DEBUG curp::server::cmd_worker: 13740163161196736920 cmd(0#8342557537241818130) after sync is called
   0.483168058s DEBUG curp_test_utils::test_cmd: cmd Put(2)-TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) } revision is 3
   0.483213709s DEBUG curp_test_utils::test_cmd: cmd Put(0)-TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) } revision is 1
   0.483304302s DEBUG curp_test_utils::test_cmd: S0 after sync cmd(Put(2) - TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) }), index: 4
   0.483310731s DEBUG curp_test_utils::test_cmd: S2 after sync cmd(Put(0) - TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(0) }), index: 1
   0.483395960s DEBUG curp::server::spec_pool: cmd(0#8342557537241818130) is removed from spec pool
   0.483396845s DEBUG curp::server::spec_pool: cmd(15319437023339269808#12127689148376051421) is removed from spec pool
   0.483432729s DEBUG curp::server::cmd_worker: 8280384654968381684 cmd(0#8342557537241818130) after sync is called
   0.483469441s DEBUG curp::server::cmd_worker: 11072999871023124112 cmd(15319437023339269808#12127689148376051421) after sync is called
   0.483522750s DEBUG curp_propose: curp::server::raw_curp: 8280384654968381684 gets proposal for cmd(15319437023339269808#653237559419033139)
   0.483575118s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#653237559419033139) into spec pool
   0.483669404s DEBUG curp_wait_synced: curp::server::curp_node: 11072999871023124112 wait synced for cmd(15319437023339269808#12127689148376051421) finishes
   0.483727208s DEBUG curp_propose: curp::server::raw_curp: 13740163161196736920 gets proposal for cmd(15319437023339269808#653237559419033139)
   0.483775468s DEBUG curp_propose: curp::server::spec_pool: insert cmd(15319437023339269808#653237559419033139) into spec pool
   0.484349240s DEBUG curp_test_utils::test_cmd: S2 execute cmd(TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) })
   0.484398021s DEBUG curp::server::cmd_worker: 8280384654968381684 cmd(15319437023339269808#11332082429541464495) is speculatively executed, exe status: true
   0.484450789s DEBUG curp_test_utils::test_cmd: S1 execute cmd(TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) })
   0.484495352s DEBUG curp::server::cmd_worker: 13740163161196736920 cmd(15319437023339269808#11332082429541464495) is speculatively executed, exe status: true
   0.485291730s DEBUG curp_test_utils::test_cmd: cmd Put(1)-TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) } revision is 2
   0.485291754s DEBUG curp_test_utils::test_cmd: cmd Put(1)-TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) } revision is 2
   0.485374695s  WARN curp::client::unary: propose cmd(15319437023339269808#653237559419033139) to server(11072999871023124112) error: ShuttingDown(())
   0.485393230s DEBUG curp_test_utils::test_cmd: S2 after sync cmd(Put(1) - TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) }), index: 3
   0.485423066s DEBUG curp::server::spec_pool: cmd(15319437023339269808#11332082429541464495) is removed from spec pool
   0.485445548s DEBUG curp::server::cmd_worker: 8280384654968381684 cmd(15319437023339269808#11332082429541464495) after sync is called
   0.485498029s DEBUG curp_test_utils::test_cmd: S1 after sync cmd(Put(1) - TestCommand { keys: [1], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(1) }), index: 3
   0.485572588s DEBUG curp::server::spec_pool: cmd(15319437023339269808#11332082429541464495) is removed from spec pool
   0.485602811s DEBUG curp::server::cmd_worker: 13740163161196736920 cmd(15319437023339269808#11332082429541464495) after sync is called
   0.494474350s  WARN curp::client::unary: propose cmd(15319437023339269808#3835162170736343063) to server(13740163161196736920) error: ShuttingDown(())
   0.496501778s  WARN curp::client::unary: propose cmd(15319437023339269808#7940163969684493405) to server(8280384654968381684) error: ShuttingDown(())
   0.498052618s  WARN curp::client::unary: propose cmd(15319437023339269808#3328045055523687884) to server(8280384654968381684) error: ShuttingDown(())
   0.499736418s  WARN curp::client::unary: propose cmd(15319437023339269808#175023078594302390) to server(13740163161196736920) error: ShuttingDown(())
   0.501508879s  WARN curp::client::unary: propose cmd(15319437023339269808#12299269811468401158) to server(8280384654968381684) error: ShuttingDown(())
   0.693224809s  INFO curp_append_entries: curp::server::cmd_worker: send event after current node shutdown
   0.693224756s  INFO curp_append_entries: curp::server::cmd_worker: send event after current node shutdown
   0.693292165s DEBUG curp_append_entries: curp::server::raw_curp: 13740163161196736920 committed log[4], last_applied updated to 4
   0.693304655s DEBUG curp_append_entries: curp::server::raw_curp: 8280384654968381684 committed log[4], last_applied updated to 4
   0.694625471s DEBUG curp::server::curp_node: election task exits
   0.694691866s DEBUG curp::server::curp_node: election task exits
   0.694881924s DEBUG curp::server::curp_node: trigger shutdown to 8280384654968381684 success
   0.694901270s DEBUG curp::server::curp_node: trigger shutdown to 13740163161196736920 success
   0.694941385s DEBUG curp::server::curp_node: 11072999871023124112 to 8280384654968381684 sync follower task exits
   0.694967003s DEBUG curp::server::curp_node: 11072999871023124112 to 13740163161196736920 sync follower task exits
   0.695118466s DEBUG curp::server::curp_node: election task exits
   1.470180762s DEBUG curp::rpc::connect: client keep alive the client id(15319437023339269808)
   1.473269968s DEBUG curp::rpc::connect: client keep alive the client id(374129606305631114)
   1.474042975s DEBUG curp::server::curp_node: log persist task exits
   1.474060494s DEBUG curp::client::stream: shutting down stream client background task
   1.474137397s DEBUG curp::client: keep heartbeat task shutdown
   7.555915405s DEBUG curp::server::raw_curp: 203168192592235079 becomes the leader
   7.556141592s DEBUG curp::server::curp_node: 203168192592235079 to 7649290866717549222 sync follower task start
   7.556138513s DEBUG curp::server::curp_node: 203168192592235079 to 15601827854439038345 sync follower task start
   7.557360936s DEBUG curp::server::curp_node: 203168192592235079 send append_entries to 15601827854439038345
   7.557380286s DEBUG curp::server::curp_node: 203168192592235079 send append_entries to 7649290866717549222
   7.598508944s DEBUG curp::server::curp_node: 15601827854439038345 to 203168192592235079 sync follower task start
   7.598508958s DEBUG curp::server::curp_node: 15601827854439038345 to 7649290866717549222 sync follower task start
   7.599795672s DEBUG curp_append_entries: curp::server::raw_curp: 15601827854439038345 received append_entries from 203168192592235079: term(1), commit(4), prev_log_index(0), prev_log_term(0), 4 entries
   7.599852018s DEBUG curp_append_entries: curp::server::raw_curp: 15601827854439038345 updates to term 1 and becomes a follower
   7.599903995s DEBUG curp_append_entries: curp::server::raw_curp: 15601827854439038345 committed log[4], last_applied updated to 4
   7.600098394s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(15319437023339269808, 12127689148376051421), entry_data: Command(TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) }) })
   7.601405189s DEBUG curp_test_utils::test_cmd: S1 execute cmd(TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) })
   7.601457978s DEBUG curp::server::cmd_worker: 15601827854439038345 cmd(15319437023339269808#12127689148376051421) is speculatively executed, exe status: true
   7.602645125s DEBUG curp_test_utils::test_cmd: cmd Put(2)-TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) } revision is 3
   7.602748789s DEBUG curp_test_utils::test_cmd: S1 after sync cmd(Put(2) - TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) }), index: 4
   7.602796538s DEBUG curp::server::spec_pool: cmd(15319437023339269808#12127689148376051421) is not in spec pool
   7.602816636s DEBUG curp::server::cmd_worker: 15601827854439038345 cmd(15319437023339269808#12127689148376051421) after sync is called
   7.609043038s  WARN curp::server::curp_node: ae to 15601827854439038345 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
   7.609050812s  WARN curp::server::curp_node: ae to 7649290866717549222 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
   7.624656075s DEBUG curp::server::curp_node: 203168192592235079 send append_entries to 15601827854439038345
   7.624655834s DEBUG curp::server::curp_node: 203168192592235079 send append_entries to 7649290866717549222
   7.625748762s DEBUG curp_append_entries: curp::server::raw_curp: 15601827854439038345 received append_entries from 203168192592235079: term(1), commit(4), prev_log_index(0), prev_log_term(0), 4 entries
   7.626340428s DEBUG curp::server::raw_curp::state: follower 15601827854439038345's match_index updated to 4
   7.642723917s DEBUG curp::server::curp_node: 7649290866717549222 to 15601827854439038345 sync follower task start
   7.642712696s DEBUG curp::server::curp_node: 7649290866717549222 to 203168192592235079 sync follower task start
   7.644005798s DEBUG curp_append_entries: curp::server::raw_curp: 7649290866717549222 received append_entries from 203168192592235079: term(1), commit(4), prev_log_index(0), prev_log_term(0), 4 entries
   7.644052204s DEBUG curp_append_entries: curp::server::raw_curp: 7649290866717549222 updates to term 1 and becomes a follower
   7.644108630s DEBUG curp_append_entries: curp::server::raw_curp: 7649290866717549222 committed log[4], last_applied updated to 4
   7.644266135s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 4, propose_id: ProposeId(15319437023339269808, 12127689148376051421), entry_data: Command(TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) }) })
   7.645554521s DEBUG curp_test_utils::test_cmd: S2 execute cmd(TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) })
   7.645598874s DEBUG curp::server::cmd_worker: 7649290866717549222 cmd(15319437023339269808#12127689148376051421) is speculatively executed, exe status: true
   7.646753110s DEBUG curp_test_utils::test_cmd: cmd Put(2)-TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) } revision is 3
   7.646831356s DEBUG curp_test_utils::test_cmd: S2 after sync cmd(Put(2) - TestCommand { keys: [2], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Put(2) }), index: 4
   7.646859569s DEBUG curp::server::spec_pool: cmd(15319437023339269808#12127689148376051421) is not in spec pool
   7.646870500s DEBUG curp::server::cmd_worker: 7649290866717549222 cmd(15319437023339269808#12127689148376051421) after sync is called
   7.676286772s  WARN curp::server::curp_node: ae to 7649290866717549222 failed, Internal("status: Cancelled, message: \"Timeout expired\", details: [], metadata: MetadataMap { headers: {} }")
   7.692806413s DEBUG curp::server::curp_node: 203168192592235079 send append_entries to 7649290866717549222
   7.693532590s DEBUG curp_append_entries: curp::server::raw_curp: 7649290866717549222 received append_entries from 203168192592235079: term(1), commit(4), prev_log_index(0), prev_log_term(0), 4 entries
   7.693952708s DEBUG curp::server::raw_curp::state: follower 7649290866717549222's match_index updated to 4
   7.947613383s DEBUG curp::rpc::connect: client request a client id
   7.949138429s DEBUG curp_propose: curp::server::raw_curp: 7649290866717549222 gets proposal for cmd(0#17290380797676990359)
   7.949138443s DEBUG curp_propose: curp::server::raw_curp: 15601827854439038345 gets proposal for cmd(0#17290380797676990359)
   7.949198091s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#17290380797676990359) into spec pool
   7.949206470s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#17290380797676990359) into spec pool
   7.949434606s DEBUG curp_wait_synced: curp::server::curp_node: 203168192592235079 get wait synced request for cmd(0#17290380797676990359)
   7.949607970s DEBUG curp_propose: curp::server::raw_curp: 203168192592235079 gets proposal for cmd(0#17290380797676990359)
   7.949657693s DEBUG curp_propose: curp::server::spec_pool: insert cmd(0#17290380797676990359) into spec pool
   7.949688607s  INFO curp::rpc::connect: client_id update to 12375464160287713811
   7.949720941s DEBUG curp_propose: curp::server::raw_curp: 203168192592235079 gets new log[5]
   7.949848148s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: SpecExeReady(LogEntry { term: 1, index: 5, propose_id: ProposeId(0, 17290380797676990359), entry_data: Command(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Get }) })
   7.951122315s DEBUG curp_test_utils::test_cmd: S0 execute cmd(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Get })
   7.951141725s DEBUG curp::rpc::connect: client keep alive the client id(12375464160287713811)
   7.951314705s DEBUG curp::server::cmd_worker: 203168192592235079 cmd(0#17290380797676990359) is speculatively executed, exe status: true
   7.954965368s DEBUG curp::server::curp_node: 203168192592235079 send append_entries to 7649290866717549222
   7.954965315s DEBUG curp::server::curp_node: 203168192592235079 send append_entries to 15601827854439038345
   7.955696460s DEBUG curp_append_entries: curp::server::raw_curp: 15601827854439038345 received append_entries from 203168192592235079: term(1), commit(4), prev_log_index(4), prev_log_term(1), 1 entries
   7.955698254s DEBUG curp_append_entries: curp::server::raw_curp: 7649290866717549222 received append_entries from 203168192592235079: term(1), commit(4), prev_log_index(4), prev_log_term(1), 1 entries
   7.956183634s DEBUG curp::server::raw_curp::state: follower 7649290866717549222's match_index updated to 5
   7.956188974s DEBUG curp::server::raw_curp::state: follower 15601827854439038345's match_index updated to 5
   7.956230371s DEBUG curp::server::raw_curp: 203168192592235079 updates commit index to 5
   7.956256610s DEBUG curp::server::raw_curp: 203168192592235079 committed log[5], last_applied updated to 5
   7.956322213s DEBUG curp::server::cmd_worker::conflict_checked_mpmc: new ce event: ASReady(LogEntry { term: 1, index: 5, propose_id: ProposeId(0, 17290380797676990359), entry_data: Command(TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Get }) })
   7.957488121s DEBUG curp_test_utils::test_cmd: S0 after sync cmd(Get - TestCommand { keys: [0], exe_dur: 0ns, as_dur: 0ns, exe_should_fail: false, as_should_fail: false, cmd_type: Get }), index: 5
   7.957526843s DEBUG curp::server::spec_pool: cmd(0#17290380797676990359) is removed from spec pool
   7.957539126s DEBUG curp::server::cmd_worker: 203168192592235079 cmd(0#17290380797676990359) after sync is called
   7.957598527s DEBUG curp_wait_synced: curp::server::curp_node: 203168192592235079 wait synced for cmd(0#17290380797676990359) finishes
   7.992927031s DEBUG curp::client::unary: slow round for cmd(0#17290380797676990359) succeed
test panic! 
@info:
panicked at 'assertion failed: `(left == right)`
  left: `[]`,
 right: `[0]`', crates/curp/tests/it/server.rs:310:9
@stackTrace:
   0: __covrec_6F6B945809267BD5
   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: core::panicking::assert_failed_inner
   8: core::panicking::assert_failed::<alloc::vec::Vec<u32>, alloc::vec::Vec<u32>>
   9: __covrec_A6CD338B337A09D6
  10: <core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>> as core::future::future::Future>::poll
  11: <tokio::runtime::park::CachedParkThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>::{closure#0}
  12: <tokio::runtime::park::CachedParkThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>
  13: <tokio::runtime::context::blocking::BlockingRegionGuard>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>
  14: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>::{closure#0}
  15: __covrec_F8179ED6D28C3D4
  16: <tokio::runtime::scheduler::multi_thread::MultiThread>::block_on::<core::pin::Pin<&mut dyn core::future::future::Future<Output = ()>>>
  17: __covrec_BF7689AC0E8B0DD3
  18: __covrec_E21B1FF1F40AE203u
  19: it::server::shutdown_rpc_should_shutdown_the_cluster::{closure#0}
  20: <it::server::shutdown_rpc_should_shutdown_the_cluster::{closure#0} as core::ops::function::FnOnce<()>>::call_once
  21: core::ops::function::FnOnce::call_once
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/ops/function.rs:250:5
  22: test::__rust_begin_short_backtrace
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:655:18
  23: test::run_test::{{closure}}
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:646:30
  24: core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/ops/function.rs:250:5
  25: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/alloc/src/boxed.rs:1985:9
  26: <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
  27: std::panicking::try::do_call
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:500:40
  28: std::panicking::try
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:464:19
  29: std::panic::catch_unwind
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panic.rs:142:14
  30: test::run_test_in_process
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:678:27
  31: test::run_test::run_test_inner::{{closure}}
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:572:39
  32: test::run_test::run_test_inner::{{closure}}
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/test/src/lib.rs:599:37
  33: std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/sys_common/backtrace.rs:135:18
  34: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/thread/mod.rs:529:17
  35: <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
  36: std::panicking::try::do_call
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:500:40
  37: std::panicking::try
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panicking.rs:464:19
  38: std::panic::catch_unwind
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/panic.rs:142:14
  39: std::thread::Builder::spawn_unchecked_::{{closure}}
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/thread/mod.rs:528:30
  40: core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/core/src/ops/function.rs:250:5
  41: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/alloc/src/boxed.rs:1985:9
  42: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/alloc/src/boxed.rs:1985:9
  43: std::sys::unix::thread::Thread::new::thread_start
             at /rustc/8ede3aae28fe6e4d52b38157d7bfe0d3bceef225/library/std/src/sys/unix/thread.rs:108:17
  44: <unknown>
  45: __clone

   Canceling due to test failure: 3 tests still running
        PASS [   0.049s] engine proxy::test::get_operation_should_success
        PASS [   1.350s] curp::it server::synced_propose
        PASS [   9.037s] curp::it server::shutdown_rpc_should_shutdown_the_cluster_when_client_has_wrong_cluster
        PASS [   9.047s] curp::it server::shutdown_rpc_should_shutdown_the_cluster_when_client_has_wrong_leader
------------
     Summary [  37.495s] 138/340 tests run: 137 passed, 1 failed, 0 skipped
     SIGABRT [   8.488s] curp::it server::shutdown_rpc_should_shutdown_the_cluster
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)

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:

Phoenix500526 commented 2 months ago

Xline employs RocksDB's OptimisticTransaction as the underlying storage transaction implementation. However, we encountered an issue where the transaction conflicted with others and we failed to handle the error appropriately. To address this, I've introduced a retry mechanism in the write_batch, resolving the error. We should do a performance regression test for this modification. @bsbds