Uploaded image for project: 'Ratis'
  1. Ratis
  2. RATIS-983

Check follower state before ask for votes

    XMLWordPrintableJSON

Details

    • Improvement
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • None
    • 1.0.0
    • None
    • None

    Description

      1. There are server s0, s1, s2, all start leader election. But s2 has not start askForVotes.

      2020-06-21 03:46:27,958 [Thread-7] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s0: start LeaderElection
2020-06-21 03:46:27,963 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.LeaderElection (LeaderElection.java:askForVotes(206)) - s0@group-D88B65C78887-LeaderElection1: begin an election at term 1 for -1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null

      2020-06-21 03:46:27,990 [Thread-8] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s1: start LeaderElection
2020-06-21 03:46:27,998 [s1@group-D88B65C78887-LeaderElection2] INFO  impl.LeaderElection (LeaderElection.java:askForVotes(206)) - s1@group-D88B65C78887-LeaderElection2: begin an election at term 1 for -1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null

      2020-06-21 03:46:28,064 [Thread-9] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s2: start LeaderElection

      2. s0 was elected as leader

      2020-06-21 03:46:28,093 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.LeaderElection (LeaderElection.java:logAndReturn(61)) - s0@group-D88B65C78887-LeaderElection1: Election PASSED; received 2 response(s) [s0<-s1#0:FAIL-t1, s0<-s2#0:OK-t1] and 0 exception(s); s0@group-D88B65C78887:t1, leader=null, voted=s0, raftlog=s0@group-D88B65C78887-SegmentedRaftLog:OPENED:c-1,f-1,i0, conf=-1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null
2020-06-21 03:46:28,093 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RoleInfo (RoleInfo.java:shutdownLeaderElection(134)) - s0: shutdown LeaderElection
2020-06-21T03:46:28.0975768Z 2020-06-21 03:46:28,094 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s0@group-D88B65C78887: changes role from CANDIDATE to LEADER at term 1 for changeToLeader
2020-06-21 03:46:28,094 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RaftServerImpl (ServerState.java:setLeader(255)) - s0@group-D88B65C78887: change Leader from null to s0 at term 1 for becomeLeader, leader elected after 474ms

      3. s2 start askForVotes which did not start in step1. Then a new leader election happens.

      2020-06-21 03:46:28,096 [s2@group-D88B65C78887-LeaderElection3] INFO  impl.LeaderElection (LeaderElection.java:askForVotes(206)) - s2@group-D88B65C78887-LeaderElection3: begin an election at term 2 for -1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null

      all the log as following:

      2020-06-21T03:46:27.9598769Z 2020-06-21 03:46:27,958 [Thread-7] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s0: start LeaderElection
2020-06-21T03:46:27.9637021Z 2020-06-21 03:46:27,963 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.LeaderElection (LeaderElection.java:askForVotes(206)) - s0@group-D88B65C78887-LeaderElection1: begin an election at term 1 for -1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null
2020-06-21T03:46:27.9912697Z 2020-06-21 03:46:27,990 [Thread-8] INFO  impl.FollowerState (FollowerState.java:run(108)) - s1@group-D88B65C78887-FollowerState: change to CANDIDATE, lastRpcTime:244ms, electionTimeout:243ms
2020-06-21T03:46:27.9918514Z 2020-06-21 03:46:27,990 [Thread-8] INFO  impl.RoleInfo (RoleInfo.java:shutdownFollowerState(121)) - s1: shutdown FollowerState
2020-06-21T03:46:27.9919033Z 2020-06-21 03:46:27,990 [Thread-8] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s1@group-D88B65C78887: changes role from  FOLLOWER to CANDIDATE at term 0 for changeToCandidate
2020-06-21T03:46:27.9920005Z 2020-06-21 03:46:27,990 [Thread-8] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s1: start LeaderElection
2020-06-21T03:46:27.9994968Z 2020-06-21 03:46:27,998 [s1@group-D88B65C78887-LeaderElection2] INFO  impl.LeaderElection (LeaderElection.java:askForVotes(206)) - s1@group-D88B65C78887-LeaderElection2: begin an election at term 1 for -1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null
2020-06-21T03:46:28.0312909Z 2020-06-21 03:46:28,026 [nioEventLoopGroup-2-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeb2e2f1c, L:/0.0.0.0:40443] READ: [id: 0x13e9fc9d, L:/10.1.0.4:40443 - R:/10.1.0.4:57104]
2020-06-21T03:46:28.0313672Z 2020-06-21 03:46:28,027 [nioEventLoopGroup-5-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0x87dcc8c6, L:/0.0.0.0:46669] READ: [id: 0x9d66979b, L:/10.1.0.4:46669 - R:/10.1.0.4:55756]
2020-06-21T03:46:28.0348907Z 2020-06-21 03:46:28,034 [nioEventLoopGroup-7-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeefdb82d, L:/0.0.0.0:41589] READ: [id: 0xd8486e82, L:/10.1.0.4:41589 - R:/10.1.0.4:60724]
2020-06-21T03:46:28.0525870Z 2020-06-21 03:46:28,048 [Thread-9] INFO  impl.FollowerState (FollowerState.java:run(108)) - s2@group-D88B65C78887-FollowerState: change to CANDIDATE, lastRpcTime:300ms, electionTimeout:300ms
2020-06-21T03:46:28.0526704Z 2020-06-21 03:46:28,049 [Thread-9] INFO  impl.RoleInfo (RoleInfo.java:shutdownFollowerState(121)) - s2: shutdown FollowerState
2020-06-21T03:46:28.0527414Z 2020-06-21 03:46:28,049 [Thread-9] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s2@group-D88B65C78887: changes role from  FOLLOWER to CANDIDATE at term 0 for changeToCandidate
2020-06-21T03:46:28.0528112Z 2020-06-21 03:46:28,050 [nioEventLoopGroup-7-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeefdb82d, L:/0.0.0.0:41589] READ COMPLETE
2020-06-21T03:46:28.0528860Z 2020-06-21 03:46:28,050 [nioEventLoopGroup-7-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeefdb82d, L:/0.0.0.0:41589] READ: [id: 0xb6163b29, L:/10.1.0.4:41589 - R:/10.1.0.4:60726]
2020-06-21T03:46:28.0535812Z 2020-06-21 03:46:28,053 [nioEventLoopGroup-7-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeefdb82d, L:/0.0.0.0:41589] READ COMPLETE
2020-06-21T03:46:28.0625519Z 2020-06-21 03:46:28,061 [nioEventLoopGroup-5-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0x87dcc8c6, L:/0.0.0.0:46669] READ COMPLETE
2020-06-21T03:46:28.0649289Z 2020-06-21 03:46:28,064 [nioEventLoopGroup-2-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeb2e2f1c, L:/0.0.0.0:40443] READ COMPLETE
2020-06-21T03:46:28.0668601Z 2020-06-21 03:46:28,064 [Thread-9] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s2: start LeaderElection
2020-06-21T03:46:28.0812923Z 2020-06-21 03:46:28,076 [nioEventLoopGroup-8-2] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s2@group-D88B65C78887: changes role from CANDIDATE to FOLLOWER at term 1 for recognizeCandidate:s1
2020-06-21T03:46:28.0821817Z 2020-06-21 03:46:28,081 [nioEventLoopGroup-8-2] INFO  impl.RoleInfo (RoleInfo.java:shutdownLeaderElection(134)) - s2: shutdown LeaderElection
2020-06-21T03:46:28.0827947Z 2020-06-21 03:46:28,082 [nioEventLoopGroup-8-2] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s2: start FollowerState
2020-06-21T03:46:28.0874158Z 2020-06-21 03:46:28,086 [nioEventLoopGroup-8-1] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s2@group-D88B65C78887: changes role from  FOLLOWER to FOLLOWER at term 1 for recognizeCandidate:s0
2020-06-21T03:46:28.0874951Z 2020-06-21 03:46:28,086 [nioEventLoopGroup-8-1] INFO  impl.RoleInfo (RoleInfo.java:shutdownFollowerState(121)) - s2: shutdown FollowerState
2020-06-21T03:46:28.0875242Z 2020-06-21 03:46:28,086 [nioEventLoopGroup-8-1] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s2: start FollowerState
2020-06-21T03:46:28.0879248Z 2020-06-21 03:46:28,087 [Thread-18] INFO  impl.FollowerState (FollowerState.java:run(117)) - s2@group-D88B65C78887-FollowerState was interrupted: java.lang.InterruptedException: sleep interrupted
2020-06-21T03:46:28.0920027Z 2020-06-21 03:46:28,090 [s1@group-D88B65C78887-LeaderElection2] INFO  impl.LeaderElection (LeaderElection.java:logAndReturn(61)) - s1@group-D88B65C78887-LeaderElection2: Election REJECTED; received 2 response(s) [s1<-s0#0:FAIL-t1, s1<-s2#0:FAIL-t1] and 0 exception(s); s1@group-D88B65C78887:t1, leader=null, voted=s1, raftlog=s1@group-D88B65C78887-SegmentedRaftLog:OPENED:c-1,f-1,i0, conf=-1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null
2020-06-21T03:46:28.0920482Z 2020-06-21 03:46:28,090 [s1@group-D88B65C78887-LeaderElection2] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s1@group-D88B65C78887: changes role from CANDIDATE to FOLLOWER at term 1 for DISCOVERED_A_NEW_TERM
2020-06-21T03:46:28.0920938Z 2020-06-21 03:46:28,090 [s1@group-D88B65C78887-LeaderElection2] INFO  impl.RoleInfo (RoleInfo.java:shutdownLeaderElection(134)) - s1: shutdown LeaderElection
2020-06-21T03:46:28.0921255Z 2020-06-21 03:46:28,091 [s1@group-D88B65C78887-LeaderElection2] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s1: start FollowerState
2020-06-21T03:46:28.0969648Z 2020-06-21 03:46:28,093 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.LeaderElection (LeaderElection.java:logAndReturn(61)) - s0@group-D88B65C78887-LeaderElection1: Election PASSED; received 2 response(s) [s0<-s1#0:FAIL-t1, s0<-s2#0:OK-t1] and 0 exception(s); s0@group-D88B65C78887:t1, leader=null, voted=s0, raftlog=s0@group-D88B65C78887-SegmentedRaftLog:OPENED:c-1,f-1,i0, conf=-1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null
2020-06-21T03:46:28.0975340Z 2020-06-21 03:46:28,093 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RoleInfo (RoleInfo.java:shutdownLeaderElection(134)) - s0: shutdown LeaderElection
2020-06-21T03:46:28.0975768Z 2020-06-21 03:46:28,094 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s0@group-D88B65C78887: changes role from CANDIDATE to LEADER at term 1 for changeToLeader
2020-06-21T03:46:28.0976322Z 2020-06-21 03:46:28,094 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RaftServerImpl (ServerState.java:setLeader(255)) - s0@group-D88B65C78887: change Leader from null to s0 at term 1 for becomeLeader, leader elected after 474ms
2020-06-21T03:46:28.0976760Z 2020-06-21 03:46:28,096 [s2@group-D88B65C78887-LeaderElection3] INFO  impl.LeaderElection (LeaderElection.java:askForVotes(206)) - s2@group-D88B65C78887-LeaderElection3: begin an election at term 2 for -1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null
2020-06-21T03:46:28.0980726Z 2020-06-21 03:46:28,097 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.staging.catchup.gap = 1000 (default)
2020-06-21T03:46:28.0982068Z 2020-06-21 03:46:28,097 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.rpc.sleep.time = 25ms (default)
2020-06-21T03:46:28.1035314Z 2020-06-21 03:46:28,100 [s0@group-D88B65C78887-LeaderElection1] INFO  metrics.RatisMetrics (RatisMetrics.java:lambda$create$0(39)) - Creating Metrics Registry : ratis.log_appender.s0@group-D88B65C78887
2020-06-21T03:46:28.1035877Z 2020-06-21 03:46:28,100 [s0@group-D88B65C78887-LeaderElection1] WARN  impl.MetricRegistriesImpl (MetricRegistriesImpl.java:lambda$create$1(61)) - First MetricRegistry has been created without registering reporters. You may need to call MetricRegistries.global().addReportRegistration(...) before.
2020-06-21T03:46:28.1036291Z 2020-06-21 03:46:28,101 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.write.element-limit = 4096 (default)
2020-06-21T03:46:28.1036789Z 2020-06-21 03:46:28,101 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.write.byte-limit = 64MB (=67108864) (default)
2020-06-21T03:46:28.1063137Z 2020-06-21 03:46:28,104 [s2@group-D88B65C78887-LeaderElection3] INFO  impl.LeaderElection (LeaderElection.java:logAndReturn(61)) - s2@group-D88B65C78887-LeaderElection3: Election REJECTED; received 0 response(s) [] and 0 exception(s); s2@group-D88B65C78887:t2, leader=null, voted=s2, raftlog=s2@group-D88B65C78887-SegmentedRaftLog:OPENED:c-1,f-1,i0, conf=-1: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null
2020-06-21T03:46:28.1063623Z 2020-06-21 03:46:28,105 [nioEventLoopGroup-2-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeb2e2f1c, L:/0.0.0.0:40443] READ: [id: 0xd7a24ea3, L:/10.1.0.4:40443 - R:/10.1.0.4:57112]
2020-06-21T03:46:28.1090607Z 2020-06-21 03:46:28,106 [nioEventLoopGroup-2-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0xeb2e2f1c, L:/0.0.0.0:40443] READ COMPLETE
2020-06-21T03:46:28.1098274Z 2020-06-21 03:46:28,107 [nioEventLoopGroup-5-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0x87dcc8c6, L:/0.0.0.0:46669] READ: [id: 0xdb116403, L:/10.1.0.4:46669 - R:/10.1.0.4:55764]
2020-06-21T03:46:28.1107308Z 2020-06-21 03:46:28,108 [nioEventLoopGroup-5-1] INFO  logging.LoggingHandler (AbstractInternalLogger.java:log(148)) - [id: 0x87dcc8c6, L:/0.0.0.0:46669] READ COMPLETE
2020-06-21T03:46:28.1108298Z 2020-06-21 03:46:28,108 [nioEventLoopGroup-6-2] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s1@group-D88B65C78887: changes role from  FOLLOWER to FOLLOWER at term 2 for recognizeCandidate:s2
2020-06-21T03:46:28.1109906Z 2020-06-21 03:46:28,108 [nioEventLoopGroup-6-2] INFO  impl.RoleInfo (RoleInfo.java:shutdownFollowerState(121)) - s1: shutdown FollowerState
2020-06-21T03:46:28.1110658Z 2020-06-21 03:46:28,109 [Thread-20] INFO  impl.FollowerState (FollowerState.java:run(117)) - s1@group-D88B65C78887-FollowerState was interrupted: java.lang.InterruptedException: sleep interrupted
2020-06-21T03:46:28.1111310Z 2020-06-21 03:46:28,109 [nioEventLoopGroup-6-2] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s1: start FollowerState
2020-06-21T03:46:28.1163725Z 2020-06-21 03:46:28,116 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.watch.timeout = 10s (default)
2020-06-21T03:46:28.1164839Z 2020-06-21 03:46:28,116 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.watch.timeout.denomination = 1s (default)
2020-06-21T03:46:28.1186640Z 2020-06-21 03:46:28,118 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.watch.element-limit = 65536 (default)
2020-06-21T03:46:28.1251657Z 2020-06-21 03:46:28,124 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default)
2020-06-21T03:46:28.1253791Z 2020-06-21 03:46:28,124 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.log.appender.buffer.byte-limit = 8KB (=8192) (custom)
2020-06-21T03:46:28.1259948Z 2020-06-21 03:46:28,125 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.log.appender.buffer.element-limit = 0 (default)
2020-06-21T03:46:28.1291098Z 2020-06-21 03:46:28,128 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.log.appender.snapshot.chunk.size.max = 16MB (=16777216) (default)
2020-06-21T03:46:28.1294354Z 2020-06-21 03:46:28,128 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.log.appender.buffer.byte-limit = 8KB (=8192) (custom)
2020-06-21T03:46:28.1294744Z 2020-06-21 03:46:28,128 [s0@group-D88B65C78887-LeaderElection1] INFO  server.RaftServerConfigKeys (ConfUtils.java:logGet(44)) - raft.server.log.appender.buffer.element-limit = 0 (default)
2020-06-21T03:46:28.1330073Z 2020-06-21 03:46:28,132 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RoleInfo (RoleInfo.java:updateAndGet(143)) - s0: start LeaderState
2020-06-21T03:46:28.1442268Z 2020-06-21 03:46:28,143 [s0@group-D88B65C78887-LeaderElection1] INFO  segmented.SegmentedRaftLogWorker (SegmentedRaftLogWorker.java:startLogSegment(391)) - s0@group-D88B65C78887-SegmentedRaftLogWorker: Starting segment from index:0
2020-06-21T03:46:28.1676758Z 2020-06-21 03:46:28,163 [s0@group-D88B65C78887-LeaderElection1] INFO  impl.RaftServerImpl (ServerState.java:setRaftConf(356)) - s0@group-D88B65C78887: set configuration 0: [s0:0.0.0.0:40443, s1:0.0.0.0:46669, s2:0.0.0.0:41589], old=null at 0
2020-06-21T03:46:28.1716372Z 2020-06-21 03:46:28,167 [nioEventLoopGroup-3-2] INFO  impl.RaftServerImpl (ServerState.java:setLeader(255)) - s0@group-D88B65C78887: change Leader from s0 to null at term 2 for updateCurrentTerm
2020-06-21T03:46:28.1716975Z 2020-06-21 03:46:28,167 [nioEventLoopGroup-3-2] INFO  impl.RaftServerImpl (RaftServerImpl.java:setRole(174)) - s0@group-D88B65C78887: changes role from    LEADER to FOLLOWER at term 2 for recognizeCandidate:s2

      Attachments

        Issue Links

          links to

          Web Link GitHub Pull Request #135

          Activity

            People

              yjxxtd runzhiwang
              yjxxtd runzhiwang
              Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 40m
                  40m