[
https://issues.apache.org/jira/browse/RATIS-2008?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17808878#comment-17808878
]
Ivan Andika commented on RATIS-2008:
------------------------------------
> Why the leader sends PRE_VOTE? Is this the case that the leader has stepped
>down and then starts an election?
Yes, the leader stepped down and then starts another election with higher term
since it has the highest priority. I encountered it recently while testing
streaming write pipeline. In CreatePipelineCommand, the suggested leader has
higher priority.
> If the leader has stepped down, the follower will time out and then it will
> accept the PRE_VOTE.
Yes, currently the follower will wait until its current leader is invalid /
isCurrentLeaderValid (not heard after min.rpc.timeout). After, the leader is
deemed invalid, it should accept the PRE_VOTE. The case where the follower
reject the PRE_VOTE looked like it's within the min.rpc.timeout, so the
follower still believes it has a valid leader.
To give more context, below are the logs for the Raft peers in the pipeline.
This is the leader's (higher priority peer) log (the client write operation
encountered NotLeaderException).
{code:java}
# Stepped down at term 8
2024-01-18 13:44:39,801
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl] WARN
org.apache.ratis.server.RaftServer$Division:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl: Lost
leadership on term: 8. Election timeout: 5200ms. In charge for: 6230370ms.
Conf: 140433: peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:39,801
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl] WARN
org.apache.ratis.server.RaftServer$Division: Follower
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137->e46cc30b-13ca-4778-b856-e84b0677493d(c142523,m142525,n142526,
caughtUp=true, lastRpcSendTime=6507, lastRpcResponseTime=6506)
2024-01-18 13:44:39,801
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl] WARN
org.apache.ratis.server.RaftServer$Division: Follower
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137->a40059d4-a1ba-4138-ad25-9fdaf98a1f8e(c142523,m142525,n142526,
caughtUp=true, lastRpcSendTime=6507, lastRpcResponseTime=6506)
2024-01-18 13:44:39,802
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl] INFO
org.apache.ratis.server.RaftServer$Division:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137: changes role from
LEADER to FOLLOWER at term 8 for StepDownReason:LOST_MAJORITY_HEARTBEATS
2024-01-18 13:44:39,802
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl] INFO
org.apache.ratis.server.impl.RoleInfo: c7e3fa47-df62-4883-8d6e-50c3b6a9b94c:
shutdown c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl
2024-01-18 13:44:39,802
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderStateImpl] INFO
org.apache.ratis.server.impl.PendingRequests:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-PendingRequests:
sendNotLeaderResponses
# GC Issue
2024-01-18 13:44:39,804
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137->a40059d4-a1ba-4138-ad25-9fdaf98a1f8e-GrpcLogAppender-LogAppenderDaemon]
WARN org.apache.ratis.grpc.server.GrpcLogAppender:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137->a40059d4-a1ba-4138-ad25-9fdaf98a1f8e-GrpcLogAppender:
Wait interrupted by java.lang.InterruptedException
2024-01-18 13:44:39,805
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137->e46cc30b-13ca-4778-b856-e84b0677493d-GrpcLogAppender-LogAppenderDaemon]
WARN org.apache.ratis.grpc.server.GrpcLogAppender:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137->e46cc30b-13ca-4778-b856-e84b0677493d-GrpcLogAppender:
Wait interrupted by java.lang.InterruptedException
2024-01-18 13:44:39,806 [grpc-default-executor-270] INFO
org.apache.ratis.grpc.server.GrpcLogAppender:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137->e46cc30b-13ca-4778-b856-e84b0677493d-AppendLogResponseHandler:
follower responses appendEntries COMPLETED
2024-01-18 13:44:39,806 [JvmPauseMonitor0] WARN
org.apache.ratis.util.JvmPauseMonitor:
JvmPauseMonitor-c7e3fa47-df62-4883-8d6e-50c3b6a9b94c: Detected pause in JVM or
host machine approximately 4.231s without any GCs.
2024-01-18 13:44:39,807
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-F0D3CB812363-FollowerState] WARN
org.apache.ratis.server.impl.FollowerState: Unexpected long sleep: sleep 5182ms
but took extra 4391710573ns (> threshold = 300ms)
# No leader election since stepped down recently
2024-01-18 13:44:44,927
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.FollowerState:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState: Skipping
leader election since it stepped down recently (elapsed = 5116ms < waitTime =
10s)
# Reject pre-vote due to higher priority
2024-01-18 13:44:45,176 [grpc-default-executor-273] INFO
org.apache.ratis.server.RaftServer$Division:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137: receive
requestVote(PRE_VOTE, a40059d4-a1ba-4138-ad25-9fdaf98a1f8e, group-059247EC8137,
8, (t:8, i:142525))
2024-01-18 13:44:45,177 [grpc-default-executor-273] INFO
org.apache.ratis.server.impl.VoteContext:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FOLLOWER: reject
PRE_VOTE from a40059d4-a1ba-4138-ad25-9fdaf98a1f8e: our priority 1 >
candidate's priority 0
2024-01-18 13:44:45,177 [grpc-default-executor-273] INFO
org.apache.ratis.server.RaftServer$Division:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137 replies to PRE_VOTE
vote request:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e<-c7e3fa47-df62-4883-8d6e-50c3b6a9b94c#0:FAIL-t8.
Peer's state: c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137:t8,
leader=null, voted=c7e3fa47-df62-4883-8d6e-50c3b6a9b94c,
raftlog=Memoized:c7e3fa47-df62-488
# Election for term 9
2024-01-18 13:44:50,117
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.FollowerState:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState: change
to CANDIDATE, lastRpcElapsedTime:10307068320ns, electionTimeout:5190ms
2024-01-18 13:44:50,117
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.RoleInfo: c7e3fa47-df62-4883-8d6e-50c3b6a9b94c:
shutdown c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState
2024-01-18 13:44:50,118
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.RaftServer$Division:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137: changes role from
FOLLOWER to CANDIDATE at term 8 for changeToCandidate
2024-01-18 13:44:50,118
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.RaftServerConfigKeys:
raft.server.leaderelection.pre-vote = true (default)
2024-01-18 13:44:50,118
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.RoleInfo: c7e3fa47-df62-4883-8d6e-50c3b6a9b94c:
start c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
2024-01-18 13:44:50,119
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
PRE_VOTE round 0: submit vote requests at term 8 for 140433:
peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10:
PRE_VOTE PASSED received 2 response(s) and 0 exception(s):
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection: Response 0:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c<-e46cc30b-13ca-4778-b856-e84b0677493d#0:FAIL-t8
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection: Response 1:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c<-a40059d4-a1ba-4138-ad25-9fdaf98a1f8e#0:OK-t8
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
PRE_VOTE round 0: result PASSED
2024-01-18 13:44:50,124
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
ELECTION round 0: submit vote requests at term 9 for 140433:
peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10:
PRE_VOTE PASSED received 2 response(s) and 0 exception(s):
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection: Response 0:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c<-e46cc30b-13ca-4778-b856-e84b0677493d#0:FAIL-t8
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection: Response 1:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c<-a40059d4-a1ba-4138-ad25-9fdaf98a1f8e#0:OK-t8
2024-01-18 13:44:50,123
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
PRE_VOTE round 0: result PASSED
2024-01-18 13:44:50,124
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
ELECTION round 0: submit vote requests at term 9 for 140433:
peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:50,127
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10:
ELECTION PASSED received 1 response(s) and 0 exception(s):
2024-01-18 13:44:50,127
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection: Response 0:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c<-e46cc30b-13ca-4778-b856-e84b0677493d#0:OK-t9
2024-01-18 13:44:50,127
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.LeaderElection:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
ELECTION round 0: result PASSED
2024-01-18 13:44:50,127
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.impl.RoleInfo: c7e3fa47-df62-4883-8d6e-50c3b6a9b94c:
shutdown
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10
2024-01-18 13:44:50,127
[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137-LeaderElection10] INFO
org.apache.ratis.server.RaftServer$Division:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c@group-059247EC8137: changes role from
CANDIDATE to LEADER at term 9 for changeToLeader {code}
This is the follower's log that rejected the pre-vote from the leader (the case
to prevent in this patch)
{code:java}
# Reject pre-vote although the leader is the same
2024-01-18 13:44:50,122 [grpc-default-executor-100] INFO
org.apache.ratis.server.RaftServer$Division:
e46cc30b-13ca-4778-b856-e84b0677493d@group-059247EC8137: receive
requestVote(PRE_VOTE, c7e3fa47-df62-4883-8d6e-50c3b6a9b94c, group-059247EC8137,
8, (t:8, i:142525))
2024-01-18 13:44:50,123 [grpc-default-executor-100] INFO
org.apache.ratis.server.impl.VoteContext:
e46cc30b-13ca-4778-b856-e84b0677493d@group-059247EC8137-FOLLOWER: reject
PRE_VOTE from c7e3fa47-df62-4883-8d6e-50c3b6a9b94c: this server is a follower
and still has a valid leader c7e3fa47-df62-4883-8d6e-50c3b6a9b94c {code}
Another follower was also trying to do PRE_VOTE, but since it's rejected by the
higher-priority peer / previous leader (see RATIS-1033), so it cannot pass the
vote. During that time, I think no leader can be elected until the
higher-priority peer start another election which is at least the leader
wait.time (10s). We might want to fix this as well to make election more timely
when there are higher priority peer.
{code:java}
2024-01-18 13:44:39,805 [grpc-default-executor-31] INFO
org.apache.ratis.grpc.server.GrpcServerProtocolService:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e: Completed APPEND_ENTRIES, lastRequest:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c->a40059d4-a1ba-4138-ad25-9fdaf98a1f8e#7024-t8,previous=(t:8,
i:142524),leaderCommit=142523,initializing? false,entries: size=1, first=(t:8,
i:142525), METADATAENTRY(c:142523)
2024-01-18 13:44:39,806 [grpc-default-executor-31] INFO
org.apache.ratis.grpc.server.GrpcServerProtocolService:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e: Completed APPEND_ENTRIES, lastReply: null
2024-01-18 13:44:40,094
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.FollowerState:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState: change
to CANDIDATE, lastRpcElapsedTime:6800576008ns, electionTimeout:5012ms
2024-01-18 13:44:40,095
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
shutdown a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState
2024-01-18 13:44:40,095
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: changes role from
FOLLOWER to CANDIDATE at term 8 for changeToCandidate
2024-01-18 13:44:40,095
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.RaftServerConfigKeys:
raft.server.leaderelection.pre-vote = true (default)
2024-01-18 13:44:40,095
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
start a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8
2024-01-18 13:44:40,096
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: change Leader from
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c to null at term 8 for PRE_VOTE
2024-01-18 13:44:40,096
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.impl.LeaderElection:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8
PRE_VOTE round 0: submit vote requests at term 8 for 140433:
peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:40,105
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.impl.LeaderElection:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8:
PRE_VOTE REJECTED received 2 response(s) and 0 exception(s):
2024-01-18 13:44:40,105
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.impl.LeaderElection: Response 0:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e<-c7e3fa47-df62-4883-8d6e-50c3b6a9b94c#0:FAIL-t8
2024-01-18 13:44:40,105
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.impl.LeaderElection: Response 1:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e<-e46cc30b-13ca-4778-b856-e84b0677493d#0:OK-t8
2024-01-18 13:44:40,105
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.impl.LeaderElection:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8
PRE_VOTE round 0: result REJECTED
2024-01-18 13:44:40,105
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: changes role from
CANDIDATE to FOLLOWER at term 8 for REJECTED
2024-01-18 13:44:40,105
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
shutdown a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8
2024-01-18 13:44:40,107
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection8] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
start a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState
2024-01-18 13:44:45,171
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.FollowerState:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState: change
to CANDIDATE, lastRpcElapsedTime:5064234355ns, electionTimeout:5064ms
2024-01-18 13:44:45,171
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
shutdown a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState
2024-01-18 13:44:45,171
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: changes role from
FOLLOWER to CANDIDATE at term 8 for changeToCandidate
2024-01-18 13:44:45,171
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.RaftServerConfigKeys:
raft.server.leaderelection.pre-vote = true (default)
2024-01-18 13:44:45,171
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
start a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9
2024-01-18 13:44:45,173
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.impl.LeaderElection:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9
PRE_VOTE round 0: submit vote requests at term 8 for 140433:
peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:45,176
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.impl.LeaderElection:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9:
PRE_VOTE REJECTED received 2 response(s) and 0 exception(s):
2024-01-18 13:44:45,176
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.impl.LeaderElection: Response 0:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e<-c7e3fa47-df62-4883-8d6e-50c3b6a9b94c#0:FAIL-t8
2024-01-18 13:44:45,176
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.impl.LeaderElection: Response 1:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e<-e46cc30b-13ca-4778-b856-e84b0677493d#0:OK-t8
2024-01-18 13:44:45,176
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.impl.LeaderElection:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9
PRE_VOTE round 0: result REJECTED
2024-01-18 13:44:45,176
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: changes role from
CANDIDATE to FOLLOWER at term 8 for REJECTED
2024-01-18 13:44:45,176
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
shutdown a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9
2024-01-18 13:44:45,177
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-LeaderElection9] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
start a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState
2024-01-18 13:44:50,121 [grpc-default-executor-30] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: receive
requestVote(PRE_VOTE, c7e3fa47-df62-4883-8d6e-50c3b6a9b94c, group-059247EC8137,
8, (t:8, i:142525))
2024-01-18 13:44:50,121 [grpc-default-executor-30] INFO
org.apache.ratis.server.impl.VoteContext:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FOLLOWER: accept
PRE_VOTE from c7e3fa47-df62-4883-8d6e-50c3b6a9b94c: our priority 0 <=
candidate's priority 1
2024-01-18 13:44:50,121 [grpc-default-executor-30] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137 replies to PRE_VOTE
vote request:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c<-a40059d4-a1ba-4138-ad25-9fdaf98a1f8e#0:OK-t8.
Peer's state: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137:t8,
leader=null, voted=c7e3fa47-df62-4883-8d6e-50c3b6a9b94c,
raftlog=Memoized:a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-SegmentedRaftLog:OPENED:c142523,
conf=140433: peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:50,124 [grpc-default-executor-30] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: receive
requestVote(ELECTION, c7e3fa47-df62-4883-8d6e-50c3b6a9b94c, group-059247EC8137,
9, (t:8, i:142525))
2024-01-18 13:44:50,124 [grpc-default-executor-30] INFO
org.apache.ratis.server.impl.VoteContext:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FOLLOWER: accept
ELECTION from c7e3fa47-df62-4883-8d6e-50c3b6a9b94c: our priority 0 <=
candidate's priority 1
2024-01-18 13:44:50,124 [grpc-default-executor-30] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: changes role from
FOLLOWER to FOLLOWER at term 9 for
candidate:c7e3fa47-df62-4883-8d6e-50c3b6a9b94c
2024-01-18 13:44:50,124 [grpc-default-executor-30] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
shutdown a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState
2024-01-18 13:44:50,124 [grpc-default-executor-30] INFO
org.apache.ratis.server.impl.RoleInfo: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e:
start a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState
2024-01-18 13:44:50,124
[a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState] INFO
org.apache.ratis.server.impl.FollowerState:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-FollowerState was
interrupted
2024-01-18 13:44:50,126 [grpc-default-executor-30] INFO
org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137 replies to ELECTION
vote request:
c7e3fa47-df62-4883-8d6e-50c3b6a9b94c<-a40059d4-a1ba-4138-ad25-9fdaf98a1f8e#0:OK-t9.
Peer's state: a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137:t9,
leader=null, voted=c7e3fa47-df62-4883-8d6e-50c3b6a9b94c,
raftlog=Memoized:a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137-SegmentedRaftLog:OPENED:c142523,
conf=140433: peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
2024-01-18 13:44:50,131 [a40059d4-a1ba-4138-ad25-9fdaf98a1f8e-server-thread33]
INFO
org.apache.hadoop.ozone.container.common.transport.server.ratis.XceiverServerRatis:
Leader change notification received for group: group-059247EC8137 with new
leaderId: c7e3fa47-df62-4883-8d6e-50c3b6a9b94c
2024-01-18 13:44:50,131 [a40059d4-a1ba-4138-ad25-9fdaf98a1f8e-server-thread33]
INFO org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: change Leader from
null to c7e3fa47-df62-4883-8d6e-50c3b6a9b94c at term 9 for appendEntries,
leader elected after 10034ms
2024-01-18 13:44:50,131 [a40059d4-a1ba-4138-ad25-9fdaf98a1f8e-server-thread33]
INFO org.apache.ratis.server.RaftServer$Division:
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e@group-059247EC8137: set configuration
142526: peers:[c7e3fa47-df62-4883-8d6e-50c3b6a9b94c|10.80.170.67:9856,
e46cc30b-13ca-4778-b856-e84b0677493d|10.80.170.74:9856,
a40059d4-a1ba-4138-ad25-9fdaf98a1f8e|10.80.170.72:9856]|listeners:[], old=null
{code}
> Follower should recognize candidate if the candidate is the same peer as the
> current recognized leader
> ------------------------------------------------------------------------------------------------------
>
> Key: RATIS-2008
> URL: https://issues.apache.org/jira/browse/RATIS-2008
> Project: Ratis
> Issue Type: Improvement
> Components: election
> Reporter: Ivan Andika
> Assignee: Ivan Andika
> Priority: Minor
>
> During pre-vote, some follower reject the PRE_VOTE request from a candidate
> although the candidate has the same peer ID as the current leader.
> {code:java}
> 2024-01-18 13:44:50,123 [grpc-default-executor-100] INFO
> org.apache.ratis.server.impl.VoteContext:
> e46cc30b-13ca-4778-b856-e84b0677493d@group-059247EC8137-FOLLOWER: reject
> PRE_VOTE from c7e3fa47-df62-4883-8d6e-50c3b6a9b94c: this server is a follower
> and still has a valid leader c7e3fa47-df62-4883-8d6e-50c3b6a9b94c
> {code}
> It might be a good idea to addd another check so that if the candidate has
> the same peer ID as the follower's current recognized leader, we approve the
> PRE_VOTE request.
> Note: The optimization might be marginal since recognized leader will expire
> after min.rpc.timeout (150ms) anyway.
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
