More detailed subscriber event logging
[lispflowmapping.git] / mappingservice / implementation / src / main / java / org / opendaylight / lispflowmapping / implementation / lisp / MapServer.java
index 5d2244907b2a93174c122c441b11c851b41958de..ed5427d7c05664ba61c390ccd77a7bfaccc3825c 100644 (file)
@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2014 Contextream, Inc. and others.  All rights reserved.
+ * Copyright (c) 2014, 2017 Contextream, Inc. and others.  All rights reserved.
  *
  * This program and the accompanying materials are made available under the
  * terms of the Eclipse Public License v1.0 which accompanies this distribution,
@@ -31,8 +31,10 @@ import java.util.concurrent.TimeUnit;
 import org.apache.commons.lang3.BooleanUtils;
 import org.opendaylight.controller.md.sal.binding.api.NotificationService;
 import org.opendaylight.lispflowmapping.config.ConfigIni;
+import org.opendaylight.lispflowmapping.implementation.util.LoggingUtil;
+import org.opendaylight.lispflowmapping.implementation.util.MSNotificationInputUtil;
 import org.opendaylight.lispflowmapping.interfaces.dao.SubKeys;
-import org.opendaylight.lispflowmapping.interfaces.dao.SubscriberRLOC;
+import org.opendaylight.lispflowmapping.interfaces.dao.Subscriber;
 import org.opendaylight.lispflowmapping.interfaces.lisp.IMapNotifyHandler;
 import org.opendaylight.lispflowmapping.interfaces.lisp.IMapServerAsync;
 import org.opendaylight.lispflowmapping.interfaces.lisp.ISmrNotificationListener;
@@ -45,6 +47,7 @@ import org.opendaylight.lispflowmapping.lisp.util.LispAddressStringifier;
 import org.opendaylight.lispflowmapping.lisp.util.LispAddressUtil;
 import org.opendaylight.lispflowmapping.lisp.util.MapNotifyBuilderHelper;
 import org.opendaylight.lispflowmapping.lisp.util.MapRequestUtil;
+import org.opendaylight.lispflowmapping.lisp.util.MappingRecordUtil;
 import org.opendaylight.lispflowmapping.lisp.util.SourceDestKeyHelper;
 import org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.inet.types.rev130715.PortNumber;
 import org.opendaylight.yang.gen.v1.urn.ietf.params.xml.ns.yang.ietf.lisp.address.types.rev151105.lisp.address.address.SourceDestKey;
@@ -62,7 +65,6 @@ import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.ma
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.maprequestnotification.MapRequestBuilder;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.transport.address.TransportAddress;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.lisp.proto.rev151105.transport.address.TransportAddressBuilder;
-import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.mappingservice.rev150906.MappingChange;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.mappingservice.rev150906.MappingChanged;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.mappingservice.rev150906.MappingOrigin;
 import org.opendaylight.yang.gen.v1.urn.opendaylight.lfm.mappingservice.rev150906.OdlMappingserviceListener;
