cita-cloud / consensus_raft

The raft consensus component for CITA Cloud.
Apache License 2.0
3 stars 0 forks source link

混沌测试后node0恢复失败 #76

Closed Jayanring closed 1 year ago

Jayanring commented 1 year ago

日志:https://grafana.devops.rivtower.com/d/deILUm6fSVkNo/cita-cloud-competent-view?orgId=1&var-loki_datasource=Loki&var-cluster_name=rivtower-developing-120&var-namespace=cita&var-chain_name=test-chain-zenoh-raft&var-chain_cpnt=consensus&var-chain_node=All&from=1677615300000&to=1677615620000

网络恢复后node123正常工作,但node0不参与共识,只同步区块。40分钟左右之后,5:05,node0发起新的选举失败,然后收到其他节点的投票请求并成为其follower,恢复正常

rink1969 commented 1 year ago

其他节点在4:20分网络一恢复之后,马上就恢复了正常选举出块。 node3

2023-03-01 04:20:14 | Feb 28 20:20:14.605 INFO new proposal, data: 0a8c010a..7ca31a00, height: 227, module: consensus::peer:402
2023-03-01 04:20:14 | Feb 28 20:20:14.601 INFO fetching proposal.., module: consensus::peer:383
2023-03-01 04:20:14 | Feb 28 20:20:14.599 INFO became leader at term 30, term: 30, raft_id: 9063134360811404448, module: raft::raft:1196
2023-03-01 04:20:14 | Feb 28 20:20:14.598 INFO received votes response, term: 30, type: MsgRequestVoteResponse, approvals: 3, rejections: 0, from: 7222868942565220257, vote: true, raft_id: 9063134360811404448, module: raft::raft:2171
2023-03-01 04:20:14 | Feb 28 20:20:14.595 INFO received votes response, term: 30, type: MsgRequestVoteResponse, approvals: 2, rejections: 0, from: 2839943415174506970, vote: true, raft_id: 9063134360811404448, module: raft::raft:2171
2023-03-01 04:20:14 | Feb 28 20:20:14.591 INFO broadcasting vote request, to: [2839943415174506970, 4761232580302610953, 7222868942565220257], log_index: 239, log_term: 12, term: 30, type: MsgRequestVote, raft_id: 9063134360811404448, module: raft::raft:1267
2023-03-01 04:20:14 | Feb 28 20:20:14.591 INFO became candidate at term 30, term: 30, raft_id: 9063134360811404448, module: raft::raft:1112

node2

2023-03-01 04:20:14 | Feb 28 20:20:14.661 WARN check proposal failed, controller replies a false, module: consensus::peer:668
2023-03-01 04:20:14 | Feb 28 20:20:14.659 INFO checking proposal.., data: 0a8c010a..a25c1a00, height: 226, module: consensus::peer:648
2023-03-01 04:20:14 | Feb 28 20:20:14.653 INFO persisted snapshot index: 238, tag: storage, module: consensus::storage:243
2023-03-01 04:20:14 | Feb 28 20:20:14.652 INFO apply_snapshot index: 238 conf_state: ConfState { voters: [9063134360811404448, 2839943415174506970, 4761232580302610953, 7222868942565220257], learners: [], voters_outgoing: [], learners_next: [], auto_leave: false }, tag: storage, module: consensus::storage:274
2023-03-01 04:20:14 | Feb 28 20:20:14.652 INFO [commit: 238, term: 30] restored snapshot [index: 238, term: 30], snapshot_term: 30, snapshot_index: 238, commit: 238, term: 30, raft_id: 2839943415174506970, module: raft::raft:2470
2023-03-01 04:20:14 | Feb 28 20:20:14.652 INFO restored snapshot, snapshot_term: 30, snapshot_index: 238, last_term: 30, last_index: 238, commit: 238, raft_id: 2839943415174506970, module: raft::raft:2589
2023-03-01 04:20:14 | Feb 28 20:20:14.652 INFO switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {9063134360811404448, 2839943415174506970, 4761232580302610953, 7222868942565220257} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 2839943415174506970, module: raft::raft:2605
2023-03-01 04:20:14 | Feb 28 20:20:14.652 INFO log [committed=238, persisted=238, applied=238, unstable.offset=239, unstable.entries.len()=0] starts to restore snapshot [index: 238, term: 30], snapshot_term: 30, snapshot_index: 238, log: committed=238, persisted=238, applied=238, unstable.offset=239, unstable.entries.len()=0, raft_id: 2839943415174506970, module: raft::raft_log:614
2023-03-01 04:20:14 | Feb 28 20:20:14.643 INFO [logterm: 12, index: 238, vote: 0] cast vote for 9063134360811404448 [logterm: 12, index: 239] at term 30, msg type: MsgRequestVote, term: 30, msg_index: 239, msg_term: 12, from: 9063134360811404448, vote: 0, log_index: 238, log_term: 12, raft_id: 2839943415174506970, module: raft::raft:1528
2023-03-01 04:20:14 | Feb 28 20:20:14.642 INFO became follower at term 30, term: 30, raft_id: 2839943415174506970, module: raft::raft:1088
2023-03-01 04:20:14 | Feb 28 20:20:14.642 INFO received a message with higher term from 9063134360811404448, msg type: MsgRequestVote, message_term: 30, term: 29, from: 9063134360811404448, raft_id: 2839943415174506970, module: raft::raft:1332

