From 5a15471e74536f8fe6d62747b7b822655a17dd4e Mon Sep 17 00:00:00 2001 From: Harman Singh Date: Mon, 15 Sep 2014 17:14:17 -0700 Subject: [PATCH] BUG 1883 - Ensure that all debug logging is done conditionally This commit is mostly about conditional logging. It also sneaks in a couple of other things, 1. Cleanup of ClientRequestTracker 2. Removal of some dead code Change-Id: I0862f1273e94856e19107d3a4beec4d66452787d Signed-off-by: Moiz Raja Signed-off-by: Harman Singh --- .../cluster/example/ExampleActor.java | 14 +- .../controller/cluster/raft/RaftActor.java | 64 ++++--- .../behaviors/AbstractRaftActorBehavior.java | 13 +- .../cluster/raft/behaviors/Follower.java | 112 +++++++----- .../cluster/raft/behaviors/Leader.java | 99 ++++++---- .../common/actor/AbstractUntypedActor.java | 18 +- .../controller/xml/codec/XmlStreamUtils.java | 24 ++- .../controller/xml/codec/XmlUtils.java | 53 +++--- .../datastore/DistributedDataStore.java | 16 +- .../controller/cluster/datastore/Shard.java | 69 ++++--- .../cluster/datastore/ShardManager.java | 10 +- .../cluster/datastore/ShardTransaction.java | 17 +- .../cluster/datastore/TerminationMonitor.java | 4 +- .../datastore/ThreePhaseCommitCohort.java | 4 +- .../ThreePhaseCommitCohortProxy.java | 65 ++++--- .../cluster/datastore/TransactionProxy.java | 170 +++++++++++------- .../cluster/datastore/utils/ActorContext.java | 22 ++- .../remote/rpc/RemoteRpcProviderFactory.java | 5 +- .../remote/rpc/RoutedRpcListener.java | 8 +- .../controller/remote/rpc/RpcBroker.java | 10 +- .../controller/remote/rpc/RpcListener.java | 8 +- .../remote/rpc/TerminationMonitor.java | 4 +- .../rpc/registry/gossip/BucketStore.java | 9 +- .../remote/rpc/registry/gossip/Gossiper.java | 26 ++- 24 files changed, 545 insertions(+), 299 deletions(-) diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/example/ExampleActor.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/example/ExampleActor.java index c4ff108611..3bfdf732cf 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/example/ExampleActor.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/example/ExampleActor.java @@ -67,11 +67,15 @@ public class ExampleActor extends RaftActor { } } else if (message instanceof PrintState) { - LOG.debug("State of the node:{} has entries={}, {}", - getId(), state.size(), getReplicatedLogState()); + if(LOG.isDebugEnabled()) { + LOG.debug("State of the node:{} has entries={}, {}", + getId(), state.size(), getReplicatedLogState()); + } } else if (message instanceof PrintRole) { - LOG.debug("{} = {}, Peers={}", getId(), getRaftState(),getPeers()); + if(LOG.isDebugEnabled()) { + LOG.debug("{} = {}, Peers={}", getId(), getRaftState(), getPeers()); + } } else { super.onReceiveCommand(message); @@ -106,7 +110,9 @@ public class ExampleActor extends RaftActor { } catch (Exception e) { LOG.error("Exception in applying snapshot", e); } - LOG.debug("Snapshot applied to state :" + ((HashMap) state).size()); + if(LOG.isDebugEnabled()) { + LOG.debug("Snapshot applied to state :" + ((HashMap) state).size()); + } } private ByteString fromObject(Object snapshot) throws Exception { diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java index 190f1bd409..91bbeeca50 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/RaftActor.java @@ -157,13 +157,16 @@ public abstract class RaftActor extends UntypedPersistentActor { } else if (message instanceof UpdateElectionTerm) { context.getTermInformation().update(((UpdateElectionTerm) message).getCurrentTerm(), ((UpdateElectionTerm) message).getVotedFor()); } else if (message instanceof RecoveryCompleted) { - LOG.debug( - "RecoveryCompleted - Switching actor to Follower - " + - "Persistence Id = " + persistenceId() + - " Last index in log:{}, snapshotIndex={}, snapshotTerm={}, " + - "journal-size={}", - replicatedLog.lastIndex(), replicatedLog.snapshotIndex, - replicatedLog.snapshotTerm, replicatedLog.size()); + if(LOG.isDebugEnabled()) { + LOG.debug( + "RecoveryCompleted - Switching actor to Follower - " + + "Persistence Id = " + persistenceId() + + " Last index in log:{}, snapshotIndex={}, snapshotTerm={}, " + + "journal-size={}", + replicatedLog.lastIndex(), replicatedLog.snapshotIndex, + replicatedLog.snapshotTerm, replicatedLog.size() + ); + } currentBehavior = switchBehavior(RaftState.Follower); onStateChanged(); } @@ -173,9 +176,11 @@ public abstract class RaftActor extends UntypedPersistentActor { if (message instanceof ApplyState){ ApplyState applyState = (ApplyState) message; - LOG.debug("Applying state for log index {} data {}", - applyState.getReplicatedLogEntry().getIndex(), - applyState.getReplicatedLogEntry().getData()); + if(LOG.isDebugEnabled()) { + LOG.debug("Applying state for log index {} data {}", + applyState.getReplicatedLogEntry().getIndex(), + applyState.getReplicatedLogEntry().getData()); + } applyState(applyState.getClientActor(), applyState.getIdentifier(), applyState.getReplicatedLogEntry().getData()); @@ -183,9 +188,12 @@ public abstract class RaftActor extends UntypedPersistentActor { } else if(message instanceof ApplySnapshot ) { Snapshot snapshot = ((ApplySnapshot) message).getSnapshot(); - LOG.debug("ApplySnapshot called on Follower Actor " + - "snapshotIndex:{}, snapshotTerm:{}", snapshot.getLastAppliedIndex(), - snapshot.getLastAppliedTerm()); + if(LOG.isDebugEnabled()) { + LOG.debug("ApplySnapshot called on Follower Actor " + + "snapshotIndex:{}, snapshotTerm:{}", snapshot.getLastAppliedIndex(), + snapshot.getLastAppliedTerm() + ); + } applySnapshot(ByteString.copyFrom(snapshot.getState())); //clears the followers log, sets the snapshot index to ensure adjusted-index works @@ -253,7 +261,9 @@ public abstract class RaftActor extends UntypedPersistentActor { } else { if (!(message instanceof AppendEntriesMessages.AppendEntries) && !(message instanceof AppendEntriesReply) && !(message instanceof SendHeartBeat)) { - LOG.debug("onReceiveCommand: message:" + message.getClass()); + if(LOG.isDebugEnabled()) { + LOG.debug("onReceiveCommand: message:" + message.getClass()); + } } RaftState state = @@ -294,7 +304,9 @@ public abstract class RaftActor extends UntypedPersistentActor { context.getReplicatedLog().lastIndex() + 1, context.getTermInformation().getCurrentTerm(), data); - LOG.debug("Persist data {}", replicatedLogEntry); + if(LOG.isDebugEnabled()) { + LOG.debug("Persist data {}", replicatedLogEntry); + } replicatedLog .appendAndPersist(clientActor, identifier, replicatedLogEntry); @@ -483,8 +495,10 @@ public abstract class RaftActor extends UntypedPersistentActor { return null; } String peerAddress = context.getPeerAddress(leaderId); - LOG.debug("getLeaderAddress leaderId = " + leaderId + " peerAddress = " - + peerAddress); + if(LOG.isDebugEnabled()) { + LOG.debug("getLeaderAddress leaderId = " + leaderId + " peerAddress = " + + peerAddress); + } return peerAddress; } @@ -584,10 +598,13 @@ public abstract class RaftActor extends UntypedPersistentActor { lastAppliedTerm = lastAppliedEntry.getTerm(); } - LOG.debug("Snapshot Capture logSize: {}", journal.size()); - LOG.debug("Snapshot Capture lastApplied:{} ", context.getLastApplied()); - LOG.debug("Snapshot Capture lastAppliedIndex:{}", lastAppliedIndex); - LOG.debug("Snapshot Capture lastAppliedTerm:{}", lastAppliedTerm); + if(LOG.isDebugEnabled()) { + LOG.debug("Snapshot Capture logSize: {}", journal.size()); + LOG.debug("Snapshot Capture lastApplied:{} ", + context.getLastApplied()); + LOG.debug("Snapshot Capture lastAppliedIndex:{}", lastAppliedIndex); + LOG.debug("Snapshot Capture lastAppliedTerm:{}", lastAppliedTerm); + } // send a CaptureSnapshot to self to make the expensive operation async. getSelf().tell(new CaptureSnapshot( @@ -639,8 +656,9 @@ public abstract class RaftActor extends UntypedPersistentActor { } @Override public void update(long currentTerm, String votedFor) { - LOG.debug("Set currentTerm={}, votedFor={}", currentTerm, votedFor); - + if(LOG.isDebugEnabled()) { + LOG.debug("Set currentTerm={}, votedFor={}", currentTerm, votedFor); + } this.currentTerm = currentTerm; this.votedFor = votedFor; } diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractRaftActorBehavior.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractRaftActorBehavior.java index 86447509d7..35d563b784 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractRaftActorBehavior.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/AbstractRaftActorBehavior.java @@ -272,6 +272,17 @@ public abstract class AbstractRaftActorBehavior implements RaftActorBehavior { return null; } + /** + * Find the client request tracker for a specific logIndex + * + * @param logIndex + * @return + */ + protected ClientRequestTracker removeClientRequestTracker(long logIndex) { + return null; + } + + /** * Find the log index from the previous to last entry in the log * @@ -311,7 +322,7 @@ public abstract class AbstractRaftActorBehavior implements RaftActorBehavior { i < index + 1; i++) { ActorRef clientActor = null; String identifier = null; - ClientRequestTracker tracker = findClientRequestTracker(i); + ClientRequestTracker tracker = removeClientRequestTracker(i); if (tracker != null) { clientActor = tracker.getClientActor(); diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Follower.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Follower.java index 610fdc987f..1cfdf9dba8 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Follower.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Follower.java @@ -9,6 +9,7 @@ package org.opendaylight.controller.cluster.raft.behaviors; import akka.actor.ActorRef; +import akka.event.LoggingAdapter; import com.google.protobuf.ByteString; import org.opendaylight.controller.cluster.raft.RaftActorContext; import org.opendaylight.controller.cluster.raft.RaftState; @@ -38,9 +39,13 @@ import java.util.ArrayList; public class Follower extends AbstractRaftActorBehavior { private ByteString snapshotChunksCollected = ByteString.EMPTY; + private final LoggingAdapter LOG; + public Follower(RaftActorContext context) { super(context); + LOG = context.getLogger(); + scheduleElection(electionDuration()); } @@ -48,8 +53,9 @@ public class Follower extends AbstractRaftActorBehavior { AppendEntries appendEntries) { if(appendEntries.getEntries() != null && appendEntries.getEntries().size() > 0) { - context.getLogger() - .debug(appendEntries.toString()); + if(LOG.isDebugEnabled()) { + LOG.debug(appendEntries.toString()); + } } // TODO : Refactor this method into a bunch of smaller methods @@ -79,9 +85,10 @@ public class Follower extends AbstractRaftActorBehavior { // an entry at prevLogIndex and this follower has no entries in // it's log. - context.getLogger().debug( - "The followers log is empty and the senders prevLogIndex is {}", - appendEntries.getPrevLogIndex()); + if(LOG.isDebugEnabled()) { + LOG.debug("The followers log is empty and the senders prevLogIndex is {}", + appendEntries.getPrevLogIndex()); + } } else if (lastIndex() > -1 && appendEntries.getPrevLogIndex() != -1 @@ -90,9 +97,10 @@ public class Follower extends AbstractRaftActorBehavior { // The follower's log is out of sync because the Leader's // prevLogIndex entry was not found in it's log - context.getLogger().debug( - "The log is not empty but the prevLogIndex {} was not found in it", - appendEntries.getPrevLogIndex()); + if(LOG.isDebugEnabled()) { + LOG.debug("The log is not empty but the prevLogIndex {} was not found in it", + appendEntries.getPrevLogIndex()); + } } else if (lastIndex() > -1 && previousEntry != null @@ -102,10 +110,12 @@ public class Follower extends AbstractRaftActorBehavior { // prevLogIndex entry does exist in the follower's log but it has // a different term in it - context.getLogger().debug( - "Cannot append entries because previous entry term {} is not equal to append entries prevLogTerm {}" - , previousEntry.getTerm() - , appendEntries.getPrevLogTerm()); + if(LOG.isDebugEnabled()) { + LOG.debug( + "Cannot append entries because previous entry term {} is not equal to append entries prevLogTerm {}" + , previousEntry.getTerm() + , appendEntries.getPrevLogTerm()); + } } else { outOfSync = false; } @@ -113,9 +123,12 @@ public class Follower extends AbstractRaftActorBehavior { if (outOfSync) { // We found that the log was out of sync so just send a negative // reply and return - context.getLogger().debug("Follower is out-of-sync, " + - "so sending negative reply, lastIndex():{}, lastTerm():{}", - lastIndex(), lastTerm()); + if(LOG.isDebugEnabled()) { + LOG.debug("Follower is out-of-sync, " + + "so sending negative reply, lastIndex():{}, lastTerm():{}", + lastIndex(), lastTerm() + ); + } sender.tell( new AppendEntriesReply(context.getId(), currentTerm(), false, lastIndex(), lastTerm()), actor() @@ -125,10 +138,12 @@ public class Follower extends AbstractRaftActorBehavior { if (appendEntries.getEntries() != null && appendEntries.getEntries().size() > 0) { - context.getLogger().debug( - "Number of entries to be appended = " + appendEntries - .getEntries().size() - ); + if(LOG.isDebugEnabled()) { + LOG.debug( + "Number of entries to be appended = " + appendEntries + .getEntries().size() + ); + } // 3. If an existing entry conflicts with a new one (same index // but different terms), delete the existing entry and all that @@ -151,10 +166,12 @@ public class Follower extends AbstractRaftActorBehavior { continue; } - context.getLogger().debug( - "Removing entries from log starting at " - + matchEntry.getIndex() - ); + if(LOG.isDebugEnabled()) { + LOG.debug( + "Removing entries from log starting at " + + matchEntry.getIndex() + ); + } // Entries do not match so remove all subsequent entries context.getReplicatedLog() @@ -163,10 +180,12 @@ public class Follower extends AbstractRaftActorBehavior { } } - context.getLogger().debug( - "After cleanup entries to be added from = " + (addEntriesFrom - + lastIndex()) - ); + if(LOG.isDebugEnabled()) { + context.getLogger().debug( + "After cleanup entries to be added from = " + (addEntriesFrom + + lastIndex()) + ); + } // 4. Append any new entries not already in the log for (int i = addEntriesFrom; @@ -181,8 +200,9 @@ public class Follower extends AbstractRaftActorBehavior { .appendAndPersist(appendEntries.getEntries().get(i)); } - context.getLogger().debug( - "Log size is now " + context.getReplicatedLog().size()); + if(LOG.isDebugEnabled()) { + LOG.debug("Log size is now " + context.getReplicatedLog().size()); + } } @@ -195,8 +215,9 @@ public class Follower extends AbstractRaftActorBehavior { context.getReplicatedLog().lastIndex())); if (prevCommitIndex != context.getCommitIndex()) { - context.getLogger() - .debug("Commit index set to " + context.getCommitIndex()); + if(LOG.isDebugEnabled()) { + LOG.debug("Commit index set to " + context.getCommitIndex()); + } } // If commitIndex > lastApplied: increment lastApplied, apply @@ -204,10 +225,14 @@ public class Follower extends AbstractRaftActorBehavior { // check if there are any entries to be applied. last-applied can be equal to last-index if (appendEntries.getLeaderCommit() > context.getLastApplied() && context.getLastApplied() < lastIndex()) { - context.getLogger().debug("applyLogToStateMachine, " + - "appendEntries.getLeaderCommit():{}," + - "context.getLastApplied():{}, lastIndex():{}", - appendEntries.getLeaderCommit(), context.getLastApplied(), lastIndex()); + if(LOG.isDebugEnabled()) { + LOG.debug("applyLogToStateMachine, " + + "appendEntries.getLeaderCommit():{}," + + "context.getLastApplied():{}, lastIndex():{}", + appendEntries.getLeaderCommit(), context.getLastApplied(), lastIndex() + ); + } + applyLogToStateMachine(appendEntries.getLeaderCommit()); } @@ -259,9 +284,13 @@ public class Follower extends AbstractRaftActorBehavior { } private void handleInstallSnapshot(ActorRef sender, InstallSnapshot installSnapshot) { - context.getLogger().debug("InstallSnapshot received by follower " + - "datasize:{} , Chunk:{}/{}", installSnapshot.getData().size(), - installSnapshot.getChunkIndex(), installSnapshot.getTotalChunks()); + + if(LOG.isDebugEnabled()) { + LOG.debug("InstallSnapshot received by follower " + + "datasize:{} , Chunk:{}/{}", installSnapshot.getData().size(), + installSnapshot.getChunkIndex(), installSnapshot.getTotalChunks() + ); + } try { if (installSnapshot.getChunkIndex() == installSnapshot.getTotalChunks()) { @@ -283,8 +312,11 @@ public class Follower extends AbstractRaftActorBehavior { } else { // we have more to go snapshotChunksCollected = snapshotChunksCollected.concat(installSnapshot.getData()); - context.getLogger().debug("Chunk={},snapshotChunksCollected.size:{}", - installSnapshot.getChunkIndex(), snapshotChunksCollected.size()); + + if(LOG.isDebugEnabled()) { + LOG.debug("Chunk={},snapshotChunksCollected.size:{}", + installSnapshot.getChunkIndex(), snapshotChunksCollected.size()); + } } sender.tell(new InstallSnapshotReply( diff --git a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Leader.java b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Leader.java index 90948ffef7..199d2d61cf 100644 --- a/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Leader.java +++ b/opendaylight/md-sal/sal-akka-raft/src/main/java/org/opendaylight/controller/cluster/raft/behaviors/Leader.java @@ -11,6 +11,7 @@ package org.opendaylight.controller.cluster.raft.behaviors; import akka.actor.ActorRef; import akka.actor.ActorSelection; import akka.actor.Cancellable; +import akka.event.LoggingAdapter; import com.google.common.base.Preconditions; import com.google.protobuf.ByteString; import org.opendaylight.controller.cluster.raft.ClientRequestTracker; @@ -80,9 +81,13 @@ public class Leader extends AbstractRaftActorBehavior { private final int minReplicationCount; + private final LoggingAdapter LOG; + public Leader(RaftActorContext context) { super(context); + LOG = context.getLogger(); + if (lastIndex() >= 0) { context.setCommitIndex(lastIndex()); } @@ -98,7 +103,9 @@ public class Leader extends AbstractRaftActorBehavior { followerToLog.put(followerId, followerLogInformation); } - context.getLogger().debug("Election:Leader has following peers:"+ followers); + if(LOG.isDebugEnabled()) { + LOG.debug("Election:Leader has following peers:" + followers); + } if (followers.size() > 0) { minReplicationCount = (followers.size() + 1) / 2 + 1; @@ -123,7 +130,9 @@ public class Leader extends AbstractRaftActorBehavior { @Override protected RaftState handleAppendEntries(ActorRef sender, AppendEntries appendEntries) { - context.getLogger().debug(appendEntries.toString()); + if(LOG.isDebugEnabled()) { + LOG.debug(appendEntries.toString()); + } return state(); } @@ -132,8 +141,9 @@ public class Leader extends AbstractRaftActorBehavior { AppendEntriesReply appendEntriesReply) { if(! appendEntriesReply.isSuccess()) { - context.getLogger() - .debug(appendEntriesReply.toString()); + if(LOG.isDebugEnabled()) { + LOG.debug(appendEntriesReply.toString()); + } } // Update the FollowerLogInformation @@ -142,7 +152,7 @@ public class Leader extends AbstractRaftActorBehavior { followerToLog.get(followerId); if(followerLogInformation == null){ - context.getLogger().error("Unknown follower {}", followerId); + LOG.error("Unknown follower {}", followerId); return state(); } @@ -196,6 +206,16 @@ public class Leader extends AbstractRaftActorBehavior { return state(); } + protected ClientRequestTracker removeClientRequestTracker(long logIndex) { + + ClientRequestTracker toRemove = findClientRequestTracker(logIndex); + if(toRemove != null) { + trackerList.remove(toRemove); + } + + return toRemove; + } + protected ClientRequestTracker findClientRequestTracker(long logIndex) { for (ClientRequestTracker tracker : trackerList) { if (tracker.getIndex() == logIndex) { @@ -260,10 +280,13 @@ public class Leader extends AbstractRaftActorBehavior { if (reply.isSuccess()) { if(followerToSnapshot.isLastChunk(reply.getChunkIndex())) { //this was the last chunk reply - context.getLogger().debug("InstallSnapshotReply received, " + - "last chunk received, Chunk:{}. Follower:{} Setting nextIndex:{}", - reply.getChunkIndex(), followerId, - context.getReplicatedLog().getSnapshotIndex() + 1); + if(LOG.isDebugEnabled()) { + LOG.debug("InstallSnapshotReply received, " + + "last chunk received, Chunk:{}. Follower:{} Setting nextIndex:{}", + reply.getChunkIndex(), followerId, + context.getReplicatedLog().getSnapshotIndex() + 1 + ); + } FollowerLogInformation followerLogInformation = followerToLog.get(followerId); @@ -272,31 +295,38 @@ public class Leader extends AbstractRaftActorBehavior { followerLogInformation.setNextIndex( context.getReplicatedLog().getSnapshotIndex() + 1); mapFollowerToSnapshot.remove(followerId); - context.getLogger().debug("followerToLog.get(followerId).getNextIndex().get()=" + - followerToLog.get(followerId).getNextIndex().get()); + + if(LOG.isDebugEnabled()) { + LOG.debug("followerToLog.get(followerId).getNextIndex().get()=" + + followerToLog.get(followerId).getNextIndex().get()); + } } else { followerToSnapshot.markSendStatus(true); } } else { - context.getLogger().info("InstallSnapshotReply received, " + - "sending snapshot chunk failed, Will retry, Chunk:{}", - reply.getChunkIndex()); + LOG.info("InstallSnapshotReply received, " + + "sending snapshot chunk failed, Will retry, Chunk:{}", + reply.getChunkIndex() + ); followerToSnapshot.markSendStatus(false); } } else { - context.getLogger().error("ERROR!!" + - "FollowerId in InstallSnapshotReply not known to Leader" + - " or Chunk Index in InstallSnapshotReply not matching {} != {}", - followerToSnapshot.getChunkIndex(), reply.getChunkIndex() ); + LOG.error("ERROR!!" + + "FollowerId in InstallSnapshotReply not known to Leader" + + " or Chunk Index in InstallSnapshotReply not matching {} != {}", + followerToSnapshot.getChunkIndex(), reply.getChunkIndex() + ); } } private void replicate(Replicate replicate) { long logIndex = replicate.getReplicatedLogEntry().getIndex(); - context.getLogger().debug("Replicate message " + logIndex); + if(LOG.isDebugEnabled()) { + LOG.debug("Replicate message " + logIndex); + } // Create a tracker entry we will use this later to notify the // client actor @@ -350,10 +380,13 @@ public class Leader extends AbstractRaftActorBehavior { if (followerNextIndex >= 0 && leaderLastIndex >= followerNextIndex ) { // if the follower is just not starting and leader's index // is more than followers index - context.getLogger().debug("SendInstallSnapshot to follower:{}," + - "follower-nextIndex:{}, leader-snapshot-index:{}, " + - "leader-last-index:{}", followerId, - followerNextIndex, leaderSnapShotIndex, leaderLastIndex); + if(LOG.isDebugEnabled()) { + LOG.debug("SendInstallSnapshot to follower:{}," + + "follower-nextIndex:{}, leader-snapshot-index:{}, " + + "leader-last-index:{}", followerId, + followerNextIndex, leaderSnapShotIndex, leaderLastIndex + ); + } actor().tell(new SendInstallSnapshot(), actor()); } else { @@ -412,11 +445,11 @@ public class Leader extends AbstractRaftActorBehavior { ).toSerializable(), actor() ); - context.getLogger().info("InstallSnapshot sent to follower {}, Chunk: {}/{}", + LOG.info("InstallSnapshot sent to follower {}, Chunk: {}/{}", followerActor.path(), mapFollowerToSnapshot.get(followerId).getChunkIndex(), mapFollowerToSnapshot.get(followerId).getTotalChunks()); } catch (IOException e) { - context.getLogger().error("InstallSnapshot failed for Leader.", e); + LOG.error("InstallSnapshot failed for Leader.", e); } } @@ -431,7 +464,9 @@ public class Leader extends AbstractRaftActorBehavior { mapFollowerToSnapshot.put(followerId, followerToSnapshot); } ByteString nextChunk = followerToSnapshot.getNextChunk(); - context.getLogger().debug("Leader's snapshot nextChunk size:{}", nextChunk.size()); + if(LOG.isDebugEnabled()) { + LOG.debug("Leader's snapshot nextChunk size:{}", nextChunk.size()); + } return nextChunk; } @@ -526,8 +561,10 @@ public class Leader extends AbstractRaftActorBehavior { int size = snapshotBytes.size(); totalChunks = ( size / context.getConfigParams().getSnapshotChunkSize()) + ((size % context.getConfigParams().getSnapshotChunkSize()) > 0 ? 1 : 0); - context.getLogger().debug("Snapshot {} bytes, total chunks to send:{}", - size, totalChunks); + if(LOG.isDebugEnabled()) { + LOG.debug("Snapshot {} bytes, total chunks to send:{}", + size, totalChunks); + } } public ByteString getSnapshotBytes() { @@ -591,8 +628,10 @@ public class Leader extends AbstractRaftActorBehavior { } } - context.getLogger().debug("length={}, offset={},size={}", - snapshotLength, start, size); + if(LOG.isDebugEnabled()) { + LOG.debug("length={}, offset={},size={}", + snapshotLength, start, size); + } return getSnapshotBytes().substring(start, start + size); } diff --git a/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/cluster/common/actor/AbstractUntypedActor.java b/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/cluster/common/actor/AbstractUntypedActor.java index ef56d02a2e..cf37cbdd00 100644 --- a/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/cluster/common/actor/AbstractUntypedActor.java +++ b/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/cluster/common/actor/AbstractUntypedActor.java @@ -17,7 +17,9 @@ public abstract class AbstractUntypedActor extends UntypedActor { Logging.getLogger(getContext().system(), this); public AbstractUntypedActor() { - LOG.debug("Actor created {}", getSelf()); + if(LOG.isDebugEnabled()) { + LOG.debug("Actor created {}", getSelf()); + } getContext(). system(). actorSelection("user/termination-monitor"). @@ -27,11 +29,13 @@ public abstract class AbstractUntypedActor extends UntypedActor { @Override public void onReceive(Object message) throws Exception { final String messageType = message.getClass().getSimpleName(); - LOG.debug("Received message {}", messageType); - + if(LOG.isDebugEnabled()) { + LOG.debug("Received message {}", messageType); + } handleReceive(message); - - LOG.debug("Done handling message {}", messageType); + if(LOG.isDebugEnabled()) { + LOG.debug("Done handling message {}", messageType); + } } protected abstract void handleReceive(Object message) throws Exception; @@ -41,7 +45,9 @@ public abstract class AbstractUntypedActor extends UntypedActor { } protected void unknownMessage(Object message) throws Exception { - LOG.debug("Received unhandled message {}", message); + if(LOG.isDebugEnabled()) { + LOG.debug("Received unhandled message {}", message); + } unhandled(message); } } diff --git a/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlStreamUtils.java b/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlStreamUtils.java index c9d5e89ae1..0f93f43c56 100644 --- a/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlStreamUtils.java +++ b/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlStreamUtils.java @@ -100,7 +100,9 @@ public class XmlStreamUtils { for (Entry e: prefixes.getPrefixes()) { writer.writeNamespace(e.getValue(), e.getKey().toString()); } - LOG.debug("Instance identifier with Random prefix is now {}", str); + if(LOG.isDebugEnabled()) { + LOG.debug("Instance identifier with Random prefix is now {}", str); + } writer.writeCharacters(str); } @@ -169,7 +171,7 @@ public class XmlStreamUtils { DataSchemaNode childSchema = null; if (schema instanceof DataNodeContainer) { childSchema = SchemaUtils.findFirstSchema(child.getNodeType(), ((DataNodeContainer) schema).getChildNodes()).orNull(); - if (childSchema == null) { + if (childSchema == null && LOG.isDebugEnabled()) { LOG.debug("Probably the data node \"{}\" does not conform to schema", child == null ? "" : child.getNodeType().getLocalName()); } } @@ -192,7 +194,9 @@ public class XmlStreamUtils { */ public void writeValue(final @Nonnull XMLStreamWriter writer, final @Nonnull TypeDefinition type, final Object value) throws XMLStreamException { if (value == null) { - LOG.debug("Value of {}:{} is null, not encoding it", type.getQName().getNamespace(), type.getQName().getLocalName()); + if(LOG.isDebugEnabled()){ + LOG.debug("Value of {}:{} is null, not encoding it", type.getQName().getNamespace(), type.getQName().getLocalName()); + } return; } @@ -232,18 +236,24 @@ public class XmlStreamUtils { writer.writeNamespace(prefix, qname.getNamespace().toString()); writer.writeCharacters(prefix + ':' + qname.getLocalName()); } else { - LOG.debug("Value of {}:{} is not a QName but {}", type.getQName().getNamespace(), type.getQName().getLocalName(), value.getClass()); + if(LOG.isDebugEnabled()) { + LOG.debug("Value of {}:{} is not a QName but {}", type.getQName().getNamespace(), type.getQName().getLocalName(), value.getClass()); + } writer.writeCharacters(String.valueOf(value)); } } private static void write(final @Nonnull XMLStreamWriter writer, final @Nonnull InstanceIdentifierTypeDefinition type, final @Nonnull Object value) throws XMLStreamException { if (value instanceof YangInstanceIdentifier) { - LOG.debug("Writing InstanceIdentifier object {}", value); + if(LOG.isDebugEnabled()) { + LOG.debug("Writing InstanceIdentifier object {}", value); + } write(writer, (YangInstanceIdentifier)value); } else { - LOG.debug("Value of {}:{} is not an InstanceIdentifier but {}", type.getQName().getNamespace(), type.getQName().getLocalName(), value.getClass()); - writer.writeCharacters(String.valueOf(value)); + if(LOG.isDebugEnabled()) { + LOG.debug("Value of {}:{} is not an InstanceIdentifier but {}", type.getQName().getNamespace(), type.getQName().getLocalName(), value.getClass()); + } + writer.writeCharacters(String.valueOf(value)); } } } diff --git a/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlUtils.java b/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlUtils.java index ea8f4a3ef1..d0cc2adb5f 100644 --- a/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlUtils.java +++ b/opendaylight/md-sal/sal-clustering-commons/src/main/java/org/opendaylight/controller/xml/codec/XmlUtils.java @@ -74,7 +74,9 @@ public class XmlUtils { * @return xml String */ public static String inputCompositeNodeToXml(CompositeNode cNode, SchemaContext schemaContext){ - LOG.debug("Converting input composite node to xml {}", cNode); + if(LOG.isDebugEnabled()) { + LOG.debug("Converting input composite node to xml {}", cNode); + } if (cNode == null) { return BLANK; } @@ -88,12 +90,14 @@ public class XmlUtils { Set rpcs = schemaContext.getOperations(); for(RpcDefinition rpc : rpcs) { if(rpc.getQName().equals(cNode.getNodeType())){ - LOG.debug("Found the rpc definition from schema context matching with input composite node {}", rpc.getQName()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Found the rpc definition from schema context matching with input composite node {}", rpc.getQName()); + } CompositeNode inputContainer = cNode.getFirstCompositeByName(QName.create(cNode.getNodeType(), "input")); domTree = XmlDocumentUtils.toDocument(inputContainer, rpc.getInput(), XmlDocumentUtils.defaultValueCodecProvider()); - - LOG.debug("input composite node to document conversion complete, document is {}", domTree); + if(LOG.isDebugEnabled()) { + LOG.debug("input composite node to document conversion complete, document is {}", domTree); + } break; } } @@ -111,7 +115,9 @@ public class XmlUtils { * @return xml string */ public static String outputCompositeNodeToXml(CompositeNode cNode, SchemaContext schemaContext){ - LOG.debug("Converting output composite node to xml {}", cNode); + if(LOG.isDebugEnabled()) { + LOG.debug("Converting output composite node to xml {}", cNode); + } if (cNode == null) { return BLANK; } @@ -125,12 +131,14 @@ public class XmlUtils { Set rpcs = schemaContext.getOperations(); for(RpcDefinition rpc : rpcs) { if(rpc.getQName().equals(cNode.getNodeType())){ - LOG.debug("Found the rpc definition from schema context matching with output composite node {}", rpc.getQName()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Found the rpc definition from schema context matching with output composite node {}", rpc.getQName()); + } CompositeNode outputContainer = cNode.getFirstCompositeByName(QName.create(cNode.getNodeType(), "output")); domTree = XmlDocumentUtils.toDocument(outputContainer, rpc.getOutput(), XmlDocumentUtils.defaultValueCodecProvider()); - - LOG.debug("output composite node to document conversion complete, document is {}", domTree); + if(LOG.isDebugEnabled()) { + LOG.debug("output composite node to document conversion complete, document is {}", domTree); + } break; } } @@ -152,8 +160,9 @@ public class XmlUtils { LOG.error("Error during translation of Document to OutputStream", e); } - LOG.debug("Document to string conversion complete, xml string is {} ", writer.toString()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Document to string conversion complete, xml string is {} ", writer.toString()); + } return writer.toString(); } @@ -188,7 +197,9 @@ public class XmlUtils { * @return CompositeNode object based on the input, if any of the input parameter is null, a null object is returned */ public static CompositeNode inputXmlToCompositeNode(QName rpc, String xml, SchemaContext schemaContext){ - LOG.debug("Converting input xml to composite node {}", xml); + if(LOG.isDebugEnabled()) { + LOG.debug("Converting input xml to composite node {}", xml); + } if (xml==null || xml.length()==0) { return null; } @@ -208,8 +219,9 @@ public class XmlUtils { Set rpcs = schemaContext.getOperations(); for(RpcDefinition rpcDef : rpcs) { if(rpcDef.getQName().equals(rpc)){ - LOG.debug("found the rpc definition from schema context matching rpc {}", rpc); - + if(LOG.isDebugEnabled()) { + LOG.debug("found the rpc definition from schema context matching rpc {}", rpc); + } if(rpcDef.getInput() == null) { LOG.warn("found rpc definition's input is null"); return null; @@ -225,9 +237,9 @@ public class XmlUtils { List> dataNodes = XmlDocumentUtils.toDomNodes(xmlData, Optional.of(rpcDef.getInput().getChildNodes()), schemaContext); - - LOG.debug("Converted xml input to list of nodes {}", dataNodes); - + if(LOG.isDebugEnabled()) { + LOG.debug("Converted xml input to list of nodes {}", dataNodes); + } final CompositeNodeBuilder it = ImmutableCompositeNode.builder(); it.setQName(rpc); it.add(ImmutableCompositeNode.create(input, dataNodes)); @@ -240,8 +252,9 @@ public class XmlUtils { } catch (IOException e) { LOG.error("Error during building data tree from XML", e); } - - LOG.debug("Xml to composite node conversion complete {} ", compositeNode); + if(LOG.isDebugEnabled()) { + LOG.debug("Xml to composite node conversion complete {} ", compositeNode); + } return compositeNode; } diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DistributedDataStore.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DistributedDataStore.java index bf541d95de..c780881a2f 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DistributedDataStore.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/DistributedDataStore.java @@ -76,9 +76,9 @@ public class DistributedDataStore implements DOMStore, SchemaContextListener, Au Preconditions.checkNotNull(path, "path should not be null"); Preconditions.checkNotNull(listener, "listener should not be null"); - - LOG.debug("Registering listener: {} for path: {} scope: {}", listener, path, scope); - + if(LOG.isDebugEnabled()) { + LOG.debug("Registering listener: {} for path: {} scope: {}", listener, path, scope); + } ActorRef dataChangeListenerActor = actorContext.getActorSystem().actorOf( DataChangeListener.props(listener )); @@ -108,11 +108,11 @@ public class DistributedDataStore implements DOMStore, SchemaContextListener, Au }, actorContext.getActorSystem().dispatcher()); return listenerRegistrationProxy; } - - LOG.debug( - "No local shard for shardName {} was found so returning a noop registration", - shardName); - + if(LOG.isDebugEnabled()) { + LOG.debug( + "No local shard for shardName {} was found so returning a noop registration", + shardName); + } return new NoOpDataChangeListenerRegistration(listener); } diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/Shard.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/Shard.java index f3f8b8b193..0fa27706e1 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/Shard.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/Shard.java @@ -35,7 +35,6 @@ import org.opendaylight.controller.cluster.datastore.jmx.mbeans.shard.ShardStats import org.opendaylight.controller.cluster.datastore.messages.CloseTransactionChain; import org.opendaylight.controller.cluster.datastore.messages.CommitTransactionReply; import org.opendaylight.controller.cluster.datastore.messages.CreateTransaction; -import org.opendaylight.controller.cluster.datastore.messages.CreateTransactionChainReply; import org.opendaylight.controller.cluster.datastore.messages.CreateTransactionReply; import org.opendaylight.controller.cluster.datastore.messages.EnableNotification; import org.opendaylight.controller.cluster.datastore.messages.ForwardedCommitTransaction; @@ -172,8 +171,11 @@ public class Shard extends RaftActor { } @Override public void onReceiveRecover(Object message) { - LOG.debug("onReceiveRecover: Received message {} from {}", message.getClass().toString(), - getSender()); + if(LOG.isDebugEnabled()) { + LOG.debug("onReceiveRecover: Received message {} from {}", + message.getClass().toString(), + getSender()); + } if (message instanceof RecoveryFailure){ LOG.error(((RecoveryFailure) message).cause(), "Recovery failed because of this cause"); @@ -183,8 +185,11 @@ public class Shard extends RaftActor { } @Override public void onReceiveCommand(Object message) { - LOG.debug("onReceiveCommand: Received message {} from {}", message.getClass().toString(), - getSender()); + if(LOG.isDebugEnabled()) { + LOG.debug("onReceiveCommand: Received message {} from {}", + message.getClass().toString(), + getSender()); + } if(message.getClass().equals(ReadDataReply.SERIALIZABLE_CLASS)) { // This must be for install snapshot. Don't want to open this up and trigger @@ -299,7 +304,9 @@ public class Shard extends RaftActor { ShardTransactionIdentifier.builder() .remoteTransactionId(remoteTransactionId) .build(); - LOG.debug("Creating transaction : {} ", transactionId); + if(LOG.isDebugEnabled()) { + LOG.debug("Creating transaction : {} ", transactionId); + } ActorRef transactionActor = createTypedTransactionActor(transactionType, transactionId, transactionChainId); @@ -326,13 +333,19 @@ public class Shard extends RaftActor { DOMStoreThreePhaseCommitCohort cohort = modificationToCohort.remove(serialized); if (cohort == null) { - LOG.debug( - "Could not find cohort for modification : {}. Writing modification using a new transaction", - modification); + + if(LOG.isDebugEnabled()) { + LOG.debug( + "Could not find cohort for modification : {}. Writing modification using a new transaction", + modification); + } + DOMStoreWriteTransaction transaction = store.newWriteOnlyTransaction(); - LOG.debug("Created new transaction {}", transaction.getIdentifier().toString()); + if(LOG.isDebugEnabled()) { + LOG.debug("Created new transaction {}", transaction.getIdentifier().toString()); + } modification.apply(transaction); try { @@ -353,13 +366,12 @@ public class Shard extends RaftActor { return; } - final ListenableFuture future = cohort.commit(); - final ActorRef self = getSelf(); + ListenableFuture future = cohort.commit(); Futures.addCallback(future, new FutureCallback() { @Override public void onSuccess(Void v) { - sender.tell(new CommitTransactionReply().toSerializable(), self); + sender.tell(new CommitTransactionReply().toSerializable(), getSelf()); shardMBean.incrementCommittedTransactionCount(); shardMBean.setLastCommittedTransactionTime(System.currentTimeMillis()); } @@ -368,7 +380,7 @@ public class Shard extends RaftActor { public void onFailure(Throwable t) { LOG.error(t, "An exception happened during commit"); shardMBean.incrementFailedTransactionsCount(); - sender.tell(new akka.actor.Status.Failure(t), self); + sender.tell(new akka.actor.Status.Failure(t), getSelf()); } }); @@ -402,8 +414,10 @@ public class Shard extends RaftActor { private void registerChangeListener( RegisterChangeListener registerChangeListener) { - LOG.debug("registerDataChangeListener for {}", registerChangeListener - .getPath()); + if(LOG.isDebugEnabled()) { + LOG.debug("registerDataChangeListener for {}", registerChangeListener + .getPath()); + } ActorSelection dataChangeListenerPath = getContext() @@ -431,23 +445,17 @@ public class Shard extends RaftActor { getContext().actorOf( DataChangeListenerRegistration.props(registration)); - LOG.debug( - "registerDataChangeListener sending reply, listenerRegistrationPath = {} " - , listenerRegistration.path().toString()); + if(LOG.isDebugEnabled()) { + LOG.debug( + "registerDataChangeListener sending reply, listenerRegistrationPath = {} " + , listenerRegistration.path().toString()); + } getSender() .tell(new RegisterChangeListenerReply(listenerRegistration.path()), getSelf()); } - private void createTransactionChain() { - DOMStoreTransactionChain chain = store.createTransactionChain(); - ActorRef transactionChain = getContext().actorOf( - ShardTransactionChain.props(chain, schemaContext, datastoreContext, shardMBean)); - getSender().tell(new CreateTransactionChainReply(transactionChain.path()).toSerializable(), - getSelf()); - } - private boolean isMetricsCaptureEnabled(){ CommonConfig config = new CommonConfig(getContext().system().settings().config()); return config.isMetricCaptureEnabled(); @@ -531,14 +539,17 @@ public class Shard extends RaftActor { .tell(new EnableNotification(isLeader()), getSelf()); } - shardMBean.setRaftState(getRaftState().name()); shardMBean.setCurrentTerm(getCurrentTerm()); // If this actor is no longer the leader close all the transaction chains if(!isLeader()){ for(Map.Entry entry : transactionChains.entrySet()){ - LOG.debug("onStateChanged: Closing transaction chain {} because shard {} is no longer the leader", entry.getKey(), getId()); + if(LOG.isDebugEnabled()) { + LOG.debug( + "onStateChanged: Closing transaction chain {} because shard {} is no longer the leader", + entry.getKey(), getId()); + } entry.getValue().close(); } diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardManager.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardManager.java index 13ecaa5619..a97c00f1d8 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardManager.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardManager.java @@ -337,11 +337,11 @@ public class ShardManager extends AbstractUntypedActorWithMetering { peerAddress); if(peerAddresses.containsKey(peerId)){ peerAddresses.put(peerId, peerAddress); - - LOG.debug( - "Sending PeerAddressResolved for peer {} with address {} to {}", - peerId, peerAddress, actor.path()); - + if(LOG.isDebugEnabled()) { + LOG.debug( + "Sending PeerAddressResolved for peer {} with address {} to {}", + peerId, peerAddress, actor.path()); + } actor .tell(new PeerAddressResolved(peerId, peerAddress), getSelf()); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardTransaction.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardTransaction.java index b810ed9575..f5ca6e3c5a 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardTransaction.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ShardTransaction.java @@ -105,7 +105,9 @@ public abstract class ShardTransaction extends AbstractUntypedActor { getSender().tell(new GetCompositeModificationReply( new ImmutableCompositeModification(modification)), getSelf()); } else if (message instanceof ReceiveTimeout) { - LOG.debug("Got ReceiveTimeout for inactivity - closing Tx"); + if(LOG.isDebugEnabled()) { + LOG.debug("Got ReceiveTimeout for inactivity - closing Tx"); + } closeTransaction(false); } else { throw new UnknownMessageException(message); @@ -163,8 +165,9 @@ public abstract class ShardTransaction extends AbstractUntypedActor { protected void writeData(DOMStoreWriteTransaction transaction, WriteData message) { modification.addModification( new WriteModification(message.getPath(), message.getData(),schemaContext)); - LOG.debug("writeData at path : " + message.getPath().toString()); - + if(LOG.isDebugEnabled()) { + LOG.debug("writeData at path : " + message.getPath().toString()); + } try { transaction.write(message.getPath(), message.getData()); getSender().tell(new WriteDataReply().toSerializable(), getSelf()); @@ -176,7 +179,9 @@ public abstract class ShardTransaction extends AbstractUntypedActor { protected void mergeData(DOMStoreWriteTransaction transaction, MergeData message) { modification.addModification( new MergeModification(message.getPath(), message.getData(), schemaContext)); - LOG.debug("mergeData at path : " + message.getPath().toString()); + if(LOG.isDebugEnabled()) { + LOG.debug("mergeData at path : " + message.getPath().toString()); + } try { transaction.merge(message.getPath(), message.getData()); getSender().tell(new MergeDataReply().toSerializable(), getSelf()); @@ -186,7 +191,9 @@ public abstract class ShardTransaction extends AbstractUntypedActor { } protected void deleteData(DOMStoreWriteTransaction transaction, DeleteData message) { - LOG.debug("deleteData at path : " + message.getPath().toString()); + if(LOG.isDebugEnabled()) { + LOG.debug("deleteData at path : " + message.getPath().toString()); + } modification.addModification(new DeleteModification(message.getPath())); try { transaction.delete(message.getPath()); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TerminationMonitor.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TerminationMonitor.java index e6ac7f8dbc..0c3d33a78c 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TerminationMonitor.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TerminationMonitor.java @@ -25,7 +25,9 @@ public class TerminationMonitor extends UntypedActor{ @Override public void onReceive(Object message) throws Exception { if(message instanceof Terminated){ Terminated terminated = (Terminated) message; - LOG.debug("Actor terminated : {}", terminated.actor()); + if(LOG.isDebugEnabled()) { + LOG.debug("Actor terminated : {}", terminated.actor()); + } } else if(message instanceof Monitor){ Monitor monitor = (Monitor) message; getContext().watch(monitor.getActorRef()); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohort.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohort.java index e3ae5dac7b..df85bb136a 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohort.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohort.java @@ -101,7 +101,9 @@ public class ThreePhaseCommitCohort extends AbstractUntypedActor { private void commit(CommitTransaction message) { // Forward the commit to the shard - log.debug("Forward commit transaction to Shard {} ", shardActor); + if(log.isDebugEnabled()) { + log.debug("Forward commit transaction to Shard {} ", shardActor); + } shardActor.forward(new ForwardedCommitTransaction(cohort, modification), getContext()); diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohortProxy.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohortProxy.java index a5be69531d..a7a5b31b17 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohortProxy.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/ThreePhaseCommitCohortProxy.java @@ -65,9 +65,10 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho @Override public Void apply(Iterable paths) { cohortPaths = Lists.newArrayList(paths); - - LOG.debug("Tx {} successfully built cohort path list: {}", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} successfully built cohort path list: {}", transactionId, cohortPaths); + } return null; } }, TransactionProxy.SAME_FAILURE_TRANSFORMER, actorContext.getActorSystem().dispatcher()); @@ -75,8 +76,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho @Override public ListenableFuture canCommit() { - LOG.debug("Tx {} canCommit", transactionId); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} canCommit", transactionId); + } final SettableFuture returnFuture = SettableFuture.create(); // The first phase of canCommit is to gather the list of cohort actor paths that will @@ -89,7 +91,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho @Override public void onComplete(Throwable failure, Void notUsed) throws Throwable { if(failure != null) { - LOG.debug("Tx {}: a cohort path Future failed: {}", transactionId, failure); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {}: a cohort path Future failed: {}", transactionId, failure); + } returnFuture.setException(failure); } else { finishCanCommit(returnFuture); @@ -101,9 +105,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho } private void finishCanCommit(final SettableFuture returnFuture) { - - LOG.debug("Tx {} finishCanCommit", transactionId); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} finishCanCommit", transactionId); + } // The last phase of canCommit is to invoke all the cohort actors asynchronously to perform // their canCommit processing. If any one fails then we'll fail canCommit. @@ -114,7 +118,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho @Override public void onComplete(Throwable failure, Iterable responses) throws Throwable { if(failure != null) { - LOG.debug("Tx {}: a canCommit cohort Future failed: {}", transactionId, failure); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {}: a canCommit cohort Future failed: {}", transactionId, failure); + } returnFuture.setException(failure); return; } @@ -135,9 +141,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho return; } } - - LOG.debug("Tx {}: canCommit returning result: {}", transactionId, result); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {}: canCommit returning result: {}", transactionId, result); + } returnFuture.set(Boolean.valueOf(result)); } }, actorContext.getActorSystem().dispatcher()); @@ -146,9 +152,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho private Future> invokeCohorts(Object message) { List> futureList = Lists.newArrayListWithCapacity(cohortPaths.size()); for(ActorPath actorPath : cohortPaths) { - - LOG.debug("Tx {}: Sending {} to cohort {}", transactionId, message, actorPath); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {}: Sending {} to cohort {}", transactionId, message, actorPath); + } ActorSelection cohort = actorContext.actorSelection(actorPath); futureList.add(actorContext.executeRemoteOperationAsync(cohort, message)); @@ -184,8 +190,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho private ListenableFuture voidOperation(final String operationName, final Object message, final Class expectedResponseClass, final boolean propagateException) { - LOG.debug("Tx {} {}", transactionId, operationName); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} {}", transactionId, operationName); + } final SettableFuture returnFuture = SettableFuture.create(); // The cohort actor list should already be built at this point by the canCommit phase but, @@ -199,9 +206,10 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho @Override public void onComplete(Throwable failure, Void notUsed) throws Throwable { if(failure != null) { - LOG.debug("Tx {}: a {} cohort path Future failed: {}", transactionId, + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {}: a {} cohort path Future failed: {}", transactionId, operationName, failure); - + } if(propagateException) { returnFuture.setException(failure); } else { @@ -221,9 +229,9 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho private void finishVoidOperation(final String operationName, final Object message, final Class expectedResponseClass, final boolean propagateException, final SettableFuture returnFuture) { - - LOG.debug("Tx {} finish {}", transactionId, operationName); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} finish {}", transactionId, operationName); + } Future> combinedFuture = invokeCohorts(message); combinedFuture.onComplete(new OnComplete>() { @@ -243,9 +251,10 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho } if(exceptionToPropagate != null) { - LOG.debug("Tx {}: a {} cohort Future failed: {}", transactionId, + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {}: a {} cohort Future failed: {}", transactionId, operationName, exceptionToPropagate); - + } if(propagateException) { // We don't log the exception here to avoid redundant logging since we're // propagating to the caller in MD-SAL core who will log it. @@ -254,12 +263,16 @@ public class ThreePhaseCommitCohortProxy implements DOMStoreThreePhaseCommitCoho // Since the caller doesn't want us to propagate the exception we'll also // not log it normally. But it's usually not good to totally silence // exceptions so we'll log it to debug level. - LOG.debug(String.format("%s failed", message.getClass().getSimpleName()), + if(LOG.isDebugEnabled()) { + LOG.debug(String.format("%s failed", message.getClass().getSimpleName()), exceptionToPropagate); + } returnFuture.set(null); } } else { - LOG.debug("Tx {}: {} succeeded", transactionId, operationName); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {}: {} succeeded", transactionId, operationName); + } returnFuture.set(null); } } diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java index 97a9ff0bf3..6cf16b4426 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/TransactionProxy.java @@ -224,8 +224,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { new TransactionProxyCleanupPhantomReference(this); phantomReferenceCache.put(cleanup, cleanup); } - - LOG.debug("Created txn {} of type {}", identifier, transactionType); + if(LOG.isDebugEnabled()) { + LOG.debug("Created txn {} of type {}", identifier, transactionType); + } } @Override @@ -235,8 +236,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { Preconditions.checkState(transactionType != TransactionType.WRITE_ONLY, "Read operation on write-only transaction is not allowed"); - LOG.debug("Tx {} read {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} read {}", identifier, path); + } createTransactionIfMissing(actorContext, path); return transactionContext(path).readData(path); @@ -248,8 +250,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { Preconditions.checkState(transactionType != TransactionType.WRITE_ONLY, "Exists operation on write-only transaction is not allowed"); - LOG.debug("Tx {} exists {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} exists {}", identifier, path); + } createTransactionIfMissing(actorContext, path); return transactionContext(path).dataExists(path); @@ -267,8 +270,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { checkModificationState(); - LOG.debug("Tx {} write {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} write {}", identifier, path); + } createTransactionIfMissing(actorContext, path); transactionContext(path).writeData(path, data); @@ -279,8 +283,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { checkModificationState(); - LOG.debug("Tx {} merge {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} merge {}", identifier, path); + } createTransactionIfMissing(actorContext, path); transactionContext(path).mergeData(path, data); @@ -290,9 +295,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { public void delete(YangInstanceIdentifier path) { checkModificationState(); - - LOG.debug("Tx {} delete {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} delete {}", identifier, path); + } createTransactionIfMissing(actorContext, path); transactionContext(path).deleteData(path); @@ -305,16 +310,18 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { inReadyState = true; - LOG.debug("Tx {} Trying to get {} transactions ready for commit", identifier, + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} Trying to get {} transactions ready for commit", identifier, remoteTransactionPaths.size()); - + } List> cohortPathFutures = Lists.newArrayList(); for(TransactionContext transactionContext : remoteTransactionPaths.values()) { - LOG.debug("Tx {} Readying transaction for shard {}", identifier, + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} Readying transaction for shard {}", identifier, transactionContext.getShardName()); - + } cohortPathFutures.add(transactionContext.readyTransaction()); } @@ -381,8 +388,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { String transactionPath = reply.getTransactionPath(); - LOG.debug("Tx {} Received transaction path = {}", identifier, transactionPath); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} Received transaction path = {}", identifier, transactionPath); + } ActorSelection transactionActor = actorContext.actorSelection(transactionPath); if (transactionType == TransactionType.READ_ONLY) { @@ -404,7 +412,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { "Invalid reply type {} for CreateTransaction", response.getClass())); } } catch (Exception e) { - LOG.debug("Tx {} Creating NoOpTransaction because of : {}", identifier, e.getMessage()); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} Creating NoOpTransaction because of : {}", identifier, e.getMessage()); + } remoteTransactionPaths .put(shardName, new NoOpTransactionContext(shardName, e, identifier)); } @@ -489,15 +499,18 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { @Override public void closeTransaction() { - LOG.debug("Tx {} closeTransaction called", identifier); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} closeTransaction called", identifier); + } actorContext.sendRemoteOperationAsync(getActor(), new CloseTransaction().toSerializable()); } @Override public Future readyTransaction() { - LOG.debug("Tx {} readyTransaction called with {} previous recorded operations pending", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readyTransaction called with {} previous recorded operations pending", identifier, recordedOperationFutures.size()); - + } // Send the ReadyTransaction message to the Tx actor. final Future replyFuture = actorContext.executeRemoteOperationAsync(getActor(), @@ -522,10 +535,10 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { return combinedFutures.transform(new AbstractFunction1, ActorPath>() { @Override public ActorPath apply(Iterable notUsed) { - - LOG.debug("Tx {} readyTransaction: pending recorded operations succeeded", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readyTransaction: pending recorded operations succeeded", identifier); - + } // At this point all the Futures succeeded and we need to extract the cohort // actor path from the ReadyTransactionReply. For the recorded operations, they // don't return any data so we're only interested that they completed @@ -543,9 +556,10 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { String resolvedCohortPath = getResolvedCohortPath( reply.getCohortPath().toString()); - LOG.debug("Tx {} readyTransaction: resolved cohort path {}", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readyTransaction: resolved cohort path {}", identifier, resolvedCohortPath); - + } return actorContext.actorFor(resolvedCohortPath); } else { // Throwing an exception here will fail the Future. @@ -559,21 +573,27 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { @Override public void deleteData(YangInstanceIdentifier path) { - LOG.debug("Tx {} deleteData called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} deleteData called path = {}", identifier, path); + } recordedOperationFutures.add(actorContext.executeRemoteOperationAsync(getActor(), new DeleteData(path).toSerializable() )); } @Override public void mergeData(YangInstanceIdentifier path, NormalizedNode data) { - LOG.debug("Tx {} mergeData called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} mergeData called path = {}", identifier, path); + } recordedOperationFutures.add(actorContext.executeRemoteOperationAsync(getActor(), new MergeData(path, data, schemaContext).toSerializable())); } @Override public void writeData(YangInstanceIdentifier path, NormalizedNode data) { - LOG.debug("Tx {} writeData called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} writeData called path = {}", identifier, path); + } recordedOperationFutures.add(actorContext.executeRemoteOperationAsync(getActor(), new WriteData(path, data, schemaContext).toSerializable())); } @@ -582,8 +602,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { public CheckedFuture>, ReadFailedException> readData( final YangInstanceIdentifier path) { - LOG.debug("Tx {} readData called path = {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readData called path = {}", identifier, path); + } final SettableFuture>> returnFuture = SettableFuture.create(); // If there were any previous recorded put/merge/delete operation reply Futures then we @@ -593,9 +614,10 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { if(recordedOperationFutures.isEmpty()) { finishReadData(path, returnFuture); } else { - LOG.debug("Tx {} readData: verifying {} previous recorded operations", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readData: verifying {} previous recorded operations", identifier, recordedOperationFutures.size()); - + } // Note: we make a copy of recordedOperationFutures to be on the safe side in case // Futures#sequence accesses the passed List on a different thread, as // recordedOperationFutures is not synchronized. @@ -608,9 +630,10 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { public void onComplete(Throwable failure, Iterable notUsed) throws Throwable { if(failure != null) { - LOG.debug("Tx {} readData: a recorded operation failed: {}", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readData: a recorded operation failed: {}", identifier, failure); - + } returnFuture.setException(new ReadFailedException( "The read could not be performed because a previous put, merge," + "or delete operation failed", failure)); @@ -629,20 +652,23 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { private void finishReadData(final YangInstanceIdentifier path, final SettableFuture>> returnFuture) { - LOG.debug("Tx {} finishReadData called path = {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} finishReadData called path = {}", identifier, path); + } OnComplete onComplete = new OnComplete() { @Override public void onComplete(Throwable failure, Object readResponse) throws Throwable { if(failure != null) { - LOG.debug("Tx {} read operation failed: {}", identifier, failure); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} read operation failed: {}", identifier, failure); + } returnFuture.setException(new ReadFailedException( "Error reading data for path " + path, failure)); } else { - LOG.debug("Tx {} read operation succeeded", identifier, failure); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} read operation succeeded", identifier, failure); + } if (readResponse.getClass().equals(ReadDataReply.SERIALIZABLE_CLASS)) { ReadDataReply reply = ReadDataReply.fromSerializable(schemaContext, path, readResponse); @@ -669,8 +695,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { public CheckedFuture dataExists( final YangInstanceIdentifier path) { - LOG.debug("Tx {} dataExists called path = {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} dataExists called path = {}", identifier, path); + } final SettableFuture returnFuture = SettableFuture.create(); // If there were any previous recorded put/merge/delete operation reply Futures then we @@ -681,9 +708,10 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { if(recordedOperationFutures.isEmpty()) { finishDataExists(path, returnFuture); } else { - LOG.debug("Tx {} dataExists: verifying {} previous recorded operations", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} dataExists: verifying {} previous recorded operations", identifier, recordedOperationFutures.size()); - + } // Note: we make a copy of recordedOperationFutures to be on the safe side in case // Futures#sequence accesses the passed List on a different thread, as // recordedOperationFutures is not synchronized. @@ -696,9 +724,10 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { public void onComplete(Throwable failure, Iterable notUsed) throws Throwable { if(failure != null) { - LOG.debug("Tx {} dataExists: a recorded operation failed: {}", + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} dataExists: a recorded operation failed: {}", identifier, failure); - + } returnFuture.setException(new ReadFailedException( "The data exists could not be performed because a previous " + "put, merge, or delete operation failed", failure)); @@ -717,19 +746,22 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { private void finishDataExists(final YangInstanceIdentifier path, final SettableFuture returnFuture) { - LOG.debug("Tx {} finishDataExists called path = {}", identifier, path); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} finishDataExists called path = {}", identifier, path); + } OnComplete onComplete = new OnComplete() { @Override public void onComplete(Throwable failure, Object response) throws Throwable { if(failure != null) { - LOG.debug("Tx {} dataExists operation failed: {}", identifier, failure); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} dataExists operation failed: {}", identifier, failure); + } returnFuture.setException(new ReadFailedException( "Error checking data exists for path " + path, failure)); } else { - LOG.debug("Tx {} dataExists operation succeeded", identifier, failure); - + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} dataExists operation succeeded", identifier, failure); + } if (response.getClass().equals(DataExistsReply.SERIALIZABLE_CLASS)) { returnFuture.set(Boolean.valueOf(DataExistsReply. fromSerializable(response).exists())); @@ -761,34 +793,46 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { @Override public void closeTransaction() { - LOG.debug("NoOpTransactionContext {} closeTransaction called", identifier); + if(LOG.isDebugEnabled()) { + LOG.debug("NoOpTransactionContext {} closeTransaction called", identifier); + } } @Override public Future readyTransaction() { - LOG.debug("Tx {} readyTransaction called", identifier); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readyTransaction called", identifier); + } return akka.dispatch.Futures.failed(failure); } @Override public void deleteData(YangInstanceIdentifier path) { - LOG.debug("Tx {} deleteData called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} deleteData called path = {}", identifier, path); + } } @Override public void mergeData(YangInstanceIdentifier path, NormalizedNode data) { - LOG.debug("Tx {} mergeData called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} mergeData called path = {}", identifier, path); + } } @Override public void writeData(YangInstanceIdentifier path, NormalizedNode data) { - LOG.debug("Tx {} writeData called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} writeData called path = {}", identifier, path); + } } @Override public CheckedFuture>, ReadFailedException> readData( YangInstanceIdentifier path) { - LOG.debug("Tx {} readData called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} readData called path = {}", identifier, path); + } return Futures.immediateFailedCheckedFuture(new ReadFailedException( "Error reading data for path " + path, failure)); } @@ -796,7 +840,9 @@ public class TransactionProxy implements DOMStoreReadWriteTransaction { @Override public CheckedFuture dataExists( YangInstanceIdentifier path) { - LOG.debug("Tx {} dataExists called path = {}", identifier, path); + if(LOG.isDebugEnabled()) { + LOG.debug("Tx {} dataExists called path = {}", identifier, path); + } return Futures.immediateFailedCheckedFuture(new ReadFailedException( "Error checking exists for path " + path, failure)); } diff --git a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/utils/ActorContext.java b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/utils/ActorContext.java index 7b5588cb19..8ba333d279 100644 --- a/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/utils/ActorContext.java +++ b/opendaylight/md-sal/sal-distributed-datastore/src/main/java/org/opendaylight/controller/cluster/datastore/utils/ActorContext.java @@ -125,8 +125,9 @@ public class ActorContext { if (result instanceof LocalShardFound) { LocalShardFound found = (LocalShardFound) result; - LOG.debug("Local shard found {}", found.getPath()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Local shard found {}", found.getPath()); + } return found.getPath(); } @@ -141,8 +142,9 @@ public class ActorContext { if (result.getClass().equals(PrimaryFound.SERIALIZABLE_CLASS)) { PrimaryFound found = PrimaryFound.fromSerializable(result); - LOG.debug("Primary found {}", found.getPrimaryPath()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Primary found {}", found.getPrimaryPath()); + } return found.getPrimaryPath(); } throw new PrimaryNotFoundException("Could not find primary for shardName " + shardName); @@ -175,9 +177,10 @@ public class ActorContext { */ public Object executeRemoteOperation(ActorSelection actor, Object message) { - LOG.debug("Sending remote message {} to {}", message.getClass().toString(), - actor.toString()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Sending remote message {} to {}", message.getClass().toString(), + actor.toString()); + } Future future = ask(actor, message, operationTimeout); try { @@ -197,8 +200,9 @@ public class ActorContext { */ public Future executeRemoteOperationAsync(ActorSelection actor, Object message) { - LOG.debug("Sending remote message {} to {}", message.getClass().toString(), actor.toString()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Sending remote message {} to {}", message.getClass().toString(), actor.toString()); + } return ask(actor, message, operationTimeout); } diff --git a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RemoteRpcProviderFactory.java b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RemoteRpcProviderFactory.java index 2e355d4f51..c82a72eaa5 100644 --- a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RemoteRpcProviderFactory.java +++ b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RemoteRpcProviderFactory.java @@ -38,8 +38,9 @@ public class RemoteRpcProviderFactory { Thread.currentThread().getContextClassLoader()); Config actorSystemConfig = config.get(); - LOG.debug("Actor system configuration\n{}", actorSystemConfig.root().render()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Actor system configuration\n{}", actorSystemConfig.root().render()); + } if (config.isMetricCaptureEnabled()) { LOG.info("Instrumentation is enabled in actor system {}. Metrics can be viewed in JMX console.", config.getActorSystemName()); diff --git a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RoutedRpcListener.java b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RoutedRpcListener.java index 98cf6a329f..2aaac5a78e 100644 --- a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RoutedRpcListener.java +++ b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RoutedRpcListener.java @@ -53,7 +53,9 @@ public class RoutedRpcListener implements RouteChangeListener> announcements) { - LOG.debug("Announcing [{}]", announcements); + if(LOG.isDebugEnabled()) { + LOG.debug("Announcing [{}]", announcements); + } RpcRegistry.Messages.AddOrUpdateRoutes addRpcMsg = new RpcRegistry.Messages.AddOrUpdateRoutes(new ArrayList<>(announcements)); rpcRegistry.tell(addRpcMsg, ActorRef.noSender()); } @@ -63,7 +65,9 @@ public class RoutedRpcListener implements RouteChangeListener> removals){ - LOG.debug("Removing [{}]", removals); + if(LOG.isDebugEnabled()) { + LOG.debug("Removing [{}]", removals); + } RpcRegistry.Messages.RemoveRoutes removeRpcMsg = new RpcRegistry.Messages.RemoveRoutes(new ArrayList<>(removals)); rpcRegistry.tell(removeRpcMsg, ActorRef.noSender()); } diff --git a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcBroker.java b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcBroker.java index 6b02235dc7..2046e419d9 100644 --- a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcBroker.java +++ b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcBroker.java @@ -79,8 +79,9 @@ public class RpcBroker extends AbstractUntypedActor { } private void invokeRemoteRpc(final InvokeRpc msg) { - LOG.debug("Looking up the remote actor for rpc {}", msg.getRpc()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Looking up the remote actor for rpc {}", msg.getRpc()); + } RpcRouter.RouteIdentifier routeId = new RouteIdentifierImpl( null, msg.getRpc(), msg.getIdentifier()); RpcRegistry.Messages.FindRouters findMsg = new RpcRegistry.Messages.FindRouters(routeId); @@ -147,8 +148,9 @@ public class RpcBroker extends AbstractUntypedActor { } private void executeRpc(final ExecuteRpc msg) { - LOG.debug("Executing rpc {}", msg.getRpc()); - + if(LOG.isDebugEnabled()) { + LOG.debug("Executing rpc {}", msg.getRpc()); + } Future> future = brokerSession.rpc(msg.getRpc(), XmlUtils.inputXmlToCompositeNode(msg.getRpc(), msg.getInputCompositeNode(), schemaContext)); diff --git a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcListener.java b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcListener.java index dee98521ae..22879dda2f 100644 --- a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcListener.java +++ b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/RpcListener.java @@ -31,7 +31,9 @@ public class RpcListener implements RpcRegistrationListener{ @Override public void onRpcImplementationAdded(QName rpc) { - LOG.debug("Adding registration for [{}]", rpc); + if(LOG.isDebugEnabled()) { + LOG.debug("Adding registration for [{}]", rpc); + } RpcRouter.RouteIdentifier routeId = new RouteIdentifierImpl(null, rpc, null); List> routeIds = new ArrayList<>(); routeIds.add(routeId); @@ -41,7 +43,9 @@ public class RpcListener implements RpcRegistrationListener{ @Override public void onRpcImplementationRemoved(QName rpc) { - LOG.debug("Removing registration for [{}]", rpc); + if(LOG.isDebugEnabled()) { + LOG.debug("Removing registration for [{}]", rpc); + } RpcRouter.RouteIdentifier routeId = new RouteIdentifierImpl(null, rpc, null); List> routeIds = new ArrayList<>(); routeIds.add(routeId); diff --git a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/TerminationMonitor.java b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/TerminationMonitor.java index abe2008c29..48ccd824d4 100644 --- a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/TerminationMonitor.java +++ b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/TerminationMonitor.java @@ -25,7 +25,9 @@ public class TerminationMonitor extends UntypedActor{ @Override public void onReceive(Object message) throws Exception { if(message instanceof Terminated){ Terminated terminated = (Terminated) message; - LOG.debug("Actor terminated : {}", terminated.actor()); + if(LOG.isDebugEnabled()) { + LOG.debug("Actor terminated : {}", terminated.actor()); + } }else if(message instanceof Monitor){ Monitor monitor = (Monitor) message; getContext().watch(monitor.getActorRef()); diff --git a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/BucketStore.java b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/BucketStore.java index 3de3fc00d0..b50dfb1ba3 100644 --- a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/BucketStore.java +++ b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/BucketStore.java @@ -111,7 +111,9 @@ public class BucketStore extends AbstractUntypedActorWithMetering { receiveUpdateRemoteBuckets( ((UpdateRemoteBuckets) message).getBuckets()); } else { - log.debug("Unhandled message [{}]", message); + if(log.isDebugEnabled()) { + log.debug("Unhandled message [{}]", message); + } unhandled(message); } } @@ -236,8 +238,9 @@ public class BucketStore extends AbstractUntypedActorWithMetering { versions.put(entry.getKey(), remoteVersion); } } - - log.debug("State after update - Local Bucket [{}], Remote Buckets [{}]", localBucket, remoteBuckets); + if(log.isDebugEnabled()) { + log.debug("State after update - Local Bucket [{}], Remote Buckets [{}]", localBucket, remoteBuckets); + } } /// diff --git a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/Gossiper.java b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/Gossiper.java index 85c6ebe26f..1bbcc69f5e 100644 --- a/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/Gossiper.java +++ b/opendaylight/md-sal/sal-remoterpc-connector/src/main/java/org/opendaylight/controller/remote/rpc/registry/gossip/Gossiper.java @@ -170,7 +170,9 @@ public class Gossiper extends AbstractUntypedActorWithMetering { } clusterMembers.remove(member.address()); - log.debug("Removed member [{}], Active member list [{}]", member.address(), clusterMembers); + if(log.isDebugEnabled()) { + log.debug("Removed member [{}], Active member list [{}]", member.address(), clusterMembers); + } } /** @@ -184,8 +186,9 @@ public class Gossiper extends AbstractUntypedActorWithMetering { if (!clusterMembers.contains(member.address())) clusterMembers.add(member.address()); - - log.debug("Added member [{}], Active member list [{}]", member.address(), clusterMembers); + if(log.isDebugEnabled()) { + log.debug("Added member [{}], Active member list [{}]", member.address(), clusterMembers); + } } /** @@ -205,8 +208,9 @@ public class Gossiper extends AbstractUntypedActorWithMetering { Integer randomIndex = ThreadLocalRandom.current().nextInt(0, clusterMembers.size()); remoteMemberToGossipTo = clusterMembers.get(randomIndex); } - - log.debug("Gossiping to [{}]", remoteMemberToGossipTo); + if(log.isDebugEnabled()) { + log.debug("Gossiping to [{}]", remoteMemberToGossipTo); + } getLocalStatusAndSendTo(remoteMemberToGossipTo); } @@ -244,7 +248,9 @@ public class Gossiper extends AbstractUntypedActorWithMetering { void receiveGossip(GossipEnvelope envelope){ //TODO: Add more validations if (!selfAddress.equals(envelope.to())) { - log.debug("Ignoring message intended for someone else. From [{}] to [{}]", envelope.from(), envelope.to()); + if(log.isDebugEnabled()) { + log.debug("Ignoring message intended for someone else. From [{}] to [{}]", envelope.from(), envelope.to()); + } return; } @@ -291,7 +297,9 @@ public class Gossiper extends AbstractUntypedActorWithMetering { ActorSelection remoteRef = getContext().system().actorSelection( remoteActorSystemAddress.toString() + getSelf().path().toStringWithoutAddress()); - log.debug("Sending bucket versions to [{}]", remoteRef); + if(log.isDebugEnabled()) { + log.debug("Sending bucket versions to [{}]", remoteRef); + } futureReply.map(getMapperToSendLocalStatus(remoteRef), getContext().dispatcher()); @@ -416,7 +424,9 @@ public class Gossiper extends AbstractUntypedActorWithMetering { public Void apply(Object msg) { if (msg instanceof GetBucketsByMembersReply) { Map buckets = ((GetBucketsByMembersReply) msg).getBuckets(); - log.debug("Buckets to send from {}: {}", selfAddress, buckets); + if(log.isDebugEnabled()) { + log.debug("Buckets to send from {}: {}", selfAddress, buckets); + } GossipEnvelope envelope = new GossipEnvelope(selfAddress, sender.path().address(), buckets); sender.tell(envelope, getSelf()); } -- 2.36.6