Add more info logging in sal-akka-raft
[controller.git] / opendaylight / md-sal / sal-akka-raft / src / main / java / org / opendaylight / controller / cluster / raft / behaviors / Candidate.java
index 7f73d0cfb0a24a8b85960c2b1fdb031c3131cfdd..7c111d28de818e225eb4b1ab8e10d4f962198c72 100644 (file)
@@ -23,8 +23,9 @@ import org.opendaylight.controller.cluster.raft.messages.RequestVote;
 import org.opendaylight.controller.cluster.raft.messages.RequestVoteReply;
 
 /**
- * The behavior of a RaftActor when it is in the CandidateState
- * <p/>
+ * The behavior of a RaftActor when it is in the Candidate raft state.
+ *
+ * <p>
  * Candidates (§5.2):
  * <ul>
  * <li> On conversion to candidate, start election:
@@ -51,40 +52,44 @@ public class Candidate extends AbstractRaftActorBehavior {
     public Candidate(RaftActorContext context) {
         super(context, RaftState.Candidate);
 
-        for(PeerInfo peer: context.getPeers()) {
-            if(peer.isVoting()) {
+        for (PeerInfo peer: context.getPeers()) {
+            if (peer.isVoting()) {
                 votingPeers.add(peer.getId());
             }
         }
 
-        if(LOG.isDebugEnabled()) {
-            LOG.debug("{}: Election: Candidate has following voting peers: {}", logName(), votingPeers);
-        }
+        log.debug("{}: Election: Candidate has following voting peers: {}", logName(), votingPeers);
 
         votesRequired = getMajorityVoteCount(votingPeers.size());
 
         startNewTerm();
 
-        if(votingPeers.isEmpty()){
-            actor().tell(ELECTION_TIMEOUT, actor());
+        if (votingPeers.isEmpty()) {
+            actor().tell(ElectionTimeout.INSTANCE, actor());
         } else {
             scheduleElection(electionDuration());
         }
+    }
 
+    @Override
+    public final String getLeaderId() {
+        return null;
+    }
 
+    @Override
+    public final short getLeaderPayloadVersion() {
+        return -1;
     }
 
-    @Override protected RaftActorBehavior handleAppendEntries(ActorRef sender,
-        AppendEntries appendEntries) {
+    @Override
+    protected RaftActorBehavior handleAppendEntries(ActorRef sender, AppendEntries appendEntries) {
 
-        if(LOG.isDebugEnabled()) {
-            LOG.debug("{}: handleAppendEntries: {}", logName(), appendEntries);
-        }
+        log.debug("{}: handleAppendEntries: {}", logName(), appendEntries);
 
         // Some other candidate for the same term became a leader and sent us an append entry
-        if(currentTerm() == appendEntries.getTerm()){
-            LOG.debug("{}: New Leader sent an append entry to Candidate for term {} will switch to Follower",
-                    logName(), currentTerm());
+        if (currentTerm() == appendEntries.getTerm()) {
+            log.info("{}: New Leader {} sent an AppendEntries to Candidate for term {} - will switch to Follower",
+                    logName(), appendEntries.getLeaderId(), currentTerm());
 
             return switchBehavior(new Follower(context));
         }
@@ -92,68 +97,76 @@ public class Candidate extends AbstractRaftActorBehavior {
         return this;
     }
 
-    @Override protected RaftActorBehavior handleAppendEntriesReply(ActorRef sender,
-        AppendEntriesReply appendEntriesReply) {
-
+    @Override
+    protected RaftActorBehavior handleAppendEntriesReply(ActorRef sender, AppendEntriesReply appendEntriesReply) {
         return this;
     }
 
-    @Override protected RaftActorBehavior handleRequestVoteReply(ActorRef sender,
-            RequestVoteReply requestVoteReply) {
-
-        LOG.debug("{}: handleRequestVoteReply: {}, current voteCount: {}", logName(), requestVoteReply,
-                voteCount);
+    @Override
+    protected RaftActorBehavior handleRequestVoteReply(ActorRef sender, RequestVoteReply requestVoteReply) {
+        log.debug("{}: handleRequestVoteReply: {}, current voteCount: {}", logName(), requestVoteReply, voteCount);
 
         if (requestVoteReply.isVoteGranted()) {
             voteCount++;
         }
 
         if (voteCount >= votesRequired) {
-            return internalSwitchBehavior(RaftState.Leader);
+            if (context.getLastApplied() < context.getReplicatedLog().lastIndex()) {
+                log.info("{}: LastApplied index {} is behind last index {} - switching to PreLeader",
+                        logName(), context.getLastApplied(), context.getReplicatedLog().lastIndex());
+                return internalSwitchBehavior(RaftState.PreLeader);
+            } else {
+                return internalSwitchBehavior(RaftState.Leader);
+            }
         }
 
         return this;
     }
 
     @Override
-    public RaftActorBehavior handleMessage(ActorRef sender, Object originalMessage) {
+    public RaftActorBehavior handleMessage(ActorRef sender, Object message) {
+        if (message instanceof ElectionTimeout) {
+            log.debug("{}: Received ElectionTimeout", logName());
+
+            if (votesRequired == 0) {
+                // If there are no peers then we should be a Leader
+                // We wait for the election timeout to occur before declare
+                // ourselves the leader. This gives enough time for a leader
+                // who we do not know about (as a peer)
+                // to send a message to the candidate
 
-        Object message = fromSerializableMessage(originalMessage);
+                return internalSwitchBehavior(RaftState.Leader);
+            }
+
+            startNewTerm();
+            scheduleElection(electionDuration());
+            return this;
+        }
 
         if (message instanceof RaftRPC) {
 
             RaftRPC rpc = (RaftRPC) message;
 
-            if(LOG.isDebugEnabled()) {
-                LOG.debug("{}: RaftRPC message received {}, my term is {}", logName(), rpc,
+            log.debug("{}: RaftRPC message received {}, my term is {}", logName(), rpc,
                         context.getTermInformation().getCurrentTerm());
-            }
 
             // If RPC request or response contains term T > currentTerm:
             // set currentTerm = T, convert to follower (§5.1)
             // This applies to all RPC messages and responses
             if (rpc.getTerm() > context.getTermInformation().getCurrentTerm()) {
-                context.getTermInformation().updateAndPersist(rpc.getTerm(), null);
+                log.info("{}: Term {} in \"{}\" message is greater than Candidate's term {} - switching to Follower",
+                        logName(), rpc.getTerm(), rpc, context.getTermInformation().getCurrentTerm());
 
-                return internalSwitchBehavior(RaftState.Follower);
-            }
-        }
-
-        if (message instanceof ElectionTimeout) {
-            LOG.debug("{}: Received ElectionTimeout", logName());
+                context.getTermInformation().updateAndPersist(rpc.getTerm(), null);
 
-            if (votesRequired == 0) {
-                // If there are no peers then we should be a Leader
-                // We wait for the election timeout to occur before declare
-                // ourselves the leader. This gives enough time for a leader
-                // who we do not know about (as a peer)
-                // to send a message to the candidate
+                // The raft paper does not say whether or not a Candidate can/should process a RequestVote in
+                // this case but doing so gains quicker convergence when the sender's log is more up-to-date.
+                if (message instanceof RequestVote) {
+                    super.handleMessage(sender, message);
+                }
 
-                return internalSwitchBehavior(RaftState.Leader);
+                return internalSwitchBehavior(RaftState.Follower);
             }
-            startNewTerm();
-            scheduleElection(electionDuration());
-            return this;
         }
 
         return super.handleMessage(sender, message);
@@ -171,28 +184,29 @@ public class Candidate extends AbstractRaftActorBehavior {
         long newTerm = currentTerm + 1;
         context.getTermInformation().updateAndPersist(newTerm, context.getId());
 
-        LOG.debug("{}: Starting new term {}", logName(), newTerm);
+        log.info("{}: Starting new election term {}", logName(), newTerm);
 
         // Request for a vote
         // TODO: Retry request for vote if replies do not arrive in a reasonable
         // amount of time TBD
         for (String peerId : votingPeers) {
             ActorSelection peerActor = context.getPeerActorSelection(peerId);
-            if(peerActor != null) {
+            if (peerActor != null) {
                 RequestVote requestVote = new RequestVote(
                         context.getTermInformation().getCurrentTerm(),
                         context.getId(),
                         context.getReplicatedLog().lastIndex(),
                         context.getReplicatedLog().lastTerm());
 
-                LOG.debug("{}: Sending {} to peer {}", logName(), requestVote, peerId);
+                log.debug("{}: Sending {} to peer {}", logName(), requestVote, peerId);
 
                 peerActor.tell(requestVote, context.getActor());
             }
         }
     }
 
-    @Override public void close() throws Exception {
+    @Override
+    public void close() {
         stopElection();
     }
 }