Fix sporadic failures in ClusterAdminRpcServiceTest
[controller.git] / opendaylight / md-sal / sal-akka-raft / src / main / java / org / opendaylight / controller / cluster / raft / behaviors / Follower.java
1 /*
2  * Copyright (c) 2014 Cisco Systems, Inc. and others.  All rights reserved.
3  *
4  * This program and the accompanying materials are made available under the
5  * terms of the Eclipse Public License v1.0 which accompanies this distribution,
6  * and is available at http://www.eclipse.org/legal/epl-v10.html
7  */
8
9 package org.opendaylight.controller.cluster.raft.behaviors;
10
11 import akka.actor.ActorRef;
12 import com.google.common.annotations.VisibleForTesting;
13 import java.util.ArrayList;
14 import org.opendaylight.controller.cluster.raft.RaftActorContext;
15 import org.opendaylight.controller.cluster.raft.RaftState;
16 import org.opendaylight.controller.cluster.raft.ReplicatedLogEntry;
17 import org.opendaylight.controller.cluster.raft.ServerConfigurationPayload;
18 import org.opendaylight.controller.cluster.raft.Snapshot;
19 import org.opendaylight.controller.cluster.raft.base.messages.ApplySnapshot;
20 import org.opendaylight.controller.cluster.raft.base.messages.ElectionTimeout;
21 import org.opendaylight.controller.cluster.raft.messages.AppendEntries;
22 import org.opendaylight.controller.cluster.raft.messages.AppendEntriesReply;
23 import org.opendaylight.controller.cluster.raft.messages.InstallSnapshot;
24 import org.opendaylight.controller.cluster.raft.messages.InstallSnapshotReply;
25 import org.opendaylight.controller.cluster.raft.messages.RaftRPC;
26 import org.opendaylight.controller.cluster.raft.messages.RequestVote;
27 import org.opendaylight.controller.cluster.raft.messages.RequestVoteReply;
28
29 /**
30  * The behavior of a RaftActor in the Follower state
31  * <p/>
32  * <ul>
33  * <li> Respond to RPCs from candidates and leaders
34  * <li> If election timeout elapses without receiving AppendEntries
35  * RPC from current leader or granting vote to candidate:
36  * convert to candidate
37  * </ul>
38  */
39 public class Follower extends AbstractRaftActorBehavior {
40
41     private SnapshotTracker snapshotTracker = null;
42
43     private final SyncStatusTracker initialSyncStatusTracker;
44
45     private static final int SYNC_THRESHOLD = 10;
46
47     public Follower(RaftActorContext context) {
48         this(context, null, (short)-1);
49     }
50
51     public Follower(RaftActorContext context, String initialLeaderId, short initialLeaderPayloadVersion) {
52         super(context, RaftState.Follower);
53         leaderId = initialLeaderId;
54         setLeaderPayloadVersion(initialLeaderPayloadVersion);
55
56         initialSyncStatusTracker = new SyncStatusTracker(context.getActor(), getId(), SYNC_THRESHOLD);
57
58         if(canStartElection()) {
59             if (context.getPeerIds().isEmpty() && getLeaderId() == null) {
60                 actor().tell(ElectionTimeout.INSTANCE, actor());
61             } else {
62                 scheduleElection(electionDuration());
63             }
64         }
65
66     }
67
68     private boolean isLogEntryPresent(long index){
69         if(index == context.getReplicatedLog().getSnapshotIndex()){
70             return true;
71         }
72
73         ReplicatedLogEntry previousEntry = context.getReplicatedLog()
74                 .get(index);
75
76         return previousEntry != null;
77
78     }
79
80     private long getLogEntryTerm(long index){
81         if(index == context.getReplicatedLog().getSnapshotIndex()){
82             return context.getReplicatedLog().getSnapshotTerm();
83         }
84
85         ReplicatedLogEntry previousEntry = context.getReplicatedLog()
86                 .get(index);
87
88         if(previousEntry != null){
89             return previousEntry.getTerm();
90         }
91
92         return -1;
93     }
94
95     private void updateInitialSyncStatus(long currentLeaderCommit, String leaderId){
96         initialSyncStatusTracker.update(leaderId, currentLeaderCommit, context.getCommitIndex());
97     }
98
99     @Override protected RaftActorBehavior handleAppendEntries(ActorRef sender,
100                                                               AppendEntries appendEntries) {
101
102         int numLogEntries = appendEntries.getEntries() != null ? appendEntries.getEntries().size() : 0;
103         if(LOG.isTraceEnabled()) {
104             LOG.trace("{}: handleAppendEntries: {}", logName(), appendEntries);
105         } else if(LOG.isDebugEnabled() && numLogEntries > 0) {
106             LOG.debug("{}: handleAppendEntries: {}", logName(), appendEntries);
107         }
108
109         // TODO : Refactor this method into a bunch of smaller methods
110         // to make it easier to read. Before refactoring ensure tests
111         // cover the code properly
112
113         if (snapshotTracker != null || context.getSnapshotManager().isApplying()) {
114             // if snapshot install is in progress, follower should just acknowledge append entries with a reply.
115             AppendEntriesReply reply = new AppendEntriesReply(context.getId(), currentTerm(), true,
116                     lastIndex(), lastTerm(), context.getPayloadVersion());
117
118             if(LOG.isDebugEnabled()) {
119                 LOG.debug("{}: snapshot install is in progress, replying immediately with {}", logName(), reply);
120             }
121             sender.tell(reply, actor());
122
123             return this;
124         }
125
126         // If we got here then we do appear to be talking to the leader
127         leaderId = appendEntries.getLeaderId();
128
129         setLeaderPayloadVersion(appendEntries.getPayloadVersion());
130
131         updateInitialSyncStatus(appendEntries.getLeaderCommit(), appendEntries.getLeaderId());
132         // First check if the logs are in sync or not
133         long lastIndex = lastIndex();
134
135         if (isOutOfSync(appendEntries)) {
136             // We found that the log was out of sync so just send a negative
137             // reply and return
138
139             LOG.debug("{}: Follower is out-of-sync, so sending negative reply, lastIndex: {}, lastTerm: {}",
140                         logName(), lastIndex, lastTerm());
141
142             sender.tell(new AppendEntriesReply(context.getId(), currentTerm(), false, lastIndex,
143                     lastTerm(), context.getPayloadVersion()), actor());
144             return this;
145         }
146
147         if (appendEntries.getEntries() != null && appendEntries.getEntries().size() > 0) {
148
149             LOG.debug("{}: Number of entries to be appended = {}", logName(),
150                         appendEntries.getEntries().size());
151
152             // 3. If an existing entry conflicts with a new one (same index
153             // but different terms), delete the existing entry and all that
154             // follow it (§5.3)
155             int addEntriesFrom = 0;
156             if (context.getReplicatedLog().size() > 0) {
157
158                 // Find the entry up until the one that is not in the follower's log
159                 for (int i = 0;i < appendEntries.getEntries().size(); i++, addEntriesFrom++) {
160                     ReplicatedLogEntry matchEntry = appendEntries.getEntries().get(i);
161                     ReplicatedLogEntry newEntry = context.getReplicatedLog().get(matchEntry.getIndex());
162
163                     if (newEntry == null) {
164                         //newEntry not found in the log
165                         break;
166                     }
167
168                     if (newEntry.getTerm() == matchEntry.getTerm()) {
169                         continue;
170                     }
171
172                     if(!context.getRaftPolicy().applyModificationToStateBeforeConsensus()) {
173
174                         LOG.debug("{}: Removing entries from log starting at {}", logName(),
175                                 matchEntry.getIndex());
176
177                         // Entries do not match so remove all subsequent entries
178                         context.getReplicatedLog().removeFromAndPersist(matchEntry.getIndex());
179                         break;
180                     } else {
181                         sender.tell(new AppendEntriesReply(context.getId(), currentTerm(), false, lastIndex,
182                                 lastTerm(), context.getPayloadVersion(), true), actor());
183                         return this;
184                     }
185                 }
186             }
187
188             lastIndex = lastIndex();
189             LOG.debug("{}: After cleanup entries to be added from = {}", logName(),
190                         (addEntriesFrom + lastIndex));
191
192             // 4. Append any new entries not already in the log
193             for (int i = addEntriesFrom; i < appendEntries.getEntries().size(); i++) {
194                 ReplicatedLogEntry entry = appendEntries.getEntries().get(i);
195
196                 LOG.debug("{}: Append entry to log {}", logName(), entry.getData());
197
198                 context.getReplicatedLog().appendAndPersist(entry);
199
200                 if(entry.getData() instanceof ServerConfigurationPayload) {
201                     context.updatePeerIds((ServerConfigurationPayload)entry.getData());
202                 }
203             }
204
205             LOG.debug("{}: Log size is now {}", logName(), context.getReplicatedLog().size());
206         }
207
208         // 5. If leaderCommit > commitIndex, set commitIndex =
209         // min(leaderCommit, index of last new entry)
210
211         lastIndex = lastIndex();
212         long prevCommitIndex = context.getCommitIndex();
213
214         context.setCommitIndex(Math.min(appendEntries.getLeaderCommit(), lastIndex));
215
216         if (prevCommitIndex != context.getCommitIndex()) {
217             LOG.debug("{}: Commit index set to {}", logName(), context.getCommitIndex());
218         }
219
220         // If commitIndex > lastApplied: increment lastApplied, apply
221         // log[lastApplied] to state machine (§5.3)
222         // check if there are any entries to be applied. last-applied can be equal to last-index
223         if (appendEntries.getLeaderCommit() > context.getLastApplied() &&
224             context.getLastApplied() < lastIndex) {
225             if(LOG.isDebugEnabled()) {
226                 LOG.debug("{}: applyLogToStateMachine, " +
227                         "appendEntries.getLeaderCommit(): {}," +
228                         "context.getLastApplied(): {}, lastIndex(): {}", logName(),
229                     appendEntries.getLeaderCommit(), context.getLastApplied(), lastIndex);
230             }
231
232             applyLogToStateMachine(appendEntries.getLeaderCommit());
233         }
234
235         AppendEntriesReply reply = new AppendEntriesReply(context.getId(), currentTerm(), true,
236             lastIndex, lastTerm(), context.getPayloadVersion());
237
238         if(LOG.isTraceEnabled()) {
239             LOG.trace("{}: handleAppendEntries returning : {}", logName(), reply);
240         } else if(LOG.isDebugEnabled() && numLogEntries > 0) {
241             LOG.debug("{}: handleAppendEntries returning : {}", logName(), reply);
242         }
243
244         sender.tell(reply, actor());
245
246         if (!context.getSnapshotManager().isCapturing()) {
247             super.performSnapshotWithoutCapture(appendEntries.getReplicatedToAllIndex());
248         }
249
250         return this;
251     }
252
253     private boolean isOutOfSync(AppendEntries appendEntries) {
254
255         long prevLogTerm = getLogEntryTerm(appendEntries.getPrevLogIndex());
256         boolean prevEntryPresent = isLogEntryPresent(appendEntries.getPrevLogIndex());
257         long lastIndex = lastIndex();
258         int numLogEntries = appendEntries.getEntries() != null ? appendEntries.getEntries().size() : 0;
259         boolean outOfSync = true;
260
261         if (lastIndex == -1 && appendEntries.getPrevLogIndex() != -1) {
262
263             // The follower's log is out of sync because the leader does have
264             // an entry at prevLogIndex and this follower has no entries in
265             // it's log.
266
267             LOG.debug("{}: The followers log is empty and the senders prevLogIndex is {}",
268                         logName(), appendEntries.getPrevLogIndex());
269         } else if (lastIndex > -1 && appendEntries.getPrevLogIndex() != -1 && !prevEntryPresent) {
270
271             // The follower's log is out of sync because the Leader's
272             // prevLogIndex entry was not found in it's log
273
274             LOG.debug("{}: The log is not empty but the prevLogIndex {} was not found in it",
275                         logName(), appendEntries.getPrevLogIndex());
276         } else if (lastIndex > -1 && prevEntryPresent && prevLogTerm != appendEntries.getPrevLogTerm()) {
277
278             // The follower's log is out of sync because the Leader's
279             // prevLogIndex entry does exist in the follower's log but it has
280             // a different term in it
281
282             LOG.debug(
283                     "{}: Cannot append entries because previous entry term {}  is not equal to append entries prevLogTerm {}",
284                     logName(), prevLogTerm, appendEntries.getPrevLogTerm());
285         } else if(appendEntries.getPrevLogIndex() == -1 && appendEntries.getPrevLogTerm() == -1
286                 && appendEntries.getReplicatedToAllIndex() != -1
287                 && !isLogEntryPresent(appendEntries.getReplicatedToAllIndex())
288                 && !context.getReplicatedLog().isInSnapshot(appendEntries.getReplicatedToAllIndex())) {
289             // This append entry comes from a leader who has it's log aggressively trimmed and so does not have
290             // the previous entry in it's in-memory journal
291
292             LOG.debug(
293                     "{}: Cannot append entries because the replicatedToAllIndex {} does not appear to be in the in-memory journal",
294                     logName(), appendEntries.getReplicatedToAllIndex());
295         } else if(appendEntries.getPrevLogIndex() == -1 && appendEntries.getPrevLogTerm() == -1
296                 && appendEntries.getReplicatedToAllIndex() != -1 && numLogEntries > 0
297                 && !isLogEntryPresent(appendEntries.getEntries().get(0).getIndex() - 1)
298                 && !context.getReplicatedLog().isInSnapshot(appendEntries.getEntries().get(0).getIndex() - 1)) {
299             LOG.debug(
300                     "{}: Cannot append entries because the calculated previousIndex {} was not found in the in-memory journal",
301                     logName(), appendEntries.getEntries().get(0).getIndex() - 1);
302         } else {
303             outOfSync = false;
304         }
305         return outOfSync;
306     }
307
308     @Override protected RaftActorBehavior handleAppendEntriesReply(ActorRef sender,
309         AppendEntriesReply appendEntriesReply) {
310         return this;
311     }
312
313     @Override protected RaftActorBehavior handleRequestVoteReply(ActorRef sender,
314         RequestVoteReply requestVoteReply) {
315         return this;
316     }
317
318     @Override public RaftActorBehavior handleMessage(ActorRef sender, Object originalMessage) {
319
320         Object message = fromSerializableMessage(originalMessage);
321
322         if (message instanceof RaftRPC) {
323             RaftRPC rpc = (RaftRPC) message;
324             // If RPC request or response contains term T > currentTerm:
325             // set currentTerm = T, convert to follower (§5.1)
326             // This applies to all RPC messages and responses
327             if (rpc.getTerm() > context.getTermInformation().getCurrentTerm()) {
328                 LOG.debug("{}: Term {} in \"{}\" message is greater than follower's term {} - updating term",
329                         logName(), rpc.getTerm(), rpc, context.getTermInformation().getCurrentTerm());
330
331                 context.getTermInformation().updateAndPersist(rpc.getTerm(), null);
332             }
333         }
334
335         if (message instanceof ElectionTimeout) {
336             if(canStartElection()) {
337                 LOG.debug("{}: Received ElectionTimeout - switching to Candidate", logName());
338                 return internalSwitchBehavior(RaftState.Candidate);
339             } else {
340                 return this;
341             }
342
343         } else if (message instanceof InstallSnapshot) {
344             InstallSnapshot installSnapshot = (InstallSnapshot) message;
345             handleInstallSnapshot(sender, installSnapshot);
346         }
347
348         if(message instanceof RaftRPC && (!(message instanceof RequestVote) || (canGrantVote((RequestVote) message)))){
349             scheduleElection(electionDuration());
350         }
351
352         return super.handleMessage(sender, message);
353     }
354
355     private void handleInstallSnapshot(final ActorRef sender, InstallSnapshot installSnapshot) {
356
357         LOG.debug("{}: handleInstallSnapshot: {}", logName(), installSnapshot);
358
359         leaderId = installSnapshot.getLeaderId();
360
361         if(snapshotTracker == null){
362             snapshotTracker = new SnapshotTracker(LOG, installSnapshot.getTotalChunks());
363         }
364
365         updateInitialSyncStatus(installSnapshot.getLastIncludedIndex(), installSnapshot.getLeaderId());
366
367         try {
368             final InstallSnapshotReply reply = new InstallSnapshotReply(
369                     currentTerm(), context.getId(), installSnapshot.getChunkIndex(), true);
370
371             if(snapshotTracker.addChunk(installSnapshot.getChunkIndex(), installSnapshot.getData(),
372                     installSnapshot.getLastChunkHashCode())){
373                 Snapshot snapshot = Snapshot.create(snapshotTracker.getSnapshot(),
374                         new ArrayList<ReplicatedLogEntry>(),
375                         installSnapshot.getLastIncludedIndex(),
376                         installSnapshot.getLastIncludedTerm(),
377                         installSnapshot.getLastIncludedIndex(),
378                         installSnapshot.getLastIncludedTerm(),
379                         context.getTermInformation().getCurrentTerm(),
380                         context.getTermInformation().getVotedFor(),
381                         context.getPeerServerInfo(true));
382
383                 ApplySnapshot.Callback applySnapshotCallback = new ApplySnapshot.Callback() {
384                     @Override
385                     public void onSuccess() {
386                         LOG.debug("{}: handleInstallSnapshot returning: {}", logName(), reply);
387
388                         sender.tell(reply, actor());
389                     }
390
391                     @Override
392                     public void onFailure() {
393                         sender.tell(new InstallSnapshotReply(currentTerm(), context.getId(), -1, false), actor());
394                     }
395                 };
396
397                 actor().tell(new ApplySnapshot(snapshot, applySnapshotCallback), actor());
398
399                 snapshotTracker = null;
400             } else {
401                 LOG.debug("{}: handleInstallSnapshot returning: {}", logName(), reply);
402
403                 sender.tell(reply, actor());
404             }
405         } catch (SnapshotTracker.InvalidChunkException e) {
406             LOG.debug("{}: Exception in InstallSnapshot of follower", logName(), e);
407
408             sender.tell(new InstallSnapshotReply(currentTerm(), context.getId(),
409                     -1, false), actor());
410             snapshotTracker = null;
411
412         } catch (Exception e){
413             LOG.error("{}: Exception in InstallSnapshot of follower", logName(), e);
414
415             //send reply with success as false. The chunk will be sent again on failure
416             sender.tell(new InstallSnapshotReply(currentTerm(), context.getId(),
417                     installSnapshot.getChunkIndex(), false), actor());
418
419         }
420     }
421
422     @Override
423     public void close() throws Exception {
424         stopElection();
425     }
426
427     @VisibleForTesting
428     SnapshotTracker getSnapshotTracker(){
429         return snapshotTracker;
430     }
431 }