@@ -102,8 +104,9 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
     @SuppressWarnings("unchecked")
     public void handleMapRegister(MapRegister mapRegister) {
         boolean mappingUpdated = false;
+        boolean oldMappingRemoved = false;
         boolean merge = ConfigIni.getInstance().mappingMergeIsSet() && mapRegister.isMergeEnabled();
-        Set<SubscriberRLOC> subscribers = null;
+        Set<Subscriber> subscribers = null;
         MappingRecord oldMapping;
 
         if (merge) {
@@ -124,6 +127,10 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
 
             oldMapping = getMappingRecord(mapService.getMapping(MappingOrigin.Southbound, eid));
             mapService.addMapping(MappingOrigin.Southbound, eid, getSiteId(mapRegister), mappingData);
+            if (oldMapping != null && MappingRecordUtil.isNegativeMapping(oldMapping)) {
+                mapService.removeMapping(MappingOrigin.Southbound, oldMapping.getEid());
+                oldMappingRemoved = true;
+            }
 
             if (subscriptionService) {
                 MappingRecord newMapping = merge
@@ -138,7 +145,13 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
                     if (oldMapping != null && !oldMapping.getEid().equals(eid)) {
                         subscribers = addParentSubscribers(eid, subscribers);
                     }
-                    sendSmrs(eid, subscribers);
+                    LoggingUtil.logSubscribers(LOG, eid, subscribers);
+                    handleSmr(eid, subscribers);
+                    if (oldMapping != null && oldMappingRemoved && !oldMapping.getEid().equals(eid)) {
+                        subscribers = getSubscribers(oldMapping.getEid());
+                        LoggingUtil.logSubscribers(LOG, oldMapping.getEid(), subscribers);
+                        handleSmr(oldMapping.getEid(), subscribers);
+                    }
                     mappingUpdated = true;
                 }
             }
@@ -203,13 +216,19 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
 
     @Override
     public void onMappingChanged(MappingChanged notification) {
+        LOG.trace("MappingChanged event of type: `{}'", notification.getChangeType());
         if (subscriptionService) {
             Eid eid = notification.getMappingRecord().getEid();
+            Set<Subscriber> subscribers = MSNotificationInputUtil.toSubscriberSet(notification.getSubscriberItem());
+            LoggingUtil.logSubscribers(LOG, eid, subscribers);
             if (mapService.isMaster()) {
-                sendSmrs(eid, getSubscribers(eid));
-            }
-            if (notification.getChangeType().equals(MappingChange.Removed)) {
-                removeSubscribers(eid);
+                sendSmrs(eid, subscribers);
+                if (eid.getAddress() instanceof SourceDestKey) {
+                    Set<Subscriber> dstSubscribers = MSNotificationInputUtil.toSubscriberSetFromDst(
+                            notification.getDstSubscriberItem());
+                    LoggingUtil.logSubscribers(LOG, SourceDestKeyHelper.getDstBinary(eid), dstSubscribers);
+                    sendSmrs(SourceDestKeyHelper.getDstBinary(eid), dstSubscribers);
+                }
             }
         }
     }
@@ -240,18 +259,18 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
         return false;
     }
 
