Improve Mastership logging

Logs only meaningful mastership changes

Change-Id: Ibbe4f85526df01b3c1b6eab317a2c15716098d80
diff --git a/core/net/src/main/java/org/onosproject/net/device/impl/DeviceManager.java b/core/net/src/main/java/org/onosproject/net/device/impl/DeviceManager.java
index e78e6d2..be114c4 100644
--- a/core/net/src/main/java/org/onosproject/net/device/impl/DeviceManager.java
+++ b/core/net/src/main/java/org/onosproject/net/device/impl/DeviceManager.java
@@ -216,6 +216,10 @@
     private ScheduledExecutorService backgroundRoleChecker;
     private static final int ROLE_TIMEOUT_SECONDS = 10;
 
+    // FIXME join this map with roleToAcknowledge and fix the back to back event issue here
+    private final Map<DeviceId, MastershipRole> lastAcknowledgedRole =
+            Maps.newConcurrentMap();
+
     @Activate
     public void activate() {
         portAnnotationOp = new PortAnnotationOperator(networkConfigService);
@@ -566,11 +570,11 @@
             } else if (isReachable) {
                 // If this node is the master, ensure the device is marked online.
                 if (myRole == MASTER && canMarkOnline(device)) {
-                    log.info("Can mark online {}", deviceId);
+                    log.debug("Can mark online {}", deviceId);
                     post(store.markOnline(deviceId));
                 }
 
-                log.info("{} is reachable - reasserting the role", deviceId);
+                log.debug("{} is reachable - reasserting the role", deviceId);
 
                 // Device is still reachable. It is useful for some protocols
                 // to reassert the role. Note: NONE triggers request to MastershipService
@@ -913,8 +917,13 @@
 
             if (Objects.equals(requested, response)) {
                 if (Objects.equals(requested, expected)) {
-                    // Stop the timer
-                    log.info("Role has been acknowledged for device {}", deviceId);
+                    if (log.isDebugEnabled()) {
+                        log.debug("Role has been acknowledged for device {}", deviceId);
+                    } else if (!requested.equals(lastAcknowledgedRole.get(deviceId))) {
+                        log.info("Role has been acknowledged for device {}", deviceId);
+                    }
+                    // Update the last known role and stop the timer
+                    lastAcknowledgedRole.put(deviceId, requested);
                     roleToAcknowledge.remove(deviceId);
                 } else {
                     log.warn("Role mismatch on {}. Set to {}, but store demands {}",
@@ -1174,6 +1183,7 @@
                 // When device is administratively removed, force disconnect.
                 DeviceId deviceId = event.subject().id();
                 deviceLocalStatus.remove(deviceId);
+                lastAcknowledgedRole.remove(deviceId);
 
                 DeviceProvider provider = getProvider(deviceId);
                 if (provider != null) {
diff --git a/protocols/p4runtime/ctl/src/main/java/org/onosproject/p4runtime/ctl/client/StreamClientImpl.java b/protocols/p4runtime/ctl/src/main/java/org/onosproject/p4runtime/ctl/client/StreamClientImpl.java
index 5d227e4..5c64a0c 100644
--- a/protocols/p4runtime/ctl/src/main/java/org/onosproject/p4runtime/ctl/client/StreamClientImpl.java
+++ b/protocols/p4runtime/ctl/src/main/java/org/onosproject/p4runtime/ctl/client/StreamClientImpl.java
@@ -181,12 +181,21 @@
                         ARBITRATION_RETRY_SECONDS, TimeUnit.SECONDS);
             } else {
                 // Send now.
-                log.info("Setting mastership on {}... " +
-                                 "master={}, newElectionId={}, " +
-                                 "masterElectionId={}, sessionOpen={}",
-                         deviceId, requestedToBeMaster.get(),
-                         pendingElectionId, masterElectionId,
-                         streamChannelManager.isOpen());
+                if (log.isDebugEnabled()) {
+                    log.debug("Setting mastership on {}... " +
+                                    "master={}, newElectionId={}, " +
+                                    "masterElectionId={}, sessionOpen={}",
+                            deviceId, requestedToBeMaster.get(),
+                            pendingElectionId, masterElectionId,
+                            streamChannelManager.isOpen());
+                } else if (!pendingElectionId.equals(lastUsedElectionId)) {
+                    log.info("Setting mastership on {}... " +
+                                    "master={}, newElectionId={}, " +
+                                    "masterElectionId={}, sessionOpen={}",
+                            deviceId, requestedToBeMaster.get(),
+                            pendingElectionId, masterElectionId,
+                            streamChannelManager.isOpen());
+                }
                 // Optimistically set the reported master status, if wrong, it
                 // will be updated by the arbitration response. This alleviates
                 // race conditions when calling isMaster() right after setting
diff --git a/providers/general/device/src/main/java/org/onosproject/provider/general/device/impl/GeneralDeviceProvider.java b/providers/general/device/src/main/java/org/onosproject/provider/general/device/impl/GeneralDeviceProvider.java
index f684d31..5b32187 100644
--- a/providers/general/device/src/main/java/org/onosproject/provider/general/device/impl/GeneralDeviceProvider.java
+++ b/providers/general/device/src/main/java/org/onosproject/provider/general/device/impl/GeneralDeviceProvider.java
@@ -19,6 +19,7 @@
 import com.google.common.collect.Maps;
 import com.google.common.collect.Sets;
 import com.google.common.util.concurrent.Futures;
+import org.apache.commons.lang3.tuple.Pair;
 import org.onlab.packet.ChassisId;
 import org.onlab.util.ItemNotFoundException;
 import org.onlab.util.SharedScheduledExecutors;
@@ -192,6 +193,9 @@
     private StatsPoller statsPoller;
     private DeviceProviderService providerService;
 
+    private final Map<DeviceId, Pair<MastershipRole, Integer>> lastRoleRequest =
+            Maps.newConcurrentMap();
+
     public GeneralDeviceProvider() {
         super(new ProviderId(URI_SCHEME, DEVICE_PROVIDER_PACKAGE));
     }
@@ -329,7 +333,13 @@
                 break;
             case NONE:
                 // No preference for NONE, apply as is.
-                log.info("Notifying role {} to {}", newRole, deviceId);
+                Pair<MastershipRole, Integer> pairRolePref = Pair.of(newRole, -1);
+                if (log.isDebugEnabled()) {
+                    log.debug("Notifying role {} to {}", newRole, deviceId);
+                } else if (!pairRolePref.equals(lastRoleRequest.get(deviceId))) {
+                    log.info("Notifying role {} to {}", newRole, deviceId);
+                }
+                lastRoleRequest.put(deviceId, pairRolePref);
                 handshaker.roleChanged(newRole);
                 return;
             default:
@@ -337,8 +347,15 @@
                 return;
         }
 
-        log.info("Notifying role {} (preference {}) for term {} to {}",
-                 newRole, preference, mastershipInfo.term(), deviceId);
+        Pair<MastershipRole, Integer> pairRolePref = Pair.of(newRole, preference);
+        if (log.isDebugEnabled()) {
+            log.debug("Notifying role {} (preference {}) for term {} to {}",
+                    newRole, preference, mastershipInfo.term(), deviceId);
+        } else if (!pairRolePref.equals(lastRoleRequest.get(deviceId))) {
+            log.info("Notifying role {} (preference {}) for term {} to {}",
+                    newRole, preference, mastershipInfo.term(), deviceId);
+        }
+        lastRoleRequest.put(deviceId, pairRolePref);
 
         try {
             handshaker.roleChanged(preference, mastershipInfo.term());