Reduce/enhance logging in AbstractLeader

If you turn on debug logging for Shard, the "Checking sendAppendEntries
for follower..." message is logged by sendUpdatesToFollower on every
AppendEntriesReply heartbeat even when no data was sent to the follower.
This bombards the karaf.log. To avoid this, we need this only logged if
something changed for the follower. So, I changed the FollwerLogInformation
setMatchIndex and setNextIndex methods to return a boolean if changed
which handleAppendEntriesReply checks to see if either were updated. If
neither changed, it passes true to sendUpdatesToFollower for isHeartbeat
so the message isn't logged.

I also made a few other minor logging changes.

Change-Id: Ib1f2109092b3656c3cc3dfdd2cd7b4641a3f890b
Signed-off-by: Tom Pantelis <tpanteli@brocade.com>

diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java
index 73c81afd187d2791703c1428beacbc8348abda69..0beccd1b2b01ead56d4ea73235a3687fd73f408b 100644 (file)
--- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java
+++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformation.java
@@ -25,10 +25,13 @@ public interface FollowerLogInformation {
     long decrNextIndex();
 
     /**
     long decrNextIndex();
 
     /**

+     * Sets the index of the next log entry for this follower.

      *
      * @param nextIndex
      *
      * @param nextIndex

+     * @return true if the new index differed from the current index and the current index was updated, false
+     *              otherwise.

      */
      */

-    void setNextIndex(long nextIndex);
+    boolean setNextIndex(long nextIndex);

 
     /**
      * Increment the value of the matchIndex
 
     /**
      * Increment the value of the matchIndex


@@ -36,7 +39,14 @@ public interface FollowerLogInformation {
      */
     long incrMatchIndex();
 
      */
     long incrMatchIndex();
 

-    void setMatchIndex(long matchIndex);
+    /**
+     * Sets the index of the highest log entry for this follower.
+     *
+     * @param matchIndex
+     * @return true if the new index differed from the current index and the current index was updated, false
+     *              otherwise.
+     */
+    boolean setMatchIndex(long matchIndex);

 
     /**
      * The identifier of the follower
 
     /**
      * The identifier of the follower

diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java
index 90e128256132437c5f2acd4cb861e0e74a759d44..288a540344bda27cab5276265ebcae6079c492fd 100644 (file)
--- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java
+++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/FollowerLogInformationImpl.java
@@ -44,8 +44,13 @@ public class FollowerLogInformationImpl implements FollowerLogInformation {
     }
 
     @Override
     }
 
     @Override

-    public void setNextIndex(long nextIndex) {
-        this.nextIndex = nextIndex;
+    public boolean setNextIndex(long nextIndex) {
+        if(this.nextIndex != nextIndex) {
+            this.nextIndex = nextIndex;
+            return true;
+        }
+
+        return false;

     }
 
     @Override
     }
 
     @Override


@@ -54,8 +59,13 @@ public class FollowerLogInformationImpl implements FollowerLogInformation {
     }
 
     @Override
     }
 
     @Override

-    public void setMatchIndex(long matchIndex) {
-        this.matchIndex = matchIndex;
+    public boolean setMatchIndex(long matchIndex) {
+        if(this.matchIndex != matchIndex) {
+            this.matchIndex = matchIndex;
+            return true;
+        }
+
+        return false;

     }
 
     @Override
     }
 
     @Override

diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java
index 831f8f9e7088ed2017a81a2ed6911fdfbedb8e5b..a4753a4fe432654554a64578af0b09233069146b 100644 (file)
--- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java
+++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractLeader.java
@@ -158,8 +158,6 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
 
         if(LOG.isTraceEnabled()) {
             LOG.trace("{}: handleAppendEntriesReply: {}", logName(), appendEntriesReply);
 
         if(LOG.isTraceEnabled()) {
             LOG.trace("{}: handleAppendEntriesReply: {}", logName(), appendEntriesReply);

-        } else if(LOG.isDebugEnabled() && !appendEntriesReply.isSuccess()) {
-            LOG.debug("{}: handleAppendEntriesReply: {}", logName(), appendEntriesReply);

         }
 
         // Update the FollowerLogInformation
         }
 
         // Update the FollowerLogInformation


@@ -174,7 +172,7 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
 
         if(followerLogInformation.timeSinceLastActivity() >
                 context.getConfigParams().getElectionTimeOutInterval().toMillis()) {
 
         if(followerLogInformation.timeSinceLastActivity() >
                 context.getConfigParams().getElectionTimeOutInterval().toMillis()) {

-            LOG.error("{} : handleAppendEntriesReply delayed beyond election timeout, " +
+            LOG.warn("{} : handleAppendEntriesReply delayed beyond election timeout, " +

                             "appendEntriesReply : {}, timeSinceLastActivity : {}, lastApplied : {}, commitIndex : {}",
                     logName(), appendEntriesReply, followerLogInformation.timeSinceLastActivity(),
                     context.getLastApplied(), context.getCommitIndex());
                             "appendEntriesReply : {}, timeSinceLastActivity : {}, lastApplied : {}, commitIndex : {}",
                     logName(), appendEntriesReply, followerLogInformation.timeSinceLastActivity(),
                     context.getLastApplied(), context.getCommitIndex());


@@ -182,12 +180,17 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
 
         followerLogInformation.markFollowerActive();
 
 
         followerLogInformation.markFollowerActive();
 

+        boolean updated = false;

         if (appendEntriesReply.isSuccess()) {
         if (appendEntriesReply.isSuccess()) {

-            followerLogInformation
-                .setMatchIndex(appendEntriesReply.getLogLastIndex());
-            followerLogInformation
-                .setNextIndex(appendEntriesReply.getLogLastIndex() + 1);
+            updated = followerLogInformation.setMatchIndex(appendEntriesReply.getLogLastIndex());
+            updated = followerLogInformation.setNextIndex(appendEntriesReply.getLogLastIndex() + 1) || updated;
+
+            if(updated && LOG.isDebugEnabled()) {
+                LOG.debug("{}: handleAppendEntriesReply - FollowerLogInformation for {} updated: matchIndex: {}, nextIndex: {}", logName(),
+                        followerId, followerLogInformation.getMatchIndex(), followerLogInformation.getNextIndex());
+            }

         } else {
         } else {

+            LOG.debug("{}: handleAppendEntriesReply: received unsuccessful reply: {}", logName(), appendEntriesReply);

 
             // TODO: When we find that the follower is out of sync with the
             // Leader we simply decrement that followers next index by 1.
 
             // TODO: When we find that the follower is out of sync with the
             // Leader we simply decrement that followers next index by 1.


@@ -224,8 +227,10 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
 
         // Apply the change to the state machine
         if (context.getCommitIndex() > context.getLastApplied()) {
 
         // Apply the change to the state machine
         if (context.getCommitIndex() > context.getLastApplied()) {

-            LOG.debug("{}: handleAppendEntriesReply: applying to log - commitIndex: {}, lastAppliedIndex: {}",
-                    logName(), context.getCommitIndex(), context.getLastApplied());
+            if(LOG.isDebugEnabled()) {
+                LOG.debug("{}: handleAppendEntriesReply from {}: applying to log - commitIndex: {}, lastAppliedIndex: {}",
+                        logName(), followerId, context.getCommitIndex(), context.getLastApplied());
+            }

 
             applyLogToStateMachine(context.getCommitIndex());
         }
 
             applyLogToStateMachine(context.getCommitIndex());
         }


@@ -235,7 +240,7 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
         }
 
         //Send the next log entry immediately, if possible, no need to wait for heartbeat to trigger that event
         }
 
         //Send the next log entry immediately, if possible, no need to wait for heartbeat to trigger that event

-        sendUpdatesToFollower(followerId, followerLogInformation, false, false);
+        sendUpdatesToFollower(followerId, followerLogInformation, false, !updated);

         return this;
     }
 
         return this;
     }
 


@@ -469,9 +474,9 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
                 long leaderLastIndex = context.getReplicatedLog().lastIndex();
                 long leaderSnapShotIndex = context.getReplicatedLog().getSnapshotIndex();
 
                 long leaderLastIndex = context.getReplicatedLog().lastIndex();
                 long leaderSnapShotIndex = context.getReplicatedLog().getSnapshotIndex();
 

-                if(!isHeartbeat || LOG.isTraceEnabled()) {
-                    LOG.debug("{}: Checking sendAppendEntries for follower {}, leaderLastIndex: {}, leaderSnapShotIndex: {}",
-                            logName(), followerId, leaderLastIndex, leaderSnapShotIndex);
+                if((!isHeartbeat && LOG.isDebugEnabled()) || LOG.isTraceEnabled()) {
+                    LOG.debug("{}: Checking sendAppendEntries for follower {}, followerNextIndex {}, leaderLastIndex: {}, leaderSnapShotIndex: {}",
+                            logName(), followerId, followerNextIndex, leaderLastIndex, leaderSnapShotIndex);

                 }
 
                 if (isFollowerActive && context.getReplicatedLog().isPresent(followerNextIndex)) {
                 }
 
                 if (isFollowerActive && context.getReplicatedLog().isPresent(followerNextIndex)) {


@@ -556,7 +561,6 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
 
             } else if (!context.isSnapshotCaptureInitiated()) {
 
 
             } else if (!context.isSnapshotCaptureInitiated()) {
 

-                LOG.info("{}: Initiating Snapshot Capture to Install Snapshot, Leader:{}", logName(), getLeaderId());

                 ReplicatedLogEntry lastAppliedEntry = context.getReplicatedLog().get(context.getLastApplied());
                 long lastAppliedIndex = -1;
                 long lastAppliedTerm = -1;
                 ReplicatedLogEntry lastAppliedEntry = context.getReplicatedLog().get(context.getLastApplied());
                 long lastAppliedIndex = -1;
                 long lastAppliedTerm = -1;


@@ -572,10 +576,19 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
                 boolean isInstallSnapshotInitiated = true;
                 long replicatedToAllIndex = super.getReplicatedToAllIndex();
                 ReplicatedLogEntry replicatedToAllEntry = context.getReplicatedLog().get(replicatedToAllIndex);
                 boolean isInstallSnapshotInitiated = true;
                 long replicatedToAllIndex = super.getReplicatedToAllIndex();
                 ReplicatedLogEntry replicatedToAllEntry = context.getReplicatedLog().get(replicatedToAllIndex);

-                actor().tell(new CaptureSnapshot(lastIndex(), lastTerm(), lastAppliedIndex, lastAppliedTerm,
-                    (replicatedToAllEntry != null ? replicatedToAllEntry.getIndex() : -1),
-                    (replicatedToAllEntry != null ? replicatedToAllEntry.getTerm() : -1),
-                    isInstallSnapshotInitiated), actor());
+
+                CaptureSnapshot captureSnapshot = new CaptureSnapshot(
+                        lastIndex(), lastTerm(), lastAppliedIndex, lastAppliedTerm,
+                        (replicatedToAllEntry != null ? replicatedToAllEntry.getIndex() : -1),
+                        (replicatedToAllEntry != null ? replicatedToAllEntry.getTerm() : -1),
+                        isInstallSnapshotInitiated);
+
+                if(LOG.isDebugEnabled()) {
+                    LOG.debug("{}: Initiating install snapshot to follower {}: {}", logName(), followerId,
+                            captureSnapshot);
+                }
+
+                actor().tell(captureSnapshot, actor());

                 context.setSnapshotCaptureInitiated(true);
             }
         }
                 context.setSnapshotCaptureInitiated(true);
             }
         }


@@ -622,10 +635,12 @@ public abstract class AbstractLeader extends AbstractRaftActorBehavior {
                     ).toSerializable(),
                     actor()
                 );
                     ).toSerializable(),
                     actor()
                 );

-                LOG.info("{}: InstallSnapshot sent to follower {}, Chunk: {}/{}",
-                        logName(), followerActor.path(),
-                        followerToSnapshot.getChunkIndex(),
-                        followerToSnapshot.getTotalChunks());
+
+                if(LOG.isDebugEnabled()) {
+                    LOG.debug("{}: InstallSnapshot sent to follower {}, Chunk: {}/{}",
+                            logName(), followerActor.path(), followerToSnapshot.getChunkIndex(),
+                            followerToSnapshot.getTotalChunks());
+                }

             }
         } catch (IOException e) {
             LOG.error("{}: InstallSnapshot failed for Leader.", logName(), e);
             }
         } catch (IOException e) {
             LOG.error("{}: InstallSnapshot failed for Leader.", logName(), e);