SEBA-669 partial fix - protects volt app from repeated add-subscriber calls
or erroneous add and remove subscriber calls that happen too close to each other.

A complete fix would also require NEM to not make these calls - see SEBA-743 and SEBA-744.
A number of log messages were also improved.

Change-Id: I88bae2883d056b1fa1f5ebec6aa5e872e979b3c7
(cherry picked from commit 4c1a6a93cce74d87dccc69b09f21e075752aa630)
diff --git a/app/src/main/java/org/opencord/olt/cli/SubscriberRemoveCommand.java b/app/src/main/java/org/opencord/olt/cli/SubscriberRemoveCommand.java
index a6d901d..eaf6049 100644
--- a/app/src/main/java/org/opencord/olt/cli/SubscriberRemoveCommand.java
+++ b/app/src/main/java/org/opencord/olt/cli/SubscriberRemoveCommand.java
@@ -28,7 +28,7 @@
  * Adds a subscriber to an access device.
  */
 @Command(scope = "onos", name = "volt-remove-subscriber-access",
-        description = "Adds a subscriber to an access device")
+        description = "Removes a subscriber to an access device")
 public class SubscriberRemoveCommand extends AbstractShellCommand {
 
     @Argument(index = 0, name = "deviceId", description = "Access device ID",
diff --git a/app/src/main/java/org/opencord/olt/impl/Olt.java b/app/src/main/java/org/opencord/olt/impl/Olt.java
index 9a3534f..36ef722 100644
--- a/app/src/main/java/org/opencord/olt/impl/Olt.java
+++ b/app/src/main/java/org/opencord/olt/impl/Olt.java
@@ -23,8 +23,8 @@
 import static org.slf4j.LoggerFactory.getLogger;
 
 import java.util.AbstractMap;
-import java.util.Arrays;
 import java.util.ArrayList;
+import java.util.Arrays;
 import java.util.Collection;
 import java.util.Dictionary;
 import java.util.List;
@@ -39,7 +39,6 @@
 import java.util.concurrent.Executors;
 import java.util.stream.Collectors;
 
-import com.google.common.collect.ImmutableSet;
 import org.apache.felix.scr.annotations.Activate;
 import org.apache.felix.scr.annotations.Component;
 import org.apache.felix.scr.annotations.Deactivate;
@@ -81,22 +80,22 @@
 import org.onosproject.net.flowobjective.Objective;
 import org.onosproject.net.flowobjective.ObjectiveContext;
 import org.onosproject.net.flowobjective.ObjectiveError;
-import org.onosproject.store.serializers.KryoNamespaces;
-import org.onosproject.store.service.ConsistentMultimap;
-import org.onosproject.store.service.Serializer;
-import org.onosproject.store.service.StorageService;
 import org.onosproject.net.meter.Band;
 import org.onosproject.net.meter.DefaultBand;
 import org.onosproject.net.meter.DefaultMeterRequest;
 import org.onosproject.net.meter.Meter;
 import org.onosproject.net.meter.MeterContext;
+import org.onosproject.net.meter.MeterEvent;
 import org.onosproject.net.meter.MeterFailReason;
+import org.onosproject.net.meter.MeterId;
 import org.onosproject.net.meter.MeterKey;
-import org.onosproject.net.meter.MeterService;
 import org.onosproject.net.meter.MeterListener;
 import org.onosproject.net.meter.MeterRequest;
-import org.onosproject.net.meter.MeterId;
-import org.onosproject.net.meter.MeterEvent;
+import org.onosproject.net.meter.MeterService;
+import org.onosproject.store.serializers.KryoNamespaces;
+import org.onosproject.store.service.ConsistentMultimap;
+import org.onosproject.store.service.Serializer;
+import org.onosproject.store.service.StorageService;
 import org.opencord.olt.AccessDeviceEvent;
 import org.opencord.olt.AccessDeviceListener;
 import org.opencord.olt.AccessDeviceService;
@@ -109,6 +108,7 @@
 import org.slf4j.Logger;
 
 import com.google.common.collect.ImmutableMap;
+import com.google.common.collect.ImmutableSet;
 import com.google.common.collect.Maps;
 import com.google.common.collect.Sets;
 
@@ -322,7 +322,7 @@
 
     @Override
     public boolean provisionSubscriber(ConnectPoint connectPoint) {
-
+        log.info("Call to provision subscriber at {}", connectPoint);
         DeviceId deviceId = connectPoint.deviceId();
         PortNumber subscriberPortNo = connectPoint.port();
 
@@ -342,10 +342,19 @@
             return false;
         }
 
-        CompletableFuture<ObjectiveError> filterFuture = new CompletableFuture();
+        SubscriberAndDeviceInformation prgSub = programmedSubs.get(connectPoint);
+        if (prgSub != null) {
+            log.warn("Subscriber {} on connectionPoint {} was previously programmed .. "
+                    + "taking no action. Note that updating a subscribers params "
+                    + "(vlans, bw, tpid etc) requires removing the subscriber"
+                    + "before re-provisioning the subscriber", prgSub.id(),
+                     connectPoint);
+            return true;
+        }
 
         //delete Eapol authentication flow with default bandwidth
         //wait until Eapol rule with defaultBpId is removed to install subscriber-based rules
+        CompletableFuture<ObjectiveError> filterFuture = new CompletableFuture();
         processEapolFilteringObjectives(deviceId, subscriberPortNo, defaultBpId, filterFuture,
                 VlanId.vlanId(EAPOL_DEFAULT_VLAN), false);
         removeMeterIdFromBpMapping(deviceId, defaultBpId);
@@ -364,9 +373,10 @@
 
     @Override
     public boolean removeSubscriber(ConnectPoint connectPoint) {
-        // Get the subscriber connected to this port from the local cache
-        // as if we don't know about the subscriber there's no need to remove it
+        log.info("Call to un-provision subscriber at {}", connectPoint);
 
+        // Get the subscriber connected to this port from the local cache
+        // If we don't know about the subscriber there's no need to remove it
         DeviceId deviceId = connectPoint.deviceId();
         PortNumber subscriberPortNo = connectPoint.port();
 
@@ -387,11 +397,11 @@
         //delete dhcp & igmp trap flows
         MeterId upstreamMeterId = getMeterIdFromBpMapping(deviceId, subscriber.upstreamBandwidthProfile());
 
-        //process dhcp filtering
+        // remove dhcp filters
         processDhcpFilteringObjectives(deviceId, subscriberPortNo,
                 upstreamMeterId, subscriber.technologyProfileId(), false, true);
 
-        //process igmp filtering
+        // remove igmp filters
         processIgmpFilteringObjectives(deviceId, subscriberPortNo,
                 upstreamMeterId, subscriber.technologyProfileId(), false);
 
@@ -410,7 +420,7 @@
             additionalVlans.remove(connectPoint, vlans);
         }
 
-        //re-install eapol
+        // re-install eapol with default bandwidth profile
         processEapolFilteringObjectives(deviceId, subscriberPortNo,
                 subscriber.upstreamBandwidthProfile(), null, subscriber.cTag(), false);
 
@@ -418,6 +428,9 @@
         if (port != null && port.isEnabled()) {
             processEapolFilteringObjectives(deviceId, subscriberPortNo, defaultBpId,
                     null, VlanId.vlanId(EAPOL_DEFAULT_VLAN), true);
+        } else {
+            log.debug("Port {} is no longer enabled or it's unavailable. Not "
+                    + "reprogramming default eapol flow", connectPoint);
         }
 
         programmedSubs.remove(connectPoint);
@@ -593,8 +606,8 @@
     private void unprovisionVlans(DeviceId deviceId, PortNumber uplink,
                                   PortNumber subscriberPort, SubscriberAndDeviceInformation subscriber,
                                   Optional<VlanId> defaultVlan) {
-
-        log.info("Unprovisioning vlans...");
+        log.info("Unprovisioning vlans for subscriber {} on dev/port: {}/{}",
+                 subscriber, deviceId, subscriberPort);
 
         CompletableFuture<ObjectiveError> downFuture = new CompletableFuture();
         CompletableFuture<ObjectiveError> upFuture = new CompletableFuture();
@@ -666,10 +679,12 @@
      * @param defaultVlan default vlan of the subscriber
      * @param sub         subscriber information that includes s, c tags, tech profile and bandwidth profile references
      */
-    private void provisionSubscriberBasedFlows(ConnectPoint port, PortNumber uplinkPort, Optional<VlanId> defaultVlan,
+    private void provisionSubscriberBasedFlows(ConnectPoint port, PortNumber uplinkPort,
+                                               Optional<VlanId> defaultVlan,
                                                SubscriberAndDeviceInformation sub) {
 
-        log.info("Provisioning vlans...");
+        log.info("Provisioning vlans for subscriber {} on dev/port: {}",
+                 sub, port);
 
         DeviceId deviceId = port.deviceId();
         PortNumber subscriberPort = port.port();
@@ -691,7 +706,7 @@
         //install upstream flows
         upstreamMeterFuture.thenAcceptAsync(result -> {
             if (result == null) {
-                log.info("Upstream Meter {} is sent to the device {}. " +
+                log.info("Upstream Meter {} is in the device {}. " +
                         "Sending subscriber flows.", upstreamMeterId, deviceId);
                 ForwardingObjective.Builder upFwd = upBuilder(uplinkPort, subscriberPort,
                         subscriberVlan, deviceVlan,
@@ -718,7 +733,7 @@
         //install downstream flows
         downsteamMeterFuture.thenAcceptAsync(result -> {
             if (result == null) {
-                log.info("Downstream Meter {} is sent to the device {}. " +
+                log.info("Downstream Meter {} is in the device {}. " +
                         "Sending subscriber flows.", downstreamMeterId, deviceId);
                 ForwardingObjective.Builder downFwd = downBuilder(uplinkPort, subscriberPort,
                         subscriberVlan, deviceVlan,
@@ -778,13 +793,14 @@
     private MeterId createMeter(DeviceId deviceId, BandwidthProfileInformation bpInfo,
                                 CompletableFuture<Object> meterFuture) {
         if (bpInfo == null) {
-            log.warn("Bandwidth profile information is not found");
+            log.warn("Bandwidth profile information cannot be null when creating meter");
             return null;
         }
 
         MeterId meterId = getMeterIdFromBpMapping(deviceId, bpInfo.id());
         if (meterId != null) {
-            log.info("Meter is already added. MeterId {}", meterId);
+            log.debug("Meter {} was previously created for bp {}", meterId,
+                     bpInfo.id());
             meterFuture.complete(null);
             return meterId;
         }
@@ -797,7 +813,7 @@
                 .withContext(new MeterContext() {
                     @Override
                     public void onSuccess(MeterRequest op) {
-                        log.debug("meter addition completed");
+                        log.debug("meter addition confirmed for bpInfo:{}", bpInfo);
                         meterFuture.complete(null);
                     }
 
@@ -813,9 +829,8 @@
 
         Meter meter = meterService.submit(meterRequest);
         addMeterIdToBpMapping(deviceId, meter.id(), bpInfo.id());
-        log.info("Meter is created. Meter Id {}", meter.id());
+        log.info("Meter creation message sent for Meter Id {}", meter.id());
         programmedMeters.add(MeterKey.key(deviceId, meter.id()));
-        log.debug("programmed Meters size {}", programmedMeters.size());
         return meter.id();
     }
 
@@ -1496,7 +1511,7 @@
     private Port getUplinkPort(Device dev) {
         // check if this device is provisioned in Sadis
         SubscriberAndDeviceInformation deviceInfo = getOltInfo(dev);
-        log.debug("getUplinkPort: deviceInfo {}", deviceInfo);
+        log.trace("getUplinkPort: deviceInfo {}", deviceInfo);
         if (deviceInfo == null) {
             log.warn("Device {} is not configured in SADIS .. cannot fetch device"
                     + " info", dev.id());
@@ -1505,12 +1520,12 @@
         // Return the port that has been configured as the uplink port of this OLT in Sadis
         for (Port p : deviceService.getPorts(dev.id())) {
             if (p.number().toLong() == deviceInfo.uplinkPort()) {
-                log.debug("getUplinkPort: Found port {}", p);
+                log.trace("getUplinkPort: Found port {}", p);
                 return p;
             }
         }
 
-        log.debug("getUplinkPort: " + NO_UPLINK_PORT, dev.id());
+        log.warn("getUplinkPort: " + NO_UPLINK_PORT, dev.id());
         return null;
     }
 
@@ -1558,9 +1573,9 @@
     }
 
     private MeterId getMeterIdFromBpMapping(DeviceId deviceId, String bandwidthProfile) {
-
         if (bpInfoToMeter.get(bandwidthProfile) == null) {
-            log.warn("Bandwidth Profile '{}' is not found in bandwidth profile map.", bandwidthProfile);
+            log.warn("Bandwidth Profile '{}' is not currently mapped to a meter",
+                      bandwidthProfile);
             return null;
         }
 
@@ -1568,7 +1583,15 @@
                 .stream()
                 .filter(meterKey -> meterKey.deviceId().equals(deviceId))
                 .findFirst();
-        return meterKeyForDevice.isPresent() ? meterKeyForDevice.get().meterId() : null;
+        if (meterKeyForDevice.isPresent()) {
+            log.debug("Found meter {} for bandwidth profile {}",
+                      meterKeyForDevice.get().meterId(), bandwidthProfile);
+            return meterKeyForDevice.get().meterId();
+        } else {
+            log.warn("Bandwidth profile '{}' is not currently mapped to a meter",
+                     bandwidthProfile);
+            return null;
+        }
     }
 
     private void addMeterIdToBpMapping(DeviceId deviceId, MeterId meterId, String bandwidthProfile) {
@@ -1619,7 +1642,8 @@
                     }
                 }
 
-                log.debug("OLT got {} event for {}", event.type(), event.subject());
+                log.debug("OLT got {} event for {}: {}", event.type(),
+                          event.subject().id(), event);
 
                 switch (event.type()) {
                     //TODO: Port handling and bookkeeping should be improved once
@@ -1627,7 +1651,6 @@
                     case PORT_ADDED:
                         if (isUniPort(dev, port)) {
                             post(new AccessDeviceEvent(AccessDeviceEvent.Type.UNI_ADDED, devId, port));
-
                             if (port.isEnabled()) {
                                 processEapolFilteringObjectives(devId, port.number(), defaultBpId,
                                         null, VlanId.vlanId(EAPOL_DEFAULT_VLAN), true);
@@ -1739,14 +1762,17 @@
         @Override
         public void event(MeterEvent meterEvent) {
             if (deleteMeters && MeterEvent.Type.METER_REFERENCE_COUNT_ZERO.equals(meterEvent.type())) {
-                log.info("Zero Count Meter Event is received. Meter is {}", meterEvent.subject());
+                log.debug("Zero Count Meter {} received", meterEvent.subject());
                 Meter meter = meterEvent.subject();
                 if (meter != null && appId.equals(meter.appId()) &&
                         !programmedMeters.contains(MeterKey.key(meter.deviceId(), meter.id()))) {
+                    log.info("Deleting unreferenced, no longer programmed Meter {}",
+                             meter.id());
                     deleteMeter(meter.deviceId(), meter.id());
                 }
             } else if (MeterEvent.Type.METER_REMOVED.equals(meterEvent.type())) {
-                log.info("Meter removed event is received. Meter is {}", meterEvent.subject());
+                log.debug("Meter removed event is received. Meter is {}",
+                          meterEvent.subject());
                 removeMeterFromBpMap(meterEvent.subject());
             }
         }