-    private void sendSmrs(Eid eid, Set<SubscriberRLOC> subscribers) {
-        handleSmr(eid, subscribers);
+    private void handleSmr(Eid eid, Set<Subscriber> subscribers) {
+        sendSmrs(eid, subscribers);
 
         // For SrcDst LCAF also send SMRs to Dst prefix
         if (eid.getAddress() instanceof SourceDestKey) {
             Eid dstAddr = SourceDestKeyHelper.getDstBinary(eid);
-            Set<SubscriberRLOC> dstSubs = getSubscribers(dstAddr);
-            handleSmr(dstAddr, dstSubs);
+            Set<Subscriber> dstSubs = getSubscribers(dstAddr);
+            sendSmrs(dstAddr, dstSubs);
         }
     }
 
-    private void handleSmr(Eid eid, Set<SubscriberRLOC> subscribers) {
+    private void sendSmrs(Eid eid, Set<Subscriber> subscribers) {
         if (subscribers == null) {
             return;
         }
@@ -259,21 +278,20 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
         LOG.trace("Built SMR packet: " + mrb.build().toString());
 
         scheduler.scheduleSmrs(mrb, subscribers.iterator());
-        addSubscribers(eid, subscribers);
     }
 
     @SuppressWarnings("unchecked")
-    private Set<SubscriberRLOC> getSubscribers(Eid address) {
-        return (Set<SubscriberRLOC>) mapService.getData(MappingOrigin.Southbound, address, SubKeys.SUBSCRIBERS);
+    private Set<Subscriber> getSubscribers(Eid address) {
+        return (Set<Subscriber>) mapService.getData(MappingOrigin.Southbound, address, SubKeys.SUBSCRIBERS);
     }
 
-    private Set<SubscriberRLOC> addParentSubscribers(Eid eid, Set<SubscriberRLOC> subscribers) {
+    private Set<Subscriber> addParentSubscribers(Eid eid, Set<Subscriber> subscribers) {
         Eid parentPrefix = mapService.getParentPrefix(eid);
         if (parentPrefix == null) {
             return subscribers;
         }
 
-        Set<SubscriberRLOC> parentSubscribers = getSubscribers(parentPrefix);
+        Set<Subscriber> parentSubscribers = getSubscribers(parentPrefix);
         if (parentSubscribers != null) {
             if (subscribers != null) {
                 subscribers.addAll(parentSubscribers);
@@ -284,11 +302,7 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
         return subscribers;
     }
 
-    private void removeSubscribers(Eid address) {
-        mapService.removeData(MappingOrigin.Southbound, address, SubKeys.SUBSCRIBERS);
-    }
-
-    private void addSubscribers(Eid address, Set<SubscriberRLOC> subscribers) {
+    private void addSubscribers(Eid address, Set<Subscriber> subscribers) {
         mapService.addData(MappingOrigin.Southbound, address, SubKeys.SUBSCRIBERS, subscribers);
     }
 
@@ -297,7 +311,7 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
             Enumeration<NetworkInterface> interfaces = NetworkInterface.getNetworkInterfaces();
             while (interfaces.hasMoreElements()) {
                 NetworkInterface current = interfaces.nextElement();
-                LOG.debug("Interface " + current.toString());
+                LOG.trace("Interface " + current.toString());
                 if (!current.isUp() || current.isLoopback() || current.isVirtual()) {
                     continue;
                 }
@@ -335,25 +349,26 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
         private final ScheduledExecutorService executor = Executors.newScheduledThreadPool(cpuCores * 2, threadFactory);
         private final Map<IpAddressBinary, Map<Eid, ScheduledFuture<?>>> subscriberFutureMap = Maps.newConcurrentMap();
 
-        void scheduleSmrs(MapRequestBuilder mrb, Iterator<SubscriberRLOC> subscribers) {
-            // Using Iterator ensures that we don't get a ConcurrentModificationException when removing a SubscriberRLOC
+        void scheduleSmrs(MapRequestBuilder mrb, Iterator<Subscriber> subscribers) {
+            // Using Iterator ensures that we don't get a ConcurrentModificationException when removing a Subscriber
             // from a Set.
             while (subscribers.hasNext()) {
-                SubscriberRLOC subscriber = subscribers.next();
+                Subscriber subscriber = subscribers.next();
                 if (subscriber.timedOut()) {
-                    LOG.trace("Lazy removing expired subscriber entry " + subscriber.toString());
+                    LOG.debug("Lazy removing expired subscriber entry " + subscriber.getString());
                     subscribers.remove();
                 } else {
+                    final Eid srcEid = mrb.getSourceEid().getEid();
                     final ScheduledFuture<?> future = executor.scheduleAtFixedRate(new CancellableRunnable(
                             mrb, subscriber), 0L, ConfigIni.getInstance().getSmrTimeout(), TimeUnit.MILLISECONDS);
                     final IpAddressBinary subscriberAddress = LispAddressUtil
                             .addressBinaryFromAddress(subscriber.getSrcRloc().getAddress());
 
                     if (subscriberFutureMap.containsKey(subscriberAddress)) {
-                        subscriberFutureMap.get(subscriberAddress).put(mrb.getSourceEid().getEid(), future);
+                        subscriberFutureMap.get(subscriberAddress).put(srcEid, future);
                     } else {
                         final Map<Eid, ScheduledFuture<?>> eidFutureMap = Maps.newConcurrentMap();
-                        eidFutureMap.put(mrb.getSourceEid().getEid(), future);
+                        eidFutureMap.put(srcEid, future);
                         subscriberFutureMap.put(subscriberAddress, eidFutureMap);
                     }
                 }
@@ -367,9 +382,10 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
                 if (eidFutureMap != null) {
                     final ScheduledFuture<?> future = eidFutureMap.get(event.getEid());
                     if (future != null && !future.isCancelled()) {
-                        future.cancel(false);
-                        LOG.trace("SMR-invoked MapRequest received, scheduled task for subscriber {} with nonce {} has "
-                                + "been canceled", subscriberAddress.toString(), event.getNonce());
+                        future.cancel(true);
+                        LOG.debug("SMR-invoked MapRequest received, scheduled task for subscriber {}, EID {} with"
+                                + " nonce {} has been cancelled", subscriberAddress.toString(),
+                                LispAddressStringifier.getString(event.getEid()), event.getNonce());
                         eidFutureMap.remove(event.getEid());
                     }
                     if (eidFutureMap.isEmpty()) {
@@ -381,10 +397,10 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
 
         private final class CancellableRunnable implements Runnable {
             private MapRequestBuilder mrb;
-            private SubscriberRLOC subscriber;
+            private Subscriber subscriber;
             private int executionCount = 1;
 
-            CancellableRunnable(MapRequestBuilder mrb, SubscriberRLOC subscriber) {
+            CancellableRunnable(MapRequestBuilder mrb, Subscriber subscriber) {
                 this.mrb = mrb;
                 this.subscriber = subscriber;
             }
@@ -394,35 +410,51 @@ public class MapServer implements IMapServerAsync, OdlMappingserviceListener, IS
             public void run() {
                 final IpAddressBinary subscriberAddress = LispAddressUtil
                         .addressBinaryFromAddress(subscriber.getSrcRloc().getAddress());
+                final Eid srcEid = mrb.getSourceEid().getEid();
+
                 try {
                     // The address stored in the SMR's EID record is used as Source EID in the SMR-invoked
                     // Map-Request. To ensure consistent behavior it is set to the value used to originally request
                     // a given mapping.
                     if (executionCount <= ConfigIni.getInstance().getSmrRetryCount()) {
-                        mrb.setEidItem(new ArrayList<EidItem>());
-                        mrb.getEidItem().add(new EidItemBuilder().setEid(subscriber.getSrcEid()).build());
-                        notifyHandler.handleSMR(mrb.build(), subscriber.getSrcRloc());
-                        LOG.trace("{}. attempt to send SMR for MapRequest " + mrb.getSourceEid().getEid()
-                                + " to subscriber " + subscriber.getSrcRloc(), executionCount);
+                        synchronized (mrb) {
+                            mrb.setEidItem(new ArrayList<EidItem>());
+                            mrb.getEidItem().add(new EidItemBuilder().setEid(subscriber.getSrcEid()).build());
+                            notifyHandler.handleSMR(mrb.build(), subscriber.getSrcRloc());
+                            if (LOG.isTraceEnabled()) {
+                                LOG.trace("Attempt #{} to send SMR for EID {} to subscriber {}, source EID {}",
+                                        executionCount,
+                                        LispAddressStringifier.getString(mrb.getSourceEid().getEid()),
+                                        LispAddressStringifier.getString(subscriber.getSrcRloc()),
+                                        LispAddressStringifier.getString(mrb.getEidItem().get(0).getEid()));
+                            }
+                        }
                     } else {
                         LOG.trace("Cancelling execution of a SMR Map-Request after {} failed attempts.",
                                 executionCount - 1);
-                        cancelAndRemove(subscriberAddress);
+                        cancelAndRemove(subscriberAddress, srcEid);
+                        return;
                     }
                 } catch (Exception e) {
                     LOG.error("Errors encountered while handling SMR:", e);
-                    cancelAndRemove(subscriberAddress);
+                    cancelAndRemove(subscriberAddress, srcEid);
+                    return;
                 }
                 executionCount++;
             }
 
-            private void cancelAndRemove(IpAddressBinary subscriberAddress) {
+            private void cancelAndRemove(IpAddressBinary subscriberAddress, Eid eid) {
                 final Map<Eid, ScheduledFuture<?>> eidFutureMap = subscriberFutureMap.get(subscriberAddress);
-                final Eid eid = mrb.getSourceEid().getEid();
+                if (eidFutureMap == null) {
+                    LOG.warn("Couldn't find subscriber {} in SMR scheduler internal list", subscriberAddress);
+                    return;
+                }
+
                 if (eidFutureMap.containsKey(eid)) {
-                    eidFutureMap.get(eid).cancel(false);
+                    ScheduledFuture<?> eidFuture = eidFutureMap.get(eid);
+                    eidFutureMap.remove(eid);
+                    eidFuture.cancel(false);
                 }
-                eidFutureMap.remove(eid);
                 if (eidFutureMap.isEmpty()) {
                     subscriberFutureMap.remove(subscriberAddress);
                 }