node1

2023-03-01 04:20:14 | Feb 28 20:20:14.612 INFO committing proposal.., module: consensus::peer:656
2023-03-01 04:20:14 | Feb 28 20:20:14.609 INFO checking proposal.., data: 0a8c010a..7ca31a00, height: 227, module: consensus::peer:648
2023-03-01 04:20:14 | Feb 28 20:20:14.588 INFO [logterm: 12, index: 239, vote: 0] cast vote for 9063134360811404448 [logterm: 12, index: 239] at term 30, msg type: MsgRequestVote, term: 30, msg_index: 239, msg_term: 12, from: 9063134360811404448, vote: 0, log_index: 239, log_term: 12, raft_id: 7222868942565220257, module: raft::raft:1528
2023-03-01 04:20:14 | Feb 28 20:20:14.588 INFO became follower at term 30, term: 30, raft_id: 7222868942565220257, module: raft::raft:1088
2023-03-01 04:20:14 | Feb 28 20:20:14.588 INFO received a message with higher term from 9063134360811404448, msg type: MsgRequestVote, message_term: 30, term: 29, from: 9063134360811404448, raft_id: 7222868942565220257, module: raft::raft:1332

但是node0卡了很久才开始参与共识

2023-03-01 05:01:21 | Feb 28 21:01:21.547 INFO checking proposal.., data: 0a8c010a..5b6d1a00, height: 1041, module: consensus::peer:648
-- | --
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.537 INFO persisted snapshot index: 1054, tag: storage, module: consensus::storage:243
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.534 INFO apply_snapshot index: 1054 conf_state: ConfState { voters: [9063134360811404448, 2839943415174506970, 4761232580302610953, 7222868942565220257], learners: [], voters_outgoing: [], learners_next: [], auto_leave: false }, tag: storage, module: consensus::storage:274
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.534 INFO [commit: 1054, term: 32] restored snapshot [index: 1054, term: 32], snapshot_term: 32, snapshot_index: 1054, commit: 1054, term: 32, raft_id: 4761232580302610953, module: raft::raft:2470
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.533 INFO restored snapshot, snapshot_term: 32, snapshot_index: 1054, last_term: 32, last_index: 1054, commit: 1054, raft_id: 4761232580302610953, module: raft::raft:2589
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.533 INFO switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {9063134360811404448, 2839943415174506970, 4761232580302610953, 7222868942565220257} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 4761232580302610953, module: raft::raft:2605
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.533 INFO log [committed=239, persisted=240, applied=239, unstable.offset=241, unstable.entries.len()=0] starts to restore snapshot [index: 1054, term: 32], snapshot_term: 32, snapshot_index: 1054, log: committed=239, persisted=240, applied=239, unstable.offset=241, unstable.entries.len()=0, raft_id: 4761232580302610953, module: raft::raft_log:614
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.527 INFO [logterm: 12, index: 240, vote: 0] cast vote for 7222868942565220257 [logterm: 30, index: 1054] at term 32, msg type: MsgRequestVote, term: 32, msg_index: 1054, msg_term: 30, from: 7222868942565220257, vote: 0, log_index: 240, log_term: 12, raft_id: 4761232580302610953, module: raft::raft:1528
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.527 INFO became follower at term 32, term: 32, raft_id: 4761232580302610953, module: raft::raft:1088
  |   | 2023-03-01 05:01:21 | Feb 28 21:01:21.526 INFO received a message with higher term from 7222868942565220257, msg type: MsgRequestVote, message_term: 32, term: 31, from: 7222868942565220257, raft_id: 4761232580302610953, module: raft::raft:1332
  |   | 2023-03-01 05:01:09 | Feb 28 21:01:09.652 INFO became follower at term 31, term: 31, raft_id: 4761232580302610953, module: raft::raft:1088
  |   | 2023-03-01 05:01:09 | Feb 28 21:01:09.652 INFO received votes response, term: 31, type: MsgRequestVoteResponse, approvals: 1, rejections: 2, from: 7222868942565220257, vote: false, raft_id: 4761232580302610953, module: raft::raft:2171
  |   | 2023-03-01 05:01:09 | Feb 28 21:01:09.650 INFO received votes response, term: 31, type: MsgRequestVoteResponse, approvals: 1, rejections: 1, from: 2839943415174506970, vote: false, raft_id: 4761232580302610953, module: raft::raft:2171
  |   | 2023-03-01 05:01:09 | Feb 28 21:01:09.489 INFO broadcasting vote request, to: [9063134360811404448, 2839943415174506970, 7222868942565220257], log_index: 240, log_term: 12, term: 31, type: MsgRequestVote, raft_id: 4761232580302610953, module: raft::raft:1267
  |   | 2023-03-01 05:01:09 | Feb 28 21:01:09.489 INFO became candidate at term 31, term: 31, raft_id: 4761232580302610953, module: raft::raft:1112
  |   | 2023-03-01 05:01:09 | Feb 28 21:01:09.489 INFO starting a new election, term: 30, raft_id: 4761232580302610953, module: raft::raft:1513
  |   | 2023-03-01 04:20:14 | Feb 28 20:20:14.651 INFO [commit: 239] ignored snapshot [index: 239, term: 30], snapshot_term: 30, snapshot_index: 239, commit: 239, raft_id: 4761232580302610953, module: raft::raft:2484
  |   | 2023-03-01 04:20:14 | Feb 28 20:20:14.651 INFO fast-forwarded commit to snapshot, snapshot_term: 30, snapshot_index: 239, last_term: 12, last_index: 240, commit: 239, raft_id: 4761232580302610953, module: raft::raft:2542
  |   | 2023-03-01 04:20:14 | Feb 28 20:20:14.637 INFO [logterm: 12, index: 240, vote: 0] rejected vote from 9063134360811404448 [logterm: 12, index: 239] at term 30, msg type: MsgRequestVote, term: 30, msg_index: 239, msg_term: 12, from: 9063134360811404448, vote: 0, log_index: 240, log_term: 12, raft_id: 4761232580302610953, module: raft::raft:1544
  |   | 2023-03-01 04:20:14 | Feb 28 20:20:14.637 INFO became follower at term 30, term: 30, raft_id: 4761232580302610953, module: raft::raft:1088
  |   | 2023-03-01 04:20:14 | Feb 28 20:20:14.633 INFO received a message with higher term from 9063134360811404448, msg type: MsgRequestVote, message_term: 30, term: 29, from: 9063134360811404448, raft_id: 4761232580302610953, module: raft::raft:1332
  |   | 2023-03-01 04:20:01 | Feb 28 20:20:01.994 INFO became follower at term 29, term: 29, raft_id: 4761232580302610953, module: raft::raft:1088